Timestamp in log for prepared queries

This problem shows up in the pglog for systems running
slony, but is not unique to slony necessarily.

The timestamp on queries logged to pglog corresponds
to the time the query was prepared rather than when
the query was run SPI_exec.

With slony, the same prepared statements may be used
for days or weeks or ???

This causes the pglog file to have interleaved within
it slony activity dated days previously along with
current update activity.

I discussed this briefly with Jan who agreed it was
a bug in the pg logging rather than a slony anomally.

In this spot of pglog, you see slony pre-prepared
queries timestamped 06-10 16:18:47 (et al) interleaved with a
connection error timestamped 06-16 16:00.

dev_core-2005-06-10 16:18:47 PDT-LOG: duration: 21.882 ms statement: select con_origin, con_received, max(con_seqno) as con_seqno, max(con_timestamp) as con_timestamp from "_plaa03_staging".sl_confirm where con_received <> 2 group by con_origin, con_received
dev_core-2005-06-10 15:01:20 PDT-LOG: duration: 96.519 ms statement: notify "_plaa03_staging_Event"; notify "_plaa03_staging_Confirm"; insert into "_plaa03_staging".sl_event (ev_origin, ev_seqno, ev_timestamp, ev_minxid, ev_maxxid, ev_xip, ev_type ) values ('2', '51740', '2005-06-16 16:00:40.947355', '3246520', '3627300', '''3603570'',''3603741'',''3620474'',''3509792'',''3246520'',''3599413'',''3613734''', 'SYNC'); insert into "_plaa03_staging".sl_confirm (con_origin, con_received, con_seqno, con_timestamp) values (2, 1, '51740', CURRENT_TIMESTAMP); commit transaction;
dev_core-2005-06-10 16:18:47 PDT-LOG: duration: 21.911 ms statement: select con_origin, con_received, max(con_seqno) as con_seqno, max(con_timestamp) as con_timestamp from "_plaa03_staging".sl_confirm where con_received <> 2 group by con_origin, con_received [unknown]-2005-06-16 16:00:48 PDT-LOG: connection received: host=[local] port=
dev_coree-2005-06-16 16:00:48 PDT-LOG: connection authorized: user=postgres database=dev_coree dev_coree-2005-06-16 16:00:48 PDT-FATAL: database "dev_coree" does not exist
dev_core-2005-06-10 15:01:20 PDT-LOG: duration: 3.766 ms statement: select "_plaa03_staging".createEvent('_plaa03_staging', 'SYNC', NULL);
dev_core-2005-06-10 15:01:20 PDT-LOG: duration: 81.188 ms statement: commit transaction;
dev_core-2005-06-10 15:25:15 PDT-LOG: duration: 22.012 ms statement: fetch 100 from LOG;
dev_core-2005-06-10 15:01:20 PDT-LOG: duration: 183.405 ms statement: select "_plaa03_staging".forwardConfirm(1, 2, '53126', '2005-06-16 16:00:48.620222');
dev_core-2005-06-10 16:18:47 PDT-LOG: duration: 22.126 ms statement: select con_origin, con_received, max(con_seqno) as con_seqno, max(con_timestamp) as con_timestamp from "_plaa03_staging".sl_confirm where con_received <> 2 group by con_origin, con_received

elein
elein(at)varlena(dot)com