BUG #8842: lo_open/fastpath transaction inconsistency

The following bug has been logged on the website:

Bug reference: 8842
Logged by: Ludovic P
Email address: ludovic(dot)pollet(at)kurmi-software(dot)com
PostgreSQL version: 9.0.3
Operating system: Windows
Description:

Summary:

Accessing LOB using the lo_open function via fastpath call sometime fails
for blob that have been concurrently deleted after the start of the
transaction, with a message "large object xxx does not exist".
However, the same access pattern implemented using plain sql select
loread(lo_open(...)) just works reliably.

I suspect that the "fastpath" way of calling lo_open is broken regarding
transaction consistency (ie it sees data that are otherwise not visible to
the transaction).

Details:

I have a table (async_operations) that holds an oid row (result) that is
really a reference to a lob.

create table async_operations (
idASYNC_OPERATION int4 not null,
result oid,
... (removed for clarity)
primary key (idASYNC_OPERATION))

This table has a trigger that manage the lob (ie lo_delete on update/
delete)

create trigger t_async_operations_result before update or delete on
async_operations for each row execute procedure lo_manage(result)
/

Two kinds of transaction may happen :
'update transaction' create a new lob and update the result oid (and the
trigger delete the old one
'consult transaction' select an entry, and perform a lo_open/loread on the
lob.

When load transaction is implemented using the jdbc api, random failures
happen in fastpath function call to to_open, just after the commit of an
'update transaction'.

Here is an extract of the service side query trace of my application (9.0.3,
default_transaction_isolation = 'repeatable read'. latest 9.3 and higher
isolation level behave the same). The log pattern is '%m %c %x %v'.

Transaction 5/37 is 'update transaction'
Transaction 3/2510 is a 'consult transaction', but it first does a plain sql
way (to show that the sql way works), then a fastpath way (returning the
error)
Transaction 4/414 is 'consult transaction' that loops the plain sql way. It
correctly reads the initial lob oid and content before and after commit, and
keep reading during the whole transaction. (this was intended to double
check that the transaction could not see value commited concurrently)

It shows that within the Transaction 3/2510, the call to lo_open using
select statement success while the call to lo_open using fastpath fails
(still in the SAME transaction). So I the problem seemns not related to the
client (in that case the jdbc driver), but to the server.

2014-01-15 11:44:40.429 CET 52d6668a.8fc 0 5/37LOG: statement: BEGIN;select
asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.result as
result570_0_ from async_operations asyncopera0_ where
asyncopera0_.idASYNC_OPERATION=304837
2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function call:
"lo_open" (OID 952)
2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function call:
"lo_creat" (OID 957)
2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
call: "lo_open" (OID 952)
2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
call: "lowrite" (OID 955)
2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
call: "lo_close" (OID 953)
2014-01-15 11:44:40.431 CET 52d6668a.8fc 493216 5/37LOG: statement: update
async_operations set result=581532 where idASYNC_OPERATION=304837
...
2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement:
BEGIN;select result from async_operations where idASYNC_OPERATION=304837
2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement: select
loread(lo_open(581531, 262144), 1000000)
...
2014-01-15 11:44:40.931 CET 52d66611.26f0 0 3/2510LOG: statement:
BEGIN;select result from async_operations where idASYNC_OPERATION=304837
2014-01-15 11:44:40.931 CET 52d6668a.8fc 493216 5/37LOG: statement: COMMIT
2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select
result from async_operations where idASYNC_OPERATION=304837
2014-01-15 11:44:40.931 CET 52d66611.26f0 0 3/2510LOG: statement: select
loread(lo_open(581531, 262144), 1000000)
2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select
loread(lo_open(581531, 262144), 1000000)
2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510LOG: statement: select
asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.userId as
userId570_0_, asyncopera0_.originalUserId as original3_570_0_,
asyncopera0_.executerTitle as executer4_570_0_, asyncopera0_.flag as
flag570_0_, asyncopera0_.status as status570_0_, asyncopera0_.startTime as
startTime570_0_, asyncopera0_.endTime as endTime570_0_,
asyncopera0_.description as descript9_570_0_, asyncopera0_.encodedForm as
encoded10_570_0_, asyncopera0_.result as result570_0_,
asyncopera0_.fileContent as fileCon12_570_0_,
asyncopera0_.fileContentEncoding as fileCon13_570_0_,
asyncopera0_.fileProc_class as fileProc14_570_0_, asyncopera0_.pojoName1 as
pojoName15_570_0_, asyncopera0_.pojoName2 as pojoName16_570_0_,
asyncopera0_.language as language570_0_, asyncopera0_.additionalHeaderField
as additio18_570_0_, asyncopera0_.massOperation as massOpe19_570_0_,
asyncopera0_.node as node570_0_, asyncopera0_.execNode as execNode570_0_
from async_operations asyncopera0_ where
asyncopera0_.idASYNC_OPERATION=304837
2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
result from async_operations where idASYNC_OPERATION=304837
2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
loread(lo_open(581531, 262144), 1000000)
2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510LOG: fastpath function
call: "lo_open" (OID 952)
=> This should work since the access using statement in the same transaction
was ok (I triple checked in the code that the OID passed to lo_open was the
same as the previous select, in this case 581531)
2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510ERROR: large object
581531 does not exist
2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
result from async_operations where idASYNC_OPERATION=304837
2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
loread(lo_open(581531, 262144), 1000000)