From 8c33e60d50c860bf5d3581ecb5fb41166f30c595 Mon Sep 17 00:00:00 2001 From: Ben Kurtovic Date: Wed, 1 Aug 2012 14:16:29 -0400 Subject: [PATCH] Adding loads of debug loggers. --- earwigbot/tasks/drn_clerkbot.py | 92 +++++++++++++++++++++++++++++------------ 1 file changed, 66 insertions(+), 26 deletions(-) diff --git a/earwigbot/tasks/drn_clerkbot.py b/earwigbot/tasks/drn_clerkbot.py index b0361ac..31cc6b5 100644 --- a/earwigbot/tasks/drn_clerkbot.py +++ b/earwigbot/tasks/drn_clerkbot.py @@ -177,6 +177,8 @@ class DRNClerkBot(Task): for row in cursor: case = _Case(*row) cases.append(case) + log = "Read {0} cases from the database" + self.logger.debug(log.format(len(cases))) return cases def read_page(self, conn, cases, text): @@ -218,17 +220,24 @@ class DRNClerkBot(Task): f_time, "", self.min_ts, "", self.min_ts, self.min_ts, False, False, 0, new=True) cases.append(case) + log = u"Added new case {0} ('{1}', status={2}, by {3})" + self.logger.debug(log.format(id_, title, status, f_user)) else: case.status = status + log = u"Read active case {0} ('{1}')".format(id_, title) + self.logger.debug(log) if case.title != title: self.update_case_title(conn, id_, title) case.title = title case.body, case.old = body, old - # Ignore cases loaded from the DB that weren't found in the page: for case in cases: if case.body is None: case.status = self.STATUS_UNKNOWN + log = u"Dropped case {0} because it is no longer on the page ('{1}')" + self.logger.debug(log.format(case.id, case.title)) + + self.logger.debug("Done reading cases from the noticeboard page") def select_next_id(self, conn): """Return the next incremental ID for a case.""" @@ -256,6 +265,8 @@ class DRNClerkBot(Task): query = "UPDATE cases SET case_title = ? WHERE case_id = ?" with conn.cursor() as cursor: cursor.execute(query, (title, id_)) + log = u"Updated title of case {0} to '{1}'".format(id_, title) + self.logger.debug(log) def clerk(self, conn, cases): """Actually go through cases and modify those to be updated.""" @@ -265,10 +276,13 @@ class DRNClerkBot(Task): volunteers = [name for (name,) in cursor.fetchall()] notices = [] for case in cases: + log = u"Clerking case {0} ('{1}')".format(case.id, case.title) + self.logger.debug(log) if case.status == self.STATUS_UNKNOWN: self.clerk_unknown_case(conn, case) else: notices += self.clerk_case(conn, case, volunteers) + self.logger.debug("Done clerking cases") return notices def clerk_case(self, conn, case, volunteers): @@ -292,47 +306,38 @@ class DRNClerkBot(Task): notices = self.clerk_review_case(case) elif case.status in [self.STATUS_RESOLVED, self.STATUS_CLOSED]: self.clerk_closed_case(case, signatures) - else: - log = u"Unsure of how to deal with case {0} (title: {1})" - self.logger.error(log.format(case.id, case.title)) - return notices self.save_case_updates(conn, case, volunteers, signatures, storedsigs) return notices def clerk_new_case(self, case, volunteers, signatures): notices = self.notify_parties(case) if any([editor in volunteers for (editor, timestamp) in signatures]): - if case.last_action != self.STATUS_OPEN: - case.status = self.STATUS_OPEN + self.update_status(case, self.STATUS_OPEN) return notices def clerk_open_case(self, case, signatures): if self.check_for_review(case): return [] if len(case.body) - case.last_volunteer_size > 15000: - if case.last_action != self.STATUS_NEEDASSIST: - case.status = self.STATUS_NEEDASSIST + self.update_status(case, self.STATUS_NEEDASSIST) timestamps = [timestamp for (editor, timestamp) in signatures] age = (datetime.utcnow() - max(timestamps)).total_seconds() if age > 60 * 60 * 24 * 2: - if case.last_action != self.STATUS_STALE: - case.status = self.STATUS_STALE + self.update_status(case, self.STATUS_STALE) return [] def clerk_needassist_case(self, case, volunteers, newsigs): if self.check_for_review(case): return [] if any([editor in volunteers for (editor, timestamp) in newsigs]): - if case.last_action != self.STATUS_OPEN: - case.status = self.STATUS_OPEN + self.update_status(case, self.STATUS_OPEN) return [] def clerk_stale_case(self, case, newsigs): if self.check_for_review(case): return [] if newsigs: - if case.last_action != self.STATUS_OPEN: - case.status = self.STATUS_OPEN + self.update_status(case, self.STATUS_OPEN) return [] def clerk_review_case(self, case): @@ -343,6 +348,9 @@ class DRNClerkBot(Task): template += case.title.replace("|", "|") + "}}" notice = _Notice(self.very_old_title, template) case.very_old_notified = True + msg = u" {0}: will notify [[{1}]] with '{2}'" + log = msg.format(case.id, self.very_old_title, template) + self.logger.debug(log) return [notice] return [] @@ -362,6 +370,7 @@ class DRNClerkBot(Task): if not re.search(arch_bottom + "\s*\}\}\s*\Z", case.body): case.body += "\n{{" + arch_bottom + "}}" case.status = self.STATUS_UNKNOWN + self.logger.debug(u" {0}: archived case".format(case.id)) def clerk_unknown_case(self, conn, case): if case.new: @@ -372,9 +381,21 @@ class DRNClerkBot(Task): def check_for_review(self, case): age = (datetime.utcnow() - case.file_time).total_seconds() if age > 60 * 60 * 24 * 4: - if case.last_action != self.STATUS_REVIEW: - case.status = self.STATUS_REVIEW - return True + return self.update_status(case, self.STATUS_REVIEW) + return False + + def update_status(self, case, new): + old_n = self.ALIASES[case.status][0].upper() + new_n = self.ALIASES[new][0].upper() + old_n = "NEW" if not old_n else old_n + new_n = "NEW" if not new_n else new_n + if case.last_action != new: + case.status = new + log = u" {0}: {1} -> {2}" + self.logger.debug(log.format(case.id, old_n, new_n)) + return True + log = u"Avoiding {0} {1} -> {2} because we already did this ('{3}')" + self.logger.info(log.format(case.id, old_n, new_n, case.title)) return False def read_signatures(self, text): @@ -418,6 +439,8 @@ class DRNClerkBot(Task): notices.append(notice) case.parties_notified = True + log = u" {0}: will try to notify {1} parties with '{3}'" + self.logger.debug(log.format(case.id, len(notices), template)) return notices def save_case_updates(self, conn, case, volunteers, sigs, storedsigs): @@ -457,6 +480,9 @@ class DRNClerkBot(Task): for name, stamp in additions: args.append((case.id, name, stamp)) cursor.executemany(query2, args) + msg = u" {0}: added {1} signatures and removed {2}" + log = msg.format(case.id, len(additions), len(removals)) + self.logger.debug(log) def save_new_case(self, conn, case): args = (case.id, case.title, case.status, case.last_action, @@ -467,6 +493,8 @@ class DRNClerkBot(Task): with conn.cursor() as cursor: query = "INSERT INTO cases VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)" cursor.execute(query, args) + log = u" {0}: inserted new case into database".format(case.id) + self.logger.debug(log) def save_existing_case(self, conn, case): with conn.cursor(oursql.DictCursor) as cursor: @@ -494,11 +522,17 @@ class DRNClerkBot(Task): if data != stored[column]: changes.append(column + " = ?") args.append(data) + msg = u" {0}: will alter {1} ('{2}' -> '{3}')" + log = msg.format(case.id, column, stored[column], data) + self.logger.debug(log) if changes: changes = ", ".join(changes) args.append(case.id) query = "UPDATE cases SET {0} WHERE case_id = ?".format(changes) cursor.execute(query, args) + else: + log = u" {0}: no changes to commit".format(case.id) + self.logger.debug(log) def save(self, page, cases, kwargs, start): """Save any changes to the noticeboard.""" @@ -514,7 +548,7 @@ class DRNClerkBot(Task): worktime = time() - start if worktime < 60: - log = "Waiting {0} seconds to make sure we don't edit conflict" + log = "Waiting {0} seconds to avoid edit conflicts" self.logger.debug(log.format(int(60 - worktime))) sleep(60 - worktime) page.reload() @@ -525,7 +559,8 @@ class DRNClerkBot(Task): summary = self.clerk_summary.replace("$3", str(counter)) summary = summary.replace("$4", "" if counter == 1 else "s") page.edit(newtext, summary, minor=True, bot=True) - self.logger.info(u"Saved page [[{0}]]".format(page.title)) + log = u"Saved page [[{0}]] ({1} updates)" + self.logger.info(log.format(page.title, counter)) def send_notices(self, site, notices): """Send out any templated notices to users or pages.""" @@ -534,25 +569,28 @@ class DRNClerkBot(Task): return for notice in notices: target, template = notice.target, notice.template - log = u"Notifying [[{0}]] with {1}".format(target, template) - self.logger.info(log) + log = u"Trying to notify [[{0}]] with '{1}'" + self.logger.debug(log.format(target, template)) page = site.get_page(target) try: text = page.get() except exceptions.PageNotFoundError: text = "" if notice.too_late and notice.too_late in text: - log = u"Skipping [[{0}]]; was already notified".format(target) - self.logger.info(log) + log = u"Skipping [[{0}]]; was already notified with '{1}'" + self.logger.info(log.format(page.title, template)) text += ("\n" if text else "") + template try: page.edit(text, self.notify_summary, minor=False, bot=True) except exceptions.EditError as error: name, msg = type(error).name, error.message - log = u"Couldn't leave notice on {0} because of {1}: {2}" + log = u"Couldn't leave notice on [[{0}]] because of {1}: {2}" self.logger.error(log.format(page.title, name, msg)) + else: + log = u"Notified [[{0}]] with '{1}'" + self.logger.info(log.format(page.title, template)) - self.logger.info("Done sending notices") + self.logger.debug("Done sending notices") def update_chart(self, conn, site): page = site.get_page(self.chart_title) @@ -618,6 +656,8 @@ class DRNClerkBot(Task): return ", ".join(msg) + " ago" if msg else "0 hours ago" def purge_old_data(self, conn): + log = "Purging closed cases older than a month from the database" + self.logger.info(log) query = """DELETE cases, signatures FROM cases JOIN signatures ON case_id = signature_case WHERE case_status = ?