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 and show the issue at the second time
//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.
---
**[tickets:#3364] amfnd: mismatch message id during split-brian in roaming SC **
**Status:** assigned
**Milestone:** 5.24.09
**Created:** Mon Nov 18, 2024 01:43 AM UTC by Thang Duc Nguyen
**Last Updated:** Mon Nov 18, 2024 01:43 AM UTC
**Owner:** 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`
---
Sent from sourceforge.net because [email protected] is
subscribed to https://sourceforge.net/p/opensaf/tickets/
To unsubscribe from further messages, a project admin can change settings at
https://sourceforge.net/p/opensaf/admin/tickets/options. Or, if this is a
mailing list, you can unsubscribe from the mailing list.
_______________________________________________
Opensaf-tickets mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/opensaf-tickets
