Re: [pve-devel] corosync bug: cluster break after 1 node clean shutdown

["Fabian Grünbichler" <f.gruenbichler@proxmox.com>]

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