Bug #77256 Unclear (incorrect ?) audit plugin notifications for stored procedures
Submitted: 5 Jun 2015 9:44 Modified: 5 Jun 2015 11:11
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Security: Audit Severity:S3 (Non-critical)
Version:5.6,5.7, 5.6.25, 5.7.7 OS:Any
Assigned to: CPU Architecture:Any
Tags: audit, plugin

[5 Jun 2015 9:44] Laurynas Biveinis
Description:
5.6 and 5.7 produce different audit plugin API notifications for preparation and execution of stored procedures. It is not clear which one (or neither one) is correct, and it is not documented what notifications are supposed to happen in this case.

How to repeat:
1) apply the following to the audit null plugin to see more info about the events it receives. The patch is identical for 5.6 and 5.7:

diff --git a/plugin/audit_null/audit_null.c b/plugin/audit_null/audit_null.c
index 5ff9375..4b0aa39 100644
--- a/plugin/audit_null/audit_null.c
+++ b/plugin/audit_null/audit_null.c
@@ -101,6 +101,10 @@ static void audit_null_notify(MYSQL_THD thd __attribute__((unused)),
   {
     const struct mysql_event_general *event_general=
       (const struct mysql_event_general *) event;
+    fprintf(stderr, "audit: MYSQL_AUDIT_GENERAL_CLASS, %s, subclass = %u, "
+            "query = %s\n",
+            event_general->general_command,
+            event_general->event_subclass, event_general->general_query);
     switch (event_general->event_subclass)
     {
     case MYSQL_AUDIT_GENERAL_LOG:

2) Run the following MTR:

foo-master.opt:

$AUDIT_NULL_OPT

foo.test:

--source include/have_null_audit_plugin.inc
--source include/not_embedded.inc

SET @general_log_save = @@general_log;
SET GLOBAL general_log=OFF;

DELIMITER //;

CREATE PROCEDURE simpleproc (OUT param1 INT)
BEGIN
  SELECT 1 INTO param1;
END//

DELIMITER ;//

# load audit plugin
--replace_result $AUDIT_NULL AUDIT_NULL
--eval INSTALL PLUGIN NULL_AUDIT SONAME '$AUDIT_NULL'

PREPARE stmt1 FROM 'SELECT 1';
EXECUTE stmt1;
SHOW STATUS LIKE 'Audit_null_general_log';

UNINSTALL PLUGIN NULL_AUDIT;
DEALLOCATE PREPARE stmt1;
DROP PROCEDURE simpleproc;

SET GLOBAL general_log=@general_log_save;

3) The testcase output will show the different counter value for 5.6 and 5.7:

5.6:
SHOW STATUS LIKE 'Audit_null_general_log';
Variable_name	Value
Audit_null_general_log	5

5.7:
SHOW STATUS LIKE 'Audit_null_general_log';
Variable_name	Value
Audit_null_general_log	3

4) Compare the error logs. I am only showing the audit bits related to SPs:

5.6:
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 0, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, Prepare, subclass = 0, query = SELECT 1
audit: MYSQL_AUDIT_GENERAL_CLASS, (null), subclass = 2, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 3, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 0, query = EXECUTE stmt1
audit: MYSQL_AUDIT_GENERAL_CLASS, Execute, subclass = 0, query = SELECT 1
audit: MYSQL_AUDIT_GENERAL_CLASS, (null), subclass = 2, query = SELECT 1
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 3, query = SELECT 1

5.7:
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 0, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, (null), subclass = 2, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 3, query = PREPARE stmt1 FROM ...
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 0, query = EXECUTE stmt1
audit: MYSQL_AUDIT_GENERAL_CLASS, (null), subclass = 2, query = SELECT 1
audit: MYSQL_AUDIT_GENERAL_CLASS, Query, subclass = 3, query = SELECT 1

(subclasses: 0 = MYSQL_AUDIT_GENERAL_LOG, 2 = ..._RESULT, 3 = ..._STATUS)

Questions:
1) Is it correct that 5.7 does not have a "Prepare"?
2) Is it correct that 5.7 does not have an "Execute"?
3) Is it correct that the plugin sometimes receives NULL for mysql_event_general::general_command in both versions? Presumably this corresponds to "Name" in http://dev.mysql.com/doc/refman/5.6/en/audit-log-file.html, which has allowed values enumerated there.
4) What should the correct notification sequence for the above be?

Suggested fix:
Fix the code bugs, if any.
If the 5.6 and 5.7 logging is intended to be different, document it in 5.7 changes.
[5 Jun 2015 11:11] Umesh Shastry
Hello Laurynas,

Thank you for the reports.
Observed as reported with 5.6.25/5.7.7.
Not sure whether this is intended behavior.

Thanks,
Umesh