Python CHIP-TOOL : "CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 604. Look at AttestationVerificationResult enum to understand the errors"

[Carla31]

Hello, I'm testing the Matter example : Template (https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/samples/matter/template/README.html) with nRF SDK v1.9.99. This example project runs on nRF5340 DK board. 

I'm trying to commission the device (Matter template) into a Thread Network created by the Open Thread Border Router running on RaspberryPI. For commissioning, I'm using the CHIP tool who plays the role of Matter controller (http://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/matter/chip_tool_guide.html#).  The CHIP tools runs on a Linux PC (Ubuntu 20.04.4 LTS).

I'm getting an error when running command for commissioning my device into Thread network over Bluetooth LE using the command.

$ sudo ./chip-tool pairing ble-thread <node_id> hex:<operational_dataset> <pin_code> <discriminator>

The error is related to Attestation Information command verification. Here below you can find my output when running the command mentioned before:

[1651655595.445469][3268141:3268146] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1651655595.445508][3268141:3268146] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1651655595.445522][3268141:3268146] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1651655595.445537][3268141:3268146] CHIP:CTL: Verifying attestation
[1651655595.449855][3268141:3268146] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 604. Look at AttestationVerificationResult enum to understand the errors
[1651655595.449898][3268141:3268146] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:945: CHIP Error 0x000000AC: Internal error'
[1651655595.449913][3268141:3268146] CHIP:CTL: Failed to perform commissioning step 8
[1651655595.449928][3268141:3268146] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:945: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1651655595.449954][3268141:3268146] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:945: CHIP Error 0x000000AC: Internal error'
[1651655595.449971][3268141:3268146] CHIP:CTL: Expiring failsafe on proxy 0x7f8178000b60
[1651655595.450018][3268141:3268146] CHIP:DMG: ICR moving to [AddingComm]
[1651655595.450038][3268141:3268146] CHIP:DMG: ICR moving to [AddedComma]
[1651655595.450093][3268141:3268146] CHIP:IN: Prepared secure message 0x7f818d3cc840 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 44183i with MessageCounter:2773086.
[1651655595.450133][3268141:3268146] CHIP:IN: Sending encrypted msg 0x7f818d3cc840 with MessageCounter:2773086 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000019F746FE msec
[1651655595.450203][3268141:3268146] CHIP:DMG: ICR moving to [CommandSen]
[1651655595.450254][3268141:3268146] CHIP:DMG: ICR moving to [AwaitingDe]
[1651655595.577666][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1651655595.757789][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1651655595.847536][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1651655595.849437][3268141:3268144] CHIP:DL: Indication received, conn = 0x7f8184118020
[1651655595.849633][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1651655595.936877][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1651655596.027568][3268141:3268144] CHIP:DL: Indication received, conn = 0x7f8184118020
[1651655596.027692][3268141:3268146] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1651655596.210120][3268141:3268144] CHIP:DL: Bluez disconnected
[1651655596.210153][3268141:3268144] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1651655596.210240][3268141:3268146] CHIP:IN: Clearing BLE pending packets.
[1651655607.453609][3268141:3268146] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 44183i
[1651655607.453676][3268141:3268146] CHIP:CTL: Received failure response  when disarming failsafe../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:211: CHIP Error 0x00000032: Timeout

[1651655607.453707][3268141:3268146] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1651655607.453739][3268141:3268146] CHIP:TOO: Device commissioning Failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:945: CHIP Error 0x000000AC: Internal error
[1651655607.453785][3268141:3268146] CHIP:DIS: Closing all BLE connections
[1651655607.453854][3268141:3268146] CHIP:DMG: ICR moving to [AwaitingDe]
[1651655607.454132][3268141:3268141] CHIP:CTL: Shutting down the commissioner
[1651655607.454229][3268141:3268141] CHIP:CTL: Shutting down the controller
[1651655607.454254][3268141:3268141] CHIP:CTL: Shutting down the commissioner
[1651655607.454298][3268141:3268141] CHIP:CTL: Shutting down the controller
[1651655607.454315][3268141:3268141] CHIP:IN: Expiring all connections for fabric 1!!
[1651655607.454350][3268141:3268141] CHIP:CTL: Shutting down the commissioner
[1651655607.454389][3268141:3268141] CHIP:CTL: Shutting down the controller
[1651655607.454404][3268141:3268141] CHIP:IN: Expiring all connections for fabric 2!!
[1651655607.454428][3268141:3268141] CHIP:CTL: Shutting down the commissioner
[1651655607.454466][3268141:3268141] CHIP:CTL: Shutting down the controller
[1651655607.454480][3268141:3268141] CHIP:IN: Expiring all connections for fabric 3!!
[1651655607.454501][3268141:3268141] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1651655607.454650][3268141:3268141] CHIP:DMG: IM WH moving to [Uninitialized]
[1651655607.454667][3268141:3268141] CHIP:DMG: IM WH moving to [Uninitialized]
[1651655607.454679][3268141:3268141] CHIP:DMG: IM WH moving to [Uninitialized]
[1651655607.454690][3268141:3268141] CHIP:DMG: IM WH moving to [Uninitialized]
[1651655607.454702][3268141:3268141] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1651655607.454742][3268141:3268141] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1651655607.454944][3268141:3268141] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rit9kH)
[1651655607.455335][3268141:3268141] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1651655607.455379][3268141:3268141] CHIP:DL: NVS set: chip-counters/total-operational-hours = 17 (0x11)
[1651655607.455395][3268141:3268141] CHIP:DL: Inet Layer shutdown
[1651655607.455407][3268141:3268141] CHIP:DL: BLE shutdown
[1651655607.466156][3268141:3268141] CHIP:DL: System Layer shutdown
[1651655607.466269][3268141:3268141] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:945: CHIP Error 0x000000AC: Internal error

In the file ble_commissioning_matter_template.txt, you can find the logging of my Matter device (Matter template example).

Fullscreen ble_commissioning_matter_template.txt Download

I: Init CHIP stack
I: Swap type: none
D: 1233 [DL]Boot reason: 6
I: 1303 [DL]BLE address: DD:CB:23:39:D9:41
I: 1331 [DL]OpenThread started: OK
I: 1338 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: Swap type: none
I: 1356 [ZCL]Using ZAP configuration...
I: 1365 [ZCL]Initiating Admin Commissioning cluster.
I: 1375 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 1392 [DIS]Add fabric pairing table delegate
D: 1401 [DIS]Init fabric pairing table with server storage
I: 1412 [IN]Loading from storage for fabric index 1
I: 1422 [IN]Loading from storage for fabric index 2
I: 1432 [IN]Loading from storage for fabric index 3
I: 1442 [IN]Loading from storage for fabric index 4
I: 1452 [IN]Loading from storage for fabric index 5
I: 1462 [DMG]AccessControl: initializing
I: 1470 [DMG]Examples::AccessControlDelegate::Init
I: 1480 [DMG]AccessControl: unable to load stored ACL entries; using empty list instead
I: 1497 [DMG]AccessControl: setting
D: 1504 [IN]UDP::Init bind&listen port=5540
E: 1512 [IN]SO_REUSEPORT failed: 109
D: 1519 [IN]UDP::Init bound to port=5540
D: 1527 [IN]BLEBase::Init - setting/overriding transport
D: 1538 [IN]TransportMgr initialized
D: 1549 [DIS]Add fabric pairing table delegate
D: 1558 [DL]Using Thread extended MAC for hostname.
I: 1569 [IN]Loading from storage for fabric index 1
I: 1581 [IN]Loading from storage for fabric index 2
I: 1593 [IN]Loading from storage for fabric index 3
I: 1604 [IN]Loading from storage for fabric index 4
I: 1616 [IN]Loading from storage for fabric index 5
D: 1630 [SC]Assigned local session key ID 1
D: 1639 [SC]Waiting for PBKDF param request
D: 1647 [DL]CHIPoBLE advertising set to on
I: 1656 [DIS]Updating services using commissioning mode 1
D: 1667 [DL]Using Thread extended MAC for hostname.
D: 1677 [DL]Using Thread extended MAC for hostname.
I: 1688 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
E: 1706 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 1720 [DIS]Scheduling discovery timeout in 900s
E: 1729 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 1742 [DIS]Updating services using commissioning mode 1
D: 1753 [DL]Using Thread extended MAC for hostname.
D: 1764 [DL]Using Thread extended MAC for hostname.
I: 1774 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
E: 1793 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 1806 [DIS]Scheduling discovery timeout in 900s
E: 1816 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 1829 [IN]CASE Server enabling CASE session setups
I: 1839 [DIS]Delaying proxy of operational discovery: missing delegate
I: 1853 [SVR]Joining Multicast groups
D: 1860 [ZCL]Emitting StartUp event
D: 1867 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000000074B
D: 1897 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
D: 1908 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to bfb24910
D: 1922 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000782
I: 1952 [SVR]Server Listening...
I: 1958 [DL]Device Configuration:
I: 1965 [DL]  Serial Number: TEST_SN
I: 1972 [DL]  Vendor Id: 65521 (0xFFF1)
I: 1980 [DL]  Product Id: 32768 (0x8000)
I: 1988 [DL]  Hardware Version: 0
I: 1995 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 2007 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 2022 [DL]  Manufacturing Date: (not set)
I: 2030 [DL]  Device Type: 65535 (0xFFFF)
I: 2040 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 2049 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 2063 [SVR]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 2081 [SVR]Manual pairing code: [34970112332]
I: 2091 [DL]CHIP task running
I: 2102 [DL]CHIPoBLE advertising started
D: 2112 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bc1cc0cc
D: 2125 [DMG]Endpoint 0, Cluster 0x0000_002A update version to bc1cc0cd
D: 2139 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_002A event id: 0x0 Sys timestamp: 0x000000000000085B
I: 2169 [SWU]Starting the Default Provider timer, timeout: 86400 seconds
I: 14942 [DL]BLE connection established (ConnId: 0x00)
I: 14953 [DL]Current number of connections: 1/1
I: 14962 [DL]CHIPoBLE advertising stopped
D: 16758 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 16770 [BLE]local and remote recv window sizes = 5
I: 16780 [BLE]selected BTP version 4
I: 16788 [BLE]using BTP fragment sizes rx 20 / tx 20.
D: 16856 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 16865 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 16878 [IN]BLE EndPoint 0x20009a28 Connection Complete
I: 16889 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 23)
D: 16953 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 16965 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 17051 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 17148 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 17246 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 17258 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 17343 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17355 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 17367 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:699162204 on exchange 62855r
D: 17388 [EM]Handling via exchange: 62855r, Delegate: 0x20006478
D: 17400 [SC]Received PBKDF param request
D: 17408 [SC]Peer assigned session ID 30865
D: 17417 [SC]Found MRP parameters in the message
D: 17427 [SC]Including MRP parameters in PBKDF param response
I: 17439 [IN]Prepared unauthenticated message 0x2002da30 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 62855r with MessageCounter:4212018463.
I: 17470 [IN]Sending unauthenticated msg 0x2002da30 with MessageCounter:4212018463 to 0x0000000000000000 at monotonic time: 000000000000443E msec
D: 17497 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 17511 [SC]Sent PBKDF param response
E: 17518 [DL]Long dispatch time: 164 ms, for event type 16388
D: 17586 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17598 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 17684 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17695 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 17782 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17793 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 17806 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 17879 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17890 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 17976 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17988 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 18074 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18085 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 18172 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18184 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18196 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 14)
D: 18269 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18281 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18367 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18464 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18477 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 18562 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18574 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18659 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 18757 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 18769 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:699162205 on exchange 62855r
D: 18790 [EM]Found matching exchange: 62855r, Delegate: 0x20006478
D: 18803 [SC]Received spake2p msg1
I: 20425 [IN]Prepared unauthenticated message 0x2002d9c0 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 62855r with MessageCounter:4212018464.
I: 20457 [IN]Sending unauthenticated msg 0x2002d9c0 with MessageCounter:4212018464 to 0x0000000000000000 at monotonic time: 0000000000004FE9 msec
D: 20484 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 20497 [SC]Sent spake2p msg2
E: 20503 [DL]Long dispatch time: 1746 ms, for event type 16388
D: 20579 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20590 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 20669 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20680 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 20759 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20770 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 20849 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20861 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 20873 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 20939 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20950 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 21029 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21040 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 21119 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21130 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 7)
D: 21209 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21221 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 21299 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 21390 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 21480 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 21492 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 21569 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21581 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 21593 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:699162206 on exchange 62855r
D: 21614 [EM]Found matching exchange: 62855r, Delegate: 0x20006478
D: 21627 [SC]Received spake2p msg3
D: 21634 [SC]Sending status report. Protocol code 0, exchange 62855
I: 21647 [IN]Prepared unauthenticated message 0x2002da48 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 62855r with MessageCounter:4212018465.
I: 21678 [IN]Sending unauthenticated msg 0x2002da48 with MessageCounter:4212018465 to 0x0000000000000000 at monotonic time: 00000000000054AE msec
D: 21705 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 21718 [IN]New secure session created for device 0xFFFFFFFB00000000, LSID:1 PSID:30865!
I: 21736 [SVR]Commissioning completed session establishment step
I: 21749 [DIS]Updating services using commissioning mode 0
D: 21760 [DL]Using Thread extended MAC for hostname.
D: 21771 [DL]Using Thread extended MAC for hostname.
I: 21781 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
E: 21800 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
D: 21817 [DIS]Scheduling extended discovery timeout in 900s
E: 21828 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 21841 [DL]CHIPoBLE advertising set to off
I: 21849 [SVR]Device completed Rendezvous process
E: 21859 [DL]Long dispatch time: 278 ms, for event type 16388
D: 21870 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21882 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 21975 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 21986 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22065 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22154 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22245 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22257 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 22335 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 22346 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22425 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22515 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22604 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 22617 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
I: 22631 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:5687792 on exchange 62856r
D: 22652 [EM]Handling via exchange: 62856r, Delegate: 0x20008ec0
D: 22664 [IM]Received Read request
D: 22672 [DMG]IM RH moving to [AwaitingDestruction]
I: 22683 [IN]Prepared secure message 0x2002dae8 to 0xFFFFFFFB00000000 (0)  of type 0x1 and protocolId (0, 1) on exchange 62856r with MessageCounter:15114281.
I: 22712 [IN]Sending encrypted msg 0x2002dae8 with MessageCounter:15114281 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000058B8 msec
E: 22738 [DL]Long dispatch time: 134 ms, for event type 16388
D: 22750 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 22761 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 22829 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 22840 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 22919 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 22930 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 23009 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23021 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 23100 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 23190 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 23324 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 23337 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 23415 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23426 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 23439 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687793 on exchange 62857r
D: 23460 [EM]Handling via exchange: 62857r, Delegate: 0x20008ec0
I: 23472 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=o
I: 23490 [DMG]AccessControl: implicit admin (PASE)
D: 23499 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
D: 23516 [DMG]ICR moving to [AddingComm]
D: 23524 [DMG]ICR moving to [AddedComma]
D: 23531 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 23546 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62857r with MessageCounter:15114282.
I: 23575 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114282 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000005C17 msec
D: 23601 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 23614 [DMG]ICR moving to [CommandSen]
D: 23622 [DMG]ICR moving to [AwaitingDe]
E: 23630 [DL]Long dispatch time: 203 ms, for event type 16388
D: 23684 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23695 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 23774 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23785 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 23864 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23876 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 23889 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 23955 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 23966 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 24045 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 24135 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 24147 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 24270 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 24281 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 24359 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 24373 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687794 on exchange 62858r
D: 24393 [EM]Handling via exchange: 62858r, Delegate: 0x20008ec0
I: 24406 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=o
I: 24423 [DMG]AccessControl: implicit admin (PASE)
D: 24433 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 24454 [DMG]ICR moving to [AddingComm]
D: 24461 [DMG]ICR moving to [AddedComma]
D: 24469 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 24484 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62858r with MessageCounter:15114283.
I: 24512 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114283 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000005FC0 msec
D: 24539 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 24552 [DMG]ICR moving to [CommandSen]
D: 24560 [DMG]ICR moving to [AwaitingDe]
E: 24567 [DL]Long dispatch time: 208 ms, for event type 16388
D: 24629 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 24640 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 24719 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 24730 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 24809 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 24820 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 24899 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 24911 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 24990 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 25080 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 25170 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 25182 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 25260 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25271 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 25284 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687795 on exchange 62859r
D: 25304 [EM]Handling via exchange: 62859r, Delegate: 0x20008ec0
I: 25317 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I: 25334 [DMG]AccessControl: implicit admin (PASE)
D: 25344 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 25360 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 25372 [DMG]ICR moving to [AddingComm]
D: 25380 [DMG]ICR moving to [AddedComma]
D: 25388 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 25405 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62859r with MessageCounter:15114284.
I: 25434 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114284 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000006359 msec
D: 25460 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25473 [DMG]ICR moving to [CommandSen]
D: 25481 [DMG]ICR moving to [AwaitingDe]
E: 25489 [DL]Long dispatch time: 218 ms, for event type 16388
D: 25529 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25540 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25619 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25630 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25709 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25721 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 25733 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25799 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25811 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25889 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25900 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 25979 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 25991 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26069 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26081 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 26094 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26159 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26170 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26249 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26260 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26339 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26350 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26429 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26441 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 26453 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26519 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26531 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26609 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26620 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26699 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26710 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26789 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26801 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 26814 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26879 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26890 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 26969 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 26980 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27059 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27070 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27149 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27194 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 27207 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27284 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27295 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27374 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27385 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27464 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27476 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27554 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27566 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 27578 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27644 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27655 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27734 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27745 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27824 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27835 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 27914 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 27926 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 27938 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 28004 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28016 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 28094 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28105 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 28185 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28196 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 28275 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 28365 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 28455 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 28467 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
I: 28481 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687796 on exchange 62860r
D: 28501 [EM]Handling via exchange: 62860r, Delegate: 0x20008ec0
I: 28514 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I: 28531 [DMG]AccessControl: implicit admin (PASE)
D: 28540 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 28557 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 28569 [DMG]ICR moving to [AddingComm]
D: 28577 [DMG]ICR moving to [AddedComma]
D: 28585 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 28602 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62860r with MessageCounter:15114285.
I: 28631 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114285 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000006FD7 msec
D: 28657 [DMG]ICR moving to [CommandSen]
D: 28665 [DMG]ICR moving to [AwaitingDe]
E: 28673 [DL]Long dispatch time: 219 ms, for event type 16388
D: 28684 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28696 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 28769 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28780 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 28859 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28870 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 28950 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 28961 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 28973 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29039 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29050 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29129 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29141 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29219 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29230 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29309 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29321 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 29334 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29399 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29410 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29489 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29501 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29579 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29591 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29670 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29681 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 29694 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29759 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29770 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29850 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29861 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 29939 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 29950 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30029 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30041 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 30054 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30119 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30131 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30254 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30266 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30344 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30356 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30435 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30446 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 30459 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30524 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30535 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30614 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30625 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30704 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30715 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30795 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30806 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 30818 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30884 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30896 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 30974 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 30986 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31064 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31076 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31155 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31166 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31178 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31244 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31255 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31334 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31346 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31424 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31435 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 31515 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31526 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31538 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 10)
D: 31605 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31616 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31695 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31785 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31797 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 31875 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 31886 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 31965 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 32055 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 32068 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687797 on exchange 62861r
D: 32089 [EM]Handling via exchange: 62861r, Delegate: 0x20008ec0
I: 32101 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=o
I: 32118 [DMG]AccessControl: implicit admin (PASE)
D: 32128 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 32144 [ZCL]OpCreds: received an AttestationRequest
D: 32184 [DMG]ICR moving to [AddingComm]
D: 32192 [DMG]ICR moving to [AddedComma]
D: 32200 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 32217 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62861r with MessageCounter:15114286.
I: 32247 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114286 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000007DF6 msec
D: 32273 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32286 [DMG]ICR moving to [CommandSen]
D: 32294 [DMG]ICR moving to [AwaitingDe]
E: 32301 [DL]Long dispatch time: 247 ms, for event type 16388
D: 32369 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32381 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32459 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32471 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32549 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32561 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32640 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32651 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 32663 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32729 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32741 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32819 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32831 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 32909 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 32920 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33000 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33011 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 33024 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33134 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33145 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33224 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33236 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33314 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33325 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33405 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33416 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 33428 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33494 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33506 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33584 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33596 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33674 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33686 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33765 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33776 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 33789 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33854 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33866 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 33944 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 33956 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34034 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34045 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34125 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34136 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 34148 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34214 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34226 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34304 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34316 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34394 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34405 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34485 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34496 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 34508 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34574 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34586 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34664 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34676 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34754 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34765 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34845 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34856 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 34868 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 34934 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 34946 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35024 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35036 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35114 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35125 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35205 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35216 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 35228 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35294 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35305 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35384 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35395 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35474 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35485 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35565 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35576 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 35588 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35654 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35665 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35744 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35755 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35834 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35845 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 35925 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 35936 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 35949 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 10)
D: 36015 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 36026 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 36150 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 36240 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 36252 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 36330 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 36341 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 36354 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5687798 on exchange 62862r
D: 36375 [EM]Handling via exchange: 62862r, Delegate: 0x20008ec0
I: 36388 [DMG]AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=o
I: 36405 [DMG]AccessControl: implicit admin (PASE)
D: 36415 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
D: 36431 [DMG]ICR moving to [AddingComm]
D: 36439 [DMG]ICR moving to [AddedComma]
D: 36447 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 36461 [IN]Prepared secure message 0x2002dad8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 62862r with MessageCounter:15114287.
I: 36490 [IN]Sending encrypted msg 0x2002dad8 with MessageCounter:15114287 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000008E8A msec
D: 36516 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 36530 [DMG]ICR moving to [CommandSen]
D: 36537 [DMG]ICR moving to [AwaitingDe]
E: 36545 [DL]Long dispatch time: 204 ms, for event type 16388
E: 36557 [SVR]Failsafe timer expired
E: 36564 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032
D: 36576 [IN]Clearing BLE pending packets.
I: 36585 [BLE]Releasing end point's BLE connection back to application.
I: 36598 [DL]Closing BLE GATT connection (ConnId 00)
D: 36613 [SC]Assigned local session key ID 2
D: 36621 [SC]Waiting for PBKDF param request
D: 36630 [DL]CHIPoBLE advertising set to on
I: 36638 [DIS]Updating services using commissioning mode 1
D: 36649 [DL]Using Thread extended MAC for hostname.
D: 36660 [DL]Using Thread extended MAC for hostname.
I: 36671 [DIS]Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
E: 36689 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 36690 [DIS]Scheduling discovery timeout in 900s
E: 36690 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 36691 [ZCL]OpCreds: Call to FailSafeCleanup
D: 36691 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 36692 [DL]Long dispatch time: 135 ms, for event type 32785
D: 36692 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
E: 36692 [BLE]no endpoint for BLE sent data ack
I: 36694 [DL]BLE GAP connection terminated (reason 0x16)
I: 36703 [DL]Current number of connections: 0/1
I: 36717 [DL]CHIPoBLE advertising started
I: 66724 [DL]CHIPoBLE advertising mode changed to slow
</pre>

In the Open Thread Border Router Web Interface, I can see only the router that is present on the Open Thread Network. It means that my Matter device failed to be commissioned to the network. Could you help me please to solve the Verification Attestation Information error ?

[Sigurd Hellesvik]

Hi

If you have a look at where the error is returned from: https://github.com/nrfconnect/sdk-connectedhomeip/blob/ec9e7f67a4fadce78be76b0a29f3407b5c424586/src/controller/CHIPDeviceController.cpp#L1150 :

"Go look at AttestationVerificationResult enum in src/credentials/DeviceAttestationVerifier.h to understand the errors."

Now from https://github.com/nrfconnect/sdk-connectedhomeip/src/credentials/DeviceAttestationVerifier.h#L69:

" kCertificationDeclarationInvalidVendorId = 604,"

$ sudo ./chip-tool pairing ble-thread <node_id> hex:<operational_dataset> <pin_code> <discriminator>

What were the exact command you used here?

Regards,
Sigurd Hellesvik

[Carla31]

I used the following command:

sudo ./chip-tool pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd278ad1d0c01517051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0fff8 20202021 3840 

Here, in the attached .txt file you can find my output after running this command. The error is at line 765.

ble_commissioning_chip_tool.txt

[Sigurd Hellesvik]

Hi

I have not been able to find the cause for your issue yet, but will continue looking into this on Monday.

Regards,
Sigurd Hellesvik

[Carla31]

Hello, I decided to use the pre-built tool for Matter controller (pre release v1.9.99-dev) that I found on the nrfconnect repo on Github for my PC Linux (chip-tool-linux_x64.zip). With this tool, BLE connection is made with success as well as commissioning over BLE. However, I can't send Matter commands to my device. The Matter controller stops at the step : 'Sending unauthenticated msg 0x556b5a798468 with MessageCounter:3734599860 to 0x0000000000000000 at monotonic time: 000000000FCBC2CB msec' You can find my output on the attached file Pre_built_chip_tool_pc: 

Fullscreen Pre_built_chip_tool_pc.txt Download

$ sudo ./chip-tool-release pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fdb1035eae19b4b4051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840
[1652085372.891668][465400:465400] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-TJw2lB)
[1652085372.891793][465400:465400] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1652085372.891803][465400:465400] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1652085372.891975][465400:465400] CHIP:DL: Got Ethernet interface: enp0s31f6
[1652085372.892096][465400:465400] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1652085372.892219][465400:465400] CHIP:DL: Got WiFi interface: wlp1s0
[1652085372.893787][465400:465400] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1652085372.893847][465400:465400] CHIP:IN: Loading from storage for fabric index 1
[1652085372.894721][465400:465400] CHIP:IN: Loading from storage for fabric index 2
[1652085372.894889][465400:465400] CHIP:IN: Loading from storage for fabric index 3
[1652085372.895047][465400:465400] CHIP:IN: Loading from storage for fabric index 4
[1652085372.895065][465400:465400] CHIP:IN: Loading from storage for fabric index 5
[1652085372.895079][465400:465400] CHIP:IN: Loading from storage for fabric index 6
[1652085372.895092][465400:465400] CHIP:IN: Loading from storage for fabric index 7
[1652085372.895106][465400:465400] CHIP:IN: Loading from storage for fabric index 8
[1652085372.895120][465400:465400] CHIP:IN: Loading from storage for fabric index 9
[1652085372.895133][465400:465400] CHIP:IN: Loading from storage for fabric index 10
[1652085372.895146][465400:465400] CHIP:IN: Loading from storage for fabric index 11
[1652085372.895160][465400:465400] CHIP:IN: Loading from storage for fabric index 12
[1652085372.895174][465400:465400] CHIP:IN: Loading from storage for fabric index 13
[1652085372.895209][465400:465400] CHIP:IN: Loading from storage for fabric index 14
[1652085372.895260][465400:465400] CHIP:IN: Loading from storage for fabric index 15
[1652085372.895274][465400:465400] CHIP:IN: Loading from storage for fabric index 16
[1652085372.895384][465400:465400] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-WyKB9x)
[1652085372.895520][465400:465400] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1652085372.895532][465400:465400] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 7000 (0x1B58)
[1652085372.896000][465400:465400] CHIP:ZCL: Using ZAP configuration...
[1652085372.897543][465400:465400] CHIP:DL: Avahi client registered
[1652085372.897900][465400:465400] CHIP:CTL: Setting attestation nonce to random value
[1652085372.897911][465400:465400] CHIP:CTL: Setting CSR nonce to random value
[1652085372.897938][465400:465400] CHIP:CTL: Setting attestation nonce to random value
[1652085372.897945][465400:465400] CHIP:CTL: Setting CSR nonce to random value
[1652085372.898167][465400:465400] CHIP:CTL: Generating NOC
[1652085372.898382][465400:465400] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.898401][465400:465400] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.898446][465400:465400] CHIP:DIS: Verifying the received credentials
[1652085372.898865][465400:465400] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1652085372.898872][465400:465400] CHIP:DIS: Assigned compressed fabric ID: 0x5C5F54E6DCDF1E42, node ID: 0x000000000001B669
[1652085372.898877][465400:465400] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x5C5F54E6DCDF1E42
[1652085372.898894][465400:465400] CHIP:CTL: Setting attestation nonce to random value
[1652085372.898903][465400:465400] CHIP:CTL: Setting CSR nonce to random value
[1652085372.899067][465400:465400] CHIP:CTL: Generating NOC
[1652085372.899253][465400:465400] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.899271][465400:465400] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.899285][465400:465400] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.899323][465400:465400] CHIP:DIS: Verifying the received credentials
[1652085372.899706][465400:465400] CHIP:DIS: Added new fabric at index: 2, Initialized: 1
[1652085372.899712][465400:465400] CHIP:DIS: Assigned compressed fabric ID: 0x11086265F3884825, node ID: 0x000000000001B669
[1652085372.899716][465400:465400] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x11086265F3884825
[1652085372.899730][465400:465400] CHIP:CTL: Setting attestation nonce to random value
[1652085372.899737][465400:465400] CHIP:CTL: Setting CSR nonce to random value
[1652085372.899900][465400:465400] CHIP:CTL: Generating NOC
[1652085372.900083][465400:465400] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.900101][465400:465400] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.900114][465400:465400] CHIP:DIS: Fabric (3) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.900128][465400:465400] CHIP:DIS: Fabric (3) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085372.900168][465400:465400] CHIP:DIS: Verifying the received credentials
[1652085372.900546][465400:465400] CHIP:DIS: Added new fabric at index: 3, Initialized: 1
[1652085372.900553][465400:465400] CHIP:DIS: Assigned compressed fabric ID: 0x9BEFC269D3A437EF, node ID: 0x000000000001B669
[1652085372.900557][465400:465400] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x9BEFC269D3A437EF
[1652085372.905282][465400:465405] CHIP:IN: Prepared unauthenticated message 0x7f2852ffc380 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 1153i with MessageCounter:3734599857.
[1652085372.905296][465400:465405] CHIP:IN: Sending unauthenticated msg 0x7f2852ffc380 with MessageCounter:3734599857 to 0x0000000000000000 at monotonic time: 000000000FCB3133 msec
[1652085372.905304][465400:465405] CHIP:CTL: Setting thread operational dataset from parameters
[1652085372.905307][465400:465405] CHIP:CTL: Setting attestation nonce to random value
[1652085372.905313][465400:465405] CHIP:CTL: Setting CSR nonce to random value
[1652085372.905319][465400:465405] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1652085372.920045][465400:465403] CHIP:BLE: BLE removing known devices.
[1652085372.939089][465400:465403] CHIP:BLE: BLE initiating scan.
[1652085373.663760][465400:465403] CHIP:BLE: New device scanned: D8:F6:4A:A2:2D:4D
[1652085373.663786][465400:465403] CHIP:BLE: Device discriminator match. Attempting to connect.
[1652085373.666956][465400:465403] CHIP:BLE: Scan complete notification without an active scan.
[1652085376.106440][465400:465405] CHIP:BLE: subscribe complete, ep = 0x556b58661f20
[1652085376.106488][465400:465405] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1652085376.106513][465400:465405] CHIP:BLE: using BTP fragment sizes rx 20 / tx 20.
[1652085376.106526][465400:465405] CHIP:BLE: local and remote recv window size = 5
[1652085377.325041][465400:465405] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:215078883 on exchange 1153i
[1652085377.331776][465400:465405] CHIP:IN: Prepared unauthenticated message 0x7f2852ffbf10 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 1153i with MessageCounter:3734599858.
[1652085377.331818][465400:465405] CHIP:IN: Sending unauthenticated msg 0x7f2852ffbf10 with MessageCounter:3734599858 to 0x0000000000000000 at monotonic time: 000000000FCB427D msec
[1652085380.223444][465400:465405] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:215078884 on exchange 1153i
[1652085380.224516][465400:465405] CHIP:IN: Prepared unauthenticated message 0x7f2852ffc010 to 0x0000000000000000 (0)  of type 0x24 and protocolId (0, 0) on exchange 1153i with MessageCounter:3734599859.
[1652085380.224558][465400:465405] CHIP:IN: Sending unauthenticated msg 0x7f2852ffc010 with MessageCounter:3734599859 to 0x0000000000000000 at monotonic time: 000000000FCB4DCA msec
[1652085380.808345][465400:465405] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:215078885 on exchange 1153i
[1652085380.808478][465400:465405] CHIP:CTL: Going from commissioning step 'SecurePairing' with lastErr = '../../src/controller/AutoCommissioner.cpp:253: Success' --> 'ReadCommissioningInfo'
[1652085380.808503][465400:465405] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' with completion status = '../../src/controller/CommissioningDelegate.h:341: Success'
[1652085380.808516][465400:465405] CHIP:CTL: Sending request for commissioning information
[1652085380.808599][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb990 to 0x0000000000000001 (1)  of type 0x2 and protocolId (0, 1) on exchange 1154i with MessageCounter:5725624.
[1652085380.808648][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb990 with MessageCounter:5725624 to 0x0000000000000001 (1) at monotonic time: 000000000FCB5012 msec
[1652085383.103838][465400:465405] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:6594972 on exchange 1154i
[1652085383.105012][465400:465405] CHIP:CTL: Finished commissioning step 'ReadCommissioningInfo' with error '../../src/controller/CHIPDeviceController.cpp:1631: Success'
[1652085383.105051][465400:465405] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1631: Success' --> 'ArmFailSafe'
[1652085383.105073][465400:465405] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' with completion status = '../../src/controller/CHIPDeviceController.cpp:1631: Success'
[1652085383.105091][465400:465405] CHIP:CTL: Arming failsafe (60 seconds)
[1652085383.105195][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb500 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1155i with MessageCounter:5725625.
[1652085383.105235][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb500 with MessageCounter:5725625 to 0x0000000000000001 (1) at monotonic time: 000000000FCB590B msec
[1652085383.914050][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594973 on exchange 1155i
[1652085383.914287][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1652085383.914344][465400:465405] CHIP:CTL: Received ArmFailSafe response
[1652085383.914366][465400:465405] CHIP:CTL: Finished commissioning step 'ArmFailSafe' with error '../../src/controller/CHIPDeviceController.cpp:1783: Success'
[1652085383.914388][465400:465405] CHIP:CTL: Going from commissioning step 'ArmFailSafe' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1783: Success' --> 'ConfigRegulatory'
[1652085383.914410][465400:465405] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' with completion status = '../../src/controller/CHIPDeviceController.cpp:1783: Success'
[1652085383.914426][465400:465405] CHIP:CTL: Setting Regulatory Config
[1652085383.914438][465400:465405] CHIP:CTL: Device does not support configurable regulatory location
[1652085383.914479][465400:465405] CHIP:CTL: Unable to find country code, defaulting to XX
[1652085383.914586][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb100 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1156i with MessageCounter:5725626.
[1652085383.914626][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb100 with MessageCounter:5725626 to 0x0000000000000001 (1) at monotonic time: 000000000FCB5C34 msec
[1652085384.768879][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594974 on exchange 1156i
[1652085384.769079][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1652085384.769118][465400:465405] CHIP:CTL: Received SetRegulatoryConfig response
[1652085384.769145][465400:465405] CHIP:CTL: Finished commissioning step 'ConfigRegulatory' with error '../../src/controller/CHIPDeviceController.cpp:1792: Success'
[1652085384.769166][465400:465405] CHIP:CTL: Going from commissioning step 'ConfigRegulatory' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1792: Success' --> 'SendPAICertificateRequest'
[1652085384.769186][465400:465405] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1792: Success'
[1652085384.769205][465400:465405] CHIP:CTL: Sending request for PAI certificate
[1652085384.769317][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb070 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1157i with MessageCounter:5725627.
[1652085384.769356][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb070 with MessageCounter:5725627 to 0x0000000000000001 (1) at monotonic time: 000000000FCB5F8B msec
[1652085388.008443][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594975 on exchange 1157i
[1652085388.008628][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1652085388.008658][465400:465405] CHIP:CTL: Received certificate chain from the device
[1652085388.008677][465400:465405] CHIP:CTL: Finished commissioning step 'SendPAICertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085388.008694][465400:465405] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1127: Success' --> 'SendDACCertificateRequest'
[1652085388.008713][465400:465405] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085388.008728][465400:465405] CHIP:CTL: Sending request for DAC certificate
[1652085388.008812][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb030 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1158i with MessageCounter:5725628.
[1652085388.008843][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb030 with MessageCounter:5725628 to 0x0000000000000001 (1) at monotonic time: 000000000FCB6C32 msec
[1652085391.248719][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594976 on exchange 1158i
[1652085391.248900][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1652085391.248930][465400:465405] CHIP:CTL: Received certificate chain from the device
[1652085391.248949][465400:465405] CHIP:CTL: Finished commissioning step 'SendDACCertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085391.248966][465400:465405] CHIP:CTL: Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1127: Success' --> 'SendAttestationRequest'
[1652085391.248985][465400:465405] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085391.249000][465400:465405] CHIP:CTL: Sending Attestation Request to the device.
[1652085391.249084][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb010 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1159i with MessageCounter:5725629.
[1652085391.249115][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb010 with MessageCounter:5725629 to 0x0000000000000001 (1) at monotonic time: 000000000FCB78DB msec
[1652085395.658866][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594977 on exchange 1159i
[1652085395.659065][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1652085395.659097][465400:465405] CHIP:CTL: Received Attestation Information from the device
[1652085395.659117][465400:465405] CHIP:CTL: Finished commissioning step 'SendAttestationRequest' with error '../../src/controller/CHIPDeviceController.cpp:1162: Success'
[1652085395.659156][465400:465405] CHIP:CTL: Going from commissioning step 'SendAttestationRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1162: Success' --> 'AttestationVerification'
[1652085395.659173][465400:465405] CHIP:CTL: Performing next commissioning step 'AttestationVerification' with completion status = '../../src/controller/CHIPDeviceController.cpp:1162: Success'
[1652085395.659185][465400:465405] CHIP:CTL: Verifying attestation
[1652085395.663972][465400:465405] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1652085395.664012][465400:465405] CHIP:CTL: Finished commissioning step 'AttestationVerification' with error '../../src/controller/CHIPDeviceController.cpp:1194: Success'
[1652085395.664027][465400:465405] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1194: Success' --> 'SendOpCertSigningRequest'
[1652085395.664041][465400:465405] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1194: Success'
[1652085395.664147][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffa590 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1160i with MessageCounter:5725630.
[1652085395.664184][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffa590 with MessageCounter:5725630 to 0x0000000000000001 (1) at monotonic time: 000000000FCB8A1A msec
[1652085398.628642][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594978 on exchange 1160i
[1652085398.628847][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1652085398.628881][465400:465405] CHIP:CTL: Received certificate signing request from the device
[1652085398.628902][465400:465405] CHIP:CTL: Finished commissioning step 'SendOpCertSigningRequest' with error '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085398.628923][465400:465405] CHIP:CTL: Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1243: Success' --> 'GenerateNOCChain'
[1652085398.628943][465400:465405] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' with completion status = '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085398.628961][465400:465405] CHIP:CTL: Getting certificate chain for the device from the issuer
[1652085398.629977][465400:465405] CHIP:CTL: Verifying Certificate Signing Request
[1652085398.630555][465400:465405] CHIP:CTL: Generating NOC
[1652085398.630907][465400:465405] CHIP:CTL: Providing certificate chain to the commissioner
[1652085398.630934][465400:465405] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:229: Success
[1652085398.630955][465400:465405] CHIP:CTL: Finished commissioning step 'GenerateNOCChain' with error '../../src/controller/ExampleOperationalCredentialsIssuer.cpp:229: Success'
[1652085398.631122][465400:465405] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' with completion status = '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085398.631146][465400:465405] CHIP:CTL: Sending root certificate to the device
[1652085398.631247][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffa3c0 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1161i with MessageCounter:5725631.
[1652085398.631284][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffa3c0 with MessageCounter:5725631 to 0x0000000000000001 (1) at monotonic time: 000000000FCB95B1 msec
[1652085398.631370][465400:465405] CHIP:CTL: Sent root certificate to the device
[1652085400.609006][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594979 on exchange 1161i
[1652085400.609178][465400:465405] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1652085400.609204][465400:465405] CHIP:CTL: Device confirmed that it has received the root certificate
[1652085400.609222][465400:465405] CHIP:CTL: Finished commissioning step 'SendTrustedRootCert' with error '../../src/controller/CHIPDeviceController.cpp:1414: Success'
[1652085400.609236][465400:465405] CHIP:CTL: Going from commissioning step 'SendTrustedRootCert' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1414: Success' --> 'SendNOC'
[1652085400.609251][465400:465405] CHIP:CTL: Performing next commissioning step 'SendNOC' with completion status = '../../src/controller/CHIPDeviceController.cpp:1414: Success'
[1652085400.609353][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb030 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1162i with MessageCounter:5725632.
[1652085400.609384][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb030 with MessageCounter:5725632 to 0x0000000000000001 (1) at monotonic time: 000000000FCB9D6B msec
[1652085400.609456][465400:465405] CHIP:CTL: Sent operational certificate to the device
[1652085404.524482][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594980 on exchange 1162i
[1652085404.524679][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1652085404.524736][465400:465405] CHIP:CTL: Device returned status 0 on receiving the NOC
[1652085404.524752][465400:465405] CHIP:CTL: Operational credentials provisioned on device 0x7f2840001730
[1652085404.524776][465400:465405] CHIP:TOO: Secure Pairing Success
[1652085404.524798][465400:465405] CHIP:CTL: Finished commissioning step 'SendNOC' with error '../../src/controller/CHIPDeviceController.cpp:1440: Success'
[1652085404.524817][465400:465405] CHIP:CTL: Going from commissioning step 'SendNOC' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1440: Success' --> 'ThreadNetworkSetup'
[1652085404.524837][465400:465405] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1440: Success'
[1652085404.524933][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb010 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1163i with MessageCounter:5725633.
[1652085404.524966][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb010 with MessageCounter:5725633 to 0x0000000000000001 (1) at monotonic time: 000000000FCBACB6 msec
[1652085405.784649][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594981 on exchange 1163i
[1652085405.784840][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1652085405.784877][465400:465405] CHIP:CTL: Received NetworkConfig response
[1652085405.784899][465400:465405] CHIP:CTL: Finished commissioning step 'ThreadNetworkSetup' with error '../../src/controller/CHIPDeviceController.cpp:1801: Success'
[1652085405.784921][465400:465405] CHIP:CTL: Going from commissioning step 'ThreadNetworkSetup' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1801: Success' --> 'ThreadNetworkEnable'
[1652085405.784951][465400:465405] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable' with completion status = '../../src/controller/CHIPDeviceController.cpp:1801: Success'
[1652085405.785054][465400:465405] CHIP:IN: Prepared secure message 0x7f2852ffb100 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 1164i with MessageCounter:5725634.
[1652085405.785084][465400:465405] CHIP:IN: Sending encrypted msg 0x7f2852ffb100 with MessageCounter:5725634 to 0x0000000000000001 (1) at monotonic time: 000000000FCBB1A3 msec
[1652085409.293882][465400:465405] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6594982 on exchange 1164i
[1652085409.294089][465400:465405] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1652085409.294129][465400:465405] CHIP:CTL: Received ConnectNetwork response
[1652085409.294155][465400:465405] CHIP:CTL: Finished commissioning step 'ThreadNetworkEnable' with error '../../src/controller/CHIPDeviceController.cpp:1810: Success'
[1652085409.294180][465400:465405] CHIP:CTL: Going from commissioning step 'ThreadNetworkEnable' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1810: Success' --> 'FindOperational'
[1652085409.294201][465400:465405] CHIP:CTL: Performing next commissioning step 'FindOperational' with completion status = '../../src/controller/CHIPDeviceController.cpp:1810: Success'
[1652085409.294230][465400:465405] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085409.294244][465400:465405] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085409.294262][465400:465405] CHIP:DIS: Resolving 5C5F54E6DCDF1E42:0000000000000001 ...
[1652085409.295332][465400:465405] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one.
[1652085409.494893][465400:465405] CHIP:DIS: Checking node lookup status after 200 ms
[1652085410.176277][465400:465405] CHIP:DL: Avahi resolve found
[1652085410.176351][465400:465405] CHIP:DIS: Node ID resolved for 5C5F54E6DCDF1E42:0000000000000001
[1652085410.176378][465400:465405] CHIP:DIS:     Addr 0: [fd11:22::8a29:aa5:51df:aeff]:5540
[1652085410.176789][465400:465405] CHIP:DIS: UDP:[fd11:22::8a29:aa5:51df:aeff%wlp1s0]:5540: new best score: 4
[1652085410.176815][465400:465405] CHIP:DIS: Checking node lookup status after 882 ms
[1652085410.176883][465400:465405] CHIP:SC: Establishing CASE session to UDP:[fd11:22::8a29:aa5:51df:aeff]:5540
[1652085410.177330][465400:465405] CHIP:IN: Prepared unauthenticated message 0x556b5a798468 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 1165i with MessageCounter:3734599860.
[1652085410.177375][465400:465405] CHIP:IN: Sending unauthenticated msg 0x556b5a798468 with MessageCounter:3734599860 to 0x0000000000000000 at monotonic time: 000000000FCBC2CB msec
[1652085410.177450][465400:465405] CHIP:DIS: Discovery does not require any more timeouts
[1652085443.711570][465400:465403] CHIP:DL: Bluez notify CHIPoBluez connection disconnected

Then, I decided to use the pre-built tool for raspberryPI (chip-tool-linux_aarch64.zip). With this tool, I can send Matter commands without any problem. You can find my output on the attached file Pre_built_chip_tool_raspberrypi:

 

Fullscreen Pre_built_chip_tool_raspberrypi.txt Download

$ sudo ./chip-tool-release pairing ble-thread 1 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fda55b6b5f370b59051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840
[1652085532.353873][9875:9875] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Mh5M9U)
[1652085532.354802][9875:9875] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1652085532.354892][9875:9875] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1652085532.355788][9875:9875] CHIP:DL: Got Ethernet interface: eth0
[1652085532.356296][9875:9875] CHIP:DL: Found the primary Ethernet interface:eth0
[1652085532.356780][9875:9875] CHIP:DL: Got WiFi interface: wlan0
[1652085532.359259][9875:9875] CHIP:DL: Found the primary WiFi interface:wlan0
[1652085532.359714][9875:9875] CHIP:IN: Loading from storage for fabric index 1
[1652085532.364012][9875:9875] CHIP:IN: Loading from storage for fabric index 2
[1652085532.365015][9875:9875] CHIP:IN: Loading from storage for fabric index 3
[1652085532.366089][9875:9875] CHIP:IN: Loading from storage for fabric index 4
[1652085532.366200][9875:9875] CHIP:IN: Loading from storage for fabric index 5
[1652085532.366288][9875:9875] CHIP:IN: Loading from storage for fabric index 6
[1652085532.366382][9875:9875] CHIP:IN: Loading from storage for fabric index 7
[1652085532.366514][9875:9875] CHIP:IN: Loading from storage for fabric index 8
[1652085532.366621][9875:9875] CHIP:IN: Loading from storage for fabric index 9
[1652085532.366731][9875:9875] CHIP:IN: Loading from storage for fabric index 10
[1652085532.366825][9875:9875] CHIP:IN: Loading from storage for fabric index 11
[1652085532.366914][9875:9875] CHIP:IN: Loading from storage for fabric index 12
[1652085532.367004][9875:9875] CHIP:IN: Loading from storage for fabric index 13
[1652085532.367115][9875:9875] CHIP:IN: Loading from storage for fabric index 14
[1652085532.367210][9875:9875] CHIP:IN: Loading from storage for fabric index 15
[1652085532.367299][9875:9875] CHIP:IN: Loading from storage for fabric index 16
[1652085532.367733][9875:9875] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ucV4fU)
[1652085532.368597][9875:9875] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1652085532.368682][9875:9875] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 9000 (0x2328)
[1652085532.373344][9875:9875] CHIP:ZCL: Using ZAP configuration...
[1652085532.378914][9875:9875] CHIP:DL: Avahi client registered
[1652085532.380722][9875:9875] CHIP:CTL: Setting attestation nonce to random value
[1652085532.380812][9875:9875] CHIP:CTL: Setting CSR nonce to random value
[1652085532.380964][9875:9875] CHIP:CTL: Setting attestation nonce to random value
[1652085532.381023][9875:9875] CHIP:CTL: Setting CSR nonce to random value
[1652085532.382589][9875:9875] CHIP:CTL: Generating NOC
[1652085532.384049][9875:9875] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.384355][9875:9875] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.384780][9875:9875] CHIP:DIS: Verifying the received credentials
[1652085532.387724][9875:9875] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1652085532.387795][9875:9875] CHIP:DIS: Assigned compressed fabric ID: 0xFD744A7D5E7C34C8, node ID: 0x000000000001B669
[1652085532.387836][9875:9875] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xFD744A7D5E7C34C8
[1652085532.388014][9875:9875] CHIP:CTL: Setting attestation nonce to random value
[1652085532.388155][9875:9875] CHIP:CTL: Setting CSR nonce to random value
[1652085532.389601][9875:9875] CHIP:CTL: Generating NOC
[1652085532.390925][9875:9875] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.391043][9875:9875] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.391133][9875:9875] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.391459][9875:9875] CHIP:DIS: Verifying the received credentials
[1652085532.394516][9875:9875] CHIP:DIS: Added new fabric at index: 2, Initialized: 1
[1652085532.394591][9875:9875] CHIP:DIS: Assigned compressed fabric ID: 0xFC354AF27321C0C0, node ID: 0x000000000001B669
[1652085532.394679][9875:9875] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0xFC354AF27321C0C0
[1652085532.394867][9875:9875] CHIP:CTL: Setting attestation nonce to random value
[1652085532.395025][9875:9875] CHIP:CTL: Setting CSR nonce to random value
[1652085532.396598][9875:9875] CHIP:CTL: Generating NOC
[1652085532.398043][9875:9875] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.398243][9875:9875] CHIP:DIS: Fabric (2) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.398368][9875:9875] CHIP:DIS: Fabric (3) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.398518][9875:9875] CHIP:DIS: Fabric (3) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085532.398933][9875:9875] CHIP:DIS: Verifying the received credentials
[1652085532.402186][9875:9875] CHIP:DIS: Added new fabric at index: 3, Initialized: 1
[1652085532.402327][9875:9875] CHIP:DIS: Assigned compressed fabric ID: 0x7975A918FB5FA41A, node ID: 0x000000000001B669
[1652085532.402401][9875:9875] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x7975A918FB5FA41A
[1652085532.456629][9875:9880] CHIP:IN: Prepared unauthenticated message 0x7f991cddd8 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 59055i with MessageCounter:514411863.
[1652085532.456774][9875:9880] CHIP:IN: Sending unauthenticated msg 0x7f991cddd8 with MessageCounter:514411863 to 0x0000000000000000 at monotonic time: 000000000EA3812D msec
[1652085532.457477][9875:9880] CHIP:CTL: Setting thread operational dataset from parameters
[1652085532.457536][9875:9880] CHIP:CTL: Setting attestation nonce to random value
[1652085532.457972][9875:9880] CHIP:CTL: Setting CSR nonce to random value
[1652085532.458235][9875:9880] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1652085532.486485][9875:9878] CHIP:BLE: BLE removing known devices.
[1652085532.488821][9875:9878] CHIP:BLE: BLE initiating scan.
[1652085533.212875][9875:9878] CHIP:BLE: New device scanned: C2:98:19:62:AA:CC
[1652085533.213024][9875:9878] CHIP:BLE: Device discriminator match. Attempting to connect.
[1652085533.219852][9875:9878] CHIP:BLE: Scan complete notification without an active scan.
[1652085535.759026][9875:9880] CHIP:BLE: subscribe complete, ep = 0x556dc539b8
[1652085535.759280][9875:9880] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1652085535.759328][9875:9880] CHIP:BLE: using BTP fragment sizes rx 20 / tx 20.
[1652085535.759412][9875:9880] CHIP:BLE: local and remote recv window size = 5
[1652085536.977639][9875:9880] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:3704879279 on exchange 59055i
[1652085536.989515][9875:9880] CHIP:IN: Prepared unauthenticated message 0x7f991cd908 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 59055i with MessageCounter:514411864.
[1652085536.989615][9875:9880] CHIP:IN: Sending unauthenticated msg 0x7f991cd908 with MessageCounter:514411864 to 0x0000000000000000 at monotonic time: 000000000EA392E2 msec
[1652085539.822549][9875:9880] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:3704879280 on exchange 59055i
[1652085539.829171][9875:9880] CHIP:IN: Prepared unauthenticated message 0x7f991cda48 to 0x0000000000000000 (0)  of type 0x24 and protocolId (0, 0) on exchange 59055i with MessageCounter:514411865.
[1652085539.829448][9875:9880] CHIP:IN: Sending unauthenticated msg 0x7f991cda48 with MessageCounter:514411865 to 0x0000000000000000 at monotonic time: 000000000EA39DF9 msec
[1652085540.407624][9875:9880] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3704879281 on exchange 59055i
[1652085540.408154][9875:9880] CHIP:CTL: Going from commissioning step 'SecurePairing' with lastErr = '../../src/controller/AutoCommissioner.cpp:253: Success' --> 'ReadCommissioningInfo'
[1652085540.408302][9875:9880] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' with completion status = '../../src/controller/CommissioningDelegate.h:341: Success'
[1652085540.408368][9875:9880] CHIP:CTL: Sending request for commissioning information
[1652085540.408929][9875:9880] CHIP:IN: Prepared secure message 0x7f991cd388 to 0x0000000000000001 (1)  of type 0x2 and protocolId (0, 1) on exchange 59056i with MessageCounter:2382648.
[1652085540.409046][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cd388 with MessageCounter:2382648 to 0x0000000000000001 (1) at monotonic time: 000000000EA3A03D msec
[1652085542.657511][9875:9880] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:12758104 on exchange 59056i
[1652085542.661825][9875:9880] CHIP:CTL: Finished commissioning step 'ReadCommissioningInfo' with error '../../src/controller/CHIPDeviceController.cpp:1631: Success'
[1652085542.661997][9875:9880] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1631: Success' --> 'ArmFailSafe'
[1652085542.662158][9875:9880] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' with completion status = '../../src/controller/CHIPDeviceController.cpp:1631: Success'
[1652085542.662238][9875:9880] CHIP:CTL: Arming failsafe (60 seconds)
[1652085542.662651][9875:9880] CHIP:IN: Prepared secure message 0x7f991ccf48 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59057i with MessageCounter:2382649.
[1652085542.662765][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991ccf48 with MessageCounter:2382649 to 0x0000000000000001 (1) at monotonic time: 000000000EA3A90B msec
[1652085543.467777][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758105 on exchange 59057i
[1652085543.468356][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1652085543.468503][9875:9880] CHIP:CTL: Received ArmFailSafe response
[1652085543.468589][9875:9880] CHIP:CTL: Finished commissioning step 'ArmFailSafe' with error '../../src/controller/CHIPDeviceController.cpp:1783: Success'
[1652085543.468715][9875:9880] CHIP:CTL: Going from commissioning step 'ArmFailSafe' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1783: Success' --> 'ConfigRegulatory'
[1652085543.468896][9875:9880] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' with completion status = '../../src/controller/CHIPDeviceController.cpp:1783: Success'
[1652085543.469049][9875:9880] CHIP:CTL: Setting Regulatory Config
[1652085543.469197][9875:9880] CHIP:CTL: Device does not support configurable regulatory location
[1652085543.469480][9875:9880] CHIP:CTL: Unable to find country code, defaulting to XX
[1652085543.469974][9875:9880] CHIP:IN: Prepared secure message 0x7f991ccb08 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59058i with MessageCounter:2382650.
[1652085543.470238][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991ccb08 with MessageCounter:2382650 to 0x0000000000000001 (1) at monotonic time: 000000000EA3AC32 msec
[1652085544.277815][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758106 on exchange 59058i
[1652085544.278396][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1652085544.278525][9875:9880] CHIP:CTL: Received SetRegulatoryConfig response
[1652085544.278612][9875:9880] CHIP:CTL: Finished commissioning step 'ConfigRegulatory' with error '../../src/controller/CHIPDeviceController.cpp:1792: Success'
[1652085544.278701][9875:9880] CHIP:CTL: Going from commissioning step 'ConfigRegulatory' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1792: Success' --> 'SendPAICertificateRequest'
[1652085544.278782][9875:9880] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1792: Success'
[1652085544.278852][9875:9880] CHIP:CTL: Sending request for PAI certificate
[1652085544.279298][9875:9880] CHIP:IN: Prepared secure message 0x7f991cca68 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59059i with MessageCounter:2382651.
[1652085544.279437][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cca68 with MessageCounter:2382651 to 0x0000000000000001 (1) at monotonic time: 000000000EA3AF5B msec
[1652085547.427826][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758107 on exchange 59059i
[1652085547.428382][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1652085547.428491][9875:9880] CHIP:CTL: Received certificate chain from the device
[1652085547.428616][9875:9880] CHIP:CTL: Finished commissioning step 'SendPAICertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085547.428703][9875:9880] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1127: Success' --> 'SendDACCertificateRequest'
[1652085547.428800][9875:9880] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085547.428872][9875:9880] CHIP:CTL: Sending request for DAC certificate
[1652085547.429275][9875:9880] CHIP:IN: Prepared secure message 0x7f991cca18 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59060i with MessageCounter:2382652.
[1652085547.429520][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cca18 with MessageCounter:2382652 to 0x0000000000000001 (1) at monotonic time: 000000000EA3BBAA msec
[1652085550.667416][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758108 on exchange 59060i
[1652085550.668047][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1652085550.668441][9875:9880] CHIP:CTL: Received certificate chain from the device
[1652085550.668855][9875:9880] CHIP:CTL: Finished commissioning step 'SendDACCertificateRequest' with error '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085550.668945][9875:9880] CHIP:CTL: Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1127: Success' --> 'SendAttestationRequest'
[1652085550.669021][9875:9880] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1127: Success'
[1652085550.669102][9875:9880] CHIP:CTL: Sending Attestation Request to the device.
[1652085550.670092][9875:9880] CHIP:IN: Prepared secure message 0x7f991cc9c8 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59061i with MessageCounter:2382653.
[1652085550.670213][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cc9c8 with MessageCounter:2382653 to 0x0000000000000001 (1) at monotonic time: 000000000EA3C852 msec
[1652085554.897481][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758109 on exchange 59061i
[1652085554.897988][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1652085554.898183][9875:9880] CHIP:CTL: Received Attestation Information from the device
[1652085554.898810][9875:9880] CHIP:CTL: Finished commissioning step 'SendAttestationRequest' with error '../../src/controller/CHIPDeviceController.cpp:1162: Success'
[1652085554.900600][9875:9880] CHIP:CTL: Going from commissioning step 'SendAttestationRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1162: Success' --> 'AttestationVerification'
[1652085554.901189][9875:9880] CHIP:CTL: Performing next commissioning step 'AttestationVerification' with completion status = '../../src/controller/CHIPDeviceController.cpp:1162: Success'
[1652085554.901896][9875:9880] CHIP:CTL: Verifying attestation
[1652085554.922918][9875:9880] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1652085554.923062][9875:9880] CHIP:CTL: Finished commissioning step 'AttestationVerification' with error '../../src/controller/CHIPDeviceController.cpp:1194: Success'
[1652085554.923144][9875:9880] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1194: Success' --> 'SendOpCertSigningRequest'
[1652085554.923213][9875:9880] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' with completion status = '../../src/controller/CHIPDeviceController.cpp:1194: Success'
[1652085554.923916][9875:9880] CHIP:IN: Prepared secure message 0x7f991cbf78 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59062i with MessageCounter:2382654.
[1652085554.924200][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cbf78 with MessageCounter:2382654 to 0x0000000000000001 (1) at monotonic time: 000000000EA3D8F0 msec
[1652085557.732168][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758110 on exchange 59062i
[1652085557.732737][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1652085557.733255][9875:9880] CHIP:CTL: Received certificate signing request from the device
[1652085557.733873][9875:9880] CHIP:CTL: Finished commissioning step 'SendOpCertSigningRequest' with error '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085557.734033][9875:9880] CHIP:CTL: Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1243: Success' --> 'GenerateNOCChain'
[1652085557.734116][9875:9880] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' with completion status = '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085557.734187][9875:9880] CHIP:CTL: Getting certificate chain for the device from the issuer
[1652085557.738798][9875:9880] CHIP:CTL: Verifying Certificate Signing Request
[1652085557.743663][9875:9880] CHIP:CTL: Generating NOC
[1652085557.745297][9875:9880] CHIP:CTL: Providing certificate chain to the commissioner
[1652085557.745407][9875:9880] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:229: Success
[1652085557.745510][9875:9880] CHIP:CTL: Finished commissioning step 'GenerateNOCChain' with error '../../src/controller/ExampleOperationalCredentialsIssuer.cpp:229: Success'
[1652085557.746430][9875:9880] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' with completion status = '../../src/controller/CHIPDeviceController.cpp:1243: Success'
[1652085557.746517][9875:9880] CHIP:CTL: Sending root certificate to the device
[1652085557.748540][9875:9880] CHIP:IN: Prepared secure message 0x7f991cbd58 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59063i with MessageCounter:2382655.
[1652085557.748680][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cbd58 with MessageCounter:2382655 to 0x0000000000000001 (1) at monotonic time: 000000000EA3E3F9 msec
[1652085557.749826][9875:9880] CHIP:CTL: Sent root certificate to the device
[1652085559.622673][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758111 on exchange 59063i
[1652085559.623245][9875:9880] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1652085559.623356][9875:9880] CHIP:CTL: Device confirmed that it has received the root certificate
[1652085559.623441][9875:9880] CHIP:CTL: Finished commissioning step 'SendTrustedRootCert' with error '../../src/controller/CHIPDeviceController.cpp:1414: Success'
[1652085559.623570][9875:9880] CHIP:CTL: Going from commissioning step 'SendTrustedRootCert' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1414: Success' --> 'SendNOC'
[1652085559.623661][9875:9880] CHIP:CTL: Performing next commissioning step 'SendNOC' with completion status = '../../src/controller/CHIPDeviceController.cpp:1414: Success'
[1652085559.624094][9875:9880] CHIP:IN: Prepared secure message 0x7f991cc9f8 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59064i with MessageCounter:2382656.
[1652085559.624211][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cc9f8 with MessageCounter:2382656 to 0x0000000000000001 (1) at monotonic time: 000000000EA3EB4C msec
[1652085559.624538][9875:9880] CHIP:CTL: Sent operational certificate to the device
[1652085563.357615][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758112 on exchange 59064i
[1652085563.358353][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1652085563.358723][9875:9880] CHIP:CTL: Device returned status 0 on receiving the NOC
[1652085563.358916][9875:9880] CHIP:CTL: Operational credentials provisioned on device 0x7f84001730
[1652085563.359149][9875:9880] CHIP:TOO: Secure Pairing Success
[1652085563.359350][9875:9880] CHIP:CTL: Finished commissioning step 'SendNOC' with error '../../src/controller/CHIPDeviceController.cpp:1440: Success'
[1652085563.359625][9875:9880] CHIP:CTL: Going from commissioning step 'SendNOC' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1440: Success' --> 'ThreadNetworkSetup'
[1652085563.359823][9875:9880] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1440: Success'
[1652085563.360346][9875:9880] CHIP:IN: Prepared secure message 0x7f991cca28 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59065i with MessageCounter:2382657.
[1652085563.360544][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cca28 with MessageCounter:2382657 to 0x0000000000000001 (1) at monotonic time: 000000000EA3F9E5 msec
[1652085564.617935][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758113 on exchange 59065i
[1652085564.618527][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1652085564.618968][9875:9880] CHIP:CTL: Received NetworkConfig response
[1652085564.619069][9875:9880] CHIP:CTL: Finished commissioning step 'ThreadNetworkSetup' with error '../../src/controller/CHIPDeviceController.cpp:1801: Success'
[1652085564.619151][9875:9880] CHIP:CTL: Going from commissioning step 'ThreadNetworkSetup' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1801: Success' --> 'ThreadNetworkEnable'
[1652085564.619227][9875:9880] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable' with completion status = '../../src/controller/CHIPDeviceController.cpp:1801: Success'
[1652085564.620618][9875:9880] CHIP:IN: Prepared secure message 0x7f991ccb08 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59066i with MessageCounter:2382658.
[1652085564.620773][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991ccb08 with MessageCounter:2382658 to 0x0000000000000001 (1) at monotonic time: 000000000EA3FED1 msec
[1652085567.181515][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:12758114 on exchange 59066i
[1652085567.181834][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1652085567.181901][9875:9880] CHIP:CTL: Received ConnectNetwork response
[1652085567.181938][9875:9880] CHIP:CTL: Finished commissioning step 'ThreadNetworkEnable' with error '../../src/controller/CHIPDeviceController.cpp:1810: Success'
[1652085567.181970][9875:9880] CHIP:CTL: Going from commissioning step 'ThreadNetworkEnable' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1810: Success' --> 'FindOperational'
[1652085567.182007][9875:9880] CHIP:CTL: Performing next commissioning step 'FindOperational' with completion status = '../../src/controller/CHIPDeviceController.cpp:1810: Success'
[1652085567.182056][9875:9880] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085567.182093][9875:9880] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1652085567.182151][9875:9880] CHIP:DIS: Resolving FD744A7D5E7C34C8:0000000000000001 ...
[1652085567.184530][9875:9880] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one.
[1652085567.381731][9875:9880] CHIP:DIS: Checking node lookup status after 200 ms
[1652085568.156289][9875:9880] CHIP:DL: Avahi resolve found
[1652085568.156417][9875:9880] CHIP:DIS: Node ID resolved for FD744A7D5E7C34C8:0000000000000001
[1652085568.156461][9875:9880] CHIP:DIS:     Addr 0: [fd11:22::c3b6:32b5:509c:ae00]:5540
[1652085568.157472][9875:9880] CHIP:DIS: UDP:[fd11:22::c3b6:32b5:509c:ae00%wlan0]:5540: new best score: 6
[1652085568.157531][9875:9880] CHIP:DIS: Checking node lookup status after 976 ms
[1652085568.157674][9875:9880] CHIP:SC: Establishing CASE session to UDP:[fd11:22::c3b6:32b5:509c:ae00]:5540
[1652085568.158817][9875:9880] CHIP:IN: Prepared unauthenticated message 0x559ea7dc48 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 59067i with MessageCounter:514411866.
[1652085568.158910][9875:9880] CHIP:IN: Sending unauthenticated msg 0x559ea7dc48 with MessageCounter:514411866 to 0x0000000000000000 at monotonic time: 000000000EA40CA3 msec
[1652085568.159130][9875:9880] CHIP:SC: Sent Sigma1 msg
[1652085568.159455][9875:9880] CHIP:DIS: Discovery does not require any more timeouts
[1652085568.486673][9875:9878] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1652085568.772760][9875:9880] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:3704879282 on exchange 59067i
[1652085568.772971][9875:9880] CHIP:SC: Received Sigma2 msg
[1652085568.774441][9875:9880] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures.
[1652085568.780310][9875:9880] CHIP:IN: Prepared unauthenticated message 0x559ea7dc48 to 0x0000000000000000 (0)  of type 0x32 and protocolId (0, 0) on exchange 59067i with MessageCounter:514411867.
[1652085568.780422][9875:9880] CHIP:IN: Sending unauthenticated msg 0x559ea7dc48 with MessageCounter:514411867 to 0x0000000000000000 at monotonic time: 000000000EA40F10 msec
[1652085568.780655][9875:9880] CHIP:SC: Sent Sigma3 msg
[1652085569.186575][9875:9880] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3704879283 on exchange 59067i
[1652085569.186740][9875:9880] CHIP:SC: Success status report received. Session was established
[1652085569.187223][9875:9880] CHIP:CTL: Finished commissioning step 'FindOperational' with error '../../src/controller/CHIPDeviceController.cpp:1575: Success'
[1652085569.187487][9875:9880] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1575: Success' --> 'SendComplete'
[1652085569.187552][9875:9880] CHIP:CTL: Performing next commissioning step 'SendComplete' with completion status = '../../src/controller/CHIPDeviceController.cpp:1575: Success'
[1652085569.188099][9875:9880] CHIP:IN: Prepared secure message 0x559ea7dc48 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 59068i with MessageCounter:7691169.
[1652085569.188190][9875:9880] CHIP:IN: Sending encrypted msg 0x559ea7dc48 with MessageCounter:7691169 to 0x0000000000000001 (1) at monotonic time: 000000000EA410A8 msec
[1652085569.188837][9875:9880] CHIP:IN: Prepared unauthenticated message 0x7f991cda48 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 59067i with MessageCounter:514411868.
[1652085569.188936][9875:9880] CHIP:IN: Sending unauthenticated msg 0x7f991cda48 with MessageCounter:514411868 to 0x0000000000000000 at monotonic time: 000000000EA410A9 msec
[1652085569.294694][9875:9880] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:13854363 on exchange 59068i
[1652085569.295593][9875:9880] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
[1652085569.296067][9875:9880] CHIP:CTL: Received CommissioningComplete response
[1652085569.296138][9875:9880] CHIP:CTL: Finished commissioning step 'SendComplete' with error '../../src/controller/CHIPDeviceController.cpp:1819: Success'
[1652085569.296533][9875:9880] CHIP:CTL: Going from commissioning step 'SendComplete' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1819: Success' --> 'Cleanup'
[1652085569.296803][9875:9880] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1819: Success'
[1652085569.297058][9875:9880] CHIP:TOO: Device commissioning completed with success
[1652085569.297618][9875:9880] CHIP:CTL: Finished commissioning step 'Cleanup' with error '../../src/controller/CHIPDeviceController.cpp:2156: Success'
[1652085569.298034][9875:9880] CHIP:IN: Prepared secure message 0x7f991cda78 to 0x0000000000000001 (1)  of type 0x10 and protocolId (0, 0) on exchange 59068i with MessageCounter:7691170.
[1652085569.298325][9875:9880] CHIP:IN: Sending encrypted msg 0x7f991cda78 with MessageCounter:7691170 to 0x0000000000000001 (1) at monotonic time: 000000000EA41116 msec
[1652085569.301090][9875:9875] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1652085569.301562][9875:9875] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JVxlmT)
[1652085569.302653][9875:9875] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1652085569.302773][9875:9875] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1652085569.302810][9875:9875] CHIP:DL: Inet Layer shutdown
[1652085569.302840][9875:9875] CHIP:DL: BLE shutdown
[1652085569.304464][9875:9875] CHIP:DL: System Layer shutdown
pi@raspberrypi:~/matter $ 

[Sigurd Hellesvik]

Hi

Carla31 said:

Then, I decided to use the pre-built tool for raspberryPI (chip-tool-linux_aarch64.zip). With this tool, I can send Matter commands without any problem. You can find my output on the attached file Pre_built_chip_tool_raspberrypi:

To clarify: Did you try the chip-tool-linux_aarch64.zip on you PC Linux or for a Raspberry Pi?

Regards,
Sigurd Hellesvik