#3364 amfnd: mismatch message id during split-brian in roaming SC

[Thang Duc Nguyen]

Issue reports in syslog
2024-11-12 16:07:29.094 SC-2 osafamfd[239]: WA avd_msg_sanity_chk: invalid msg id 2, msg type 8, from 2070f should be 3

[Thang Duc Nguyen]

The root cause is due to avnd_diq_rec_send_buffered_msg() called in both avnd_evt_avd_ack_evh() and avnd_evt_avd_set_leds_evh() to send the same msg to active AMFD.
//1st

<143>1 2024-11-15T09:04:45.620547+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8528"] 250:amf/amfnd/main.cc:689 TR Evt type:10
<143>1 2024-11-15T09:04:45.620554+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8529"] 250:amf/amfnd/di.cc:449 >> avnd_evt_avd_ack_evh 
<143>1 2024-11-15T09:04:45.620559+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8530"] 250:amf/amfnd/di.cc:1395 >> avnd_di_msg_ack_process: 1
<143>1 2024-11-15T09:04:45.620566+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8531"] 250:amf/amfnd/di.cc:1414 TR msg node_up acked
<143>1 2024-11-15T09:04:45.620571+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8532"] 250:amf/amfnd/di.cc:1591 >> avnd_diq_rec_send_buffered_msg 
<141>1 2024-11-15T09:04:45.620608+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8533"] 250:amf/amfnd/di.cc:1671 NO DBDB: func avnd_diq_rec_send_buffered_msg, line 1671, snd_msg_id: 2
<141>1 2024-11-15T09:04:45.620622+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8534"] 250:amf/amfnd/di.cc:1672 NO Found and resend buffered Data Req msg for SU:'safComp=IMMND,safSu=SC-7,safSg=NoRed,safApp=OpenSAF', msg_id:'2'
<143>1 2024-11-15T09:04:45.620627+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8535"] 250:amf/amfnd/di.cc:1685 TR retransmit message to amfd
<143>1 2024-11-15T09:04:45.620633+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8536"] 250:amf/amfnd/di.cc:1709 >> avnd_diq_rec_send 
<143>1 2024-11-15T09:04:45.62064+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8537"] 250:amf/amfnd/mds.cc:1508 >> avnd_mds_send: Msg type '1'
<143>1 2024-11-15T09:04:45.620886+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8538"] 250:amf/amfnd/mds.cc:1567 << avnd_mds_send: 1
<143>1 2024-11-15T09:04:45.620892+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8539"] 250:amf/amfnd/di.cc:1731 << avnd_diq_rec_send: 1
<143>1 2024-11-15T09:04:45.620897+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8540"] 250:amf/amfnd/di.cc:1689 << avnd_diq_rec_send_buffered_msg 
<143>1 2024-11-15T09:04:45.620903+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8541"] 250:amf/amfnd/di.cc:1420 TR remove msg 1 from queue
<143>1 2024-11-15T09:04:45.620908+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8542"] 250:amf/amfnd/di.cc:1559 >> avnd_diq_rec_del 
<143>1 2024-11-15T09:04:45.620979+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8543"] 250:amf/amfnd/tmr.cc:119 TR message response timer stopped
<143>1 2024-11-15T09:04:45.620988+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8544"] 250:amf/amfnd/di.cc:1901 >> avnd_di_resend_pg_start_track 
<143>1 2024-11-15T09:04:45.620993+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8545"] 250:amf/amfnd/di.cc:1910 << avnd_di_resend_pg_start_track 
<143>1 2024-11-15T09:04:45.620999+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8546"] 250:amf/amfnd/di.cc:1575 << avnd_diq_rec_del 
<143>1 2024-11-15T09:04:45.621004+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8547"] 250:amf/amfnd/di.cc:1426 << avnd_di_msg_ack_process: 
<143>1 2024-11-15T09:04:45.621009+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8548"] 250:amf/amfnd/di.cc:458 << avnd_evt_avd_ack_evh 

//2nd

<143>1 2024-11-15T09:04:45.741483+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8552"] 250:amf/amfnd/main.cc:672 >> avnd_evt_process 
<143>1 2024-11-15T09:04:45.741536+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8553"] 250:amf/amfnd/main.cc:689 TR Evt type:12
<143>1 2024-11-15T09:04:45.741543+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8554"] 250:amf/amfnd/term.cc:201 >> avnd_evt_avd_set_leds_evh 
<143>1 2024-11-15T09:04:45.741549+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8555"] 250:amf/amfnd/di.cc:1591 >> avnd_diq_rec_send_buffered_msg 
<143>1 2024-11-15T09:04:45.741554+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8556"] 250:amf/amfnd/di.cc:1685 TR retransmit message to amfd
<143>1 2024-11-15T09:04:45.741559+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8557"] 250:amf/amfnd/di.cc:1709 >> avnd_diq_rec_send 
<143>1 2024-11-15T09:04:45.741566+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8558"] 250:amf/amfnd/mds.cc:1508 >> avnd_mds_send: Msg type '1'
<143>1 2024-11-15T09:04:45.741773+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8559"] 250:amf/amfnd/mds.cc:1567 << avnd_mds_send: 1
<143>1 2024-11-15T09:04:45.741779+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8560"] 250:amf/amfnd/di.cc:1731 << avnd_diq_rec_send: 1
<143>1 2024-11-15T09:04:45.741784+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8561"] 250:amf/amfnd/di.cc:1689 << avnd_diq_rec_send_buffered_msg 
<143>1 2024-11-15T09:04:45.74179+07:00 SC-7 osafamfnd 250 osafamfnd [meta sequenceId="8562"] 250:amf/amfnd/term.cc:218 << avnd_evt_avd_set_leds_evh 

At active AMFD, it processes the msg and meets the issue at the second processing
//1st

<143>1 2024-11-15T09:04:45.766174+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53956"] 239:amf/amfd/main.cc:810 >> process_event: evt->rcv_evt 8
<143>1 2024-11-15T09:04:45.766195+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53957"] 239:amf/amfd/ndproc.cc:858 >> avd_data_update_req_evh: from 2070f
<141>1 2024-11-15T09:04:45.766223+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53958"] 239:amf/amfd/ndproc.cc:859 NO DBDB: avd_data_update_req_evh, addr of evt: 140319937125840
<143>1 2024-11-15T09:04:45.766251+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53959"] 239:mbc/mbcsv_api.c:799 >> mbcsv_process_snd_ckpt_request: Sending checkpoint data to all STANDBY peers, as per the send-type specified
<143>1 2024-11-15T09:04:45.766273+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53960"] 239:mbc/mbcsv_api.c:832 TR svc_id:10, pwe_hdl:65537
<143>1 2024-11-15T09:04:45.766292+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53961"] 239:mbc/mbcsv_api.c:836 T1 No STANDBY peers found yet
<143>1 2024-11-15T09:04:45.766313+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53962"] 239:mbc/mbcsv_api.c:899 << mbcsv_process_snd_ckpt_request: retval: 1
<141>1 2024-11-15T09:04:45.766348+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53963"] 239:amf/amfd/ndproc.cc:880 NO DBDB: avd_data_update_req_evh, rcv_msg_id: 2, node_id: 0x2070f
<143>1 2024-11-15T09:04:45.766373+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53964"] 239:amf/amfd/util.cc:113 TR Send ack msg to 2070f
<143>1 2024-11-15T09:04:45.766401+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53965"] 239:amf/amfd/ndproc.cc:987 TR comp restart count
<143>1 2024-11-15T09:04:45.766423+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53966"] 239:mbc/mbcsv_api.c:799 >> mbcsv_process_snd_ckpt_request: Sending checkpoint data to all STANDBY peers, as per the send-type specified
<143>1 2024-11-15T09:04:45.766444+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53967"] 239:mbc/mbcsv_api.c:832 TR svc_id:10, pwe_hdl:65537
<143>1 2024-11-15T09:04:45.766464+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53968"] 239:mbc/mbcsv_api.c:836 T1 No STANDBY peers found yet
<143>1 2024-11-15T09:04:45.766482+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53969"] 239:mbc/mbcsv_api.c:899 << mbcsv_process_snd_ckpt_request: retval: 1
<143>1 2024-11-15T09:04:45.766504+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53970"] 239:amf/amfd/ndproc.cc:1195 << avd_data_update_req_evh 

//2nd

<143>1 2024-11-15T09:04:45.776196+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53988"] 239:amf/amfd/main.cc:810 >> process_event: evt->rcv_evt 8
<143>1 2024-11-15T09:04:45.776219+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53989"] 239:amf/amfd/ndproc.cc:858 >> avd_data_update_req_evh: from 2070f
<141>1 2024-11-15T09:04:45.776249+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53990"] 239:amf/amfd/ndproc.cc:859 NO DBDB: avd_data_update_req_evh, addr of evt: 140319937299680
<140>1 2024-11-15T09:04:45.776276+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53991"] 239:amf/amfd/ndproc.cc:73 WA avd_msg_sanity_chk: invalid msg id 2, msg type 8, from 2070f should be 3
<143>1 2024-11-15T09:04:45.776298+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53992"] 239:amf/amfd/ndproc.cc:1195 << avd_data_update_req_evh 
<143>1 2024-11-15T09:04:45.776319+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53993"] 239:mbc/mbcsv_api.c:799 >> mbcsv_process_snd_ckpt_request: Sending checkpoint data to all STANDBY peers, as per the send-type specified
<143>1 2024-11-15T09:04:45.776344+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53994"] 239:mbc/mbcsv_api.c:832 TR svc_id:10, pwe_hdl:65537
<143>1 2024-11-15T09:04:45.776372+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53995"] 239:mbc/mbcsv_api.c:836 T1 No STANDBY peers found yet
<143>1 2024-11-15T09:04:45.776391+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53996"] 239:mbc/mbcsv_api.c:899 << mbcsv_process_snd_ckpt_request: retval: 1
<143>1 2024-11-15T09:04:45.776412+07:00 SC-2 osafamfd 239 osafamfd [meta sequenceId="53997"] 239:amf/amfd/main.cc:858 << process_event 

The solution is AMFND removes the msg in it's queue after it sends to active AMFD.