Bug #87611 EVENTS, crash recovery fails with Can't init tc log, EVENTS
Submitted: 30 Aug 2017 16:49 Modified: 17 Oct 2017 13:31
Reporter: Matthias Leich Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: DDL Severity:S3 (Non-critical)
Version:9.0.0-dmr-debug-log OS:Any
Assigned to: CPU Architecture:Any

[30 Aug 2017 16:49] Matthias Leich
Description:
Problem found during crash recovery testing with RQG.

mysql-trunk (~2017-08-30)
Revision-Id: 4a159a09882059380177fc3f4ea4cb4d99357745
MySQL 9.0.0-dmr-debug-log

The RQG runner performs
1. Start server , initialize + load some data
2. Loop
   2.1 Make heavy load (32 concurrent sessions)
       CREATE EVENT IF NOT EXISTS testdb_N5 . e1__N5 ...
       CREATE DATABASE IF NOT EXISTS testdb_N5 ....
       SET GLOBAL EVENT_SCHEDULER = ON
   2.2 After 30s of load kill the server process with SIGKILL
   2.3 Restart the server
   2.4 Run certain checks of the DD, tables etc.
   2.2 After 

At some point of time the restart fails with
2017-08-30T16:19:24.587977Z 1 [Note] [000000] InnoDB: Database was not shutdown normally!
[Note] [000000] InnoDB: Starting crash recovery.
[Note] [000000] InnoDB: Using 'tablespaces.open.1' max LSN: 24145342
[Note] [000000] InnoDB: Tablespace file './test/executors.ibd' ID mismatch, expected 10 but found 11
[Note] [000000] InnoDB: Tablespace ID already maps to: './test/executors.ibd', rename ignored.
...
[Note] [000000] InnoDB: Applying a batch of 642 redo log records ...
[Note] [000000] InnoDB: 10%
...
[Note] [000000] InnoDB: 100%
[Note] [000000] InnoDB: Apply batch completed!
...
[Note] [000000] InnoDB: 9.0.0 started; log sequence number 24203769
...
# 2017-08-30T18:21:24 | 2017-08-30T16:19:25.942270Z 1 [Note] [003629] Found data dictionary with version 1
[Note] [004478] Recovering after a crash using binlog
[ERROR] [004486] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete (or rename) binary log and start mysqld with --tc-heuristic-recover={commit|rollback}
[ERROR] [003664] Can't init tc log
[ERROR] [003742] Aborting

How to repeat:
I will add more information soon.

Shrinked RQG grammar reformatted.
--------------------------------
become_stubborn:
   SET SESSION lock_wait_timeout = 11; SET SESSION innodb_lock_wait_timeout = 5; 

create_event:
   CREATE EVENT IF NOT EXISTS testdb_N5.e1__N5
   ON SCHEDULE EVERY 1 SECOND STARTS NOW() ENDS NOW() + INTERVAL 21 SECOND ON COMPLETION NOT PRESERVE
   DO SELECT * FROM testdb_N5 . t1_part_N5 LIMIT 1;
# Note: testdb_N5 . t1_part_N5 does not exist at all.

event_ddl:
   create_event |
   create_event |
   create_event |
   create_event |
   create_event |
   create_event |
   create_event |
   create_event |
   SET GLOBAL EVENT_SCHEDULER = ON;

query:
   CREATE DATABASE IF NOT EXISTS testdb_N5 DEFAULT CHARACTER SET = utf8  |
   event_ddl;

query_init:
   SET SESSION wait_timeout = 45 ; 

thread1:
   {sleep 1; if ($flip_time < Time::HiRes::time()) {kill(9, $ENV{DB_SERVER_PID1}); sleep 1; exit STATUS_SERVER_KILLED} else {return ''}}; 

thread1_init:
   become_stubborn ; { if (not defined $flip_time) {$flip_time= Time::HiRes::time() + 30; }; return undef} COMMIT;
[31 Aug 2017 10:22] Matthias Leich
Posted by developer:
 
Same bad effect on
mysql-8.0 , pull 2017-08-30
901fd9ed8ec8972a3fec9221cf1c29eb346feec5

mysql-8.0.3-rc-release , pull 2017-08-31
c023fccefd26f6969ed6a3c7284440fcea8b2c1a
[17 Oct 2017 13:31] Paul DuBois
Posted by developer:
 
Fixed in 8.0.4, 9.0.0.

Bug affects no released version. No changelog entry needed.