[sqlite] UPDATE silently failing
Table schema: CREATE TABLE cv (cv_s integer not null, cv_o blob not null, cv_t integer not null, primary key(cv_s, cv_o)); Prepared statement: UPDATE cv SET cv_t=? where cv_s=? and cv_o=?; Most of the time the row is updated as expected but in some rare cases we've seen this statement fail silently, as in: - the row exists - the row it is not updated - step returns SQLITE_OK - changes returns 0 We've only observed this on OS X so far, with both 3.8.7 and 3.8.11.1. The new value is always exactly the old value +1 when the statement fails. The db is accessed through the sqlite-jdbc java wrapper. It is opened in WAL mode with exclusive locking. Multiple threads are sharing the connection but access is serialized by locks both in sqlite-jdbc and the application itself. sqlite was built with clang on OS X Yosemite from the amalgamation and with the following compiler flags: -O2 -fPIC -mmacosx-version-min=10.6 -fvisibility=hidden -DSQLITE_ENABLE_COLUMN_METADATA -DSQLITE_THREADSAFE=2 -DSQLITE_CORE The issue does not persist across application restart which suggests something is wrong with the in-memory state but not with the db itself.
[sqlite] UPDATE silently failing
> > Ideally, open the database which exhibits the problem and first execute > > PRAGMA integrity_check; > Integrity check does not report any issue. > If this fails to show any problems run your UPDATE command, repeatedly if > necessary, and see if you can make the shell tool do anything that suggests > it isn't working perfectly. > I cannot reproduce the issue in the shell but that doesn't mean much as this differs in many ways from the real scenario: - the shell uses shared cache - the shell is single threaded - the shell doesn't use transactions - I can't accurately reproduce all the other operations that happen to the database (insert, delete, select, ...) prior to the failing update and may contribute to the issue in subtle ways ... I would be more interested in any ways I can get more verbose logging or some sort of execution trace out of sqlite: re-running tests against a patched sqlite is more practical than trying to extract a minimal reproducer at this point.
[sqlite] UPDATE silently failing
On Mon, Sep 21, 2015 at 6:49 PM, Richard Hipp wrote: > On 9/21/15, Hugues Bruant wrote: > > Table schema: > > > > CREATE TABLE cv (cv_s integer not null, cv_o blob not null, cv_t integer > > not null, primary key(cv_s, cv_o)); > > > > Prepared statement: > > > > UPDATE cv SET cv_t=? where cv_s=? and cv_o=?; > > My guess is that the WHERE clause matches no rows. So it isn't > silently failing, it is doing exactly what it is suppose to do: > Update only those rows you have specified. > I wish it where that simple. The where clause should match, as evidenced by the fact that: SELECT cv_t from cv where cv_s=? and cv_o=?; returns the correct value both before and after the failing UPDATE. If that's not convincing enough, I should mention that the code checks the change count and falls back to an INSERT if the UPDATE reports that no rows where updated. This results in a SQLITE_CONSTRAINT error, which is how we discovered that the update was failing in the first place.
[sqlite] UPDATE silently failing
On Mon, Sep 21, 2015 at 8:23 PM, Richard Hipp wrote: > On 9/21/15, Hugues Bruant wrote: > > On Mon, Sep 21, 2015 at 6:49 PM, Richard Hipp wrote: > > > >> On 9/21/15, Hugues Bruant wrote: > >> > Table schema: > >> > > >> > CREATE TABLE cv (cv_s integer not null, cv_o blob not null, cv_t > >> > integer > >> > not null, primary key(cv_s, cv_o)); > >> > > >> > Prepared statement: > >> > > >> > UPDATE cv SET cv_t=? where cv_s=? and cv_o=?; > >> > >> My guess is that the WHERE clause matches no rows. So it isn't > >> silently failing, it is doing exactly what it is suppose to do: > >> Update only those rows you have specified. > >> > > I wish it where that simple. > > > > The where clause should match, as evidenced by the fact that: > > > > SELECT cv_t from cv where cv_s=? and cv_o=?; > > > > returns the correct value both before and after the failing UPDATE. > > > > If that's not convincing enough, I should mention that the code checks > the > > change count and falls back to an INSERT if the UPDATE reports that no > > rows where updated. This results in a SQLITE_CONSTRAINT error, which > > is how we discovered that the update was failing in the first place. > > If you can tell us how to reproduce the problem, we'll work on it for > you. But until then, there isn't much we can do. > I've been trying to isolate the issue but that's unfortunately non-trivial. I would be happy to build and test a patched sqlite with extra logging, some sort of vdbe execution tracing or really anything that would allow more information to be gathered from the full application. If nothing of the sort is possible I'll work on extracting a minimal reproducer but that will probably take a while. Which version of SQLite is this, btw? What OS? Are you compiling > SQLite yourself, or using a library that somebody has built for you? > What programming language are you using? > As mentioned in the first email of the thread: OS: OS X (we use Linux and Windows as well but so far haven't reproduced the issue on these environments) SQLite version: both 3.8.7 and 3.8.11.1 exhibit the issue We build native code ourselves and access the db through the sqlite-jdbc java wrapper ( https://github.com/xerial/sqlite-jdbc ).
[sqlite] UPDATE silently failing
On Mon, Sep 21, 2015 at 8:43 PM, Richard Hipp wrote: > On 9/21/15, Hugues Bruant wrote: > > > > I would be happy to build and test a patched sqlite with extra logging, > > some sort of vdbe execution tracing > > Compile with -DSQLITE_DEBUG and then use "PRAGMA vdbe_debug=ON;" > before the offending UPDATE and turn if off afterwards. > Will do. Does that go through the error/logging callback ( https://www.sqlite.org/errlog.html) or directly to stdout/stderr?
[sqlite] UPDATE silently failing
> > If you can capture a malfunctioning trace, and send in the database > file and the SQL statement that is running, that should allow us to > localize the problem. > Trace for the failing UPDATE: cv_s=1 cv_o=b8b9f4... cv_t=28 -> 29 SQL: [update cv set cv_t=? where cv_s=? and cv_o=?] VDBE Program Listing: 0 Init 0 250 00 Start at 25 1 Null 012 00 r[1..2]=NULL 2 OpenWrite0 740 3 00 root=74 iDb=0; cv 3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; sqlite_autoindex_cv_1 4 Explain 000 SEARCH TABLE cv USING INDEX sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 5 Variable 260 00 r[6]=parameter(2,) 6 IsNull 6 150 00 if r[6]==NULL goto 15 7 Variable 370 00 r[7]=parameter(3,) 8 IsNull 7 150 00 if r[7]==NULL goto 15 9 Affinity 610 D 00 affinity(r[6]) 10 SeekGE 1 156 2 00 key=r[6..7] 11 IdxGT1 156 2 00 key=r[6..7] 12 IdxRowid 180 00 r[8]=rowid 13 Seek 080 00 intkey=r[8] 14 IdxRowid 120 00 r[2]=rowid 15 IsNull 2 240 00 if r[2]==NULL goto 24 16 Column 003 00 r[3]=cv.cv_s 17 Column 014 00 r[4]=cv.cv_o 18 Variable 150 00 r[5]=parameter(1,) 19 HaltIfNull129923 cv.cv_s 01 if r[3]=null halt 20 HaltIfNull129924 cv.cv_o 01 if r[4]=null halt 21 HaltIfNull129925 cv.cv_t 01 if r[5]=null halt 22 MakeRecord 339 DAD 00 r[9]=mkrec(r[3..5]) 23 Insert 092 cv05 intkey=r[2] data=r[9] 24 Halt 000 00 25 Transaction 01 56 0 01 26 TableLock0 741 cv00 iDb=0 root=74 write=1 27 Goto 010 00 VDBE Trace: 0 Init 0 250 00 Start at 25 SQL-trace: update cv set cv_t=? where cv_s=? and cv_o=? 25 Transaction 01 56 0 01 26 TableLock0 741 cv00 iDb=0 root=74 write=1 27 Goto 010 00 1 Null 012 00 r[1..2]=NULL REG[1] = NULL 2 OpenWrite0 740 3 00 root=74 iDb=0; cv 3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; sqlite_autoindex_cv_1 4 Explain 000 SEARCH TABLE cv USING INDEX sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 5 Variable 260 00 r[6]=parameter(2,) REG[6] = i:0 6 IsNull 6 150 00 if r[6]==NULL goto 15 REG[6] = i:0 7 Variable 370 00 r[7]=parameter(3,) REG[7] = t16[B8B9F4D5F3E8432E86E248C2EBE14D5D..C...H...M]](8) 8 IsNull 7 150 00 if r[7]==NULL goto 15 REG[7] = t16[B8B9F4D5F3E8432E86E248C2EBE14D5D..C...H...M]](8) 9 Affinity 610 D 00 affinity(r[6]) 10 SeekGE 1 156 2 00 key=r[6..7] REG[6] = i:0 11 IdxGT1 156 2 00 key=r[6..7] 15 IsNull 2 240 00 if r[2]==NULL goto 24 REG[2] = NULL 24 Halt 000 00 Followed by a failing insert for the same row: sqlite:1555: abort at 16 in [insert into cv (cv_s,cv_o,cv_t) VALUES(?,?,?)]: UNIQUE constraint failed: cv.cv_s, cv.cv_o Trace for the previous successful UPDATE to the same row: cv_s=1 cv_o=b8b9f4... cv_t=27 -> 28 SQL: [update cv set cv_t=? where cv_s=? and cv_o=?] VDBE Program Listing: 0 Init 0 250 00 Start at 25 1 Null 012 00 r[1..2]=NULL 2 OpenWrite0 740 3 00 root=74 iDb=0; cv 3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; sqlite_autoindex_cv_1 4 Explain 000 SEARCH TABLE cv USING INDEX sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 5 Variable 260 00 r[6]=parameter(2,) 6 IsNull 6 150 00 if r[6]==NULL goto 15 7 Variable 370 00 r[7]=parameter(3,) 8 IsNull 7 150 00 if r[7]==NULL goto 15 9 Affinity 610 D 00 affinity(r[6]) 10 SeekGE 1 156 2 00 key=r[6..7] 11 IdxGT1 156 2 00 key=r[6..7] 12 IdxRowid 180 00 r[8]=rowid 13 Seek 080 00 intkey=r[8] 14 I
[sqlite] UPDATE silently failing
On Tue, Sep 22, 2015 at 6:22 AM, Richard Hipp wrote: > On 9/22/15, Hugues Bruant wrote: > >> > >> If you can capture a malfunctioning trace, and send in the database > >> file and the SQL statement that is running, that should allow us to > >> localize the problem. > >> > > > > Trace for the failing UPDATE: > > > > cv_s=1 > > The trace shows that you have this value set to 0, not 1. And > apparently there is no row with cv_s=0 and cv_o=b8b9f4... > That is rather curious. The method where the UPDATE fails is as follows: public void setVersion_(SIndex sidx, OID oid, long version, Trans t) throws SQLException { try (Statement s = c().createStatement()) { s.execute("pragma vdbe_debug=ON"); } int n = exec(_pswSetVersion, ps -> { ps.setLong(1, version); ps.setInt(2, sidx.getInt()); ps.setBytes(3, oid.getBytes()); return ps.executeUpdate(); }); try (Statement s = c().createStatement()) { s.execute("pragma vdbe_debug=OFF"); } if (n == 1) return; if (version > 1) { l.warn("{}{} {} {} {}", sidx, oid, version, getVersion_(sidx, oid), n); } exec(_pswInsertVersion, ps -> { ps.setInt(1, sidx.getInt()); ps.setBytes(2, oid.getBytes()); ps.setLong(3, version); checkState(ps.executeUpdate() == 1); return null; }); } SIndex sidx is just a boxed immutable integer. Its value is bound to the UPDATE and the trace shows it to be 0 But the log line printed when the number of rows updated is zero clearly shows the value to be 1 and this is further confirmed by the fact that when bound to the INSERT, the value turns out to be 1 (or there would be no constraint violation). This leaves essentially two places for the error to arise: - sqlite3_bind_int - somewhere in the JVM I will add more logging and see if I can pinpoint the location where the (incorrect) 0 value appears.
[sqlite] UPDATE silently failing
> > That does look a bit like magic - and as is 99.9% the case when > inexplicable magic happens, memory is getting corrupt or overwritten. You > are obviously prudent about this, but is there no clue when running under > Valgrind or similar for OSX? Nothing out of the ordinary or warnings? > Memory corruption seems unlikely: I would expect more errors to follow once some piece of memory is corrupted. Valgrind is unfortunately not very useful in this case as its OS X support is limited and it doesn't like JIT very much. (I'm unfortunately not strong on the JAVA VM, so another approach might be > needed to achieve the checking...) > After further testing I'm more and more leaning towards blaming the JVM here. In particular I've seen some weird behaviors related to captured variables, which could conceivably explain why the wrong value was bound to the UPDATE but both the log line and the INSERT used the correct one. I haven't been able to reproduce the issue after ripping out lambdas from the java snippet in my previous email. I'll report back if the issue resurfaces at some point in the future.
[sqlite] UPDATE silently failing
Forgot to include the db in the previous email. On Tue, Sep 22, 2015 at 12:37 AM, Hugues Bruant wrote: > If you can capture a malfunctioning trace, and send in the database >> file and the SQL statement that is running, that should allow us to >> localize the problem. >> > > Trace for the failing UPDATE: > > cv_s=1 > cv_o=b8b9f4... > cv_t=28 -> 29 > > SQL: [update cv set cv_t=? where cv_s=? and cv_o=?] > VDBE Program Listing: >0 Init 0 250 00 Start at 25 >1 Null 012 00 r[1..2]=NULL >2 OpenWrite0 740 3 00 root=74 iDb=0; cv >3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; > sqlite_autoindex_cv_1 >4 Explain 000 SEARCH TABLE cv USING INDEX > sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 >5 Variable 260 00 r[6]=parameter(2,) >6 IsNull 6 150 00 if r[6]==NULL goto 15 >7 Variable 370 00 r[7]=parameter(3,) >8 IsNull 7 150 00 if r[7]==NULL goto 15 >9 Affinity 610 D 00 affinity(r[6]) > 10 SeekGE 1 156 2 00 key=r[6..7] > 11 IdxGT1 156 2 00 key=r[6..7] > 12 IdxRowid 180 00 r[8]=rowid > 13 Seek 080 00 intkey=r[8] > 14 IdxRowid 120 00 r[2]=rowid > 15 IsNull 2 240 00 if r[2]==NULL goto 24 > 16 Column 003 00 r[3]=cv.cv_s > 17 Column 014 00 r[4]=cv.cv_o > 18 Variable 150 00 r[5]=parameter(1,) > 19 HaltIfNull129923 cv.cv_s 01 if r[3]=null halt > 20 HaltIfNull129924 cv.cv_o 01 if r[4]=null halt > 21 HaltIfNull129925 cv.cv_t 01 if r[5]=null halt > 22 MakeRecord 339 DAD 00 r[9]=mkrec(r[3..5]) > 23 Insert 092 cv05 intkey=r[2] data=r[9] > 24 Halt 000 00 > 25 Transaction 01 56 0 01 > 26 TableLock0 741 cv00 iDb=0 root=74 write=1 > 27 Goto 010 00 > VDBE Trace: >0 Init 0 250 00 Start at 25 > SQL-trace: update cv set cv_t=? where cv_s=? and cv_o=? > 25 Transaction 01 56 0 01 > 26 TableLock0 741 cv00 iDb=0 root=74 write=1 > 27 Goto 010 00 >1 Null 012 00 r[1..2]=NULL > REG[1] = NULL >2 OpenWrite0 740 3 00 root=74 iDb=0; cv >3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; > sqlite_autoindex_cv_1 >4 Explain 000 SEARCH TABLE cv USING INDEX > sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 >5 Variable 260 00 r[6]=parameter(2,) > REG[6] = i:0 >6 IsNull 6 150 00 if r[6]==NULL goto 15 > REG[6] = i:0 >7 Variable 370 00 r[7]=parameter(3,) > REG[7] = t16[B8B9F4D5F3E8432E86E248C2EBE14D5D..C...H...M]](8) >8 IsNull 7 150 00 if r[7]==NULL goto 15 > REG[7] = t16[B8B9F4D5F3E8432E86E248C2EBE14D5D..C...H...M]](8) >9 Affinity 610 D 00 affinity(r[6]) > 10 SeekGE 1 156 2 00 key=r[6..7] > REG[6] = i:0 > 11 IdxGT1 156 2 00 key=r[6..7] > 15 IsNull 2 240 00 if r[2]==NULL goto 24 > REG[2] = NULL > 24 Halt 000 00 > > > Followed by a failing insert for the same row: > > sqlite:1555: abort at 16 in [insert into cv (cv_s,cv_o,cv_t) > VALUES(?,?,?)]: UNIQUE constraint failed: cv.cv_s, cv.cv_o > > > Trace for the previous successful UPDATE to the same row: > > cv_s=1 > cv_o=b8b9f4... > cv_t=27 -> 28 > > SQL: [update cv set cv_t=? where cv_s=? and cv_o=?] > VDBE Program Listing: >0 Init 0 250 00 Start at 25 >1 Null 012 00 r[1..2]=NULL >2 OpenWrite0 740 3 00 root=74 iDb=0; cv >3 OpenWrite1 750 k(2,nil,nil) 02 root=75 iDb=0; > sqlite_autoindex_cv_1 >4 Explain 000 SEARCH TABLE cv USING INDEX > sqlite_autoindex_cv_1 (cv_s=? AND cv_o=?) 00 >5 Variable 26
[sqlite] UPDATE silently failing
Not important. On Tue, Sep 22, 2015 at 6:00 PM, Simon Slavin wrote: > > On 22 Sep 2015, at 5:40am, Hugues Bruant wrote: > > > Forgot to include the db in the previous email. > > You can't attach files to messages in this list. If it's important, > please post the file somewhere and send us -- or perhaps just a couple of > people -- a URL. > > Simon. > ___ > sqlite-users mailing list > sqlite-users at mailinglists.sqlite.org > http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users >
[sqlite] UPDATE silently failing
On Wed, Sep 23, 2015 at 12:00 AM, Rowan Worth wrote: > > SIndex sidx is just a boxed immutable integer. > > If it were me I'd be reviewing this assumption very carefully. The sequence > of events: > public class SIndex { private final int _i; public SIndex(int i) { _i = i; } public int getInt() { return _i; } @Override public String toString() { return Integer.toString(getInt()); } } The way these objects are created ensures that the integer value is always strictly positive. > 1. SIndex.getInt() returns 0 > 2. SIndex.toString() returns "1" > 3. SIndex.getInt() returns 1 > You forgot step 0 where getInt() returns 1 > Has many possible explanations. > I can't think of any that is consistent with the Java specification. Interestingly enough, I ran into something even weirder over the course of my testing: in some cases the SIndex captured inside the first lambda (UPDATE statement) appeared to be null even though it wasn't null in the enclosing scope (setVersion_) and the second lambda (INSERT statement). I don't have time to dig into JVM internals so I just opted to remove all uses of lambdas in DB code.
[sqlite] UPDATE silently failing
> > in some cases the SIndex captured inside the first lambda > > (UPDATE statement) appeared to be null even though it wasn't null in the > > enclosing scope (setVersion_) > > Interesting (and disturbing) result. Is this with Oracle's java compiler? > Compiler is Oracle JDK 8u40-b25 on OSX Runtime is OpenJDK 8u60-b04 built from source on OS X, Windows and Linux It's pretty rare but damaging enough that I'm going to avoid capturing lambdas in critical code paths from now on.