Need doomed transaction API

We need to add some more debugging information to the OOPS reports:

- Ensure the connection doesn't change by logging id(connection_wrapper)
- Log database commits and rollbacks

Recent OOPSes at http://shipit.ubuntu.com/myrequest

OOPS-152B1188
OOPS-152B1199

OOPS-155D710 at: https://launchpad.net/distros/ubuntu/dapper/+source/ktorrent/+pots/ktorrent/lv/+translate

OOPS-156A670 at:
https://launchpad.net/+login

OOPS-170D339 Recent OOPS with the Connection ID.

I don't think OOPS-170D339 has the problem. Although the connection id in the traceback is different from that in the statement log, I think this is due to the bug where connection id was used for the statement log, but the cursor id used elsewhere.

This bug has now been fixed in production.

The connection ids in the statement log in this oops report are all the same connection.

Well, if that's the case, then I think we have a more complicated problem than I initially predicted, because that log says:

/*46912674137040*/ INSERT INTO POFile (id...) VALUES (169860, ...)

and then

/*46912674137040*/ SELECT NEXTVAL('POMsgSet_id_seq')
/*46912674137040*/ INSERT INTO POMsgSet (id, ... pofile) VALUES (71049052, ... 169860)

successfully, and then at the end

/*46912674137040*/ SELECT NEXTVAL('POMsgSet_id_seq')
/*46912674137040*/ INSERT INTO POMsgSet (id, ... pofile) VALUES (71049059, ... 169860)

Which, if the IDs make sense, means that we inserted 7 POMsgSets before the last one failed. So some other hypotheses that might explain this problem:

  - Somewhere along the line we are doing an ABORT/ROLLBACK which causes all the work before the POMsgSet insertion to be invalidated. The sequence stays sequential because sequences are transaction independent (right?)
  - The message we are getting is lying to us. In this case it is:

    DETAIL: Key (pofile)=(169860) is not present in table "pofile".

I'll look at the log a bit more.

There is a rollback. Look at statement 193.

Now we just need to add traceback recording to rollbacks in the logging, and we'll be able to see where the rollback comes from.

I knew it! I looked at the log more carefully, and guess what? When inserting the POMsgSet before the one that fails, we do:

/*46912674137040*/ INSERT INTO POMsgSet (id, ... pofile) VALUES (71049058, ... 169860)
/*46912674137040*/ SELECT ... FROM POMsgSet WHERE id = 71049058
/*46912674137040*/ ROLLBACK

I'm trying to figure out what triggered this rollback. The interesting part is that after the rollback a bunch of queries is reissued, but not the query in which we insert the pofile. So it appears we are holding references over this rollback.

<kiko> SteveA, were rollbacks not being logged before, then?
<kiko> hmmm
<SteveA> it was something stu added after he and i discussed the issue on voip
<SteveA> we guessed that the problem was due to either
<SteveA> 1. spurious rollbacks
<SteveA> 2. more than one connection
<SteveA> so, the logging code was specifically designed to find out if it was one of those possibilities, or something else

Both GeneralForm and SQLObjectEditView issue abort()s internally when WidgetsError is issued. It is somewhat surprising to me that the loop which validates widgets is not done before actually trying to modify data, though I can understand why that may be so (widget validation may depend on previous modifications done as part of the transaction).

I think the rollback is caused by the form processing machinery. GeneralForm, and the various EditForm and FormView variants all do an abort() if there is a WidgetError.

This is dangerous. I think we implicitly start a new transaction after an abort(). What we should be doing is "dooming" the transaction, so that by the time we get to the end of publication, the publication knows it must not commit the transaction, but instead will always abort it, regardless.

Sometime ago, I proposed a doom() method for the transaction manager API in Zope. We can do an equivalent thing either by extending the TM api or hooking into the publisher.

We should also log the stack trace when we have ROLLBACKS in OOPS reports, so we can see exactly where these are occuring.

Steve Alexander wrote:
> I think the rollback is caused by the form processing machinery.
> GeneralForm, and the various EditForm and FormView variants all do an
> abort() if there is a WidgetError.
>
> This is dangerous. I think we implicitly start a new transaction after
> an abort(). What we should be doing is "dooming" the transaction, so
> that by the time we get to the end of publication, the publication knows
> it must not commit the transaction, but instead will always abort it,
> regardless.
>
> Sometime ago, I proposed a doom() method for the transaction manager API
> in Zope. We can do an equivalent thing either by extending the TM api
> or hooking into the publisher.

Is it obvious what the abort() in EditForm is attempting to do? If it is to
ensure that the transaction is never committed (by aborting the transactions
and deliberately not starting a fresh one), then the bug would be in the
psycopgda because it will automatically start a fresh transaction.

If this is what the abort() is supposed to achieve, I think that doom()
would be good as I can imagine other code that hooks into the transactional
system such as the email delivery subsystem will have the same behaviour.
doom() would ensure that commit() is a noop or raises an exception I assume?

--
Stuart Bishop <email address hidden> http://www.canonical.com/
Canonical Ltd. http://www.ubuntu.com/

Committing a doomed transaction would raise a specific DoomedTransaction exception. The publisher would catch this exception and explicitly abort instead.

Recent OOPS-194C656

Matsubara, that OOPS appears to be related to a different problem (it reports a duplicated key, and there are no UPDATEs in the SQL log AFAICS)

On Fri, Jul 14, 2006 at 04:39:17PM -0000, Christian Reis wrote:
> Matsubara, that OOPS appears to be related to a different problem (it
> reports a duplicated key, and there are no UPDATEs in the SQL log
> AFAICS)

Indeed, you are right. I chatted with Carlos and he confirmed that this is
a race condition on that page. I reported bug 53018 and appended all occurances
of that oops there.

>
--
Diogo M. Matsubara

Steve - should you have this for the doomed transactions?

This was added to Zope3 (see bug 98382). We should try to backport this change. (Upgrading to a recent Zope3 is bug 145746).

Running Zope 3.4 with doom().

We still need to use it in GeneralForm, as it is still calling transaction.abort() when it shouldn't be.

As is SQLObjectEditView.

Isn't the proper fix to get rid of GeneralFormView and SQLObjectEditView? That means 10 views for the former and 8 for the latter.

I have a branch, which I started before the epic and didn't have time to
finish, that gets rid of SQLObjectEditView. I'll try to finish it this
week, and GFV is certainly the next one on my radar.