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

Bug #1722442 reported by sampson,li on 2017-10-10
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
New
Undecided
Unassigned

Bug Description

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

sampson,li (sampsonli) on 2017-10-10
Changed in percona-xtradb-cluster:
status: New → Incomplete
status: Incomplete → New
assignee: nobody → sampson,li (sampsonli)
assignee: sampson,li (sampsonli) → nobody
Krunal Bauskar (krunal-bauskar) wrote :

* 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.

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers