Bug #62456 (./mysql-test-run --debug) AND (set of DEBUG variable) => disabled trace
Submitted: 17 Sep 2011 0:39 Modified: 21 Sep 2011 14:40
Reporter: Oleg Tsarev Email Updates:
Status: Not a Bug Impact on me:
None 
Category:Tests Severity:S3 (Non-critical)
Version:5.1.58, 5.5.17 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D3 (Medium)

[17 Sep 2011 0:39] Oleg Tsarev
Description:
 * Actual behavior: If I run ./mysql-test-run with "--debug" flag and than try to setup DEBUG variable (SET GLOBAL DEBUG="+d,after_mysql_insert") debug's trace has been disabled.

 * Expected behavior: debug trace should be work fine

 * Synopsis: incorrect variable DEBUG setup (internally):
d,after_mysql_insert:i:A,/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/log/mysqld.1.trace:t

How to repeat:
I tried to do following:
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ cat t/debug_disabled_trace.test
SHOW GLOBAL VARIABLES LIKE 'DEBUG';
SHOW SESSION VARIABLES LIKE 'DEBUG';
SET GLOBAL DEBUG='+d,after_mysql_insert';
SHOW GLOBAL VARIABLES LIKE 'DEBUG';
SHOW SESSION VARIABLES LIKE 'DEBUG';
SELECT SLEEP(1) /* COMMENT */;
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ ./mysql-test-run debug_disabled_trace --debug --record
Logging: ./mysql-test-run  debug_disabled_trace --debug --record
110917  3:30:36 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.1.58
Checking supported features...
 - skipping ndbcluster
 - skipping SSL, mysqld not compiled with SSL
 - binaries are debug compiled
Collecting tests...
vardir: /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var'...
Installing system database...
Using server port 44620

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.debug_disabled_trace                [ pass ]   1034

MTR's internal check of the test case 'main.debug_disabled_trace' failed.
This means that the test case does not preserve the state that existed
before the test case was executed.  Most likely the test case did not
do a proper clean-up. It could also be caused by the previous test run
by this thread, if the server wasn't restarted.
This is the diff of the states of the servers before and after the
test case was executed:
mysqltest: Logging to '/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/tmp/check-mysqld_1.log'.
mysqltest: Results saved in '/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/tmp/check-mysqld_1.result'.
mysqltest: Connecting to server localhost:13000 (socket /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-testcase.test' ...
mysqltest: ... Done processing test commands.
--- /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/tmp/check-mysqld_1.result	2011-09-17 03:30:39.389605784 +0300
+++ /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/tmp/check-mysqld_1.reject	2011-09-17 03:30:40.724712597 +0300
@@ -27,7 +27,7 @@
 DATADIR	/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/mysqld.1/data/
 DATETIME_FORMAT	%Y-%m-%d %H:%i:%s
 DATE_FORMAT	%Y-%m-%d
-DEBUG	d:i:A,/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/log/mysqld.1.trace:t
+DEBUG	d,after_mysql_insert:i:A,/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var/log/mysqld.1.trace:t
 DEBUG_SYNC	ON - current signal: ''
 DEFAULT_WEEK_FORMAT	0
 DELAYED_INSERT_LIMIT	100

mysqltest: Result content mismatch

not ok

------------------------------------------------------------
The servers were restarted 0 times
Spent 1.034 of 6 seconds executing testcases

Check of testcase failed for: main.debug_disabled_trace

Completed: All 1 tests were successful.

oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ cat var/log/mysqld.1.trace  | grep "query: "
T@3    : | | query: SHOW SLAVE STATUS
T@3    : | | query: call mtr.check_testcase()
T@4    : | | query: SHOW GLOBAL VARIABLES LIKE 'DEBUG'
T@4    : | | query: SHOW SESSION VARIABLES LIKE 'DEBUG'
T@4    : | | query: SET GLOBAL DEBUG='+d,after_mysql_insert'
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ cat t/debug_disabled_trace.test | sed -e "s/SET/\#SET/g" > t/debug_disabled_trace.test.new; cat t/debug_disabled_trace.test.new > t/debug_disabled_trace.test
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ cat t/debug_disabled_trace.test
SHOW GLOBAL VARIABLES LIKE 'DEBUG';
SHOW SESSION VARIABLES LIKE 'DEBUG';
#SET GLOBAL DEBUG='+d,after_mysql_insert';
SHOW GLOBAL VARIABLES LIKE 'DEBUG';
SHOW SESSION VARIABLES LIKE 'DEBUG';
SELECT SLEEP(1) /* COMMENT */;
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ ./mysql-test-run debug_disabled_trace --debug --record
Logging: ./mysql-test-run  debug_disabled_trace --debug --record
110917  3:32:03 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.1.58
Checking supported features...
 - skipping ndbcluster
 - skipping SSL, mysqld not compiled with SSL
 - binaries are debug compiled
Collecting tests...
vardir: /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test/var'...
Installing system database...
Using server port 45090

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.debug_disabled_trace                [ pass ]   1038
------------------------------------------------------------
The servers were restarted 0 times
Spent 1.038 of 7 seconds executing testcases

Completed: All 1 tests were successful.

oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$ cat var/log/mysqld.1.trace  | grep "query: "
T@3    : | | query: SHOW SLAVE STATUS
T@3    : | | query: call mtr.check_testcase()
T@4    : | | query: SHOW GLOBAL VARIABLES LIKE 'DEBUG'
T@4    : | | query: SHOW SESSION VARIABLES LIKE 'DEBUG'
T@4    : | | query: SHOW GLOBAL VARIABLES LIKE 'DEBUG'
T@4    : | | query: SHOW SESSION VARIABLES LIKE 'DEBUG'
T@4    : | | query: SELECT SLEEP(1) /* COMMENT */
T@5    : | | query: set SQL_LOG_BIN=0
T@5    : | | query: set debug=""
T@6    : | | query: SHOW SLAVE STATUS
T@6    : | | query: call mtr.check_testcase()
oleg.tsarev (0) /ram/dbug_bug/Percona-Server-5.1.58-rel12.9/mysql-test$
[17 Sep 2011 9:39] Valeriy Kravchuk
Thank you for the bug report. Verified with 5.5.17 on Mac OS X also:

macbook-pro:mysql-test openxs$ ./mtr --debug --record debug_dsabled_trace
Logging: ./mtr  --debug --record debug_dsabled_trace
110917 12:31:42 [Warning] Setting lower_case_table_names=2 because file system for /var/folders/dX/dXCzvuSlHX4Op1g-o1jIWk+++TI/-Tmp-/BI0aMLon22/ is case insensitive
110917 12:31:42 [Note] Plugin 'FEDERATED' is disabled.
MySQL Version 5.5.17
Checking supported features...
 - skipping ndbcluster
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
vardir: /Users/openxs/dbs/5.5/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/Users/openxs/dbs/5.5/mysql-test/var'...
Installing system database...
Using server port 58506

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.debug_dsabled_trace                 [ pass ]   1066

MTR's internal check of the test case 'main.debug_dsabled_trace' failed.
This means that the test case does not preserve the state that existed
before the test case was executed.  Most likely the test case did not
do a proper clean-up. It could also be caused by the previous test run
by this thread, if the server wasn't restarted.
This is the diff of the states of the servers before and after the
test case was executed:
mysqltest: Logging to '/Users/openxs/dbs/5.5/mysql-test/var/tmp/check-mysqld_1.log'.
mysqltest: Results saved in '/Users/openxs/dbs/5.5/mysql-test/var/tmp/check-mysqld_1.result'.
mysqltest: Connecting to server localhost:13000 (socket /Users/openxs/dbs/5.5/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-testcase.test' ...
mysqltest: ... Done processing test commands.
--- /Users/openxs/dbs/5.5/mysql-test/var/tmp/check-mysqld_1.result	2011-09-17 12:31:58.000000000 +0300
+++ /Users/openxs/dbs/5.5/mysql-test/var/tmp/check-mysqld_1.reject	2011-09-17 12:32:00.000000000 +0300
@@ -68,7 +68,7 @@
 DATADIR	/Users/openxs/dbs/5.5/mysql-test/var/mysqld.1/data/
 DATETIME_FORMAT	%Y-%m-%d %H:%i:%s
 DATE_FORMAT	%Y-%m-%d
-DEBUG	d:i:A,/Users/openxs/dbs/5.5/mysql-test/var/log/mysqld.1.trace:t
+DEBUG	d,after_mysql_insert:i:A,/Users/openxs/dbs/5.5/mysql-test/var/log/mysqld.1.trace:t
 DEFAULT_STORAGE_ENGINE	MyISAM
 DEFAULT_WEEK_FORMAT	0
 DELAYED_INSERT_LIMIT	100

mysqltest: Result content mismatch

not ok

--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 1.066 of 20 seconds executing testcases

Check of testcase failed for: main.debug_dsabled_trace

Completed: All 1 tests were successful.

macbook-pro:mysql-test openxs$ cat var/log/mysqld.1.trace | grep "query:"
T@1    : | | | | | info: query: (null)

...

T@4    : | | query: SHOW GLOBAL VARIABLES LIKE 'DEBUG'
T@4    : | | | | | | info: query: SHOW GLOBAL VARIABLES LIKE 'DEBUG'
T@4    : | | query: SHOW SESSION VARIABLES LIKE 'DEBUG'
T@4    : | | | | | | info: query: SHOW SESSION VARIABLES LIKE 'DEBUG'
T@4    : | | query: SET GLOBAL DEBUG='+d,after_mysql_insert'
T@4    : | | | | | | info: query: SET GLOBAL DEBUG='+d,after_mysql_insert'
macbook-pro:mysql-test openxs$ 

So, indeed, further trace is disabled by setting DEBUG.
[21 Sep 2011 9:26] Oleg Tsarev
Sorry, bug is invalid.
DBUG_PRINT("query", .... ) work on in two cases:
1) "d" is not setuped
2) "query" is setuped.
In my test-case enough add "+d,query".