Bug #18969 race condition involving slave and mysqltest. was rpl_insert_id test case fails
Submitted: 10 Apr 2006 16:46 Modified: 3 Oct 2006 20:23
Reporter: Brian Pontz Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Tests Severity:S3 (Non-critical)
Version:5.1.9-pre OS:Linux (RHAS3 x86)
Assigned to: Magnus BlÄudd

[10 Apr 2006 16:46] Brian Pontz
Description:
rpl_insert_id                  [ fail ]

Errors are (from PATH/mysqltest-time) :
mysqltest: In included file "./extra/rpl_tests/rpl_insert_id.test": At line 47:
could not sync with master ('select master_pos_wait('master-bin.000001', 1415)'
returned NULL)
(the last lines may be the most important ones)
Result from queries before failure can be found in r/rpl_insert_id.log

Killing Possible Leftover Processes

How to repeat:
run test case
[10 Jul 2006 14:08] Andrei Elkin
The failure is not about replication. To prove there is a slave.err
e.g https://intranet.mysql.com/~knielsen/getlog.pl?dir=mysql-5.1-new-rpl&entry=mats@romeo.none...

CURRENT_TEST: rpl_insert_id
060708  8:43:55  InnoDB: Started; log sequence number 0 184637
060708  8:43:55 [Note] /data/pushbuild/pb/mysql-5.1-new-rpl/mats@romeo.none-20060708062142/mysql-5.1-new-rpl-clone/sql/mysqld: ready for connections.
Version: '5.1.12-beta-debug-log'  socket: '/dev/shm/pbtmp-ps_row-6/slave.sock'  port: 10062  Source distribution
060708  8:43:55 [Note] SCHEDULER: Manager thread booting
060708  8:43:55 [Note] SCHEDULER: Loaded 0 events
060708  8:43:55 [Note] SCHEDULER: Suspending operations
060708  8:43:55 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log '/dev/shm/var-ps_row-6/log/slave-relay-bin.000001' position: 4
060708  8:43:55 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:10060',  replication started in log 'FIRST' at position 4
060708  8:43:55  InnoDB: Error: table test.t1 already exists in InnoDB internal

This is quite probable that rpl_foreign_key_innodb.test has not cleaned table test.t1 for a race condition of slave mysqld and mysqltest.
The problem is in that the included test extra/rpl_tests/rpl_foreign_key.test
ends with
  connection master;
  SET FOREIGN_KEY_CHECKS=0;
  DROP TABLE IF EXISTS t1,t2,t3;
  SET FOREIGN_KEY_CHECKS=1;
i.e without sync with the slave so that there is no guarantee slave mysql DROPed the tables.
A method to avoid that already is widely used is to complete the test with

  sync_slave_with_master;

or equivalents. TODO: We need to instuct developers on that separetly!

Since this is not the only single test that has the flaw, the full list of vulnerable tests besides mentioned parent rpl_foreign_key_innodb.test
includes
 
- check me out! -
  
  rpl_auto_increment_11932.test
  rpl_misc_functions.test
  rpl_multi_delete2.test
  rpl_ndb_bank.test
  rpl_ndb_basic.test
  rpl_ndb_dd_basic.test
  rpl_ndb_idempotent.test
  rpl_ndb_load.test
  The failure is not about replication. To prove there is a slave.err
e.g https://intranet.mysql.com/~knielsen/getlog.pl?dir=mysql-5.1-new-rpl&entry=mats@romeo.none...

CURRENT_TEST: rpl_insert_id
060708  8:43:55  InnoDB: Started; log sequence number 0 184637
060708  8:43:55 [Note] /data/pushbuild/pb/mysql-5.1-new-rpl/mats@romeo.none-20060708062142/mysql-5.1-new-rpl-clone/sql/mysqld: ready for connections.
Version: '5.1.12-beta-debug-log'  socket: '/dev/shm/pbtmp-ps_row-6/slave.sock'  port: 10062  Source distribution
060708  8:43:55 [Note] SCHEDULER: Manager thread booting
060708  8:43:55 [Note] SCHEDULER: Loaded 0 events
060708  8:43:55 [Note] SCHEDULER: Suspending operations
060708  8:43:55 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log '/dev/shm/var-ps_row-6/log/slave-relay-bin.000001' position: 4
060708  8:43:55 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:10060',  replication started in log 'FIRST' at position 4
060708  8:43:55  InnoDB: Error: table test.t1 already exists in InnoDB internal

This is quite probable that rpl_foreign_key_innodb.test has not cleaned table test.t1 for a race condition of slave mysqld and mysqltest.
The problem is in that the included test extra/rpl_tests/rpl_foreign_key.test
ends with
  connection master;
  SET FOREIGN_KEY_CHECKS=0;
  DROP TABLE IF EXISTS t1,t2,t3;
  SET FOREIGN_KEY_CHECKS=1;
i.e without sync with the slave so that there is no guarantee slave mysql DROPed the tables.
A method to avoid that already is widely used is to complete the test with
  sync_slave_with_master;

Since this is not the only single test that has the flaw, the full list includes 
besides the parent rpl_foreign_key_innodb.test
 
- check me out! -
  
  rpl_auto_increment_11932.test
  rpl_misc_functions.test
  rpl_multi_delete2.test
  rpl_ndb_bank.test
  rpl_ndb_basic.test
  rpl_ndb_dd_basic.test
  rpl_ndb_idempotent.test
  rpl_ndb_load.test
  
rpl_ndb_multi.test
rpl_rbr_to_sbr.test
rpl_relayspace.test
rpl_rewrt_db.test
rpl_row_basic_11bugs.test
rpl_row_inexist_tbl.test
rpl_row_stop_middle.test
rpl_row_stop_middle_update.test (make it uniform to DROP only on master - and   user replication to drop for granted on slave - always at least one line of code less)
rpl_row_trig003.test
 rpl_slave_status.test (same comment on uniform)
rpl_temporary.test
rpl_truncate_7ndb.test

and called from top level tests:

  extra/rpl_tests/{
     rpl_ddl.test, rpl_failed_optimize.test, rpl_flsh_tbls.test,     rpl_loaddata.test, rpl_row_func003.test, rpl_row_sp007.test, rpl_row_UUID.test,rpl_stm_EE_err2.test, rpl_truncate_helper.test}

Mats, I am asking to readdress the issue to QA since the issues carries rather intergral character to deal with many tests.
[26 Sep 2006 11:50] 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/commits/12514

ChangeSet@1.2285, 2006-09-26 13:49:42+02:00, msvensson@neptunus.(none) +1 -0
  Bug#18969 race condition involving slave and mysqltest. was rpl_insert_id test case fails
   - As the slaves are restarted for each testcase, take the opportunity to restore their databases to a known state with the help of the snapshot(s)
   - Count max number of slaves used in testcases
   - Use copy_install_db to speed up "Installing db" phase
[3 Oct 2006 20:02] Chad MILLER
Available in 5.0.26.
[3 Oct 2006 20:10] Chad MILLER
Available in 5.1.12-beta.
[3 Oct 2006 20:23] Paul Dubois
Test suite change only. No changelog entry needed.