From mboxrd@z Thu Jan 1 00:00:00 1970
Return-Path: <aderumier@odiso.com>
Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68])
(using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
key-exchange X25519 server-signature RSA-PSS (2048 bits))
(No client certificate requested)
by lists.proxmox.com (Postfix) with ESMTPS id E273860ACC
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:16:21 +0200 (CEST)
Received: from firstgate.proxmox.com (localhost [127.0.0.1])
by firstgate.proxmox.com (Proxmox) with ESMTP id DC966187BE
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:15:51 +0200 (CEST)
Received: from mailpro.odiso.net (mailpro.odiso.net [89.248.211.110])
(using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits))
(No client certificate requested)
by firstgate.proxmox.com (Proxmox) with ESMTPS id 49F46187B4
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:15:50 +0200 (CEST)
Received: from localhost (localhost [127.0.0.1])
by mailpro.odiso.net (Postfix) with ESMTP id 200991BBA274
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:15:50 +0200 (CEST)
Received: from mailpro.odiso.net ([127.0.0.1])
by localhost (mailpro.odiso.net [127.0.0.1]) (amavisd-new, port 10032)
with ESMTP id Pwga8EmmwzMb for <pve-devel@lists.proxmox.com>;
Fri, 25 Sep 2020 09:15:50 +0200 (CEST)
Received: from localhost (localhost [127.0.0.1])
by mailpro.odiso.net (Postfix) with ESMTP id 031381BBA27C
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:15:50 +0200 (CEST)
X-Virus-Scanned: amavisd-new at mailpro.odiso.com
Received: from mailpro.odiso.net ([127.0.0.1])
by localhost (mailpro.odiso.net [127.0.0.1]) (amavisd-new, port 10026)
with ESMTP id XkCsfJTad-Uy for <pve-devel@lists.proxmox.com>;
Fri, 25 Sep 2020 09:15:49 +0200 (CEST)
Received: from mailpro.odiso.net (mailpro.odiso.net [10.1.31.111])
by mailpro.odiso.net (Postfix) with ESMTP id DFCF41BBA274
for <pve-devel@lists.proxmox.com>; Fri, 25 Sep 2020 09:15:49 +0200 (CEST)
Date: Fri, 25 Sep 2020 09:15:49 +0200 (CEST)
From: Alexandre DERUMIER <aderumier@odiso.com>
To: Proxmox VE development discussion <pve-devel@lists.proxmox.com>
Message-ID: <1264529857.1248647.1601018149719.JavaMail.zimbra@odiso.com>
In-Reply-To: <2019315449.1247737.1601016264202.JavaMail.zimbra@odiso.com>
References: <216436814.339545.1599142316781.JavaMail.zimbra@odiso.com>
<501f031f-3f1b-0633-fab3-7fcb7fdddaf5@proxmox.com>
<335862527.964527.1600646099489.JavaMail.zimbra@odiso.com>
<7286111.1004215.1600753433567.JavaMail.zimbra@odiso.com>
<1600955976.my09kyug7a.astroid@nora.none>
<448071987.1233936.1600957757611.JavaMail.zimbra@odiso.com>
<906463192.1239798.1600970863982.JavaMail.zimbra@odiso.com>
<2019315449.1247737.1601016264202.JavaMail.zimbra@odiso.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
X-Mailer: Zimbra 8.8.12_GA_3866 (ZimbraWebClient - GC83 (Linux)/8.8.12_GA_3844)
Thread-Topic: corosync bug: cluster break after 1 node clean shutdown
Thread-Index: 9/7vDexiYTrgZ2b8e1L+mbuGAIj+sLY8NnWCQ82iBz0syN/mbg==
X-SPAM-LEVEL: Spam detection results: 0
AWL -0.113 Adjusted score from AWL reputation of From: address
KAM_ASCII_DIVIDERS 0.8 Spam that uses ascii formatting tricks
KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment
KAM_LOTSOFHASH 0.25 Emails with lots of hash-like gibberish
RCVD_IN_DNSWL_NONE -0.0001 Sender listed at https://www.dnswl.org/,
no trust
SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record
SPF_PASS -0.001 SPF: sender matches SPF record
URIBL_BLOCKED 0.001 ADMINISTRATOR NOTICE: The query to URIBL was blocked. See
http://wiki.apache.org/spamassassin/DnsBlocklists#dnsbl-block for more
information. [odiso.net, proxmox.com]
Subject: Re: [pve-devel] corosync bug: cluster break after 1 node clean
shutdown
X-BeenThere: pve-devel@lists.proxmox.com
X-Mailman-Version: 2.1.29
Precedence: list
List-Id: Proxmox VE development discussion <pve-devel.lists.proxmox.com>
List-Unsubscribe: <https://lists.proxmox.com/cgi-bin/mailman/options/pve-devel>,
<mailto:pve-devel-request@lists.proxmox.com?subject=unsubscribe>
List-Archive: <http://lists.proxmox.com/pipermail/pve-devel/>
List-Post: <mailto:pve-devel@lists.proxmox.com>
List-Help: <mailto:pve-devel-request@lists.proxmox.com?subject=help>
List-Subscribe: <https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel>,
<mailto:pve-devel-request@lists.proxmox.com?subject=subscribe>
X-List-Received-Date: Fri, 25 Sep 2020 07:16:21 -0000
Another hang, this time on corosync stop, coredump available
http://odisoweb1.odiso.net/test3/=20
=
=20
node1
----
stop corosync : 09:03:10
node2: /etc/pve locked
------
Current time : 09:03:10
----- Mail original -----
De: "aderumier" <aderumier@odiso.com>
=C3=80: "Proxmox VE development discussion" <pve-devel@lists.proxmox.com>
Envoy=C3=A9: Vendredi 25 Septembre 2020 08:44:24
Objet: Re: [pve-devel] corosync bug: cluster break after 1 node clean shutd=
own
Another test this morning with the coredump available=20
http://odisoweb1.odiso.net/test2/=20
Something different this time, it has happened on corosync start=20
node1 (corosync start)=20
------=20
start corosync : 08:06:56=20
node2 (/etc/pve locked)=20
-----=20
Current time : 08:07:01=20
I had a warning on coredump=20
(gdb) generate-core-file=20
warning: target file /proc/35248/cmdline contained unexpected null characte=
rs=20
warning: Memory read failed for corefile section, 4096 bytes at 0xfffffffff=
f600000.=20
Saved corefile core.35248=20
I hope it's ok.=20
I'll do another test this morning=20
----- Mail original -----=20
De: "aderumier" <aderumier@odiso.com>=20
=C3=80: "Proxmox VE development discussion" <pve-devel@lists.proxmox.com>=
=20
Envoy=C3=A9: Jeudi 24 Septembre 2020 20:07:43=20
Objet: Re: [pve-devel] corosync bug: cluster break after 1 node clean shutd=
own=20
I was able to reproduce=20
stop corosync on node1 : 18:12:29=20
/etc/pve locked at 18:12:30=20
logs of all nodes are here:=20
http://odisoweb1.odiso.net/test1/=20
I don't have coredump, as my coworker have restarted pmxcfs too fast :/ . S=
orry.=20
I'm going to launch another test with coredump this time=20
----- Mail original -----=20
De: "aderumier" <aderumier@odiso.com>=20
=C3=80: "Proxmox VE development discussion" <pve-devel@lists.proxmox.com>=
=20
Envoy=C3=A9: Jeudi 24 Septembre 2020 16:29:17=20
Objet: Re: [pve-devel] corosync bug: cluster break after 1 node clean shutd=
own=20
Hi fabian,=20
>>if you are still able to test, it would be great if you could give the=20
>>following packages a spin (they only contain some extra debug prints=20
>>on message processing/sending):=20
Sure, no problem, I'm going to test it tonight.=20
>>ideally, you could get the debug logs from all nodes, and the=20
>>coredump/bt from the node where pmxcfs hangs. thanks!=20
ok,no problem.=20
I'll keep you in touch tomorrow.=20
----- Mail original -----=20
De: "Fabian Gr=C3=BCnbichler" <f.gruenbichler@proxmox.com>=20
=C3=80: "Proxmox VE development discussion" <pve-devel@lists.proxmox.com>=
=20
Envoy=C3=A9: Jeudi 24 Septembre 2020 16:02:04=20
Objet: Re: [pve-devel] corosync bug: cluster break after 1 node clean shutd=
own=20
On September 22, 2020 7:43 am, Alexandre DERUMIER wrote:=20
> I have done test with "kill -9 <pidofcorosync", and I have around 20s han=
g on other nodes,=20
> but after that it's become available again.=20
>=20
>=20
> So, it's really something when corosync is in shutdown phase, and pmxcfs =
is running.=20
>=20
> So, for now, as workaround, I have changed=20
>=20
> /lib/systemd/system/pve-cluster.service=20
>=20
> #Wants=3Dcorosync.service=20
> #Before=3Dcorosync.service=20
> Requires=3Dcorosync.service=20
> After=3Dcorosync.service=20
>=20
>=20
> Like this, at shutdown, pve-cluster is stopped before corosync, and if I =
restart corosync, pve-cluster is stopped first.=20
if you are still able to test, it would be great if you could give the=20
following packages a spin (they only contain some extra debug prints=20
on message processing/sending):=20
http://download.proxmox.com/temp/pmxcfs-dbg/=20
64eb9dbd2f60fe319abaeece89a84fd5de1f05a8c38cb9871058ec1f55025486ec15b7c0053=
976159fe5c2518615fd80084925abf4d3a5061ea7d6edef264c36 pve-cluster_6.1-8_amd=
64.deb=20
04b557c7f0dc1aa2846b534d6afab70c2b8d4720ac307364e015d885e2e997b6dcaa54cad67=
3b22d626d27cb053e5723510fde15d078d5fe1f262fc5486e6cef pve-cluster-dbgsym_6.=
1-8_amd64.deb=20
ideally, you could get the debug logs from all nodes, and the=20
coredump/bt from the node where pmxcfs hangs. thanks!=20
diff --git a/data/src/dfsm.c b/data/src/dfsm.c=20
index 529c7f9..e0bd93f 100644=20
--- a/data/src/dfsm.c=20
+++ b/data/src/dfsm.c=20
@@ -162,8 +162,8 @@ static void=20
dfsm_send_sync_message_abort(dfsm_t *dfsm)=20
{=20
g_return_if_fail(dfsm !=3D NULL);=20
-=20
g_mutex_lock (&dfsm->sync_mutex);=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_send_sync_message_abort - %" PRIu64=
" / %" PRIu64, dfsm->msgcount_rcvd, dfsm->msgcount);=20
dfsm->msgcount_rcvd =3D dfsm->msgcount;=20
g_cond_broadcast (&dfsm->sync_cond);=20
g_mutex_unlock (&dfsm->sync_mutex);=20
@@ -181,6 +181,7 @@ dfsm_record_local_result(=20
g_mutex_lock (&dfsm->sync_mutex);=20
dfsm_result_t *rp =3D (dfsm_result_t *)g_hash_table_lookup(dfsm->results, &=
msg_count);=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_record_local_result - %" PRIu64": %=
d", msg_count, msg_result);=20
if (rp) {=20
rp->result =3D msg_result;=20
rp->processed =3D processed;=20
@@ -235,6 +236,8 @@ dfsm_send_state_message_full(=20
g_return_val_if_fail(DFSM_VALID_STATE_MESSAGE(type), CS_ERR_INVALID_PARAM);=
=20
g_return_val_if_fail(!len || iov !=3D NULL, CS_ERR_INVALID_PARAM);=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_send_state_message_full: type %d le=
n %d", type, len);=20
+=20
dfsm_message_state_header_t header;=20
header.base.type =3D type;=20
header.base.subtype =3D 0;=20
@@ -317,6 +320,7 @@ dfsm_send_message_sync(=20
for (int i =3D 0; i < len; i++)=20
real_iov[i + 1] =3D iov[i];=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_send_messag_sync: type NORMAL, msgt=
ype %d, len %d", msgtype, len);=20
cs_error_t result =3D dfsm_send_message_full(dfsm, real_iov, len + 1, 1);=
=20
g_mutex_unlock (&dfsm->sync_mutex);=20
@@ -335,10 +339,12 @@ dfsm_send_message_sync(=20
if (rp) {=20
g_mutex_lock (&dfsm->sync_mutex);=20
- while (dfsm->msgcount_rcvd < msgcount)=20
+ while (dfsm->msgcount_rcvd < msgcount) {=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_send_message_sync: waiting for rece=
ived messages %" PRIu64 " / %" PRIu64, dfsm->msgcount_rcvd, msgcount);=20
g_cond_wait (&dfsm->sync_cond, &dfsm->sync_mutex);=20
+ }=20
+ cfs_dom_debug(dfsm->log_domain, "dfsm_send_message_sync: done waiting for=
received messages!");=20
-=20
g_hash_table_remove(dfsm->results, &rp->msgcount);=20
g_mutex_unlock (&dfsm->sync_mutex);=20
@@ -685,9 +691,13 @@ dfsm_cpg_deliver_callback(=20
return;=20
}=20
+ cfs_dom_debug(dfsm->log_domain, "received message's header type is %d", b=
ase_header->type);=20
+=20
if (base_header->type =3D=3D DFSM_MESSAGE_NORMAL) {=20
dfsm_message_normal_header_t *header =3D (dfsm_message_normal_header_t *)ms=
g;=20
+ cfs_dom_debug(dfsm->log_domain, "received normal message (type =3D %d, su=
btype =3D %d, %zd bytes)",=20
+ base_header->type, base_header->subtype, msg_len);=20
if (msg_len < sizeof(dfsm_message_normal_header_t)) {=20
cfs_dom_critical(dfsm->log_domain, "received short message (type =3D %d, su=
btype =3D %d, %zd bytes)",=20
@@ -704,6 +714,8 @@ dfsm_cpg_deliver_callback(=20
} else {=20
int msg_res =3D -1;=20
+ cfs_dom_debug(dfsm->log_domain, "deliver message %" PRIu64 " (subtype =3D=
%d, length =3D %zd)",=20
+ header->count, base_header->subtype, msg_len);=20
int res =3D dfsm->dfsm_callbacks->dfsm_deliver_fn(=20
dfsm, dfsm->data, &msg_res, nodeid, pid, base_header->subtype,=20
base_header->time, (uint8_t *)msg + sizeof(dfsm_message_normal_header_t),=
=20
@@ -724,6 +736,8 @@ dfsm_cpg_deliver_callback(=20
*/=20
dfsm_message_state_header_t *header =3D (dfsm_message_state_header_t *)msg;=
=20
+ cfs_dom_debug(dfsm->log_domain, "received state message (type =3D %d, sub=
type =3D %d, %zd bytes), mode is %d",=20
+ base_header->type, base_header->subtype, msg_len, mode);=20
if (msg_len < sizeof(dfsm_message_state_header_t)) {=20
cfs_dom_critical(dfsm->log_domain, "received short state message (type =3D =
%d, subtype =3D %d, %zd bytes)",=20
@@ -744,6 +758,7 @@ dfsm_cpg_deliver_callback(=20
if (mode =3D=3D DFSM_MODE_SYNCED) {=20
if (base_header->type =3D=3D DFSM_MESSAGE_UPDATE_COMPLETE) {=20
+ cfs_dom_debug(dfsm->log_domain, "received update complete message");=20
for (int i =3D 0; i < dfsm->sync_info->node_count; i++)=20
dfsm->sync_info->nodes[i].synced =3D 1;=20
@@ -754,6 +769,7 @@ dfsm_cpg_deliver_callback(=20
return;=20
} else if (base_header->type =3D=3D DFSM_MESSAGE_VERIFY_REQUEST) {=20
+ cfs_dom_debug(dfsm->log_domain, "received verify request message");=20
if (msg_len !=3D sizeof(dfsm->csum_counter)) {=20
cfs_dom_critical(dfsm->log_domain, "cpg received verify request with wrong =
length (%zd bytes) form node %d/%d", msg_len, nodeid, pid);=20
@@ -823,7 +839,6 @@ dfsm_cpg_deliver_callback(=20
} else if (mode =3D=3D DFSM_MODE_START_SYNC) {=20
if (base_header->type =3D=3D DFSM_MESSAGE_SYNC_START) {=20
-=20
if (nodeid !=3D dfsm->lowest_nodeid) {=20
cfs_dom_critical(dfsm->log_domain, "ignore sync request from wrong member %=
d/%d",=20
nodeid, pid);=20
@@ -861,6 +876,7 @@ dfsm_cpg_deliver_callback(=20
return;=20
} else if (base_header->type =3D=3D DFSM_MESSAGE_STATE) {=20
+ cfs_dom_debug(dfsm->log_domain, "received state message for %d/%d", nodei=
d, pid);=20
dfsm_node_info_t *ni;=20
@@ -906,6 +922,8 @@ dfsm_cpg_deliver_callback(=20
goto leave;=20
}=20
+ } else {=20
+ cfs_dom_debug(dfsm->log_domain, "haven't received all states, waiting for=
more");=20
}=20
return;=20
@@ -914,6 +932,7 @@ dfsm_cpg_deliver_callback(=20
} else if (mode =3D=3D DFSM_MODE_UPDATE) {=20
if (base_header->type =3D=3D DFSM_MESSAGE_UPDATE) {=20
+ cfs_dom_debug(dfsm->log_domain, "received update message");=20
int res =3D dfsm->dfsm_callbacks->dfsm_process_update_fn(=20
dfsm, dfsm->data, dfsm->sync_info, nodeid, pid, msg, msg_len);=20
@@ -925,6 +944,7 @@ dfsm_cpg_deliver_callback(=20
} else if (base_header->type =3D=3D DFSM_MESSAGE_UPDATE_COMPLETE) {=20
+ cfs_dom_debug(dfsm->log_domain, "received update complete message");=20
int res =3D dfsm->dfsm_callbacks->dfsm_commit_fn(dfsm, dfsm->data, dfsm->sy=
nc_info);=20
@@ -1104,6 +1124,7 @@ dfsm_cpg_confchg_callback(=20
size_t joined_list_entries)=20
{=20
cs_error_t result;=20
+ cfs_debug("dfsm_cpg_confchg_callback called");=20
dfsm_t *dfsm =3D NULL;=20
result =3D cpg_context_get(handle, (gpointer *)&dfsm);=20
_______________________________________________=20
pve-devel mailing list=20
pve-devel@lists.proxmox.com=20
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel=20
_______________________________________________=20
pve-devel mailing list=20
pve-devel@lists.proxmox.com=20
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel=20
_______________________________________________=20
pve-devel mailing list=20
pve-devel@lists.proxmox.com=20
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel=20
_______________________________________________=20
pve-devel mailing list=20
pve-devel@lists.proxmox.com=20
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pve-devel=20