The initial test flow was this:
- start 10.1.34 server with the following options:
`
|
--no-defaults --file-key-management --file-key-management-filename=keys.txt --plugin-load-add=file_key_management.so --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --encrypt-binlog --innodb-page-size=8K --innodb-compression-algorithm=none --loose-innodb-file-format=Barracuda --loose-innodb-file-per-table=1 --loose-max-statement-time=20 --loose-lock-wait-timeout=20 --loose-innodb-lock-wait-timeout=10 --loose-innodb_log_compressed_pages=on --loose-innodb-change-buffering=none
|
- run a mix of DDL/DML on the server for a few minutes;
- SIGKILL the server;
- start the same server with the exact same options and additionally --innodb-force-recovery=3
InnoDB doesn't start:
|
10.1.34
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: innodb-page-size has been changed from the default value 16384 to 8192 .
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: The InnoDB memory heap is disabled
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Using Linux native AIO
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Using SSE crc32 instructions
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Initializing buffer pool, size = 128.0M
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Completed initialization of buffer pool
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Highest supported file format is Barracuda.
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Starting crash recovery from checkpoint LSN=23790689
|
2018-07-31 16:08:31 140279075214848 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
|
InnoDB: redo log checkpoint: 0 [ chk key ]: [ 4 1 ]
|
2018-07-31 16:08:32 140279075214848 [ERROR] InnoDB: Redo log crypto: failed to decrypt log block. Reason could be that requested key version is not found, required encryption key management plugin is not found or configured encryption algorithm and/or method does not match.
|
2018-07-31 16:08:32 140279075214848 [ERROR] Plugin 'InnoDB' init function returned error.
|
2018-07-31 16:08:32 140279075214848 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
|
2018-07-31 16:08:32 140279075214848 [Note] Plugin 'FEEDBACK' is disabled.
|
2018-07-31 16:08:32 140279075214848 [ERROR] Unknown/unsupported storage engine: InnoDB
|
2018-07-31 16:08:32 140279075214848 [ERROR] Aborting
|
|
Error in my_thread_global_end(): 1 threads didn't exit
|
The key file is present and is the same for both starts.
The datadir and the key file are available, nothing is confidential, the datadir just doesn't fit into JIRA.
{"report":{"fcp":1881.9000000953674,"ttfb":716,"pageVisibility":"visible","entityId":68950,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"1fc80609-5a79-41b4-aafe-4661c2d541a3","navigationType":0,"readyForUser":1957.1000001430511,"redirectCount":0,"resourceLoadedEnd":2109.4000000953674,"resourceLoadedStart":724.6000001430511,"resourceTiming":[{"duration":485.7000000476837,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":724.6000001430511,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":724.6000001430511,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1210.3000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":485.7999999523163,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":724.9000000953674,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":724.9000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1210.7000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":489.39999985694885,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":725.1000001430511,"connectEnd":725.1000001430511,"connectStart":725.1000001430511,"domainLookupEnd":725.1000001430511,"domainLookupStart":725.1000001430511,"fetchStart":725.1000001430511,"redirectEnd":0,"redirectStart":0,"requestStart":725.1000001430511,"responseEnd":1214.5,"responseStart":1214.5,"secureConnectionStart":725.1000001430511},{"duration":592.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true&whisper-enabled=true","startTime":725.3000001907349,"connectEnd":725.3000001907349,"connectStart":725.3000001907349,"domainLookupEnd":725.3000001907349,"domainLookupStart":725.3000001907349,"fetchStart":725.3000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":725.3000001907349,"responseEnd":1317.6000001430511,"responseStart":1317.5,"secureConnectionStart":725.3000001907349},{"duration":601.9000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":725.5,"connectEnd":725.5,"connectStart":725.5,"domainLookupEnd":725.5,"domainLookupStart":725.5,"fetchStart":725.5,"redirectEnd":0,"redirectStart":0,"requestStart":725.5,"responseEnd":1327.4000000953674,"responseStart":1327.4000000953674,"secureConnectionStart":725.5},{"duration":611.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":725.8000001907349,"connectEnd":725.8000001907349,"connectStart":725.8000001907349,"domainLookupEnd":725.8000001907349,"domainLookupStart":725.8000001907349,"fetchStart":725.8000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":725.8000001907349,"responseEnd":1337.3000001907349,"responseStart":1337.3000001907349,"secureConnectionStart":725.8000001907349},{"duration":611.8000001907349,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":726,"connectEnd":726,"connectStart":726,"domainLookupEnd":726,"domainLookupStart":726,"fetchStart":726,"redirectEnd":0,"redirectStart":0,"requestStart":726,"responseEnd":1337.8000001907349,"responseStart":1337.8000001907349,"secureConnectionStart":726},{"duration":704,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":726.2000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":726.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1430.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":612,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":726.4000000953674,"connectEnd":726.4000000953674,"connectStart":726.4000000953674,"domainLookupEnd":726.4000000953674,"domainLookupStart":726.4000000953674,"fetchStart":726.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":726.4000000953674,"responseEnd":1338.4000000953674,"responseStart":1338.4000000953674,"secureConnectionStart":726.4000000953674},{"duration":704.4000000953674,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":726.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":726.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1430.9000000953674,"responseStart":0,"secureConnectionStart":0},{"duration":612.9000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":726.7000000476837,"connectEnd":726.7000000476837,"connectStart":726.7000000476837,"domainLookupEnd":726.7000000476837,"domainLookupStart":726.7000000476837,"fetchStart":726.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":726.7000000476837,"responseEnd":1339.6000001430511,"responseStart":1339.6000001430511,"secureConnectionStart":726.7000000476837},{"duration":1334.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":727.6000001430511,"connectEnd":727.6000001430511,"connectStart":727.6000001430511,"domainLookupEnd":727.6000001430511,"domainLookupStart":727.6000001430511,"fetchStart":727.6000001430511,"redirectEnd":0,"redirectStart":0,"requestStart":727.6000001430511,"responseEnd":2062.4000000953674,"responseStart":2062.4000000953674,"secureConnectionStart":727.6000001430511},{"duration":1338.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":727.7000000476837,"connectEnd":727.7000000476837,"connectStart":727.7000000476837,"domainLookupEnd":727.7000000476837,"domainLookupStart":727.7000000476837,"fetchStart":727.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":727.7000000476837,"responseEnd":2066,"responseStart":2066,"secureConnectionStart":727.7000000476837},{"duration":113.09999990463257,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":1462.6000001430511,"connectEnd":1462.6000001430511,"connectStart":1462.6000001430511,"domainLookupEnd":1462.6000001430511,"domainLookupStart":1462.6000001430511,"fetchStart":1462.6000001430511,"redirectEnd":0,"redirectStart":0,"requestStart":1462.6000001430511,"responseEnd":1575.7000000476837,"responseStart":1575.7000000476837,"secureConnectionStart":1462.6000001430511},{"duration":357,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2cib/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true&whisper-enabled=true","startTime":1752.4000000953674,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1752.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":2109.4000000953674,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":514,"responseStart":716,"responseEnd":718,"domLoading":721,"domInteractive":2128,"domContentLoadedEventStart":2128,"domContentLoadedEventEnd":2186,"domComplete":2733,"loadEventStart":2733,"loadEventEnd":2733,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":2068.2000000476837},{"name":"bigPipe.sidebar-id.end","time":2069},{"name":"bigPipe.activity-panel-pipe-id.start","time":2069.5},{"name":"bigPipe.activity-panel-pipe-id.end","time":2073.600000143051},{"name":"activityTabFullyLoaded","time":2207}],"measures":[],"correlationId":"ebad53ea5b75dd","effectiveType":"4g","downlink":9.4,"rtt":0,"serverDuration":123,"dbReadsTimeInMs":17,"dbConnsTimeInMs":27,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Critical
The following has been observed on 10.2.16, might be related?
10.2.16
2018-08-05 18:20:13 139628292781952 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M2018-08-05 18:20:13 139628292781952 [Note] InnoDB: Completed initialization of buffer pool2018-08-05 18:20:13 139627563095808 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().2018-08-05 18:20:13 139628292781952 [Note] InnoDB: Highest supported file format is Barracuda.2018-08-05 18:20:13 139628292781952 [Note] InnoDB: Starting crash recovery from checkpoint LSN=346689962018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=16] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=17] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=18] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=19] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=20] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=21] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=22] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=23] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=24] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=25] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=26] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Recovered page [page id: space=16, page number=27] from the doublewrite buffer.2018-08-05 18:20:14 139628292781952 [Note] InnoDB: Starting final batch to recover 1576 pages from redo log.2018-08-05 18:20:14 139628036220672 [ERROR] InnoDB: Space id and page no stored in the page, read in are [page id: space=14, page number=1], should be [page id: space=16, page number=16]2018-08-05 18:20:14 139628036220672 [ERROR] InnoDB: The page [page id: space=16, page number=16] in file './test/t004.ibd' cannot be decrypted.2018-08-05 18:20:14 139628036220672 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.2018-08-05 18:20:14 139628036220672 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.2018-08-05 18:20:14 0x7efdaf7fe700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/storage/innobase/rem/rem0rec.cc line 580InnoDB: We intentionally generate a memory trap.InnoDB: Submit a detailed bug report to https://jira.mariadb.org/InnoDB: If you get repeated assertion failures or crashes, evenInnoDB: immediately after the mysqld startup, there may beInnoDB: corruption in the InnoDB tablespace. Please refer toInnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/InnoDB: about forcing recovery.180805 18:20:14 [ERROR] mysqld got signal 6 ;This could be because you hit a bug. It is also possible that this binaryor 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 https://mariadb.com/kb/en/reporting-bugsWe will try our best to scrape up some info that will hopefully helpdiagnose the problem, but since we have already crashed,something is definitely wrong and this may fail.Server version: 10.2.16-MariaDB-logkey_buffer_size=134217728read_buffer_size=131072max_used_connections=0max_threads=153thread_count=0It is possible that mysqld could use up tokey_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467246 K bytes of memoryHope that's ok; if not, decrease some variables in the equation.Thread pointer: 0x0Attempting backtrace. You can use the following information to find outwhere mysqld died. If you see no messages after this, something wentterribly wrong...stack_bottom = 0x0 thread_stack 0x49000mysys/stacktrace.c:268(my_print_stacktrace)[0x557774f9c9ab]sql/signal_handler.cc:168(handle_fatal_signal)[0x557774a6df65]/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7efdbde42330]/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7efdbd495c37]/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7efdbd499028]ut/ut0rbt.cc:461(rbt_eject_node)[0x55777483d88a]rem/rem0rec.cc:580(rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**))[0x557774cb1686]page/page0cur.cc:2267(page_cur_parse_delete_rec(unsigned char*, unsigned char*, buf_block_t*, dict_index_t*, mtr_t*))[0x557774c915d9]log/log0recv.cc:1480(recv_parse_or_apply_log_rec_body)[0x557774c70912]log/log0recv.cc:1900(recv_recover_page(bool, buf_block_t*))[0x557774c7290d]buf/buf0buf.cc:6198(buf_page_io_complete(buf_page_t*, bool, bool))[0x557774db095c]fil/fil0fil.cc:5291(fil_aio_wait(unsigned long))[0x557774e1fc62]srv/srv0start.cc:334(io_handler_thread)[0x557774d21a98]/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7efdbde3a184]/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7efdbd55cffd]The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html containsinformation that should help you find out what is causing the crash.Writing a core file at /home/travis/logs/current1_1/data/Aborted (core dumped)