MySQL Bugs: #68638: read_gtids_from_binlog improperly calls my_error with ER_MASTER_FATAL_ERROR

Bug #68638	read_gtids_from_binlog improperly calls my_error with ER_MASTER_FATAL_ERROR_READ
Submitted:	11 Mar 2013 16:15	Modified:	28 May 2013 6:17
Reporter:	Udo Gubbels	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.6.10-enterprise-commercial-advanced	OS:	Linux (3.2.0-38-generic #61-Ubuntu SMP Tue Feb 19 12:18:21 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux)
Assigned to:		CPU Architecture:	Any
Tags:	crash, full-disk, MySQL, resizefs, server

Description:
Hi MySQL Team,

first the description of our problem after that, I will insert the results from my test:

We use the MySQL Server Version (Ver 5.6.10-enterprise-commercial-advanced for debian6.0 on x86_64 (MySQL Enterprise Server - Advanced Edition (Commercial))) on an Ubuntu 12.04 LTS Version (3.2.0-38-generic #61-Ubuntu SMP Tue Feb 19 12:18:21 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux).

Today we had a full-disk and resize our lvm and filesystem for the mysql log partition but we couldn't login into our MySQL Service before and after this action, so we made a restart, the service shutdown but didn't comeback again. So we made a complete reboot from the server but this didn't solve the problem, too. The mysql service wouldn't start again. We work with a Master/Master GTID configuration, so we could restore the data from the second node but we will use this DB as production machine in the future so we will be sure, that this will not be happen again, maybe if the disk runs full again.

Here the results from our logs:
Error-log:

130311 16:28:37 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2013-03-11 16:28:38 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-03-11 16:28:38 11887 [Note] Plugin 'FEDERATED' is disabled.
2013-03-11 16:28:38 11887 [Note] InnoDB: The InnoDB memory heap is disabled
2013-03-11 16:28:38 11887 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-03-11 16:28:38 11887 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-03-11 16:28:38 11887 [Note] InnoDB: CPU does not support crc32 instructions
2013-03-11 16:28:38 11887 [Note] InnoDB: Using Linux native AIO
2013-03-11 16:28:38 11887 [Note] InnoDB: Initializing buffer pool, size = 10.0G
2013-03-11 16:28:39 11887 [Note] InnoDB: Completed initialization of buffer pool
2013-03-11 16:28:39 11887 [Note] InnoDB: Highest supported file format is Barracuda.
2013-03-11 16:28:39 11887 [Note] InnoDB: 128 rollback segment(s) are active.
2013-03-11 16:28:39 11887 [Note] InnoDB: Waiting for purge to start
2013-03-11 16:28:39 11887 [Note] InnoDB: 1.2.10 started; log sequence number 3224850494
2013-03-11 16:28:39 11887 [ERROR] Plugin 'audit_log' init function returned error.
2013-03-11 16:28:39 11887 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
2013-03-11 16:28:39 11887 [Note] Recovering after a crash using /var/log/mysql/mysql-bin
2013-03-11 16:28:39 11887 [Note] Starting crash recovery...
2013-03-11 16:28:39 11887 [Note] Crash recovery finished.
15:28:39 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=0
max_threads=2048
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 830496 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0x911e35]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x6a2e34]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7f36c615dcb0]
/lib/x86_64-linux-gnu/libc.so.6(+0x89221)[0x7f36c4dbf221]
/usr/local/mysql/bin/mysqld[0xb75514]
/usr/local/mysql/bin/mysqld(my_vsnprintf_ex+0x27d)[0xb762dd]
/usr/local/mysql/bin/mysqld(my_error+0xcf)[0x90bd9f]
/usr/local/mysql/bin/mysqld[0x8c36a6]
/usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG14init_gtid_setsEP8Gtid_setS1_bb+0x493)[0x8c6713]
/usr/local/mysql/bin/mysqld(_Z11mysqld_mainiPPc+0x100d)[0x5de49d]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7f36c4d5776d]
/usr/local/mysql/bin/mysqld[0x5cfe5d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
130311 16:28:39 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

resolve_stack
resolve_stack_dump -s /tmp/mysqld.sym -n /tmp/mysqld.stack
0x40000 (?)
0x911e35 my_print_stacktrace + 53
0x6a2e34 handle_fatal_signal + 1188
0x7f36c615dcb0 _end + -993041424
0x7f36c4dbf221 _end + -1013614239
0xb75514 process_str_arg + 68
0xb762dd my_vsnprintf_ex + 637
0x90bd9f my_error + 207
0x8c36a6 _ZL22read_gtids_from_binlogPKcP8Gtid_setS2_b + 1094
0x8c6713 _ZN13MYSQL_BIN_LOG14init_gtid_setsEP8Gtid_setS1_bb + 1171
0x5de49d _Z11mysqld_mainiPPc + 4109
0x7f36c4d5776d _end + -1014038867
0x5cfe5d _start + 41

Thank you in advance for your help.

br
Udo

How to repeat:
I couldn't repeat it because I didn't have a system which I could crash.

So I analyze the debian binary, and found the call that crashed. It is this my_error in read_gtids_from_binlog():

case GTID_LOG_EVENT:
{
 if (ret != GOT_GTIDS)
 {
  if (ret != GOT_PREVIOUS_GTIDS)
  // should not happen
    my_error(ER_MASTER_FATAL_ERROR_READING_BINLOG, MYF(0));  <-------
  else
    ret= GOT_GTIDS;
 }

And we have ER_MASTER_FATAL_ERROR_READING_BINLOG defined as:
"Got fatal error %d from master when reading data from binary log: '%-.320s'"

But no arguments given to my_error to fill in the format string!
I'll set this to verified based on code analysis. I hope that's okay.

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 bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Fixed in 5.6+. Documented in the 5.6.12 and 5.7.2 changelogs, as follows:

        When one or more GTID log events but no previous GTIDs log
        events were found in the binary log, the resulting error was
        mishandled and led to a failure of the server. (This is an
        extremely rare condition that should never occur under normal
        circumstances, and likely indicates that the binary log file has
        somehow been corrupted.) Now in such cases, an appropriate error
        is issued, and is handled correctly.
      

Closed.