pg logs filling up very fast after starting the pgAudit Analyzer daemon

[pgaudit]

pg logs filling up very fast after starting the pgAudit Analyzer daemon

[dwsteele]

Hi Dylan,

You can reduce the audit log volume by disabling audit logging for the pgaudit user:

alter role pgaudit set pgaudit.log = 'none';
alter role pgaudit set pgaudit.role = '';

I'll also add this to the basic install scripts.

[dwsteele]

This works for me - committed at 0bff1be.

[dylanluong]

Hi dwsteele,
I tried your suggestion, unfortunately it did not resolve the issue. I am still getting those entries filling up the log/csv as soon as I start the daemon.

[dwsteele]

Since you are not logging the statements it's hard to tell what's going on, but I would disable logging for postgres in general. Follow the same steps for pgaudit above.

[dylanluong]

Hi dwsteele
I have trialled the pgaudit/pgaudit_analyzer install on another postgres instance. I enable extension on a testdb and ran the sql/audit.sql against this testdb and its ok (after starting the daemon), however, it appears that this issue starts as soon as I enable pgaudit extension on the postgres database (after running sql/audit.sql script against postgres database) and starting up the pgAudit_analyzw daemon. So I tried to disable pgaudit logging of the postgres database (as you suggested) by dropping the extension and restarted everything. But that did not stop the issue? what else do I need to do to disable pgaudit logging on the postgres database?

[dylanluong]

Hi dwsteele
I have dropped the pgaudit schema in the protgres database (and dropped the extension pgaudit as well) and it appears to have stopped logging the postgres database. However now I am seeing these repeated records filling up the csv files (it is now on the testdb):
2017-07-18 17:03:47.577 ACST,"postgres","testdb",10115,"[local]",596db7f8.2783,1166300,"BEGIN",2017-07-18 16:55:44 ACST,5/154009,0,LOG,00000,"AUDIT: SESSION,307633,1,MISC,BEGIN,,,begin,",,,,,,,,,""
2017-07-18 17:03:47.577 ACST,"postgres","testdb",10115,"[local]",596db7f8.2783,1166301,"BEGIN",2017-07-18 16:55:44 ACST,5/154009,0,LOG,00000,"duration: 0.031 ms",,,,,,,,,""
2017-07-18 17:03:47.577 ACST,"postgres","testdb",10115,"[local]",596db7f8.2783,1166302,"BIND",2017-07-18 16:55:44 ACST,5/154009,0,LOG,00000,"duration: 0.019 ms",,,,,,,,,""
2017-07-18 17:03:47.577 ACST,"postgres","testdb",10115,"[local]",596db7f8.2783,1166303,"INSERT",2017-07-18 16:55:44 ACST,5/154009,901103,LOG,00000,"duration: 0.081 ms",,,,,,,,,""

I am seeing the following local process that corresponds to the records in the csv logs.

postgres 10115 9893 14 16:55 ? 00:02:06 postgres: postgres testdb [local] COMMIT

Stopping the pgaudit analyzer daemon stops this local process.

I am running the daemon as the postgres OS user. this is the command to start the daemon:
$ ./pgaudit_analyze --daemon --log-file=/var/lib/pgsql/9.6/pgAudit_analyze/bin/pgaudit_analyze.log /pg_logs/data/pg_log

[dylanluong]

Hi
Please help me out.

[dylanluong]

Ok, I think the issue is related to setting up auditing to include 'misc'.
ie when I set the pgaudit.log = 'role, ddl, misc'

eg, I get the following records filling up the .csv file continuously;

2017-07-25 15:20:35.824 ACST LOG: AUDIT: SESSION,2450,1,MISC,COMMIT,,,commit,
2017-07-25 15:20:35.826 ACST LOG: AUDIT: SESSION,2451,1,MISC,BEGIN,,,begin,
2017-07-25 15:20:35.826 ACST LOG: AUDIT: SESSION,2452,1,MISC,COMMIT,,,commit,
2017-07-25 15:20:35.828 ACST LOG: AUDIT: SESSION,2453,1,MISC,BEGIN,,,begin,
2017-07-25 15:20:35.828 ACST LOG: AUDIT: SESSION,2454,1,MISC,COMMIT,,,commit,
2017-07-25 15:20:35.830 ACST LOG: AUDIT: SESSION,2455,1,MISC,BEGIN,,,begin,
2017-07-25 15:20:35.830 ACST LOG: AUDIT: SESSION,2456,1,MISC,COMMIT,,,commit,
2017-07-25 15:20:35.832 ACST LOG: AUDIT: SESSION,2457,1,MISC,BEGIN,,,begin,

If I remove 'misc' from the pgaudit.log, restart postggres and start the daemon, its appears to be ok.
Is this a bug of the Daemon?

[dwsteele]

Hi Dylan, sorry for the late reply, I've been on vacation the last three weeks and am just catching up now.

This is not a bug in the daemon. The goal of pgaudit it to allow everything to be logged but in fact there are many commands (like BEGIN and COMMIT) that are not very useful to log and can be very noisy as you have witnessed. These have been placed in the misc category so they are easily excluded and I would recommend that you do so.

[dylanluong]

Hi
Now that I am not auditing 'misc' I don't get any more of those (LOG: AUDIT: SESSION,2450,1,MISC,COMMIT,,,commit,) noises, but I think my original issue where setting "log_duration = on" in the postgresql.conf is still an issue.
I think those log entries that I mentioned in my first post, is just the feature of having 'log_during = on'.
So I am still geting large csv files fill up a by these pgaudit analyzer daemon session values:
2017-08-11 17:43:34.660 ACST,"postgres","moodle",134855,"[local]",598d5ddb.20ec7,9017684,"INSERT",2017-08-11 17:03:47 ACST,6/2254941,16340431,LOG,00000,"duration: 0.061 ms",,,,,,,,,""
2017-08-11 17:43:34.661 ACST,"postgres","moodle",134855,"[local]",598d5ddb.20ec7,9017685,"COMMIT",2017-08-11 17:03:47 ACST,6/0,0,LOG,00000,"duration: 0.935 ms",,,,,,,,,""
2017-08-11 17:43:34.662 ACST,"postgres","moodle",134855,"[local]",598d5ddb.20ec7,9017686,"BEGIN",2017-08-11 17:03:47 ACST,6/2254942,0,LOG,00000,"duration: 0.008 ms",,,,,,,,,""
2017-08-11 17:43:34.662 ACST,"postgres","moodle",134855,"[local]",598d5ddb.20ec7,9017687,"BIND",2017-08-11 17:03:47 ACST,6/2254942,0,LOG,00000,"duration: 0.013 ms",,,,,,,,,""

Is it possible to exclude these noise as well in the csv file?

I find also that looking at the pgaudit_analyze.log file, the daemon seem to stuck at reading a (large) csv file and is not moving onto the next file csv file.
eg:
here is the last few log\csv file in my log directory:
-rw-------. 1 postgres postgres 502K Aug 11 16:00 postgresql-11-08-17-14-56.csv
-rw-------. 1 postgres postgres 2.3M Aug 11 16:00 postgresql-11-08-17-15-00.csv
-rw-------. 1 postgres postgres 1.8M Aug 11 16:00 postgresql-11-08-17-15-30.csv
-rw-------. 1 postgres postgres 324K Aug 11 16:00 postgresql-11-08-17-15-55.csv
-rw-------. 1 postgres postgres 384M Aug 11 16:30 postgresql-11-08-17-16-30.log
-rw-------. 1 postgres postgres 160M Aug 11 16:33 postgresql-11-08-17-16-00.log
-rw-------. 1 postgres postgres 229M Aug 11 16:43 postgresql-11-08-17-16-00.csv
-rw-------. 1 postgres postgres 85K Aug 11 16:58 postgresql-11-08-17-16-58.log
-rw-------. 1 postgres postgres 112K Aug 11 16:59 postgresql-11-08-17-16-58.csv
-rw-------. 1 postgres postgres 549M Aug 11 17:09 postgresql-11-08-17-16-30.csv
-rw-------. 1 postgres postgres 658M Aug 11 17:21 postgresql-11-08-17-17-00.log
-rw-------. 1 postgres postgres 942M Aug 11 17:22 postgresql-11-08-17-17-00.csv
-rw-------. 1 postgres postgres 844M Aug 11 17:47 postgresql-11-08-17-17-30.log
-rw-------. 1 postgres postgres 1.2G Aug 11 17:50 postgresql-11-08-17-17-30.csv

eg:
my the pgaudit_analyze.log file seem to stuck at reading "postgresql-11-08-17-16-30.csv"

$ more pgaudit_analyze.log
session select 598d3ff6.1ba65: sessionreading postgresql-11-08-17-15-00.csv
reading postgresql-11-08-17-15-30.csv
reading postgresql-11-08-17-15-55.csv
reading postgresql-11-08-17-16-00.csv
reading postgresql-11-08-17-16-30.csv
tement_id 0, substatement_id 0
session select 598d4064.1bb76: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4065.1bb78: session_line_num 459, statement_id 0, substatement_id 0
session select 598d406e.1bb88: session_line_num 18, statement_id 0, substatement_id 0
session select 598d40ab.1bca2: session_line_num 12, statement_id 0, substatement_id 0
session select 598d40af.1bce1: session_line_num 12, statement_id 0, substatement_id 0
session select 598d40b4.1bd20: session_line_num 12, statement_id 0, substatement_id 0
session select 598d40cd.1beb0: session_line_num 12, statement_id 0, substatement_id 0
session select 598d40e6.1bee8: session_line_num 18, statement_id 0, substatement_id 0
session select 598d415e.1bfc4: session_line_num 18, statement_id 0, substatement_id 0
session select 598d41b1.1c07c: session_line_num 23, statement_id 0, substatement_id 0
session select 598d41b2.1c07e: session_line_num 459, statement_id 0, substatement_id 0
session select 598d41d6.1c0cf: session_line_num 18, statement_id 0, substatement_id 0
session select 598d41ef.1c0ee: session_line_num 23, statement_id 0, substatement_id 0
session select 598d41ef.1c0f0: session_line_num 459, statement_id 0, substatement_id 0
session select 598d424e.1c17f: session_line_num 18, statement_id 0, substatement_id 0
session select 598d42c6.1c28d: session_line_num 18, statement_id 0, substatement_id 0
session select 598d433e.1c372: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4360.1c39c: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4361.1c39e: session_line_num 459, statement_id 0, substatement_id 0
session select 598d43b6.1c43c: session_line_num 18, statement_id 0, substatement_id 0
session select 598d442e.1c573: session_line_num 18, statement_id 0, substatement_id 0
session select 598d44a6.1c61d: session_line_num 18, statement_id 0, substatement_id 0
session select 598d451e.1c72a: session_line_num 18, statement_id 0, substatement_id 0
session select 598d458b.1c7df: session_line_num 23, statement_id 0, substatement_id 0
session select 598d458c.1c7e1: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4596.1c7f3: session_line_num 18, statement_id 0, substatement_id 0
session select 598d460e.1c8b3: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4686.1ccfe: session_line_num 18, statement_id 0, substatement_id 0
session select 598d46fc.1cdaa: session_line_num 23, statement_id 0, substatement_id 0
session select 598d46fc.1cdac: session_line_num 459, statement_id 0, substatement_id 0
session select 598d46fe.1cdba: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4761.1cec4: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4762.1cec6: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4776.1ceec: session_line_num 18, statement_id 0, substatement_id 0
session select 598d47b3.1d006: session_line_num 12, statement_id 0, substatement_id 0
session select 598d47b7.1d046: session_line_num 12, statement_id 0, substatement_id 0
session select 598d47bc.1d085: session_line_num 12, statement_id 0, substatement_id 0
session select 598d47d5.1d214: session_line_num 12, statement_id 0, substatement_id 0
session select 598d47ee.1d24c: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4866.1d30e: session_line_num 18, statement_id 0, substatement_id 0
session select 598d48c0.1d3d0: session_line_num 23, statement_id 0, substatement_id 0
session select 598d48c1.1d3d1: session_line_num 459, statement_id 0, substatement_id 0
session select 598d48de.1d41a: session_line_num 18, statement_id 0, substatement_id 0
session select 598d48fa.1d43e: session_line_num 23, statement_id 0, substatement_id 0
session select 598d48fb.1d440: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4956.1d4c3: session_line_num 18, statement_id 0, substatement_id 0
session select 598d49cf.1d5da: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4a46.1d6ae: session_line_num 19, statement_id 0, substatement_id 0
session select 598d4a68.1d6d8: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4a69.1d6da: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4a6a.1d6dd: session_line_num 61, statement_id 20, substatement_id 5
session select 598d4a74.1d6ec: session_line_num 4, statement_id 0, substatement_id 0
session select 598d4abe.1d77d: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4b36.1d8c8: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4bae.1d970: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4c26.1da7c: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4c94.1db31: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4c95.1db34: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4c9f.1db44: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4d16.1dc18: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4d8e.1e061: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4e04.1e116: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4e05.1e118: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4e06.1e126: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4e67.1e223: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4e68.1e225: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4e7e.1e254: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4eba.1e36f: session_line_num 12, statement_id 0, substatement_id 0
session select 598d4ebf.1e3ae: session_line_num 12, statement_id 0, substatement_id 0
session select 598d4ec4.1e3ee: session_line_num 12, statement_id 0, substatement_id 0
session select 598d4edd.1e57d: session_line_num 12, statement_id 0, substatement_id 0
session select 598d4ef7.1e5b5: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4f04.1e5cc: session_line_num 1150259, statement_id 0, substatement_id 0
session select 598d4f6e.1e6bd: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4fc0.1e778: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4fc1.1e77a: session_line_num 459, statement_id 0, substatement_id 0
session select 598d4fe6.1e7cc: session_line_num 18, statement_id 0, substatement_id 0
session select 598d4ffe.1e7ed: session_line_num 23, statement_id 0, substatement_id 0
session select 598d4fff.1e7ef: session_line_num 459, statement_id 0, substatement_id 0
session insert = 598d505e.1e885
session insert = 598d50d6.1e996
session insert = 598d50f6.1e9bf
session insert = 598d50f6.1e9c0
session insert = 598d514e.1ea6a
session insert = 598d5171.1ea96
session insert = 598d5171.1ea98
session insert = 598d51c6.1eb34
session insert = 598d523f.1ec62
session insert = 598d52b6.1ed0b
session insert = 598d532e.1ee1a
session insert = 598d539c.1eee1
session insert = 598d539c.1eee3
session insert = 598d53a7.1eef3
session insert = 598d541e.1efb3
session insert = 598d5496.1f3fe
session insert = 598d550d.1f4ab
session insert = 598d550d.1f4ad
session insert = 598d550e.1f4b9
session insert = 598d5571.1f5b1
session insert = 598d5572.1f5b3
session insert = 598d5586.1f5d9
session insert = 598d55c3.1f6f7
session insert = 598d55c7.1f738
session insert = 598d55cc.1f777
session insert = 598d55e5.1f906
session insert = 598d55fe.1f93d
session insert = 598d5676.1f9ff
session insert = 598d56c9.1fabb
session insert = 598d56c9.1fabc
session insert = 598d56ef.1fb0d
session insert = 598d5707.1fb2d
session insert = 598d5707.1fb2f
session insert = 598d5766.1fbc9
session insert = 598d57de.1fcd6
session insert = 598d581f.1fd4f
session update = 598d581f.1fd4f, application = pgAdmin 4 - DB:moodle
session insert = 598d5856.1fdab
session insert = 598d5879.1fdd7
session insert = 598d5879.1fdd9
session insert = 598d589f.1fe18
session update = 598d589f.1fe18, application = pgAdmin 4 - DB:moodle
session insert = 598d58a5.1fe21
session update = 598d58a5.1fe21, application = pgAdmin 4 - CONN:6377698
session insert = 598d58ce.1fe7b
session insert = 598d591e.1ff53
session insert = 598d5946.1ffbf
session insert = 598d59be.20070
session insert = 598d5a36.20184
session insert = 598d5aa4.20290
session insert = 598d5aa5.20292
session insert = 598d5aae.202a1
session insert = 598d5b26.20367

Thanks for your help.

[dwsteele]

Is it possible to exclude these noise as well in the csv file?

Currently there is no way to filter these in pgaudit_analyze. I would suggest increasing log_min_duration_statement to something meaningful. Are you really interested in statements that run in 0.008 ms?

the daemon seem to stuck at reading a (large) csv file and is not moving onto the next file csv file

I prefer to do log rotation at no more than 100MB as anything larger can be unwieldy to work with. It may be that you are running into some resource constraint here, but it's hard to tell from the information given.