Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-10176

innodb.innodb_bug60196 fails sporadically in buildbot on Windows

    Details

    • Sprint:
      5.5.50

      Description

      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.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                wlad Vladislav Vaintroub
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: