[MDEV-13509] (draft) Crash recovery from tc.log failed after tokuft couldn't start Created: 2017-08-12  Updated: 2017-08-13

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.2
Fix Version/s: None

Type: Bug Priority: Minor
Reporter: Alice Sherepa Assignee: Alice Sherepa
Resolution: Unresolved Votes: 0
Labels: None


 Description   

server with innodb + tokudb => innodb brings server down with long semaphore wait (or maybe on any sigabrt? we don't know) => a tokudb process keeps running or at least pretends to => server restarts => tokudb fails to initialize due to the (pseudo-?)running process => crash recovery from tc.log doesn't work most likely because it needs tokudb which isn't there

170811 14:32:59 mysqld_safe Number of processes running now: 0
170811 14:32:59 mysqld_safe mysqld restarted
2017-08-11 14:33:00 140579079071552 [Note] /data/bld/10.2/bin/mysqld (mysqld 10.2.8-MariaDB-debug) starting as process 11778 ...
Couldn't start tokuft because some other tokuft process is using the same directory [/data/bld/10.2/data/] for [environment]
2017-08-11 14:33:01 140579079071552 [ERROR] TokuDB unknown error 11
2017-08-11 14:33:01 140579079071552 [ERROR] Plugin 'TokuDB' init function returned error.
2017-08-11 14:33:01 140579079071552 [ERROR] Plugin 'TokuDB' registration as a STORAGE ENGINE failed.
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Uses event mutexes
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Using Linux native AIO
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Number of pools: 1
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Using SSE2 crc32 instructions
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Completed initialization of buffer pool
2017-08-11 14:33:01 140578282624768 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Highest supported file format is Barracuda.
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1835550761
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 79623 row operations to undo
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Trx id counter is 36864
2017-08-11 14:33:01 140579079071552 [Note] InnoDB: Starting final batch to recover 347 pages from redo log.
2017-08-11 14:33:02 140578274232064 [Note] InnoDB: Starting in background the rollback of recovered transactions
2017-08-11 14:33:02 140578274232064 [Note] InnoDB: Rolling back trx with id 36372, 79623 rows to undo
 
InnoDB: Progress in percents: 12017-08-11 14:33:02 140579079071552 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-08-11 14:33:02 140579079071552 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-08-11 14:33:02 140579079071552 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-08-11 14:33:02 140579079071552 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 2 3 4 5 6 7 8 9 102017-08-11 14:33:03 140579079071552 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 112017-08-11 14:33:03 140579079071552 [Note] InnoDB: Waiting for purge to start
 122017-08-11 14:33:03 140579079071552 [Note] InnoDB: 5.7.19 started; log sequence number 1840667123
2017-08-11 14:33:03 140577299494656 [Note] InnoDB: Loading buffer pool(s) from /data/bld/10.2/data/ib_buffer_pool
 13 14 152017-08-11 14:33:04 140577299494656 [Note] InnoDB: Buffer pool(s) load completed at 170811 14:33:04
 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 392017-08-11 14:33:08 140579079071552 [Note] CONNECT: Version 1.06.0001 April 17, 2017
2017-08-11 14:33:08 140579079071552 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-11 14:33:08 140579079071552 [Note] Recovering after a crash using tc.log
2017-08-11 14:33:08 140579079071552 [ERROR] Recovery failed! You must enable all engines that were enabled at the moment of the crash
2017-08-11 14:33:08 140579079071552 [ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete tc log and start mysqld with --tc-heuristic-recover={commit|rollback}
2017-08-11 14:33:08 140579079071552 [ERROR] Can't init tc log
2017-08-11 14:33:08 140579079071552 [ERROR] Aborting
 
 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 100mysqld: /home/alice/git/10.2/sql/mysqld.cc:2161: void mysqld_exit(int): Assertion `global_status_var.global_memory_used == 0' failed.
170811 14:40: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 https://mariadb.com/kb/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.2.8-MariaDB-debug
read_buffer_size=131072
max_used_connections=0
thread_count=0
Thread pointer: 0x0
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 0x49000
/data/bld/10.2/bin/mysqld(my_print_stacktrace+0x38)[0x5601716e0c64]
/data/bld/10.2/bin/mysqld(handle_fatal_signal+0x3a3)[0x560170f6e2f2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fdb1cba6390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fdb1bf5f428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fdb1bf6102a]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7fdb1bf57bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7fdb1bf57c82]
sql/mysqld.cc:2163(mysqld_exit(int))[0x560170c21a04]
sql/mysqld.cc:2129(unireg_abort)[0x560170c218fc]
sql/mysqld.cc:5406(init_server_components())[0x560170c28670]
sql/mysqld.cc:5845(mysqld_main(int, char**))[0x560170c291a6]
sql/main.cc:26(main)[0x560170c1e020]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fdb1bf4a830]
/data/bld/10.2/bin/mysqld(_start+0x29)[0x560170c1def9]
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.
170811 14:40:11 mysqld_safe mysqld from pid file /data/bld/10.2/data/LenaU.pid ended


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