MySQL Bugs: #83705: Assertion `!thd_get_cache_mngr(thd)->dbug_any

Bug #83705	Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' while stopping master
Submitted:	5 Nov 2016 16:50	Modified:	11 Nov 2016 12:24
Reporter:	Shahriyar Rzayev	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.6.32, 5.6.34	OS:	Linux
Assigned to:		CPU Architecture:	Any

Description:
After creating full disk condition  on binary log path:

2016-11-05 20:41:19 7564 [Warning] Disk is full writing '/home/sh/small_mounted_dir/mysql-bin.000001' (Errcode: 28 - No space left on device). Waiting for someone to f
ree space...
2016-11-05 20:41:19 7564 [Warning] Retry in 60 secs. Message reprinted in 600 secs

Trying to shutdown server:

2016-11-05 20:42:14 7564 [Note] /home/sh/MySQLPakcages/mysql-5.6.32/5.6.32/bin/mysqld: Normal shutdown
2016-11-05 20:42:19 7564 [ERROR] An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'IGNORE_ERROR'. Hence turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.
mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/binlog.cc:6864: bool MYSQL_BIN_LOG::change_stage(THD*, Stage_manager::StageID, THD*, mysql_mutex_t*, mysql_mutex_t*): Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' failed.
mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/binlog.cc:6864: bool MYSQL_BIN_LOG::change_stage(THD*, Stage_manager::StageID, THD*, mysql_mutex_t*, mysql_mutex_t*): Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' failed.
mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/binlog.cc:6864: bool MYSQL_BIN_LOG::change_stage(THD*, Stage_manager::StageID, THD*, mysql_mutex_t*, mysql_mutex_t*): Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' failed.
16:42:19 UTC - mysqld got signal 6 ;
.
.
mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/binlog.cc:6864: bool MYSQL_BIN_LOG::change_stage(THD*, Stage_manager::StageID, THD*, mysql_mutex_t*, mysql_mutex_t*): Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' failed.
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68183 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

mysqld: /home/sh/MySQLPakcages/mysql-5.6.32/sql/binlog.cc:6864: bool MYSQL_BIN_LOG::change_stage(THD*, Stage_manager::StageID, THD*, mysql_mutex_t*, mysql_mutex_t*): Assertion `!thd_get_cache_mngr(thd)->dbug_any_finalized()' failed.

How to repeat:
1. Create full disk condition for binary-log path running sysbench:
/home/sh/small_mounted_dir# sysbench --test=/home/sh/REPOS/sysbench/sysbench/tests/db/insert.lua --oltp-test-mode=complex --num-threads=100 --mysql-db=dbtest --mysql-user=root --mysql-password=msandbox --db-driver=mysql --max-requests=0 --innodb-table-size=1000000 --mysql-socket=/tmp/mysql_sandbox23097.sock run

2. Config
relay-log-index=mysql-relay
relay-log=mysql-relay
log-bin=/home/sh/small_mounted_dir/mysql-bin
server-id=1
log-error=msandbox.err

master-info-repository=table
relay-log-info-repository=table
gtid_mode=ON
log-slave-updates
enforce-gtid-consistency

3. Shutdown master

Hello Shahriyar,

Thank you for the bug report and details.
I'm not seeing any issues with current GA 5.6.34 and while bringing down server under the scenario you mentioned. Could you please try with 5.6.34 and let us know if you are still seeing this issue? Thanks..

-- Extract from error log pre/post shutdown 

2016-11-09 12:21:22 1613 [Note] bin/mysqld: ready for connections.
Version: '5.6.34-enterprise-commercial-advanced-log'  socket: '/tmp/mysql_master.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (Commercial)
2016-11-09 12:23:31 1613 [Warning] Disk is full writing '/ramdisk/83705/mysql-bin.000003' (Errcode: 28 - No space left on device). Waiting for someone to free space...
2016-11-09 12:23:31 1613 [Warning] Retry in 60 secs. Message reprinted in 600 secs
2016-11-09 12:25:31 1613 [Note] bin/mysqld: Normal shutdown

2016-11-09 12:25:31 1613 [Note] Giving 2 client threads a chance to die gracefully
2016-11-09 12:25:31 1613 [Note] Event Scheduler: Purging the queue. 0 events
2016-11-09 12:25:31 1613 [Note] Shutting down slave threads
2016-11-09 12:26:31 1613 [ERROR] An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'IGNORE_ERROR'. Hence turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.
2016-11-09 12:26:33 1613 [Note] Forcefully disconnecting 0 remaining clients
2016-11-09 12:26:33 1613 [Note] Binlog end
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'partition'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'ARCHIVE'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'BLACKHOLE'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_METRICS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_CMP'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'INNODB_TRX'
2016-11-09 12:26:33 1613 [Note] Shutting down plugin 'InnoDB'
2016-11-09 12:26:33 1613 [Note] InnoDB: FTS optimize thread exiting.
2016-11-09 12:26:33 1613 [Note] InnoDB: Starting shutdown...
2016-11-09 12:26:35 1613 [Note] InnoDB: Shutdown completed; log sequence number 221431215
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'CSV'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'MEMORY'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'MyISAM'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'MRG_MYISAM'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'sha256_password'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'mysql_old_password'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'mysql_native_password'
2016-11-09 12:26:35 1613 [Note] Shutting down plugin 'binlog'
2016-11-09 12:26:35 1613 [Note] bin/mysqld: Shutdown complete

Thanks,
Umesh

Could you please check it using debug build?

Thank you for the feedback.
Observed that only debug build is affected and release build has no issues in stopping master server.