File: slow_log.test

package info (click to toggle)
mysql-8.0 8.0.43-3
  • links: PTS, VCS
  • area: main
  • in suites: sid
  • size: 1,273,924 kB
  • sloc: cpp: 4,684,605; ansic: 412,450; pascal: 108,398; java: 83,641; perl: 30,221; cs: 27,067; sql: 26,594; sh: 24,181; python: 21,816; yacc: 17,169; php: 11,522; xml: 7,388; javascript: 7,076; makefile: 2,194; lex: 1,075; awk: 670; asm: 520; objc: 183; ruby: 97; lisp: 86
file content (309 lines) | stat: -rw-r--r-- 9,459 bytes parent folder | download
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
--source include/not_parallel.inc
--source include/not_valgrind.inc

# We'll be using a long_query_time of 0 below, logging everything.
# This means that in normal mode, we'll get one log line for each
# statement when we use COM_QUERY, but two when we use --ps-protocol
# (and thus, COM_STMT_PREPARE/COM_STMT_EXECUTE pairs). This normally
# skews test results. Therefore, we assign a divisor here
# (1 for normal mode, 2 for ps protocol) by which we divide the
# row-counts of our results. The trick is to take counts of both
# the log-rows that have obfuscated passwords in them, and those
# that have unobfuscated passwords in them. That way we can show
# both that password-containing lines are logged at all, *and*
# that they don't contain sensitive data.
#
# We could of course modify the server to never slow-log when
# thd->get_command() == COM_STMT_PREPRARE, but this wouldn't solve
# the same issue for the general log, and since the general log is
# expected to reflect all incoming requests, we shouldn't introduce
# such server-side filtering there. That said, the general_log offers
# us the command_type field, so the test itself could filter on
#   AND command_type!="Prepare"
# allowing through "Query" and "Execute" type rows and resulting in
# a correct row count either way.
#
# The thing however is that since we have the opportunity to, we
# should look at all the rows we can get (so we don't end up
# filtering out lines that wrongfully have unobfuscated passwords
# in them).
let IS_PS=`SELECT $PS_PROTOCOL=1`;
--disable_query_log
--eval SELECT 1+$IS_PS INTO @protdiv
--enable_query_log

# Additionally, KILL ... will fail with --cursor-protocol.
--source include/no_cursor_protocol.inc

SET @save_sqlf=@@global.slow_query_log_file;

--replace_result $MYSQL_TMP_DIR ...
eval SET GLOBAL slow_query_log_file= '$MYSQL_TMP_DIR/my_slow.log';

SET timestamp=10;
SELECT unix_timestamp(), sleep(2);

let SLOW_LOG= `SELECT @@global.slow_query_log_file`;

--perl
   use strict;

   my $file= $ENV{'SLOW_LOG'} or die("slow log not set");
   my $result=0;

   open(FILE, "$file") or die("Unable to open $file: $!");
   while (<FILE>) {
     my $line = $_;
     $result++ if ($line =~ /SET timestamp=10;/);
   }
   close(FILE);

   if($result != 1) {
     print "[ FAIL ] timestamp not found\n";
   }
   else {
     print "[ PASS ] timestamp found\n";
   }

EOF

SET @@global.slow_query_log_file=@save_sqlf;

--remove_file $MYSQL_TMP_DIR/my_slow.log


--echo
--echo #
--echo # Bug#30789032: INCONSISTENT BEHAVIOR WHILE LOGGING A KILLED QUERY IN THE SLOW QUERY LOG
--echo #
--echo

SET @old_slow_query_log_file= @@global.slow_query_log_file;
SET @old_log_output         = @@global.log_output;

--replace_result $MYSQL_TMP_DIR ...
eval SET GLOBAL slow_query_log_file= '$MYSQL_TMP_DIR/my_slow.log';

# SET timestamp=10;
SET @main_thd_id=CONNECTION_ID();

# Set slow log output to table
SET GLOBAL log_output=        'TABLE,FILE';
SET GLOBAL slow_query_log=    1;

SET SESSION long_query_time=  0;

--echo #
--echo # LOG OUTPUT TO TABLE WITH KILL THREAD
--echo # Should not write to the slow log.
--echo #

--echo # "long query" connection (killee)
connect (con1, localhost, root,,);
--connection con1
--disable_reconnect
TRUNCATE mysql.slow_log;
--let $id= `SELECT CONNECTION_ID()`

--echo # Check variables:
SET SESSION long_query_time= 0;
SELECT @@log_output,@@slow_query_log,@@long_query_time;

# Wait in 'before_do_command_net_read' until killed.
--send /* KILL CONNECTION: should not be logged */ SELECT SLEEP(1001)

--echo # default connection (from whence we use KILL CONNECTION)
--connection default
let $wait_condition= SELECT COUNT(processlist_info) FROM performance_schema.threads WHERE processlist_state="User sleep";
--source include/wait_condition.inc
--replace_result $id <CONNECTION_ID>
--eval KILL CONNECTION $id

--echo # show rows (0) in slow_log:
SELECT "Connx" AS kill_type,
       IF(thread_id=@main_thd_id,"KILLER","killee") AS thread,
       sql_text AS query
  FROM mysql.slow_log
 WHERE INSTR(sql_text,"SLEEP(10")>0
 ORDER BY start_time;

--echo # error indicates that the connection's gone (as expected):
--connection con1
# These are client-library errors, not ER_*, so we're using the numeric value.
--error 1317,2013
--reap
# clean up
--disconnect con1

--echo #
--echo # LOG OUTPUT TO TABLE WITH KILL QUERY
--echo # Should write to the slow log.
--echo #

connect (con1, localhost, root,,);
--connection con1
--disable_reconnect
TRUNCATE mysql.slow_log;
--let $id= `SELECT CONNECTION_ID()`

--echo # Check variables:
SET SESSION long_query_time= 0;
SELECT @@log_output,@@slow_query_log,@@long_query_time;

# Wait in 'before_do_command_net_read' until killed.
--send /* KILL QUERY: should be logged */ SELECT SLEEP(1002)

# --echo # default connection (from whence we use KILL QUERY)
--connection default
let $wait_condition= SELECT COUNT(processlist_info) FROM performance_schema.threads WHERE processlist_state="User sleep" AND processlist_info LIKE "%KILL QUERY: should be logged%";
--source include/wait_condition.inc
--replace_result $id <CONNECTION_ID>
--eval KILL QUERY $id

# Wait for the query to hit the log (guard against race condition).
let $wait_condition= SELECT COUNT(sql_text)=1 FROM mysql.slow_log WHERE sql_text LIKE "% KILL QUERY: should be logged %";
--source include/wait_condition.inc

--echo # show rows (1) in slow_log:
SELECT "Query" AS kill_type,
       IF(thread_id=@main_thd_id,"KILLER","killee") AS thread,
       sql_text AS query
  FROM mysql.slow_log
 WHERE INSTR(sql_text,"SLEEP(10")>0
 ORDER BY start_time;

# show that the connection's gone:
--connection con1
--reap
SELECT "con1 is still here.";

# clean up
--disconnect con1

--connection default

# show file log:
let SLOW_LOG= `SELECT @@global.slow_query_log_file`;

--perl
   use strict;

   my $file= $ENV{'SLOW_LOG'} or die("slow log not set");

   open(FILE, "$file") or die("Unable to open $file: $!");
   while (<FILE>) {
     my $line = $_;
     if ($line =~ /SELECT SLEEP\(10/) {
       print "F>".$line; }
   }
   close(FILE);
EOF

SET @@global.slow_query_log_file= @old_slow_query_log_file;
SET @@global.log_output         = @old_log_output;
TRUNCATE TABLE mysql.general_log;
TRUNCATE TABLE mysql.slow_log;


--remove_file $MYSQL_TMP_DIR/my_slow.log

--echo
--echo #
--echo # Bug#33732907: Slow query log logs password in plain text on syntax error
--echo #
--echo

SET @save_sqlf=@@global.slow_query_log_file;
SET @save_sql=@@global.slow_query_log;
SET @save_lo=@@global.log_output;
SET @save_lqt=@@session.long_query_time;

--replace_result $MYSQL_TMP_DIR ...
eval SET GLOBAL slow_query_log_file= '$MYSQL_TMP_DIR/slow33732907.log';
SET @@global.slow_query_log=1;
SET @@global.log_output='file,table';
SET @@session.long_query_time=0;

let SLOW_LOG= `SELECT @@global.slow_query_log_file`;

SET @my_start=CURRENT_TIMESTAMP(6);

--echo
--echo # This succeeds, and the password is correctly obfuscated.
CREATE USER 'duplicate_user'@'%' IDENTIFIED BY 'mypassword';
--echo # This fails, but the password is still correctly obfuscated.
--error ER_CANNOT_USER
CREATE USER 'duplicate_user'@'%' IDENTIFIED BY 'mypassword';

--echo
--echo # Since we throw an error during the parse stage, we don't know which
--echo # part of the statement is the password (or whether there even is one),
--echo # so we cannot obfuscate it. In that case, the statement should not be
--echo # logged, either. The general log also behaves like this by default.
--error ER_PARSE_ERROR
CREATE USER ‘bad_characters’@’%’ IDENTIFIED BY 'mypassword';

--echo # Expected: 2 (1 OK stmt, 1 failed stmt, 0 unparseable stmts)
SELECT COUNT(argument)/@protdiv
  FROM mysql.general_log
 WHERE INSTR(argument,"CREATE USER")=1
   AND INSTR(argument," IDENTIFIED BY <secret>")>0
   AND event_time>=@my_start
 ORDER BY event_time;

SELECT COUNT(argument)/@protdiv
  FROM mysql.general_log
 WHERE INSTR(argument,"CREATE USER")=1
   AND INSTR(argument," IDENTIFIED BY <secret>")=0
   AND event_time>=@my_start
 ORDER BY event_time;

--echo # Expected: 2 (1 OK stmt, 1 failed stmt, 0 unparseable stmts)
SELECT COUNT(sql_text)/@protdiv
  FROM mysql.slow_log
 WHERE INSTR(sql_text,"CREATE USER")=1
   AND INSTR(sql_text," IDENTIFIED BY <secret>")>0
   AND start_time>=@my_start
 ORDER BY start_time;

SELECT COUNT(sql_text)/@protdiv
  FROM mysql.slow_log
 WHERE INSTR(sql_text,"CREATE USER")=1
   AND INSTR(sql_text," IDENTIFIED BY <secret>")=0
   AND start_time>=@my_start
 ORDER BY start_time;

SET @@global.slow_query_log_file=@save_sqlf;
SET @@global.slow_query_log=@save_sql;
SET @@global.log_output=@save_lo;
SET @@session.long_query_time=@save_lqt;

DROP USER 'duplicate_user'@'%';

--echo # Expected: 1 OK stmt, 1 failed stmt, 0 unparseable stmts
--perl
   use strict;

   my $obfs = 0;
   my $nono = 0;
   my $file= $ENV{'SLOW_LOG'} or die("slow log not set");
   my $protdiv= $ENV{'IS_PS'}+1;

   open(FILE, "$file") or die("Unable to open $file: $!");
   while (<FILE>) {
     my $line = $_;
     $obfs++ if(($line =~ /CREATE USER /)&& ($line =~ / IDENTIFIED BY <secret>/));
     $nono++ if(($line =~ /CREATE USER /)&&!($line =~ / IDENTIFIED BY <secret>/));
   }
   print "slow file     obfuscated statements>".($obfs/$protdiv)."\n";
   print "slow file non-obfuscated statements>".($nono/$protdiv)."\n";
   close(FILE);
EOF

--remove_file $MYSQL_TMP_DIR/slow33732907.log
TRUNCATE mysql.slow_log;
TRUNCATE mysql.general_log;


--echo #
--echo # Done.