Bug #117424 InnoDB Cluster with group_replication_paxos_single_leader=ON unable to process write traffic
Submitted: 10 Feb 11:06 Modified: 10 Feb 12:35
Reporter: Nikolaos Smyrnioudis Email Updates:
Status: Analyzing Impact on me:
None 
Category:MySQL Server: Group Replication Severity:S2 (Serious)
Version:8.0.35,8.4.2,8.0.40 OS:Red Hat (8)
Assigned to: MySQL Verification Team CPU Architecture:x86
Tags: group replication, lock, lock wait timeout exceeded

[10 Feb 11:06] Nikolaos Smyrnioudis
Description:
We are running Group Replication with InnoDB Clusters with version 8.0.35 in production. We think we may have discovered a bug with group_replication_paxos_single_leader=ON (paxosSingleLeader=True, in mysql-shell configuration) . After a momentary loss of connectivity, the primary got fenced, reestablished connectivity, there was no failover (since the cut in connectivity was too short), but in that primary, transactions from the application were stuck with a state waiting for handler commit , and they were holding locks to some data of the tables, which in turn caused a downtime in on of our applications, since most transactions later couldn't execute with the error: 

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting. 

Some more details of our InnoDB cluster setup: We are running 3 MySQLRouter process in different availability zones in a container orchestation system (Nomad). Our instances are running in Bare Metal hosts with <0.3 ms latency between each of them EVEN if we run one of the replicas in a different datacenter. Group replication has been configured with mysql-shell according to the InnoDB Cluster documentation(using paxosSingleLeader=True) 

How to repeat:
We managed to reproduced the issue with group_replications_paxos_single_leader=ON for versions 8.0.35, 8.4.2, 8.0.40 (It was a bit harder for 8.0.40). We did the following: 

1) We set up sysbench to execute a constant number of transactions on the server. Specifically these are the options passed to sysbench :

tables_count: 20
table_size: 100000
test: oltp_read_write.lua
threads: 16
mysql_ignore_errors: 1042,1062,2013,1213,3100,1053,9001,107 (This is for sysbench to constantly retry the transactions) 

2) We partitioned the primary (we used nftables to block bidirectional access from primary to first secondary, and primary to second secondary) for long enough until the primary gets fenced but not long enough to cause a failover. (This had to be repeated quite some times, sometimes sysbench was exiting, sometimes the cluster was behaving normal as usual)  

3) We observed that the primary had many processes in the state `waiting for handler commit`, holding locks most likely, since any updates to the tables were exiting with :

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

We still have the development 8.0.40 instance stuck in that state so we can provide any more information needed. For now here are some logs we can get: 

Log of the primary: 

2025-02-06T11:41:05.176085Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-04.cern.ch:5513 has become unreachable.'
2025-02-06T11:41:06.317733Z 0 [Warning] [MY-011494] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-04.cern.ch:5513 is reachable again.'
2025-02-06T11:41:30.306250Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-04.cern.ch:5513 has become unreachable.'
2025-02-06T11:41:30.306307Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-02.cern.ch:5508 has become unreachable.'
2025-02-06T11:41:30.306317Z 0 [ERROR] [MY-011495] [Repl] Plugin group_replication reported: 'This server is not able to reach a majority of members in the group. This server will now block all updates. The server will remain blocked until contact with the majority is restored. It is possible to use group_replication_force_members to force a new group membership.'
2025-02-06T11:41:36.045823Z 0 [ERROR] [MY-013780] [Repl] Plugin group_replication reported: 'Failed to establish MySQL client connection in Group Replication. Error establishing connection. Please refer to the manual to make sure that you configured Group Replication properly to work with MySQL Protocol connections.'
2025-02-06T11:41:37.146828Z 0 [ERROR] [MY-013780] [Repl] Plugin group_replication reported: 'Failed to establish MySQL client connection in Group Replication. Error establishing connection. Please refer to the manual to make sure that you configured Group Replication properly to work with MySQL Protocol connections.'
2025-02-06T11:41:39.248041Z 0 [ERROR] [MY-013780] [Repl] Plugin group_replication reported: 'Failed to establish MySQL client connection in Group Replication. Error establishing connection. Please refer to the manual to make sure that you configured Group Replication properly to work with MySQL Protocol connections.'
2025-02-06T11:41:41.380466Z 0 [Warning] [MY-011494] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-04.cern.ch:5513 is reachable again.'
2025-02-06T11:41:41.380521Z 0 [Warning] [MY-011498] [Repl] Plugin group_replication reported: 'The member has resumed contact with a majority of the members in the group. Regular operation is restored and transactions are unblocked.'
2025-02-06T11:41:50.932265Z 0 [Warning] [MY-011494] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-02.cern.ch:5508 is reachable again.'
2025-02-06T11:42:53.812427Z 7264 [Warning] [MY-013360] [Server] Plugin mysql_native_password reported: ''mysql_native_password' is deprecated and will be removed in a future release. Please use caching_sha2_password instead'
2025-02-06T11:42:55.833786Z 7281 [Warning] [MY-013360] [Server] Plugin mysql_native_password reported: ''mysql_native_password' is deprecated and will be removed in a future release. Please use caching_sha2_password instead'
2025-02-06T11:42:58.863631Z 7304 [Warning] [MY-013360] [Server] Plugin sha256_password reported: ''sha256_password' is deprecated and will be removed in a future release. Please use caching_sha2_password instead'

Log first secondary

2025-02-07T16:55:20.234247Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-01.cern.ch:5508 has become unreachable.'
2025-02-07T16:55:25.430277Z 0 [Warning] [MY-011494] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-01.cern.ch:5508 is reachable again.'

Log of second secondary: 

2025-02-07T16:55:20.500844Z 0 [Warning] [MY-011493] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-01.cern.ch:5508 has become unreachable.'
2025-02-07T16:55:27.322478Z 0 [Warning] [MY-011735] [Repl] Plugin group_replication reported: '[GCS] Shutting down an outgoing connection. This happens because something might be wrong on a bi-directional connection to node dbod-dbod-dev-nic-ha-01.cern.ch:5508. Please check the connection status to this member'
2025-02-07T16:55:27.323288Z 0 [Warning] [MY-011494] [Repl] Plugin group_replication reported: 'Member with address dbod-dbod-dev-nic-ha-01.cern.ch:5508 is reachable again.' 

SELECT * from information_schema.processlist: 

mysql> select * from information_schema.processlist;
+---------+-------------------------+--------------------------------------+-----------+------------------+--------+----------------------------------------------------------+----------------------------------------------+
| ID      | USER                    | HOST                                 | DB        | COMMAND          | TIME   | STATE                                                    | INFO                                         |
+---------+-------------------------+--------------------------------------+-----------+------------------+--------+----------------------------------------------------------+----------------------------------------------+
|   22608 | dod_mysql               | dia-nomad-dbod-dev-b01.cern.ch:41016 | sysbench  | Execute          | 238152 | waiting for handler commit                               | COMMIT                                       |
|   22736 | dod_mysql               | dia-nomad-dbod-dev-b01.cern.ch:58582 | sysbench  | Execute          | 238146 | waiting for handler commit                               | COMMIT                                       |
|   20640 | system user             |                                      | NULL      | Connect          | 238435 | waiting for handler commit                               | Group replication applier module             |
|   20656 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20648 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   22809 | mysql_innodb_cluster_10 | dbod-ga056.cern.ch:44872             | NULL      | Group Replicatio | 238141 | Connection delegated to Group Replication                | NULL                                         |
|   22601 | dod_mysql               | dia-nomad-dbod-dev-b01.cern.ch:41000 | sysbench  | Execute          | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20657 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20650 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   22842 | mysql_innodb_cluster_30 | dbod-gb031.cern.ch:54874             | NULL      | Group Replicatio | 238139 | Connection delegated to Group Replication                | NULL                                         |
|   22602 | dod_mysql               | dia-nomad-dbod-dev-b01.cern.ch:41010 | sysbench  | Execute          | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20658 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20642 | system user             |                                      | NULL      | Query            |  26124 | Replica has read all relay log; waiting for more updates | NULL                                         |
|   22611 | dod_mysql               | dia-nomad-dbod-dev-c00.cern.ch:59056 | sysbench  | Execute          | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20659 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   22243 | dod_mysql               | dia-nomad-dbod-dev-a00.cern.ch:36210 | dod_dbmon | Query            | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20643 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   22612 | dod_mysql               | dia-nomad-dbod-dev-a00.cern.ch:33704 | sysbench  | Execute          | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20644 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20660 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20652 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20645 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20653 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   22605 | dod_mysql               | dia-nomad-dbod-dev-a00.cern.ch:33656 | sysbench  | Killed           | 238152 | waiting for handler commit                               | COMMIT                                       |
|   20654 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20646 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|       7 | event_scheduler         | localhost                            | NULL      | Daemon           | 242018 | Waiting on empty queue                                   | NULL                                         |
| 1708015 | dod_mysql               | nsmyrnio-mac.dyndns.cern.ch:53459    | NULL      | Query            |      0 | executing                                                | select * from information_schema.processlist |
|   20655 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
|   20647 | system user             |                                      | NULL      | Query            | 238382 | Waiting for an event from Coordinator                    | NULL                                         |
+---------+-------------------------+--------------------------------------+-----------+------------------+--------+----------------------------------------------------------+----------------------------------------------+
30 rows in set, 1 warning (0.01 sec)

SHOW ENGINE INNODB STATUS\G

mysql> show engine innodb status\G;
*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2025-02-10 12:04:41 140363362563840 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 19631 srv_active, 0 srv_shutdown, 222352 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 895696
OS WAIT ARRAY INFO: signal count 655444
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2025-02-07 17:20:17 140363466446592
*** (1) TRANSACTION:
TRANSACTION 14708531, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 7 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 2
MySQL thread id 12553, OS thread handle 140365036181248, query id 5584342 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql update
INSERT INTO sbtest11 (id, k, c, pad) VALUES (50319, 50111, '70499727803-50024564641-32640939475-87345508419-45664720193-65672660967-40940656112-45122643438-55303355498-12228124623', '87117621077-95985376469-06425682019-87586279487-15350921075')

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 96 page no 4 n bits 80 index PRIMARY of table `sysbench`.`sbtest11` trx id 14708531 lock_mode X locks gap before rec
Record lock, heap no 8 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 8000c4cb; asc     ;;
 1: len 6; hex 000000e06ee7; asc     n ;;
 2: len 7; hex 82000000a00110; asc        ;;
 3: len 4; hex 8000c316; asc     ;;
 4: len 30; hex 30373835323231343634362d37323438393938393939322d343239343637; asc 07852214646-72489989992-429467; (total 120 bytes);
 5: len 30; hex 37323438313532383836342d35333231333031363633352d363936383036; asc 72481528864-53213016635-696806; (total 60 bytes);

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 96 page no 4 n bits 80 index PRIMARY of table `sysbench`.`sbtest11` trx id 14708531 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 8 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 8000c4cb; asc     ;;
 1: len 6; hex 000000e06ee7; asc     n ;;
 2: len 7; hex 82000000a00110; asc        ;;
 3: len 4; hex 8000c316; asc     ;;
 4: len 30; hex 30373835323231343634362d37323438393938393939322d343239343637; asc 07852214646-72489989992-429467; (total 120 bytes);
 5: len 30; hex 37323438313532383836342d35333231333031363633352d363936383036; asc 72481528864-53213016635-696806; (total 60 bytes);

*** (2) TRANSACTION:
TRANSACTION 14708534, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 1
MySQL thread id 12563, OS thread handle 140359732557568, query id 5584349 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql update
INSERT INTO sbtest11 (id, k, c, pad) VALUES (50229, 45455, '54523954113-61638795634-03768792922-58174061504-59049221316-37283979466-58517158561-94235962237-58687908466-70102052603', '60875566916-09717772664-40449231282-05019735087-32047311662')

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 96 page no 4 n bits 80 index PRIMARY of table `sysbench`.`sbtest11` trx id 14708534 lock_mode X locks gap before rec
Record lock, heap no 8 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 8000c4cb; asc     ;;
 1: len 6; hex 000000e06ee7; asc     n ;;
 2: len 7; hex 82000000a00110; asc        ;;
 3: len 4; hex 8000c316; asc     ;;
 4: len 30; hex 30373835323231343634362d37323438393938393939322d343239343637; asc 07852214646-72489989992-429467; (total 120 bytes);
 5: len 30; hex 37323438313532383836342d35333231333031363633352d363936383036; asc 72481528864-53213016635-696806; (total 60 bytes);

Record lock, heap no 9 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 8000c2c2; asc     ;;
 1: len 6; hex 000000e06eef; asc     n ;;
 2: len 7; hex 81000001510110; asc     Q  ;;
 3: len 4; hex 8000c3e6; asc     ;;
 4: len 30; hex 30383236313731323332332d30383138373834343031392d313233343139; asc 08261712323-08187844019-123419; (total 120 bytes);
 5: len 30; hex 34373231393336323136332d30353039343832383430372d353634383838; asc 47219362163-05094828407-564888; (total 60 bytes);

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 96 page no 4 n bits 80 index PRIMARY of table `sysbench`.`sbtest11` trx id 14708534 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 8 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 8000c4cb; asc     ;;
 1: len 6; hex 000000e06ee7; asc     n ;;
 2: len 7; hex 82000000a00110; asc        ;;
 3: len 4; hex 8000c316; asc     ;;
 4: len 30; hex 30373835323231343634362d37323438393938393939322d343239343637; asc 07852214646-72489989992-429467; (total 120 bytes);
 5: len 30; hex 37323438313532383836342d35333231333031363633352d363936383036; asc 72481528864-53213016635-696806; (total 60 bytes);

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 16440784
Purge done for trx's n:o < 16231766 undo n:o < 0 state: running but idle
History list length 31902
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421840417322352, not started
mysql tables in use 7, locked 0
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417320736, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417319928, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417319120, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417317504, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417316696, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417315888, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417315080, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417314272, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417313464, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417312656, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417311848, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417311040, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417310232, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417309424, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417308616, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417307808, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417307000, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417306192, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417305384, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417304576, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417303768, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417302960, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421840417302152, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 16231799, ACTIVE (PREPARED) 238161 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22736, OS thread handle 140365037233920, query id 18531773 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231799, sees < 16231772
---TRANSACTION 16231794, ACTIVE (PREPARED) 238167 sec
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1
MySQL thread id 22243, OS thread handle 140359681980160, query id 18531125 dia-nomad-dbod-dev-a00.cern.ch 188.184.84.4 dod_mysql waiting for handler commit
COMMIT
---TRANSACTION 16231793, ACTIVE (PREPARED) 238167 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22612, OS thread handle 140365038290688, query id 18531123 dia-nomad-dbod-dev-a00.cern.ch 188.184.84.4 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231785, sees < 16231772
---TRANSACTION 16231792, ACTIVE (PREPARED) 238167 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22611, OS thread handle 140365036177152, query id 18531119 dia-nomad-dbod-dev-c00.cern.ch 188.184.75.43 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231784, sees < 16231772
---TRANSACTION 16231791, ACTIVE (PREPARED) 238167 sec
5 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22602, OS thread handle 140359731500800, query id 18531110 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231784, sees < 16231772
---TRANSACTION 16231790, ACTIVE (PREPARED) 238167 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22605, OS thread handle 140359717771008, query id 18531114 dia-nomad-dbod-dev-a00.cern.ch 188.184.84.4 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231764, sees < 16231762
---TRANSACTION 16231789, ACTIVE (PREPARED) 238167 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22601, OS thread handle 140359697762048, query id 18531108 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231784, sees < 16231772
---TRANSACTION 16231788, ACTIVE (PREPARED) 238167 sec
6 lock struct(s), heap size 1128, 3 row lock(s), undo log entries 4
MySQL thread id 22608, OS thread handle 140359723046656, query id 18531104 dia-nomad-dbod-dev-b01.cern.ch 188.184.92.35 dod_mysql waiting for handler commit
COMMIT
Trx read view will not see trx with id >= 16231784, sees < 16231772
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (read thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
23929 OS file reads, 3766440 OS file writes, 2406566 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 2.77 writes/s, 2.31 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 12, seg size 14, 1422 merges
merged operations:
 insert 1390, delete mark 1913, delete 1028
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 161 buffer(s)
Hash table size 276707, node heap has 80 buffer(s)
Hash table size 276707, node heap has 310 buffer(s)
Hash table size 276707, node heap has 311 buffer(s)
Hash table size 276707, node heap has 81 buffer(s)
Hash table size 276707, node heap has 237 buffer(s)
Hash table size 276707, node heap has 79 buffer(s)
Hash table size 276707, node heap has 233 buffer(s)
3.50 hash searches/s, 4.50 non-hash searches/s
---
LOG
---
Log sequence number          18394094058
Log buffer assigned up to    18394094058
Log buffer completed up to   18394094058
Log written up to            18394094058
Log flushed up to            18394094058
Added dirty pages up to      18394094058
Pages flushed up to          18394094038
Last checkpoint at           18394094038
Log minimum file id is       2174
Log maximum file id is       2190
2538092 log i/o's done, 1.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 985032
Buffer pool size   65530
Free buffers       8194
Database pages     55844
Old database pages 20450
Modified db pages  1
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 138854, not young 37860
3.70 youngs/s, 0.00 non-youngs/s
Pages read 22243, created 94754, written 810015
0.00 reads/s, 1.39 creates/s, 0.92 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 4 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 55844, unzip_LRU len: 0
I/O sum[440]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   8192
Free buffers       1024
Database pages     6982
Old database pages 2557
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 642, not young 2343
0.00 youngs/s, 0.00 non-youngs/s
Pages read 3055, created 7256, written 98559
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6982, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   8191
Free buffers       1024
Database pages     6979
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 577, not young 2528
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2855, created 7442, written 95260
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6979, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   8192
Free buffers       1024
Database pages     6981
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 485, not young 3028
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2660, created 7338, written 73025
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6981, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   8191
Free buffers       1024
Database pages     6981
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 473, not young 2758
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2723, created 7126, written 88766
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6981, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   8191
Free buffers       1024
Database pages     6981
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 429, not young 2393
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2441, created 7194, written 77854
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6981, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   8191
Free buffers       1026
Database pages     6978
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 16957, not young 10188
3.70 youngs/s, 0.00 non-youngs/s
Pages read 2806, created 7805, written 79501
0.00 reads/s, 1.39 creates/s, 0.46 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 33 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6978, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   8191
Free buffers       1024
Database pages     6980
Old database pages 2556
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 118435, not young 11558
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2751, created 43258, written 97215
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6980, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   8191
Free buffers       1024
Database pages     6982
Old database pages 2557
Modified db pages  1
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 856, not young 3064
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2952, created 7335, written 199835
0.00 reads/s, 0.00 creates/s, 0.46 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6982, unzip_LRU len: 0
I/O sum[55]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
8 read views open inside InnoDB
Process ID=2902031, Main thread ID=140363458053888 , state=sleeping
Number of rows inserted 5300931, updated 1843110, deleted 925377, read 341929096
30.98 inserts/s, 0.00 updates/s, 0.00 deletes/s, 135.93 reads/s
Number of system rows inserted 18370, updated 1612, deleted 17780, read 2856309
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 29.99 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.02 sec)

ERROR: 
No query specified

mysql>
[10 Feb 12:35] Nikolaos Smyrnioudis
Additionally this is the verbose cluster status we can obtain from MySQL Shell: 

{
  "clusterName": "dbod_dev_nic_ha",
  "defaultReplicaSet": {
    "GRProtocolVersion": "8.0.27",
    "communicationStack": "MYSQL",
    "groupName": "5a2b7941-e56b-11ef-94ef-fa163ef92e10",
    "groupViewChangeUuid": "5a2b807e-e56b-11ef-94ef-fa163ef92e10",
    "groupViewId": "17389434712577234:9",
    "name": "default",
    "paxosSingleLeader": "ON",
    "primary": "dbod-dbod-dev-nic-ha-01.cern.ch:5508",
    "ssl": "REQUIRED",
    "status": "OK",
    "statusText": "Cluster is ONLINE and can tolerate up to ONE failure.",
    "topology": {
      "dbod-dbod-dev-nic-ha-01.cern.ch:5508": {
        "address": "dbod-dbod-dev-nic-ha-01.cern.ch:5508",
        "applierWorkerThreads": 16,
        "fenceSysVars": [],
        "instanceErrors": [
          "WARNING: Detected unused recovery accounts: mysql_innodb_cluster_2, mysql_innodb_cluster_3. Use Cluster.rescan() to clean up."
        ],
        "memberId": "83a33cb3-e46d-11ef-a045-fa163ef92e10",
        "memberRole": "PRIMARY",
        "memberState": "ONLINE",
        "mode": "R/W",
        "readReplicas": {},
        "replicationLag": "applier_queue_applied",
        "role": "HA",
        "status": "ONLINE",
        "version": "8.0.40"
      },
      "dbod-dbod-dev-nic-ha-02.cern.ch:5508": {
        "address": "dbod-dbod-dev-nic-ha-02.cern.ch:5508",
        "applierWorkerThreads": 16,
        "fenceSysVars": [
          "read_only",
          "super_read_only"
        ],
        "memberId": "78d85cd7-e46b-11ef-b106-fa163eedca95",
        "memberRole": "SECONDARY",
        "memberState": "ONLINE",
        "mode": "R/O",
        "readReplicas": {},
        "replicationLag": "applier_queue_applied",
        "role": "HA",
        "status": "ONLINE",
        "version": "8.0.40"
      },
      "dbod-dbod-dev-nic-ha-04.cern.ch:5513": {
        "address": "dbod-dbod-dev-nic-ha-04.cern.ch:5513",
        "applierWorkerThreads": 16,
        "fenceSysVars": [
          "read_only",
          "super_read_only"
        ],
        "memberId": "5d454d21-e46b-11ef-9cfc-fa163e8a591a",
        "memberRole": "SECONDARY",
        "memberState": "ONLINE",
        "mode": "R/O",
        "readReplicas": {},
        "replicationLag": "applier_queue_applied",
        "role": "HA",
        "status": "ONLINE",
        "version": "8.0.40"
      }
    },
    "topologyMode": "Single-Primary"
  },
  "groupInformationSourceMember": "dbod-dbod-dev-nic-ha-01.cern.ch:5508",
  "metadataVersion": "2.1.0"
} 

And to also not that we haven't been able to reproduce in 8.0.35 when setting paxosSingleLeader=False