MySQL Bugs: #76825: SIGABRT -> binlog_cache_data::reset(): Assertion `is_binlog

Bug #76825	SIGABRT -> binlog_cache_data::reset(): Assertion `is_binlog_empty()' failed
Submitted:	24 Apr 2015 12:20	Modified:	8 May 2018 13:04
Reporter:	Shahriyar Rzayev (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.6.24,5.7.7-rc	OS:	Linux (CentOS 6.5, 7)
Assigned to:		CPU Architecture:	Any

Description:
Dear experts,
while testing disk full conditions using MySQL 5.6.24-debug server with GTID enabled as following:

log_bin                        = /opt/mysql/datadir/mysql-bin
log_bin_index                  = /opt/mysql/datadir/mysql-bin
sync_binlog                    = 1
binlog_format                  = row
gtid-mode                      = on
log_slave_updates              = 1
enforce-gtid-consistency       = true

While importing huge dump file:

InnoDB: 1048576 bytes should have been written, only 53248 were written.
InnoDB: Operating system error number 0.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 0 means 'Success'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2015-04-24 07:40:06 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:40:13 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:40:19 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:40:26 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:40:32 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full

Interesting thing about OS error message number, that it is equal to 0.
And 0 is success.
Usually while rising disk errors, OS number is 11 and 28.
After a while:

2015-04-24 07:46:16 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:46:22 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
2015-04-24 07:46:28 27574 [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full
mysqld: /root/mysql-5.6.24/sql/binlog.cc:418: virtual void binlog_cache_data::reset(): Assertion `is_binlog_empty()' failed.
11:46:32 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
Thread pointer: 0x27e13f0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f9452744d20 thread_stack 0x40000
/opt/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xaf3925]
/opt/mysql/bin/mysqld(handle_fatal_signal+0x404)[0x7491a6]
/lib64/libpthread.so.0(+0xf710)[0x7f947e787710]
/lib64/libc.so.6(gsignal+0x35)[0x7f947cdce925]
/lib64/libc.so.6(abort+0x175)[0x7f947cdd0105]
/lib64/libc.so.6(+0x2ba4e)[0x7f947cdc7a4e]
/lib64/libc.so.6(__assert_perror_fail+0x0)[0x7f947cdc7b10]
/opt/mysql/bin/mysqld(_ZN17binlog_cache_data5resetEv+0x17d)[0xa7db53]
/opt/mysql/bin/mysqld(_ZN21binlog_trx_cache_data5resetEv+0x9d)[0xa7df65]
/opt/mysql/bin/mysqld(_ZN21binlog_trx_cache_data8truncateEP3THDb+0x14f)[0xa693a9]
/opt/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG8rollbackEP3THDb+0x3fe)[0xa6a0d8]
/opt/mysql/bin/mysqld(_Z17ha_rollback_transP3THDb+0x126)[0x6528b9]
/opt/mysql/bin/mysqld(_Z19trans_rollback_stmtP3THD+0x15d)[0x8d3529]
/opt/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x7ee0)[0x80501b]
/opt/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x423)[0x8081b5]
/opt/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xd15)[0x7fad43]
/opt/mysql/bin/mysqld(_Z10do_commandP3THD+0x34f)[0x7f9dbd]
/opt/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x1be)[0x7beb67]
/opt/mysql/bin/mysqld(handle_one_connection+0x33)[0x7be66f]
/opt/mysql/bin/mysqld(pfs_spawn_thread+0x159)[0xbb79ff]
/lib64/libpthread.so.0(+0x79d1)[0x7f947e77f9d1]
/lib64/libc.so.6(clone+0x6d)[0x7f947ce84b5d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f942da3db70): is an invalid pointer
Connection ID (thread ID): 1
Status: NOT_KILLED

How to repeat:
1. Create a full disk error condition
2. Activate GTID binlog
3. Import quiet huge dump file, wait assertion fail.

Suggested fix:
Can provide any necessary information if needed.

Changed Category of report.

Reprodicable with MySQl 5.7.7-rc-debug build.
Output from gdb:

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffde31f700 (LWP 2816)]
0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	  return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);

(gdb) bt
#0  0x00007ffff61675d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007ffff6168cc8 in __GI_abort () at abort.c:90
#2  0x00007ffff6160546 in __assert_fail_base (fmt=0x7ffff62b0128 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x20fdb01 "is_binlog_empty()", file=file@entry=0x20fd990 "/root/mysql-5.7.7-rc/sql/binlog.cc", line=line@entry=389, 
    function=function@entry=0x21030c0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "virtual void binlog_cache_data::reset()") at assert.c:92
#3  0x00007ffff61605f2 in __GI___assert_fail (assertion=0x20fdb01 "is_binlog_empty()", file=0x20fd990 "/root/mysql-5.7.7-rc/sql/binlog.cc", line=389, 
    function=0x21030c0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "virtual void binlog_cache_data::reset()") at assert.c:101
#4  0x000000000181ed71 in binlog_cache_data::reset (this=0x7fffb400da68) at /root/mysql-5.7.7-rc/sql/binlog.cc:389
#5  0x000000000181f091 in binlog_trx_cache_data::reset (this=0x7fffb400da68) at /root/mysql-5.7.7-rc/sql/binlog.cc:599
#6  0x000000000180776a in binlog_trx_cache_data::truncate (this=0x7fffb400da68, thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/binlog.cc:1457
#7  0x00000000018089fa in MYSQL_BIN_LOG::rollback (this=0x2bd78c0 <mysql_bin_log>, thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/binlog.cc:1994
#8  0x0000000000f84dfa in ha_rollback_trans (thd=0x7fffb4000c80, all=false) at /root/mysql-5.7.7-rc/sql/handler.cc:1854
#9  0x0000000001682449 in trans_rollback_stmt (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/transaction.cc:442
#10 0x000000000158e778 in mysql_execute_command (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:4586
#11 0x000000000158ff62 in mysql_parse (thd=0x7fffb4000c80, parser_state=0x7fffde31e5a0) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:5159
#12 0x0000000001585cf1 in dispatch_command (command=COM_QUERY, thd=0x7fffb4000c80, 
    packet=0x7fffb49fd901 "INSERT INTO `sales` VALUES (408505,'1155','40','2001-06-30 14:28:05','253','6399','34','597','0','A','','0'),(408506,'827','5','2005-05-31 14:28:05','378','1169','46','707','0','A','','0'),(408507,'16"..., packet_length=1034768) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:1249
#13 0x0000000001584b21 in do_command (thd=0x7fffb4000c80) at /root/mysql-5.7.7-rc/sql/sql_parse.cc:835
#14 0x00000000016adcff in handle_connection (arg=0x3cbd6b0) at /root/mysql-5.7.7-rc/sql/conn_handler/connection_handler_per_thread.cc:298
#15 0x0000000001cd9905 in pfs_spawn_thread (arg=0x3bfb1f0) at /root/mysql-5.7.7-rc/storage/perfschema/pfs.cc:2147
#16 0x00007ffff7bc6df5 in start_thread (arg=0x7fffde31f700) at pthread_create.c:308
#17 0x00007ffff62281ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Added  bt full output

Attachment: bt_full_#76825.txt (text/plain), 10.30 KiB.

It is difficult to spot this issue, but here another interesting error:

2016-11-08 18:05:00 7fffcd54f700 InnoDB: Error: Write to file ./employees/titles.ibd failed at offset 98304.
InnoDB: 32768 bytes should have been written, only 20480 were written.
InnoDB: Operating system error number 0.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 0 means 'Success'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
/home/sh/MySQLPakcages/mysql-5.6.32/5.6.32/bin/mysqld: Error writing file './mysql-bin.index_crash_safe' (Errcode: 28 - No space left on device)
2016-11-08 18:05:00 13493 [ERROR] MYSQL_BIN_LOG::add_log_to_index failed to copy index file to crash safe index file.
2016-11-08 18:05:00 13493 [ERROR] Could not use (null) for logging (error 0). 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-08 18:05:00 13493 [ERROR] Aborting

Error is very sporadic and can't be catch easily.
So please safely close.

Closing according last comment.