MySQL crash when data initialized with autocommit=0 and GTID
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
| Percona Server moved to https://jira.percona.com/projects/PS |
Invalid
|
High
|
Vlad Lesin | |
| 5.1 |
Invalid
|
High
|
Vlad Lesin | |
| 5.5 |
Fix Released
|
High
|
Laurynas Biveinis | |
| 5.6 |
Invalid
|
High
|
Vlad Lesin |
Bug Description
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/
log-error = /var/lib/
explicit_
log_bin = /var/lib/
gtid-mode = ON
log-slave-updates = 1
enforce-
autocommit = 0
* install Percona-
* clean data dir and re-initialize:
[root@vagrant-
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/
Useless use of a constant in void context at /usr/bin/
WARNING: The host 'vagrant-
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-
Starting MySQL (Percona Server).. SUCCESS!
[root@vagrant-
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-
2014-05-22 14:50:44 16586 [Note] RSA private key file not found: /var/lib/
2014-05-22 14:50:44 16586 [Note] RSA public key file not found: /var/lib/
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-
* try login:
[root@vagrant-
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://
key_buffer_
read_buffer_
max_used_
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_
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/
/usr/sbin/
/lib64/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/usr/sbin/
/lib64/
/lib64/
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://
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
Related branches
- Laurynas Biveinis (community): Needs Information on 2014-09-25
- Laurynas Biveinis (community): Needs Information on 2014-09-25
-
Diff: 86 lines (+52/-2) (has conflicts)2 files modifiedscripts/mysql_install_db.pl.in (+28/-2)
sql/sql_acl.cc (+24/-0)
- Laurynas Biveinis (community): Needs Information on 2014-09-25
-
Diff: 47 lines (+28/-2)1 file modifiedPercona-Server/scripts/mysql_install_db.pl.in (+28/-2)
Przemek (pmalkowski) wrote : | #2 |
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://
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/
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_
1048 make
1049 make install && make clean
1050 cd ~/dbs/5.6
1051 rm -rf data/*
1052 scripts/
1053 ls -lh data/
1054 bin/mysqld_safe --no-defaults --server-id=256 --explicit_
1055 tail data/chief.err
1056 bin/mysql -uroot test
1057 bin/mysql -uroot -proot test
Vlad Lesin (vlad-lesin) wrote : | #4 |
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.
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/
my $create_
my $fill_system_tables = "$pkgdatadir/
The code use 'open(PIPE, "| $mysqld_
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_
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_
#1 0x00000000008709a5 in gtid_pre_
#2 0x00000000006f37b2 in mysql_execute_
#3 0x00000000006fa458 in mysql_parse (thd=0x1432340, rawbuf=<optimized out>, length=<optimized out>,
parser_
#4 0x00000000006fa684 in handle_boots...
Przemek (pmalkowski) wrote : | #5 |
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.
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) wrote : | #6 |
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:/
So as (1) is fixed and (2) is a separate bug I propose to close the current bug.
Fixed in the 5.5.39 merge.
Shahriyar Rzayev (rzayev-sehriyar) wrote : | #8 |
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/
Confirmed with my own build from recent bzr sources suing commands like these:
1000 rm CMakeCache.txt INSTALL_ PREFIX= /home/openxs/ dbs/p5. 6 -DCMAKE_ BUILD_TYPE= RelWithDebInfo -DBUILD_ CONFIG= mysql_release -DFEATURE_ SET=community -DWITH_ EMBEDDED_ SERVER= OFF
1001 cmake . -DCMAKE_
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-consistenc y=1 --autocommit=0 defaults_ for_timestamp= 1 --log-bin --gtid-mode=ON --log-slave- updates= 1 --enforce- gtid-consistenc y=1 --autocommit=0 &
1027 ls -lh data/
1028 bin/mysqld_safe --no-defaults --server-id=256 --explicit_
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.percona. com/
bugs at http://
key_buffer_ size=8388608 size=131072 connections= 1 size)*max_ threads = 69168 K bytes of memory
read_buffer_
max_used_
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_
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x28b1d50 dbs/p5. 6/bin/mysqld( my_print_ stacktrace+ 0x35)[0x902035] dbs/p5. 6/bin/mysqld( handle_ fatal_signal+ 0x4c4)[ 0x66cd24] libpthread. so.0[0x3ffac0ee b0] dbs/p5. 6/bin/mysqld[ 0x68f629] dbs/p5. 6/bin/mysqld[ 0x68fc98] dbs/p5. 6/bin/mysqld[ 0x69007e] dbs/p5. 6/bin/mysqld[ 0x67d779] dbs/p5. 6/bin/mysqld[ 0x67d944] dbs/p5. 6/bin/mysqld( _Z16acl_ authenticateP3T HDj+0x1c0) [0x690430] dbs/p5. 6/bin/mysqld[ 0x6bcb2a] dbs/p5. 6/bin/mysqld( _Z16login_ connectionP3THD +0x4d)[ 0x6be4bd] dbs/p5. 6/bin/mysqld( _Z22thd_ prepare_ connectionP3THD +0x24)[ 0x6bec14] dbs/p5. 6/bin/mysqld( _Z24do_ handle_ one_connectionP 3THD+0x135) [0x6bef15] dbs/p5. 6/bin/mysqld( handle_ one_connection+ 0x47)[0x6bf017] dbs/p5. 6/bin/mysqld( pfs_spawn_ thread+ 0x12a)[ 0x98fa0a] libpthread. so.0[0x3ffac06c cb] libc.so. 6(clone+ 0x6d)[0x3ffa8e0 c2d]
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/
/home/openxs/
/lib64/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/home/openxs/
/lib64/
/lib64/
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
...