[MDEV-18935] Galera test mysql-wsrep#198 sporaric assertion transaction.cpp:362: int wsrep::transaction::before_commit(): Assertion `state() == s_executing || state() == s_committing || state() == s_must_abort || state() == s_replaying' failed. Created: 2019-03-15  Updated: 2021-02-18  Resolved: 2020-08-04

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Affects Version/s: 10.4
Fix Version/s: 10.4.14, 10.5.5

Type: Bug Priority: Major
Reporter: Jan Lindström (Inactive) Assignee: Stepan Patryshev (Inactive)
Resolution: Fixed Votes: 2
Labels: None

Issue Links:
PartOf
Relates
relates to MDEV-22222 Assertion `state() == s_executing || ... Closed
relates to MDEV-22223 Server crashes in gu::Mutex::lock / g... Closed
relates to MDEV-23025 int wsrep::transaction::before_rollba... Closed
relates to MDEV-22897 mariadb server crashed on 2 instances... Closed
relates to MDEV-24912 Assertion `state() == s_executing || ... Closed

 Description   

galera.mysql-wsrep#198 'innodb'          w3 [ fail ]
        Test ended at 2019-03-13 21:45:44
 
CURRENT_TEST: galera.mysql-wsrep#198
mysqltest: At line 27: query 'INSERT INTO t2 VALUES (1)' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
connection node_2;
connection node_1;
CREATE TABLE t1 (id INT PRIMARY KEY) ENGINE=InnoDB;
CREATE TABLE t2 (id INT PRIMARY KEY) ENGINE=InnoDB;
connection node_2;
SELECT 1 FROM DUAL;
1
1
LOCK TABLE t2 WRITE;
connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2;
connection node_2a;
OPTIMIZE TABLE t1,t2;;
connect node_2b, 127.0.0.1, root, , test, $NODE_MYPORT_2;
connection node_2b;
REPAIR TABLE t1,t2;;
connection node_2;
SET SESSION wsrep_sync_wait = 0;
connection node_1;
INSERT INTO t2 VALUES (1);
 
 
Server [mysqld.1 - pid: 24356, winpid: 24356, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2019-03-13 21:45:32 0 [Warning] WSREP: option --wsrep-causal-reads is deprecated
2019-03-13 21:45:32 0 [Note] /usr/sbin/mysqld (mysqld 10.4.4-MariaDB-log) starting as process 24357 ...
2019-03-13 21:45:32 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4186)
2019-03-13 21:45:32 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2019-03-13 21:45:32 0 [Warning] WSREP: wsrep_sst_receive_address is set to '127.0.0.1:16044' which makes it impossible for another host to reach this one. Please set it to the address which this node can be connected at by other cluster members.
2019-03-13 21:45:32 0 [Note] WSREP: Loading provider /usr/lib64/galera-4/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
wsrep loader: [INFO] wsrep_load(): loading provider library '/usr/lib64/galera-4/libgalera_smm.so'
wsrep loader: [INFO] wsrep_load(): Galera 26.4.1(r4486) by Codership Oy <info@codership.com> loaded successfully.
2019-03-13 21:45:32 0 [Note] WSREP: CRC-32C: using "slicing-by-8" algorithm.
2019-03-13 21:45:32 0 [Warning] WSREP: Could not open state file for reading: '/dev/shm/var/3/mysqld.1/data//grastate.dat'
2019-03-13 21:45:32 0 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1
2019-03-13 21:45:32 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 0
UUID: 00000000-0000-0000-0000-000000000000
Seqno: -1 - -1
Offset: -1
Synced: 0
2019-03-13 21:45:32 0 [Note] WSREP: Skipped GCache ring buffer recovery: could not determine history UUID.
2019-03-13 21:45:32 0 [Note] WSREP: Passing config to GCS: base_dir = /dev/shm/var/3/mysqld.1/data/; base_host = 127.0.0.1; base_port = 16042; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT30S; evs.install_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT10S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /dev/shm/var/3/mysqld.1/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /dev/shm/var/3/mysqld.1/data//galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 10M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = n
2019-03-13 21:45:32 0 [Note] WSREP: GCache history reset: old(00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1
2019-03-13 21:45:32 0 [Note] WSREP: Start replication
2019-03-13 21:45:32 0 [Note] WSREP: Connecting with bootstrap option: 1
2019-03-13 21:45:32 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
2019-03-13 21:45:32 0 [Note] WSREP: protonet asio version 0
2019-03-13 21:45:32 0 [Note] WSREP: Using CRC-32C for message checksums.
2019-03-13 21:45:32 0 [Note] WSREP: backend: asio
2019-03-13 21:45:32 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2019-03-13 21:45:32 0 [Warning] WSREP: access file(/dev/shm/var/3/mysqld.1/data//gvwstate.dat) failed(No such file or directory)
2019-03-13 21:45:32 0 [Note] WSREP: restore pc from disk failed
2019-03-13 21:45:32 0 [Note] WSREP: GMCast version 0
2019-03-13 21:45:32 0 [Note] WSREP: (53a44f18, 'tcp://0.0.0.0:16042') listening at tcp://0.0.0.0:16042
2019-03-13 21:45:32 0 [Note] WSREP: (53a44f18, 'tcp://0.0.0.0:16042') multicast: , ttl: 1
2019-03-13 21:45:32 0 [Note] WSREP: EVS version 1
2019-03-13 21:45:32 0 [Note] WSREP: gcomm: bootstrapping new group 'my_wsrep_cluster'
2019-03-13 21:45:32 0 [Note] WSREP: start_prim is enabled, turn off pc_recovery
2019-03-13 21:45:32 0 [Note] WSREP: EVS version upgrade 0 -> 1
2019-03-13 21:45:32 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2019-03-13 21:45:32 0 [Note] WSREP: Node 53a44f18 state prim
2019-03-13 21:45:32 0 [Note] WSREP: view(view_id(PRIM,53a44f18,1) memb {
	53a44f18,0
} joined {
} left {
} partitioned {
})
2019-03-13 21:45:32 0 [Note] WSREP: save pc into disk
2019-03-13 21:45:32 0 [Note] WSREP: gcomm: connected
2019-03-13 21:45:32 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2019-03-13 21:45:32 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2019-03-13 21:45:32 0 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2019-03-13 21:45:32 1 [Note] WSREP: Starting applier thread 1
2019-03-13 21:45:32 2 [Note] WSREP: Starting post rollbacker thread 2
2019-03-13 21:45:32 3 [Note] WSREP: Starting rollbacker thread 3
2019-03-13 21:45:32 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2019-03-13 21:45:32 0 [Note] WSREP: Starting new group from scratch: 53a78195-45d9-11e9-a1a9-02fff903d77c
2019-03-13 21:45:32 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 53a783ab-45d9-11e9-9c37-f7bf90d912d3
2019-03-13 21:45:32 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 53a783ab-45d9-11e9-9c37-f7bf90d912d3
2019-03-13 21:45:32 0 [Note] WSREP: STATE EXCHANGE: got state msg: 53a783ab-45d9-11e9-9c37-f7bf90d912d3 from 0 (centos74-amd64)
2019-03-13 21:45:32 0 [Note] WSREP: Quorum results:
	version    = 5,
	component  = PRIMARY,
	conf_id    = 0,
	members    = 1/1 (joined/total),
	act_id     = 0,
	last_appl. = -1,
	protocols  = 1/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = 53a78195-45d9-11e9-a1a9-02fff903d77c
2019-03-13 21:45:32 0 [Note] WSREP: Writing down CC checksum: dee2a2e1 09de7123 33260028 0ddef2ea at offset 136
2019-03-13 21:45:32 0 [Note] WSREP: Flow-control interval: [16, 16]
2019-03-13 21:45:32 0 [Note] WSREP: Trying to continue unpaused monitor
2019-03-13 21:45:32 0 [Note] WSREP: Restored state OPEN -> JOINED (1)
2019-03-13 21:45:32 0 [Note] WSREP: Member 0.0 (centos74-amd64) synced with group.
2019-03-13 21:45:32 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 1)
2019-03-13 21:45:32 1 [Note] WSREP: ####### processing CC 1, local, ordered
2019-03-13 21:45:32 1 [Note] WSREP: ####### drain monitors upto -1
2019-03-13 21:45:32 1 [Note] WSREP: REPL Protocols: 10 (5, 3)
2019-03-13 21:45:32 1 [Note] WSREP: ####### My UUID: 53a44f18-45d9-11e9-9faa-ce41c86c9104
2019-03-13 21:45:32 1 [Note] WSREP: Server centos74-amd64 connected to cluster at position 53a78195-45d9-11e9-a1a9-02fff903d77c:1 with ID 53a44f18-45d9-11e9-9faa-ce41c86c9104
2019-03-13 21:45:32 1 [Note] WSREP: Server status change disconnected -> connected
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 1 [Note] WSREP: ####### ST not required
2019-03-13 21:45:32 1 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:0 (proto: 10), state transfer needed: no
2019-03-13 21:45:32 0 [Note] WSREP: Service thread queue flushed.
2019-03-13 21:45:32 1 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:0, protocol version: 5
2019-03-13 21:45:32 1 [Note] WSREP: ####### Adjusting cert position: 0 -> 1
2019-03-13 21:45:32 0 [Note] WSREP: Service thread queue flushed.
2019-03-13 21:45:32 1 [Note] WSREP: ####### Setting monitor position to 1
2019-03-13 21:45:32 1 [Note] WSREP: Lowest cert indnex boundary for CC from group: 1
2019-03-13 21:45:32 1 [Note] WSREP: Min available from gcache for CC from group: 1
2019-03-13 21:45:32 1 [Note] WSREP: ================================================
View:
  id: 53a78195-45d9-11e9-a1a9-02fff903d77c:1
  status: 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: 53a44f18-45d9-11e9-9faa-ce41c86c9104, centos74-amd64
=================================================
2019-03-13 21:45:32 1 [Note] WSREP: Server status change connected -> joiner
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 1 [Note] WSREP: Server status change joiner -> initializing
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 0 [Note] Plugin 'SEQUENCE' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'partition' is disabled.
2019-03-13 21:45:32 0 [Note] InnoDB: Using Linux native AIO
2019-03-13 21:45:32 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-13 21:45:32 0 [Note] InnoDB: Uses event mutexes
2019-03-13 21:45:32 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2019-03-13 21:45:32 0 [Note] InnoDB: Number of pools: 1
2019-03-13 21:45:32 0 [Note] InnoDB: Using generic crc32 instructions
2019-03-13 21:45:32 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2019-03-13 21:45:32 0 [Note] InnoDB: Completed initialization of buffer pool
2019-03-13 21:45:32 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-03-13 21:45:32 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-03-13 21:45:32 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-03-13 21:45:32 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-03-13 21:45:32 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-03-13 21:45:32 0 [Note] InnoDB: Waiting for purge to start
2019-03-13 21:45:32 0 [Note] InnoDB: 10.4.4 started; log sequence number 151233; transaction id 34
2019-03-13 21:45:32 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var/3/mysqld.1/data/ib_buffer_pool
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_CMP' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2019-03-13 21:45:32 0 [Note] InnoDB: Buffer pool(s) load completed at 190313 21:45:32
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'user_variables' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2019-03-13 21:45:32 0 [Note] Plugin 'unix_socket' is disabled.
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-pam-debug'
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown option '--loose-aria'
2019-03-13 21:45:32 0 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2019-03-13 21:45:32 0 [Note] Server socket created on IP: '127.0.0.1'.
2019-03-13 21:45:32 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)
2019-03-13 21:45:32 0 [Note] WSREP: Server initialized
2019-03-13 21:45:32 0 [Note] WSREP: Server status change initializing -> initialized
2019-03-13 21:45:32 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 1 [Note] WSREP: Bootstrapping a new cluster, setting initial position to 00000000-0000-0000-0000-000000000000:-1
2019-03-13 21:45:32 11 [Note] WSREP: Cluster table is empty, not recovering transactions
2019-03-13 21:45:32 1 [Note] WSREP: Server status change initialized -> joined
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 1 [Note] WSREP: Server centos74-amd64 synced with group
2019-03-13 21:45:32 1 [Note] WSREP: Server status change joined -> synced
2019-03-13 21:45:32 1 [Note] WSREP: Synchronized with group, ready for connections
2019-03-13 21:45:32 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:32 0 [Note] Reading of all Master_info entries succeded
2019-03-13 21:45:32 0 [Note] Added new Master_info '' to hash table
2019-03-13 21:45:32 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.4.4-MariaDB-log'  socket: '/dev/shm/var/tmp/3/mysqld.1.sock'  port: 16040  MariaDB Server
2019-03-13 21:45:33 0 [Note] WSREP: (53a44f18, 'tcp://0.0.0.0:16042') connection established to 54201532 tcp://127.0.0.1:16045
2019-03-13 21:45:33 0 [Note] WSREP: (53a44f18, 'tcp://0.0.0.0:16042') turning message relay requesting on, nonlive peers: 
2019-03-13 21:45:33 0 [Note] WSREP: declaring 54201532 at tcp://127.0.0.1:16045 stable
2019-03-13 21:45:33 0 [Note] WSREP: Node 53a44f18 state prim
2019-03-13 21:45:33 0 [Note] WSREP: view(view_id(PRIM,53a44f18,2) memb {
	53a44f18,0
	54201532,0
} joined {
} left {
} partitioned {
})
2019-03-13 21:45:33 0 [Note] WSREP: save pc into disk
2019-03-13 21:45:33 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
2019-03-13 21:45:33 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 54710f54-45d9-11e9-81c1-62cb9f54250d
2019-03-13 21:45:33 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 54710f54-45d9-11e9-81c1-62cb9f54250d
2019-03-13 21:45:33 0 [Note] WSREP: STATE EXCHANGE: got state msg: 54710f54-45d9-11e9-81c1-62cb9f54250d from 0 (centos74-amd64)
2019-03-13 21:45:34 0 [Note] WSREP: STATE EXCHANGE: got state msg: 54710f54-45d9-11e9-81c1-62cb9f54250d from 1 (centos74-amd64)
2019-03-13 21:45:34 0 [Note] WSREP: Quorum results:
	version    = 5,
	component  = PRIMARY,
	conf_id    = 1,
	members    = 1/2 (joined/total),
	act_id     = 1,
	last_appl. = 0,
	protocols  = 1/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = 53a78195-45d9-11e9-a1a9-02fff903d77c
2019-03-13 21:45:34 0 [Note] WSREP: Writing down CC checksum: 4b75accd 1eda8527 52e02089 111c7757 at offset 216
2019-03-13 21:45:34 0 [Note] WSREP: Flow-control interval: [23, 23]
2019-03-13 21:45:34 0 [Note] WSREP: Trying to continue unpaused monitor
2019-03-13 21:45:34 1 [Note] WSREP: ####### processing CC 2, local, ordered
2019-03-13 21:45:34 1 [Note] WSREP: ####### drain monitors upto 1
2019-03-13 21:45:34 1 [Note] WSREP: REPL Protocols: 10 (5, 3)
2019-03-13 21:45:34 1 [Note] WSREP: ####### My UUID: 53a44f18-45d9-11e9-9faa-ce41c86c9104
2019-03-13 21:45:34 1 [Note] WSREP: ####### ST not required
2019-03-13 21:45:34 1 [Note] WSREP: Skipping cert index reset
2019-03-13 21:45:34 1 [Note] WSREP: ####### Adjusting cert position: 1 -> 2
2019-03-13 21:45:34 0 [Note] WSREP: Service thread queue flushed.
2019-03-13 21:45:34 1 [Note] WSREP: ####### Setting monitor position to 2
2019-03-13 21:45:34 1 [Note] WSREP: Lowest cert indnex boundary for CC from group: 2
2019-03-13 21:45:34 1 [Note] WSREP: Min available from gcache for CC from group: 1
2019-03-13 21:45:34 1 [Note] WSREP: ================================================
View:
  id: 53a78195-45d9-11e9-a1a9-02fff903d77c:2
  status: 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(2):
	0: 53a44f18-45d9-11e9-9faa-ce41c86c9104, centos74-amd64
	1: 54201532-45d9-11e9-b456-ffbb826d5fc4, centos74-amd64
=================================================
2019-03-13 21:45:34 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:34 0 [Note] WSREP: Member 1.0 (centos74-amd64) requested state transfer from '*any*'. Selected 0.0 (centos74-amd64)(SYNCED) as donor.
2019-03-13 21:45:34 0 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 2)
2019-03-13 21:45:34 1 [Note] WSREP: Detected STR version: 1, req_len: 110, req: STRv1
2019-03-13 21:45:34 1 [Note] WSREP: Cert index preload: 2 -> 2
2019-03-13 21:45:34 1 [Note] WSREP: Server status change synced -> donor
2019-03-13 21:45:34 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:34 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:34 0 [Note] WSREP: async IST sender starting to serve tcp://127.0.0.1:16046 sending 2-2
2019-03-13 21:45:34 0 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'donor' --address '127.0.0.2:16047/rsync_sst' --socket '/dev/shm/var/tmp/3/mysqld.1.sock' --datadir '/dev/shm/var/3/mysqld.1/data/'  --defaults-file '/dev/shm/var/3/my.cnf' --defaults-group-suffix '.1'   --binlog 'mysqld-bin'  --binlog-index 'mysqld-bin.index' --gtid '53a78195-45d9-11e9-a1a9-02fff903d77c:2' --gtid-domain-id '0''
2019-03-13 21:45:35 1 [Note] WSREP: sst_donor_thread signaled with 0
2019-03-13 21:45:35 0 [Note] WSREP: IST sender 2 -> 2
2019-03-13 21:45:35 0 [Note] WSREP: Flushing tables for SST...
2019-03-13 21:45:35 0 [Note] WSREP: pause
2019-03-13 21:45:35 0 [Note] WSREP: Provider paused at 53a78195-45d9-11e9-a1a9-02fff903d77c:2 (5)
2019-03-13 21:45:35 0 [Note] WSREP: Server paused at: 2
2019-03-13 21:45:35 0 [Note] WSREP: Tables flushed.
WSREP_SST: [INFO] Preparing binlog files for transfer: (20190313 21:45:35.640)
mysqld-bin.000002
2019-03-13 21:45:36 0 [Note] WSREP: (53a44f18, 'tcp://0.0.0.0:16042') turning message relay requesting off
2019-03-13 21:45:36 0 [Note] WSREP: resume
2019-03-13 21:45:36 0 [Note] WSREP: resuming provider at 5
2019-03-13 21:45:36 0 [Note] WSREP: Provider resumed.
2019-03-13 21:45:36 0 [Note] WSREP: SST sent: 53a78195-45d9-11e9-a1a9-02fff903d77c:2
2019-03-13 21:45:36 0 [Note] WSREP: Server status change donor -> joined
2019-03-13 21:45:36 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:36 0 [Note] WSREP: 0.0 (centos74-amd64): State transfer to 1.0 (centos74-amd64) complete.
2019-03-13 21:45:36 0 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 2)
2019-03-13 21:45:36 0 [Note] WSREP: Member 0.0 (centos74-amd64) synced with group.
2019-03-13 21:45:36 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 2)
2019-03-13 21:45:36 1 [Note] WSREP: Server centos74-amd64 synced with group
2019-03-13 21:45:36 1 [Note] WSREP: Server status change joined -> synced
2019-03-13 21:45:36 1 [Note] WSREP: Synchronized with group, ready for connections
2019-03-13 21:45:36 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-03-13 21:45:38 0 [Note] WSREP: async IST sender served
2019-03-13 21:45:38 0 [Note] WSREP: 1.0 (centos74-amd64): State transfer from 0.0 (centos74-amd64) complete.
2019-03-13 21:45:38 0 [Note] WSREP: Member 1.0 (centos74-amd64) synced with group.
mysqld: /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.4.4/wsrep-lib/src/transaction.cpp:362: int wsrep::transaction::before_commit(): Assertion `state() == s_executing || state() == s_committing || state() == s_must_abort || state() == s_replaying' failed.
190313 21:45:41 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.4.4-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=153
thread_count=12
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63458 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x55764d6ea008
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7f3ebbf81c40 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55764252f0fe]
/usr/sbin/mysqld(handle_fatal_signal+0x357)[0x557641fc8b87]
sigaction.c:0(__restore_rt)[0x7f3ec47025e0]
:0(__GI_raise)[0x7f3ec2a031f7]
:0(__GI_abort)[0x7f3ec2a048e8]
:0(__assert_fail_base)[0x7f3ec29fc266]
:0(__GI___assert_fail)[0x7f3ec29fc312]
/usr/sbin/mysqld(_ZN5wsrep11transaction13before_commitEv+0x44b)[0x5576425c4d7b]
/usr/sbin/mysqld(_Z15ha_commit_transP3THDb+0xbce)[0x557641fd812e]
src/transaction.cpp:425(wsrep::transaction::before_commit())[0x557641eb84ff]
sql/wsrep_trans_observer.h:263(ha_commit_trans(THD*, bool))[0x557641dc28b2]
sql/transaction.cc:514(trans_commit_stmt(THD*))[0x557641dcb4bb]
sql/sql_class.h:3928(THD::get_stmt_da())[0x557641dcbd77]
sql/sql_parse.cc:1813(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x557641dcf04b]
sql/sql_parse.cc:1358(do_command(THD*))[0x557641dcf7fc]
sql/sql_connect.cc:1399(do_handle_one_connection(CONNECT*))[0x557641ea978a]
sql/sql_connect.cc:1304(handle_one_connection)[0x557641ea98ed]
perfschema/pfs.cc:1865(pfs_spawn_thread)[0x5576421814dd]
pthread_create.c:0(start_thread)[0x7f3ec46fae25]
/lib64/libc.so.6(clone+0x6d)[0x7f3ec2ac634d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x55764d6f0820): INSERT INTO t2 VALUES (1)
Connection ID (thread ID): 18
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file at /dev/shm/var/3/mysqld.1/data/



 Comments   
Comment by Teemu Ollakka [ 2019-03-15 ]

Could not reproduce this locally. Would it be possible to get binaries and core dump from this?

Comment by Jan Lindström (Inactive) [ 2019-03-15 ]

Known recent failures:

Comment by Jan Lindström (Inactive) [ 2020-07-29 ]

Failed to find any failure on buildbot or in ES.

Comment by Roel Van de Paar [ 2020-07-31 ]

I also tried to reproduce this at length on CS 10.5.3 I had handy, no success.

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f (Optimized)

$ WSREP_PROVIDER='${LIBGAL}/lib/libgalera_smm.so' ./mysql-test-run --repeat=700 galera.mysql-wsrep#198 
...
galera.mysql-wsrep#198 'innodb'          [ pass ]   2186
galera.mysql-wsrep#198 'innodb'          [ 2 pass ]   2183
...
galera.mysql-wsrep#198 'innodb'          [ 699 pass ]   2188
galera.mysql-wsrep#198 'innodb'          [ 700 pass ]   2187

Comment by Roel Van de Paar [ 2020-07-31 ]

ES 10.4.13 test also yields no results.

10.4.13-7 8ff65be433c1a896219da2afa06793c73741a723 (Optimized)

$ WSREP_PROVIDER='/test/GAL_EMD310720-mariadb-10.4.13-7-linux-x86_64-opt/lib/libgalera_enterprise_smm.so' ./mysql-test-run --repeat=1113 galera.mysql-wsrep#198
...
galera.mysql-wsrep#198 'innodb'          [ pass ]   2224
galera.mysql-wsrep#198 'innodb'          [ 2 pass ]   2223
...
galera.mysql-wsrep#198 'innodb'          [ 1112 pass ]   2168
galera.mysql-wsrep#198 'innodb'          [ 1113 pass ]   2172

Comment by Roel Van de Paar [ 2020-07-31 ]
  • Lowered prio to Major as issue is either highly sporadic, or specific to certain machines/OS'es
  • Note that the crash is in wsrep-lib/src/transaction.cpp on line 632, so it looks like it specifically revolves around the 'state() == s_replaying' part of the assert, corresponding to the 'state() == s_must_replay' code on that line. Perhaps this helps developers to find the cause? Or, it could be that the assert lists the last line of the command, which is 632. Not sure.
  • Propose to re-enable the MTR testcases (can we enable core file dumps?) and when it re-occurs to analyze any dump given and what OS and hardware this was
Comment by Roel Van de Paar [ 2020-08-04 ]

stepan.patryshev can you please re-enable `galera.mysql-wsrep#198` ? Thanks

Comment by Jan Lindström (Inactive) [ 2020-08-04 ]

I expect this issue is also fixed on

commit 2b8b7394a129ab27225a1284bab253a6714aaf03
Author: mkaruza <mario.karuza@galeracluster.com>
Date: Sun Jun 28 23:03:38 2020 +0200

MDEV-22222: Assertion `state() == s_executing || state() == s_preparing || state() == s_prepared || state() == s_must_abort || state() == s_aborting || state() == s_cert_failed || state() == s_must_replay' failed in wsrep::transaction::before_rollback

LOCK TABLE will do implicit commit, we need to properly handle transaction after commit.

Comment by Roel Van de Paar [ 2020-08-04 ]

Thank you stepan.patryshev and jplindst

Comment by Stepan Patryshev (Inactive) [ 2020-09-10 ]

It's enabled on 10.5 ES now.

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