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.

[Marte Myrvold]

Hi,

What are you running the OTBR on, and are you running it in docker mode or manually?

Are you able to communicate with both the nRF52840 DK and OTA provider on the Matter network, and is the computer with the OTA provider on the same Wi-Fi network as the OTBR?

Best regards,
Marte

[bluemelony]

Yes, OTBR is running in docker mode and has been confirmed to communicate with the nRF52840DK with the Led onoff toggle command. They are all on the same WIFI network. 

 

<OTA provider>                                         <OTA Requestor>

| PC(ubuntu)             |                              | nRF52840DK        |
| nRF52840 Dongle  |          <----->    

It has also been confirmed that both Node1 (OTA provider) and Node2 (OTA requester) work using Chip tool on Linux PCs (read Vender id or Product id...etc)

[AHaug]

Hi again,

After discussing this topic with the developers we can't state that this is due to anything we already know of so we will have to do some more investigation

The procedure you describe in your case description looks correct, and the troubleshooter looks nice. Based on the logs the Matter team states that the nRF52DK tries to send the Sigma 1 to the OTA provider to initiate CASE session, but the DK does not get a response from it. They find this interesting considering that you state that there is communication between DK and CHIP Tool running on the same PC which is how the OTA provider works.

The Matter team would like to verify if the Sigma1 message hasn't reached the OTA provider at all or if the message reached the provider which responded and the response was lost somewhere on the way to the DK. It should be possible to see by looking at the logs from the OTA provider, so if you can provide them here that would be great

It could also be helpful if you can provide a 802.15.4 sniffer trace using Wireshark. One theory is that the issue you are observing could be caused by routing problems which might be revealed in a pcap. However if a routing issue is the root cause, then they would expect that communication with CHIP Tool also shouldn't work

Let me know about these items when you are able to provide them, and I'll relay them to the Matter team

Kind regards,
Andreas

[bluemelony]

Hello

Thank you for your answer.

This is the Provider side log you requested.

1. Deliver OTA file to Provider APP

kumho@kumho-B360M-H:~/connectedhomeip$ sudo ./out/provider/chip-ota-provider-app -f matter.ota

[1687852817.123106][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687852817.123367][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687852817.123374][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1687852817.125200][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1687852817.125235][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1687852817.125254][3931:3931] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1687852817.125327][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-UdWGiM)
[1687852817.125461][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687852817.125472][3931:3931] CHIP:DL: NVS set: chip-counters/reboot-count = 8 (0x8)
[1687852817.125654][3931:3931] CHIP:DL: Got Ethernet interface: enp1s0
[1687852817.125774][3931:3931] CHIP:DL: Found the primary Ethernet interface:enp1s0
[1687852817.125959][3931:3931] CHIP:DL: Failed to get WiFi interface
[1687852817.125964][3931:3931] CHIP:DL: Failed to reset WiFi statistic counts
[1687852817.125970][3931:3931] CHIP:SPT: *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. ***
[1687852817.125975][3931:3931] CHIP:SPT: *** WARNING: Using temporary test discriminator 3840 due to --discriminator not given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure discriminator. ***
[1687852817.125979][3931:3931] CHIP:SPT: PASE PBKDF iterations set to 1000
[1687852817.125983][3931:3931] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one.
[1687852817.127960][3931:3931] CHIP:DL: Device Configuration:
[1687852817.127969][3931:3931] CHIP:DL: Serial Number: TEST_SN
[1687852817.127974][3931:3931] CHIP:DL: Vendor Id: 65521 (0xFFF1)
[1687852817.127979][3931:3931] CHIP:DL: Product Id: 32769 (0x8001)
[1687852817.127982][3931:3931] CHIP:DL: Product Name: TEST_PRODUCT
[1687852817.127987][3931:3931] CHIP:DL: Hardware Version: 0
[1687852817.127990][3931:3931] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1687852817.127993][3931:3931] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1687852817.128005][3931:3931] CHIP:DL: Manufacturing Date: (not set)
[1687852817.128009][3931:3931] CHIP:DL: Device Type: 65535 (0xFFFF)
[1687852817.128012][3931:3931] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ====
[1687852817.128021][3931:3931] CHIP:SVR: SetupQRCode: [MT:-24J0AFN00KA0648G00]
[1687852817.128026][3931:3931] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1687852817.128029][3931:3931] CHIP:SVR: project-chip.github.io/.../qrcode.html
[1687852817.128034][3931:3931] CHIP:SVR: Manual pairing code: [34970112332]
[1687852817.128042][3931:3931] CHIP:SVR: Initializing subscription resumption storage...
[1687852817.128076][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_kvs-Ch6rKn)
[1687852817.128180][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687852817.128196][3931:3931] CHIP:SVR: Server initializing...
[1687852817.128200][3931:3931] CHIP:FP: Initializing FabricTable from persistent storage
[1687852817.128216][3931:3931] CHIP:TS: Last Known Good Time: 2023-06-26T17:21:28
[1687852817.128227][3931:3931] CHIP:DMG: AccessControl: initializing
[1687852817.128230][3931:3931] CHIP:DMG: Examples::AccessControlDelegate::Init
[1687852817.128236][3931:3931] CHIP:DMG: AccessControl: setting
[1687852817.128240][3931:3931] CHIP:DMG: DefaultAclStorage: initializing
[1687852817.128243][3931:3931] CHIP:DMG: DefaultAclStorage: 0 entries loaded
[1687852817.128253][3931:3931] CHIP:IN: UDP::Init bind&listen port=5540
[1687852817.128273][3931:3931] CHIP:IN: UDP::Init bound to port=5540
[1687852817.128276][3931:3931] CHIP:IN: UDP::Init bind&listen port=5540
[1687852817.128290][3931:3931] CHIP:IN: UDP::Init bound to port=5540
[1687852817.128293][3931:3931] CHIP:IN: TransportMgr initialized
[1687852817.128342][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_kvs-CssWQI)
[1687852817.128452][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687852817.128482][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_kvs-VG4UK4)
[1687852817.128570][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687852817.130253][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_kvs-gTm0lR)
[1687852817.130341][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687852817.130352][3931:3931] CHIP:ZCL: Using ZAP configuration...
[1687852817.130370][3931:3931] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1687852817.130378][3931:3931] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1687852817.130391][3931:3931] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1687852817.130398][3931:3931] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1687852817.130407][3931:3931] CHIP:DMG: AccessControlCluster: initializing
[1687852817.130410][3931:3931] CHIP:ZCL: Initiating Admin Commissioning cluster.
[1687852817.130415][3931:3931] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 96d93a90
[1687852817.130425][3931:3931] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot
[1687852817.130428][3931:3931] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to 4326c5d4
[1687852817.130443][3931:3931] CHIP:EVL: LogEvent event number: 0x0000000000030000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Epoch timestamp: 0x00000188FBDE1AEA
[1687852817.130480][3931:3931] CHIP:DL: writing settings to file (/tmp/chip_kvs-h1kHSA)
[1687852817.130561][3931:3931] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687852817.130571][3931:3931] CHIP:DMG: Endpoint 0, Cluster 0x0000_002B update version to e387c47a
[1687852817.130586][3931:3931] CHIP:DL: Cannot get device role with Thread api client:
[1687852817.130599][3931:3931] CHIP:IN: SecureSession[0x5639f9d029f0]: Allocated Type:1 LSID:29632
[1687852817.130610][3931:3931] CHIP:SC: Assigned local session key ID 29632
[1687852817.130614][3931:3931] CHIP:SC: Waiting for PBKDF param request
[1687852817.130620][3931:3931] CHIP:DIS: Updating services using commissioning mode 1
[1687852817.132272][3931:3931] CHIP:DIS: CHIP minimal mDNS started advertising.
[1687852817.136360][3931:3931] CHIP:DL: Using wifi MAC for hostname
[1687852817.136377][3931:3931] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1687852817.136386][3931:3931] CHIP:DIS: Responding with _matterc._udp.local
[1687852817.136390][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.136393][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.136396][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.136401][3931:3931] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1687852817.136405][3931:3931] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1687852817.136409][3931:3931] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1687852817.136414][3931:3931] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1687852817.136420][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.136424][3931:3931] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 64EC48AF170C6C6F.
[1687852817.141493][3931:3931] CHIP:DIS: mDNS service published: _matterc._udp
[1687852817.141500][3931:3931] CHIP:DIS: Updating services using commissioning mode 1
[1687852817.143152][3931:3931] CHIP:DIS: CHIP minimal mDNS started advertising.
[1687852817.153402][3931:3931] CHIP:DL: Using wifi MAC for hostname
[1687852817.153426][3931:3931] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1687852817.153436][3931:3931] CHIP:DIS: Responding with _matterc._udp.local
[1687852817.153440][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.153443][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.153447][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.153451][3931:3931] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1687852817.153455][3931:3931] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1687852817.153459][3931:3931] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1687852817.153464][3931:3931] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1687852817.153471][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.153474][3931:3931] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 64EC48AF170C6C6F.
[1687852817.158666][3931:3931] CHIP:DIS: mDNS service published: _matterc._udp
[1687852817.158676][3931:3931] CHIP:IN: CASE Server enabling CASE session setups
[1687852817.158693][3931:3931] CHIP:IN: SecureSession[0x5639f9d02db0]: Allocated Type:2 LSID:29633
[1687852817.158699][3931:3931] CHIP:SC: Allocated SecureSession (0x5639f9d02db0) - waiting for Sigma1 msg
[1687852817.158704][3931:3931] CHIP:SVR: Joining Multicast groups
[1687852817.158711][3931:3931] CHIP:ZCL: Emitting StartUp event
[1687852817.158727][3931:3931] CHIP:EVL: LogEvent event number: 0x0000000000030001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Epoch timestamp: 0x00000188FBDE1B06
[1687852817.158734][3931:3931] CHIP:SVR: Server initialization complete
[1687852817.158739][3931:3931] CHIP:SVR: Server Listening...
[1687852817.158743][3931:3931] CHIP:DL: Device Configuration:
[1687852817.158753][3931:3931] CHIP:DL: Serial Number: TEST_SN
[1687852817.158763][3931:3931] CHIP:DL: Vendor Id: 65521 (0xFFF1)
[1687852817.158769][3931:3931] CHIP:DL: Product Id: 32769 (0x8001)
[1687852817.158773][3931:3931] CHIP:DL: Product Name: TEST_PRODUCT
[1687852817.158779][3931:3931] CHIP:DL: Hardware Version: 0
[1687852817.158783][3931:3931] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1687852817.158788][3931:3931] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1687852817.158793][3931:3931] CHIP:DL: Manufacturing Date: (not set)
[1687852817.158797][3931:3931] CHIP:DL: Device Type: 65535 (0xFFFF)
[1687852817.158803][3931:3931] CHIP:SVR: SetupQRCode: [MT:-24J0AFN00KA0648G00]
[1687852817.158808][3931:3931] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1687852817.158811][3931:3931] CHIP:SVR: project-chip.github.io/.../qrcode.html
[1687852817.158816][3931:3931] CHIP:SVR: Manual pairing code: [34970112332]
[1687852817.158819][3931:3931] CHIP:SWU: Using OTA file: matter.ota
[1687852817.158822][3931:3931] CHIP:SWU: Using ImageList file: (none)
[1687852817.158961][3931:3931] CHIP:DIS: Updating services using commissioning mode 1
[1687852817.160574][3931:3931] CHIP:DIS: CHIP minimal mDNS started advertising.
[1687852817.170770][3931:3931] CHIP:DL: Using wifi MAC for hostname
[1687852817.170789][3931:3931] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1687852817.170798][3931:3931] CHIP:DIS: Responding with _matterc._udp.local
[1687852817.170802][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.170805][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.170809][3931:3931] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687852817.170814][3931:3931] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1687852817.170818][3931:3931] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1687852817.170823][3931:3931] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1687852817.170826][3931:3931] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1687852817.170833][3931:3931] CHIP:DIS: Responding with 64EC48AF170C6C6F._matterc._udp.local
[1687852817.170836][3931:3931] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 64EC48AF170C6C6F.
[1687852817.175785][3931:3931] CHIP:DIS: mDNS service published: _matterc._udp
[1687852817.175898][3931:3931] CHIP:IM: No subscriptions to resume

OTBR is working on the same network, but the OTA file has been passed to the Provider App, but there is no response from the OTBR side log.

2. Pairing Provider to OTBR

(I entered the command below through another terminal.

sudo ./out/chiptool/chip-tool pairing onnetwork-long 5 20202021 3840)

[1687853724.051634][4846:4846] CHIP:EM: >>> [E:48469r S:0 M:216711552] (U) Msg RX from 0:214B88186B3D426B [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1687853724.051687][4846:4846] CHIP:EM: Handling via exchange: 48469r, Delegate: 0x5556ff929a80
[1687853724.051724][4846:4846] CHIP:SC: Received PBKDF param request
[1687853724.051757][4846:4846] CHIP:SC: Peer assigned session ID 31496
[1687853724.051821][4846:4846] CHIP:SC: Including MRP parameters in PBKDF param response
[1687853724.052005][4846:4846] CHIP:EM: <<< [E:48469r S:0 M:55669581 (Ack:216711552)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1687853724.052106][4846:4846] CHIP:IN: (U) Sending msg 55669581 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:45412'
[1687853724.052226][4846:4846] CHIP:SC: Sent PBKDF param response
[1687853724.060242][4846:4846] CHIP:EM: >>> [E:48469r S:0 M:216711553 (Ack:55669581)] (U) Msg RX from 0:214B88186B3D426B [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1687853724.060250][4846:4846] CHIP:EM: Found matching exchange: 48469r, Delegate: 0x5556ff929a80
[1687853724.060257][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:55669581 from Retrans Table on exchange 48469r
[1687853724.060264][4846:4846] CHIP:SC: Received spake2p msg1
[1687853724.060691][4846:4846] CHIP:EM: <<< [E:48469r S:0 M:55669582 (Ack:216711553)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1687853724.060714][4846:4846] CHIP:IN: (U) Sending msg 55669582 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:45412'
[1687853724.060741][4846:4846] CHIP:SC: Sent spake2p msg2
[1687853724.061506][4846:4846] CHIP:EM: >>> [E:48469r S:0 M:216711554 (Ack:55669582)] (U) Msg RX from 0:214B88186B3D426B [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1687853724.061515][4846:4846] CHIP:EM: Found matching exchange: 48469r, Delegate: 0x5556ff929a80
[1687853724.061521][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:55669582 from Retrans Table on exchange 48469r
[1687853724.061529][4846:4846] CHIP:SC: Received spake2p msg3
[1687853724.061550][4846:4846] CHIP:SC: Sending status report. Protocol code 0, exchange 48469
[1687853724.061560][4846:4846] CHIP:EM: <<< [E:48469r S:0 M:55669583 (Ack:216711554)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687853724.061579][4846:4846] CHIP:IN: (U) Sending msg 55669583 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:45412'
[1687853724.061638][4846:4846] CHIP:SC: SecureSession[0x555700537d20, LSID:36065]: State change 'kEstablishing' --> 'kActive'
[1687853724.061644][4846:4846] CHIP:IN: SecureSession[0x555700537d20]: Activated - Type:1 LSID:36065
[1687853724.061649][4846:4846] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:36065 PSID:31496!
[1687853724.061654][4846:4846] CHIP:SVR: Commissioning completed session establishment step
[1687853724.061665][4846:4846] CHIP:DIS: Updating services using commissioning mode 0
[1687853724.063346][4846:4846] CHIP:DIS: CHIP minimal mDNS started advertising.
[1687853724.073432][4846:4846] CHIP:SVR: Device completed Rendezvous process
[1687853724.073479][4846:4846] CHIP:EM: >>> [E:48470r S:36065 M:13703060] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1687853724.073491][4846:4846] CHIP:EM: Handling via exchange: 48470r, Delegate: 0x5556ff92afa8
[1687853724.073499][4846:4846] CHIP:IM: Received Read request
[1687853724.073514][4846:4846] CHIP:DMG: ReadRequestMessage =
[1687853724.073518][4846:4846] CHIP:DMG: {
[1687853724.073521][4846:4846] CHIP:DMG: AttributePathIBs =
[1687853724.073525][4846:4846] CHIP:DMG: [
[1687853724.073529][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073532][4846:4846] CHIP:DMG: {
[1687853724.073538][4846:4846] CHIP:DMG: Cluster = 0x31,
[1687853724.073547][4846:4846] CHIP:DMG: Attribute = 0x0000_FFFC,
[1687853724.073550][4846:4846] CHIP:DMG: }
[1687853724.073554][4846:4846] CHIP:DMG:
[1687853724.073559][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073564][4846:4846] CHIP:DMG: {
[1687853724.073568][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073573][4846:4846] CHIP:DMG: Cluster = 0x30,
[1687853724.073578][4846:4846] CHIP:DMG: Attribute = 0x0000_0000,
[1687853724.073582][4846:4846] CHIP:DMG: }
[1687853724.073587][4846:4846] CHIP:DMG:
[1687853724.073592][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073599][4846:4846] CHIP:DMG: {
[1687853724.073604][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073607][4846:4846] CHIP:DMG: Cluster = 0x30,
[1687853724.073611][4846:4846] CHIP:DMG: Attribute = 0x0000_0001,
[1687853724.073615][4846:4846] CHIP:DMG: }
[1687853724.073619][4846:4846] CHIP:DMG:
[1687853724.073622][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073625][4846:4846] CHIP:DMG: {
[1687853724.073629][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073633][4846:4846] CHIP:DMG: Cluster = 0x30,
[1687853724.073637][4846:4846] CHIP:DMG: Attribute = 0x0000_0002,
[1687853724.073644][4846:4846] CHIP:DMG: }
[1687853724.073648][4846:4846] CHIP:DMG:
[1687853724.073651][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073654][4846:4846] CHIP:DMG: {
[1687853724.073658][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073662][4846:4846] CHIP:DMG: Cluster = 0x30,
[1687853724.073665][4846:4846] CHIP:DMG: Attribute = 0x0000_0003,
[1687853724.073669][4846:4846] CHIP:DMG: }
[1687853724.073674][4846:4846] CHIP:DMG:
[1687853724.073677][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073681][4846:4846] CHIP:DMG: {
[1687853724.073685][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073690][4846:4846] CHIP:DMG: Cluster = 0x28,
[1687853724.073693][4846:4846] CHIP:DMG: Attribute = 0x0000_0002,
[1687853724.073698][4846:4846] CHIP:DMG: }
[1687853724.073702][4846:4846] CHIP:DMG:
[1687853724.073706][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073710][4846:4846] CHIP:DMG: {
[1687853724.073714][4846:4846] CHIP:DMG: Endpoint = 0x0,
[1687853724.073718][4846:4846] CHIP:DMG: Cluster = 0x28,
[1687853724.073722][4846:4846] CHIP:DMG: Attribute = 0x0000_0004,
[1687853724.073726][4846:4846] CHIP:DMG: }
[1687853724.073730][4846:4846] CHIP:DMG:
[1687853724.073734][4846:4846] CHIP:DMG: AttributePathIB =
[1687853724.073739][4846:4846] CHIP:DMG: {
[1687853724.073756][4846:4846] CHIP:DMG: Cluster = 0x31,
[1687853724.073767][4846:4846] CHIP:DMG: Attribute = 0x0000_0003,
[1687853724.073772][4846:4846] CHIP:DMG: }
[1687853724.073783][4846:4846] CHIP:DMG:
[1687853724.073787][4846:4846] CHIP:DMG: ],
[1687853724.073796][4846:4846] CHIP:DMG:
[1687853724.073800][4846:4846] CHIP:DMG: isFabricFiltered = false,
[1687853724.073804][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.073807][4846:4846] CHIP:DMG: },
[1687853724.073899][4846:4846] CHIP:DMG: IM RH moving to [GeneratingReports]
[1687853724.074042][4846:4846] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[1687853724.074049][4846:4846] CHIP:DMG: <RE:Run> Cluster 31, Attribute 3 is dirty
[1687853724.074053][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[1687853724.074058][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v
[1687853724.074063][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074071][4846:4846] CHIP:DMG: <RE:Run> Cluster 28, Attribute 4 is dirty
[1687853724.074075][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[1687853724.074079][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v
[1687853724.074083][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074105][4846:4846] CHIP:DMG: <RE:Run> Cluster 28, Attribute 2 is dirty
[1687853724.074109][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[1687853724.074113][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v
[1687853724.074116][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074125][4846:4846] CHIP:DMG: <RE:Run> Cluster 30, Attribute 3 is dirty
[1687853724.074128][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[1687853724.074136][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
[1687853724.074140][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074151][4846:4846] CHIP:DMG: <RE:Run> Cluster 30, Attribute 2 is dirty
[1687853724.074155][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[1687853724.074159][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
[1687853724.074162][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074171][4846:4846] CHIP:DMG: <RE:Run> Cluster 30, Attribute 1 is dirty
[1687853724.074175][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[1687853724.074179][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
[1687853724.074183][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074188][4846:4846] CHIP:DMG: <RE:Run> Cluster 30, Attribute 0 is dirty
[1687853724.074191][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[1687853724.074195][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v
[1687853724.074199][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074214][4846:4846] CHIP:DMG: <RE:Run> Cluster 31, Attribute fffc is dirty
[1687853724.074218][4846:4846] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[1687853724.074232][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v
[1687853724.074236][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.074247][4846:4846] CHIP:DMG: <RE> Sending report (payload has 228 bytes)...
[1687853724.074267][4846:4846] CHIP:EM: <<< [E:48470r S:36065 M:1578812 (Ack:13703060)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1687853724.074278][4846:4846] CHIP:IN: (S) Sending msg 1578812 on secure session with LSID: 36065
[1687853724.074307][4846:4846] CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
[1687853724.074317][4846:4846] CHIP:DMG: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[1687853724.074320][4846:4846] CHIP:DMG: IM RH moving to [AwaitingDestruction]
[1687853724.074327][4846:4846] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687853724.074342][4846:4846] CHIP:EM: >>> [E:48469r S:0 M:216711555 (Ack:55669583)] (U) Msg RX from 0:214B88186B3D426B [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.074347][4846:4846] CHIP:EM: Found matching exchange: 48469r, Delegate: (nil)
[1687853724.074356][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:55669583 from Retrans Table on exchange 48469r
[1687853724.076428][4846:4846] CHIP:EM: >>> [E:48471r S:36065 M:13703061] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.076437][4846:4846] CHIP:EM: Handling via exchange: 48471r, Delegate: 0x5556ff92afa8
[1687853724.076450][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.076454][4846:4846] CHIP:DMG: {
[1687853724.076457][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.076461][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.076465][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.076473][4846:4846] CHIP:DMG: [
[1687853724.076477][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.076482][4846:4846] CHIP:DMG: {
[1687853724.076486][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.076490][4846:4846] CHIP:DMG: {
[1687853724.076494][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.076499][4846:4846] CHIP:DMG: ClusterId = 0x30,
[1687853724.076503][4846:4846] CHIP:DMG: CommandId = 0x0,
[1687853724.076507][4846:4846] CHIP:DMG: },
[1687853724.076512][4846:4846] CHIP:DMG:
[1687853724.076516][4846:4846] CHIP:DMG: CommandFields =
[1687853724.076521][4846:4846] CHIP:DMG: {
[1687853724.076525][4846:4846] CHIP:DMG: 0x0 = 60,
[1687853724.076530][4846:4846] CHIP:DMG: 0x1 = 3,
[1687853724.076534][4846:4846] CHIP:DMG: },
[1687853724.076538][4846:4846] CHIP:DMG: },
[1687853724.076543][4846:4846] CHIP:DMG:
[1687853724.076547][4846:4846] CHIP:DMG: ],
[1687853724.076553][4846:4846] CHIP:DMG:
[1687853724.076557][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.076560][4846:4846] CHIP:DMG: },
[1687853724.076574][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a
[1687853724.076579][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.076583][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[1687853724.076589][4846:4846] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s)
[1687853724.076596][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 4359345
[1687853724.076602][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.076607][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.076613][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.076621][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.076635][4846:4846] CHIP:EM: <<< [E:48471r S:36065 M:1578813 (Ack:13703061)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.076642][4846:4846] CHIP:IN: (S) Sending msg 1578813 on secure session with LSID: 36065
[1687853724.076665][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.076670][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.077743][4846:4846] CHIP:EM: >>> [E:48470r S:36065 M:13703062 (Ack:1578812)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.077750][4846:4846] CHIP:EM: Found matching exchange: 48470r, Delegate: (nil)
[1687853724.077757][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578812 from Retrans Table on exchange 48470r
[1687853724.078793][4846:4846] CHIP:EM: >>> [E:48472r S:36065 M:13703063] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.078801][4846:4846] CHIP:EM: Handling via exchange: 48472r, Delegate: 0x5556ff92afa8
[1687853724.078813][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.078817][4846:4846] CHIP:DMG: {
[1687853724.078820][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.078824][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.078827][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.078834][4846:4846] CHIP:DMG: [
[1687853724.078837][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.078841][4846:4846] CHIP:DMG: {
[1687853724.078844][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.078849][4846:4846] CHIP:DMG: {
[1687853724.078853][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.078857][4846:4846] CHIP:DMG: ClusterId = 0x30,
[1687853724.078862][4846:4846] CHIP:DMG: CommandId = 0x2,
[1687853724.078866][4846:4846] CHIP:DMG: },
[1687853724.078870][4846:4846] CHIP:DMG:
[1687853724.078876][4846:4846] CHIP:DMG: CommandFields =
[1687853724.078881][4846:4846] CHIP:DMG: {
[1687853724.078885][4846:4846] CHIP:DMG: 0x0 = 0,
[1687853724.078891][4846:4846] CHIP:DMG: 0x1 = "XX" (2 chars),
[1687853724.078895][4846:4846] CHIP:DMG: 0x2 = 4,
[1687853724.078899][4846:4846] CHIP:DMG: },
[1687853724.078904][4846:4846] CHIP:DMG: },
[1687853724.078915][4846:4846] CHIP:DMG:
[1687853724.078919][4846:4846] CHIP:DMG: ],
[1687853724.078929][4846:4846] CHIP:DMG:
[1687853724.078933][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.078947][4846:4846] CHIP:DMG: },
[1687853724.078966][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a
[1687853724.078970][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.078975][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
[1687853724.079054][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_config.ini-bhqvlP)
[1687853724.079183][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1687853724.079197][4846:4846] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0)
[1687853724.079221][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_config.ini-oi0J68)
[1687853724.079491][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1687853724.079505][4846:4846] CHIP:DL: NVS set: chip-config/country-code = "XX"
[1687853724.079511][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 4359346
[1687853724.079519][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.079524][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.079529][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.079540][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.079558][4846:4846] CHIP:EM: <<< [E:48472r S:36065 M:1578814 (Ack:13703063)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.079567][4846:4846] CHIP:IN: (S) Sending msg 1578814 on secure session with LSID: 36065
[1687853724.079601][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.079606][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.079781][4846:4846] CHIP:EM: >>> [E:48471r S:36065 M:13703064 (Ack:1578813)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.079790][4846:4846] CHIP:EM: Found matching exchange: 48471r, Delegate: (nil)
[1687853724.079801][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578813 from Retrans Table on exchange 48471r
[1687853724.080886][4846:4846] CHIP:EM: >>> [E:48473r S:36065 M:13703065] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.080895][4846:4846] CHIP:EM: Handling via exchange: 48473r, Delegate: 0x5556ff92afa8
[1687853724.080907][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.080912][4846:4846] CHIP:DMG: {
[1687853724.080915][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.080919][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.080926][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.080931][4846:4846] CHIP:DMG: [
[1687853724.080935][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.080939][4846:4846] CHIP:DMG: {
[1687853724.080943][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.080948][4846:4846] CHIP:DMG: {
[1687853724.080952][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.080957][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.080961][4846:4846] CHIP:DMG: CommandId = 0x2,
[1687853724.080965][4846:4846] CHIP:DMG: },
[1687853724.080969][4846:4846] CHIP:DMG:
[1687853724.080984][4846:4846] CHIP:DMG: CommandFields =
[1687853724.080989][4846:4846] CHIP:DMG: {
[1687853724.080999][4846:4846] CHIP:DMG: 0x0 = 2,
[1687853724.081004][4846:4846] CHIP:DMG: },
[1687853724.081012][4846:4846] CHIP:DMG: },
[1687853724.081017][4846:4846] CHIP:DMG:
[1687853724.081021][4846:4846] CHIP:DMG: ],
[1687853724.081026][4846:4846] CHIP:DMG:
[1687853724.081042][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.081062][4846:4846] CHIP:DMG: },
[1687853724.081087][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.081092][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.081097][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[1687853724.081103][4846:4846] CHIP:ZCL: OpCreds: Certificate Chain request received for PAI
[1687853724.081109][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.081114][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.081119][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.081127][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.081153][4846:4846] CHIP:EM: <<< [E:48473r S:36065 M:1578815 (Ack:13703065)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.081169][4846:4846] CHIP:IN: (S) Sending msg 1578815 on secure session with LSID: 36065
[1687853724.081199][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.081204][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.082522][4846:4846] CHIP:EM: >>> [E:48472r S:36065 M:13703066 (Ack:1578814)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.082529][4846:4846] CHIP:EM: Found matching exchange: 48472r, Delegate: (nil)
[1687853724.082537][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578814 from Retrans Table on exchange 48472r
[1687853724.083537][4846:4846] CHIP:EM: >>> [E:48474r S:36065 M:13703067] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.083546][4846:4846] CHIP:EM: Handling via exchange: 48474r, Delegate: 0x5556ff92afa8
[1687853724.083558][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.083562][4846:4846] CHIP:DMG: {
[1687853724.083565][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.083569][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.083573][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.083578][4846:4846] CHIP:DMG: [
[1687853724.083582][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.083587][4846:4846] CHIP:DMG: {
[1687853724.083590][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.083595][4846:4846] CHIP:DMG: {
[1687853724.083600][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.083604][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.083608][4846:4846] CHIP:DMG: CommandId = 0x2,
[1687853724.083612][4846:4846] CHIP:DMG: },
[1687853724.083617][4846:4846] CHIP:DMG:
[1687853724.083621][4846:4846] CHIP:DMG: CommandFields =
[1687853724.083625][4846:4846] CHIP:DMG: {
[1687853724.083630][4846:4846] CHIP:DMG: 0x0 = 1,
[1687853724.083645][4846:4846] CHIP:DMG: },
[1687853724.083649][4846:4846] CHIP:DMG: },
[1687853724.083658][4846:4846] CHIP:DMG:
[1687853724.083662][4846:4846] CHIP:DMG: ],
[1687853724.083669][4846:4846] CHIP:DMG:
[1687853724.083673][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.083677][4846:4846] CHIP:DMG: },
[1687853724.083690][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.083699][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.083704][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[1687853724.083709][4846:4846] CHIP:ZCL: OpCreds: Certificate Chain request received for DAC
[1687853724.083715][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.083720][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.083724][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.083732][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.083755][4846:4846] CHIP:EM: <<< [E:48474r S:36065 M:1578816 (Ack:13703067)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.083761][4846:4846] CHIP:IN: (S) Sending msg 1578816 on secure session with LSID: 36065
[1687853724.083789][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.083793][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.084827][4846:4846] CHIP:EM: >>> [E:48473r S:36065 M:13703068 (Ack:1578815)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.084834][4846:4846] CHIP:EM: Found matching exchange: 48473r, Delegate: (nil)
[1687853724.084841][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578815 from Retrans Table on exchange 48473r
[1687853724.084930][4846:4846] CHIP:EM: >>> [E:48475r S:36065 M:13703069] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.084938][4846:4846] CHIP:EM: Handling via exchange: 48475r, Delegate: 0x5556ff92afa8
[1687853724.084949][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.084953][4846:4846] CHIP:DMG: {
[1687853724.084957][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.084961][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.084965][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.084970][4846:4846] CHIP:DMG: [
[1687853724.084974][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.084982][4846:4846] CHIP:DMG: {
[1687853724.084986][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.084990][4846:4846] CHIP:DMG: {
[1687853724.084997][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.085002][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.085006][4846:4846] CHIP:DMG: CommandId = 0x0,
[1687853724.085020][4846:4846] CHIP:DMG: },
[1687853724.085029][4846:4846] CHIP:DMG:
[1687853724.085033][4846:4846] CHIP:DMG: CommandFields =
[1687853724.085045][4846:4846] CHIP:DMG: {
[1687853724.085049][4846:4846] CHIP:DMG: 0x0 = [
[1687853724.085061][4846:4846] CHIP:DMG: 0xda, 0x0c, 0xbc, 0xe2, 0x57, 0x46, 0x68, 0x5a, 0x26, 0x6f, 0x9e, 0x65, 0x80, 0x82, 0xc4, 0x8f, 0xa8, 0x64, 0xa9, 0x64, 0x16, 0x77, 0xc7, 0x5a, 0xc2, 0x4d, 0xea, 0x06, 0xbf, 0xa2, 0x93, 0x5e,
[1687853724.085067][4846:4846] CHIP:DMG: ] (32 bytes)
[1687853724.085077][4846:4846] CHIP:DMG: },
[1687853724.085081][4846:4846] CHIP:DMG: },
[1687853724.085090][4846:4846] CHIP:DMG:
[1687853724.085094][4846:4846] CHIP:DMG: ],
[1687853724.085099][4846:4846] CHIP:DMG:
[1687853724.085103][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.085111][4846:4846] CHIP:DMG: },
[1687853724.085125][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.085129][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.085140][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
[1687853724.085147][4846:4846] CHIP:ZCL: OpCreds: Received an AttestationRequest command
[1687853724.085162][4846:4846] CHIP:EM: <<< [E:48475r S:36065 M:1578817 (Ack:13703069)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.085169][4846:4846] CHIP:IN: (S) Sending msg 1578817 on secure session with LSID: 36065
[1687853724.085191][4846:4846] CHIP:EM: Flushed pending ack for MessageCounter:13703069 on exchange 48475r
[1687853724.085341][4846:4846] CHIP:ZCL: OpCreds: AttestationRequest successful.
[1687853724.085350][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.085355][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.085360][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.085370][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.085384][4846:4846] CHIP:EM: <<< [E:48475r S:36065 M:1578818 (Ack:13703069)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.085395][4846:4846] CHIP:IN: (S) Sending msg 1578818 on secure session with LSID: 36065
[1687853724.085417][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.085422][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.085455][4846:4846] CHIP:EM: >>> [E:48474r S:36065 M:13703070 (Ack:1578816)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.085462][4846:4846] CHIP:EM: Found matching exchange: 48474r, Delegate: (nil)
[1687853724.085468][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578816 from Retrans Table on exchange 48474r
[1687853724.094440][4846:4846] CHIP:EM: >>> [E:48476r S:36065 M:13703071] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.094452][4846:4846] CHIP:EM: Handling via exchange: 48476r, Delegate: 0x5556ff92afa8
[1687853724.094466][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.094470][4846:4846] CHIP:DMG: {
[1687853724.094473][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.094477][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.094482][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.094487][4846:4846] CHIP:DMG: [
[1687853724.094492][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.094497][4846:4846] CHIP:DMG: {
[1687853724.094501][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.094505][4846:4846] CHIP:DMG: {
[1687853724.094510][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.094514][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.094521][4846:4846] CHIP:DMG: CommandId = 0x4,
[1687853724.094525][4846:4846] CHIP:DMG: },
[1687853724.094530][4846:4846] CHIP:DMG:
[1687853724.094535][4846:4846] CHIP:DMG: CommandFields =
[1687853724.094539][4846:4846] CHIP:DMG: {
[1687853724.094543][4846:4846] CHIP:DMG: 0x0 = [
[1687853724.094550][4846:4846] CHIP:DMG: 0x30, 0xb5, 0x2f, 0x90, 0x58, 0x9f, 0x74, 0xd3, 0x7a, 0x3b, 0x59, 0x54, 0xac, 0x54, 0xba, 0xcf, 0x3f, 0x5d, 0x8f, 0x09, 0x1d, 0x7e, 0xf5, 0x0f, 0x87, 0x86, 0x0f, 0xe9, 0xe1, 0xc3, 0xe6, 0xdf,
[1687853724.094556][4846:4846] CHIP:DMG: ] (32 bytes)
[1687853724.094560][4846:4846] CHIP:DMG: },
[1687853724.094565][4846:4846] CHIP:DMG: },
[1687853724.094571][4846:4846] CHIP:DMG:
[1687853724.094574][4846:4846] CHIP:DMG: ],
[1687853724.094580][4846:4846] CHIP:DMG:
[1687853724.094584][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.094588][4846:4846] CHIP:DMG: },
[1687853724.094602][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.094607][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.094612][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
[1687853724.094618][4846:4846] CHIP:ZCL: OpCreds: Received a CSRRequest command
[1687853724.094622][4846:4846] CHIP:ZCL: OpCreds: Finding fabric with fabricIndex 0x0
[1687853724.094636][4846:4846] CHIP:EM: <<< [E:48476r S:36065 M:1578819 (Ack:13703071)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.094643][4846:4846] CHIP:IN: (S) Sending msg 1578819 on secure session with LSID: 36065
[1687853724.094663][4846:4846] CHIP:EM: Flushed pending ack for MessageCounter:13703071 on exchange 48476r
[1687853724.094940][4846:4846] CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded
[1687853724.095009][4846:4846] CHIP:ZCL: OpCreds: CSRRequest successful.
[1687853724.095018][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.095023][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.095032][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.095042][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.095057][4846:4846] CHIP:EM: <<< [E:48476r S:36065 M:1578820 (Ack:13703071)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.095064][4846:4846] CHIP:IN: (S) Sending msg 1578820 on secure session with LSID: 36065
[1687853724.095089][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.095094][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.095121][4846:4846] CHIP:EM: >>> [E:48475r S:36065 M:13703072 (Ack:1578818)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.095127][4846:4846] CHIP:EM: Found matching exchange: 48475r, Delegate: (nil)
[1687853724.095134][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578818 from Retrans Table on exchange 48475r
[1687853724.098504][4846:4846] CHIP:EM: >>> [E:48477r S:36065 M:13703073] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.098515][4846:4846] CHIP:EM: Handling via exchange: 48477r, Delegate: 0x5556ff92afa8
[1687853724.098531][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.098535][4846:4846] CHIP:DMG: {
[1687853724.098538][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.098544][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.098549][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.098556][4846:4846] CHIP:DMG: [
[1687853724.098560][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.098565][4846:4846] CHIP:DMG: {
[1687853724.098570][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.098574][4846:4846] CHIP:DMG: {
[1687853724.098578][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.098582][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.098588][4846:4846] CHIP:DMG: CommandId = 0xb,
[1687853724.098593][4846:4846] CHIP:DMG: },
[1687853724.098598][4846:4846] CHIP:DMG:
[1687853724.098602][4846:4846] CHIP:DMG: CommandFields =
[1687853724.098607][4846:4846] CHIP:DMG: {
[1687853724.098611][4846:4846] CHIP:DMG: 0x0 = [
[1687853724.098633][4846:4846] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x14, 0x01, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x02, 0xcc, 0xff, 0xe8, 0x5e, 0x1c, 0x2f, 0xa8, 0x66, 0x4a, 0xc5, 0x05, 0x82, 0x60, 0xb5, 0x3a, 0xb9, 0x94, 0x56, 0xeb, 0x34, 0x4c, 0x30, 0x2d, 0x5c, 0x91, 0x29, 0xf2, 0x0b, 0x54, 0x68, 0xfd, 0x3a, 0xc8, 0xe2, 0x66, 0x43, 0x3d, 0x09, 0x70, 0xf5, 0xca, 0xa7, 0x89, 0x0e, 0x5b, 0xf2, 0xe8, 0x3d, 0xd8, 0xe8, 0xc6, 0x97, 0xc8, 0x4f, 0x7e, 0xd5, 0xdd, 0xcd, 0xa9, 0xe7, 0x39, 0xa0, 0x6f, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x0c, 0xb1, 0x46, 0x6f, 0x6c, 0xb6, 0xd9, 0x33, 0x91, 0x67, 0x54, 0x43, 0x93, 0xaa, 0x3a, 0x4b, 0x46, 0x21, 0xed, 0x06, 0x30, 0x05, 0x14, 0x0c, 0xb1, 0x46, 0x6f, 0x6c, 0xb6, 0xd9, 0x33, 0x91, 0x67, 0x54, 0x43, 0x93, 0xaa, 0x3a, 0x4b, 0x46, 0x21, 0xed, 0x06, 0x18, 0x30, 0x0b, 0x40, 0x11, 0x63, 0xeb, 0x38, 0x3b, 0xdd, 0xc0, 0x9a, 0x2e, 0xcd, 0xb1, 0xa9, 0x2d, 0x69, 0xd6, 0xdd, 0x56, 0x16, 0xa9, 0xe8, 0xf9, 0x86, 0xd5, 0xcf, 0x9e, 0xf7, 0x64, 0xa6, 0xbb, 0x52, 0x58, 0x0b, 0x8b, 0xe7, 0x80, 0x2f, 0xa8, 0xc3, 0xa5, 0xc9, 0x93, 0x3b, 0x69, 0x37, 0x35, 0xf0, 0x00, 0x8c, 0xbf, 0x1d, 0xf4, 0xdb, 0xc2, 0xc4, 0xdd, 0x5a, 0xd8, 0x6c, 0xbd, 0xd6, 0x22, 0xdc, 0x6e, 0x74, 0x18,
[1687853724.098645][4846:4846] CHIP:DMG: ] (231 bytes)
[1687853724.098650][4846:4846] CHIP:DMG: },
[1687853724.098653][4846:4846] CHIP:DMG: },
[1687853724.098659][4846:4846] CHIP:DMG:
[1687853724.098662][4846:4846] CHIP:DMG: ],
[1687853724.098668][4846:4846] CHIP:DMG:
[1687853724.098672][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.098675][4846:4846] CHIP:DMG: },
[1687853724.098690][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.098695][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.098699][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
[1687853724.098705][4846:4846] CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command
[1687853724.098719][4846:4846] CHIP:EM: <<< [E:48477r S:36065 M:1578821 (Ack:13703073)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.098726][4846:4846] CHIP:IN: (S) Sending msg 1578821 on secure session with LSID: 36065
[1687853724.098746][4846:4846] CHIP:EM: Flushed pending ack for MessageCounter:13703073 on exchange 48477r
[1687853724.098947][4846:4846] CHIP:ZCL: OpCreds: AddTrustedRootCertificate successful.
[1687853724.098956][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.098961][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.098965][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.098975][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.098988][4846:4846] CHIP:EM: <<< [E:48477r S:36065 M:1578822 (Ack:13703073)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.098995][4846:4846] CHIP:IN: (S) Sending msg 1578822 on secure session with LSID: 36065
[1687853724.099019][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.099024][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.099049][4846:4846] CHIP:EM: >>> [E:48476r S:36065 M:13703074 (Ack:1578820)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.099055][4846:4846] CHIP:EM: Found matching exchange: 48476r, Delegate: (nil)
[1687853724.099061][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578820 from Retrans Table on exchange 48476r
[1687853724.099321][4846:4846] CHIP:EM: >>> [E:48478r S:36065 M:13703075] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.099332][4846:4846] CHIP:EM: Handling via exchange: 48478r, Delegate: 0x5556ff92afa8
[1687853724.099357][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.099362][4846:4846] CHIP:DMG: {
[1687853724.099366][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.099369][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.099373][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.099381][4846:4846] CHIP:DMG: [
[1687853724.099385][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.099389][4846:4846] CHIP:DMG: {
[1687853724.099393][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.099398][4846:4846] CHIP:DMG: {
[1687853724.099402][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.099408][4846:4846] CHIP:DMG: ClusterId = 0x3e,
[1687853724.099412][4846:4846] CHIP:DMG: CommandId = 0x6,
[1687853724.099416][4846:4846] CHIP:DMG: },
[1687853724.099421][4846:4846] CHIP:DMG:
[1687853724.099425][4846:4846] CHIP:DMG: CommandFields =
[1687853724.099429][4846:4846] CHIP:DMG: {
[1687853724.099434][4846:4846] CHIP:DMG: 0x0 = [
[1687853724.099456][4846:4846] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x13, 0x02, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x15, 0x01, 0x24, 0x11, 0x05, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x05, 0xe9, 0x15, 0xa6, 0xc6, 0xb1, 0x2d, 0xfa, 0xf4, 0x02, 0x80, 0x69, 0x0f, 0x2e, 0xf9, 0x22, 0xe2, 0x9b, 0x02, 0x89, 0xa3, 0xaf, 0x7c, 0xe4, 0xb4, 0x2c, 0x61, 0x7f, 0x23, 0x58, 0x4d, 0x34, 0x07, 0x3d, 0xc4, 0x21, 0xb4, 0x69, 0x19, 0xe7, 0xfa, 0x15, 0xb3, 0xb7, 0x48, 0x83, 0xcb, 0xe4, 0x39, 0x01, 0x0f, 0x96, 0x9c, 0x55, 0x79, 0x6e, 0x9e, 0x7d, 0x4c, 0x9c, 0x4c, 0xf2, 0xaf, 0xf5, 0x37, 0x0a, 0x35, 0x01, 0x28, 0x01, 0x18, 0x24, 0x02, 0x01, 0x36, 0x03, 0x04, 0x02, 0x04, 0x01, 0x18, 0x30, 0x04, 0x14, 0x4a, 0xb1, 0x17, 0x3c, 0xe1, 0x2e, 0x55, 0x96, 0x7d, 0x96, 0xdf, 0x5b, 0xf7, 0x61, 0x6d, 0xbb, 0xef, 0xd8, 0x41, 0x6a, 0x30, 0x05, 0x14, 0xff, 0xf1, 0x03, 0x59, 0x57, 0x1c, 0xd1, 0x75, 0x33, 0x2b, 0xa6, 0xe2, 0xf8, 0x82, 0x18, 0xfa, 0x64, 0x7e, 0x6a, 0x59, 0x18, 0x30, 0x0b, 0x40, 0x0e, 0xa1, 0x00, 0x44, 0xa4, 0x60, 0x07, 0xa3, 0xca, 0x06, 0xbd, 0x55, 0xd5, 0xd8, 0xe6, 0x57, 0x34, 0x0c, 0xba, 0xdc, 0x4d, 0x40, 0x47, 0x63, 0x5f, 0x90, 0xa2, 0xff, 0xf1, 0x75, 0xf9, 0x39, 0x07, 0x5d, 0x44, 0x92, 0x8f, 0x2d, 0xa8, 0x63, 0xc3, 0x14, 0x3c, 0xda, 0xa0, 0xf8, 0x31, 0x66, 0x0b, 0x9f, 0x6a, 0xf9, 0xe5, 0xd1, 0xb2, 0x72, 0x7d, 0xc2, 0xb8, 0x5f, 0x4d, 0xdd, 0x12, 0x24, 0x18,
[1687853724.099468][4846:4846] CHIP:DMG: ] (241 bytes)
[1687853724.099472][4846:4846] CHIP:DMG: 0x1 = [
[1687853724.099493][4846:4846] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x13, 0x02, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x0b, 0x14, 0x72, 0xe1, 0x8e, 0x35, 0x9f, 0x29, 0x3b, 0x54, 0xdd, 0x03, 0xd5, 0xf2, 0x64, 0xaf, 0x87, 0xb8, 0x72, 0xb0, 0x79, 0x5e, 0xff, 0xb9, 0x86, 0x4c, 0x70, 0x8b, 0xf0, 0x65, 0x24, 0x7c, 0x08, 0xee, 0x5d, 0xfd, 0x5b, 0xe3, 0x0b, 0x7b, 0x7b, 0xfd, 0x73, 0x98, 0xb4, 0x25, 0xe0, 0x4f, 0xbf, 0xda, 0x92, 0xc9, 0xa7, 0x9b, 0x57, 0x70, 0x96, 0xd3, 0x32, 0xd1, 0x34, 0xe0, 0xef, 0x6c, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0xff, 0xf1, 0x03, 0x59, 0x57, 0x1c, 0xd1, 0x75, 0x33, 0x2b, 0xa6, 0xe2, 0xf8, 0x82, 0x18, 0xfa, 0x64, 0x7e, 0x6a, 0x59, 0x30, 0x05, 0x14, 0x0c, 0xb1, 0x46, 0x6f, 0x6c, 0xb6, 0xd9, 0x33, 0x91, 0x67, 0x54, 0x43, 0x93, 0xaa, 0x3a, 0x4b, 0x46, 0x21, 0xed, 0x06, 0x18, 0x30, 0x0b, 0x40, 0x55, 0xb3, 0x7a, 0x5d, 0x5c, 0xb6, 0x2c, 0x51, 0x12, 0x85, 0x98, 0x8c, 0xf2, 0xec, 0x88, 0x9b, 0x69, 0x3a, 0x25, 0x19, 0x27, 0x8f, 0x92, 0xd8, 0xfe, 0x56, 0x76, 0xbd, 0xae, 0x85, 0x3b, 0x1b, 0x36, 0x0d, 0xbf, 0xb8, 0x64, 0x67, 0xd3, 0xb1, 0xb2, 0x81, 0xc5, 0x19, 0x6f, 0xfb, 0x91, 0x75, 0xa5, 0x06, 0x32, 0xb4, 0x31, 0x98, 0x09, 0xb5, 0x2e, 0x56, 0x36, 0x95, 0xf8, 0x68, 0x72, 0x5f, 0x18,
[1687853724.099504][4846:4846] CHIP:DMG: ] (231 bytes)
[1687853724.099508][4846:4846] CHIP:DMG: 0x2 = [
[1687853724.099514][4846:4846] CHIP:DMG: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31,
[1687853724.099519][4846:4846] CHIP:DMG: ] (16 bytes)
[1687853724.099524][4846:4846] CHIP:DMG: 0x3 = 112233,
[1687853724.099528][4846:4846] CHIP:DMG: 0x4 = 65521,
[1687853724.099532][4846:4846] CHIP:DMG: },
[1687853724.099536][4846:4846] CHIP:DMG: },
[1687853724.099543][4846:4846] CHIP:DMG:
[1687853724.099546][4846:4846] CHIP:DMG: ],
[1687853724.099553][4846:4846] CHIP:DMG:
[1687853724.099557][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.099560][4846:4846] CHIP:DMG: },
[1687853724.099575][4846:4846] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a
[1687853724.099581][4846:4846] CHIP:DMG: AccessControl: implicit admin (PASE)
[1687853724.099586][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
[1687853724.099594][4846:4846] CHIP:ZCL: OpCreds: Received an AddNOC command
[1687853724.099608][4846:4846] CHIP:EM: <<< [E:48478r S:36065 M:1578823 (Ack:13703075)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.099615][4846:4846] CHIP:IN: (S) Sending msg 1578823 on secure session with LSID: 36065
[1687853724.099636][4846:4846] CHIP:EM: Flushed pending ack for MessageCounter:13703075 on exchange 48478r
[1687853724.099689][4846:4846] CHIP:FP: Validating NOC chain
[1687853724.100077][4846:4846] CHIP:FP: NOC chain validation successful
[1687853724.100084][4846:4846] CHIP:FP: Added new fabric at index: 0x2
[1687853724.100088][4846:4846] CHIP:FP: Assigned compressed fabric ID: 0xB041468536BEE9DB, node ID: 0x0000000000000005
[1687853724.100093][4846:4846] CHIP:TS: Last Known Good Time: 2023-06-26T17:21:28
[1687853724.100097][4846:4846] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687853724.100100][4846:4846] CHIP:TS: Retaining current Last Known Good Time
[1687853724.100106][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 6c6c4edf
[1687853724.100110][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 6c6c4ee0
[1687853724.100220][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-veZ9PO)
[1687853724.100356][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.100400][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-2vRbys)
[1687853724.100581][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.100613][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-x05yuW)
[1687853724.100715][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.100728][4846:4846] CHIP:DMG: AccessControl: validating f=2 p=a a=c s=1 t=0
[1687853724.100732][4846:4846] CHIP:DMG: validating subject 0x000000000001B669
[1687853724.100764][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-12oZFz)
[1687853724.100865][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.100890][4846:4846] CHIP:EVL: LogEvent event number: 0x0000000000060002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000188FBEBF1C4
[1687853724.100896][4846:4846] CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0x000000000001B669
[1687853724.101029][4846:4846] CHIP:DL: Using wifi MAC for hostname
[1687853724.101036][4846:4846] CHIP:DIS: Advertise operational node B041468536BEE9DB-0000000000000005
[1687853724.101046][4846:4846] CHIP:DIS: Responding with _matter._tcp.local
[1687853724.101051][4846:4846] CHIP:DIS: Responding with B041468536BEE9DB-0000000000000005._matter._tcp.local
[1687853724.101056][4846:4846] CHIP:DIS: Responding with B041468536BEE9DB-0000000000000005._matter._tcp.local
[1687853724.101060][4846:4846] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687853724.101065][4846:4846] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687853724.101070][4846:4846] CHIP:DIS: Responding with _IB041468536BEE9DB._sub._matter._tcp.local
[1687853724.101074][4846:4846] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: B041468536BEE9DB-0000000000000005.
[1687853724.105817][4846:4846] CHIP:DIS: mDNS service published: _matter._tcp
[1687853724.105826][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 6c6c4ee1
[1687853724.105830][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 6c6c4ee2
[1687853724.105836][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.105843][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.105849][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.105852][4846:4846] CHIP:ZCL: OpCreds: successfully created fabric index 0x2 via AddNOC
[1687853724.105865][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.105887][4846:4846] CHIP:EM: <<< [E:48478r S:36065 M:1578824 (Ack:13703075)] (S) Msg TX to 2:FFFFFFFB00000000 [E9DB] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.105894][4846:4846] CHIP:IN: (S) Sending msg 1578824 on secure session with LSID: 36065
[1687853724.105921][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.105926][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.105954][4846:4846] CHIP:EM: >>> [E:48477r S:36065 M:13703076 (Ack:1578822)] (S) Msg RX from 2:FFFFFFFB00000000 [E9DB] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.105959][4846:4846] CHIP:EM: Found matching exchange: 48477r, Delegate: (nil)
[1687853724.105965][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578822 from Retrans Table on exchange 48477r
[1687853724.106752][4846:4846] CHIP:EM: >>> [E:48478r S:36065 M:13703077 (Ack:1578824)] (S) Msg RX from 2:FFFFFFFB00000000 [E9DB] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.106761][4846:4846] CHIP:EM: Found matching exchange: 48478r, Delegate: (nil)
[1687853724.106769][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:1578824 from Retrans Table on exchange 48478r
[1687853724.307787][4846:4846] CHIP:EM: >>> [E:48479r S:0 M:216711556] (U) Msg RX from 0:1B7E57D5869201C9 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1687853724.307836][4846:4846] CHIP:EM: Handling via exchange: 48479r, Delegate: 0x5556ff927750
[1687853724.307877][4846:4846] CHIP:IN: CASE Server received Sigma1 message . Starting handshake. EC 0x555700536690
[1687853724.307898][4846:4846] CHIP:IN: CASE Server disabling CASE session setups
[1687853724.307925][4846:4846] CHIP:SC: Received Sigma1 msg
[1687853724.307963][4846:4846] CHIP:SC: Peer assigned session key ID 31497
[1687853724.308384][4846:4846] CHIP:SC: CASE matched destination ID: fabricIndex 2, NodeID 0x0000000000000005
[1687853724.309997][4846:4846] CHIP:SC: Including MRP parameters
[1687853724.310069][4846:4846] CHIP:EM: <<< [E:48479r S:0 M:55669584 (Ack:216711556)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1687853724.310157][4846:4846] CHIP:IN: (U) Sending msg 55669584 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:45412'
[1687853724.310319][4846:4846] CHIP:SC: Sent Sigma2 msg
[1687853724.315357][4846:4846] CHIP:EM: >>> [E:48479r S:0 M:216711557 (Ack:55669584)] (U) Msg RX from 0:1B7E57D5869201C9 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1687853724.315394][4846:4846] CHIP:EM: Found matching exchange: 48479r, Delegate: 0x5556ff927788
[1687853724.315429][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:55669584 from Retrans Table on exchange 48479r
[1687853724.315463][4846:4846] CHIP:SC: Received Sigma3 msg
[1687853724.318335][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-9fJiux)
[1687853724.318855][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.319011][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-hYUduw)
[1687853724.319457][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.319592][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-qmfzOq)
[1687853724.320013][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.320057][4846:4846] CHIP:SC: Sending status report. Protocol code 0, exchange 48479
[1687853724.320104][4846:4846] CHIP:EM: <<< [E:48479r S:0 M:55669585 (Ack:216711557)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687853724.320189][4846:4846] CHIP:IN: (U) Sending msg 55669585 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:45412'
[1687853724.320410][4846:4846] CHIP:SC: SecureSession[0x5557005380e0, LSID:36066]: State change 'kEstablishing' --> 'kActive'
[1687853724.320416][4846:4846] CHIP:IN: SecureSession[0x5557005380e0]: Activated - Type:2 LSID:36066
[1687853724.320419][4846:4846] CHIP:IN: New secure session activated for device <000000000001B669, 2>, LSID:36066 PSID:31497!
[1687853724.320423][4846:4846] CHIP:IN: CASE Session established to peer: <000000000001B669, 2>
[1687853724.320427][4846:4846] CHIP:IN: CASE Server enabling CASE session setups
[1687853724.320440][4846:4846] CHIP:IN: SecureSession[0x55570054f140]: Allocated Type:2 LSID:36067
[1687853724.320447][4846:4846] CHIP:SC: Allocated SecureSession (0x55570054f140) - waiting for Sigma1 msg
[1687853724.321116][4846:4846] CHIP:EM: >>> [E:48480r S:36066 M:216258696] (S) Msg RX from 2:000000000001B669 [E9DB] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687853724.321126][4846:4846] CHIP:EM: Handling via exchange: 48480r, Delegate: 0x5556ff92afa8
[1687853724.321141][4846:4846] CHIP:DMG: InvokeRequestMessage =
[1687853724.321149][4846:4846] CHIP:DMG: {
[1687853724.321154][4846:4846] CHIP:DMG: suppressResponse = false,
[1687853724.321158][4846:4846] CHIP:DMG: timedRequest = false,
[1687853724.321162][4846:4846] CHIP:DMG: InvokeRequests =
[1687853724.321169][4846:4846] CHIP:DMG: [
[1687853724.321173][4846:4846] CHIP:DMG: CommandDataIB =
[1687853724.321177][4846:4846] CHIP:DMG: {
[1687853724.321181][4846:4846] CHIP:DMG: CommandPathIB =
[1687853724.321186][4846:4846] CHIP:DMG: {
[1687853724.321191][4846:4846] CHIP:DMG: EndpointId = 0x0,
[1687853724.321196][4846:4846] CHIP:DMG: ClusterId = 0x30,
[1687853724.321200][4846:4846] CHIP:DMG: CommandId = 0x4,
[1687853724.321205][4846:4846] CHIP:DMG: },
[1687853724.321209][4846:4846] CHIP:DMG:
[1687853724.321214][4846:4846] CHIP:DMG: CommandFields =
[1687853724.321220][4846:4846] CHIP:DMG: {
[1687853724.321224][4846:4846] CHIP:DMG: },
[1687853724.321227][4846:4846] CHIP:DMG: },
[1687853724.321232][4846:4846] CHIP:DMG:
[1687853724.321236][4846:4846] CHIP:DMG: ],
[1687853724.321241][4846:4846] CHIP:DMG:
[1687853724.321245][4846:4846] CHIP:DMG: InteractionModelRevision = 1
[1687853724.321249][4846:4846] CHIP:DMG: },
[1687853724.321263][4846:4846] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0030 e=0 p=a
[1687853724.321270][4846:4846] CHIP:DMG: AccessControl: allowed
[1687853724.321275][4846:4846] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[1687853724.321280][4846:4846] CHIP:FS: GeneralCommissioning: Received CommissioningComplete
[1687853724.321315][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-8V6VMz)
[1687853724.321428][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.321462][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-lqmrDw)
[1687853724.321569][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.321578][4846:4846] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1687853724.321610][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-OE2snc)
[1687853724.321711][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.321749][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-8DPYFJ)
[1687853724.321851][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.321883][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-1orfJx)
[1687853724.321987][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.322020][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-STMQMg)
[1687853724.322126][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.322137][4846:4846] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-26T17:21:28
[1687853724.322161][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-Xq9ay4)
[1687853724.322274][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.322305][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-CLVxep)
[1687853724.322426][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.322438][4846:4846] CHIP:ZCL: OpCreds: Fabric index 0x2 was committed to storage. Compressed Fabric Id 0xB041468536BEE9DB, FabricId 0000000000000001, NodeId 0000000000000005, VendorId 0xFFF1
[1687853724.322463][4846:4846] CHIP:DL: writing settings to file (/tmp/chip_kvs-kpYuqF)
[1687853724.322575][4846:4846] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853724.322585][4846:4846] CHIP:FS: GeneralCommissioning: Successfully commited pending fabric data
[1687853724.322590][4846:4846] CHIP:FS: Fail-safe cleanly disarmed
[1687853724.322597][4846:4846] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 4359347
[1687853724.322606][4846:4846] CHIP:DMG: Command handler moving to [ Preparing]
[1687853724.322612][4846:4846] CHIP:DMG: Command handler moving to [AddingComm]
[1687853724.322618][4846:4846] CHIP:DMG: Command handler moving to [AddedComma]
[1687853724.322628][4846:4846] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1687853724.322646][4846:4846] CHIP:EM: <<< [E:48480r S:36066 M:79628260 (Ack:216258696)] (S) Msg TX to 2:000000000001B669 [E9DB] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687853724.322654][4846:4846] CHIP:IN: (S) Sending msg 79628260 on secure session with LSID: 36066
[1687853724.322687][4846:4846] CHIP:DMG: Command handler moving to [CommandSen]
[1687853724.322692][4846:4846] CHIP:DMG: Command handler moving to [AwaitingDe]
[1687853724.322701][4846:4846] CHIP:SVR: Commissioning completed successfully
[1687853724.322709][4846:4846] CHIP:DIS: Updating services using commissioning mode 0
[1687853724.324540][4846:4846] CHIP:DIS: CHIP minimal mDNS started advertising.
[1687853724.335640][4846:4846] CHIP:DL: Using wifi MAC for hostname
[1687853724.335653][4846:4846] CHIP:DIS: Advertise operational node B041468536BEE9DB-0000000000000005
[1687853724.335664][4846:4846] CHIP:DIS: Responding with _matter._tcp.local
[1687853724.335668][4846:4846] CHIP:DIS: Responding with B041468536BEE9DB-0000000000000005._matter._tcp.local
[1687853724.335673][4846:4846] CHIP:DIS: Responding with B041468536BEE9DB-0000000000000005._matter._tcp.local
[1687853724.335679][4846:4846] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687853724.335685][4846:4846] CHIP:DIS: Responding with E0D55EB9F3140000.local
[1687853724.335692][4846:4846] CHIP:DIS: Responding with _IB041468536BEE9DB._sub._matter._tcp.local
[1687853724.335696][4846:4846] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: B041468536BEE9DB-0000000000000005.
[1687853724.340622][4846:4846] CHIP:DIS: mDNS service published: _matter._tcp
[1687853724.340635][4846:4846] CHIP:IN: Expiring all PASE sessions
[1687853724.340639][4846:4846] CHIP:IN: SecureSession[0x555700537d20]: MarkForEviction Type:1 LSID:36065
[1687853724.340643][4846:4846] CHIP:SC: SecureSession[0x555700537d20, LSID:36065]: State change 'kActive' --> 'kPendingEviction'
[1687853724.340648][4846:4846] CHIP:IN: SecureSession[0x555700537d20]: Released - Type:1 LSID:36065
[1687853724.340686][4846:4846] CHIP:EM: >>> [E:48479r S:0 M:216711558 (Ack:55669585)] (U) Msg RX from 0:1B7E57D5869201C9 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.340693][4846:4846] CHIP:EM: Found matching exchange: 48479r, Delegate: (nil)
[1687853724.340701][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:55669585 from Retrans Table on exchange 48479r
[1687853724.340821][4846:4846] CHIP:EM: >>> [E:48480r S:36066 M:216258697 (Ack:79628260)] (S) Msg RX from 2:000000000001B669 [E9DB] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853724.340827][4846:4846] CHIP:EM: Found matching exchange: 48480r, Delegate: (nil)
[1687853724.340833][4846:4846] CHIP:EM: Rxd Ack; Removing MessageCounter:79628260 from Retrans Table on exchange 48480r

As expected, there was no response to the OTBR side log (only the log that comes out constantly, not a large number of logs)

3. Modifying Provider Permissions

(I entered the command below through another terminal.

sudo ./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)

[1687853946.736072][4923:4923] CHIP:EM: >>> [E:28978r S:0 M:193956048] (U) Msg RX from 0:03C288D3E286CBBB [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1687853946.736126][4923:4923] CHIP:EM: Handling via exchange: 28978r, Delegate: 0x563e5ddb7750
[1687853946.736156][4923:4923] CHIP:IN: CASE Server received Sigma1 message . Starting handshake. EC 0x563e5e008510
[1687853946.736173][4923:4923] CHIP:IN: CASE Server disabling CASE session setups
[1687853946.736195][4923:4923] CHIP:SC: Received Sigma1 msg
[1687853946.736235][4923:4923] CHIP:SC: Peer assigned session key ID 39407
[1687853946.736683][4923:4923] CHIP:SC: CASE matched destination ID: fabricIndex 2, NodeID 0x0000000000000005
[1687853946.738709][4923:4923] CHIP:SC: Including MRP parameters
[1687853946.738779][4923:4923] CHIP:EM: <<< [E:28978r S:0 M:41196414 (Ack:193956048)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1687853946.738874][4923:4923] CHIP:IN: (U) Sending msg 41196414 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:32925'
[1687853946.738999][4923:4923] CHIP:SC: Sent Sigma2 msg
[1687853946.743877][4923:4923] CHIP:EM: >>> [E:28978r S:0 M:193956049 (Ack:41196414)] (U) Msg RX from 0:03C288D3E286CBBB [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1687853946.743919][4923:4923] CHIP:EM: Found matching exchange: 28978r, Delegate: 0x563e5ddb7788
[1687853946.743947][4923:4923] CHIP:EM: Rxd Ack; Removing MessageCounter:41196414 from Retrans Table on exchange 28978r
[1687853946.743980][4923:4923] CHIP:SC: Received Sigma3 msg
[1687853946.747010][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-QgBdAD)
[1687853946.747570][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.747730][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-B8o4ac)
[1687853946.748201][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.748360][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-LaVoFc)
[1687853946.748833][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.748875][4923:4923] CHIP:SC: Sending status report. Protocol code 0, exchange 28978
[1687853946.748921][4923:4923] CHIP:EM: <<< [E:28978r S:0 M:41196415 (Ack:193956049)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687853946.749003][4923:4923] CHIP:IN: (U) Sending msg 41196415 to IP address 'UDP:[fe80::d0e2:36ff:fefb:5574%veth2167abf]:32925'
[1687853946.749178][4923:4923] CHIP:SC: SecureSession[0x563e5e0098d0, LSID:16800]: State change 'kEstablishing' --> 'kActive'
[1687853946.749186][4923:4923] CHIP:IN: SecureSession[0x563e5e0098d0]: Activated - Type:2 LSID:16800
[1687853946.749189][4923:4923] CHIP:IN: New secure session activated for device <000000000001B669, 2>, LSID:16800 PSID:39407!
[1687853946.749193][4923:4923] CHIP:IN: CASE Session established to peer: <000000000001B669, 2>
[1687853946.749196][4923:4923] CHIP:IN: CASE Server enabling CASE session setups
[1687853946.749210][4923:4923] CHIP:IN: SecureSession[0x563e5e0075b0]: Allocated Type:2 LSID:16801
[1687853946.749218][4923:4923] CHIP:SC: Allocated SecureSession (0x563e5e0075b0) - waiting for Sigma1 msg
[1687853946.749918][4923:4923] CHIP:EM: >>> [E:28979r S:16800 M:84615548] (S) Msg RX from 2:000000000001B669 [E9DB] --- Type 0001:06 (IM:WriteRequest)
[1687853946.749931][4923:4923] CHIP:EM: Handling via exchange: 28979r, Delegate: 0x563e5ddbafa8
[1687853946.749940][4923:4923] CHIP:IM: Received Write request
[1687853946.749944][4923:4923] CHIP:DMG: IM WH moving to [Initialized]
[1687853946.749960][4923:4923] CHIP:DMG: WriteRequestMessage =
[1687853946.749964][4923:4923] CHIP:DMG: {
[1687853946.749968][4923:4923] CHIP:DMG: suppressResponse = false,
[1687853946.749972][4923:4923] CHIP:DMG: timedRequest = false,
[1687853946.749976][4923:4923] CHIP:DMG: AttributeDataIBs =
[1687853946.749983][4923:4923] CHIP:DMG: [
[1687853946.749988][4923:4923] CHIP:DMG: AttributeDataIB =
[1687853946.749992][4923:4923] CHIP:DMG: {
[1687853946.749996][4923:4923] CHIP:DMG: AttributePathIB =
[1687853946.750000][4923:4923] CHIP:DMG: {
[1687853946.750005][4923:4923] CHIP:DMG: Endpoint = 0x0,
[1687853946.750009][4923:4923] CHIP:DMG: Cluster = 0x1f,
[1687853946.750013][4923:4923] CHIP:DMG: Attribute = 0x0000_0000,
[1687853946.750019][4923:4923] CHIP:DMG: }
[1687853946.750023][4923:4923] CHIP:DMG:
[1687853946.750028][4923:4923] CHIP:DMG: Data = [
[1687853946.750032][4923:4923] CHIP:DMG:
[1687853946.750036][4923:4923] CHIP:DMG: ],
[1687853946.750042][4923:4923] CHIP:DMG: },
[1687853946.750050][4923:4923] CHIP:DMG:
[1687853946.750054][4923:4923] CHIP:DMG: AttributeDataIB =
[1687853946.750058][4923:4923] CHIP:DMG: {
[1687853946.750062][4923:4923] CHIP:DMG: AttributePathIB =
[1687853946.750066][4923:4923] CHIP:DMG: {
[1687853946.750071][4923:4923] CHIP:DMG: Endpoint = 0x0,
[1687853946.750075][4923:4923] CHIP:DMG: Cluster = 0x1f,
[1687853946.750080][4923:4923] CHIP:DMG: Attribute = 0x0000_0000,
[1687853946.750085][4923:4923] CHIP:DMG: ListIndex = Null,
[1687853946.750089][4923:4923] CHIP:DMG: }
[1687853946.750094][4923:4923] CHIP:DMG:
[1687853946.750098][4923:4923] CHIP:DMG: Data =
[1687853946.750103][4923:4923] CHIP:DMG: {
[1687853946.750108][4923:4923] CHIP:DMG: 0x1 = 5,
[1687853946.750112][4923:4923] CHIP:DMG: 0x2 = 2,
[1687853946.750116][4923:4923] CHIP:DMG: 0x3 = [
[1687853946.750125][4923:4923] CHIP:DMG: 112233,
[1687853946.750132][4923:4923] CHIP:DMG: ],
[1687853946.750136][4923:4923] CHIP:DMG: 0x4 = NULL
[1687853946.750140][4923:4923] CHIP:DMG: },
[1687853946.750144][4923:4923] CHIP:DMG: },
[1687853946.750152][4923:4923] CHIP:DMG:
[1687853946.750156][4923:4923] CHIP:DMG: AttributeDataIB =
[1687853946.750160][4923:4923] CHIP:DMG: {
[1687853946.750164][4923:4923] CHIP:DMG: AttributePathIB =
[1687853946.750168][4923:4923] CHIP:DMG: {
[1687853946.750173][4923:4923] CHIP:DMG: Endpoint = 0x0,
[1687853946.750177][4923:4923] CHIP:DMG: Cluster = 0x1f,
[1687853946.750181][4923:4923] CHIP:DMG: Attribute = 0x0000_0000,
[1687853946.750186][4923:4923] CHIP:DMG: ListIndex = Null,
[1687853946.750190][4923:4923] CHIP:DMG: }
[1687853946.750194][4923:4923] CHIP:DMG:
[1687853946.750198][4923:4923] CHIP:DMG: Data =
[1687853946.750202][4923:4923] CHIP:DMG: {
[1687853946.750206][4923:4923] CHIP:DMG: 0x1 = 3,
[1687853946.750211][4923:4923] CHIP:DMG: 0x2 = 2,
[1687853946.750215][4923:4923] CHIP:DMG: 0x3 = NULL
[1687853946.750220][4923:4923] CHIP:DMG: 0x4 = NULL
[1687853946.750230][4923:4923] CHIP:DMG: },
[1687853946.750233][4923:4923] CHIP:DMG: },
[1687853946.750239][4923:4923] CHIP:DMG:
[1687853946.750243][4923:4923] CHIP:DMG: ],
[1687853946.750252][4923:4923] CHIP:DMG:
[1687853946.750256][4923:4923] CHIP:DMG: moreChunkedMessages = false,
[1687853946.750260][4923:4923] CHIP:DMG: InteractionModelRevision = 1
[1687853946.750264][4923:4923] CHIP:DMG: },
[1687853946.750288][4923:4923] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_001F e=0 p=a
[1687853946.750295][4923:4923] CHIP:DMG: AccessControl: allowed
[1687853946.750342][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-oijEQm)
[1687853946.750466][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.750493][4923:4923] CHIP:EVL: LogEvent event number: 0x0000000000070002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000188FBEF577E
[1687853946.750501][4923:4923] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 3864ca7e
[1687853946.750507][4923:4923] CHIP:DMG: IM WH moving to [AddStatus]
[1687853946.750530][4923:4923] CHIP:DMG: AccessControl: validating f=2 p=a a=c s=1 t=0
[1687853946.750534][4923:4923] CHIP:DMG: validating subject 0x000000000001B669
[1687853946.750564][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-cKznwU)
[1687853946.750673][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.750694][4923:4923] CHIP:EVL: LogEvent event number: 0x0000000000070003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000188FBEF577E
[1687853946.750700][4923:4923] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 3864ca7f
[1687853946.750705][4923:4923] CHIP:DMG: IM WH moving to [AddStatus]
[1687853946.750726][4923:4923] CHIP:DMG: AccessControl: validating f=2 p=o a=c s=0 t=0
[1687853946.750754][4923:4923] CHIP:DL: writing settings to file (/tmp/chip_kvs-UCvihQ)
[1687853946.750863][4923:4923] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1687853946.750882][4923:4923] CHIP:EVL: LogEvent event number: 0x0000000000070004 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000188FBEF577E
[1687853946.750889][4923:4923] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 3864ca80
[1687853946.750894][4923:4923] CHIP:DMG: IM WH moving to [AddStatus]
[1687853946.750922][4923:4923] CHIP:EM: <<< [E:28979r S:16800 M:259055697 (Ack:84615548)] (S) Msg TX to 2:000000000001B669 [E9DB] --- Type 0001:07 (IM:WriteResponse)
[1687853946.750930][4923:4923] CHIP:IN: (S) Sending msg 259055697 on secure session with LSID: 16800
[1687853946.750961][4923:4923] CHIP:DMG: IM WH moving to [Sending]
[1687853946.750966][4923:4923] CHIP:DMG: IM WH moving to [Uninitialized]
[1687853946.750986][4923:4923] CHIP:EM: >>> [E:28978r S:0 M:193956050 (Ack:41196415)] (U) Msg RX from 0:03C288D3E286CBBB [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853946.750992][4923:4923] CHIP:EM: Found matching exchange: 28978r, Delegate: (nil)
[1687853946.750998][4923:4923] CHIP:EM: Rxd Ack; Removing MessageCounter:41196415 from Retrans Table on exchange 28978r
[1687853946.751472][4923:4923] CHIP:EM: >>> [E:28979r S:16800 M:84615549 (Ack:259055697)] (S) Msg RX from 2:000000000001B669 [E9DB] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1687853946.751481][4923:4923] CHIP:EM: Found matching exchange: 28979r, Delegate: (nil)
[1687853946.751489][4923:4923] CHIP:EM: Rxd Ack; Removing MessageCounter:259055697 from Retrans Table on exchange 28979r

4. OTA announce

(I entered the command below through another terminal.

sudo ./out/chiptool/chip-tool otasoftwareupdaterequestor announce-otaprovider 5 0 0 0 10 0)

OTA target nRF52840DK board shows the same error log as above, but no response from OTA Provider (no log output)

Additionally, in the current situation (OTA Provider with Node 5 and Matter Device with Node 10, nrf52840DK) are both

Respond to the chip tool command below.
(The OTA Provider does not operate because there is no cluster at its end point, but the corresponding error log is output.)
"sudo ./out/chiptool/chip-tool onoff toggle 5 1"
"sudo ./out/chiptool/chip-tool onoff toggle 10 1"

This makes it appear that both OTA Provider and Matter Device are connected to OTBR.
(Conversely, the Unpair command works too!)

And I found the guide below through YouTube, and it was confirmed that OTA works after configuring the environment in the same way!
(In the guide, only OTA ProviderAPP and OTA Requestor are configured on one PC without Matter Device.)

www.youtube.com/watch

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

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.

Please reply if you need additional information. 

 

[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. 

[AHaug]

Hi,

Just a heads up that I've queried the Matter team regarding the results you've posted and but I am yet to receive a result. The log from item 2 is still very helpful if you are able to get one! 

I will be out of office until next week starting today, but I'll check back in with you and the status from the developers when I return.

Kind regards,
Andreas

[AHaug]

Hi

I'm back with some more info from the Matter team:

It is hard to say what is going wrong. Everything looks quite correct regarding IP addresses and etc. The developers reproduced the test on their desk and pcap looks the same, with the one difference. For them the procedure works correctly and packets are forwarded. The next thing they suspect is that something must be wrong with the OpenThread Border Router or routing configuration, but since communication with CHIP Tool works correctly, this might not be the case

1. Could you try to invoke the following two commands before running the OTBR docker and report back the result??
sudo sysctl -w net.ipv6.conf.otbr0.accept_ra_rt_info_max_plen=128
sudo sysctl -w net.ipv6.conf.otbr0.accept_ra=2

2. If you've used a different OTBR setup than what is recommended/specified in the DFU guide & testing Matter in NCS guide, could you try with the recommended hardware and see if that makes any changes?

Kind regards,
Andreas

[bluemelony]

Thank you for your confirmation.

The results of the confirmation of your request are as follows.

1. After entering that command, I configured OTBR again and tested it, but the OTA did not proceed similarly. However, a different log has been identified.

- Log to Matter Device

I: 465451 [EM]>>> [E:34015r S:0 M:186092791] (U) Msg RX from 0:DBA51F5EF7A1A2AD [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 465463 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20004e60
I: 465471 [IN]CASE Server disabling CASE session setups
I: 465476 [EM]<<< [E:34015r S:0 M:220419010 (Ack:186092791)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 465489 [IN](U) Sending msg 220419010 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:45258'
I: 465500 [SC]Received Sigma1 msg
I: 465507 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000005
I: 465723 [EM]<<< [E:34015r S:0 M:220419011 (Ack:186092791)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 465735 [IN](U) Sending msg 220419011 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:45258'
I: 465747 [SC]Sent Sigma2 msg
I: 465868 [EM]>>> [E:34015r S:0 M:186092792 (Ack:220419011)] (U) Msg RX from 0:DBA51F5EF7A1A2AD [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 465882 [EM]<<< [E:34015r S:0 M:220419012 (Ack:186092792)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 465895 [IN](U) Sending msg 220419012 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:45258'
I: 465905 [SC]Received Sigma3 msg
E: 465914 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 466111 [DL]Long dispatch time: 187 ms, for event type 2
I: 466214 [EM]<<< [E:34015r S:0 M:220419013 (Ack:186092792)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 466227 [IN](U) Sending msg 220419013 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:45258'
I: 466239 [SC]SecureSession[0x20003838]: Moving from state 'kEstablishing' --> 'kActive'
D: 466247 [IN]SecureSession[0x20003838]: Activated - Type:2 LSID:46171
D: 466254 [IN]New secure session activated for device <000000000001B669, 1>, LSID:46171 PSID:48533!
I: 466263 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 466270 [IN]CASE Server enabling CASE session setups
D: 466277 [IN]SecureSession[0x200038f0]: Allocated Type:2 LSID:46173
E: 466284 [DL]Long dispatch time: 168 ms, for event type 2
I: 466291 [EM]>>> [E:34016r S:46171 M:85657165] (S) Msg RX from 1:000000000001B669 [E4A4] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 466303 [SWU]OTA Requestor received AnnounceOTAProvider
D: 466308 [SWU]  FabricIndex: 1
D: 466311 [SWU]  ProviderNodeID: 0x0000000000000001
D: 466316 [SWU]  VendorID: 0x0
D: 466319 [SWU]  AnnouncementReason: 0
D: 466322 [SWU]  Endpoint: 0
I: 466326 [EM]<<< [E:34016r S:46171 M:119443558 (Ack:85657165)] (S) Msg TX to 1:000000000001B669 [E4A4] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 466339 [IN](S) Sending msg 119443558 on secure session with LSID: 46171
I: 466347 [EM]>>> [E:34015r S:0 M:186092793 (Ack:220419013)] (U) Msg RX from 0:DBA51F5EF7A1A2AD [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 466362 [SWU]Stopping the Periodic Query timer
I: 466367 [SWU]Starting the watchdog timer, timeout: 21600 seconds
D: 466373 [SWU]Establishing session to provider node ID 0x0000000000000001 on fabric index 1
D: 466383 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
I: 466390 [DIS]Resolving 8FAB4E5B9E78E4A4:0000000000000001 ...
I: 466398 [EM]>>> [E:34016r S:46171 M:85657166 (Ack:119443558)] (S) Msg RX from 1:000000000001B669 [E4A4] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 466451 [DIS]Node ID resolved for 8FAB4E5B9E78E4A4:0000000000000001
D: 466457 [DIS] Hostname: E0D55EB9F3140000
D: 466461 [DIS] IP Address #1: fd11:1111:1122:2222:3079:47c7:9eda:cb9a
D: 466467 [DIS] Port: 5540
D: 466470 [DIS] Mrp Interval idle: 300 ms
D: 466474 [DIS] Mrp Interval active: 2000 ms
D: 466478 [DIS] TCP Supported: 1
D: 466481 [DIS]Lookup clearing interface for non LL address
I: 466486 [DIS]UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540: new best score: 4
I: 466493 [DIS]Checking node lookup status after 103 ms
I: 466498 [DIS]Keeping DNSSD lookup active
I: 466591 [DIS]Checking node lookup status after 200 ms
D: 466596 [DIS]OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540 while in state 2
D: 466609 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
D: 466617 [IN]SecureSession[0x200039a8]: Allocated Type:2 LSID:46174
I: 466623 [SC]Initiating session on local FabricIndex 1 from 0x0000000000000005 -> 0x0000000000000001
I: 466780 [EM]<<< [E:4672i S:0 M:220419014] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 466792 [IN](U) Sending msg 220419014 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540'
I: 466802 [SC]Sent Sigma1 msg
D: 466805 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
I: 467642 [IN](U) Sending msg 220419014 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540'
I: 468516 [IN](U) Sending msg 220419014 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540'
I: 469603 [IN](U) Sending msg 220419014 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540'
I: 470977 [IN](U) Sending msg 220419014 to IP address 'UDP:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540'
E: 472953 [EM]Failed to Send CHIP MessageCounter:220419014 on exchange 4672i sendCount: 4 max retries: 4
E: 475504 [SC]CASESession timed out while waiting for a response from the peer. Current state was 1
D: 475513 [IN]SecureSession[0x200039a8]: Released - Type:2 LSID:46174
D: 475520 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2
D: 475527 [DIS]OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1
E: 475534 [SWU]Failed to connect to node 0x0000000000000001: 32
I: 475541 [SWU]Unknown idle state reason so set the periodic timer for a next attempt
I: 475549 [SWU]Stopping the watchdog timer
I: 475553 [SWU]Starting the periodic query timer, timeout: 86400 seconds

- Log to OTBR

Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.213 [I] MeshForwarder-: Sent IPv6 UDP msg, len:214, chksum:4ee2, ecn:no, to:0x6400, sec:yes, prio:low
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.213 [I] MeshForwarder-:     src:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.213 [I] MeshForwarder-:     dst:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.270 [I] MeshForwarder-: Received IPv6 UDP msg, len:74, chksum:b837, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-43.0
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.270 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.270 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.567 [I] MeshForwarder-: Received IPv6 UDP msg, len:780, chksum:763c, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-40.0
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.567 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.567 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.626 [I] MeshForwarder-: Sent IPv6 UDP msg, len:646, chksum:e796, ecn:no, to:0x6400, sec:yes, prio:low
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.626 [I] MeshForwarder-:     src:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.627 [I] MeshForwarder-:     dst:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.673 [I] MeshForwarder-: Received IPv6 UDP msg, len:74, chksum:b537, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.0
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.673 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:54 f6de2ba70eca otbr-agent[191]: 00:52:08.673 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.008 [I] MeshForwarder-: Received IPv6 UDP msg, len:82, chksum:aff7, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.008 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.008 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.025 [I] MeshForwarder-: Sent IPv6 UDP msg, len:119, chksum:a387, ecn:no, to:0x6400, sec:yes, prio:low
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.025 [I] MeshForwarder-:     src:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.025 [I] MeshForwarder-:     dst:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.031 [I] MeshForwarder-: Sent IPv6 UDP msg, len:74, chksum:af37, ecn:no, to:0x6400, sec:yes, prio:low
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.031 [I] MeshForwarder-:     src:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.031 [I] MeshForwarder-:     dst:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.124 [I] MeshForwarder-: Received IPv6 UDP msg, len:115, chksum:9ac8, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-40.0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.124 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.124 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.133 [I] MeshForwarder-: Sent IPv6 UDP msg, len:82, chksum:ab89, ecn:no, to:0x6400, sec:yes, prio:low
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.133 [I] MeshForwarder-:     src:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:46501
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.133 [I] MeshForwarder-:     dst:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.180 [I] MeshForwarder-: Received IPv6 UDP msg, len:206, chksum:88a0, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-40.5
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.180 [I] MeshForwarder-:     src:[fd4b:93b9:8e2f:21a9:e105:3c31:c9a6:c5fb]:49153
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.180 [I] MeshForwarder-:     dst:[fd4b:93b9:8e2f:21a9:2cd6:7f27:11c9:efdf]:53
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.180 [I] DnssdServer---: ANSWER: TRANSACTION=0x5f24, QUESTION=[8FAB4E5B9E78E4A4-0000000000000001._matter._tcp.default.service.arpa. 1 33], RCODE=3
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.180 [I] DnssdServer---: ANSWER: TRANSACTION=0x5f24, QUESTION=[8FAB4E5B9E78E4A4-0000000000000001._matter._tcp.default.service.arpa. 1 16], RCODE=3
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-DPROXY--: Subscribe: 8FAB4E5B9E78E4A4-0000000000000001._matter._tcp.default.service.arpa.
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: Subscribe service 8FAB4E5B9E78E4A4-0000000000000001._matter._tcp (total 1)
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: DNSServiceResolve 8FAB4E5B9E78E4A4-0000000000000001 _matter._tcp inf 0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: DNSServiceResolve reply: 8FAB4E5B9E78E4A4-0000000000000001._matter._tcp.local. host E0D55EB9F3140000.local.:42005, TXT=21B inf 6, flags=0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: DNSServiceGetAddrInfo E0D55EB9F3140000.local. inf 6
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: DNSServiceGetAddrInfo reply: flags=1073741827, host=E0D55EB9F3140000.local., sa_family=10, error=0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: DNSServiceGetAddrInfo reply: address=fd11:1111:1122:2222:3079:47c7:9eda:cb9a, ttl=120
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: Service _matter._tcp is resolved successfully: add 8FAB4E5B9E78E4A4-0000000000000001 host E0D55EB9F3140000.local. addresses 1
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-DPROXY--: Service discovered: _matter._tcp, instance 8FAB4E5B9E78E4A4-0000000000000001 hostname E0D55EB9F3140000.local. addresses 1 port 5540 priority 0 weight 0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [DEBG]-DPROXY--: Translate domain: E0D55EB9F3140000.local. => E0D55EB9F3140000.default.service.arpa.
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-DPROXY--: Unsubscribe: 8FAB4E5B9E78E4A4-0000000000000001._matter._tcp.default.service.arpa.
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: [INFO]-MDNS----: Unsubscribe service 8FAB4E5B9E78E4A4-0000000000000001._matter._tcp (left 0)
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.181 [I] DnssdServer---: send DNS-SD reply: OK, RCODE=0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.205 [I] MeshForwarder-: Sent IPv6 UDP msg, len:257, chksum:4f65, ecn:no, to:0x6400, sec:yes, prio:normal
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.205 [I] MeshForwarder-:     src:[fd4b:93b9:8e2f:21a9:2cd6:7f27:11c9:efdf]:53
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.205 [I] MeshForwarder-:     dst:[fd4b:93b9:8e2f:21a9:e105:3c31:c9a6:c5fb]:49153
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.583 [I] MeshForwarder-: Received IPv6 UDP msg, len:225, chksum:8bd1, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-40.0
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.583 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:55 f6de2ba70eca otbr-agent[191]: 00:52:09.583 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540
Jul  5 01:21:56 f6de2ba70eca otbr-agent[191]: 00:52:10.473 [I] MeshForwarder-: Received IPv6 UDP msg, len:225, chksum:8bd1, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.25
Jul  5 01:21:56 f6de2ba70eca otbr-agent[191]: 00:52:10.473 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:56 f6de2ba70eca otbr-agent[191]: 00:52:10.473 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540
Jul  5 01:21:57 f6de2ba70eca otbr-agent[191]: 00:52:11.339 [I] MeshForwarder-: Received IPv6 UDP msg, len:225, chksum:8bd1, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.0
Jul  5 01:21:57 f6de2ba70eca otbr-agent[191]: 00:52:11.340 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:57 f6de2ba70eca otbr-agent[191]: 00:52:11.340 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540
Jul  5 01:21:58 f6de2ba70eca otbr-agent[191]: 00:52:12.464 [I] MeshForwarder-: Received IPv6 UDP msg, len:225, chksum:8bd1, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.0
Jul  5 01:21:58 f6de2ba70eca otbr-agent[191]: 00:52:12.464 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:21:58 f6de2ba70eca otbr-agent[191]: 00:52:12.464 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540
Jul  5 01:22:00 f6de2ba70eca otbr-agent[191]: 00:52:13.958 [I] MeshForwarder-: Received IPv6 UDP msg, len:225, chksum:8bd1, ecn:no, from:0x6400, sec:yes, prio:normal, rss:-41.0
Jul  5 01:22:00 f6de2ba70eca otbr-agent[191]: 00:52:13.958 [I] MeshForwarder-:     src:[fd11:22:0:0:33c1:f158:876a:7d0a]:5540
Jul  5 01:22:00 f6de2ba70eca otbr-agent[191]: 00:52:13.958 [I] MeshForwarder-:     dst:[fd11:1111:1122:2222:3079:47c7:9eda:cb9a]:5540
Jul  5 01:22:09 f6de2ba70eca otbr-agent[191]: 00:52:22.967 [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
Jul  5 01:22:09 f6de2ba70eca otbr-agent[191]: 00:52:22.971 [I] MeshForwarder-: Sent IPv6 UDP msg, len:91, chksum:872d, ecn:no, to:0xffff, sec:no, prio:net
Jul  5 01:22:09 f6de2ba70eca otbr-agent[191]: 00:52:22.971 [I] MeshForwarder-:     src:[fe80:0:0:0:c11:c613:ac00:ab74]:19788
Jul  5 01:22:09 f6de2ba70eca otbr-agent[191]: 00:52:22.971 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
Jul  5 01:22:13 f6de2ba70eca otbr-agent[191]: 00:52:27.630 [I] MeshForwarder-: Received IPv6 UDP msg, len:91, chksum:5158, ecn:no, from:46f1453276713147, sec:no, prio:net, rss:-40.0
Jul  5 01:22:13 f6de2ba70eca otbr-agent[191]: 00:52:27.630 [I] MeshForwarder-:     src:[fe80:0:0:0:44f1:4532:7671:3147]:19788
Jul  5 01:22:13 f6de2ba70eca otbr-agent[191]: 00:52:27.630 [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
Jul  5 01:22:13 f6de2ba70eca otbr-agent[191]: 00:52:27.630 [I] Mle-----------: Receive Advertisement (fe80:0:0:0:44f1:4532:7671:3147,0x6400)

- Wire Shark capture

Cp3.pcapng

Unlike before, OTBR also showed a response during the announce-otaprovider.

2. Yes, I configured it the same as the site guide. But could you check if the environment we organized is correct? The configuration is as follows.
(Please let me know if you need additional confirmation of our configuration environment)

- OTBR Form Therd Networks

Lastly, can I get the OTA file (Build Target: nrf52840DK) that the Matter team used?
I'd like to replace the OTA file we used for the test.

Thank you..