Merge lp:~mbp/launchpad/612171-diff-generation-spam into lp:launchpad

[Martin Pool]

This was proposed into the wrong branch, and anyhow had a confused message, here's the right thing:

* log all job failures, even those caused by user errors
* treat 'branch has pending writes' as a retryable job error, rather than immediately mailing the user

[Aaron Bentley (abentley)]

On 11-10-13 07:49 PM, Martin Pool wrote:
> Oh, perhaps I was unclear, I'm not suppressing mail for all user errors.
> That would be bad.

I'm glad you're not suppressing all user errors. The point of a user error is that the user should be notified. If it's not something the user should be notified about, then it shouldn't be a user error, and conversely, no user errors should be suppressed.

You are suppressing errors about pending writes, but you are also suppressing errors about missing source and target revisions. I believe that kind of error is something the user should be notified about, because either they made a mistake, or they need to push to the source or target.

The obvious solution is to raise a different exception when there are pending writes.

> I'm logging all user errors

That's great; I have a branch to do that, also: lp:~abentley/launchpad/log-user-errors

I haven't submitted mine yet, because it doesn't have tests. Unfortunately, it appears you haven't tested that, either. The bug is #850974: No indication when a job resulted in a user error

> Then for this particular error, diff generation failure, which we may agree
> is not really a user error, I'm suppressing the mail. Perhaps I should also
> formally reclassify it.

You should definitely formally reclassify it. I think you should do that by raising a different exception for pending writes, but if you want to reclassify all UpdatePreviewDiffNotReady exceptions, you can just delete UpdatePreviewDiffJob.user_error_types

It appears that you've deleted the original merge proposal, which makes it hard to continue the conversation. In the future, please consider resubmitting in these circumstances. Resubmitting will allow you to change the target branch.

[Martin Pool (mbp)]

On 14 October 2011 11:47, Aaron Bentley <email address hidden> wrote:
> On 11-10-13 07:49 PM, Martin Pool wrote:
>> Oh, perhaps I was unclear, I'm not suppressing mail for all user errors.
>> That would be bad.
>
> I'm glad you're not suppressing all user errors.  The point of a user error is that the user should be notified.  If it's not something the user should be notified about, then it shouldn't be a user error, and conversely, no user errors should be suppressed.
>
> You are suppressing errors about pending writes, but you are also suppressing errors about missing source and target revisions.  I believe that kind of error is something the user should be notified about, because either they made a mistake, or they need to push to the source or target.

OK, so we could certainly handle them differently.

On the case of empty branches:

 - that seems like a pretty obscure case; I make mistakes with mps all
the time (even the previous iteration of this one) but I don't think
I've ever done that; it's more common to target the wrong branch
 - when it does happen, are we sure it's a user error not something else?
 - I don't really understand the user story by which someone would try
to merge to or from an empty branch
 - it seems more useful to tell them about it at the time they are
proposing the merge rather than some time later
 - if we are going to tell them about it, we ought to say which branch
and what they are expected to do about it
 - won't the problem be pretty obvious when they look at the mp page?

If we didn't send mail about it, I doubt it would be a high bug.

> The obvious solution is to raise a different exception when there are pending writes.

yep

>
>> I'm logging all user errors
>
> That's great; I have a branch to do that, also: lp:~abentley/launchpad/log-user-errors
>
> I haven't submitted mine yet, because it doesn't have tests.  Unfortunately, it appears you haven't tested that, either.  The bug is #850974: No indication when a job resulted in a user error

Personally I'm not very rigorous about testing dev/ops oriented
logging, other than making sure it does not crash (eg when formatting
the string.) If we're not getting the information we want, we can
add more logging. You might say, what if something changes that means
the logs are unintentionally not emitted, but I think often those
changes happen at a level that means a unit test won't catch them (eg
different code is run, or not run.) I would never block adding
logging to wait for tests, but of course I don't decide lp's review
policy.

>
>> Then for this particular error, diff generation failure, which we may agree
>> is not really a user error, I'm suppressing the mail. Perhaps I should also
>> formally reclassify it.
>
> You should definitely formally reclassify it.  I think you should do that by raising a different exception for pending writes, but if you want to reclassify all UpdatePreviewDiffNotReady exceptions, you can just delete UpdatePreviewDiffJob.user_error_types

ok

> It appears that you've deleted the original merge proposal, which makes it hard to continue the conversation.  In the future, please consider resubmitting in these circumstances. ...

[Aaron Bentley (abentley)]

> On the case of empty branches:
>
> - that seems like a pretty obscure case; I make mistakes with mps all
> the time (even the previous iteration of this one) but I don't think
> I've ever done that; it's more common to target the wrong branch

Okay. Still, your current approach is swatting a fly with a sledgehammer. Sometimes that's necessary, but in this case, a flyswatter is just as convenient.

> - when it does happen, are we sure it's a user error not something else?

Yes, it's something that significantly reduces the value of their merge proposal, and that they generally have the ability to correct.

> - I don't really understand the user story by which someone would try
> to merge to or from an empty branch

One is that the user proposes a merge into the wrong branch. Another is that they register the branch and forget to push it.

> - it seems more useful to tell them about it at the time they are
> proposing the merge rather than some time later

It is, but because we are not generating the diff at the instant the user requests it, there are race conditions.

> - if we are going to tell them about it, we ought to say which branch

These messages refer to the merge proposal, so they do refer to the branch indirectly. It would be an improvement to refer to them explicitly.

> and what they are expected to do about it

That would be an improvement, sure. I don't think the fact that the message can be improved is a good argument for removing it.

> - won't the problem be pretty obvious when they look at the mp page?

It shouldn't be their responsibility to check the page to ensure the diff was correctly generated. People sometimes don't check it until after reviews have started.

> If we didn't send mail about it, I doubt it would be a high bug.

It would be a regression, and regressions are automatically critical. So yes, it wouldn't be high :-)

>> The bug is #850974: No indication when a job resulted in a user error
>
> I would never block adding
> logging to wait for tests, but of course I don't decide lp's review
> policy.

When I fix a bug, I add a test to make sure that it does not regress, unless that's unreasonably difficult. I don't think that's the case here. In fact, TestCase.expectedLog() should make it pretty easy.

[Martin Pool (mbp)]

> It would be a regression, and regressions are automatically critical. So yes, it wouldn't be high :-)

I think lp's definition of critical is screwy but that's beside the point.

What I meant was: if we had never sent mail about attempts to merge empty branches, I doubt people would be queuing up to ask that we should, in the same way they are repeatedly asking us to stop sending pointless mail.

But, since the empty branch error isn't what bug 612171 and dupes complain about, I will update this branch to treat the pending writes case as a non-user error, and then leave the empty branch cases alone.

[Martin Pool (mbp)]

How about something like this? (The tests don't pass yet.)

=== modified file 'lib/lp/code/model/branchmergeproposaljob.py'
--- lib/lp/code/model/branchmergeproposaljob.py 2011-10-13 09:56:53 +0000
+++ lib/lp/code/model/branchmergeproposaljob.py 2011-10-18 07:58:02 +0000
@@ -332,6 +332,15 @@
     """Raised if the the preview diff is not ready to run."""

+class BranchHasPendingWrites(Exception):
+ """Raised if the branch can't be processed because a write is pending.
+
+ In this case the operation can usually be retried in a while.
+
+ See bug 612171.
+ """
+
+
 class UpdatePreviewDiffJob(BranchMergeProposalJobDerived):
     """A job to update the preview diff for a branch merge proposal.

@@ -346,6 +355,16 @@

     user_error_types = (UpdatePreviewDiffNotReady, )

+ retry_error_types = [BranchHasPendingWrites]
+
+ @classmethod
+ def create(cls, bmp):
+ """See `IMergeProposalCreationJob`."""
+ job = BranchMergeProposalJob(
+ bmp, cls.class_job_type, {})
+ job.max_retries = 20
+ return cls(job)
+
     def checkReady(self):
         """Is this job ready to run?"""
         bmp = self.branch_merge_proposal
@@ -356,8 +375,8 @@
             raise UpdatePreviewDiffNotReady(
                 'The target branch has no revisions.')
         if bmp.source_branch.pending_writes:
- raise UpdatePreviewDiffNotReady(
- 'The source branch has pending writes.')
+ raise BranchHasPendingWrites(
+ 'The source branch has pending writes')

     @staticmethod
     @contextlib.contextmanager
@@ -386,11 +405,8 @@

     def getErrorRecipients(self):
         """Return a list of email-ids to notify about user errors."""
- # All these failures are either obvious user errors in the web ui (eg
- # nothing in the branch), or Launchpad internal errors (eg the branch
- # is being written to). See bug 612171. Either way, the user can't
- # be anything but annoyed by mail about it. -- mbp 2011-10-13
- return []
+ registrant = self.branch_merge_proposal.registrant
+ return format_address_for_person(registrant)

 class CreateMergeProposalJob(BaseRunnableJob):

[Aaron Bentley (abentley)]

Thanks, Martin, that looks great. Exceptions should go in stable/lib/lp/code/errors.py (I don't know how I missed that with UpdatePreviewDiffNotReady).

[Martin Pool (mbp)]

I think this now passes all its tests, but I'm being bitten by bug 871596 so I'm not sure. I'll try it on ec2.

I don't understand the comment on this test: specifically how it is checking jobs that have been waiting for a long period of time:

    def test_run_branches_not_ready(self):
        # If the job has been waiting for a significant period of time (15
        # minutes for now), we run the job anyway. The checkReady method
        # then raises and this is caught as a user error by the job system,
        # and as such sends an email to the error recipients, which for this
        # job is the merge proposal registrant.
        eric = self.factory.makePerson(name='eric', <email address hidden>')
        bmp = self.factory.makeBranchMergeProposal(registrant=eric)
        job = UpdatePreviewDiffJob.create(bmp)
        pop_notifications()
        JobRunner([job]).runAll()
        [email] = pop_notifications()
        self.assertEqual('Eric <email address hidden>', email['to'])
        self.assertEqual(
            'Launchpad error while generating the diff for a merge proposal',
            email['subject'])
        self.assertEqual(
            'Launchpad encountered an error during the following operation: '
            'generating the diff for a merge proposal. '
            'The source branch has no revisions.',
            email.get_payload(decode=True))

[Martin Pool (mbp)]

This does pass its tests in its current form.

I feel there ought to be a (group of) tests that say something like:

 A bmpdj on a branch with pending writes does not generate a mail to the user
 The job is retried several times
 If the branch never gets up to date the job fails and logs an oops

Perhaps testing that it actually is retried would be out of scope and it's enough to check that we are communicating the right thing to the job infrastructure:

 A bmpdj on a branch with pending writes doesn't emit mail, doesn't error, and does ask to be retried.

but this seems to be somewhat covered already.

Why do we actually care about pending writes, anyhow? bzr ought to be fairly happy reading from an in-use repository.

[Aaron Bentley (abentley)]

This looks very nice. Since it fixes a bug, it should provide a test to ensure the bug stays fixed, i.e. that a pending write does not generate an emeasily ail.

Was providing retry_error_types as a list rather than a tuple deliberate? Given that the main difference between lists and tuples is that lists are mutable, are you intending the class variable to be mutated? Since that would affect all instances of the class, I think that could be confusing.

We care about pending writes because we want the diffs to be in sync with information displayed on the branch page.

If we generate a diff using the last_scanned_id, the diff will be soon be stale, and if the user deleted the relevant revision, the diff will fail to generate. We would also want to schedule a new diff to be generated once the scan completes.

If we generate a diff using an un-scanned last_mirrored id, it will be newer than the other information we display about the branch, and Launchpad could get upset that we ask it to display information about the revision, when the revision hasn't been scanned yet.

review: Needs Fixing

[Aaron Bentley (abentley)]

Errr, "i.e. that a pending write does not generate an email."

[Martin Pool (mbp)]

> This looks very nice. Since it fixes a bug, it should provide a test to
> ensure the bug stays fixed, i.e. that a pending write does not generate an
> emeasily ail.
>
> Was providing retry_error_types as a list rather than a tuple deliberate?
> Given that the main difference between lists and tuples is that lists are
> mutable, are you intending the class variable to be mutated? Since that would
> affect all instances of the class, I think that could be confusing.

It was intentional. I think there is a semantic difference which is that lists convey there can be any arbitrary number of elements and all the elements are treated identically, which is the case here. I think tuples are generally more important when the structure is more like a mathematical vector with different positions having different meanings or dimensions. I don't feel that getting protection against "accidental" mutation is important here because there are so many other ways that can be broken in Python, most obviously by just assigning to the attribute on either the instance or the class.

But, I don't really care, if Launchpad style or consistency wants a tuple I'll change it.

> We care about pending writes because we want the diffs to be in sync with
> information displayed on the branch page.
>
> If we generate a diff using the last_scanned_id, the diff will be soon be
> stale, and if the user deleted the relevant revision, the diff will fail to
> generate. We would also want to schedule a new diff to be generated once the
> scan completes.
>
> If we generate a diff using an un-scanned last_mirrored id, it will be newer
> than the other information we display about the branch, and Launchpad could
> get upset that we ask it to display information about the revision, when the
> revision hasn't been scanned yet.

OK, thanks for explaining that. That confirms Launchpad should just cope with it, certainly without complaining to the user. It seems like we can get quite similar cases if the user just pushes immediately after the diff job starts, rather than just before.

[Aaron Bentley (abentley)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 11-10-30 08:49 PM, Martin Pool wrote:
>> Was providing retry_error_types as a list rather than a tuple
>> deliberate? Given that the main difference between lists and
>> tuples is that lists are mutable, are you intending the class
>> variable to be mutated? Since that would affect all instances of
>> the class, I think that could be confusing.
>
> It was intentional. I think there is a semantic difference which
> is that lists convey there can be any arbitrary number of elements
> and all the elements are treated identically, which is the case
> here. I think tuples are generally more important when the
> structure is more like a mathematical vector with different
> positions having different meanings or dimensions.

The meaning you give to tuples is not consistent with the way tuples
are used in except clauses. Except clauses use a tuple to specify a
sequence of fixed but arbitrary length, in which all elements are
treated the same. The retry_error_types member is that portion of an
except clause, extracted to a member variable. isinstance has the
same semantics. So I think a tuple conforms to Python style, and a
list varies from it.

> I don't feel that getting protection against "accidental" mutation
> is important here because there are so many other ways that can be
> broken in Python, most obviously by just assigning to the attribute
> on either the instance or the class.

Python usually assumes that we're consenting adults, so there's very
little you can't do, if you try.

There's a big difference between "self.retry_error_types.append" and
"self.retry_error_types = self.retry_error_types +". The second will
affect only the instance, while the first will affect all instances.
You can affect all instances, if you want, but you have to spell that out.

> But, I don't really care, if Launchpad style or consistency wants a
> tuple I'll change it.

Please do, and consider that it's consistency with Python, as well as
with Launchpad.

Aaron
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk6uE2wACgkQ0F+nu1YWqI36MQCfelBM65Tl8SU6HrKro5+8tnXs
tVAAniGZHw1CpL2eA+U8wjaSLr0RFYCE
=ag6f
-----END PGP SIGNATURE-----

[Martin Pool (mbp)]

On 31 October 2011 14:19, Aaron Bentley <email address hidden> wrote:
> The meaning you give to tuples is not consistent with the way tuples
> are used in except clauses.  Except clauses use a tuple to specify a
> sequence of fixed but arbitrary length, in which all elements are
> treated the same.  The retry_error_types member is that portion of an
> except clause, extracted to a member variable.   isinstance has the
> same semantics.  So I think a tuple conforms to Python style, and a
> list varies from it.

One interesting thing here is that Python accepts

  except [IndexError, ValueError], e:

but it won't actually match them: I guess it may be looking for
old-style exceptions that raised a List or something. So I should
definitely fix that, and it's apparently not being tested enough.

>> I don't feel that getting protection against "accidental" mutation
>> is important here because there are so many other ways that can be
>> broken in Python, most obviously by just assigning to the attribute
>> on either the instance or the class.
>
> Python usually assumes that we're consenting adults, so there's very
> little you can't do, if you try.
>
> There's a big difference between "self.retry_error_types.append" and
> "self.retry_error_types = self.retry_error_types +".  The second will
> affect only the instance, while the first will affect all instances.
> You can affect all instances, if you want, but you have to spell that out.

I realize that.

[Martin Pool (mbp)]

OK, thanks for your patient reviews, here's another update:

 * add a test that the job wants to retry on pending writes and that no mail is sent
 * fix up the tuple thing
 * simplify (or maybe correct) the code that says the job can be retried

Happily the test does fail if retry_error_types is not a tuple.

=== modified file 'lib/lp/code/errors.py'
--- lib/lp/code/errors.py	2011-08-24 13:09:29 +0000
+++ lib/lp/code/errors.py	2011-11-02 03:08:30 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Errors used in the lp/code modules."""
@@ -15,6 +15,7 @@
     'BranchCreatorNotMemberOfOwnerTeam',
     'BranchCreatorNotOwner',
     'BranchExists',
+    'BranchHasPendingWrites',
     'BranchTargetError',
     'BranchTypeError',
     'BuildAlreadyPending',
@@ -39,6 +40,7 @@
     'TooManyBuilds',
     'TooNewRecipeFormat',
     'UnknownBranchTypeError',
+    'UpdatePreviewDiffNotReady',
     'UpgradePending',
     'UserHasExistingReview',
     'UserNotBranchReviewer',
@@ -92,6 +94,15 @@
         BranchCreationException.__init__(self, message)
 
 
+class BranchHasPendingWrites(Exception):
+    """Raised if the branch can't be processed because a write is pending.
+
+    In this case the operation can usually be retried in a while.
+
+    See bug 612171.
+    """
+
+
 class BranchTargetError(Exception):
     """Raised when there is an error determining a branch target."""
 
@@ -284,6 +295,10 @@
     """The requested review is not in a pending state."""
 
 
+class UpdatePreviewDiffNotReady(Exception):
+    """Raised if the the preview diff is not ready to run."""
+
+
 class UserHasExistingReview(Exception):
     """The user has an existing review."""
 

=== modified file 'lib/lp/code/model/branchmergeproposaljob.py'
--- lib/lp/code/model/branchmergeproposaljob.py	2011-09-26 20:00:50 +0000
+++ lib/lp/code/model/branchmergeproposaljob.py	2011-11-02 03:08:30 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009, 2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2009, 2010, 2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 
@@ -72,6 +72,10 @@
     )
 from lp.code.adapters.branch import BranchMergeProposalDelta
 from lp.code.enums import BranchType
+from lp.code.errors import (
+    BranchHasPendingWrites,
+    UpdatePreviewDiffNotReady,
+    )
 from lp.code.interfaces.branchmergeproposal import (
     IBranchMergeProposalJob,
     IBranchMergeProposalJobSource,
@@ -328,10 +332,6 @@
              self.branch_merge_proposal.target_branch.bzr_identity))
 
 
-class UpdatePreviewDiffNotReady(Exception):
-    """Raised if the the preview diff is not ready to run."""
-
-
 class UpdatePreviewDiffJob(BranchMergeProposalJobDerived):
     """A job to update the preview diff for a branch merge proposal.
 
@@ -346,6 +346,10 @@
 
     user_error_types = (UpdatePreviewDiffNotReady, )
 
+    retry_error_types = (BranchHasPendingWrites, )
+
+    max_retries = 20
+
     def checkReady(self):
         """Is this job ready to run?"""
         bmp = self.branch_merge_proposal
@@ -356,8 +360,8 @@
             raise UpdatePreviewDiffNotReady(
                 'The target branch has no revisions.')
         if bmp.source_branch.pending_writes:
-            raise UpdatePreviewDiffNotReady(
-                'The source branch has pending writes.')
+            raise BranchHasPendingWrites(
+                'The source branch has pending writes')
 
     @staticmethod
     @contextlib.contextmanager
@@ -814,7 +818,7 @@
             if IUpdatePreviewDiffJob.providedBy(derived_job):
                 try:
                     derived_job.checkReady()
-                except UpdatePreviewDiffNotReady:
+                except (UpdatePreviewDiffNotReady, BranchHasPendingWrites):
                     # If the job was created under 15 minutes ago wait a bit.
                     minutes = (
                         config.codehosting.update_preview_diff_ready_timeout)

=== modified file 'lib/lp/code/model/tests/test_branchmergeproposaljobs.py'
--- lib/lp/code/model/tests/test_branchmergeproposaljobs.py	2011-09-26 20:00:50 +0000
+++ lib/lp/code/model/tests/test_branchmergeproposaljobs.py	2011-11-02 03:08:30 +0000
@@ -18,6 +18,11 @@
 from storm.store import Store
 import transaction
 from zope.component import getUtility
+from zope.security.proxy import removeSecurityProxy
+
+from testtools.matchers import (
+    Equals,
+    )
 
 from canonical.config import config
 from canonical.launchpad.webapp.testing import verifyObject
@@ -55,6 +60,7 @@
     DiffTestCase,
     )
 from lp.code.subscribers.branchmergeproposal import merge_proposal_modified
+from lp.services.job.interfaces.job import JobStatus
 from lp.services.job.model.job import Job
 from lp.services.job.runner import JobRunner
 from lp.services.osutils import override_environ
@@ -231,7 +237,8 @@
         self.assertEqual(
             ["preview_diff"], bmp_object_events[0].edited_fields)
 
-    def test_run_branches_not_ready(self):
+    def test_run_branches_empty(self):
+        """If the branches are empty, we tell the user."""
         # If the job has been waiting for a significant period of time (15
         # minutes for now), we run the job anyway.  The checkReady method
         # then raises and this is caught as a user error by the job system,
@@ -253,6 +260,25 @@
             'The source branch has no revisions.',
             email.get_payload(decode=True))
 
+    def test_run_branches_pending_writes(self):
+        """If the branches are being written, we retry but don't complain."""
+        eric = self.factory.makePerson(name='eric', email='[e-mail]')
+        bmp = self.factory.makeBranchMergeProposal(registrant=eric)
+        self.factory.makeRevisionsForBranch(bmp.source_branch, count=1)
+        self.factory.makeRevisionsForBranch(bmp.target_branch, count=1)
+        # Kludge a branch being a bit out of date in a way that will make
+        # pending_writes true, without anything else failing.
+        removeSecurityProxy(bmp.source_branch).last_mirrored_id = \
+            self.factory.getUniqueString()
+        job = UpdatePreviewDiffJob.create(bmp)
+        # pop_notifications()
+        JobRunner([job]).runAll()
+        emails = pop_notifications()
+        self.assertThat(emails, Equals([]))
+        self.assertThat(job.status, Equals(JobStatus.WAITING))
+        self.assertThat(job.attempt_count, Equals(1))
+        self.assertThat(job.max_retries, Equals(20))
+
     def test_10_minute_lease(self):
         self.useBzrBranches(direct_database=True)
         bmp = create_example_merge(self)[0]

=== modified file 'lib/lp/services/job/runner.py'
--- lib/lp/services/job/runner.py	2011-10-25 04:15:06 +0000
+++ lib/lp/services/job/runner.py	2011-11-02 03:08:30 +0000
@@ -258,6 +258,8 @@
                     self.logger.debug('Running %r', job)
                     self.runJob(job)
                 except job.user_error_types, e:
+                    self.logger.info('Job %r failed with user error %r' %
+                        (job, e))
                     job.notifyUserError(e)
                 except Exception:
                     info = sys.exc_info()