Re: BUG #8842: lo_open/fastpath transaction inconsistency

I see no one replied to you. Can you recreate the problem in a newer
version of Postgres?

---------------------------------------------------------------------------

On Wed, Jan 15, 2014 at 12:49:35PM +0000, ludovic(dot)pollet(at)kurmi-software(dot)com wrote:
> 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)
>
>
>
>
>
>
> --
> Sent via pgsql-bugs mailing list (pgsql-bugs(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs

--
Bruce Momjian <bruce(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ Everyone has their own god. +