MySQL crash when data initialized with autocommit=0 and GTID

[Przemek]

With following configuration the mysqld crashes when trying to log in via mysql client.
How to reproduce:
* my.cnf:

[mysqld]
server-id = 256
user = mysql
basedir = /usr
datadir = /var/lib/mysql
port = 3306
pid-file = /var/lib/mysql/mysql.pid
log-error = /var/lib/mysql/mysql.err
explicit_defaults_for_timestamp = 1
log_bin = /var/lib/mysql/mysql-bin
gtid-mode = ON
log-slave-updates = 1
enforce-gtid-consistency = 1
autocommit = 0

* install Percona-Server-server-56-5.6.17-rel65.0.el6.x86_64
* clean data dir and re-initialize:
[root@vagrant-centos65 ~]# su mysql
bash-4.1$ cd /var/lib/mysql/
bash-4.1$ rm -fr *; mysql_install_db
Useless use of a constant in void context at /usr/bin/mysql_install_db line 888.
Useless use of a constant in void context at /usr/bin/mysql_install_db line 458.
WARNING: The host 'vagrant-centos65.vagrantup.com' could not be looked up with /usr/bin/resolveip.
This probably means that your libc libraries are not 100 % compatible
with this binary MySQL version. The MySQL daemon, mysqld, should work
normally with the exception that host name resolving will not work.
This means that you should use IP addresses instead of hostnames
when specifying MySQL privileges !

Installing MySQL system tables...OK

Filling help tables...OK

(...)

bash-4.1$ ls -lh
total 110M
-rw-rw---- 1 mysql mysql 12M May 22 14:48 ibdata1
-rw-rw---- 1 mysql mysql 48M May 22 14:48 ib_logfile0
-rw-rw---- 1 mysql mysql 48M May 22 14:48 ib_logfile1
drwx------ 2 mysql mysql 4.0K May 22 14:48 mysql
-rw-rw---- 1 mysql mysql 62K May 22 14:48 mysql-bin.000001
-rw-rw---- 1 mysql mysql 1.2M May 22 14:48 mysql-bin.000002
-rw-rw---- 1 mysql mysql 64 May 22 14:48 mysql-bin.index
-rw-rw---- 1 mysql mysql 5.2K May 22 14:48 mysql.err
drwx------ 2 mysql mysql 4.0K May 22 14:48 performance_schema
drwx------ 2 mysql mysql 4.0K May 22 14:48 test

* start mysql
[root@vagrant-centos65 ~]# /etc/init.d/mysql start
Starting MySQL (Percona Server).. SUCCESS!

[root@vagrant-centos65 ~]# tail /var/lib/mysql/mysql.err
2014-05-22 14:50:44 16586 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 739fe40f-e1c0-11e3-82f3-080027079e3d.
2014-05-22 14:50:44 16586 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2014-05-22 14:50:44 16586 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2014-05-22 14:50:44 16586 [Note] Server hostname (bind-address): '*'; port: 3306
2014-05-22 14:50:44 16586 [Note] IPv6 is available.
2014-05-22 14:50:44 16586 [Note] - '::' resolves to '::';
2014-05-22 14:50:44 16586 [Note] Server socket created on IP: '::'.
2014-05-22 14:50:44 16586 [Note] Event Scheduler: Loaded 0 events
2014-05-22 14:50:44 16586 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.17-65.0-56-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 65.0, Revision 587

* try login:
[root@vagrant-centos65 ~]# mysql
ERROR 2013 (HY000): Lost connection to MySQL server at 'reading authorization packet', system error: 95

* error log:

14:51:39 UTC - mysqld got signal 8 ;
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x33482e0
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 = 7f443805ed48 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8cd695]
/usr/sbin/mysqld(handle_fatal_signal+0x4c4)[0x647694]
/lib64/libpthread.so.0(+0xf710)[0x7f443c71d710]
/usr/sbin/mysqld[0x664275]
/usr/sbin/mysqld[0x6648ce]
/usr/sbin/mysqld[0x664bf6]
/usr/sbin/mysqld[0x659239]
/usr/sbin/mysqld[0x659564]
/usr/sbin/mysqld(_Z16acl_authenticateP3THDj+0x1fe)[0x664e5e]
/usr/sbin/mysqld[0x69ac9a]
/usr/sbin/mysqld(_Z16login_connectionP3THD+0x4d)[0x69aecd]
/usr/sbin/mysqld(_Z22thd_prepare_connectionP3THD+0x24)[0x69b0c4]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x13f)[0x69c48f]
/usr/sbin/mysqld(handle_one_connection+0x47)[0x69c597]
/usr/sbin/mysqld(pfs_spawn_thread+0x12a)[0xb064ea]
/lib64/libpthread.so.0(+0x79d1)[0x7f443c7159d1]
/lib64/libc.so.6(clone+0x6d)[0x7f443ae34b6d]

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

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
140522 14:51:39 mysqld_safe Number of processes running now: 0
140522 14:51:39 mysqld_safe mysqld restarted
(...)

* mysql recovers but then crashes on evey login attempt

[Valerii Kravchuk (valerii-kravchuk)]

Confirmed with my own build from recent bzr sources suing commands like these:

1000 rm CMakeCache.txt
1001 cmake . -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/p5.6 -DCMAKE_BUILD_TYPE=RelWithDebInfo -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF
1002 make
1003 make install && make clean

...

1015 cd dbs/p5.6
1016 ls
1017 ls data/
1018 rm -rf data/*

...

1026 scripts/mysql_install_db --no-defaults --server-id=256 --explicit_defaults_for_timestamp=1 --log-bin --gtid-mode=ON --log-slave-updates=1 --enforce-gtid-consistency=1 --autocommit=0
1027 ls -lh data/
1028 bin/mysqld_safe --no-defaults --server-id=256 --explicit_defaults_for_timestamp=1 --log-bin --gtid-mode=ON --log-slave-updates=1 --enforce-gtid-consistency=1 --autocommit=0 &
1029 tail data/chief.err
1030 bin/mysql -uroot test
1031 tail -80 data/chief.err

This is what we see in the error log:

[openxs@chief p5.6]$ bin/mysql -uroot test
ERROR 2013 (HY000): Lost connection to MySQL server at 'reading authorization packet', system error: 95
[openxs@chief p5.6]$ 140523 12:38:27 mysqld_safe Number of processes running now: 0
140523 12:38:27 mysqld_safe mysqld restarted

[openxs@chief p5.6]$ tail -80 data/chief.err Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x28b1d50
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 = 7fa5e006be10 thread_stack 0x40000
/home/openxs/dbs/p5.6/bin/mysqld(my_print_stacktrace+0x35)[0x902035]
/home/openxs/dbs/p5.6/bin/mysqld(handle_fatal_signal+0x4c4)[0x66cd24]
/lib64/libpthread.so.0[0x3ffac0eeb0]
/home/openxs/dbs/p5.6/bin/mysqld[0x68f629]
/home/openxs/dbs/p5.6/bin/mysqld[0x68fc98]
/home/openxs/dbs/p5.6/bin/mysqld[0x69007e]
/home/openxs/dbs/p5.6/bin/mysqld[0x67d779]
/home/openxs/dbs/p5.6/bin/mysqld[0x67d944]
/home/openxs/dbs/p5.6/bin/mysqld(_Z16acl_authenticateP3THDj+0x1c0)[0x690430]
/home/openxs/dbs/p5.6/bin/mysqld[0x6bcb2a]
/home/openxs/dbs/p5.6/bin/mysqld(_Z16login_connectionP3THD+0x4d)[0x6be4bd]
/home/openxs/dbs/p5.6/bin/mysqld(_Z22thd_prepare_connectionP3THD+0x24)[0x6bec14]
/home/openxs/dbs/p5.6/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x135)[0x6bef15]
/home/openxs/dbs/p5.6/bin/mysqld(handle_one_connection+0x47)[0x6bf017]
/home/openxs/dbs/p5.6/bin/mysqld(pfs_spawn_thread+0x12a)[0x98fa0a]
/lib64/libpthread.so.0[0x3ffac06ccb]
/lib64/libc.so.6(clone+0x6d)[0x3ffa8e0c2d]

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

[Przemek (pmalkowski)]

So far could not reproduce on MySQL Community 5.6.17 (yum repo for Centos6) but also could not repeat exactly the same test case due to: http://bugs.mysql.com/bug.php?id=72724

[Valerii Kravchuk (valerii-kravchuk)]

Upstream MySQL is not directly affected as root user is just not there with the same actions:

...
2014-05-23 13:06:19 2533 [Note] Event Scheduler: Loaded 0 events
2014-05-23 13:06:19 2533 [Note] /home/openxs/dbs/5.6/bin/mysqld: ready for connections.
Version: '5.6.17-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
[openxs@chief 5.6]$ bin/mysql -uroot test
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: NO)
[openxs@chief 5.6]$ bin/mysql -uroot -proot test
Warning: Using a password on the command line interface can be insecure.
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
[openxs@chief 5.6]$ fc -l
...
1046 rm CMakeCache.txt
1047 cmake . -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/5.6 -DCMAKE_BUILD_TYPE=RelWithDebInfo -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF
1048 make
1049 make install && make clean
1050 cd ~/dbs/5.6
1051 rm -rf data/*
1052 scripts/mysql_install_db --no-defaults --server-id=256 --explicit_defaults_for_timestamp=1 --log-bin --gtid-mode=ON --log-slave-updates=1 --enforce-gtid-consistency=1 --autocommit=0
1053 ls -lh data/
1054 bin/mysqld_safe --no-defaults --server-id=256 --explicit_defaults_for_timestamp=1 --log-bin --gtid-mode=ON --log-slave-updates=1 --enforce-gtid-consistency=1 --autocommit=0 &
1055 tail data/chief.err
1056 bin/mysql -uroot test
1057 bin/mysql -uroot -proot test

[Vlad Lesin (vlad-lesin)]

I am working with revision 601 of 5.6 branch and all line numbers in the code are for this revision.

The main issue I see here is in this error message during execution mysq_install_db:
ERROR: 1787 When @@GLOBAL.ENFORCE_GTID_CONSISTENCY = 1, the statements CREATE TEMPORARY TABLE and DROP TEMPORARY TABLE can be executed in a non-transactional context only, and require that AUTOCOMMIT = 1.
2014-05-30 00:55:19 25139 [ERROR] Aborting

I see at least three issues on different layers here:

1)
If we look into scripts/mysql_install_db.pl.in lines 740-787 are responsible for invoking mysqld in bootstrap mode and feeding the following files to it:
my $create_system_tables = "$pkgdatadir/mysql_system_tables.sql";
my $fill_system_tables = "$pkgdatadir/mysql_system_tables_data.sql";

The code use 'open(PIPE, "| $mysqld_install_cmd_line")' perl construction which allows easily work with pipes, but the return code of mysqld is not checked, so if something went wrong as in our case with mutually exclusive mysqld options mysql_install_db will ignore the error and continue the execution.

I would propose to check the return value of perl "close" function when the pipe is closed. Here is the description how to check error code of the child on another side of pipe with "close":

"If the filehandle came from a piped open, close returns false if one of the other syscalls involved fails or if its program exits with non-zero status. If the only problem was that the program exited non-zero, $! will be set to 0 . Closing a pipe also waits for the process executing on the pipe to exit--in case you wish to look at the output of the pipe afterwards--and implicitly puts the exit status value of that command into $? and ${^CHILD_ERROR_NATIVE}." (http://perldoc.perl.org/functions/close.html)

In the case of unexpected mysqld termination mysql_install_db should be stopped with corresponding error message.

But this will not solve the issue completely. Imagine we have options in my.cnf which are not compatible with statements for creating and filling system tables. In this case mysql_install_db will fail and this will not allow to create and initialize data directory.

At the other hand this can be right solution as changing some common rules or checks depending on suggestions about the purpose of server launching would be not obvious and sometimes confusing. The error message will give possibility to understand what exactly options are incompatible with bootstrap and fix them manually completely understanding the situation.

2)
Here is the backtrace of mysqld when the error message is output during creating tables in mysql_install_db:

#0 THD::is_ddl_gtid_compatible (this=0x1432340) at /tmp/1/5.6/sql/binlog.cc:8393
#1 0x00000000008709a5 in gtid_pre_statement_checks (thd=thd@entry=0x1432340) at /tmp/1/5.6/sql/rpl_gtid_execution.cc:301
#2 0x00000000006f37b2 in mysql_execute_command (thd=thd@entry=0x1432340) at /tmp/1/5.6/sql/sql_parse.cc:2797
#3 0x00000000006fa458 in mysql_parse (thd=0x1432340, rawbuf=<optimized out>, length=<optimized out>,
    parser_state=parser_state@entry=0x7fffe0087e70) at /tmp/1/5.6/sql/sql_parse.cc:6738
#4 0x00000000006fa684 in handle_boots...

[Przemek (pmalkowski)]

I tried to reproduce on upstream MySQL 5.6.17 again, but now with workaround the missing root user problem:
* removed datadir contents
* mysql_install_db --user=mysql
* overwritten the user.frm user.MYD user.MYI from another 5.6.17 instance having root@localhost
* started mysqld
* logged as root - no crash happens

Error log from the mysql_install_db stage:

2014-06-02 08:11:50 22015 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-06-02 08:11:50 22015 [Note] InnoDB: The InnoDB memory heap is disabled
2014-06-02 08:11:50 22015 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-06-02 08:11:50 22015 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-06-02 08:11:50 22015 [Note] InnoDB: Using Linux native AIO
2014-06-02 08:11:50 22015 [Note] InnoDB: Not using CPU crc32 instructions
2014-06-02 08:11:50 22015 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-06-02 08:11:50 22015 [Note] InnoDB: Completed initialization of buffer pool
2014-06-02 08:11:50 22015 [Note] InnoDB: The first specified data file ./ibdata1 did not exist: a new database to be created!
2014-06-02 08:11:50 22015 [Note] InnoDB: Setting file ./ibdata1 size to 12 MB
2014-06-02 08:11:50 22015 [Note] InnoDB: Database physically writes the file full: wait...
2014-06-02 08:11:50 22015 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2014-06-02 08:11:50 22015 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2014-06-02 08:11:51 22015 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2014-06-02 08:11:51 22015 [Warning] InnoDB: New log files created, LSN=45781
2014-06-02 08:11:51 22015 [Note] InnoDB: Doublewrite buffer not found: creating new
2014-06-02 08:11:51 22015 [Note] InnoDB: Doublewrite buffer created
2014-06-02 08:11:51 22015 [Note] InnoDB: 128 rollback segment(s) are active.
2014-06-02 08:11:51 22015 [Warning] InnoDB: Creating foreign key constraint system tables.
2014-06-02 08:11:51 22015 [Note] InnoDB: Foreign key constraint system tables created
2014-06-02 08:11:51 22015 [Note] InnoDB: Creating tablespace and datafile system tables.
2014-06-02 08:11:51 22015 [Note] InnoDB: Tablespace and datafile system tables created.
2014-06-02 08:11:51 22015 [Note] InnoDB: Waiting for purge to start
2014-06-02 08:11:51 22015 [Note] InnoDB: 5.6.17 started; log sequence number 0
2014-06-02 08:11:51 22015 [Warning] Bootstrap mode disables GTIDs. Bootstrap mode should only be used by mysql_install_db which initializes the MySQL data directory and creates system tables.
ERROR: 1787 When @@GLOBAL.ENFORCE_GTID_CONSISTENCY = 1, the statements CREATE TEMPORARY TABLE and DROP TEMPORARY TABLE can be executed in a non-transactional context only, and require that AUTOCOMMIT = 1.
2014-06-02 08:11:51 22015 [ERROR] Aborting

2014-06-02 08:11:51 22015 [Note] Binlog end
2014-06-02 08:11:51 22015 [Note] InnoDB: FTS optimize thread exiting.
2014-06-02 08:11:51 22015 [Note] InnoDB: Starting shutdown...
2014-06-02 08:11:52 22015 [Note] InnoDB: Shutdown completed; log sequence number 1625977
2014-06-02 08:11:52 22015 [Note] ./bin/mysqld: Shutdown complete

2014-06-02 08:11:52 22038 [Note] InnoDB: Using atomics to ref count buf...

[Vlad Lesin (vlad-lesin)]

This bug is divided into two bugs.

1) The first one is the floating point error if 'users' system table is empty. This is the case described in this bug report. The current releases (5.6.21-69.0-r675, 5.5.40-rel36.1-707, 5.1.73) do not contain the code with error, i.e. the bug has been already fixed.

2) The second one is reported here https://bugs.launchpad.net/percona-server/+bug/1382782 and this is a silent behaviour of mysql_install_db if mysqld is terminated on the step of system tables creating and filling. This is a separate upstream bug(http://bugs.mysql.com/bug.php?id=74440) and it should not be considered here.

So as (1) is fixed and (2) is a separate bug I propose to close the current bug.

[Laurynas Biveinis (laurynas-biveinis)]

Fixed in the 5.5.39 merge.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-788