[MDEV-8575] MySQL refuse to start after a crash Created: 2015-08-07  Updated: 2017-08-15  Resolved: 2015-09-08

Status: Closed
Project: MariaDB Server
Component/s: Encryption
Affects Version/s: 10.1.6
Fix Version/s: N/A

Type: Bug Priority: Blocker
Reporter: Aurélien LEQUOY Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

Ubuntu 12.04 + MariaDB 10.1.6 (from the repository)

Issue Links:
Relates
relates to MDEV-13537 InnoDB: Failing assertion: event afte... Closed

 Description    

150807 14:58:27 mysqld_safe Starting mysqld daemon with databases from /data/mysql/data
 
2015-08-07 14:58:28 140191626835840 [Note] /usr/sbin/mysqld (mysqld 10.1.6-MariaDB-1~precise-log) starting as process 7174 ...
 
2015-08-07 14:58:28 140191626835840 [Note] Using encryption key id 1 for temporary files
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Memory barrier is not used
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Using Linux native AIO
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Not using CPU crc32 instructions
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Initializing buffer pool, size = 1.0G
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Completed initialization of buffer pool
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Highest supported file format is Barracuda.
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Log scan progressed past the checkpoint lsn 21384312922
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Database was not shutdown normally!
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Starting crash recovery.
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Restoring possible half-written data pages
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: from the doublewrite buffer...
 
InnoDB: Doing recovery: scanned up to log sequence number 21384329285
 
2015-08-07 14:58:28 140191626835840 [Note] InnoDB: Starting an apply batch of log records to the database...
 
InnoDB: Progress in percent: 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
 
InnoDB: Apply batch completed
 
InnoDB: Last MySQL binlog file position 0 3589410, file name /data/mysql/binlog/mariadb-bin.000003
 
2015-08-07 14:58:30 140191626835840 [Note] InnoDB: 128 rollback segment(s) are active.
 
2015-08-07 14:58:30 140191626835840 [Note] InnoDB: Waiting for purge to start
 
2015-08-07 14:58:30 140191626835840 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 21384329285
 
2015-08-07 14:58:30 7f80e81e3780  InnoDB: Assertion failure in thread 140191626835840 in file os0sync.cc line 419
 
InnoDB: Failing assertion: event
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
150807 14:58:30 [ERROR] mysqld got signal 6 ;
 
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.
 
 
 
To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.1.6-MariaDB-1~precise-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1002
 
thread_count=0
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10540258 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
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 = 0x0 thread_stack 0x48000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7f80e8c35e2b]
 
/usr/sbin/mysqld(handle_fatal_signal+0x455)[0x7f80e87cdbd5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7f80e7dd9cb0]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f80e617b0d5]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7f80e617e83b]
 
/usr/sbin/mysqld(+0x756247)[0x7f80e8962247]
 
/usr/sbin/mysqld(+0x89e448)[0x7f80e8aaa448]
 
/usr/sbin/mysqld(+0x83ea5b)[0x7f80e8a4aa5b]
 
/usr/sbin/mysqld(+0x847c44)[0x7f80e8a53c44]
 
/usr/sbin/mysqld(+0x848e7d)[0x7f80e8a54e7d]
 
/usr/sbin/mysqld(+0x84a013)[0x7f80e8a56013]
 
/usr/sbin/mysqld(+0x84b0f3)[0x7f80e8a570f3]
 
/usr/sbin/mysqld(+0x729f27)[0x7f80e8935f27]
 
/usr/sbin/mysqld(+0x732c98)[0x7f80e893ec98]
 
/usr/sbin/mysqld(+0x7ce657)[0x7f80e89da657]
 
/usr/sbin/mysqld(+0x6f66d5)[0x7f80e89026d5]
 
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x68)[0x7f80e87d0178]
 
/usr/sbin/mysqld(+0x46c8c5)[0x7f80e86788c5]
 
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x8e2)[0x7f80e8679822]
 
/usr/sbin/mysqld(+0x3a63e7)[0x7f80e85b23e7]
 
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x1d10)[0x7f80e85b4c10]
 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7f80e616676d]
 
/usr/sbin/mysqld(+0x39d099)[0x7f80e85a9099]
 
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.
 
150807 14:58:30 mysqld_safe mysqld from pid file /data/mysql/data/aurelien-VGN-CR42Z-R.pid ended

The goal was to see impact on perf with and without encryption.

my.cnf

[client]
 
 
 
# default-character-set = utf8
 
 
 
[mysqld]
 
 
 
performance_schema = on
 
event_scheduler = on
 
character-set-server = utf8
 
open_files_limit =  65535
 
 
 
 
 
character-set-client-handshake = FALSE
 
collation-server = utf8_general_ci
 
 
 
log_error = /data/mysql/log/error.log
 
 
 
bind-address        = 0.0.0.0
 
external-locking    = off
 
skip-name-resolve
 
datadir             = /data/mysql/data
 
 
 
#make a crc32 of ip server
 
server-id=476467
 
 
 
replicate-ignore-db=mysql
 
replicate-ignore-db=information_schema
 
replicate-ignore-db=performance_schema
 
skip-slave-start
 
 
 
log-slave-updates
 
 
 
#innodb
 
innodb_buffer_pool_size = 1G
 
innodb_flush_method     = O_DIRECT
 
 
 
 
 
 #for master
 
log_bin                 = /data/mysql/binlog/mariadb-bin
 
log_bin_index           = /data/mysql/binlog/mariadb-bin.index
 
 
 
max_binlog_size         = 1G
 
max_binlog_size         = 1G
 
expire_logs_days        = 15
 
binlog-ignore-db    = information_schema
 
binlog-ignore-db    = mysql
 
binlog-ignore-db    = performance_schema
 
 
 
binlog_format = ROW
 
 
 
#log
 
slow_query_log_file     = /data/mysql/log/mariadb-slow.log
 
long_query_time = 1
 
 
 
 
 
# * Fine Tuning
 
#
 
max_connections         = 1000
 
connect_timeout         = 60
 
wait_timeout            = 600
 
max_allowed_packet      = 16M
 
thread_cache_size       = 128
 
sort_buffer_size        = 10M
 
bulk_insert_buffer_size = 16M
 
tmp_table_size          = 64M
 
max_heap_table_size     = 64M
 
 
 
 
 
innodb_file_per_table
 
innodb_autoinc_lock_mode = 2
 
innodb_flush_log_at_trx_commit = 2
 
 
 
 
 
[mysql]
 
default-character-set   = utf8
 
 
 
[mariadb-10.1]
 
plugin-load-add=file_key_management.so
 
file-key-management
 
file-key-management-filename='key.enc'
 
file_key_management_filekey='secretPassword2'
 
 
 
innodb-encrypt-tables
 
innodb-encrypt-log
 
innodb-encryption-threads=2
 
encrypt-tmp-disk-tables=1

I made some test with sysbench and server crashed few time after (and server was inactif), because I could finish my test and I see that the encryption decrease perf of 15%.

last sysbench :

sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --num-threads=32 --mysql-host=localhost --mysql-user=root --db-driver=mysql --mysql-password=password --mysql-db=test --max-time=60 --max-requests=0 run

(with table encrypted)

 Comments   
Comment by Aurélien LEQUOY [ 2015-08-07 ]

I removed options of encryptions and set i back in [mysqld] and I got :

150807 15:29:52 mysqld_safe Starting mysqld daemon with databases from /data/mysql/data
 
2015-08-07 15:29:53 140185766647680 [Note] /usr/sbin/mysqld (mysqld 10.1.6-MariaDB-1~precise-log) starting as process 14448 ...
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Memory barrier is not used
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Using Linux native AIO
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Not using CPU crc32 instructions
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Initializing buffer pool, size = 1.0G
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Completed initialization of buffer pool
 
2015-08-07 15:29:53 140185766647680 [Note] InnoDB: Highest supported file format is Barracuda.
 
2015-08-07 15:29:53 140185766647680 [ERROR] InnoDB: Redo log crypto: getting mysqld crypto key from key version failed. Reason could be that requested key_version 1 is not found or required encryption  key management is not found.
 
2015-08-07 15:29:53 140185766647680 [ERROR] Plugin 'InnoDB' init function returned error.
 
2015-08-07 15:29:53 140185766647680 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2015-08-07 15:29:53 140185766647680 [Note] Plugin 'FEEDBACK' is disabled.
 
2015-08-07 15:29:53 140185766647680 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2015-08-07 15:29:53 140185766647680 [ERROR] Aborting
 
 
 
2015-08-07 15:29:53 140185766647680 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
150807 15:29:53 mysqld_safe mysqld from pid file /data/mysql/data/aurelien-VGN-CR42Z-R.pid ended

i guess server tried to encrypt somthing on server and make it wrong and now impossible to start the server due to this problem

Comment by Aurélien LEQUOY [ 2015-08-07 ]

I removed options of encryptions and set i back in section * [mariadb-10.1]* and I got :

150807 16:51:09 mysqld_safe Starting mysqld daemon with databases from /data/mysql/data
 
2015-08-07 16:51:10 140585934886784 [Note] /usr/sbin/mysqld (mysqld 10.1.6-MariaDB-1~precise-log) starting as process 28251 ...
 
2015-08-07 16:51:10 140585934886784 [Note] Using encryption key id 1 for temporary files
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: The InnoDB memory heap is disabled
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Memory barrier is not used
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Using Linux native AIO
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Not using CPU crc32 instructions
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Initializing buffer pool, size = 1.0G
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Completed initialization of buffer pool
 
2015-08-07 16:51:10 140585934886784 [Note] InnoDB: Highest supported file format is Barracuda.
 
BROKEN: block: 41766237 checkpoint: 406168 57a4b7bd 84958a0a
 
BROKEN: block: 41766237 checkpoint: 406168 57a4b7bd 84958a0a
 
InnoDB: Log block no 41766237 at lsn 21384312832 has
 
InnoDB: ok header, but checksum field contains 2224392714, should be 1470412733
 
InnoDB: Set innodb_force_recovery to ignore this error.
 
2015-08-07 16:51:10 7fdcb6b59780  InnoDB: Assertion failure in thread 140585934886784 in file log0recv.cc line 2833
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
150807 16:51:10 [ERROR] mysqld got signal 6 ;
 
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.
 
 
 
To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.1.6-MariaDB-1~precise-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1002
 
max_used_connections=0
 
max_threads=1002
 
thread_count=0
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10540258 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
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 = 0x0 thread_stack 0x48000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0x7fdcb75abe2b]
 
/usr/sbin/mysqld(handle_fatal_signal+0x455)[0x7fdcb7143bd5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7fdcb674fcb0]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7fdcb4af10d5]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7fdcb4af483b]
 
/usr/sbin/mysqld(+0x7414d6)[0x7fdcb72c34d6]
 
/usr/sbin/mysqld(+0x742afb)[0x7fdcb72c4afb]
 
/usr/sbin/mysqld(+0x7cf408)[0x7fdcb7351408]
 
/usr/sbin/mysqld(+0x6f66d5)[0x7fdcb72786d5]
 
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x68)[0x7fdcb7146178]
 
/usr/sbin/mysqld(+0x46c8c5)[0x7fdcb6fee8c5]
 
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x8e2)[0x7fdcb6fef822]
 
/usr/sbin/mysqld(+0x3a63e7)[0x7fdcb6f283e7]
 
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x1d10)[0x7fdcb6f2ac10]
 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed)[0x7fdcb4adc76d]
 
/usr/sbin/mysqld(+0x39d099)[0x7fdcb6f1f099]
 
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.
 
150807 16:51:10 mysqld_safe mysqld from pid file /data/mysql/data/aurelien-VGN-CR42Z-R.pid ended

Comment by Aurélien LEQUOY [ 2015-08-10 ]

to make server back I delete database directory with encrypted table and server started

Comment by Elena Stepanova [ 2015-08-11 ]

So, there are several failures here. In the reverse order:

Assertion failure in thread 140585934886784 in file log0recv.cc line 2833

I also had this one here: MDEV-8586. In my case it would happen because InnoDB log was encrypted, but there were no key to decrypt it on the server restart. For you, the reason is probably the same, if I understand correctly that before getting it you removed encryption options from the config.
The assertion stopped failing a few commits ago, instead now InnoDB just fails to initialize. I assume it's unavoidable, because the log file is really encrypted, and it really cannot be decrypted without the plugin and/or key.

"InnoDB: Redo log crypto: getting mysqld crypto key from key version failed. Reason could be that requested key_version 1 is not found or required encryption key management is not found."

I did not quite understand how you got this one. You said "I removed options of encryptions and set i back in [mysqld]", but it would be easier if you just provided the config you used at that time.

"Assertion failure in thread 140191626835840 in file os0sync.cc line 419" "InnoDB: Failing assertion: event"

You put it in the initial description saying that it just happened some time after the test; but according to the log, it actually happened on server startup, when InnoDB was performing recovery. So, it either means that somebody killed the server before, or that the server crashed before. To see which it was, we need the part of the error log BEFORE this happened, before the server was restarted. Could you please provide it?

Comment by Elena Stepanova [ 2015-09-08 ]

It could be useful to know more about the second and third problems, but on the other hand, 10.1.7 will be out very soon (most likely in 1-2 days), there were lots of encryption-related fixes and changes in there, so you could just try it out.

In any case, if you have new information regarding the issues you described, please comment to re-open the report.

Comment by Alexander Rubin [ 2016-02-26 ]

Same problem with Galera Cluster and rsync for SST.

Generated at Thu Feb 08 07:28:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.