Connection failure error during DFU over Matter guide

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.

Top Replies

Parents

0 Marte Myrvold over 2 years ago

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
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 bluemelony over 2 years ago in reply to Marte Myrvold

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)
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 AHaug over 2 years ago in reply to bluemelony

Hi,

I'm handling this case for Marte while she is on out of office for the next weeks.

I've queried the Matter team for some input regarding the issue you're observing and I will return back to you with a reply as soon as I hear back from them

Kind regards,
Andreas
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

Reply

0 AHaug over 2 years ago in reply to bluemelony

Hi,

I'm handling this case for Marte while she is on out of office for the next weeks.

I've queried the Matter team for some input regarding the issue you're observing and I will return back to you with a reply as soon as I hear back from them

Kind regards,
Andreas
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

Children

+1 AHaug over 2 years ago in reply to 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
Cancel
Vote Up +1 Vote Down

Sign in to reply

Reject Answer

Cancel

0 bluemelony over 2 years ago in reply to AHaug

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.

0 AHaug over 2 years ago in reply to bluemelony

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
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 bluemelony over 2 years ago in reply to 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.

...

...
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 bluemelony over 2 years ago in reply to 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.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel