Failure receiving payment capture notification

[Michael Nelson]

Since bug 656533 was released, we are not seeing the huge number of payment_notification errors for other statuses, but we are still seeing oopses during CAPTURE notifications.

There was one example of this at 2010-11-30T12:53:59.881324+00:00
/rangpur/sca/www-oops/2010-11-30/46439-1795rangpur17.oops

There is no corresponding traceback in the webapp log at this time :/
{{{
2010-11-30 12:16:48,625 - sca.models - INFO - subscription (id: 2233) by https://login.ubuntu.com/+id/******** for Vendetta Online ($0.00): New -> PaymentNotificationReceived: Skipping payment process for free app.
2010-11-30 12:59:52,960 - sca.models - INFO - subscription (id: 2240) by https://login.ubuntu.com/+id/******* for Vendetta Online ($0.00): New -> PaymentNotificationReceived: Skipping payment process for free app.
}}}

[Michael Nelson (michael.nelson)]

Although it doesn't affect the purchase process (as we don't trust the insecure notifications received from pay and instead query pay via the API), we are still seeing 500 errors when receiving the captured payment notification, like:

https://admin.isd.canonical.com/oops/?oopsid=1933rangpur3

so I've put this back to confirmed and may take a quick look.

[Michael Nelson (michael.nelson)]

Here's a dump of what I found out in case anyone else has ideas:

   * There are plenty of subscriptions where the CAPTURED notification is handled without error in the logs, so either something about the state of the subscription or the server different.
   * I can even post to the notification url given in the above oops and it works just fine https://pastebin.canonical.com/48866/
   * The fact that there is no log message before the oops suggests that we're not getting to the
 subscription._set_state() call.

So I'm left thinking something temporal (a transaction rollback on the view? or something related to the timestamp used during _set_state?) is causing these few remaining notification 500s.

Of course, if we had tracebacks in the related oopses, things would be a lot simpler. At first I thought it was to do with the:
    2011-04-17 14:37:46,144 - root - ERROR - Error when dumping OOPS 1933rangpur3
messages we were seeing in the log, but then, it's hard to tell, as we currently have r54 installed on the production server [1], and it was r56 that stopped this (incorrect) error message being printed for each oops [2].

[1] https://pastebin.canonical.com/48862/
[2] https://pastebin.canonical.com/48863/