307 lines
9.2 KiB
Text
307 lines
9.2 KiB
Text
--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
|
||
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
|
||
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.
|