Merge lp:~wgrant/launchpad/no-key-oopses into lp:launchpad

[William Grant]

[r=jtv][bug=862032] Don't OOPS on FatalUploadErrors. Even though we can't tell anyone about them, they are still user error.

This branch fixes some user-error Soyuz OOPSes: FatalUploadErrors from process-upload.

FatalUploadErrors are caused by ChangesFile in case of signature issues (no signature, bad signature, unrecognized key, etc.) or corrupt changes files. Since we use the changes file to determine the notification recipient, such a failure means that we're unable to email anyone about it.

Long ago it was decided to turn such unreportable user errors into OOPSes. But that runs counter to ZeroOopsPolicy, so we should not do it. This branch logs them at DEBUG instead, with the rest of the normal processing stuff.

[Jeroen T. Vermeulen (jtv)]

This is a change that I've been craving. So much kudos for implementing it.

I heartily approve of most of this branch. Of course as a reviewer, I have a reputation to uphold and thus:

=== modified file 'lib/lp/archiveuploader/nascentupload.py'
--- lib/lp/archiveuploader/nascentupload.py 2011-08-23 14:35:43 +0000
+++ lib/lp/archiveuploader/nascentupload.py 2011-09-29 05:22:06 +0000

@@ -114,23 +110,14 @@
     def from_changesfile_path(cls, changesfile_path, policy, logger):
         """Create a NascentUpload from the given changesfile path.

- May raise FatalUploadError due to unrecoverable problems building
+ May raise UploadError due to unrecoverable problems building
         the ChangesFile object.

If we're crossing the boundary of "fatal" here, consider replacing or removing the word "unrecoverable" as well. It's not so much the error that is unrecoverable, as an extent of code. But what extent exactly? Like "Fatal," "unrecoverable" sort of suggests that that extent is the entire script run.

=== modified file 'lib/lp/archiveuploader/tests/test_uploadprocessor.py'
--- lib/lp/archiveuploader/tests/test_uploadprocessor.py 2011-08-26 06:14:54 +0000
+++ lib/lp/archiveuploader/tests/test_uploadprocessor.py 2011-09-29 05:22:06 +0000

@@ -1361,28 +1363,27 @@
         self.options.builds = False
         processor = self.getUploadProcessor(self.layer.txn)

- upload_dir = self.queueUpload("foocomm_1.0-1_proposed")
- bogus_changesfile_data = '''
- Ubuntu is a community developed, Linux-based operating system that is
- perfect for laptops, desktops and servers. It contains all the
- applications you need - a web browser, presentation, document and
- spreadsheet software, instant messaging and much more.
- '''
- file_handle = open(
- '%s/%s' % (upload_dir, 'bogus.changes'), 'w')
- file_handle.write(bogus_changesfile_data)
- file_handle.close()
+ self.queueUpload("foocomm_1.0-1_proposed")
+
+ # Any code that causes an OOPS is a bug that must be fixed, so
+ # let's monkeypatch something in that we know will OOPS.

I find this explanation unnecessarily confusing. To a hurried reader (and we all are from time to time) it seems to say "let's create bugs that must be fixed," which of course is fine from a job-security standpoint but...

What I think you mean is: "This test verifies that oopses get handled properly, which is very important because oopses must be caught and fixed. The following simulates an error that will be treated as an oops. We verify that the oops gets handled properly later."

If so, the first of those sentences probably belongs at the top of the test (if roughly the same thing isn't being said there already), and the last belongs at the point of verification.

For some reason the term "let's" seems to be a very reliable indicator of this kind of muddled expression in tests, so treat it as inherently suspicious.

+ class SomeException(Exception):
+ pass
+
+ def from_changesfile_path(cls, changesfile_path, policy, logger):
+ raise SomeException("I am an explanation.")
+ ...

review: Approve

[William Grant (wgrant)]

> Well done, well explained. Just one question here: wouldn't logger.info make
> more sense than logger.debug? After all this situation is still a bit of a
> problem.
>
> In particular, I'm assuming that sometimes we'll want to search the logs for
> this message to find out what happened to an upload. If so, I imagine we
> would want this logged by default.

Good point. I've bumped it to INFO and adding the changes file path to the message, as everything else that mentions the path is at DEBUG.

=== modified file 'lib/lp/archiveuploader/nascentupload.py'
--- lib/lp/archiveuploader/nascentupload.py	2011-08-23 14:35:43 +0000
+++ lib/lp/archiveuploader/nascentupload.py	2011-09-29 12:10:29 +0000
@@ -49,10 +49,6 @@
 PARTNER_COMPONENT_NAME = 'partner'
 
 
-class FatalUploadError(Exception):
-    """A fatal error occurred processing the upload; processing aborted."""
-
-
 class EarlyReturnUploadError(Exception):
     """An error occurred that prevented further error collection."""
 
@@ -114,23 +110,14 @@
     def from_changesfile_path(cls, changesfile_path, policy, logger):
         """Create a NascentUpload from the given changesfile path.
 
-        May raise FatalUploadError due to unrecoverable problems building
+        May raise UploadError due to unrecoverable problems building
         the ChangesFile object.
 
         :param changesfile_path: path to the changesfile to be uploaded.
         :param policy: the upload policy to be used.
         :param logger: the logger to be used.
         """
-        try:
-            changesfile = ChangesFile(changesfile_path, policy, logger)
-        except UploadError, e:
-            # We can't run reject() because unfortunately we don't have
-            # the address of the uploader to notify -- we broke in that
-            # exact step.
-            # XXX cprov 2007-03-26: we should really be emailing this
-            # rejection to the archive admins. For now, this will end
-            # up in the script log.
-            raise FatalUploadError(str(e))
+        changesfile = ChangesFile(changesfile_path, policy, logger)
         return cls(changesfile, policy, logger)
 
     def process(self, build=None):

=== modified file 'lib/lp/archiveuploader/tests/nascentupload.txt'
--- lib/lp/archiveuploader/tests/nascentupload.txt	2011-06-28 15:04:29 +0000
+++ lib/lp/archiveuploader/tests/nascentupload.txt	2011-09-29 12:10:29 +0000
@@ -45,14 +45,14 @@
 Constructing a NascentUpload instance verifies that the changes file
 specified exists and tries to build a ChangesFile (see
 doc/nascentuploadfile.txt) object based on that. If anything goes
-wrong during this process FatalUploadError is raised:
+wrong during this process UploadError is raised:
 
     >>> from lp.services.log.logger import DevNullLogger, FakeLogger
     >>> NascentUpload.from_changesfile_path(
     ...     datadir("DOES-NOT-EXIST"), buildd_policy, FakeLogger())
     Traceback (most recent call last):
     ...
-    FatalUploadError:...
+    UploadError:...
 
 Otherwise a ChangesFile object is ready to use.
 

=== modified file 'lib/lp/archiveuploader/tests/test_uploadprocessor.py'
--- lib/lp/archiveuploader/tests/test_uploadprocessor.py	2011-08-26 06:14:54 +0000
+++ lib/lp/archiveuploader/tests/test_uploadprocessor.py	2011-09-29 12:10:29 +0000
@@ -15,6 +15,7 @@
 from StringIO import StringIO
 import tempfile
 
+from fixtures import MonkeyPatch
 from storm.locals import Store
 import transaction
 from zope.component import (
@@ -42,6 +43,7 @@
     parse_build_upload_leaf_name,
     UploadHandler,
     UploadProcessor,
+    UploadStatusEnum,
     )
 from lp.buildmaster.enums import (
     BuildFarmJobType,
@@ -92,6 +94,7 @@
     TestCase,
     TestCaseWithFactory,
     )
+from lp.testing.fakemethod import FakeMethod
 from lp.testing.mail_helpers import pop_notifications
 
 
@@ -1352,37 +1355,27 @@
         self.checkComponentOverride("bar_1.0-1", "universe")
 
     def testOopsCreation(self):
-        """Test the the creation of an OOPS upon upload processing failure.
-
-        In order to trigger the exception needed a bogus changes file will be
-        used.
-        That exception will then initiate the creation of an OOPS report.
-        """
+        """Test that an unhandled exception generates an OOPS."""
         self.options.builds = False
         processor = self.getUploadProcessor(self.layer.txn)
 
-        upload_dir = self.queueUpload("foocomm_1.0-1_proposed")
-        bogus_changesfile_data = '''
-        Ubuntu is a community developed, Linux-based operating system that is
-        perfect for laptops, desktops and servers. It contains all the
-        applications you need - a web browser, presentation, document and
-        spreadsheet software, instant messaging and much more.
-        '''
-        file_handle = open(
-            '%s/%s' % (upload_dir, 'bogus.changes'), 'w')
-        file_handle.write(bogus_changesfile_data)
-        file_handle.close()
+        self.queueUpload("foocomm_1.0-1_proposed")
+
+        # Inject an unhandled exception into the upload processor.
+        class SomeException(Exception):
+            pass
+        self.useFixture(
+            MonkeyPatch(
+                'lp.archiveuploader.nascentupload.NascentUpload.'
+                'from_changesfile_path',
+                FakeMethod(failure=SomeException("I am an explanation."))))
 
         processor.processUploadQueue()
 
         error_utility = ErrorReportingUtility()
         error_report = error_utility.getLastOopsReport()
-        self.assertEqual('FatalUploadError', error_report.type)
-        # The upload policy requires a signature but none is present, so
-        # we get gpg verification errors.
-        expected_explanation = (
-            "Verification failed 3 times: ['No data', 'No data', 'No data']")
-        self.assertIn(expected_explanation, error_report.tb_text)
+        self.assertEqual('SomeException', error_report.type)
+        self.assertIn("I am an explanation", error_report.tb_text)
 
     def testLZMADebUpload(self):
         """Make sure that data files compressed with lzma in Debs work.
@@ -1919,6 +1912,21 @@
         self.PGPSignatureNotPreserved(archive=self.breezy.main_archive)
         self.switchToUploader()
 
+    def test_unsigned_upload_is_silently_rejected(self):
+        # Unsigned uploads are rejected without OOPS or email.
+        uploadprocessor = self.setupBreezyAndGetUploadProcessor()
+        upload_dir = self.queueUpload("netapplet_1.0-1")
+
+        last_oops = ErrorReportingUtility().getLastOopsReport()
+
+        [result] = self.processUpload(uploadprocessor, upload_dir)
+
+        self.assertEqual(UploadStatusEnum.REJECTED, result)
+        self.assertLogContains(
+            "INFO Failed to parse changes file")
+        self.assertEqual(len(stub.test_emails), 0)
+        self.assertNoNewOops(last_oops)
+
 
 class TestBuildUploadProcessor(TestUploadProcessorBase):
     """Test that processing build uploads works."""

=== modified file 'lib/lp/archiveuploader/uploadprocessor.py'
--- lib/lp/archiveuploader/uploadprocessor.py	2011-05-04 06:37:50 +0000
+++ lib/lp/archiveuploader/uploadprocessor.py	2011-09-29 12:10:29 +0000
@@ -63,8 +63,8 @@
 from lp.app.errors import NotFoundError
 from lp.archiveuploader.nascentupload import (
     EarlyReturnUploadError,
-    FatalUploadError,
     NascentUpload,
+    UploadError,
     )
 from lp.archiveuploader.uploadpolicy import (
     BuildDaemonUploadPolicy,
@@ -370,8 +370,22 @@
         # The path we want for NascentUpload is the path to the folder
         # containing the changes file (and the other files referenced by it).
         changesfile_path = os.path.join(self.upload_path, changes_file)
-        upload = NascentUpload.from_changesfile_path(
-            changesfile_path, policy, self.processor.log)
+        try:
+            upload = NascentUpload.from_changesfile_path(
+                changesfile_path, policy, self.processor.log)
+        except UploadError as e:
+            # We failed to parse the changes file, so we have no key or
+            # Changed-By to notify of the rejection. Just log it and
+            # move on.
+            # XXX wgrant 2011-09-29 bug=499438: With some refactoring we
+            # could do better here: if we have a signature then we have
+            # somebody to email, even if the rest of the file is
+            # corrupt.
+            logger.info(
+                "Failed to parse changes file '%s': %s" % (
+                    os.path.join(self.upload_path, changes_file),
+                    str(e)))
+            return UploadStatusEnum.REJECTED
 
         # Reject source upload to buildd upload paths.
         first_path = relative_path.split(os.path.sep)[0]
@@ -401,10 +415,6 @@
                               "%s " % e)
                 logger.debug(
                     "UploadPolicyError escaped upload.process", exc_info=True)
-            except FatalUploadError, e:
-                upload.reject("UploadError escaped upload.process: %s" % e)
-                logger.debug(
-                    "UploadError escaped upload.process", exc_info=True)
             except (KeyboardInterrupt, SystemExit):
                 raise
             except EarlyReturnUploadError:

=== modified file 'lib/lp/soyuz/doc/soyuz-upload.txt'
--- lib/lp/soyuz/doc/soyuz-upload.txt	2011-09-18 10:22:51 +0000
+++ lib/lp/soyuz/doc/soyuz-upload.txt	2011-09-29 12:10:29 +0000
@@ -246,12 +246,12 @@
     >>> process.returncode
     0
 
-Check the four uploads are all where we expect - number 1 in failed,
+Check the four uploads are all where we expect - number 1 in rejected,
 the other three still in incoming.
 
     >>> for i in range(4):
     ...     find_upload_dir_result(i + 1)
-    'failed'
+    'rejected'
     'incoming'
     'incoming'
     'incoming'
@@ -339,7 +339,7 @@
 
     >>> for i in range(0, 4):
     ...     find_upload_dir_result(i + 1)
-    'failed'
+    'rejected'
     'failed'
 
 Also check the upload folders contain all the files we uploaded.