Hello,
I'm working with the matter light_bulb and light_switch example provided by Nordic semiconductor. I followed the tutorial that's provided with these two examples to set up the network. I have two nrf52840 DK and a border router running on a Raspberry Pi.
My problem is that sometimes everything with the commissioning works fine and other times, like today, I simply can not connect the two devices.
When I try to execute the command: ./chip-tool-debug pairing ble-thread 1 hex:0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef000005104dfaa112a3e3d3d7b4e6b40b199eda3c030a4f70656e5468726561640102c95e0410c3ea8d5448f776348b4d2a63fa889f220c0402a0f7f8 20202021 3840. Which in theory should be the command for the light_bulb I get following output on the light_bulb:
I: Init CHIP stack I: 229 [DL]BLE address: DE:61:CB:D1:FE:40 I: 240 [DL]OpenThread started: OK I: 243 [DL]Setting OpenThread device type to ROUTER I: 247 [SVR]Server initializing... I: 251 [TS]Last Known Good Time: [unknown] I: 255 [TS]Setting Last Known Good Time to firmware build time 2023-04-21T12:42:24 I: 266 [DMG]AccessControl: initializing I: 270 [DMG]Examples::AccessControlDelegate::Init I: 274 [DMG]AccessControl: setting I: 277 [DMG]DefaultAclStorage: initializing I: 281 [DMG]DefaultAclStorage: 0 entries loaded D: 285 [IN]UDP::Init bind&listen port=5540 E: 289 [IN]SO_REUSEPORT failed: 109 D: 293 [IN]UDP::Init bound to port=5540 D: 296 [IN]BLEBase::Init - setting/overriding transport D: 301 [IN]TransportMgr initialized I: 315 [ZCL]Using ZAP configuration... I: 322 [DMG]AccessControlCluster: initializing I: 326 [ZCL]Initiating Admin Commissioning cluster. I: 331 [ZCL]On/Off set value: 1 0 I: 334 [ZCL]On/off already set to new value I: 341 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1 D: 349 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:35526 I: 355 [DIS]Updating services using commissioning mode 1 I: 361 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 370 [DIS]Failed to advertise commissionable node: 3 E: 375 [DIS]Failed to finalize service update: 1c I: 379 [DIS]Updating services using commissioning mode 1 I: 385 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 394 [DIS]Failed to advertise commissionable node: 3 E: 399 [DIS]Failed to finalize service update: 1c I: 404 [DIS]Delaying proxy of operational discovery: missing delegate I: 410 [IN]CASE Server enabling CASE session setups D: 415 [IN]SecureSession[0x20003620]: Allocated Type:2 LSID:35527 I: 421 [SVR]Joining Multicast groups I: 424 [SVR]Server Listening... I: 427 [DL]Device Configuration: I: 430 [DL] Serial Number: 11223344556677889900 I: 435 [DL] Vendor Id: 65521 (0xFFF1) I: 438 [DL] Product Id: 32773 (0x8005) I: 442 [DL] Hardware Version: 0 I: 446 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 I: 451 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) I: 458 [DL] Manufacturing Date: (not set) I: 462 [DL] Device Type: 65535 (0xFFFF) I: 467 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00] I: 471 [SVR]Copy/paste the below URL in a browser to see the QR Code: I: 477 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00 I: 486 [SVR]Manual pairing code: [34970112332] I: 491 [DL]CHIP task running I: 496 [DL]CHIPoBLE advertising started I: Initialize binding Handler I: Binding Table size: [0]: I: 509 [ZCL]Cluster OnOff: attribute OnOff set to 0 I: 514 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254 I: 521 [DL]NFC Tag emulation started I: 14887 [DL]BLE connection established (ConnId: 0x00) I: 14892 [DL]Current number of connections: 1/1 I: 14896 [DL]CHIPoBLE advertising stopped I: 14900 [DL]NFC Tag emulation stopped I: 16430 [BLE]local and remote recv window sizes = 5 I: 16435 [BLE]selected BTP version 4 I: 16438 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 16520 [IN]BLE EndPoint 0x2000a860 Connection Complete I: 16525 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) I: 16611 [EM]>>> [E:63399r M:118094686] (U) Msg RX from 0:C987A5FD6182A5DF [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I: 16624 [EM]<<< [E:63399r M:83479088] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I: 16635 [IN](U) Sending msg 83479088 to IP address 'BLE' I: 16701 [EM]>>> [E:63399r M:118094687] (U) Msg RX from 0:C987A5FD6182A5DF [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I: 18557 [EM]<<< [E:63399r M:83479089] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I: 18568 [IN](U) Sending msg 83479089 to IP address 'BLE' E: 18573 [DL]Long dispatch time: 1872 ms, for event type 16388 I: 18636 [EM]>>> [E:63399r M:118094688] (U) Msg RX from 0:C987A5FD6182A5DF [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I: 18648 [EM]<<< [E:63399r M:83479090] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I: 18659 [IN](U) Sending msg 83479090 to IP address 'BLE' I: 18665 [SC]SecureSession[0x20003568]: Moving from state 'kEstablishing' --> 'kActive' D: 18673 [IN]SecureSession[0x20003568]: Activated - Type:1 LSID:35526 D: 18679 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:35526 PSID:9221! I: 18688 [SVR]Commissioning completed session establishment step I: 18694 [DIS]Updating services using commissioning mode 0 I: 18700 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0 E: 18709 [DIS]Failed to advertise extended commissionable node: 3 D: 18715 [DIS]Scheduling extended discovery timeout in 900s E: 18721 [DIS]Failed to finalize service update: 1c I: 18726 [SVR]Device completed Rendezvous process I: 18732 [EM]>>> [E:63400r M:235529806] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) D: 18742 [IM]Received Read request I: 18755 [EM]<<< [E:63400r M:232613890] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I: 18765 [IN](S) Sending msg 232613890 on secure session with LSID: 35526 I: 18952 [EM]>>> [E:63401r M:235529807] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 18963 [FS]GeneralCommissioning: Received ArmFailSafe (60s) I: 18970 [EM]<<< [E:63401r M:232613891] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 18980 [IN](S) Sending msg 232613891 on secure session with LSID: 35526 I: 19042 [EM]>>> [E:63402r M:235529808] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 19058 [EM]<<< [E:63402r M:232613892] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 19069 [IN](S) Sending msg 232613892 on secure session with LSID: 35526 I: 19132 [EM]>>> [E:63403r M:235529809] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 19143 [ZCL]OpCreds: Certificate Chain request received for PAI I: 19152 [EM]<<< [E:63403r M:232613893] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 19163 [IN](S) Sending msg 232613893 on secure session with LSID: 35526 I: 19402 [EM]>>> [E:63404r M:235529810] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 19413 [ZCL]OpCreds: Certificate Chain request received for DAC I: 19422 [EM]<<< [E:63404r M:232613894] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 19433 [IN](S) Sending msg 232613894 on secure session with LSID: 35526 I: 19672 [EM]>>> [E:63405r M:235529811] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 19683 [ZCL]OpCreds: Received an AttestationRequest command I: 19720 [ZCL]OpCreds: AttestationRequest successful. I: 19729 [EM]<<< [E:63405r M:232613895] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 19739 [IN](S) Sending msg 232613895 on secure session with LSID: 35526 I: 19987 [EM]>>> [E:63406r M:235529812] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 19998 [ZCL]OpCreds: Received a CSRRequest command I: 20186 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded I: 20223 [ZCL]OpCreds: CSRRequest successful. I: 20229 [EM]<<< [E:63406r M:232613896] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 20240 [IN](S) Sending msg 232613896 on secure session with LSID: 35526 E: 20247 [DL]Long dispatch time: 261 ms, for event type 16388 I: 20482 [EM]>>> [E:63407r M:235529813] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 20493 [ZCL]OpCreds: Received an AddTrustedRootCertificate command I: 20557 [ZCL]OpCreds: AddTrustedRootCertificate successful. I: 20563 [EM]<<< [E:63407r M:232613897] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I: 20574 [IN](S) Sending msg 232613897 on secure session with LSID: 35526 E: 20581 [DL]Long dispatch time: 101 ms, for event type 16388 I: 20844 [EM]>>> [E:63408r M:235529814] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I: 20855 [ZCL]OpCreds: Received an AddNOC command I: 20862 [FP]Validating NOC chain I: 20980 [FP]NOC chain validation successful I: 20984 [FP]Added new fabric at index: 0x1 I: 20988 [FP]Assigned compressed fabric ID: 0x56DB79D6283C786D, node ID: 0x0000000000000001 I: 20996 [TS]Last Known Good Time: 2023-04-21T12:42:24 I: 21001 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00 I: 21007 [TS]Retaining current Last Known Good Time I: 21036 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I: 21044 [DIS]Advertise operational node 56DB79D6283C786D-0000000000000001 I: 21051 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC I: 21058 [EM]<<< [E:63408r M:232613898] (S) Msg TX to 1:FFFFFFFB00000000 [786D] --- Type 0001:09 (IM:InvokeCommandResponse) I: 21069 [IN](S) Sending msg 232613898 on secure session with LSID: 35526 E: 21076 [DL]Long dispatch time: 236 ms, for event type 16388 I: 21247 [EM]>>> [E:63409r M:235529815] (S) Msg RX from 1:FFFFFFFB00000000 [786D] --- Type 0001:08 (IM:InvokeCommandRequest) I: 21259 [EM]<<< [E:63409r M:232613899] (S) Msg TX to 1:FFFFFFFB00000000 [786D] --- Type 0001:09 (IM:InvokeCommandResponse) I: 21270 [IN](S) Sending msg 232613899 on secure session with LSID: 35526 D: 21335 [IN]Clearing BLE pending packets. I: 21339 [BLE]Releasing end point's BLE connection back to application. I: 21345 [DL]Closing BLE GATT connection (ConnId 00) I: 21470 [DL]BLE GAP connection terminated (reason 0x16) I: 21475 [DL]Current number of connections: 0/1 I: 78968 [FS]Fail-safe timer expired E: 78972 [SVR]Failsafe timer expired D: 78975 [IN]SecureSession[0x20003568]: MarkForEviction Type:1 LSID:35526 I: 78981 [SC]SecureSession[0x20003568]: Moving from state 'kActive' --> 'kPendingEviction' D: 78989 [IN]SecureSession[0x20003568]: Released - Type:1 LSID:35526 E: 78996 [SVR]Commissioning failed (attempt 1): 32 D: 79002 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:35528 I: 79008 [DIS]Updating services using commissioning mode 1 I: 79013 [DIS]Advertise operational node 56DB79D6283C786D-0000000000000001 E: 79020 [DIS]Failed to advertise operational node: 3 I: 79026 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 79035 [DIS]Failed to advertise commissionable node: 3 E: 79040 [DIS]Failed to finalize service update: 1c E: 79044 [ZCL]OpCreds: Got FailSafeTimerExpired E: 79049 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! D: 79055 [IN]Expiring all sessions for fabric 0x1!! E: 79060 [FP]Reverting pending fabric data for fabric 0x1 E: 79066 [FP]Warning: metadata not found during delete of fabric 0x1 I: 79079 [FP]Fabric (0x1) deleted. I: 79082 [ZCL]OpCreds: Fabric index 0x1 was removed I: 79087 [DIS]Updating services using commissioning mode 1 I: 79093 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 E: 79102 [DIS]Failed to advertise commissionable node: 3 E: 79107 [DIS]Failed to finalize service update: 1c I: 79127 [TS]Pending Last Known Good Time: 2023-04-21T12:42:24 I: 79133 [TS]Previous Last Known Good Time: 2023-04-21T12:42:24 I: 79139 [TS]Reverted Last Known Good Time to previous value E: 79145 [FP]Warning: metadata not found during delete of fabric 0x1 E: 79153 [ZCL]OpCreds: failed to delete fabric at index 1: d8 E: 79159 [DL]Long dispatch time: 187 ms, for event type 32782 I: 79164 [FS]Fail-safe cleanly disarmed I: 79170 [DL]CHIPoBLE advertising started I: 79174 [DL]NFC Tag emulation started
and in ./chip-tool-debug results in this output:
./chip-tool-debug pairing ble-thread 1 0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef000005104dfaa112a3e3d3d7b4e6b40b199eda3c030a4f70656e5468726561640102c95e0410c3ea8d5448f776348b4d2a63fa889f220c0402a0f7f8 20202021 3840
[1683890081.302069][8723:8723] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1683890081.302134][8723:8723] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1683890081.302147][8723:8723] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1683890081.302156][8723:8723] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1683890081.302234][8723:8723] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-7quTwc)
[1683890081.302312][8723:8723] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1683890081.302316][8723:8723] CHIP:DL: NVS set: chip-counters/reboot-count = 8 (0x8)
[1683890081.302500][8723:8723] CHIP:DL: Got Ethernet interface: enp89s0
[1683890081.302631][8723:8723] CHIP:DL: Found the primary Ethernet interface:enp89s0
[1683890081.302778][8723:8723] CHIP:DL: Got WiFi interface: wlo1
[1683890081.303603][8723:8723] CHIP:DL: Found the primary WiFi interface:wlo1
[1683890081.303627][8723:8723] CHIP:IN: UDP::Init bind&listen port=0
[1683890081.303647][8723:8723] CHIP:IN: UDP::Init bound to port=40565
[1683890081.303650][8723:8723] CHIP:IN: UDP::Init bind&listen port=0
[1683890081.303658][8723:8723] CHIP:IN: UDP::Init bound to port=54610
[1683890081.303660][8723:8723] CHIP:IN: BLEBase::Init - setting/overriding transport
[1683890081.303662][8723:8723] CHIP:IN: TransportMgr initialized
[1683890081.303671][8723:8723] CHIP:FP: Initializing FabricTable from persistent storage
[1683890081.303716][8723:8723] CHIP:TS: Last Known Good Time: 2023-03-02T09:25:05
[1683890081.303822][8723:8723] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x56DB79D6283C786D, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1683890081.304206][8723:8723] CHIP:ZCL: Using ZAP configuration...
[1683890081.305033][8723:8723] CHIP:DL: Avahi client registered
[1683890081.305255][8723:8723] CHIP:CTL: System State Initialized...
[1683890081.305276][8723:8723] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1683890081.305287][8723:8723] CHIP:CTL: Setting attestation nonce to random value
[1683890081.305290][8723:8723] CHIP:CTL: Setting CSR nonce to random value
[1683890081.305352][8723:8725] CHIP:DL: CHIP task running
[1683890081.305396][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1683890081.305452][8723:8725] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1683890081.305458][8723:8725] CHIP:CTL: Setting attestation nonce to random value
[1683890081.305462][8723:8725] CHIP:CTL: Setting CSR nonce to random value
[1683890081.308222][8723:8725] CHIP:CTL: Generating NOC
[1683890081.311221][8723:8725] CHIP:FP: Validating NOC chain
[1683890081.321172][8723:8725] CHIP:FP: NOC chain validation successful
[1683890081.321203][8723:8725] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1683890081.321209][8723:8725] CHIP:TS: Last Known Good Time: 2023-03-02T09:25:05
[1683890081.321210][8723:8725] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1683890081.321212][8723:8725] CHIP:TS: Retaining current Last Known Good Time
[1683890081.321514][8723:8725] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1683890081.321670][8723:8725] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-02T09:25:05
[1683890081.321812][8723:8725] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 56DB79D6283C786D)
[1683890081.322836][8723:8725] CHIP:CTL: Setting thread operational dataset from parameters
[1683890081.322839][8723:8725] CHIP:CTL: Setting attempt thread scan from parameters
[1683890081.322842][8723:8725] CHIP:CTL: Setting attestation nonce to random value
[1683890081.322847][8723:8725] CHIP:CTL: Setting CSR nonce to random value
[1683890081.322849][8723:8725] CHIP:CTL: Setting PASE-only commissioning from parameters
[1683890081.322851][8723:8725] CHIP:CTL: Commission called for node ID 0x0000000000000001
[1683890081.323760][8723:8724] CHIP:DL: TRACE: Bus acquired for name C-2213
[1683890081.325140][8723:8725] CHIP:DL: PlatformBlueZInit init success
[1683890081.326061][8723:8724] CHIP:BLE: BLE removing known devices.
[1683890081.326303][8723:8724] CHIP:BLE: BLE initiating scan.
[1683890081.448589][8723:8725] CHIP:DL: Long dispatch time: 126 ms, for event type 2
[1683890081.471966][8723:8724] CHIP:BLE: New device scanned: DE:61:CB:D1:FE:40
[1683890081.471989][8723:8724] CHIP:BLE: Device discriminator match. Attempting to connect.
[1683890081.489676][8723:8724] CHIP:BLE: Scan complete notification without an active scan.
[1683890081.601476][8723:8724] CHIP:DL: ConnectDevice complete
[1683890082.689389][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689400][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689403][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689405][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689407][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689409][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689412][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689413][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689416][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689418][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689420][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689422][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689424][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689426][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689430][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689432][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689434][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689436][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689439][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0001
[1683890082.689440][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689444][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689445][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689448][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689450][8723:8724] CHIP:DL: Char1 /org/bluez/hci0/dev_DE_61_CB_D1_FE_40/service0010
[1683890082.689453][8723:8724] CHIP:DL: New BLE connection 0x7f0e9004a0e0, device DE:61:CB:D1:FE:40, path /org/bluez/hci0/dev_DE_61_CB_D1_FE_40
[1683890082.689478][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1683890082.689486][8723:8725] CHIP:DIS: Closing all BLE connections
[1683890082.689501][8723:8725] CHIP:IN: BleConnectionComplete: endPoint 0x5602760d9420
[1683890082.689527][8723:8725] CHIP:IN: SecureSession[0x7f0e8800e800]: Allocated Type:1 LSID:9221
[1683890082.689533][8723:8725] CHIP:SC: Assigned local session key ID 9221
[1683890082.689556][8723:8725] CHIP:EM: <<< [E:63399i M:118094686] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1683890082.689565][8723:8725] CHIP:IN: (U) Sending msg 118094686 to IP address 'BLE'
[1683890082.689570][8723:8725] CHIP:IN: Message appended to BLE send queue
[1683890082.689573][8723:8725] CHIP:SC: Sent PBKDF param request
[1683890083.129942][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890083.220790][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1683890083.220818][8723:8725] CHIP:BLE: subscribe complete, ep = 0x5602760d9420
[1683890083.221261][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890083.221319][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890083.221348][8723:8725] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1683890083.221358][8723:8725] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1683890083.221364][8723:8725] CHIP:BLE: local and remote recv window size = 5
[1683890083.221410][8723:8725] CHIP:IN: BLE EndPoint 0x5602760d9420 Connection Complete
[1683890083.309966][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890083.312418][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890083.312488][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890083.312566][8723:8725] CHIP:EM: >>> [E:63399i M:83479088] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1683890083.312581][8723:8725] CHIP:EM: Found matching exchange: 63399i, Delegate: 0x7f0e8800ba50
[1683890083.312595][8723:8725] CHIP:SC: Received PBKDF param response
[1683890083.312615][8723:8725] CHIP:SC: Peer assigned session ID 35526
[1683890083.312626][8723:8725] CHIP:SC: Found MRP parameters in the message
[1683890083.336119][8723:8725] CHIP:EM: <<< [E:63399i M:118094687] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1683890083.336134][8723:8725] CHIP:IN: (U) Sending msg 118094687 to IP address 'BLE'
[1683890083.336150][8723:8725] CHIP:SC: Sent spake2p msg1
[1683890083.400239][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.246595][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.246677][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.246757][8723:8725] CHIP:EM: >>> [E:63399i M:83479089] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1683890085.246773][8723:8725] CHIP:EM: Found matching exchange: 63399i, Delegate: 0x7f0e8800ba50
[1683890085.246785][8723:8725] CHIP:SC: Received spake2p msg2
[1683890085.267085][8723:8725] CHIP:EM: <<< [E:63399i M:118094688] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1683890085.267104][8723:8725] CHIP:IN: (U) Sending msg 118094688 to IP address 'BLE'
[1683890085.267125][8723:8725] CHIP:SC: Sent spake2p msg3
[1683890085.334973][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.335867][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.336016][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.336086][8723:8725] CHIP:EM: >>> [E:63399i M:83479090] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1683890085.336100][8723:8725] CHIP:EM: Found matching exchange: 63399i, Delegate: 0x7f0e8800ba50
[1683890085.336157][8723:8725] CHIP:SC: SecureSession[0x7f0e8800e800]: Moving from state 'kEstablishing' --> 'kActive'
[1683890085.336163][8723:8725] CHIP:IN: SecureSession[0x7f0e8800e800]: Activated - Type:1 LSID:9221
[1683890085.336170][8723:8725] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:9221 PSID:35526!
[1683890085.336180][8723:8725] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1683890085.336186][8723:8725] CHIP:TOO: Pairing Success
[1683890085.336195][8723:8725] CHIP:TOO: PASE establishment successful
[1683890085.336203][8723:8725] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1683890085.336211][8723:8725] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1683890085.336217][8723:8725] CHIP:CTL: Sending request for commissioning information
[1683890085.336233][8723:8725] CHIP:DMG: SendReadRequest ReadClient[0x7f0e8801c4f0]: Sending Read Request
[1683890085.336297][8723:8725] CHIP:EM: <<< [E:63400i M:235529806] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1683890085.336310][8723:8725] CHIP:IN: (S) Sending msg 235529806 on secure session with LSID: 9221
[1683890085.336346][8723:8725] CHIP:DMG: MoveToState ReadClient[0x7f0e8801c4f0]: Moving to [AwaitingIn]
[1683890085.424891][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.472738][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.472825][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.560818][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.560907][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.561015][8723:8725] CHIP:EM: >>> [E:63400i M:232613890] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1683890085.561033][8723:8725] CHIP:EM: Found matching exchange: 63400i, Delegate: 0x7f0e8801c500
[1683890085.561105][8723:8725] CHIP:DMG: ReportDataMessage =
[1683890085.561115][8723:8725] CHIP:DMG: {
[1683890085.561124][8723:8725] CHIP:DMG: AttributeReportIBs =
[1683890085.561141][8723:8725] CHIP:DMG: [
[1683890085.561151][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.561168][8723:8725] CHIP:DMG: {
[1683890085.561205][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.561218][8723:8725] CHIP:DMG: {
[1683890085.561231][8723:8725] CHIP:DMG: DataVersion = 0x4c752156,
[1683890085.561242][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.561255][8723:8725] CHIP:DMG: {
[1683890085.561267][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.561280][8723:8725] CHIP:DMG: Cluster = 0x31,
[1683890085.561293][8723:8725] CHIP:DMG: Attribute = 0x0000_0003,
[1683890085.561304][8723:8725] CHIP:DMG: }
[1683890085.561318][8723:8725] CHIP:DMG:
[1683890085.561332][8723:8725] CHIP:DMG: Data = 20,
[1683890085.561344][8723:8725] CHIP:DMG: },
[1683890085.561359][8723:8725] CHIP:DMG:
[1683890085.561368][8723:8725] CHIP:DMG: },
[1683890085.561391][8723:8725] CHIP:DMG:
[1683890085.561400][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.561416][8723:8725] CHIP:DMG: {
[1683890085.561425][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.561437][8723:8725] CHIP:DMG: {
[1683890085.561448][8723:8725] CHIP:DMG: DataVersion = 0xe0a13b3e,
[1683890085.561459][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.561470][8723:8725] CHIP:DMG: {
[1683890085.561483][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.561494][8723:8725] CHIP:DMG: Cluster = 0x28,
[1683890085.561507][8723:8725] CHIP:DMG: Attribute = 0x0000_0004,
[1683890085.561518][8723:8725] CHIP:DMG: }
[1683890085.561531][8723:8725] CHIP:DMG:
[1683890085.561543][8723:8725] CHIP:DMG: Data = 32773,
[1683890085.561553][8723:8725] CHIP:DMG: },
[1683890085.561567][8723:8725] CHIP:DMG:
[1683890085.561579][8723:8725] CHIP:DMG: },
[1683890085.561594][8723:8725] CHIP:DMG:
[1683890085.561599][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.561608][8723:8725] CHIP:DMG: {
[1683890085.561612][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.561618][8723:8725] CHIP:DMG: {
[1683890085.561624][8723:8725] CHIP:DMG: DataVersion = 0xe0a13b3e,
[1683890085.561629][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.561635][8723:8725] CHIP:DMG: {
[1683890085.561641][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.561648][8723:8725] CHIP:DMG: Cluster = 0x28,
[1683890085.561654][8723:8725] CHIP:DMG: Attribute = 0x0000_0002,
[1683890085.561662][8723:8725] CHIP:DMG: }
[1683890085.561673][8723:8725] CHIP:DMG:
[1683890085.561684][8723:8725] CHIP:DMG: Data = 65521,
[1683890085.561694][8723:8725] CHIP:DMG: },
[1683890085.561706][8723:8725] CHIP:DMG:
[1683890085.561716][8723:8725] CHIP:DMG: },
[1683890085.561737][8723:8725] CHIP:DMG:
[1683890085.561749][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.561770][8723:8725] CHIP:DMG: {
[1683890085.561779][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.561788][8723:8725] CHIP:DMG: {
[1683890085.561799][8723:8725] CHIP:DMG: DataVersion = 0x52001294,
[1683890085.561809][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.561820][8723:8725] CHIP:DMG: {
[1683890085.561832][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.561844][8723:8725] CHIP:DMG: Cluster = 0x30,
[1683890085.561858][8723:8725] CHIP:DMG: Attribute = 0x0000_0003,
[1683890085.561872][8723:8725] CHIP:DMG: }
[1683890085.561888][8723:8725] CHIP:DMG:
[1683890085.561900][8723:8725] CHIP:DMG: Data = 0,
[1683890085.561910][8723:8725] CHIP:DMG: },
[1683890085.561928][8723:8725] CHIP:DMG:
[1683890085.561938][8723:8725] CHIP:DMG: },
[1683890085.561959][8723:8725] CHIP:DMG:
[1683890085.561968][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.561980][8723:8725] CHIP:DMG: {
[1683890085.561985][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.561991][8723:8725] CHIP:DMG: {
[1683890085.561997][8723:8725] CHIP:DMG: DataVersion = 0x52001294,
[1683890085.562002][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.562008][8723:8725] CHIP:DMG: {
[1683890085.562014][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.562020][8723:8725] CHIP:DMG: Cluster = 0x30,
[1683890085.562027][8723:8725] CHIP:DMG: Attribute = 0x0000_0002,
[1683890085.562033][8723:8725] CHIP:DMG: }
[1683890085.562044][8723:8725] CHIP:DMG:
[1683890085.562056][8723:8725] CHIP:DMG: Data = 0,
[1683890085.562066][8723:8725] CHIP:DMG: },
[1683890085.562081][8723:8725] CHIP:DMG:
[1683890085.562091][8723:8725] CHIP:DMG: },
[1683890085.562116][8723:8725] CHIP:DMG:
[1683890085.562126][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.562144][8723:8725] CHIP:DMG: {
[1683890085.562154][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.562166][8723:8725] CHIP:DMG: {
[1683890085.562181][8723:8725] CHIP:DMG: DataVersion = 0x52001294,
[1683890085.562192][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.562203][8723:8725] CHIP:DMG: {
[1683890085.562215][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.562226][8723:8725] CHIP:DMG: Cluster = 0x30,
[1683890085.562239][8723:8725] CHIP:DMG: Attribute = 0x0000_0001,
[1683890085.562250][8723:8725] CHIP:DMG: }
[1683890085.562264][8723:8725] CHIP:DMG:
[1683890085.562275][8723:8725] CHIP:DMG: Data =
[1683890085.562287][8723:8725] CHIP:DMG: {
[1683890085.562301][8723:8725] CHIP:DMG: 0x0 = 60,
[1683890085.562314][8723:8725] CHIP:DMG: 0x1 = 900,
[1683890085.562326][8723:8725] CHIP:DMG: },
[1683890085.562337][8723:8725] CHIP:DMG: },
[1683890085.562353][8723:8725] CHIP:DMG:
[1683890085.562362][8723:8725] CHIP:DMG: },
[1683890085.562386][8723:8725] CHIP:DMG:
[1683890085.562395][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.562411][8723:8725] CHIP:DMG: {
[1683890085.562420][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.562431][8723:8725] CHIP:DMG: {
[1683890085.562444][8723:8725] CHIP:DMG: DataVersion = 0x52001294,
[1683890085.562455][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.562466][8723:8725] CHIP:DMG: {
[1683890085.562478][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.562490][8723:8725] CHIP:DMG: Cluster = 0x30,
[1683890085.562502][8723:8725] CHIP:DMG: Attribute = 0x0000_0000,
[1683890085.562514][8723:8725] CHIP:DMG: }
[1683890085.562527][8723:8725] CHIP:DMG:
[1683890085.562540][8723:8725] CHIP:DMG: Data = 0,
[1683890085.562550][8723:8725] CHIP:DMG: },
[1683890085.562565][8723:8725] CHIP:DMG:
[1683890085.562575][8723:8725] CHIP:DMG: },
[1683890085.562595][8723:8725] CHIP:DMG:
[1683890085.562605][8723:8725] CHIP:DMG: AttributeReportIB =
[1683890085.562621][8723:8725] CHIP:DMG: {
[1683890085.562631][8723:8725] CHIP:DMG: AttributeDataIB =
[1683890085.562642][8723:8725] CHIP:DMG: {
[1683890085.562654][8723:8725] CHIP:DMG: DataVersion = 0x4c752156,
[1683890085.562664][8723:8725] CHIP:DMG: AttributePathIB =
[1683890085.562675][8723:8725] CHIP:DMG: {
[1683890085.562693][8723:8725] CHIP:DMG: Endpoint = 0x0,
[1683890085.562706][8723:8725] CHIP:DMG: Cluster = 0x31,
[1683890085.562719][8723:8725] CHIP:DMG: Attribute = 0x0000_FFFC,
[1683890085.562730][8723:8725] CHIP:DMG: }
[1683890085.562745][8723:8725] CHIP:DMG:
[1683890085.562757][8723:8725] CHIP:DMG: Data = 2,
[1683890085.562767][8723:8725] CHIP:DMG: },
[1683890085.562787][8723:8725] CHIP:DMG:
[1683890085.562796][8723:8725] CHIP:DMG: },
[1683890085.562811][8723:8725] CHIP:DMG:
[1683890085.562820][8723:8725] CHIP:DMG: ],
[1683890085.562873][8723:8725] CHIP:DMG:
[1683890085.562882][8723:8725] CHIP:DMG: SuppressResponse = true,
[1683890085.562892][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890085.562900][8723:8725] CHIP:DMG: }
[1683890085.563375][8723:8725] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1683890085.563416][8723:8725] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1683890085.563430][8723:8725] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1683890085.563444][8723:8725] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1683890085.563453][8723:8725] CHIP:CTL: Arming failsafe (60 seconds)
[1683890085.563490][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890085.563502][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890085.563549][8723:8725] CHIP:EM: <<< [E:63401i M:235529807] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890085.563565][8723:8725] CHIP:IN: (S) Sending msg 235529807 on secure session with LSID: 9221
[1683890085.563609][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890085.650091][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.651505][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.651569][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.651674][8723:8725] CHIP:EM: >>> [E:63401i M:232613891] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890085.651691][8723:8725] CHIP:EM: Found matching exchange: 63401i, Delegate: 0x7f0e9004bca8
[1683890085.651706][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890085.651737][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890085.651747][8723:8725] CHIP:DMG: {
[1683890085.651757][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890085.651767][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890085.651783][8723:8725] CHIP:DMG: [
[1683890085.651791][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890085.651806][8723:8725] CHIP:DMG: {
[1683890085.651814][8723:8725] CHIP:DMG: CommandDataIB =
[1683890085.651824][8723:8725] CHIP:DMG: {
[1683890085.651831][8723:8725] CHIP:DMG: CommandPathIB =
[1683890085.651841][8723:8725] CHIP:DMG: {
[1683890085.651851][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890085.651861][8723:8725] CHIP:DMG: ClusterId = 0x30,
[1683890085.651873][8723:8725] CHIP:DMG: CommandId = 0x1,
[1683890085.651886][8723:8725] CHIP:DMG: },
[1683890085.651899][8723:8725] CHIP:DMG:
[1683890085.651910][8723:8725] CHIP:DMG: CommandFields =
[1683890085.651921][8723:8725] CHIP:DMG: {
[1683890085.651934][8723:8725] CHIP:DMG: 0x0 = 0,
[1683890085.651948][8723:8725] CHIP:DMG: 0x1 = "" (0 chars),
[1683890085.651961][8723:8725] CHIP:DMG: },
[1683890085.651974][8723:8725] CHIP:DMG: },
[1683890085.651989][8723:8725] CHIP:DMG:
[1683890085.651998][8723:8725] CHIP:DMG: },
[1683890085.652014][8723:8725] CHIP:DMG:
[1683890085.652022][8723:8725] CHIP:DMG: ],
[1683890085.652039][8723:8725] CHIP:DMG:
[1683890085.652047][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890085.652055][8723:8725] CHIP:DMG: },
[1683890085.652105][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1683890085.652125][8723:8725] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1683890085.652141][8723:8725] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1683890085.652150][8723:8725] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1683890085.652162][8723:8725] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1683890085.652170][8723:8725] CHIP:CTL: Setting Regulatory Config
[1683890085.652179][8723:8725] CHIP:CTL: Device does not support configurable regulatory location
[1683890085.652216][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890085.652231][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890085.652272][8723:8725] CHIP:EM: <<< [E:63402i M:235529808] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890085.652289][8723:8725] CHIP:IN: (S) Sending msg 235529808 on secure session with LSID: 9221
[1683890085.652334][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890085.652370][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890085.740185][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.741374][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.741460][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.741549][8723:8725] CHIP:EM: >>> [E:63402i M:232613892] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890085.741563][8723:8725] CHIP:EM: Found matching exchange: 63402i, Delegate: 0x7f0e88008d78
[1683890085.741574][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890085.741597][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890085.741602][8723:8725] CHIP:DMG: {
[1683890085.741607][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890085.741622][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890085.741640][8723:8725] CHIP:DMG: [
[1683890085.741647][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890085.741663][8723:8725] CHIP:DMG: {
[1683890085.741671][8723:8725] CHIP:DMG: CommandDataIB =
[1683890085.741682][8723:8725] CHIP:DMG: {
[1683890085.741690][8723:8725] CHIP:DMG: CommandPathIB =
[1683890085.741701][8723:8725] CHIP:DMG: {
[1683890085.741714][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890085.741725][8723:8725] CHIP:DMG: ClusterId = 0x30,
[1683890085.741739][8723:8725] CHIP:DMG: CommandId = 0x3,
[1683890085.741750][8723:8725] CHIP:DMG: },
[1683890085.741762][8723:8725] CHIP:DMG:
[1683890085.741771][8723:8725] CHIP:DMG: CommandFields =
[1683890085.741784][8723:8725] CHIP:DMG: {
[1683890085.741795][8723:8725] CHIP:DMG: 0x0 = 0,
[1683890085.741809][8723:8725] CHIP:DMG: 0x1 = "" (0 chars),
[1683890085.741820][8723:8725] CHIP:DMG: },
[1683890085.741830][8723:8725] CHIP:DMG: },
[1683890085.741847][8723:8725] CHIP:DMG:
[1683890085.741854][8723:8725] CHIP:DMG: },
[1683890085.741869][8723:8725] CHIP:DMG:
[1683890085.741876][8723:8725] CHIP:DMG: ],
[1683890085.741893][8723:8725] CHIP:DMG:
[1683890085.741900][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890085.741908][8723:8725] CHIP:DMG: },
[1683890085.741943][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1683890085.741978][8723:8725] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1683890085.741991][8723:8725] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1683890085.741999][8723:8725] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1683890085.742011][8723:8725] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1683890085.742018][8723:8725] CHIP:CTL: Sending request for PAI certificate
[1683890085.742025][8723:8725] CHIP:CTL: Sending Certificate Chain request to 0x7f0e8800ba00 device
[1683890085.742055][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890085.742066][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890085.742103][8723:8725] CHIP:EM: <<< [E:63403i M:235529809] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890085.742117][8723:8725] CHIP:IN: (S) Sending msg 235529809 on secure session with LSID: 9221
[1683890085.742154][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890085.742180][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890085.829794][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890085.832724][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.832791][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890085.922821][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890085.922915][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.010903][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.011039][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.011131][8723:8725] CHIP:EM: >>> [E:63403i M:232613893] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890086.011147][8723:8725] CHIP:EM: Found matching exchange: 63403i, Delegate: 0x7f0e9004bca8
[1683890086.011165][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890086.011191][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890086.011198][8723:8725] CHIP:DMG: {
[1683890086.011204][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890086.011214][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890086.011229][8723:8725] CHIP:DMG: [
[1683890086.011236][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890086.011248][8723:8725] CHIP:DMG: {
[1683890086.011255][8723:8725] CHIP:DMG: CommandDataIB =
[1683890086.011265][8723:8725] CHIP:DMG: {
[1683890086.011272][8723:8725] CHIP:DMG: CommandPathIB =
[1683890086.011282][8723:8725] CHIP:DMG: {
[1683890086.011291][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890086.011300][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890086.011309][8723:8725] CHIP:DMG: CommandId = 0x3,
[1683890086.011317][8723:8725] CHIP:DMG: },
[1683890086.011327][8723:8725] CHIP:DMG:
[1683890086.011335][8723:8725] CHIP:DMG: CommandFields =
[1683890086.011343][8723:8725] CHIP:DMG: {
[1683890086.011353][8723:8725] CHIP:DMG: 0x0 = [
[1683890086.011415][8723:8725] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x
[1683890086.011449][8723:8725] CHIP:DMG: ] (463 bytes)
[1683890086.011459][8723:8725] CHIP:DMG: },
[1683890086.011466][8723:8725] CHIP:DMG: },
[1683890086.011478][8723:8725] CHIP:DMG:
[1683890086.011485][8723:8725] CHIP:DMG: },
[1683890086.011495][8723:8725] CHIP:DMG:
[1683890086.011502][8723:8725] CHIP:DMG: ],
[1683890086.011515][8723:8725] CHIP:DMG:
[1683890086.011522][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890086.011529][8723:8725] CHIP:DMG: },
[1683890086.011558][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1683890086.011573][8723:8725] CHIP:CTL: Received certificate chain from the device
[1683890086.011586][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1683890086.011597][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1683890086.011607][8723:8725] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1683890086.011613][8723:8725] CHIP:CTL: Sending request for DAC certificate
[1683890086.011619][8723:8725] CHIP:CTL: Sending Certificate Chain request to 0x7f0e8800ba00 device
[1683890086.011648][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890086.011658][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890086.011695][8723:8725] CHIP:EM: <<< [E:63404i M:235529810] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890086.011709][8723:8725] CHIP:IN: (S) Sending msg 235529810 on secure session with LSID: 9221
[1683890086.011747][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890086.011771][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890086.100140][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890086.102756][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.102836][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.192792][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.192874][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.281368][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.281448][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.281541][8723:8725] CHIP:EM: >>> [E:63404i M:232613894] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890086.281556][8723:8725] CHIP:EM: Found matching exchange: 63404i, Delegate: 0x7f0e9004bf98
[1683890086.281571][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890086.281594][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890086.281599][8723:8725] CHIP:DMG: {
[1683890086.281605][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890086.281612][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890086.281622][8723:8725] CHIP:DMG: [
[1683890086.281627][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890086.281639][8723:8725] CHIP:DMG: {
[1683890086.281646][8723:8725] CHIP:DMG: CommandDataIB =
[1683890086.281656][8723:8725] CHIP:DMG: {
[1683890086.281663][8723:8725] CHIP:DMG: CommandPathIB =
[1683890086.281670][8723:8725] CHIP:DMG: {
[1683890086.281678][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890086.281688][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890086.281700][8723:8725] CHIP:DMG: CommandId = 0x3,
[1683890086.281707][8723:8725] CHIP:DMG: },
[1683890086.281722][8723:8725] CHIP:DMG:
[1683890086.281729][8723:8725] CHIP:DMG: CommandFields =
[1683890086.281736][8723:8725] CHIP:DMG: {
[1683890086.281743][8723:8725] CHIP:DMG: 0x0 = [
[1683890086.281806][8723:8725] CHIP:DMG: 0x30, 0x82, 0x01, 0xe8, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x6f, 0xdc, 0xb6, 0xed, 0x06, 0xf3, 0x58, 0xf9, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x35, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x35, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x7e, 0xf2, 0xf1, 0x08, 0x2b, 0x2a, 0x56, 0x4a, 0x05, 0x44, 0xc0, 0xa6, 0x13, 0xd2, 0x1b, 0x15, 0x75, 0x00, 0x55, 0x2d, 0x03, 0x5f, 0x23, 0x02, 0x25, 0x2f, 0xce, 0xe8, 0x1d, 0x6e, 0xc6, 0x74, 0x17, 0x34, 0x18, 0xa9, 0x4a, 0x88, 0xdb, 0x
[1683890086.281839][8723:8725] CHIP:DMG: ] (492 bytes)
[1683890086.281848][8723:8725] CHIP:DMG: },
[1683890086.281856][8723:8725] CHIP:DMG: },
[1683890086.281869][8723:8725] CHIP:DMG:
[1683890086.281878][8723:8725] CHIP:DMG: },
[1683890086.281889][8723:8725] CHIP:DMG:
[1683890086.281896][8723:8725] CHIP:DMG: ],
[1683890086.281909][8723:8725] CHIP:DMG:
[1683890086.281916][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890086.281923][8723:8725] CHIP:DMG: },
[1683890086.281953][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1683890086.281967][8723:8725] CHIP:CTL: Received certificate chain from the device
[1683890086.281980][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1683890086.281991][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1683890086.282001][8723:8725] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1683890086.282008][8723:8725] CHIP:CTL: Sending Attestation Request to the device.
[1683890086.282014][8723:8725] CHIP:CTL: Sending Attestation request to 0x7f0e8800ba00 device
[1683890086.282043][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890086.282054][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890086.282089][8723:8725] CHIP:EM: <<< [E:63405i M:235529811] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890086.282102][8723:8725] CHIP:IN: (S) Sending msg 235529811 on secure session with LSID: 9221
[1683890086.282139][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890086.282149][8723:8725] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1683890086.282168][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890086.369913][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890086.417383][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.417471][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.507824][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.507978][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.597672][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.597772][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890086.597871][8723:8725] CHIP:EM: >>> [E:63405i M:232613895] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890086.597886][8723:8725] CHIP:EM: Found matching exchange: 63405i, Delegate: 0x7f0e9004c4b8
[1683890086.597901][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890086.597925][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890086.597932][8723:8725] CHIP:DMG: {
[1683890086.597938][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890086.597943][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890086.597954][8723:8725] CHIP:DMG: [
[1683890086.597959][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890086.597977][8723:8725] CHIP:DMG: {
[1683890086.597987][8723:8725] CHIP:DMG: CommandDataIB =
[1683890086.597999][8723:8725] CHIP:DMG: {
[1683890086.598008][8723:8725] CHIP:DMG: CommandPathIB =
[1683890086.598021][8723:8725] CHIP:DMG: {
[1683890086.598033][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890086.598046][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890086.598059][8723:8725] CHIP:DMG: CommandId = 0x1,
[1683890086.598070][8723:8725] CHIP:DMG: },
[1683890086.598085][8723:8725] CHIP:DMG:
[1683890086.598096][8723:8725] CHIP:DMG: CommandFields =
[1683890086.598109][8723:8725] CHIP:DMG: {
[1683890086.598124][8723:8725] CHIP:DMG: 0x0 = [
[1683890086.598196][8723:8725] CHIP:DMG: 0x15, 0x31, 0x01, 0x1b, 0x02, 0x30, 0x82, 0x02, 0x17, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x08, 0x30, 0x82, 0x02, 0x04, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x
[1683890086.598226][8723:8725] CHIP:DMG: ] (583 bytes)
[1683890086.598232][8723:8725] CHIP:DMG: 0x1 = [
[1683890086.598249][8723:8725] CHIP:DMG: 0x52, 0x10, 0x6a, 0x6b, 0xc4, 0x55, 0x57, 0xc4, 0xc6, 0xda, 0x3e, 0xb8, 0xbc, 0xbb, 0xfd, 0x28, 0x50, 0x95, 0xf2, 0x70, 0xc3, 0x99, 0xd5, 0x11, 0xd2, 0x87, 0xbe, 0xca, 0x6d, 0x51, 0x70, 0xed, 0x9a, 0xc2, 0xa7, 0x67, 0xb1, 0x0b, 0x24, 0xcb, 0xec, 0x5f, 0x2e, 0x6f, 0x0c, 0x7b, 0xee, 0x2f, 0xf0, 0x79, 0x88, 0xc6, 0xaa, 0x3e, 0xdb, 0xfe, 0x2a, 0x75, 0xe2, 0x30, 0x13, 0x66, 0x9b, 0x53,
[1683890086.598271][8723:8725] CHIP:DMG: ] (64 bytes)
[1683890086.598280][8723:8725] CHIP:DMG: },
[1683890086.598287][8723:8725] CHIP:DMG: },
[1683890086.598302][8723:8725] CHIP:DMG:
[1683890086.598309][8723:8725] CHIP:DMG: },
[1683890086.598318][8723:8725] CHIP:DMG:
[1683890086.598324][8723:8725] CHIP:DMG: ],
[1683890086.598335][8723:8725] CHIP:DMG:
[1683890086.598342][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890086.598348][8723:8725] CHIP:DMG: },
[1683890086.598379][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1683890086.598394][8723:8725] CHIP:CTL: Received Attestation Information from the device
[1683890086.598408][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1683890086.598417][8723:8725] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583
[1683890086.598429][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1683890086.598440][8723:8725] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1683890086.598446][8723:8725] CHIP:CTL: Verifying attestation
[1683890086.614561][8723:8725] CHIP:CR: mbedTLS error: ERROR - Generic error
[1683890086.631029][8723:8725] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1683890086.631039][8723:8725] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1683890086.631042][8723:8725] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1683890086.631047][8723:8725] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1683890086.631050][8723:8725] CHIP:CTL: Sending CSR request to 0x7f0e8800ba00 device
[1683890086.631070][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890086.631075][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890086.631098][8723:8725] CHIP:EM: <<< [E:63406i M:235529812] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890086.631104][8723:8725] CHIP:IN: (S) Sending msg 235529812 on secure session with LSID: 9221
[1683890086.631124][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890086.631127][8723:8725] CHIP:CTL: Sent CSR request, waiting for the CSR
[1683890086.631137][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890086.684969][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890086.912143][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890086.912187][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890087.001883][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890087.002030][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890087.002117][8723:8725] CHIP:EM: >>> [E:63406i M:232613896] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890087.002133][8723:8725] CHIP:EM: Found matching exchange: 63406i, Delegate: 0x7f0e9004c748
[1683890087.002148][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890087.002173][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890087.002179][8723:8725] CHIP:DMG: {
[1683890087.002185][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890087.002190][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890087.002201][8723:8725] CHIP:DMG: [
[1683890087.002206][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890087.002224][8723:8725] CHIP:DMG: {
[1683890087.002234][8723:8725] CHIP:DMG: CommandDataIB =
[1683890087.002247][8723:8725] CHIP:DMG: {
[1683890087.002257][8723:8725] CHIP:DMG: CommandPathIB =
[1683890087.002269][8723:8725] CHIP:DMG: {
[1683890087.002283][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890087.002295][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890087.002307][8723:8725] CHIP:DMG: CommandId = 0x5,
[1683890087.002317][8723:8725] CHIP:DMG: },
[1683890087.002331][8723:8725] CHIP:DMG:
[1683890087.002341][8723:8725] CHIP:DMG: CommandFields =
[1683890087.002355][8723:8725] CHIP:DMG: {
[1683890087.002368][8723:8725] CHIP:DMG: 0x0 = [
[1683890087.002428][8723:8725] CHIP:DMG: 0x15, 0x30, 0x01, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x77, 0xbd, 0x14, 0x1c, 0x35, 0x58, 0xf0, 0x9c, 0xcf, 0x6f, 0xcd, 0xbb, 0xe9, 0xbd, 0xd1, 0x08, 0xce, 0xb1, 0x45, 0xf1, 0x4d, 0x17, 0xf0, 0xd2, 0x6d, 0x59, 0x56, 0x3d, 0x63, 0x34, 0x94, 0x29, 0x86, 0x20, 0xb2, 0x9b, 0xb1, 0xe6, 0x45, 0xec, 0x25, 0x08, 0x3e, 0x5b, 0x34, 0x55, 0x5d, 0xda, 0xff, 0xc4, 0x7b, 0x03, 0x6d, 0x5a, 0x0d, 0x1b, 0x88, 0x37, 0xda, 0x80, 0xe6, 0x6b, 0x49, 0xa2, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x48, 0x00, 0x30, 0x45, 0x02, 0x20, 0x6c, 0x54, 0x0f, 0x7f, 0x74, 0xd7, 0x57, 0x30, 0xdc, 0xbd, 0x35, 0x51, 0x54, 0x89, 0xbe, 0x83, 0x4e, 0x58, 0x5a, 0xf1, 0x66, 0xfc, 0xcb, 0x43, 0xf0, 0x2a, 0xf5, 0xb6, 0xb1, 0x14, 0x2b, 0xdb, 0x02, 0x21, 0x00, 0x9c, 0x47, 0x11, 0xec, 0xc5, 0x4c, 0xa6, 0x7f, 0x92, 0x44, 0xcf, 0x08, 0xe4, 0xd6, 0xd6, 0x5e, 0x28, 0xfd, 0xaf, 0xa0, 0xdb, 0x65, 0x8a, 0xa4, 0x72, 0xca, 0xe5, 0xc7, 0x42, 0x52, 0x22, 0x4c, 0x30, 0x02, 0x20, 0x8c, 0xf3, 0x80, 0x37, 0xd5, 0xd8, 0xf3, 0x9c, 0xb1, 0xbe, 0xe1, 0xee, 0xca, 0x88, 0x44, 0xc9, 0x85, 0x57, 0x39, 0x2f, 0xc0, 0xba, 0xa3, 0x6a, 0x68, 0xca, 0x2f, 0x52, 0x33, 0xcc, 0x12, 0x4c, 0x18,
[1683890087.002469][8723:8725] CHIP:DMG: ] (245 bytes)
[1683890087.002482][8723:8725] CHIP:DMG: 0x1 = [
[1683890087.002508][8723:8725] CHIP:DMG: 0xc0, 0xcf, 0xdc, 0x24, 0xe5, 0x4e, 0xde, 0xd3, 0x65, 0xa0, 0x01, 0x18, 0xb8, 0x2b, 0x38, 0xc5, 0x0f, 0x47, 0xfb, 0xc7, 0xde, 0xd1, 0x69, 0xa7, 0x3f, 0xe8, 0x49, 0xd6, 0x80, 0x30, 0x5b, 0x7c, 0x9c, 0x40, 0x00, 0x10, 0xd8, 0xc6, 0xa3, 0x17, 0x82, 0x84, 0x49, 0x27, 0x61, 0xe2, 0xf6, 0xf8, 0x41, 0x74, 0x5c, 0x47, 0x96, 0xaa, 0xa1, 0x8f, 0xd5, 0xf1, 0x3d, 0x5f, 0xba, 0xc6, 0x15, 0x83,
[1683890087.002525][8723:8725] CHIP:DMG: ] (64 bytes)
[1683890087.002536][8723:8725] CHIP:DMG: },
[1683890087.002547][8723:8725] CHIP:DMG: },
[1683890087.002565][8723:8725] CHIP:DMG:
[1683890087.002574][8723:8725] CHIP:DMG: },
[1683890087.002592][8723:8725] CHIP:DMG:
[1683890087.002600][8723:8725] CHIP:DMG: ],
[1683890087.002620][8723:8725] CHIP:DMG:
[1683890087.002628][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890087.002640][8723:8725] CHIP:DMG: },
[1683890087.002679][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1683890087.002698][8723:8725] CHIP:CTL: Received certificate signing request from the device
[1683890087.002714][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1683890087.002724][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1683890087.002739][8723:8725] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1683890087.010620][8723:8725] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1683890087.010623][8723:8725] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1683890087.010628][8723:8725] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1683890087.010645][8723:8725] CHIP:CTL: Getting certificate chain for the device from the issuer
[1683890087.010657][8723:8725] CHIP:CTL: Verifying Certificate Signing Request
[1683890087.015218][8723:8725] CHIP:CTL: Generating NOC
[1683890087.017513][8723:8725] CHIP:CTL: Providing certificate chain to the commissioner
[1683890087.017524][8723:8725] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1683890087.017529][8723:8725] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1683890087.017571][8723:8725] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1683890087.017575][8723:8725] CHIP:CTL: Sending root certificate to the device
[1683890087.017593][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890087.017597][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890087.017620][8723:8725] CHIP:EM: <<< [E:63407i M:235529813] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890087.017626][8723:8725] CHIP:IN: (S) Sending msg 235529813 on secure session with LSID: 9221
[1683890087.017650][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890087.017653][8723:8725] CHIP:CTL: Sent root certificate to the device
[1683890087.017703][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890087.090104][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.180021][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.271078][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890087.271216][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890087.271331][8723:8725] CHIP:EM: >>> [E:63407i M:232613897] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890087.271349][8723:8725] CHIP:EM: Found matching exchange: 63407i, Delegate: 0x7f0e9004c4b8
[1683890087.271365][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890087.271396][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890087.271404][8723:8725] CHIP:DMG: {
[1683890087.271413][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890087.271422][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890087.271437][8723:8725] CHIP:DMG: [
[1683890087.271444][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890087.271469][8723:8725] CHIP:DMG: {
[1683890087.271477][8723:8725] CHIP:DMG: CommandStatusIB =
[1683890087.271491][8723:8725] CHIP:DMG: {
[1683890087.271501][8723:8725] CHIP:DMG: CommandPathIB =
[1683890087.271515][8723:8725] CHIP:DMG: {
[1683890087.271527][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890087.271539][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890087.271551][8723:8725] CHIP:DMG: CommandId = 0xb,
[1683890087.271562][8723:8725] CHIP:DMG: },
[1683890087.271579][8723:8725] CHIP:DMG:
[1683890087.271587][8723:8725] CHIP:DMG: StatusIB =
[1683890087.271599][8723:8725] CHIP:DMG: {
[1683890087.271610][8723:8725] CHIP:DMG: status = 0x00 (SUCCESS),
[1683890087.271621][8723:8725] CHIP:DMG: },
[1683890087.271633][8723:8725] CHIP:DMG:
[1683890087.271642][8723:8725] CHIP:DMG: },
[1683890087.271658][8723:8725] CHIP:DMG:
[1683890087.271667][8723:8725] CHIP:DMG: },
[1683890087.271682][8723:8725] CHIP:DMG:
[1683890087.271689][8723:8725] CHIP:DMG: ],
[1683890087.271704][8723:8725] CHIP:DMG:
[1683890087.271712][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890087.271721][8723:8725] CHIP:DMG: },
[1683890087.271752][8723:8725] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1683890087.271764][8723:8725] CHIP:CTL: Device confirmed that it has received the root certificate
[1683890087.271781][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1683890087.271790][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1683890087.271798][8723:8725] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1683890087.271837][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890087.271851][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890087.271891][8723:8725] CHIP:EM: <<< [E:63408i M:235529814] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890087.271902][8723:8725] CHIP:IN: (S) Sending msg 235529814 on secure session with LSID: 9221
[1683890087.271942][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890087.271953][8723:8725] CHIP:CTL: Sent operational certificate to the device
[1683890087.271980][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890087.359800][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.450107][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.539882][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.766041][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890087.766162][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890087.766253][8723:8725] CHIP:EM: >>> [E:63408i M:232613898] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890087.766268][8723:8725] CHIP:EM: Found matching exchange: 63408i, Delegate: 0x7f0e9004c748
[1683890087.766279][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890087.766301][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890087.766306][8723:8725] CHIP:DMG: {
[1683890087.766312][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890087.766316][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890087.766326][8723:8725] CHIP:DMG: [
[1683890087.766330][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890087.766340][8723:8725] CHIP:DMG: {
[1683890087.766345][8723:8725] CHIP:DMG: CommandDataIB =
[1683890087.766351][8723:8725] CHIP:DMG: {
[1683890087.766356][8723:8725] CHIP:DMG: CommandPathIB =
[1683890087.766362][8723:8725] CHIP:DMG: {
[1683890087.766372][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890087.766380][8723:8725] CHIP:DMG: ClusterId = 0x3e,
[1683890087.766387][8723:8725] CHIP:DMG: CommandId = 0x8,
[1683890087.766394][8723:8725] CHIP:DMG: },
[1683890087.766405][8723:8725] CHIP:DMG:
[1683890087.766412][8723:8725] CHIP:DMG: CommandFields =
[1683890087.766419][8723:8725] CHIP:DMG: {
[1683890087.766427][8723:8725] CHIP:DMG: 0x0 = 0,
[1683890087.766437][8723:8725] CHIP:DMG: 0x1 = 1,
[1683890087.766445][8723:8725] CHIP:DMG: },
[1683890087.766454][8723:8725] CHIP:DMG: },
[1683890087.766465][8723:8725] CHIP:DMG:
[1683890087.766471][8723:8725] CHIP:DMG: },
[1683890087.766483][8723:8725] CHIP:DMG:
[1683890087.766488][8723:8725] CHIP:DMG: ],
[1683890087.766497][8723:8725] CHIP:DMG:
[1683890087.766503][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890087.766509][8723:8725] CHIP:DMG: },
[1683890087.766536][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1683890087.766552][8723:8725] CHIP:CTL: Device returned status 0 on receiving the NOC
[1683890087.766559][8723:8725] CHIP:CTL: Operational credentials provisioned on device 0x7f0e8800ba00
[1683890087.766565][8723:8725] CHIP:TOO: Secure Pairing Success
[1683890087.766570][8723:8725] CHIP:TOO: CASE establishment successful
[1683890087.766582][8723:8725] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1683890087.766590][8723:8725] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1683890087.766597][8723:8725] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
[1683890087.766606][8723:8725] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup'
[1683890087.766636][8723:8725] CHIP:DMG: ICR moving to [AddingComm]
[1683890087.766646][8723:8725] CHIP:DMG: ICR moving to [AddedComma]
[1683890087.766682][8723:8725] CHIP:EM: <<< [E:63409i M:235529815] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1683890087.766694][8723:8725] CHIP:IN: (S) Sending msg 235529815 on secure session with LSID: 9221
[1683890087.766729][8723:8725] CHIP:DMG: ICR moving to [CommandSen]
[1683890087.766754][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890087.855082][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.944838][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1683890087.946247][8723:8724] CHIP:DL: Indication received, conn = 0x7f0e9004a0e0
[1683890087.946360][8723:8725] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1683890087.946465][8723:8725] CHIP:EM: >>> [E:63409i M:232613899] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1683890087.946483][8723:8725] CHIP:EM: Found matching exchange: 63409i, Delegate: 0x7f0e9004c4b8
[1683890087.946499][8723:8725] CHIP:DMG: ICR moving to [ResponseRe]
[1683890087.946526][8723:8725] CHIP:DMG: InvokeResponseMessage =
[1683890087.946534][8723:8725] CHIP:DMG: {
[1683890087.946544][8723:8725] CHIP:DMG: suppressResponse = false,
[1683890087.946553][8723:8725] CHIP:DMG: InvokeResponseIBs =
[1683890087.946570][8723:8725] CHIP:DMG: [
[1683890087.946577][8723:8725] CHIP:DMG: InvokeResponseIB =
[1683890087.946593][8723:8725] CHIP:DMG: {
[1683890087.946601][8723:8725] CHIP:DMG: CommandDataIB =
[1683890087.946613][8723:8725] CHIP:DMG: {
[1683890087.946621][8723:8725] CHIP:DMG: CommandPathIB =
[1683890087.946634][8723:8725] CHIP:DMG: {
[1683890087.946645][8723:8725] CHIP:DMG: EndpointId = 0x0,
[1683890087.946656][8723:8725] CHIP:DMG: ClusterId = 0x31,
[1683890087.946667][8723:8725] CHIP:DMG: CommandId = 0x5,
[1683890087.946677][8723:8725] CHIP:DMG: },
[1683890087.946690][8723:8725] CHIP:DMG:
[1683890087.946699][8723:8725] CHIP:DMG: CommandFields =
[1683890087.946710][8723:8725] CHIP:DMG: {
[1683890087.946723][8723:8725] CHIP:DMG: 0x0 = 1,
[1683890087.946733][8723:8725] CHIP:DMG: },
[1683890087.946742][8723:8725] CHIP:DMG: },
[1683890087.946757][8723:8725] CHIP:DMG:
[1683890087.946764][8723:8725] CHIP:DMG: },
[1683890087.946779][8723:8725] CHIP:DMG:
[1683890087.946786][8723:8725] CHIP:DMG: ],
[1683890087.946802][8723:8725] CHIP:DMG:
[1683890087.946810][8723:8725] CHIP:DMG: InteractionModelRevision = 1
[1683890087.946818][8723:8725] CHIP:DMG: },
[1683890087.946850][8723:8725] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1683890087.946882][8723:8725] CHIP:CTL: Received NetworkConfig response, networkingStatus=1
[1683890087.946902][8723:8725] CHIP:CTL: Error on commissioning step 'ThreadNetworkSetup': '../../src/controller/CHIPDeviceController.cpp:2050: CHIP Error 0x000000AC: Internal error'
[1683890087.946910][8723:8725] CHIP:CTL: Failed to perform commissioning step 15
[1683890087.946924][8723:8725] CHIP:CTL: Going from commissioning step 'ThreadNetworkSetup' with lastErr = '../../src/controller/CHIPDeviceController.cpp:2050: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1683890087.946939][8723:8725] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:2050: CHIP Error 0x000000AC: Internal error'
[1683890087.946948][8723:8725] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1683890087.946963][8723:8725] CHIP:TOO: Device commissioning Failure: ../../src/controller/CHIPDeviceController.cpp:2050: CHIP Error 0x000000AC: Internal error
[1683890087.946986][8723:8725] CHIP:DMG: ICR moving to [AwaitingDe]
[1683890087.947190][8723:8723] CHIP:CTL: Shutting down the commissioner
[1683890087.947208][8723:8723] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1683890087.947218][8723:8723] CHIP:DIS: Closing all BLE connections
[1683890087.947226][8723:8723] CHIP:IN: Clearing BLE pending packets.
[1683890087.947253][8723:8723] CHIP:BLE: Auto-closing end point's BLE connection.
[1683890087.947259][8723:8723] CHIP:DL: Closing BLE GATT connection (con 0x7f0e9004a0e0)
[1683890087.947274][8723:8723] CHIP:IN: SecureSession[0x7f0e8800e800]: MarkForEviction Type:1 LSID:9221
[1683890087.947281][8723:8723] CHIP:SC: SecureSession[0x7f0e8800e800]: Moving from state 'kActive' --> 'kPendingEviction'
[1683890087.947300][8723:8723] CHIP:IN: SecureSession[0x7f0e8800e800]: Released - Type:1 LSID:9221
[1683890087.947312][8723:8723] CHIP:CTL: Shutting down the controller
[1683890087.947321][8723:8723] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1683890087.947327][8723:8723] CHIP:FP: Forgetting fabric 0x1
[1683890087.947341][8723:8723] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1683890087.947401][8723:8723] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1683890087.947407][8723:8723] CHIP:TS: Reverted Last Known Good Time to previous value
[1683890087.947419][8723:8723] CHIP:CTL: Shutting down the commissioner
[1683890087.947424][8723:8723] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1683890087.947428][8723:8723] CHIP:CTL: Shutting down the controller
[1683890087.947434][8723:8723] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1683890087.947465][8723:8724] CHIP:DL: BluezDisconnect peer=DE:61:CB:D1:FE:40
[1683890087.948024][8723:8723] CHIP:DMG: IM WH moving to [Uninitialized]
[1683890087.948036][8723:8723] CHIP:DMG: IM WH moving to [Uninitialized]
[1683890087.948042][8723:8723] CHIP:DMG: IM WH moving to [Uninitialized]
[1683890087.948048][8723:8723] CHIP:DMG: IM WH moving to [Uninitialized]
[1683890087.948057][8723:8723] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1683890087.948094][8723:8723] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1683890087.948115][8723:8723] CHIP:FP: Shutting down FabricTable
[1683890087.948127][8723:8723] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:25:05
[1683890087.948192][8723:8723] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:25:05
[1683890087.948201][8723:8723] CHIP:TS: Reverted Last Known Good Time to previous value
[1683890087.948386][8723:8723] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-NkpOcy)
[1683890087.948696][8723:8723] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1683890087.948729][8723:8723] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1683890087.948746][8723:8723] CHIP:DL: Inet Layer shutdown
[1683890087.948752][8723:8723] CHIP:DL: BLE shutdown
[1683890087.949346][8723:8723] CHIP:DL: System Layer shutdown
[1683890088.125949][8723:8723] CHIP:TOO: Run command failure: ../../src/controller/CHIPDeviceController.cpp:2050: CHIP Error 0x000000AC: Internal error
I honestly don't know what could be the issue here. I even flashed the sourcecode of the light_bulb example on the DK for a second time, have restartet a couple of times again but I can't seem to make it work.
Could the problem have something to do with E: 374 [DIS]Failed to finalize service update: 1c ?
Thanks for any help!
Emily
