MySQL Bugs: #107390: Audit plugin does not log multiqueries correctly

Bug #107390	Audit plugin does not log multiqueries correctly
Submitted:	24 May 2022 20:48	Modified:	8 Dec 2022 16:13
Reporter:	Manuel Ung	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Security: Audit	Severity:	S3 (Non-critical)
Version:	8.0.29	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
The audit plugin does not log multiqueries correctly, and will always log the full request, instead of only the query of interested.

How to repeat:
Make this small change in sql_audit.cc to print out the query being logged.

diff --git a/sql/sql_audit.cc b/sql/sql_audit.cc
index 2dce8622f25..827b157de62 100644
--- a/sql/sql_audit.cc
+++ b/sql/sql_audit.cc
@@ -309,6 +309,7 @@ inline const CHARSET_INFO *thd_get_audit_query(THD *thd,
   } else {
     query->str = thd->query().str;
     query->length = thd->query().length;
+    fprintf(stderr, "%*s\n", (int)query->length, query->str);
     return thd->charset();
   }
 }

Run this mtr test:

diff --git a/mysql-test/suite/audit_null/t/foo-master.opt b/mysql-test/suite/audit_null/t/foo-master.opt
new file mode 100644
index 00000000000..bc88b4d7d91
--- /dev/null
+++ b/mysql-test/suite/audit_null/t/foo-master.opt
@@ -0,0 +1 @@
+$AUDIT_NULL_OPT
\ No newline at end of file
diff --git a/mysql-test/suite/audit_null/t/foo.test b/mysql-test/suite/audit_null/t/foo.test
new file mode 100644
index 00000000000..4e857ca3c67
--- /dev/null
+++ b/mysql-test/suite/audit_null/t/foo.test
@@ -0,0 +1,12 @@
+--source include/have_null_audit_plugin.inc
+--source include/no_protocol.inc
+
+--replace_regex /\.dll/.so/
+eval INSTALL PLUGIN null_audit SONAME '$AUDIT_NULL';
+
+delimiter |;
+select 1; select 2; select 3; select 4; select 5;|
+delimiter ;|
+
+
+UNINSTALL PLUGIN null_audit;

Check error logs and find:

select 1; select 2; select 3; select 4; select 5
select 1; select 2; select 3; select 4; select 5
select 1; select 2; select 3; select 4; select 5
select 1; select 2; select 3; select 4; select 5
select 2; select 3; select 4; select 5
select 2; select 3; select 4; select 5
select 2; select 3; select 4; select 5
select 2; select 3; select 4; select 5
select 3; select 4; select 5
select 3; select 4; select 5
select 3; select 4; select 5
select 3; select 4; select 5
select 4; select 5
select 4; select 5
select 4; select 5
select 4; select 5
select 5
select 5
select 5
select 5
select 5

The expected output should be:
select 1;
select 1;
select 1;
select 1;
select 2;
select 2;
select 2;
select 2;
select 3;
select 3;
select 3;
select 3;
select 4;
select 4;
select 4;
select 4;
select 5;
select 5;
select 5;
select 5;
select 5;

Suggested fix:
There are different call sites depending on the audit event class.

At least, for MYSQL_AUDIT_GENERAL_LOG, we do have the query length information passed into Query_logger::general_log_write. However, we throw away that information when we call mysql_audit_general_log.

The most general solution is probably to store the current query length on the THD so that it is accessible from thd_get_audit_query. I'm not sure how safe it is to use m_parser_state->m_lip.found_semicolon directly.

Hello Manuel Ung,

Thank you for the report and feedback.

regards,
Umesh

Posted by developer:
 
I am guessing this is only a problem for the GENERAL LOG events. And that's because the general log event is logged before the query is manipulated into the THD. The query events should be fine since the logging is done after the THD data are reset. 

Can you maybe be specific on which event classes do you see the issue?

fprintf line should be:
fprintf(stderr, "%.*s\n", (int)query->length, query->str);

fprintf line should be:
fprintf(stderr, "%.*s\n", (int)query->length, query->str);

Yes, you're right, it only affects GENERAL LOG events. I got my fprintf statement wrong, so it looked like it affected all event classes.

Posted by developer:
 
Fixed as of the upcoming MySQL 8.0.32 / 5.7.41 releases, and here's the proposed changelog entry from the documentation team:

The audit_log server-side plugin always logged an entire multiple query,
rather than logging only the specific part of the query that was executed.
Changing when the query length is set resolves the issue.

Thank you for the bug report.