Bug #107159 for DBIx-Class: Bug: Spurious rollback when commit fails

Fri Sep 18 04:38:40 2015 cpt [...] novozymes.com - Ticket created

Subject:	Bug: Spurious rollback when commit fails
Date:	Fri, 18 Sep 2015 10:38:17 +0200
To:	<bug-DBIx-Class [...] rt.cpan.org>
From:	Christopher Travers <cpt [...] novozymes.com>

This is reproduced in DBIx::Class from Ubuntu 14.04, but the code didn't look that different for most recent so I figured it was almost certain to exist there too. Scenario: Initially deferred constraints and PostgreSQL violated by a $schema->txn_do() transaction. This would be common in cases where you might have a circular foreign key constraint and so you check one at insert time and the other at commit time (in our case, it is slightly different -- it is a custom constraint trigger but one which enforces something conceptually similar). What happens: rollback ineffective with AutoCommit enabled at DBIx::Class::Storage::DBI::_exec_txn_rollback(/usr/share/perl5/DBIx/Class/Storage/DBI.pm line 1552, <DATA>:751) at DBIx::Class::Storage::txn_rollback(/usr/share/perl5/DBIx/Class/Storage.pm:255) at DBIx::Class::Storage::DBI::txn_rollback(/usr/share/perl5/DBIx/Class/Storage/DBI.pm:1538) at <eval>(/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:174) at DBIx::Class::Storage::BlockRunner::__ANON__(/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:174) at Context::Preserve::preserve_context(/usr/share/perl5/Context/Preserve.pm:27) at DBIx::Class::Storage::BlockRunner::_run(/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:221) at DBIx::Class::Storage::BlockRunner::run(/usr/share/perl5/DBIx/Class/Storage/BlockRunner.pm:112) at DBIx::Class::Storage::txn_do(/usr/share/perl5/DBIx/Class/Storage.pm:189) at DBIx::Class::Storage::DBI::txn_do(/usr/share/perl5/DBIx/Class/Storage/DBI.pm:816) at DBIx::Class::Schema::txn_do(/usr/share/perl5/DBIx/Class/Schema.pm:656) .... DBIC_TRACE shows that the commit that raised the error was followed by a rollback. There was no additional begin transaction statement, and tracing the code via the call stack shows that the commit occurs and the exception is handled properly. Impact: This is primarily an issue of clarity of the logs. An error like this could indicates a transaction was committed twice but it doesn't say enough by itself that one can quickly/easily determine that it was an exception on commit. This means that while the bug is itself harmless it can make it harder to spot harmful bugs in the log files, and that can eventually result in data loss (when combined with other bugs of course).

Fri Sep 18 04:46:53 2015 ribasushi [...] leporine.io - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Fri, 18 Sep 2015 10:46:38 +0200
To:	bug-DBIx-Class [...] rt.cpan.org
From:	Peter Rabbitson <ribasushi [...] cpan.org>

On 09/18/2015 10:38 AM, Christopher Travers via RT wrote: Show quoted text

> Fri Sep 18 04:38:40 2015: Request 107159 was acted upon. > Transaction: Ticket created by cpt@novozymes.com > Queue: DBIx-Class > Subject: Bug: Spurious rollback when commit fails > Broken in: (no value) > Severity: (no value) > Owner: Nobody > Requestors: cpt@novozymes.com > Status: new > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > > > > This is reproduced in DBIx::Class from Ubuntu 14.04

Could you please tell me the *exact* version you are running. "from Ubuntu 14.04" is too ambiguous for correct analysis. Show quoted text

> Scenario: Initially deferred constraints and PostgreSQL violated by a > $schema->txn_do() transaction.

Please show an example invocation of this ( ideally as an addition to this block: https://metacpan.org/source/RIBASUSHI/DBIx-Class-0.082820/t/72pg.t#L441-464, or at least as some sort of pseudocode ). The stacktrace while useful is not conductive to recreating the internal state of the various objects - this can be done only by executing a set of steps in an order you did. Show quoted text

> DBIC_TRACE shows that the commit that raised the error was followed by a > rollback. There was no additional begin transaction statement, and > tracing the code via the call stack shows that the commit occurs and the > exception is handled properly. > > Impact: This is primarily an issue of clarity of the logs.

This part isn't relevant. A commit followed by rollback is most definitely a defect and needs fixing. Please get more of the requested info to get this fixed.

Fri Sep 18 04:46:54 2015 The RT System itself - Status changed from 'new' to 'open'

Fri Sep 18 05:27:08 2015 cpt [...] novozymes.com - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Fri, 18 Sep 2015 11:26:53 +0200
To:	"bug-DBIx-Class [...] rt.cpan.org" <bug-DBIx-Class [...] rt.cpan.org>
From:	Christopher Travers <cpt [...] novozymes.com>

On 2015-09-18 10:46, Peter Rabbitson via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > > > On 09/18/2015 10:38 AM, Christopher Travers via RT wrote:

>> Fri Sep 18 04:38:40 2015: Request 107159 was acted upon. >> Transaction: Ticket created by cpt@novozymes.com >> Queue: DBIx-Class >> Subject: Bug: Spurious rollback when commit fails >> Broken in: (no value) >> Severity: (no value) >> Owner: Nobody >> Requestors: cpt@novozymes.com >> Status: new >> Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > >> >> >> This is reproduced in DBIx::Class from Ubuntu 14.04

> Could you please tell me the *exact* version you are running. "from > Ubuntu 14.04" is too ambiguous for correct analysis.

$ perl -MDBIx::Class -M5.010 -e 'say $DBIx::Class::VERSION' 0.08250 Show quoted text

>

>> Scenario: Initially deferred constraints and PostgreSQL violated by a >> $schema->txn_do() transaction.

> Please show an example invocation of this ( ideally as an addition to > this block: > https://metacpan.org/source/RIBASUSHI/DBIx-Class-0.082820/t/72pg.t#L441-464, > or at least as some sort of pseudocode ). The stacktrace while useful is > not conductive to recreating the internal state of the various objects -

REPRO SCENARIO: =============== In our db schema, we create a deferrable, by default deferred constraint trigger: CREATE CONSTRAINT TRIGGER artistid_deferred_not_null() RETURNS TRIGGER LANGUAGE PLPGSQL AS $$ BEGIN IF new.artistid IS NULL THEN RAISE EXCEPTION 'Bad Transaction'; END IF; RETURN new; END $$; CREATE CONSTRAINT TRIGGER artistid_eventually_not_null AFTER INSERT OR UPDATE ON cd FOR EACH ROW EXECUTE PROCEDURE artistid_deferred_not_null() DEFERRABLE INITIALLY DEFERRED; -- the critical part is this line This means that the trigger is fired, by default, at commit time, not at db insert or update time. If it fails, it raises an exception on the commit statement itself. Then in the Perl code the following would work: $schema->txn_do(sub { $cd = |$schema||->resultset(||'CD'||)->create({| |||||||cdid| |=> 999, ||year| |=> ||'2003'||, ||title| |=> ||'deferred FK cd'| |||}); # hmmmm where is the artist? oh ok let's assign to one after all. $cd->artistid(1); $cd->update(); # if you comment this out then, you get the warning. }); But if we comment out the $cd->update, it should fail and it does. But the problem is then that when the commit fails, the exception triggers a rollback then outside the transaction. This leads to a warning. Does this make sense? CODE TRACING I HAVE DONE THUS FAR ================================== What is happening in the code (via the stack trace): 1. Transaction is executed in a try block. In the catch we catch errors and assign them to a variable in an outer scope. 2. As we go through we check if we had an error and if so, roll back the transaction. However because the commit statement issued the transaction, there is no transaction to roll back. Hence DBI throws a warning..... I suspect the solution check the db handle as to whether it has begun work or not before issuing the roll back. Since the commit statement failed, we are both out of the transaction and with an exception which requires the commit statement itself to raise the exception.|

Fri Sep 18 05:53:38 2015 ribasushi [...] leporine.io - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Fri, 18 Sep 2015 11:53:23 +0200
To:	bug-DBIx-Class [...] rt.cpan.org
From:	Peter Rabbitson <ribasushi [...] cpan.org>

On 09/18/2015 11:27 AM, Christopher Travers via RT wrote: Show quoted text

> > $ perl -MDBIx::Class -M5.010 -e 'say $DBIx::Class::VERSION' > 0.08250 >

rabbit@Ahasver:~/devel/dbic$ git diff -w --stat v0.08250..v0.082820 -- lib/DBIx/Class/Storage.pm lib/DBIx/Class/Storage/DBI.pm lib/DBIx/Class/Storage/BlockRunner.pm lib/DBIx/Class/Storage.pm | 40 +++++----- lib/DBIx/Class/Storage/BlockRunner.pm | 135 +++++++++++++++++----------------- lib/DBIx/Class/Storage/DBI.pm | 669 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----------------------------------------------------------------------- 3 files changed, 470 insertions(+), 374 deletions(-) These are changes since 0.08250 in just the files which are directly related to transaction handling, with likely a lot more indirect changes. Before going further I need you to test with 0.082820 and report back whether the problem persists. The easiest way to do so is `cpanm --look DBIx::Class` and then add the resulting tempdir to @INC.

Tue Sep 22 04:00:56 2015 cpt [...] novozymes.com - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Tue, 22 Sep 2015 10:00:32 +0200
To:	"bug-DBIx-Class [...] rt.cpan.org" <bug-DBIx-Class [...] rt.cpan.org>
From:	Christopher Travers <cpt [...] novozymes.com>

On 2015-09-18 11:53, Peter Rabbitson via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > > > On 09/18/2015 11:27 AM, Christopher Travers via RT wrote:

>> $ perl -MDBIx::Class -M5.010 -e 'say $DBIx::Class::VERSION' >> 0.08250 >>

> rabbit@Ahasver:~/devel/dbic$ git diff -w --stat v0.08250..v0.082820 -- > lib/DBIx/Class/Storage.pm lib/DBIx/Class/Storage/DBI.pm > lib/DBIx/Class/Storage/BlockRunner.pm > lib/DBIx/Class/Storage.pm | 40 +++++----- > lib/DBIx/Class/Storage/BlockRunner.pm | 135 > +++++++++++++++++----------------- > lib/DBIx/Class/Storage/DBI.pm | 669 > ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----------------------------------------------------------------------- > 3 files changed, 470 insertions(+), 374 deletions(-) > > These are changes since 0.08250 in just the files which are directly > related to transaction handling, with likely a lot more indirect > changes. Before going further I need you to test with 0.082820 and > report back whether the problem persists. The easiest way to do so is > `cpanm --look DBIx::Class` and then add the resulting tempdir to @INC.

My reading of the code indicates this should occur. I will see what I can do about a test on it. I first ran into a much more serious version of this problem in 0.08196, btw (the commit is in a finally block there and therefore if the commit fails, $schema->txn_do() reports success). The fact that the problem is now fairly minor is a major improvement :-). Assuming I can reproduce, do you have a preferred fix? I would be happy to submit a patch since I suspect the actual fix is likely to be trivial. (I would probably check the transaction state on the db handle). Show quoted text

> >

Tue Sep 22 04:12:22 2015 ribasushi [...] leporine.io - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Tue, 22 Sep 2015 10:12:07 +0200
To:	bug-DBIx-Class [...] rt.cpan.org
From:	Peter Rabbitson <ribasushi [...] cpan.org>

On 09/22/2015 10:00 AM, Christopher Travers via RT wrote: Show quoted text

> Queue: DBIx-Class > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > > > > > On 2015-09-18 11:53, Peter Rabbitson via RT wrote:

>> <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > >> >> On 09/18/2015 11:27 AM, Christopher Travers via RT wrote:

>>> $ perl -MDBIx::Class -M5.010 -e 'say $DBIx::Class::VERSION' >>> 0.08250 >>>

>> rabbit@Ahasver:~/devel/dbic$ git diff -w --stat v0.08250..v0.082820 -- >> lib/DBIx/Class/Storage.pm lib/DBIx/Class/Storage/DBI.pm >> lib/DBIx/Class/Storage/BlockRunner.pm >> lib/DBIx/Class/Storage.pm | 40 +++++----- >> lib/DBIx/Class/Storage/BlockRunner.pm | 135 >> +++++++++++++++++----------------- >> lib/DBIx/Class/Storage/DBI.pm | 669 >> ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----------------------------------------------------------------------- >> 3 files changed, 470 insertions(+), 374 deletions(-) >> >> These are changes since 0.08250 in just the files which are directly >> related to transaction handling, with likely a lot more indirect >> changes. Before going further I need you to test with 0.082820 and >> report back whether the problem persists. The easiest way to do so is >> `cpanm --look DBIx::Class` and then add the resulting tempdir to @INC.

> My reading of the code indicates this should occur. I will see what I > can do about a test on it. > > I first ran into a much more serious version of this problem in 0.08196, > btw (the commit is in a finally block there and therefore if the commit > fails, $schema->txn_do() reports success). The fact that the problem is > now fairly minor is a major improvement :-). > > Assuming I can reproduce, do you have a preferred fix?

I have not looked at it at all yet. Basically 95% of the work in fixing these issues is constructing the proper test case. Indeed you described one in almost complete detail, but it is still work to integrate it into the test suite, while testing with the current version is something you can do in less than a minute. I am not dropping this on the ground, but I am currently working on something unrelated, and don't want to lose steam/focus. Show quoted text

> I would be happy > to submit a patch since I suspect the actual fix is likely to be > trivial. (I would probably check the transaction state on the db handle).

The fix indeed will likely be trivial, but doing anything with the db handle is almost certainly a mistake. The underlying problem is a desync of the internal transaction depth counter, which can not be papered over by just deferring to "I will skip if it doesn't look right". The underlying reason for this desync needs to be found/fixed. In summary - I would be very happy if you look into this further, and beat me to a solution. But please be aware that a cosmetic fixup is not something I am willing to go forward with. We either fix it right, or don't fix it at all ;) Cheers!

Tue Nov 03 06:34:04 2015 ribasushi [...] leporine.io - Correspondence added

Issue has been reproduced, fix will be delayed a bit as the entire subsystem handling this is in the process of a rewrite. If the warnings are *really* annoying - please chime in, and some sort of middle-ground-to-be-thrown-away-workaround will be devised. Thanks for the report!

Tue Nov 03 06:34:08 2015 ribasushi [...] leporine.io - Taken

Tue Nov 03 07:49:39 2015 ribasushi [...] leporine.io - Correspondence added

On Tue Nov 03 12:34:04 2015, RIBASUSHI wrote: Show quoted text

> Issue has been reproduced, fix will be delayed a bit as the entire > subsystem handling this is in the process of a rewrite. > > If the warnings are *really* annoying - please chime in, and some sort > of middle-ground-to-be-thrown-away-workaround will be devised. >

After spending more time looking at this, I came up with what I believe is a safe workaround (but as the comment says - I am rather queasy about it): https://github.com/dbsrgits/dbix-class/commit/0bec44d5d7 This will be a part of the 0.082899_15 devrel in some days.

Tue Nov 03 07:49:47 2015 ribasushi [...] leporine.io - Status changed from 'open' to 'patched'

Wed Nov 04 06:54:42 2015 cpt [...] novozymes.com - Correspondence added

Subject:	Re: [rt.cpan.org #107159] Bug: Spurious rollback when commit fails
Date:	Wed, 4 Nov 2015 12:54:19 +0100
To:	"bug-DBIx-Class [...] rt.cpan.org" <bug-DBIx-Class [...] rt.cpan.org>
From:	Christopher Travers <cpt [...] novozymes.com>

On 2015-11-03 12:34, Peter Rabbitson via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=107159 > > > Issue has been reproduced, fix will be delayed a bit as the entire subsystem handling this is in the process of a rewrite. > > If the warnings are *really* annoying - please chime in, and some sort of middle-ground-to-be-thrown-away-workaround will be devised. > > Thanks for the report!

I have been thinking about your comment on the commit. I am not aware of any cases where the commit needs to be rolled back if it fails (one of the basic points in the database world is that commits are supposed to roll back if unsuccessful). A quick review suggests that SQLState may be standardized well enough to be useful at least at the class level here (i.e. first two characters matching). Best Wishes, Chris Travers

Mon Jun 20 08:32:54 2016 ribasushi [...] leporine.io - Correspondence added

On Wed Nov 04 12:54:42 2015, cpt@novozymes.com wrote: Show quoted text

> I am not aware of any cases where the commit needs to be rolled back > if > it fails (one of the basic points in the database world is that > commits > are supposed to roll back if unsuccessful).

You would be surprised how much "counterintuitive" stuff is out there: https://github.com/perl5-dbi/dbi/blob/1.635/DBI.pm#L4929-L4934 In any case: Despite my unease, the fix is now properly in the CPAN index. Sorry it took so long :/

Mon Jun 20 08:32:55 2016 ribasushi [...] leporine.io - Status changed from 'patched' to 'resolved'

Mon Jun 20 08:32:55 2016 ribasushi [...] leporine.io - Fixed in 0.082840 added