Bug #7293 for DBD-SQLite: v1.02 Commit Problem

Sun Aug 08 19:48:18 2004 Guest - Ticket created

Subject:

v1.02 Commit Problem

Back again, sorry. I'm seeing a problem with v 1.02 and journaling. The perl program, popfile, runs as a daemon in the background. After upgrading from v .31 to v 1.02 and converting the database, I see the following errors; POPFile Engine v0.21.1 running DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 540 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1828, <GEN3> line 5. DBD::SQLite::st execute failed: SQL logic error or missing database(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2912, <$reader> line 3. DBD::SQLite::db begin_work failed: Already in a transaction at /usr/local/bin/popfile/Classifier/Bayes.pm line 1808, <GEN15> line 5. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 203 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1828, <GEN15> line 5. DBD::SQLite::st execute failed: SQL logic error or missing database(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2912, <$reader> line 3. DBD::SQLite::db begin_work failed: Already in a transaction at /usr/local/bin/popfile/Classifier/Bayes.pm line 1808, <GEN49> line 5. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 203 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1828, <GEN49> line 5. DBD::SQLite::st execute failed: SQL logic error or missing database(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2912, <$reader> line 3. The -journal file never gets committed. The popfile perl program runs fine on v .31 and I'm stumped on the 'SQL statements in progress' message that apparently is the cause of all the rest of the errors. Can you point me in the right direction? Scott

Sun Aug 08 20:51:14 2004 Guest - Correspondence added

[guest - Sun Aug 8 19:48:18 2004]: Switched to sqlite 3.04 just released. Now the error changes to POPFile Engine v0.21.1 running DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 540 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1289. DBD::SQLite::db begin_work failed: Already in a transaction at /usr/local/bin/popfile/Classifier/Bayes.pm line 1260. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 203 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1289. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 371 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2916. helphand:/var/log/popfile # So it looks like it is probably some type of logic error in popfile not complying with the new locking strategy of SQLite3. Will take this to the SQLite forum since it doesn't appear to be a DBD::SQLite issue. Scott

Mon Aug 09 04:36:58 2004 matt [...] sergeant.org - Correspondence added

From:	Matt Sergeant <matt [...] sergeant.org>
Subject:	Re: [cpan #7293] v1.02 Commit Problem
Date:	Mon, 9 Aug 2004 09:31:07 +0100
To:	bug-DBD-SQLite [...] rt.cpan.org
RT-Send-Cc:

On 9 Aug 2004, at 01:51, Guest via RT wrote: Show quoted text

> So it looks like it is probably some type of logic error in popfile not > complying with the new locking strategy of SQLite3. Will take this to > the SQLite forum since it doesn't appear to be a DBD::SQLite issue.

Actually I think this *is* a DBD::SQLite issue, and has to do with slightly changed behaviour from sqlite not being handled right by DBD::SQLite. I believe it could be fixed in DBD::SQLite's CVS though. (see http://axkit.org/cvs.xml if you want access to the repo).

Mon Aug 09 08:39:18 2004 Guest - Correspondence added

From:

helphand [...] pacbell.net

[matt@sergeant.org - Mon Aug 9 04:36:58 2004]: Show quoted text

> > Actually I think this *is* a DBD::SQLite issue, and has to do with > slightly changed behaviour from sqlite not being handled right by > DBD::SQLite. I believe it could be fixed in DBD::SQLite's CVS though. > (see http://axkit.org/cvs.xml if you want access to the repo). >

Hi Matt, I pretty much nailed this down as a problem in the application logic. Here's a copy of a post to the SQLite Mailing list recapping what I found. Those 'dangling SELECTS' and a case of nested transactions were causing the errors, once I fixed those in the application, everything worked fine. Scott POST TO SQLITE LIST Solved! Just to close the loop on this for the benefit of any other DBD::SQLite users who may be trying to upgrade from v 0.31 to v 1.x.x. Watch out for cases where your former working code left unfinished SELECT statements since under SQLite v 3.x.x they will hold locks on the database causing subsequent SQL calls to fail. In my case, the code had several instances where we knew there could only be one result to the query so we basically grabbed that result and moved on, e.g., $sth = $dbh->prepare($statement); $sth->execute; return $sth->fetchrow_arrayref; This left the SELECT statement in a not finalized state and the dataset locked. Worked fine under SQLite 2.8.xx but it fails under 3.x.x. We had to change the code to, $sth = $dbh->prepare($statement); $sth->execute; my $result= $sth->fetchrow_arrayref; $sth->finish(); return $result; to solve the problem by finalizing the SELECT so the lock came off the database. Hope that helps someone else from banging their head against the wall searching for the problem <g>. Again, a big thanks to D. Richard Hipp for pointing me in the right direction!

Mon Aug 09 13:01:51 2004 matt [...] sergeant.org - Correspondence added

Date:	Mon, 9 Aug 2004 18:02:46 +0100 (BST)
From:	Matt Sergeant <matt [...] sergeant.org>
To:	Guest via RT <bug-DBD-SQLite [...] rt.cpan.org>
Subject:	Re: [cpan #7293] v1.02 Commit Problem
RT-Send-Cc:

On Mon, 9 Aug 2004, Guest via RT wrote: Show quoted text

> I pretty much nailed this down as a problem in the application logic. > Here's a copy of a post to the SQLite Mailing list recapping what I > found. Those 'dangling SELECTS' and a case of nested transactions were > causing the errors, once I fixed those in the application, everything > worked fine.

I still think this is a bug in the driver though. I've now uploaded 1.03 to CPAN - can you check if this is fixed there? You should never have to call finish() manually. Matt.

Mon Aug 09 21:01:20 2004 Guest - Correspondence added

[matt@sergeant.org - Mon Aug 9 13:01:51 2004]: Show quoted text

> > I still think this is a bug in the driver though. I've now uploaded > 1.03 > to CPAN - can you check if this is fixed there? You should never have > to > call finish() manually. >

OK, I downloaded 1.03 from CPAN, compiled, tested and installed it without any issues at all. I then ran popfile with the changes in place (to make sure all SELECT's were finished) and it ran fine, no errors, warnings, or strange messages. I then removed the changes from popfile to put it back to the way it was with version .31 (dangling 'SELECTS') and tried running again. I got the lock messages shown below, the -journal file showed up and remained on disk so it looks like your change did not work (assuming the intent was to allow unfinished selects) :( Scott DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 547 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1288. DBD::SQLite::db begin_work failed: Already in a transaction at /usr/local/bin/popfile/Classifier/Bayes.pm line 1259. DBD::SQLite::db commit failed: cannot commit transaction - SQL statements in progress(1) at dbdimp.c line 214 at /usr/local/bin/popfile/Classifier/Bayes.pm line 1288. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922. DBD::SQLite::st execute failed: database table is locked(1) at dbdimp.c line 383 at /usr/local/bin/popfile/Classifier/Bayes.pm line 2922.

Wed Aug 11 16:40:27 2004 msergeant [...] cpan.org - Correspondence added

OK, I can see how I have to fix this now. With 0.3x I did the sqlite internal "fetch" (called "step" there) before DBI's fetch got called, so by the time you call the last "fetch" in DBI the last row has already gone past, so you know to finalize the statement. I changed this in 1.x (sqlite3) because I thought I could, but I can't - I have to revert to the old way. I'll fix it back again, and upload 1.04 as soon as I get the time to do it.

Wed Aug 11 16:40:28 2004 msergeant [...] cpan.org - Status changed from 'new' to 'open'

Wed Aug 11 21:01:37 2004 Guest - Correspondence added

From:

helphand [...] pacbell.net

[MSERGEANT - Wed Aug 11 16:40:27 2004]: Show quoted text

> > I'll fix it back again, and upload 1.04 as soon as I get the time to > do it.

OK, I'll watch for it. I also found another possible issue. There's a behavior change between v .31 and earlier and v 1.00 and later. To demonstrate, the following small program can be used. use DBI(); use strict; my $dbh=DBI->connect("DBI:SQLite:dbname=test.db", "gluser","pgarules", {'RaiseError'=>1}); my $sqlversion=$DBD::SQLite::VERSION; my $dbiversion=$DBI::VERSION; print "Running DBI $dbiversion and DBD::SQLite $sqlversion\n"; my @tables = $dbh->tables(); foreach my $table (@tables) { print "$table \n"; } $dbh->disconnect(); exit(0); When run from .31 or earlier, the following results; Running DBI 1.37 and DBD::SQLite 0.28 sqlite_master sqlite_temp_master When run from 1.03, we get these results; Running DBI 1.43 and DBD::SQLite 1.03 "sqlite_master" "sqlite_temp_master" As you can see, the table names are now returned in double quotes. Scott

Sun Aug 29 05:48:24 2004 msergeant [...] cpan.org - Status changed from 'open' to 'resolved'