MySQL Bugs: #75519: Potential InnoDB data loss when binary logging is enabled

Bug #75519	Potential InnoDB data loss when binary logging is enabled
Submitted:	15 Jan 2015 17:05	Modified:	4 Jun 2015 10:05
Reporter:	Davi Arnaut (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6, 5.6.25	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	binary log, data loss, innodb, innodb_flush_log_at_trx_commit

Description:
When binary logging is enabled, InnoDB’s redo log is not flushed to
disk even if innodb_flush_log_at_trx_commit is set to 1. This means
that if there is a crash shortly after a transaction is committed,
the transaction will be in prepared state after recovery (there is
still a redo log flush during prepare).

This would normally not be a problem since one of the steps in
recovery is to commit any prepared transactions that have made it to
the binary log. But if sync_binlog is not used, there are no
guarantees that the committed transaction will be in the binary log,
in which case recovery will rollback any prepared transactions, thus
leading to data loss of committed transactions.

How to repeat:
Crash server after a transaction is committed, but before redo log is flushed.
Before recovery, remove binary log.
After recovery, the transaction will have been rolled back.

Example:

2015-01-14 18:34:09 7fd818e30740  InnoDB: Transaction 1295 in prepared state after recovery
2015-01-14 18:34:09 7fd818e30740  InnoDB: Transaction contains changes to 1 rows
2015-01-14 18:34:09 7fd818e30740  InnoDB: 1 transactions in prepared state after recovery
2015-01-14 18:34:09 14515 [Note] Found 1 prepared transaction(s) in InnoDB
2015-01-14 18:34:09 14515 [Note] rollback xid 'MySQLXid\1\0\0\0\0\0\0\0!\0\0\0\0\0\0\0'

Hello Davi,

Thank you for the report.
Sorry somehow this report sipped from my queue.
Observed this behavior with 5.6.25 build(source).

Thanks,
Umesh

This bug is still actual as of 8.0.34.

Setting innodb_flush_log_at_trx_commit to 1 does not actually flush the redo log on commits when binlog is enabled, and this is not documented anywhere. It does seem like a specific design decision with binlog group commit (https://dev.mysql.com/worklog/task/?id=5223), to have binlog as the source of truth of what was committed and just roll forward prepared transactions in other SEs.

Moreover, in 8.0, where InnoDB keeps the server DD too, it takes care to flush on commit all the DD transactions, in any configuration. Which is absolutely needed, because the DD is initialized after InnoDB but before binlog crash recovery, meaning that any committed-in-binlog but prepared-in-InnoDB DD transactions would be invisible otherwise. This would result in DD inconsistency with what's on disk.  

So at the very least, this is a documentation bug on several points:
- innodb_flush_log_at_trx_commit = 1 isn't, when binlog is enabled.
- Is innodb_flush_log_at_trx_commit = 0 & sync_binlog = 1 actually a fully durable configuration?
- Is innodb_flush_log_at_trx_commit = 1 & sync_binlog = 0 actually a data-losing configuration?
- If a server acknowledges a commit to client and then crashes, is it normal to see binlog XA crash recovery to roll forward to committed state that same transaction that was already acknowledged as committed?

Test for bug 75519

Attachment: bug75519-test.patch (application/octet-stream, text), 2.42 KiB.

I have uploaded a test to show InnoDB losing its commit and then being rolled forward by binlog.

An error log from its run:
...
Blocking log write & flush after committing LSN 19621273
Blocking log writer thread
safe_process[95631]: Child process: 95632, killed by signal: 9
...
[InnoDB] Doing recovery: scanned up to log sequence number 19621265 <- the committed LSN is not there
...
[Server] Recovering after a crash using binlog
[Server] Starting XA crash recovery...
[Server] Crash recovery finished in binlog engine. No attempts to commit, rollback or prepare any transactions.
[InnoDB] Starting recovery for XA transactions...
[InnoDB] Transaction 1554 in prepared state after recovery
[InnoDB] Transaction contains changes to 1 rows
[InnoDB] 1 transactions in prepared state after recovery
[Server] Found 1 prepared transaction(s) in InnoDB
[Server] Crash recovery finished in InnoDB engine. Successfully committed 1 internal transaction(s). 
[Server] XA crash recovery finished.