Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.4.11
-
OS: CentOS Linux release 7.6.1810 (Core).
Description
When RQG is used with --galera=mms, master node 1 and slave node 2 disconnect from the cluster after HA_ERR_KEY_NOT_FOUND and HA_ERR_FOUND_DUPP_KEY accordingly.
MariaDB Version 10.4.11-MariaDB-debug: Repository: MariaDB/server; branch 10.4; Revision ae72205e31e7665238c1757ede352d9ca53d5327.
Galera lib 26.4.3(r4548) debug: Repository: MariaDB/galera; branch mariadb-4.x; Revision a5431753a3f6bdd348adcbca00e3450ba0ef9045.
RQG: Repository: MariaDB/randgen; master branch; Revision bea5b6b07d08ba6349d8a6ff4356b01678822727.
Run:
perl ./runall-new.pl --grammar=conf/galera/galera_stress.yy --gendata=conf/galera/galera_stress.zz --duration=600 --queries=200M --threads=1 --galera=mms --basedir=/home/stepan/mariadb/10.4/git --vardir=/home/stepan/rqg/github/var "--mysqld=--wsrep-provider=/usr/lib/libgalera_smm_4.so" "--mysqld=--wsrep_sst_method=rsync" "--mysqld=--core" "--mysqld=--general-log" "--mysqld=--general-log-file=queries.log" "--mysqld=--log-output=file" "--mysqld=--wsrep-debug=server" "--mysqld=--wsrep-sync-wait=15" "--mysqld=--wsrep_retry_autocommit=0" "--mysqld=--wsrep_log_conflicts=1" "--mysqld=--wsrep_on=ON"
|
Master node 1
:
2019-11-20 16:22:09 2 [ERROR] mysqld: Can't find record in 'table100_innodb_int'
2019-11-20 16:22:09 2 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table test.table100_innodb_int; Can't find record in 'table100_innodb_int', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 321, Internal MariaDB error code: 1032
2019-11-20 16:22:09 2 [ERROR] WSREP: Failed to apply write set: gtid: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:130 server_id: 09f7e5f7-0ba1-11ea-a944-d7f74653ae06 client_id: 17 trx_id: 1748 flags: 3 (start_transaction | commit)
2019-11-20 16:22:09 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: connected -> disconnected
2019-11-20 16:22:09 2 [Note] WSREP: Server status change connected -> disconnected
2019-11-20 16:22:09 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-11-20 16:22:09 2 [Note] WSREP: assigned new next trx id: 1384
|
2019-11-20 16:22:09 2 [ERROR] mysqld: Can't find record in 'table100_innodb_int'
|
2019-11-20 16:22:09 2 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table test.table100_innodb_int; Can't find record in 'table100_innodb_int', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 321, Internal MariaDB error code: 1032
|
2019-11-20 16:22:09 2 [Note] WSREP: ha_rollback_trans(2, FALSE) rolled back: REPLACE INTO `table100_innodb_int` ( `col_char_12`, `col_char_12_key` ) VALUES ( 'u', 406257664 ), ( 4083875840, 5 ) /* QNO 1280 CON_ID 17 */L՝: Can't find record in 'table100_innodb_int'; is_real 0
|
2019-11-20 16:22:09 2 [Warning] WSREP: Event 3 Update_rows_v1 apply failed: 120, seqno 130
|
2019-11-20 16:22:09 2 [Note] WSREP: ha_rollback_trans(2, TRUE) rolled back: REPLACE INTO `table100_innodb_int` ( `col_char_12`, `col_char_12_key` ) VALUES ( 'u', 406257664 ), ( 4083875840, 5 ) /* QNO 1280 CON_ID 17 */L՝: Can't find record in 'table100_innodb_int'; is_real 1
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_after_apply 2
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:09 2 [Note] WSREP: Log dummy write set 130
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:09 2 [ERROR] WSREP: Failed to apply write set: gtid: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:130 server_id: 09f7e5f7-0ba1-11ea-a944-d7f74653ae06 client_id: 17 trx_id: 1748 flags: 3 (start_transaction | commit)
|
2019-11-20 16:22:09 2 [Note] WSREP: Closing send monitor...
|
2019-11-20 16:22:09 2 [Note] WSREP: Closed send monitor.
|
2019-11-20 16:22:09 2 [Note] WSREP: gcomm: terminating thread
|
2019-11-20 16:22:09 2 [Note] WSREP: gcomm: joining thread
|
2019-11-20 16:22:09 2 [Note] WSREP: gcomm: closing backend
|
2019-11-20 16:22:09 17 [Note] WSREP: assigned new next trx id: 1385
|
2019-11-20 16:22:09 2 [Note] WSREP: view(view_id(NON_PRIM,09f7e5f7,3) memb {
|
0a54a855,0
|
} joined {
|
} left {
|
} partitioned {
|
09f7e5f7,0
|
0d528ca2,0
|
})
|
2019-11-20 16:22:09 2 [Note] WSREP: PC protocol downgrade 1 -> 0
|
2019-11-20 16:22:09 17 [Note] WSREP: wsrep_sync_wait: thd->variables.wsrep_sync_wait= 15, mask= 4, thd->variables.wsrep_on= 1
|
2019-11-20 16:22:09 2 [Note] WSREP: view((empty))
|
2019-11-20 16:22:09 2 [Note] WSREP: gcomm: closed
|
2019-11-20 16:22:09 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
|
2019-11-20 16:22:09 0 [Note] WSREP: Flow-control interval: [16, 16]
|
2019-11-20 16:22:09 0 [Note] WSREP: Received NON-PRIMARY.
|
2019-11-20 16:22:09 0 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 130)
|
2019-11-20 16:22:09 0 [Note] WSREP: New SELF-LEAVE.
|
2019-11-20 16:22:09 0 [Note] WSREP: Flow-control interval: [0, 0]
|
2019-11-20 16:22:09 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
|
2019-11-20 16:22:09 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: -1)
|
2019-11-20 16:22:09 0 [Note] WSREP: RECV thread exiting 0: Success
|
2019-11-20 16:22:09 17 [Warning] WSREP: gcs_caused() returned -103 (Software caused connection abort)
|
2019-11-20 16:22:09 2 [Note] WSREP: recv_thread() joined.
|
2019-11-20 16:22:09 2 [Note] WSREP: Closing replication queue.
|
2019-11-20 16:22:09 2 [Note] WSREP: Closing slave action queue.
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### processing CC -1, local, ordered
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### My UUID: 0a54a855-0ba1-11ea-93a9-d724df0d647a
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### ST not required
|
2019-11-20 16:22:09 2 [Note] WSREP: ================================================
|
View:
|
id: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:-1
|
status: non-primary
|
protocol_version: 4
|
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: no
|
own_index: 0
|
members(1):
|
0: 0a54a855-0ba1-11ea-93a9-d724df0d647a, cnt7glr11.localdomain
|
=================================================
|
2019-11-20 16:22:09 2 [Note] WSREP: Non-primary view
|
2019-11-20 16:22:09 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: synced -> connected
|
2019-11-20 16:22:09 2 [Note] WSREP: Server status change synced -> connected
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### processing CC -1, local, ordered
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### My UUID: 0a54a855-0ba1-11ea-93a9-d724df0d647a
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### ST not required
|
2019-11-20 16:22:09 2 [Note] WSREP: ================================================
|
View:
|
id: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:-1
|
status: non-primary
|
protocol_version: 4
|
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: yes
|
own_index: -1
|
members(0):
|
=================================================
|
2019-11-20 16:22:09 2 [Note] WSREP: Non-primary view
|
2019-11-20 16:22:09 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: connected -> disconnected
|
2019-11-20 16:22:09 2 [Note] WSREP: Server status change connected -> disconnected
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:09 17 [Note] WSREP: wsrep_commit_empty(17)
|
2019-11-20 16:22:09 17 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:09 17 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:09 17 [Note] WSREP: dispatch_command leave
|
thd: 17 thd_ptr: 0x7f4eb0000af0 client_mode: local client_state: result trx_state: aborted
|
next_trx_id: 1385 trx_id: -1 seqno: -1
|
is_streaming: 0 fragments: 0
|
sql_errno: 1205 message: Lock wait timeout exceeded; try restarting transaction
|
command: 40 query: REPLACE INTO `table100_innodb_int` ( `col_char_12`, `col_char_12_key` )
|
2019-11-20 16:22:09 0 [Note] WSREP: Service thread queue flushed.
|
2019-11-20 16:22:09 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: 5
|
2019-11-20 16:22:09 2 [Note] WSREP: Applier thread exiting ret: 0 thd: 2
|
2019-11-20 16:22:09 2 [Note] WSREP: closing applier 2
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep system thread: 2, 0x7f4f34000af0 closing
|
2019-11-20 16:22:09 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
|
2019-11-20 16:22:09 2 [Note] WSREP: wsrep running threads now: 1
|
2019-11-20 16:22:09 2 [Note] WSREP: ha_rollback_trans(2, TRUE) rolled back: (null): Can't find record in 'table100_innodb_int'; is_real 1
|
Slave node 2:
2019-11-20 16:22:16 2 [ERROR] Slave SQL: Could not execute Write_rows_v1 event on table test.table10000_innodb_int; Duplicate entry '0' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 8406, Internal MariaDB error code: 1062
2019-11-20 16:22:16 2 [ERROR] WSREP: Failed to apply write set: gtid: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:147 server_id: 09f7e5f7-0ba1-11ea-a944-d7f74653ae06 client_id: 17 trx_id: 1940 flags: 3 (start_transaction | commit)
2019-11-20 16:22:17 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: connected -> disconnected
2019-11-20 16:22:17 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-11-20 16:22:16 2 [Note] WSREP: assigned new next trx id: 986
|
2019-11-20 16:22:16 2 [ERROR] Slave SQL: Could not execute Write_rows_v1 event on table test.table10000_innodb_int; Duplicate entry '0' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 8406, Internal MariaDB error code: 1062
|
2019-11-20 16:22:16 2 [Note] WSREP: ha_rollback_trans(2, FALSE) rolled back: INSERT IGNORE INTO `table10000_innodb_int` ( `col_int_key`, `col_char_12` ) VALUES ( 'b', 'w' ), ( 5, 'b' ) /* QNO 1682 CON_ID 17 */LÕ]: Duplicate entry '0' for key 'PRIMARY'; is_real 0
|
2019-11-20 16:22:16 2 [Warning] WSREP: Event 64 Write_rows_v1 apply failed: 121, seqno 147
|
2019-11-20 16:22:16 2 [Note] WSREP: ha_rollback_trans(2, TRUE) rolled back: INSERT IGNORE INTO `table10000_innodb_int` ( `col_int_key`, `col_char_12` ) VALUES ( 'b', 'w' ), ( 5, 'b' ) /* QNO 1682 CON_ID 17 */LÕ]: Duplicate entry '0' for key 'PRIMARY'; is_real 1
|
2019-11-20 16:22:16 2 [Note] WSREP: wsrep_after_apply 2
|
2019-11-20 16:22:16 2 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:16 2 [Note] WSREP: Log dummy write set 147
|
2019-11-20 16:22:16 2 [Note] WSREP: wsrep_thd_binlog_reset
|
2019-11-20 16:22:16 2 [ERROR] WSREP: Failed to apply write set: gtid: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:147 server_id: 09f7e5f7-0ba1-11ea-a944-d7f74653ae06 client_id: 17 trx_id: 1940 flags: 3 (start_transaction | commit)
|
2019-11-20 16:22:16 2 [Note] WSREP: Closing send monitor...
|
2019-11-20 16:22:16 2 [Note] WSREP: Closed send monitor.
|
2019-11-20 16:22:16 2 [Note] WSREP: gcomm: terminating thread
|
2019-11-20 16:22:16 2 [Note] WSREP: gcomm: joining thread
|
2019-11-20 16:22:16 2 [Note] WSREP: gcomm: closing backend
|
2019-11-20 16:22:17 2 [Note] WSREP: view(view_id(NON_PRIM,09f7e5f7,4) memb {
|
0d528ca2,0
|
} joined {
|
} left {
|
} partitioned {
|
09f7e5f7,0
|
})
|
2019-11-20 16:22:17 2 [Note] WSREP: PC protocol downgrade 1 -> 0
|
2019-11-20 16:22:17 2 [Note] WSREP: view((empty))
|
2019-11-20 16:22:17 2 [Note] WSREP: gcomm: closed
|
2019-11-20 16:22:17 0 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
|
2019-11-20 16:22:17 0 [Note] WSREP: Flow-control interval: [16, 16]
|
2019-11-20 16:22:17 0 [Note] WSREP: Received NON-PRIMARY.
|
2019-11-20 16:22:17 0 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 147)
|
2019-11-20 16:22:17 0 [Note] WSREP: New SELF-LEAVE.
|
2019-11-20 16:22:17 0 [Note] WSREP: Flow-control interval: [0, 0]
|
2019-11-20 16:22:17 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
|
2019-11-20 16:22:17 0 [Note] WSREP: Shifting OPEN -> CLOSED (TO: -1)
|
2019-11-20 16:22:17 0 [Note] WSREP: RECV thread exiting 0: Success
|
2019-11-20 16:22:17 2 [Note] WSREP: recv_thread() joined.
|
2019-11-20 16:22:17 2 [Note] WSREP: Closing replication queue.
|
2019-11-20 16:22:17 2 [Note] WSREP: Closing slave action queue.
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### processing CC -1, local, ordered
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### My UUID: 0d528ca2-0ba1-11ea-a7e1-5a09a105dcfd
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### ST not required
|
2019-11-20 16:22:17 2 [Note] WSREP: ================================================
|
View:
|
id: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:-1
|
status: non-primary
|
protocol_version: 4
|
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: no
|
own_index: 0
|
members(1):
|
0: 0d528ca2-0ba1-11ea-a7e1-5a09a105dcfd, cnt7glr11.localdomain
|
=================================================
|
2019-11-20 16:22:17 2 [Note] WSREP: Non-primary view
|
2019-11-20 16:22:17 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: synced -> connected
|
2019-11-20 16:22:17 2 [Note] WSREP: Server status change synced -> connected
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### processing CC -1, local, ordered
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### My UUID: 0d528ca2-0ba1-11ea-a7e1-5a09a105dcfd
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### ST not required
|
2019-11-20 16:22:17 2 [Note] WSREP: ================================================
|
View:
|
id: 09f8e15a-0ba1-11ea-bed3-56e4b108bea5:-1
|
status: non-primary
|
protocol_version: 4
|
capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO
|
final: yes
|
own_index: -1
|
members(0):
|
=================================================
|
2019-11-20 16:22:17 2 [Note] WSREP: Non-primary view
|
2019-11-20 16:22:17 2 [Note] [Debug] WSREP: server cnt7glr11.localdomain state change: connected -> disconnected
|
2019-11-20 16:22:17 2 [Note] WSREP: Server status change connected -> disconnected
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2019-11-20 16:22:17 0 [Note] WSREP: Service thread queue flushed.
|
2019-11-20 16:22:17 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: 5
|
2019-11-20 16:22:17 2 [Note] WSREP: Applier thread exiting ret: 0 thd: 2
|
2019-11-20 16:22:17 2 [Note] WSREP: closing applier 2
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep system thread: 2, 0x7f36d4000af0 closing
|
2019-11-20 16:22:17 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
|
2019-11-20 16:22:17 2 [Note] WSREP: wsrep running threads now: 1
|
2019-11-20 16:22:17 2 [Note] WSREP: ha_rollback_trans(2, TRUE) rolled back: (null): Duplicate entry '0' for key 'PRIMARY'; is_real 1
|
2019-11-20 16:32:02 13 [Note] WSREP: assigned new next trx id: 987
|
2019-11-20 16:32:02 13 [Note] WSREP: assigned new next trx id: 987
|
2019-11-20 16:32:02 0 [Note] /home/stepan/mariadb/10.4/git/sql/mysqld (initiated by: [stepan] @ localhost [127.0.0.1]): Normal shutdown
|
2019-11-20 16:32:02 0 [Note] WSREP: Shutdown replication
|
# 2019-11-20T16:31:58 [14601] No differences were found between servers 0 and 1.
|
# 2019-11-20T16:31:58 [14601] No differences were found between servers 1 and 2.
|
[...]
|
# 2019-11-20T16:32:04 [14601] [14601] ./runall-new.pl will exit with exit status STATUS_OK (0)
|