Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Blocker
-
Resolution: Incomplete
-
Affects Version/s: 10.1.6
-
Fix Version/s: N/A
-
Component/s: Encryption
-
Labels:
-
Environment:Ubuntu 12.04 + MariaDB 10.1.6 (from the repository)
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)
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
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
to make server back I delete database directory with encrypted table and server started
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?
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.
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 endedi guess server tried to encrypt somthing on server and make it wrong and now impossible to start the server due to this problem