Transaction lost after recovery

[Iwo]

If PXC is crashed (killed with -9, power failure) when running a lot of DML transactions (for example, single-threaded INSERT loop) after recovery last successfully commited transaction is rolled back even with
  - innodb_flush_log_at_trx_commit = 1
  - innodb_doublewrite=1
  - sync_binlog = 1

Steps to reproduce:

Generate a lot of INSERTs:
#!/usr/bin/php
<?php
$conn = new PDO("mysql:host="127.0.0.1";port=3306", "root", "root");
$conn->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION);

$conn->query("CREATE TABLE IF NOT EXISTS demo.lostcheck3 (v varchar(50) PRIMARY KEY) ENGINE=InnoDB ");
$conn->query("TRUNCATE demo.lostcheck3");

$c = 0;
while (1) {
    $q = "INSERT INTO demo.lostcheck3 (v) VALUES( 'percona${c}');";
    try {
    $f= $conn->query($q);
        print "$q, Query OK, rc = ".$f->errorCode() .PHP_EOL;
    } catch (Exception $e) {
        printf("$q FAILED, %s", $e);
        exit(1);
    }
    $c++;
}

After recovery, the last successfully committed transaction is lost and a corresponding binlog is trimmed:

2017-11-21T15:53:01.548693+01:00 0 [Note] Recovering after a crash using mysqld-bin
2017-11-21T15:53:01.548721+01:00 0 [Note] WSREP: Binlog recovery, found wsrep position a8f17ba6-ceca-11e7-9240-773701a2f364:3159
2017-11-21T15:53:01.559725+01:00 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/data/ib_buffer_pool
2017-11-21T15:53:01.565921+01:00 0 [Note] InnoDB: Buffer pool(s) load completed at 171121 15:53:01
2017-11-21T15:53:01.682846+01:00 0 [Note] WSREP: Binlog recovery scan stopped at Xid event 3159
2017-11-21T15:53:01.683136+01:00 0 [Note] Starting crash recovery...
2017-11-21T15:53:01.683288+01:00 0 [Note] InnoDB: Starting recovery for XA transactions...
2017-11-21T15:53:01.683406+01:00 0 [Note] InnoDB: Transaction 8842 in prepared state after recovery
2017-11-21T15:53:01.683553+01:00 0 [Note] InnoDB: Transaction contains changes to 1 rows
2017-11-21T15:53:01.683658+01:00 0 [Note] InnoDB: 1 transactions in prepared state after recovery
2017-11-21T15:53:01.683775+01:00 0 [Note] Found 1 prepared transaction(s) in InnoDB
2017-11-21T15:53:01.683879+01:00 0 [Note] rollback xid 'WSREPXid\250\361{\246\316\312\21\347\222@w7\1\242\363dX\14\0\0\0\0\0\0'
2017-11-21T15:53:01.684591+01:00 0 [Note] Crash recovery finished.
2017-11-21T15:53:01.684776+01:00 0 [Note] Crashed binlog file ./mysqld-bin.000003 size is 833222, but recovered up to 832965. Binlog trimmed to 832965 bytes.

# mysql -e "select * from demo.lostcheck3 where v ='percona1956' or v ='percona1957'";
+-------------+
| v |
+-------------+
| percona1956 |
+-------------+

However, if data is recovered with WSREP disabled (even if WSREP was enabled when committing) the transaction is recovered.

#head -n 3 /etc/mysql/my.cnf
[mysqld]
#wsrep_provider=/usr/lib/galera3/libgalera_smm.so
#wsrep_cluster_address = gcomm://

[...]
2017-11-22T13:50:17.673249Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /var/lib/mysql/xb_doublewrite, size 3932160 bytes
2017-11-22T13:50:17.813775Z 0 [Note] InnoDB: Transaction 3271 was in the XA prepared state.
2017-11-22T13:50:17.818508Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2017-11-22T13:50:17.818918Z 0 [Note] InnoDB: Trx id counter is 3584
2017-11-22T13:50:17.820100Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
2017-11-22T13:50:18.340807Z 0 [Note] InnoDB: Apply batch completed
2017-11-22T13:50:18.340876Z 0 [Note] InnoDB: Last MySQL binlog file position 0 524210, file name mysqld-bin.000002
[...]

# mysql -e "select * from demo.lostcheck3 where v ='percona1956' or v ='percona1957'";
+-------------+
| v |
+-------------+
| percona1956 |
| percona1957 |
+-------------+

Tested against PXC 5.7.19-19.22-3 and 5.6.37-26.21-3

[Krunal Bauskar (krunal-bauskar)]

commit 65510b5c1f59a52bcf18da5452a64f0c9ba4282d
Merge: fb8e85e 5059434
Author: Krunal Bauskar <email address hidden>
Date: Thu Nov 30 19:01:07 2017 +0530
Merge pull request #574 from kbauskar/5.7-pxc-895
PXC#895: Transaction lost after recovery
commit 5059434eb2eeaac685262d242f2e5f9b5a252952
Author: Krunal Bauskar <email address hidden>
Date: Tue Nov 28 12:08:44 2017 +0530
PXC#895: Transaction lost after recovery
If binlog is enabled then SE will persist redo at following stages:
during prepare
during binlog write
during innodb-commit
3rd stage (fsync) can be skipped as transaction can be recovered
from binlog.
During 3rd stage, commit co-ordinates are also recorded in sysheader
under wsrep placeholder. These co-ordinates are then used to stop
binlog scan (in addition to get recovery position in case of node-crash).
Since fsync of 3rd stage is delayed (as transaction can be recovered
using binlog) it is possible that even though transaction is reported
as success to end-user said co-ordinates are not persisted to disk.
On restart, a prepare state transaction could be recovered and committed
but since wsrep co-ordinates are not persisted a successfully committed
transaction recovery is skipped causing data inconsistency from end-user
application perspective.
This behavior is now changed to let recovery proceed independent of
wsrep co-ordinates and wsrep co-ordinates are updated to reflect
the recovery committed transaction.

Fixed with 5.6 and 5.7

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-895