pi@ubuntu:~/connectedhomeip$ rm -rf /tmp/chip_* pi@ubuntu:~/connectedhomeip$ ./src/app/ota_image_tool.py create -v 0xFFF1 -p 0x8005 -vn 99 -vs "1.0" -da sha256 /home/pi/connectedhomeip/out/ota/BRD4164A/otaImage.txt /home/pi/connectedhomeip/out/ota/BRD4164A/chip-efr32-lighting-example.ota pi@ubuntu:~/connectedhomeip$ ./out/debug/chip-ota-provider-app -f /home/pi/connectedhomeip/out/ota/BRD4164A/chip-efr32-lighting-example.ota -q busy -t 180 [1652388125.316301][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388125.316628][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Wg1RpB) [1652388125.316847][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388125.322102][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1652388125.322155][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1652388125.322512][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1652388125.322759][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-cfBg5c) [1652388125.322949][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388125.323061][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1652388125.323187][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-YLJEsJ) [1652388125.323317][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388125.323404][1890:1890] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1652388125.323512][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CdAzi2) [1652388125.323634][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388125.323893][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-vRpjvD) [1652388125.324416][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388125.324469][1890:1890] CHIP:DL: NVS set: chip-factory/unique-id = "6ADA30B15FC3A66C" [1652388125.324622][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-RTwlrt) [1652388125.326152][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388125.326205][1890:1890] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1652388125.326346][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-FCURpK) [1652388125.326959][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1652388125.327006][1890:1890] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1652388125.327138][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-9sJBWn) [1652388125.327499][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388125.327542][1890:1890] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1652388125.327748][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8M5AlU) [1652388125.328652][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388125.328706][1890:1890] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388125.328859][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-M2Pl7D) [1652388125.329498][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388125.329548][1890:1890] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1652388125.329685][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-ytzwIB) [1652388125.330054][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388125.330100][1890:1890] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1652388125.330297][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-zeTY3k) [1652388125.331255][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388125.331311][1890:1890] CHIP:DL: NVS set: chip-config/location-capability = 0 (0x0) [1652388125.331956][1890:1890] CHIP:DL: Got Ethernet interface: eth0 [1652388125.332392][1890:1890] CHIP:DL: Found the primary Ethernet interface:eth0 [1652388125.332838][1890:1890] CHIP:DL: Got WiFi interface: wlan0 [1652388125.338656][1890:1890] CHIP:DL: Found the primary WiFi interface:wlan0 [1652388125.338714][1890:1890] CHIP:SPT: *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. *** [1652388125.338745][1890:1890] CHIP:SPT: *** WARNING: Using temporary test discriminator 3840 due to --discriminator not given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure discriminator. *** [1652388125.338771][1890:1890] CHIP:SPT: PASE PBKDF iterations set to 1000 [1652388125.338804][1890:1890] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one. [1652388125.346021][1890:1890] CHIP:DL: Device Configuration: [1652388125.346092][1890:1890] CHIP:DL: Serial Number: TEST_SN [1652388125.346143][1890:1890] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1652388125.346196][1890:1890] CHIP:DL: Product Id: 32769 (0x8001) [1652388125.346243][1890:1890] CHIP:DL: Hardware Version: 0 [1652388125.346277][1890:1890] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1652388125.346308][1890:1890] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1652388125.346349][1890:1890] CHIP:DL: Manufacturing Date: (not set) [1652388125.346383][1890:1890] CHIP:DL: Device Type: 65535 (0xFFFF) [1652388125.346413][1890:1890] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ==== [1652388125.346485][1890:1890] CHIP:SVR: SetupQRCode: [MT:-24J0AFN00KA0648G00] [1652388125.346530][1890:1890] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1652388125.346560][1890:1890] CHIP:SVR: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0AFN00KA0648G00 [1652388125.346603][1890:1890] CHIP:SVR: Manual pairing code: [34970112332] [1652388125.346634][1890:1890] CHIP:-: ==== Onboarding payload for Custom Commissioning Flows ==== [1652388125.346717][1890:1890] CHIP:SVR: SetupQRCode: [MT:-24J029Q00KA0648G00] [1652388125.346758][1890:1890] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1652388125.346788][1890:1890] CHIP:SVR: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J029Q00KA0648G00 [1652388125.346834][1890:1890] CHIP:SVR: Manual pairing code: [749701123365521327694] [1652388125.346884][1890:1890] CHIP:ZCL: Using ZAP configuration... [1652388125.347029][1890:1890] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388125.347086][1890:1890] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388125.347141][1890:1890] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002B, 0x0000_0001: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388125.347191][1890:1890] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388125.347240][1890:1890] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1652388125.347294][1890:1890] CHIP:DMG: AccessControlCluster: initializing [1652388125.347326][1890:1890] CHIP:DIS: Add fabric pairing table delegate [1652388125.347366][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 29d0a28b [1652388125.347409][1890:1890] CHIP:ZCL: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. [1652388125.347441][1890:1890] CHIP:DIS: Add fabric pairing table delegate [1652388125.347712][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-0YfXAL) [1652388125.348436][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388125.348521][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_002B update version to d7be5aa2 [1652388125.348580][1890:1890] CHIP:DIS: Init fabric pairing table with server storage [1652388125.348654][1890:1890] CHIP:DMG: AccessControl: initializing [1652388125.348688][1890:1890] CHIP:DMG: Examples::AccessControlDelegate::Init [1652388125.348730][1890:1890] CHIP:DMG: AccessControl: unable to load stored ACL entries; using empty list instead [1652388125.348779][1890:1890] CHIP:DMG: AccessControl: setting [1652388125.348817][1890:1890] CHIP:IN: UDP::Init bind&listen port=5540 [1652388125.348986][1890:1890] CHIP:IN: UDP::Init bound to port=5540 [1652388125.349023][1890:1890] CHIP:IN: UDP::Init bind&listen port=5540 [1652388125.349155][1890:1890] CHIP:IN: UDP::Init bound to port=5540 [1652388125.349191][1890:1890] CHIP:IN: TransportMgr initialized [1652388125.349495][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-D4Oa1c) [1652388125.350169][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388125.350386][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-FGEF7b) [1652388125.351344][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388125.351427][1890:1890] CHIP:DIS: Add fabric pairing table delegate [1652388125.353413][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-yTv1zt) [1652388125.353978][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388125.354181][1890:1890] CHIP:SC: Assigned local session key ID 31110 [1652388125.354210][1890:1890] CHIP:SC: Waiting for PBKDF param request [1652388125.354232][1890:1890] CHIP:DIS: Updating services using commissioning mode 1 [1652388125.356054][1890:1890] CHIP:DIS: CHIP minimal mDNS started advertising. [1652388125.357116][1890:1890] CHIP:DL: Using wifi MAC for hostname [1652388125.357222][1890:1890] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 [1652388125.357301][1890:1890] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'. [1652388125.359021][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388125.360906][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388125.362524][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388125.364159][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388125.365758][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388125.367348][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388125.367486][1890:1890] CHIP:DIS: mDNS service published: _matterc._udp [1652388125.367523][1890:1890] CHIP:DIS: Scheduling discovery timeout in 900s [1652388125.367557][1890:1890] CHIP:DIS: Updating services using commissioning mode 1 [1652388125.369405][1890:1890] CHIP:DIS: CHIP minimal mDNS started advertising. [1652388125.371140][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388125.372837][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388125.374454][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388125.376558][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388125.378192][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388125.379783][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388125.380238][1890:1890] CHIP:DL: Using wifi MAC for hostname [1652388125.380353][1890:1890] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 [1652388125.380433][1890:1890] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'. [1652388125.382194][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388125.383897][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388125.385541][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388125.387183][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388125.388808][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388125.390439][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388125.390582][1890:1890] CHIP:DIS: mDNS service published: _matterc._udp [1652388125.390619][1890:1890] CHIP:DIS: Scheduling discovery timeout in 900s [1652388125.390685][1890:1890] CHIP:IN: CASE Server enabling CASE session setups [1652388125.390714][1890:1890] CHIP:SVR: Joining Multicast groups [1652388125.390740][1890:1890] CHIP:ZCL: Emitting StartUp event [1652388125.390806][1890:1890] CHIP:EVL: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000103C99A [1652388125.390840][1890:1890] CHIP:SVR: Server Listening... [1652388125.390862][1890:1890] CHIP:DL: Device Configuration: [1652388125.390917][1890:1890] CHIP:DL: Serial Number: TEST_SN [1652388125.390974][1890:1890] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1652388125.391010][1890:1890] CHIP:DL: Product Id: 32769 (0x8001) [1652388125.391043][1890:1890] CHIP:DL: Hardware Version: 0 [1652388125.391066][1890:1890] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1652388125.391083][1890:1890] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1652388125.391108][1890:1890] CHIP:DL: Manufacturing Date: (not set) [1652388125.391130][1890:1890] CHIP:DL: Device Type: 65535 (0xFFFF) [1652388125.391190][1890:1890] CHIP:SVR: SetupQRCode: [MT:-24J029Q00KA0648G00] [1652388125.391221][1890:1890] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1652388125.391242][1890:1890] CHIP:SVR: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J029Q00KA0648G00 [1652388125.391279][1890:1890] CHIP:SVR: Manual pairing code: [749701123365521327694] [1652388125.391346][1890:1890] CHIP:SWU: Using OTA file: /home/pi/connectedhomeip/out/ota/BRD4164A/chip-efr32-lighting-example.ota [1652388125.391370][1890:1890] CHIP:SWU: Using ImageList file: (none) [1652388147.793287][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 55001 [1652388147.796853][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 56950 [1652388147.800374][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 55001 [1652388147.802519][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 56950 [1652388147.802771][1890:1890] CHIP:EM: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:1864588015 on exchange 54982r [1652388147.802821][1890:1890] CHIP:EM: Handling via exchange: 54982r, Delegate: 0xaaaaca7bc358 [1652388147.802873][1890:1890] CHIP:SC: Received PBKDF param request [1652388147.802919][1890:1890] CHIP:SC: Peer assigned session ID 8738 [1652388147.802947][1890:1890] CHIP:SC: Found MRP parameters in the message [1652388147.803045][1890:1890] CHIP:SC: Including MRP parameters in PBKDF param response [1652388147.803216][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1864588015 on exchange: 54982r [1652388147.803273][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 54982r with MessageCounter:1378659132. [1652388147.803312][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659132 to 0x0000000000000000 at monotonic time: 0000000001042127 msec [1652388147.803470][1890:1890] CHIP:SC: Sent PBKDF param response [1652388147.812769][1890:1890] CHIP:EM: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:1864588016 on exchange 54982r [1652388147.812806][1890:1890] CHIP:EM: Found matching exchange: 54982r, Delegate: 0xaaaaca7bc358 [1652388147.812845][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659132 from Retrans Table on exchange 54982r [1652388147.812870][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659132 from RetransTable on exchange 54982r [1652388147.812904][1890:1890] CHIP:SC: Received spake2p msg1 [1652388147.815321][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1864588016 on exchange: 54982r [1652388147.815397][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 54982r with MessageCounter:1378659133. [1652388147.815455][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659133 to 0x0000000000000000 at monotonic time: 0000000001042133 msec [1652388147.815701][1890:1890] CHIP:SC: Sent spake2p msg2 [1652388147.818667][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 192.168.162.30 on port 42733 [1652388147.819020][1890:1890] CHIP:EM: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:1864588017 on exchange 54982r [1652388147.819095][1890:1890] CHIP:EM: Found matching exchange: 54982r, Delegate: 0xaaaaca7bc358 [1652388147.819161][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659133 from Retrans Table on exchange 54982r [1652388147.819202][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659133 from RetransTable on exchange 54982r [1652388147.819260][1890:1890] CHIP:SC: Received spake2p msg3 [1652388147.819384][1890:1890] CHIP:SC: Sending status report. Protocol code 0, exchange 54982 [1652388147.819457][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1864588017 on exchange: 54982r [1652388147.819514][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 54982r with MessageCounter:1378659134. [1652388147.819588][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659134 to 0x0000000000000000 at monotonic time: 0000000001042137 msec [1652388147.819937][1890:1890] CHIP:IN: New secure session created for device , LSID:31110 PSID:8738! [1652388147.819994][1890:1890] CHIP:SVR: Commissioning completed session establishment step [1652388147.820065][1890:1890] CHIP:DIS: Updating services using commissioning mode 0 [1652388147.822837][1890:1890] CHIP:DIS: CHIP minimal mDNS started advertising. [1652388147.825516][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388147.827267][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388147.829039][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388147.830844][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388147.832602][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388147.834341][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388147.834776][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-M6JD4w) [1652388147.835417][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.835597][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-zmrnoD) [1652388147.836075][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.836128][1890:1890] CHIP:DL: NVS set: chip-config/fail-safe-armed = true [1652388147.836153][1890:1890] CHIP:SVR: Device completed Rendezvous process [1652388147.836536][1890:1890] CHIP:EM: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:4283992 on exchange 54983r [1652388147.836682][1890:1890] CHIP:EM: Handling via exchange: 54983r, Delegate: 0xaaaaca7bd558 [1652388147.836734][1890:1890] CHIP:IM: Received Read request [1652388147.836815][1890:1890] CHIP:DMG: ReadRequestMessage = [1652388147.836841][1890:1890] CHIP:DMG: { [1652388147.836875][1890:1890] CHIP:DMG: AttributePathIBs = [1652388147.836903][1890:1890] CHIP:DMG: [ [1652388147.836927][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.836963][1890:1890] CHIP:DMG: { [1652388147.836995][1890:1890] CHIP:DMG: Cluster = 0x31, [1652388147.837029][1890:1890] CHIP:DMG: Attribute = 0x0000_FFFC, [1652388147.837061][1890:1890] CHIP:DMG: } [1652388147.837101][1890:1890] CHIP:DMG: [1652388147.837128][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.837155][1890:1890] CHIP:DMG: { [1652388147.837193][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.837227][1890:1890] CHIP:DMG: Cluster = 0x30, [1652388147.837260][1890:1890] CHIP:DMG: Attribute = 0x0000_0000, [1652388147.837296][1890:1890] CHIP:DMG: } [1652388147.837326][1890:1890] CHIP:DMG: [1652388147.837351][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.837387][1890:1890] CHIP:DMG: { [1652388147.837416][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.837447][1890:1890] CHIP:DMG: Cluster = 0x30, [1652388147.837488][1890:1890] CHIP:DMG: Attribute = 0x0000_0001, [1652388147.837517][1890:1890] CHIP:DMG: } [1652388147.837554][1890:1890] CHIP:DMG: [1652388147.837580][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.837606][1890:1890] CHIP:DMG: { [1652388147.837640][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.837675][1890:1890] CHIP:DMG: Cluster = 0x30, [1652388147.837705][1890:1890] CHIP:DMG: Attribute = 0x0000_0002, [1652388147.837742][1890:1890] CHIP:DMG: } [1652388147.837771][1890:1890] CHIP:DMG: [1652388147.837807][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.837835][1890:1890] CHIP:DMG: { [1652388147.837858][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.837891][1890:1890] CHIP:DMG: Cluster = 0x30, [1652388147.837925][1890:1890] CHIP:DMG: Attribute = 0x0000_0003, [1652388147.837957][1890:1890] CHIP:DMG: } [1652388147.837996][1890:1890] CHIP:DMG: [1652388147.838024][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.838053][1890:1890] CHIP:DMG: { [1652388147.838089][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.838123][1890:1890] CHIP:DMG: Cluster = 0x28, [1652388147.838162][1890:1890] CHIP:DMG: Attribute = 0x0000_0002, [1652388147.838194][1890:1890] CHIP:DMG: } [1652388147.838221][1890:1890] CHIP:DMG: [1652388147.838255][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.838282][1890:1890] CHIP:DMG: { [1652388147.838310][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388147.838353][1890:1890] CHIP:DMG: Cluster = 0x28, [1652388147.838386][1890:1890] CHIP:DMG: Attribute = 0x0000_0004, [1652388147.838427][1890:1890] CHIP:DMG: } [1652388147.838457][1890:1890] CHIP:DMG: [1652388147.838496][1890:1890] CHIP:DMG: AttributePathIB = [1652388147.838524][1890:1890] CHIP:DMG: { [1652388147.838550][1890:1890] CHIP:DMG: Cluster = 0x31, [1652388147.838589][1890:1890] CHIP:DMG: Attribute = 0x0000_0003, [1652388147.838618][1890:1890] CHIP:DMG: } [1652388147.838655][1890:1890] CHIP:DMG: [1652388147.838683][1890:1890] CHIP:DMG: ], [1652388147.838730][1890:1890] CHIP:DMG: [1652388147.838758][1890:1890] CHIP:DMG: isFabricFiltered = true, [1652388147.838782][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.838816][1890:1890] CHIP:DMG: }, [1652388147.839035][1890:1890] CHIP:DMG: IM RH moving to [GeneratingReports] [1652388147.839330][1890:1890] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 [1652388147.839362][1890:1890] CHIP:DMG: Cluster 31, Attribute 3 is dirty [1652388147.839384][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) [1652388147.839412][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v [1652388147.839436][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.839479][1890:1890] CHIP:DMG: Cluster 28, Attribute 4 is dirty [1652388147.839501][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) [1652388147.839524][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v [1652388147.839557][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.839642][1890:1890] CHIP:DMG: Cluster 28, Attribute 2 is dirty [1652388147.839668][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [1652388147.839701][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v [1652388147.839724][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.839765][1890:1890] CHIP:DMG: Cluster 30, Attribute 3 is dirty [1652388147.839801][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) [1652388147.839853][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1652388147.839874][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.839951][1890:1890] CHIP:DMG: Cluster 30, Attribute 2 is dirty [1652388147.839976][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [1652388147.839999][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1652388147.840021][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.840072][1890:1890] CHIP:DMG: Cluster 30, Attribute 1 is dirty [1652388147.840096][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) [1652388147.840131][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1652388147.840155][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.840183][1890:1890] CHIP:DMG: Cluster 30, Attribute 0 is dirty [1652388147.840205][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) [1652388147.840237][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1652388147.840259][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.840293][1890:1890] CHIP:DMG: Cluster 31, Attribute fffc is dirty [1652388147.840323][1890:1890] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) [1652388147.840348][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v [1652388147.840370][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.840408][1890:1890] CHIP:DMG: Sending report (payload has 224 bytes)... [1652388147.840453][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4283992 on exchange: 54983r [1652388147.840544][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 54983r with MessageCounter:1691224. [1652388147.840586][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1691224 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000104214C msec [1652388147.840790][1890:1890] CHIP:DMG: OnReportConfirm: NumReports = 0 [1652388147.840830][1890:1890] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1652388147.840852][1890:1890] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1652388147.840884][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388147.840982][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1864588018 on exchange 54982r [1652388147.841022][1890:1890] CHIP:EM: Found matching exchange: 54982r, Delegate: (nil) [1652388147.841061][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659134 from Retrans Table on exchange 54982r [1652388147.841086][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659134 from RetransTable on exchange 54982r [1652388147.850916][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4283993 on exchange 54984r [1652388147.850968][1890:1890] CHIP:EM: Handling via exchange: 54984r, Delegate: 0xaaaaca7bd558 [1652388147.851044][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.851075][1890:1890] CHIP:DMG: { [1652388147.851102][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.851132][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.851176][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.851213][1890:1890] CHIP:DMG: [ [1652388147.851240][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.851287][1890:1890] CHIP:DMG: { [1652388147.851317][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.851349][1890:1890] CHIP:DMG: { [1652388147.851395][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.851434][1890:1890] CHIP:DMG: ClusterId = 0x30, [1652388147.851471][1890:1890] CHIP:DMG: CommandId = 0x0, [1652388147.851520][1890:1890] CHIP:DMG: }, [1652388147.851560][1890:1890] CHIP:DMG: [1652388147.851589][1890:1890] CHIP:DMG: CommandData = [1652388147.851636][1890:1890] CHIP:DMG: { [1652388147.851674][1890:1890] CHIP:DMG: 0x0 = 60, [1652388147.851721][1890:1890] CHIP:DMG: 0x1 = 3, [1652388147.851761][1890:1890] CHIP:DMG: }, [1652388147.851800][1890:1890] CHIP:DMG: }, [1652388147.852424][1890:1890] CHIP:DMG: [1652388147.852452][1890:1890] CHIP:DMG: ], [1652388147.852488][1890:1890] CHIP:DMG: [1652388147.852515][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.852542][1890:1890] CHIP:DMG: }, [1652388147.852624][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a [1652388147.852665][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.852696][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1652388147.852983][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-yAxEnP) [1652388147.853648][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.853827][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-RdizXR) [1652388147.854516][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.854582][1890:1890] CHIP:DL: NVS set: chip-config/fail-safe-armed = true [1652388147.854625][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 29d0a28c [1652388147.854690][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.854727][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.854761][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.854923][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.854981][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4283993 on exchange: 54984r [1652388147.855083][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54984r with MessageCounter:1691225. [1652388147.855133][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:1691225 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000104215B msec [1652388147.855362][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.855508][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.855647][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388147.855867][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4283994 on exchange 54983r [1652388147.855924][1890:1890] CHIP:EM: Found matching exchange: 54983r, Delegate: (nil) [1652388147.855991][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691224 from Retrans Table on exchange 54983r [1652388147.856047][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691224 from RetransTable on exchange 54983r [1652388147.857675][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4283995 on exchange 54985r [1652388147.857752][1890:1890] CHIP:EM: Handling via exchange: 54985r, Delegate: 0xaaaaca7bd558 [1652388147.857858][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.857902][1890:1890] CHIP:DMG: { [1652388147.857940][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.857988][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.858029][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.858101][1890:1890] CHIP:DMG: [ [1652388147.858143][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.858206][1890:1890] CHIP:DMG: { [1652388147.858253][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.858309][1890:1890] CHIP:DMG: { [1652388147.858374][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.858434][1890:1890] CHIP:DMG: ClusterId = 0x30, [1652388147.858487][1890:1890] CHIP:DMG: CommandId = 0x2, [1652388147.858554][1890:1890] CHIP:DMG: }, [1652388147.858610][1890:1890] CHIP:DMG: [1652388147.858656][1890:1890] CHIP:DMG: CommandData = [1652388147.858727][1890:1890] CHIP:DMG: { [1652388147.858784][1890:1890] CHIP:DMG: 0x0 = 0, [1652388147.858855][1890:1890] CHIP:DMG: 0x1 = "XX", [1652388147.858917][1890:1890] CHIP:DMG: 0x2 = 4, [1652388147.858985][1890:1890] CHIP:DMG: }, [1652388147.859035][1890:1890] CHIP:DMG: }, [1652388147.859090][1890:1890] CHIP:DMG: [1652388147.859132][1890:1890] CHIP:DMG: ], [1652388147.859198][1890:1890] CHIP:DMG: [1652388147.859237][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.859276][1890:1890] CHIP:DMG: }, [1652388147.859388][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a [1652388147.859432][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.859486][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [1652388147.859846][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-coD7dH) [1652388147.860677][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.860758][1890:1890] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1652388147.860965][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-AFKMfq) [1652388147.861969][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388147.862049][1890:1890] CHIP:DL: NVS set: chip-config/country-code = "XX" [1652388147.862105][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 29d0a28d [1652388147.862183][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.862233][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.862300][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.862374][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.862426][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4283995 on exchange: 54985r [1652388147.862550][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54985r with MessageCounter:1691226. [1652388147.862630][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1691226 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000001042162 msec [1652388147.862907][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.862968][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.863078][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388147.863260][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4283996 on exchange 54984r [1652388147.863310][1890:1890] CHIP:EM: Found matching exchange: 54984r, Delegate: (nil) [1652388147.863391][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691225 from Retrans Table on exchange 54984r [1652388147.863426][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691225 from RetransTable on exchange 54984r [1652388147.865002][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4283997 on exchange 54986r [1652388147.865068][1890:1890] CHIP:EM: Handling via exchange: 54986r, Delegate: 0xaaaaca7bd558 [1652388147.865165][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.865208][1890:1890] CHIP:DMG: { [1652388147.865245][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.865296][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.865357][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.865409][1890:1890] CHIP:DMG: [ [1652388147.865449][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.865510][1890:1890] CHIP:DMG: { [1652388147.865557][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.865609][1890:1890] CHIP:DMG: { [1652388147.865677][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.865733][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.865790][1890:1890] CHIP:DMG: CommandId = 0x2, [1652388147.865856][1890:1890] CHIP:DMG: }, [1652388147.865911][1890:1890] CHIP:DMG: [1652388147.865969][1890:1890] CHIP:DMG: CommandData = [1652388147.866022][1890:1890] CHIP:DMG: { [1652388147.866078][1890:1890] CHIP:DMG: 0x0 = 2, [1652388147.866150][1890:1890] CHIP:DMG: }, [1652388147.866199][1890:1890] CHIP:DMG: }, [1652388147.866250][1890:1890] CHIP:DMG: [1652388147.866300][1890:1890] CHIP:DMG: ], [1652388147.866335][1890:1890] CHIP:DMG: [1652388147.866361][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.866401][1890:1890] CHIP:DMG: }, [1652388147.866470][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.866500][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.866529][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1652388147.866574][1890:1890] CHIP:ZCL: OpCreds: Certificate Chain request received for PAI [1652388147.866614][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.866647][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.866689][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.866731][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.866763][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4283997 on exchange: 54986r [1652388147.866869][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54986r with MessageCounter:1691227. [1652388147.866913][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:1691227 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000001042167 msec [1652388147.867118][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.867149][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.867325][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4283998 on exchange 54985r [1652388147.867360][1890:1890] CHIP:EM: Found matching exchange: 54985r, Delegate: (nil) [1652388147.867404][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691226 from Retrans Table on exchange 54985r [1652388147.867431][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691226 from RetransTable on exchange 54985r [1652388147.869444][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4283999 on exchange 54987r [1652388147.869489][1890:1890] CHIP:EM: Handling via exchange: 54987r, Delegate: 0xaaaaca7bd558 [1652388147.869550][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.869579][1890:1890] CHIP:DMG: { [1652388147.869604][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.869634][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.869674][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.869709][1890:1890] CHIP:DMG: [ [1652388147.869737][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.869780][1890:1890] CHIP:DMG: { [1652388147.869812][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.869849][1890:1890] CHIP:DMG: { [1652388147.869895][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.869933][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.869970][1890:1890] CHIP:DMG: CommandId = 0x2, [1652388147.870016][1890:1890] CHIP:DMG: }, [1652388147.870054][1890:1890] CHIP:DMG: [1652388147.870095][1890:1890] CHIP:DMG: CommandData = [1652388147.870132][1890:1890] CHIP:DMG: { [1652388147.870172][1890:1890] CHIP:DMG: 0x0 = 1, [1652388147.870219][1890:1890] CHIP:DMG: }, [1652388147.870253][1890:1890] CHIP:DMG: }, [1652388147.870298][1890:1890] CHIP:DMG: [1652388147.870327][1890:1890] CHIP:DMG: ], [1652388147.870361][1890:1890] CHIP:DMG: [1652388147.870388][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.870426][1890:1890] CHIP:DMG: }, [1652388147.870490][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.870532][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.870562][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1652388147.870594][1890:1890] CHIP:ZCL: OpCreds: Certificate Chain request received for DAC [1652388147.870632][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.870676][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.870707][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.870757][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.870789][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4283999 on exchange: 54987r [1652388147.870890][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54987r with MessageCounter:1691228. [1652388147.870933][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1691228 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000104216B msec [1652388147.871105][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.871136][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.871313][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284000 on exchange 54986r [1652388147.871348][1890:1890] CHIP:EM: Found matching exchange: 54986r, Delegate: (nil) [1652388147.871389][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691227 from Retrans Table on exchange 54986r [1652388147.871427][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691227 from RetransTable on exchange 54986r [1652388147.873434][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4284001 on exchange 54988r [1652388147.873485][1890:1890] CHIP:EM: Handling via exchange: 54988r, Delegate: 0xaaaaca7bd558 [1652388147.873556][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.873586][1890:1890] CHIP:DMG: { [1652388147.873612][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.873641][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.873668][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.873719][1890:1890] CHIP:DMG: [ [1652388147.873748][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.873782][1890:1890] CHIP:DMG: { [1652388147.873825][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.873862][1890:1890] CHIP:DMG: { [1652388147.873899][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.873952][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.873989][1890:1890] CHIP:DMG: CommandId = 0x0, [1652388147.874028][1890:1890] CHIP:DMG: }, [1652388147.874080][1890:1890] CHIP:DMG: [1652388147.874112][1890:1890] CHIP:DMG: CommandData = [1652388147.874150][1890:1890] CHIP:DMG: { [1652388147.874199][1890:1890] CHIP:DMG: 0x0 = [ [1652388147.874251][1890:1890] CHIP:DMG: 0x9c, 0x2d, 0x6d, 0x7a, 0x31, 0x9c, 0xd5, 0x5d, 0x16, 0x52, 0x77, 0x28, 0x2, 0x77, 0xc0, 0x55, 0x19, 0x77, 0x5c, 0xfb, 0x23, 0x2b, 0x29, 0xc2, 0x6e, 0xc2, 0x7d, 0x88, 0x3d, 0x5f, 0x18, 0x67, [1652388147.874302][1890:1890] CHIP:DMG: ] [1652388147.874340][1890:1890] CHIP:DMG: }, [1652388147.874374][1890:1890] CHIP:DMG: }, [1652388147.874421][1890:1890] CHIP:DMG: [1652388147.874451][1890:1890] CHIP:DMG: ], [1652388147.874485][1890:1890] CHIP:DMG: [1652388147.874512][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.874539][1890:1890] CHIP:DMG: }, [1652388147.874613][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.874644][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.874673][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [1652388147.874720][1890:1890] CHIP:ZCL: OpCreds: received an AttestationRequest [1652388147.877316][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.877381][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.877419][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.877477][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.877520][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4284001 on exchange: 54988r [1652388147.877671][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54988r with MessageCounter:1691229. [1652388147.877726][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:1691229 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000001042171 msec [1652388147.877969][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.878014][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.878214][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284002 on exchange 54987r [1652388147.878267][1890:1890] CHIP:EM: Found matching exchange: 54987r, Delegate: (nil) [1652388147.878317][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691228 from Retrans Table on exchange 54987r [1652388147.878347][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691228 from RetransTable on exchange 54987r [1652388147.888028][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4284003 on exchange 54989r [1652388147.888085][1890:1890] CHIP:EM: Handling via exchange: 54989r, Delegate: 0xaaaaca7bd558 [1652388147.888167][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.888200][1890:1890] CHIP:DMG: { [1652388147.888228][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.888265][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.888297][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.888335][1890:1890] CHIP:DMG: [ [1652388147.888364][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.888398][1890:1890] CHIP:DMG: { [1652388147.888432][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.888471][1890:1890] CHIP:DMG: { [1652388147.888511][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.888551][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.888590][1890:1890] CHIP:DMG: CommandId = 0x4, [1652388147.888628][1890:1890] CHIP:DMG: }, [1652388147.888668][1890:1890] CHIP:DMG: [1652388147.888702][1890:1890] CHIP:DMG: CommandData = [1652388147.888740][1890:1890] CHIP:DMG: { [1652388147.888782][1890:1890] CHIP:DMG: 0x0 = [ [1652388147.888834][1890:1890] CHIP:DMG: 0xc7, 0x2e, 0x18, 0xce, 0xb0, 0xbb, 0x49, 0x75, 0x7e, 0xa0, 0xcd, 0x54, 0x29, 0xf8, 0x74, 0x63, 0xb8, 0x37, 0x16, 0x8d, 0x80, 0x37, 0xc4, 0x12, 0x83, 0x0, 0x7e, 0x5b, 0x4e, 0x33, 0x2f, 0x7a, [1652388147.888878][1890:1890] CHIP:DMG: ] [1652388147.888919][1890:1890] CHIP:DMG: }, [1652388147.888959][1890:1890] CHIP:DMG: }, [1652388147.888999][1890:1890] CHIP:DMG: [1652388147.889030][1890:1890] CHIP:DMG: ], [1652388147.889066][1890:1890] CHIP:DMG: [1652388147.889095][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.889125][1890:1890] CHIP:DMG: }, [1652388147.889199][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.889232][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.889262][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 [1652388147.889309][1890:1890] CHIP:ZCL: OpCreds: commissioner has requested a CSR [1652388147.891547][1890:1890] CHIP:ZCL: OpCreds: NewCertificateSigningRequest returned ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/crypto/CHIPCryptoPALOpenSSL.cpp:1114: Success [1652388147.892254][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.892326][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.892379][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.892457][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.892513][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4284003 on exchange: 54989r [1652388147.892655][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54989r with MessageCounter:1691230. [1652388147.892727][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1691230 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000001042180 msec [1652388147.892991][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.893041][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.893337][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284004 on exchange 54988r [1652388147.893395][1890:1890] CHIP:EM: Found matching exchange: 54988r, Delegate: (nil) [1652388147.893463][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691229 from Retrans Table on exchange 54988r [1652388147.893507][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691229 from RetransTable on exchange 54988r [1652388147.897762][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4284005 on exchange 54990r [1652388147.897831][1890:1890] CHIP:EM: Handling via exchange: 54990r, Delegate: 0xaaaaca7bd558 [1652388147.897937][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.897985][1890:1890] CHIP:DMG: { [1652388147.898026][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.898077][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.898121][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.898182][1890:1890] CHIP:DMG: [ [1652388147.898229][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.898289][1890:1890] CHIP:DMG: { [1652388147.898345][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.898405][1890:1890] CHIP:DMG: { [1652388147.898465][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.898529][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.898589][1890:1890] CHIP:DMG: CommandId = 0xb, [1652388147.898644][1890:1890] CHIP:DMG: }, [1652388147.898709][1890:1890] CHIP:DMG: [1652388147.898760][1890:1890] CHIP:DMG: CommandData = [1652388147.898822][1890:1890] CHIP:DMG: { [1652388147.898879][1890:1890] CHIP:DMG: 0x0 = [ [1652388147.898971][1890:1890] CHIP:DMG: 0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x14, 0x0, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x41, 0x4, 0xd7, 0xe3, 0xe [1652388147.899037][1890:1890] CHIP:DMG: ] [1652388147.899099][1890:1890] CHIP:DMG: }, [1652388147.899157][1890:1890] CHIP:DMG: }, [1652388147.899214][1890:1890] CHIP:DMG: [1652388147.899260][1890:1890] CHIP:DMG: ], [1652388147.899307][1890:1890] CHIP:DMG: [1652388147.899339][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.899373][1890:1890] CHIP:DMG: }, [1652388147.899465][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.899500][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.899533][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B [1652388147.899573][1890:1890] CHIP:ZCL: OpCreds: commissioner has added a trusted root Cert [1652388147.899617][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388147.899654][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388147.899688][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388147.899720][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to e8b65795 [1652388147.899781][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388147.899854][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4284005 on exchange: 54990r [1652388147.899936][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 54990r with MessageCounter:1691231. [1652388147.899986][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:1691231 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000001042188 msec [1652388147.900178][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388147.900215][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388147.900297][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388147.900422][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284006 on exchange 54989r [1652388147.900461][1890:1890] CHIP:EM: Found matching exchange: 54989r, Delegate: (nil) [1652388147.900509][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691230 from Retrans Table on exchange 54989r [1652388147.900542][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691230 from RetransTable on exchange 54989r [1652388147.901987][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4284007 on exchange 54991r [1652388147.902036][1890:1890] CHIP:EM: Handling via exchange: 54991r, Delegate: 0xaaaaca7bd558 [1652388147.902113][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388147.902147][1890:1890] CHIP:DMG: { [1652388147.902177][1890:1890] CHIP:DMG: suppressResponse = false, [1652388147.902215][1890:1890] CHIP:DMG: timedRequest = false, [1652388147.902249][1890:1890] CHIP:DMG: InvokeRequests = [1652388147.902295][1890:1890] CHIP:DMG: [ [1652388147.902327][1890:1890] CHIP:DMG: CommandDataIB = [1652388147.902363][1890:1890] CHIP:DMG: { [1652388147.902399][1890:1890] CHIP:DMG: CommandPathIB = [1652388147.902441][1890:1890] CHIP:DMG: { [1652388147.902485][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388147.902533][1890:1890] CHIP:DMG: ClusterId = 0x3e, [1652388147.902577][1890:1890] CHIP:DMG: CommandId = 0x6, [1652388147.902617][1890:1890] CHIP:DMG: }, [1652388147.902660][1890:1890] CHIP:DMG: [1652388147.902697][1890:1890] CHIP:DMG: CommandData = [1652388147.902741][1890:1890] CHIP:DMG: { [1652388147.902787][1890:1890] CHIP:DMG: 0x0 = [ [1652388147.902858][1890:1890] CHIP:DMG: 0x15, 0x30, 0x1, 0x1, 0x1, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x13, 0x1, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x15, 0x1, 0x24, 0x11, 0x1, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x41, 0x4 [1652388147.902904][1890:1890] CHIP:DMG: ] [1652388147.902945][1890:1890] CHIP:DMG: 0x1 = [ [1652388147.903017][1890:1890] CHIP:DMG: 0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x13, 0x1, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x41, 0x4, 0xd6, 0x38, 0x4 [1652388147.903070][1890:1890] CHIP:DMG: ] [1652388147.903114][1890:1890] CHIP:DMG: 0x2 = [ [1652388147.903166][1890:1890] CHIP:DMG: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31, [1652388147.903212][1890:1890] CHIP:DMG: ] [1652388147.903255][1890:1890] CHIP:DMG: 0x3 = 112233, [1652388147.903299][1890:1890] CHIP:DMG: 0x4 = 65521, [1652388147.903338][1890:1890] CHIP:DMG: }, [1652388147.903377][1890:1890] CHIP:DMG: }, [1652388147.903421][1890:1890] CHIP:DMG: [1652388147.903455][1890:1890] CHIP:DMG: ], [1652388147.903497][1890:1890] CHIP:DMG: [1652388147.903529][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388147.903560][1890:1890] CHIP:DMG: }, [1652388147.903640][1890:1890] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1652388147.903674][1890:1890] CHIP:DMG: AccessControl: implicit admin (PASE) [1652388147.903707][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 [1652388147.903754][1890:1890] CHIP:ZCL: OpCreds: Received AddNOC command [1652388147.904144][1890:1890] CHIP:DIS: Verifying the received credentials [1652388147.906526][1890:1890] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1652388147.906578][1890:1890] CHIP:DIS: Assigned compressed fabric ID: 0x54076DAA023833D1, node ID: 0x0000000000000001 [1652388147.906862][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ycFsUY) [1652388147.907644][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.907986][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-cmxdvr) [1652388147.909324][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.909579][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-44LLIU) [1652388147.910911][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.911101][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-lP58JM) [1652388147.912536][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.912712][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-mhQRkZ) [1652388147.914173][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.914226][1890:1890] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage [1652388147.914254][1890:1890] CHIP:ZCL: OpCreds: Fabric index 0x1 was persisted to storage. FabricId 0000000000000001, NodeId 0000000000000001, VendorId 0xFFF1 [1652388147.914280][1890:1890] CHIP:ZCL: OpCreds: Call to fabricListChanged [1652388147.914307][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to e8b65796 [1652388147.914348][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to e8b65797 [1652388147.914521][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-u6nWCH) [1652388147.915865][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.916045][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-SxdMcR) [1652388147.917516][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.917586][1890:1890] CHIP:DMG: AccessControl: validating f=1 p=a a=c s=1 t=0 [1652388147.917615][1890:1890] CHIP:DMG: validating subject 0x000000000001B669 [1652388147.917785][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-M6n0vG) [1652388147.921944][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.922175][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Dg8SoS) [1652388147.922988][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.923198][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-83ldBm) [1652388147.924029][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.924241][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-KKLX94) [1652388147.925332][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.925551][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nhVUVS) [1652388147.926397][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.926603][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rYCScc) [1652388147.927444][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.927645][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-gFnYlN) [1652388147.928549][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.928858][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1jkWav) [1652388147.929772][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.929974][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-4XZ71L) [1652388147.930876][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.931070][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-gujxtM) [1652388147.932057][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.932253][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WaJGXM) [1652388147.933300][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.933487][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-mMuoOZ) [1652388147.934554][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.934738][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3f1NRy) [1652388147.935891][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.936090][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-yLtffn) [1652388147.937082][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.937267][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-43hP5h) [1652388147.938367][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.938554][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ZvhuUt) [1652388147.939668][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.939896][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-7iTtfs) [1652388147.940950][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.941133][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qEARcH) [1652388147.942504][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.942673][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qahWQE) [1652388147.944118][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.944291][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-QtvIQc) [1652388147.945737][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.945900][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1kEVd5) [1652388147.947366][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.947529][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WPHNrQ) [1652388147.949041][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.949254][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-HpxBZA) [1652388147.950705][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.950917][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-pKLKCq) [1652388147.952370][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.952577][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-aQOikX) [1652388147.956770][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.956982][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Zs4NiR) [1652388147.958064][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.958260][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-eoR89I) [1652388147.959352][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.959541][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-wXPVP8) [1652388147.960673][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.960874][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-bTxkxO) [1652388147.961973][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.962162][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3HABno) [1652388147.963264][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.963449][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nISCFW) [1652388147.965554][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.965795][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WrtNVR) [1652388147.967032][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.967232][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-UIT2BM) [1652388147.968456][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.968659][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WDtajz) [1652388147.969895][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.970094][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-UGUpLp) [1652388147.971295][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.971468][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-YtxaJ4) [1652388147.972678][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.972865][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-aZos3N) [1652388147.973970][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.974142][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rP6dDD) [1652388147.975860][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.976053][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-AvGuG5) [1652388147.977533][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.977710][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-2c7RyR) [1652388147.979236][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.979409][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-DR6tc9) [1652388147.980974][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.981159][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ELzYDm) [1652388147.985938][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.986120][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-5NYJ23) [1652388147.987361][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.987570][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-T0Sraz) [1652388147.988900][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.989091][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-EZzaFS) [1652388147.990378][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.990561][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-xUNWnM) [1652388147.991898][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.992114][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-34EEZL) [1652388147.993558][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.993759][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-lBK3Z3) [1652388147.995205][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.995386][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-VXY5du) [1652388147.996934][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.996999][1890:1890] CHIP:ZCL: OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x000000000001B669 [1652388147.997388][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ZmRbZ2) [1652388147.998898][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388147.999166][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-6qzdEq) [1652388148.000710][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.000918][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Nbrqq3) [1652388148.002395][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.002848][1890:1890] CHIP:DL: Using wifi MAC for hostname [1652388148.002884][1890:1890] CHIP:DIS: Advertise operational node 54076DAA023833D1-0000000000000001 [1652388148.002961][1890:1890] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'. [1652388148.004690][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388148.006343][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388148.008001][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388148.009523][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388148.011039][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388148.012627][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388148.012768][1890:1890] CHIP:DIS: mDNS service published: _matter._tcp [1652388148.012846][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388148.012879][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388148.012910][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388148.012934][1890:1890] CHIP:ZCL: OpCreds: successfully created fabric index 1 via AddNOC [1652388148.013022][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388148.013063][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4284007 on exchange: 54991r [1652388148.013152][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 54991r with MessageCounter:1691232. [1652388148.013198][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1691232 to 0xFFFFFFFB00000000 (1) at monotonic time: 00000000010421F9 msec [1652388148.013395][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388148.013425][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388148.013506][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388148.013650][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284008 on exchange 54990r [1652388148.013683][1890:1890] CHIP:EM: Found matching exchange: 54990r, Delegate: (nil) [1652388148.013725][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691231 from Retrans Table on exchange 54990r [1652388148.013750][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691231 from RetransTable on exchange 54990r [1652388148.018748][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 55001 [1652388148.020136][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 55001 [1652388148.020361][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4284009 on exchange 54991r [1652388148.020396][1890:1890] CHIP:EM: Found matching exchange: 54991r, Delegate: (nil) [1652388148.020486][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1691232 from Retrans Table on exchange 54991r [1652388148.020514][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1691232 from RetransTable on exchange 54991r [1652388148.021870][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 56950 [1652388148.023284][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 56950 [1652388148.025014][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 192.168.162.30 on port 42733 [1652388148.026564][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f547 on port 56674 [1652388148.029096][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 192.168.162.30 on port 42733 [1652388148.030677][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f547 on port 56674 [1652388148.226032][1890:1890] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:1864588019 on exchange 54992r [1652388148.226149][1890:1890] CHIP:EM: Handling via exchange: 54992r, Delegate: 0xaaaaca7b4920 [1652388148.226244][1890:1890] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaaca7b6220 [1652388148.226418][1890:1890] CHIP:SC: Waiting for Sigma1 msg [1652388148.226475][1890:1890] CHIP:IN: CASE Server disabling CASE session setups [1652388148.226532][1890:1890] CHIP:SC: Received Sigma1 msg [1652388148.226639][1890:1890] CHIP:SC: Found MRP parameters in the message [1652388148.226707][1890:1890] CHIP:SC: Peer assigned session key ID 8739 [1652388148.227571][1890:1890] CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 [1652388148.230184][1890:1890] CHIP:SC: Including MRP parameters [1652388148.230327][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1864588019 on exchange: 54992r [1652388148.230425][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 54992r with MessageCounter:1378659135. [1652388148.230519][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659135 to 0x0000000000000000 at monotonic time: 00000000010422D2 msec [1652388148.230881][1890:1890] CHIP:SC: Sent Sigma2 msg [1652388148.244485][1890:1890] CHIP:EM: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1864588020 on exchange 54992r [1652388148.244570][1890:1890] CHIP:EM: Found matching exchange: 54992r, Delegate: 0xaaaaca7b4940 [1652388148.244657][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659135 from Retrans Table on exchange 54992r [1652388148.244715][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659135 from RetransTable on exchange 54992r [1652388148.244798][1890:1890] CHIP:SC: Received Sigma3 msg [1652388148.249892][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-zmahOj) [1652388148.252152][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.252465][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3EQ80j) [1652388148.256997][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.257189][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-r50O3A) [1652388148.258507][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.258563][1890:1890] CHIP:SC: Sending status report. Protocol code 0, exchange 54992 [1652388148.258611][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1864588020 on exchange: 54992r [1652388148.258658][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 54992r with MessageCounter:1378659136. [1652388148.258703][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659136 to 0x0000000000000000 at monotonic time: 00000000010422EE msec [1652388148.258965][1890:1890] CHIP:IN: New secure session created for device <000000000001B669, 1>, LSID:31111 PSID:8739! [1652388148.259002][1890:1890] CHIP:IN: CASE Session established to peer: <000000000001B669, 1> [1652388148.259023][1890:1890] CHIP:IN: CASE Server enabling CASE session setups [1652388148.270626][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:2080282 on exchange 54993r [1652388148.270681][1890:1890] CHIP:EM: Handling via exchange: 54993r, Delegate: 0xaaaaca7bd558 [1652388148.270760][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388148.270787][1890:1890] CHIP:DMG: { [1652388148.270809][1890:1890] CHIP:DMG: suppressResponse = false, [1652388148.270836][1890:1890] CHIP:DMG: timedRequest = false, [1652388148.270860][1890:1890] CHIP:DMG: InvokeRequests = [1652388148.270891][1890:1890] CHIP:DMG: [ [1652388148.270914][1890:1890] CHIP:DMG: CommandDataIB = [1652388148.270942][1890:1890] CHIP:DMG: { [1652388148.270968][1890:1890] CHIP:DMG: CommandPathIB = [1652388148.271039][1890:1890] CHIP:DMG: { [1652388148.271077][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388148.271114][1890:1890] CHIP:DMG: ClusterId = 0x30, [1652388148.271147][1890:1890] CHIP:DMG: CommandId = 0x4, [1652388148.271181][1890:1890] CHIP:DMG: }, [1652388148.271213][1890:1890] CHIP:DMG: [1652388148.271240][1890:1890] CHIP:DMG: CommandData = [1652388148.271273][1890:1890] CHIP:DMG: { [1652388148.271303][1890:1890] CHIP:DMG: }, [1652388148.271333][1890:1890] CHIP:DMG: }, [1652388148.271363][1890:1890] CHIP:DMG: [1652388148.271387][1890:1890] CHIP:DMG: ], [1652388148.271417][1890:1890] CHIP:DMG: [1652388148.271467][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388148.271491][1890:1890] CHIP:DMG: }, [1652388148.271573][1890:1890] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t= c=0x0000_0030 e=0 p=a [1652388148.271611][1890:1890] CHIP:DMG: AccessControl: allowed [1652388148.271638][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 [1652388148.272074][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_config.ini-hT4Wr2) [1652388148.273113][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1652388148.273214][1890:1890] CHIP:DL: NVS set: chip-config/fail-safe-armed = false [1652388148.273449][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-EXO30Y) [1652388148.276105][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388148.276230][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 29d0a28e [1652388148.276331][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388148.276396][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388148.276454][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388148.276540][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388148.276604][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:2080282 on exchange: 54993r [1652388148.276735][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f38 to 0x000000000001B669 (1) of type 0x9 and protocolId (0, 1) on exchange 54993r with MessageCounter:1785609. [1652388148.276815][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f38 with MessageCounter:1785609 to 0x000000000001B669 (1) at monotonic time: 0000000001042301 msec [1652388148.277213][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388148.277274][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388148.277344][1890:1890] CHIP:SVR: Commissioning completed successfully [1652388148.277429][1890:1890] CHIP:DIS: Updating services using commissioning mode 0 [1652388148.281209][1890:1890] CHIP:DIS: CHIP minimal mDNS started advertising. [1652388148.283772][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388148.285422][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388148.286997][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388148.288527][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388148.290057][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388148.291559][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388148.292260][1890:1890] CHIP:DL: Using wifi MAC for hostname [1652388148.292304][1890:1890] CHIP:DIS: Advertise operational node 54076DAA023833D1-0000000000000001 [1652388148.292376][1890:1890] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'. [1652388148.294022][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.117 [1652388148.295519][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from 192.168.162.33 [1652388148.297085][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:33::e65f:1ff:fe6a:fa9f [1652388148.298630][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:fa9f [1652388148.300186][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fd11:34::e65f:1ff:fe6a:faa0 [1652388148.301699][1890:1890] CHIP:DIS: Broadcasting mDns reply for query from fe80::e65f:1ff:fe6a:faa0 [1652388148.301878][1890:1890] CHIP:DIS: mDNS service published: _matter._tcp [1652388148.301919][1890:1890] CHIP:IN: Expiring all PASE pairings [1652388148.302011][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388148.302178][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1864588021 on exchange 54992r [1652388148.302213][1890:1890] CHIP:EM: Found matching exchange: 54992r, Delegate: (nil) [1652388148.302260][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659136 from Retrans Table on exchange 54992r [1652388148.302284][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659136 from RetransTable on exchange 54992r [1652388148.302650][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2080283 on exchange 54993r [1652388148.302682][1890:1890] CHIP:EM: Found matching exchange: 54993r, Delegate: (nil) [1652388148.302715][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1785609 from Retrans Table on exchange 54993r [1652388148.302738][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1785609 from RetransTable on exchange 54993r [1652388152.131337][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 58860 [1652388152.134680][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 60059 [1652388152.138050][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 172.16.0.50 on port 58860 [1652388152.140617][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f546 on port 60059 [1652388152.221970][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 192.168.162.30 on port 58708 [1652388152.224474][1890:1890] CHIP:DIS: Directly sending mDns reply to peer 192.168.162.30 on port 58708 [1652388152.227040][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f547 on port 39367 [1652388152.229529][1890:1890] CHIP:DIS: Directly sending mDns reply to peer fe80::e65f:1ff:fe01:f547 on port 39367 [1652388152.331098][1890:1890] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:1736088650 on exchange 1770r [1652388152.331209][1890:1890] CHIP:EM: Handling via exchange: 1770r, Delegate: 0xaaaaca7b4920 [1652388152.331307][1890:1890] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaaca7b6220 [1652388152.331474][1890:1890] CHIP:SC: Waiting for Sigma1 msg [1652388152.331533][1890:1890] CHIP:IN: CASE Server disabling CASE session setups [1652388152.331593][1890:1890] CHIP:SC: Received Sigma1 msg [1652388152.331698][1890:1890] CHIP:SC: Found MRP parameters in the message [1652388152.331771][1890:1890] CHIP:SC: Peer assigned session key ID 9662 [1652388152.332896][1890:1890] CHIP:SC: Including MRP parameters [1652388152.333001][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:1736088650 on exchange: 1770r [1652388152.333090][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 1770r with MessageCounter:1378659137. [1652388152.333177][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659137 to 0x0000000000000000 at monotonic time: 00000000010432D9 msec [1652388152.333490][1890:1890] CHIP:SC: Sent Sigma2Resume msg [1652388152.341338][1890:1890] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1736088651 on exchange 1770r [1652388152.341416][1890:1890] CHIP:EM: Found matching exchange: 1770r, Delegate: 0xaaaaca7b4940 [1652388152.341502][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:1378659137 from Retrans Table on exchange 1770r [1652388152.341560][1890:1890] CHIP:EM: Removed CHIP MessageCounter:1378659137 from RetransTable on exchange 1770r [1652388152.341686][1890:1890] CHIP:SC: Success status report received. Session was established [1652388152.342506][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-YtyRXH) [1652388152.344965][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.345234][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-GgJ8PL) [1652388152.347428][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.347668][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-hrNytx) [1652388152.349881][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.349976][1890:1890] CHIP:IN: Expired/released previous local session ID 31111 for peer <000000000001B669, 1> [1652388152.350100][1890:1890] CHIP:IN: New secure session created for device <000000000001B669, 1>, LSID:31112 PSID:9662! [1652388152.350144][1890:1890] CHIP:IN: CASE Session established to peer: <000000000001B669, 1> [1652388152.350180][1890:1890] CHIP:IN: CASE Server enabling CASE session setups [1652388152.350231][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:1736088651 on exchange 1770r [1652388152.350300][1890:1890] CHIP:IN: Prepared unauthenticated message 0xfffffe8389c8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 1770r with MessageCounter:1378659138. [1652388152.350365][1890:1890] CHIP:IN: Sending unauthenticated msg 0xfffffe8389c8 with MessageCounter:1378659138 to 0x0000000000000000 at monotonic time: 00000000010432EA msec [1652388152.350591][1890:1890] CHIP:EM: Flushed pending ack for MessageCounter:1736088651 on exchange 1770r [1652388152.350890][1890:1890] CHIP:EM: Received message of type 0x6 with protocolId (0, 1) and MessageCounter:4069524 on exchange 1771r [1652388152.350952][1890:1890] CHIP:EM: Handling via exchange: 1771r, Delegate: 0xaaaaca7bd558 [1652388152.351028][1890:1890] CHIP:IM: Received Write request [1652388152.351068][1890:1890] CHIP:DMG: IM WH moving to [Initialized] [1652388152.351218][1890:1890] CHIP:DMG: WriteRequestMessage = [1652388152.351265][1890:1890] CHIP:DMG: { [1652388152.351302][1890:1890] CHIP:DMG: suppressResponse = false, [1652388152.351345][1890:1890] CHIP:DMG: timedRequest = false, [1652388152.351385][1890:1890] CHIP:DMG: AttributeDataIBs = [1652388152.351435][1890:1890] CHIP:DMG: [ [1652388152.351475][1890:1890] CHIP:DMG: AttributeDataIB = [1652388152.351521][1890:1890] CHIP:DMG: { [1652388152.351570][1890:1890] CHIP:DMG: AttributePathIB = [1652388152.351622][1890:1890] CHIP:DMG: { [1652388152.351710][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388152.351772][1890:1890] CHIP:DMG: Cluster = 0x1f, [1652388152.351851][1890:1890] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.351906][1890:1890] CHIP:DMG: } [1652388152.352007][1890:1890] CHIP:DMG: [1652388152.352059][1890:1890] CHIP:DMG: Data = [ [1652388152.352113][1890:1890] CHIP:DMG: [1652388152.352166][1890:1890] CHIP:DMG: ], [1652388152.352222][1890:1890] CHIP:DMG: }, [1652388152.352322][1890:1890] CHIP:DMG: [1652388152.352364][1890:1890] CHIP:DMG: AttributeDataIB = [1652388152.352417][1890:1890] CHIP:DMG: { [1652388152.352462][1890:1890] CHIP:DMG: AttributePathIB = [1652388152.352500][1890:1890] CHIP:DMG: { [1652388152.352530][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388152.352563][1890:1890] CHIP:DMG: Cluster = 0x1f, [1652388152.352594][1890:1890] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.352629][1890:1890] CHIP:DMG: ListIndex = Null, [1652388152.352661][1890:1890] CHIP:DMG: } [1652388152.352691][1890:1890] CHIP:DMG: [1652388152.352720][1890:1890] CHIP:DMG: Data = [1652388152.352752][1890:1890] CHIP:DMG: { [1652388152.352789][1890:1890] CHIP:DMG: 0x1 = 5, [1652388152.352826][1890:1890] CHIP:DMG: 0x2 = 2, [1652388152.352859][1890:1890] CHIP:DMG: 0x3 = [ [1652388152.352894][1890:1890] CHIP:DMG: 112233, [1652388152.352935][1890:1890] CHIP:DMG: ], [1652388152.352972][1890:1890] CHIP:DMG: 0x4 = NULL [1652388152.353007][1890:1890] CHIP:DMG: }, [1652388152.353038][1890:1890] CHIP:DMG: }, [1652388152.353077][1890:1890] CHIP:DMG: [1652388152.353101][1890:1890] CHIP:DMG: AttributeDataIB = [1652388152.353130][1890:1890] CHIP:DMG: { [1652388152.353160][1890:1890] CHIP:DMG: AttributePathIB = [1652388152.353194][1890:1890] CHIP:DMG: { [1652388152.353228][1890:1890] CHIP:DMG: Endpoint = 0x0, [1652388152.353260][1890:1890] CHIP:DMG: Cluster = 0x1f, [1652388152.353293][1890:1890] CHIP:DMG: Attribute = 0x0000_0000, [1652388152.353324][1890:1890] CHIP:DMG: ListIndex = Null, [1652388152.353397][1890:1890] CHIP:DMG: } [1652388152.353432][1890:1890] CHIP:DMG: [1652388152.353465][1890:1890] CHIP:DMG: Data = [1652388152.353500][1890:1890] CHIP:DMG: { [1652388152.353535][1890:1890] CHIP:DMG: 0x1 = 3, [1652388152.353572][1890:1890] CHIP:DMG: 0x2 = 2, [1652388152.353606][1890:1890] CHIP:DMG: 0x3 = NULL [1652388152.353643][1890:1890] CHIP:DMG: 0x4 = NULL [1652388152.353676][1890:1890] CHIP:DMG: }, [1652388152.353707][1890:1890] CHIP:DMG: }, [1652388152.353738][1890:1890] CHIP:DMG: [1652388152.353761][1890:1890] CHIP:DMG: ], [1652388152.353800][1890:1890] CHIP:DMG: [1652388152.353824][1890:1890] CHIP:DMG: moreChunkedMessages = false, [1652388152.353849][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388152.353871][1890:1890] CHIP:DMG: }, [1652388152.353964][1890:1890] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t= c=0x0000_001F e=0 p=a [1652388152.354001][1890:1890] CHIP:DMG: AccessControl: allowed [1652388152.354100][1890:1890] CHIP:EVL: LogEvent event number: 0x0000000000000001 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000010432EE [1652388152.354373][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rt17PZ) [1652388152.355874][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.356065][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-7QdGOf) [1652388152.357444][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.357616][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nqrej0) [1652388152.359076][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.359245][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-U0ogYG) [1652388152.360771][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.360945][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-TVtiPU) [1652388152.362475][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.362649][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qaIIzy) [1652388152.366831][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.367001][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-cccuSZ) [1652388152.368404][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.368575][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-dxmYLy) [1652388152.369932][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.370094][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-sGLDfE) [1652388152.371420][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.371581][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-SLuCAS) [1652388152.373041][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.373217][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-hM0aTy) [1652388152.374766][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.374962][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-A5YRuM) [1652388152.376652][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.376852][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-s92qeb) [1652388152.378496][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.378682][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-sXs6Gs) [1652388152.380342][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.380535][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-4SQcrF) [1652388152.382192][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.382391][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-9oI9Cs) [1652388152.384029][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.384220][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-8nkTHI) [1652388152.385716][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.385883][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-oxQ8i8) [1652388152.389950][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.390120][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Ixh3T0) [1652388152.391470][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.391630][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-0PMxu5) [1652388152.393036][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.393211][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1K1Bti) [1652388152.394685][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.394875][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-VjaOoP) [1652388152.396442][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.396624][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3W9vPp) [1652388152.398161][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.398367][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-JSVKBb) [1652388152.399913][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.400105][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-QE0oOJ) [1652388152.401646][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.401824][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-pn4FwR) [1652388152.403357][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.403538][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ztar2g) [1652388152.405044][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.405216][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-6W9Y1y) [1652388152.406725][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.406891][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-L7RYcZ) [1652388152.408428][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.408592][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-wssTs8) [1652388152.412646][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.412822][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-2kXs6y) [1652388152.414204][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.414380][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-tyYxi2) [1652388152.415929][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.416121][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-iVH3bv) [1652388152.417651][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.417830][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-LOBwzP) [1652388152.419345][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.419520][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-y1R290) [1652388152.421207][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.421390][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-NvE9xn) [1652388152.422907][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.423177][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-aGWv0l) [1652388152.424788][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.424958][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-KLEnxV) [1652388152.426305][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.426460][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Vz8l72) [1652388152.427973][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.428167][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-XJ8aB1) [1652388152.429630][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.429797][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-VkQTjk) [1652388152.431332][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.431488][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-S0p5fz) [1652388152.435694][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.435916][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WcixCw) [1652388152.437348][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.437571][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-8Aa2UJ) [1652388152.439513][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.439729][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-IOz3bQ) [1652388152.441681][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.441898][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-DMyJXu) [1652388152.443832][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.444055][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-vNuzmX) [1652388152.446049][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.446268][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-yITzwY) [1652388152.447981][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.448137][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-0CKvdm) [1652388152.449450][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.449508][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 783c3bf6 [1652388152.449567][1890:1890] CHIP:DMG: IM WH moving to [AddStatus] [1652388152.449703][1890:1890] CHIP:DMG: AccessControl: validating f=1 p=a a=c s=1 t=0 [1652388152.449732][1890:1890] CHIP:DMG: validating subject 0x000000000001B669 [1652388152.449915][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-KMhrWM) [1652388152.451268][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.451438][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-o8GWye) [1652388152.452880][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.453050][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1KSsKB) [1652388152.454567][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.454749][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ep5JqR) [1652388152.456279][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.456453][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-bd3xek) [1652388152.460591][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.460760][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-B4jSnF) [1652388152.462082][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.462238][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-vUw6Ub) [1652388152.463548][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.463703][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-BeQupI) [1652388152.465099][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.465263][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qEbUI9) [1652388152.466583][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.466748][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-HbEadt) [1652388152.468252][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.468453][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-u489Lf) [1652388152.470067][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.470247][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-wNFb0R) [1652388152.471981][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.472171][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-GNPkQz) [1652388152.473782][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.473958][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Gdoscq) [1652388152.475556][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.475728][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-HBiG4d) [1652388152.477384][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.477580][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-x830Uo) [1652388152.479087][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.479247][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-YRP10z) [1652388152.483390][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.483569][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-yGBLAf) [1652388152.484908][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.485068][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qWNLM4) [1652388152.486381][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.486534][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-R4qGdk) [1652388152.487940][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.488110][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-bcLbR2) [1652388152.489619][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.489814][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-HhMVks) [1652388152.491475][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.491672][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-kneWvS) [1652388152.493333][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.493527][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-KGzp8c) [1652388152.495138][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.495318][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1z3CZ3) [1652388152.496963][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.497147][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-tMn5NL) [1652388152.498771][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.498963][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-uDnMpW) [1652388152.500492][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.500659][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-OJOI1l) [1652388152.502183][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.502348][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1IxLP7) [1652388152.506428][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.506591][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Fr47Yh) [1652388152.507941][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.508103][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nWuo7e) [1652388152.509432][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.509593][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ekNvml) [1652388152.511017][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.511192][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-dEJepq) [1652388152.512737][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.512917][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-fzFC9v) [1652388152.514410][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.514583][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-e4y2AR) [1652388152.516229][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.516412][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1a9Xln) [1652388152.517911][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.518082][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-tYMJna) [1652388152.519586][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.519763][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-7lfrDj) [1652388152.521214][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.521380][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-IifPeG) [1652388152.522897][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.523060][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-qJKQHq) [1652388152.524603][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.524766][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-SkHN5y) [1652388152.528848][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.529031][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-5E2BtO) [1652388152.530348][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.530513][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-ohrgJg) [1652388152.532166][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.532360][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-9OtqtP) [1652388152.533980][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.534161][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-IcQZKj) [1652388152.535760][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.535973][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-umWVdy) [1652388152.537596][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.537782][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3GWuuc) [1652388152.539389][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.539568][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-QxzJXx) [1652388152.541216][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.541373][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-YFhFl9) [1652388152.542678][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.542804][1890:1890] CHIP:EVL: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000010433AA [1652388152.542862][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 783c3bf7 [1652388152.542901][1890:1890] CHIP:DMG: IM WH moving to [AddStatus] [1652388152.543022][1890:1890] CHIP:DMG: AccessControl: validating f=1 p=o a=c s=0 t=0 [1652388152.543218][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-voZ1rM) [1652388152.544619][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.544800][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-3FF5xH) [1652388152.546300][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.546470][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Ym4Kmn) [1652388152.548060][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.548248][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-cLtMuG) [1652388152.552308][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.552480][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-4SZsac) [1652388152.553886][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.554070][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-MLJbJJ) [1652388152.555574][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.555746][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-lKw2H0) [1652388152.557277][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.557455][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-EWjxke) [1652388152.558943][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.559117][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-vxQIk1) [1652388152.560715][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.560895][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nQvNYy) [1652388152.562411][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.562595][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-5Pn1z5) [1652388152.564029][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.564195][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-iZE7dp) [1652388152.565521][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.565676][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-2r0EBU) [1652388152.567148][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.567313][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-RkOHDW) [1652388152.568849][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.569039][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-6W1Wa3) [1652388152.570559][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.570718][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-9ZIpHk) [1652388152.574927][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.575129][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-cmlUc3) [1652388152.576632][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.576820][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-RB4jKw) [1652388152.578322][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.578498][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-IvbEO8) [1652388152.580015][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.580202][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-iDDGXA) [1652388152.581706][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.581879][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-5jJ9k1) [1652388152.583373][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.583551][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-MFKZTo) [1652388152.585147][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.585333][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-WkXGkm) [1652388152.586841][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.587008][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-NOnN62) [1652388152.588358][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.588553][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-Q04Run) [1652388152.589981][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.590139][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rq7NqE) [1652388152.591675][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.591933][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-PuVDv1) [1652388152.593394][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.593580][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-2Hq9uD) [1652388152.597650][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.597830][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-6kulmh) [1652388152.599250][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.599420][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-BcL2ow) [1652388152.600910][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.601085][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-stFWtS) [1652388152.602493][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.602661][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rzBCN4) [1652388152.604098][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.604273][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-N0Nuqv) [1652388152.605663][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.605825][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-6YOmOS) [1652388152.607246][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.607425][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-NQLTiI) [1652388152.609101][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.609289][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-uRtZxG) [1652388152.610798][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.610980][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-P0dvxy) [1652388152.612515][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.612700][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-K9wuYR) [1652388152.614216][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.614389][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-UvEGP9) [1652388152.616028][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.616228][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-hoEPh1) [1652388152.620152][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.620350][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-rbpUX5) [1652388152.621671][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.621834][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-pLgQjq) [1652388152.623151][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.623305][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-9AMlsB) [1652388152.624728][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.624894][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-9CeONT) [1652388152.626213][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.626366][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-PeblO2) [1652388152.627680][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.627867][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-lyZ3YC) [1652388152.629271][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.629453][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-1sYZbe) [1652388152.630951][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.631125][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-nCW9u3) [1652388152.632653][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.632827][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-MVQsTf) [1652388152.634313][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388152.634446][1890:1890] CHIP:EVL: LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000001043406 [1652388152.634497][1890:1890] CHIP:DMG: Endpoint 0, Cluster 0x0000_001F update version to 783c3bf8 [1652388152.634554][1890:1890] CHIP:DMG: IM WH moving to [AddStatus] [1652388152.634638][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:4069524 on exchange: 1771r [1652388152.634757][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x000000000001B669 (1) of type 0x7 and protocolId (0, 1) on exchange 1771r with MessageCounter:11415748. [1652388152.634805][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:11415748 to 0x000000000001B669 (1) at monotonic time: 0000000001043406 msec [1652388152.635035][1890:1890] CHIP:DMG: IM WH moving to [Sending] [1652388152.635081][1890:1890] CHIP:DMG: IM WH moving to [Uninitialized] [1652388152.635160][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388152.640810][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4069525 on exchange 1771r [1652388152.640853][1890:1890] CHIP:EM: Found matching exchange: 1771r, Delegate: (nil) [1652388152.640898][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:11415748 from Retrans Table on exchange 1771r [1652388152.640926][1890:1890] CHIP:EM: Removed CHIP MessageCounter:11415748 from RetransTable on exchange 1771r [1652388178.198344][1890:1890] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:3236845304 on exchange 59671r [1652388178.198465][1890:1890] CHIP:EM: Handling via exchange: 59671r, Delegate: 0xaaaaca7b4920 [1652388178.198563][1890:1890] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaaca7b6220 [1652388178.198738][1890:1890] CHIP:SC: Waiting for Sigma1 msg [1652388178.198798][1890:1890] CHIP:IN: CASE Server disabling CASE session setups [1652388178.198858][1890:1890] CHIP:SC: Received Sigma1 msg [1652388178.198960][1890:1890] CHIP:SC: Peer assigned session key ID 13806 [1652388178.200026][1890:1890] CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 [1652388178.202469][1890:1890] CHIP:SC: Including MRP parameters [1652388178.202607][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:3236845304 on exchange: 59671r [1652388178.202703][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 59671r with MessageCounter:1378659139. [1652388178.202795][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659139 to 0x0000000000000000 at monotonic time: 00000000010497E6 msec [1652388178.203169][1890:1890] CHIP:SC: Sent Sigma2 msg [1652388178.531779][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659139 on exchange 59671r Send Cnt 0 [1652388178.531972][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659139 to 0x0000000000000000 at monotonic time: 0000000001049930 msec [1652388178.876736][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659139 on exchange 59671r Send Cnt 1 [1652388178.876891][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659139 to 0x0000000000000000 at monotonic time: 0000000001049A89 msec [1652388179.216623][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659139 on exchange 59671r Send Cnt 2 [1652388179.216769][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659139 to 0x0000000000000000 at monotonic time: 0000000001049BDC msec [1652388179.781738][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:1378659139 on exchange 59671r sendCount: 3 max retries: 3 [1652388180.074005][1890:1890] CHIP:EM: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3236845305 on exchange 59671r [1652388180.074089][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: 0xaaaaca7b4940 [1652388180.074156][1890:1890] CHIP:EM: CHIP MessageCounter:1378659139 not in RetransTable on exchange 59671r [1652388180.074247][1890:1890] CHIP:SC: Received Sigma3 msg [1652388180.081530][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-pOIQ6i) [1652388180.084945][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388180.085308][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-hX5hbx) [1652388180.086834][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388180.087006][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_kvs-eaSdFJ) [1652388180.088356][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1652388180.088415][1890:1890] CHIP:SC: Sending status report. Protocol code 0, exchange 59671 [1652388180.088461][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:3236845305 on exchange: 59671r [1652388180.088508][1890:1890] CHIP:IN: Prepared unauthenticated message 0xaaaaca7b4f18 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 59671r with MessageCounter:1378659140. [1652388180.088554][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659140 to 0x0000000000000000 at monotonic time: 0000000001049F44 msec [1652388180.088833][1890:1890] CHIP:IN: New secure session created for device <0000000000000002, 1>, LSID:31113 PSID:13806! [1652388180.088867][1890:1890] CHIP:IN: CASE Session established to peer: <0000000000000002, 1> [1652388180.088889][1890:1890] CHIP:IN: CASE Server enabling CASE session setups [1652388180.191951][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3236845306 on exchange 59671r [1652388180.192037][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: (nil) [1652388180.192109][1890:1890] CHIP:EM: CHIP MessageCounter:1378659139 not in RetransTable on exchange 59671r [1652388180.411890][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:3236845305 on exchange 59671r [1652388180.411968][1890:1890] CHIP:EM: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3236845305 on exchange 59671r [1652388180.412030][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: (nil) [1652388180.412088][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:3236845305 on exchange 59671r [1652388180.412144][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:3236845305 on exchange 59671r [1652388180.412222][1890:1890] CHIP:IN: Prepared unauthenticated message 0xfffffe838968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 59671r with MessageCounter:1378659141. [1652388180.412304][1890:1890] CHIP:IN: Sending unauthenticated msg 0xfffffe838968 with MessageCounter:1378659141 to 0x0000000000000000 at monotonic time: 000000000104A088 msec [1652388180.451795][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659140 on exchange 59671r Send Cnt 0 [1652388180.451987][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659140 to 0x0000000000000000 at monotonic time: 000000000104A0B0 msec [1652388180.771982][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:3236845305 on exchange 59671r [1652388180.772072][1890:1890] CHIP:EM: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3236845305 on exchange 59671r [1652388180.772136][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: (nil) [1652388180.772196][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:3236845305 on exchange 59671r [1652388180.772252][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:3236845305 on exchange 59671r [1652388180.772331][1890:1890] CHIP:IN: Prepared unauthenticated message 0xfffffe838968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 59671r with MessageCounter:1378659142. [1652388180.772413][1890:1890] CHIP:IN: Sending unauthenticated msg 0xfffffe838968 with MessageCounter:1378659142 to 0x0000000000000000 at monotonic time: 000000000104A1F0 msec [1652388180.785883][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659140 on exchange 59671r Send Cnt 1 [1652388180.786035][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659140 to 0x0000000000000000 at monotonic time: 000000000104A1FE msec [1652388181.102692][1890:1890] CHIP:EM: Retransmitting MessageCounter:1378659140 on exchange 59671r Send Cnt 2 [1652388181.102852][1890:1890] CHIP:IN: Sending unauthenticated msg 0xaaaaca7b4f18 with MessageCounter:1378659140 to 0x0000000000000000 at monotonic time: 000000000104A33B msec [1652388181.125723][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:3236845305 on exchange 59671r [1652388181.125802][1890:1890] CHIP:EM: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3236845305 on exchange 59671r [1652388181.125864][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: (nil) [1652388181.125923][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:3236845305 on exchange 59671r [1652388181.125977][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:3236845305 on exchange 59671r [1652388181.126052][1890:1890] CHIP:IN: Prepared unauthenticated message 0xfffffe838968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 59671r with MessageCounter:1378659143. [1652388181.126132][1890:1890] CHIP:IN: Sending unauthenticated msg 0xfffffe838968 with MessageCounter:1378659143 to 0x0000000000000000 at monotonic time: 000000000104A352 msec [1652388181.179755][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3236845307 on exchange 59671r [1652388181.179853][1890:1890] CHIP:EM: Found matching exchange: 59671r, Delegate: (nil) [1652388181.179917][1890:1890] CHIP:EM: CHIP MessageCounter:1378659139 not in RetransTable on exchange 59671r [1652388181.617282][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:1378659140 on exchange 59671r sendCount: 3 max retries: 3 [1652388182.168750][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3236845308 on exchange 59671r [1652388182.306658][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051192 on exchange 59672r [1652388182.306751][1890:1890] CHIP:EM: Handling via exchange: 59672r, Delegate: 0xaaaaca7bd558 [1652388182.306911][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388182.306978][1890:1890] CHIP:DMG: { [1652388182.307035][1890:1890] CHIP:DMG: suppressResponse = false, [1652388182.307101][1890:1890] CHIP:DMG: timedRequest = false, [1652388182.307162][1890:1890] CHIP:DMG: InvokeRequests = [1652388182.307247][1890:1890] CHIP:DMG: [ [1652388182.307307][1890:1890] CHIP:DMG: CommandDataIB = [1652388182.307388][1890:1890] CHIP:DMG: { [1652388182.307452][1890:1890] CHIP:DMG: CommandPathIB = [1652388182.307527][1890:1890] CHIP:DMG: { [1652388182.307671][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388182.307761][1890:1890] CHIP:DMG: ClusterId = 0x29, [1652388182.307890][1890:1890] CHIP:DMG: CommandId = 0x0, [1652388182.307970][1890:1890] CHIP:DMG: }, [1652388182.308052][1890:1890] CHIP:DMG: [1652388182.308120][1890:1890] CHIP:DMG: CommandData = [1652388182.308204][1890:1890] CHIP:DMG: { [1652388182.308318][1890:1890] CHIP:DMG: 0x0 = 65521, [1652388182.308410][1890:1890] CHIP:DMG: 0x1 = 32773, [1652388182.308500][1890:1890] CHIP:DMG: 0x2 = 1, [1652388182.308580][1890:1890] CHIP:DMG: 0x3 = [ [1652388182.308662][1890:1890] CHIP:DMG: 0, [1652388182.308777][1890:1890] CHIP:DMG: ], [1652388182.308872][1890:1890] CHIP:DMG: 0x4 = 0, [1652388182.308965][1890:1890] CHIP:DMG: 0x5 = "XX", [1652388182.309057][1890:1890] CHIP:DMG: 0x6 = false, [1652388182.309143][1890:1890] CHIP:DMG: }, [1652388182.309213][1890:1890] CHIP:DMG: }, [1652388182.309347][1890:1890] CHIP:DMG: [1652388182.309412][1890:1890] CHIP:DMG: ], [1652388182.309496][1890:1890] CHIP:DMG: [1652388182.309555][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388182.309612][1890:1890] CHIP:DMG: }, [1652388182.309808][1890:1890] CHIP:DMG: AccessControl: checking f=1 a=c s=0x0000000000000002 t= c=0x0000_0029 e=0 p=o [1652388182.309894][1890:1890] CHIP:DMG: AccessControl: allowed [1652388182.309958][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0029 Command=0x0000_0000 [1652388182.310056][1890:1890] CHIP:ZCL: OTA Provider received QueryImage [1652388182.310112][1890:1890] CHIP:ZCL: VendorID: 0xfff1 [1652388182.310161][1890:1890] CHIP:ZCL: ProductID: 32773 [1652388182.310242][1890:1890] CHIP:ZCL: SoftwareVersion: 1 [1652388182.310293][1890:1890] CHIP:ZCL: ProtocolsSupported: [ [1652388182.310350][1890:1890] CHIP:ZCL: 0 [1652388182.310403][1890:1890] CHIP:ZCL: ] [1652388182.310451][1890:1890] CHIP:ZCL: HardwareVersion: 0 [1652388182.310500][1890:1890] CHIP:ZCL: Location: XX [1652388182.310549][1890:1890] CHIP:ZCL: RequestorCanConsent: 0 [1652388182.310626][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388182.310694][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388182.310766][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388182.310931][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388182.311001][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051192 on exchange: 59672r [1652388182.311135][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x9 and protocolId (0, 1) on exchange 59672r with MessageCounter:16419145. [1652388182.311225][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419145 to 0x0000000000000002 (1) at monotonic time: 000000000104A7F3 msec [1652388182.311611][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388182.311680][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388182.318985][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3236845309 on exchange 59671r [1652388182.661568][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419145 on exchange 59672r Send Cnt 0 [1652388182.661726][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419145 to 0x0000000000000002 (1) at monotonic time: 000000000104A951 msec [1652388183.029466][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419145 on exchange 59672r Send Cnt 1 [1652388183.029634][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419145 to 0x0000000000000002 (1) at monotonic time: 000000000104AAC1 msec [1652388183.334325][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419145 on exchange 59672r Send Cnt 2 [1652388183.334476][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419145 to 0x0000000000000002 (1) at monotonic time: 000000000104ABF2 msec [1652388183.370762][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051193 on exchange 59672r [1652388183.370842][1890:1890] CHIP:EM: Found matching exchange: 59672r, Delegate: (nil) [1652388183.370929][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:16419145 from Retrans Table on exchange 59672r [1652388183.370989][1890:1890] CHIP:EM: Removed CHIP MessageCounter:16419145 from RetransTable on exchange 59672r [1652388183.607769][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051194 on exchange 59672r [1652388183.848733][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051195 on exchange 59672r [1652388184.088719][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051196 on exchange 59672r [1652388303.427553][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051197 on exchange 59673r [1652388303.427678][1890:1890] CHIP:EM: Handling via exchange: 59673r, Delegate: 0xaaaaca7bd558 [1652388303.427888][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388303.427959][1890:1890] CHIP:DMG: { [1652388303.428016][1890:1890] CHIP:DMG: suppressResponse = false, [1652388303.428082][1890:1890] CHIP:DMG: timedRequest = false, [1652388303.428143][1890:1890] CHIP:DMG: InvokeRequests = [1652388303.428228][1890:1890] CHIP:DMG: [ [1652388303.428288][1890:1890] CHIP:DMG: CommandDataIB = [1652388303.428367][1890:1890] CHIP:DMG: { [1652388303.428432][1890:1890] CHIP:DMG: CommandPathIB = [1652388303.428507][1890:1890] CHIP:DMG: { [1652388303.428589][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388303.428672][1890:1890] CHIP:DMG: ClusterId = 0x29, [1652388303.428813][1890:1890] CHIP:DMG: CommandId = 0x0, [1652388303.428898][1890:1890] CHIP:DMG: }, [1652388303.428981][1890:1890] CHIP:DMG: [1652388303.429050][1890:1890] CHIP:DMG: CommandData = [1652388303.429133][1890:1890] CHIP:DMG: { [1652388303.429215][1890:1890] CHIP:DMG: 0x0 = 65521, [1652388303.429305][1890:1890] CHIP:DMG: 0x1 = 32773, [1652388303.429388][1890:1890] CHIP:DMG: 0x2 = 1, [1652388303.429467][1890:1890] CHIP:DMG: 0x3 = [ [1652388303.429558][1890:1890] CHIP:DMG: 0, [1652388303.429718][1890:1890] CHIP:DMG: ], [1652388303.429804][1890:1890] CHIP:DMG: 0x4 = 0, [1652388303.429900][1890:1890] CHIP:DMG: 0x5 = "XX", [1652388303.429983][1890:1890] CHIP:DMG: 0x6 = false, [1652388303.430065][1890:1890] CHIP:DMG: }, [1652388303.430165][1890:1890] CHIP:DMG: }, [1652388303.430258][1890:1890] CHIP:DMG: [1652388303.430317][1890:1890] CHIP:DMG: ], [1652388303.430398][1890:1890] CHIP:DMG: [1652388303.430458][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388303.430516][1890:1890] CHIP:DMG: }, [1652388303.430703][1890:1890] CHIP:DMG: AccessControl: checking f=1 a=c s=0x0000000000000002 t= c=0x0000_0029 e=0 p=o [1652388303.430789][1890:1890] CHIP:DMG: AccessControl: allowed [1652388303.430855][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0029 Command=0x0000_0000 [1652388303.430951][1890:1890] CHIP:ZCL: OTA Provider received QueryImage [1652388303.431006][1890:1890] CHIP:ZCL: VendorID: 0xfff1 [1652388303.431054][1890:1890] CHIP:ZCL: ProductID: 32773 [1652388303.431139][1890:1890] CHIP:ZCL: SoftwareVersion: 1 [1652388303.431192][1890:1890] CHIP:ZCL: ProtocolsSupported: [ [1652388303.431249][1890:1890] CHIP:ZCL: 0 [1652388303.431301][1890:1890] CHIP:ZCL: ] [1652388303.431349][1890:1890] CHIP:ZCL: HardwareVersion: 0 [1652388303.431398][1890:1890] CHIP:ZCL: Location: XX [1652388303.431447][1890:1890] CHIP:ZCL: RequestorCanConsent: 0 [1652388303.433692][1890:1890] CHIP:SWU: Generated updateToken: 1EE21642C8ECD1223A561209DC8A99 [1652388303.433774][1890:1890] CHIP:SWU: Generated URI: bdx://0000000000000001//home/pi/connectedhomeip/out/ota/BRD4164A/chip-efr32-lighting-example.ota [1652388303.433873][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388303.433946][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388303.434025][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388303.434139][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388303.434211][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051197 on exchange: 59673r [1652388303.434371][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x9 and protocolId (0, 1) on exchange 59673r with MessageCounter:16419146. [1652388303.434461][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419146 to 0x0000000000000002 (1) at monotonic time: 0000000001068116 msec [1652388303.434852][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388303.434922][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388303.785031][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051198 on exchange 59673r [1652388303.785116][1890:1890] CHIP:EM: Found matching exchange: 59673r, Delegate: (nil) [1652388303.785202][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:16419146 from Retrans Table on exchange 59673r [1652388303.785262][1890:1890] CHIP:EM: Removed CHIP MessageCounter:16419146 from RetransTable on exchange 59673r [1652388303.866911][1890:1890] CHIP:EM: Received message of type 0x4 with protocolId (0, 2) and MessageCounter:9051199 on exchange 59674r [1652388303.867004][1890:1890] CHIP:EM: Handling via exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388303.867089][1890:1890] CHIP:BDX: OnMessageReceived: message 0x4 protocol (0, 2) [1652388303.867150][1890:1890] CHIP:ATM: Handling received BDX Message [1652388303.867216][1890:1890] CHIP:ATM: ReceiveInit [1652388303.867268][1890:1890] CHIP:ATM: Proposed Transfer Control: 0x20 [1652388303.867317][1890:1890] CHIP:ATM: Range Control: 0x0 [1652388303.867365][1890:1890] CHIP:ATM: Proposed Max Block Size: 1024 [1652388303.867413][1890:1890] CHIP:ATM: Start Offset: 0x0000000000000000 [1652388303.867464][1890:1890] CHIP:ATM: Proposed Max Length: 0x0000000000000000 [1652388303.867514][1890:1890] CHIP:ATM: File Designator Length: 73 [1652388303.867562][1890:1890] CHIP:ATM: File Designator: /home/pi/connectedhomeip/out/ota/BRD4164A/chip-efr32-lighting-example.ota [1652388303.934831][1890:1890] CHIP:BDX: OutputEvent type: InitReceived [1652388303.934908][1890:1890] CHIP:ATM: Sending BDX Message [1652388303.934960][1890:1890] CHIP:ATM: ReceiveAccept [1652388303.935008][1890:1890] CHIP:ATM: Transfer Control: 0x20 [1652388303.935058][1890:1890] CHIP:ATM: Range Control: 0x0 [1652388303.935106][1890:1890] CHIP:ATM: Max Block Size: 1024 [1652388303.935154][1890:1890] CHIP:ATM: Length: 0x0000000000000000 [1652388304.067491][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051199 on exchange 59674r [1652388304.067633][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419147. [1652388304.067723][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419147 to 0x0000000000000002 (1) at monotonic time: 000000000106838F msec [1652388304.435512][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388304.435597][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051199 on exchange: 59674r [1652388304.435717][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x5 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419148. [1652388304.435803][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419148 to 0x0000000000000002 (1) at monotonic time: 00000000010684FF msec [1652388304.482828][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051200 on exchange 59674r [1652388304.482908][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388304.482992][1890:1890] CHIP:EM: Rxd Ack; Removing MessageCounter:16419148 from Retrans Table on exchange 59674r [1652388304.483051][1890:1890] CHIP:EM: Removed CHIP MessageCounter:16419148 from RetransTable on exchange 59674r [1652388304.483126][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388304.483183][1890:1890] CHIP:ATM: Handling received BDX Message [1652388304.483238][1890:1890] CHIP:ATM: BlockQuery [1652388304.483287][1890:1890] CHIP:ATM: Block Counter: 0 [1652388304.683691][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051200 on exchange 59674r [1652388304.683860][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419149. [1652388304.683946][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419149 to 0x0000000000000002 (1) at monotonic time: 00000000010685F8 msec [1652388304.792104][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051200 on exchange 59674r [1652388304.792186][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051200 on exchange 59674r [1652388304.792247][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388304.792304][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051200 on exchange 59674r [1652388304.792360][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051200 on exchange 59674r [1652388304.792457][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419150. [1652388304.792539][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419150 to 0x0000000000000002 (1) at monotonic time: 0000000001068664 msec [1652388304.937022][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388304.937374][1890:1890] CHIP:ATM: Sending BDX Message [1652388304.937437][1890:1890] CHIP:ATM: Block [1652388304.937488][1890:1890] CHIP:ATM: Block Counter: 0 [1652388304.937537][1890:1890] CHIP:ATM: Data Length: 1024 [1652388305.438249][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388305.438332][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051200 on exchange: 59674r [1652388305.438584][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419151. [1652388305.438674][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419151 to 0x0000000000000002 (1) at monotonic time: 00000000010688EA msec [1652388305.745571][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419151 on exchange 59674r Send Cnt 0 [1652388305.745742][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419151 to 0x0000000000000002 (1) at monotonic time: 0000000001068A1D msec [1652388306.068586][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419151 on exchange 59674r Send Cnt 1 [1652388306.068745][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419151 to 0x0000000000000002 (1) at monotonic time: 0000000001068B60 msec [1652388306.384395][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419151 on exchange 59674r Send Cnt 2 [1652388306.384548][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419151 to 0x0000000000000002 (1) at monotonic time: 0000000001068C9C msec [1652388306.884535][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419151 on exchange 59674r sendCount: 3 max retries: 3 [1652388306.934899][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051201 on exchange 59674r [1652388306.934977][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388306.935043][1890:1890] CHIP:EM: CHIP MessageCounter:16419151 not in RetransTable on exchange 59674r [1652388306.935122][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388306.935180][1890:1890] CHIP:ATM: Handling received BDX Message [1652388306.935235][1890:1890] CHIP:ATM: BlockQuery [1652388306.935284][1890:1890] CHIP:ATM: Block Counter: 1 [1652388306.940595][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388306.940921][1890:1890] CHIP:ATM: Sending BDX Message [1652388306.940982][1890:1890] CHIP:ATM: Block [1652388306.941031][1890:1890] CHIP:ATM: Block Counter: 1 [1652388306.941080][1890:1890] CHIP:ATM: Data Length: 1024 [1652388307.135528][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051201 on exchange 59674r [1652388307.135676][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419152. [1652388307.135765][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419152 to 0x0000000000000002 (1) at monotonic time: 0000000001068F8B msec [1652388307.249653][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051201 on exchange 59674r [1652388307.249736][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051201 on exchange 59674r [1652388307.249798][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388307.249855][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051201 on exchange 59674r [1652388307.249910][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051201 on exchange 59674r [1652388307.250007][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419153. [1652388307.250088][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419153 to 0x0000000000000002 (1) at monotonic time: 0000000001068FFE msec [1652388307.441585][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388307.441664][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051201 on exchange: 59674r [1652388307.441903][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419154. [1652388307.441988][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419154 to 0x0000000000000002 (1) at monotonic time: 00000000010690BE msec [1652388307.566744][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051201 on exchange 59674r [1652388307.566826][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051201 on exchange 59674r [1652388307.566887][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388307.566946][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051201 on exchange 59674r [1652388307.567001][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051201 on exchange 59674r [1652388307.567097][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419155. [1652388307.567178][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419155 to 0x0000000000000002 (1) at monotonic time: 000000000106913B msec [1652388307.778739][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419154 on exchange 59674r Send Cnt 0 [1652388307.778897][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419154 to 0x0000000000000002 (1) at monotonic time: 000000000106920F msec [1652388307.941711][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051201 on exchange 59674r [1652388307.941793][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051201 on exchange 59674r [1652388307.941854][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388307.941912][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051201 on exchange 59674r [1652388307.941968][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051201 on exchange 59674r [1652388307.942067][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419156. [1652388307.942148][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419156 to 0x0000000000000002 (1) at monotonic time: 00000000010692B2 msec [1652388308.110776][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419154 on exchange 59674r Send Cnt 1 [1652388308.110963][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419154 to 0x0000000000000002 (1) at monotonic time: 000000000106935B msec [1652388308.337715][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051202 on exchange 59674r [1652388308.337799][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388308.337871][1890:1890] CHIP:EM: CHIP MessageCounter:16419151 not in RetransTable on exchange 59674r [1652388308.423171][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419154 on exchange 59674r Send Cnt 2 [1652388308.423324][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419154 to 0x0000000000000002 (1) at monotonic time: 0000000001069493 msec [1652388309.020626][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419154 on exchange 59674r sendCount: 3 max retries: 3 [1652388309.813647][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051203 on exchange 59674r [1652388309.813742][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388309.813810][1890:1890] CHIP:EM: CHIP MessageCounter:16419151 not in RetransTable on exchange 59674r [1652388311.292514][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051204 on exchange 59674r [1652388311.292615][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388311.292683][1890:1890] CHIP:EM: CHIP MessageCounter:16419151 not in RetransTable on exchange 59674r [1652388313.028602][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051205 on exchange 59674r [1652388313.028699][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388313.028768][1890:1890] CHIP:EM: CHIP MessageCounter:16419154 not in RetransTable on exchange 59674r [1652388313.028853][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388313.028912][1890:1890] CHIP:ATM: Handling received BDX Message [1652388313.028969][1890:1890] CHIP:ATM: BlockQuery [1652388313.029019][1890:1890] CHIP:ATM: Block Counter: 2 [1652388313.229423][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051205 on exchange 59674r [1652388313.229571][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419157. [1652388313.229660][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419157 to 0x0000000000000002 (1) at monotonic time: 000000000106A759 msec [1652388313.373434][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051205 on exchange 59674r [1652388313.373518][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051205 on exchange 59674r [1652388313.373579][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388313.373636][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051205 on exchange 59674r [1652388313.373692][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051205 on exchange 59674r [1652388313.373791][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419158. [1652388313.373872][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419158 to 0x0000000000000002 (1) at monotonic time: 000000000106A7EA msec [1652388313.446286][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388313.446625][1890:1890] CHIP:ATM: Sending BDX Message [1652388313.446685][1890:1890] CHIP:ATM: Block [1652388313.446731][1890:1890] CHIP:ATM: Block Counter: 2 [1652388313.446779][1890:1890] CHIP:ATM: Data Length: 1024 [1652388313.674478][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051205 on exchange 59674r [1652388313.674572][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051205 on exchange 59674r [1652388313.674634][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388313.674694][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051205 on exchange 59674r [1652388313.674751][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051205 on exchange 59674r [1652388313.674859][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419159. [1652388313.674943][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419159 to 0x0000000000000002 (1) at monotonic time: 000000000106A917 msec [1652388313.947590][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388313.947673][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051205 on exchange: 59674r [1652388313.947950][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419160. [1652388313.948037][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419160 to 0x0000000000000002 (1) at monotonic time: 000000000106AA28 msec [1652388313.997425][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051205 on exchange 59674r [1652388313.997508][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051205 on exchange 59674r [1652388313.997568][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388313.997625][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051205 on exchange 59674r [1652388313.997680][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051205 on exchange 59674r [1652388313.997777][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419161. [1652388313.997855][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419161 to 0x0000000000000002 (1) at monotonic time: 000000000106AA5A msec [1652388314.264673][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419160 on exchange 59674r Send Cnt 0 [1652388314.264825][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419160 to 0x0000000000000002 (1) at monotonic time: 000000000106AB65 msec [1652388314.585848][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419160 on exchange 59674r Send Cnt 1 [1652388314.586067][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419160 to 0x0000000000000002 (1) at monotonic time: 000000000106ACA6 msec [1652388314.607380][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051206 on exchange 59674r [1652388314.607459][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388314.607529][1890:1890] CHIP:EM: CHIP MessageCounter:16419154 not in RetransTable on exchange 59674r [1652388314.887027][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419160 on exchange 59674r Send Cnt 2 [1652388314.887183][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419160 to 0x0000000000000002 (1) at monotonic time: 000000000106ADD3 msec [1652388315.398208][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419160 on exchange 59674r sendCount: 3 max retries: 3 [1652388316.206229][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051207 on exchange 59674r [1652388316.206324][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388316.206392][1890:1890] CHIP:EM: CHIP MessageCounter:16419154 not in RetransTable on exchange 59674r [1652388317.684151][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051208 on exchange 59674r [1652388317.684247][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388317.684315][1890:1890] CHIP:EM: CHIP MessageCounter:16419154 not in RetransTable on exchange 59674r [1652388319.541931][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051209 on exchange 59674r [1652388319.542026][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388319.542095][1890:1890] CHIP:EM: CHIP MessageCounter:16419160 not in RetransTable on exchange 59674r [1652388319.542175][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388319.542235][1890:1890] CHIP:ATM: Handling received BDX Message [1652388319.542291][1890:1890] CHIP:ATM: BlockQuery [1652388319.542340][1890:1890] CHIP:ATM: Block Counter: 3 [1652388319.742739][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051209 on exchange 59674r [1652388319.742883][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419162. [1652388319.742972][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419162 to 0x0000000000000002 (1) at monotonic time: 000000000106C0CB msec [1652388319.863100][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051209 on exchange 59674r [1652388319.863184][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051209 on exchange 59674r [1652388319.863246][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388319.863301][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051209 on exchange 59674r [1652388319.863358][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051209 on exchange 59674r [1652388319.863458][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419163. [1652388319.863539][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419163 to 0x0000000000000002 (1) at monotonic time: 000000000106C143 msec [1652388319.953941][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388319.954275][1890:1890] CHIP:ATM: Sending BDX Message [1652388319.954337][1890:1890] CHIP:ATM: Block [1652388319.954386][1890:1890] CHIP:ATM: Block Counter: 3 [1652388319.954435][1890:1890] CHIP:ATM: Data Length: 1024 [1652388320.233012][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051209 on exchange 59674r [1652388320.233101][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051209 on exchange 59674r [1652388320.233164][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388320.233223][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051209 on exchange 59674r [1652388320.233279][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051209 on exchange 59674r [1652388320.233386][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419164. [1652388320.233469][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419164 to 0x0000000000000002 (1) at monotonic time: 000000000106C2B5 msec [1652388320.455028][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388320.455104][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051209 on exchange: 59674r [1652388320.455342][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419165. [1652388320.455428][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419165 to 0x0000000000000002 (1) at monotonic time: 000000000106C393 msec [1652388320.575446][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051209 on exchange 59674r [1652388320.575529][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051209 on exchange 59674r [1652388320.575584][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388320.575633][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051209 on exchange 59674r [1652388320.575683][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051209 on exchange 59674r [1652388320.575775][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419166. [1652388320.575876][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419166 to 0x0000000000000002 (1) at monotonic time: 000000000106C40C msec [1652388320.809479][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419165 on exchange 59674r Send Cnt 0 [1652388320.809645][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419165 to 0x0000000000000002 (1) at monotonic time: 000000000106C4F5 msec [1652388321.119072][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051210 on exchange 59674r [1652388321.119152][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388321.119222][1890:1890] CHIP:EM: CHIP MessageCounter:16419160 not in RetransTable on exchange 59674r [1652388321.168454][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419165 on exchange 59674r Send Cnt 1 [1652388321.168600][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419165 to 0x0000000000000002 (1) at monotonic time: 000000000106C65C msec [1652388321.516431][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419165 on exchange 59674r Send Cnt 2 [1652388321.516579][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419165 to 0x0000000000000002 (1) at monotonic time: 000000000106C7B8 msec [1652388322.028564][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419165 on exchange 59674r sendCount: 3 max retries: 3 [1652388322.593803][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051211 on exchange 59674r [1652388322.593884][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388322.593943][1890:1890] CHIP:EM: CHIP MessageCounter:16419160 not in RetransTable on exchange 59674r [1652388324.069549][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051212 on exchange 59674r [1652388324.069648][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388324.069717][1890:1890] CHIP:EM: CHIP MessageCounter:16419160 not in RetransTable on exchange 59674r [1652388326.050775][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051213 on exchange 59674r [1652388326.050871][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388326.050939][1890:1890] CHIP:EM: CHIP MessageCounter:16419165 not in RetransTable on exchange 59674r [1652388326.051023][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388326.051083][1890:1890] CHIP:ATM: Handling received BDX Message [1652388326.051140][1890:1890] CHIP:ATM: BlockQuery [1652388326.051190][1890:1890] CHIP:ATM: Block Counter: 4 [1652388326.251595][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051213 on exchange 59674r [1652388326.251739][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419167. [1652388326.251863][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419167 to 0x0000000000000002 (1) at monotonic time: 000000000106DA38 msec [1652388326.359646][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051213 on exchange 59674r [1652388326.359728][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051213 on exchange 59674r [1652388326.359790][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388326.359876][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051213 on exchange 59674r [1652388326.359935][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051213 on exchange 59674r [1652388326.360034][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419168. [1652388326.360115][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419168 to 0x0000000000000002 (1) at monotonic time: 000000000106DAA4 msec [1652388326.462576][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388326.462905][1890:1890] CHIP:ATM: Sending BDX Message [1652388326.462967][1890:1890] CHIP:ATM: Block [1652388326.463018][1890:1890] CHIP:ATM: Block Counter: 4 [1652388326.463067][1890:1890] CHIP:ATM: Data Length: 1024 [1652388326.724958][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051213 on exchange 59674r [1652388326.725048][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051213 on exchange 59674r [1652388326.725110][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388326.725170][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051213 on exchange 59674r [1652388326.725227][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051213 on exchange 59674r [1652388326.725330][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419169. [1652388326.725412][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419169 to 0x0000000000000002 (1) at monotonic time: 000000000106DC11 msec [1652388326.964006][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388326.964084][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051213 on exchange: 59674r [1652388326.964324][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419170. [1652388326.964407][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419170 to 0x0000000000000002 (1) at monotonic time: 000000000106DD00 msec [1652388327.044895][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051213 on exchange 59674r [1652388327.044979][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051213 on exchange 59674r [1652388327.045041][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388327.045099][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051213 on exchange 59674r [1652388327.045155][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051213 on exchange 59674r [1652388327.045252][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419171. [1652388327.045332][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419171 to 0x0000000000000002 (1) at monotonic time: 000000000106DD51 msec [1652388327.320956][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419170 on exchange 59674r Send Cnt 0 [1652388327.321109][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419170 to 0x0000000000000002 (1) at monotonic time: 000000000106DE65 msec [1652388327.626667][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051214 on exchange 59674r [1652388327.626745][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388327.626815][1890:1890] CHIP:EM: CHIP MessageCounter:16419165 not in RetransTable on exchange 59674r [1652388327.677079][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419170 on exchange 59674r Send Cnt 1 [1652388327.677225][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419170 to 0x0000000000000002 (1) at monotonic time: 000000000106DFC9 msec [1652388328.049987][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419170 on exchange 59674r Send Cnt 2 [1652388328.050180][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419170 to 0x0000000000000002 (1) at monotonic time: 000000000106E13E msec [1652388328.646339][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419170 on exchange 59674r sendCount: 3 max retries: 3 [1652388329.102473][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051215 on exchange 59674r [1652388329.102556][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388329.102623][1890:1890] CHIP:EM: CHIP MessageCounter:16419165 not in RetransTable on exchange 59674r [1652388330.580645][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051216 on exchange 59674r [1652388330.580743][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388330.580813][1890:1890] CHIP:EM: CHIP MessageCounter:16419165 not in RetransTable on exchange 59674r [1652388332.494921][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051217 on exchange 59674r [1652388332.495012][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388332.495078][1890:1890] CHIP:EM: CHIP MessageCounter:16419170 not in RetransTable on exchange 59674r [1652388332.495159][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388332.495219][1890:1890] CHIP:ATM: Handling received BDX Message [1652388332.495274][1890:1890] CHIP:ATM: BlockQuery [1652388332.495323][1890:1890] CHIP:ATM: Block Counter: 5 [1652388332.695724][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051217 on exchange 59674r [1652388332.695905][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419172. [1652388332.695997][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419172 to 0x0000000000000002 (1) at monotonic time: 000000000106F364 msec [1652388332.808287][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051217 on exchange 59674r [1652388332.808369][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051217 on exchange 59674r [1652388332.808430][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388332.808488][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051217 on exchange 59674r [1652388332.808544][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051217 on exchange 59674r [1652388332.808640][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419173. [1652388332.808721][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419173 to 0x0000000000000002 (1) at monotonic time: 000000000106F3D4 msec [1652388332.970224][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388332.970553][1890:1890] CHIP:ATM: Sending BDX Message [1652388332.970616][1890:1890] CHIP:ATM: Block [1652388332.970667][1890:1890] CHIP:ATM: Block Counter: 5 [1652388332.970716][1890:1890] CHIP:ATM: Data Length: 1024 [1652388333.126335][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051217 on exchange 59674r [1652388333.126431][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051217 on exchange 59674r [1652388333.126494][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388333.126555][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051217 on exchange 59674r [1652388333.126611][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051217 on exchange 59674r [1652388333.126721][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419174. [1652388333.126805][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419174 to 0x0000000000000002 (1) at monotonic time: 000000000106F512 msec [1652388333.470523][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388333.470601][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051217 on exchange: 59674r [1652388333.470841][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419175. [1652388333.470926][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419175 to 0x0000000000000002 (1) at monotonic time: 000000000106F66B msec [1652388333.483145][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051217 on exchange 59674r [1652388333.483229][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051217 on exchange 59674r [1652388333.483290][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388333.483347][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051217 on exchange 59674r [1652388333.483403][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051217 on exchange 59674r [1652388333.483500][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419176. [1652388333.483579][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419176 to 0x0000000000000002 (1) at monotonic time: 000000000106F677 msec [1652388333.800248][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419175 on exchange 59674r Send Cnt 0 [1652388333.800410][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419175 to 0x0000000000000002 (1) at monotonic time: 000000000106F7B4 msec [1652388334.017326][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051218 on exchange 59674r [1652388334.017409][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388334.017481][1890:1890] CHIP:EM: CHIP MessageCounter:16419170 not in RetransTable on exchange 59674r [1652388334.131859][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419175 on exchange 59674r Send Cnt 1 [1652388334.132010][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419175 to 0x0000000000000002 (1) at monotonic time: 000000000106F900 msec [1652388334.480908][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419175 on exchange 59674r Send Cnt 2 [1652388334.481071][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419175 to 0x0000000000000002 (1) at monotonic time: 000000000106FA5D msec [1652388335.021117][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419175 on exchange 59674r sendCount: 3 max retries: 3 [1652388335.493095][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051219 on exchange 59674r [1652388335.493185][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388335.493252][1890:1890] CHIP:EM: CHIP MessageCounter:16419170 not in RetransTable on exchange 59674r [1652388336.973066][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051220 on exchange 59674r [1652388336.973154][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388336.973221][1890:1890] CHIP:EM: CHIP MessageCounter:16419170 not in RetransTable on exchange 59674r [1652388338.832099][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051221 on exchange 59674r [1652388338.832195][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388338.832261][1890:1890] CHIP:EM: CHIP MessageCounter:16419175 not in RetransTable on exchange 59674r [1652388338.832343][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388338.832402][1890:1890] CHIP:ATM: Handling received BDX Message [1652388338.832457][1890:1890] CHIP:ATM: BlockQuery [1652388338.832507][1890:1890] CHIP:ATM: Block Counter: 6 [1652388338.977853][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388338.978169][1890:1890] CHIP:ATM: Sending BDX Message [1652388338.978232][1890:1890] CHIP:ATM: Block [1652388338.978277][1890:1890] CHIP:ATM: Block Counter: 6 [1652388338.978325][1890:1890] CHIP:ATM: Data Length: 1024 [1652388339.032570][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051221 on exchange 59674r [1652388339.032700][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419177. [1652388339.032779][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419177 to 0x0000000000000002 (1) at monotonic time: 0000000001070C24 msec [1652388339.140932][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051221 on exchange 59674r [1652388339.141016][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051221 on exchange 59674r [1652388339.141078][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388339.141137][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051221 on exchange 59674r [1652388339.141192][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051221 on exchange 59674r [1652388339.141292][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419178. [1652388339.141373][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419178 to 0x0000000000000002 (1) at monotonic time: 0000000001070C91 msec [1652388339.479058][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388339.479134][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051221 on exchange: 59674r [1652388339.479371][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419179. [1652388339.479456][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419179 to 0x0000000000000002 (1) at monotonic time: 0000000001070DE3 msec [1652388339.496736][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051221 on exchange 59674r [1652388339.496818][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051221 on exchange 59674r [1652388339.496880][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388339.496936][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051221 on exchange 59674r [1652388339.496991][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051221 on exchange 59674r [1652388339.497089][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419180. [1652388339.497169][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419180 to 0x0000000000000002 (1) at monotonic time: 0000000001070DF5 msec [1652388339.800831][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419179 on exchange 59674r Send Cnt 0 [1652388339.800994][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419179 to 0x0000000000000002 (1) at monotonic time: 0000000001070F25 msec [1652388339.852880][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051221 on exchange 59674r [1652388339.852962][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051221 on exchange 59674r [1652388339.853024][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388339.853082][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051221 on exchange 59674r [1652388339.853136][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051221 on exchange 59674r [1652388339.853239][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419181. [1652388339.853320][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419181 to 0x0000000000000002 (1) at monotonic time: 0000000001070F59 msec [1652388340.135133][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419179 on exchange 59674r Send Cnt 1 [1652388340.135293][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419179 to 0x0000000000000002 (1) at monotonic time: 0000000001071073 msec [1652388340.410857][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051222 on exchange 59674r [1652388340.410936][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388340.411005][1890:1890] CHIP:EM: CHIP MessageCounter:16419175 not in RetransTable on exchange 59674r [1652388340.501629][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419179 on exchange 59674r Send Cnt 2 [1652388340.501876][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419179 to 0x0000000000000002 (1) at monotonic time: 00000000010711E2 msec [1652388341.053989][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419179 on exchange 59674r sendCount: 3 max retries: 3 [1652388341.888791][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051223 on exchange 59674r [1652388341.888873][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388341.888938][1890:1890] CHIP:EM: CHIP MessageCounter:16419175 not in RetransTable on exchange 59674r [1652388343.367619][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051224 on exchange 59674r [1652388343.367713][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388343.367779][1890:1890] CHIP:EM: CHIP MessageCounter:16419175 not in RetransTable on exchange 59674r [1652388345.110693][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051225 on exchange 59674r [1652388345.110781][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388345.110847][1890:1890] CHIP:EM: CHIP MessageCounter:16419179 not in RetransTable on exchange 59674r [1652388345.110927][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388345.110984][1890:1890] CHIP:ATM: Handling received BDX Message [1652388345.111039][1890:1890] CHIP:ATM: BlockQuery [1652388345.111087][1890:1890] CHIP:ATM: Block Counter: 7 [1652388345.311487][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051225 on exchange 59674r [1652388345.311621][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419182. [1652388345.311709][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419182 to 0x0000000000000002 (1) at monotonic time: 00000000010724AB msec [1652388345.450316][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051225 on exchange 59674r [1652388345.450398][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051225 on exchange 59674r [1652388345.450458][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388345.450516][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051225 on exchange 59674r [1652388345.450571][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051225 on exchange 59674r [1652388345.450670][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419183. [1652388345.450750][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419183 to 0x0000000000000002 (1) at monotonic time: 0000000001072536 msec [1652388345.482398][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388345.482686][1890:1890] CHIP:ATM: Sending BDX Message [1652388345.482741][1890:1890] CHIP:ATM: Block [1652388345.482784][1890:1890] CHIP:ATM: Block Counter: 7 [1652388345.482825][1890:1890] CHIP:ATM: Data Length: 1024 [1652388345.812645][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051225 on exchange 59674r [1652388345.812740][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051225 on exchange 59674r [1652388345.812805][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388345.812865][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051225 on exchange 59674r [1652388345.812922][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051225 on exchange 59674r [1652388345.813030][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419184. [1652388345.813112][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419184 to 0x0000000000000002 (1) at monotonic time: 00000000010726A1 msec [1652388345.983641][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388345.983720][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051225 on exchange: 59674r [1652388345.984012][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x11 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419185. [1652388345.984102][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419185 to 0x0000000000000002 (1) at monotonic time: 000000000107274C msec [1652388346.133782][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051225 on exchange 59674r [1652388346.133866][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051225 on exchange 59674r [1652388346.133926][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388346.133981][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051225 on exchange 59674r [1652388346.134036][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051225 on exchange 59674r [1652388346.134134][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419186. [1652388346.134214][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419186 to 0x0000000000000002 (1) at monotonic time: 00000000010727E2 msec [1652388346.341775][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419185 on exchange 59674r Send Cnt 0 [1652388346.341928][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419185 to 0x0000000000000002 (1) at monotonic time: 00000000010728B2 msec [1652388346.591474][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051226 on exchange 59674r [1652388346.591551][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388346.591621][1890:1890] CHIP:EM: CHIP MessageCounter:16419179 not in RetransTable on exchange 59674r [1652388346.669911][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419185 on exchange 59674r Send Cnt 1 [1652388346.670057][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419185 to 0x0000000000000002 (1) at monotonic time: 00000000010729FA msec [1652388347.036915][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419185 on exchange 59674r Send Cnt 2 [1652388347.037069][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419185 to 0x0000000000000002 (1) at monotonic time: 0000000001072B69 msec [1652388347.624135][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419185 on exchange 59674r sendCount: 3 max retries: 3 [1652388348.193644][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051227 on exchange 59674r [1652388348.193738][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388348.193805][1890:1890] CHIP:EM: CHIP MessageCounter:16419179 not in RetransTable on exchange 59674r [1652388349.672252][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051228 on exchange 59674r [1652388349.672331][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388349.672394][1890:1890] CHIP:EM: CHIP MessageCounter:16419179 not in RetransTable on exchange 59674r [1652388351.534344][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051229 on exchange 59674r [1652388351.534443][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388351.534511][1890:1890] CHIP:EM: CHIP MessageCounter:16419185 not in RetransTable on exchange 59674r [1652388351.534594][1890:1890] CHIP:BDX: OnMessageReceived: message 0x10 protocol (0, 2) [1652388351.534654][1890:1890] CHIP:ATM: Handling received BDX Message [1652388351.534710][1890:1890] CHIP:ATM: BlockQuery [1652388351.534759][1890:1890] CHIP:ATM: Block Counter: 8 [1652388351.734159][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051229 on exchange 59674r [1652388351.734297][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419187. [1652388351.734385][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419187 to 0x0000000000000002 (1) at monotonic time: 0000000001073DC2 msec [1652388351.833183][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051229 on exchange 59674r [1652388351.833266][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051229 on exchange 59674r [1652388351.833328][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388351.833385][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051229 on exchange 59674r [1652388351.833440][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051229 on exchange 59674r [1652388351.833540][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419188. [1652388351.833622][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419188 to 0x0000000000000002 (1) at monotonic time: 0000000001073E25 msec [1652388351.987081][1890:1890] CHIP:BDX: OutputEvent type: QueryReceived [1652388351.987412][1890:1890] CHIP:ATM: Sending BDX Message [1652388351.987473][1890:1890] CHIP:ATM: BlockEOF [1652388351.987522][1890:1890] CHIP:ATM: Block Counter: 8 [1652388351.987571][1890:1890] CHIP:ATM: Data Length: 927 [1652388352.148199][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051229 on exchange 59674r [1652388352.148273][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051229 on exchange 59674r [1652388352.148326][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388352.148378][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051229 on exchange 59674r [1652388352.148426][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051229 on exchange 59674r [1652388352.148518][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419189. [1652388352.148589][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419189 to 0x0000000000000002 (1) at monotonic time: 0000000001073F60 msec [1652388352.456635][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051229 on exchange 59674r [1652388352.456712][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 2) and MessageCounter:9051229 on exchange 59674r [1652388352.456760][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388352.456805][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051229 on exchange 59674r [1652388352.456848][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051229 on exchange 59674r [1652388352.456930][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419190. [1652388352.456993][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419190 to 0x0000000000000002 (1) at monotonic time: 0000000001074095 msec [1652388352.487367][1890:1890] CHIP:BDX: OutputEvent type: MsgToSend [1652388352.487442][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051229 on exchange: 59674r [1652388352.487668][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x12 and protocolId (0, 2) on exchange 59674r with MessageCounter:16419191. [1652388352.487753][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419191 to 0x0000000000000002 (1) at monotonic time: 00000000010740B3 msec [1652388352.862597][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419191 on exchange 59674r Send Cnt 0 [1652388352.862758][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419191 to 0x0000000000000002 (1) at monotonic time: 000000000107422A msec [1652388353.110097][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051230 on exchange 59674r [1652388353.110186][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388353.110259][1890:1890] CHIP:EM: CHIP MessageCounter:16419185 not in RetransTable on exchange 59674r [1652388353.186550][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419191 on exchange 59674r Send Cnt 1 [1652388353.186704][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419191 to 0x0000000000000002 (1) at monotonic time: 000000000107436E msec [1652388353.546542][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419191 on exchange 59674r Send Cnt 2 [1652388353.546692][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419191 to 0x0000000000000002 (1) at monotonic time: 00000000010744D6 msec [1652388354.090684][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419191 on exchange 59674r sendCount: 3 max retries: 3 [1652388354.584926][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051231 on exchange 59674r [1652388354.585010][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388354.585076][1890:1890] CHIP:EM: CHIP MessageCounter:16419185 not in RetransTable on exchange 59674r [1652388356.063281][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051232 on exchange 59674r [1652388356.063371][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388356.063437][1890:1890] CHIP:EM: CHIP MessageCounter:16419185 not in RetransTable on exchange 59674r [1652388358.030143][1890:1890] CHIP:EM: Received message of type 0x14 with protocolId (0, 2) and MessageCounter:9051233 on exchange 59674r [1652388358.030240][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388358.030307][1890:1890] CHIP:EM: CHIP MessageCounter:16419191 not in RetransTable on exchange 59674r [1652388358.030390][1890:1890] CHIP:BDX: OnMessageReceived: message 0x14 protocol (0, 2) [1652388358.030451][1890:1890] CHIP:ATM: Handling received BDX Message [1652388358.030507][1890:1890] CHIP:ATM: BlockAckEOF [1652388358.030556][1890:1890] CHIP:ATM: Block Counter: 8 [1652388358.105713][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051234 on exchange 59675r [1652388358.105810][1890:1890] CHIP:EM: Handling via exchange: 59675r, Delegate: 0xaaaaca7bd558 [1652388358.105954][1890:1890] CHIP:DMG: InvokeRequestMessage = [1652388358.106020][1890:1890] CHIP:DMG: { [1652388358.106076][1890:1890] CHIP:DMG: suppressResponse = false, [1652388358.106139][1890:1890] CHIP:DMG: timedRequest = false, [1652388358.106227][1890:1890] CHIP:DMG: InvokeRequests = [1652388358.106307][1890:1890] CHIP:DMG: [ [1652388358.106367][1890:1890] CHIP:DMG: CommandDataIB = [1652388358.106435][1890:1890] CHIP:DMG: { [1652388358.106498][1890:1890] CHIP:DMG: CommandPathIB = [1652388358.106574][1890:1890] CHIP:DMG: { [1652388358.106660][1890:1890] CHIP:DMG: EndpointId = 0x0, [1652388358.106742][1890:1890] CHIP:DMG: ClusterId = 0x29, [1652388358.106824][1890:1890] CHIP:DMG: CommandId = 0x2, [1652388358.106908][1890:1890] CHIP:DMG: }, [1652388358.106996][1890:1890] CHIP:DMG: [1652388358.107060][1890:1890] CHIP:DMG: CommandData = [1652388358.107134][1890:1890] CHIP:DMG: { [1652388358.107214][1890:1890] CHIP:DMG: 0x0 = [ [1652388358.107317][1890:1890] CHIP:DMG: 0x1e, 0xe2, 0x16, 0x42, 0xc8, 0xec, 0xd1, 0x22, 0x3a, 0x56, 0x12, 0x9, 0xdc, 0x8a, 0x99, 0xa6, 0x15, 0x7, 0x24, 0x93, 0xfb, 0xe4, 0x86, 0x53, 0x7b, 0x52, 0x5, 0x7d, 0x15, 0xeb, 0x9b, 0x81, [1652388358.107407][1890:1890] CHIP:DMG: ] [1652388358.107487][1890:1890] CHIP:DMG: 0x1 = 99, [1652388358.107568][1890:1890] CHIP:DMG: }, [1652388358.107647][1890:1890] CHIP:DMG: }, [1652388358.107728][1890:1890] CHIP:DMG: [1652388358.107787][1890:1890] CHIP:DMG: ], [1652388358.107911][1890:1890] CHIP:DMG: [1652388358.107974][1890:1890] CHIP:DMG: InteractionModelRevision = 1 [1652388358.108032][1890:1890] CHIP:DMG: }, [1652388358.108170][1890:1890] CHIP:DMG: AccessControl: checking f=1 a=c s=0x0000000000000002 t= c=0x0000_0029 e=0 p=o [1652388358.108252][1890:1890] CHIP:DMG: AccessControl: allowed [1652388358.108316][1890:1890] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0029 Command=0x0000_0002 [1652388358.108392][1890:1890] CHIP:ZCL: OTA Provider received ApplyUpdateRequest [1652388358.108446][1890:1890] CHIP:ZCL: Update Token: 32 [1652388358.108494][1890:1890] CHIP:ZCL: New Version: 99 [1652388358.108559][1890:1890] CHIP:SWU: HandleApplyUpdateRequest: token: 1EE21642C8ECD1223A561209DC8A99, version: 99 [1652388358.108631][1890:1890] CHIP:DMG: ICR moving to [ Preparing] [1652388358.108699][1890:1890] CHIP:DMG: ICR moving to [AddingComm] [1652388358.108763][1890:1890] CHIP:DMG: ICR moving to [AddedComma] [1652388358.108854][1890:1890] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1652388358.108922][1890:1890] CHIP:EM: Piggybacking Ack for MessageCounter:9051234 on exchange: 59675r [1652388358.109054][1890:1890] CHIP:IN: Prepared secure message 0xaaaaca7b4f18 to 0x0000000000000002 (1) of type 0x9 and protocolId (0, 1) on exchange 59675r with MessageCounter:16419192. [1652388358.109144][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419192 to 0x0000000000000002 (1) at monotonic time: 00000000010756A9 msec [1652388358.109469][1890:1890] CHIP:DMG: ICR moving to [CommandSen] [1652388358.109537][1890:1890] CHIP:DMG: ICR moving to [AwaitingDe] [1652388358.230575][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051233 on exchange 59674r [1652388358.230738][1890:1890] CHIP:IN: Prepared secure message 0xfffffe839248 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419193. [1652388358.230831][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe839248 with MessageCounter:16419193 to 0x0000000000000002 (1) at monotonic time: 0000000001075723 msec [1652388358.415903][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051233 on exchange 59674r [1652388358.415987][1890:1890] CHIP:EM: Received message of type 0x14 with protocolId (0, 2) and MessageCounter:9051233 on exchange 59674r [1652388358.416050][1890:1890] CHIP:EM: Found matching exchange: 59674r, Delegate: 0xaaaaca7b1bf8 [1652388358.416108][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051233 on exchange 59674r [1652388358.416164][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051233 on exchange 59674r [1652388358.416262][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419194. [1652388358.416344][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419194 to 0x0000000000000002 (1) at monotonic time: 00000000010757DC msec [1652388358.419724][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419192 on exchange 59675r Send Cnt 0 [1652388358.419900][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419192 to 0x0000000000000002 (1) at monotonic time: 00000000010757E0 msec [1652388358.493308][1890:1890] CHIP:BDX: OutputEvent type: AckEOFReceived [1652388358.493373][1890:1890] CHIP:BDX: Transfer completed, got AckEOF [1652388358.497731][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051234 on exchange 59675r [1652388358.497807][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051234 on exchange 59675r [1652388358.497868][1890:1890] CHIP:EM: Found matching exchange: 59675r, Delegate: (nil) [1652388358.497925][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051234 on exchange 59675r [1652388358.497980][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051234 on exchange 59675r [1652388358.498078][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59675r with MessageCounter:16419195. [1652388358.498159][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419195 to 0x0000000000000002 (1) at monotonic time: 000000000107582E msec [1652388358.734752][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419192 on exchange 59675r Send Cnt 1 [1652388358.734912][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419192 to 0x0000000000000002 (1) at monotonic time: 000000000107591B msec [1652388358.753852][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051233 on exchange 59674r [1652388358.753936][1890:1890] CHIP:EM: Received message of type 0x14 with protocolId (0, 2) and MessageCounter:9051233 on exchange 59674r [1652388358.754014][1890:1890] CHIP:EM: Handling via exchange: 59674r, Delegate: (nil) [1652388358.754074][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051233 on exchange 59674r [1652388358.754129][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051233 on exchange 59674r [1652388358.754229][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838ac8 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419196. [1652388358.754310][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838ac8 with MessageCounter:16419196 to 0x0000000000000002 (1) at monotonic time: 000000000107592E msec [1652388358.829130][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051234 on exchange 59675r [1652388358.829212][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051234 on exchange 59675r [1652388358.829272][1890:1890] CHIP:EM: Found matching exchange: 59675r, Delegate: (nil) [1652388358.829328][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051234 on exchange 59675r [1652388358.829383][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051234 on exchange 59675r [1652388358.829476][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59675r with MessageCounter:16419197. [1652388358.829557][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419197 to 0x0000000000000002 (1) at monotonic time: 0000000001075979 msec [1652388359.047224][1890:1890] CHIP:EM: Retransmitting MessageCounter:16419192 on exchange 59675r Send Cnt 2 [1652388359.047377][1890:1890] CHIP:IN: Sending encrypted msg 0xaaaaca7b4f18 with MessageCounter:16419192 to 0x0000000000000002 (1) at monotonic time: 0000000001075A53 msec [1652388359.048790][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051233 on exchange 59674r [1652388359.048868][1890:1890] CHIP:EM: Received message of type 0x14 with protocolId (0, 2) and MessageCounter:9051233 on exchange 59674r [1652388359.048942][1890:1890] CHIP:EM: Handling via exchange: 59674r, Delegate: (nil) [1652388359.049001][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051233 on exchange 59674r [1652388359.049056][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051233 on exchange 59674r [1652388359.049153][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838ac8 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59674r with MessageCounter:16419198. [1652388359.049233][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838ac8 with MessageCounter:16419198 to 0x0000000000000002 (1) at monotonic time: 0000000001075A55 msec [1652388359.174191][1890:1890] CHIP:IN: Received a duplicate message with MessageCounter:9051234 on exchange 59675r [1652388359.174273][1890:1890] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9051234 on exchange 59675r [1652388359.174333][1890:1890] CHIP:EM: Found matching exchange: 59675r, Delegate: (nil) [1652388359.174390][1890:1890] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:9051234 on exchange 59675r [1652388359.174445][1890:1890] CHIP:EM: Sending Standalone Ack for MessageCounter:9051234 on exchange 59675r [1652388359.174541][1890:1890] CHIP:IN: Prepared secure message 0xfffffe838978 to 0x0000000000000002 (1) of type 0x10 and protocolId (0, 0) on exchange 59675r with MessageCounter:16419199. [1652388359.174623][1890:1890] CHIP:IN: Sending encrypted msg 0xfffffe838978 with MessageCounter:16419199 to 0x0000000000000002 (1) at monotonic time: 0000000001075AD2 msec [1652388359.373178][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051235 on exchange 59674r [1652388359.554724][1890:1890] CHIP:EM: Failed to Send CHIP MessageCounter:16419192 on exchange 59675r sendCount: 3 max retries: 3 [1652388360.726677][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051236 on exchange 59674r [1652388362.078520][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051237 on exchange 59674r [1652388362.319577][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051238 on exchange 59675r [1652388362.803521][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051239 on exchange 59675r [1652388363.159481][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051240 on exchange 59675r [1652388363.641538][1890:1890] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:9051241 on exchange 59675r [1652388379.662575][1890:1890] CHIP:DL: Caught signal 2 [1652388379.662944][1890:1890] CHIP:DL: select failed: ../../examples/ota-provider-app/linux/third_party/connectedhomeip/src/system/SystemLayerImplSelect.cpp:383: OS Error 0x02000004: Interrupted system call [1652388379.663062][1890:1890] CHIP:ZCL: Emitting ShutDown event [1652388379.663194][1890:1890] CHIP:EVL: LogEvent event number: 0x0000000000000004 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x1 Sys timestamp: 0x000000000107AADB [1652388379.663273][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388379.663989][1890:1890] CHIP:DMG: IM WH moving to [Uninitialized] [1652388379.664056][1890:1890] CHIP:DMG: IM WH moving to [Uninitialized] [1652388379.664107][1890:1890] CHIP:DMG: IM WH moving to [Uninitialized] [1652388379.664156][1890:1890] CHIP:DMG: IM WH moving to [Uninitialized] [1652388379.664207][1890:1890] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1652388379.664863][1890:1890] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-SEskUj) [1652388379.666038][1890:1890] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1652388379.666155][1890:1890] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1652388379.666218][1890:1890] CHIP:DL: Inet Layer shutdown [1652388379.666273][1890:1890] CHIP:DL: System Layer shutdown