Could not execute Write/Delete_rows event,Node consistency compromized, aborting

[sampson,li]

OS: Red Hat Enterprise Linux Server release 7.2 (Maipo)
Software: Percona XtraDB Cluster 5.7.18-29.20
Cluster: we have three nodes==>node85 for write;node86 and node87 for read only.

there are a pressure test at that time,table cart & shopcart had many insert & delete operation.

The node86(read node) aborted at 2017-09-28T10:00:11 and node85(write node) aborted at 2017-09-28T10:28:49.

we start these nodes by .../bin/mysqld later,the cluster recovery.

error log for node86：

017-09-28T10:00:11.095242Z 2 [ERROR] Slave SQL: Could not execute Write_rows event on table shopcart.cart; Duplicate entry '2005485142-1-20064' for key 'PRIMARY', Error_code: 1062; handler e
rror HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 207, Error_code: 1062
2017-09-28T10:00:11.095285Z 2 [Warning] WSREP: RBR event 3 Write_rows apply warning: 121, 163162
2017-09-28T10:00:11.095823Z 2 [Warning] WSREP: Failed to apply app buffer: seqno: 163162, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 2th time
2017-09-28T10:00:11.095999Z 2 [ERROR] Slave SQL: Could not execute Write_rows event on table shopcart.cart; Duplicate entry '2005485142-1-20064' for key 'PRIMARY', Error_code: 1062; handler e
rror HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 207, Error_code: 1062
2017-09-28T10:00:11.096012Z 2 [Warning] WSREP: RBR event 3 Write_rows apply warning: 121, 163162
2017-09-28T10:00:11.096301Z 2 [Warning] WSREP: Failed to apply app buffer: seqno: 163162, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 3th time
2017-09-28T10:00:11.096459Z 2 [ERROR] Slave SQL: Could not execute Write_rows event on table shopcart.cart; Duplicate entry '2005485142-1-20064' for key 'PRIMARY', Error_code: 1062; handler e
rror HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 207, Error_code: 1062
2017-09-28T10:00:11.096471Z 2 [Warning] WSREP: RBR event 3 Write_rows apply warning: 121, 163162
2017-09-28T10:00:11.096984Z 2 [Warning] WSREP: Failed to apply app buffer: seqno: 163162, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 4th time
2017-09-28T10:00:11.097163Z 2 [ERROR] Slave SQL: Could not execute Write_rows event on table shopcart.cart; Duplicate entry '2005485142-1-20064' for key 'PRIMARY', Error_code: 1062; handler e
rror HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 207, Error_code: 1062
2017-09-28T10:00:11.097175Z 2 [Warning] WSREP: RBR event 3 Write_rows apply warning: 121, 163162
2017-09-28T10:00:11.097824Z 2 [ERROR] WSREP: Failed to apply trx: source: 59a4e002-921c-11e7-b4f7-6bbb8bd5aa20 version: 3 local: 0 state: APPLYING flags: 1 conn_id: 5434 trx_id: 3319435 seqno
s (l: 165942, g: 163162, s: 163161, d: 163027, ts: 13749441138646984)

2017-09-28T10:00:11.097838Z 2 [ERROR] WSREP: Failed to apply trx 163162 4 times
2017-09-28T10:00:11.097845Z 2 [ERROR] WSREP: Node consistency compromized, aborting...

error log for node85：

2017-09-28T10:28:49.729606Z 3 [ERROR] Slave SQL: Could not execute Delete_rows event on table shopcart.shopcart; Can't find record in 'shopcart', Error_code: 1032; handler error HA_ERR_KEY_NO
T_FOUND; the event's master log FIRST, end_log_pos 497, Error_code: 1032
2017-09-28T10:28:49.729649Z 3 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 120, 456024
2017-09-28T10:28:49.730282Z 3 [Warning] WSREP: Failed to apply app buffer: seqno: 456024, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 2th time
2017-09-28T10:28:49.730514Z 3 [ERROR] Slave SQL: Could not execute Delete_rows event on table shopcart.shopcart; Can't find record in 'shopcart', Error_code: 1032; handler error HA_ERR_KEY_NO
T_FOUND; the event's master log FIRST, end_log_pos 497, Error_code: 1032
2017-09-28T10:28:49.730535Z 3 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 120, 456024
2017-09-28T10:28:49.730883Z 3 [Warning] WSREP: Failed to apply app buffer: seqno: 456024, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 3th time
2017-09-28T10:28:49.731080Z 3 [ERROR] Slave SQL: Could not execute Delete_rows event on table shopcart.shopcart; Can't find record in 'shopcart', Error_code: 1032; handler error HA_ERR_KEY_NO
T_FOUND; the event's master log FIRST, end_log_pos 497, Error_code: 1032
2017-09-28T10:28:49.731093Z 3 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 120, 456024
2017-09-28T10:28:49.731619Z 3 [Warning] WSREP: Failed to apply app buffer: seqno: 456024, status: 1
         at galera/src/trx_handle.cpp:apply():351
Retrying 4th time
2017-09-28T10:28:49.731786Z 3 [ERROR] Slave SQL: Could not execute Delete_rows event on table shopcart.shopcart; Can't find record in 'shopcart', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 497, Error_code: 1032
2017-09-28T10:28:49.731816Z 3 [Warning] WSREP: RBR event 3 Delete_rows apply warning: 120, 456024
2017-09-28T10:28:49.733146Z 3 [ERROR] WSREP: Failed to apply trx: source: fe22378c-921d-11e7-a0b5-9b2d6f4fa17c version: 3 local: 0 state: APPLYING flags: 1 conn_id: 437 trx_id: 11638955 seqnos (l: 463391, g: 456024, s: 456023, d: 455947, ts: 13751156325301172)
2017-09-28T10:28:49.733160Z 3 [ERROR] WSREP: Failed to apply trx 456024 4 times
2017-09-28T10:28:49.733168Z 3 [ERROR] WSREP: Node consistency compromized, aborting...

here are the two tables:

system@localhost 11:40: [shopcart]> show create table cart\G
*************************** 1. row ***************************
       Table: cart
Create Table: CREATE TABLE `cart` (
  `sku_id` int(10) unsigned NOT NULL,
  `quantity` smallint(5) unsigned NOT NULL,
  `user_id` bigint(10) unsigned NOT NULL,
  `channel` varchar(100) DEFAULT NULL,
  `type` tinyint(3) unsigned NOT NULL,
  `checked` varchar(10) NOT NULL DEFAULT '1' COMMENT '勾选：1—选中,0-未选中',
  `create_time` timestamp NULL DEFAULT NULL ON UPDATE CURRENT_TIMESTAMP,
  `last_update` timestamp NULL DEFAULT NULL ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`user_id`,`type`,`sku_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

system@localhost 11:40: [shopcart]> show create table shopcart\G
*************************** 1. row ***************************
       Table: shopcart
Create Table: CREATE TABLE `shopcart` (
  `id` varchar(50) NOT NULL,
  `user_id` bigint(20) NOT NULL COMMENT '用户ID',
  `type` tinyint(4) NOT NULL COMMENT '订单类型 1--普通订单 2--定金订单 3--预售订单',
  `order_id` varchar(50) DEFAULT NULL COMMENT '订单号',
  `total_amount` decimal(20,2) NOT NULL DEFAULT '0.00' COMMENT '总价',
  `total_adjustment` decimal(20,2) NOT NULL DEFAULT '0.00' COMMENT '优惠金额',
  `shipping` decimal(20,2) NOT NULL DEFAULT '0.00' COMMENT '运费',
  `shipping_adjustment` decimal(20,2) NOT NULL DEFAULT '0.00' COMMENT '运费的促销金额',
  `pay_method` varchar(50) DEFAULT NULL COMMENT '支付方式 ： ONLINE_PAY COD',
  `channel` varchar(50) DEFAULT NULL COMMENT '渠道 PC、MOBILE、APP、WECHAT，O2O',
  `warp_part` varchar(64) DEFAULT NULL COMMENT '礼品包装货号',
  `wrap_price` decimal(20,2) DEFAULT NULL COMMENT '礼品包装价格',
  `comments` text COMMENT '备注',
  `gift_comments` varchar(50) DEFAULT NULL COMMENT '礼品卡',
  `address_id` bigint(20) DEFAULT NULL COMMENT '收货地址',
  `invoice_type` varchar(50) DEFAULT '' COMMENT '发票类型',
  `delivery_info` varchar(500) DEFAULT NULL COMMENT '配送信息',
  `PAYMENT_CODE` varchar(32) DEFAULT NULL COMMENT '支付方式',
  `BANK_CODE` varchar(19) DEFAULT NULL COMMENT '银行编码',
  `create_time` timestamp NOT NULL COMMENT '订单创建时间',
  `update_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '订单更新时间',
  `create_user` varchar(50) NOT NULL,
  `update_user` varchar(50) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='购物车表'
1 row in set (0.00 sec)

my.cnf:

node85:
root@dpsvstadbs02 11:49:49:~$ cat /etc/my.cnf
#
##mysql configure file my.cnf
#
[client]
port = 3306
socket = /tmp/mysql.sock
default-character-set = utf8mb4

[mysql]
prompt="\u@\h \R:\m:\s [\d]> "
no-auto-rehash
default-character-set = utf8mb4

[mysqld]
user = mysql
port = 3306
basedir = /usr/local/mysql
datadir = /docker/mysql/mysql_3306/data
socket = /tmp/mysql.sock
pid-file = dpppnewdbs04.sephora.cn.pid
character-set-server = utf8mb4
skip_name_resolve = 1
log_bin_trust_function_creators=1
lower_case_table_names = 1
open_files_limit = 65535
back_log = 1024
server-id = 853306

#binlog
log-bin = /docker/mysql/mysql_3306/logs/binlog/mysql-bin
binlog_format = row
sync_binlog = 1
binlog_cache_size = 512M
expire_logs_days = 3
max_binlog_cache_size = 2G
max_binlog_size = 1G
master_info_repository = TABLE
relay_log_info_repository = TABLE
gtid_mode = on
enforce_gtid_consistency = 1
log_slave_updates

#slow & error log
slow_query_log = 1
slow_query_log_file = /docker/mysql/mysql_3306/logs/slow.log
log-error = /docker/mysql/mysql_3306/logs/error.log
long_query_time = 0.1
#general_log=on
#general_log_file=/docker/mysql/mysql_3306/logs/general_85.log

max_connections = 10000
max_connect_errors = 1000000
table_open_cache = 128
table_definition_cache = 128
table_open_cache_instances = 64
thread_stack = 512K
external-locking = FALSE
max_allowed_packet = 64M
sort_buffer_size = 8M
join_buffer_size = 8M
thread_cache_size = 1500
query_cache_size = 0
query_cache_type = 0
interactive_timeout = 600
wait_timeout = 600
tmp_table_size = 64M
max_heap_table_size = 32M

relay_log_recovery = 1
relay-log-purge = 1
key_buffer_size = 32M
read_buffer_size = 8M
read_rnd_buffer_size = 4M
bulk_insert_buffer_size = 64M
myisam_sort_buffer_size = 128M
myisam_max_sort_file_size = 10G
myisam_repair_threads = 1
lock_wait_timeout = 3600
explicit_defaults_for_timestamp = 1
transaction_isolation = READ-COMMITTED

#innodb
default_storage_engine=Innodb
innodb_thread_concurrency = 0
innodb_sync_spin_loops = 100
innodb_spin_wait_delay = 30
#innodb_additional_mem_pool_size = 16M
innodb_buffer_pool_size = 20480M
innodb_buffer_pool_instances = 8
innodb_buffer_pool_load_at_startup = 1
innodb_buffer_pool_dump_at_shutdown = 1
innodb_data_file_path = ibdata1:1G:autoextend
innodb_flush_log_at_trx_commit = 1
innodb_log_buffer_size = 32M
innodb_log_file_size = 2G
innodb_log_files_in_group = 2
innodb_max_undo_log_size = 4G

innodb_io_capacity = 4000
innodb_io_capacity_max = 8000

innodb_write_io_threads = 8
innodb_read_io_threads = 16
innodb_purge_threads = 4
innodb_page_cleaners = 4
innodb_open_files = 65535
innodb_max_dirty_pages_pct = 50
innodb_flush_method = O_DIRECT
innodb_lru_scan_depth = 4000
innodb_checksum_algorithm = crc32
#innodb_file_format = Barracuda
#innodb_file_format_max = Barracuda
innodb_lock_wait_timeout = 10
innodb_rollback_on_timeout = 1
innodb_print_all_deadlocks = 1
innodb_file_per_table = 1
innodb_online_alter_log_max_size = 4G
internal_tmp_disk_storage_engine = InnoDB
innodb_stats_on_metadata = 0

innodb_status_file = 1
# 注意: 开启 innodb_status_output & innodb_status_output_locks 后, 可能会导致log-error文件增长较快
innodb_status_output = 0
innodb_status_output_locks = 0

#performance_schema
#performance_schema = 1
#performance_schema_instrument = '%=on'

#innodb monitor
#innodb_monitor_enable="module_innodb"
#innodb_monitor_enable="module_server"
#innodb_monitor_enable="module_dml"
#innodb_monitor_enable="module_ddl"
#innodb_monitor_enable="module_trx"
#innodb_monitor_enable="module_os"
#innodb_monitor_enable="module_purge"
#innodb_monitor_enable="module_log"
#innodb_monitor_enable="module_lock"
#innodb_monitor_enable="module_buffer"
#innodb_monitor_enable="module_index"
#innodb_monitor_enable="module_ibuf_system"
#innodb_monitor_enable="module_buffer_page"
#innodb_monitor_enable="module_adaptive_hash"

#pxc
wsrep_provider = /usr/local/mysql/lib/libgalera_smm.so
wsrep_cluster_address = gcomm://10.157.24.85,10.157.24.86,10.157.24.87
wsrep_node_name = node85
wsrep_node_address = 10.157.24.85
wsrep_cluster_name = pxc_stage
wsrep_sst_auth = sst:sst123
wsrep_sst_method = xtrabackup-v2
wsrep_slave_threads = 8
pxc_strict_mode = ENFORCING
innodb_autoinc_lock_mode = 2
wsrep_provider_options = "gcache.size=4G"

[mysqldump]
quick
max_allowed_packet = 1024M

node86：

root@dpsvstadbs03 11:50:22:~$ cat /etc/my.cnf
#
##mysql configure file my.cnf
#
[client]
port = 3306
socket = /tmp/mysql.sock
default-character-set = utf8mb4

[mysql]
prompt="\u@\h \R:\m:\s [\d]> "
no-auto-rehash
default-character-set = utf8mb4

[mysqld]
user = mysql
port = 3306
basedir = /usr/local/mysql
datadir = /docker/mysql/mysql_3306/data
socket = /tmp/mysql.sock
pid-file = dpppnewdbs04.sephora.cn.pid
character-set-server = utf8mb4
skip_name_resolve = 1
log_bin_trust_function_creators=1
lower_case_table_names = 1
open_files_limit = 65535
back_log = 1024
server-id = 863306

#binlog
log-bin = /docker/mysql/mysql_3306/logs/binlog/mysql-bin
binlog_format = row
sync_binlog = 1
binlog_cache_size = 512M
expire_logs_days = 7
max_binlog_cache_size = 2G
max_binlog_size = 1G
master_info_repository = TABLE
relay_log_info_repository = TABLE
gtid_mode = on
enforce_gtid_consistency = 1
log_slave_updates

#slow & error log
slow_query_log = 1
slow_query_log_file = /docker/mysql/mysql_3306/logs/slow.log
log-error = /docker/mysql/mysql_3306/logs/error.log
long_query_time = 0.1
#general_log=on
#general_log_file=/docker/mysql/mysql_3306/logs/general_86.log

max_connections = 10000
max_connect_errors = 1000000
table_open_cache = 128
table_definition_cache = 128
table_open_cache_instances = 64
thread_stack = 512K
external-locking = FALSE
max_allowed_packet = 64M
sort_buffer_size = 8M
join_buffer_size = 8M
thread_cache_size = 1500
query_cache_size = 0
query_cache_type = 0
interactive_timeout = 600
wait_timeout = 600
tmp_table_size = 64M
max_heap_table_size = 32M

relay_log_recovery = 1
relay-log-purge = 1
key_buffer_size = 32M
read_buffer_size = 8M
read_rnd_buffer_size = 4M
bulk_insert_buffer_size = 64M
myisam_sort_buffer_size = 128M
myisam_max_sort_file_size = 10G
myisam_repair_threads = 1
lock_wait_timeout = 3600
explicit_defaults_for_timestamp = 1
transaction_isolation = READ-COMMITTED

#innodb
default_storage_engine=Innodb
innodb_thread_concurrency = 0
innodb_sync_spin_loops = 100
innodb_spin_wait_delay = 30
#innodb_additional_mem_pool_size = 16M
innodb_buffer_pool_size = 20480M
innodb_buffer_pool_instances = 8
innodb_buffer_pool_load_at_startup = 1
innodb_buffer_pool_dump_at_shutdown = 1
innodb_data_file_path = ibdata1:1G:autoextend
innodb_flush_log_at_trx_commit = 1
innodb_log_buffer_size = 32M
innodb_log_file_size = 2G
innodb_log_files_in_group = 2
innodb_max_undo_log_size = 4G

innodb_io_capacity = 4000
innodb_io_capacity_max = 8000

innodb_write_io_threads = 8
innodb_read_io_threads = 16
innodb_purge_threads = 4
innodb_page_cleaners = 4
innodb_open_files = 65535
innodb_max_dirty_pages_pct = 50
innodb_flush_method = O_DIRECT
innodb_lru_scan_depth = 4000
innodb_checksum_algorithm = crc32
#innodb_file_format = Barracuda
#innodb_file_format_max = Barracuda
innodb_lock_wait_timeout = 10
innodb_rollback_on_timeout = 1
innodb_print_all_deadlocks = 1
innodb_file_per_table = 1
innodb_online_alter_log_max_size = 4G
internal_tmp_disk_storage_engine = InnoDB
innodb_stats_on_metadata = 0

innodb_status_file = 1
# 注意: 开启 innodb_status_output & innodb_status_output_locks 后, 可能会导致log-error文件增长较快
innodb_status_output = 0
innodb_status_output_locks = 0

#performance_schema
#performance_schema = 1
#performance_schema_instrument = '%=on'

#innodb monitor
#innodb_monitor_enable="module_innodb"
#innodb_monitor_enable="module_server"
#innodb_monitor_enable="module_dml"
#innodb_monitor_enable="module_ddl"
#innodb_monitor_enable="module_trx"
#innodb_monitor_enable="module_os"
#innodb_monitor_enable="module_purge"
#innodb_monitor_enable="module_log"
#innodb_monitor_enable="module_lock"
#innodb_monitor_enable="module_buffer"
#innodb_monitor_enable="module_index"
#innodb_monitor_enable="module_ibuf_system"
#innodb_monitor_enable="module_buffer_page"
#innodb_monitor_enable="module_adaptive_hash"

#pxc
wsrep_provider = /usr/local/mysql/lib/libgalera_smm.so
wsrep_cluster_address = gcomm://10.157.24.85,10.157.24.86,10.157.24.87
wsrep_node_name = node86
wsrep_node_address = 10.157.24.86
wsrep_cluster_name = pxc_stage
wsrep_sst_auth = sst:sst123
wsrep_sst_method = xtrabackup-v2
wsrep_slave_threads = 8
pxc_strict_mode = ENFORCING
innodb_autoinc_lock_mode = 2
wsrep_provider_options = "gcache.size=4G"

[mysqldump]
quick
max_allowed_packet = 1024M

[Krunal Bauskar (krunal-bauskar)]

* Normally an error like that suggest some inconsitency with cluster node.
  This can happen if there is local trx that is not replicated.

* If above is not the case wondering if you can still reproduce it at will and can share the steps for us to investigate it locally.

[Shahriyar Rzayev (rzayev-sehriyar)]

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