csvlog gets crazy when csv file is not writable - Mailing list pgsql-bugs

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