thr3ads.net - samba - [Samba] Create network oscillations on the leader node, resulting in brain splitting [Jun 2023]

If this information is useful, please help other people find it:
Share via:
tu.qiuping
2023-Jun-13 00:52 UTC
[Samba] Create network oscillations on the leader node, resulting in brain splitting

My ctdb version is 4.17.7


Hello, everyone.
My ctdb cluster configuration is correct and the cluster is healthy before
operation.
My cluster has three nodes, namely 192.168.40.131?node 0?, 192.168.40.132?node
1?, and 192.168.40.133?node 2?. And the node 192.168.40.133 is the leader.


I conducted network oscillation testing on node 192.168.40.133, and after a
period of time, the lock update of this node failed, and at this time, the lock
was taken away by node 0.
Amazingly, after node 0 received the lock, it sent a message with leader=0 to
node 1, but did not send it to node 2, even though the network of node 2 was
healthy at this time.
And when I restored the network of node 2, node 1 and node 2 kept trying to
acquire the lock and reported an error: Unable to take cluster lock -
contention.


Here is the logs of three nodes:


node 0?
2023-06-12T19:38:24.810747+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Reenabling takeover runs
2023-06-12T19:39:32.603600+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Leader broadcast timeout
2023-06-12T19:39:32.603791+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Start election
2023-06-12T19:39:32.603951+08:00 host-192-168-40-131 ctdbd[2853172]: Recovery
mode set to ACTIVE
2023-06-12T19:39:35.414699+08:00 host-192-168-40-131 ctdbd[2853172]: dead count
reached for node 2
2023-06-12T19:39:35.414878+08:00 host-192-168-40-131 ctdbd[2853172]: Tearing
down connection to dead node :2
2023-06-12T19:39:35.414975+08:00 host-192-168-40-131 ctdbd[2853172]:
192.136.40.131:4379: node 192.136.40.133:4379 is dead: 1 connected
2023-06-12T19:39:35.415107+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:35.415153+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:35.415177+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async operation failed with ret=-1 res=-1 opcode=16
2023-06-12T19:39:35.415199+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async wait failed - fail_count=1
2023-06-12T19:39:35.415215+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:504 Unable to set recovery mode. Recovery
failed.
2023-06-12T19:39:35.415239+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1921 Unable to set recovery mode to active on
cluster
2023-06-12T19:39:35.415257+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:35.415271+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:35.415285+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:35.415296+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async wait failed - fail_count=1
2023-06-12T19:39:35.415310+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_client.c:1558 Failed to read node capabilities.
2023-06-12T19:39:35.415325+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:456 Failed to get node capabilities
2023-06-12T19:39:35.415341+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:2636 Unable to update node capabilities.
2023-06-12T19:39:39.008818+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:39:39.229010+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Cluster lock taken successfully
2023-06-12T19:39:39.229085+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Took cluster lock, leader=0
2023-06-12T19:39:39.419851+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Node:0 was in recovery mode. Start recovery process
2023-06-12T19:39:39.419986+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Node:1 was in recovery mode. Start recovery process
2023-06-12T19:39:39.420005+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1312 Starting do_recovery
2023-06-12T19:39:39.420020+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1356 Recovery initiated due to problem with
node 0
2023-06-12T19:39:39.420479+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1386 Recovery - updated flags
2023-06-12T19:39:39.420531+08:00 host-192-168-40-131 ctdb-recoverd[2853595]: Set
recovery_helper to "/usr/libexec/ctdb/ctdb_recovery_helper"
2023-06-12T19:39:39.432698+08:00 host-192-168-40-131 ctdb-recovery[3065583]: Set
recovery mode to ACTIVE
2023-06-12T19:39:39.432822+08:00 host-192-168-40-131 ctdbd[2853172]: Recovery
has started
2023-06-12T19:39:39.433998+08:00 host-192-168-40-131 ctdbd[2853172]: Monitoring
event was cancelled
2023-06-12T19:39:39.523430+08:00 host-192-168-40-131 ctdb-recovery[3065583]:
start_recovery event finished
2023-06-12T19:39:39.523783+08:00 host-192-168-40-131 ctdb-recovery[3065583]:
updated VNNMAP
2023-06-12T19:39:39.523826+08:00 host-192-168-40-131 ctdb-recovery[3065583]:
recover database 0x6645c6c4
2023-06-12T19:39:39.524090+08:00 host-192-168-40-131 ctdbd[2853172]: Freeze db:
ctdb.tdb
2023-06-12T19:39:39.549471+08:00 host-192-168-40-131 ctdbd[2853172]: Thaw db:
ctdb.tdb generation 629720908
2023-06-12T19:39:39.549571+08:00 host-192-168-40-131 ctdbd[2853172]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:39.549613+08:00 host-192-168-40-131 ctdbd[2853172]: Resent
calls for database=ctdb.tdb, generation=629720908, count=0
2023-06-12T19:39:39.549895+08:00 host-192-168-40-131 ctdb-recovery[3065583]: 1
of 1 databases recovered
2023-06-12T19:39:39.549985+08:00 host-192-168-40-131 ctdbd[2853172]: Recovery
mode set to NORMAL
2023-06-12T19:39:39.779180+08:00 host-192-168-40-131 ctdb-recovery[3065583]: Set
recovery mode to NORMAL
2023-06-12T19:39:39.779404+08:00 host-192-168-40-131 ctdbd[2853172]: Recovery
has finished
2023-06-12T19:39:39.871666+08:00 host-192-168-40-131 ctdb-recovery[3065583]:
recovered event finished
2023-06-12T19:39:39.871811+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Takeover run starting
2023-06-12T19:39:39.871914+08:00 host-192-168-40-131 ctdb-recoverd[2853595]: Set
takeover_helper to "/usr/libexec/ctdb/ctdb_takeover_helper"
2023-06-12T19:39:39.887613+08:00 host-192-168-40-131 ctdbd[2853172]: Takeover of
IP 101.101.40.131/16 on interface bond1.906
2023-06-12T19:39:40.091901+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Takeover run completed successfully
2023-06-12T19:39:40.092002+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1404 Recovery complete
2023-06-12T19:39:40.092022+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Resetting ban count to 0 for all nodes
2023-06-12T19:39:40.092038+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Just finished a recovery. New recoveries will now be suppressed for the
rerecovery timeout (10 seconds)
2023-06-12T19:39:40.092057+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Disabling recoveries for 10 seconds
2023-06-12T19:39:41.420521+08:00 host-192-168-40-131 ctdbd[2853172]:
192.136.40.131:4379: connected to 192.136.40.133:4379 - 2 connected
2023-06-12T19:39:41.424132+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Pushing updated flags for node 0 (0x0)
2023-06-12T19:39:41.424411+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Pushing updated flags for node 1 (0x0)
2023-06-12T19:39:41.424595+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Remote node 2 had flags 0x0, local had 0x2 - updating local
2023-06-12T19:39:41.424624+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Pushing updated flags for node 2 (0x0)
2023-06-12T19:39:41.424697+08:00 host-192-168-40-131 ctdbd[2853172]: Node 2 has
changed flags - 0x2 -&gt; 0x0
2023-06-12T19:39:41.615784+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Received leader broadcast, leader=2
2023-06-12T19:39:42.895351+08:00 host-192-168-40-131 ctdbd[2853172]: Recovery
mode set to ACTIVE
2023-06-12T19:39:48.425262+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Leader broadcast timeout
2023-06-12T19:39:48.425472+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Start election
2023-06-12T19:39:50.092932+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Reenabling recoveries after timeout
2023-06-12T19:39:51.420623+08:00 host-192-168-40-131 ctdbd[2853172]: dead count
reached for node 2
2023-06-12T19:39:51.420823+08:00 host-192-168-40-131 ctdbd[2853172]: Tearing
down connection to dead node :2
2023-06-12T19:39:51.420902+08:00 host-192-168-40-131 ctdbd[2853172]:
192.136.40.131:4379: node 192.136.40.133:4379 is dead: 1 connected
2023-06-12T19:39:51.421146+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:51.421208+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:51.421229+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async operation failed with ret=-1 res=-1 opcode=16
2023-06-12T19:39:51.421250+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async wait failed - fail_count=1
2023-06-12T19:39:51.421270+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:504 Unable to set recovery mode. Recovery
failed.
2023-06-12T19:39:51.421288+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:1921 Unable to set recovery mode to active on
cluster
2023-06-12T19:39:51.421306+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:51.421340+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:51.421359+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:51.421374+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Async wait failed - fail_count=1
2023-06-12T19:39:51.421387+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_client.c:1558 Failed to read node capabilities.
2023-06-12T19:39:51.421403+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:456 Failed to get node capabilities
2023-06-12T19:39:51.421418+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
../../ctdb/server/ctdb_recoverd.c:2636 Unable to update node capabilities.
2023-06-12T19:39:56.422492+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Leader broadcast timeout
2023-06-12T19:39:56.422854+08:00 host-192-168-40-131 ctdb-recoverd[2853595]:
Start election
2023-06-12T19:39:58.426518+08:00 host-192-168-40-131 ctdbd[2853172]:
192.136.40.131:4379: connected to 192.136.40.133:4379 - 2 connected
......
2023-06-12T19:41:42.896165+08:00 host-192-168-40-131 ctdbd[2853172]:
../../ctdb/server/ctdb_recover.c:609 Been in recovery mode for too long.
Dropping all IPS
2023-06-12T19:41:43.129050+08:00 host-192-168-40-131 ctdbd[2853172]:
../../ctdb/server/ctdb_takeover.c:1689 Released 2 public IPs




node 1?
2023-06-12T19:38:21.816071+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Reenabling takeover runs
2023-06-12T19:38:23.567879+08:00 host-192-168-40-132 ctdbd[659192]: Node 0 has
changed flags - 0x2 -&gt; 0x0
2023-06-12T19:38:24.498391+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Disabling takeover runs for 60 seconds
2023-06-12T19:38:24.810767+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Reenabling takeover runs


2023-06-12T19:39:32.604151+08:00 host-192-168-40-132 ctdbd[659192]: Recovery
mode set to ACTIVE
2023-06-12T19:39:32.604185+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:39:32.604497+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:39:34.005643+08:00 host-192-168-40-132 ctdbd[659192]: dead count
reached for node 2
2023-06-12T19:39:34.005944+08:00 host-192-168-40-132 ctdbd[659192]: Tearing down
connection to dead node :2
2023-06-12T19:39:34.006030+08:00 host-192-168-40-132 ctdbd[659192]:
192.136.40.132:4379: node 192.136.40.133:4379 is dead: 1 connected
2023-06-12T19:39:34.006220+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.006270+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.006292+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async operation failed with ret=-1 res=-1 opcode=16
2023-06-12T19:39:34.006312+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async wait failed - fail_count=1
2023-06-12T19:39:34.006327+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:504 Unable to set recovery mode. Recovery
failed.
2023-06-12T19:39:34.006343+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:1921 Unable to set recovery mode to active on
cluster
2023-06-12T19:39:34.006355+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.006368+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.006388+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:34.006404+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async wait failed - fail_count=1
2023-06-12T19:39:34.006420+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_client.c:1558 Failed to read node capabilities.
2023-06-12T19:39:34.006445+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:456 Failed to get node capabilities
2023-06-12T19:39:34.006460+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:2636 Unable to update node capabilities.
2023-06-12T19:39:39.007830+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:39:39.008166+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:39:39.008670+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:39:39.239919+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:39:39.432969+08:00 host-192-168-40-132 ctdbd[659192]: Recovery has
started
2023-06-12T19:39:39.434278+08:00 host-192-168-40-132 ctdbd[659192]: Monitoring
event was cancelled
2023-06-12T19:39:39.524137+08:00 host-192-168-40-132 ctdbd[659192]: Freeze db:
ctdb.tdb
2023-06-12T19:39:39.549504+08:00 host-192-168-40-132 ctdbd[659192]: Thaw db:
ctdb.tdb generation 629720908
2023-06-12T19:39:39.549541+08:00 host-192-168-40-132 ctdbd[659192]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:39.549572+08:00 host-192-168-40-132 ctdbd[659192]: Resent calls
for database=ctdb.tdb, generation=629720908, count=0
2023-06-12T19:39:39.551083+08:00 host-192-168-40-132 ctdbd[659192]: Recovery
mode set to NORMAL
2023-06-12T19:39:39.685181+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Received leader broadcast, leader=0
2023-06-12T19:39:39.779475+08:00 host-192-168-40-132 ctdbd[659192]: Recovery has
finished
2023-06-12T19:39:39.872177+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Disabling takeover runs for 60 seconds
2023-06-12T19:39:40.092083+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Reenabling takeover runs
2023-06-12T19:39:42.013100+08:00 host-192-168-40-132 ctdbd[659192]:
192.136.40.132:4379: connected to 192.136.40.133:4379 - 2 connected
2023-06-12T19:39:42.617032+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Received leader broadcast, leader=2
2023-06-12T19:39:42.690377+08:00 host-192-168-40-132 ctdbd[659192]: Node 2 has
changed flags - 0x2 -&gt; 0x0
2023-06-12T19:39:42.895359+08:00 host-192-168-40-132 ctdbd[659192]: Recovery
mode set to ACTIVE
2023-06-12T19:39:42.895786+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:39:43.128864+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:39:48.243826+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:39:48.244196+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:39:52.012650+08:00 host-192-168-40-132 ctdbd[659192]: dead count
reached for node 2
2023-06-12T19:39:52.013026+08:00 host-192-168-40-132 ctdbd[659192]: Tearing down
connection to dead node :2
2023-06-12T19:39:52.013115+08:00 host-192-168-40-132 ctdbd[659192]:
192.136.40.132:4379: node 192.136.40.133:4379 is dead: 1 connected
2023-06-12T19:39:52.013315+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:52.013357+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:52.013377+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async operation failed with ret=-1 res=-1 opcode=16
2023-06-12T19:39:52.013395+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async wait failed - fail_count=1
2023-06-12T19:39:52.013412+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:504 Unable to set recovery mode. Recovery
failed.
2023-06-12T19:39:52.013426+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:1921 Unable to set recovery mode to active on
cluster
2023-06-12T19:39:52.013440+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:52.013451+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:52.013469+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:52.013484+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Async wait failed - fail_count=1
2023-06-12T19:39:52.013496+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_client.c:1558 Failed to read node capabilities.
2023-06-12T19:39:52.013510+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:456 Failed to get node capabilities
2023-06-12T19:39:52.013548+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
../../ctdb/server/ctdb_recoverd.c:2636 Unable to update node capabilities.
2023-06-12T19:39:58.361119+08:00 host-192-168-40-132 ctdbd[659192]:
192.136.40.132:4379: connected to 192.136.40.133:4379 - 2 connected
......
2023-06-12T19:41:21.395073+08:00 host-192-168-40-132 ctdbd[659192]:
192.136.40.132:4379: connected to 192.136.40.133:4379 - 2 connected
2023-06-12T19:41:23.457821+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:41:23.457993+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:41:23.458442+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:41:23.687664+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:41:33.460741+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:41:33.460987+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:41:33.461322+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:41:33.691522+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:41:38.463097+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:41:38.463319+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:41:38.463547+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:41:38.690525+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:41:42.896175+08:00 host-192-168-40-132 ctdbd[659192]:
../../ctdb/server/ctdb_recover.c:609 Been in recovery mode for too long.
Dropping all IPS
2023-06-12T19:41:43.015057+08:00 host-192-168-40-132 ctdbd[659192]:
../../ctdb/server/ctdb_takeover.c:1689 Released 1 public IPs
2023-06-12T19:41:48.465489+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout
2023-06-12T19:41:48.465680+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Start election
2023-06-12T19:41:48.466097+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Attempting to take cluster lock
(!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin fs_pool
ctdb_reclock 4)
2023-06-12T19:41:48.699376+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Unable to take cluster lock - contention
2023-06-12T19:41:53.467823+08:00 host-192-168-40-132 ctdb-recoverd[659348]:
Leader broadcast timeout




node 2
2023-06-12T19:38:24.810606+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Takeover run completed successfully
2023-06-12T19:39:34.343927+08:00 host-192-168-40-133 ctdbd[2520003]: dead count
reached for node 0
2023-06-12T19:39:34.344224+08:00 host-192-168-40-133 ctdbd[2520003]: Tearing
down connection to dead node :0
2023-06-12T19:39:34.344286+08:00 host-192-168-40-133 ctdbd[2520003]:
192.136.40.133:4379: node 192.136.40.131:4379 is dead: 1 connected
2023-06-12T19:39:34.344332+08:00 host-192-168-40-133 ctdbd[2520003]: dead count
reached for node 1
2023-06-12T19:39:34.344346+08:00 host-192-168-40-133 ctdbd[2520003]: Tearing
down connection to dead node :1
2023-06-12T19:39:34.344363+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.344385+08:00 host-192-168-40-133 ctdbd[2520003]:
192.136.40.133:4379: node 192.136.40.132:4379 is dead: 0 connected
2023-06-12T19:39:34.344402+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.344421+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:34.344444+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.344462+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
ctdb_control error: 'node is disconnected'
2023-06-12T19:39:34.344498+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Async operation failed with ret=-1 res=-1 opcode=80
2023-06-12T19:39:34.344512+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Async wait failed - fail_count=2
2023-06-12T19:39:34.344528+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_client.c:1558 Failed to read node capabilities.
2023-06-12T19:39:34.344540+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:456 Failed to get node capabilities
2023-06-12T19:39:34.344558+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:2636 Unable to update node capabilities.
2023-06-12T19:39:34.347698+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Assigned IP 101.101.40.131 not on an interface
2023-06-12T19:39:34.347741+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Trigger takeoverrun
2023-06-12T19:39:34.347831+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:2778 The vnnmap count is different from the
number of active lmaster nodes: 3 vs 1
2023-06-12T19:39:34.347883+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1312 Starting do_recovery
2023-06-12T19:39:34.347902+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1356 Recovery initiated due to problem with
node 2
2023-06-12T19:39:34.347968+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1386 Recovery - updated flags
2023-06-12T19:39:34.361318+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
mode set to ACTIVE
2023-06-12T19:39:34.361391+08:00 host-192-168-40-133 ctdb-recovery[2602609]: Set
recovery mode to ACTIVE
2023-06-12T19:39:34.361534+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
has started
2023-06-12T19:39:34.432177+08:00 host-192-168-40-133 ctdb-recovery[2602609]:
start_recovery event finished
2023-06-12T19:39:34.432300+08:00 host-192-168-40-133 ctdb-recovery[2602609]:
updated VNNMAP
2023-06-12T19:39:34.432332+08:00 host-192-168-40-133 ctdb-recovery[2602609]:
recover database 0x6645c6c4
2023-06-12T19:39:34.432552+08:00 host-192-168-40-133 ctdbd[2520003]: Freeze db:
ctdb.tdb
2023-06-12T19:39:34.444853+08:00 host-192-168-40-133 ctdbd[2520003]: Thaw db:
ctdb.tdb generation 2038499985
2023-06-12T19:39:34.444893+08:00 host-192-168-40-133 ctdbd[2520003]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:34.444929+08:00 host-192-168-40-133 ctdbd[2520003]: Resent
calls for database=ctdb.tdb, generation=2038499985, count=0
2023-06-12T19:39:34.445165+08:00 host-192-168-40-133 ctdb-recovery[2602609]: 1
of 1 databases recovered
2023-06-12T19:39:34.445242+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
mode set to NORMAL
2023-06-12T19:39:37.680876+08:00 host-192-168-40-133 ctdbd[2520003]: ERROR:
Daemon able to take recovery lock on
"!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin
fs_pool ctdb_reclock 4" during recovery
2023-06-12T19:39:37.681222+08:00 host-192-168-40-133 ctdb-recovery[2602609]:
failed to set recovery mode NORMAL on node 2, ret=-1
2023-06-12T19:39:37.681295+08:00 host-192-168-40-133 ctdb-recovery[2602609]:
database recovery failed, ret=-1
2023-06-12T19:39:37.683075+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1312 Starting do_recovery
2023-06-12T19:39:37.683118+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1356 Recovery initiated due to problem with
node 2
2023-06-12T19:39:37.683184+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1386 Recovery - updated flags
2023-06-12T19:39:37.696168+08:00 host-192-168-40-133 ctdb-recovery[2603390]: Set
recovery mode to ACTIVE
2023-06-12T19:39:37.696303+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
has started
2023-06-12T19:39:37.765714+08:00 host-192-168-40-133 ctdb-recovery[2603390]:
start_recovery event finished
2023-06-12T19:39:37.765836+08:00 host-192-168-40-133 ctdb-recovery[2603390]:
updated VNNMAP
2023-06-12T19:39:37.765868+08:00 host-192-168-40-133 ctdb-recovery[2603390]:
recover database 0x6645c6c4
2023-06-12T19:39:37.766049+08:00 host-192-168-40-133 ctdbd[2520003]: Freeze db:
ctdb.tdb
2023-06-12T19:39:37.782767+08:00 host-192-168-40-133 ctdbd[2520003]: Thaw db:
ctdb.tdb generation 17680608
2023-06-12T19:39:37.782805+08:00 host-192-168-40-133 ctdbd[2520003]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:37.782839+08:00 host-192-168-40-133 ctdbd[2520003]: Resent
calls for database=ctdb.tdb, generation=17680608, count=0
2023-06-12T19:39:37.783066+08:00 host-192-168-40-133 ctdb-recovery[2603390]: 1
of 1 databases recovered
2023-06-12T19:39:37.783141+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
mode set to NORMAL
2023-06-12T19:39:38.012885+08:00 host-192-168-40-133 ctdbd[2520003]: ERROR:
Daemon able to take recovery lock on
"!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin
fs_pool ctdb_reclock 4" during recovery
2023-06-12T19:39:38.013088+08:00 host-192-168-40-133 ctdb-recovery[2603390]:
failed to set recovery mode NORMAL on node 2, ret=-1
2023-06-12T19:39:38.013160+08:00 host-192-168-40-133 ctdb-recovery[2603390]:
database recovery failed, ret=-1
2023-06-12T19:39:38.683213+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1312 Starting do_recovery
2023-06-12T19:39:38.683268+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1356 Recovery initiated due to problem with
node 2
2023-06-12T19:39:38.683331+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1386 Recovery - updated flags
2023-06-12T19:39:38.696114+08:00 host-192-168-40-133 ctdb-recovery[2603477]: Set
recovery mode to ACTIVE
2023-06-12T19:39:38.696251+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
has started
2023-06-12T19:39:38.766848+08:00 host-192-168-40-133 ctdb-recovery[2603477]:
start_recovery event finished
2023-06-12T19:39:38.766949+08:00 host-192-168-40-133 ctdb-recovery[2603477]:
updated VNNMAP
2023-06-12T19:39:38.766977+08:00 host-192-168-40-133 ctdb-recovery[2603477]:
recover database 0x6645c6c4
2023-06-12T19:39:38.767114+08:00 host-192-168-40-133 ctdbd[2520003]: Freeze db:
ctdb.tdb
2023-06-12T19:39:38.783705+08:00 host-192-168-40-133 ctdbd[2520003]: Thaw db:
ctdb.tdb generation 1195788082
2023-06-12T19:39:38.783746+08:00 host-192-168-40-133 ctdbd[2520003]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:38.783782+08:00 host-192-168-40-133 ctdbd[2520003]: Resent
calls for database=ctdb.tdb, generation=1195788082, count=0
2023-06-12T19:39:38.784015+08:00 host-192-168-40-133 ctdb-recovery[2603477]: 1
of 1 databases recovered
2023-06-12T19:39:38.784084+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
mode set to NORMAL
2023-06-12T19:39:39.012847+08:00 host-192-168-40-133 ctdbd[2520003]: ERROR:
Daemon able to take recovery lock on
"!/usr/libexec/ctdb/ctdb_mutex_clove_rados_helper clove client.admin
fs_pool ctdb_reclock 4" during recovery
2023-06-12T19:39:39.012980+08:00 host-192-168-40-133 ctdb-recovery[2603477]:
failed to set recovery mode NORMAL on node 2, ret=-1
2023-06-12T19:39:39.013035+08:00 host-192-168-40-133 ctdb-recovery[2603477]:
database recovery failed, ret=-1
2023-06-12T19:39:39.684162+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1312 Starting do_recovery
2023-06-12T19:39:39.684386+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1356 Recovery initiated due to problem with
node 2
2023-06-12T19:39:39.684451+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
../../ctdb/server/ctdb_recoverd.c:1386 Recovery - updated flags
2023-06-12T19:39:39.697442+08:00 host-192-168-40-133 ctdb-recovery[2603566]: Set
recovery mode to ACTIVE
2023-06-12T19:39:39.697579+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
has started
2023-06-12T19:39:39.768395+08:00 host-192-168-40-133 ctdb-recovery[2603566]:
start_recovery event finished
2023-06-12T19:39:39.768527+08:00 host-192-168-40-133 ctdb-recovery[2603566]:
updated VNNMAP
2023-06-12T19:39:39.768563+08:00 host-192-168-40-133 ctdb-recovery[2603566]:
recover database 0x6645c6c4
2023-06-12T19:39:39.768781+08:00 host-192-168-40-133 ctdbd[2520003]: Freeze db:
ctdb.tdb
2023-06-12T19:39:39.785087+08:00 host-192-168-40-133 ctdbd[2520003]: Thaw db:
ctdb.tdb generation 1185443889
2023-06-12T19:39:39.785126+08:00 host-192-168-40-133 ctdbd[2520003]: Release
freeze handle for db ctdb.tdb
2023-06-12T19:39:39.785158+08:00 host-192-168-40-133 ctdbd[2520003]: Resent
calls for database=ctdb.tdb, generation=1185443889, count=0
2023-06-12T19:39:39.785483+08:00 host-192-168-40-133 ctdb-recovery[2603566]: 1
of 1 databases recovered
2023-06-12T19:39:39.785557+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
mode set to NORMAL
2023-06-12T19:39:40.016882+08:00 host-192-168-40-133 ctdb-recovery[2603566]: Set
recovery mode to NORMAL
2023-06-12T19:39:40.016973+08:00 host-192-168-40-133 ctdbd[2520003]: Recovery
has finished
2023-06-12T19:39:40.086536+08:00 host-192-168-40-133 ctdb-recovery[2603566]:
recovered event finished
2023-06-12T19:39:40.086620+08:00 host-192-168-40-133 ctdb-recoverd[2520071]:
Takeover run starting





????iPhone
samba - Jun 2023 - Create network oscillations on the leader node, resulting in brain splitting

[Samba] Create network oscillations on the leader node, resulting in brain splitting
