[MDEV-18828] Error during XID COMMIT: failed to update GTID state in mysql.gtid_slave_pos: 1062: Duplicate entry '0-3913850' for key 'PRIMARY' Created: 2019-03-06  Updated: 2020-03-12  Resolved: 2020-02-11

Status: Closed
Project: MariaDB Server
Component/s: Replication, Storage Engine - InnoDB
Affects Version/s: 10.1.22
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: wy Assignee: Andrei Elkin
Resolution: Incomplete Votes: 3
Labels: GTID, need_feedback, parallelreplication, server
Environment:

Debian 8.2
parallel replication without gtid model


Attachments: PNG File 20190411.png     PNG File Repl-error-info.png    
Issue Links:
Relates
relates to MDEV-15393 gtid_slave_pos duplicate key errors a... Open

 Description   

Last_Errno: 1942
Last_Error: Error during XID COMMIT: failed to update GTID state in mysql.gtid_slave_pos: 1062: Duplicate entry '0-3913850' for key 'PRIMARY'

variables:

root@localhost:(none) 10:27:55> show global variables like '%repl%';
+----------------------------------+-----------+
| Variable_name                    | Value     |
+----------------------------------+-----------+
| innodb_replication_delay         | 0         |
| replicate_annotate_row_events    | OFF       |
| replicate_do_db                  |           |
| replicate_do_table               |           |
| replicate_events_marked_for_skip | REPLICATE |
| replicate_ignore_db              |           |
| replicate_ignore_table           |           |
| replicate_wild_do_table          |           |
| replicate_wild_ignore_table      |           |
| wsrep_mysql_replication_bundle   | 0         |
| wsrep_replicate_myisam           | OFF       |
+----------------------------------+-----------+
11 rows in set (0.00 sec)

root@localhost:(none) 10:27:57> show global variables like '%para%';
+-------------------------------+--------------+
| Variable_name                 | Value        |
+-------------------------------+--------------+
| slave_domain_parallel_threads | 0            |
| slave_parallel_max_queued     | 131072       |
| slave_parallel_mode           | conservative |
| slave_parallel_threads        | 8            |
+-------------------------------+--------------+
4 rows in set (0.00 sec)

root@localhost:(none) 10:28:03> show global variables like '%gtid%';
+------------------------+-------------------+
| Variable_name          | Value             |
+------------------------+-------------------+
| gtid_binlog_pos        | 0-23603584-215540 |
| gtid_binlog_state      | 0-23603584-215540 |
| gtid_current_pos       | 0-23603584-215540 |
| gtid_domain_id         | 0                 |
| gtid_ignore_duplicates | OFF               |
| gtid_slave_pos         | 0-23603584-215540 |
| gtid_strict_mode       | OFF               |
| wsrep_gtid_domain_id   | 0                 |
| wsrep_gtid_mode        | OFF               |
+------------------------+-------------------+
9 rows in set (0.00 sec)

root@localhost:(none) 10:37:50> show global variables like '%binlog%';
+-----------------------------------------+----------------------+
| Variable_name                           | Value                |
+-----------------------------------------+----------------------+
| binlog_annotate_row_events              | OFF                  |
| binlog_cache_size                       | 2097152              |
| binlog_checksum                         | NONE                 |
| binlog_commit_wait_count                | 0                    |
| binlog_commit_wait_usec                 | 100000               |
| binlog_direct_non_transactional_updates | OFF                  |
| binlog_format                           | ROW                  |
| binlog_optimize_thread_scheduling       | ON                   |
| binlog_row_image                        | FULL                 |
| binlog_stmt_cache_size                  | 1048576              |
| encrypt_binlog                          | OFF                  |
| gtid_binlog_pos                         | 0-23603584-215945    |
| gtid_binlog_state                       | 0-23603584-215945    |
| innodb_api_enable_binlog                | OFF                  |
| innodb_locks_unsafe_for_binlog          | OFF                  |
| max_binlog_cache_size                   | 18446744073709547520 |
| max_binlog_size                         | 1073741824           |
| max_binlog_stmt_cache_size              | 18446744073709547520 |
| sync_binlog                             | 1                    |
| wsrep_forced_binlog_format              | NONE                 |
+-----------------------------------------+----------------------+
20 rows in set (0.00 sec)

root@localhost:(none) 10:39:28> show global variables like '%slave%';
+-------------------------------+-------------------+
| Variable_name                 | Value             |
+-------------------------------+-------------------+
| gtid_slave_pos                | 0-23603584-221689 |
| init_slave                    |                   |
| log_slave_updates             | ON                |
| log_slow_slave_statements     | ON                |
| slave_compressed_protocol     | OFF               |
| slave_ddl_exec_mode           | IDEMPOTENT        |
| slave_domain_parallel_threads | 0                 |
| slave_exec_mode               | STRICT            |
| slave_load_tmpdir             | /dev/shm          |
| slave_max_allowed_packet      | 1073741824        |
| slave_net_timeout             | 360               |
| slave_parallel_max_queued     | 131072            |
| slave_parallel_mode           | conservative      |
| slave_parallel_threads        | 8                 |
| slave_run_triggers_for_rbr    | NO                |
| slave_skip_errors             |                   |
| slave_sql_verify_checksum     | ON                |
| slave_transaction_retries     | 10                |
| slave_type_conversions        |                   |
| sql_slave_skip_counter        | 0                 |
| wsrep_restart_slave           | OFF               |
| wsrep_slave_fk_checks         | ON                |
| wsrep_slave_uk_checks         | OFF               |
| wsrep_slave_threads           | 1                 |
+-------------------------------+-------------------+
24 rows in set (0.00 sec)



 Comments   
Comment by Andrei Elkin [ 2019-04-04 ]

ruochen, thanks for the report.

There is a chance that Duplicate entry '0-3913850' was caused by having this gtid transaction (group of repl events) in relaylog (binlog) twice.
I gather there's just one replication sources - one master, so we can rule out duplication caused by that. Anyway please check out.

Could you please show both binlog and relaylog events near the failure, say -/+ 100 from 0-3913850 in both directions.
Next that we need is the master's and slave's error log specifically to see whether there were reconnections and what gtid:s the slave was resuming from.

I find a bit strange that the error message speaks 0-3913850 while the description shows gtid_slave_pos | 0-23603584-221689. If gtid_slave_pos value was extracted right after the failure on that slave that would mean the binlog/relaylog contains transactions out of gtid seq_no order, which certainly may contribute to the issue.

So could you please clarify on all these points. Thank you.

Comment by wy [ 2019-04-08 ]

@Andrei Elkin
Thank you very much.

Yes,it's just one replication sources.
According to my observation,the problem occur in weak network like over IDC replacation frequently(but this rarely happens) ,or network throughput overflow,it was repaired by stop slave and then start slave,we will catch detail binlog/relaylog information next time for analysis.

Please ignore gtid seq_no in variables list,the config setting come from another instance.

Comment by wy [ 2019-04-12 ]

Yesterday case(20190411):

1)Slave show slave status info in 20190411.png image file.

2)Slave error log

2019-04-11 21:32:40 139825027365632 [ERROR] Slave SQL: Error during XID COMMIT: failed to update GTID state in mysql.gtid_slave_pos: 1062: Duplicate entry '0-153773074' for key 'PRIMARY', Gtid 0-16823342-307546139, Internal MariaDB error code: 1942
2019-04-11 21:32:40 139825027365632 [ERROR] Slave (additional info): Duplicate entry '0-153773074' for key 'PRIMARY' Error_code: 1062
2019-04-11 21:32:40 139825027365632 [Warning] Slave: Duplicate entry '0-153773074' for key 'PRIMARY' Error_code: 1062
2019-04-11 21:32:40 139825027365632 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000159' position 567712572
2019-04-11 21:32:40 139823896505088 [Note] Error reading relay log event: slave SQL thread was killed
2019-04-11 21:32:40 139823896505088 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.000159' at position 567712572

3)Master binglog events

# at 567710582
#190411 21:32:39 server id 16823342  end_log_pos 567710609      Xid = 4020831567
COMMIT/*!*/;
# at 567710609
#190411 21:32:39 server id 16823342  end_log_pos 567710647      GTID 0-16823342-307546137 trans
/*!100001 SET @@session.gtid_seq_no=307546137*//*!*/;
BEGIN
/*!*/;
# at 567710647
#190411 21:32:39 server id 16823342  end_log_pos 567710746      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567710746
#190411 21:32:39 server id 16823342  end_log_pos 567711181      Update_rows: table id 21 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_FIRED_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219162' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989557277 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219162' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560001 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='EXECUTING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @11='cpt' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567711181
#190411 21:32:39 server id 16823342  end_log_pos 567711276      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567711276
#190411 21:32:39 server id 16823342  end_log_pos 567711561      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989570000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567711561
#190411 21:32:39 server id 16823342  end_log_pos 567711588      Xid = 4020831570
COMMIT/*!*/;
# at 567711588
#190411 21:32:40 server id 16823342  end_log_pos 567711626      GTID 0-16823342-307546138 trans
/*!100001 SET @@session.gtid_seq_no=307546138*//*!*/;
BEGIN
/*!*/;
# at 567711626
#190411 21:32:40 server id 16823342  end_log_pos 567711725      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567711725
#190411 21:32:40 server id 16823342  end_log_pos 567712163      Update_rows: table id 21 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_FIRED_TRIGGERS`
### WHERE
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='crm-portal-70806-5b4497f759-jmzcx15548887805081554888807633' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-portal-70806-5b4497f759-jmzcx1554888780508' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989550138 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
### SET
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='crm-portal-70806-5b4497f759-jmzcx15548887805081554888807633' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-portal-70806-5b4497f759-jmzcx1554888780508' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560002 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='EXECUTING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @11='crm-order' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567712163
#190411 21:32:40 server id 16823342  end_log_pos 567712258      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567712258
#190411 21:32:40 server id 16823342  end_log_pos 567712545      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554894168000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989570000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554894168000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567712545
#190411 21:32:40 server id 16823342  end_log_pos 567712572      Xid = 4020831573
COMMIT/*!*/;
# at 567712572
#190411 21:32:40 server id 16823342  end_log_pos 567712610      GTID 0-16823342-307546139 trans
/*!100001 SET @@session.gtid_seq_no=307546139*//*!*/;
BEGIN
/*!*/;
# at 567712610
#190411 21:32:39 server id 16823342  end_log_pos 567712705      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567712705
#190411 21:32:39 server id 16823342  end_log_pos 567713026      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='AdoptOrderByCrmJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='AdoptOrderByCrmJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567713026
#190411 21:32:40 server id 16823342  end_log_pos 567713125      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567713125
#190411 21:32:40 server id 16823342  end_log_pos 567713353      Write_rows: table id 21 flags: STMT_END_F
### INSERT INTO `business_job`.`QRTZ_FIRED_TRIGGERS`
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219163' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560014 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567713353
#190411 21:32:40 server id 16823342  end_log_pos 567713380      Xid = 4020831576
COMMIT/*!*/;
# at 567713380
#190411 21:32:40 server id 16823342  end_log_pos 567713420      GTID 0-16823342-307546140 cid=4020831580 trans
/*!100001 SET @@session.gtid_seq_no=307546140*//*!*/;
BEGIN
/*!*/;
# at 567713420
#190411 21:32:40 server id 16823342  end_log_pos 567713519      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567713519

4)Slave relaylog events

# at 567710870
#190411 21:32:39 server id 16823342  end_log_pos 567710609      Xid = 4020831567
COMMIT/*!*/;
# at 567710897
#190411 21:32:39 server id 16823342  end_log_pos 567710647      GTID 0-16823342-307546137 trans
/*!100001 SET @@session.gtid_seq_no=307546137*//*!*/;
BEGIN
/*!*/;
# at 567710935
#190411 21:32:39 server id 16823342  end_log_pos 567710746      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567711034
#190411 21:32:39 server id 16823342  end_log_pos 567711181      Update_rows: table id 21 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_FIRED_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219162' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989557277 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219162' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560001 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='EXECUTING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @11='cpt' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567711469
#190411 21:32:39 server id 16823342  end_log_pos 567711276      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567711564
#190411 21:32:39 server id 16823342  end_log_pos 567711561      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='CptOrderStatusJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='CptOrderStatusJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='cpt' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989570000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567711849
#190411 21:32:39 server id 16823342  end_log_pos 567711588      Xid = 4020831570
COMMIT/*!*/;
# at 567711876
#190411 21:32:40 server id 16823342  end_log_pos 567711626      GTID 0-16823342-307546138 trans
/*!100001 SET @@session.gtid_seq_no=307546138*//*!*/;
BEGIN
/*!*/;
# at 567711914
#190411 21:32:40 server id 16823342  end_log_pos 567711725      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567712013
#190411 21:32:40 server id 16823342  end_log_pos 567712163      Update_rows: table id 21 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_FIRED_TRIGGERS`
### WHERE
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='crm-portal-70806-5b4497f759-jmzcx15548887805081554888807633' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-portal-70806-5b4497f759-jmzcx1554888780508' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989550138 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
### SET
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='crm-portal-70806-5b4497f759-jmzcx15548887805081554888807633' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-portal-70806-5b4497f759-jmzcx1554888780508' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560002 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='EXECUTING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @11='crm-order' /* VARSTRING(570) meta=570 nullable=1 is_null=0 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567712451
#190411 21:32:40 server id 16823342  end_log_pos 567712258      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567712546
#190411 21:32:40 server id 16823342  end_log_pos 567712545      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554894168000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='CRM-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='ReWaitOrderTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='ReWaitOrderJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='crm-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989570000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554894168000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567712833
#190411 21:32:40 server id 16823342  end_log_pos 567712572      Xid = 4020831573
COMMIT/*!*/;
# at 567712860
#190411 21:32:40 server id 16823342  end_log_pos 567712610      GTID 0-16823342-307546139 trans
/*!100001 SET @@session.gtid_seq_no=307546139*//*!*/;
BEGIN
/*!*/;
# at 567712898
#190411 21:32:39 server id 16823342  end_log_pos 567712705      Table_map: `business_job`.`QRTZ_TRIGGERS` mapped to number 43
# at 567712993
#190411 21:32:39 server id 16823342  end_log_pos 567713026      Update_rows: table id 43 flags: STMT_END_F
### UPDATE `business_job`.`QRTZ_TRIGGERS`
### WHERE
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='AdoptOrderByCrmJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='WAITING' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @3='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='AdoptOrderByCrmJob' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=NULL /* VARSTRING(750) meta=750 nullable=1 is_null=1 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @8=1554989550000 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @9=5 /* INT meta=0 nullable=1 is_null=0 */
###   @10='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @11='CRON' /* VARSTRING(24) meta=24 nullable=0 is_null=0 */
###   @12=1554799338000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @13=0 /* LONGINT meta=0 nullable=1 is_null=0 */
###   @14=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @15=2 /* SHORTINT meta=0 nullable=1 is_null=0 */
###   @16='' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
# at 567713314
#190411 21:32:40 server id 16823342  end_log_pos 567713125      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567713413
#190411 21:32:40 server id 16823342  end_log_pos 567713353      Write_rows: table id 21 flags: STMT_END_F
### INSERT INTO `business_job`.`QRTZ_FIRED_TRIGGERS`
### SET
###   @1='BRAND-SCHEDULE' /* VARSTRING(360) meta=360 nullable=0 is_null=0 */
###   @2='brand-adp-70471-55b755f695-hx74l15547991982031554799219163' /* VARSTRING(285) meta=285 nullable=0 is_null=0 */
###   @3='AdoptOrderByCrmJobTrigger' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @4='brand-order' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @5='brand-adp-70471-55b755f695-hx74l1554799198203' /* VARSTRING(570) meta=570 nullable=0 is_null=0 */
###   @6=1554989560014 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @7=1554989560000 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @8=5 /* INT meta=0 nullable=0 is_null=0 */
###   @9='ACQUIRED' /* VARSTRING(48) meta=48 nullable=0 is_null=0 */
###   @10=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(570) meta=570 nullable=1 is_null=1 */
###   @12='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @13='0' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
# at 567713641
#190411 21:32:40 server id 16823342  end_log_pos 567713380      Xid = 4020831576
COMMIT/*!*/;
# at 567713668
#190411 21:32:40 server id 16823342  end_log_pos 567713420      GTID 0-16823342-307546140 cid=4020831580 trans
/*!100001 SET @@session.gtid_seq_no=307546140*//*!*/;
BEGIN
/*!*/;
# at 567713708
#190411 21:32:40 server id 16823342  end_log_pos 567713519      Table_map: `business_job`.`QRTZ_FIRED_TRIGGERS` mapped to number 21
# at 567713807

Comment by Young Chen [ 2019-08-04 ]

hi team,
Any update?

Comment by Andrei Elkin [ 2019-09-16 ]

ruochen: In the initial report the parallel mode is CONSERVATIVE. What is like that in your latest followup as well?
I finally got a test case displaying a similar error but it requires OPTIMISTIC mode.

Young.chen.2019: if you have another setup that leads to the same error, could you please share details, including
what was the slave parallel mode?

Comment by wy [ 2020-03-12 ]


CONSERVATIVE mode all the time.

Comment by Andrei Elkin [ 2020-03-12 ]

ruochen: Thanks to clear it out a bit!

Let me ask for few details:
1. SHOW CREATE TABLE mysql.gtid_slave_ps,
2. the most recent failure instance's

  • The master and slave error log, only relevant to the failure time interval is enough
  • SHOW SLAVE STATUS
  • mysqlbinlog -v for events in the failed binlog, if the binlog file is big, provide with the output
    some range of events. I may specify the range criteria once again after seeing the 1st snippet uploaded.

Cheers.
Andrei

Generated at Thu Feb 08 08:47:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.