Foreign constraint error on one slave

[monty solomon]

One slave of a pair of slaves experienced replication failure due to a foreign key constraint error.

One of three slaves was promoted to be the master a few hours earlier.

[monty solomon (monty+launchpad)]

Here are excerpts from the error.log file.

131122 4:21:42 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.33-31.1-log' socket: '/opt/mysql/dbprod/xxxxx-p0.sock' port: 3306 Percona Server (GPL), Release rel31.1, Revision 566

131122 4:21:43 [Note] Slave SQL thread initialized, starting replication in log 'bin.000001' at position 4, relay log '/opt/mysql/dblogs1/xxxxx-p0/relay/relay.000002' position: 4

131122 4:21:43 [Note] Slave I/O thread: connected to master 'SUSR_Repl@yyyyy:3306',replication started in log 'bin.000001' at position 4

131122 7:17:02 [ERROR] Slave SQL: Could not execute Write_rows event on table xxxxx.userAttributes; Cannot add or update a child row: a foreign key constraint fails (`xxxxx`.`userAttributes`, CONSTRAINT `userAttributes_ibfk_1` FOREIGN KEY (`userId`) REFERENCES `users` (`ID`) ON DELETE CASCADE), Error_code: 1452; handler error HA_ERR_NO_REFERENCED_ROW; the event's master log bin.000003, end_log_pos 15527775, Error_code: 1452

131122 7:17:02 [Warning] Slave: Cannot add or update a child row: a foreign key constraint fails (`xxxxx`.`userAttributes`, CONSTRAINT `userAttributes_ibfk_1` FOREIGN KEY (`userId`) REFERENCES `users` (`ID`) ON DELETE CASCADE) Error_code: 1452

131122 7:17:02 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'bin.000003' position 15527524

[monty solomon (monty+launchpad)]

After further analysis of the error.log I see that there was a crash recovery during an earlier restart. The error/discrepancy may have been introduced during that crash recovery.

InnoDB: relay-log.info is detected.
InnoDB: relay log: position 404756, file name /opt/mysql/dblogs1/xxxxx-p0/relay/relay.000044
InnoDB: master log: position 482462824, file name bin.000029
131121 1:15:15 InnoDB: The InnoDB memory heap is disabled
131121 1:15:15 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131121 1:15:15 InnoDB: Compressed tables use zlib 1.2.3
131121 1:15:15 InnoDB: Using Linux native AIO
131121 1:15:15 InnoDB: Initializing buffer pool, size = 11.0G
131121 01:15:15 mysqld_safe mysqld from pid file /opt/mysql/dbprod/xxxxx-p0.pid ended
131121 1:15:17 InnoDB: Completed initialization of buffer pool
131121 1:15:17 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 1065744363665
131121 1:15:17 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1065745716474
131121 1:15:18 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 482462824, file name bin.000029
InnoDB: and relay log file
InnoDB: position 404756, file name /opt/mysql/dblogs1/xxxxx-p0/relay/relay.000044
InnoDB: Last MySQL binlog file position 0 239148860, file name /opt/mysql/dblogs1/xxxxx-p0/bin/bin.000018
131121 1:15:20 InnoDB: Waiting for the background threads to start
131121 1:15:21 Percona XtraDB (http://www.percona.com) 5.5.33-rel31.1 started; log sequence number 1065745716474
InnoDB: InnoDB and relay-log.info are synchronized. InnoDB will not overwrite it.
131121 1:15:21 [Note] Recovering after a crash using /opt/mysql/dblogs1/xxxxx-p0/bin/bin
131121 1:15:21 [Note] Starting crash recovery...
131121 1:15:21 [Note] Crash recovery finished.
131121 1:15:21 [Warning] Recovery from master pos 482462824 and file bin.000029.
131121 1:15:21 [Note] Event Scheduler: Loaded 0 events
131121 1:15:21 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.33-31.1-log' socket: '/opt/mysql/dbprod/xxxxx-p0.sock' port: 3306 Percona Server (GPL), Release rel31.1, Revision 566

[Valerii Kravchuk (valerii-kravchuk)]

Please, upload my.cnf from this slave and share some more lines from the error log on that problematic slave, showing slave start and maybe few errors.

I see this:

InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 482462824, file name bin.000029
InnoDB: and relay log file
InnoDB: position 404756, file name /opt/mysql/dblogs1/xxxxx-p0/relay/relay.000044
InnoDB: Last MySQL binlog file position 0 239148860, file name /opt/mysql/dblogs1/xxxxx-p0/bin/bin.000018
131121 1:15:20 InnoDB: Waiting for the background threads to start
131121 1:15:21 Percona XtraDB (http://www.percona.com) 5.5.33-rel31.1 started; log sequence number 1065745716474
InnoDB: InnoDB and relay-log.info are synchronized. InnoDB will not overwrite it.

Note bin.000018 vs bin.000029. I feel crash safe replication can be a problem here.

[monty solomon (monty+launchpad)]

My intuition is that crash safe replication was involved.

Sorry, but I replaced the server and don't have access to the logs.

[Valerii Kravchuk (valerii-kravchuk)]

Can be related to https://bugs.launchpad.net/percona-server/+bug/1239958

[Valerii Kravchuk (valerii-kravchuk)]

As we lack more evidence and can not get it, I assume it's a duplicate of https://bugs.launchpad.net/percona-server/+bug/1239958 for now.