Audit log of MISC class command is not displayed correctly in PostgreSQL development version. (refactored branch)

[harada-toshi]

Hi.

I am trying pgaudit (refactored branch).
Audit log of MISC class command is not displayed correctly in PostgreSQL development version.

pgaudit configuration file.

[option]
log_level = 'NOTICE'
log_catalog = on
log_for_test = on

[rule]
        format = 'AUDIT: %class,%command_tag,%object_type,%object_name,%command_text'

Executed SQL commands.

CREATE TABLE foo (id int primary key, data text);
INSERt INTO foo VALUES (1, 'aaa'),(2, 'bbb'),(3,'ccc');

-- VACUUM, ANALYZE,CHECKPOINT
VACUUM foo;
ANALYZE foo;
CHECKPOINT;

-- FETCH
BEGIN;
DECLARE mycur CURSOR FOR SELECT * FROM foo;
FETCH FORWARD 2 FROM mycur;
FETCH PRIOR FROM mycur;
PREPARE myprep AS SELECT * FROM foo WHERE id = $1;
EXECUTE myprep(2);
END;

-- DISCARD
DISCARD ALL;

DROP TABLE foo;

Class of audit log output summary

The following SQL command is MISC class in 9.6, but it is READ class in devel.

• VACUUM, ANALYZE, CHECKPOINT, BEGIN, FETCH, EXECUTE, COMMIT, DISCARD

Audit logs.

on 9.6.1

CREATE TABLE foo (id int primary key, data text);
psql:/tmp/sql_misc.sql:1: NOTICE:  AUDIT: SESSION,1,1,DDL,,testdb,[local],psql,,,,,CREATE TABLE,,,"CREATE TABLE foo (id int primary key, data text);",<not logged>
CREATE TABLE
INSERt INTO foo VALUES (1, 'aaa'),(2, 'bbb'),(3,'ccc');
psql:/tmp/sql_misc.sql:2: NOTICE:  AUDIT: SESSION,2,1,WRITE,,testdb,[local],psql,,,,,INSERT,TABLE,public.foo,"INSERt INTO foo VALUES (1, 'aaa'),(2, 'bbb'),(3,'ccc');",<not logged>
INSERT 0 3
VACUUM foo;
psql:/tmp/sql_misc.sql:5: NOTICE:  AUDIT: SESSION,3,1,MISC,,testdb,[local],psql,,,,,VACUUM,,,VACUUM foo;,<not logged>
VACUUM
ANALYZE foo;
psql:/tmp/sql_misc.sql:6: NOTICE:  AUDIT: SESSION,4,1,MISC,,testdb,[local],psql,,,,,ANALYZE,,,ANALYZE foo;,<not logged>
ANALYZE
CHECKPOINT;
psql:/tmp/sql_misc.sql:7: NOTICE:  AUDIT: SESSION,5,1,MISC,,testdb,[local],psql,,,,,CHECKPOINT,,,CHECKPOINT;,<not logged>
CHECKPOINT
BEGIN;
psql:/tmp/sql_misc.sql:10: NOTICE:  AUDIT: SESSION,6,1,MISC,,testdb,[local],psql,,,,,BEGIN,,,BEGIN;,<not logged>
BEGIN
DECLARE mycur CURSOR FOR SELECT * FROM foo;
psql:/tmp/sql_misc.sql:11: NOTICE:  AUDIT: SESSION,7,1,READ,,testdb,[local],psql,,,,,SELECT,TABLE,public.foo,DECLARE mycur CURSOR FOR SELECT * FROM foo;,<not logged>
psql:/tmp/sql_misc.sql:11: NOTICE:  AUDIT: SESSION,7,2,READ,,testdb,[local],psql,,,,,DECLARE CURSOR,,,DECLARE mycur CURSOR FOR SELECT * FROM foo;,<not logged>
DECLARE CURSOR
FETCH FORWARD 2 FROM mycur;
psql:/tmp/sql_misc.sql:12: NOTICE:  AUDIT: SESSION,8,1,MISC,,testdb,[local],psql,,,,,FETCH,,,FETCH FORWARD 2 FROM mycur;,<not logged>
 id | data
----+------
  1 | aaa
  2 | bbb
(2 rows)

FETCH PRIOR FROM mycur;
psql:/tmp/sql_misc.sql:13: NOTICE:  AUDIT: SESSION,9,1,MISC,,testdb,[local],psql,,,,,FETCH,,,FETCH PRIOR FROM mycur;,<not logged>
 id | data
----+------
  1 | aaa
(1 row)

PREPARE myprep AS SELECT * FROM foo WHERE id = $1;
psql:/tmp/sql_misc.sql:14: NOTICE:  AUDIT: SESSION,10,1,READ,,testdb,[local],psql,,,,,PREPARE,,,PREPARE myprep AS SELECT * FROM foo WHERE id = $1;,<not logged>
PREPARE
EXECUTE myprep(2);
psql:/tmp/sql_misc.sql:15: NOTICE:  AUDIT: SESSION,11,1,READ,,testdb,[local],psql,,,,,SELECT,TABLE,public.foo,PREPARE myprep AS SELECT * FROM foo WHERE id = $1;,<not logged>
psql:/tmp/sql_misc.sql:15: NOTICE:  AUDIT: SESSION,11,2,MISC,,testdb,[local],psql,,,,,EXECUTE,,,EXECUTE myprep(2);,<not logged>
 id | data
----+------
  2 | bbb
(1 row)

END;
psql:/tmp/sql_misc.sql:16: NOTICE:  AUDIT: SESSION,12,1,MISC,,testdb,[local],psql,,,,,COMMIT,,,END;,<not logged>
COMMIT
DISCARD ALL;
psql:/tmp/sql_misc.sql:19: NOTICE:  AUDIT: SESSION,13,1,MISC,,testdb,[local],psql,,,,,DISCARD ALL,,,DISCARD ALL;,<not logged>
DISCARD ALL
DROP TABLE foo;
psql:/tmp/sql_misc.sql:21: NOTICE:  AUDIT: SESSION,14,1,DDL,,testdb,[local],psql,,,,,DROP TABLE,,,DROP TABLE foo;,<not logged>
DROP TABLE

on devel

CREATE TABLE foo (id int primary key, data text);
psql:/tmp/sql_misc.sql:1: NOTICE:  AUDIT: SESSION,1,1,DDL,,testdb,[local],psql,,,,,CREATE TABLE,,,"CREATE TABLE foo (id int primary key, data text);",<not logged>
CREATE TABLE
INSERt INTO foo VALUES (1, 'aaa'),(2, 'bbb'),(3,'ccc');
psql:/tmp/sql_misc.sql:2: NOTICE:  AUDIT: SESSION,2,1,WRITE,,testdb,[local],psql,,,,,INSERT,TABLE,public.foo,"INSERt INTO foo VALUES (1, 'aaa'),(2, 'bbb'),(3,'ccc');",<not logged>
INSERT 0 3
VACUUM foo;
psql:/tmp/sql_misc.sql:5: NOTICE:  AUDIT: SESSION,3,1,READ,,testdb,[local],psql,,,,,VACUUM,,,VACUUM foo;,<not logged>
VACUUM
ANALYZE foo;
psql:/tmp/sql_misc.sql:6: NOTICE:  AUDIT: SESSION,4,1,READ,,testdb,[local],psql,,,,,ANALYZE,,,ANALYZE foo;,<not logged>
ANALYZE
CHECKPOINT;
psql:/tmp/sql_misc.sql:7: NOTICE:  AUDIT: SESSION,5,1,READ,,testdb,[local],psql,,,,,CHECKPOINT,,,CHECKPOINT;,<not logged>
CHECKPOINT
BEGIN;
psql:/tmp/sql_misc.sql:10: NOTICE:  AUDIT: SESSION,6,1,READ,,testdb,[local],psql,,,,,BEGIN,,,BEGIN;,<not logged>
BEGIN
DECLARE mycur CURSOR FOR SELECT * FROM foo;
psql:/tmp/sql_misc.sql:11: NOTICE:  AUDIT: SESSION,7,1,READ,,testdb,[local],psql,,,,,SELECT,TABLE,public.foo,DECLARE mycur CURSOR FOR SELECT * FROM foo;,<not logged>
psql:/tmp/sql_misc.sql:11: NOTICE:  AUDIT: SESSION,7,2,READ,,testdb,[local],psql,,,,,DECLARE CURSOR,,,DECLARE mycur CURSOR FOR SELECT * FROM foo;,<not logged>
DECLARE CURSOR
FETCH FORWARD 2 FROM mycur;
psql:/tmp/sql_misc.sql:12: NOTICE:  AUDIT: SESSION,8,1,READ,,testdb,[local],psql,,,,,FETCH,,,FETCH FORWARD 2 FROM mycur;,<not logged>
 id | data
----+------
  1 | aaa
  2 | bbb
(2 rows)

FETCH PRIOR FROM mycur;
psql:/tmp/sql_misc.sql:13: NOTICE:  AUDIT: SESSION,9,1,READ,,testdb,[local],psql,,,,,FETCH,,,FETCH PRIOR FROM mycur;,<not logged>
 id | data
----+------
  1 | aaa
(1 row)

PREPARE myprep AS SELECT * FROM foo WHERE id = $1;
psql:/tmp/sql_misc.sql:14: NOTICE:  AUDIT: SESSION,10,1,READ,,testdb,[local],psql,,,,,PREPARE,,,PREPARE myprep AS SELECT * FROM foo WHERE id = $1;,<not logged>
PREPARE
EXECUTE myprep(2);
psql:/tmp/sql_misc.sql:15: NOTICE:  AUDIT: SESSION,11,1,READ,,testdb,[local],psql,,,,,SELECT,TABLE,public.foo,PREPARE myprep AS SELECT * FROM foo WHERE id = $1;,<not logged>
psql:/tmp/sql_misc.sql:15: NOTICE:  AUDIT: SESSION,11,2,READ,,testdb,[local],psql,,,,,EXECUTE,,,EXECUTE myprep(2);,<not logged>
 id | data
----+------
  2 | bbb
(1 row)

END;
psql:/tmp/sql_misc.sql:16: NOTICE:  AUDIT: SESSION,12,1,READ,,testdb,[local],psql,,,,,COMMIT,,,END;,<not logged>
COMMIT
DISCARD ALL;
psql:/tmp/sql_misc.sql:19: NOTICE:  AUDIT: SESSION,13,1,READ,,testdb,[local],psql,,,,,DISCARD ALL,,,DISCARD ALL;,<not logged>
DISCARD ALL
DROP TABLE foo;
psql:/tmp/sql_misc.sql:21: NOTICE:  AUDIT: SESSION,14,1,DDL,,testdb,[local],psql,,,,,DROP TABLE,,,DROP TABLE foo;,<not logged>
DROP TABLE

[MasahikoSawada]

Thank you for reporting.

I guess this cause is that the commit ab1f0c8225714aaa18d2f9ca4f80cd009f145421 changed the argument type of ProcessUtility. We should deal with this after feature freezed or at least PG 10 beta released.

[harada-toshi]

Thanks for your answer.
Also, I understand that we can not respond immediately.
This problem seems to affect "pgaudit (master branchl)" as well.