Description:
When a stored procedure or stored function is invoked through a prepared statement, the audit plugin is invoked once for every statement executed inside that stored procedure/function.
As a result, the statements inside the stored procedure/function are written to the audit log even though the client never executed them directly.
As explained below, this behavior appears to be introduced by commit e3c9955 (https://github.com/mysql/mysql-server/commit/e3c9955d236ac19bae4674fea46576aeb41e0d90).
I have also confirmed that the behavior is present in 8.4.11, the latest release in the 8.4 series.
How to repeat:
First, here is a reproduction using mysqltest, together with the results. The key points are:
- To run statements over the prepared-statement protocol, mysqltest was invoked with --ps-protocol.
- The NULL_AUDIT plugin was used, and the Audit_null_general_status status variable was used as an indicator of how many times the plugin was invoked.
- The Audit_null_general_status value was compared before and after calling the stored procedure/function to see how often the plugin was invoked.
- The test environment was built by cloning the source of each version from GitHub and building it on Amazon Linux 2023.
--- excerpt from INFO_BIN ---
Build was done on Linux-6.1.168-202.320.amzn2023.x86_64 processor x86_64
Build was done using cmake 3.22.2
------------
The tests were run with the attached repro_case.test.
The results for each version are shown below. The ports are not 3306 simply because of how the build environment is set up.
##### 8.0.41 #####
$ /usr/local/mysql8041/bin/mysqltest --ps-protocol -u root -p$DB_PASSWORD -P 3308 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=9 delta=3
# test_proc : Audit_null_general_status before=11 after=15 delta=4
# cleanup done
ok
$ /usr/local/mysql8041/bin/mysqltest -u root -p$DB_PASSWORD -P 3308 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=8 delta=2
# test_proc : Audit_null_general_status before=10 after=12 delta=2
# cleanup done
ok
##### 8.0.42 #####
$ /usr/local/mysql8042/bin/mysqltest --ps-protocol -u root -p$DB_PASSWORD -P 3309 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=12 delta=6
# test_proc : Audit_null_general_status before=14 after=22 delta=8
# cleanup done
ok
$ /usr/local/mysql8042/bin/mysqltest -u root -p$DB_PASSWORD -P 3309 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=8 delta=2
# test_proc : Audit_null_general_status before=10 after=12 delta=2
# cleanup done
ok
##### 8.0.42 (only commit e3c9955 reverted via git revert) #####
$ /usr/local/mysql8042custom/bin/mysqltest --ps-protocol -u root -p$DB_PASSWORD -P 3310 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=9 delta=3
# test_proc : Audit_null_general_status before=11 after=15 delta=4
# cleanup done
ok
$ /usr/local/mysql8042custom/bin/mysqltest -u root -p$DB_PASSWORD -P 3310 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=8 delta=2
# test_proc : Audit_null_general_status before=10 after=12 delta=2
# cleanup done
ok
##### 8.4.11 #####
$ /usr/local/mysql8411/bin/mysqltest --ps-protocol -u root -p$DB_PASSWORD -P 3311 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=12 delta=6
# test_proc : Audit_null_general_status before=14 after=22 delta=8
# cleanup done
ok
$ /usr/local/mysql8411/bin/mysqltest -u root -p$DB_PASSWORD -P 3311 -h 127.0.0.1 < repro_case.test
# setup done
# test_fn : Audit_null_general_status before=6 after=8 delta=2
# test_proc : Audit_null_general_status before=10 after=12 delta=2
# cleanup done
ok
The conditions and the Audit_null_general_status deltas are summarized below:
server version prepared-statement protocol test_fn test_proc
-------------------------- --------------------------- ------- ---------
8.0.41 disabled 2 2
8.0.42 disabled 2 2
8.0.42 (e3c9955 reverted) disabled 2 2
8.4.11 disabled 2 2
8.0.41 enabled 3 4
8.0.42 enabled 6 8
8.0.42 (e3c9955 reverted) enabled 3 4
8.4.11 enabled 6 8
When the prepared-statement protocol is disabled, the Audit_null_general_status delta is the same across all versions.
When it is enabled, however, the delta on 8.0.42 and 8.4.11 is larger than on 8.0.41. Specifically, the value for test_fn grows by 6 - 3 = 3, and the value for test_proc grows by 8 - 4 = 4. These increases match the number of SQL statements inside test_fn and test_proc, respectively.
Furthermore, on the build where only commit e3c9955 was reverted, the Audit_null_general_status delta is back to the same values as on 8.0.41.
Since the Audit_null_general_status delta alone can be hard to picture, here is a concrete example of the queries being written to the audit log, using the Audit Plugin for MySQL Server (https://github.com/aws/audit-plugin-for-mysql).
This plugin is configured through system variables named server_audit_%. The settings used here were:
mysql> show variables like '%audit%';
+-------------------------------+-------------------------------------------------+
| Variable_name | Value |
+-------------------------------+-------------------------------------------------+
| server_audit_events | CONNECT,QUERY |
| server_audit_excl_users | |
| server_audit_file_path | /usr/local/mysql/log/audit/server_audit.log |
| server_audit_file_rotate_now | OFF |
| server_audit_file_rotate_size | 1000000 |
| server_audit_file_rotations | 9 |
| server_audit_incl_users | |
| server_audit_loc_info | |
| server_audit_logging | ON |
| server_audit_output_type | file |
| server_audit_query_log_limit | 1024 |
| server_audit_syslog_facility | LOG_USER |
| server_audit_syslog_ident | mysql-server_auditing |
| server_audit_syslog_info | |
| server_audit_syslog_priority | LOG_INFO |
+-------------------------------+-------------------------------------------------+
15 rows in set (0.01 sec)
On an instance with this plugin installed, I ran the attached run_repro.py and inspected the audit log.
Example: python3 run_repro.py --host 127.0.0.1 --port 3308 --user root
On 8.0.41 and on 8.0.42 (e3c9955 reverted), the audit log looked like this:
/----
20260817 05:52:06,<serverhost>,root,localhost,11,0,CONNECT,audit_test,,0,SSL
20260817 05:52:06,<serverhost>,root,localhost,11,66,QUERY,audit_test,'SET NAMES \'utf8mb4\' COLLATE \'utf8mb4_0900_ai_ci\'',0,,
20260817 05:52:06,<serverhost>,root,localhost,11,67,QUERY,audit_test,'set autocommit=0',0,,
20260817 05:52:06,<serverhost>,root,localhost,11,73,QUERY,audit_test,'SELECT test_fn(1)',0,,
20260817 05:52:06,<serverhost>,root,localhost,11,78,QUERY,audit_test,'CALL test_proc(1)',0,,
20260817 05:52:06,<serverhost>,root,localhost,11,82,QUERY,audit_test,'commit',0,,
20260817 05:52:06,<serverhost>,root,localhost,11,0,DISCONNECT,audit_test,,0,SSL
----/
In contrast, on 8.0.42 and 8.4.11 it looked like this:
/----
20260817 05:54:30,<serverhost>,root,localhost,9,0,CONNECT,audit_test,,0,SSL
20260817 05:54:30,<serverhost>,root,localhost,9,15,QUERY,audit_test,'SET NAMES \'utf8mb4\' COLLATE \'utf8mb4_0900_ai_ci\'',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,16,QUERY,audit_test,'set autocommit=0',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,20,QUERY,audit_test,'SELECT 1 INTO r1',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,21,QUERY,audit_test,'SELECT 2 INTO r2',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,22,QUERY,audit_test,'SELECT 3 INTO r3',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,22,QUERY,audit_test,'SELECT test_fn(1)',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,27,QUERY,audit_test,'INSERT INTO t(id) VALUES (p_id)',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,27,QUERY,audit_test,'SELECT COUNT(*) INTO @c FROM t WHERE id = p_id',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,27,QUERY,audit_test,'UPDATE t SET id = p_id',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,27,QUERY,audit_test,'DELETE FROM t',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,27,QUERY,audit_test,'CALL test_proc(1)',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,31,QUERY,audit_test,'commit',0,,
20260817 05:54:30,<serverhost>,root,localhost,9,0,DISCONNECT,audit_test,,0,SSL
----/
On 8.0.42 and 8.4.11, the statements inside test_fn and test_proc are also written to the audit log.
On 8.0.42 (e3c9955 reverted) they are not, which indicates that commit e3c9955 is what causes the internal statements to be written to the audit log.
Suggested fix:
The audit plugin should be invoked only once per top-level command issued by the client, and not once per internal sub-statement. This matches the behavior of 8.0.41 (before e3c9955).
