Merge lp:~wgrant/launchpad/checkwatches-will-you-be-quiet-please into lp:launchpad

[William Grant]

[r=lifeless][bug=592345,719288][incr] Several checkwatches OOPSes have been demoted to INFO log entries.

This branch suppresses lots of checkwatches OOPSes. In particular, InvalidBugId, BugNotFound, PrivateRemoteBug, UnknownRemoteStatus, and UnknownRemoteImportance are now logged at INFO instead of as OOPSes and at WARNING.

The first three show up already in the UI as BugWatchActivity entries. The OOPS had no further useful information. There is some argument that UnknownRemote(Status|Importance) deserve OOPSes, but they will be easily greppable from logs, the Unknown value will be obvious to anyone looking at an affected bug, and they only tend to get fixed when users complain anyway.

InvalidBugId, BugNotFound, and PrivateRemoteBug were easily fixed by changing the logging in their exception handler.

RemoteBugUpdater had a wrapper around status conversion which logged the exception nicely, but there was no similar thing for importance. I turned the OOPS into an INFO log entry, and generalised it to work for importance too. _convertRemoteStatus was tested in a doctest where the log level was WARNING, making it hard to check that it logged correctly. So I replaced it with unit tests and extended them to _convertRemoteImportance.

[Robert Collins (lifeless)]

 def test_suite():
    return unittest.TestLoader().loadTestsFromName(__name__)

can be deleted

you might find a matcher to call _convertRemote... would be more pithy than the assertions you have at the moment.

review: Approve

=== modified file 'lib/lp/bugs/doc/bug-watch-activity.txt'
--- lib/lp/bugs/doc/bug-watch-activity.txt	2010-12-20 03:21:03 +0000
+++ lib/lp/bugs/doc/bug-watch-activity.txt	2011-02-23 22:12:50 +0000
@@ -107,11 +107,11 @@
 If the remote bug tracker breaks during an update the error will be
 recorded in the activity entry for that update.
 
-    >>> from lp.bugs.externalbugtracker.base import BugNotFound
+    >>> from lp.bugs.externalbugtracker.base import UnparsableBugData
     >>> from lp.bugs.tests.externalbugtracker import (
     ...     TestBrokenExternalBugTracker)
     >>> broken_bugtracker = TestBrokenExternalBugTracker('http://example.com')
-    >>> broken_bugtracker.get_remote_status_error = BugNotFound
+    >>> broken_bugtracker.get_remote_status_error = UnparsableBugData
 
     >>> updater.updateBugWatches(broken_bugtracker, [bug_watch])
 
@@ -125,7 +125,7 @@
 
     >>> most_recent_activity = bug_watch.activity.first()
     >>> print most_recent_activity.result.title
-    Bug Not Found
+    Unparsable Bug
 
 The OOPS ID for the error will also have been recorded.
 

=== modified file 'lib/lp/bugs/doc/externalbugtracker-bugzilla-oddities.txt'
--- lib/lp/bugs/doc/externalbugtracker-bugzilla-oddities.txt	2011-01-19 00:10:48 +0000
+++ lib/lp/bugs/doc/externalbugtracker-bugzilla-oddities.txt	2011-02-23 22:12:50 +0000
@@ -34,8 +34,8 @@
     >>> bug_watch_updater.updateBugWatches(
     ...     issuezilla, mozilla_bugzilla.watches)
     INFO:...:Updating 4 watches for 3 bugs on https://bugzilla.mozilla.org
-    WARNING:...:Didn't find bug u'42' on https://bugzilla.mozilla.org
-    (local bugs: 1, 2). (OOPS-...)
+    INFO:...:Didn't find bug u'42' on https://bugzilla.mozilla.org
+    (local bugs: 1, 2).
 
     >>> for bug_watch in mozilla_bugzilla.watches:
     ...     print "%s: %s %s" % (bug_watch.remotebug,

=== modified file 'lib/lp/bugs/doc/externalbugtracker-bugzilla.txt'
--- lib/lp/bugs/doc/externalbugtracker-bugzilla.txt	2011-02-23 06:44:36 +0000
+++ lib/lp/bugs/doc/externalbugtracker-bugzilla.txt	2011-02-23 22:12:50 +0000
@@ -443,8 +443,8 @@
     >>> bug_watch_updater.updateBugWatches(
     ...     external_bugzilla, gnome_bugzilla.watches)
     INFO:...:Updating 2 watches for 2 bugs on http://bugzilla.gnome.org/bugs
-    WARNING:...Didn't find bug u'304070' on
-    http://bugzilla.gnome.org/bugs (local bugs: 15). (OOPS-...)
+    INFO:...Didn't find bug u'304070' on
+    http://bugzilla.gnome.org/bugs (local bugs: 15).
 
     >>> for bug_watch in gnome_bugzilla.watches:
     ...     print "%s: %s %s" % (bug_watch.remotebug,
@@ -498,8 +498,8 @@
     CALLED _postPage()
     CALLED _postPage()
     CALLED _postPage()
-    WARNING:...:Didn't find bug u'304070' on
-    http://bugzilla.gnome.org/bugs (local bugs: 15). (OOPS-...)
+    INFO:...:Didn't find bug u'304070' on
+    http://bugzilla.gnome.org/bugs (local bugs: 15).
 
     >>> remote_statuses = dict(
     ...     [(int(bug_watch.remotebug), bug_watch.remotestatus)
@@ -548,8 +548,8 @@
     ...     external_bugzilla, gnome_bugzilla.watches)
     INFO:...:Updating 207 watches for 207 bugs...
     CALLED _postPage()
-    WARNING:...:Didn't find bug u'304070' on
-    http://bugzilla.gnome.org/bugs (local bugs: 15). (OOPS-...)
+    INFO:...:Didn't find bug u'304070' on
+    http://bugzilla.gnome.org/bugs (local bugs: 15).
 
     >>> remote_statuses = dict(
     ...     [(int(bug_watch.remotebug), bug_watch.remotestatus)

=== modified file 'lib/lp/bugs/doc/externalbugtracker-mantis.txt'
--- lib/lp/bugs/doc/externalbugtracker-mantis.txt	2010-10-18 22:24:59 +0000
+++ lib/lp/bugs/doc/externalbugtracker-mantis.txt	2011-02-23 22:12:50 +0000
@@ -142,8 +142,8 @@
     CALLED _getPage(u'view.php?id=1738')
     CALLED _getPage(u'view.php?id=1748')
     CALLED _getPage(u'view.php?id=1798')
-    WARNING:...:Didn't find bug u'1798' on http://bugs.some.where
-    (local bugs: 10). (OOPS-...)
+    INFO:...:Didn't find bug u'1798' on http://bugs.some.where
+    (local bugs: 10).
 
     >>> remote_statuses = dict(
     ...     (int(bug_watch.remotebug), bug_watch.remotestatus)

=== modified file 'lib/lp/bugs/doc/externalbugtracker.txt'
--- lib/lp/bugs/doc/externalbugtracker.txt	2011-01-19 00:10:48 +0000
+++ lib/lp/bugs/doc/externalbugtracker.txt	2011-02-23 22:12:50 +0000
@@ -643,44 +643,6 @@
     []
 
 
-=== Converting statuses ===
-
-Once it has retrieved the bugs from the remote server, RemoteBugUpdater
-attempts to convert their statuses into Launchpad BugTaskStatuses by
-calling the convertRemoteStatus() method on the ExternalBugTracker via
-its own _convertRemoteStatus() method.
-
-ExternalBugTracker.convertRemoteStatus() will either return a
-BugTaskStatus or will raise an UnknownRemoteStatusError.
-
-    >>> from lp.bugs.interfaces.bugtask import BugTaskStatus
-    >>> from lp.bugs.externalbugtracker import (
-    ...     UnknownRemoteStatusError)
-    >>> class StatusConvertingExternalBugTracker(TestExternalBugTracker):
-    ...
-    ...     def convertRemoteStatus(self, remote_status):
-    ...         if remote_status == 'new':
-    ...             return BugTaskStatus.NEW
-    ...         else:
-    ...             raise UnknownRemoteStatusError(remote_status)
-
-RemoteBugUpdater._convertRemoteStatus() will handle these errors and will
-return BugTaskStatus.UNKNOWN when they occur. It will also log a
-warning.
-
-    >>> remote_bug_updater = bug_watch_updater.remote_bug_updater_factory(
-    ...     bug_watch_updater, StatusConvertingExternalBugTracker(),
-    ...     '1', [1], [], utc_now)
-    >>> status = remote_bug_updater._convertRemoteStatus('new')
-    >>> print status.title
-    New
-
-    >>> status = remote_bug_updater._convertRemoteStatus('spam')
-    WARNING...Unknown remote status 'spam'. (OOPS-...)
-    >>> print status.title
-    Unknown
-
-
 == Configuration Options ==
 
 All ExternalBugTrackers have a batch_query_threshold attribute which is
@@ -776,8 +738,7 @@
     >>> error_utility = CheckWatchesErrorUtility()
 
     >>> external_bugtracker.initialize_remote_bugdb_error = None
-    >>> for error in [BugNotFound, InvalidBugId, UnparsableBugData,
-    ...               Exception]:
+    >>> for error in [UnparsableBugData, Exception]:
     ...     example_bugwatch.lastchecked = None
     ...     external_bugtracker.get_remote_status_error = error
     ...     bug_watch_updater.updateBugWatches(
@@ -787,8 +748,6 @@
     ...         example_bugwatch.last_error_type.title,
     ...         example_bugwatch.lastchecked is not None,
     ...         oops.id, oops.url)
-    Bug Not Found: True (OOPS-...; http://bugs.example.com/show_bug.cgi?id=1)
-    Invalid Bug ID: True (OOPS-...; http://bugs.example.com/show_bug.cgi?id=1)
     Unparsable Bug: True (OOPS-...; http://bugs.example.com/show_bug.cgi?id=1)
     Unknown: True (OOPS-...; http://bugs.example.com/show_bug.cgi?id=1)
 
@@ -808,6 +767,7 @@
 
 First, we need a tree to document.
 
+  >>> from lp.bugs.interfaces.bugtask import BugTaskStatus
   >>> tree = LookupTree(
   ...     ('ASSIGNED', 'STARTED', BugTaskStatus.INPROGRESS),
   ...     ('NEEDINFO', 'WAITING', 'SUSPENDED', BugTaskStatus.INCOMPLETE),

=== modified file 'lib/lp/bugs/externalbugtracker/base.py'
--- lib/lp/bugs/externalbugtracker/base.py	2011-01-23 09:34:35 +0000
+++ lib/lp/bugs/externalbugtracker/base.py	2011-02-23 22:12:50 +0000
@@ -18,6 +18,7 @@
     'UnknownBugTrackerTypeError',
     'UnknownRemoteImportanceError',
     'UnknownRemoteStatusError',
+    'UnknownRemoteValueError',
     'UnparsableBugData',
     'UnparsableBugTrackerVersion',
     'UnsupportedBugTrackerVersion',
@@ -122,12 +123,18 @@
     """The bug was not found in the external bug tracker."""
 
 
-class UnknownRemoteImportanceError(BugWatchUpdateWarning):
+class UnknownRemoteValueError(BugWatchUpdateWarning):
+    """A matching Launchpad value could not be found for the remote value."""
+
+
+class UnknownRemoteImportanceError(UnknownRemoteValueError):
     """The remote bug's importance isn't mapped to a `BugTaskImportance`."""
-
-
-class UnknownRemoteStatusError(BugWatchUpdateWarning):
+    field_name = 'importance'
+
+
+class UnknownRemoteStatusError(UnknownRemoteValueError):
     """The remote bug's status isn't mapped to a `BugTaskStatus`."""
+    field_name = 'status'
 
 
 class PrivateRemoteBug(BugWatchUpdateWarning):

=== modified file 'lib/lp/bugs/scripts/checkwatches/remotebugupdater.py'
--- lib/lp/bugs/scripts/checkwatches/remotebugupdater.py	2011-01-27 15:23:53 +0000
+++ lib/lp/bugs/scripts/checkwatches/remotebugupdater.py	2011-02-23 22:12:50 +0000
@@ -17,9 +17,12 @@
     BugNotFound,
     InvalidBugId,
     PrivateRemoteBug,
-    UnknownRemoteStatusError,
-    )
-from lp.bugs.interfaces.bugtask import BugTaskStatus
+    UnknownRemoteValueError,
+    )
+from lp.bugs.interfaces.bugtask import (
+    BugTaskImportance,
+    BugTaskStatus,
+    )
 from lp.bugs.interfaces.bugwatch import (
     BugWatchActivityStatus,
     IBugWatchSet,
@@ -28,6 +31,7 @@
     ISupportsBackLinking,
     ISupportsCommentImport,
     ISupportsCommentPushing,
+    UNKNOWN_REMOTE_IMPORTANCE,
     UNKNOWN_REMOTE_STATUS,
     )
 from lp.bugs.scripts.checkwatches.base import (
@@ -141,34 +145,24 @@
                 new_remote_importance = (
                     self.external_bugtracker.getRemoteImportance(
                         self.remote_bug))
-                new_malone_importance = (
-                    self.external_bugtracker.convertRemoteImportance(
-                        new_remote_importance))
+                new_malone_importance = self._convertRemoteImportance(
+                    new_remote_importance)
             except (InvalidBugId, BugNotFound, PrivateRemoteBug), ex:
                 error = get_bugwatcherrortype_for_error(ex)
                 message = self.error_type_messages.get(
                     error, self.error_type_message_default)
-                oops_id = self.warning(
+                self.logger.info(
                     message % {
                         'bug_id': self.remote_bug,
                         'base_url': self.external_bugtracker.baseurl,
                         'local_ids': local_ids,
-                        },
-                    properties=[
-                        ('URL', remote_bug_url),
-                        ('bug_id', self.remote_bug),
-                        ('local_ids', local_ids),
-                        ] + get_remote_system_oops_properties(
-                            self.external_bugtracker),
-                    info=sys.exc_info())
-
+                        })
                 # Set the error and activity on all bug watches
                 with self.transaction:
                     getUtility(IBugWatchSet).bulkSetError(
                         bug_watches, error)
                     getUtility(IBugWatchSet).bulkAddActivity(
-                        bug_watches, result=error, oops_id=oops_id)
-
+                        bug_watches, result=error)
             else:
                 # Assuming nothing's gone wrong, we can now deal with
                 # each BugWatch in turn.
@@ -178,7 +172,6 @@
                     bug_watch_updater.updateBugWatch(
                         new_remote_status, new_malone_status,
                         new_remote_importance, new_malone_importance)
-
         except Exception, error:
             # Send the error to the log.
             oops_id = self.error(
@@ -201,31 +194,46 @@
                     bug_watches, result=error_type, oops_id=oops_id)
 
     def _convertRemoteStatus(self, remote_status):
-        """Convert a remote bug status to a Launchpad status and return it.
-
-        :param remote_status: The remote status to be converted into a
-            Launchpad status.
-
-        If the remote status cannot be mapped to a Launchpad status,
-        BugTaskStatus.UNKNOWN will be returned and a warning will be
-        logged.
+        """Convert a remote status to a Launchpad one and return it."""
+        return self._convertRemoteValue(
+            self.external_bugtracker.convertRemoteStatus,
+            UNKNOWN_REMOTE_STATUS, BugTaskStatus.UNKNOWN, remote_status)
+
+    def _convertRemoteImportance(self, remote_importance):
+        """Convert a remote importance to a Launchpad one and return it."""
+        return self._convertRemoteValue(
+            self.external_bugtracker.convertRemoteImportance,
+            UNKNOWN_REMOTE_IMPORTANCE, BugTaskImportance.UNKNOWN,
+            remote_importance)
+
+    def _convertRemoteValue(self, conversion_method, remote_unknown,
+                            launchpad_unknown, remote_value):
+        """Convert a remote bug value to a Launchpad value and return it.
+
+        :param conversion_method: A method returning the Launchpad value
+            corresponding to the given remote value.
+        :param remote_unknown: The remote value which indicates an unknown
+            value.
+        :param launchpad_unknown: The Launchpad value which indicates an
+            unknown value.
+        :param remote_value: The remote value to be converted.
+
+        If the remote value cannot be mapped to a Launchpad value,
+        launchpad_unknown will be returned and a warning will be logged.
         """
-        # We don't bother trying to convert UNKNOWN_REMOTE_STATUS.
-        if remote_status == UNKNOWN_REMOTE_STATUS:
-            return BugTaskStatus.UNKNOWN
+        # We don't bother trying to convert remote_unknown.
+        if remote_value == remote_unknown:
+            return launchpad_unknown
 
         try:
-            launchpad_status = self.external_bugtracker.convertRemoteStatus(
-                remote_status)
-        except UnknownRemoteStatusError:
-            # We log the warning, since we need to know about statuses
+            launchpad_value = conversion_method(remote_value)
+        except UnknownRemoteValueError, e:
+            # We log the warning, since we need to know about values
             # that we don't handle correctly.
-            self.warning(
-                "Unknown remote status '%s'." % remote_status,
-                get_remote_system_oops_properties(
-                    self.external_bugtracker),
-                sys.exc_info())
-
-            launchpad_status = BugTaskStatus.UNKNOWN
-
-        return launchpad_status
+            self.logger.info(
+                "Unknown remote %s '%s' for bug %r on %s." %
+                (e.field_name, remote_value, self.remote_bug,
+                 self.bug_tracker_url))
+            launchpad_value = launchpad_unknown
+
+        return launchpad_value

=== modified file 'lib/lp/bugs/scripts/checkwatches/tests/test_remotebugupdater.py'
--- lib/lp/bugs/scripts/checkwatches/tests/test_remotebugupdater.py	2010-10-04 19:50:45 +0000
+++ lib/lp/bugs/scripts/checkwatches/tests/test_remotebugupdater.py	2011-02-23 22:12:50 +0000
@@ -10,16 +10,54 @@
 import transaction
 
 from canonical.testing.layers import LaunchpadZopelessLayer
+from lp.bugs.externalbugtracker.base import (
+    UnknownRemoteImportanceError,
+    UnknownRemoteStatusError,
+    )
 from lp.bugs.externalbugtracker.bugzilla import Bugzilla
+from lp.bugs.interfaces.bugtask import (
+    BugTaskImportance,
+    BugTaskStatus,
+    )
 from lp.bugs.scripts.checkwatches.core import CheckwatchesMaster
 from lp.bugs.scripts.checkwatches.remotebugupdater import RemoteBugUpdater
+from lp.bugs.tests.externalbugtracker import TestExternalBugTracker
+from lp.services.log.logger import BufferLogger
 from lp.testing import TestCaseWithFactory
 
 
+class StatusConvertingExternalBugTracker(TestExternalBugTracker):
+
+    def convertRemoteStatus(self, remote_status):
+        if remote_status == 'new':
+            return BugTaskStatus.NEW
+        else:
+            raise UnknownRemoteStatusError(remote_status)
+
+
+class ImportanceConvertingExternalBugTracker(TestExternalBugTracker):
+
+    def convertRemoteImportance(self, remote_importance):
+        if remote_importance == 'low':
+            return BugTaskImportance.LOW
+        else:
+            raise UnknownRemoteImportanceError(remote_importance)
+
+
 class RemoteBugUpdaterTestCase(TestCaseWithFactory):
 
     layer = LaunchpadZopelessLayer
 
+    def makeUpdater(self, remote_system=None, remote_bug_id=None,
+                    bug_watch_ids=None, unmodified_remote_ids=None,
+                    logger=None):
+        checkwatches_master = CheckwatchesMaster(transaction)
+        if logger is not None:
+            checkwatches_master.logger = logger
+        return checkwatches_master.remote_bug_updater_factory(
+            checkwatches_master, remote_system, remote_bug_id,
+            bug_watch_ids, unmodified_remote_ids, None)
+
     def test_create(self):
         # CheckwatchesMaster.remote_bug_updater_factory points to the
         # RemoteBugUpdater class, so it can be used to create
@@ -28,12 +66,9 @@
         remote_bug_id = '42'
         bug_watch_ids = [1, 2]
         unmodified_remote_ids = ['76']
-
-        checkwatches_master = CheckwatchesMaster(transaction)
-        updater = checkwatches_master.remote_bug_updater_factory(
-            checkwatches_master, remote_system, remote_bug_id,
-            bug_watch_ids, unmodified_remote_ids, None)
-
+        updater = self.makeUpdater(
+            remote_system, remote_bug_id, bug_watch_ids,
+            unmodified_remote_ids)
         self.assertTrue(
             isinstance(updater, RemoteBugUpdater),
             "updater should be an instance of RemoteBugUpdater.")
@@ -51,9 +86,40 @@
         self.assertEqual(
             unmodified_remote_ids, updater.unmodified_remote_ids,
             "RemoteBugUpdater's unmodified_remote_ids should be '%s', "
-            "were '%s'" % 
+            "were '%s'" %
             (unmodified_remote_ids, updater.unmodified_remote_ids))
 
-
-def test_suite():
-    return unittest.TestLoader().loadTestsFromName(__name__)
+    def test_convertRemoteStatus(self):
+        updater = self.makeUpdater(
+            remote_system=StatusConvertingExternalBugTracker())
+        self.assertEqual(
+            BugTaskStatus.NEW, updater._convertRemoteStatus('new'))
+
+    def test_convertRemoteStatus_logs_unknown_values(self):
+        updater = self.makeUpdater(
+            remote_system=StatusConvertingExternalBugTracker(),
+            remote_bug_id=42,
+            logger=BufferLogger())
+        self.assertEqual(
+            BugTaskStatus.UNKNOWN, updater._convertRemoteStatus('spam'))
+        self.assertEqual(
+            "INFO Unknown remote status 'spam' for bug 42 on "
+            "http://example.com.\n", updater.logger.getLogBuffer())
+
+    def test_convertRemoteImportance(self):
+        updater = self.makeUpdater(
+            remote_system=ImportanceConvertingExternalBugTracker())
+        self.assertEqual(
+            BugTaskImportance.LOW, updater._convertRemoteImportance('low'))
+
+    def test_convertRemoteImportance_logs_unknown_values(self):
+        updater = self.makeUpdater(
+            remote_system=ImportanceConvertingExternalBugTracker(),
+            remote_bug_id=42,
+            logger=BufferLogger())
+        self.assertEqual(
+            BugTaskImportance.UNKNOWN,
+            updater._convertRemoteImportance('spam'))
+        self.assertEqual(
+            "INFO Unknown remote importance 'spam' for bug 42 on "
+            "http://example.com.\n", updater.logger.getLogBuffer())