Horton

Thread

Commits

  1. Make syslogger more robust against failures in opening CSV log files.

  1. csvlog gets crazy when csv file is not writable

    Alexander Kukushkin <cyberdemn@gmail.com> — 2018-08-20T13:55:01Z

    Hi,

I am using the following config parameters for logging:
log_destination = 'csvlog'
logging_collector = on
log_filename = 'postgresql-%Y-%m-%d.log'

If for some reason postgres can't open 'postgresql-%Y-%m-%d.csv' file
for writing, it gets mad and outputs a few thousands of lines to
stderr:

2018-08-20 15:40:46.919 CEST [22067] HINT:  Future log output will
appear in directory "log".
2018-08-20 15:40:46.920 CEST [22069] FATAL:  could not open log file
"log/postgresql-2018-08-20.csv": Permission denied
2018-08-20 15:40:46.920 CEST [22069] FATAL:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] FATAL:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] FATAL:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] FATAL:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] PANIC:  ERRORDATA_STACK_SIZE exceeded
2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file
"could not open log file "%s": Permission denied": Permission denied
2018-08-20 15:40:46.920 CEST [22069] PANIC:  ERRORDATA_STACK_SIZE exceeded

And so on. ERRORDATA_STACK_SIZE is presented in the output 3963 times

Sure, it is entirely my fault, that csv file is not writable, but such
avalanche of PANIC lines is really scary.

We tried to debug it a little bit and here is the backtrace:
#0 logfile_open (filename=0x555556011ec8
"log/postgresql-2018-08-20.csv", mode=<optimized out>,
allow_errors=<optimized out>) at syslogger.c:1149
#1 0x00005555558de0fe in open_csvlogfile () at syslogger.c:1105
#2 0x00005555558de19e in write_syslogger_file (buffer=0x5555560122e0
"2018-08-20 15:51:41.292 CEST,,,20696,,5b7ac76b.50d8,3,,2018-08-20
15:51:39 CEST,,0,FATAL,42501,\"could not open log file \"\"could not
open log file \"\"%s\"\": Permission denied\"\": Permission
denied\",,,,,,,"..., count=205, destination=destination@entry=8) at
syslogger.c:1002
#3 0x0000555555a8f461 in write_csvlog
(edata=edata@entry=0x555555fdad30 <errordata+368>) at elog.c:2837
#4 0x0000555555a8f8c7 in send_message_to_server_log
(edata=edata@entry=0x555555fdad30 <errordata+368>) at elog.c:3055
#5 0x0000555555a8fec2 in EmitErrorReport () at elog.c:1479
#6 0x0000555555a9000a in errfinish (dummy=<optimized out>) at elog.c:483
#7 0x00005555558dda8d in logfile_open (filename=<optimized out>,
mode=<optimized out>, allow_errors=<optimized out>) at
syslogger.c:1149
#8 0x00005555558de0fe in open_csvlogfile () at syslogger.c:1105
#9 0x00005555558de19e in write_syslogger_file (buffer=0x55555603b740
'\177' <repeats 200 times>..., count=2052,
destination=destination@entry=8) at syslogger.c:1002
#10 0x0000555555a8f461 in write_csvlog
(edata=edata@entry=0x555555fdac78 <errordata+184>) at elog.c:2837
#11 0x0000555555a8f8c7 in send_message_to_server_log
(edata=edata@entry=0x555555fdac78 <errordata+184>) at elog.c:3055
#12 0x0000555555a8fec2 in EmitErrorReport () at elog.c:1479
#13 0x0000555555a9000a in errfinish (dummy=<optimized out>) at elog.c:483
#14 0x00005555558dda8d in logfile_open (filename=<optimized out>,
mode=<optimized out>, allow_errors=<optimized out>) at
syslogger.c:1149
#15 0x00005555558de0fe in open_csvlogfile () at syslogger.c:1105
#16 0x00005555558de19e in write_syslogger_file (buffer=0x555556011ec8
"log/postgresql-2018-08-20.csv", count=185,
destination=destination@entry=8) at syslogger.c:1002
#17 0x0000555555a8f461 in write_csvlog
(edata=edata@entry=0x555555fdabc0 <errordata>) at elog.c:2837
#18 0x0000555555a8f8c7 in send_message_to_server_log
(edata=edata@entry=0x555555fdabc0 <errordata>) at elog.c:3055
#19 0x0000555555a8fec2 in EmitErrorReport () at elog.c:1479
#20 0x0000555555a9000a in errfinish (dummy=<optimized out>) at elog.c:483
#21 0x00005555558dda8d in logfile_open (filename=<optimized out>,
mode=<optimized out>, allow_errors=<optimized out>) at
syslogger.c:1149
#22 0x00005555558de0fe in open_csvlogfile () at syslogger.c:1105
#23 0x00005555558de19e in write_syslogger_file (buffer=0x7fffffffc48c
"2018-08-20 15:51:39.187 CEST,,,20669,,5b7ac76b.50bd,1,,2018-08-20
15:51:39 CEST,,0,LOG,00000,\"ending log output to stderr\",,\"Future
log output will go to log destination \"\"csvlog\"\".\",,,,,,,\"\"\n",
count=192, destination=8) at syslogger.c:1002
#24 0x00005555558de3d0 in process_pipe_input (logbuffer=0x7fffffffc3d0
"", bytes_in_logbuffer=0x7fffffffc3cc) at syslogger.c:898
#25 0x00005555558dea7c in SysLoggerMain (argc=<optimized out>,
argv=<optimized out>) at syslogger.c:458
#26 0x00005555558decdb in SysLogger_Start () at syslogger.c:613
#27 0x00005555558dd114 in PostmasterMain (argc=3, argv=<optimized
out>) at postmaster.c:1281
#28 0x000055555583b3da in main (argc=3, argv=0x55555600fcf0) at main.c:228

Regards,
--
Alexander Kukushkin

  2. Re: csvlog gets crazy when csv file is not writable

    Michael Paquier <michael@paquier.xyz> — 2018-08-21T02:23:42Z

    On Mon, Aug 20, 2018 at 03:55:01PM +0200, Alexander Kukushkin wrote:
> If for some reason postgres can't open 'postgresql-%Y-%m-%d.csv' file
> for writing, it gets mad and outputs a few thousands of lines to
> stderr:
>
> 2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file

Ah, this log message could be changed to be simply "could not open
file", the file name offers enough context...

> And so on. ERRORDATA_STACK_SIZE is presented in the output 3963 times
> 
> Sure, it is entirely my fault, that csv file is not writable, but such
> avalanche of PANIC lines is really scary.

Yeah, this is a recursion in logfile_open -> open_csvlogfile.  With
stderr there is a much better effort, where the server just quits with a
FATAL if the log file cannot be opened in SysLogger_Start.  Could this
be an argument for allowing logfile_open() to use write_stderr?  I am
not sure under the hood of the don't-do-that rule.  And we make sure
that log_destination is writable already at early stage, which would
cover any scenarios like a kernel switching the log partition to be
read-only.
--
Michael

  3. Re: csvlog gets crazy when csv file is not writable

    Dmitry Dolgov <9erthalion6@gmail.com> — 2018-08-21T09:18:55Z

    > On Tue, 21 Aug 2018 at 04:23, Michael Paquier <michael@paquier.xyz> wrote:
> > On Mon, Aug 20, 2018 at 03:55:01PM +0200, Alexander Kukushkin wrote:
> > If for some reason postgres can't open 'postgresql-%Y-%m-%d.csv' file
> > for writing, it gets mad and outputs a few thousands of lines to
> > stderr:
> >
> > 2018-08-20 15:40:46.920 CEST [22069] PANIC:  could not open log file
>
> Ah, this log message could be changed to be simply "could not open
> file", the file name offers enough context...

Yeah, I had the same idea while investigating this, that it would be easier
just to change this log message and remove the filename completely or format
the message somehow without using va_list.

> > And so on. ERRORDATA_STACK_SIZE is presented in the output 3963 times
> >
> > Sure, it is entirely my fault, that csv file is not writable, but such
> > avalanche of PANIC lines is really scary.
>
> Yeah, this is a recursion in logfile_open -> open_csvlogfile.  With
> stderr there is a much better effort, where the server just quits with a
> FATAL if the log file cannot be opened in SysLogger_Start.

I also wonder if there are any strong reasons why in the case of errors with
csv log file behaviour is different, maybe it's possible to unify them?

  4. Re: csvlog gets crazy when csv file is not writable

    Tom Lane <tgl@sss.pgh.pa.us> — 2018-08-25T22:39:32Z

    Dmitry Dolgov <9erthalion6@gmail.com> writes:
>> On Tue, 21 Aug 2018 at 04:23, Michael Paquier <michael@paquier.xyz> wrote:
> On Mon, Aug 20, 2018 at 03:55:01PM +0200, Alexander Kukushkin wrote:
>>> If for some reason postgres can't open 'postgresql-%Y-%m-%d.csv' file
>>> for writing, it gets mad and outputs a few thousands of lines to
>>> stderr:

>> Yeah, this is a recursion in logfile_open -> open_csvlogfile.  With
>> stderr there is a much better effort, where the server just quits with a
>> FATAL if the log file cannot be opened in SysLogger_Start.

> I also wonder if there are any strong reasons why in the case of errors with
> csv log file behaviour is different, maybe it's possible to unify them?

Yeah.  This seems to boil down to somebody deciding that it'd be okay
to delay opening the csvlogFile until we actually need to write to it.
As this example shows, that's just crazy, because it neglects to account
for the possibility of failure.  What we need to do is, first, make the
csvlogFile handling look as much as possible like the well-tested
syslogFile handling, and second, decide what we'll do about open failures
so that they *don't* lead to recursion.

At postmaster startup, we can open csvlogFile if requested and fail if
we can't, just as for syslogFile.  And if we fail to make a rotation,
it's okay to keep writing to the old file, just as for syslogFile.
But we have to allow for Log_destination to change after startup,
and that means we might need to open csvlogFile when it wasn't open
before, and we can't just quit if we fail.

What the attached patch does about that is to redirect CSV-format
output to syslogFile if we get CSV output when csvlogFile isn't open.
The only other plausible answer I can see is to drop such output on
the floor, and that seems pretty unfriendly.

Also we really ought to close csvlogFile if CSV logging is turned off;
the existing code doesn't, but this adds that.

Also, while looking at this I noticed what seems to be pretty dodgy code
in write_stderr:

void
write_stderr(const char *fmt,...)
{
	va_list		ap;

	fmt = _(fmt);

	va_start(ap, fmt);

I'm not sure how, or if, va_start actually uses its second argument;
it seems likely that that's vestigial in all modern compilers.  But
on a machine where it's *not* vestigial, assigning a new value to fmt
before we give it to va_start doesn't seem like a bright idea.
I think it'd be better to avoid that and just write _(fmt) twice,
as attached.

			regards, tom lane

  5. Re: csvlog gets crazy when csv file is not writable

    Dmitry Dolgov <9erthalion6@gmail.com> — 2018-08-26T19:39:44Z

    > On Sun, 26 Aug 2018 at 00:39, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> At postmaster startup, we can open csvlogFile if requested and fail if
> we can't, just as for syslogFile.  And if we fail to make a rotation,
> it's okay to keep writing to the old file, just as for syslogFile.
> But we have to allow for Log_destination to change after startup,
> and that means we might need to open csvlogFile when it wasn't open
> before, and we can't just quit if we fail.

I agree, sounds great.

> What the attached patch does about that is to redirect CSV-format
> output to syslogFile if we get CSV output when csvlogFile isn't open.
> The only other plausible answer I can see is to drop such output on
> the floor, and that seems pretty unfriendly.

Yes, probably it's the only plausible answer for now. But then I would argue
that in the ideal world we will redirect output, that we can't write to
csvlogFile, to syslogFile in non-csv format, which will be less surprising. It
would require to move the actual csv formatting logic to the syslogger, or to
let backends to know somehow that csv log is not available at this moment
(although I assume both options are not particularly realistic).

  6. Re: csvlog gets crazy when csv file is not writable

    Tom Lane <tgl@sss.pgh.pa.us> — 2018-08-26T19:51:11Z

    Dmitry Dolgov <9erthalion6@gmail.com> writes:
>> On Sun, 26 Aug 2018 at 00:39, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> What the attached patch does about that is to redirect CSV-format
>> output to syslogFile if we get CSV output when csvlogFile isn't open.
>> The only other plausible answer I can see is to drop such output on
>> the floor, and that seems pretty unfriendly.

> Yes, probably it's the only plausible answer for now. But then I would argue
> that in the ideal world we will redirect output, that we can't write to
> csvlogFile, to syslogFile in non-csv format, which will be less surprising. It
> would require to move the actual csv formatting logic to the syslogger, or to
> let backends to know somehow that csv log is not available at this moment
> (although I assume both options are not particularly realistic).

Yeah, something like that is what would have to happen.  The second option
is a complete nonstarter though: (a) there's no feedback path and (b) even
with feedback, there'd be race conditions.  It's conceivable that we could
push the formatting work down to the syslogger; but I think that would be
a net loss in both reliability and performance --- remember the syslogger
is a bottleneck for logging activities, since it's inherently not
parallel.

Given that this is such a corner-case scenario, and one that generally
implies a DBA screwup that needs to be fixed, I don't want to expend a
lot of work and potentially reduce performance in order to make it
cleaner.

			regards, tom lane