[MDEV-20866] Hang on shutdown Created: 2019-10-20  Updated: 2021-12-23  Resolved: 2021-12-23

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.4.8
Fix Version/s: 10.4.22

Type: Bug Priority: Major
Reporter: Bai Yang Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Environment:

Ubuntu 18.04 / x64



 Description   

`systemctl stop mariadb` hang until `kill -9`.

Reproduce step:

1. Start up the first (and only) node by `galera_new_cluster`.
2. Connect to the server with mysql client, and run some simple queries like `SHOW STATUS LIKE 'wsrep_%';`
3. Shutdown mariadb using `systemctl stop mariadb`.

Mysqld version string

root@DB-0:~# mysqld --version
mysqld  Ver 10.4.8-MariaDB-1:10.4.8+maria~bionic for debian-linux-gnu on x86_64 (mariadb.org binary distribution)
Segmentation fault (core dumped)

The syslog:

Oct 20 09:38:51 DB-0 systemd[1]: Stopping MariaDB 10.4.8 database server...
Oct 20 09:39:21 DB-0 systemd[1]: mariadb.service: Stopping timed out. Terminating.
Oct 20 09:39:21 DB-0 mysqld[6222]: Warning;  Aborted waiting on pid file: '/var/run/mysqld/mysqld.pid' after 30 seconds
Oct 20 09:39:21 DB-0 systemd[1]: mariadb.service: Control process exited, code=exited status=255
Oct 20 09:39:51 DB-0 systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Killing.
Oct 20 09:39:51 DB-0 systemd[1]: mariadb.service: Killing process 6117 (mysqld) with signal SIGKILL.
Oct 20 09:39:51 DB-0 systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
Oct 20 09:39:51 DB-0 systemd[1]: mariadb.service: Failed with result 'timeout'.
Oct 20 09:39:51 DB-0 systemd[1]: Stopped MariaDB 10.4.8 database server.

The mysql error log:

2019-10-20  9:37:48 0 [Note] WSREP: Server initial position: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:438
2019-10-20  9:37:48 0 [Note] WSREP: Loading provider /usr/lib/libgalera_smm.so initial position: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:438
wsrep loader: [INFO] wsrep_load(): loading provider library '/usr/lib/libgalera_smm.so'
wsrep loader: [INFO] wsrep_load(): Galera 26.4.2(r4498) by Codership Oy <info@codership.com> loaded successfully.
2019-10-20  9:37:48 0 [Note] WSREP: CRC-32C: using hardware acceleration.
2019-10-20  9:37:48 0 [Note] WSREP: Found saved state: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:438, safe_to_bootstrap: 1
2019-10-20  9:37:48 0 [Note] WSREP: GCache DEBUG: opened preamble:
Version: 2
UUID: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2
Seqno: -1 - -1
Offset: -1
Synced: 0
2019-10-20  9:37:48 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2, offset: -1
2019-10-20  9:37:48 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (       0/16777240 bytes) complete.
2019-10-20  9:37:48 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (16777240/16777240 bytes) complete.
2019-10-20  9:37:48 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 2-438
2019-10-20  9:37:48 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (     0/112808 bytes) complete.
2019-10-20  9:37:48 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (112808/112808 bytes) complete.
2019-10-20  9:37:48 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 157/594 locked buffers
2019-10-20  9:37:48 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 112808/16777216
2019-10-20  9:37:48 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 192.168.143.200; base_port = 4567; 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 = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 128; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 128; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 16M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 0.99; gcs.fc_limit = 256; 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 = no; gmcast.listen_addr = tcp://192.168.143.200:4567; gmcast.peer_timeout = PT2
2019-10-20  9:37:48 0 [Note] WSREP: SR storage init for: table
2019-10-20  9:37:48 0 [Note] WSREP: wsrep_start_replication
2019-10-20  9:37:48 0 [Note] WSREP: Start replication
2019-10-20  9:37:48 0 [Note] WSREP: Connecting with bootstrap option: 1
2019-10-20  9:37:48 0 [Note] WSREP: Setting GCS initial position to d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:438
2019-10-20  9:37:48 0 [Note] WSREP: protonet asio version 0
2019-10-20  9:37:48 0 [Note] WSREP: Using CRC-32C for message checksums.
2019-10-20  9:37:48 0 [Note] WSREP: backend: asio
2019-10-20  9:37:48 0 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2019-10-20  9:37:48 0 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
2019-10-20  9:37:48 0 [Note] WSREP: restore pc from disk failed
2019-10-20  9:37:48 0 [Note] WSREP: GMCast version 0
2019-10-20  9:37:48 0 [Note] WSREP: (3951e78b, 'tcp://192.168.143.200:4567') listening at tcp://192.168.143.200:4567
2019-10-20  9:37:48 0 [Note] WSREP: (3951e78b, 'tcp://192.168.143.200:4567') multicast: , ttl: 1
2019-10-20  9:37:48 0 [Note] WSREP: EVS version 1
2019-10-20  9:37:48 0 [Note] WSREP: gcomm: bootstrapping new group 'MYAPP-GC-001'
2019-10-20  9:37:48 0 [Note] WSREP: start_prim is enabled, turn off pc_recovery
2019-10-20  9:37:48 0 [Note] WSREP: EVS version upgrade 0 -> 1
2019-10-20  9:37:48 0 [Note] WSREP: PC protocol upgrade 0 -> 1
2019-10-20  9:37:48 0 [Note] WSREP: Node 3951e78b state prim
2019-10-20  9:37:48 0 [Note] WSREP: view(view_id(PRIM,3951e78b,1) memb {
	3951e78b,0
} joined {
} left {
} partitioned {
})
2019-10-20  9:37:48 0 [Note] WSREP: save pc into disk
2019-10-20  9:37:49 0 [Note] WSREP: discarding pending addr without UUID: tcp://192.168.143.201:4567
2019-10-20  9:37:49 0 [Note] WSREP: discarding pending addr proto entry 0x5566f439ae90
2019-10-20  9:37:49 0 [Note] WSREP: gcomm: connected
2019-10-20  9:37:49 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2019-10-20  9:37:49 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2019-10-20  9:37:49 0 [Note] WSREP: Opened channel 'MYAPP-GC-001'
2019-10-20  9:37:49 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2019-10-20  9:37:49 0 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 39538253-f2da-11e9-b06c-d3d9eb2d1a10
2019-10-20  9:37:49 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 39538253-f2da-11e9-b06c-d3d9eb2d1a10
2019-10-20  9:37:49 0 [Note] WSREP: STATE EXCHANGE: got state msg: 39538253-f2da-11e9-b06c-d3d9eb2d1a10 from 0 (DB-0)
2019-10-20  9:37:49 0 [Note] WSREP: Quorum results:
	version    = 5,
	component  = PRIMARY,
	conf_id    = 0,
	members    = 1/1 (joined/total),
	act_id     = 438,
	last_appl. = -1,
	protocols  = 1/10/4 (gcs/repl/appl),
	vote policy= 0,
	group UUID = d4e10b2c-f17f-11e9-8fee-ce97cf6630f2
2019-10-20  9:37:49 0 [Note] WSREP: Writing down CC checksum: 53bec602 27d03eb5 0f8606a9 da397c3c at offset 120
2019-10-20  9:37:49 0 [Note] WSREP: Flow-control interval: [253, 256]
2019-10-20  9:37:49 0 [Note] WSREP: Trying to continue unpaused monitor
2019-10-20  9:37:49 0 [Note] WSREP: Restored state OPEN -> JOINED (439)
2019-10-20  9:37:49 0 [Note] WSREP: Member 0.0 (DB-0) synced with group.
2019-10-20  9:37:49 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 439)
2019-10-20  9:37:49 1 [Note] WSREP: wsrep system thread 1, 0x7fd3ac000c08 starting
2019-10-20  9:37:49 1 [Note] WSREP: Starting rollbacker thread 1
2019-10-20  9:37:49 2 [Note] WSREP: wsrep system thread 2, 0x7fd3a4000c08 starting
2019-10-20  9:37:49 2 [Note] WSREP: Starting applier thread 2
2019-10-20  9:37:49 2 [Note] WSREP: ####### processing CC 439, local, ordered
2019-10-20  9:37:49 2 [Note] WSREP: ####### drain monitors upto -1
2019-10-20  9:37:49 2 [Note] WSREP: REPL Protocols: 10 (5, 3)
2019-10-20  9:37:49 2 [Note] WSREP: ####### My UUID: 3951e78b-f2da-11e9-9fa4-7efcbdcb8146
2019-10-20  9:37:49 2 [Note] WSREP: Server DB-0 connected to cluster at position d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:439 with ID 3951e78b-f2da-11e9-9fa4-7efcbdcb8146
2019-10-20  9:37:49 2 [Note] [Debug] WSREP: server DB-0 state change: disconnected -> connected
2019-10-20  9:37:49 2 [Note] WSREP: Server status change disconnected -> connected
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 2 [Note] WSREP: ####### ST not required
2019-10-20  9:37:49 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:0 (proto: 10), state transfer needed: no
2019-10-20  9:37:49 0 [Note] WSREP: Service thread queue flushed.
2019-10-20  9:37:49 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:0, protocol version: 5
2019-10-20  9:37:49 2 [Note] WSREP: ####### Adjusting cert position: 0 -> 439
2019-10-20  9:37:49 0 [Note] WSREP: Service thread queue flushed.
2019-10-20  9:37:49 2 [Note] WSREP: ####### Setting monitor position to 439
2019-10-20  9:37:49 2 [Note] WSREP: Lowest cert indnex boundary for CC from group: 439
2019-10-20  9:37:49 2 [Note] WSREP: Min available from gcache for CC from group: 2
2019-10-20  9:37:49 2 [Note] WSREP: ================================================
View:
  id: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:439
  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: 3951e78b-f2da-11e9-9fa4-7efcbdcb8146, DB-0
=================================================
2019-10-20  9:37:49 2 [Note] [Debug] WSREP: server DB-0 state change: connected -> joiner
2019-10-20  9:37:49 2 [Note] WSREP: Server status change connected -> joiner
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 2 [Note] [Debug] WSREP: server DB-0 state change: joiner -> initializing
2019-10-20  9:37:49 2 [Note] WSREP: Server status change joiner -> initializing
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 0 [Note] InnoDB: Using Linux native AIO
2019-10-20  9:37:49 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-10-20  9:37:49 0 [Note] InnoDB: Uses event mutexes
2019-10-20  9:37:49 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-10-20  9:37:49 0 [Note] InnoDB: Number of pools: 1
2019-10-20  9:37:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-10-20  9:37:49 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2019-10-20  9:37:49 0 [Note] InnoDB: Initializing buffer pool, total size = 16M, instances = 1, chunk size = 16M
2019-10-20  9:37:49 0 [Note] InnoDB: Completed initialization of buffer pool
2019-10-20  9:37:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-10-20  9:37:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-10-20  9:37:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-10-20  9:37:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-10-20  9:37:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-10-20  9:37:49 0 [Note] InnoDB: Waiting for purge to start
2019-10-20  9:37:49 0 [Note] InnoDB: 10.4.8 started; log sequence number 2474139; transaction id 3825
2019-10-20  9:37:49 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-10-20  9:37:49 0 [Note] InnoDB: Buffer pool(s) load completed at 191020  9:37:49
2019-10-20  9:37:49 0 [Note] Plugin 'FEEDBACK' is disabled.
2019-10-20  9:37:49 0 [Note] WSREP: wsrep_plugin_init()
2019-10-20  9:37:49 0 [Note] Server socket created on IP: '0.0.0.0'.
2019-10-20  9:37:49 0 [Warning] 'user' entry '@db' ignored in --skip-name-resolve mode.
2019-10-20  9:37:49 0 [Warning] 'proxies_priv' entry '@% root@db' ignored in --skip-name-resolve mode.
2019-10-20  9:37:49 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)
2019-10-20  9:37:49 8 [Note] WSREP: SQL: 202 CREATE TABLE IF NOT EXISTS mysql.wsrep_cluster(cluster_uuid CHAR(36) PRIMARY KEY,view_id BIGINT NOT NULL,view_seqno BIGINT NOT NULL,protocol_version INT NOT NULL,capabilities INT NOT NULL) ENGINE=InnoDB thd: 8
2019-10-20  9:37:49 8 [Note] WSREP: SQL: 203 CREATE TABLE IF NOT EXISTS mysql.wsrep_cluster_members(node_uuid CHAR(36) PRIMARY KEY,cluster_uuid CHAR(36) NOT NULL,node_name CHAR(32) NOT NULL,node_incoming_address VARCHAR(256) NOT NULL) ENGINE=InnoDB thd: 8
2019-10-20  9:37:49 8 [Note] WSREP: SQL: 199 CREATE TABLE IF NOT EXISTS mysql.wsrep_streaming_log(node_uuid CHAR(36), trx_id BIGINT, seqno BIGINT, flags INT NOT NULL, frag LONGBLOB NOT NULL, PRIMARY KEY (node_uuid, trx_id, seqno)) ENGINE=InnoDB thd: 8
2019-10-20  9:37:49 0 [Note] WSREP: Server initialized
2019-10-20  9:37:49 0 [Note] [Debug] WSREP: server DB-0 state change: initializing -> initialized
2019-10-20  9:37:49 0 [Note] WSREP: Server status change initializing -> initialized
2019-10-20  9:37:49 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 2 [Note] WSREP: Bootstrapping a new cluster, setting initial position to 00000000-0000-0000-0000-000000000000:-1
2019-10-20  9:37:49 2 [Note] WSREP: Set WSREPXid for InnoDB:  00000000-0000-0000-0000-000000000000:-1
2019-10-20  9:37:49 0 [Note] WSREP: Startup creating 3 applier threads running 1
2019-10-20  9:37:49 10 [Note] WSREP: wsrep system thread 10, 0x7fd36c000f38 starting
2019-10-20  9:37:49 9 [Note] WSREP: Recovered cluster id d4e10b2c-f17f-11e9-8fee-ce97cf6630f2
2019-10-20  9:37:49 10 [Note] WSREP: Starting applier thread 10
2019-10-20  9:37:49 2 [Note] [Debug] WSREP: server DB-0 state change: initialized -> joined
2019-10-20  9:37:49 2 [Note] WSREP: Server status change initialized -> joined
2019-10-20  9:37:49 13 [Note] WSREP: wsrep system thread 13, 0x7fd38c0011d8 starting
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 13 [Note] WSREP: Starting applier thread 13
2019-10-20  9:37:49 2 [Note] WSREP: Restored cluster view:
  id: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:438
  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: -1
  members(1):
	0: 5cba1291-f2d9-11e9-8ca2-f39a5f69fae6, DB-0
 
2019-10-20  9:37:49 2 [Note] WSREP: Storing cluster view:
  id: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:439
  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: 3951e78b-f2da-11e9-9fa4-7efcbdcb8146, DB-0
 
2019-10-20  9:37:49 2 [Note] WSREP: SQL: 31 DELETE FROM mysql.wsrep_cluster thd: 2
2019-10-20  9:37:49 2 [Note] WSREP: SQL: 39 DELETE FROM mysql.wsrep_cluster_members thd: 2
2019-10-20  9:37:49 2 [Note] WSREP: Set WSREPXid for InnoDB:  d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:439
2019-10-20  9:37:49 0 [Note] Reading of all Master_info entries succeeded
2019-10-20  9:37:49 0 [Note] Added new Master_info '' to hash table
2019-10-20  9:37:49 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.4.8-MariaDB-1:10.4.8+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2019-10-20  9:37:49 11 [Note] WSREP: wsrep system thread 11, 0x7fd37c007fa8 starting
2019-10-20  9:37:49 11 [Note] WSREP: Starting applier thread 11
2019-10-20  9:37:49 2 [Note] WSREP: Server DB-0 synced with group
2019-10-20  9:37:49 2 [Note] [Debug] WSREP: server DB-0 state change: joined -> synced
2019-10-20  9:37:49 2 [Note] WSREP: Server status change joined -> synced
2019-10-20  9:37:49 2 [Note] WSREP: Synchronized with group, ready for connections
2019-10-20  9:37:49 2 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:37:49 15 [Note] WSREP: assigned new next trx id: 6
2019-10-20  9:37:49 16 [Note] WSREP: assigned new next trx id: 9
2019-10-20  9:37:49 16 [Note] WSREP: wsrep_commit_empty(16)
2019-10-20  9:37:49 16 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 16 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 16 [Note] WSREP: assigned new next trx id: 10
2019-10-20  9:37:49 17 [Note] WSREP: assigned new next trx id: 11
2019-10-20  9:37:49 17 [Note] WSREP: wsrep_commit_empty(17)
2019-10-20  9:37:49 17 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 17 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 17 [Note] WSREP: assigned new next trx id: 12
2019-10-20  9:37:49 18 [Note] WSREP: assigned new next trx id: 13
2019-10-20  9:37:49 18 [Note] WSREP: wsrep_commit_empty(18)
2019-10-20  9:37:49 18 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 18 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 18 [Note] WSREP: assigned new next trx id: 14
2019-10-20  9:37:49 19 [Note] WSREP: assigned new next trx id: 15
2019-10-20  9:37:49 19 [Note] WSREP: wsrep_commit_empty(19)
2019-10-20  9:37:49 19 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 19 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 19 [Note] WSREP: assigned new next trx id: 16
2019-10-20  9:37:49 20 [Note] WSREP: assigned new next trx id: 17
2019-10-20  9:37:49 20 [Note] WSREP: wsrep_commit_empty(20)
2019-10-20  9:37:49 20 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 20 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 20 [Note] WSREP: assigned new next trx id: 18
2019-10-20  9:37:49 21 [Note] WSREP: assigned new next trx id: 19
2019-10-20  9:37:49 21 [Note] WSREP: wsrep_commit_empty(21)
2019-10-20  9:37:49 21 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 21 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 21 [Note] WSREP: assigned new next trx id: 20
2019-10-20  9:37:49 22 [Note] WSREP: assigned new next trx id: 21
2019-10-20  9:37:49 22 [Note] WSREP: wsrep_commit_empty(22)
2019-10-20  9:37:49 22 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 22 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 22 [Note] WSREP: assigned new next trx id: 22
2019-10-20  9:37:49 23 [Note] WSREP: assigned new next trx id: 23
2019-10-20  9:37:49 23 [Note] WSREP: wsrep_commit_empty(23)
2019-10-20  9:37:49 23 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 23 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 23 [Note] WSREP: assigned new next trx id: 24
2019-10-20  9:37:49 24 [Note] WSREP: assigned new next trx id: 25
2019-10-20  9:37:49 24 [Note] WSREP: wsrep_commit_empty(24)
2019-10-20  9:37:49 24 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 24 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 24 [Note] WSREP: assigned new next trx id: 26
2019-10-20  9:37:49 25 [Note] WSREP: assigned new next trx id: 27
2019-10-20  9:37:49 25 [Note] WSREP: wsrep_commit_empty(25)
2019-10-20  9:37:49 25 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 25 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 25 [Note] WSREP: assigned new next trx id: 28
2019-10-20  9:37:49 26 [Note] WSREP: assigned new next trx id: 29
2019-10-20  9:37:49 26 [Note] WSREP: wsrep_commit_empty(26)
2019-10-20  9:37:49 26 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 26 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 26 [Note] WSREP: assigned new next trx id: 30
2019-10-20  9:37:49 27 [Note] WSREP: assigned new next trx id: 31
2019-10-20  9:37:49 27 [Note] WSREP: wsrep_commit_empty(27)
2019-10-20  9:37:49 27 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 27 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 27 [Note] WSREP: assigned new next trx id: 32
2019-10-20  9:37:49 28 [Note] WSREP: assigned new next trx id: 33
2019-10-20  9:37:49 28 [Note] WSREP: wsrep_commit_empty(28)
2019-10-20  9:37:49 28 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 28 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 28 [Note] WSREP: assigned new next trx id: 34
2019-10-20  9:37:49 29 [Note] WSREP: assigned new next trx id: 35
2019-10-20  9:37:49 29 [Note] WSREP: wsrep_commit_empty(29)
2019-10-20  9:37:49 29 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 29 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 29 [Note] WSREP: assigned new next trx id: 36
2019-10-20  9:37:49 30 [Note] WSREP: assigned new next trx id: 37
2019-10-20  9:37:49 30 [Note] WSREP: wsrep_commit_empty(30)
2019-10-20  9:37:49 30 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 30 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 30 [Note] WSREP: assigned new next trx id: 38
2019-10-20  9:37:49 31 [Note] WSREP: assigned new next trx id: 39
2019-10-20  9:37:49 31 [Note] WSREP: wsrep_commit_empty(31)
2019-10-20  9:37:49 31 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 31 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 31 [Note] WSREP: assigned new next trx id: 40
2019-10-20  9:37:49 32 [Note] WSREP: assigned new next trx id: 41
2019-10-20  9:37:49 32 [Note] WSREP: wsrep_commit_empty(32)
2019-10-20  9:37:49 32 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 32 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 32 [Note] WSREP: assigned new next trx id: 42
2019-10-20  9:37:49 33 [Note] WSREP: assigned new next trx id: 43
2019-10-20  9:37:49 33 [Note] WSREP: wsrep_commit_empty(33)
2019-10-20  9:37:49 33 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 33 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 33 [Note] WSREP: assigned new next trx id: 44
2019-10-20  9:37:49 34 [Note] WSREP: assigned new next trx id: 45
2019-10-20  9:37:49 34 [Note] WSREP: wsrep_commit_empty(34)
2019-10-20  9:37:49 34 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 34 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 34 [Note] WSREP: assigned new next trx id: 46
2019-10-20  9:37:49 35 [Note] WSREP: assigned new next trx id: 47
2019-10-20  9:37:49 35 [Note] WSREP: wsrep_commit_empty(35)
2019-10-20  9:37:49 35 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 35 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 35 [Note] WSREP: assigned new next trx id: 48
2019-10-20  9:37:49 36 [Note] WSREP: assigned new next trx id: 49
2019-10-20  9:37:49 36 [Note] WSREP: wsrep_commit_empty(36)
2019-10-20  9:37:49 36 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 36 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 36 [Note] WSREP: assigned new next trx id: 50
2019-10-20  9:37:49 37 [Note] WSREP: assigned new next trx id: 51
2019-10-20  9:37:49 37 [Note] WSREP: wsrep_commit_empty(37)
2019-10-20  9:37:49 37 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 37 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 37 [Note] WSREP: assigned new next trx id: 52
2019-10-20  9:37:49 38 [Note] WSREP: assigned new next trx id: 53
2019-10-20  9:37:49 38 [Note] WSREP: wsrep_commit_empty(38)
2019-10-20  9:37:49 38 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 38 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 38 [Note] WSREP: assigned new next trx id: 54
2019-10-20  9:37:49 39 [Note] WSREP: assigned new next trx id: 55
2019-10-20  9:37:49 39 [Note] WSREP: wsrep_commit_empty(39)
2019-10-20  9:37:49 39 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 39 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 39 [Note] WSREP: assigned new next trx id: 56
2019-10-20  9:37:49 40 [Note] WSREP: assigned new next trx id: 57
2019-10-20  9:37:49 40 [Note] WSREP: wsrep_commit_empty(40)
2019-10-20  9:37:49 40 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 40 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 40 [Note] WSREP: assigned new next trx id: 58
2019-10-20  9:37:49 41 [Note] WSREP: assigned new next trx id: 59
2019-10-20  9:37:49 41 [Note] WSREP: wsrep_commit_empty(41)
2019-10-20  9:37:49 41 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 41 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:37:49 41 [Note] WSREP: assigned new next trx id: 60
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 61
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 62
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 63
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 64
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 65
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 66
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 67
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 68
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 69
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 70
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 71
2019-10-20  9:38:34 42 [Note] WSREP: assigned new next trx id: 71
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:34 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:42 42 [Note] WSREP: assigned new next trx id: 72
2019-10-20  9:38:42 42 [Note] WSREP: assigned new next trx id: 72
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:42 42 [Note] WSREP: assigned new next trx id: 73
2019-10-20  9:38:42 42 [Note] WSREP: assigned new next trx id: 73
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_commit_empty(42)
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:42 42 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:51 43 [Note] WSREP: assigned new next trx id: 74
2019-10-20  9:38:51 43 [Note] WSREP: wsrep_commit_empty(43)
2019-10-20  9:38:51 43 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:51 43 [Note] WSREP: wsrep_thd_binlog_reset
2019-10-20  9:38:51 43 [Note] WSREP: assigned new next trx id: 75
2019-10-20  9:38:51 0 [Note] /usr/sbin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
2019-10-20  9:38:51 0 [Note] WSREP: Shutdown replication
2019-10-20  9:38:51 0 [Note] WSREP: Disconnect provider
2019-10-20  9:38:51 0 [Note] [Debug] WSREP: server DB-0 state change: synced -> disconnecting
2019-10-20  9:38:51 0 [Note] WSREP: Server status change synced -> disconnecting
2019-10-20  9:38:51 0 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:38:51 0 [Note] WSREP: Closing send monitor...
2019-10-20  9:38:51 0 [Note] WSREP: Closed send monitor.
2019-10-20  9:38:51 0 [Note] WSREP: gcomm: terminating thread
2019-10-20  9:38:51 0 [Note] WSREP: gcomm: joining thread
2019-10-20  9:38:51 0 [Note] WSREP: gcomm: closing backend
2019-10-20  9:38:51 0 [Note] WSREP: PC protocol downgrade 1 -> 0
2019-10-20  9:38:51 0 [Note] WSREP: view((empty))
2019-10-20  9:38:51 0 [Note] WSREP: gcomm: closed
2019-10-20  9:38:51 0 [Note] WSREP: Received self-leave message.
2019-10-20  9:38:51 0 [Note] WSREP: Writing down CC checksum: b8ffac2a 682e0605 b47dccc3 84924fc1 at offset 64
2019-10-20  9:38:51 0 [Note] WSREP: Flow-control interval: [0, 0]
2019-10-20  9:38:51 0 [Note] WSREP: Trying to continue unpaused monitor
2019-10-20  9:38:51 0 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2019-10-20  9:38:51 0 [Note] WSREP: Shifting SYNCED -> CLOSED (TO: 439)
2019-10-20  9:38:51 0 [Note] WSREP: RECV thread exiting 0: Success
2019-10-20  9:38:51 0 [Note] WSREP: recv_thread() joined.
2019-10-20  9:38:51 0 [Note] WSREP: Closing replication queue.
2019-10-20  9:38:51 0 [Note] WSREP: Closing slave action queue.
2019-10-20  9:38:51 10 [Note] WSREP: ####### processing CC -1, local, ordered
2019-10-20  9:38:51 10 [Note] WSREP: ####### drain monitors upto 439
2019-10-20  9:38:51 10 [Note] WSREP: ####### My UUID: 3951e78b-f2da-11e9-9fa4-7efcbdcb8146
2019-10-20  9:38:51 10 [Note] WSREP: ####### ST not required
2019-10-20  9:38:51 10 [Note] WSREP: ================================================
View:
  id: d4e10b2c-f17f-11e9-8fee-ce97cf6630f2:-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-10-20  9:38:51 10 [Note] WSREP: Non-primary view
2019-10-20  9:38:51 10 [Note] [Debug] WSREP: server DB-0 state change: disconnecting -> disconnected
2019-10-20  9:38:51 10 [Note] WSREP: Server status change disconnecting -> disconnected
2019-10-20  9:38:51 10 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:38:51 10 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2019-10-20  9:38:51 10 [Note] WSREP: Applier thread exiting ret: 0 thd: 10
2019-10-20  9:38:51 10 [Note] WSREP: closing applier 10
2019-10-20  9:38:51 10 [Note] WSREP: wsrep system thread: 10, 0x7fd36c000f38 closing
2019-10-20  9:38:51 10 [Warning] Aborted connection 10 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-10-20  9:38:51 10 [Note] WSREP: wsrep running threads now: 4
2019-10-20  9:38:51 0 [Note] WSREP: closing connection 42
2019-10-20  9:38:51 0 [Note] WSREP: killing local connection: 42
2019-10-20  9:38:51 0 [Note] WSREP: waiting for client connections to close: 11
2019-10-20  9:38:51 11 [Note] WSREP: Applier thread exiting ret: 6 thd: 11
2019-10-20  9:38:51 11 [Note] WSREP: closing applier 11
2019-10-20  9:38:51 11 [Note] WSREP: wsrep system thread: 11, 0x7fd37c007fa8 closing
2019-10-20  9:38:51 11 [Warning] Aborted connection 11 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-10-20  9:38:51 11 [Note] WSREP: wsrep running threads now: 3
2019-10-20  9:38:51 2 [Note] WSREP: Applier thread exiting ret: 6 thd: 2
2019-10-20  9:38:51 2 [Note] WSREP: closing applier 2
2019-10-20  9:38:51 2 [Note] WSREP: wsrep system thread: 2, 0x7fd3a4000c08 closing
2019-10-20  9:38:51 2 [Warning] Aborted connection 2 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-10-20  9:38:51 2 [Note] WSREP: wsrep running threads now: 2
2019-10-20  9:38:51 13 [Note] WSREP: Applier thread exiting ret: 6 thd: 13
2019-10-20  9:38:51 13 [Note] WSREP: closing applier 13
2019-10-20  9:38:51 13 [Note] WSREP: wsrep system thread: 13, 0x7fd38c0011d8 closing
2019-10-20  9:38:51 13 [Warning] Aborted connection 13 to db: 'unconnected' user: 'unauthenticated' host: '' (This connection closed normally without authentication)
2019-10-20  9:38:51 13 [Note] WSREP: wsrep running threads now: 1

Stack backtrace using gdb:

(gdb) bt
#0  0x00007f318592a9d0 in __GI___nanosleep (requested_time=requested_time@entry=0x7ffc79ea2400, remaining=remaining@entry=0x7ffc79ea2400)
    at ../sysdeps/unix/sysv/linux/nanosleep.c:28
#1  0x00007f318592a8aa in __sleep (seconds=0) at ../sysdeps/posix/sleep.c:55
#2  0x000055d18fe341f2 in wsrep_close_client_connections(char, THD*) ()
#3  0x000055d18fe38361 in wsrep_shutdown_replication() ()
#4  0x000055d18fc05ab5 in mysqld_main(int, char**) ()
#5  0x00007f3185867b97 in __libc_start_main (main=0x55d18fbdfac0 <main>, argc=3, argv=0x7ffc79ea3338, init=<optimized out>, fini=<optimized out>,
    rtld_fini=<optimized out>, stack_end=0x7ffc79ea3328) at ../csu/libc-start.c:310
#6  0x000055d18fbf7f6a in _start ()



 Comments   
Comment by Bai Yang [ 2019-10-20 ]

It seems to be stuck on waiting for the last galera slave thread.

I'm using `wsrep_debug = 1`

I also changed the systemd configuration, set the Stop timeout to 30s, and allowed systemd to send a KILL signal to mysqld.

Comment by Bai Yang [ 2019-11-06 ]

I'm using thread pool (`thread_handling=pool-of-threads`). And I suspect this is a problem that has been resolved in PXC: https://jira.percona.com/browse/PXC-2127...

I have already uninstalled MariaDB 10.4.8, so I can't confirm this further.

Comment by Christian Hesse [ 2020-03-10 ]

The commit referenced in PXC-2127 is this one:
https://github.com/percona/percona-xtradb-cluster/commit/620329bdc85fc2c215fa344a839cb6d6e5574f15

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