InnoDB: Failing assertion: total_trx >= trx_sys->n_prepared_trx

[Ovais Tariq]

XtraBackup is hitting an assertion during the prepare stage.

The OS in question is:
SunOS 5.11 joyent_20131218T184706Z i86pc i386 i86pc Solaris

The XtraBackup version is:
[root@node1 ~] # /mysql/bin/xtrabackup --version
/mysql/bin/xtrabackup version 2.1.7 for MySQL server 5.6.15 solaris11 (x86_64) (revision id: undefined)

Here is the relevant part from the XtraBackup run log:
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 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
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 13964339006976 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 13964344249856 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 13964349492736 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 13964354735616 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 13964359978496 (99%)
InnoDB: Doing recovery: scanned up to log sequence number 13964365221376 (99%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 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
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 13964367506732 (100%)
InnoDB: Transaction 19428798537 was in the XA prepared state.
InnoDB: Transaction 19428798538 was in the XA prepared state.
InnoDB: Transaction 19428798538 was in the XA prepared state.
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 4 row operations to undo
InnoDB: Trx id counter is 19428798976
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 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
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 119397162, file name bin.000752
InnoDB: Last MySQL binlog file position 0 660234708, file name bin.000137
InnoDB: InnoDB: Starting in background the rollback of uncommitted transactions
128 rollback segment(s) are active.
2014-01-26 22:04:06 f InnoDB: Rolling back trx with id 19428798538, 2 rows to undo
InnoDB: Rollback of trx with id 19428798538 completed
2014-01-26 22:04:06 f InnoDB: Rolling back trx with id 19428798537, 2 rows to undo
InnoDB: Rollback of trx with id 19428798537 completed
2014-01-26 22:04:06 f InnoDB: Rollback of non-prepared transactions completed
InnoDB: Waiting for purge to start
InnoDB: 5.6.15 started; log sequence number 13964367506732

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 660234708, file name bin.000137

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
2014-01-26 22:04:08 1 InnoDB: Assertion failure in thread 1 in file trx0sys.cc line 1264
InnoDB: Failing assertion: total_trx >= trx_sys->n_prepared_trx
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
innobackupex: Error:
innobackupex: ibbackup failed at /mysql/bin/innobackupex line 2580.

However, starting up PXC 5.6.15 on the same backup and shutting it down does not produce any crash or assertion and it starts up and shuts down fine. The data was also checked to see if it is query-able and it was.

Here is the relevant part of the log from shutting down mysqld on the backup that had XB crash during the prepare stage:
[root@node1 ~] # tail -f /var/log/mysql/error.log
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'INNODB_LOCKS'
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'INNODB_TRX'
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'XTRADB_RSEG'
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2014-01-27 20:12:23 24527 [Note] Shutting down plugin 'InnoDB'
2014-01-27 20:12:23 24527 [Note] InnoDB: FTS optimize thread exiting.
2014-01-27 20:12:23 24527 [Note] InnoDB: Starting shutdown...
2014-01-27 20:12:24 28 InnoDB: Dumping buffer pool(s) to /databases/ib_buffer_pool
2014-01-27 20:12:24 28 InnoDB: Buffer pool(s) dump completed at 140127 20:12:24
2014-01-27 20:12:43 24527 [Note] InnoDB: Shutdown completed; log sequence number 13721309288333
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'BLACKHOLE'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'CSV'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'MyISAM'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'MEMORY'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'MRG_MYISAM'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'sha256_password'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'mysql_old_password'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'mysql_native_password'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'wsrep'
2014-01-27 20:12:43 24527 [Note] Shutting down plugin 'binlog'
2014-01-27 20:12:43 24527 [Note] /mysql/bin/mysqld: Shutdown complete

So you can see that shutdown completed successfully.

[Ryan Gordon (ryan-5)]

I should note that we do receive these type of messages during startup/intermittent during use of the database:

2014-01-27 20:11:01 3c InnoDB: Error: page 3 log sequence number 13964278694739
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 3 log sequence number 13953425201168
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 33 log sequence number 13953425195822
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 34 log sequence number 13723389897026
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 253032 log sequence number 13964348920739
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 231290 log sequence number 13964365007225
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 777 log sequence number 13961089315935
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2014-01-27 20:11:01 3c InnoDB: Error: page 9 log sequence number 13961089320809
InnoDB: is in the future! Current system log sequence number 13721309288333.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB:...

[Ovais Tariq (ovais-tariq)]

@Ryan,

I don't believe the above messages are related. They are simply there because we did not reuse the transactional logs produced by XB when starting up mysql and hence mysqld resorted to generating fresh transactional logs.

[Ryan Gordon (ryan-5)]

Ah okay, thanks for the explanation Ovais!

[Shahriyar Rzayev (rzayev-sehriyar)]

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