Hi Thuan,
I agree with Minh. We need to know why Node left has come
before and Mds down came later and about other flows. I would be great if you
could please reproduce the scenario and upload the traces of payload and
controller(Please keep the time in sync) in the ticket.
Thanks,
Nagendra, 91-9866424860
www.hasolutions.in
https://www.linkedin.com/company/hasolutions/
High Availability Solutions Pvt. Ltd.
- OpenSAF support and services
--------- Original Message --------- Subject: Re: [PATCH 1/1] amf: amfd should
reset msg_id counter to avoid message ID mismatch [#2891]
From: "Minh Hon Chau" <minh.c...@dektech.com.au>
Date: 7/10/18 10:49 am
To: "Tran Thuan" <thuan.t...@dektech.com.au>, nagen...@hasolutions.in,
hans.nordeb...@ericsson.com, gary....@dektech.com.au
Cc: opensaf-devel@lists.sourceforge.net
Hi again,
I am not sure how you replicate this scenario. It looks to me you
deliberately reboot the PL-3 before amfd process the synced assignment.
The node_up sequence has many branches, you are replicating one of those.
What I mean, at the time amfd calls avd_process_state_info_queue(), PL
has not joined the AMF cluster and PL keeps resending node_up message
for every one second.
When amfd finishes creating synced assignment, the node sync windows is
still open, the cb->init_state has not moved to APP_STATE, so the
node_up of PL is still acceptable. At this time a PL can be reboot by
someone.
For your reference, I attach to ticket the full trace of amfd, I have to
turn off PL-3 to trigger the node sync window up 10 seconds, I reboot
PL-4. Please note this scenario of node sync timeout did happen at
application sides.
Reseting the counters in CLM callback is easy way, but it's not fully
fixed and not make us safe from the issue.
Thanks
Minh
On 10/07/18 14:00, Tran Thuan wrote:
> Hi Minh,
>
> I check your concern about if PL down before sending node up but after
> synced assignments (recover after headless).
> Current code still work correctly. Because active AMFD don't recreate
> assignments.
> So, my point of view is still there, just reset 3 fields as current patch.
>
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO Synced
> SISU:safSi=NoRed2,safApp=OpenSAF,safSu=PL-3,safSg=NoRed,safApp=OpenSAF <1, 3>
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO Synced
> SU:safSu=PL-3,safSg=NoRed,safApp=OpenSAF <0, 1, 3>
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO 8 CSICOMP states sent
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO 8 COMP states sent
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO Sending node up due to
> NCSMDS_NEW_ACTIVE
> Jul 10 13:40:05 PL-2-3 osafamfnd[5971]: NO ====================delay to
> power off this node ====================
> Jul 10 13:40:05 PL-2-3 osafckptnd[5984]: NO CLM selection object was
> updated. (17)
> Jul 10 13:40:06 PL-2-3 osafamfnd[5971]: NO ====================delay to
> power off this node ====================
> Jul 10 13:40:07 PL-2-3 osafamfnd[5971]: NO ====================delay to
> power off this node ====================
> Jul 10 13:40:08 PL-2-3 osafamfnd[5971]: NO ====================delay to
> power off this node ====================
>
> <143>1 2018-07-10T13:40:15.365252+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13233"] 4827:amf/amfd/ndfsm.cc:296 >> avd_node_up_evh: from
> 2010f, safAmfNode=SC-1,safAmfCluster=myAmfCluster
> <143>1 2018-07-10T13:40:15.365259+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13234"] 4827:amf/amfd/node.cc:231 >> avd_node_get:
> safAmfNode=SC-1,safAmfCluster=myAmfCluster
> <143>1 2018-07-10T13:40:15.365263+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13235"] 4827:amf/amfd/node.cc:232 << avd_node_get
> <143>1 2018-07-10T13:40:15.365314+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13236"] 4827:amf/amfd/ndfsm.cc:216 >> avd_count_node_up
> <143>1 2018-07-10T13:40:15.36532+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13237"] 4827:amf/amfd/ndfsm.cc:226 TR Number of node director(s)
> that director received node_up msg:0
> <143>1 2018-07-10T13:40:15.365325+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13238"] 4827:amf/amfd/ndfsm.cc:228 << avd_count_node_up
> <143>1 2018-07-10T13:40:15.365329+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13239"] 4827:amf/amfd/ndfsm.cc:353 TR NodeSync timer is active,
> ignore this node_up msg (nodeid:2010f)
> <143>1 2018-07-10T13:40:15.365334+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13240"] 4827:amf/amfd/ndfsm.cc:534 << avd_node_up_evh
>
> <143>1 2018-07-10T13:40:16.462939+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13280"] 4827:amf/amfd/ndfsm.cc:296 >> avd_node_up_evh: from
> 2010f, safAmfNode=SC-1,safAmfCluster=myAmfCluster
> <141>1 2018-07-10T13:40:16.462975+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13281"] 4827:amf/amfd/ndfsm.cc:254 NO Received node_up from
> 2010f: msg_id 1
> <143>1 2018-07-10T13:40:16.462981+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13282"] 4827:amf/amfd/ndfsm.cc:63 >> avd_process_state_info_queue
> <143>1 2018-07-10T13:40:16.462986+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13283"] 4827:amf/amfd/ndfsm.cc:65 TR queue_size before
> processing: 2
> <143>1 2018-07-10T13:40:16.463162+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13284"] 4827:amf/amfd/ndfsm.cc:73 TR rcv_evt: 12
> <143>1 2018-07-10T13:40:16.463175+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13285"] 4827:amf/amfd/ndfsm.cc:79 TR msg_type: 31
> <143>1 2018-07-10T13:40:16.463203+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13286"] 4827:amf/amfd/siass.cc:1132 >> avd_susi_recreate:
> msg_id: 0 node_id: 131855 num_sisu: 3
> <139>1 2018-07-10T13:40:16.463224+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13287"] 4827:amf/amfd/siass.cc:1140 ER Node 2030f has left the
> cluster
> <143>1 2018-07-10T13:40:16.463258+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13288"] 4827:amf/amfd/siass.cc:0 << avd_susi_recreate
> <143>1 2018-07-10T13:40:16.463273+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13289"] 4827:amf/common/d2nmsg.c:931 >>
> avsv_free_n2d_nd_sisu_state_info
> <143>1 2018-07-10T13:40:16.463278+10:00 SC-2-1 osafamfd 4827 osafamfd [meta
> sequenceId="13290"] 4827:amf/common/d2nmsg.c:953 TR 3 SISU records to free
>
> Best Regards,
> Thuan
>
> -----Original Message-----
> From: Minh Hon Chau <minh.c...@dektech.com.au>
> Sent: Monday, July 9, 2018 4:04 PM
> To: Tran Thuan <thuan.t...@dektech.com.au>; nagen...@hasolutions.in;
> hans.nordeb...@ericsson.com; gary....@dektech.com.au
> Cc: opensaf-devel@lists.sourceforge.net
> Subject: Re: [PATCH 1/1] amf: amfd should reset msg_id counter to avoid
> message ID mismatch [#2891]
>
> Hi,
>
> How about the @nodes_exit_cnt? The active amfd checkpoints this
> @nodes_exit_cnt to the standby amfd inside mds down event. You can say it's
> not used but it's what's happening for this counter.
>
> "AMFND not yet up", what you mean is node_state AVD_AVND_STATE_ABSENT?
> You reset counter if node state as AVD_AVND_STATE_ABSENT in clm callback.
> If a payload is coming from headless, it syncs the assignments to the active
> amfd first and enters node_up sequence. This node_up sequence can take up to
> 10 seconds before this payload becomes AVD_AVND_STATE_PRESENT.
> If this issue happens during this 10 seconds, the node_state is still
> AVD_AVND_STATE_ABSENT and active amfd does not process mds down event
> properly, how could amfd remove the synced assignment?
>
> As mentioned, the problem is not that the active amfd is missing 1, 2 or
> 3 counters to be reset, it misses to process the mds down event properly.
>
> Are you able to reproduce this problem?
>
> Thanks
> Minh
>
> On 09/07/18 16:33, Tran Thuan wrote:
>> Hi Minh,
>>
>> Since AMFND not yet up before, other fields are not updated yet.
>> I think only 3 fields is changed in this scenario, that's why my is reset
>> them only.
>> Do you think so?
>>
>> Best Regards,
>> Thuan
>>
>> -----Original Message-----
>> From: Minh Hon Chau <minh.c...@dektech.com.au>
>> Sent: Monday, July 9, 2018 1:22 PM
>> To: Tran Thuan <thuan.t...@dektech.com.au>; nagen...@hasolutions.in;
>> hans.nordeb...@ericsson.com; gary....@dektech.com.au
>> Cc: opensaf-devel@lists.sourceforge.net
>> Subject: Re: [PATCH 1/1] amf: amfd should reset msg_id counter to
>> avoid message ID mismatch [#2891]
>>
>> Hi,
>>
>> Ok, so we can ignore the "AMFND already up" case.
>>
>> "- AMFND not yet up before (node reboot up/first up): this is our issue.
>> + current only delete node without care msg_id counter."
>>
>> Are you able to reproduce this problem?
>> You only reset the msg_id counter of a node, how about the others:
>> adest, recvr_fail_sw, node_info.initialViewNumber, nodes_exit_cnt,..
>> they all are checked in the other places.
>> Also, when the node goes down, the standby resets all of above variables
>> directly, while the active doesn't as of this issue or only resets msg_id
>> counters within your patch. The active and standby may not be consistent.
>>
>> Another thing you may consider, if any new/old attributes/variables of
>> AVD_AVND is going to be added/removed, we only look at one place - event of
>> MDS down, don't have to look at/reset those ones in the CLM callback.
>>
>> Thanks
>> Minh
>>
>> On 09/07/18 12:12, Tran Thuan wrote:
>>> Hi Minh,
>>>
>>> OK, so CLM callback can handle before/after AMFND down.
>>> In case AMFND down then CLM callback, current flow works correctly.
>>> In case CLM callback then AMFND down:
>>> - AMFND already up before: current flow will do clm_node_exit_complete(),
>>> still works correctly.
>>> - AMFND not yet up before (node reboot up/first up): this is our issue.
>>> + current only delete node without care msg_id counter.
>>>
>>> Best Regards,
>>> Thuan
>>>
>>> -----Original Message-----
>>> From: Minh Hon Chau <minh.c...@dektech.com.au>
>>> Sent: Monday, July 9, 2018 8:52 AM
>>> To: Tran Thuan <thuan.t...@dektech.com.au>; nagen...@hasolutions.in;
>>> hans.nordeb...@ericsson.com; gary....@dektech.com.au
>>> Cc: opensaf-devel@lists.sourceforge.net
>>> Subject: Re: [PATCH 1/1] amf: amfd should reset msg_id counter to
>>> avoid message ID mismatch [#2891]
>>>
>>> This problem possibly happens in normal situation, not only "AMFND not yet
>>> up", so seeing it as a race and can also fixes the problem in case of
>>> "AMFND already up"
>>>
>>>
>>> On 09/07/18 11:41, Minh Hon Chau wrote:
>>>> Hi Thuan,
>>>>
>>>> I often see mds down coming before clm callback in my test, the
>>>> problem in this ticket has those events coming reverse order.
>>>>
>>>> <143>1 2018-07-09T11:19:22.185279+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23028"] 372:amf/amfd/ndfsm.cc:772 >>
>>>> avd_mds_avnd_down_evh: 2030f, 0x55895024e410
>>>> <143>1 2018-07-09T11:19:22.185303+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23029"] 372:amf/amfd/ndproc.cc:1219 >>
>>>> avd_node_failover: 'safAmfNode=PL-3,safAmfCluster=myAmfCluster'
>>>> <143>1 2018-07-09T11:19:22.185324+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23030"] 372:amf/amfd/ndfsm.cc:1111 >>
>>>> avd_node_mark_absent ...
>>>> <143>1 2018-07-09T11:19:22.253699+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23890"] 372:amf/amfd/ndfsm.cc:821 <<
>>>> avd_mds_avnd_down_evh
>>>>
>>>> <143>1 2018-07-09T11:19:22.272188+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23917"] 372:clm/agent/clma_api.cc:786 >>
>>>> saClmDispatch ...
>>>> <143>1 2018-07-09T11:19:22.272268+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23926"] 372:amf/amfd/clm.cc:223 >> clm_track_cb: '0'
>>>> '4' '1'
>>>> <143>1 2018-07-09T11:19:22.272277+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23927"] 372:amf/amfd/clm.cc:239 TR
>>>> numberOfMembers:'4', numberOfItems:'1'
>>>> <143>1 2018-07-09T11:19:22.272285+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23928"] 372:amf/amfd/clm.cc:245 TR i = 0,
>>>> node:'safNode=PL-3,safCluster=myClmCluster', clusterChange:3
>>>> <142>1 2018-07-09T11:19:22.272294+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23929"] 372:amf/amfd/clm.cc:320 IN clm_track_cb:
>>>> CLM node 'safNode=PL-3,safCluster=myClmCluster' is not an AMF
>>>> cluster member; MDS down received
>>>> <143>1 2018-07-09T11:19:22.272303+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23930"] 372:amf/amfd/clm.cc:443 << clm_track_cb ...
>>>> <143>1 2018-07-09T11:19:22.272352+10:00 SC-1 osafamfd 372 osafamfd
>>>> [meta sequenceId="23936"] 372:clm/agent/clma_api.cc:834 <<
>>>> saClmDispatch
>>>>
>>>>
>>>> Reset counter can avoid the msg mismatch, but I'm not sure it's
>>>> completely fixed since the mds down event is not handled properly.
>>>> If you have mds down event handled properly in both cases, will
>>>> there be this msg mismatch problem?
>>>>
>>>> Thanks,
>>>> Minh
>>>>
>>>> On 09/07/18 11:11, Tran Thuan wrote:
>>>>> Hi Minh,
>>>>>
>>>>> If I understand correctly, CLM callback always before AMFND down/up
>>>>> event.
>>>>> The problem is just because AMFND not yet up and CLM callback
>>>>> receive MDS down of node and delete node.
>>>>> After that AMFND down event come cannot find the node, cannot find
>>>>> the node is expected I guess.
>>>>> So, we only need to reset counter to make thing right, what do you
>>>>> think?
>>>>>
>>>>> <143>1 2018-07-03T18:40:27.239707+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2448"] 4815:amf/amfd/clm.cc:223 >>
>>>>> clm_track_cb:
>>>>> '0' '4' '1'
>>>>> <142>1 2018-07-03T18:40:27.239778+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2451"] 4815:amf/amfd/clm.cc:299 IN
>>>>> clm_track_cb:
>>>>> CLM node 'safNode=PL-2-3,safCluster=myClmCluster' is not an AMF
>>>>> cluster member; MDS down received
>>>>> <143>1 2018-07-03T18:40:27.239792+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2452"] 4815:amf/amfd/clm.cc:418 <<
>>>>> clm_track_cb
>>>>> <143>1 2018-07-03T18:40:27.243287+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2465"] 4815:amf/amfd/ndfsm.cc:772 >>
>>>>> avd_mds_avnd_down_evh: 2030f, (nil)
>>>>> <143>1 2018-07-03T18:40:27.243307+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2466"] 4815:amf/amfd/ndfsm.cc:821 <<
>>>>> avd_mds_avnd_down_evh
>>>>>
>>>>> <143>1 2018-07-03T18:41:37.965003+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2596"] 4815:amf/amfd/clm.cc:223 >>
>>>>> clm_track_cb:
>>>>> '0' '4' '1'
>>>>> <143>1 2018-07-03T18:41:37.965104+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2605"] 4815:amf/amfd/clm.cc:418 <<
>>>>> clm_track_cb
>>>>> <143>1 2018-07-03T18:41:45.016379+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2631"] 4815:amf/amfd/ndfsm.cc:750 TR
>>>>> amfnd on 2030f is up
>>>>> <143>1 2018-07-03T18:41:45.139262+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="2686"] 4815:amf/amfd/ndfsm.cc:772 >>
>>>>> avd_mds_avnd_down_evh: 2030f, 0x7ff9ac3dc940
>>>>> <143>1 2018-07-03T18:41:45.141883+10:00 SC-2-1 osafamfd 4815
>>>>> osafamfd [meta sequenceId="3008"] 4815:amf/amfd/ndfsm.cc:821 <<
>>>>> avd_mds_avnd_down_evh
>>>>>
>>>>> Best Regards,
>>>>> Thuan
>>>>>
>>>>>
>>>>> -----Original Message-----
>>>>> From: Minh Hon Chau <minh.c...@dektech.com.au>
>>>>> Sent: Monday, July 9, 2018 7:15 AM
>>>>> To: thuan.tran <thuan.t...@dektech.com.au>;
>>>>> nagen...@hasolutions.in; hans.nordeb...@ericsson.com;
>>>>> gary....@dektech.com.au
>>>>> Cc: opensaf-devel@lists.sourceforge.net
>>>>> Subject: Re: [PATCH 1/1] amf: amfd should reset msg_id counter to
>>>>> avoid message ID mismatch [#2891]
>>>>>
>>>>> Hi,
>>>>>
>>>>> In normal situation when I stop Opensaf or reboot the node, I often
>>>>> get MDS down first, then CLM track callback. [1]
>>>>>
>>>>> The problem in this ticket is because AMFD has CLM track callback
>>>>> coming before MDS down. [2]
>>>>>
>>>>> We need to see it as a race condition, not because of missing the
>>>>> counters reset, so that the amfd's function to deal with MDS down
>>>>> should be called. That would be equivalent to [1], which is
>>>>> currently working.
>>>>>
>>>>> With this patch, we still don't have avd_mds_avnd_down_evh() to be
>>>>> called, that function processes many things in the event of mds down.
>>>>> (ie. @nodes_exit_cnt, ...)
>>>>>
>>>>> I think the node_info.member should be set TRUE or FALSE in the
>>>>> event of CLM callback since it means CLM membership. We can use
>>>>> both @member and one of variables indicating MDS down, to trap each
>>>>> other in the events of MDS down and CLM callback, so that in the
>>>>> end we have
>>>>> avd_mds_avnd_down_evh() and nodeid is removed out of node_id_db in
>>>>> both [1] and [2].
>>>>>
>>>>> Thanks,
>>>>> Minh
>>>>> On 06/07/18 20:36, thuan.tran wrote:
>>>>>> There is a case that after AMFD send reboot order due to “out of
>>>>>> sync window”.
>>>>>> AMFD receive CLM track callback but node is not member yet and
>>>>>> delete node.
>>>>>> Later AMFND MDS down will not reset msg_id counter since it cannot
>>>>>> find node.
>>>>>> When node reboot up, AMFD continue use current msg_id counter send
>>>>>> to AMFND cause messasge ID mismatch in AMFND then AMFND order
>>>>>> reboot itself node.
>>>>>> ---
>>>>>> src/amf/amfd/clm.cc | 7 ++++++-
>>>>>> 1 file changed, 6 insertions(+), 1 deletion(-)
>>>>>>
>>>>>> diff --git a/src/amf/amfd/clm.cc b/src/amf/amfd/clm.cc index
>>>>>> e113a65f9..4a15d5ad7 100644
>>>>>> --- a/src/amf/amfd/clm.cc
>>>>>> +++ b/src/amf/amfd/clm.cc
>>>>>> @@ -316,9 +316,14 @@ static void clm_track_cb(
>>>>>> __FUNCTION__, node_name.c_str());
>>>>>> goto done;
>>>>>> } else if (node->node_state == AVD_AVND_STATE_ABSENT) {
>>>>>> - LOG_IN("%s: CLM node '%s' is not an AMF cluster member;
>>>>>> MDS down received",
>>>>>> + LOG_IN("%s: CLM node '%s' is ABSENT; MDS down
>>>>>> +received",
>>>>>> __FUNCTION__, node_name.c_str());
>>>>>> avd_node_delete_nodeid(node);
>>>>>> + /* Reset msg_id because AVND MDS down may come later
>>>>>> + and cannot find node to reset these, cause message
>>>>>> + ID
>>>>>> mismatch. */
>>>>>> + node->rcv_msg_id = 0;
>>>>>> + node->snd_msg_id = 0;
>>>>>> + node->node_info.member = SA_FALSE;
>>>>>> goto done;
>>>>>> }
>>>>>> TRACE(" Node Left: rootCauseEntity %s for node %u",
>>
>
>
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Opensaf-devel mailing list
Opensaf-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/opensaf-devel
