Re: "Garbled" postgres logs

Tim Goodaire <tgoodair@ca.afilias.info> writes:
> While going through some log files, we noticed that some of the log entries 
> are "garbled".  For example:

> 2007-03-27 01:19:44.139 UTC [1761474] oxrsa aepp xx.xx.xx.xx LOG:
> duratio2007-03-n: 3751.27 01:19801 ms  :44.139 statemenUTC [421940]
> oxrt: EXECUsor
> g aTE <unnaepp 10.4med>  [P0.136.10REPARE: 8 LOG:   select
> durationname fro: 3866.1m epp_do88 ms  smain_dz_tatementnames wh:
> EXECUTere nameE <unnam = $1]
> 2007-03-27 01:19:49.213 UTC [528480] oxrsa aepp xx.xx.xx.xx LOG:
> duration: 4510.129 ms  statement: EXECUTE <unnam2007-03-ed>  [PR27
> 01:19EPARE:  :49
> .213 select nUTC [294ame from930] oxr b_domsa aain_dz_nb
> 10.4ames whe0.136.10re name 7 LOG:  = $1]

> We're seeing this in postgresql 8.1.8 on AIX 5.3. Also, even though we're 
> using the same binaries for a bunch of clusters, we've only seen this issue 
> on one of them.

It looks like you've got messages from different backends being
interleaved, which is surely not impossible but normally it only happens
line-by-line at worst.  This must have something to do with the
buffering behavior on stderr.  Perhaps the difference is caused
by a difference in where the postmaster's stderr originally pointed
--- was this postmaster started in a different fashion than the others?

Note to hackers: would it make sense to use write() instead of
fprintf() in send_message_to_server_log to avoid any possibility
of stdio deciding to fragment the message?  Possibly there'd be
some marginal efficiency gain too.
        regards, tom lane