Re: "Garbled" postgres logs

Tim Goodaire <tgoodair(at)ca(dot)afilias(dot)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