[sqlite] UPDATE silently failing

2015-09-23 Thread Nelson, Erik - 2 
Hugues Bruant wrote on Wednesday, September 23, 2015 2:06 AM
> > > 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.

Perhaps everyone is aware already, but it seems like at least sometimes lambdas 
expose underlying thread synchronization problems.

--
This message, and any attachments, is for the intended recipient(s) only, may 
contain information that is privileged, confidential and/or proprietary and 
subject to important terms and conditions available at 
http://www.bankofamerica.com/emaildisclaimer.   If you are not the intended 
recipient, please delete this message.

[sqlite] UPDATE silently failing

2015-09-23 Thread Rowan Worth 
On 23 September 2015 at 12:32, Hugues Bruant  wrote:

> On Wed, Sep 23, 2015 at 12:00 AM, Rowan Worth  wrote:
>
> > Has many possible explanations.
>
> I can't think of any that is consistent with the Java specification.
>

Yeah fair enough, SIndex looks watertight. It's still possible for some
other code to change _i through reflection but (a) I presume you would know
if you were doing something like that and (b) it wouldn't explain the null
SIndex capture.

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?
-Rowan

[sqlite] UPDATE silently failing

2015-09-23 Thread Rowan Worth 
> SIndex sidx is just a boxed immutable integer.

If it were me I'd be reviewing this assumption very carefully. The sequence
of events:

1. SIndex.getInt() returns 0
2. SIndex.toString() returns "1"
3. SIndex.getInt() returns 1

Has many possible explanations. You could also try 'final int sid =
sidx.getInt();' at the start of setVersion_, and refer to sid throughout
instead of sidx to guarantee a consistent value. If the same problem occurs
then you know something is going wrong in the jdbc/sqlite layer, otherwise
if you start getting rows inserted with cv_s = 0 you know sidx is somehow
changing.

-Rowan

[sqlite] UPDATE silently failing

2015-09-23 Thread Hugues Bruant 
> > 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.

[sqlite] UPDATE silently failing

2015-09-23 Thread Hugues Bruant 
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

2015-09-23 Thread Simon Slavin 

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] UPDATE silently failing

2015-09-22 Thread Simon Slavin 

On 22 Sep 2015, at 5:44pm, Hugues Bruant  wrote:

> 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.

If a JVM is involved, you may not be using Xcode to write your program.  But if 
you are using Xcode then it has memory-testing tools just as paranoid as 
valgrind built into it.  Check out the 'Instruments' related to memory 
management.  You may find this useful:



Simon.

[sqlite] UPDATE silently failing

2015-09-22 Thread Hugues Bruant 
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

2015-09-22 Thread R.Smith 


On 2015-09-22 03:58 PM, Hugues Bruant wrote:
> 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.

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?

(I'm unfortunately not strong on the JAVA VM, so another approach might 
be needed to achieve the checking...)
Ryan

[sqlite] UPDATE silently failing

2015-09-22 Thread Nelson, Erik - 2 
R.Smith wrote on Tuesday, September 22, 2015 10:08 AM
> 
> On 2015-09-22 03:58 PM, Hugues Bruant wrote:
> > 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
> >
> 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?

I find that most of the time when I see magic it's because I've made an 
incorrect assumption, overlooked something, or have an incorrect mental model 
about what's actually going on.

--
This message, and any attachments, is for the intended recipient(s) only, may 
contain information that is privileged, confidential and/or proprietary and 
subject to important terms and conditions available at 
http://www.bankofamerica.com/emaildisclaimer.   If you are not the intended 
recipient, please delete this message.

[sqlite] UPDATE silently failing

2015-09-22 Thread R.Smith 


On 2015-09-22 06: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

If I'm reading this right, cv_s looks like 0 and not 1 here (REG[6]). 
What is the type of the bound variable? Might this be a rounding / 
truncation inefficiency, perhaps only manifest in OSX?

>
>
> 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

[sqlite] UPDATE silently failing

2015-09-22 Thread Hugues Bruant 
>
> 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

2015-09-22 Thread Hugues Bruant 
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

2015-09-22 Thread Richard Hipp 
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...


> 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

[sqlite] UPDATE silently failing

2015-09-22 Thread Hugues Bruant 
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 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

[sqlite] UPDATE silently failing

2015-09-22 Thread Hugues Bruant 
>
> 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

[sqlite] UPDATE silently failing

2015-09-22 Thread Simon Slavin 

On 21 Sep 2015, at 10:44pm, Hugues Bruant  wrote:

> 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.

Can you reproduce this problem with the SQLite shell tool included with Mac OS 
X ?  You should find one already installed on your Mac as '/usr/bin/sqlite3'.

Ideally, open the database which exhibits the problem and first execute

PRAGMA integrity_check;

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.

> It is opened in
> WAL mode with exclusive locking.

Just a quick note that the journal mode is an attribute of the database itself. 
 There is no need to specify the mode each time a connection opens the 
database.  It is saved in the journal file and connections which access the 
database will automatically understand what mode to use.  You can check the 
journal mode of the database using

PRAGMA journal_mode;

Simon.

[sqlite] UPDATE silently failing

2015-09-21 Thread James K. Lowden 
On Mon, 21 Sep 2015 17:44:13 -0400
Hugues Bruant  wrote:

> 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

Commit?  

This behavior is consistent with an uncommitted UPDATE.  

--jkl

[sqlite] UPDATE silently failing

2015-09-21 Thread Richard Hipp 
On 9/21/15, Hugues Bruant  wrote:
> 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?

Directly to stdout.

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.

-- 
D. Richard Hipp
drh at sqlite.org

[sqlite] UPDATE silently failing

2015-09-21 Thread Hugues Bruant 
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

2015-09-21 Thread Richard Hipp 
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.
-- 
D. Richard Hipp
drh at sqlite.org

[sqlite] UPDATE silently failing

2015-09-21 Thread Hugues Bruant 
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

2015-09-21 Thread Richard Hipp 
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.

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?
-- 
D. Richard Hipp
drh at sqlite.org

[sqlite] UPDATE silently failing

2015-09-21 Thread Hugues Bruant 
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

2015-09-21 Thread Richard Hipp 
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.

>
> 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-users mailing list
> sqlite-users at mailinglists.sqlite.org
> http://mailinglists.sqlite.org/cgi-bin/mailman/listinfo/sqlite-users
>


-- 
D. Richard Hipp
drh at sqlite.org

[sqlite] UPDATE silently failing

2015-09-21 Thread Hugues Bruant 
>
> 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

2015-09-21 Thread Hugues Bruant 
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.