Bug #83314 Failed to start the server while fixup for truncating undo tablespace is require
Submitted: 9 Oct 2016 9:21 Modified: 20 Feb 2017 15:10
Reporter: zhai weixiang (OCA) Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[9 Oct 2016 9:21] zhai weixiang 
Description:
I crashed the server manually at the point where undo-trunc.log has been created but not yet removed. 

Then I started the server. The first time it failed to start the server with the following messages in error log:

2016-10-09T07:55:08.065084Z 1 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 7 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 
2016-10-09T07:55:11.481089Z 1 [Note] InnoDB: Apply batch completed
2016-10-09T07:55:11.481173Z 1 [Note] InnoDB: Last MySQL binlog file position 0 483407742, file name mysql-bin.000211
2016-10-09T07:56:02.418473Z 1 [Note] InnoDB: Data file .//undo001 did not exist: new to be created
2016-10-09T07:56:02.418518Z 1 [Note] InnoDB: Setting file .//undo001 size to 10 MB
2016-10-09T07:56:02.418528Z 1 [Note] InnoDB: Database physically writes the file full: wait...
2016-10-09T07:56:02.424985Z 1 [Note] InnoDB: Opened 20 undo tablespaces
2016-10-09T07:56:02.425008Z 1 [Note] InnoDB: 20 undo tablespaces made active
2016-10-09T07:56:02.427798Z 1 [ERROR] InnoDB: Trying to access page number 1 in space 1, space name innodb_undo001, which is outside the tablespace bounds. Byte offset 0, len 16384, i/o type write. If you get this error at mysqld startup, please check that your my.cnf matches the ibdata files that you have in the MySQL server.
2016-10-09T07:56:02.427819Z 1 [ERROR] InnoDB: Server exits.

Then i restarted the server and this time everything goes well, quoted message from error log:

2016-10-09T07:56:34.609074Z 1 [Note] InnoDB: Log scan progressed past the checkpoint lsn 127425076489
2016-10-09T07:56:34.664041Z 1 [Note] InnoDB: Doing recovery: scanned up to log sequence number 127430319104
2016-10-09T07:56:34.719249Z 1 [Note] InnoDB: Doing recovery: scanned up to log sequence number 127435561984
2016-10-09T07:56:34.774476Z 1 [Note] InnoDB: Doing recovery: scanned up to log sequence number 127440804864
2016-10-09T07:56:34.829687Z 1 [Note] InnoDB: Doing recovery: scanned up to log sequence number 127446047744
2016-10-09T07:56:34.863779Z 1 [ERROR] InnoDB: Header page consists of zero bytes in datafile: .//undo001, Space ID:0, Flags: 0. Please refer to http://dev.mysql.com/doc/refman/8.0/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2016-10-09T07:56:34.863846Z 1 [Note] InnoDB: Page size:1024. Pages to analyze:64
2016-10-09T07:56:34.863977Z 1 [Note] InnoDB: Page size: 1024. Possible space_id count:0
2016-10-09T07:56:34.864005Z 1 [Note] InnoDB: Page size:2048. Pages to analyze:64
2016-10-09T07:56:34.864260Z 1 [Note] InnoDB: Page size: 2048. Possible space_id count:0
2016-10-09T07:56:34.864280Z 1 [Note] InnoDB: Page size:4096. Pages to analyze:64
2016-10-09T07:56:34.864655Z 1 [Note] InnoDB: Page size: 4096. Possible space_id count:0
2016-10-09T07:56:34.864674Z 1 [Note] InnoDB: Page size:8192. Pages to analyze:64
2016-10-09T07:56:34.865373Z 1 [Note] InnoDB: Page size: 8192. Possible space_id count:0
2016-10-09T07:56:34.865395Z 1 [Note] InnoDB: Page size:16384. Pages to analyze:64
2016-10-09T07:56:34.868105Z 1 [Note] InnoDB: Page size: 16384. Possible space_id count:0
2016-10-09T07:56:34.868129Z 1 [Note] InnoDB: Page size:32768. Pages to analyze:64
2016-10-09T07:56:34.868971Z 1 [Note] InnoDB: Page size: 32768. Possible space_id count:0
2016-10-09T07:56:34.869006Z 1 [Note] InnoDB: Page size:65536. Pages to analyze:64
2016-10-09T07:56:34.870647Z 1 [Note] InnoDB: Page size: 65536. Possible space_id count:0
2016-10-09T07:56:34.870679Z 1 [ERROR] InnoDB: Datafile './/undo001' is corrupted. Cannot determine the space ID from the first 64 pages.

....
...
2016-10-09T07:56:37.729026Z 1 [Note] InnoDB: Doing recovery: scanned up to log sequence number 127512436438
2016-10-09T07:56:37.729096Z 1 [Note] InnoDB: Database was not shutdown normally!
2016-10-09T07:56:37.729114Z 1 [Note] InnoDB: Starting crash recovery.
2016-10-09T07:56:37.748657Z 1 [ERROR] InnoDB: Tablespace 1 was not found at .//undo001.
2016-10-09T07:56:38.125807Z 1 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 7 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 
2016-10-09T07:56:41.526440Z 1 [Note] InnoDB: Apply batch completed
2016-10-09T07:56:41.526531Z 1 [Note] InnoDB: Last MySQL binlog file position 0 483407742, file name mysql-bin.000211
2016-10-09T07:56:41.696536Z 1 [Note] InnoDB: Data file .//undo001 did not exist: new to be created
2016-10-09T07:56:41.696576Z 1 [Note] InnoDB: Setting file .//undo001 size to 10 MB
2016-10-09T07:56:41.696594Z 1 [Note] InnoDB: Database physically writes the file full: wait...
2016-10-09T07:56:41.702478Z 1 [Note] InnoDB: Opened 20 undo tablespaces

 

How to repeat:
N/A

Suggested fix:
have no spare time to look into the issue. Will update the report if i found anything new.
[20 Jan 2017 15:10] Sinisa Milivojevic 
Hi !

Thank you for your bug report.

We are very eager to fix the bug that causes such problems, but we need the exact steps on how to do the crash ourselves.

Please send the exact procedure on how did you manage to come to this point where the servers can not start up.

Also,  please check that your my.cnf matches the ibdata files that you have in the MySQL server. If it does not match, please let us know the details.

Thanks in advance !!!
[20 Jan 2017 15:39] Sinisa Milivojevic 
I see the test case from #83313. 

Does it also lead to this bug phenomena ????
[20 Jan 2017 15:39] Sinisa Milivojevic 
With a SMALL difference that this is 8.0 ...
[21 Feb 2017 1:00] Bugs System 
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".