Thread: inconsistent debug log output

inconsistent debug log output

From
pgsql-bugs@postgresql.org
Date:
Dave E Martin (xxiii@cyberdude.com) reports a bug with a severity of 3
The lower the number the more severe it is.

Short Description
inconsistent debug log output

Long Description
a transaction from psql shows referential integrity statements in the output, but a transaction from a client using
libpqdoes not; they are both using the same backend, PGDEBUG=2: 

<PRE>
libpq:
000829.20:05:17.179  [2521] StartTransactionCommand
000829.20:05:17.180  [2521] query: INSERT INTO NAS (...) VALUES (...)
000829.20:05:17.180  [2521] ProcessQuery
000829.20:05:17.182  [2521] CommitTransactionCommand
000829.20:05:17.182  [2521] StartTransactionCommand
000829.20:05:17.182  [2521] query: COMMIT
000829.20:05:17.182  [2521] ProcessUtility: COMMIT
000829.20:05:17.182  [2521] CommitTransactionCommand
000829.20:05:17.183  [2521] ERROR:  nas_make: Permission denied.
000829.20:05:17.183  [2521] AbortCurrentTransaction

psql:
000829.23:18:08.413  [2542] StartTransactionCommand
000829.23:18:08.413  [2542] query: INSERT INTO NAS (...) VALUES (...);
000829.23:18:08.414  [2542] ProcessQuery
000829.23:18:08.417  [2542] CommitTransactionCommand
000829.23:18:46.444  [2542] StartTransactionCommand
000829.23:18:46.444  [2542] query: commit;
000829.23:18:46.444  [2542] ProcessUtility: commit;
000829.23:18:46.444  [2542] CommitTransactionCommand
000829.23:18:46.446  [2542] query: SELECT oid FROM "nas_make" WHERE "id" = $1 FOR UPDATE OF "nas_make"
000829.23:18:46.450  [2542] ERROR:  nas_make: Permission denied.
000829.23:18:46.450  [2542] AbortCurrentTransaction
</PRE>

Sample Code


No file was uploaded with this report

Re: inconsistent debug log output

From
Tom Lane
Date:
pgsql-bugs@postgresql.org writes:
> a transaction from psql shows referential integrity statements in the
> output, but a transaction from a client using libpq does not; they are
> both using the same backend, PGDEBUG=2:

I think you are misinterpreting what you see.  The additional queries
needed for RI checks are compiled only once per backend (when first
invoked), and thereafter cached.  The "query:" log entry at debuglevel 2
actually comes from the parser, and so will only appear when the RI
check is compiled.  Your client trace presumably is from a segment of
activity later than first execution of this particular RI check.

            regards, tom lane