|
The failure happened twice on one day on 5.5. Before that, cross-reference returns only two other occasions – one on ob-10.1 in May, and another one on 5.5 4 years ago.
http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/155/steps/test/logs/stdio
innodb.innodb_bug60196 'xtradb' w2 [ fail ]
|
Test ended at 2016-05-24 16:16:30
|
|
CURRENT_TEST: innodb.innodb_bug60196
|
mysqltest: At line 53: mysql_shutdown failed
|
|
The result from queries just before the failure was:
|
< snip >
|
SELECT * FROM bug_60196_FK1;
|
Primary_Key
|
1
|
2
|
3
|
4
|
5
|
SELECT * FROM bug_60196_FK2;
|
Primary_Key
|
1
|
2
|
3
|
4
|
5
|
SELECT * FROM bug_60196;
|
FK1_Key FK2_Key
|
1 1
|
1 2
|
1 3
|
# Stop server
|
The corresponding fragment in the test looks okay at the first glance:
47: --echo # Stop server
|
48:
|
49: # Write file to make mysql-test-run.pl wait for the server to stop
|
50: -- exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
|
51:
|
52: # Send a shutdown request to the server
|
53: -- shutdown_server 10
|
54:
|
55: # Call script that will poll the server waiting for it to disapear
|
56: -- source include/wait_until_disconnected.inc
|
57:
|
58: --echo # Restart server.
|
59:
|
60: # Write file to make mysql-test-run.pl start up the server again
|
61: --exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
|
62:
|
63: # Turn on reconnect
|
64: --enable_reconnect
|
But according to the server log, wait timeout in shutdown does not work at all.
Here is the restart in the failed test:
CURRENT_TEST: innodb.innodb_bug60196
|
160524 16:16:26 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 5.5.50-MariaDB-debug) starting as process 6040 ...
|
...
|
...
|
160524 16:16:29 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: ready for connections.
|
...
|
...
|
160524 16:16:30 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: Normal shutdown
|
|
160524 16:16:30 [Note] Event Scheduler: Purging the queue. 0 events
|
160524 16:16:30 InnoDB: Starting shutdown...
|
CURRENT_TEST: innodb.innodb_bug60196
|
160524 16:16:31 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 5.5.50-MariaDB-debug) starting as process 3592 ...
|
160524 16:16:31 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
So, there is no 10 second waiting, on some reason the shutdown was considered failed right away, and the new test (or rather, the same test retry) started same second.
Moreover, if we look at the retry attempt (which succeeded),
CURRENT_TEST: innodb.innodb_bug60196
|
160524 16:16:31 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 5.5.50-MariaDB-debug) starting as process 3592 ...
|
160524 16:16:31 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
...
|
...
|
160524 16:16:34 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: ready for connections.
|
...
|
...
|
160524 16:16:37 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: Normal shutdown
|
|
160524 16:16:37 [Note] Event Scheduler: Purging the queue. 0 events
|
160524 16:16:37 InnoDB: Starting shutdown...
|
160524 16:16:38 InnoDB: Shutdown completed; log sequence number 1616885
|
160524 16:16:38 [Note] Debug sync points hit: 1076
|
160524 16:16:38 [Note] Debug sync points executed: 0
|
160524 16:16:38 [Note] Debug sync points max active per thread: 0
|
160524 16:16:38 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe: Shutdown complete
|
|
160524 16:16:48 [Note] D:/win32-debug/build/sql//Debug/mysqld.exe (mysqld 5.5.50-MariaDB-debug) starting as process 2488 ...
|
Here the shutdown completed in 1 second, but mysqltest still waited for 10 seconds before the server got restarted.
So, it's all backwards.
Disclaimer: error log on Windows is known to get mislabeled, i.e. CURRENT_TEST records can be in a wrong place, so the above fragments might be irrelevant, although it doesn't look likely in this case.
|