Re: currval() race condition on server?

[Adriaan Joubert <a(dot)joubert(at)albourne(dot)com>]

Oliver Jowett wrote:

> The driver should split this query on the semicolons and send 
> Parse/Bind/Execute for each part, followed by a Sync at the end. If it 
> ends up using named statements due to JDBC statement reuse, it should 
> use a different name for each part. Of course there might be unknown 
> bugs in there, but it has been designed to handle this sort of compound 
> statement..
>
> To the OP: Is autocommit on or off? Can you reproduce the problem with a 
> URL parameter of loglevel=2 and see what it looks like? (that'll 
> generate a trace protocol-level messages)

autocommit is off.

I have not been able to reproduce this with logging on - even with 
logging off the problem only occurs intermittently. Looking at the 
output from the trace everything seems to happen as expected - see trace 
below. Yet we are getting a few of these errors in our logs every day - 
obviously only the first time we ask for the value of the sequence back. 
Scary thought is that may be getting an older value back in other 
instances. It feels an awful lot like a timing issue where the sequence 
number is retrieved, but there is a delay until currval can use it. I'm 
not sure how currval works.

I will continue to try to reproduce this with more logging, but would 
appreciate any ideas.

Thanks!

Adriaan

<=BE CommandStatus(BEGIN)
 <=BE ParseComplete [null]
 <=BE BindComplete [null]
 <=BE RowDescription(1)
 <=BE DataRow
 <=BE CommandStatus(SELECT)
 <=BE ReadyForQuery(T)
simple execute, 
handler=org(dot)postgresql(dot)jdbc2(dot)AbstractJdbc2Statement$StatementResultHandler(at)87e9bf, 
maxRows=0, fetchSize=0, flags=1
 FE=> Parse(stmt=null,query="UPDATE prm SET ... AND 
_audit=$16",oids={23,23,701,23,701,23,23,0,701,701,701,0,0,23,23,23})
 FE=> 
Bind(stmt=null,portal=null,$1=<421>,$2=<1>,$3=<0.21927195726630877>,$4=<18>,$5=<0.376345008550404>,$6=<2>,$7=<1>,$8=<NULL>,$9=<0.045037791453060014>,$10=<0.020180805785169714>,$11=<1.0>,$12=<NULL>,$13=<NULL>,$14=<387>,$15=<435>,$16=<3382993>)
 FE=> Describe(portal=null)
 FE=> Execute(portal=null,limit=0)
 FE=> Parse(stmt=null,query=" SELECT currval('ip_audit_seq')",oids={})
 FE=> Bind(stmt=null,portal=null)
 FE=> Describe(portal=null)
 FE=> Execute(portal=null,limit=0)
 FE=> Sync
 <=BE ParseComplete [null]
 <=BE BindComplete [null]
 <=BE NoData
 <=BE CommandStatus(UPDATE 1)
 <=BE ParseComplete [null]
 <=BE BindComplete [null]
 <=BE RowDescription(1)
 <=BE DataRow
 <=BE CommandStatus(SELECT)
 <=BE ReadyForQuery(T)
simple execute, 
handler=org(dot)postgresql(dot)jdbc2(dot)AbstractJdbc2Connection$TransactionCommandHandler(at)1033450, 
maxRows=0, fetchSize=0, flags=22
 FE=> Bind(stmt=S_2,portal=null)
 FE=> Execute(portal=null,limit=1)
 FE=> Sync
 <=BE BindComplete [null]
 <=BE CommandStatus(COMMIT)
 <=BE ReadyForQuery(I)