Re: BUG #8842: lo_open/fastpath transaction inconsistency - Mailing list pgsql-bugs

We just checked on a 9.3.4-3 (win32) and the problem is still present.

Ludovic

-----Message d'origine-----
De=A0: Bruce Momjian [mailto:bruce@momjian.us]=20
Envoy=E9=A0: mercredi 16 avril 2014 19:55
=C0=A0: Ludovic POLLET
Cc=A0: pgsql-bugs@postgresql.org
Objet=A0: Re: [BUGS] 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.pollet@kurmi-software.com=
 wrote:
> The following bug has been logged on the website:
>=20
> Bug reference:      8842
> Logged by:          Ludovic P
> Email address:      ludovic.pollet@kurmi-software.com
> PostgreSQL version: 9.0.3
> Operating system:   Windows
> Description:       =20
>=20
> Summary:
>=20
> 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".=20
> However, the same access pattern implemented using plain sql select
> loread(lo_open(...)) just works reliably.
>=20
> I suspect that the "fastpath" way of calling lo_open is broken regarding
> transaction consistency (ie it sees data that are otherwise not visible t=
o
> the transaction).
>=20
> Details:
>=20
> I have a table (async_operations) that holds an oid row (result) that is
> really a reference to a lob.
>=20
> create table async_operations (
>    idASYNC_OPERATION int4 not null,=20
>    result oid,=20
>    ... (removed for clarity)
>    primary key (idASYNC_OPERATION))
>=20
> This table has a trigger that manage the lob (ie lo_delete on update/
> delete)
>=20
> create trigger t_async_operations_result before update or delete on
> async_operations for each row execute procedure lo_manage(result)
> /
>=20
> Two kinds of transaction may happen :=20
>  '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 t=
he
> lob.
>=20
> 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'.
>=20
> Here is an extract of the service side query trace of my application (9.0=
.3,
> default_transaction_isolation =3D 'repeatable read'. latest 9.3 and highe=
r
> isolation level behave the same). The log pattern is '%m %c %x %v'.
>=20
>=20
> 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)
>=20
> 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 t=
he
> client (in that case the jdbc driver), but to the server.
>=20
> 2014-01-15 11:44:40.429 CET 52d6668a.8fc 0 5/37LOG:  statement: BEGIN;sel=
ect
> asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.result as
> result570_0_ from async_operations asyncopera0_ where
> asyncopera0_.idASYNC_OPERATION=3D304837
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG:  fastpath function ca=
ll:
> "lo_open" (OID 952)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG:  fastpath function ca=
ll:
> "lo_creat" (OID 957)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG:  fastpath functi=
on
> call: "lo_open" (OID 952)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG:  fastpath functi=
on
> call: "lowrite" (OID 955)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG:  fastpath functi=
on
> call: "lo_close" (OID 953)
> 2014-01-15 11:44:40.431 CET 52d6668a.8fc 493216 5/37LOG:  statement: upda=
te
> async_operations set result=3D581532 where idASYNC_OPERATION=3D304837
> ...
> 2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG:  statement:
> BEGIN;select result from async_operations where idASYNC_OPERATION=3D30483=
7
> 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=3D30483=
7
> 2014-01-15 11:44:40.931 CET 52d6668a.8fc 493216 5/37LOG:  statement: COMM=
IT
> 2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG:  statement: select
> result from async_operations where idASYNC_OPERATION=3D304837
> 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 a=
s
> 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_.additionalHeaderFie=
ld
> 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=3D304837
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG:  statement: select
> result from async_operations where idASYNC_OPERATION=3D304837
> 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)
> =3D> This should work since the access using statement in the same transa=
ction
> was ok (I triple checked in the code that the OID passed to lo_open was t=
he
> 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=3D304837
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG:  statement: select
> loread(lo_open(581531, 262144), 1000000)
>=20
>=20
>=20
>=20
>=20
>=20
> --=20
> Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs

--=20
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://enterprisedb.com

  + Everyone has their own god. +