Обсуждение: jsonlog logging only some messages?
I tried loading the jsonlog module from https://github.com/michaelpq/pg_plugins into Postgres 9.6. However it seems it resulted in logs only for session log messages but not any background worker log messages. We have log_checkpoints set but there were no log messages in the json log about checkpoints. Nor were there any from autovacuum. Also I have log_destination set to stderr,cvslog and as I understand it the jsonlog module effectively overrides the "stderr" output which goes to the file named *.log (which I find super confusing, incidentally). But I was expecting to get the csv file as well. We didn't, we only got the *.log file with the (partial) json logs. Is there something I'm missing here or is this unexpected? -- greg
On Mon, Feb 26, 2018 at 05:38:56PM +0000, Greg Stark wrote: > I tried loading the jsonlog module from > https://github.com/michaelpq/pg_plugins into Postgres 9.6. > > However it seems it resulted in logs only for session log messages but > not any background worker log messages. We have log_checkpoints set > but there were no log messages in the json log about checkpoints. Nor > were there any from autovacuum. Hm. I have just loaded jsonlog on a 9.6 and 10 instance where log_checkpoints is enabled with this background worker which logs a simple string every 10s: https://github.com/michaelpq/pg_plugins/tree/master/hello_world Both checkpoint logs and the logs of the bgworker are showing up for me. > Also I have log_destination set to stderr,cvslog and as I understand > it the jsonlog module effectively overrides the "stderr" output which > goes to the file named *.log (which I find super confusing, > incidentally). But I was expecting to get the csv file as well. We > didn't, we only got the *.log file with the (partial) json logs. Is > there something I'm missing here or is this unexpected? Yeah, that's unfortunately expected... jsonlog enforces edata->output_to_server to false, which has the advantage of disabling extra log outputs, but also has the advantage of preventing duplicate entries into stderr. One way that I can see to solve things would be to patch the backend and get output_to_server replaced by a filter which allows a plugin to choose what are the extra output types allowed. In this case you don't want stderr later on, but would still want csvlog to happen, instead of having an all-or-nothing switch. I haven't tested, but it could be possible to have as well jsonlog enforce Log_destination to only use csvlog after it generates its entry so as stderr is not duplicated by csvlog gets though. Not sure how you would reset the parameter though, so you may perhaps want to invoke an extra plugin which outputs to csvlog as jsonlog cascades through things. -- Michael
Вложения
On 27 February 2018 at 02:04, Michael Paquier <michael@paquier.xyz> wrote: > On Mon, Feb 26, 2018 at 05:38:56PM +0000, Greg Stark wrote: >> I tried loading the jsonlog module from >> https://github.com/michaelpq/pg_plugins into Postgres 9.6. >> >> However it seems it resulted in logs only for session log messages but >> not any background worker log messages. We have log_checkpoints set >> but there were no log messages in the json log about checkpoints. Nor >> were there any from autovacuum. > > Hm. I have just loaded jsonlog on a 9.6 and 10 instance where > log_checkpoints is enabled with this background worker which logs a > simple string every 10s: > https://github.com/michaelpq/pg_plugins/tree/master/hello_world > > Both checkpoint logs and the logs of the bgworker are showing up for me. Weird. I guess I have some more debugging with gdb to do. >> Also I have log_destination set to stderr,cvslog and as I understand >> it the jsonlog module effectively overrides the "stderr" output which >> goes to the file named *.log (which I find super confusing, >> incidentally). But I was expecting to get the csv file as well. We >> didn't, we only got the *.log file with the (partial) json logs. Is >> there something I'm missing here or is this unexpected? > > Yeah, that's unfortunately expected... jsonlog enforces > edata->output_to_server to false, which has the advantage of disabling > extra log outputs, but also has the advantage of preventing duplicate > entries into stderr. One way that I can see to solve things would be to > patch the backend and get output_to_server replaced by a filter which > allows a plugin to choose what are the extra output types allowed. In > this case you don't want stderr later on, but would still want csvlog to > happen, instead of having an all-or-nothing switch. I haven't tested, > but it could be possible to have as well jsonlog enforce Log_destination > to only use csvlog after it generates its entry so as stderr is not > duplicated by csvlog gets though. Not sure how you would reset the > parameter though, so you may perhaps want to invoke an extra plugin > which outputs to csvlog as jsonlog cascades through things. I would actually lean another way. If jsonlog opened *.json and wrote there then it could leave the output_to_server field unchanged. It does look like this might be a bit awkward with yet more of the static functions needing to be duplicated. -- greg
On Tue, Feb 27, 2018 at 04:50:24PM +0000, Greg Stark wrote: > I would actually lean another way. If jsonlog opened *.json and wrote > there then it could leave the output_to_server field unchanged. It > does look like this might be a bit awkward with yet more of the static > functions needing to be duplicated. Which brings in why the chunked protocol that the syslogger uses is useful, because by using a custom file you would either need to introduce a global locking mechanism or to create a background worker that jsonlog can feed its data to so as the log file does not finish with overlapping writes. This bgworker which could use its own protocol or use the same protocol as the syslogger, resulting in a sort of secondary syslogger process. If you feel motivated to code anything like that, I'll be happy to merge it in my tree with jsonlog :) -- Michael
Вложения
On 27 February 2018 at 16:50, Greg Stark <stark@mit.edu> wrote: > On 27 February 2018 at 02:04, Michael Paquier <michael@paquier.xyz> wrote: >> On Mon, Feb 26, 2018 at 05:38:56PM +0000, Greg Stark wrote: >> >> Hm. I have just loaded jsonlog on a 9.6 and 10 instance where >> log_checkpoints is enabled with this background worker which logs a >> simple string every 10s: >> https://github.com/michaelpq/pg_plugins/tree/master/hello_world >> >> Both checkpoint logs and the logs of the bgworker are showing up for me. > > Weird. I guess I have some more debugging with gdb to do. I think I see what's going on. The log_min_messages is set to the default value of warning. Which is a higher level than "LOG" so this code in jsonlog.c is ignoring these messages: if (edata->elevel < log_min_messages) return; But the normal processing for logs uses is_log_level_output to compare error levels with log_min_messages which treats LOG (and LOG_SERVER_ONLY) as logically equivalent to ERROR: /* * is_log_level_output -- is elevel logically >= log_min_level? * * We use this for tests that should consider LOG to sort out-of-order, * between ERROR and FATAL. Generally this is the right thing for testing * whether a message should go to the postmaster log, whereas a simple >= * test is correct for testing whether the message should go to the client. */ static bool is_log_level_output(int elevel, int log_min_level) { if (elevel == LOG || elevel == LOG_SERVER_ONLY) { if (log_min_level == LOG || log_min_level <= ERROR) return true; } else if (log_min_level == LOG) { /* elevel != LOG */ if (elevel >= FATAL) return true; } /* Neither is LOG */ else if (elevel >= log_min_level) return true; return false; } -- greg