Bug #80174 Some LOCK TABLES errors skip MYSQL_AUDIT_QUERY_STATUS_END audit notification
Submitted: 27 Jan 2016 11:36 Modified: 27 Jan 2016 12:23
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Security: Audit Severity:S3 (Non-critical)
Version:5.7.10 OS:Any
Assigned to: CPU Architecture:Any
Tags: plugin api

[27 Jan 2016 11:36] Laurynas Biveinis
Description:
If LOCK TABLES fails because of an open XA transaction, the MYSQL_AUDIT_QUERY_STATUS_END notification for this failed LOCK TABLES statement will not happen.

How to repeat:
Patch audit_null for easier tracking of MYSQL_AUDIT_QUERY_START/STATUS_END:

diff --git a/plugin/audit_null/audit_null.c b/plugin/audit_null/audit_null.c
index f27b77f..bd93ad6 100644
--- a/plugin/audit_null/audit_null.c
+++ b/plugin/audit_null/audit_null.c
@@ -515,12 +515,16 @@ static int audit_null_notify(MYSQL_THD thd __attribute__((unused)),
     {
     case MYSQL_AUDIT_QUERY_START:
       number_of_calls_query_start++;
+      fprintf(stderr, "audit_null: MYSQL_AUDIT_QUERY_START for %s\n",
+              event_query->query.str);
       break;
     case MYSQL_AUDIT_QUERY_NESTED_START:
       number_of_calls_query_nested_start++;
       break;
     case MYSQL_AUDIT_QUERY_STATUS_END:
       number_of_calls_query_status_end++;
+      fprintf(stderr, "audit_null: MYSQL_AUDIT_QUERY_STATUS_END for %s\n",
+              event_query->query.str);
       break;
     case MYSQL_AUDIT_QUERY_NESTED_STATUS_END:
       number_of_calls_query_nested_status_end++;

Run this MTR:

foo-master.opt:
$AUDIT_NULL_OPT

foo.test:
--source include/have_null_audit_plugin.inc
--source include/not_embedded.inc

connection default;
 let $expected_extension= so;
 if(`SELECT CONVERT(@@version_compile_os USING latin1)
           IN ("Win32","Win64","Windows")`)
{
   let $expected_extension= dll;
}
--replace_result $expected_extension <expected_extension>
eval INSTALL PLUGIN null_audit SONAME 'adt_null.$expected_extension';

CREATE TABLE t (a INT PRIMARY KEY);

XA START '';
SHOW STATUS LIKE 'audit_null_called';
--error ER_XAER_RMFAIL
LOCK TABLES t WRITE;
SHOW STATUS LIKE 'audit_null_called';
XA END '';
XA PREPARE '';
XA COMMIT '';

DROP TABLE t;

UNINSTALL PLUGIN null_audit;

Check error log:

audit_null: MYSQL_AUDIT_QUERY_START for SHOW STATUS LIKE 'audit_null_called'
audit_null: MYSQL_AUDIT_QUERY_STATUS_END for SHOW STATUS LIKE 'audit_null_called'
audit_null: MYSQL_AUDIT_QUERY_START for LOCK TABLES t WRITE
audit_null: MYSQL_AUDIT_QUERY_START for SHOW STATUS LIKE 'audit_null_called'
audit_null: MYSQL_AUDIT_QUERY_STATUS_END for SHOW STATUS LIKE 'audit_null_called'

Note the missing QUERY_STATUS_END for LOCK TABLES.

Suggested fix:
This is because mysql_execute_command has two early DBUG_RETURNS instead of regular "goto err" from its middle, and one is 

  case SQLCOM_LOCK_TABLES:
    /*
      Can we commit safely? If not, return to avoid releasing
      transactional metadata locks.
    */
    if (trans_check_state(thd))
      DBUG_RETURN(-1);

This skips lots of things, including

    mysql_audit_notify(thd,
                       first_level ? MYSQL_AUDIT_QUERY_STATUS_END :
                                     MYSQL_AUDIT_QUERY_NESTED_STATUS_END,
                       first_level ? "MYSQL_AUDIT_QUERY_STATUS_END" :
                                     "MYSQL_AUDIT_QUERY_NESTED_STATUS_END");

Early returns are hard to get right for such a big function as mysql_execute_command. The suggested fix would be to split it to functions of more manageable size and do not do DBUG_RETURN here. Some goto or maybe even RAII with a scope would work better.

The other early return is for SQLCOM_UNLOCK_TABLES but that one seems benign to me, see bug 77689.
[27 Jan 2016 12:23] Umesh Shastry
Hello Laurynas,

Thank you for the report.

Thanks,
Umesh