MySQL Bugs: #102475: Binlog coordinates no longer appear in .err log following crash recovery

Bug #102475	Binlog coordinates no longer appear in .err log following crash recovery
Submitted:	3 Feb 2021 16:25	Modified:	4 Feb 2021 13:59
Reporter:	Rob Wagner	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	8.0.23	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
in MySQL < 8.0, following crash recovery, the binlog coordinates to which InnoDB recovered were displayed in the .err log.  For example:

2018-05-24 14:05:31 16098 [Note] Plugin 'FEDERATED' is disabled.
2018-05-24 14:05:31 16098 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-05-24 14:05:31 16098 [Note] InnoDB: The InnoDB memory heap is disabled
2018-05-24 14:05:31 16098 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-24 14:05:31 16098 [Note] InnoDB: Memory barrier is not used
2018-05-24 14:05:31 16098 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-24 14:05:31 16098 [Note] InnoDB: Using Linux native AIO
2018-05-24 14:05:31 16098 [Note] InnoDB: Using CPU crc32 instructions
2018-05-24 14:05:31 16098 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2018-05-24 14:05:31 16098 [Note] InnoDB: Completed initialization of buffer pool
2018-05-24 14:05:31 16098 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-24 14:05:31 16098 [Note] InnoDB: The log sequence numbers 2812209 and 2812209 in ibdata files do not match the log sequence number 48593147 in the ib_logfiles!
2018-05-24 14:05:31 16098 [Note] InnoDB: Database was not shutdown normally!
2018-05-24 14:05:31 16098 [Note] InnoDB: Starting crash recovery.
2018-05-24 14:05:31 16098 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-05-24 14:05:31 16098 [Note] InnoDB: Restoring possible half-written data pages
2018-05-24 14:05:31 16098 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Last MySQL binlog file position 0 23195778, file name mysql-bin.000005 <--- ** THIS LINE **
2018-05-24 14:05:31 16098 [Note] InnoDB: 128 rollback segment(s) are active.
2018-05-24 14:05:31 16098 [Note] InnoDB: Waiting for purge to start
2018-05-24 14:05:31 16098 [Note] InnoDB: 5.6.32 started; log sequence number 48593147

Note the line labeled "THIS LINE".  In MySQL 8.0, we no longer see this information:

2021-02-02T19:48:51.378475Z 0 [System] [MY-010116] [Server] /sso/sfw/mysql/bin/mysqld (mysqld 8.0.23) starting as process 23900
2021-02-02T19:48:51.448273Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-02-02T19:48:53.616044Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-02-02T19:48:54.529151Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /tmp/mysqlx.sock
2021-02-02T19:48:54.571252Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2021-02-02T19:48:54.579919Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2021-02-02T19:48:54.667175Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-02-02T19:48:54.667460Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-02-02T19:48:54.711383Z 0 [System] [MY-010931] [Server] /sso/sfw/mysql/bin/mysqld: ready for connections. Version: '8.0.23'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server - GPL.

Without knowing to where InnoDB recovered, there is no way to perform additional PIT recovery using binlogs (i.e., I don't know where to start applying binlogs).

How to repeat:
Cause InnoDB to perform crash recovery.  I do it by:

1. run MySQL on a filesystem that supports snapshots
2. generate some DML against MySQL
3. snapshot the filesystem while MySQL is running and processing DML
4. stop MySQL and replace the data directory with the contents of the snapshot
5. start MySQL and view the .err log and witness the above (i.e., no indication of the binlog coordinates to which InnoDB recovered is present).

Suggested fix:
Restore old instrumentation; provide binlog coordinates to which InnoDB recovered in the .err log.

Hi Rob,

Thanks for the report. I changed this to "Feature Request" as I can't agree this is a bug, but this info is valuable and having it in 8.0 should be useful so I'm verifying this as FR.

Kind regards
Bogdan

Bogdan - thanks. Late yesterday, I read https://dev.mysql.com/doc/refman/8.0/en/binary-log.html:

---
In 8.0.0 and higher, the InnoDB support for two-phase commit in XA transactions is always enabled.

InnoDB support for two-phase commit in XA transactions ensures that the binary log and InnoDB data files are synchronized. However, the MySQL server should also be configured to synchronize the binary log and the InnoDB logs to disk before committing the transaction. The InnoDB logs are synchronized by default, and sync_binlog=1 ensures the binary log is synchronized. The effect of implicit InnoDB support for two-phase commit in XA transactions and sync_binlog=1 is that at restart after a crash, after doing a rollback of transactions, the MySQL server scans the latest binary log file to collect transaction xid values and calculate the last valid position in the binary log file. The MySQL server then tells InnoDB to complete any prepared transactions that were successfully written to the to the binary log, and truncates the binary log to the last valid position. This ensures that the binary log reflects the exact data of InnoDB tables, and therefore the replica remains in synchrony with the source because it does not receive a statement which has been rolled back.
---

If I am only using InnoDB, then this suggests that I should be able to obtain the coordinates by simply looking at the end of the largest binary log, right? If so, then we certainly have a workaround and I agree this is only a feature request.

Hi,

Yes, that's why I changed the report to FR.

kind regards
Bogdan

Posted by developer:
 
This message was removed in 951464867b53c12d5430f8f6b2d0e50bd849bb8d
WL#9211 InnoDB: Clone Replication Coordinates
It was printed from InnoDB code, so changing category to InnoDB.