Thread: bug on log generation ?

Marcos Pegoraro <marcos@f10.com.br> writes:
> I have to fix log files because its content is not properly formatted,

What mechanism are you using to store the log?  If syslog is involved,
it's reputed to drop data under load.

            regards, tom lane

Hi,

On 2022-08-07 11:56:44 -0300, Marcos Pegoraro wrote:
> it´s csvlog only

How are you running postgres? If the logger process runs into trouble it might
write to stderr.

Is there a chance your huge statements would make you run out of space?

Greetings,

Andres Freund

On 2022-08-08 Mo 07:34, Marcos Pegoraro wrote:
>
>
>     How are you running postgres? If the logger process runs into
>     trouble it might
>     write to stderr.
>
>     Is there a chance your huge statements would make you run out of
>     space?
>
> Well, I don't think it is a  out of space problem, because it
> doesn´t stop logging, it just splits that message. As you can see, the
> next message is logged properly. And that statement is not so huge,
> these statements have not more than 10 or 20kb. And as I said these
> statements occur dozens of times a day, but only once or twice is
> not correctly logged 
> An additional info, that splitted message has an out of order log
> time. At that time the log file was having 2 or 3 logs per second, and
> that message was 1 or 2 minutes later. It seems like it occurs now but
> it's stored a minute or two later.
>
>

It looks like a failure of the log chunking protocol, with long messages
being improperly interleaved. I don't think we've had reports of such a
failure since commit c17e863bc7 back in 2012, but maybe my memory is
failing.

What platform is this on? Is it possible that on some platform the chunk
size we're using is not doing an atomic write?


syslogger.h says:


    #ifdef PIPE_BUF
    /* Are there any systems with PIPE_BUF > 64K?  Unlikely, but ... */
    #if PIPE_BUF > 65536
    #define PIPE_CHUNK_SIZE  65536
    #else
    #define PIPE_CHUNK_SIZE  ((int) PIPE_BUF)
    #endif
    #else                           /* not defined */
    /* POSIX says the value of PIPE_BUF must be at least 512, so use that */
    #define PIPE_CHUNK_SIZE  512
    #endif


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

Andrew Dunstan <andrew@dunslane.net> writes:
> What platform is this on? Is it possible that on some platform the chunk
> size we're using is not doing an atomic write?

Another idea is that some of the write() calls are failing --- elog.c
doesn't check for that.  Eyeing the POSIX spec for write(), I wonder
if somehow the pipe has gotten set into O_NONBLOCK mode and we're
not retrying EAGAIN failures.

            regards, tom lane

On 2022-08-08 Mo 11:07, Marcos Pegoraro wrote:
>
>     What platform is this on? Is it possible that on some platform the
>     chunk
>     size we're using is not doing an atomic write?
>
>  
> Until last year we were Ubuntu 16.04 and Postgres 11 with the latest
> minor update.
> This January we changed to Ubuntu 20.04 and Postgres 14, now updated
> to 14.4.
>
> But the problem occured on both old and new SO and Postgres versions.
> Right now I opened the current log file and there are 20 or 30 of
> these statements and all of them are fine, maybe tomorrow the problem
> comes back, maybe this afternoon.
>
>

OK, we really need a repeatable test if possible. Perhaps a pgbench run
with lots of concurrent runs of a some very long query would do the trick.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

Hi,

On 2022-08-08 10:32:22 -0400, Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
> > What platform is this on? Is it possible that on some platform the chunk
> > size we're using is not doing an atomic write?
> 
> Another idea is that some of the write() calls are failing --- elog.c
> doesn't check for that.

I was suspicious of those as well. It might be a good idea to at least write
such failures to stderr, otherwise it's just about impossible to debug. Not
that stderr will always point anywhere useful...

I can imagine that a system under heavy memory pressure might fail writing, if
there's a lot of writes in a row or such.

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> On 2022-08-08 10:32:22 -0400, Tom Lane wrote:
>> Another idea is that some of the write() calls are failing --- elog.c
>> doesn't check for that.

> I was suspicious of those as well. It might be a good idea to at least write
> such failures to stderr, otherwise it's just about impossible to debug. Not
> that stderr will always point anywhere useful...

Uh ... what we are talking about is a failure to write to stderr.
It's not likely that adding more output will help.

Having said that, looping on EAGAIN seems like a reasonably harmless
change.  Whether it will help here is really hard to say, though.

            regards, tom lane

Hi,

On 2022-08-08 12:19:22 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > On 2022-08-08 10:32:22 -0400, Tom Lane wrote:
> >> Another idea is that some of the write() calls are failing --- elog.c
> >> doesn't check for that.
> 
> > I was suspicious of those as well. It might be a good idea to at least write
> > such failures to stderr, otherwise it's just about impossible to debug. Not
> > that stderr will always point anywhere useful...
> 
> Uh ... what we are talking about is a failure to write to stderr.
> It's not likely that adding more output will help.

I forgot that we don't preserve the original stderr in some other fd, likely
because the logger itself still has it open and can use write_stderr().

Greetings,

Andres Freund