json log output problem sometimes

[dmpvost]

Hello!

First thank for this plugin it's very nice!!!

I got some problem with the output time to time. It's like a part of postgresql continue to generate some log as text.

Capture

I use json for forward my log to elasticsearch and it make some trouble to parse it.

Capture elasticsearch

Do you have some advice? thank.

postgresql : 9.5
Ubuntu 16.04.3 LTS

[michaelpq]

As far as I can see, the SQL statements are using quotes which are messing up with the JSON format produced. If you have a schema where the problem is reproducible, this could offer a base for an investigation. Until then, it is hard to dig into what you are seeing.

[dmpvost]

ok, I'm looking how i can do it :

One of my case is a python script :

CREATE OR REPLACE FUNCTION exec ( query TEXT ) RETURNS TEXT LANGUAGE plpythonu AS $$ import os tmp = os.popen(query).read() return tmp $$;

I execute it with curl & google map for calculate best road in background with a trigger.

When I execute curl I have in my log file :

% Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 70069 0 70069 0 0 144k 0 --:--:-- --:--:-- --:--:-- 144k

And generally I have different script which work with trigger or with shell in background because some task are too long, and so the client didn't need to wait the end of action.
Some of them work with crontab

exemple

psql -U postgres -d exemple -tc "SELECT * FROM road_refresh_for_ride(8);" &

[dmpvost]

On my SQL code I have a lot of commentary like this using pipe :

a := b -- HELLO | EXEMPLE | LOG

[dmpvost]

I use a function for generate my own error :

`CREATE FUNCTION raise_exception
(
http_code INTEGER
, oxy_err TEXT
, severity INTEGER
, v_message TEXT
)
RETURNS BOOLEAN
LANGUAGE plpgsql
AS $$
DECLARE
severity_text TEXT;
special_field TEXT;
BEGIN

IF severity = 1
THEN
severity_text := '1:ALERT';
ELSEIF severity = 2
THEN
severity_text := '2:CRITICAL';
ELSEIF severity = 3
THEN
severity_text := '3:ERROR';
ELSEIF severity = 4
THEN
severity_text := '4:WARNING';
ELSEIF severity = 5
THEN
severity_text := '5:NOTICE';
ELSE
severity_text := '0:EMERGENCY';
END IF;

special_field := http_code || '|' || oxy_err || '|' || severity_text;

RAISE EXCEPTION '%', v_message
USING HINT = special_field,
DETAIL = special_field;

RETURN FALSE;

END;
$$;
`

exemple of error in IDE

Thank in advance for helping

[dmpvost]

Any idea @michaelpq ?

[michaelpq]

Still, I did not find the time to dig into that.

[gsstark]

None of those links appears to work any more. I'm curious what the error was. Could you post enough to see the problem here?

[dmpvost]

I have update all link, they are up now.
Let me know if I can help, or provide more information

[gsstark]

Are you using the logging collector? If not I think you'll have problems like this due to multiple processes writing to the same file getting their logs interleaved.

You might also check with lsof or puser whether there are any other processes writing to the log file but I don't see how that could happen.

[henkjan]

I also see the same problem, running posgresql 9.6.6 with pg_audit extension enabled. Some loglines start with a few chars noise. As you can see in the log output, the problem doesnt always show up. The 'checkpoint starting: xlog' logline sometimes starts with a few chars of garbage, but the last line isnt affected. Also the loglines from pg_audit are just sometimes wrong.

{"timestamp":"2018-03-08T10:39:20.917 UTC","pid":266,"session_id":"5aa112d8.10a","error_severity":"LOG","message":"database system was shut down at 2018-03-08 10:39:19 UTC"}
 {"timestamp":"2018-03-08T10:39:20.922 UTC","pid":266,"session_id":"5aa112d8.10a","error_severity":"LOG","message":"MultiXact member wraparound protections are now enabled"}
 {"timestamp":"2018-03-08T10:39:20.928 UTC","pid":1,"session_id":"5aa112d8.1","error_severity":"LOG","message":"database system is ready to accept connections"}
 {"timestamp":"2018-03-08T10:39:20.928 UTC","pid":270,"session_id":"5aa112d8.10e","error_severity":"LOG","message":"autovacuum launcher started"}
 {"timestamp":"2018-03-08T10:40:02.124 UTC","pid":273,"remote_host":"172.18.0.1","remote_port":"35858","session_id":"5aa11302.111","error_severity":"LOG","message":"connection received: host=172.18.0.1 port=35858"}
 {"timestamp":"2018-03-08T10:40:25.837 UTC","pid":275,"remote_host":"172.18.0.1","remote_port":"35942","session_id":"5aa11319.113","error_severity":"LOG","message":"connection received: host=172.18.0.1 port=35942"}
 {"timestamp":"2018-03-08T10:40:39.167 UTC","pid":276,"remote_host":"172.18.0.1","remote_port":"35974","session_id":"5aa11327.114","error_severity":"LOG","message":"connection received: host=172.18.0.1 port=35974"}
 {"timestamp":"2018-03-08T10:40:39.169 UTC","user":"ctr_mgmt","dbname":"ctr_mgmt","pid":276,"remote_host":"172.18.0.1","remote_port":"35974","session_id":"5aa11327.114","vxid":"2/7","error_severity":"LOG","message":"connection authorized: user=ctr_mgmt database=ctr_mgmt"}
 {"timestamp":"2018-03-08T10:40:39.169 UTC","user":"ctr_mgmt","dbname":"ctr_mgmt","pid":276,"remote_host":"172.18.0.1","remote_port":"35974","session_id":"5aa11327.114","vxid":"2/7","error_severity":"FATAL","state_code":"3D000","message":"database \"ctr_mgmt\" does not exist"}
 {"timestamp":"2018-03-08T10:40:43.850 UTC","pid":277,"remote_host":"172.18.0.1","remote_port":"35990","session_id":"5aa1132b.115","error_severity":"LOG","message":"connection received: host=172.18.0.1 port=35990"}
 {"timestamp":"2018-03-08T10:40:45.526 UTC","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","error_severity":"LOG","message":"connection received: host=172.18.0.1 port=35998"}
 {"timestamp":"2018-03-08T10:40:45.528 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/9","error_severity":"LOG","message":"connection authorized: user=ctr_mgmt database=ctr"}
 {"timestamp":"2018-03-08T10:41:14.222 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/10","txid":572,"error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,1,1,DDL,CREATE TABLE,TABLE,public.document_template,\"CREATE TABLE DOCUMENT_TEMPLATE(\n   ID INTEGER NOT NULL,                                                 \n   NAME TEXT,                                  \n   SHORT_DESCRIPTION TEXT,\n   AUTHOR TEXT,                                         \n   DESCRIPTION TEXT,                                          \n   CONTENT TEXT,\n   LAST_UPDATED DATE,\n   CREATED DATE\n);\",<not logged>"}
 {"timestamp":"2018-03-08T10:41:23.211 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/11","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,2,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,100) id;\",<not logged>"}
 {"timestamp":"2018-03-08T10:44:20.729 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: time"}
 {"timestamp":"2018-03-08T10:44:25.918 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 47 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=4.834 s, sync=0.155 s, total=5.189 s; sync files=36, longest=0.078 s, average=0.004 s; distance=140248 kB, estimate=140248 kB"}
 {"timestamp":"2018-03-08T10:45:34.604 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/12","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,3,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,100) id;\",<not logged>"}
 \",<not {"timestamp":"2018-03-08T10:45:40.873 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/13","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,4,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,1000) id;\",<not logged>"}
 {"timestamp":"2018-03-08T10:49:20.596 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: time"}
 s; sync {"timestamp":"2018-03-08T10:49:25.009 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 37 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 9 recycled; write=3.903 s, sync=0.010 s, total=4.413 s; sync files=9, longest=0.006 s, average=0.001 s; distance=163840 kB, estimate=163840 kB"}
 {"timestamp":"2018-03-08T10:52:32.465 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/14","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,5,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,1000) id;\",<not logged>"}
 ",<not l{"timestamp":"2018-03-08T10:52:34.197 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/15","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,6,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,1000) id;\",<not logged>"}
 {"timestamp":"2018-03-08T10:53:17.061 UTC","user":"ctr_mgmt","dbname":"ctr","pid":278,"remote_host":"172.18.0.1","remote_port":"35998","session_id":"5aa1132d.116","vxid":"2/16","error_severity":"LOG","application_name":"psql","message":"AUDIT: SESSION,7,1,WRITE,INSERT,,,\"INSERT INTO DOCUMENT_TEMPLATE(id,name, short_description, author,\n                              description,content, last_updated,created)\nSELECT id, 'name', md5(random()::text), 'name2'\n      ,md5(random()::text),md5(random()::text)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100)\n      ,NOW() - '1 day'::INTERVAL * (RANDOM()::int * 100 + 100)\nFROM generate_series(1,10000000) id;\",<not logged>"}
 ot logge{"timestamp":"2018-03-08T10:53:28.495 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: xlog"}
 s; sync {"timestamp":"2018-03-08T10:53:38.842 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 66 buffers (0.4%); 0 transaction log file(s) added, 0 removed, 10 recycled; write=10.022 s, sync=0.057 s, total=10.347 s; sync files=7, longest=0.046 s, average=0.008 s; distance=413693 kB, estimate=413693 kB"}
 {"timestamp":"2018-03-08T10:53:45.373 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","hint":"Consider increasing the configuration parameter \"max_wal_size\".","message":"checkpoints are occurring too frequently (17 seconds apart)"}
 =10.347 {"timestamp":"2018-03-08T10:53:45.373 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: xlog"}
 47 s; sy{"timestamp":"2018-03-08T10:53:55.102 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 43 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 25 recycled; write=7.762 s, sync=0.857 s, total=9.728 s; sync files=2, longest=0.847 s, average=0.428 s; distance=409600 kB, estimate=413283 kB"}
 
 {"timestamp":"2018-03-08T10:54:01.906 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","hint":"Consider increasing the configuration parameter \"max_wal_size\".","message":"checkpoints are occurring too frequently (16 seconds apart)"}
 9.728 s;{"timestamp":"2018-03-08T10:54:01.906 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: xlog"}
  s; sync{"timestamp":"2018-03-08T10:54:10.405 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 100 buffers (0.6%); 0 transaction log file(s) added, 0 removed, 25 recycled; write=6.819 s, sync=1.211 s, total=8.498 s; sync files=3, longest=0.867 s, average=0.403 s; distance=409599 kB, estimate=412915 kB"}
 {"timestamp":"2018-03-08T10:54:15.599 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","hint":"Consider increasing the configuration parameter \"max_wal_size\".","message":"checkpoints are occurring too frequently (14 seconds apart)"}
 =8.498 s{"timestamp":"2018-03-08T10:54:15.599 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: xlog"}
 8 s; syn{"timestamp":"2018-03-08T10:54:23.473 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint complete: wrote 62 buffers (0.4%); 0 transaction log file(s) added, 0 removed, 25 recycled; write=5.815 s, sync=1.123 s, total=7.874 s; sync files=3, longest=1.088 s, average=0.374 s; distance=409599 kB, estimate=412583 kB"}
 {"timestamp":"2018-03-08T10:55:37.400 UTC","pid":267,"session_id":"5aa112d8.10b","error_severity":"LOG","message":"checkpoint starting: xlog"}

[gsstark]

Same question as the other poster Are you using the logging collector?

[henkjan]

i'm not using logging collector but log to stderr, running postgresql in docker.

[henkjan]

enabling logging collector seems to generate correct json output but output goes to file on disk.

while i'm running postgresql in docker i need my output to go to stderr

[dmpvost]

I don't use logging collector, I should look what is this. I have a default configuration.
I will try this logging collector next week and see the difference. There is something special to apply?

@henkjan : for your problem, maybe you can use something like rsyslog for read your log and print it to stderr ?

[michaelpq]

This is mentioned on the documentation of PostgreSQL:
https://www.postgresql.org/docs/devel/static/runtime-config-logging.html#GUC-LOGGING-COLLECTOR
"Also, on some platforms not using the logging collector can result in lost or garbled log output, because multiple processes writing concurrently to the same log file can overwrite each other's output."

So I am not surprised if you see things messed up, the json strings are way longer than normal logs so you increase the likelihood of messed up output. I am going to add a note in the README about that.

@dmpvost : are you using logging_collector = off? If you are enabling it and still see issues, then let's dig into any bug. If not, please enable it.

[henkjan]

@michaelpq thanks for your explanation.

@dmpvost running rsyslog within the docker container where postgres also lives is somewhat against my principles. i prefere running only one process

[dmpvost]

@gsstark @michaelpq thank, i will apply your advices and report after.

@michaelpq ok, i'm not an expert in docker, I have only try one or twice. I don't use it in production yet. Or maybe simple bash command : "tail -f" ? or something like this? Good luck!

[michaelpq]

I am closing the bug for now. If you see anything actually broken, feel free to reopen it by providing details about what you found.