[Pgpool-general] Does log_statement always log statements?

[Tatsuo Ishii]

> Is it known that pgpool not always shows statements when activated
> "log_statement"?

Yes, if it's an extended protocol query(your case). IMO previous
PostgreSQL did not log statement executed by EXECUTE. The reason was,
it's a little bit hard to remember what was the original query.

So bottom line is, it's not impossible but a little bit hard to
implement.
--
Tatsuo Ishii
SRA OSS, Inc. Japan

> I have 3 servers: JBOSS, PGPOOL and PGSQL. In PGSQL a database called
> 'webcreds' with a table called 'sample'.
> In JBOSS I have deployed an application that makes some selects/inserts on
> that table.
> 
> If I connect with client psql from server JBOSS and execute a select, I can
> see that select in pgpool's logs and in postgresql's logs.
> But if I start my application in Jboss appserver, I don't see the queries in
> pgpool's logs but I do see then in postgresql's. Why??
> 
> Here is the log of tests, first from psql:
> 
> [JBOSS]
> psql -h pgpool -p 5431 -U wc_jboss webcreds
> 
> [PGPOOL]
> $ tail -f /var/log/pgpool/pgpool.log | grep statement
> Jul 21 19:26:34 vapp1a pgpool: 2009-07-21 19:26:30 DEBUG: pid 28060: key:
> log_statement
> Jul 21 19:27:55 vapp1a pgpool: 2009-07-21 19:27:55 LOG:   pid 28101:
> statement: select count(*) from webcreds.sample
> Jul 21 19:29:55 vapp1a pgpool: 2009-07-21 19:29:55 LOG:   pid 28101:
> statement:  DISCARD ALL
> 
> [PGSQL]
> $ tail -f /var/log/postgresql/postgresql-8.3-main.log
> 2009-07-21 19:27:26 MSD LOG:  connection received: host=172.16.0.211
> port=42154
> 2009-07-21 19:27:26 MSD LOG:  connection authorized: user=wc_jboss
> database=webcreds
> 2009-07-21 19:27:55 MSD LOG:  statement: select count(*) from
> webcreds.sample;
> 2009-07-21 19:29:54 MSD LOG:  statement:  DISCARD ALL
> 
> And here is the log of tests, first from the Jboss application:
> 
> [JBOSS]
> $ tail -f /usr/local/jboss/server/standard/log/server.log
> 2009-07-21 19:32:54,029 INFO  [STDOUT] (ConnectionProcessor) select complete
> without errors
> 2009-07-21 19:32:54,272 INFO  [STDOUT] (ConnectionProcessor) selected 10
> records
> 2009-07-21 19:32:54,272 INFO  [STDOUT] (ConnectionProcessor) ...
> 2009-07-21 19:32:54,273 INFO  [STDOUT] (ConnectionProcessor) going to
> perform insert query
> 2009-07-21 19:32:54,318 INFO  [STDOUT] (ConnectionProcessor) insert complete
> without errors
> 2009-07-21 19:32:54,318 INFO  [STDOUT] (ConnectionProcessor) inserted record
> with id 10050173
> 2009-07-21 19:32:54,318 INFO  [STDOUT] (ConnectionProcessor) ...
> 2009-07-21 19:32:54,318 INFO  [STDOUT] (ConnectionProcessor) going to
> perform delete query
> 2009-07-21 19:32:54,321 INFO  [STDOUT] (ConnectionProcessor) delete complete
> without errors
> 2009-07-21 19:32:54,322 INFO  [STDOUT] (ConnectionProcessor) end check
> connection
> 2009-07-21 19:33:01,058 INFO  [STDOUT] (ConnectionProcessor) validate
> started
> 2009-07-21 19:33:01,059 INFO  [STDOUT] (ConnectionProcessor) start check
> connection
> 2009-07-21 19:33:01,059 INFO  [STDOUT] (ConnectionProcessor) going to
> perform select query
> 2009-07-21 19:33:01,069 INFO  [STDOUT] (ConnectionProcessor) select complete
> without errors
> 2009-07-21 19:33:01,069 INFO  [STDOUT] (ConnectionProcessor) selected 10
> records
> 2009-07-21 19:33:01,069 INFO  [STDOUT] (ConnectionProcessor) ...
> 
> [PGPOOL]
> $ tail -f /var/log/pgpool/pgpool.log | grep statement
> Jul 21 19:33:17 vapp1a pgpool: 2009-07-21 19:33:13 LOG:   pid 28097:
> statement:  DISCARD ALL
> 
> [PGSQL]
> 2009-07-21 19:32:42 MSD LOG:  connection authorized: user=wc_jboss
> database=webcreds
> 2009-07-21 19:32:42 MSD LOG:  execute <unnamed>: SHOW TRANSACTION ISOLATION
> LEVEL
> 2009-07-21 19:32:54 MSD LOG:  execute S_1: BEGIN
> 2009-07-21 19:32:54 MSD LOG:  execute <unnamed>: select sampleobje0_.so_pk
> as so1_0_, sampleobje0_.anotherField as anotherF2_0_, sampleobje0_.someField
> as someField0_ from webcreds.sample sampleobje0_
> 2009-07-21 19:32:54 MSD LOG:  execute <unnamed>: select nextval
> ('webcreds.wc_global_seq')
> 2009-07-21 19:32:54 MSD LOG:  execute <unnamed>: insert into webcreds.sample
> (anotherField, someField, so_pk) values ($1, $2, $3)
> 2009-07-21 19:32:54 MSD DETAIL:  parameters: $1 =
> 'абвгдеёжзийклмнопрстуфхцчшщъыьэюяАБВГДЕЁЖЗИЙКЛМНОПРСТУФХЦЧШЩЪЫЬЭЮЯ', $2 =
> 'Кириллица', $3 = '10050173'
> 2009-07-21 19:32:54 MSD LOG:  execute <unnamed>: delete from webcreds.sample
> where so_pk=$1
> 2009-07-21 19:32:54 MSD DETAIL:  parameters: $1 = '10050163'
> 2009-07-21 19:32:54 MSD LOG:  execute S_2: COMMIT
> 2009-07-21 19:33:01 MSD LOG:  execute S_1: BEGIN
> 2009-07-21 19:33:01 MSD LOG:  execute <unnamed>: select sampleobje0_.so_pk
> as so1_0_, sampleobje0_.anotherField as anotherF2_0_, sampleobje0_.someField
> as someField0_ from webcreds.sample sampleobje0_
> 2009-07-21 19:33:01 MSD LOG:  execute <unnamed>: select nextval
> ('webcreds.wc_global_seq')
> 2009-07-21 19:33:01 MSD LOG:  execute <unnamed>: insert into webcreds.sample
> (anotherField, someField, so_pk) values ($1, $2, $3)
> 2009-07-21 19:33:01 MSD DETAIL:  parameters: $1 =
> 'абвгдеёжзийклмнопрстуфхцчшщъыьэюяАБВГДЕЁЖЗИЙКЛМНОПРСТУФХЦЧШЩЪЫЬЭЮЯ', $2 =
> 'Кириллица', $3 = '10050174'
> 2009-07-21 19:33:01 MSD LOG:  execute <unnamed>: delete from webcreds.sample
> where so_pk=$1
> 2009-07-21 19:33:01 MSD DETAIL:  parameters: $1 = '10050173'
> 2009-07-21 19:33:01 MSD LOG:  execute S_2: COMMIT
> [....]
> 2009-07-21 19:33:13 MSD LOG:  statement:  DISCARD ALL
> 
> 
> Thanks!!