Bug #15624 Test cases rpl_deadlock, rpl_insert_id, rpl_insert_ignore fails on OpenBSD 3.7
Submitted: 9 Dec 2005 10:03 Modified: 10 Jan 2006 10:59
Reporter: Kristian Nielsen Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:clone-5.0.17-release OS:Other (OpenBSD 3.7)
Assigned to: Magnus Blåudd CPU Architecture:Any

[9 Dec 2005 10:03] Kristian Nielsen
Description:
The test case rpl_deadlock failed during a test build of 5.0.17:

11699: rpl_deadlock                   [ fail ]
11700: 
11701: Errors are (from /var/extra/home/mysqldev/ds9/test/mysql-max-5.0.17-openbsd3.7-i386/mysql-test/var/log/mysqltest-time) :
11702: mysqltest: At line 64: could not sync with master ('select master_pos_wait('master-bin.000001', 18911)' returned NULL)
11703: (the last lines may be the most important ones)

How to repeat:
Run the test suite.
[9 Dec 2005 10:38] Kristian Nielsen
The test cases rpl_insert_id and rpl_insert_ignore also failed on just that host in the same test build:

11730: rpl_insert_id                  [ fail ]
11731: 
11732: Errors are (from /var/extra/home/mysqldev/ds9/test/mysql-max-5.0.17-openbsd3.7-i386/mysql-test/var/log/mysqltest-time) :
11733: mysqltest: At line 37: could not sync with master ('select master_pos_wait('master-bin.000001', 1720)' returned NULL)
11734: (the last lines may be the most important ones)

11743: rpl_insert_ignore              [ fail ]
11744: 
11745: Errors are (from /var/extra/home/mysqldev/ds9/test/mysql-max-5.0.17-openbsd3.7-i386/mysql-test/var/log/mysqltest-time) :
11746: mysqltest: In included file "./include/master-slave.inc": At line 14: query 'drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9' failed: 1217: Cannot delete or update a parent row: a foreign key constraint fails
11747: (the last lines may be the most important ones)
[9 Dec 2005 10:39] Kristian Nielsen
Same with rpl_relayrotate:

11778: rpl_relayrotate                [ fail ]
11779: 
11780: Errors are (from /var/extra/home/mysqldev/ds9/test/mysql-max-5.0.17-openbsd3.7-i386/mysql-test/var/log/mysqltest-time) :
11781: mysqltest: At line 58: query 'select max(a) from t1' failed: 1146: Table 'test.t1' doesn't exist
11782: (the last lines may be the most important ones)
[9 Dec 2005 20:42] MySQL Verification Team
I was unable to repeat on Linux with 5.0.18 BK source.

ChangeSet@1.1992, 2005-12-09 00:58:59+03:00, konstantin@mysql.com

TEST                            RESULT
-------------------------------------------------------
rpl_deadlock                   [ pass ]   
-------------------------------------------------------

TEST                            RESULT
-------------------------------------------------------
rpl_insert_id                  [ pass ]   
-------------------------------------------------------

TEST                            RESULT
-------------------------------------------------------
rpl_insert_ignore              [ pass ]   
-------------------------------------------------------

TEST                            RESULT
-------------------------------------------------------
rpl_relayrotate                [ pass ]   
-------------------------------------------------------
[12 Dec 2005 14:58] Magnus Blåudd
Reproduced on ds9, the --sleep argument need to be set for test to fail.
[12 Dec 2005 15:49] Magnus Blåudd
This is the var/log/slave.log when test rpl_deadlock has failed with error
"mysqltest: At line 64: could not sync with master ('select master_pos_wait('master-bin.000001', 18911, 10)' returned NULL)"

Apparently the SQL thread has died when  select master_pos_wait is called.

CURRENT_TEST: rpl_deadlock
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
051212 18:29:10  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
051212 18:29:10  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
051212 18:29:10  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
051212 18:29:10  InnoDB: Started; log sequence number 0 0
051212 18:29:10 [Note] /var/extra/home/mysqldev/magnus/mysql-5.0.17/sql/mysqld: ready for connections.
Version: '5.0.17-pro-gpl-log'  socket: '/var/extra/home/mysqldev/magnus/mysql-5.0.17/mysql-test/var/tmp/slave.sock'  port: 10011  MySQL Pro (GPL)
051212 18:29:11 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:10009',  replication started in log 'FIRST' at position 4
051212 18:29:11 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log '/var/extra/home/mysqldev/magnus/mysql-5.0.17/mysql-test/var/log/slave-relay-bin.000001' position: 4
051212 18:29:11 [Note] Slave I/O thread killed while reading event
051212 18:29:11 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 532
051212 18:29:11 [Note] Error reading relay log event: slave SQL thread was killed
051212 18:29:11 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:10009',  replication started in log 'master-bin.000001' at position 532
051212 18:29:11 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 532, relay log '/var/extra/home/mysqldev/magnus/mysql-5.0.17/mysql-test/var/log/slave-relay-bin.000003' position: 670
051212 18:29:17 [ERROR] Slave: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'test'. Query: 'insert into t1 values(1)', Error_code: 1205
051212 18:29:22 [ERROR] Slave: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'test'. Query: 'insert into t1 values(1)', Error_code: 1205
051212 18:29:23 [ERROR] Slave: Error 'Deadlock found when trying to get lock; try restarting transaction' on query. Default database: 'test'. Query: 'insert into t1 values(1)', Error_code: 1213
051212 18:29:23 [ERROR] Slave SQL thread retried transaction 2 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable.
051212 18:29:23 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000001' position 532
051212 18:29:26 [Note] Slave: received end packet from server, apparent master shutdown: 
051212 18:29:26 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000001' position 18911
051212 18:29:32 [ERROR] Slave I/O thread: error reconnecting to master 'root@127.0.0.1:10009': Error: 'Lost connection to MySQL server during query'  errno: 2013  retry-time: 1  retries: 10
051212 18:29:37 [Note] /var/extra/home/mysqldev/magnus/mysql-5.0.17/sql/mysqld: Normal shutdown

051212 18:29:39 [Note] Slave I/O thread killed during or after a reconnect done to recover from failed read
051212 18:29:39 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 18911
051212 18:29:39  InnoDB: Starting shutdown...
051212 18:29:41  InnoDB: Shutdown completed; log sequence number 0 195186
051212 18:29:41 [Note] /var/extra/home/mysqldev/magnus/mysql-5.0.17/sql/mysqld: Shutdown complete

User time 0.44, System time 0.29
Maximum resident set size 0, Integral resident set size 0
Non-physical pagefaults 6754, Physical pagefaults 0, Swaps 0
Blocks in 61 out 1328, Messages in 1050 out 2083, Signals 62
Voluntary context switches 569, Involuntary context switches 997
[12 Dec 2005 16:18] Magnus Blåudd
The SQL thread has been aborted when the test failed. Thus "select master_pos_wait" should return NULL.

Conclusion, either the testcase is missing a "START MASTER" or the SQL thread should not die after a deadlock....
[13 Dec 2005 10:43] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/33220
[10 Jan 2006 10:59] Magnus Blåudd
Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html