Slave assertion in unpack_row with ROLLBACK TO SAVEPOINT in error handler
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
MySQL Server |
Unknown
|
Unknown
|
||||
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
High
|
Vlad Lesin | |||
5.6 |
Fix Released
|
High
|
Vlad Lesin | |||
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC | ||||||
5.5 |
New
|
Undecided
|
Unassigned | |||
5.6 |
Fix Released
|
Undecided
|
Raghavendra D Prabhu |
Bug Description
Customer has 5.6.22 25-3.9 cluster crashing every so often, all nodes crash except the designated master.
...
Retrying 3th time
2015-03-13 17:42:13 50436 [ERROR] Slave SQL: Could not execute Write_rows event on table db_1.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1514, Error_code: 1105
2015-03-13 17:42:13 50436 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 5671546
2015-03-13 17:42:13 50436 [Warning] WSREP: Failed to apply app buffer: seqno: 5671546, status: 1
at galera/
Retrying 4th time
2015-03-13 17:42:13 50436 [ERROR] Slave SQL: Could not execute Write_rows event on table db_1.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1514, Error_code: 1105
2015-03-13 17:42:13 50436 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 5671546
2015-03-13 17:42:13 50436 [ERROR] WSREP: Failed to apply trx: source: 8d873190-
2015-03-13 17:42:13 50436 [ERROR] WSREP: Failed to apply trx 5671546 4 times
2015-03-13 17:42:13 50436 [ERROR] WSREP: Node consistency compromized, aborting...
Alexey suggested the problem could have been related to https:/
2015-03-20 15:10:39 43760 [ERROR] Slave SQL: Could not execute Write_rows event on table db_2.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1492, Error_code: 1105
2015-03-20 15:10:39 43760 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 6041375
2015-03-20 15:10:39 43760 [Warning] WSREP: Failed to apply app buffer: seqno: 6041375, status: 1
at galera/
Retrying 2th time
2015-03-20 15:10:39 43760 [ERROR] Slave SQL: Could not execute Write_rows event on table db_2.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1492, Error_code: 1105
2015-03-20 15:10:39 43760 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 6041375
2015-03-20 15:10:39 43760 [Warning] WSREP: Failed to apply app buffer: seqno: 6041375, status: 1
at galera/
Retrying 3th time
2015-03-20 15:10:39 43760 [ERROR] Slave SQL: Could not execute Write_rows event on table db_2.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1492, Error_code: 1105
2015-03-20 15:10:39 43760 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 6041375
2015-03-20 15:10:39 43760 [Warning] WSREP: Failed to apply app buffer: seqno: 6041375, status: 1
at galera/
Retrying 4th time
2015-03-20 15:10:39 43760 [ERROR] Slave SQL: Could not execute Write_rows event on table db_2.table_1; Unknown error, Error_code: 1105; handler error HA_ERR_GENERIC; the event's master log FIRST, end_log_pos 1492, Error_code: 1105
2015-03-20 15:10:39 43760 [Warning] WSREP: RBR event 17 Write_rows apply warning: 168, 6041375
2015-03-20 15:10:39 43760 [ERROR] WSREP: Failed to apply trx: source: 8beb12a2-
2015-03-20 15:10:39 43760 [ERROR] WSREP: Failed to apply trx 6041375 4 times
2015-03-20 15:10:39 43760 [ERROR] WSREP: Node consistency compromized, aborting...
Different database, same table; Sveta worked with Teemu and they discussed about this bit:
#150320 21:10:39 server id 102 end_log_pos 80 Query thread_id=3805 exec_time=0 error_code=0
SET TIMESTAMP=
SET @@session.
SET @@session.
SET @@session.
SET @@session.
/*!\C utf8 *//*!*/;
SET @@session.
SET @@session.
SET @@session.
BEGIN
/*!*/;
# at 187
#150320 21:10:39 server id 102 end_log_pos 172 Table_map: `db_2`.`table_2` mapped to number 305
# at 279
#150320 21:10:39 server id 102 end_log_pos 243 Table_map: `db_2`.`table_1` mapped to number 146
# at 350
#150320 21:10:39 server id 102 end_log_pos 317 Table_map: `db_2`.`table_3` mapped to number 272
# at 424
#150320 21:10:39 server id 102 end_log_pos 388 Table_map: `db_2`.`table_4` mapped to number 270
ERROR: Error in Log_event:
WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output.
DELIMITER ;
# End of log file
And Teemu asked for transaction from surviving node binlog, and here it is:
# at 3037980
#150320 16:10:39 server id 102 end_log_pos 3038064 CRC32 0x15d044e7 Query thread_id=3805 exec_time=0 error_code=0
SET TIMESTAMP=
BEGIN
/*!*/;
# at 3038064
# at 3038160
# at 3038235
# at 3038313
# at 3038388
#150320 16:10:39 server id 102 end_log_pos 3038160 CRC32 0x211b066d Table_map: `db_2`.`table_2` mapped to number 305
#150320 16:10:39 server id 102 end_log_pos 3038235 CRC32 0xdcf4126d Table_map: `db_2`.`table_1` mapped to number 146
#150320 16:10:39 server id 102 end_log_pos 3038313 CRC32 0xa6302dee Table_map: `db_2`.`table_3` mapped to number 272
#150320 16:10:39 server id 102 end_log_pos 3038388 CRC32 0xa9265597 Table_map: `db_2`.`table_4` mapped to number 270
#150320 16:10:39 server id 102 end_log_pos 3038549 CRC32 0x3905db2a Update_rows: table id 305 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAAYAA
EwMDAxISAxIPEg8
r3AMVRNmAAAASwA
AwEBEhIDAwT9AgA
r3AMVRNmAAAATgA
Dw8SEgMDCP0C/
r3AMVRNmAAAASwA
EhIDAwj9Av0C/
r3AMVR9mAAAAoQA
lakyngEAAAAGQ1J
mZWpMp4BAAAAmZW
'/*!*/;
### UPDATE `db_2`.`table_2`
### WHERE
### @1=1174
### @2=1179
### @3=1
### @4='2015-03-20 19:10:19'
### @5='2015-03-20 19:10:30'
### @6=1
### @7=NULL
### @8='CREATE'
### @9='2015-03-20 19:10:20'
### @10=NULL
### @11=NULL
### @12=0
### @13=NULL
### @14=NULL
### @15=21329
### @16=3
### @17=1
### @18=NULL
### @19=2
### SET
### @1=1174
### @2=1179
### @3=1
### @4='2015-03-20 19:10:19'
### @5='2015-03-20 19:10:30'
### @6=1
### @7='2015-03-20 19:10:39'
### @8='CREATE'
### @9='2015-03-20 19:10:20'
### @10=NULL
### @11=NULL
### @12=0
### @13=NULL
### @14=NULL
### @15=21329
### @16=3
### @17=1
### @18=NULL
### @19=2
# at 3038549
# at 3038623
#150320 16:10:39 server id 102 end_log_pos 3038623 CRC32 0x0a4e0b13 Table_map: `db_2`.`table_5` mapped to number 124
#150320 16:10:39 server id 102 end_log_pos 3038719 CRC32 0x44c43bb0 Update_rows: table id 124 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAASgA
BgMDDwMSEgQeAAA
r3AMVR9mAAAAYAA
mqj/fvvAGwcAAJY
'/*!*/;
### UPDATE `db_2`.`table_5`
### WHERE
### @1=1819
### @2=1174
### @3='CREATE'
### @4=582
### @5='2015-03-20 19:10:20'
### @6='2099-12-31 23:59:59'
### SET
### @1=1819
### @2=1174
### @3='CREATE'
### @4=582
### @5='2015-03-20 19:10:20'
### @6='2015-03-20 19:10:40'
# at 3038719
# at 3038793
#150320 16:10:39 server id 102 end_log_pos 3038793 CRC32 0x51a07ebd Table_map: `db_2`.`table_5` mapped to number 124
#150320 16:10:39 server id 102 end_log_pos 3038855 CRC32 0x7e9602b5 Write_rows: table id 124 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAASgA
BgMDDwMSEgQeAAA
r3AMVR5mAAAAPgA
+7UCln4=
'/*!*/;
### INSERT INTO `db_2`.`table_5`
### SET
### @1=1829
### @2=1174
### @3='NEW'
### @4=582
### @5='2015-03-20 19:10:40'
### @6='2099-12-31 23:59:59'
# at 3038855
# at 3038951
# at 3039026
# at 3039104
# at 3039179
# at 3039342
#150320 16:10:39 server id 102 end_log_pos 3039446 CRC32 0x8d0e6222 Query thread_id=3805 exec_time=0 error_code=0
SET TIMESTAMP=
SET @@session.
SAVEPOINT `save_point_name`
/*!*/;
# at 3039446
# at 3039540
#150320 16:10:39 server id 102 end_log_pos 3039540 CRC32 0x695e518a Write_rows: table id 146
#150320 16:10:39 server id 102 end_log_pos 3039613 CRC32 0xc4574a36 Write_rows: table id 272 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAAYAA
EwMDAxISAxIPEg8
r3AMVRNmAAAASwA
AwEBEhIDAwT9AgA
r3AMVRNmAAAATgA
Dw8SEgMDCP0C/
r3AMVRNmAAAASwA
EhIDAwj9Av0C/
r3AMVR9mAAAAowA
lakyngEAAACZlak
mZWpMpOZlakyngE
### UPDATE `db_2`.`table_2`
### WHERE
### @1=1174
### @2=1179
### @3=1
### @4='2015-03-20 19:10:19'
### @5='2015-03-20 19:10:30'
### @6=1
### @7='2015-03-20 19:10:39'
### @8='CREATE'
### @9='2015-03-20 19:10:20'
### @10=NULL
### @11=NULL
### @12=0
### @13=NULL
### @14=NULL
### @15=21329
### @16=3
### @17=1
### @18=NULL
### @19=2
### SET
### @1=1174
### @2=1179
### @3=1
### @4='2015-03-20 19:10:19'
### @5='2015-03-20 19:10:30'
### @6=1
### @7='2015-03-20 19:10:39'
### @8='NEW'
### @9='2015-03-20 19:10:40'
### @10=NULL
### @11=NULL
### @12=0
### @13=NULL
### @14=NULL
### @15=21329
### @16=3
### @17=1
### @18=NULL
### @19=2
r3AMVR5mAAAAXgA
dDoxMTc0AgAAAAM
### INSERT INTO `db_2`.`table_1`
### SET
### @1=29
### @2='new_
### @3=2
### @4=3
### @5=1
### @6=1
### @7=NULL
### @8=0
### @9=1
### @10='2015-03-20 19:10:39'
### @11=NULL
### @12=2
### @13=NULL
r3AMVR5mAAAASQA
MTc0mZWpMqcCAAA
'/*!*/;
### INSERT INTO `db_2`.`table_3`
### SET
### @1=29
### @2=29
### @3=NULL
### @4='request_id'
### @5=NULL
### @6='1174'
### @7='2015-03-20 19:10:39'
### @8=NULL
### @9=2
### @10=NULL
# at 3039613
#150320 16:10:39 server id 102 end_log_pos 3039644 CRC32 0x4c709170 Xid = 6041375
COMMIT/*!*/;
# at 3039644
Teemu Ollakka: "the healthy transaction seems to report crc32 checksums but the parsed GRA file does not".
And here is the parsed GRA:
/*!50530 SET @@SESSION.
/*!40019 SET @@session.
/*!50003 SET @OLD_COMPLETION
DELIMITER /*!*/;
# at 4
#140113 17:12:42 server id 3 end_log_pos 120 CRC32 0xe6f1f7fe Start: binlog v 4, server v 5.6.15-log created 140113 17:12:42 at startup
ROLLBACK/*!*/;
BINLOG '
qjrUUg8DAAAAdAA
AAAAAAAAAAAAAAA
8eY=
'/*!*/;
# at 120
#140113 17:12:43 server id 3 end_log_pos 143 CRC32 0x26e85337 Stop
# at 143
#150320 16:10:39 server id 102 end_log_pos 80 CRC32 0x4e494745 Query thread_id=3805 exec_time=0 error_code=0
SET TIMESTAMP=
SET @@session.
SET @@session.
SET @@session.
SET @@session.
/*!\C utf8 *//*!*/;
SET @@session.
SET @@session.
SET @@session.
B
/*!*/;
# at 223
# at 315
# at 386
# at 460
# at 531
#150320 16:10:39 server id 102 end_log_pos 172 CRC32 0x06365017 Table_map: `db_2`.`table_2` mapped to number 305
#150320 16:10:39 server id 102 end_log_pos 243 CRC32 0x147a0000 Table_map: `db_2`.`table_1` mapped to number 146
#150320 16:10:39 server id 102 end_log_pos 317 CRC32 0x02940000 Table_map: `db_2`.`table_3` mapped to number 272
#150320 16:10:39 server id 102 end_log_pos 388 CRC32 0xa0000002 Table_map: `db_2`.`table_4` mapped to number 270
#150320 16:10:39 server id 102 end_log_pos 545 CRC32 0x00000002 Update_rows: table id 305 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAAXAA
EwMDAxISAxIPEg8
r3AMVRNmAAAARwA
AwEBEhIDAwT9AgA
r3AMVRNmAAAASgA
Dw8SEgMDCP0C/
r3AMVRNmAAAARwA
EhIDAwj9Av0C/
r3AMVR9mAAAAnQA
lakyngEAAAAGQ1J
mZWpMp4BAAAAmZW
'/*!*/;
### UPDATE `db_2`.`table_2`
### WHERE
### @1=1174 /* INT meta=0 nullable=0 is_null=0 */
### @2=1179 /* INT meta=0 nullable=0 is_null=0 */
### @3=1 /* INT meta=0 nullable=0 is_null=0 */
### @4='2015-03-20 19:10:19' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:30' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @6=1 /* INT meta=0 nullable=0 is_null=0 */
### @7=NULL /* INT meta=0 nullable=1 is_null=1 */
### @8='CREATE' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @9='2015-03-20 19:10:20' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @10=NULL /* DATETIME(0) meta=6000 nullable=1 is_null=1 */
### @11=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @12=0 /* TINYINT meta=0 nullable=0 is_null=0 */
### @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
### @14=NULL /* TINYINT meta=6000 nullable=1 is_null=1 */
### @15=21329 /* INT meta=0 nullable=0 is_null=0 */
### @16=3 /* INT meta=0 nullable=0 is_null=0 */
### @17=1 /* INT meta=0 nullable=0 is_null=0 */
### @18=NULL /* INT meta=0 nullable=1 is_null=1 */
### @19=2 /* INT meta=0 nullable=1 is_null=0 */
### SET
### @1=1174 /* INT meta=0 nullable=0 is_null=0 */
### @2=1179 /* INT meta=0 nullable=0 is_null=0 */
### @3=1 /* INT meta=0 nullable=0 is_null=0 */
### @4='2015-03-20 19:10:19' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:30' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @6=1 /* INT meta=0 nullable=0 is_null=0 */
### @7='2015-03-20 19:10:39' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @8='CREATE' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @9='2015-03-20 19:10:20' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @10=NULL /* DATETIME(0) meta=6000 nullable=1 is_null=1 */
### @11=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @12=0 /* TINYINT meta=0 nullable=0 is_null=0 */
### @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
### @14=NULL /* TINYINT meta=6000 nullable=1 is_null=1 */
### @15=21329 /* INT meta=0 nullable=0 is_null=0 */
### @16=3 /* INT meta=0 nullable=0 is_null=0 */
### @17=1 /* INT meta=0 nullable=0 is_null=0 */
### @18=NULL /* INT meta=0 nullable=1 is_null=1 */
### @19=***Corrupted replication event was detected. Not printing the value***
# at 688
# at 758
#150320 16:10:39 server id 102 end_log_pos 615 CRC32 0x00000000 Table_map: `db_2`.`table_5` mapped to number 124
#150320 16:10:39 server id 102 end_log_pos 707 CRC32 0xa832a995 Update_rows: table id 124 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAARgA
BgMDDwMSEgQeAAA
r3AMVR9mAAAAXAA
mqj/fvvAGwcAAJY
'/*!*/;
### UPDATE `db_2`.`table_5`
### WHERE
### @1=1819 /* INT meta=0 nullable=0 is_null=0 */
### @2=1174 /* INT meta=0 nullable=0 is_null=0 */
### @3='CREATE' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @4=582 /* INT meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:20' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @6='2099-12-31 23:59:59' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### SET
### @1=1819 /* INT meta=0 nullable=0 is_null=0 */
### @2=1174 /* INT meta=0 nullable=0 is_null=0 */
### @3='CREATE' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @4=582 /* INT meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:20' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @6=***Corrupted replication event was detected. Not printing the value***
# at 850
# at 920
#150320 16:10:39 server id 102 end_log_pos 777 CRC32 0x00000000 Table_map: `db_2`.`table_5` mapped to number 124
#150320 16:10:39 server id 102 end_log_pos 835 CRC32 0xfb7effa8 Write_rows: table id 124 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAARgA
BgMDDwMSEgQeAAA
r3AMVR5mAAAAOgA
+w==
'/*!*/;
### INSERT INTO `db_2`.`table_5`
### SET
### @1=1829 /* INT meta=0 nullable=0 is_null=0 */
### @2=1174 /* INT meta=0 nullable=0 is_null=0 */
### @3='NEW' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @4=582 /* INT meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:40' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @6=***Corrupted replication event was detected. Not printing the value***
# at 978
# at 1070
# at 1141
# at 1215
# at 1286
# at 1445
#150320 16:10:39 server id 102 end_log_pos 1402 CRC32 0x60676e69 Query thread_id=3805 exec_time=0 error_code=0
SET TIMESTAMP=
SET @@session.
SAVEPOINT `event_logg
/*!*/;
# at 1545
# at 1635
#150320 16:10:39 server id 102 end_log_pos 1492 CRC32 0x00000002 Write_rows: table id 146
#150320 16:10:39 server id 102 end_log_pos 1561 CRC32 0x00000002 Write_rows: table id 272 flags: STMT_END_F
BINLOG '
r3AMVRNmAAAAXAA
EwMDAxISAxIPEg8
r3AMVRNmAAAARwA
AwEBEhIDAwT9AgA
r3AMVRNmAAAASgA
Dw8SEgMDCP0C/
r3AMVRNmAAAARwA
EhIDAwj9Av0C/
r3AMVR9mAAAAnwA
lakyngEAAACZlak
mZWpMpOZlakyngE
### UPDATE `db_2`.`table_2`
### WHERE
### @1=1174 /* INT meta=0 nullable=0 is_null=0 */
### @2=1179 /* INT meta=0 nullable=0 is_null=0 */
### @3=1 /* INT meta=0 nullable=0 is_null=0 */
### @4='2015-03-20 19:10:19' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:30' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @6=1 /* INT meta=0 nullable=0 is_null=0 */
### @7='2015-03-20 19:10:39' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @8='CREATE' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @9='2015-03-20 19:10:20' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @10=NULL /* DATETIME(0) meta=6000 nullable=1 is_null=1 */
### @11=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @12=0 /* TINYINT meta=0 nullable=0 is_null=0 */
### @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
### @14=NULL /* TINYINT meta=6000 nullable=1 is_null=1 */
### @15=21329 /* INT meta=0 nullable=0 is_null=0 */
### @16=3 /* INT meta=0 nullable=0 is_null=0 */
### @17=1 /* INT meta=0 nullable=0 is_null=0 */
### @18=NULL /* INT meta=0 nullable=1 is_null=1 */
### @19=2 /* INT meta=0 nullable=1 is_null=0 */
### SET
### @1=1174 /* INT meta=0 nullable=0 is_null=0 */
### @2=1179 /* INT meta=0 nullable=0 is_null=0 */
### @3=1 /* INT meta=0 nullable=0 is_null=0 */
### @4='2015-03-20 19:10:19' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @5='2015-03-20 19:10:30' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @6=1 /* INT meta=0 nullable=0 is_null=0 */
### @7='2015-03-20 19:10:39' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
### @8='NEW' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
### @9='2015-03-20 19:10:40' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @10=NULL /* DATETIME(0) meta=6000 nullable=1 is_null=1 */
### @11=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @12=0 /* TINYINT meta=0 nullable=0 is_null=0 */
### @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
### @14=NULL /* TINYINT meta=6000 nullable=1 is_null=1 */
### @15=21329 /* INT meta=0 nullable=0 is_null=0 */
### @16=3 /* INT meta=0 nullable=0 is_null=0 */
### @17=1 /* INT meta=0 nullable=0 is_null=0 */
### @18=NULL /* INT meta=0 nullable=1 is_null=1 */
### @19=***Corrupted replication event was detected. Not printing the value***
r3AMVR5mAAAAWgA
dDoxMTc0AgAAAAM
### INSERT INTO `db_2`.`table_1`
### SET
### @1=29 /* INT meta=0 nullable=0 is_null=0 */
### @2='new_
### @3=2 /* INT meta=0 nullable=0 is_null=0 */
### @4=3 /* INT meta=0 nullable=1 is_null=0 */
### @5=1 /* INT meta=0 nullable=1 is_null=0 */
### @6=1 /* INT meta=0 nullable=1 is_null=0 */
### @7=NULL /* INT meta=0 nullable=1 is_null=1 */
### @8=0 /* TINYINT meta=0 nullable=0 is_null=0 */
### @9=1 /* TINYINT meta=0 nullable=0 is_null=0 */
### @10='2015-03-20 19:10:39' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @11=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @12=***Corrupted replication event was detected. Not printing the value***
r3AMVR5mAAAARQA
MTc0mZWpMqcCAAAA
'/*!*/;
### INSERT INTO `db_2`.`table_3`
### SET
### @1=29 /* INT meta=0 nullable=0 is_null=0 */
### @2=29 /* INT meta=0 nullable=0 is_null=0 */
### @3=NULL /* INT meta=0 nullable=1 is_null=1 */
### @4='request_id' /* VARSTRING(765) meta=765 nullable=0 is_null=0 */
### @5=NULL /* VARSTRING(765) meta=765 nullable=1 is_null=1 */
### @6='1174' /* VARSTRING(765) meta=765 nullable=0 is_null=0 */
### @7='2015-03-20 19:10:39' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
### @8=NULL /* DATETIME(0) meta=0 nullable=1 is_null=1 */
### @9=***Corrupted replication event was detected. Not printing the value***
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_
/*!50530 SET @@SESSION.
So, the BINLOG strings of the corrupt Xid are all literally "cut" or corrupt
by 8 bytes:
In binlog:
BINLOG '
r3AMVRNmAAAASgA
BgMDDwMSEgQeAAA
r3AMVR9mAAAAYAA
mqj/fvvAGwcAAJY
'/*!*/;
In GRA:
BINLOG '
r3AMVRNmAAAARgA
BgMDDwMSEgQeAAA
r3AMVR9mAAAAXAA
mqj/fvvAGwcAAJY
'/*!*/;
You can see the last few bytes "iwO8RE" were cut and instead we see "g="
Here's another example:
From binlog:
BINLOG '
r3AMVRNmAAAASgA
BgMDDwMSEgQeAAA
r3AMVR5mAAAAPgA
+7UCln4=
'/*!*/;
From GRA:
BINLOG '
r3AMVRNmAAAARgA
BgMDDwMSEgQeAAA
r3AMVR5mAAAAOgA
+w==
You can see "+7UCln4=" was transformed to "+w=="
And one more:
In binlog
r3AMVR5mAAAAXgA
dDoxMTc0AgAAAAM
In GRA
r3AMVR5mAAAAWgA
dDoxMTc0AgAAAAM
Here the whole "ilFeaQ==" is missing in gra
> Teemu Ollakka: we might have asymmetric settings
I verified my.cnf from each node and only found small divergences in one of
the node's .cnf where character-sets-dir, sync_binlog and
innodb_
And the my.cnf from one of the nodes:
[client]
port = 4301
socket = /customrootdir/
character-
[mysqld]
port = 4301
socket = /customrootdir/
datadir = /customrootdir/
tmpdir = /customrootdir/
slave-load-
log-bin=
relay-log=
relay-log-
max_binlog_size = 1G
binlog_format = ROW
expire_logs_days = 15
sync_binlog = 1
slow-query-log = 1
slow_query_log_file = slow_query.log
long_query_time = 2
log_warnings = 2
character-
collation_
skip-external-
back_log = 500
max_connections = 500
max_connect_errors = 500
table_open_cache = 4000
table_definitio
open-files-limit = 24000
interactive_timeout = 3600
wait_timeout = 3600
net_read_timeout = 120
net_write_timeout = 240
max_allowed_packet = 2048M
binlog_cache_size = 8M
max_heap_table_size = 128M
tmp_table_size = 128M
read_buffer_size = 1M
read_rnd_
sort_buffer_size = 1M
join_buffer_size = 1M
thread_cache_size = 250
large-pages
query_cache_type = 0
query_cache_size = 0
query_cache_limit = 2M
thread_pool_size=36
server-id = 202
auto_increment_
auto_increment_
key_buffer_size = 256M
bulk_insert_
myisam_
myisam-recover = BACKUP,FORCE
default-
innodb_
innodb_support_xa = 0
innodb_
innodb_
innodb_
innodb_
innodb_
innodb_
innodb_open_files = 16000
innodb_
innodb_
innodb_
innodb_
innodb_
innodb_io_capacity = 10000
innodb_
innodb_
innodb_
innodb_file_format = 'Barracuda'
innodb_
log-bin-
metadata_
innodb_
innodb_
innodb_
innodb_
innodb_
innodb_
innodb_undo_logs=8
innodb_
innodb_
slave-parallel-
slave_pending_
wsrep_provider=
wsrep_provider_
binlog_format=ROW
default_
innodb_
wsrep_cluster_
wsrep_sst_
wsrep_sst_
wsrep_node_
wsrep_slave_
[mysqldump]
quick
max_allowed_packet = 64M
[mysql]
no-auto-rehash
[mysqld_safe]
core-file-size=2G
[mysqlhotcopy]
interactive-timeout
[sst]
transferfmt=nc
mysqlbinlog --verbose GRA_2_6041375.
SET @@session.
SET @@session.
Not sure if relevant, but they switch sql mode through the transaction...
no longer affects: | percona-xtradb-cluster |
tags: | added: i53148 |
tags: | added: upstream |
summary: |
- Corrupt replication events + Slave assertion in unpack_row with ROLLBACK TO SAVEPOINT in error + handler |
It seems that the log events stored in wsrep write sets won't contain checksums since crc:s are computed only when writing IO cache to binlog (see MYSQL_BIN_ LOG::do_ write_cache( )). This in turn means that:
* Parsing GRA files using binlog header and mysqlbinlog will display corrupted replication events if the binlog header has checksum setting on even if the events in GRA file are perfectly valid.
* The cause of slave failure is still unknown.