Connection failure error during DFU over Matter guide

[bluemelony]

Hi

I have a question because a connection failure error occurred during the DFU over Matter guide.

- guide URL : developer.nordicsemi.com/.../nrfconnect_examples_software_update.html

The PC using Ubuntu OS(with nRF52840 dongle) is configured as the OTA provider and the nRF52840DK board is configured as the OTA requester.

I completed the installation of ota-provider-app and chip-tool on the Linux PC and commissioned the Linux PC as an OTA provider through the command below

./out/chiptool/chip-tool pairing onnetwork 1 20202021

And after configuring the new thread network through OTBR, nRF52840DK board was commissioned with node ID 2.

./out/chiptool/chip-tool pairing ble-thread 2 hex:0e08000000000001000035060004001fffe00708fdb96028cd2611df0c0402a0f7f8051000112233445566778899aabbccddeeff030
e4f70656e54687265616444656d6f0410445f2b5ca6f2a93a55ce570a70efeecb000300000f0208111111112222222201021234 20202021 3840

Finally, I performed the steps 8 and 9 commands.

./out/chiptool/chip-tool otasoftwareupdaterequestor write default-otaproviders '[{"fabricIndex": 1, "providerNodeID": 1, "endpoint": 0}]' 2 0

('default-ota-providers' command did not exist, so we used 'default-otaproviders')

./out/chiptool/chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": null}, {"fabricIndex": 1, "privilege": 3, "authMode": 2, "subjects": null, "targets": null}]' 1 0

And I sent Announce OTA Provider command using Chip tool, but an error appears in the nRF52840DK board log

./out/chiptool/chip-tool otasoftwareupdaterequestor announce-otaprovider 1 0 0 0 2 0

('announce-ota-provider' command did not exist, so we used 'announce-ota-provider')

Log >>

I: 1515622 [EM]>>> [E:60665r S:0 M:182234332] (U) Msg RX from 0:EBA082CFD0009BF0 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 1515634 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004e60
I: 1515641 [IN]CASE Server disabling CASE session setups
I: 1515647 [EM]<<< [E:60665r S:0 M:209788448 (Ack:182234332)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1515660 [IN](U) Sending msg 209788448 to IP address 'UDP:[fd11:db8:1::1]:46385'
I: 1515668 [SC]Received Sigma1 msg
I: 1515676 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 1515885 [EM]<<< [E:60665r S:0 M:209788449 (Ack:182234332)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 1515898 [IN](U) Sending msg 209788449 to IP address 'UDP:[fd11:db8:1::1]:46385'
I: 1515907 [SC]Sent Sigma2 msg
I: 1516027 [EM]>>> [E:60665r S:0 M:182234333 (Ack:209788449)] (U) Msg RX from 0:EBA082CFD0009BF0 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 1516040 [EM]<<< [E:60665r S:0 M:209788450 (Ack:182234333)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1516053 [IN](U) Sending msg 209788450 to IP address 'UDP:[fd11:db8:1::1]:46385'
I: 1516062 [SC]Received Sigma3 msg
E: 1516070 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time
E: 1516267 [DL]Long dispatch time: 187 ms, for event type 2
I: 1516368 [EM]<<< [E:60665r S:0 M:209788451 (Ack:182234333)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1516381 [IN](U) Sending msg 209788451 to IP address 'UDP:[fd11:db8:1::1]:46385'
I: 1516391 [SC]SecureSession[0x20003838]: Moving from state 'kEstablishing' --> 'kActive'
D: 1516400 [IN]SecureSession[0x20003838]: Activated - Type:2 LSID:38704
D: 1516406 [IN]New secure session activated for device <000000000001B669, 1>, LSID:38704 PSID:14355!
I: 1516419 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 1516425 [IN]CASE Server enabling CASE session setups
D: 1516431 [IN]SecureSession[0x200038f0]: Allocated Type:2 LSID:38706
E: 1516437 [DL]Long dispatch time: 165 ms, for event type 2
I: 1516443 [EM]>>> [E:60666r S:38704 M:131944375] (S) Msg RX from 1:000000000001B669 [4661] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 1516456 [SWU]OTA Requestor received AnnounceOTAProvider
D: 1516461 [SWU] FabricIndex: 1
D: 1516464 [SWU] ProviderNodeID: 0x0000000000000001
D: 1516469 [SWU] VendorID: 0x0
D: 1516472 [SWU] AnnouncementReason: 0
D: 1516475 [SWU] Endpoint: 0
I: 1516479 [EM]<<< [E:60666r S:38704 M:3219666 (Ack:131944375)] (S) Msg TX to 1:000000000001B669 [4661] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1516492 [IN](S) Sending msg 3219666 on secure session with LSID: 38704
I: 1516500 [EM]>>> [E:60665r S:0 M:182234334 (Ack:209788451)] (U) Msg RX from 0:EBA082CFD0009BF0 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1516514 [SWU]Stopping the Periodic Query timer
I: 1516519 [SWU]Starting the watchdog timer, timeout: 21600 seconds
D: 1516525 [SWU]Establishing session to provider node ID 0x0000000000000001 on fabric index 1
D: 1516535 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
I: 1516543 [DIS]Resolving DFAABB27E9334661:0000000000000001 ...
I: 1516551 [EM]>>> [E:60666r S:38704 M:131944376 (Ack:3219666)] (S) Msg RX from 1:000000000001B669 [4661] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1516635 [DIS]Node ID resolved for DFAABB27E9334661:0000000000000001
D: 1516641 [DIS] Hostname: E0D55EB9F3140000
D: 1516645 [DIS] IP Address #1: fd11:db8:1::1
D: 1516649 [DIS] Port: 5540
D: 1516652 [DIS] Mrp Interval idle: 300 ms
D: 1516656 [DIS] Mrp Interval active: 2000 ms
D: 1516660 [DIS] TCP Supported: 1
D: 1516663 [DIS]Lookup clearing interface for non LL address
I: 1516668 [DIS]UDP:[fd11:db8:1::1]:5540: new best score: 4
I: 1516674 [DIS]Checking node lookup status after 131 ms
I: 1516679 [DIS]Keeping DNSSD lookup active
I: 1516743 [DIS]Checking node lookup status after 200 ms
D: 1516748 [DIS]OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:db8:1::1]:5540 while in state 2
D: 1516760 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
D: 1516767 [IN]SecureSession[0x200039a8]: Allocated Type:2 LSID:38707
I: 1516774 [SC]Initiating session on local FabricIndex 1 from 0x0000000000000002 -> 0x0000000000000001
I: 1516924 [EM]<<< [E:31162i S:0 M:209788452] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 1516936 [IN](U) Sending msg 209788452 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1516944 [SC]Sent Sigma1 msg
D: 1516947 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
I: 1517852 [IN](U) Sending msg 209788452 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1518686 [IN](U) Sending msg 209788452 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1519741 [IN](U) Sending msg 209788452 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1521217 [IN](U) Sending msg 209788452 to IP address 'UDP:[fd11:db8:1::1]:5540'
E: 1523365 [EM]Failed to Send CHIP MessageCounter:209788452 on exchange 31162i sendCount: 4 max retries: 4
E: 1525648 [SC]CASESession timed out while waiting for a response from the peer. Current state was 1
D: 1525657 [IN]SecureSession[0x200039a8]: Released - Type:2 LSID:38707
D: 1525664 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
D: 1525671 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
E: 1525679 [SWU]Failed to connect to node 0x0000000000000001: 32
I: 1525686 [SWU]Unknown idle state reason so set the periodic timer for a next attempt
I: 1525694 [SWU]Stopping the watchdog timer
I: 1525698 [SWU]Starting the periodic query timer, timeout: 86400 seconds

When you send the Query command from the nRF52840DK board, the error log appears as shown below.

matter ota query

Log >>
matter ota query
uart:~$ I: 1682151 [SWU]Triggered immediate OTA query for fabric: 0x1
I: 1682159 [SWU]Stopping the Periodic Query timer
I: 1682163 [SWU]Starting the watchdog timer, timeout: 21600 seconds
D: 1682169 [SWU]Establishing session to provider node ID 0x0000000000000001 on fabric index 1
D: 1682177 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
I: 1682185 [DIS]Resolving DFAABB27E9334661:0000000000000001 ...
I: 1682284 [DIS]Node ID resolved for DFAABB27E9334661:0000000000000001
D: 1682290 [DIS] Hostname: E0D55EB9F3140000
D: 1682294 [DIS] IP Address #1: fd11:db8:1::1
D: 1682298 [DIS] Port: 5540
D: 1682301 [DIS] Mrp Interval idle: 300 ms
D: 1682305 [DIS] Mrp Interval active: 2000 ms
D: 1682309 [DIS] TCP Supported: 1
D: 1682312 [DIS]Lookup clearing interface for non LL address
I: 1682317 [DIS]UDP:[fd11:db8:1::1]:5540: new best score: 4
I: 1682323 [DIS]Checking node lookup status after 138 ms
I: 1682328 [DIS]Keeping DNSSD lookup active
I: 1682385 [DIS]Checking node lookup status after 200 ms
D: 1682390 [DIS]OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:db8:1::1]:5540 while in state 2
D: 1682402 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
D: 1682409 [IN]SecureSession[0x200039a8]: Allocated Type:2 LSID:38709
I: 1682416 [SC]Initiating session on local FabricIndex 1 from 0x0000000000000002 -> 0x0000000000000001
I: 1682567 [EM]<<< [E:31164i S:0 M:209788454] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 1682578 [IN](U) Sending msg 209788454 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1682587 [SC]Sent Sigma1 msg
D: 1682590 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
I: 1683417 [IN](U) Sending msg 209788454 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1684297 [IN](U) Sending msg 209788454 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1685441 [IN](U) Sending msg 209788454 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 1686890 [IN](U) Sending msg 209788454 to IP address 'UDP:[fd11:db8:1::1]:5540'
E: 1688790 [EM]Failed to Send CHIP MessageCounter:209788454 on exchange 31164i sendCount: 4 max retries: 4
E: 1691290 [SC]CASESession timed out while waiting for a response from the peer. Current state was 1
D: 1691299 [IN]SecureSession[0x200039a8]: Released - Type:2 LSID:38709
D: 1691305 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
D: 1691313 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
E: 1691320 [SWU]Failed to connect to node 0x0000000000000001: 32
I: 1691327 [SWU]Unknown idle state reason so set the periodic timer for a next attempt
I: 1691334 [SWU]Stopping the watchdog timer
I: 1691338 [SWU]Starting the periodic query timer, timeout: 86400 seconds

How can I solve this problem?

Also, could you check if DFU over Matter works well with the contents of the above guide Url?

+) The example "ncs\v2.4.0\nrf\samples\matter\light_bulb" was used, and only 'CONFIG_CHIP_DFU_OVER_BT_SMP=y' was added to the prj.conf file.

[AHaug]

Thank you for providing the logs!

bluemelony said:

If it consists of only OTA ProviderAPP and OTA Requestor, it seems that OTA can be tested without OTBR. It this for real?

I will ask the developers about this

bluemelony said:

I don't know how to check 802.15.4 Sniffer using WireShark.....

If you explain the part in detail again, I will let you know the results of the confirmation.

No worries! Here's a couple of links that will take you through how to do that https://www.nordicsemi.com/Products/Development-tools/nrf-sniffer-for-802154 and https://infocenter.nordicsemi.com/index.jsp?topic=%2Fug_sniffer_802154%2FUG%2Fsniffer_802154%2Fintro_802154.html

If you don't have a nRF52840 dongle available, you can always use one of your nRF52840dks instead

PS: A tip for attaching the logs is to use the code snippet function found under insert to make the case more manageable to scroll through! :) I will go through your replies now and edit them into boxes for you but for future logs and attachment that will really improve readability of your case

[bluemelony]

One more thing.

With OTBR, OTA Provider, and Matter Device (nrf52840dk) all configured as above, when Matter Device is rebooted, the following log appears immediately on the OTA Provider. What does this mean?

[1687855637.419277][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.419364][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.419509][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.419534][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.420811][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.420841][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.420965][5148:5148] CHIP:DIS: SRV record already actively processed.
[1687855637.420984][5148:5148] CHIP:DIS: SRV record already actively processed.

...

...

[bluemelony]

Hello!

We did nRF Sniffer Capture based on the WireShark setting guide you answered.

First of all, it is a capture when the Onoff toggle command is delivered to Matter Device (nRF52840DK) in the

above situation.

sudo ./out/chiptool/chip-tool onoff toggle 10 1

(sorry, I don't know if it's all set up correctly...

and I don't know how to extract it, so sending a raw capture file..)

Cp1.pcapng

 

Next, the behavior for the Provider

* OTA file set : sudo ./out/provider/chip-ota-provider-app -f matter.ota,

* Provider pairing : sudo ./out/chiptool/chip-tool pairing onnetwork-long 5 20202021 3840,

* OTA request : sudo ./out/chiptool/chip-tool otasoftwareupdaterequestor announce-otaprovider 5 0 0 0 10 0

did not show any packets..

No packets of content appeared in Wireshark except packets coming out of OTBR continuously.

This makes me suspect that the OTA Provider app is not behaving incorrectly.

[AHaug]

Hi,

I brought your results to the Matter team and this is what they had to say:

The info that no packets were captured after invoking announce-otaprovider command made me become super suspicious, as it's very unlikely to happen.

1. They think that the you have invoked the commands correctly, at least at first as they can see in your first post that pairing for the DK, pairing for the OTA provider, write default ota providers, write acls and announce ota provider, but then in the following attempts the flow is not complete (e.g. here:
   1. OTA file set : sudo ./out/provider/chip-ota-provider-app -f matter.ota
   2. Provider pairing : sudo ./out/chiptool/chip-tool pairing onnetwork-long 5 20202021 3840
   3. OTA request : sudo ./out/chiptool/chip-tool otasoftwareupdaterequestor announce-otaprovider 5 0 0 0 10 0
      
      I don't see setting acls and default-otaprovider. They assume that you have done it correctly and the presented example is just simplified, but just to make sure, could you verify if the proper flow was used?
      
      
2. Regarding that no packets of content appeared in Wireshark except packets coming out of OTBR continuously. This makes me suspect that the OTA Provider app is not behaving incorrectly.
   
   The commands sent from CHIP Tool to OTA provider will not be visible in the wireshark, because it sniffs the Thread traffic, and these commands are sent over Wi-Fi (because both CHIP Tool and OTA provider are working on Wi-Fi). What should be visible is traffic between CHIP Tool <-> DK and also DK <-> OTA Provider.
   
   Could you check if you're able to narrow down the issue by verifying if you're able to observe the traffic that should be visible?
   
   
3. They would also attempt to try the setup once more from scratch (the best option would be to reset everything), then connect the Wireshark and repeat all the steps. Please be careful and observe the packets and logs displayed after every invoked command.
   
   Especially pay attention to this one: chip-tool otasoftwareupdaterequestor announce-otaprovider 5 0 0 0 10 0
   
   They are expecting that the DK should a log about trying to send Sigma 1 message: I: 1682587 [SC]Sent Sigma1 msg
   
   and also the packets should appear in wireshark just after that. It's almost impossible that after displaying such a log the corresponding packets didn't appear in the Wireshark (the only case they could imagine is that the radio signal was too low and the sniffer didn't capture it).
   
   I know that may be a lot of work, but if you're able to recreate the issue by following the guides once more, then we can with more certainty state that it might be a bug and not due to missing one step at an earlier step

Let me know about this and I'll bring it back to the Matter team if this does not resolve the issue! 

Kind regards,
Andreas

[bluemelony]

Hi

Thank you for your reply.

This is the result of checking the 3 items you requested.

 

1. Previously, the acls and default-otaprovider commands were also performed, and the results were the same.

"./out/chiptool/chip-tool otasoftwareupdaterequestor write default-ota-providers '[{"fabricIndex": 1, "providerNodeID": 5, "endpoint": 0}]' 10 0"  ---> Packets checked in Wireshark

"./out/chiptool/chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": null}, {"fabricIndex": 1, "privilege": 3, "authMode": 2, "subjects": null, "targets": null}]' 5 0" ----> No response to Wireshark

 And in OTA announce, we checked incorrectly and the packet was seen in Wireshark. The details of the packet are in number 3 below.

2. I will check the contents again using Wireshark and send it to you.

 

3. We repeated the same configuration from the beginning (from Matter Build and OTBR configuration) using a different PC, but the same situation continued.

Additionally, we are sending you a full capture of Wireshark packets that occurred while proceeding

with the Matter OTA guide document.

(OTA Provider build ~ OTA announce, The OTA Provider Node is 1, and the Matter Device

,nRF52840DK Node is 2.)

(https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/matter/nrfconnect_examples_software_update.html)

Cp2.pcapng

And below is the DK side log that occurred during OTA Provider announce operation.

I: 387185 [EM]>>> [E:34109r S:0 M:104490976] (U) Msg RX from 0:2326305E0017DBA6 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 387197 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004e60
I: 387205 [IN]CASE Server disabling CASE session setups
I: 387210 [EM]<<< [E:34109r S:0 M:220107179 (Ack:104490976)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 387223 [IN](U) Sending msg 220107179 to IP address 'UDP:[fd11:db8:1::1]:48082'
I: 387231 [SC]Received Sigma1 msg
I: 387239 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 387454 [EM]<<< [E:34109r S:0 M:220107180 (Ack:104490976)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 387467 [IN](U) Sending msg 220107180 to IP address 'UDP:[fd11:db8:1::1]:48082'
I: 387476 [SC]Sent Sigma2 msg
I: 387601 [EM]>>> [E:34109r S:0 M:104490977 (Ack:220107180)] (U) Msg RX from 0:2326305E0017DBA6 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 387614 [EM]<<< [E:34109r S:0 M:220107181 (Ack:104490977)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 387627 [IN](U) Sending msg 220107181 to IP address 'UDP:[fd11:db8:1::1]:48082'
I: 387636 [SC]Received Sigma3 msg
E: 387644 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 387841 [DL]Long dispatch time: 187 ms, for event type 2
I: 387944 [EM]<<< [E:34109r S:0 M:220107182 (Ack:104490977)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 387957 [IN](U) Sending msg 220107182 to IP address 'UDP:[fd11:db8:1::1]:48082'
I: 387967 [SC]SecureSession[0x200039a8]: Moving from state 'kEstablishing' --> 'kActive'
D: 387975 [IN]SecureSession[0x200039a8]: Activated - Type:2 LSID:55573
D: 387982 [IN]New secure session activated for device <000000000001B669, 1>, LSID:55573 PSID:31464!
I: 387991 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 388000 [IN]CASE Server enabling CASE session setups
D: 388007 [IN]SecureSession[0x20003a60]: Allocated Type:2 LSID:55575
E: 388013 [DL]Long dispatch time: 167 ms, for event type 2
I: 388019 [EM]>>> [E:34110r S:55573 M:214202345] (S) Msg RX from 1:000000000001B669 [3829] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 388032 [SWU]OTA Requestor received AnnounceOTAProvider
D: 388037 [SWU]  FabricIndex: 1
D: 388040 [SWU]  ProviderNodeID: 0x0000000000000001
D: 388044 [SWU]  VendorID: 0x0
D: 388047 [SWU]  AnnouncementReason: 0
D: 388051 [SWU]  Endpoint: 0
I: 388054 [EM]<<< [E:34110r S:55573 M:166002962 (Ack:214202345)] (S) Msg TX to 1:000000000001B669 [3829] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 388067 [IN](S) Sending msg 166002962 on secure session with LSID: 55573
I: 388076 [EM]>>> [E:34109r S:0 M:104490978 (Ack:220107182)] (U) Msg RX from 0:2326305E0017DBA6 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 388093 [SWU]Stopping the Periodic Query timer
I: 388097 [SWU]Starting the watchdog timer, timeout: 21600 seconds
D: 388103 [SWU]Establishing session to provider node ID 0x0000000000000001 on fabric index 1
D: 388111 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
I: 388119 [DIS]Resolving 5F72E24097313829:0000000000000001 ...
I: 388127 [EM]>>> [E:34110r S:55573 M:214202346 (Ack:166002962)] (S) Msg RX from 1:000000000001B669 [3829] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 388280 [DIS]Node ID resolved for 5F72E24097313829:0000000000000001
D: 388286 [DIS] Hostname: E0D55EB9F3140000
D: 388290 [DIS] IP Address #1: fd11:db8:1::1
D: 388294 [DIS] Port: 5540
D: 388296 [DIS] Mrp Interval idle: 300 ms
D: 388300 [DIS] Mrp Interval active: 2000 ms
D: 388304 [DIS] TCP Supported: 1
D: 388307 [DIS]Lookup clearing interface for non LL address
I: 388313 [DIS]UDP:[fd11:db8:1::1]:5540: new best score: 4
I: 388318 [DIS]Checking node lookup status after 200 ms
D: 388323 [DIS]OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:db8:1::1]:5540 while in state 2
D: 388334 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
D: 388342 [IN]SecureSession[0x20003b18]: Allocated Type:2 LSID:55576
I: 388348 [SC]Initiating session on local FabricIndex 1 from 0x0000000000000002 -> 0x0000000000000001
I: 388503 [EM]<<< [E:34040i S:0 M:220107183] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 388514 [IN](U) Sending msg 220107183 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 388523 [SC]Sent Sigma1 msg
D: 388526 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
E: 388534 [DL]Long dispatch time: 254 ms, for event type 2
I: 389382 [IN](U) Sending msg 220107183 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 390270 [IN](U) Sending msg 220107183 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 391303 [IN](U) Sending msg 220107183 to IP address 'UDP:[fd11:db8:1::1]:5540'
I: 392829 [IN](U) Sending msg 220107183 to IP address 'UDP:[fd11:db8:1::1]:5540'
E: 394901 [EM]Failed to Send CHIP MessageCounter:220107183 on exchange 34040i sendCount: 4 max retries: 4
E: 397226 [SC]CASESession timed out while waiting for a response from the peer. Current state was 1
D: 397235 [IN]SecureSession[0x20003b18]: Released - Type:2 LSID:55576
D: 397242 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
D: 397249 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
E: 397256 [SWU]Failed to connect to node 0x0000000000000001: 32
I: 397263 [SWU]Unknown idle state reason so set the periodic timer for a next attempt
I: 397271 [SWU]Stopping the watchdog timer
I: 397275 [SWU]Starting the periodic query timer, timeout: 86400 seconds

as you can see "I: 388523 [SC]Sent Sigma1 msg" Log is confirmed.

I hope this information is helpful.

If you need additional information, please request it.