Merge lp:~thumper/launchpad/more-careful-network-service-usage into lp:launchpad/db-devel

[Tim Penhey]

Add missing operation descriptions for the jobs, and catch errors that might arise during emailing users about errors.

This branch adds a default getOperationDescription to the BaseRunnableJob, and also adds extra exception handling around the handing of other exceptions.

If the run job raises an error, we attempt to notify the recipients. However, as we have found with staging, that can fail. The extra try/except block catches this failures to notify about failures, but it just logs the error and makes an oops.

Extra tests were added for the other job types to make sure they have a sensible getOperationDescription.

[Michael Hudson-Doyle (mwhudson)]

As mentioned on IRC, please us logger.exception() instead of using logger.error(e).

Otherwise fine.

review: Approve

[Björn Tillenius (bjornt)]

On Fri, Apr 30, 2010 at 05:26:29AM -0000, Tim Penhey wrote:
> === modified file 'lib/lp/services/job/runner.py'
> --- lib/lp/services/job/runner.py 2010-04-06 03:37:16 +0000
> +++ lib/lp/services/job/runner.py 2010-04-30 05:22:33 +0000

> @@ -181,13 +184,24 @@
> with self.error_utility.oopsMessage(
> dict(job.getOopsVars())):
> try:
> - self.logger.debug('Running %r', job)
> - self.runJob(job)
> - except job.user_error_types, e:
> - job.notifyUserError(e)
> - except Exception:
> + try:
> + self.logger.debug('Running %r', job)
> + self.runJob(job)
> + except job.user_error_types, e:
> + job.notifyUserError(e)
> + except Exception:
> + info = sys.exc_info()
> + return self._doOops(job, info)
> + except Exception, e:
> + # This only happens if sending attempting to notify users
> + # about errors fails for some reason (like a misconfigured
> + # email server).
> + self.logger.exception(e)
> info = sys.exc_info()
> - return self._doOops(job, info)
> + self.error_utility.raising(info)
> + oops = self.error_utility.getLastOopsReport()
> + # Returning the oops says something went wrong.
> + return oops

As discussed on IRC, this new exception handling is untested. To avoid
things breaking, and to avoid people getting tempted into refactoring
the outer exception handling into using self._doOops(), we need two
tests; one where job.notifyUserError() errors out, and one where
job.notifyOops() errors out.

Since it's EOD for you now, I'd be willing to let this branch land
without tests (since it won't break anything not already broken), so
that you can QA it more easily on Monday. Given that you promise to
write the tests on Monday, of course.

    vote approve

--
Björn Tillenius | https://launchpad.net/~bjornt

review: Approve

[Tim Penhey (thumper)]

I've updated the test cases for the job runner to confirm that the
errors are handled as expected and that oopses are generated
when we expect them to be.

As a part of this change I have updated the base launchpad TestCase to record
oopses that are generated during the test execution.

These are available as self.oopses and is a list.

This is done by adding an object event to the global error reporting utility
class so that when new oopses are generated and saved it notifies listeners.
The test case starts listening in setUp and stops listening in tearDown thanks
to Fixture code that was in the branch scanner. This code has been moved into
the testing module as no code was currently using it (due to a past change in
the scanner). The tests for the fixtures were also moved into the testing
module.

This also fixes bug 567689, and I did a drive by fix of a spurious test failure,
bug 567257.

[Michael Hudson-Doyle (mwhudson)]

All the new stuff looks great to me. There *may* be oops-related APIs that aren't needed any more, but that can wait.

review: Approve

[Björn Tillenius (bjornt)]

Those changes look good. firing off an event is a good idea, and the tests look good.

=== modified file 'lib/canonical/launchpad/webapp/errorlog.py'
--- lib/canonical/launchpad/webapp/errorlog.py	2009-11-26 21:25:17 +0000
+++ lib/canonical/launchpad/webapp/errorlog.py	2010-05-03 14:15:42 +0000
@@ -20,7 +20,9 @@
 import urllib
 
 import pytz
+from zope.component.interfaces import ObjectEvent
 from zope.error.interfaces import IErrorReportingUtility
+from zope.event import notify
 from zope.exceptions.exceptionformatter import format_exception
 from zope.interface import implements
 from zope.publisher.interfaces.xmlrpc import IXMLRPCRequest
@@ -35,7 +37,7 @@
     get_request_statements, get_request_duration,
     soft_timeout_expired)
 from canonical.launchpad.webapp.interfaces import (
-    IErrorReport, IErrorReportRequest)
+    IErrorReport, IErrorReportEvent, IErrorReportRequest)
 from canonical.launchpad.webapp.opstats import OpStats
 
 UTC = pytz.utc
@@ -130,6 +132,11 @@
         *(int(elem) for elem in re.findall('[0-9]+', datestring)[:7]))
 
 
+class ErrorReportEvent(ObjectEvent):
+    """A new error report has been created."""
+    implements(IErrorReportEvent)
+
+
 class ErrorReport:
     implements(IErrorReport)
 
@@ -426,6 +433,7 @@
         if self.copy_to_zlog:
             self._do_copy_to_zlog(
                 entry.time, entry.type, entry.url, info, entry.id)
+        notify(ErrorReportEvent(entry))
 
     def _makeErrorReport(self, info, request=None, now=None,
                          informational=False):

=== modified file 'lib/canonical/launchpad/webapp/interfaces.py'
--- lib/canonical/launchpad/webapp/interfaces.py	2010-04-01 17:20:31 +0000
+++ lib/canonical/launchpad/webapp/interfaces.py	2010-05-03 14:15:42 +0000
@@ -8,6 +8,7 @@
 import logging
 
 import zope.app.publication.interfaces
+from zope.component.interfaces import IObjectEvent
 from zope.interface import Interface, Attribute, implements
 from zope.app.security.interfaces import (
     IAuthentication, IPrincipal, IPrincipalSource)
@@ -674,6 +675,10 @@
         """
 
 
+class IErrorReportEvent(IObjectEvent):
+    """A new error report has been created."""
+
+
 class IErrorReport(Interface):
     id = TextLine(description=u"The name of this error report.")
     type = TextLine(description=u"The type of the exception that occurred.")

=== modified file 'lib/lp/code/model/branchmergeproposaljob.py'
--- lib/lp/code/model/branchmergeproposaljob.py	2010-04-23 08:33:14 +0000
+++ lib/lp/code/model/branchmergeproposaljob.py	2010-05-03 14:15:42 +0000
@@ -471,6 +471,9 @@
         commenter = self.code_review_comment.message.owner
         return [format_address_for_person(commenter)]
 
+    def getOperationDescription(self):
+        return 'emailing a code review comment'
+
 
 class ReviewRequestedEmailJob(BranchMergeProposalJobDerived):
     """Send email to the reviewer telling them to review the proposal.
@@ -533,6 +536,9 @@
             recipients.append(format_address_for_person(self.requester))
         return recipients
 
+    def getOperationDescription(self):
+        return 'emailing a reviewer requesting a review'
+
 
 class MergeProposalUpdatedEmailJob(BranchMergeProposalJobDerived):
     """Send email to the subscribers informing them of updated fields.
@@ -598,6 +604,9 @@
             recipients.append(format_address_for_person(self.editor))
         return recipients
 
+    def getOperationDescription(self):
+        return 'emailing subscribers about merge proposal changes'
+
 
 class BranchMergeProposalJobFactory:
     """Construct a derived merge proposal job for a BranchMergeProposalJob."""

=== modified file 'lib/lp/code/model/tests/test_branchmergeproposaljobs.py'
--- lib/lp/code/model/tests/test_branchmergeproposaljobs.py	2010-04-26 00:24:26 +0000
+++ lib/lp/code/model/tests/test_branchmergeproposaljobs.py	2010-05-03 14:15:42 +0000
@@ -23,7 +23,11 @@
 from lp.code.adapters.branch import BranchMergeProposalDelta
 from lp.code.interfaces.branchmergeproposal import (
     IBranchMergeProposalJob, IBranchMergeProposalJobSource,
-    IMergeProposalCreatedJob, IUpdatePreviewDiffJobSource,
+    ICodeReviewCommentEmailJob, ICodeReviewCommentEmailJobSource,
+    IMergeProposalCreatedJob, IMergeProposalUpdatedEmailJob,
+    IMergeProposalUpdatedEmailJobSource,
+    IReviewRequestedEmailJob, IReviewRequestedEmailJobSource,
+    IUpdatePreviewDiffJob, IUpdatePreviewDiffJobSource,
     )
 from lp.code.model.branchmergeproposaljob import (
      BranchMergeProposalJob, BranchMergeProposalJobDerived,
@@ -87,6 +91,13 @@
         verifyObject(IMergeProposalCreatedJob, job)
         verifyObject(IBranchMergeProposalJob, job)
 
+    def test_getOperationDescription(self):
+        bmp = self.factory.makeBranchMergeProposal()
+        job = MergeProposalCreatedJob.create(bmp)
+        self.assertTrue(
+            job.getOperationDescription().startswith(
+                'notifying people about the proposal to merge'))
+
     def checkDiff(self, diff):
         self.assertNotIn('+bar', diff.diff.text)
         self.assertIn('+qux', diff.diff.text)
@@ -144,6 +155,20 @@
         """UpdatePreviewDiffJob implements IUpdatePreviewDiffJobSource."""
         verifyObject(IUpdatePreviewDiffJobSource, UpdatePreviewDiffJob)
 
+    def test_providesInterface(self):
+        """MergeProposalCreatedJob provides the expected interfaces."""
+        bmp = self.factory.makeBranchMergeProposal()
+        job = UpdatePreviewDiffJob.create(bmp)
+        verifyObject(IUpdatePreviewDiffJob, job)
+        verifyObject(IBranchMergeProposalJob, job)
+
+    def test_getOperationDescription(self):
+        bmp = self.factory.makeBranchMergeProposal()
+        job = UpdatePreviewDiffJob.create(bmp)
+        self.assertEqual(
+            'generating the diff for a merge proposal',
+            job.getOperationDescription())
+
     def test_run(self):
         self.useBzrBranches(direct_database=True)
         bmp = self.createExampleMerge()[0]
@@ -345,5 +370,77 @@
         self.assertIsInstance(job, MergeProposalUpdatedEmailJob)
 
 
+class TestCodeReviewCommentEmailJob(TestCaseWithFactory):
+
+    layer = LaunchpadZopelessLayer
+
+    def test_implement_interface(self):
+        """UpdatePreviewDiffJob implements IUpdatePreviewDiffJobSource."""
+        verifyObject(
+            ICodeReviewCommentEmailJobSource, CodeReviewCommentEmailJob)
+
+    def test_providesInterface(self):
+        """CodeReviewCommentEmailJob provides the expected interfaces."""
+        comment = self.factory.makeCodeReviewComment()
+        job = CodeReviewCommentEmailJob.create(comment)
+        verifyObject(ICodeReviewCommentEmailJob, job)
+        verifyObject(IBranchMergeProposalJob, job)
+
+    def test_getOperationDescription(self):
+        comment = self.factory.makeCodeReviewComment()
+        job = CodeReviewCommentEmailJob.create(comment)
+        self.assertEqual(
+            'emailing a code review comment',
+            job.getOperationDescription())
+
+
+class TestReviewRequestedEmailJob(TestCaseWithFactory):
+
+    layer = LaunchpadZopelessLayer
+
+    def test_implement_interface(self):
+        """UpdatePreviewDiffJob implements IUpdatePreviewDiffJobSource."""
+        verifyObject(IReviewRequestedEmailJobSource, ReviewRequestedEmailJob)
+
+    def test_providesInterface(self):
+        """MergeProposalCreatedJob provides the expected interfaces."""
+        request = self.factory.makeCodeReviewVoteReference()
+        job = ReviewRequestedEmailJob.create(request)
+        verifyObject(IReviewRequestedEmailJob, job)
+        verifyObject(IBranchMergeProposalJob, job)
+
+    def test_getOperationDescription(self):
+        request = self.factory.makeCodeReviewVoteReference()
+        job = ReviewRequestedEmailJob.create(request)
+        self.assertEqual(
+            'emailing a reviewer requesting a review',
+            job.getOperationDescription())
+
+
+class TestMergeProposalUpdatedEmailJob(TestCaseWithFactory):
+
+    layer = LaunchpadZopelessLayer
+
+    def test_class_implements_interface(self):
+        verifyObject(
+            IMergeProposalUpdatedEmailJobSource, MergeProposalUpdatedEmailJob)
+
+    def test_providesInterface(self):
+        """MergeProposalUpdatedEmailJob provides the expected interfaces."""
+        bmp = self.factory.makeBranchMergeProposal()
+        job = MergeProposalUpdatedEmailJob.create(
+            bmp, 'change', bmp.registrant)
+        verifyObject(IMergeProposalUpdatedEmailJob, job)
+        verifyObject(IBranchMergeProposalJob, job)
+
+    def test_getOperationDescription(self):
+        bmp = self.factory.makeBranchMergeProposal()
+        job = MergeProposalUpdatedEmailJob.create(
+            bmp, 'change', bmp.registrant)
+        self.assertEqual(
+            'emailing subscribers about merge proposal changes',
+            job.getOperationDescription())
+
+
 def test_suite():
     return unittest.TestLoader().loadTestsFromName(__name__)

=== modified file 'lib/lp/code/model/tests/test_diff.py'
--- lib/lp/code/model/tests/test_diff.py	2010-04-30 03:10:17 +0000
+++ lib/lp/code/model/tests/test_diff.py	2010-05-03 14:15:42 +0000
@@ -260,12 +260,10 @@
     def test_fromFile_withError(self):
         # If the diff is formatted such that generating the diffstat fails, we
         # want to record an oops but continue.
-        last_oops_id = errorlog.globalErrorUtility.lastid
         diff_bytes = "not a real diff"
         diff = Diff.fromFile(StringIO(diff_bytes), len(diff_bytes))
-        # XXX MichaelHudson, 2010-04-29, bug=567257: This test fails
-        # intermittently when run close to midnight.
-        #self.assertNotEqual(last_oops_id, errorlog.globalErrorUtility.lastid)
+        oops = self.oopses[0]
+        self.assertEqual('MalformedPatchHeader', oops.type)
         self.assertIs(None, diff.diffstat)
         self.assertIs(None, diff.added_lines_count)
         self.assertIs(None, diff.removed_lines_count)

=== modified file 'lib/lp/codehosting/scanner/tests/test_bzrsync.py'
--- lib/lp/codehosting/scanner/tests/test_bzrsync.py	2010-04-28 05:40:02 +0000
+++ lib/lp/codehosting/scanner/tests/test_bzrsync.py	2010-05-03 14:15:42 +0000
@@ -59,14 +59,16 @@
     LOG = "Log message"
 
     def setUp(self):
-        TestCaseWithTransport.setUp(self)
-        TestCaseWithFactory.setUp(self)
+        super(BzrSyncTestCase, self).setUp()
         self.disable_directory_isolation()
         self.useBzrBranches(direct_database=True)
         self.lp_db_user = config.launchpad.dbuser
         self.makeFixtures()
         LaunchpadZopelessLayer.switchDbUser(config.branchscanner.dbuser)
 
+    def tearDown(self):
+        super(BzrSyncTestCase, self).tearDown()
+
     def makeFixtures(self):
         """Makes test fixtures before we switch to the scanner db user."""
         self.db_branch, self.bzr_tree = self.create_branch_and_tree(

=== modified file 'lib/lp/services/job/runner.py'
--- lib/lp/services/job/runner.py	2010-04-06 03:37:16 +0000
+++ lib/lp/services/job/runner.py	2010-05-03 14:15:42 +0000
@@ -72,6 +72,9 @@
         """Return a list of email-ids to notify about oopses."""
         return self.getErrorRecipients()
 
+    def getOperationDescription(self):
+        return 'unspecified operation'
+
     def getErrorRecipients(self):
         """Return a list of email-ids to notify about user errors."""
         return []
@@ -155,8 +158,8 @@
 
         try:
             job.run()
-        except Exception, e:
-            self.logger.error(e)
+        except Exception:
+            self.logger.exception("Job execution raised an exception.")
             transaction.abort()
             job.fail()
             # Record the failure.
@@ -181,13 +184,25 @@
         with self.error_utility.oopsMessage(
             dict(job.getOopsVars())):
             try:
-                self.logger.debug('Running %r', job)
-                self.runJob(job)
-            except job.user_error_types, e:
-                job.notifyUserError(e)
+                try:
+                    self.logger.debug('Running %r', job)
+                    self.runJob(job)
+                except job.user_error_types, e:
+                    job.notifyUserError(e)
+                except Exception:
+                    info = sys.exc_info()
+                    return self._doOops(job, info)
             except Exception:
+                # This only happens if sending attempting to notify users
+                # about errors fails for some reason (like a misconfigured
+                # email server).
+                self.logger.exception(
+                    "Failed to notify users about a failure.")
                 info = sys.exc_info()
-                return self._doOops(job, info)
+                self.error_utility.raising(info)
+                oops = self.error_utility.getLastOopsReport()
+                # Returning the oops says something went wrong.
+                return oops
 
     def _doOops(self, job, info):
         """Report an OOPS for the provided job and info.

=== modified file 'lib/lp/services/job/tests/test_runner.py'
--- lib/lp/services/job/tests/test_runner.py	2010-04-06 00:01:24 +0000
+++ lib/lp/services/job/tests/test_runner.py	2010-05-03 14:15:42 +0000
@@ -76,6 +76,37 @@
         raise RaisingJobException(self.message)
 
 
+class RaisingJobUserError(NullJob):
+    """A job that raises a user error when it runs."""
+
+    user_error_types = (RaisingJobException, )
+
+    def run(self):
+        raise RaisingJobException(self.message)
+
+
+class RaisingJobRaisingNotifyOops(NullJob):
+    """A job that raises when it runs, and when calling notifyOops."""
+
+    def run(self):
+        raise RaisingJobException(self.message)
+
+    def notifyOops(self, oops):
+        raise RaisingJobException('oops notifying oops')
+
+
+class RaisingJobRaisingNotifyUserError(NullJob):
+    """A job that raises when it runs, and when notifying user errors."""
+
+    user_error_types = (RaisingJobException, )
+
+    def run(self):
+        raise RaisingJobException(self.message)
+
+    def notifyUserError(self, error):
+        raise RaisingJobException('oops notifying users')
+
+
 class TestJobRunner(TestCaseWithFactory):
     """Ensure JobRunner behaves as expected."""
 
@@ -254,6 +285,38 @@
         transaction.abort()
         self.assertEqual(JobStatus.FAILED, job.job.status)
 
+    def test_runJobHandleErrors_oops_generated(self):
+        """The handle errors method records an oops for raised errors."""
+        job = RaisingJob('boom')
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(1, len(self.oopses))
+
+    def test_runJobHandleErrors_user_error_no_oops(self):
+        """If the job raises a user error, there is no oops."""
+        job = RaisingJobUserError('boom')
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(0, len(self.oopses))
+
+    def test_runJobHandleErrors_oops_generated_notify_fails(self):
+        """A second oops is logged if the notification of the oops fails."""
+        job = RaisingJobRaisingNotifyOops('boom')
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(2, len(self.oopses))
+
+    def test_runJobHandleErrors_oops_generated_user_notify_fails(self):
+        """A second oops is logged if the notification of the oops fails.
+
+        In this test case the error is a user expected error, so the
+        notifyUserError is called, and in this case the notify raises too.
+        """
+        job = RaisingJobRaisingNotifyUserError('boom')
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(1, len(self.oopses))
+
 
 class StuckJob(BaseRunnableJob):
     """Simulation of a job that stalls."""

=== modified file 'lib/lp/testing/__init__.py'
--- lib/lp/testing/__init__.py	2010-04-30 12:33:16 +0000
+++ lib/lp/testing/__init__.py	2010-05-03 14:15:42 +0000
@@ -73,7 +73,7 @@
 
 from windmill.authoring import WindmillTestClient
 
-from zope.component import getUtility
+from zope.component import adapter, getUtility
 import zope.event
 from zope.interface.verify import verifyClass, verifyObject
 from zope.security.proxy import (
@@ -83,6 +83,7 @@
 from canonical.launchpad.webapp import canonical_url, errorlog
 from canonical.launchpad.webapp.servers import WebServiceTestRequest
 from canonical.config import config
+from canonical.launchpad.webapp.errorlog import ErrorReportEvent
 from canonical.launchpad.webapp.interaction import ANONYMOUS
 from canonical.launchpad.webapp.interfaces import ILaunchBag
 from canonical.launchpad.windmill.testing import constants
@@ -97,6 +98,7 @@
 from lp.testing._tales import test_tales
 from lp.testing._webservice import (
     launchpadlib_credentials_for, launchpadlib_for, oauth_access_token_for)
+from lp.testing.fixture import ZopeEventHandlerFixture
 
 # zope.exception demands more of frame objects than twisted.python.failure
 # provides in its fake frames.  This is enough to make it work with them
@@ -384,6 +386,14 @@
         testtools.TestCase.setUp(self)
         from lp.testing.factory import ObjectFactory
         self.factory = ObjectFactory()
+        # Record the oopses generated during the test run.
+        self.oopses = []
+        self.installFixture(ZopeEventHandlerFixture(self._recordOops))
+
+    @adapter(ErrorReportEvent)
+    def _recordOops(self, event):
+        """Add the oops to the testcase's list."""
+        self.oopses.append(event.object)
 
     def assertStatementCount(self, expected_count, function, *args, **kwargs):
         """Assert that the expected number of SQL statements occurred.

=== renamed file 'lib/lp/codehosting/scanner/fixture.py' => 'lib/lp/testing/fixture.py'
=== renamed file 'lib/lp/codehosting/scanner/tests/test_fixture.py' => 'lib/lp/testing/tests/test_fixture.py'
--- lib/lp/codehosting/scanner/tests/test_fixture.py	2009-06-30 16:56:07 +0000
+++ lib/lp/testing/tests/test_fixture.py	2010-05-03 14:15:42 +0000
@@ -9,7 +9,7 @@
 
 from zope.interface import implements
 
-from lp.codehosting.scanner.fixture import (
+from lp.testing.fixture import (
     Fixtures, FixtureWithCleanup, IFixture, run_with_fixture, with_fixture)
 from lp.testing import TestCase