Bug #103616 Audit log may record set statements that were not executed
Submitted: 7 May 2021 5:57 Modified: 10 May 2021 8:02
Reporter: Xiaodong Huang (OCA) Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Security: Audit Severity:S3 (Non-critical)
Version:8.0.24 OS:Any
Assigned to: CPU Architecture:Any

[7 May 2021 5:57] Xiaodong Huang
Description:
When execute set statement "SET GLOBAL max_connections = 1000, sort_buffer_size = abc;" , because the "sort_buffer_size = abc" check error here, the statement will not executed. But the "max_connections = 1000" will be recorded in audit log. 

This is mainly because as long as the variable check is successful, it will be recorded in the audit log in the set_var::check. The detail code is as below.

 1076 int set_var::check(THD *thd) {
 1077   DBUG_TRACE;
 1078   DEBUG_SYNC(current_thd, "after_error_checking");
 1079
 1080   if (var == nullptr) {
 1081     var = var_tracker.bind_system_variable(thd);
 1082   } else {
 1083     // No need to rebind: called from sql_set_variables().
 1084   }
 1085   if (var == nullptr) {
 1086     return -1;
 1087   }
 1088
 1089   /* value is a NULL pointer if we are using SET ... = DEFAULT */
 1090   if (!value) return 0;
 1091
 1092   if (var->check_update_type(value->result_type())) {
 1093     my_error(ER_WRONG_TYPE_FOR_VAR, MYF(0), var->name.str);
 1094     return -1;
 1095   }
 1096   int ret = (type != OPT_PERSIST_ONLY && var->check(thd, this)) ? -1 : 0;
 1097
 1098   if (!ret && (is_global_persist())) {
 1099     ret = mysql_audit_notify(thd, AUDIT_EVENT(MYSQL_AUDIT_GLOBAL_VARIABLE_SET),
 1100                              var->name.str, value->item_name.ptr(),
 1101                              value->item_name.length());
 1102   }
 1103
 1104   return ret;
 1105 }

When we execute the "SET GLOBAL max_connections = 1000, sort_buffer_size = abc;", the implementation process is consist of two phase.First phase, check whether "max_connections = 1000" and  sort_buffer_size = abc are both valid. if both are valid , execute second phase , otherwise return error. Second phase, update the max_connections and sort_buffer_size.

Here "max_connections = 1000" is vaild but "sort_buffer_size = abc" is invalid, so the set statement is not executed. The checking action is judged by the set_var::check. Then the log entry which content is "max_connections = 1000" is recorded in audit log but the "max_connections = 1000" isn't executed

How to repeat:
1. Open audit log;
2. Execute "SET GLOBAL max_connections = 1000, sort_buffer_size = abc;";
3. The statement return error, but the audit log occur "max_connections = 1000";

Suggested fix:
It is suggested to record the audit log after all variables have passed the checking.
[7 May 2021 13:54] MySQL Verification Team
Hello Xiaodong,

Thank you for the report and feedback.

regards,
Umesh
[10 May 2021 8:02] MySQL Verification Team
Hello Xiaodong,

Our internal discussion concluded that this is an expected and documented behavior of audit log. Audit log will have record of all the executed SQL statements(STATUS will indicate i.e An unsigned integer representing the command status: 0 for success, nonzero if an error occurred) - more details at https://dev.mysql.com/doc/refman/8.0/en/audit-log-file-formats.html

regards,
Umesh
[10 May 2021 9:11] Georgi Kodinov
One comment I'd like to add too: Most of the audit API events should be used for "pre-filtering" and only some of them (e.g. MYSQL_AUDIT_QUERY_STATUS_END) should be used for actual logging. It's all about the time when the event is generated. This particular event (MYSQL_AUDIT_GLOBAL_VARIABLE_SET) is generated at a time when the execution of the statement can easily be interrupted. It's not to signify that the event has actually been put into effect.