#3304 mds: Packet loss without log

[Hieu Hong Hoang]

In mds module, there is a packet loss feature. This feature provide a packet loss callback which is called when packet loss is detected. Because it is turn off by default, there are no callback or log when packet loss occurs.
In this ticket, the log of packet loss will be printed out by default . These logs are helpful in many cases.

[Hieu Hong Hoang]

There are several packet loss logs which is always printed out although no packet loss.

<139>1 2022-01-04T11:34:35.408579+07:00 SC-1 osafntfd 276 mds.log [meta sequenceId="6"] MDS_SND_RCV: msg loss detected, Src svc_id = LGS(20), Src vdest id= 11, Src Adest = 564116277870562, local svc_id = LGA(21) msg num=1, recvd cnt=0
<139>1 2022-01-04T11:34:35.589418+07:00 SC-1 osafclmd 291 mds.log [meta sequenceId="70"] MDS_SND_RCV: msg loss detected, Src svc_id = CLMA(35), Src vdest id= 65535, Src Adest = 567413190905029, local svc_id = CLMS(34) msg num=1, recvd cnt=0
<139>1 2022-01-04T11:37:37.308394+07:00 SC-1 osafamfd 305 mds.log [meta sequenceId="66"] MDS_SND_RCV: msg loss detected, Src svc_id = LGS(20), Src vdest id= 11, Src Adest = 565213955236610, local svc_id = LGA(21) msg num=1, recvd cnt=0

The reason for that is the first packet was received before this receiver subscribed its sender.

[Hieu Hong Hoang]

There is another error with the broadcast message. Currently, mds chooses an adest (active adest for normal mode or any adest for redundancy mode) and gets its sent message count to assign the sequence number of broadcast message. That sequence number is only valid to the chosen adest and invalid to other adests. Therefore, other adests will raise a packet loss when it receive that broadcast message.

Log analysis:

• IMMD in SC-1 sends first message to IMMND in SC-2:

<142>1 2022-01-05T08:32:21.083532+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="766"] MDTM: User Sending Data lenght=35 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:21.08354+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="767"] MDTM:Sending message with Service Seqno=0, TO Dest_Tipc_id=<0x01001002:783550957>

• IMMD in SC-1 sends first four messages to IMMND in SC-1:

<142>1 2022-01-05T08:32:21.060335+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="708"] MDTM: User Sending Data lenght=392 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:21.060338+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="709"] MDTM:Sending message with Service Seqno=0, TO Dest_Tipc_id=<0x01001001:3762921757> 
...
<142>1 2022-01-05T08:32:21.083985+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="794"] MDTM: User Sending Data lenght=392 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:21.083997+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="795"] MDTM:Sending message with Service Seqno=1, TO Dest_Tipc_id=<0x01001001:3762921757> 
... 
<142>1 2022-01-05T08:32:21.086354+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="880"] MDTM: User Sending Data lenght=392 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:21.086361+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="881"] MDTM:Sending message with Service Seqno=2, TO Dest_Tipc_id=<0x01001001:3762921757> 
...
<142>1 2022-01-05T08:32:21.13546+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="938"] MDTM: User Sending Data lenght=392 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:21.135468+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="939"] MDTM:Sending message with Service Seqno=3, TO Dest_Tipc_id=<0x01001001:3762921757> 

• IMMD in SC-1 broadcasts a message to all IMMNDs. The sequence number of this message is 4, because it's based on the number of sent message to IMMND in SC-1.

<142>1 2022-01-05T08:32:24.25973+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="992"] MDTM: User Sending Data lenght=35 From svc_id = IMMD(24) to svc_id = IMMND(25)
<143>1 2022-01-05T08:32:24.259735+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="993"] MDTM:Sending message with Service Seqno=4, TO Dest_Tipc_id=<0x01001001:3762921757> 
<143>1 2022-01-05T08:32:24.259738+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="994"] MDTM: User Sending Multicast Data lenght=74 From svc_id = IMMD(24) to svc_id = IMMND(25)
<142>1 2022-01-05T08:32:24.262517+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="995"] MDTM: Successfully sent mcast message
<143>1 2022-01-05T08:32:24.262545+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="996"] MDTM: Break while(1) prev_ver_sub_count: 0  svc_id =IMMD(24)  to_msg.bcast_buff_len: 35 
<142>1 2022-01-05T08:32:24.262555+07:00 SC-1 osafimmd 232 mds.log [meta sequenceId="997"] MDS_SND_RCV: Normal Bcast Message sent successfully from svc_id = IMMD(24), to svc_id = IMMND(25)

• IMMND in SC-2 receives that broadcast message then notify a packet loss. The reason is the IMMND in SC-2 received only one message from IMMD in SC-1 but the sequence number of broadcast message is 4.

<139>1 2022-01-05T08:32:24.260379+07:00 SC-2 osafimmnd 236 mds.log [meta sequenceId="350"] MDS_SND_RCV: msg loss detected, Src svc_id = IMMD(24), Src vdest id= 13, Src Adest = 564117141757651, local svc_id = IMMND(25) msg num=4, recvd cnt=1

[Hieu Hong Hoang]

commit fb5a176285562d08edd6a7d04e67ba4a96f8e9f8 (HEAD -> develop, origin/develop)
Author: hieu.h.hoang hieu.h.hoang@dektech.com.au
Date: Thu Jan 6 10:37:51 2022 +0700

mds: Correct checking the sequence number in loss indication [#3304]

The sequence number of broadcast message is associated with a specific destination not all destinations, therefore the loss indication shouldn't check those broadcast messages.
The messages received before subscribing the service shouldn't be checked too, because those messages wasn't tracked by mds.