[pve-devel] corosync bug: cluster break after 1 node clean shutdown
Alexandre DERUMIER
aderumier at odiso.com
Mon Sep 28 11:35:00 CEST 2020
>>but, just to make sure, could you reproduce the issue once more, and
>>then (with debug symbols installed) run
>>
>>$ gdb -ex 'set pagination 0' -ex 'thread apply all bt' --batch -p $(pidof pmxcfs)
>>
>>on all nodes at the same time? this should minimize the fallout and show
>>us whether the thread that logged the first part of sending the state is
>>still around on the node that triggers the hang..
ok, no problem, I'll do a new test today
>>this looks like you bt-ed corosync this time around? if so, than this is
>>expected:
>>
>>- attach gdb to corosync
>>- corosync blocks
>>- other nodes notice corosync is gone on node X
>>- config change triggered
>>- sync restarts on all nodes, does not trigger bug this time
ok, thanks, make sense. I didn't notice this previously, but this time it was with corosync started.
----- Mail original -----
De: "Fabian Grünbichler" <f.gruenbichler at proxmox.com>
À: "Proxmox VE development discussion" <pve-devel at lists.proxmox.com>
Envoyé: Lundi 28 Septembre 2020 11:17:37
Objet: Re: [pve-devel] corosync bug: cluster break after 1 node clean shutdown
On September 25, 2020 6:29 pm, Alexandre DERUMIER wrote:
> here a new hang:
>
> http://odisoweb1.odiso.net/test4/
okay, so at least we now know something strange inside pmxcfs is going
on, and not inside corosync - we never reach the part where the broken
node (again #13 in this hang!) sends out the state message:
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] debug: dfsm mode is 1 (dfsm.c:706:dfsm_cpg_deliver_callback)
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] debug: received message's header type is 1 (dfsm.c:736:dfsm_cpg_deliver_callback)
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] debug: received state message (type = 1, subtype = 0, 32 bytes), mode is 1 (dfsm.c:782:dfsm_cpg_deliver_callback)
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] notice: received sync request (epoch 1/23389/000000A8) (dfsm.c:890:dfsm_cpg_deliver_callback)
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [main] debug: enter dfsm_release_sync_resources (dfsm.c:640:dfsm_release_sync_resources)
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] debug: enter dcdb_get_state 00000000365345C2 5F6E0B1F (dcdb.c:444:dcdb_get_state)
[...]
Sep 25 17:22:08 m6kvm13 pmxcfs[10086]: [dcdb] debug: dfsm_send_state_message_full: type 2 len 1 (dfsm.c:281:dfsm_send_state_message_full)
this should be followed by output like this (from the -unblock log,
where the sync went through):
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: send state message debug (dfsm.c:241:dfsm_send_message_full_debug_state)
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: cpg_handle 5109470997161967616 (dfsm.c:242:dfsm_send_message_full_debug_state)
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: iov[0] len 32 (dfsm.c:244:dfsm_send_message_full_debug_state)
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: iov[1] len 64792 (dfsm.c:244:dfsm_send_message_full_debug_state)
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: send state message loop body (dfsm.c:246:dfsm_send_message_full_debug_state)
Sep 25 17:57:39 m6kvm13 pmxcfs[10086]: [dcdb] notice: send state message result: 1 (dfsm.c:250:dfsm_send_message_full_debug_state)
but this never happens. the relevant code from our patched dfsm.c
(reordered):
static cs_error_t
dfsm_send_state_message_full(
dfsm_t *dfsm,
uint16_t type,
struct iovec *iov,
unsigned int len)
{
g_return_val_if_fail(dfsm != NULL, CS_ERR_INVALID_PARAM);
g_return_val_if_fail(DFSM_VALID_STATE_MESSAGE(type), CS_ERR_INVALID_PARAM);
g_return_val_if_fail(!len || iov != NULL, CS_ERR_INVALID_PARAM);
// this message is still logged
cfs_dom_debug(dfsm->log_domain, "dfsm_send_state_message_full: type %d len %d", type, len);
// everything below this point might not have happened anymore
dfsm_message_state_header_t header;
header.base.type = type;
header.base.subtype = 0;
header.base.protocol_version = dfsm->protocol_version;
header.base.time = time(NULL);
header.base.reserved = 0;
header.epoch = dfsm->sync_epoch;
struct iovec real_iov[len + 1];
real_iov[0].iov_base = (char *)&header;
real_iov[0].iov_len = sizeof(header);
for (int i = 0; i < len; i++)
real_iov[i + 1] = iov[i];
return type == DFSM_MESSAGE_STATE ? dfsm_send_message_full_debug_state(dfsm, real_iov, len + 1, 1) : dfsm_send_message_full(dfsm, real_iov, len + 1, 1);
}
static cs_error_t
dfsm_send_message_full_debug_state(
dfsm_t *dfsm,
struct iovec *iov,
unsigned int len,
int retry)
{
g_return_val_if_fail(dfsm != NULL, CS_ERR_INVALID_PARAM);
g_return_val_if_fail(!len || iov != NULL, CS_ERR_INVALID_PARAM);
struct timespec tvreq = { .tv_sec = 0, .tv_nsec = 100000000 };
cs_error_t result;
int retries = 0;
// this message is not visible in log
// we don't know how far above this we managed to run
cfs_dom_message(dfsm->log_domain, "send state message debug");
cfs_dom_message(dfsm->log_domain, "cpg_handle %" PRIu64, dfsm->cpg_handle);
for (int i = 0; i < len; i++)
cfs_dom_message(dfsm->log_domain, "iov[%d] len %zd", i, iov[i].iov_len);
loop:
cfs_dom_message(dfsm->log_domain, "send state message loop body");
result = cpg_mcast_joined(dfsm->cpg_handle, CPG_TYPE_AGREED, iov, len);
cfs_dom_message(dfsm->log_domain, "send state message result: %d", result);
if (retry && result == CS_ERR_TRY_AGAIN) {
nanosleep(&tvreq, NULL);
++retries;
if ((retries % 10) == 0)
cfs_dom_message(dfsm->log_domain, "cpg_send_message retry %d", retries);
if (retries < 100)
goto loop;
}
if (retries)
cfs_dom_message(dfsm->log_domain, "cpg_send_message retried %d times", retries);
if (result != CS_OK &&
(!retry || result != CS_ERR_TRY_AGAIN))
cfs_dom_critical(dfsm->log_domain, "cpg_send_message failed: %d", result);
return result;
}
I don't see much that could go wrong inside dfsm_send_state_message_full
after the debug log statement (it's just filling out the header and iov
structs, and calling 'dfsm_send_message_full_debug_state' since type ==
2 == DFSM_MESSAGE_STATE).
inside dfsm_send_message_full_debug, before the first log statement we
only check for dfsm or the message length/content being NULL/0, all of
which can't really happen with that call path. also, in that case we'd
return CS_ERR_INVALID_PARAM , which would bubble up into the delivery
callback and cause us to leave CPG, which would again be visible in the
logs..
but, just to make sure, could you reproduce the issue once more, and
then (with debug symbols installed) run
$ gdb -ex 'set pagination 0' -ex 'thread apply all bt' --batch -p $(pidof pmxcfs)
on all nodes at the same time? this should minimize the fallout and show
us whether the thread that logged the first part of sending the state is
still around on the node that triggers the hang..
> Something new: where doing coredump or bt-full on pmxcfs on node1,
> this have unlocked /etc/pve on other nodes
>
> /etc/pve unlocked(with coredump or bt-full): 17:57:40
this looks like you bt-ed corosync this time around? if so, than this is
expected:
- attach gdb to corosync
- corosync blocks
- other nodes notice corosync is gone on node X
- config change triggered
- sync restarts on all nodes, does not trigger bug this time
_______________________________________________
pve-devel mailing list
pve-devel at lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel
More information about the pve-devel
mailing list