Skip to content

Commit 62b2171

Browse files
arcivanovvuvova
arcivanov
authored and
vuvova
committed
Reproducible test case for MDEV-37434
Add debug logging to help with tracing Add the fix
1 parent 9aca89f commit 62b2171

File tree

8 files changed

+236
-6
lines changed

8 files changed

+236
-6
lines changed

‎mysql-test/suite/plugins/r/server_audit_query_id.result‎

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,69 @@
1+
set global server_audit_logging=on;
2+
USE test;
3+
CREATE TABLE source (
4+
id bigint(20) NOT NULL AUTO_INCREMENT,
5+
PRIMARY KEY (id)
6+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
7+
CREATE TABLE dest (
8+
id bigint(20) NOT NULL,
9+
PRIMARY KEY (id)
10+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
11+
CREATE TABLE dest_2 (
12+
id bigint(20) NOT NULL,
13+
PRIMARY KEY (id)
14+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
15+
CREATE TRIGGER test_trigger
16+
AFTER INSERT ON source
17+
FOR EACH ROW
18+
INSERT INTO dest (id) VALUES(NEW.id)//
19+
CREATE TRIGGER test_trigger_2
20+
AFTER INSERT ON dest
21+
FOR EACH ROW
22+
INSERT INTO dest_2 (id) VALUES(NEW.id)//
23+
CREATE PROCEDURE test_procedure (IN id bigint(20))
24+
NOT DETERMINISTIC MODIFIES SQL DATA
25+
BEGIN
26+
INSERT INTO source VALUES (id), (NULL);
27+
END;//
28+
# Insert a row to trigger the AFTER trigger
29+
INSERT INTO source VALUES (NULL);
30+
# Insert another row to see the pattern
31+
INSERT INTO source VALUES (NULL);
32+
# Test with multi-row insert
33+
INSERT INTO source VALUES (NULL), (NULL);
34+
# Test with stored procedure
35+
CALL test_procedure(NULL);
36+
# Clean up
37+
DROP PROCEDURE test_procedure;
38+
DROP TABLE source, dest, dest_2;
39+
set global server_audit_logging=off;
40+
# Wait for audit events to be written
41+
FOUND 1 /set global server_audit_logging=off/ in server_audit_query_id.log
42+
TIMESTAMP,HOSTNAME,root,localhost,4,0,QUERY,test,'set global server_audit_logging=on',0
43+
TIMESTAMP,HOSTNAME,root,localhost,4,1,QUERY,test,'USE test',0
44+
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
45+
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
46+
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
47+
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
48+
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
49+
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
50+
TIMESTAMP,HOSTNAME,root,localhost,4,10,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
51+
TIMESTAMP,HOSTNAME,root,localhost,4,9,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
52+
TIMESTAMP,HOSTNAME,root,localhost,4,8,QUERY,test,'INSERT INTO source VALUES (NULL)',0
53+
TIMESTAMP,HOSTNAME,root,localhost,4,13,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
54+
TIMESTAMP,HOSTNAME,root,localhost,4,12,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
55+
TIMESTAMP,HOSTNAME,root,localhost,4,11,QUERY,test,'INSERT INTO source VALUES (NULL)',0
56+
TIMESTAMP,HOSTNAME,root,localhost,4,16,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
57+
TIMESTAMP,HOSTNAME,root,localhost,4,15,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
58+
TIMESTAMP,HOSTNAME,root,localhost,4,18,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
59+
TIMESTAMP,HOSTNAME,root,localhost,4,17,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
60+
TIMESTAMP,HOSTNAME,root,localhost,4,14,QUERY,test,'INSERT INTO source VALUES (NULL), (NULL)',0
61+
TIMESTAMP,HOSTNAME,root,localhost,4,22,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
62+
TIMESTAMP,HOSTNAME,root,localhost,4,21,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
63+
TIMESTAMP,HOSTNAME,root,localhost,4,24,QUERY,test,'INSERT INTO dest_2 (id) VALUES(NEW.id)',0
64+
TIMESTAMP,HOSTNAME,root,localhost,4,23,QUERY,test,'INSERT INTO dest (id) VALUES(NEW.id)',0
65+
TIMESTAMP,HOSTNAME,root,localhost,4,20,QUERY,test,'INSERT INTO source VALUES ( NAME_CONST(\'id\',NULL)), (NULL)',0
66+
TIMESTAMP,HOSTNAME,root,localhost,4,19,QUERY,test,'CALL test_procedure(NULL)',0
67+
TIMESTAMP,HOSTNAME,root,localhost,4,25,QUERY,test,'DROP PROCEDURE test_procedure',0
68+
TIMESTAMP,HOSTNAME,root,localhost,4,26,QUERY,test,'DROP TABLE source, dest, dest_2',0
69+
TIMESTAMP,HOSTNAME,root,localhost,4,27,QUERY,test,'set global server_audit_logging=off',0

‎mysql-test/suite/plugins/t/normalize_query_id.pl‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
#!/usr/bin/perl
2+
use strict;
3+
use warnings;
4+
5+
my $filename = $ARGV[0] or die "Usage: $0 <logfile>\n";
6+
7+
# Read all lines into memory
8+
open(my $fh, '<', $filename) or die "Cannot open file '$filename': $!";
9+
my @lines = <$fh>;
10+
close($fh);
11+
12+
# Process lines and normalize query IDs
13+
my $first_id;
14+
foreach my $line (@lines) {
15+
if ($line =~ /,(\d+),QUERY/) {
16+
$first_id = $1 unless defined $first_id;
17+
my $normalized = $1 - $first_id;
18+
$line =~ s/,$1,QUERY/,$normalized,QUERY/;
19+
}
20+
}
21+
22+
# Write back to the same file
23+
open($fh, '>', $filename) or die "Cannot write to file '$filename': $!";
24+
print $fh @lines;
25+
close($fh);

‎mysql-test/suite/plugins/t/server_audit_query_id.opt‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
--plugin-load-add=server_audit
2+
--server_audit_mode=0
3+
--server_audit_file_path='server_audit_query_id.log'
4+
--server_audit_output_type=file
5+
--server_audit_events='QUERY'

‎mysql-test/suite/plugins/t/server_audit_query_id.test‎

Lines changed: 89 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,89 @@
1+
--source include/have_innodb.inc
2+
--source include/have_plugin_auth.inc
3+
--source include/not_embedded.inc
4+
5+
if (!$SERVER_AUDIT_SO) {
6+
skip No SERVER_AUDIT plugin;
7+
}
8+
9+
# An unfortunate wait for check-testcase.inc to complete disconnect.
10+
let count_sessions= 1;
11+
source include/wait_until_count_sessions.inc;
12+
13+
let $MYSQLD_DATADIR= `SELECT @@datadir`;
14+
let SEARCH_FILE= $MYSQLD_DATADIR/server_audit_query_id.log;
15+
16+
--disable_ps_protocol
17+
18+
set global server_audit_logging=on;
19+
20+
USE test;
21+
22+
CREATE TABLE source (
23+
id bigint(20) NOT NULL AUTO_INCREMENT,
24+
PRIMARY KEY (id)
25+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
26+
27+
CREATE TABLE dest (
28+
id bigint(20) NOT NULL,
29+
PRIMARY KEY (id)
30+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
31+
32+
CREATE TABLE dest_2 (
33+
id bigint(20) NOT NULL,
34+
PRIMARY KEY (id)
35+
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
36+
37+
DELIMITER //;
38+
CREATE TRIGGER test_trigger
39+
AFTER INSERT ON source
40+
FOR EACH ROW
41+
INSERT INTO dest (id) VALUES(NEW.id)//
42+
DELIMITER ;//
43+
44+
DELIMITER //;
45+
CREATE TRIGGER test_trigger_2
46+
AFTER INSERT ON dest
47+
FOR EACH ROW
48+
INSERT INTO dest_2 (id) VALUES(NEW.id)//
49+
DELIMITER ;//
50+
51+
DELIMITER //;
52+
CREATE PROCEDURE test_procedure (IN id bigint(20))
53+
NOT DETERMINISTIC MODIFIES SQL DATA
54+
BEGIN
55+
INSERT INTO source VALUES (id), (NULL);
56+
END;//
57+
DELIMITER ;//
58+
59+
--echo # Insert a row to trigger the AFTER trigger
60+
INSERT INTO source VALUES (NULL);
61+
62+
--echo # Insert another row to see the pattern
63+
INSERT INTO source VALUES (NULL);
64+
65+
--echo # Test with multi-row insert
66+
INSERT INTO source VALUES (NULL), (NULL);
67+
68+
--echo # Test with stored procedure
69+
CALL test_procedure(NULL);
70+
71+
--echo # Clean up
72+
DROP PROCEDURE test_procedure;
73+
DROP TABLE source, dest, dest_2;
74+
75+
set global server_audit_logging=off;
76+
77+
--echo # Wait for audit events to be written
78+
--let SEARCH_FILE = $MYSQLD_DATADIR/server_audit_query_id.log
79+
--let SEARCH_PATTERN = set global server_audit_logging=off
80+
--source include/search_pattern_in_file.inc
81+
82+
# Read and normalize the log
83+
--exec perl $MYSQL_TEST_DIR/suite/plugins/t/normalize_query_id.pl $SEARCH_FILE
84+
85+
# Output the log without heavy replacements so we can see the actual order
86+
--replace_regex /\d\d\d\d\d\d\d\d \d\d:\d\d:\d\d/TIMESTAMP/ /,[^,]+,root,localhost,/,HOSTNAME,root,localhost,/
87+
88+
cat_file $SEARCH_FILE;
89+
remove_file $SEARCH_FILE;

‎plugin/server_audit/server_audit.c‎

Lines changed: 40 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2013,6 +2013,16 @@ static int log_statement(const struct connection_info *cn,
20132013
const struct mysql_event_general *event,
20142014
const char *type)
20152015
{
2016+
DBUG_PRINT("info", ("log_statement: event_subclass=%d, general_command=%.*s, "
2017+
"cn->query_id=%lld, cn->query=%.*s, event->query_id=%lld, "
2018+
"event->general_query=%.*s, type=%s",
2019+
event->event_subclass, event->general_command_length,
2020+
event->general_command,
2021+
cn->query_id,
2022+
cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length,
2023+
cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query,
2024+
event->query_id, event->general_query_length,
2025+
event->general_query, type));
20162026
return log_statement_ex(cn, event->general_time, event->general_thread_id,
20172027
event->general_query, event->general_query_length,
20182028
event->general_error_code, type, 1);
@@ -2113,6 +2123,16 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn,
21132123
{
21142124
const struct mysql_event_general *event =
21152125
(const struct mysql_event_general *) ev;
2126+
DBUG_PRINT("info", ("update_connection_info: before: event_subclass=%d, "
2127+
"general_command=%.*s, cn->query_id=%lld, cn->query=%.*s, "
2128+
"event->query_id=%lld, event->general_query=%.*s",
2129+
event->event_subclass, event->general_command_length,
2130+
event->general_command,
2131+
cn->query_id,
2132+
cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length,
2133+
cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query,
2134+
event->query_id, event->general_query_length,
2135+
event->general_query));
21162136
switch (event->event_subclass) {
21172137
case MYSQL_AUDIT_GENERAL_LOG:
21182138
{
@@ -2142,19 +2162,23 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn,
21422162
setup_connection_query(cn, event);
21432163
else
21442164
setup_connection_simple(cn);
2145-
break;
21462165
}
2166+
break;
21472167

21482168
case MYSQL_AUDIT_GENERAL_STATUS:
21492169
if (event_query_command(event))
21502170
{
21512171
if (ci_needs_setup(cn))
21522172
setup_connection_query(cn, event);
21532173

2154-
if (mode == 0 && cn->db_length == 0 && event->database.length > 0)
2155-
get_str_n(cn->db, &cn->db_length, sizeof(cn->db),
2156-
event->database.str, event->database.length);
2174+
if (mode == 0)
2175+
{
2176+
if (cn->db_length == 0 && event->database.length > 0)
2177+
get_str_n(cn->db, &cn->db_length, sizeof(cn->db),
2178+
event->database.str, event->database.length);
21572179

2180+
cn->query_id= event->query_id;
2181+
}
21582182
if (event->general_error_code == 0)
21592183
{
21602184
/* 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,
21742198
update_general_user(cn, event);
21752199
}
21762200
break;
2201+
21772202
case MYSQL_AUDIT_GENERAL_ERROR:
21782203
/*
21792204
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,
21902215
break;
21912216
default:;
21922217
}
2218+
DBUG_PRINT("info", ("update_connection_info: after: event_subclass=%d, "
2219+
"general_command=%.*s, cn->query_id=%lld, cn->query=%.*s, "
2220+
"event->query_id=%lld, event->general_query=%.*s",
2221+
event->event_subclass, event->general_command_length,
2222+
event->general_command,
2223+
cn->query_id,
2224+
cn->query_length == 0x4f4f4f4f ? 0 : cn->query_length,
2225+
cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query,
2226+
event->query_id, event->general_query_length,
2227+
event->general_query));
21932228
break;
21942229
}
21952230
case MYSQL_AUDIT_TABLE_CLASS:
@@ -2307,6 +2342,7 @@ void auditing(MYSQL_THD thd, unsigned int event_class, const void *ev)
23072342
{
23082343
log_statement(cn, event, "QUERY");
23092344
cn->query_length= 0; /* So the log_current_query() won't log this again. */
2345+
cn->query_id= 0;
23102346
cn->log_always= 0;
23112347
}
23122348
}

‎sql/sp_head.cc‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1612,6 +1612,9 @@ sp_head::execute(THD *thd, bool merge_da_on_success)
16121612
DBUG_ASSERT(thd->Item_change_list::is_empty());
16131613
old_change_list.move_elements_to(thd);
16141614
thd->lex= old_lex;
1615+
DBUG_PRINT("info", ("sp_head::execute: query_id restore: old_query_id=%lld, query_id=%lld, query=%.*s",
1616+
old_query_id,
1617+
thd->query_id, thd->query_length(), thd->query()));
16151618
thd->set_query_id(old_query_id);
16161619
thd->set_query_inner(old_query);
16171620
DBUG_ASSERT(!thd->derived_tables);
@@ -3609,7 +3612,8 @@ sp_lex_keeper::reset_lex_and_exec_core(THD *thd, uint *nextp,
36093612
thd->lex= m_lex;
36103613

36113614
thd->set_query_id(next_query_id());
3612-
3615+
DBUG_PRINT("info", ("reset_lex_and_exec_core: query_id=%lld, query=%.*s",
3616+
thd->query_id, thd->query_length(), thd->query()));
36133617
if (thd->locked_tables_mode <= LTM_LOCK_TABLES)
36143618
{
36153619
/*

‎sql/sql_audit.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -175,6 +175,8 @@ void mysql_audit_general(THD *thd, uint event_subtype,
175175
event.general_rows= thd->get_stmt_da()->current_row_for_warning();
176176
event.database= thd->db;
177177
event.query_id= thd->query_id;
178+
DBUG_PRINT("info", ("mysql_audit_general: query_id=%lld, query=%.*s, subtype=%d, error_code=%d, msg=%s",
179+
thd->query_id, thd->query_length(), thd->query(), event_subtype, error_code, msg));
178180
}
179181
else
180182
{

‎sql/sql_parse.cc‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1876,7 +1876,7 @@ dispatch_command_return dispatch_command(enum enum_server_command command, THD *
18761876
(char *) thd->security_ctx->host_or_ip);
18771877
char *packet_end= thd->query() + thd->query_length();
18781878
general_log_write(thd, command, thd->query(), thd->query_length());
1879-
DBUG_PRINT("query",("%-.4096s",thd->query()));
1879+
DBUG_PRINT("query",("query_id=%lld, %.*s", thd->query_id, thd->query_length(), thd->query()));
18801880
#if defined(ENABLED_PROFILING)
18811881
thd->profiling.set_query_source(thd->query(), thd->query_length());
18821882
#endif

0 commit comments

Comments
 (0)