`chip-tool` built with commit SHA: `fa5561c23d8c1f9464da8669931affbae0660f51` Lines of Interest: ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool pairing onnetwork 17 20202021 ... [1650578349.007276][17409:17416] CHIP:TOO: Device commissioning completed with success ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 17 1 ... [1650579166.721625][17799:17804] CHIP:TOO: ClusterRevision: 3 ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool pairing onnetwork 17 20202021 [1650578348.157375][17409:17409] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650578348.157777][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_kvs-RS6zhs) [1650578348.158005][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1650578348.158198][17409:17409] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650578348.158449][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_device_info.ini-J9Ciy5) [1650578348.158627][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_device_info.ini) [1650578348.181275][17409:17409] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650578348.181671][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-mphSbg) [1650578348.181947][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1650578348.182097][17409:17409] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650578348.182321][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_config.ini-OdinXK) [1650578348.182666][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1650578348.182807][17409:17409] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650578348.187682][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BDFB0d) [1650578348.187936][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578348.188884][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-kmWwBI) [1650578348.189949][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1650578348.190023][17409:17409] CHIP:DL: NVS set: chip-factory/unique-id = "B0D0E427896267C7" [1650578348.190218][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-88iAUS) [1650578348.191085][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1650578348.191172][17409:17409] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1650578348.191374][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-UrTqde) [1650578348.191931][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1650578348.192032][17409:17409] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1650578348.192230][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-mbQ0u0) [1650578348.192789][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578348.192858][17409:17409] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1650578348.193042][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jhlW3t) [1650578348.193634][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578348.193701][17409:17409] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650578348.193936][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-uVfbDQ) [1650578348.194510][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578348.194580][17409:17409] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1650578348.194758][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_config.ini-CVHITP) [1650578348.195313][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1650578348.195378][17409:17409] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1650578348.195564][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_config.ini-AXaowE) [1650578348.196281][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1650578348.196358][17409:17409] CHIP:DL: NVS set: chip-config/location-capability = 0 (0x0) [1650578348.197306][17409:17409] CHIP:DL: Got Ethernet interface: eth0 [1650578348.198079][17409:17409] CHIP:DL: Found the primary Ethernet interface:eth0 [1650578348.198863][17409:17409] CHIP:DL: Got WiFi interface: wlan0 [1650578348.198970][17409:17409] CHIP:DL: Failed to reset WiFi statistic counts [1650578348.199154][17409:17409] CHIP:IN: UDP::Init bind&listen port=0 [1650578348.199358][17409:17409] CHIP:IN: UDP::Init bound to port=38966 [1650578348.199393][17409:17409] CHIP:IN: UDP::Init bind&listen port=0 [1650578348.199512][17409:17409] CHIP:IN: UDP::Init bound to port=43427 [1650578348.199548][17409:17409] CHIP:IN: BLEBase::Init - setting/overriding transport [1650578348.199571][17409:17409] CHIP:IN: TransportMgr initialized [1650578348.199666][17409:17409] CHIP:DIS: Init fabric pairing table with server storage [1650578348.199717][17409:17409] CHIP:DIS: Add fabric pairing table delegate [1650578348.200066][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-MKG8Mk) [1650578348.200723][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578348.200795][17409:17409] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) [1650578348.203440][17409:17409] CHIP:ZCL: Using ZAP configuration... [1650578348.207148][17409:17409] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.214871][17409:17409] CHIP:DL: MDNS failed to join multicast group on vetha3d8a56 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.216901][17409:17409] CHIP:DL: MDNS failed to join multicast group on veth3191e7b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.218631][17409:17409] CHIP:DL: MDNS failed to join multicast group on veth6595114 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.220445][17409:17409] CHIP:DL: MDNS failed to join multicast group on vethee76aa7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.222247][17409:17409] CHIP:DL: MDNS failed to join multicast group on veth1c17fb7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650578348.222675][17409:17409] CHIP:CTL: System State Initialized... [1650578348.222796][17409:17409] CHIP:CTL: Setting attestation nonce to random value [1650578348.222913][17409:17409] CHIP:CTL: Setting CSR nonce to random value [1650578348.223001][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.223106][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.223141][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.223228][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.223253][17409:17409] CHIP:IN: TransportMgr initialized [1650578348.223352][17409:17409] CHIP:CTL: Setting attestation nonce to random value [1650578348.223405][17409:17409] CHIP:CTL: Setting CSR nonce to random value [1650578348.223836][17409:17409] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../../examples/chip-tool/config/PersistentStorage.cpp:108: CHIP Error 0x000000A0: Value not found in the persisted storage [1650578348.242260][17409:17409] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../../examples/chip-tool/config/PersistentStorage.cpp:108: CHIP Error 0x000000A0: Value not found in the persisted storage [1650578348.244497][17409:17409] CHIP:CTL: Generating RCAC [1650578348.246120][17409:17409] CHIP:CTL: Generating ICAC [1650578348.247433][17409:17409] CHIP:CTL: Generating NOC [1650578348.248776][17409:17409] CHIP:DIS: Verifying the received credentials [1650578348.250920][17409:17409] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650578348.250962][17409:17409] CHIP:DIS: Assigned compressed fabric ID: 0x1CA619EC425B4FB0, node ID: 0x000000000001B669 [1650578348.257962][17409:17409] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage [1650578348.259588][17409:17409] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x1CA619EC425B4FB0 [1650578348.259660][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.259799][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.259827][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.259927][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.259970][17409:17409] CHIP:IN: TransportMgr initialized [1650578348.260107][17409:17409] CHIP:CTL: Setting attestation nonce to random value [1650578348.260176][17409:17409] CHIP:CTL: Setting CSR nonce to random value [1650578348.261415][17409:17409] CHIP:CTL: Generating NOC [1650578348.262422][17409:17409] CHIP:DIS: Verifying the received credentials [1650578348.264374][17409:17409] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650578348.264430][17409:17409] CHIP:DIS: Assigned compressed fabric ID: 0x42F76D3950ED0C16, node ID: 0x000000000001B669 [1650578348.273828][17409:17409] CHIP:DIS: Fabric (2) persisted to storage. Calling OnFabricPersistedToStorage [1650578348.274783][17409:17409] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x42F76D3950ED0C16 [1650578348.274876][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.275029][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.275062][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.275176][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.275204][17409:17409] CHIP:IN: TransportMgr initialized [1650578348.275312][17409:17409] CHIP:CTL: Setting attestation nonce to random value [1650578348.275393][17409:17409] CHIP:CTL: Setting CSR nonce to random value [1650578348.277090][17409:17409] CHIP:CTL: Generating NOC [1650578348.278432][17409:17409] CHIP:DIS: Verifying the received credentials [1650578348.281166][17409:17409] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650578348.281238][17409:17409] CHIP:DIS: Assigned compressed fabric ID: 0x99A6E98698D73B9F, node ID: 0x000000000001B669 [1650578348.286445][17409:17409] CHIP:DIS: Fabric (3) persisted to storage. Calling OnFabricPersistedToStorage [1650578348.287589][17409:17409] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x99A6E98698D73B9F [1650578348.287691][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.287832][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.287860][17409:17409] CHIP:IN: UDP::Init bind&listen port=5550 [1650578348.287953][17409:17409] CHIP:IN: UDP::Init bound to port=5550 [1650578348.287977][17409:17409] CHIP:IN: TransportMgr initialized [1650578348.387963][17409:17416] CHIP:DL: CHIP task running [1650578348.389552][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.389879][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.390122][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.390331][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.394003][17409:17416] CHIP:TOO: Discovered Device: 2620:149:af:2820:dea6:32ff:fe8d:6e32:5540 [1650578348.394372][17409:17416] CHIP:SC: Assigned local session key ID 63759 [1650578348.394449][17409:17416] CHIP:SC: Including MRP parameters in PBKDF param request [1650578348.394521][17409:17416] CHIP:IN: Prepared unauthenticated message 0xaaaaf1440f58 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 12503i with MessageCounter:1492815440. [1650578348.394568][17409:17416] CHIP:IN: Sending unauthenticated msg 0xaaaaf1440f58 with MessageCounter:1492815440 to 0x0000000000000000 at monotonic time: 00000000010B7D66 msec [1650578348.394773][17409:17416] CHIP:SC: Sent PBKDF param request [1650578348.394814][17409:17416] CHIP:CTL: Setting attestation nonce to random value [1650578348.394863][17409:17416] CHIP:CTL: Setting CSR nonce to random value [1650578348.394911][17409:17416] CHIP:CTL: Commission called for node ID 0x0000000000000011 [1650578348.447579][17409:17416] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:4016367935 on exchange 12503i [1650578348.447831][17409:17416] CHIP:EM: Found matching exchange: 12503i, Delegate: 0xffff8c002388 [1650578348.447903][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:1492815440 from Retrans Table on exchange 12503i [1650578348.447945][17409:17416] CHIP:EM: Removed CHIP MessageCounter:1492815440 from RetransTable on exchange 12503i [1650578348.448037][17409:17416] CHIP:SC: Received PBKDF param response [1650578348.448111][17409:17416] CHIP:SC: Peer assigned session ID 20516 [1650578348.448166][17409:17416] CHIP:SC: Found MRP parameters in the message [1650578348.454445][17409:17416] CHIP:EM: Piggybacking Ack for MessageCounter:4016367935 on exchange: 12503i [1650578348.454538][17409:17416] CHIP:IN: Prepared unauthenticated message 0xaaaaf1440f58 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 12503i with MessageCounter:1492815441. [1650578348.454584][17409:17416] CHIP:IN: Sending unauthenticated msg 0xaaaaf1440f58 with MessageCounter:1492815441 to 0x0000000000000000 at monotonic time: 00000000010B7DA2 msec [1650578348.454789][17409:17416] CHIP:SC: Sent spake2p msg1 [1650578348.457949][17409:17416] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:4016367936 on exchange 12503i [1650578348.458018][17409:17416] CHIP:EM: Found matching exchange: 12503i, Delegate: 0xffff8c002388 [1650578348.458069][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:1492815441 from Retrans Table on exchange 12503i [1650578348.458095][17409:17416] CHIP:EM: Removed CHIP MessageCounter:1492815441 from RetransTable on exchange 12503i [1650578348.458174][17409:17416] CHIP:SC: Received spake2p msg2 [1650578348.459594][17409:17416] CHIP:EM: Piggybacking Ack for MessageCounter:4016367936 on exchange: 12503i [1650578348.459683][17409:17416] CHIP:IN: Prepared unauthenticated message 0xaaaaf1440f58 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 12503i with MessageCounter:1492815442. [1650578348.459728][17409:17416] CHIP:IN: Sending unauthenticated msg 0xaaaaf1440f58 with MessageCounter:1492815442 to 0x0000000000000000 at monotonic time: 00000000010B7DA7 msec [1650578348.459917][17409:17416] CHIP:SC: Sent spake2p msg3 [1650578348.460891][17409:17416] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4016367937 on exchange 12503i [1650578348.460937][17409:17416] CHIP:EM: Found matching exchange: 12503i, Delegate: 0xffff8c002388 [1650578348.460978][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:1492815442 from Retrans Table on exchange 12503i [1650578348.461003][17409:17416] CHIP:EM: Removed CHIP MessageCounter:1492815442 from RetransTable on exchange 12503i [1650578348.461046][17409:17416] CHIP:IN: New secure session created for device 0x0000000000000011, LSID:63759 PSID:20516! [1650578348.461118][17409:17416] CHIP:CTL: Remote device completed SPAKE2+ handshake [1650578348.461144][17409:17416] CHIP:TOO: Pairing Success [1650578348.461173][17409:17416] CHIP:CTL: Going from commissioning step 'SecurePairing' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/AutoCommissioner.cpp:265: Success' --> 'ReadCommissioningInfo' [1650578348.461200][17409:17416] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CommissioningDelegate.h:73: Success' [1650578348.461223][17409:17416] CHIP:CTL: Sending request for commissioning information [1650578348.461261][17409:17416] CHIP:DMG: SendReadRequest ReadClient[0xffff8c0015a0]: Sending Read Request [1650578348.461418][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x2 and protocolId (0, 1) on exchange 12504i with MessageCounter:14103664. [1650578348.461462][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103664 to 0x0000000000000011 (1) at monotonic time: 00000000010B7DA9 msec [1650578348.461638][17409:17416] CHIP:DMG: MoveToState ReadClient[0xffff8c0015a0]: Moving to [AwaitingIn] [1650578348.461685][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:4016367937 on exchange 12503i [1650578348.461726][17409:17416] CHIP:IN: Prepared unauthenticated message 0xffffa21229a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 12503i with MessageCounter:1492815443. [1650578348.461763][17409:17416] CHIP:IN: Sending unauthenticated msg 0xffffa21229a8 with MessageCounter:1492815443 to 0x0000000000000000 at monotonic time: 00000000010B7DA9 msec [1650578348.461866][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:4016367937 on exchange 12503i [1650578348.560111][17409:17416] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14364827 on exchange 12504i [1650578348.560189][17409:17416] CHIP:EM: Found matching exchange: 12504i, Delegate: 0xffff8c0015a0 [1650578348.560241][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103664 from Retrans Table on exchange 12504i [1650578348.560268][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103664 from RetransTable on exchange 12504i [1650578348.560360][17409:17416] CHIP:DMG: ReportDataMessage = [1650578348.560392][17409:17416] CHIP:DMG: { [1650578348.560415][17409:17416] CHIP:DMG: AttributeReportIBs = [1650578348.560445][17409:17416] CHIP:DMG: [ [1650578348.560470][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.560510][17409:17416] CHIP:DMG: { [1650578348.560537][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.560571][17409:17416] CHIP:DMG: { [1650578348.560604][17409:17416] CHIP:DMG: DataVersion = 0x29a23ca8, [1650578348.560641][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.560679][17409:17416] CHIP:DMG: { [1650578348.560719][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.560760][17409:17416] CHIP:DMG: Cluster = 0x31, [1650578348.560801][17409:17416] CHIP:DMG: Attribute = 0x0000_0003, [1650578348.560837][17409:17416] CHIP:DMG: } [1650578348.560876][17409:17416] CHIP:DMG: [1650578348.560916][17409:17416] CHIP:DMG: Data = 0, [1650578348.560953][17409:17416] CHIP:DMG: }, [1650578348.560987][17409:17416] CHIP:DMG: [1650578348.561013][17409:17416] CHIP:DMG: }, [1650578348.561052][17409:17416] CHIP:DMG: [1650578348.561077][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.561111][17409:17416] CHIP:DMG: { [1650578348.561136][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.561167][17409:17416] CHIP:DMG: { [1650578348.561204][17409:17416] CHIP:DMG: DataVersion = 0xb431c938, [1650578348.561239][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.561275][17409:17416] CHIP:DMG: { [1650578348.561312][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.561351][17409:17416] CHIP:DMG: Cluster = 0x28, [1650578348.561390][17409:17416] CHIP:DMG: Attribute = 0x0000_0004, [1650578348.561426][17409:17416] CHIP:DMG: } [1650578348.561463][17409:17416] CHIP:DMG: [1650578348.561498][17409:17416] CHIP:DMG: Data = 32769, [1650578348.561534][17409:17416] CHIP:DMG: }, [1650578348.561568][17409:17416] CHIP:DMG: [1650578348.561596][17409:17416] CHIP:DMG: }, [1650578348.561632][17409:17416] CHIP:DMG: [1650578348.561656][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.561689][17409:17416] CHIP:DMG: { [1650578348.561715][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.561748][17409:17416] CHIP:DMG: { [1650578348.561778][17409:17416] CHIP:DMG: DataVersion = 0xb431c938, [1650578348.561812][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.561847][17409:17416] CHIP:DMG: { [1650578348.561883][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.561920][17409:17416] CHIP:DMG: Cluster = 0x28, [1650578348.561956][17409:17416] CHIP:DMG: Attribute = 0x0000_0002, [1650578348.561989][17409:17416] CHIP:DMG: } [1650578348.562025][17409:17416] CHIP:DMG: [1650578348.562059][17409:17416] CHIP:DMG: Data = 65521, [1650578348.562093][17409:17416] CHIP:DMG: }, [1650578348.562126][17409:17416] CHIP:DMG: [1650578348.562153][17409:17416] CHIP:DMG: }, [1650578348.562189][17409:17416] CHIP:DMG: [1650578348.562213][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.562246][17409:17416] CHIP:DMG: { [1650578348.562273][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.562302][17409:17416] CHIP:DMG: { [1650578348.562336][17409:17416] CHIP:DMG: DataVersion = 0x4dcc51bb, [1650578348.562368][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.562400][17409:17416] CHIP:DMG: { [1650578348.562436][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.562473][17409:17416] CHIP:DMG: Cluster = 0x30, [1650578348.562506][17409:17416] CHIP:DMG: Attribute = 0x0000_0003, [1650578348.562538][17409:17416] CHIP:DMG: } [1650578348.562574][17409:17416] CHIP:DMG: [1650578348.562607][17409:17416] CHIP:DMG: Data = 0, [1650578348.562639][17409:17416] CHIP:DMG: }, [1650578348.562672][17409:17416] CHIP:DMG: [1650578348.562699][17409:17416] CHIP:DMG: }, [1650578348.562733][17409:17416] CHIP:DMG: [1650578348.562757][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.562807][17409:17416] CHIP:DMG: { [1650578348.562835][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.562871][17409:17416] CHIP:DMG: { [1650578348.562903][17409:17416] CHIP:DMG: DataVersion = 0x4dcc51bb, [1650578348.562938][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.562974][17409:17416] CHIP:DMG: { [1650578348.563011][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.563049][17409:17416] CHIP:DMG: Cluster = 0x30, [1650578348.563086][17409:17416] CHIP:DMG: Attribute = 0x0000_0002, [1650578348.563121][17409:17416] CHIP:DMG: } [1650578348.563158][17409:17416] CHIP:DMG: [1650578348.563190][17409:17416] CHIP:DMG: Data = 0, [1650578348.563225][17409:17416] CHIP:DMG: }, [1650578348.563261][17409:17416] CHIP:DMG: [1650578348.563288][17409:17416] CHIP:DMG: }, [1650578348.563323][17409:17416] CHIP:DMG: [1650578348.563347][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.563380][17409:17416] CHIP:DMG: { [1650578348.563407][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.563440][17409:17416] CHIP:DMG: { [1650578348.563472][17409:17416] CHIP:DMG: DataVersion = 0x4dcc51bb, [1650578348.563505][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.563540][17409:17416] CHIP:DMG: { [1650578348.563575][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.563609][17409:17416] CHIP:DMG: Cluster = 0x30, [1650578348.563647][17409:17416] CHIP:DMG: Attribute = 0x0000_0001, [1650578348.563679][17409:17416] CHIP:DMG: } [1650578348.563714][17409:17416] CHIP:DMG: [1650578348.563748][17409:17416] CHIP:DMG: Data = [1650578348.563785][17409:17416] CHIP:DMG: { [1650578348.563820][17409:17416] CHIP:DMG: 0x0 = 60, [1650578348.563858][17409:17416] CHIP:DMG: }, [1650578348.563892][17409:17416] CHIP:DMG: }, [1650578348.563928][17409:17416] CHIP:DMG: [1650578348.563955][17409:17416] CHIP:DMG: }, [1650578348.564013][17409:17416] CHIP:DMG: [1650578348.564040][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.564072][17409:17416] CHIP:DMG: { [1650578348.564100][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.564131][17409:17416] CHIP:DMG: { [1650578348.564165][17409:17416] CHIP:DMG: DataVersion = 0x4dcc51bb, [1650578348.564196][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.564228][17409:17416] CHIP:DMG: { [1650578348.564264][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.564300][17409:17416] CHIP:DMG: Cluster = 0x30, [1650578348.564336][17409:17416] CHIP:DMG: Attribute = 0x0000_0000, [1650578348.564371][17409:17416] CHIP:DMG: } [1650578348.564408][17409:17416] CHIP:DMG: [1650578348.564442][17409:17416] CHIP:DMG: Data = 0, [1650578348.564477][17409:17416] CHIP:DMG: }, [1650578348.564512][17409:17416] CHIP:DMG: [1650578348.564539][17409:17416] CHIP:DMG: }, [1650578348.564574][17409:17416] CHIP:DMG: [1650578348.564599][17409:17416] CHIP:DMG: AttributeReportIB = [1650578348.564631][17409:17416] CHIP:DMG: { [1650578348.564658][17409:17416] CHIP:DMG: AttributeDataIB = [1650578348.564688][17409:17416] CHIP:DMG: { [1650578348.564722][17409:17416] CHIP:DMG: DataVersion = 0x29a23ca8, [1650578348.564753][17409:17416] CHIP:DMG: AttributePathIB = [1650578348.564785][17409:17416] CHIP:DMG: { [1650578348.564821][17409:17416] CHIP:DMG: Endpoint = 0x0, [1650578348.564856][17409:17416] CHIP:DMG: Cluster = 0x31, [1650578348.564892][17409:17416] CHIP:DMG: Attribute = 0x0000_FFFC, [1650578348.564924][17409:17416] CHIP:DMG: } [1650578348.564958][17409:17416] CHIP:DMG: [1650578348.564991][17409:17416] CHIP:DMG: Data = 2, [1650578348.565023][17409:17416] CHIP:DMG: }, [1650578348.565059][17409:17416] CHIP:DMG: [1650578348.565088][17409:17416] CHIP:DMG: }, [1650578348.565120][17409:17416] CHIP:DMG: [1650578348.565144][17409:17416] CHIP:DMG: ], [1650578348.565200][17409:17416] CHIP:DMG: [1650578348.565226][17409:17416] CHIP:DMG: SuppressResponse = true, [1650578348.565254][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.565280][17409:17416] CHIP:DMG: } [1650578348.566187][17409:17416] CHIP:CTL: Finished commissioning step 'ReadCommissioningInfo' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' [1650578348.566226][17409:17416] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' --> 'ArmFailSafe' [1650578348.566254][17409:17416] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1666: Success' [1650578348.566277][17409:17416] CHIP:CTL: Arming failsafe (60 seconds) [1650578348.566371][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.566403][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.566510][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12505i with MessageCounter:14103665. [1650578348.566553][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103665 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E12 msec [1650578348.566763][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.566800][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364827 on exchange 12504i [1650578348.566849][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12504i with MessageCounter:14103666. [1650578348.566883][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103666 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E12 msec [1650578348.566960][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364827 on exchange 12504i [1650578348.570883][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364828 on exchange 12505i [1650578348.570922][17409:17416] CHIP:EM: Found matching exchange: 12505i, Delegate: 0xffff8c003ba0 [1650578348.570959][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103665 from Retrans Table on exchange 12505i [1650578348.570984][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103665 from RetransTable on exchange 12505i [1650578348.571015][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.571061][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.571086][17409:17416] CHIP:DMG: { [1650578348.571111][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.571135][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.571166][17409:17416] CHIP:DMG: [ [1650578348.571191][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.571231][17409:17416] CHIP:DMG: { [1650578348.571260][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.571293][17409:17416] CHIP:DMG: { [1650578348.571326][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.571362][17409:17416] CHIP:DMG: { [1650578348.571399][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.571437][17409:17416] CHIP:DMG: ClusterId = 0x30, [1650578348.571473][17409:17416] CHIP:DMG: CommandId = 0x1, [1650578348.571505][17409:17416] CHIP:DMG: }, [1650578348.571546][17409:17416] CHIP:DMG: [1650578348.571584][17409:17416] CHIP:DMG: CommandData = [1650578348.571623][17409:17416] CHIP:DMG: { [1650578348.571662][17409:17416] CHIP:DMG: 0x0 = 0, [1650578348.571704][17409:17416] CHIP:DMG: 0x1 = "", [1650578348.571749][17409:17416] CHIP:DMG: }, [1650578348.571787][17409:17416] CHIP:DMG: }, [1650578348.571830][17409:17416] CHIP:DMG: [1650578348.571864][17409:17416] CHIP:DMG: }, [1650578348.571905][17409:17416] CHIP:DMG: [1650578348.571935][17409:17416] CHIP:DMG: ], [1650578348.571973][17409:17416] CHIP:DMG: [1650578348.572029][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.572059][17409:17416] CHIP:DMG: }, [1650578348.572134][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1650578348.572236][17409:17416] CHIP:CTL: Received ArmFailSafe response [1650578348.572273][17409:17416] CHIP:CTL: Finished commissioning step 'ArmFailSafe' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' [1650578348.572304][17409:17416] CHIP:CTL: Going from commissioning step 'ArmFailSafe' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' --> 'ConfigRegulatory' [1650578348.572337][17409:17416] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1819: Success' [1650578348.572364][17409:17416] CHIP:CTL: Setting Regulatory Config [1650578348.572390][17409:17416] CHIP:CTL: Device does not support configurable regulatory location [1650578348.572450][17409:17416] CHIP:CTL: Unable to find country code, defaulting to XX [1650578348.572521][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.572562][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.572660][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12506i with MessageCounter:14103667. [1650578348.572731][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103667 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E18 msec [1650578348.572927][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.572993][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.573030][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364828 on exchange 12505i [1650578348.573086][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12505i with MessageCounter:14103668. [1650578348.573128][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103668 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E19 msec [1650578348.573219][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364828 on exchange 12505i [1650578348.579072][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364829 on exchange 12506i [1650578348.579121][17409:17416] CHIP:EM: Found matching exchange: 12506i, Delegate: 0xffff8c006620 [1650578348.579169][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103667 from Retrans Table on exchange 12506i [1650578348.579200][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103667 from RetransTable on exchange 12506i [1650578348.579240][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.579297][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.579328][17409:17416] CHIP:DMG: { [1650578348.579358][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.579388][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.579426][17409:17416] CHIP:DMG: [ [1650578348.579458][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.579498][17409:17416] CHIP:DMG: { [1650578348.579531][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.579599][17409:17416] CHIP:DMG: { [1650578348.579644][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.579692][17409:17416] CHIP:DMG: { [1650578348.579740][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.579789][17409:17416] CHIP:DMG: ClusterId = 0x30, [1650578348.579838][17409:17416] CHIP:DMG: CommandId = 0x3, [1650578348.579885][17409:17416] CHIP:DMG: }, [1650578348.579935][17409:17416] CHIP:DMG: [1650578348.579972][17409:17416] CHIP:DMG: CommandData = [1650578348.580054][17409:17416] CHIP:DMG: { [1650578348.580104][17409:17416] CHIP:DMG: 0x0 = 0, [1650578348.580156][17409:17416] CHIP:DMG: 0x1 = "", [1650578348.580205][17409:17416] CHIP:DMG: }, [1650578348.580248][17409:17416] CHIP:DMG: }, [1650578348.580298][17409:17416] CHIP:DMG: [1650578348.580333][17409:17416] CHIP:DMG: }, [1650578348.580377][17409:17416] CHIP:DMG: [1650578348.580406][17409:17416] CHIP:DMG: ], [1650578348.580446][17409:17416] CHIP:DMG: [1650578348.580477][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.580508][17409:17416] CHIP:DMG: }, [1650578348.580590][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1650578348.580696][17409:17416] CHIP:CTL: Received SetRegulatoryConfig response [1650578348.580739][17409:17416] CHIP:CTL: Finished commissioning step 'ConfigRegulatory' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' [1650578348.580772][17409:17416] CHIP:CTL: Going from commissioning step 'ConfigRegulatory' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' --> 'SendPAICertificateRequest' [1650578348.580806][17409:17416] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1828: Success' [1650578348.580834][17409:17416] CHIP:CTL: Sending request for PAI certificate [1650578348.580859][17409:17416] CHIP:CTL: Sending Certificate Chain request to 0xffff8c002330 device [1650578348.580933][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.581027][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.581160][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12507i with MessageCounter:14103669. [1650578348.581216][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103669 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E21 msec [1650578348.581453][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.581534][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.581577][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364829 on exchange 12506i [1650578348.581652][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12506i with MessageCounter:14103670. [1650578348.581697][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103670 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E21 msec [1650578348.581829][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364829 on exchange 12506i [1650578348.584318][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364830 on exchange 12507i [1650578348.584394][17409:17416] CHIP:EM: Found matching exchange: 12507i, Delegate: 0xffff8c003ba0 [1650578348.584459][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103669 from Retrans Table on exchange 12507i [1650578348.584495][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103669 from RetransTable on exchange 12507i [1650578348.584545][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.584617][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.584654][17409:17416] CHIP:DMG: { [1650578348.584690][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.584727][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.584772][17409:17416] CHIP:DMG: [ [1650578348.584810][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.584866][17409:17416] CHIP:DMG: { [1650578348.584906][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.584954][17409:17416] CHIP:DMG: { [1650578348.585004][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.585060][17409:17416] CHIP:DMG: { [1650578348.585116][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.585174][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.585234][17409:17416] CHIP:DMG: CommandId = 0x3, [1650578348.585290][17409:17416] CHIP:DMG: }, [1650578348.585349][17409:17416] CHIP:DMG: [1650578348.585401][17409:17416] CHIP:DMG: CommandData = [1650578348.585457][17409:17416] CHIP:DMG: { [1650578348.585512][17409:17416] CHIP:DMG: 0x0 = [ [1650578348.585568][17409:17416] CHIP:DMG: ... (byte string too long) ... [1650578348.585628][17409:17416] CHIP:DMG: ] [1650578348.585684][17409:17416] CHIP:DMG: }, [1650578348.585730][17409:17416] CHIP:DMG: }, [1650578348.585783][17409:17416] CHIP:DMG: [1650578348.585822][17409:17416] CHIP:DMG: }, [1650578348.585869][17409:17416] CHIP:DMG: [1650578348.585905][17409:17416] CHIP:DMG: ], [1650578348.585951][17409:17416] CHIP:DMG: [1650578348.585988][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.586023][17409:17416] CHIP:DMG: }, [1650578348.586115][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1650578348.586170][17409:17416] CHIP:CTL: Received certificate chain from the device [1650578348.586214][17409:17416] CHIP:CTL: Finished commissioning step 'SendPAICertificateRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650578348.586260][17409:17416] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' --> 'SendDACCertificateRequest' [1650578348.586303][17409:17416] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650578348.586337][17409:17416] CHIP:CTL: Sending request for DAC certificate [1650578348.586366][17409:17416] CHIP:CTL: Sending Certificate Chain request to 0xffff8c002330 device [1650578348.586447][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.586498][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.586636][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12508i with MessageCounter:14103671. [1650578348.586700][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103671 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E26 msec [1650578348.586967][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.587061][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.587106][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364830 on exchange 12507i [1650578348.587193][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12507i with MessageCounter:14103672. [1650578348.587250][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103672 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E27 msec [1650578348.587402][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364830 on exchange 12507i [1650578348.589025][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364831 on exchange 12508i [1650578348.589081][17409:17416] CHIP:EM: Found matching exchange: 12508i, Delegate: 0xffff8c006620 [1650578348.589138][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103671 from Retrans Table on exchange 12508i [1650578348.589175][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103671 from RetransTable on exchange 12508i [1650578348.589220][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.589285][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.589322][17409:17416] CHIP:DMG: { [1650578348.589357][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.589404][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.589450][17409:17416] CHIP:DMG: [ [1650578348.589487][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.589542][17409:17416] CHIP:DMG: { [1650578348.589585][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.589633][17409:17416] CHIP:DMG: { [1650578348.589678][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.589731][17409:17416] CHIP:DMG: { [1650578348.589781][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.589833][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.589885][17409:17416] CHIP:DMG: CommandId = 0x3, [1650578348.589942][17409:17416] CHIP:DMG: }, [1650578348.589999][17409:17416] CHIP:DMG: [1650578348.590045][17409:17416] CHIP:DMG: CommandData = [1650578348.590092][17409:17416] CHIP:DMG: { [1650578348.590145][17409:17416] CHIP:DMG: 0x0 = [ [1650578348.590197][17409:17416] CHIP:DMG: ... (byte string too long) ... [1650578348.590277][17409:17416] CHIP:DMG: ] [1650578348.590328][17409:17416] CHIP:DMG: }, [1650578348.590379][17409:17416] CHIP:DMG: }, [1650578348.590435][17409:17416] CHIP:DMG: [1650578348.590480][17409:17416] CHIP:DMG: }, [1650578348.590529][17409:17416] CHIP:DMG: [1650578348.590568][17409:17416] CHIP:DMG: ], [1650578348.590613][17409:17416] CHIP:DMG: [1650578348.590649][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.590684][17409:17416] CHIP:DMG: }, [1650578348.590773][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1650578348.590821][17409:17416] CHIP:CTL: Received certificate chain from the device [1650578348.590864][17409:17416] CHIP:CTL: Finished commissioning step 'SendDACCertificateRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650578348.590907][17409:17416] CHIP:CTL: Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' --> 'SendAttestationRequest' [1650578348.590947][17409:17416] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:981: Success' [1650578348.590979][17409:17416] CHIP:CTL: Sending Attestation Request to the device. [1650578348.591010][17409:17416] CHIP:CTL: Sending Attestation request to 0xffff8c002330 device [1650578348.591084][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.591131][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.591240][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12509i with MessageCounter:14103673. [1650578348.591294][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103673 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E2B msec [1650578348.591517][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.591560][17409:17416] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1650578348.591619][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.591662][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364831 on exchange 12508i [1650578348.591723][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12508i with MessageCounter:14103674. [1650578348.591771][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103674 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E2B msec [1650578348.591874][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364831 on exchange 12508i [1650578348.599413][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364832 on exchange 12509i [1650578348.599489][17409:17416] CHIP:EM: Found matching exchange: 12509i, Delegate: 0xffff8c003ba0 [1650578348.599543][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103673 from Retrans Table on exchange 12509i [1650578348.599571][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103673 from RetransTable on exchange 12509i [1650578348.599610][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.599668][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.599697][17409:17416] CHIP:DMG: { [1650578348.599725][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.599762][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.599806][17409:17416] CHIP:DMG: [ [1650578348.599835][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.599882][17409:17416] CHIP:DMG: { [1650578348.599916][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.599955][17409:17416] CHIP:DMG: { [1650578348.600018][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.600053][17409:17416] CHIP:DMG: { [1650578348.600094][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.600135][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.600176][17409:17416] CHIP:DMG: CommandId = 0x1, [1650578348.600213][17409:17416] CHIP:DMG: }, [1650578348.600255][17409:17416] CHIP:DMG: [1650578348.600293][17409:17416] CHIP:DMG: CommandData = [1650578348.600338][17409:17416] CHIP:DMG: { [1650578348.600377][17409:17416] CHIP:DMG: 0x0 = [ [1650578348.600416][17409:17416] CHIP:DMG: ... (byte string too long) ... [1650578348.600458][17409:17416] CHIP:DMG: ] [1650578348.600495][17409:17416] CHIP:DMG: 0x1 = [ [1650578348.600551][17409:17416] CHIP:DMG: 0x5a, 0xf2, 0x3e, 0x2a, 0xf9, 0x8c, 0x7e, 0x16, 0x4c, 0x9, 0x9e, 0x42, 0x91, 0x9f, 0x9c, 0x26, 0x29, 0xe4, 0x0, 0xca, 0x39, 0x6c, 0x16, 0xeb, 0x7f, 0x4f, 0xef, 0x51, 0xf9, 0x33, 0xbf, 0xd, 0xc0, 0x1d, 0xb4, 0xcb, 0xb2, 0x6d, 0xcc, 0xb3, 0xde, 0xc6, [1650578348.600595][17409:17416] CHIP:DMG: ] [1650578348.600637][17409:17416] CHIP:DMG: }, [1650578348.600675][17409:17416] CHIP:DMG: }, [1650578348.600716][17409:17416] CHIP:DMG: [1650578348.600747][17409:17416] CHIP:DMG: }, [1650578348.600784][17409:17416] CHIP:DMG: [1650578348.600812][17409:17416] CHIP:DMG: ], [1650578348.600850][17409:17416] CHIP:DMG: [1650578348.600878][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.600905][17409:17416] CHIP:DMG: }, [1650578348.600981][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1650578348.601027][17409:17416] CHIP:CTL: Received Attestation Information from the device [1650578348.601063][17409:17416] CHIP:CTL: Finished commissioning step 'SendAttestationRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' [1650578348.601144][17409:17416] CHIP:CTL: Going from commissioning step 'SendAttestationRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' --> 'AttestationVerification' [1650578348.601178][17409:17416] CHIP:CTL: Performing next commissioning step 'AttestationVerification' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1016: Success' [1650578348.601204][17409:17416] CHIP:CTL: Verifying attestation [1650578348.611130][17409:17416] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1650578348.611237][17409:17416] CHIP:CTL: Finished commissioning step 'AttestationVerification' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' [1650578348.611272][17409:17416] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' --> 'SendOpCertSigningRequest' [1650578348.611307][17409:17416] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1061: Success' [1650578348.611338][17409:17416] CHIP:CTL: Sending CSR request to 0xffff8c002330 device [1650578348.611424][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.611468][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.611602][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12510i with MessageCounter:14103675. [1650578348.611659][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103675 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E3F msec [1650578348.611904][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.611950][17409:17416] CHIP:CTL: Sent CSR request, waiting for the CSR [1650578348.612152][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.612197][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364832 on exchange 12509i [1650578348.612283][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12509i with MessageCounter:14103676. [1650578348.612331][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103676 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E40 msec [1650578348.612476][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364832 on exchange 12509i [1650578348.616620][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364833 on exchange 12510i [1650578348.616686][17409:17416] CHIP:EM: Found matching exchange: 12510i, Delegate: 0xffff8c006620 [1650578348.616737][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103675 from Retrans Table on exchange 12510i [1650578348.616762][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103675 from RetransTable on exchange 12510i [1650578348.616798][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.616849][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.616876][17409:17416] CHIP:DMG: { [1650578348.616901][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.616933][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.616965][17409:17416] CHIP:DMG: [ [1650578348.616989][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.617026][17409:17416] CHIP:DMG: { [1650578348.617055][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.617089][17409:17416] CHIP:DMG: { [1650578348.617119][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.617153][17409:17416] CHIP:DMG: { [1650578348.617189][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.617225][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.617260][17409:17416] CHIP:DMG: CommandId = 0x5, [1650578348.617293][17409:17416] CHIP:DMG: }, [1650578348.617329][17409:17416] CHIP:DMG: [1650578348.617360][17409:17416] CHIP:DMG: CommandData = [1650578348.617393][17409:17416] CHIP:DMG: { [1650578348.617427][17409:17416] CHIP:DMG: 0x0 = [ [1650578348.617481][17409:17416] CHIP:DMG: 0x15, 0x30, 0x1, 0xca, 0x30, 0x81, 0xc7, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86 [1650578348.617531][17409:17416] CHIP:DMG: ] [1650578348.617565][17409:17416] CHIP:DMG: 0x1 = [ [1650578348.617612][17409:17416] CHIP:DMG: 0x6d, 0xaa, 0xcb, 0x11, 0x7a, 0xaf, 0x6e, 0xa5, 0x59, 0x5e, 0xda, 0x3e, 0x58, 0xff, 0xa3, 0xf2, 0x1d, 0x3d, 0xaf, 0xfc, 0x83, 0xb4, 0xdf, 0xd0, 0xd4, 0xc8, 0x10, 0xaa, 0xb5, 0xab, 0xda, 0x81, 0xac, 0xfe, 0x58, 0x1c, 0xa3, 0xf5, 0xb9, 0xf9, 0x5b, 0x8 [1650578348.617649][17409:17416] CHIP:DMG: ] [1650578348.617683][17409:17416] CHIP:DMG: }, [1650578348.617714][17409:17416] CHIP:DMG: }, [1650578348.617750][17409:17416] CHIP:DMG: [1650578348.617778][17409:17416] CHIP:DMG: }, [1650578348.617818][17409:17416] CHIP:DMG: [1650578348.617844][17409:17416] CHIP:DMG: ], [1650578348.617877][17409:17416] CHIP:DMG: [1650578348.617901][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.617927][17409:17416] CHIP:DMG: }, [1650578348.617994][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1650578348.618035][17409:17416] CHIP:CTL: Received certificate signing request from the device [1650578348.618069][17409:17416] CHIP:CTL: Finished commissioning step 'SendOpCertSigningRequest' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' [1650578348.618097][17409:17416] CHIP:CTL: Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' --> 'ValidateCSR' [1650578348.618125][17409:17416] CHIP:CTL: Performing next commissioning step 'ValidateCSR' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1194: Success' [1650578348.619237][17409:17416] CHIP:CTL: Finished commissioning step 'ValidateCSR' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650578348.619307][17409:17416] CHIP:CTL: Going from commissioning step 'ValidateCSR' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' --> 'GenerateNOCChain' [1650578348.619339][17409:17416] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650578348.619365][17409:17416] CHIP:CTL: Getting certificate chain for the device from the issuer [1650578348.619615][17409:17416] CHIP:CTL: Verifying Certificate Signing Request [1650578348.620433][17409:17416] CHIP:CTL: Generating NOC [1650578348.620797][17409:17416] CHIP:CTL: Providing certificate chain to the commissioner [1650578348.620847][17409:17416] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success [1650578348.620881][17409:17416] CHIP:CTL: Finished commissioning step 'GenerateNOCChain' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:255: Success' [1650578348.621055][17409:17416] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/credentials/attestation_verifier/DefaultDeviceAttestationVerifier.cpp:420: Success' [1650578348.621088][17409:17416] CHIP:CTL: Sending root certificate to the device [1650578348.621166][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.621256][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.621408][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12511i with MessageCounter:14103677. [1650578348.621457][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103677 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E49 msec [1650578348.621667][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.621707][17409:17416] CHIP:CTL: Sent root certificate to the device [1650578348.622030][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.622083][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364833 on exchange 12510i [1650578348.622163][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12510i with MessageCounter:14103678. [1650578348.622204][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103678 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E4A msec [1650578348.622342][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364833 on exchange 12510i [1650578348.623836][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364834 on exchange 12511i [1650578348.623893][17409:17416] CHIP:EM: Found matching exchange: 12511i, Delegate: 0xffff8c003ba0 [1650578348.623942][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103677 from Retrans Table on exchange 12511i [1650578348.623968][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103677 from RetransTable on exchange 12511i [1650578348.624032][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.624087][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.624112][17409:17416] CHIP:DMG: { [1650578348.624137][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.624161][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.624192][17409:17416] CHIP:DMG: [ [1650578348.624216][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.624254][17409:17416] CHIP:DMG: { [1650578348.624284][17409:17416] CHIP:DMG: CommandStatusIB = [1650578348.624317][17409:17416] CHIP:DMG: { [1650578348.624347][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.624381][17409:17416] CHIP:DMG: { [1650578348.624417][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.624455][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.624492][17409:17416] CHIP:DMG: CommandId = 0xb, [1650578348.624529][17409:17416] CHIP:DMG: }, [1650578348.624568][17409:17416] CHIP:DMG: [1650578348.624599][17409:17416] CHIP:DMG: StatusIB = [1650578348.624632][17409:17416] CHIP:DMG: { [1650578348.624666][17409:17416] CHIP:DMG: status = 0x00 (SUCCESS), [1650578348.624699][17409:17416] CHIP:DMG: }, [1650578348.624733][17409:17416] CHIP:DMG: [1650578348.624763][17409:17416] CHIP:DMG: }, [1650578348.624798][17409:17416] CHIP:DMG: [1650578348.624823][17409:17416] CHIP:DMG: }, [1650578348.624853][17409:17416] CHIP:DMG: [1650578348.624877][17409:17416] CHIP:DMG: ], [1650578348.624909][17409:17416] CHIP:DMG: [1650578348.624933][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.624956][17409:17416] CHIP:DMG: }, [1650578348.625019][17409:17416] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1650578348.625051][17409:17416] CHIP:CTL: Device confirmed that it has received the root certificate [1650578348.625080][17409:17416] CHIP:CTL: Finished commissioning step 'SendTrustedRootCert' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' [1650578348.625106][17409:17416] CHIP:CTL: Going from commissioning step 'SendTrustedRootCert' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' --> 'SendNOC' [1650578348.625133][17409:17416] CHIP:CTL: Performing next commissioning step 'SendNOC' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1364: Success' [1650578348.625208][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578348.625249][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578348.625378][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12512i with MessageCounter:14103679. [1650578348.625424][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:14103679 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E4D msec [1650578348.625633][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578348.625669][17409:17416] CHIP:CTL: Sent operational certificate to the device [1650578348.625717][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.625750][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364834 on exchange 12511i [1650578348.625812][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12511i with MessageCounter:14103680. [1650578348.625849][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103680 to 0x0000000000000011 (1) at monotonic time: 00000000010B7E4D msec [1650578348.625958][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364834 on exchange 12511i [1650578348.782704][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:14364835 on exchange 12512i [1650578348.782810][17409:17416] CHIP:EM: Found matching exchange: 12512i, Delegate: 0xffff8c006620 [1650578348.782901][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:14103679 from Retrans Table on exchange 12512i [1650578348.782955][17409:17416] CHIP:EM: Removed CHIP MessageCounter:14103679 from RetransTable on exchange 12512i [1650578348.783023][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578348.783117][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578348.783169][17409:17416] CHIP:DMG: { [1650578348.783221][17409:17416] CHIP:DMG: suppressResponse = false, [1650578348.783274][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578348.783340][17409:17416] CHIP:DMG: [ [1650578348.783392][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578348.783472][17409:17416] CHIP:DMG: { [1650578348.783535][17409:17416] CHIP:DMG: CommandDataIB = [1650578348.783611][17409:17416] CHIP:DMG: { [1650578348.783683][17409:17416] CHIP:DMG: CommandPathIB = [1650578348.783762][17409:17416] CHIP:DMG: { [1650578348.783836][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578348.783920][17409:17416] CHIP:DMG: ClusterId = 0x3e, [1650578348.784050][17409:17416] CHIP:DMG: CommandId = 0x8, [1650578348.784132][17409:17416] CHIP:DMG: }, [1650578348.784214][17409:17416] CHIP:DMG: [1650578348.784287][17409:17416] CHIP:DMG: CommandData = [1650578348.784364][17409:17416] CHIP:DMG: { [1650578348.784446][17409:17416] CHIP:DMG: 0x0 = 0, [1650578348.784529][17409:17416] CHIP:DMG: 0x1 = 1, [1650578348.784610][17409:17416] CHIP:DMG: }, [1650578348.784675][17409:17416] CHIP:DMG: }, [1650578348.784749][17409:17416] CHIP:DMG: [1650578348.784804][17409:17416] CHIP:DMG: }, [1650578348.784869][17409:17416] CHIP:DMG: [1650578348.784921][17409:17416] CHIP:DMG: ], [1650578348.784987][17409:17416] CHIP:DMG: [1650578348.785039][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578348.785090][17409:17416] CHIP:DMG: }, [1650578348.785218][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1650578348.785460][17409:17416] CHIP:CTL: Device returned status 0 on receiving the NOC [1650578348.785516][17409:17416] CHIP:CTL: Operational credentials provisioned on device 0xffff8c002330 [1650578348.785584][17409:17416] CHIP:TOO: Secure Pairing Success [1650578348.785642][17409:17416] CHIP:CTL: Finished commissioning step 'SendNOC' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1390: Success' [1650578348.785694][17409:17416] CHIP:CTL: Going from commissioning step 'SendNOC' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1390: Success' --> 'FindOperational' [1650578348.785750][17409:17416] CHIP:CTL: Performing next commissioning step 'FindOperational' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1390: Success' [1650578348.785801][17409:17416] CHIP:CSM: FindOrEstablishSession: PeerId = 1CA619EC425B4FB0:0000000000000011 [1650578348.785851][17409:17416] CHIP:CSM: FindOrEstablishSession: No existing session found [1650578348.786631][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.786917][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.787154][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.787374][17409:17416] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650578348.788691][17409:17416] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one. [1650578348.788783][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578348.788827][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:14364835 on exchange 12512i [1650578348.788929][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12512i with MessageCounter:14103681. [1650578348.788979][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:14103681 to 0x0000000000000011 (1) at monotonic time: 00000000010B7EF0 msec [1650578348.789094][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:14364835 on exchange 12512i [1650578348.799871][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.799929][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.799954][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.799976][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.800833][17409:17416] CHIP:DIS: Lookup clearing interface for non LL address [1650578348.800877][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: new best score: 7 [1650578348.800976][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.801051][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.801079][17409:17416] CHIP:DIS: Checking node lookup status after 16 ms [1650578348.801100][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.803727][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.803788][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.803818][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.803843][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.803865][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.804636][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.804736][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.804809][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.804837][17409:17416] CHIP:DIS: Checking node lookup status after 19 ms [1650578348.804859][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.806922][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.806978][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.807009][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.807032][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.807054][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.807830][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.807973][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.808081][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.808110][17409:17416] CHIP:DIS: Checking node lookup status after 23 ms [1650578348.808132][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.810062][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.810103][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.810140][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.810172][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.810202][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.811048][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.811158][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.811250][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.811283][17409:17416] CHIP:DIS: Checking node lookup status after 26 ms [1650578348.811312][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.812879][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.812918][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.812954][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.812986][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.813016][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.813806][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.813910][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.814000][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.814034][17409:17416] CHIP:DIS: Checking node lookup status after 29 ms [1650578348.814062][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.815695][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.815733][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.815768][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.815799][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.815828][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.816624][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.816732][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.816822][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.816855][17409:17416] CHIP:DIS: Checking node lookup status after 31 ms [1650578348.816884][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.818501][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.818537][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.818573][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.818604][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.818633][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.819407][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.819510][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.819600][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.819634][17409:17416] CHIP:DIS: Checking node lookup status after 34 ms [1650578348.819663][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.822765][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.822802][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.822837][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.822868][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.822898][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.823671][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.823774][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.823864][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.823897][17409:17416] CHIP:DIS: Checking node lookup status after 38 ms [1650578348.823926][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.825509][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.825544][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.825579][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.825611][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.825640][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.826421][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.826519][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.826608][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.826642][17409:17416] CHIP:DIS: Checking node lookup status after 41 ms [1650578348.826670][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.828380][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.828422][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.828524][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.828563][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.828598][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.829459][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.829569][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.829667][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.829703][17409:17416] CHIP:DIS: Checking node lookup status after 44 ms [1650578348.829734][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.831593][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.831632][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.831671][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.831706][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.831738][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.832632][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.832759][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.832868][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.832906][17409:17416] CHIP:DIS: Checking node lookup status after 47 ms [1650578348.832939][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.835789][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.835864][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.835908][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.835943][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.835975][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.837143][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.837429][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.837539][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.837579][17409:17416] CHIP:DIS: Checking node lookup status after 52 ms [1650578348.837611][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.838993][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.839051][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.839089][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.839122][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.839152][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.840137][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.840288][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.840388][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.840425][17409:17416] CHIP:DIS: Checking node lookup status after 55 ms [1650578348.840455][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.843611][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.843682][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.843722][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.843754][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.843783][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.844778][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.844906][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.844999][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.845035][17409:17416] CHIP:DIS: Checking node lookup status after 60 ms [1650578348.845065][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.868708][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.868757][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.868788][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.868812][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.868833][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.869560][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.869648][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.869719][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.869745][17409:17416] CHIP:DIS: Checking node lookup status after 84 ms [1650578348.869767][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.871712][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.871744][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.871771][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.871794][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.871816][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.872497][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.872585][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.872660][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.872687][17409:17416] CHIP:DIS: Checking node lookup status after 87 ms [1650578348.872709][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.874736][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.874768][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.874795][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.874818][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.874840][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.875469][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.875560][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.875630][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.875655][17409:17416] CHIP:DIS: Checking node lookup status after 90 ms [1650578348.875676][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.877678][17409:17416] CHIP:DIS: Discovered node without a pending query [1650578348.877712][17409:17416] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650578348.877739][17409:17416] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.877762][17409:17416] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650578348.877784][17409:17416] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650578348.878447][17409:17416] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650578348.878565][17409:17416] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650578348.878633][17409:17416] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650578348.878661][17409:17416] CHIP:DIS: Checking node lookup status after 93 ms [1650578348.878682][17409:17416] CHIP:DIS: Keeping DNSSD lookup active [1650578348.985188][17409:17416] CHIP:DIS: Checking node lookup status after 200 ms [1650578348.985262][17409:17416] CHIP:CTL: Updating device address to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 while in state 1 [1650578348.985287][17409:17416] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 1 --> 2 [1650578348.985397][17409:17416] CHIP:SC: Establishing CASE session to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650578348.986032][17409:17416] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaaaf0af1180, Got IPK for FabricIndex 1 [1650578348.986076][17409:17416] CHIP:SC: 0x17, 0x9a, 0xb1, 0x3b, 0xb3, 0xab, 0x9c, 0xb8, [1650578348.986102][17409:17416] CHIP:SC: 0x6d, 0xff, 0x25, 0xaa, 0xf0, 0xf5, 0xf9, 0x4e, [1650578348.986238][17409:17416] CHIP:SC: Including MRP parameters [1650578348.986309][17409:17416] CHIP:IN: Prepared unauthenticated message 0xaaaaf1440f58 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 12513i with MessageCounter:1492815444. [1650578348.986351][17409:17416] CHIP:IN: Sending unauthenticated msg 0xaaaaf1440f58 with MessageCounter:1492815444 to 0x0000000000000000 at monotonic time: 00000000010B7FB6 msec [1650578348.986542][17409:17416] CHIP:SC: Sent Sigma1 msg [1650578348.986568][17409:17416] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 2 --> 3 [1650578348.986593][17409:17416] CHIP:DIS: Discovery does not require any more timeouts [1650578348.989922][17409:17416] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:4016367938 on exchange 12513i [1650578348.990019][17409:17416] CHIP:EM: Found matching exchange: 12513i, Delegate: 0xffff8c00bbc0 [1650578348.990095][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:1492815444 from Retrans Table on exchange 12513i [1650578348.990137][17409:17416] CHIP:EM: Removed CHIP MessageCounter:1492815444 from RetransTable on exchange 12513i [1650578348.990196][17409:17416] CHIP:SC: Received Sigma2 msg [1650578348.990253][17409:17416] CHIP:SC: Peer assigned session session ID 20517 [1650578348.991216][17409:17416] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1650578348.995652][17409:17416] CHIP:SC: Found MRP parameters in the message [1650578348.995766][17409:17416] CHIP:SC: Sending Sigma3 [1650578348.996337][17409:17416] CHIP:EM: Piggybacking Ack for MessageCounter:4016367938 on exchange: 12513i [1650578348.996595][17409:17416] CHIP:IN: Prepared unauthenticated message 0xaaaaf1440f58 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 12513i with MessageCounter:1492815445. [1650578348.996669][17409:17416] CHIP:IN: Sending unauthenticated msg 0xaaaaf1440f58 with MessageCounter:1492815445 to 0x0000000000000000 at monotonic time: 00000000010B7FC0 msec [1650578348.996962][17409:17416] CHIP:SC: Sent Sigma3 msg [1650578349.000863][17409:17416] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4016367939 on exchange 12513i [1650578349.000909][17409:17416] CHIP:EM: Found matching exchange: 12513i, Delegate: 0xffff8c00bbc0 [1650578349.000957][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:1492815445 from Retrans Table on exchange 12513i [1650578349.000982][17409:17416] CHIP:EM: Removed CHIP MessageCounter:1492815445 from RetransTable on exchange 12513i [1650578349.001019][17409:17416] CHIP:SC: Success status report received. Session was established [1650578349.001049][17409:17416] CHIP:IN: New secure session created for device 0x0000000000000011, LSID:63760 PSID:20517! [1650578349.001123][17409:17416] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 3 --> 4 [1650578349.001186][17409:17416] CHIP:CTL: Finished commissioning step 'FindOperational' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1610: Success' [1650578349.001214][17409:17416] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1610: Success' --> 'SendComplete' [1650578349.001242][17409:17416] CHIP:CTL: Performing next commissioning step 'SendComplete' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1610: Success' [1650578349.001309][17409:17416] CHIP:DMG: ICR moving to [AddingComm] [1650578349.001341][17409:17416] CHIP:DMG: ICR moving to [AddedComma] [1650578349.001426][17409:17416] CHIP:IN: Prepared secure message 0xaaaaf1440f58 to 0x0000000000000011 (1) of type 0x8 and protocolId (0, 1) on exchange 12514i with MessageCounter:4626768. [1650578349.001463][17409:17416] CHIP:IN: Sending encrypted msg 0xaaaaf1440f58 with MessageCounter:4626768 to 0x0000000000000011 (1) at monotonic time: 00000000010B7FC5 msec [1650578349.001628][17409:17416] CHIP:DMG: ICR moving to [CommandSen] [1650578349.001688][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:4016367939 on exchange 12513i [1650578349.001725][17409:17416] CHIP:IN: Prepared unauthenticated message 0xffffa21229a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 12513i with MessageCounter:1492815446. [1650578349.001757][17409:17416] CHIP:IN: Sending unauthenticated msg 0xffffa21229a8 with MessageCounter:1492815446 to 0x0000000000000000 at monotonic time: 00000000010B7FC5 msec [1650578349.001835][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:4016367939 on exchange 12513i [1650578349.005858][17409:17416] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:6683892 on exchange 12514i [1650578349.005899][17409:17416] CHIP:EM: Found matching exchange: 12514i, Delegate: 0xffff8c006620 [1650578349.005940][17409:17416] CHIP:EM: Rxd Ack; Removing MessageCounter:4626768 from Retrans Table on exchange 12514i [1650578349.005964][17409:17416] CHIP:EM: Removed CHIP MessageCounter:4626768 from RetransTable on exchange 12514i [1650578349.005997][17409:17416] CHIP:DMG: ICR moving to [ResponseRe] [1650578349.006049][17409:17416] CHIP:DMG: InvokeResponseMessage = [1650578349.006074][17409:17416] CHIP:DMG: { [1650578349.006099][17409:17416] CHIP:DMG: suppressResponse = false, [1650578349.006128][17409:17416] CHIP:DMG: InvokeResponseIBs = [1650578349.006161][17409:17416] CHIP:DMG: [ [1650578349.006185][17409:17416] CHIP:DMG: InvokeResponseIB = [1650578349.006224][17409:17416] CHIP:DMG: { [1650578349.006256][17409:17416] CHIP:DMG: CommandDataIB = [1650578349.006289][17409:17416] CHIP:DMG: { [1650578349.006319][17409:17416] CHIP:DMG: CommandPathIB = [1650578349.006352][17409:17416] CHIP:DMG: { [1650578349.006385][17409:17416] CHIP:DMG: EndpointId = 0x0, [1650578349.006421][17409:17416] CHIP:DMG: ClusterId = 0x30, [1650578349.006456][17409:17416] CHIP:DMG: CommandId = 0x5, [1650578349.006489][17409:17416] CHIP:DMG: }, [1650578349.006524][17409:17416] CHIP:DMG: [1650578349.006557][17409:17416] CHIP:DMG: CommandData = [1650578349.006695][17409:17416] CHIP:DMG: { [1650578349.006734][17409:17416] CHIP:DMG: 0x0 = 0, [1650578349.006774][17409:17416] CHIP:DMG: 0x1 = "", [1650578349.006807][17409:17416] CHIP:DMG: }, [1650578349.006838][17409:17416] CHIP:DMG: }, [1650578349.006876][17409:17416] CHIP:DMG: [1650578349.006903][17409:17416] CHIP:DMG: }, [1650578349.006934][17409:17416] CHIP:DMG: [1650578349.006958][17409:17416] CHIP:DMG: ], [1650578349.006990][17409:17416] CHIP:DMG: [1650578349.007014][17409:17416] CHIP:DMG: InteractionModelRevision = 1 [1650578349.007038][17409:17416] CHIP:DMG: }, [1650578349.007103][17409:17416] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1650578349.007142][17409:17416] CHIP:CTL: Received CommissioningComplete response [1650578349.007171][17409:17416] CHIP:CTL: Finished commissioning step 'SendComplete' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1855: Success' [1650578349.007197][17409:17416] CHIP:CTL: Going from commissioning step 'SendComplete' with lastErr = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1855: Success' --> 'Cleanup' [1650578349.007224][17409:17416] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1855: Success' [1650578349.007249][17409:17416] CHIP:CTL: Finished commissioning step 'Cleanup' with error '../../../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1497: Success' [1650578349.007276][17409:17416] CHIP:TOO: Device commissioning completed with success [1650578349.007342][17409:17416] CHIP:DMG: ICR moving to [AwaitingDe] [1650578349.007376][17409:17416] CHIP:EM: Sending Standalone Ack for MessageCounter:6683892 on exchange 12514i [1650578349.007444][17409:17416] CHIP:IN: Prepared secure message 0xffffa21229b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 12514i with MessageCounter:4626769. [1650578349.007482][17409:17416] CHIP:IN: Sending encrypted msg 0xffffa21229b8 with MessageCounter:4626769 to 0x0000000000000011 (1) at monotonic time: 00000000010B7FCB msec [1650578349.007613][17409:17416] CHIP:EM: Flushed pending ack for MessageCounter:6683892 on exchange 12514i [1650578349.007826][17409:17409] CHIP:CTL: Shutting down the commissioner [1650578349.007956][17409:17409] CHIP:CTL: Shutting down the controller [1650578349.007989][17409:17409] CHIP:CTL: Shutting down the commissioner [1650578349.008108][17409:17409] CHIP:CTL: Shutting down the controller [1650578349.008154][17409:17409] CHIP:IN: Expiring all connections for fabric 1!! [1650578349.008221][17409:17409] CHIP:CTL: Shutting down the commissioner [1650578349.008342][17409:17409] CHIP:CTL: Shutting down the controller [1650578349.008378][17409:17409] CHIP:IN: Expiring all connections for fabric 2!! [1650578349.008428][17409:17409] CHIP:CTL: Shutting down the commissioner [1650578349.008544][17409:17409] CHIP:CTL: Shutting down the controller [1650578349.008579][17409:17409] CHIP:IN: Expiring all connections for fabric 3!! [1650578349.008624][17409:17409] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650578349.010367][17409:17409] CHIP:DMG: IM WH moving to [Uninitialized] [1650578349.010411][17409:17409] CHIP:DMG: IM WH moving to [Uninitialized] [1650578349.010446][17409:17409] CHIP:DMG: IM WH moving to [Uninitialized] [1650578349.010477][17409:17409] CHIP:DMG: IM WH moving to [Uninitialized] [1650578349.010509][17409:17409] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650578349.010627][17409:17409] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650578349.010946][17409:17409] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-PmK1q2) [1650578349.011756][17409:17409] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650578349.011832][17409:17409] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650578349.011870][17409:17409] CHIP:DL: Inet Layer shutdown [1650578349.011903][17409:17409] CHIP:DL: BLE shutdown [1650578349.011937][17409:17409] CHIP:DL: System Layer shutdown ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 17 1 [1650579163.435201][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650579163.435493][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650579163.435966][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650579163.436204][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650579163.436337][17787:17787] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650579163.436711][17787:17787] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-miowfA) [1650579163.437462][17787:17787] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579163.437546][17787:17787] CHIP:DL: NVS set: chip-counters/reboot-count = 57 (0x39) [1650579163.438595][17787:17787] CHIP:DL: Got Ethernet interface: eth0 [1650579163.439426][17787:17787] CHIP:DL: Found the primary Ethernet interface:eth0 [1650579163.440355][17787:17787] CHIP:DL: Got WiFi interface: wlan0 [1650579163.440459][17787:17787] CHIP:DL: Failed to reset WiFi statistic counts [1650579163.440578][17787:17787] CHIP:IN: UDP::Init bind&listen port=0 [1650579163.440739][17787:17787] CHIP:IN: UDP::Init bound to port=34612 [1650579163.440772][17787:17787] CHIP:IN: UDP::Init bind&listen port=0 [1650579163.440881][17787:17787] CHIP:IN: UDP::Init bound to port=41611 [1650579163.440909][17787:17787] CHIP:IN: BLEBase::Init - setting/overriding transport [1650579163.440932][17787:17787] CHIP:IN: TransportMgr initialized [1650579163.440991][17787:17787] CHIP:DIS: Init fabric pairing table with server storage [1650579163.441137][17787:17787] CHIP:IN: Loading from storage for fabric index 1 [1650579163.443888][17787:17787] CHIP:IN: Loading from storage for fabric index 2 [1650579163.444665][17787:17787] CHIP:IN: Loading from storage for fabric index 3 [1650579163.445315][17787:17787] CHIP:DIS: Add fabric pairing table delegate [1650579163.445755][17787:17787] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-sHDjK4) [1650579163.446438][17787:17787] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579163.446517][17787:17787] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 57000 (0xDEA8) [1650579163.450151][17787:17787] CHIP:ZCL: Using ZAP configuration... [1650579163.453811][17787:17787] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.461829][17787:17787] CHIP:DL: MDNS failed to join multicast group on vetha3d8a56 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.463780][17787:17787] CHIP:DL: MDNS failed to join multicast group on veth3191e7b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.465890][17787:17787] CHIP:DL: MDNS failed to join multicast group on veth6595114 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.467862][17787:17787] CHIP:DL: MDNS failed to join multicast group on vethee76aa7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.470064][17787:17787] CHIP:DL: MDNS failed to join multicast group on veth1c17fb7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579163.470503][17787:17787] CHIP:CTL: System State Initialized... [1650579163.470608][17787:17787] CHIP:CTL: Setting attestation nonce to random value [1650579163.470691][17787:17787] CHIP:CTL: Setting CSR nonce to random value [1650579163.470771][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.470885][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.470913][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.471009][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.471035][17787:17787] CHIP:IN: TransportMgr initialized [1650579163.471102][17787:17787] CHIP:CTL: Setting attestation nonce to random value [1650579163.471159][17787:17787] CHIP:CTL: Setting CSR nonce to random value [1650579163.472152][17787:17787] CHIP:CTL: Generating NOC [1650579163.473184][17787:17787] CHIP:DIS: Verifying the received credentials [1650579163.475083][17787:17787] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650579163.475163][17787:17787] CHIP:DIS: Assigned compressed fabric ID: 0x1CA619EC425B4FB0, node ID: 0x000000000001B669 [1650579163.475188][17787:17787] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x1CA619EC425B4FB0 [1650579163.475236][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.475392][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.475422][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.475515][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.475541][17787:17787] CHIP:IN: TransportMgr initialized [1650579163.475663][17787:17787] CHIP:CTL: Setting attestation nonce to random value [1650579163.475730][17787:17787] CHIP:CTL: Setting CSR nonce to random value [1650579163.476663][17787:17787] CHIP:CTL: Generating NOC [1650579163.477731][17787:17787] CHIP:DIS: Verifying the received credentials [1650579163.479610][17787:17787] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650579163.479675][17787:17787] CHIP:DIS: Assigned compressed fabric ID: 0x42F76D3950ED0C16, node ID: 0x000000000001B669 [1650579163.479709][17787:17787] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x42F76D3950ED0C16 [1650579163.479755][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.479898][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.479927][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.480902][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.480945][17787:17787] CHIP:IN: TransportMgr initialized [1650579163.481072][17787:17787] CHIP:CTL: Setting attestation nonce to random value [1650579163.481139][17787:17787] CHIP:CTL: Setting CSR nonce to random value [1650579163.482012][17787:17787] CHIP:CTL: Generating NOC [1650579163.482948][17787:17787] CHIP:DIS: Verifying the received credentials [1650579163.484670][17787:17787] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650579163.484705][17787:17787] CHIP:DIS: Assigned compressed fabric ID: 0x99A6E98698D73B9F, node ID: 0x000000000001B669 [1650579163.484730][17787:17787] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x99A6E98698D73B9F [1650579163.484774][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.484916][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.484943][17787:17787] CHIP:IN: UDP::Init bind&listen port=5550 [1650579163.485034][17787:17787] CHIP:IN: UDP::Init bound to port=5550 [1650579163.485058][17787:17787] CHIP:IN: TransportMgr initialized [1650579163.525826][17787:17792] CHIP:DL: CHIP task running [1650579163.527653][17787:17792] CHIP:TOO: Sending command to node 0x11 [1650579163.527712][17787:17792] CHIP:CSM: FindOrEstablishSession: PeerId = 1CA619EC425B4FB0:0000000000000011 [1650579163.527748][17787:17792] CHIP:CSM: FindOrEstablishSession: No existing session found [1650579163.528383][17787:17792] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579163.528648][17787:17792] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579163.528897][17787:17792] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579163.529138][17787:17792] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579163.535900][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.535981][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.536041][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.536067][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.537120][17787:17792] CHIP:DIS: Lookup clearing interface for non LL address [1650579163.537176][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: new best score: 7 [1650579163.537293][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.537389][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.537425][17787:17792] CHIP:DIS: Checking node lookup status after 10 ms [1650579163.537484][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.541007][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.541181][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.541223][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.541256][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.541286][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.542231][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.542360][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.542459][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.542495][17787:17792] CHIP:DIS: Checking node lookup status after 15 ms [1650579163.542526][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.543489][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.543528][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.543556][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.543580][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.543602][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.544326][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.544429][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.544503][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.544529][17787:17792] CHIP:DIS: Checking node lookup status after 17 ms [1650579163.544551][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.546033][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.546078][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.546107][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.546130][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.546152][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.546849][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.546935][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.547009][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.547035][17787:17792] CHIP:DIS: Checking node lookup status after 20 ms [1650579163.547056][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.548730][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.548761][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.548788][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.548815][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.548838][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.549494][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.549581][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.549652][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.549678][17787:17792] CHIP:DIS: Checking node lookup status after 22 ms [1650579163.549699][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.551221][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.551296][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.551326][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.551349][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.551370][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.552054][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.552143][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.552210][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.552234][17787:17792] CHIP:DIS: Checking node lookup status after 25 ms [1650579163.552255][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.553856][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.553886][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.553914][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.553937][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.553958][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.554574][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.554663][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.554733][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.554758][17787:17792] CHIP:DIS: Checking node lookup status after 27 ms [1650579163.554779][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.556984][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.557019][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.557046][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.557069][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.557091][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.557725][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.557810][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.557880][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.557904][17787:17792] CHIP:DIS: Checking node lookup status after 30 ms [1650579163.557926][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.559749][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.559779][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.559805][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.559828][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.559849][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.560557][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.560653][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.560723][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.560748][17787:17792] CHIP:DIS: Checking node lookup status after 33 ms [1650579163.560769][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.562483][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.562513][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.562540][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.562563][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.562584][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.563217][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.563300][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.563369][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.563394][17787:17792] CHIP:DIS: Checking node lookup status after 36 ms [1650579163.563415][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.565725][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.565802][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.565846][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.565881][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.565914][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.566929][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.567103][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.567209][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.567249][17787:17792] CHIP:DIS: Checking node lookup status after 40 ms [1650579163.567284][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.569751][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.569822][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.569867][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.569902][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.569935][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.570956][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.571140][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.571251][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.571292][17787:17792] CHIP:DIS: Checking node lookup status after 44 ms [1650579163.571325][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.573018][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.573086][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.573129][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.573164][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.573196][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.574198][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.574415][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.574500][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.574530][17787:17792] CHIP:DIS: Checking node lookup status after 47 ms [1650579163.574553][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.576068][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.576124][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.576157][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.576181][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.576205][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.576998][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.577135][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.577214][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.577243][17787:17792] CHIP:DIS: Checking node lookup status after 50 ms [1650579163.577267][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.579220][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.579279][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.579312][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.579336][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.579359][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.580353][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.580496][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.580582][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.580612][17787:17792] CHIP:DIS: Checking node lookup status after 53 ms [1650579163.580636][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.582505][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.582566][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.582598][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.582623][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.582647][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.583441][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.583589][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.583681][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.583711][17787:17792] CHIP:DIS: Checking node lookup status after 56 ms [1650579163.583735][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.585861][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.585902][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.585929][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.585952][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.585974][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.586698][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.586802][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.586875][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.586901][17787:17792] CHIP:DIS: Checking node lookup status after 59 ms [1650579163.586924][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.589689][17787:17792] CHIP:DIS: Discovered node without a pending query [1650579163.589754][17787:17792] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579163.589784][17787:17792] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.589807][17787:17792] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579163.589830][17787:17792] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579163.590593][17787:17792] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579163.590724][17787:17792] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579163.590799][17787:17792] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579163.590826][17787:17792] CHIP:DIS: Checking node lookup status after 63 ms [1650579163.590849][17787:17792] CHIP:DIS: Keeping DNSSD lookup active [1650579163.727909][17787:17792] CHIP:DIS: Checking node lookup status after 200 ms [1650579163.727984][17787:17792] CHIP:CTL: Updating device address to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 while in state 1 [1650579163.728034][17787:17792] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 1 --> 2 [1650579163.728194][17787:17792] CHIP:SC: Establishing CASE session to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579163.728835][17787:17792] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaab04764830, Got IPK for FabricIndex 1 [1650579163.728926][17787:17792] CHIP:SC: 0x17, 0x9a, 0xb1, 0x3b, 0xb3, 0xab, 0x9c, 0xb8, [1650579163.728953][17787:17792] CHIP:SC: 0x6d, 0xff, 0x25, 0xaa, 0xf0, 0xf5, 0xf9, 0x4e, [1650579163.729129][17787:17792] CHIP:SC: Including MRP parameters [1650579163.729251][17787:17792] CHIP:IN: Prepared unauthenticated message 0xaaab04c9ed38 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 10615i with MessageCounter:1338931402. [1650579163.729306][17787:17792] CHIP:IN: Sending unauthenticated msg 0xaaab04c9ed38 with MessageCounter:1338931402 to 0x0000000000000000 at monotonic time: 000000000117EE4D msec [1650579163.729524][17787:17792] CHIP:SC: Sent Sigma1 msg [1650579163.729563][17787:17792] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 2 --> 3 [1650579163.729595][17787:17792] CHIP:DIS: Discovery does not require any more timeouts [1650579163.732794][17787:17792] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:4016368034 on exchange 10615i [1650579163.732866][17787:17792] CHIP:EM: Found matching exchange: 10615i, Delegate: 0xffff880024c0 [1650579163.732917][17787:17792] CHIP:EM: Rxd Ack; Removing MessageCounter:1338931402 from Retrans Table on exchange 10615i [1650579163.732944][17787:17792] CHIP:EM: Removed CHIP MessageCounter:1338931402 from RetransTable on exchange 10615i [1650579163.732983][17787:17792] CHIP:SC: Received Sigma2 msg [1650579163.733023][17787:17792] CHIP:SC: Peer assigned session session ID 20565 [1650579163.733657][17787:17792] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1650579163.736427][17787:17792] CHIP:SC: Found MRP parameters in the message [1650579163.736487][17787:17792] CHIP:SC: Sending Sigma3 [1650579163.736841][17787:17792] CHIP:EM: Piggybacking Ack for MessageCounter:4016368034 on exchange: 10615i [1650579163.736909][17787:17792] CHIP:IN: Prepared unauthenticated message 0xaaab04c9ed38 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 10615i with MessageCounter:1338931403. [1650579163.736953][17787:17792] CHIP:IN: Sending unauthenticated msg 0xaaab04c9ed38 with MessageCounter:1338931403 to 0x0000000000000000 at monotonic time: 000000000117EE54 msec [1650579163.737140][17787:17792] CHIP:SC: Sent Sigma3 msg [1650579163.741179][17787:17792] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4016368035 on exchange 10615i [1650579163.741240][17787:17792] CHIP:EM: Found matching exchange: 10615i, Delegate: 0xffff880024c0 [1650579163.741287][17787:17792] CHIP:EM: Rxd Ack; Removing MessageCounter:1338931403 from Retrans Table on exchange 10615i [1650579163.741312][17787:17792] CHIP:EM: Removed CHIP MessageCounter:1338931403 from RetransTable on exchange 10615i [1650579163.741351][17787:17792] CHIP:SC: Success status report received. Session was established [1650579163.741380][17787:17792] CHIP:IN: New secure session created for device 0x0000000000000011, LSID:54425 PSID:20565! [1650579163.741460][17787:17792] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 3 --> 4 [1650579163.741522][17787:17792] CHIP:TOO: Sending ReadAttribute to: [1650579163.741550][17787:17792] CHIP:TOO: cluster 0x0000_0101, attribute: 0x0000_FFFD, endpoint 1 [1650579163.741592][17787:17792] CHIP:DMG: SendReadRequest ReadClient[0xffff880016c0]: Sending Read Request [1650579163.741717][17787:17792] CHIP:IN: Prepared secure message 0xaaab04c9ed38 to 0x0000000000000011 (1) of type 0x2 and protocolId (0, 1) on exchange 10616i with MessageCounter:15735763. [1650579163.741759][17787:17792] CHIP:IN: Sending encrypted msg 0xaaab04c9ed38 with MessageCounter:15735763 to 0x0000000000000011 (1) at monotonic time: 000000000117EE59 msec [1650579163.741929][17787:17792] CHIP:DMG: MoveToState ReadClient[0xffff880016c0]: Moving to [AwaitingIn] [1650579163.741971][17787:17792] CHIP:EM: Sending Standalone Ack for MessageCounter:4016368035 on exchange 10615i [1650579163.742010][17787:17792] CHIP:IN: Prepared unauthenticated message 0xffff8fffd9a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 10615i with MessageCounter:1338931404. [1650579163.742046][17787:17792] CHIP:IN: Sending unauthenticated msg 0xffff8fffd9a8 with MessageCounter:1338931404 to 0x0000000000000000 at monotonic time: 000000000117EE5A msec [1650579163.742132][17787:17792] CHIP:EM: Flushed pending ack for MessageCounter:4016368035 on exchange 10615i [1650579163.744264][17787:17792] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:6119598 on exchange 10616i [1650579163.744301][17787:17792] CHIP:EM: Found matching exchange: 10616i, Delegate: 0xffff880016c0 [1650579163.744337][17787:17792] CHIP:EM: Rxd Ack; Removing MessageCounter:15735763 from Retrans Table on exchange 10616i [1650579163.744362][17787:17792] CHIP:EM: Removed CHIP MessageCounter:15735763 from RetransTable on exchange 10616i [1650579163.744422][17787:17792] CHIP:DMG: ReportDataMessage = [1650579163.744450][17787:17792] CHIP:DMG: { [1650579163.744470][17787:17792] CHIP:DMG: AttributeReportIBs = [1650579163.744500][17787:17792] CHIP:DMG: [ [1650579163.744525][17787:17792] CHIP:DMG: AttributeReportIB = [1650579163.744559][17787:17792] CHIP:DMG: { [1650579163.744587][17787:17792] CHIP:DMG: AttributeDataIB = [1650579163.744619][17787:17792] CHIP:DMG: { [1650579163.744650][17787:17792] CHIP:DMG: DataVersion = 0xa9cace8e, [1650579163.744681][17787:17792] CHIP:DMG: AttributePathIB = [1650579163.744712][17787:17792] CHIP:DMG: { [1650579163.744746][17787:17792] CHIP:DMG: Endpoint = 0x1, [1650579163.744778][17787:17792] CHIP:DMG: Cluster = 0x101, [1650579163.744813][17787:17792] CHIP:DMG: Attribute = 0x0000_FFFD, [1650579163.744845][17787:17792] CHIP:DMG: } [1650579163.744882][17787:17792] CHIP:DMG: [1650579163.744917][17787:17792] CHIP:DMG: Data = 3, [1650579163.744949][17787:17792] CHIP:DMG: }, [1650579163.744983][17787:17792] CHIP:DMG: [1650579163.745010][17787:17792] CHIP:DMG: }, [1650579163.745040][17787:17792] CHIP:DMG: [1650579163.745064][17787:17792] CHIP:DMG: ], [1650579163.745095][17787:17792] CHIP:DMG: [1650579163.745120][17787:17792] CHIP:DMG: SuppressResponse = true, [1650579163.745145][17787:17792] CHIP:DMG: InteractionModelRevision = 1 [1650579163.745169][17787:17792] CHIP:DMG: } [1650579163.745313][17787:17792] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Attribute 0x0000_FFFD DataVersion: 2848640654 [1650579163.745392][17787:17792] CHIP:TOO: ClusterRevision: 3 [1650579163.745470][17787:17792] CHIP:EM: Sending Standalone Ack for MessageCounter:6119598 on exchange 10616i [1650579163.745533][17787:17792] CHIP:IN: Prepared secure message 0xffff8fffd9b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 10616i with MessageCounter:15735764. [1650579163.745571][17787:17792] CHIP:IN: Sending encrypted msg 0xffff8fffd9b8 with MessageCounter:15735764 to 0x0000000000000011 (1) at monotonic time: 000000000117EE5D msec [1650579163.745681][17787:17792] CHIP:EM: Flushed pending ack for MessageCounter:6119598 on exchange 10616i [1650579163.745885][17787:17787] CHIP:CTL: Shutting down the commissioner [1650579163.746012][17787:17787] CHIP:CTL: Shutting down the controller [1650579163.746045][17787:17787] CHIP:CTL: Shutting down the commissioner [1650579163.746125][17787:17787] CHIP:CTL: Shutting down the controller [1650579163.746157][17787:17787] CHIP:IN: Expiring all connections for fabric 1!! [1650579163.746205][17787:17787] CHIP:CTL: Shutting down the commissioner [1650579163.746287][17787:17787] CHIP:CTL: Shutting down the controller [1650579163.746424][17787:17787] CHIP:IN: Expiring all connections for fabric 2!! [1650579163.746466][17787:17787] CHIP:CTL: Shutting down the commissioner [1650579163.746552][17787:17787] CHIP:CTL: Shutting down the controller [1650579163.746576][17787:17787] CHIP:IN: Expiring all connections for fabric 3!! [1650579163.746607][17787:17787] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650579163.747800][17787:17787] CHIP:DMG: IM WH moving to [Uninitialized] [1650579163.747840][17787:17787] CHIP:DMG: IM WH moving to [Uninitialized] [1650579163.747866][17787:17787] CHIP:DMG: IM WH moving to [Uninitialized] [1650579163.747891][17787:17787] CHIP:DMG: IM WH moving to [Uninitialized] [1650579163.747919][17787:17787] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650579163.748127][17787:17787] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650579163.748425][17787:17787] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-HuUcfS) [1650579163.749166][17787:17787] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579163.749246][17787:17787] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650579163.749280][17787:17787] CHIP:DL: Inet Layer shutdown [1650579163.749307][17787:17787] CHIP:DL: BLE shutdown [1650579163.749335][17787:17787] CHIP:DL: System Layer shutdown ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 17 1 [1650579164.791132][17793:17793] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650579164.791370][17793:17793] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650579164.791916][17793:17793] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650579164.792134][17793:17793] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650579164.792252][17793:17793] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650579164.792615][17793:17793] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-g8qcGx) [1650579164.793251][17793:17793] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579164.793303][17793:17793] CHIP:DL: NVS set: chip-counters/reboot-count = 58 (0x3A) [1650579164.794251][17793:17793] CHIP:DL: Got Ethernet interface: eth0 [1650579164.794912][17793:17793] CHIP:DL: Found the primary Ethernet interface:eth0 [1650579164.795605][17793:17793] CHIP:DL: Got WiFi interface: wlan0 [1650579164.795685][17793:17793] CHIP:DL: Failed to reset WiFi statistic counts [1650579164.795789][17793:17793] CHIP:IN: UDP::Init bind&listen port=0 [1650579164.795934][17793:17793] CHIP:IN: UDP::Init bound to port=58367 [1650579164.795964][17793:17793] CHIP:IN: UDP::Init bind&listen port=0 [1650579164.796097][17793:17793] CHIP:IN: UDP::Init bound to port=60595 [1650579164.796125][17793:17793] CHIP:IN: BLEBase::Init - setting/overriding transport [1650579164.796149][17793:17793] CHIP:IN: TransportMgr initialized [1650579164.796204][17793:17793] CHIP:DIS: Init fabric pairing table with server storage [1650579164.796342][17793:17793] CHIP:IN: Loading from storage for fabric index 1 [1650579164.798972][17793:17793] CHIP:IN: Loading from storage for fabric index 2 [1650579164.799573][17793:17793] CHIP:IN: Loading from storage for fabric index 3 [1650579164.800182][17793:17793] CHIP:DIS: Add fabric pairing table delegate [1650579164.800466][17793:17793] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yrog9x) [1650579164.801175][17793:17793] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579164.801234][17793:17793] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 58000 (0xE290) [1650579164.804046][17793:17793] CHIP:ZCL: Using ZAP configuration... [1650579164.807227][17793:17793] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.814386][17793:17793] CHIP:DL: MDNS failed to join multicast group on vetha3d8a56 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.816205][17793:17793] CHIP:DL: MDNS failed to join multicast group on veth3191e7b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.817907][17793:17793] CHIP:DL: MDNS failed to join multicast group on veth6595114 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.819594][17793:17793] CHIP:DL: MDNS failed to join multicast group on vethee76aa7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.821373][17793:17793] CHIP:DL: MDNS failed to join multicast group on veth1c17fb7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579164.821755][17793:17793] CHIP:CTL: System State Initialized... [1650579164.821849][17793:17793] CHIP:CTL: Setting attestation nonce to random value [1650579164.821930][17793:17793] CHIP:CTL: Setting CSR nonce to random value [1650579164.822009][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.822106][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.822133][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.822219][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.822243][17793:17793] CHIP:IN: TransportMgr initialized [1650579164.822301][17793:17793] CHIP:CTL: Setting attestation nonce to random value [1650579164.822355][17793:17793] CHIP:CTL: Setting CSR nonce to random value [1650579164.823276][17793:17793] CHIP:CTL: Generating NOC [1650579164.824283][17793:17793] CHIP:DIS: Verifying the received credentials [1650579164.826016][17793:17793] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650579164.826052][17793:17793] CHIP:DIS: Assigned compressed fabric ID: 0x1CA619EC425B4FB0, node ID: 0x000000000001B669 [1650579164.826076][17793:17793] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x1CA619EC425B4FB0 [1650579164.826119][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.826256][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.826284][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.826374][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.826399][17793:17793] CHIP:IN: TransportMgr initialized [1650579164.826498][17793:17793] CHIP:CTL: Setting attestation nonce to random value [1650579164.826559][17793:17793] CHIP:CTL: Setting CSR nonce to random value [1650579164.827547][17793:17793] CHIP:CTL: Generating NOC [1650579164.828556][17793:17793] CHIP:DIS: Verifying the received credentials [1650579164.830406][17793:17793] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650579164.830462][17793:17793] CHIP:DIS: Assigned compressed fabric ID: 0x42F76D3950ED0C16, node ID: 0x000000000001B669 [1650579164.830487][17793:17793] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x42F76D3950ED0C16 [1650579164.830531][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.830681][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.830712][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.830810][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.830836][17793:17793] CHIP:IN: TransportMgr initialized [1650579164.830953][17793:17793] CHIP:CTL: Setting attestation nonce to random value [1650579164.831018][17793:17793] CHIP:CTL: Setting CSR nonce to random value [1650579164.832084][17793:17793] CHIP:CTL: Generating NOC [1650579164.833148][17793:17793] CHIP:DIS: Verifying the received credentials [1650579164.834992][17793:17793] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650579164.835049][17793:17793] CHIP:DIS: Assigned compressed fabric ID: 0x99A6E98698D73B9F, node ID: 0x000000000001B669 [1650579164.835074][17793:17793] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x99A6E98698D73B9F [1650579164.835120][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.835268][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.835302][17793:17793] CHIP:IN: UDP::Init bind&listen port=5550 [1650579164.835404][17793:17793] CHIP:IN: UDP::Init bound to port=5550 [1650579164.835430][17793:17793] CHIP:IN: TransportMgr initialized [1650579164.895075][17793:17798] CHIP:DL: CHIP task running [1650579164.896442][17793:17798] CHIP:TOO: Sending command to node 0x11 [1650579164.896504][17793:17798] CHIP:CSM: FindOrEstablishSession: PeerId = 1CA619EC425B4FB0:0000000000000011 [1650579164.896532][17793:17798] CHIP:CSM: FindOrEstablishSession: No existing session found [1650579164.897100][17793:17798] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579164.897351][17793:17798] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579164.897588][17793:17798] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579164.897805][17793:17798] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579164.900518][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.900613][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.900640][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.900663][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.901507][17793:17798] CHIP:DIS: Lookup clearing interface for non LL address [1650579164.901545][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: new best score: 7 [1650579164.901633][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.901705][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.901732][17793:17798] CHIP:DIS: Checking node lookup status after 5 ms [1650579164.901753][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.903982][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.904037][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.904065][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.904089][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.904112][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.904771][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.904858][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.904928][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.904954][17793:17798] CHIP:DIS: Checking node lookup status after 8 ms [1650579164.904975][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.906506][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.906538][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.906566][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.906591][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.906614][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.907242][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.907326][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.907394][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.907419][17793:17798] CHIP:DIS: Checking node lookup status after 11 ms [1650579164.907440][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.909468][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.909501][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.909529][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.909552][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.909574][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.910203][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.910291][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.910358][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.910384][17793:17798] CHIP:DIS: Checking node lookup status after 14 ms [1650579164.910405][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.912202][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.912234][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.912260][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.912283][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.912306][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.912929][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.913016][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.913083][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.913108][17793:17798] CHIP:DIS: Checking node lookup status after 17 ms [1650579164.913129][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.915063][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.915094][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.915121][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.915144][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.915166][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.915819][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.915906][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.915972][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.916017][17793:17798] CHIP:DIS: Checking node lookup status after 20 ms [1650579164.916036][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.918328][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.918361][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.918390][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.918414][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.918438][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.919119][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.919210][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.919282][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.919309][17793:17798] CHIP:DIS: Checking node lookup status after 23 ms [1650579164.919332][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.921169][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.921204][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.921232][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.921257][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.921280][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.921947][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.922038][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.922114][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.922141][17793:17798] CHIP:DIS: Checking node lookup status after 26 ms [1650579164.922163][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.923868][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.923900][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.923928][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.923953][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.923977][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.924809][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.924901][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.924976][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.925005][17793:17798] CHIP:DIS: Checking node lookup status after 29 ms [1650579164.925029][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.926615][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.926648][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.926677][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.926709][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.926742][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.927699][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.927817][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.927916][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.927954][17793:17798] CHIP:DIS: Checking node lookup status after 31 ms [1650579164.927988][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.930098][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.930157][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.930197][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.930233][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.930268][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.931234][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.931363][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.931468][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.931506][17793:17798] CHIP:DIS: Checking node lookup status after 35 ms [1650579164.931538][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.932515][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.932562][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.932603][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.932638][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.932673][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.933608][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.933733][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.933834][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.933871][17793:17798] CHIP:DIS: Checking node lookup status after 37 ms [1650579164.933903][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.935301][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.935469][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.935511][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.935546][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.935579][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.936527][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.936645][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.936752][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.936790][17793:17798] CHIP:DIS: Checking node lookup status after 40 ms [1650579164.936822][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.938921][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.938956][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.938988][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.939017][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.939044][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.939780][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.939880][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.939968][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.940110][17793:17798] CHIP:DIS: Checking node lookup status after 44 ms [1650579164.940138][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.941654][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.941687][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.941720][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.941749][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.941776][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.942498][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.942591][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.942673][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.942703][17793:17798] CHIP:DIS: Checking node lookup status after 46 ms [1650579164.942730][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.944448][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.944481][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.944513][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.944542][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.944569][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.945269][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.945360][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.945447][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.945478][17793:17798] CHIP:DIS: Checking node lookup status after 49 ms [1650579164.945505][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.947313][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.947363][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.947402][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.947435][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.947466][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.948393][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.948519][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.948616][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.948652][17793:17798] CHIP:DIS: Checking node lookup status after 52 ms [1650579164.948681][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579164.950957][17793:17798] CHIP:DIS: Discovered node without a pending query [1650579164.951003][17793:17798] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579164.951040][17793:17798] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579164.951072][17793:17798] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579164.951103][17793:17798] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579164.951966][17793:17798] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579164.952204][17793:17798] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579164.952295][17793:17798] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579164.952329][17793:17798] CHIP:DIS: Checking node lookup status after 56 ms [1650579164.952358][17793:17798] CHIP:DIS: Keeping DNSSD lookup active [1650579165.096846][17793:17798] CHIP:DIS: Checking node lookup status after 200 ms [1650579165.096928][17793:17798] CHIP:CTL: Updating device address to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 while in state 1 [1650579165.096954][17793:17798] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 1 --> 2 [1650579165.097119][17793:17798] CHIP:SC: Establishing CASE session to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579165.097729][17793:17798] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaab118fc830, Got IPK for FabricIndex 1 [1650579165.097784][17793:17798] CHIP:SC: 0x17, 0x9a, 0xb1, 0x3b, 0xb3, 0xab, 0x9c, 0xb8, [1650579165.097809][17793:17798] CHIP:SC: 0x6d, 0xff, 0x25, 0xaa, 0xf0, 0xf5, 0xf9, 0x4e, [1650579165.097946][17793:17798] CHIP:SC: Including MRP parameters [1650579165.098036][17793:17798] CHIP:IN: Prepared unauthenticated message 0xaaab11e36d38 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 50802i with MessageCounter:652977138. [1650579165.098125][17793:17798] CHIP:IN: Sending unauthenticated msg 0xaaab11e36d38 with MessageCounter:652977138 to 0x0000000000000000 at monotonic time: 000000000117F3A6 msec [1650579165.098319][17793:17798] CHIP:SC: Sent Sigma1 msg [1650579165.098354][17793:17798] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 2 --> 3 [1650579165.098385][17793:17798] CHIP:DIS: Discovery does not require any more timeouts [1650579165.101141][17793:17798] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:4016368036 on exchange 50802i [1650579165.101213][17793:17798] CHIP:EM: Found matching exchange: 50802i, Delegate: 0xffff6c002820 [1650579165.101261][17793:17798] CHIP:EM: Rxd Ack; Removing MessageCounter:652977138 from Retrans Table on exchange 50802i [1650579165.101288][17793:17798] CHIP:EM: Removed CHIP MessageCounter:652977138 from RetransTable on exchange 50802i [1650579165.101328][17793:17798] CHIP:SC: Received Sigma2 msg [1650579165.101366][17793:17798] CHIP:SC: Peer assigned session session ID 20566 [1650579165.101990][17793:17798] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1650579165.104767][17793:17798] CHIP:SC: Found MRP parameters in the message [1650579165.104839][17793:17798] CHIP:SC: Sending Sigma3 [1650579165.105186][17793:17798] CHIP:EM: Piggybacking Ack for MessageCounter:4016368036 on exchange: 50802i [1650579165.105258][17793:17798] CHIP:IN: Prepared unauthenticated message 0xaaab11e36d38 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 50802i with MessageCounter:652977139. [1650579165.105304][17793:17798] CHIP:IN: Sending unauthenticated msg 0xaaab11e36d38 with MessageCounter:652977139 to 0x0000000000000000 at monotonic time: 000000000117F3AD msec [1650579165.105509][17793:17798] CHIP:SC: Sent Sigma3 msg [1650579165.110285][17793:17798] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4016368037 on exchange 50802i [1650579165.110348][17793:17798] CHIP:EM: Found matching exchange: 50802i, Delegate: 0xffff6c002820 [1650579165.110394][17793:17798] CHIP:EM: Rxd Ack; Removing MessageCounter:652977139 from Retrans Table on exchange 50802i [1650579165.110420][17793:17798] CHIP:EM: Removed CHIP MessageCounter:652977139 from RetransTable on exchange 50802i [1650579165.110460][17793:17798] CHIP:SC: Success status report received. Session was established [1650579165.110490][17793:17798] CHIP:IN: New secure session created for device 0x0000000000000011, LSID:21155 PSID:20566! [1650579165.110569][17793:17798] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 3 --> 4 [1650579165.110630][17793:17798] CHIP:TOO: Sending ReadAttribute to: [1650579165.110658][17793:17798] CHIP:TOO: cluster 0x0000_0101, attribute: 0x0000_FFFD, endpoint 1 [1650579165.110721][17793:17798] CHIP:DMG: SendReadRequest ReadClient[0xffff6c001e00]: Sending Read Request [1650579165.110845][17793:17798] CHIP:IN: Prepared secure message 0xaaab11e36d38 to 0x0000000000000011 (1) of type 0x2 and protocolId (0, 1) on exchange 50803i with MessageCounter:4106407. [1650579165.110890][17793:17798] CHIP:IN: Sending encrypted msg 0xaaab11e36d38 with MessageCounter:4106407 to 0x0000000000000011 (1) at monotonic time: 000000000117F3B2 msec [1650579165.111062][17793:17798] CHIP:DMG: MoveToState ReadClient[0xffff6c001e00]: Moving to [AwaitingIn] [1650579165.111104][17793:17798] CHIP:EM: Sending Standalone Ack for MessageCounter:4016368037 on exchange 50802i [1650579165.111142][17793:17798] CHIP:IN: Prepared unauthenticated message 0xffff7efdd9a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 50802i with MessageCounter:652977140. [1650579165.111178][17793:17798] CHIP:IN: Sending unauthenticated msg 0xffff7efdd9a8 with MessageCounter:652977140 to 0x0000000000000000 at monotonic time: 000000000117F3B3 msec [1650579165.111261][17793:17798] CHIP:EM: Flushed pending ack for MessageCounter:4016368037 on exchange 50802i [1650579165.113096][17793:17798] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:8925379 on exchange 50803i [1650579165.113142][17793:17798] CHIP:EM: Found matching exchange: 50803i, Delegate: 0xffff6c001e00 [1650579165.113181][17793:17798] CHIP:EM: Rxd Ack; Removing MessageCounter:4106407 from Retrans Table on exchange 50803i [1650579165.113206][17793:17798] CHIP:EM: Removed CHIP MessageCounter:4106407 from RetransTable on exchange 50803i [1650579165.113267][17793:17798] CHIP:DMG: ReportDataMessage = [1650579165.113297][17793:17798] CHIP:DMG: { [1650579165.113320][17793:17798] CHIP:DMG: AttributeReportIBs = [1650579165.113357][17793:17798] CHIP:DMG: [ [1650579165.113383][17793:17798] CHIP:DMG: AttributeReportIB = [1650579165.113423][17793:17798] CHIP:DMG: { [1650579165.113453][17793:17798] CHIP:DMG: AttributeDataIB = [1650579165.113490][17793:17798] CHIP:DMG: { [1650579165.113527][17793:17798] CHIP:DMG: DataVersion = 0xa9cace8e, [1650579165.113562][17793:17798] CHIP:DMG: AttributePathIB = [1650579165.113599][17793:17798] CHIP:DMG: { [1650579165.113637][17793:17798] CHIP:DMG: Endpoint = 0x1, [1650579165.113676][17793:17798] CHIP:DMG: Cluster = 0x101, [1650579165.113715][17793:17798] CHIP:DMG: Attribute = 0x0000_FFFD, [1650579165.113750][17793:17798] CHIP:DMG: } [1650579165.113789][17793:17798] CHIP:DMG: [1650579165.113827][17793:17798] CHIP:DMG: Data = 3, [1650579165.113863][17793:17798] CHIP:DMG: }, [1650579165.113903][17793:17798] CHIP:DMG: [1650579165.113931][17793:17798] CHIP:DMG: }, [1650579165.113964][17793:17798] CHIP:DMG: [1650579165.113987][17793:17798] CHIP:DMG: ], [1650579165.114017][17793:17798] CHIP:DMG: [1650579165.114042][17793:17798] CHIP:DMG: SuppressResponse = true, [1650579165.114071][17793:17798] CHIP:DMG: InteractionModelRevision = 1 [1650579165.114098][17793:17798] CHIP:DMG: } [1650579165.114244][17793:17798] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Attribute 0x0000_FFFD DataVersion: 2848640654 [1650579165.114326][17793:17798] CHIP:TOO: ClusterRevision: 3 [1650579165.114411][17793:17798] CHIP:EM: Sending Standalone Ack for MessageCounter:8925379 on exchange 50803i [1650579165.114485][17793:17798] CHIP:IN: Prepared secure message 0xffff7efdd9b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 50803i with MessageCounter:4106408. [1650579165.114527][17793:17798] CHIP:IN: Sending encrypted msg 0xffff7efdd9b8 with MessageCounter:4106408 to 0x0000000000000011 (1) at monotonic time: 000000000117F3B6 msec [1650579165.114648][17793:17798] CHIP:EM: Flushed pending ack for MessageCounter:8925379 on exchange 50803i [1650579165.114862][17793:17793] CHIP:CTL: Shutting down the commissioner [1650579165.115008][17793:17793] CHIP:CTL: Shutting down the controller [1650579165.115043][17793:17793] CHIP:CTL: Shutting down the commissioner [1650579165.115125][17793:17793] CHIP:CTL: Shutting down the controller [1650579165.115178][17793:17793] CHIP:IN: Expiring all connections for fabric 1!! [1650579165.115234][17793:17793] CHIP:CTL: Shutting down the commissioner [1650579165.115328][17793:17793] CHIP:CTL: Shutting down the controller [1650579165.115356][17793:17793] CHIP:IN: Expiring all connections for fabric 2!! [1650579165.115395][17793:17793] CHIP:CTL: Shutting down the commissioner [1650579165.115483][17793:17793] CHIP:CTL: Shutting down the controller [1650579165.115507][17793:17793] CHIP:IN: Expiring all connections for fabric 3!! [1650579165.115539][17793:17793] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650579165.116809][17793:17793] CHIP:DMG: IM WH moving to [Uninitialized] [1650579165.116853][17793:17793] CHIP:DMG: IM WH moving to [Uninitialized] [1650579165.116874][17793:17793] CHIP:DMG: IM WH moving to [Uninitialized] [1650579165.116893][17793:17793] CHIP:DMG: IM WH moving to [Uninitialized] [1650579165.116915][17793:17793] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650579165.117001][17793:17793] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650579165.117269][17793:17793] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-SGl0ux) [1650579165.117926][17793:17793] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579165.117992][17793:17793] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650579165.118019][17793:17793] CHIP:DL: Inet Layer shutdown [1650579165.118041][17793:17793] CHIP:DL: BLE shutdown [1650579165.118065][17793:17793] CHIP:DL: System Layer shutdown ubuntu@controller:~/TE/stableBuild/connectedhomeip$ ./out/debug/standalone/chip-tool doorlock read cluster-revision 17 1 [1650579166.415794][17799:17799] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1650579166.416095][17799:17799] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_device_info.ini [1650579166.416615][17799:17799] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1650579166.416828][17799:17799] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1650579166.416946][17799:17799] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1650579166.417331][17799:17799] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-3KWgLN) [1650579166.418050][17799:17799] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579166.418131][17799:17799] CHIP:DL: NVS set: chip-counters/reboot-count = 59 (0x3B) [1650579166.419139][17799:17799] CHIP:DL: Got Ethernet interface: eth0 [1650579166.419927][17799:17799] CHIP:DL: Found the primary Ethernet interface:eth0 [1650579166.420737][17799:17799] CHIP:DL: Got WiFi interface: wlan0 [1650579166.420832][17799:17799] CHIP:DL: Failed to reset WiFi statistic counts [1650579166.420956][17799:17799] CHIP:IN: UDP::Init bind&listen port=0 [1650579166.421124][17799:17799] CHIP:IN: UDP::Init bound to port=36929 [1650579166.421155][17799:17799] CHIP:IN: UDP::Init bind&listen port=0 [1650579166.421263][17799:17799] CHIP:IN: UDP::Init bound to port=36020 [1650579166.421288][17799:17799] CHIP:IN: BLEBase::Init - setting/overriding transport [1650579166.421310][17799:17799] CHIP:IN: TransportMgr initialized [1650579166.421364][17799:17799] CHIP:DIS: Init fabric pairing table with server storage [1650579166.421526][17799:17799] CHIP:IN: Loading from storage for fabric index 1 [1650579166.424193][17799:17799] CHIP:IN: Loading from storage for fabric index 2 [1650579166.424969][17799:17799] CHIP:IN: Loading from storage for fabric index 3 [1650579166.425659][17799:17799] CHIP:DIS: Add fabric pairing table delegate [1650579166.426000][17799:17799] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-unsao4) [1650579166.426647][17799:17799] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579166.426706][17799:17799] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 59000 (0xE678) [1650579166.429563][17799:17799] CHIP:ZCL: Using ZAP configuration... [1650579166.433033][17799:17799] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.440658][17799:17799] CHIP:DL: MDNS failed to join multicast group on vetha3d8a56 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.442507][17799:17799] CHIP:DL: MDNS failed to join multicast group on veth3191e7b for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.444607][17799:17799] CHIP:DL: MDNS failed to join multicast group on veth6595114 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.446468][17799:17799] CHIP:DL: MDNS failed to join multicast group on vethee76aa7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.448408][17799:17799] CHIP:DL: MDNS failed to join multicast group on veth1c17fb7 for address type IPv4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found [1650579166.448808][17799:17799] CHIP:CTL: System State Initialized... [1650579166.448911][17799:17799] CHIP:CTL: Setting attestation nonce to random value [1650579166.449008][17799:17799] CHIP:CTL: Setting CSR nonce to random value [1650579166.449099][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.449204][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.449230][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.449323][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.449348][17799:17799] CHIP:IN: TransportMgr initialized [1650579166.449408][17799:17799] CHIP:CTL: Setting attestation nonce to random value [1650579166.449462][17799:17799] CHIP:CTL: Setting CSR nonce to random value [1650579166.450398][17799:17799] CHIP:CTL: Generating NOC [1650579166.451364][17799:17799] CHIP:DIS: Verifying the received credentials [1650579166.453441][17799:17799] CHIP:DIS: Added new fabric at index: 1, Initialized: 1 [1650579166.453503][17799:17799] CHIP:DIS: Assigned compressed fabric ID: 0x1CA619EC425B4FB0, node ID: 0x000000000001B669 [1650579166.453527][17799:17799] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x1CA619EC425B4FB0 [1650579166.453578][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.453722][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.453750][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.453845][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.453868][17799:17799] CHIP:IN: TransportMgr initialized [1650579166.453982][17799:17799] CHIP:CTL: Setting attestation nonce to random value [1650579166.454045][17799:17799] CHIP:CTL: Setting CSR nonce to random value [1650579166.454901][17799:17799] CHIP:CTL: Generating NOC [1650579166.455839][17799:17799] CHIP:DIS: Verifying the received credentials [1650579166.457614][17799:17799] CHIP:DIS: Added new fabric at index: 2, Initialized: 1 [1650579166.457708][17799:17799] CHIP:DIS: Assigned compressed fabric ID: 0x42F76D3950ED0C16, node ID: 0x000000000001B669 [1650579166.457734][17799:17799] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x42F76D3950ED0C16 [1650579166.457779][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.457918][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.457946][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.458042][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.458067][17799:17799] CHIP:IN: TransportMgr initialized [1650579166.458177][17799:17799] CHIP:CTL: Setting attestation nonce to random value [1650579166.458242][17799:17799] CHIP:CTL: Setting CSR nonce to random value [1650579166.459091][17799:17799] CHIP:CTL: Generating NOC [1650579166.460139][17799:17799] CHIP:DIS: Verifying the received credentials [1650579166.461909][17799:17799] CHIP:DIS: Added new fabric at index: 3, Initialized: 1 [1650579166.461959][17799:17799] CHIP:DIS: Assigned compressed fabric ID: 0x99A6E98698D73B9F, node ID: 0x000000000001B669 [1650579166.461984][17799:17799] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x99A6E98698D73B9F [1650579166.462029][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.462178][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.462206][17799:17799] CHIP:IN: UDP::Init bind&listen port=5550 [1650579166.462298][17799:17799] CHIP:IN: UDP::Init bound to port=5550 [1650579166.462322][17799:17799] CHIP:IN: TransportMgr initialized [1650579166.502822][17799:17804] CHIP:DL: CHIP task running [1650579166.504144][17799:17804] CHIP:TOO: Sending command to node 0x11 [1650579166.504202][17799:17804] CHIP:CSM: FindOrEstablishSession: PeerId = 1CA619EC425B4FB0:0000000000000011 [1650579166.504231][17799:17804] CHIP:CSM: FindOrEstablishSession: No existing session found [1650579166.504820][17799:17804] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579166.505046][17799:17804] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579166.505243][17799:17804] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on br-a8036eb609c4: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579166.505430][17799:17804] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on otbr0: ../../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1650579166.508340][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.508408][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.508432][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.508454][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.509310][17799:17804] CHIP:DIS: Lookup clearing interface for non LL address [1650579166.509356][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: new best score: 7 [1650579166.509469][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.509543][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.509570][17799:17804] CHIP:DIS: Checking node lookup status after 5 ms [1650579166.509592][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.511101][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.511147][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.511174][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.511198][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.511220][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.511915][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.512047][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.512126][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.512153][17799:17804] CHIP:DIS: Checking node lookup status after 8 ms [1650579166.512175][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.514222][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.514268][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.514296][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.514319][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.514341][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.515057][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.515159][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.515233][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.515259][17799:17804] CHIP:DIS: Checking node lookup status after 11 ms [1650579166.515281][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.517348][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.517404][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.517462][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.517487][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.517509][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.518241][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.518353][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.518434][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.518463][17799:17804] CHIP:DIS: Checking node lookup status after 14 ms [1650579166.518485][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.519949][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.520022][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.520063][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.520088][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.520110][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.520836][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.520944][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.521019][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.521047][17799:17804] CHIP:DIS: Checking node lookup status after 17 ms [1650579166.521070][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.523065][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.523105][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.523134][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.523157][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.523179][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.523871][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.523987][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.524090][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.524117][17799:17804] CHIP:DIS: Checking node lookup status after 20 ms [1650579166.524138][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.526838][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.526878][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.526906][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.526928][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.526950][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.527635][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.527739][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.527811][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.527839][17799:17804] CHIP:DIS: Checking node lookup status after 23 ms [1650579166.527861][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.530061][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.530117][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.530148][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.530171][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.530193][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.530968][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.531106][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.531178][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.531207][17799:17804] CHIP:DIS: Checking node lookup status after 27 ms [1650579166.531230][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.533196][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.533253][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.533284][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.533307][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.533329][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.534106][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.534244][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.534316][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.534345][17799:17804] CHIP:DIS: Checking node lookup status after 30 ms [1650579166.534367][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.537005][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.537066][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.537098][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.537121][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.537143][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.537923][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.538061][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.538131][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.538160][17799:17804] CHIP:DIS: Checking node lookup status after 34 ms [1650579166.538182][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.540219][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.540273][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.540306][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.540330][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.540351][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.541118][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.541244][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.541318][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.541347][17799:17804] CHIP:DIS: Checking node lookup status after 37 ms [1650579166.541370][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.543283][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.543337][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.543369][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.543392][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.543413][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.544285][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.544422][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.544499][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.544527][17799:17804] CHIP:DIS: Checking node lookup status after 40 ms [1650579166.544549][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.546468][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.546529][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.546559][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.546583][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.546604][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.547356][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.547481][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.547556][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.547584][17799:17804] CHIP:DIS: Checking node lookup status after 43 ms [1650579166.547607][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.549839][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.549899][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.549932][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.549955][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.549976][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.550718][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.550896][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.550974][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.551003][17799:17804] CHIP:DIS: Checking node lookup status after 47 ms [1650579166.551026][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.552615][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.552666][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.552696][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.552719][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.552740][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.553469][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.553570][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.553640][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.553666][17799:17804] CHIP:DIS: Checking node lookup status after 49 ms [1650579166.553688][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.555353][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.555408][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.555438][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.555461][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.555482][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.556365][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.556473][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.556545][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.556572][17799:17804] CHIP:DIS: Checking node lookup status after 52 ms [1650579166.556594][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.558908][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.558960][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.558991][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.559014][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.559035][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.559748][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.559842][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.559915][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.559942][17799:17804] CHIP:DIS: Checking node lookup status after 55 ms [1650579166.559964][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.561528][17799:17804] CHIP:DIS: Discovered node without a pending query [1650579166.561559][17799:17804] CHIP:DIS: Node ID resolved for 1CA619EC425B4FB0:0000000000000011 [1650579166.561586][17799:17804] CHIP:DIS: Addr 0: [2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.561609][17799:17804] CHIP:DIS: Addr 1: [fe80::dea6:32ff:fe8d:6e32]:5540 [1650579166.561631][17799:17804] CHIP:DIS: Addr 2: [17.44.37.53]:5540 [1650579166.562269][17799:17804] CHIP:DIS: UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 7 [1650579166.562352][17799:17804] CHIP:DIS: UDP:[fe80::dea6:32ff:fe8d:6e32%eth0]:5540: score has not improved: 3 [1650579166.562422][17799:17804] CHIP:DIS: UDP:17.44.37.53%eth0:5540: score has not improved: 2 [1650579166.562447][17799:17804] CHIP:DIS: Checking node lookup status after 58 ms [1650579166.562469][17799:17804] CHIP:DIS: Keeping DNSSD lookup active [1650579166.704099][17799:17804] CHIP:DIS: Checking node lookup status after 200 ms [1650579166.704179][17799:17804] CHIP:CTL: Updating device address to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 while in state 1 [1650579166.704205][17799:17804] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 1 --> 2 [1650579166.704377][17799:17804] CHIP:SC: Establishing CASE session to UDP:[2620:149:af:2820:dea6:32ff:fe8d:6e32]:5540 [1650579166.705024][17799:17804] CHIP:SC: RecoverInitiatorIpk: GroupDataProvider 0xaaaaf8a28830, Got IPK for FabricIndex 1 [1650579166.705074][17799:17804] CHIP:SC: 0x17, 0x9a, 0xb1, 0x3b, 0xb3, 0xab, 0x9c, 0xb8, [1650579166.705103][17799:17804] CHIP:SC: 0x6d, 0xff, 0x25, 0xaa, 0xf0, 0xf5, 0xf9, 0x4e, [1650579166.705246][17799:17804] CHIP:SC: Including MRP parameters [1650579166.705335][17799:17804] CHIP:IN: Prepared unauthenticated message 0xaaaaf8f62d18 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 23654i with MessageCounter:1816963361. [1650579166.705389][17799:17804] CHIP:IN: Sending unauthenticated msg 0xaaaaf8f62d18 with MessageCounter:1816963361 to 0x0000000000000000 at monotonic time: 000000000117F9ED msec [1650579166.705588][17799:17804] CHIP:SC: Sent Sigma1 msg [1650579166.705628][17799:17804] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 2 --> 3 [1650579166.705662][17799:17804] CHIP:DIS: Discovery does not require any more timeouts [1650579166.708531][17799:17804] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:4016368038 on exchange 23654i [1650579166.708589][17799:17804] CHIP:EM: Found matching exchange: 23654i, Delegate: 0xffff8c002450 [1650579166.708638][17799:17804] CHIP:EM: Rxd Ack; Removing MessageCounter:1816963361 from Retrans Table on exchange 23654i [1650579166.708668][17799:17804] CHIP:EM: Removed CHIP MessageCounter:1816963361 from RetransTable on exchange 23654i [1650579166.708707][17799:17804] CHIP:SC: Received Sigma2 msg [1650579166.708747][17799:17804] CHIP:SC: Peer assigned session session ID 20567 [1650579166.709428][17799:17804] CHIP:SC: The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures. [1650579166.712536][17799:17804] CHIP:SC: Found MRP parameters in the message [1650579166.712610][17799:17804] CHIP:SC: Sending Sigma3 [1650579166.712984][17799:17804] CHIP:EM: Piggybacking Ack for MessageCounter:4016368038 on exchange: 23654i [1650579166.713057][17799:17804] CHIP:IN: Prepared unauthenticated message 0xaaaaf8f62d18 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 23654i with MessageCounter:1816963362. [1650579166.713108][17799:17804] CHIP:IN: Sending unauthenticated msg 0xaaaaf8f62d18 with MessageCounter:1816963362 to 0x0000000000000000 at monotonic time: 000000000117F9F5 msec [1650579166.713327][17799:17804] CHIP:SC: Sent Sigma3 msg [1650579166.717605][17799:17804] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4016368039 on exchange 23654i [1650579166.717680][17799:17804] CHIP:EM: Found matching exchange: 23654i, Delegate: 0xffff8c002450 [1650579166.717736][17799:17804] CHIP:EM: Rxd Ack; Removing MessageCounter:1816963362 from Retrans Table on exchange 23654i [1650579166.717765][17799:17804] CHIP:EM: Removed CHIP MessageCounter:1816963362 from RetransTable on exchange 23654i [1650579166.717810][17799:17804] CHIP:SC: Success status report received. Session was established [1650579166.717845][17799:17804] CHIP:IN: New secure session created for device 0x0000000000000011, LSID:50279 PSID:20567! [1650579166.717938][17799:17804] CHIP:CTL: OperationalDeviceProxy[1CA619EC425B4FB0:0000000000000011]: State change 3 --> 4 [1650579166.718008][17799:17804] CHIP:TOO: Sending ReadAttribute to: [1650579166.718039][17799:17804] CHIP:TOO: cluster 0x0000_0101, attribute: 0x0000_FFFD, endpoint 1 [1650579166.718085][17799:17804] CHIP:DMG: SendReadRequest ReadClient[0xffff8c001b10]: Sending Read Request [1650579166.718219][17799:17804] CHIP:IN: Prepared secure message 0xaaaaf8f62d18 to 0x0000000000000011 (1) of type 0x2 and protocolId (0, 1) on exchange 23655i with MessageCounter:10081879. [1650579166.718266][17799:17804] CHIP:IN: Sending encrypted msg 0xaaaaf8f62d18 with MessageCounter:10081879 to 0x0000000000000011 (1) at monotonic time: 000000000117F9FA msec [1650579166.718450][17799:17804] CHIP:DMG: MoveToState ReadClient[0xffff8c001b10]: Moving to [AwaitingIn] [1650579166.718496][17799:17804] CHIP:EM: Sending Standalone Ack for MessageCounter:4016368039 on exchange 23654i [1650579166.718536][17799:17804] CHIP:IN: Prepared unauthenticated message 0xffffa0acd9a8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 23654i with MessageCounter:1816963363. [1650579166.718574][17799:17804] CHIP:IN: Sending unauthenticated msg 0xffffa0acd9a8 with MessageCounter:1816963363 to 0x0000000000000000 at monotonic time: 000000000117F9FA msec [1650579166.718661][17799:17804] CHIP:EM: Flushed pending ack for MessageCounter:4016368039 on exchange 23654i [1650579166.720324][17799:17804] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:926543 on exchange 23655i [1650579166.720363][17799:17804] CHIP:EM: Found matching exchange: 23655i, Delegate: 0xffff8c001b10 [1650579166.720404][17799:17804] CHIP:EM: Rxd Ack; Removing MessageCounter:10081879 from Retrans Table on exchange 23655i [1650579166.720433][17799:17804] CHIP:EM: Removed CHIP MessageCounter:10081879 from RetransTable on exchange 23655i [1650579166.720497][17799:17804] CHIP:DMG: ReportDataMessage = [1650579166.720530][17799:17804] CHIP:DMG: { [1650579166.720554][17799:17804] CHIP:DMG: AttributeReportIBs = [1650579166.720590][17799:17804] CHIP:DMG: [ [1650579166.720619][17799:17804] CHIP:DMG: AttributeReportIB = [1650579166.720666][17799:17804] CHIP:DMG: { [1650579166.720699][17799:17804] CHIP:DMG: AttributeDataIB = [1650579166.720735][17799:17804] CHIP:DMG: { [1650579166.720771][17799:17804] CHIP:DMG: DataVersion = 0xa9cace8e, [1650579166.720809][17799:17804] CHIP:DMG: AttributePathIB = [1650579166.720847][17799:17804] CHIP:DMG: { [1650579166.720883][17799:17804] CHIP:DMG: Endpoint = 0x1, [1650579166.720926][17799:17804] CHIP:DMG: Cluster = 0x101, [1650579166.720970][17799:17804] CHIP:DMG: Attribute = 0x0000_FFFD, [1650579166.721010][17799:17804] CHIP:DMG: } [1650579166.721052][17799:17804] CHIP:DMG: [1650579166.721092][17799:17804] CHIP:DMG: Data = 3, [1650579166.721128][17799:17804] CHIP:DMG: }, [1650579166.721163][17799:17804] CHIP:DMG: [1650579166.721194][17799:17804] CHIP:DMG: }, [1650579166.721231][17799:17804] CHIP:DMG: [1650579166.721258][17799:17804] CHIP:DMG: ], [1650579166.721293][17799:17804] CHIP:DMG: [1650579166.721321][17799:17804] CHIP:DMG: SuppressResponse = true, [1650579166.721350][17799:17804] CHIP:DMG: InteractionModelRevision = 1 [1650579166.721376][17799:17804] CHIP:DMG: } [1650579166.721538][17799:17804] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Attribute 0x0000_FFFD DataVersion: 2848640654 [1650579166.721625][17799:17804] CHIP:TOO: ClusterRevision: 3 [1650579166.721714][17799:17804] CHIP:EM: Sending Standalone Ack for MessageCounter:926543 on exchange 23655i [1650579166.721786][17799:17804] CHIP:IN: Prepared secure message 0xffffa0acd9b8 to 0x0000000000000011 (1) of type 0x10 and protocolId (0, 0) on exchange 23655i with MessageCounter:10081880. [1650579166.721828][17799:17804] CHIP:IN: Sending encrypted msg 0xffffa0acd9b8 with MessageCounter:10081880 to 0x0000000000000011 (1) at monotonic time: 000000000117F9FD msec [1650579166.721949][17799:17804] CHIP:EM: Flushed pending ack for MessageCounter:926543 on exchange 23655i [1650579166.722155][17799:17799] CHIP:CTL: Shutting down the commissioner [1650579166.722308][17799:17799] CHIP:CTL: Shutting down the controller [1650579166.722345][17799:17799] CHIP:CTL: Shutting down the commissioner [1650579166.722433][17799:17799] CHIP:CTL: Shutting down the controller [1650579166.722479][17799:17799] CHIP:IN: Expiring all connections for fabric 1!! [1650579166.722531][17799:17799] CHIP:CTL: Shutting down the commissioner [1650579166.722636][17799:17799] CHIP:CTL: Shutting down the controller [1650579166.722663][17799:17799] CHIP:IN: Expiring all connections for fabric 2!! [1650579166.722720][17799:17799] CHIP:CTL: Shutting down the commissioner [1650579166.722824][17799:17799] CHIP:CTL: Shutting down the controller [1650579166.722851][17799:17799] CHIP:IN: Expiring all connections for fabric 3!! [1650579166.722896][17799:17799] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1650579166.724291][17799:17799] CHIP:DMG: IM WH moving to [Uninitialized] [1650579166.724326][17799:17799] CHIP:DMG: IM WH moving to [Uninitialized] [1650579166.724349][17799:17799] CHIP:DMG: IM WH moving to [Uninitialized] [1650579166.724372][17799:17799] CHIP:DMG: IM WH moving to [Uninitialized] [1650579166.724397][17799:17799] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1650579166.724500][17799:17799] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1650579166.724806][17799:17799] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-aGTlPk) [1650579166.725505][17799:17799] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1650579166.725687][17799:17799] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1650579166.725736][17799:17799] CHIP:DL: Inet Layer shutdown [1650579166.725762][17799:17799] CHIP:DL: BLE shutdown [1650579166.725788][17799:17799] CHIP:DL: System Layer shutdown