From 62b21714d0bab340872de0aec572cce5b5dd3b09 Mon Sep 17 00:00:00 2001 From: Arcadiy Ivanov Date: Tue, 12 Aug 2025 23:25:11 -0400 Subject: [PATCH] Reproducible test case for MDEV-37434 Add debug logging to help with tracing Add the fix --- .../plugins/r/server_audit_query_id.result | 69 ++++++++++++++ .../suite/plugins/t/normalize_query_id.pl | 25 ++++++ .../suite/plugins/t/server_audit_query_id.opt | 5 ++ .../plugins/t/server_audit_query_id.test | 89 +++++++++++++++++++ plugin/server_audit/server_audit.c | 44 ++++++++- sql/sp_head.cc | 6 +- sql/sql_audit.h | 2 + sql/sql_parse.cc | 2 +- 8 files changed, 236 insertions(+), 6 deletions(-) create mode 100644 mysql-test/suite/plugins/r/server_audit_query_id.result create mode 100644 mysql-test/suite/plugins/t/normalize_query_id.pl create mode 100644 mysql-test/suite/plugins/t/server_audit_query_id.opt create mode 100644 mysql-test/suite/plugins/t/server_audit_query_id.test diff --git a/mysql-test/suite/plugins/r/server_audit_query_id.result b/mysql-test/suite/plugins/r/server_audit_query_id.result new file mode 100644 index 00000000000..3d2d9f18cc2 --- /dev/null +++ b/mysql-test/suite/plugins/r/server_audit_query_id.result @@ -0,0 +1,69 @@ +set global server_audit_logging=on; +USE test; +CREATE TABLE source ( +id bigint(20) NOT NULL AUTO_INCREMENT, +PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; +CREATE TABLE dest ( +id bigint(20) NOT NULL, +PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; +CREATE TABLE dest_2 ( +id bigint(20) NOT NULL, +PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; +CREATE TRIGGER test_trigger +AFTER INSERT ON source +FOR EACH ROW +INSERT INTO dest (id) VALUES(NEW.id)// +CREATE TRIGGER test_trigger_2 +AFTER INSERT ON dest +FOR EACH ROW +INSERT INTO dest_2 (id) VALUES(NEW.id)// +CREATE PROCEDURE test_procedure (IN id bigint(20)) +NOT DETERMINISTIC MODIFIES SQL DATA +BEGIN +INSERT INTO source VALUES (id), (NULL); +END;// +# Insert a row to trigger the AFTER trigger +INSERT INTO source VALUES (NULL); +# Insert another row to see the pattern +INSERT INTO source VALUES (NULL); +# Test with multi-row insert +INSERT INTO source VALUES (NULL), (NULL); +# Test with stored procedure +CALL test_procedure(NULL); +# Clean up +DROP PROCEDURE test_procedure; +DROP TABLE source, dest, dest_2; +set global server_audit_logging=off; +# Wait for audit events to be written +FOUND 1 /set global server_audit_logging=off/ in server_audit_query_id.log +TIMESTAMP,HOSTNAME,root,localhost,4,0,QUERY,test,'set global server_audit_logging=on',0 +TIMESTAMP,HOSTNAME,root,localhost,4,1,QUERY,test,'USE test',0 +TIMESTAMP,HOSTNAME,root,localhost,4,2,QUERY,test,'CREATE TABLE source (\nid bigint(20) NOT NULL AUTO_INCREMENT,\nPRIMARY KEY (id)\n) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4',0 +TIMESTAMP,HOSTNAME,root,localhost,4,3,QUERY,test,'CREATE TABLE dest (\nid bigint(20) NOT NULL,\nPRIMARY KEY (id)\n) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4',0 +TIMESTAMP,HOSTNAME,root,localhost,4,4,QUERY,test,'CREATE TABLE dest_2 (\nid bigint(20) NOT NULL,\nPRIMARY KEY (id)\n) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4',0 +TIMESTAMP,HOSTNAME,root,localhost,4,5,QUERY,test,'CREATE TRIGGER test_trigger\nAFTER INSERT ON source\nFOR EACH ROW\nINSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,6,QUERY,test,'CREATE TRIGGER test_trigger_2\nAFTER INSERT ON dest\nFOR EACH ROW\nINSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,7,QUERY,test,'CREATE PROCEDURE test_procedure (IN id bigint(20))\nNOT DETERMINISTIC MODIFIES SQL DATA\nBEGIN\nINSERT INTO source VALUES (id), (NULL);\nEND',0 +TIMESTAMP,HOSTNAME,root,localhost,4,10,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,9,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,8,QUERY,test,'INSERT INTO source VALUES (NULL)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,13,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,12,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,11,QUERY,test,'INSERT INTO source VALUES (NULL)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,16,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,15,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,18,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,17,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,14,QUERY,test,'INSERT INTO source VALUES (NULL), (NULL)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,22,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,21,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,24,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,23,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,20,QUERY,test,'INSERT INTO source VALUES ( NAME_CONST(\'id\',NULL)), (NULL)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,19,QUERY,test,'CALL test_procedure(NULL)',0 +TIMESTAMP,HOSTNAME,root,localhost,4,25,QUERY,test,'DROP PROCEDURE test_procedure',0 +TIMESTAMP,HOSTNAME,root,localhost,4,26,QUERY,test,'DROP TABLE source, dest, dest_2',0 +TIMESTAMP,HOSTNAME,root,localhost,4,27,QUERY,test,'set global server_audit_logging=off',0 diff --git a/mysql-test/suite/plugins/t/normalize_query_id.pl b/mysql-test/suite/plugins/t/normalize_query_id.pl new file mode 100644 index 00000000000..601809a429d --- /dev/null +++ b/mysql-test/suite/plugins/t/normalize_query_id.pl @@ -0,0 +1,25 @@ +#!/usr/bin/perl +use strict; +use warnings; + +my $filename = $ARGV[0] or die "Usage: $0 \n"; + +# Read all lines into memory +open(my $fh, '<', $filename) or die "Cannot open file '$filename': $!"; +my @lines = <$fh>; +close($fh); + +# Process lines and normalize query IDs +my $first_id; +foreach my $line (@lines) { + if ($line =~ /,(\d+),QUERY/) { + $first_id = $1 unless defined $first_id; + my $normalized = $1 - $first_id; + $line =~ s/,$1,QUERY/,$normalized,QUERY/; + } +} + +# Write back to the same file +open($fh, '>', $filename) or die "Cannot write to file '$filename': $!"; +print $fh @lines; +close($fh); diff --git a/mysql-test/suite/plugins/t/server_audit_query_id.opt b/mysql-test/suite/plugins/t/server_audit_query_id.opt new file mode 100644 index 00000000000..869b5f81739 --- /dev/null +++ b/mysql-test/suite/plugins/t/server_audit_query_id.opt @@ -0,0 +1,5 @@ +--plugin-load-add=server_audit +--server_audit_mode=0 +--server_audit_file_path='server_audit_query_id.log' +--server_audit_output_type=file +--server_audit_events='QUERY' diff --git a/mysql-test/suite/plugins/t/server_audit_query_id.test b/mysql-test/suite/plugins/t/server_audit_query_id.test new file mode 100644 index 00000000000..0b88a6deef5 --- /dev/null +++ b/mysql-test/suite/plugins/t/server_audit_query_id.test @@ -0,0 +1,89 @@ +--source include/have_innodb.inc +--source include/have_plugin_auth.inc +--source include/not_embedded.inc + +if (!$SERVER_AUDIT_SO) { + skip No SERVER_AUDIT plugin; +} + +# An unfortunate wait for check-testcase.inc to complete disconnect. +let count_sessions= 1; +source include/wait_until_count_sessions.inc; + +let $MYSQLD_DATADIR= `SELECT @@datadir`; +let SEARCH_FILE= $MYSQLD_DATADIR/server_audit_query_id.log; + +--disable_ps_protocol + +set global server_audit_logging=on; + +USE test; + +CREATE TABLE source ( + id bigint(20) NOT NULL AUTO_INCREMENT, + PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; + +CREATE TABLE dest ( + id bigint(20) NOT NULL, + PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; + +CREATE TABLE dest_2 ( + id bigint(20) NOT NULL, + PRIMARY KEY (id) +) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4; + +DELIMITER //; +CREATE TRIGGER test_trigger +AFTER INSERT ON source +FOR EACH ROW +INSERT INTO dest (id) VALUES(NEW.id)// +DELIMITER ;// + +DELIMITER //; +CREATE TRIGGER test_trigger_2 +AFTER INSERT ON dest +FOR EACH ROW +INSERT INTO dest_2 (id) VALUES(NEW.id)// +DELIMITER ;// + +DELIMITER //; +CREATE PROCEDURE test_procedure (IN id bigint(20)) +NOT DETERMINISTIC MODIFIES SQL DATA +BEGIN + INSERT INTO source VALUES (id), (NULL); +END;// +DELIMITER ;// + +--echo # Insert a row to trigger the AFTER trigger +INSERT INTO source VALUES (NULL); + +--echo # Insert another row to see the pattern +INSERT INTO source VALUES (NULL); + +--echo # Test with multi-row insert +INSERT INTO source VALUES (NULL), (NULL); + +--echo # Test with stored procedure +CALL test_procedure(NULL); + +--echo # Clean up +DROP PROCEDURE test_procedure; +DROP TABLE source, dest, dest_2; + +set global server_audit_logging=off; + +--echo # Wait for audit events to be written +--let SEARCH_FILE = $MYSQLD_DATADIR/server_audit_query_id.log +--let SEARCH_PATTERN = set global server_audit_logging=off +--source include/search_pattern_in_file.inc + +# Read and normalize the log +--exec perl $MYSQL_TEST_DIR/suite/plugins/t/normalize_query_id.pl $SEARCH_FILE + +# Output the log without heavy replacements so we can see the actual order +--replace_regex /\d\d\d\d\d\d\d\d \d\d:\d\d:\d\d/TIMESTAMP/ /,[^,]+,root,localhost,/,HOSTNAME,root,localhost,/ + +cat_file $SEARCH_FILE; +remove_file $SEARCH_FILE; diff --git a/plugin/server_audit/server_audit.c b/plugin/server_audit/server_audit.c index e17f001ee47..2d5b89aca69 100644 --- a/plugin/server_audit/server_audit.c +++ b/plugin/server_audit/server_audit.c @@ -2013,6 +2013,16 @@ static int log_statement(const struct connection_info *cn, const struct mysql_event_general *event, const char *type) { + DBUG_PRINT("info", ("log_statement: event_subclass=%d, general_command=%.*s, " + "cn->query_id=%lld, cn->query=%.*s, event->query_id=%lld, " + "event->general_query=%.*s, type=%s", + event->event_subclass, event->general_command_length, + event->general_command, + cn->query_id, + cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length, + cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query, + event->query_id, event->general_query_length, + event->general_query, type)); return log_statement_ex(cn, event->general_time, event->general_thread_id, event->general_query, event->general_query_length, event->general_error_code, type, 1); @@ -2113,6 +2123,16 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, { const struct mysql_event_general *event = (const struct mysql_event_general *) ev; + DBUG_PRINT("info", ("update_connection_info: before: event_subclass=%d, " + "general_command=%.*s, cn->query_id=%lld, cn->query=%.*s, " + "event->query_id=%lld, event->general_query=%.*s", + event->event_subclass, event->general_command_length, + event->general_command, + cn->query_id, + cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length, + cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query, + event->query_id, event->general_query_length, + event->general_query)); switch (event->event_subclass) { case MYSQL_AUDIT_GENERAL_LOG: { @@ -2142,8 +2162,8 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, setup_connection_query(cn, event); else setup_connection_simple(cn); - break; } + break; case MYSQL_AUDIT_GENERAL_STATUS: if (event_query_command(event)) @@ -2151,10 +2171,14 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, if (ci_needs_setup(cn)) setup_connection_query(cn, event); - if (mode == 0 && cn->db_length == 0 && event->database.length > 0) - get_str_n(cn->db, &cn->db_length, sizeof(cn->db), - event->database.str, event->database.length); + if (mode == 0) + { + if (cn->db_length == 0 && event->database.length > 0) + get_str_n(cn->db, &cn->db_length, sizeof(cn->db), + event->database.str, event->database.length); + cn->query_id= event->query_id; + } if (event->general_error_code == 0) { /* We need to check if it's the USE command to change the DB */ @@ -2174,6 +2198,7 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, update_general_user(cn, event); } break; + case MYSQL_AUDIT_GENERAL_ERROR: /* We need this because the MariaDB returns NULL query field for the @@ -2190,6 +2215,16 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, break; default:; } + DBUG_PRINT("info", ("update_connection_info: after: event_subclass=%d, " + "general_command=%.*s, cn->query_id=%lld, cn->query=%.*s, " + "event->query_id=%lld, event->general_query=%.*s", + event->event_subclass, event->general_command_length, + event->general_command, + cn->query_id, + cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length, + cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query, + event->query_id, event->general_query_length, + event->general_query)); break; } case MYSQL_AUDIT_TABLE_CLASS: @@ -2307,6 +2342,7 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev) { log_statement(cn, event, "QUERY"); cn->query_length= 0; /* So the log_current_query() won't log this again. */ + cn->query_id= 0; cn->log_always= 0; } } diff --git a/sql/sp_head.cc b/sql/sp_head.cc index bd95b8060e5..07cba674c0e 100644 --- a/sql/sp_head.cc +++ b/sql/sp_head.cc @@ -1612,6 +1612,9 @@ sp_head::execute(THD *thd, bool merge_da_on_success) DBUG_ASSERT(thd->Item_change_list::is_empty()); old_change_list.move_elements_to(thd); thd->lex= old_lex; + DBUG_PRINT("info", ("sp_head::execute: query_id restore: old_query_id=%lld, query_id=%lld, query=%.*s", + old_query_id, + thd->query_id, thd->query_length(), thd->query())); thd->set_query_id(old_query_id); thd->set_query_inner(old_query); DBUG_ASSERT(!thd->derived_tables); @@ -3609,7 +3612,8 @@ sp_lex_keeper::reset_lex_and_exec_core(THD *thd, uint *nextp, thd->lex= m_lex; thd->set_query_id(next_query_id()); - + DBUG_PRINT("info", ("reset_lex_and_exec_core: query_id=%lld, query=%.*s", + thd->query_id, thd->query_length(), thd->query())); if (thd->locked_tables_mode <= LTM_LOCK_TABLES) { /* diff --git a/sql/sql_audit.h b/sql/sql_audit.h index 64500067699..49b877ada94 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -175,6 +175,8 @@ void mysql_audit_general(THD *thd, uint event_subtype, event.general_rows= thd->get_stmt_da()->current_row_for_warning(); event.database= thd->db; event.query_id= thd->query_id; + DBUG_PRINT("info", ("mysql_audit_general: query_id=%lld, query=%.*s, subtype=%d, error_code=%d, msg=%s", + thd->query_id, thd->query_length(), thd->query(), event_subtype, error_code, msg)); } else { diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 758a57a0967..e6dad577f22 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -1876,7 +1876,7 @@ dispatch_command_return dispatch_command(enum enum_server_command command, THD * (char *) thd->security_ctx->host_or_ip); char *packet_end= thd->query() + thd->query_length(); general_log_write(thd, command, thd->query(), thd->query_length()); - DBUG_PRINT("query",("%-.4096s",thd->query())); + DBUG_PRINT("query",("query_id=%lld, %.*s", thd->query_id, thd->query_length(), thd->query())); #if defined(ENABLED_PROFILING) thd->profiling.set_query_source(thd->query(), thd->query_length()); #endif