Bug #38694 Race condition in replication thread shutdown

Description:
We have a test that uses a master-slave setup, does many inserts into the master and intermittently restarts the slave (via STOP SLAVE, START SLAVE or restarting the slave process).

When a debug mysqld binary is used, there are intermittent crashes on shutdown because a mutex is destroyed while it is still locked. The mutex is rli->run_lock - the mutex used by the slave SQL thread.

The problem is that terminate_slave_threads() does not try to stop the SQL slave thread or wait for it to finish, because it reads rli->slave_running=0. The SQL slave thread sets rli->slave_running=0 before it unlocks rli->run_lock. If the thread that called terminate_slave_threads() is fast, it can then call pthread_mutex_destroy() on rli->run_lock before the SQL slave thread unlocks rli->run_lock.

The SQL slave thread is able to detect a shutdown in progress before terminate_slave_threads() runs, because mysqld.cc sets abort_loop=1 on shutdown and sql_slave_killed() reads abort_loop.

How to repeat:
Described above

Suggested fix:
None yet, but the SQL thread needs to delay setting slave_running=0 until release rli->run_lock, or terminate_slave_threads() needs changes in how it blocks on stopping either the SQL or IO thread.

changed synopsis

looks like bug #27675?

Yes, I think it is a duplicate. But it has more details on the cause of the failure.

Thanks for the analysis Mark.  Verified.

Build a --debug=full slave with a small patch to put a sleep before unlocking rli->run_lock.  Start the slave with --skip-innodb --server-id=1 

So in handle_slave_io we have this:
printf("sleeping before unlocking!\n");
sleep(10);
pthread_mutex_unlock(&rli->run_lock);  // tell the world we are done

then run inserts against the master.  While this happens, run mysqladmin shutdown on the slave.
crash happens on the line pthread_mutex_unlock(&rli->run_lock);

mysqld.exe!handle_slave_sql(void * arg=0x04e0bf50)  Line 4108
mysqld.exe!pthread_start(void * param=0x04d7ffc8)  Line 85
mysqld.exe!_callthreadstart()  Line 293
mysqld.exe!_threadstart(void * ptd=0x05d66530)  Line 277

Is this bug verified towards 5.1 or 5.0?

I suspect it is already fixed in 5.1.

crashes in 5.0.76-debug:

safe_mutex: Trying to destroy a mutex that was locked at slave.cc, line 3835 at slave.h, line 462

0x81c15d4 handle_segfault + 671
0x110416 (?)
0xb4b028 (?)
0x84bb181 safe_mutex_destroy + 162
0x831e504 st_master_info::~st_master_info() + 38
0x831deac end_slave() + 214
0x81c577b close_connections() + 1172
0x81c5bce kill_server(void*) + 451
0x81c5c15 kill_server_thread + 23
0xcc232f (?)

I couldn't repeat this in 5.1.31.

This seems to be yet another version of the following bugs: BUG#20850, BUG#27675, BUG#25306, BUG#25245.

Note, that [11 Aug 2008 10:41] comments mentioning crash in
pthread_mutex_unlock(&rli->run_lock) executing by the SQL thread is a
subject of bug#25306 fixed in 5.0.38.

The bug description scenaio, reported for 5.0.37, and most probably
the comments of [17 Jan 17:10]  
claim mi[->rli]->run_lock is being taken by a repliction thread at time of
delete active_mi in end_slave().

Considering the latest source code, the terminator thread invokes

  terminate_slave_threads(active_mi, SLAVE_FORCE_ALL, [0]);
  terminate_slave_thread();

[0] of terminate_slave_threads() stands for acquiring `run_lock'
prior to read `slave_running' value.
Once `slave_running' is found to be 0 `run_lock' is released
and end_slave() gets to `delete active_mi'.
slave_running is reset to 0 at the end of handle_slave_* and within
a critical section guarded by run_lock mutex.
That means the terminatior can't get the reset case of 
slave_running == 0, 
However it actually could catch a unset case of the equality.
I.e the slave threads are in the initialization stage having not
set yet slave_running := 1.
That means a race condition between `start slave' and `shutdown'.

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/72723

2730 Andrei Elkin	2009-04-23
      Bug #38694  Race condition in replication thread shutdown 
      
      There were two issues:
      - a race condition between init_slave() and  end_slave().
        The thread running init_slave() does not wait for the slave threads
        signalling and it unlock LOCK_active_mi for the end_slave() running
        terminator to find the being started slave threads running status 0,
        i.e unchanged yet from the inititial value. That lets it to run
        delete active_mi without any obstacles. The slave threads crash e.g
        at trying to lock run_lock that belong in active_mi.
      
      - unguarded access to mi->slave_running by the shutdown thread
        calling end_slave().
      
      Fixed:
         - to wait for the slave threads ack by init_slave();
         - to remove the unguarded read of the running status
           and perform reading it in terminate_slave_thread()
           at time run_lock is taken.

Setting BUG#44312 + BUG#38716,  BUG#38694 in-progress back, after
getting couple of *new* issues at testing 
The issues of the 3 bugs remains valid and hopefully
the patches have solved them. 
However, I think we would like to not see any failures with restart of shutdown ever.

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/72798

2730 Andrei Elkin	2009-04-24
      Bug #38694  Race condition in replication thread shutdown 
      
      Two issues were identified out of the bug report:
      - a race condition between init_slave() and  end_slave().
      The thread running init_slave() does not wait for the being started 
      slave threads' signalling. It unlocks LOCK_active_mi to let 
      the end_slave() running terminator to find the slave threads
      running status as 0, i.e unchanged yet from the inititial value.
      The terminator in that case goes straight to delete active_mi without any ado.
      The slave threads will crash e.g at trying to lock run_lock that belong in
      the deleted active_mi.
      - unguarded access to mi->slave_running by the shutdown thread
      calling end_slave() that is bug#29968 (alas happened not to be cross-linked
      with the current bug)
      
      Fixed:
      - to wait for the slave threads ack by init_slave();
      - to remove the unguarded read of the running status
      and perform reading it in terminate_slave_thread()
      at time run_lock is taken (mostly bug#29968 backporting, still with some
      improvements over that patch - see the error reporting from 
      terminate_slave_thread()).

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/72804

2730 Andrei Elkin	2009-04-24
      Bug #38694  Race condition in replication thread shutdown 
      
      The issue of the current bug is unguarded access to mi->slave_running 
      by the shutdown thread calling end_slave() that is bug#29968 
      (alas happened not to be cross-linked with the current bug)
      
      Fixed:
      
      - to remove the unguarded read of the running status
      and perform reading it in terminate_slave_thread()
      at time run_lock is taken (mostly bug#29968 backporting, still with some
      improvements over that patch - see the error reporting from 
      terminate_slave_thread()).
      Issue of bug38716 is fixed here for 5.0 branch as well.
      
      Note:
      
      There has been a separate artifact identified - 
      a race condition between init_slave() and  end_slave() - 
      reported as  Bug#44467.

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/72901

2730 Andrei Elkin	2009-04-28
      Bug #38694  Race condition in replication thread shutdown 
      
      The issue of the current bug is unguarded access to mi->slave_running 
      by the shutdown thread calling end_slave() that is bug#29968 
      (alas happened not to be cross-linked with the current bug)
      
      Fixed:
      
      with removing the unguarded read of the running status
      and perform reading it in terminate_slave_thread()
      at time run_lock is taken (mostly bug#29968 backporting, still with some
      improvements over that patch - see the error reporting from 
      terminate_slave_thread()).
      Issue of bug#38716 is fixed here for 5.0 branch as well.
      
      Note:
      
      There has been a separate artifact identified - 
      a race condition between init_slave() and  end_slave() - 
      reported as  Bug#44467.

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/73158

2885 Andrei Elkin	2009-04-30
      moving bug#38694 test files into rpl suite

Pushed into 5.0.82 (revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (version source revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (merge vers: 5.0.82) (pib:6)

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:joro@sun.com-20090430145106-gsb4j17nl4yf9htf) (merge vers: 6.0.12-alpha) (pib:6)

Questions for Docs:

1. Was this issue confined to 5.0 only?

2. If not, what were the affected and fixed versions?

Thanks!

Documented bugfix in the 5.0.82 changelog as follows:

        Restarting the replication slave -- either by using STOP
        SLAVE plus START SLAVE, or by restarting the slave mysqld
        process -- could sometimes cause the slave to crash when
        using a debug version of the server.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)