ubuntu@raspberrypi:~/Feb_cntr/connectedhomeip/examples/terms-and-conditions-app/linux/out/terms-and-conditions-app$ sudo rm -rf /tmp/chip_* ubuntu@raspberrypi:~/Feb_cntr/connectedhomeip/examples/terms-and-conditions-app/linux/out/terms-and-conditions-app$ ./chip-terms-and-conditions-app --tc-min-required-version 1 --tc-required-acknowledgements 1 --custom-flow 2 --capabilities 6 [1739188292.593164][25013:25013] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1739188292.598092][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.599829][25013:25013] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1739188292.615038][25013:25013] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1739188292.620645][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_factory.ini [1739188292.621084][25013:25013] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1739188292.627975][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188292.628309][25013:25013] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1739188292.632797][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188292.642926][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_factory.ini [1739188292.643064][25013:25013] CHIP:DL: NVS set: chip-factory/unique-id = "C1BB9308C4657F1F" [1739188292.649477][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_factory.ini [1739188292.649610][25013:25013] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1739188292.659508][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_factory.ini [1739188292.659639][25013:25013] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1739188292.683036][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188292.683187][25013:25013] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1739188292.702809][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188292.702948][25013:25013] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1739188292.711841][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188292.711971][25013:25013] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1739188292.731304][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188292.731437][25013:25013] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1739188292.751180][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188292.751330][25013:25013] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2) [1739188292.753419][25013:25013] CHIP:DL: Got Ethernet interface: eth0 [1739188292.754973][25013:25013] CHIP:DL: Found the primary Ethernet interface:eth0 [1739188292.756552][25013:25013] CHIP:DL: Got WiFi interface: wlan0 [1739188292.764689][25013:25013] CHIP:DL: Found the primary WiFi interface:wlan0 [1739188292.764805][25013:25013] 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. *** [1739188292.764866][25013:25013] 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. *** [1739188292.764920][25013:25013] CHIP:SPT: PASE PBKDF iterations set to 1000 [1739188292.765033][25013:25013] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one. [1739188292.782384][25013:25013] CHIP:DL: Device Configuration: [1739188292.782519][25013:25013] CHIP:DL: Serial Number: TEST_SN [1739188292.782602][25013:25013] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1739188292.782683][25013:25013] CHIP:DL: Product Id: 32769 (0x8001) [1739188292.782739][25013:25013] CHIP:DL: Product Name: TEST_PRODUCT [1739188292.782808][25013:25013] CHIP:DL: Hardware Version: 0 [1739188292.782861][25013:25013] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1739188292.782909][25013:25013] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1739188292.782977][25013:25013] CHIP:DL: Manufacturing Date: (not set) [1739188292.783029][25013:25013] CHIP:DL: Device Type: 65535 (0xFFFF) [1739188292.783074][25013:25013] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ==== [1739188292.783151][25013:25013] CHIP:SVR: SetupQRCode: [MT:-24J08M.00KA0648G00] [1739188292.783213][25013:25013] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1739188292.783262][25013:25013] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J08M.00KA0648G00 [1739188292.783341][25013:25013] CHIP:SVR: Manual pairing code: [749701123365521327694] [1739188292.783453][25013:25013] CHIP:SVR: Initializing subscription resumption storage... [1739188292.792853][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.793097][25013:25013] CHIP:SVR: Server initializing... [1739188292.793179][25013:25013] CHIP:FP: Initializing FabricTable from persistent storage [1739188292.793296][25013:25013] CHIP:TS: Last Known Good Time: [unknown] [1739188292.793366][25013:25013] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48 [1739188292.813595][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.813828][25013:25013] CHIP:DMG: AccessControl: initializing [1739188292.813889][25013:25013] CHIP:DMG: Examples::AccessControlDelegate::Init [1739188292.813965][25013:25013] CHIP:DMG: AccessControl: setting [1739188292.814017][25013:25013] CHIP:DMG: DefaultAclStorage: initializing [1739188292.814064][25013:25013] CHIP:DMG: DefaultAclStorage: 0 entries loaded [1739188292.814134][25013:25013] CHIP:IN: UDP::Init bind&listen port=5540 [1739188292.814397][25013:25013] CHIP:IN: UDP::Init bound to port=5540 [1739188292.814455][25013:25013] CHIP:IN: BLEBase::Init - setting/overriding transport [1739188292.814639][25013:25013] CHIP:IN: TCP server listening on port 5540 for incoming connections [1739188292.814696][25013:25013] CHIP:IN: TransportMgr initialized [1739188292.824783][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.845448][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.867293][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188292.867372][25013:25013] CHIP:DMG: Ember attribute persistence requires setting up [1739188292.867391][25013:25013] CHIP:ZCL: Using ZAP configuration... [1739188292.867506][25013:25013] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1739188292.867545][25013:25013] CHIP:DMG: AccessControlCluster: initializing [1739188292.867565][25013:25013] CHIP:ZCL: Initiating Admin Commissioning cluster. [1739188292.867634][25013:25013] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot [1739188292.867659][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to 7660bce9 [1739188292.867730][25013:25013] CHIP:EVL: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Epoch timestamp: 0x00000194EFB34D03 [1739188292.867765][25013:25013] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to be1644a6 [1739188292.867787][25013:25013] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to be1644a7 [1739188292.867937][25013:25013] CHIP:IN: SecureSession[0xaaaae96310b0]: Allocated Type:1 LSID:51913 [1739188292.867970][25013:25013] CHIP:SC: Assigned local session key ID 51913 [1739188292.867990][25013:25013] CHIP:SC: Waiting for PBKDF param request [1739188292.868020][25013:25013] CHIP:DIS: Updating services using commissioning mode 1 [1739188292.879350][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188292.920871][25013:25013] CHIP:DL: Using WiFi MAC for hostname [1739188292.921602][25013:25013] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188292.921714][25013:25013] CHIP:DIS: Responding with _matterc._udp.local [1739188292.921775][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188292.921829][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188292.921880][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188292.921943][25013:25013] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188292.922004][25013:25013] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188292.922063][25013:25013] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188292.922121][25013:25013] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188292.922195][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188292.922247][25013:25013] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B9251587E599920D. [1739188292.966802][25013:25013] CHIP:DIS: mDNS service published: _matterc._udp [1739188292.966909][25013:25013] CHIP:DIS: Updating services using commissioning mode 1 [1739188292.992876][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188293.086803][25013:25013] CHIP:DL: Using WiFi MAC for hostname [1739188293.087035][25013:25013] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188293.087142][25013:25013] CHIP:DIS: Responding with _matterc._udp.local [1739188293.087202][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188293.087255][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188293.087307][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188293.087367][25013:25013] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188293.087425][25013:25013] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188293.087483][25013:25013] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188293.087542][25013:25013] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188293.087615][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188293.087666][25013:25013] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B9251587E599920D. [1739188293.132730][25013:25013] CHIP:DIS: mDNS service published: _matterc._udp [1739188293.132847][25013:25013] CHIP:IN: CASE Server enabling CASE session setups [1739188293.133085][25013:25013] CHIP:IN: SecureSession[0xaaaae96316a0]: Allocated Type:2 LSID:51914 [1739188293.133181][25013:25013] CHIP:SC: Allocated SecureSession (0xaaaae96316a0) - waiting for Sigma1 msg [1739188293.133247][25013:25013] CHIP:SVR: Joining Multicast groups [1739188293.133312][25013:25013] CHIP:ZCL: Emitting StartUp event [1739188293.133457][25013:25013] CHIP:EVL: LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Epoch timestamp: 0x00000194EFB34E0D [1739188293.133532][25013:25013] CHIP:SVR: Server initialization complete [1739188293.133615][25013:25013] CHIP:SVR: Server Listening... [1739188293.133665][25013:25013] CHIP:DL: Device Configuration: [1739188293.133770][25013:25013] CHIP:DL: Serial Number: TEST_SN [1739188293.133876][25013:25013] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1739188293.133959][25013:25013] CHIP:DL: Product Id: 32769 (0x8001) [1739188293.134013][25013:25013] CHIP:DL: Product Name: TEST_PRODUCT [1739188293.134081][25013:25013] CHIP:DL: Hardware Version: 0 [1739188293.134134][25013:25013] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1739188293.134179][25013:25013] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1739188293.134241][25013:25013] CHIP:DL: Manufacturing Date: (not set) [1739188293.134292][25013:25013] CHIP:DL: Device Type: 65535 (0xFFFF) [1739188293.134367][25013:25013] CHIP:SVR: SetupQRCode: [MT:-24J08M.00KA0648G00] [1739188293.134427][25013:25013] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1739188293.134474][25013:25013] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J08M.00KA0648G00 [1739188293.134553][25013:25013] CHIP:SVR: Manual pairing code: [749701123365521327694] [1739188293.163328][25013:25014] CHIP:DL: CREATE service object at /chipoble/61b5/service [1739188293.164338][25013:25014] CHIP:DL: Create characteristic object at /chipoble/61b5/service/c1 [1739188293.165150][25013:25014] CHIP:DL: Create characteristic object at /chipoble/61b5/service/c2 [1739188293.165563][25013:25014] CHIP:DL: CHIP BTP C1 /chipoble/61b5/service [1739188293.165630][25013:25014] CHIP:DL: CHIP BTP C2 /chipoble/61b5/service [1739188293.165675][25013:25014] CHIP:DL: CHIP_ENABLE_ADDITIONAL_DATA_ADVERTISING is FALSE [1739188293.166483][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1739188293.166570][25013:25013] CHIP:DIS: Updating services using commissioning mode 1 [1739188293.180741][25013:25014] CHIP:DL: GATT application registered successfully [1739188293.192369][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188293.285941][25013:25013] CHIP:DL: Using WiFi MAC for hostname [1739188293.286182][25013:25013] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188293.286292][25013:25013] CHIP:DIS: Responding with _matterc._udp.local [1739188293.286351][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188293.286404][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188293.286455][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188293.286517][25013:25013] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188293.286585][25013:25013] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188293.286644][25013:25013] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188293.286702][25013:25013] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188293.286776][25013:25013] CHIP:DIS: Responding with B9251587E599920D._matterc._udp.local [1739188293.286827][25013:25013] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B9251587E599920D. [1739188293.331900][25013:25013] CHIP:DIS: mDNS service published: _matterc._udp [1739188293.332015][25013:25013] CHIP:DL: Long dispatch time: 166 ms, for event type 32786 [1739188293.332100][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 32790 [1739188293.333315][25013:25013] CHIP:IM: No subscriptions to resume [1739188293.333395][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 16394 [1739188293.333662][25013:25014] CHIP:DL: Create BLE adv object at /chipoble/61b5/advertising [1739188293.335522][25013:25013] CHIP:DL: SET service data to {'fff6': <[byte 0x00, 0x00, 0x0f, 0xf1, 0xff, 0x01, 0x80, 0x00]>} [1739188293.356405][25013:25014] CHIP:DL: BLE advertisement started successfully [1739188293.359439][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 16395 [1739188304.109314][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.110180][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.110530][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.110751][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.110961][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.111512][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.111795][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.112019][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.114657][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.114909][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.115118][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.115326][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.115534][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.116064][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.116277][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.116548][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.116810][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.123292][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.123537][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.123747][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.123953][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.124158][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.124473][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.124682][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.124888][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.138817][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.139057][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.139261][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.139468][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.139668][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.139967][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.140230][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.140435][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188304.518358][25013:25013] CHIP:EM: >>> [E:31333r S:0 M:251017295] (U) Msg RX from 0:4551F650E1156C68 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98) [1739188304.518492][25013:25013] CHIP:EM: Handling via exchange: 31333r, Delegate: 0xaaaae10619b8 [1739188304.518619][25013:25013] CHIP:SC: Received PBKDF param request [1739188304.518723][25013:25013] CHIP:SC: Peer assigned session ID 21996 [1739188304.518787][25013:25013] CHIP:SC: Found MRP parameters in the message [1739188304.519695][25013:25013] CHIP:EM: <<< [E:31333r S:0 M:99396220 (Ack:251017295)] (U) Msg TX from 0000000000000000 to 0:4551F650E1156C68 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:174) [1739188304.520079][25013:25013] CHIP:EM: ??1 [E:31333r S:0 M:99396220] (U) Msg Retransmission to 0:0000000000000000 scheduled for 339ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.520190][25013:25013] CHIP:SC: Sent PBKDF param response [1739188304.520256][25013:25013] CHIP:SVR: Commissioning session establishment step started [1739188304.591620][25013:25013] CHIP:EM: >>> [E:31333r S:0 M:251017296 (Ack:99396220)] (U) Msg RX from 0:4551F650E1156C68 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:96) [1739188304.591705][25013:25013] CHIP:EM: Found matching exchange: 31333r, Delegate: 0xaaaae10619b8 [1739188304.591786][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:99396220 from Retrans Table on exchange 31333r [1739188304.591899][25013:25013] CHIP:SC: Received spake2p msg1 [1739188304.597433][25013:25013] CHIP:EM: <<< [E:31333r S:0 M:99396221 (Ack:251017296)] (U) Msg TX from 0000000000000000 to 0:4551F650E1156C68 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:131) [1739188304.597805][25013:25013] CHIP:EM: ??1 [E:31333r S:0 M:99396221] (U) Msg Retransmission to 0:0000000000000000 scheduled for 343ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.597910][25013:25013] CHIP:SC: Sent spake2p msg2 [1739188304.653391][25013:25013] CHIP:EM: >>> [E:31333r S:0 M:251017297 (Ack:99396221)] (U) Msg RX from 0:4551F650E1156C68 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:63) [1739188304.653501][25013:25013] CHIP:EM: Found matching exchange: 31333r, Delegate: 0xaaaae10619b8 [1739188304.653586][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:99396221 from Retrans Table on exchange 31333r [1739188304.653704][25013:25013] CHIP:SC: Received spake2p msg3 [1739188304.653936][25013:25013] CHIP:SC: Sending status report. Protocol code 0, exchange 31333 [1739188304.654270][25013:25013] CHIP:EM: <<< [E:31333r S:0 M:99396222 (Ack:251017297)] (U) Msg TX from 0000000000000000 to 0:4551F650E1156C68 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:40 (SecureChannel:StatusReport) (B:34) [1739188304.654749][25013:25013] CHIP:EM: ??1 [E:31333r S:0 M:99396222] (U) Msg Retransmission to 0:0000000000000000 scheduled for 347ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.655268][25013:25013] CHIP:SC: SecureSession[0xaaaae96310b0, LSID:51913]: State change 'kEstablishing' --> 'kActive' [1739188304.655346][25013:25013] CHIP:IN: SecureSession[0xaaaae96310b0]: Activated - Type:1 LSID:51913 [1739188304.655398][25013:25013] CHIP:IN: New secure session activated for device , LSID:51913 PSID:21996! [1739188304.655472][25013:25013] CHIP:SVR: Commissioning completed session establishment step [1739188304.655584][25013:25013] CHIP:DIS: Updating services using commissioning mode 0 [1739188304.680511][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188304.771545][25013:25013] CHIP:SVR: Device completed Rendezvous process [1739188304.771690][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 32792 [1739188304.773018][25013:25013] CHIP:EM: >>> [E:31334r S:51913 M:248780207] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:134) [1739188304.773152][25013:25013] CHIP:EM: Handling via exchange: 31334r, Delegate: 0xaaaae105e5c8 [1739188304.773251][25013:25013] CHIP:IM: Received Read request [1739188304.773400][25013:25013] CHIP:DMG: ReadRequestMessage = [1739188304.773460][25013:25013] CHIP:DMG: { [1739188304.773513][25013:25013] CHIP:DMG: AttributePathIBs = [1739188304.773576][25013:25013] CHIP:DMG: [ [1739188304.773633][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.773717][25013:25013] CHIP:DMG: { [1739188304.773788][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.773881][25013:25013] CHIP:DMG: Cluster = 0x30, [1739188304.773962][25013:25013] CHIP:DMG: Attribute = 0x0000_0004, [1739188304.774046][25013:25013] CHIP:DMG: } [1739188304.774118][25013:25013] CHIP:DMG: [1739188304.774272][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.774343][25013:25013] CHIP:DMG: { [1739188304.774420][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.774497][25013:25013] CHIP:DMG: Cluster = 0x30, [1739188304.774656][25013:25013] CHIP:DMG: Attribute = 0x0000_0000, [1739188304.774737][25013:25013] CHIP:DMG: } [1739188304.774808][25013:25013] CHIP:DMG: [1739188304.774870][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.775015][25013:25013] CHIP:DMG: { [1739188304.775092][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.775172][25013:25013] CHIP:DMG: Cluster = 0x30, [1739188304.775242][25013:25013] CHIP:DMG: Attribute = 0x0000_0001, [1739188304.775302][25013:25013] CHIP:DMG: } [1739188304.775368][25013:25013] CHIP:DMG: [1739188304.775424][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.775569][25013:25013] CHIP:DMG: { [1739188304.775638][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.775794][25013:25013] CHIP:DMG: Cluster = 0x30, [1739188304.775889][25013:25013] CHIP:DMG: Attribute = 0x0000_0002, [1739188304.775976][25013:25013] CHIP:DMG: } [1739188304.776059][25013:25013] CHIP:DMG: [1739188304.776132][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.776202][25013:25013] CHIP:DMG: { [1739188304.776280][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.776438][25013:25013] CHIP:DMG: Cluster = 0x30, [1739188304.776536][25013:25013] CHIP:DMG: Attribute = 0x0000_0003, [1739188304.776689][25013:25013] CHIP:DMG: } [1739188304.776769][25013:25013] CHIP:DMG: [1739188304.776843][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.776913][25013:25013] CHIP:DMG: { [1739188304.777313][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.777716][25013:25013] CHIP:DMG: Cluster = 0x28, [1739188304.777855][25013:25013] CHIP:DMG: Attribute = 0x0000_0002, [1739188304.777923][25013:25013] CHIP:DMG: } [1739188304.777991][25013:25013] CHIP:DMG: [1739188304.778057][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.778122][25013:25013] CHIP:DMG: { [1739188304.778188][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.778257][25013:25013] CHIP:DMG: Cluster = 0x28, [1739188304.778403][25013:25013] CHIP:DMG: Attribute = 0x0000_0004, [1739188304.778469][25013:25013] CHIP:DMG: } [1739188304.778554][25013:25013] CHIP:DMG: [1739188304.778647][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.778723][25013:25013] CHIP:DMG: { [1739188304.778488][25013:25014] CHIP:DL: BLE advertisement stopped successfully [1739188304.778875][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.779745][25013:25013] CHIP:DMG: Cluster = 0x38, [1739188304.779817][25013:25013] CHIP:DMG: } [1739188304.779928][25013:25013] CHIP:DMG: [1739188304.779993][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.780059][25013:25013] CHIP:DMG: { [1739188304.780126][25013:25013] CHIP:DMG: Cluster = 0x31, [1739188304.780198][25013:25013] CHIP:DMG: Attribute = 0x0000_FFFC, [1739188304.780263][25013:25013] CHIP:DMG: } [1739188304.780337][25013:25013] CHIP:DMG: [1739188304.780393][25013:25013] CHIP:DMG: ], [1739188304.780497][25013:25013] CHIP:DMG: [1739188304.780553][25013:25013] CHIP:DMG: isFabricFiltered = false, [1739188304.780608][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.780664][25013:25013] CHIP:DMG: }, [1739188304.781733][25013:25013] CHIP:DMG: IM RH moving to [CanStartReporting] [1739188304.783462][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 16396 [1739188304.783562][25013:25013] CHIP:DL: CHIPoBLE advertising stopped [1739188304.783779][25013:25013] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000 [1739188304.783928][25013:25013] CHIP:DMG: Cluster 31, Attribute fffc is dirty [1739188304.784029][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v r=r [1739188304.784090][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.784143][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0x0 AttributeId=0x0000_FFFC (expanded=1) [1739188304.784337][25013:25013] CHIP:DMG: Cluster 28, Attribute 4 is dirty [1739188304.784434][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v r=r [1739188304.784492][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.784540][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0x0 AttributeId=0x0000_0004 (expanded=0) [1739188304.784785][25013:25013] CHIP:DMG: Cluster 28, Attribute 2 is dirty [1739188304.784886][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v r=r [1739188304.784985][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.785039][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188304.785235][25013:25013] CHIP:DMG: Cluster 30, Attribute 3 is dirty [1739188304.785328][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188304.785387][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.785435][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0003 (expanded=0) [1739188304.785617][25013:25013] CHIP:DMG: Cluster 30, Attribute 2 is dirty [1739188304.785709][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188304.785767][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.785816][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188304.785988][25013:25013] CHIP:DMG: Cluster 30, Attribute 1 is dirty [1739188304.786079][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188304.786132][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.786181][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0001 (expanded=0) [1739188304.786326][25013:25013] CHIP:DMG: Cluster 30, Attribute 0 is dirty [1739188304.786417][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188304.786475][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.786523][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0000 (expanded=0) [1739188304.786668][25013:25013] CHIP:DMG: Cluster 30, Attribute 4 is dirty [1739188304.786755][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188304.786813][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.786860][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0004 (expanded=0) [1739188304.786988][25013:25013] CHIP:DMG: Sending report (payload has 227 bytes)... [1739188304.787485][25013:25013] CHIP:EM: <<< [E:31334r S:51913 M:12603939 (Ack:248780207)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:05 (IM:ReportData) (B:261) [1739188304.787889][25013:25013] CHIP:EM: ??1 [E:31334r S:51913 M:12603939] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 375ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.788079][25013:25013] CHIP:DMG: OnReportConfirm: NumReports = 0 [1739188304.788141][25013:25013] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1739188304.788192][25013:25013] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1739188304.789512][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188304.789781][25013:25013] CHIP:EM: >>> [E:31333r S:0 M:251017298 (Ack:99396222)] (U) Msg RX from 0:4551F650E1156C68 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [1739188304.789853][25013:25013] CHIP:EM: Found matching exchange: 31333r, Delegate: (nil) [1739188304.789937][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:99396222 from Retrans Table on exchange 31333r [1739188304.840338][25013:25013] CHIP:EM: >>> [E:31335r S:51913 M:248780208] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:103) [1739188304.840462][25013:25013] CHIP:EM: Handling via exchange: 31335r, Delegate: 0xaaaae105e5c8 [1739188304.840555][25013:25013] CHIP:IM: Received Read request [1739188304.840683][25013:25013] CHIP:DMG: ReadRequestMessage = [1739188304.840742][25013:25013] CHIP:DMG: { [1739188304.840791][25013:25013] CHIP:DMG: AttributePathIBs = [1739188304.840852][25013:25013] CHIP:DMG: [ [1739188304.840908][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.841119][25013:25013] CHIP:DMG: { [1739188304.841190][25013:25013] CHIP:DMG: Cluster = 0x31, [1739188304.841272][25013:25013] CHIP:DMG: Attribute = 0x0000_0003, [1739188304.841340][25013:25013] CHIP:DMG: } [1739188304.841409][25013:25013] CHIP:DMG: [1739188304.841469][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.841539][25013:25013] CHIP:DMG: { [1739188304.841603][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.841676][25013:25013] CHIP:DMG: Cluster = 0x46, [1739188304.841746][25013:25013] CHIP:DMG: Attribute = 0x0000_0006, [1739188304.841813][25013:25013] CHIP:DMG: } [1739188304.841880][25013:25013] CHIP:DMG: [1739188304.841940][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.842004][25013:25013] CHIP:DMG: { [1739188304.842068][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.842139][25013:25013] CHIP:DMG: Cluster = 0x46, [1739188304.842208][25013:25013] CHIP:DMG: Attribute = 0x0000_0007, [1739188304.842275][25013:25013] CHIP:DMG: } [1739188304.842344][25013:25013] CHIP:DMG: [1739188304.842403][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.842465][25013:25013] CHIP:DMG: { [1739188304.842528][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.842598][25013:25013] CHIP:DMG: Cluster = 0x46, [1739188304.842666][25013:25013] CHIP:DMG: Attribute = 0x0000_0000, [1739188304.842733][25013:25013] CHIP:DMG: } [1739188304.842799][25013:25013] CHIP:DMG: [1739188304.842858][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.842919][25013:25013] CHIP:DMG: { [1739188304.842982][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.843050][25013:25013] CHIP:DMG: Cluster = 0x46, [1739188304.843112][25013:25013] CHIP:DMG: Attribute = 0x0000_0001, [1739188304.843174][25013:25013] CHIP:DMG: } [1739188304.843240][25013:25013] CHIP:DMG: [1739188304.843299][25013:25013] CHIP:DMG: AttributePathIB = [1739188304.843360][25013:25013] CHIP:DMG: { [1739188304.843424][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188304.843490][25013:25013] CHIP:DMG: Cluster = 0x46, [1739188304.843565][25013:25013] CHIP:DMG: Attribute = 0x0000_0002, [1739188304.843633][25013:25013] CHIP:DMG: } [1739188304.843698][25013:25013] CHIP:DMG: [1739188304.843757][25013:25013] CHIP:DMG: ], [1739188304.843848][25013:25013] CHIP:DMG: [1739188304.843909][25013:25013] CHIP:DMG: isFabricFiltered = false, [1739188304.843968][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.844022][25013:25013] CHIP:DMG: }, [1739188304.844649][25013:25013] CHIP:DMG: IM RH moving to [CanStartReporting] [1739188304.846435][25013:25013] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000 [1739188304.846561][25013:25013] CHIP:DMG: Cluster 46, Attribute 2 is dirty [1739188304.846632][25013:25013] CHIP:DMG: Read request on unknown cluster - no data version available [1739188304.846697][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188304.846755][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.846806][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188304.846891][25013:25013] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188304.846962][25013:25013] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188304.847092][25013:25013] CHIP:DMG: Cluster 46, Attribute 1 is dirty [1739188304.847159][25013:25013] CHIP:DMG: Read request on unknown cluster - no data version available [1739188304.847215][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188304.847269][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.847316][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0001 (expanded=0) [1739188304.847379][25013:25013] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188304.847442][25013:25013] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188304.847551][25013:25013] CHIP:DMG: Cluster 46, Attribute 0 is dirty [1739188304.847617][25013:25013] CHIP:DMG: Read request on unknown cluster - no data version available [1739188304.847673][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188304.847723][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.847769][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0000 (expanded=0) [1739188304.847834][25013:25013] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188304.847897][25013:25013] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188304.848004][25013:25013] CHIP:DMG: Cluster 46, Attribute 7 is dirty [1739188304.848070][25013:25013] CHIP:DMG: Read request on unknown cluster - no data version available [1739188304.848127][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188304.848181][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.848228][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0007 (expanded=0) [1739188304.848292][25013:25013] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188304.848354][25013:25013] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188304.848461][25013:25013] CHIP:DMG: Cluster 46, Attribute 6 is dirty [1739188304.848527][25013:25013] CHIP:DMG: Read request on unknown cluster - no data version available [1739188304.848582][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188304.848636][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.848683][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0006 (expanded=0) [1739188304.848747][25013:25013] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188304.848809][25013:25013] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188304.849013][25013:25013] CHIP:DMG: Sending report (payload has 125 bytes)... [1739188304.849459][25013:25013] CHIP:EM: <<< [E:31335r S:51913 M:12603940 (Ack:248780208)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:05 (IM:ReportData) (B:159) [1739188304.849871][25013:25013] CHIP:EM: ??1 [E:31335r S:51913 M:12603940] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 370ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.849974][25013:25013] CHIP:DMG: OnReportConfirm: NumReports = 0 [1739188304.850032][25013:25013] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1739188304.850083][25013:25013] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1739188304.851282][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188304.851552][25013:25013] CHIP:EM: >>> [E:31334r S:51913 M:248780209 (Ack:12603939)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188304.851623][25013:25013] CHIP:EM: Found matching exchange: 31334r, Delegate: (nil) [1739188304.851706][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603939 from Retrans Table on exchange 31334r [1739188304.886330][25013:25013] CHIP:EM: >>> [E:31336r S:51913 M:248780210] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65) [1739188304.886433][25013:25013] CHIP:EM: Handling via exchange: 31336r, Delegate: 0xaaaae105e5c8 [1739188304.886593][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188304.886655][25013:25013] CHIP:DMG: { [1739188304.886708][25013:25013] CHIP:DMG: suppressResponse = false, [1739188304.886769][25013:25013] CHIP:DMG: timedRequest = false, [1739188304.886826][25013:25013] CHIP:DMG: InvokeRequests = [1739188304.886904][25013:25013] CHIP:DMG: [ [1739188304.886960][25013:25013] CHIP:DMG: CommandDataIB = [1739188304.887024][25013:25013] CHIP:DMG: { [1739188304.887083][25013:25013] CHIP:DMG: CommandPathIB = [1739188304.887154][25013:25013] CHIP:DMG: { [1739188304.887227][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188304.887303][25013:25013] CHIP:DMG: ClusterId = 0x30, [1739188304.887377][25013:25013] CHIP:DMG: CommandId = 0x0, [1739188304.887444][25013:25013] CHIP:DMG: }, [1739188304.887521][25013:25013] CHIP:DMG: [1739188304.887586][25013:25013] CHIP:DMG: CommandFields = [1739188304.887908][25013:25013] CHIP:DMG: { [1739188304.888018][25013:25013] CHIP:DMG: 0x0 = 60 (unsigned), [1739188304.888123][25013:25013] CHIP:DMG: 0x1 = 3 (unsigned), [1739188304.888201][25013:25013] CHIP:DMG: }, [1739188304.888270][25013:25013] CHIP:DMG: }, [1739188304.888344][25013:25013] CHIP:DMG: [1739188304.888399][25013:25013] CHIP:DMG: ], [1739188304.888474][25013:25013] CHIP:DMG: [1739188304.888530][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.888584][25013:25013] CHIP:DMG: }, [1739188304.888894][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a r=i [1739188304.889006][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.889073][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1739188304.889161][25013:25013] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s) [1739188304.889257][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4b7 [1739188304.889362][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188304.889419][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188304.889483][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188304.889549][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188304.889647][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188304.889703][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188304.889768][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188304.890135][25013:25013] CHIP:EM: <<< [E:31336r S:51913 M:12603941 (Ack:248780210)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188304.890522][25013:25013] CHIP:EM: ??1 [E:31336r S:51913 M:12603941] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 345ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.890622][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188304.891023][25013:25013] CHIP:EM: >>> [E:31335r S:51913 M:248780211 (Ack:12603940)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188304.891097][25013:25013] CHIP:EM: Found matching exchange: 31335r, Delegate: (nil) [1739188304.891178][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603940 from Retrans Table on exchange 31335r [1739188304.906346][25013:25013] CHIP:EM: >>> [E:31337r S:51913 M:248780212] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70) [1739188304.906441][25013:25013] CHIP:EM: Handling via exchange: 31337r, Delegate: 0xaaaae105e5c8 [1739188304.906592][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188304.906654][25013:25013] CHIP:DMG: { [1739188304.906709][25013:25013] CHIP:DMG: suppressResponse = false, [1739188304.906770][25013:25013] CHIP:DMG: timedRequest = false, [1739188304.906826][25013:25013] CHIP:DMG: InvokeRequests = [1739188304.906905][25013:25013] CHIP:DMG: [ [1739188304.906962][25013:25013] CHIP:DMG: CommandDataIB = [1739188304.907026][25013:25013] CHIP:DMG: { [1739188304.907086][25013:25013] CHIP:DMG: CommandPathIB = [1739188304.907157][25013:25013] CHIP:DMG: { [1739188304.907228][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188304.907300][25013:25013] CHIP:DMG: ClusterId = 0x30, [1739188304.907373][25013:25013] CHIP:DMG: CommandId = 0x2, [1739188304.907443][25013:25013] CHIP:DMG: }, [1739188304.907517][25013:25013] CHIP:DMG: [1739188304.907579][25013:25013] CHIP:DMG: CommandFields = [1739188304.907650][25013:25013] CHIP:DMG: { [1739188304.907722][25013:25013] CHIP:DMG: 0x0 = 0 (unsigned), [1739188304.907803][25013:25013] CHIP:DMG: 0x1 = "XX" (2 chars), [1739188304.907882][25013:25013] CHIP:DMG: 0x2 = 4 (unsigned), [1739188304.907957][25013:25013] CHIP:DMG: }, [1739188304.908023][25013:25013] CHIP:DMG: }, [1739188304.908097][25013:25013] CHIP:DMG: [1739188304.908152][25013:25013] CHIP:DMG: ], [1739188304.908231][25013:25013] CHIP:DMG: [1739188304.908287][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.908341][25013:25013] CHIP:DMG: }, [1739188304.908654][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a r=i [1739188304.908719][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.908776][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [1739188304.916698][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188304.916848][25013:25013] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1739188304.925192][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188304.925349][25013:25013] CHIP:DL: NVS set: chip-config/country-code = "XX" [1739188304.925438][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4b8 [1739188304.925569][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188304.925629][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188304.925696][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188304.925766][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188304.925889][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188304.925947][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188304.926013][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188304.926431][25013:25013] CHIP:EM: <<< [E:31337r S:51913 M:12603942 (Ack:248780212)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188304.926877][25013:25013] CHIP:EM: ??1 [E:31337r S:51913 M:12603942] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 368ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.926994][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188304.927455][25013:25013] CHIP:EM: >>> [E:31336r S:51913 M:248780213 (Ack:12603941)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188304.927532][25013:25013] CHIP:EM: Found matching exchange: 31336r, Delegate: (nil) [1739188304.927620][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603941 from Retrans Table on exchange 31336r [1739188304.953454][25013:25013] CHIP:EM: >>> [E:31338r S:51913 M:248780214] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) [1739188304.953577][25013:25013] CHIP:EM: Handling via exchange: 31338r, Delegate: 0xaaaae105e5c8 [1739188304.953747][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188304.953808][25013:25013] CHIP:DMG: { [1739188304.953861][25013:25013] CHIP:DMG: suppressResponse = false, [1739188304.953923][25013:25013] CHIP:DMG: timedRequest = false, [1739188304.953978][25013:25013] CHIP:DMG: InvokeRequests = [1739188304.954053][25013:25013] CHIP:DMG: [ [1739188304.954110][25013:25013] CHIP:DMG: CommandDataIB = [1739188304.954175][25013:25013] CHIP:DMG: { [1739188304.954235][25013:25013] CHIP:DMG: CommandPathIB = [1739188304.954311][25013:25013] CHIP:DMG: { [1739188304.954383][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188304.954459][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188304.954533][25013:25013] CHIP:DMG: CommandId = 0x2, [1739188304.954603][25013:25013] CHIP:DMG: }, [1739188304.954676][25013:25013] CHIP:DMG: [1739188304.954737][25013:25013] CHIP:DMG: CommandFields = [1739188304.954806][25013:25013] CHIP:DMG: { [1739188304.954878][25013:25013] CHIP:DMG: 0x0 = 2 (unsigned), [1739188304.954953][25013:25013] CHIP:DMG: }, [1739188304.955019][25013:25013] CHIP:DMG: }, [1739188304.955089][25013:25013] CHIP:DMG: [1739188304.955301][25013:25013] CHIP:DMG: ], [1739188304.955380][25013:25013] CHIP:DMG: [1739188304.955436][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.955490][25013:25013] CHIP:DMG: }, [1739188304.956096][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188304.956164][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.956255][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1739188304.956340][25013:25013] CHIP:ZCL: OpCreds: Certificate Chain request received for PAI [1739188304.956441][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188304.956496][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188304.956560][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188304.956625][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188304.956721][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188304.956778][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188304.956841][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188304.957336][25013:25013] CHIP:EM: <<< [E:31338r S:51913 M:12603943 (Ack:248780214)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:531) [1739188304.957751][25013:25013] CHIP:EM: ??1 [E:31338r S:51913 M:12603943] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 391ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.957889][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188304.958309][25013:25013] CHIP:EM: >>> [E:31337r S:51913 M:248780215 (Ack:12603942)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188304.958381][25013:25013] CHIP:EM: Found matching exchange: 31337r, Delegate: (nil) [1739188304.958463][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603942 from Retrans Table on exchange 31337r [1739188304.978057][25013:25013] CHIP:EM: >>> [E:31339r S:51913 M:248780216] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) [1739188304.978154][25013:25013] CHIP:EM: Handling via exchange: 31339r, Delegate: 0xaaaae105e5c8 [1739188304.978302][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188304.978362][25013:25013] CHIP:DMG: { [1739188304.978416][25013:25013] CHIP:DMG: suppressResponse = false, [1739188304.978477][25013:25013] CHIP:DMG: timedRequest = false, [1739188304.978532][25013:25013] CHIP:DMG: InvokeRequests = [1739188304.978608][25013:25013] CHIP:DMG: [ [1739188304.978665][25013:25013] CHIP:DMG: CommandDataIB = [1739188304.978728][25013:25013] CHIP:DMG: { [1739188304.978787][25013:25013] CHIP:DMG: CommandPathIB = [1739188304.978857][25013:25013] CHIP:DMG: { [1739188304.978926][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188304.978998][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188304.979071][25013:25013] CHIP:DMG: CommandId = 0x2, [1739188304.979141][25013:25013] CHIP:DMG: }, [1739188304.979378][25013:25013] CHIP:DMG: [1739188304.979445][25013:25013] CHIP:DMG: CommandFields = [1739188304.979512][25013:25013] CHIP:DMG: { [1739188304.979584][25013:25013] CHIP:DMG: 0x0 = 1 (unsigned), [1739188304.979659][25013:25013] CHIP:DMG: }, [1739188304.979725][25013:25013] CHIP:DMG: }, [1739188304.979796][25013:25013] CHIP:DMG: [1739188304.979851][25013:25013] CHIP:DMG: ], [1739188304.979923][25013:25013] CHIP:DMG: [1739188304.979978][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188304.980033][25013:25013] CHIP:DMG: }, [1739188304.980324][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188304.980388][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188304.980449][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1739188304.980530][25013:25013] CHIP:ZCL: OpCreds: Certificate Chain request received for DAC [1739188304.980626][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188304.980682][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188304.980744][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188304.980807][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188304.980902][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188304.980997][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188304.981063][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188304.981470][25013:25013] CHIP:EM: <<< [E:31339r S:51913 M:12603944 (Ack:248780216)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:559) [1739188304.981839][25013:25013] CHIP:EM: ??1 [E:31339r S:51913 M:12603944] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 361ms from now [State:Active II:500 AI:300 AT:4000] [1739188304.981997][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188304.982392][25013:25013] CHIP:EM: >>> [E:31338r S:51913 M:248780217 (Ack:12603943)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188304.982464][25013:25013] CHIP:EM: Found matching exchange: 31338r, Delegate: (nil) [1739188304.982544][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603943 from Retrans Table on exchange 31338r [1739188305.001165][25013:25013] CHIP:EM: >>> [E:31340r S:51913 M:248780218] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) [1739188305.001257][25013:25013] CHIP:EM: Handling via exchange: 31340r, Delegate: 0xaaaae105e5c8 [1739188305.001402][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.001464][25013:25013] CHIP:DMG: { [1739188305.001518][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.001579][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.001635][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.001711][25013:25013] CHIP:DMG: [ [1739188305.001767][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.001830][25013:25013] CHIP:DMG: { [1739188305.001890][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.001960][25013:25013] CHIP:DMG: { [1739188305.002029][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.002104][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188305.002178][25013:25013] CHIP:DMG: CommandId = 0x0, [1739188305.002249][25013:25013] CHIP:DMG: }, [1739188305.002322][25013:25013] CHIP:DMG: [1739188305.002384][25013:25013] CHIP:DMG: CommandFields = [1739188305.002452][25013:25013] CHIP:DMG: { [1739188305.002522][25013:25013] CHIP:DMG: 0x0 = [ [1739188305.002628][25013:25013] CHIP:DMG: 0xa5, 0x09, 0x3b, 0xde, 0x23, 0x6c, 0xd9, 0xf6, 0x03, 0x5b, 0xbe, 0x60, 0xab, 0x9e, 0x3b, 0x70, 0x85, 0x63, 0x02, 0xa5, 0x32, 0xca, 0x5f, 0x7a, 0xbe, 0x0d, 0x70, 0x55, 0xa8, 0xaa, 0x85, 0x77, [1739188305.002881][25013:25013] CHIP:DMG: ] (32 bytes) [1739188305.002965][25013:25013] CHIP:DMG: }, [1739188305.003031][25013:25013] CHIP:DMG: }, [1739188305.003106][25013:25013] CHIP:DMG: [1739188305.003161][25013:25013] CHIP:DMG: ], [1739188305.003234][25013:25013] CHIP:DMG: [1739188305.003544][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.003628][25013:25013] CHIP:DMG: }, [1739188305.003953][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188305.004017][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188305.004079][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [1739188305.004165][25013:25013] CHIP:ZCL: OpCreds: Received an AttestationRequest command [1739188305.004505][25013:25013] CHIP:EM: <<< [E:31340r S:51913 M:12603945 (Ack:248780218)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.004749][25013:25013] CHIP:EM: Flushed pending ack for MessageCounter:248780218 on exchange 31340r [1739188305.005779][25013:25013] CHIP:ZCL: OpCreds: AttestationRequest successful. [1739188305.005915][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.005973][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.006036][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.006102][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.006214][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.006272][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.006335][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.006778][25013:25013] CHIP:EM: <<< [E:31340r S:51913 M:12603946 (Ack:248780218)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:718) [1739188305.007144][25013:25013] CHIP:EM: ??1 [E:31340r S:51913 M:12603946] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 406ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.007314][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.007732][25013:25013] CHIP:EM: >>> [E:31339r S:51913 M:248780219 (Ack:12603944)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.007805][25013:25013] CHIP:EM: Found matching exchange: 31339r, Delegate: (nil) [1739188305.007887][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603944 from Retrans Table on exchange 31339r [1739188305.090364][25013:25013] CHIP:EM: >>> [E:31341r S:51913 M:248780220] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) [1739188305.090493][25013:25013] CHIP:EM: Handling via exchange: 31341r, Delegate: 0xaaaae105e5c8 [1739188305.090676][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.090740][25013:25013] CHIP:DMG: { [1739188305.090795][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.090857][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.090913][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.090987][25013:25013] CHIP:DMG: [ [1739188305.091039][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.091103][25013:25013] CHIP:DMG: { [1739188305.091164][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.091247][25013:25013] CHIP:DMG: { [1739188305.091317][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.091393][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188305.091467][25013:25013] CHIP:DMG: CommandId = 0x4, [1739188305.091536][25013:25013] CHIP:DMG: }, [1739188305.091611][25013:25013] CHIP:DMG: [1739188305.091673][25013:25013] CHIP:DMG: CommandFields = [1739188305.091752][25013:25013] CHIP:DMG: { [1739188305.091830][25013:25013] CHIP:DMG: 0x0 = [ [1739188305.091944][25013:25013] CHIP:DMG: 0x81, 0x32, 0xb6, 0xb5, 0xdd, 0x0e, 0xc4, 0xb8, 0x81, 0xf4, 0x9e, 0x4e, 0x94, 0x35, 0x9e, 0xb3, 0xd8, 0x3a, 0x17, 0x6f, 0x14, 0x4a, 0x7b, 0xab, 0xc7, 0x8e, 0x68, 0x83, 0xa7, 0x3c, 0x9d, 0x02, [1739188305.092055][25013:25013] CHIP:DMG: ] (32 bytes) [1739188305.092147][25013:25013] CHIP:DMG: }, [1739188305.092216][25013:25013] CHIP:DMG: }, [1739188305.092290][25013:25013] CHIP:DMG: [1739188305.092346][25013:25013] CHIP:DMG: ], [1739188305.092419][25013:25013] CHIP:DMG: [1739188305.092475][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.092530][25013:25013] CHIP:DMG: }, [1739188305.092834][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188305.092899][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188305.092995][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 [1739188305.093087][25013:25013] CHIP:ZCL: OpCreds: Received a CSRRequest command [1739188305.093148][25013:25013] CHIP:ZCL: OpCreds: Finding fabric with fabricIndex 0x0 [1739188305.093534][25013:25013] CHIP:EM: <<< [E:31341r S:51913 M:12603947 (Ack:248780220)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.093802][25013:25013] CHIP:EM: Flushed pending ack for MessageCounter:248780220 on exchange 31341r [1739188305.096782][25013:25013] CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded [1739188305.097606][25013:25013] CHIP:ZCL: OpCreds: CSRRequest successful. [1739188305.097735][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.097794][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.097860][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.097967][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.098080][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.098138][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.098202][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.098642][25013:25013] CHIP:EM: <<< [E:31341r S:51913 M:12603948 (Ack:248780220)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:377) [1739188305.098993][25013:25013] CHIP:EM: ??1 [E:31341r S:51913 M:12603948] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 376ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.099102][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.101138][25013:25013] CHIP:EM: >>> [E:31340r S:51913 M:248780221 (Ack:12603946)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.101215][25013:25013] CHIP:EM: Found matching exchange: 31340r, Delegate: (nil) [1739188305.101304][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603946 from Retrans Table on exchange 31340r [1739188305.113589][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.113830][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.114040][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.114248][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.114454][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.114661][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.114866][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.115092][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.118325][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.118599][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.118814][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.119023][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.119232][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.119438][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.119648][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.119854][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.120069][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.126793][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.127033][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.127239][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.127443][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.127646][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.127853][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.130020][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.130268][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.131101][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.131388][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.131631][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.131835][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.132038][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.132243][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188305.189414][25013:25013] CHIP:EM: >>> [E:31342r S:51913 M:248780222] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:463) [1739188305.189542][25013:25013] CHIP:EM: Handling via exchange: 31342r, Delegate: 0xaaaae105e5c8 [1739188305.189714][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.189778][25013:25013] CHIP:DMG: { [1739188305.189832][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.189896][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.189954][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.190031][25013:25013] CHIP:DMG: [ [1739188305.190089][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.190156][25013:25013] CHIP:DMG: { [1739188305.190217][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.190295][25013:25013] CHIP:DMG: { [1739188305.190365][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.190442][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188305.190610][25013:25013] CHIP:DMG: CommandId = 0xb, [1739188305.190688][25013:25013] CHIP:DMG: }, [1739188305.190765][25013:25013] CHIP:DMG: [1739188305.190828][25013:25013] CHIP:DMG: CommandFields = [1739188305.190967][25013:25013] CHIP:DMG: { [1739188305.191042][25013:25013] CHIP:DMG: 0x0 = [ [1739188305.191424][25013:25013] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x14, 0x01, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x49, 0x21, 0xf7, 0xc4, 0xea, 0x64, 0x44, 0x41, 0xb6, 0xe9, 0x1a, 0xcd, 0x9a, 0x68, 0x30, 0x33, 0x85, 0x1c, 0x58, 0x40, 0xa6, 0xe1, 0x06, 0xde, 0x5d, 0x68, 0x0d, 0xb2, 0xa0, 0xb2, 0xa1, 0x53, 0x7b, 0xfe, 0xda, 0x81, 0xe3, 0x43, 0xc3, 0xf9, 0x25, 0x0b, 0xb1, 0x8b, 0xa2, 0x36, 0x41, 0x40, 0x4e, 0x5a, 0xc5, 0x16, 0xd0, 0x20, 0x60, 0x6d, 0x86, 0x10, 0xee, 0xd2, 0xac, 0xd6, 0x24, 0x2a, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x05, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x06, 0xa6, 0x30, 0x81, 0xa3, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x81, 0x9b, 0x04, 0x81, 0x98, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188305.191609][25013:25013] CHIP:DMG: ] (400 bytes) [1739188305.191686][25013:25013] CHIP:DMG: }, [1739188305.191752][25013:25013] CHIP:DMG: }, [1739188305.191885][25013:25013] CHIP:DMG: [1739188305.191941][25013:25013] CHIP:DMG: ], [1739188305.192015][25013:25013] CHIP:DMG: [1739188305.192070][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.192125][25013:25013] CHIP:DMG: }, [1739188305.192435][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188305.192500][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188305.192609][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B [1739188305.192701][25013:25013] CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command [1739188305.193154][25013:25013] CHIP:EM: <<< [E:31342r S:51913 M:12603949 (Ack:248780222)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.193488][25013:25013] CHIP:EM: Flushed pending ack for MessageCounter:248780222 on exchange 31342r [1739188305.195965][25013:25013] CHIP:ZCL: OpCreds: AddTrustedRootCertificate successful. [1739188305.196110][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.196173][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.196239][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.196298][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.196411][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.196470][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.196535][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.196987][25013:25013] CHIP:EM: <<< [E:31342r S:51913 M:12603950 (Ack:248780222)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67) [1739188305.197453][25013:25013] CHIP:EM: ??1 [E:31342r S:51913 M:12603950] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 390ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.197570][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.198034][25013:25013] CHIP:EM: >>> [E:31341r S:51913 M:248780223 (Ack:12603948)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.198115][25013:25013] CHIP:EM: Found matching exchange: 31341r, Delegate: (nil) [1739188305.198202][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603948 from Retrans Table on exchange 31341r [1739188305.215063][25013:25013] CHIP:EM: >>> [E:31343r S:51913 M:248780224] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:864) [1739188305.215181][25013:25013] CHIP:EM: Handling via exchange: 31343r, Delegate: 0xaaaae105e5c8 [1739188305.215356][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.215421][25013:25013] CHIP:DMG: { [1739188305.215475][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.215537][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.215593][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.215675][25013:25013] CHIP:DMG: [ [1739188305.215732][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.215796][25013:25013] CHIP:DMG: { [1739188305.215856][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.215942][25013:25013] CHIP:DMG: { [1739188305.216024][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.216220][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188305.216318][25013:25013] CHIP:DMG: CommandId = 0x6, [1739188305.216407][25013:25013] CHIP:DMG: }, [1739188305.216547][25013:25013] CHIP:DMG: [1739188305.216615][25013:25013] CHIP:DMG: CommandFields = [1739188305.216693][25013:25013] CHIP:DMG: { [1739188305.216771][25013:25013] CHIP:DMG: 0x0 = [ [1739188305.217295][25013:25013] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x13, 0x02, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x15, 0x01, 0x26, 0x11, 0x21, 0x43, 0x34, 0x12, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x9a, 0xfd, 0xf3, 0x86, 0x97, 0x45, 0x94, 0xac, 0xd1, 0x74, 0xc7, 0x74, 0xfa, 0x63, 0x68, 0x44, 0xcd, 0x08, 0xbb, 0xd6, 0x2d, 0x5d, 0x94, 0x03, 0x0f, 0xfc, 0x55, 0x62, 0x56, 0x6e, 0xae, 0x81, 0x3d, 0x47, 0xd3, 0xcf, 0x53, 0xcf, 0xf4, 0x99, 0x8c, 0x56, 0x1a, 0xfd, 0x77, 0x63, 0x22, 0x79, 0xb2, 0x23, 0x5b, 0xbe, 0xa1, 0x38, 0xdd, 0x75, 0x6a, 0x7b, 0x4c, 0x29, 0x31, 0x30, 0x5e, 0x24, 0x37, 0x0a, 0x35, 0x01, 0x28, 0x01, 0x18, 0x24, 0x02, 0x01, 0x36, 0x03, 0x04, 0x02, 0x04, 0x01, 0x18, 0x30, 0x04, 0x14, 0x24, 0xd7, 0xc0, 0x83, 0x7c, 0x62, 0xa2, 0x98, 0x93, 0xe3, 0x06, 0xa5, 0xe8, 0xb1, 0x98, 0xdb, 0xee, 0xda, 0x49, 0x8b, 0x30, 0x05, 0x14, 0x08, 0xd0, 0xd3, 0xbd, 0xfd, 0xa3, 0xd8, 0xe6, 0x1e, 0x4c, 0x1c, 0x9a, 0xe5, 0x5d, 0x84, 0x70, 0x75, 0x69, 0x44, 0xe0, 0x30, 0x06, 0x79, 0x30, 0x77, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x70, 0x04, 0x6e, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188305.217487][25013:25013] CHIP:DMG: ] (368 bytes) [1739188305.217579][25013:25013] CHIP:DMG: 0x1 = [ [1739188305.217959][25013:25013] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x13, 0x02, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0xb4, 0x15, 0xe1, 0x53, 0x3c, 0xa2, 0xcf, 0xe5, 0x82, 0xc7, 0x3a, 0xa1, 0x33, 0x22, 0x4d, 0x7c, 0x93, 0x83, 0x98, 0x9b, 0xa7, 0x84, 0xf3, 0xeb, 0xea, 0x7a, 0xe3, 0x42, 0x8e, 0x7d, 0xd6, 0xb7, 0x58, 0xbf, 0x3f, 0x62, 0x3a, 0x5b, 0x2f, 0x4c, 0xfd, 0x62, 0x3c, 0x6c, 0xac, 0xb1, 0x74, 0xb4, 0x42, 0x14, 0xf4, 0x18, 0x8f, 0x2c, 0xdd, 0xad, 0xc6, 0xa8, 0xf8, 0x90, 0x69, 0x57, 0x58, 0xc4, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x08, 0xd0, 0xd3, 0xbd, 0xfd, 0xa3, 0xd8, 0xe6, 0x1e, 0x4c, 0x1c, 0x9a, 0xe5, 0x5d, 0x84, 0x70, 0x75, 0x69, 0x44, 0xe0, 0x30, 0x05, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x06, 0xa6, 0x30, 0x81, 0xa3, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x81, 0x9b, 0x04, 0x81, 0x98, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188305.218147][25013:25013] CHIP:DMG: ] (400 bytes) [1739188305.218238][25013:25013] CHIP:DMG: 0x2 = [ [1739188305.218335][25013:25013] CHIP:DMG: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31, [1739188305.218434][25013:25013] CHIP:DMG: ] (16 bytes) [1739188305.218521][25013:25013] CHIP:DMG: 0x3 = 112233 (unsigned), [1739188305.218665][25013:25013] CHIP:DMG: 0x4 = 65521 (unsigned), [1739188305.218808][25013:25013] CHIP:DMG: }, [1739188305.218876][25013:25013] CHIP:DMG: }, [1739188305.218958][25013:25013] CHIP:DMG: [1739188305.219014][25013:25013] CHIP:DMG: ], [1739188305.219093][25013:25013] CHIP:DMG: [1739188305.219149][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.219204][25013:25013] CHIP:DMG: }, [1739188305.219742][25013:25013] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188305.219813][25013:25013] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188305.219878][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 [1739188305.219989][25013:25013] CHIP:ZCL: OpCreds: Received an AddNOC command [1739188305.220394][25013:25013] CHIP:EM: <<< [E:31343r S:51913 M:12603951 (Ack:248780224)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.220733][25013:25013] CHIP:EM: Flushed pending ack for MessageCounter:248780224 on exchange 31343r [1739188305.221397][25013:25013] CHIP:FP: Validating NOC chain [1739188305.226194][25013:25013] CHIP:FP: NOC chain validation successful [1739188305.226313][25013:25013] CHIP:FP: Added new fabric at index: 0x1 [1739188305.226364][25013:25013] CHIP:FP: Assigned compressed fabric ID: 0x29FF093EE9A85335, node ID: 0x0000000012344321 [1739188305.226429][25013:25013] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1739188305.226482][25013:25013] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1739188305.226531][25013:25013] CHIP:TS: Retaining current Last Known Good Time [1739188305.226596][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97b8 [1739188305.226657][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97b9 [1739188305.235506][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.255650][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.275541][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.275727][25013:25013] CHIP:DMG: AccessControl: validating f=1 p=a a=c s=1 t=0 [1739188305.275790][25013:25013] CHIP:DMG: validating subject 0x000000000001B669 [1739188305.295449][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.295752][25013:25013] CHIP:EVL: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000194EFB37D8F [1739188305.295827][25013:25013] CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 [1739188305.297508][25013:25013] CHIP:DL: Using WiFi MAC for hostname [1739188305.297595][25013:25013] CHIP:DIS: Advertise operational node 29FF093EE9A85335-0000000012344321 [1739188305.297712][25013:25013] CHIP:DIS: Responding with _matter._tcp.local [1739188305.297773][25013:25013] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188305.297834][25013:25013] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188305.297888][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188305.297938][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188305.298001][25013:25013] CHIP:DIS: Responding with _I29FF093EE9A85335._sub._matter._tcp.local [1739188305.298051][25013:25013] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 29FF093EE9A85335-0000000012344321. [1739188305.341804][25013:25013] CHIP:DIS: mDNS service published: _matter._tcp [1739188305.341916][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97ba [1739188305.341980][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97bb [1739188305.342094][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.342155][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.342221][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.342290][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.342342][25013:25013] CHIP:ZCL: OpCreds: successfully created fabric index 0x1 via AddNOC [1739188305.342472][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.342530][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.342594][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.343002][25013:25013] CHIP:EM: <<< [E:31343r S:51913 M:12603952 (Ack:248780224)] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188305.343402][25013:25013] CHIP:EM: ??1 [E:31343r S:51913 M:12603952] (S) Msg Retransmission to 1:FFFFFFFB00000000 scheduled for 396ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.343562][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.344034][25013:25013] CHIP:EM: >>> [E:31342r S:51913 M:248780225 (Ack:12603950)] (S) Msg RX from 1:FFFFFFFB00000000 [5335] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.344109][25013:25013] CHIP:EM: Found matching exchange: 31342r, Delegate: (nil) [1739188305.344192][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:12603950 from Retrans Table on exchange 31342r [1739188305.593238][25013:25013] CHIP:EM: >>> [E:31344r S:0 M:251017299] (U) Msg RX from 0:BF2F19D225A1C63D [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196) [1739188305.593359][25013:25013] CHIP:EM: Handling via exchange: 31344r, Delegate: 0xaaaae105f298 [1739188305.593456][25013:25013] CHIP:IN: CASE Server received Sigma1 message . Starting handshake. EC 0xaaaae962ff00 [1739188305.593549][25013:25013] CHIP:SC: Received Sigma1 msg [1739188305.593664][25013:25013] CHIP:SC: Found MRP parameters in the message [1739188305.593747][25013:25013] CHIP:SC: Peer (Initiator) assigned session ID 21997 [1739188305.594683][25013:25013] CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000012344321 [1739188305.599358][25013:25013] CHIP:EM: <<< [E:31344r S:0 M:99396223 (Ack:251017299)] (U) Msg TX from 0000000000000000 to 0:BF2F19D225A1C63D [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:1049) [1739188305.599819][25013:25013] CHIP:EM: ??1 [E:31344r S:0 M:99396223] (U) Msg Retransmission to 0:0000000000000000 scheduled for 401ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.599986][25013:25013] CHIP:SC: Sent Sigma2 msg [1739188305.679390][25013:25013] CHIP:EM: >>> [E:31344r S:0 M:251017300 (Ack:99396223)] (U) Msg RX from 0:BF2F19D225A1C63D [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:873) [1739188305.679482][25013:25013] CHIP:EM: Found matching exchange: 31344r, Delegate: 0xaaaae105f2d0 [1739188305.679576][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:99396223 from Retrans Table on exchange 31344r [1739188305.679688][25013:25013] CHIP:SC: Received Sigma3 msg [1739188305.696010][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.715888][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.735944][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.736101][25013:25013] CHIP:SC: Sending status report. Protocol code 0, exchange 31344 [1739188305.736442][25013:25013] CHIP:EM: <<< [E:31344r S:0 M:99396224 (Ack:251017300)] (U) Msg TX from 0000000000000000 to 0:BF2F19D225A1C63D [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:40 (SecureChannel:StatusReport) (B:34) [1739188305.736855][25013:25013] CHIP:EM: ??1 [E:31344r S:0 M:99396224] (U) Msg Retransmission to 0:0000000000000000 scheduled for 389ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.737503][25013:25013] CHIP:SC: SecureSession[0xaaaae96316a0, LSID:51914]: State change 'kEstablishing' --> 'kActive' [1739188305.737587][25013:25013] CHIP:IN: SecureSession[0xaaaae96316a0]: Activated - Type:2 LSID:51914 [1739188305.737639][25013:25013] CHIP:IN: New secure session activated for device <000000000001B669, 1>, LSID:51914 PSID:21997! [1739188305.737722][25013:25013] CHIP:IN: CASE Session established to peer: <000000000001B669, 1> [1739188305.737897][25013:25013] CHIP:IN: SecureSession[0xaaaae964aac0]: Allocated Type:2 LSID:51915 [1739188305.737974][25013:25013] CHIP:SC: Allocated SecureSession (0xaaaae964aac0) - waiting for Sigma1 msg [1739188305.738055][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 32792 [1739188305.739498][25013:25013] CHIP:EM: <<1 [E:31343r S:51913 M:12603952] (S) Msg Retransmission to 1:FFFFFFFB00000000 [1739188305.739626][25013:25013] CHIP:EM: ??2 [E:31343r S:51913 M:12603952] (S) Msg Retransmission to 1:FFFFFFFB00000000 scheduled for 400ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.757827][25013:25013] CHIP:EM: >>> [E:31344r S:0 M:251017301 (Ack:99396224)] (U) Msg RX from 0:BF2F19D225A1C63D [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [1739188305.757930][25013:25013] CHIP:EM: Found matching exchange: 31344r, Delegate: (nil) [1739188305.758038][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:99396224 from Retrans Table on exchange 31344r [1739188305.760273][25013:25013] CHIP:EM: >>> [E:31345r S:51914 M:81193551] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0001:08 (IM:InvokeCommandRequest) (B:66) [1739188305.760393][25013:25013] CHIP:EM: Handling via exchange: 31345r, Delegate: 0xaaaae105e5c8 [1739188305.760561][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.760624][25013:25013] CHIP:DMG: { [1739188305.760677][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.760739][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.760796][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.760874][25013:25013] CHIP:DMG: [ [1739188305.760992][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.761065][25013:25013] CHIP:DMG: { [1739188305.761126][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.761208][25013:25013] CHIP:DMG: { [1739188305.761283][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.761377][25013:25013] CHIP:DMG: ClusterId = 0x30, [1739188305.761469][25013:25013] CHIP:DMG: CommandId = 0x0, [1739188305.761557][25013:25013] CHIP:DMG: }, [1739188305.761638][25013:25013] CHIP:DMG: [1739188305.761701][25013:25013] CHIP:DMG: CommandFields = [1739188305.761776][25013:25013] CHIP:DMG: { [1739188305.761855][25013:25013] CHIP:DMG: 0x0 = 900 (unsigned), [1739188305.761949][25013:25013] CHIP:DMG: 0x1 = 1 (unsigned), [1739188305.762055][25013:25013] CHIP:DMG: }, [1739188305.762129][25013:25013] CHIP:DMG: }, [1739188305.762204][25013:25013] CHIP:DMG: [1739188305.762259][25013:25013] CHIP:DMG: ], [1739188305.762334][25013:25013] CHIP:DMG: [1739188305.762389][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.762444][25013:25013] CHIP:DMG: }, [1739188305.762757][25013:25013] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t=0x00010001 c=0x0000_0030 e=0 p=a r=i [1739188305.762840][25013:25013] CHIP:DMG: AccessControl: allowed [1739188305.762913][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1739188305.763010][25013:25013] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (900s) [1739188305.763125][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4b9 [1739188305.763250][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.763317][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.763389][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.763463][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.763574][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.763639][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.763711][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.764139][25013:25013] CHIP:EM: <<< [E:31345r S:51914 M:239055666 (Ack:81193551)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188305.764527][25013:25013] CHIP:EM: ??1 [E:31345r S:51914 M:239055666] (S) Msg Retransmission to 1:000000000001B669 scheduled for 361ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.764652][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.809361][25013:25013] CHIP:EM: >>> [E:31345r S:51914 M:81193552 (Ack:239055666)] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.809469][25013:25013] CHIP:EM: Found matching exchange: 31345r, Delegate: (nil) [1739188305.809569][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:239055666 from Retrans Table on exchange 31345r [1739188305.829385][25013:25013] CHIP:EM: >>> [E:31346r S:51914 M:81193553] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65) [1739188305.829496][25013:25013] CHIP:EM: Handling via exchange: 31346r, Delegate: 0xaaaae105e5c8 [1739188305.829665][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.829728][25013:25013] CHIP:DMG: { [1739188305.829782][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.829845][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.829902][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.830015][25013:25013] CHIP:DMG: [ [1739188305.830074][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.830162][25013:25013] CHIP:DMG: { [1739188305.830224][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.830302][25013:25013] CHIP:DMG: { [1739188305.830399][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.830476][25013:25013] CHIP:DMG: ClusterId = 0x30, [1739188305.830576][25013:25013] CHIP:DMG: CommandId = 0x6, [1739188305.830649][25013:25013] CHIP:DMG: }, [1739188305.830746][25013:25013] CHIP:DMG: [1739188305.830809][25013:25013] CHIP:DMG: CommandFields = [1739188305.830879][25013:25013] CHIP:DMG: { [1739188305.830976][25013:25013] CHIP:DMG: 0x0 = 1 (unsigned), [1739188305.831054][25013:25013] CHIP:DMG: 0x1 = 1 (unsigned), [1739188305.831152][25013:25013] CHIP:DMG: }, [1739188305.831216][25013:25013] CHIP:DMG: }, [1739188305.831312][25013:25013] CHIP:DMG: [1739188305.831369][25013:25013] CHIP:DMG: ], [1739188305.831464][25013:25013] CHIP:DMG: [1739188305.831522][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.831576][25013:25013] CHIP:DMG: }, [1739188305.831955][25013:25013] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t=0x00010001 c=0x0000_0030 e=0 p=a r=i [1739188305.832036][25013:25013] CHIP:DMG: AccessControl: allowed [1739188305.832101][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0006 [1739188305.832388][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4ba [1739188305.832457][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4bb [1739188305.832538][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4bc [1739188305.832638][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188305.832696][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188305.832762][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188305.832847][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188305.832982][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188305.833063][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188305.833130][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188305.833605][25013:25013] CHIP:EM: <<< [E:31346r S:51914 M:239055667 (Ack:81193553)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67) [1739188305.833978][25013:25013] CHIP:EM: ??1 [E:31346r S:51914 M:239055667] (S) Msg Retransmission to 1:000000000001B669 scheduled for 377ms from now [State:Active II:500 AI:300 AT:4000] [1739188305.834112][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188305.886149][25013:25013] CHIP:EM: >>> [E:31346r S:51914 M:81193554 (Ack:239055667)] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188305.886235][25013:25013] CHIP:EM: Found matching exchange: 31346r, Delegate: (nil) [1739188305.886325][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:239055667 from Retrans Table on exchange 31346r [1739188305.897231][25013:25013] CHIP:EM: >>> [E:31347r S:51914 M:81193555] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59) [1739188305.897324][25013:25013] CHIP:EM: Handling via exchange: 31347r, Delegate: 0xaaaae105e5c8 [1739188305.897471][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188305.897532][25013:25013] CHIP:DMG: { [1739188305.897585][25013:25013] CHIP:DMG: suppressResponse = false, [1739188305.897647][25013:25013] CHIP:DMG: timedRequest = false, [1739188305.897703][25013:25013] CHIP:DMG: InvokeRequests = [1739188305.897806][25013:25013] CHIP:DMG: [ [1739188305.897863][25013:25013] CHIP:DMG: CommandDataIB = [1739188305.897962][25013:25013] CHIP:DMG: { [1739188305.898024][25013:25013] CHIP:DMG: CommandPathIB = [1739188305.898116][25013:25013] CHIP:DMG: { [1739188305.898189][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188305.898286][25013:25013] CHIP:DMG: ClusterId = 0x30, [1739188305.898362][25013:25013] CHIP:DMG: CommandId = 0x4, [1739188305.898434][25013:25013] CHIP:DMG: }, [1739188305.898530][25013:25013] CHIP:DMG: [1739188305.898597][25013:25013] CHIP:DMG: CommandFields = [1739188305.898686][25013:25013] CHIP:DMG: { [1739188305.898757][25013:25013] CHIP:DMG: }, [1739188305.898852][25013:25013] CHIP:DMG: }, [1739188305.898925][25013:25013] CHIP:DMG: [1739188305.898982][25013:25013] CHIP:DMG: ], [1739188305.899053][25013:25013] CHIP:DMG: [1739188305.899108][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188305.899183][25013:25013] CHIP:DMG: }, [1739188305.899515][25013:25013] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t=0x00010001 c=0x0000_0030 e=0 p=a r=i [1739188305.899594][25013:25013] CHIP:DMG: AccessControl: allowed [1739188305.899659][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 [1739188305.899737][25013:25013] CHIP:FS: GeneralCommissioning: Received CommissioningComplete [1739188305.908785][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.909052][25013:25013] CHIP:SVR: Terms and conditions have been committed [1739188305.909111][25013:25013] CHIP:FS: GeneralCommissioning: Successfully committed terms and conditions [1739188305.928683][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.948676][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.948828][25013:25013] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1739188305.968680][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188305.988758][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.008765][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.028602][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.028774][25013:25013] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1739188306.048625][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.068879][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.069093][25013:25013] CHIP:ZCL: OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x29FF093EE9A85335, FabricId 0000000000000001, NodeId 0000000012344321, VendorId 0xFFF1 [1739188306.089003][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.089158][25013:25013] CHIP:FS: GeneralCommissioning: Successfully committed pending fabric data [1739188306.089233][25013:25013] CHIP:FS: Fail-safe cleanly disarmed [1739188306.089318][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4bd [1739188306.089451][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188306.089512][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188306.089577][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188306.089646][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188306.089761][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188306.089819][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188306.089883][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188306.090307][25013:25013] CHIP:EM: <<< [E:31347r S:51914 M:239055668 (Ack:81193555)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188306.090691][25013:25013] CHIP:EM: ??1 [E:31347r S:51914 M:239055668] (S) Msg Retransmission to 1:000000000001B669 scheduled for 394ms from now [State:Active II:500 AI:300 AT:4000] [1739188306.090799][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188306.090893][25013:25013] CHIP:DL: HandlePlatformSpecificBLEEvent 32783 [1739188306.090951][25013:25013] CHIP:SVR: Commissioning completed successfully [1739188306.091045][25013:25013] CHIP:DIS: Updating services using commissioning mode 0 [1739188306.116126][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188306.206944][25013:25013] CHIP:DL: Using WiFi MAC for hostname [1739188306.207051][25013:25013] CHIP:DIS: Advertise operational node 29FF093EE9A85335-0000000012344321 [1739188306.207163][25013:25013] CHIP:DIS: Responding with _matter._tcp.local [1739188306.207224][25013:25013] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188306.207286][25013:25013] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188306.207339][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188306.207389][25013:25013] CHIP:DIS: Responding with E45F010F1A010000.local [1739188306.207454][25013:25013] CHIP:DIS: Responding with _I29FF093EE9A85335._sub._matter._tcp.local [1739188306.207504][25013:25013] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 29FF093EE9A85335-0000000012344321. [1739188306.250778][25013:25013] CHIP:DIS: mDNS service published: _matter._tcp [1739188306.250944][25013:25013] CHIP:IN: Expiring all PASE sessions [1739188306.251002][25013:25013] CHIP:IN: SecureSession[0xaaaae96310b0]: MarkForEviction Type:1 LSID:51913 [1739188306.251060][25013:25013] CHIP:SC: SecureSession[0xaaaae96310b0, LSID:51913]: State change 'kActive' --> 'kPendingEviction' [1739188306.251206][25013:25013] CHIP:IN: SecureSession[0xaaaae96310b0]: Released - Type:1 LSID:51913 [1739188306.251281][25013:25013] CHIP:DL: Long dispatch time: 161 ms, for event type 32783 [1739188306.251796][25013:25013] CHIP:EM: >>> [E:31347r S:51914 M:81193556 (Ack:239055668)] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188306.251876][25013:25013] CHIP:EM: Found matching exchange: 31347r, Delegate: (nil) [1739188306.251951][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:239055668 from Retrans Table on exchange 31347r [1739188306.253757][25013:25013] CHIP:EM: >>> [E:31348r S:51914 M:81193557] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0001:02 (IM:ReadRequest) (B:51) [1739188306.253849][25013:25013] CHIP:EM: Handling via exchange: 31348r, Delegate: 0xaaaae105e5c8 [1739188306.253929][25013:25013] CHIP:IM: Received Read request [1739188306.254030][25013:25013] CHIP:DMG: ReadRequestMessage = [1739188306.254088][25013:25013] CHIP:DMG: { [1739188306.254138][25013:25013] CHIP:DMG: AttributePathIBs = [1739188306.254199][25013:25013] CHIP:DMG: [ [1739188306.254255][25013:25013] CHIP:DMG: AttributePathIB = [1739188306.254324][25013:25013] CHIP:DMG: { [1739188306.254389][25013:25013] CHIP:DMG: Endpoint = 0x0, [1739188306.254468][25013:25013] CHIP:DMG: Cluster = 0x3e, [1739188306.254536][25013:25013] CHIP:DMG: Attribute = 0x0000_0001, [1739188306.254599][25013:25013] CHIP:DMG: } [1739188306.254666][25013:25013] CHIP:DMG: [1739188306.254725][25013:25013] CHIP:DMG: ], [1739188306.254792][25013:25013] CHIP:DMG: [1739188306.254853][25013:25013] CHIP:DMG: isFabricFiltered = true, [1739188306.254912][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188306.254966][25013:25013] CHIP:DMG: }, [1739188306.255255][25013:25013] CHIP:DMG: IM RH moving to [CanStartReporting] [1739188306.256818][25013:25013] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000 [1739188306.256984][25013:25013] CHIP:DMG: Cluster 3e, Attribute 1 is dirty [1739188306.257090][25013:25013] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t=0x00010001 c=0x0000_003E e=0 p=v r=r [1739188306.257167][25013:25013] CHIP:DMG: AccessControl: allowed [1739188306.257221][25013:25013] CHIP:DMG: Reading attribute: Cluster=0x0000_003E Endpoint=0x0 AttributeId=0x0000_0001 (expanded=0) [1739188306.257435][25013:25013] CHIP:DMG: Sending report (payload has 125 bytes)... [1739188306.257879][25013:25013] CHIP:EM: <<< [E:31348r S:51914 M:239055669 (Ack:81193557)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:05 (IM:ReportData) (B:159) [1739188306.258235][25013:25013] CHIP:EM: ??1 [E:31348r S:51914 M:239055669] (S) Msg Retransmission to 1:000000000001B669 scheduled for 343ms from now [State:Active II:500 AI:300 AT:4000] [1739188306.258343][25013:25013] CHIP:DMG: OnReportConfirm: NumReports = 0 [1739188306.258403][25013:25013] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1739188306.258455][25013:25013] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1739188306.260882][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188306.287905][25013:25013] CHIP:EM: >>> [E:31348r S:51914 M:81193558 (Ack:239055669)] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188306.288000][25013:25013] CHIP:EM: Found matching exchange: 31348r, Delegate: (nil) [1739188306.288079][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:239055669 from Retrans Table on exchange 31348r [1739188306.292576][25013:25013] CHIP:EM: >>> [E:31349r S:51914 M:81193559] (S) Msg RX from 1:000000000001B669 [5335] to 0000000012344321 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) [1739188306.292668][25013:25013] CHIP:EM: Handling via exchange: 31349r, Delegate: 0xaaaae105e5c8 [1739188306.292818][25013:25013] CHIP:DMG: InvokeRequestMessage = [1739188306.292880][25013:25013] CHIP:DMG: { [1739188306.292964][25013:25013] CHIP:DMG: suppressResponse = false, [1739188306.293031][25013:25013] CHIP:DMG: timedRequest = false, [1739188306.293088][25013:25013] CHIP:DMG: InvokeRequests = [1739188306.293164][25013:25013] CHIP:DMG: [ [1739188306.293220][25013:25013] CHIP:DMG: CommandDataIB = [1739188306.293284][25013:25013] CHIP:DMG: { [1739188306.293344][25013:25013] CHIP:DMG: CommandPathIB = [1739188306.293419][25013:25013] CHIP:DMG: { [1739188306.293492][25013:25013] CHIP:DMG: EndpointId = 0x0, [1739188306.293569][25013:25013] CHIP:DMG: ClusterId = 0x3e, [1739188306.293643][25013:25013] CHIP:DMG: CommandId = 0xa, [1739188306.293714][25013:25013] CHIP:DMG: }, [1739188306.293788][25013:25013] CHIP:DMG: [1739188306.293849][25013:25013] CHIP:DMG: CommandFields = [1739188306.293918][25013:25013] CHIP:DMG: { [1739188306.293990][25013:25013] CHIP:DMG: 0x0 = 1 (unsigned), [1739188306.294061][25013:25013] CHIP:DMG: }, [1739188306.294126][25013:25013] CHIP:DMG: }, [1739188306.294197][25013:25013] CHIP:DMG: [1739188306.294252][25013:25013] CHIP:DMG: ], [1739188306.294324][25013:25013] CHIP:DMG: [1739188306.294379][25013:25013] CHIP:DMG: InteractionModelRevision = 12 [1739188306.294434][25013:25013] CHIP:DMG: }, [1739188306.294742][25013:25013] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t=0x00010001 c=0x0000_003E e=0 p=a r=i [1739188306.294820][25013:25013] CHIP:DMG: AccessControl: allowed [1739188306.294884][25013:25013] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000A [1739188306.294965][25013:25013] CHIP:ZCL: OpCreds: Received a RemoveFabric Command for FabricIndex 0x1 [1739188306.295319][25013:25013] CHIP:EM: <<< [E:31349r S:51914 M:239055670 (Ack:81193559)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188306.295582][25013:25013] CHIP:EM: Flushed pending ack for MessageCounter:81193559 on exchange 31349r [1739188306.295733][25013:25013] CHIP:EVL: LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Epoch timestamp: 0x00000194EFB38177 [1739188306.295809][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188306.305323][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.325432][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.345484][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.365383][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.385363][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.405268][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.405411][25013:25013] CHIP:FP: Fabric (0x1) deleted. [1739188306.405472][25013:25013] CHIP:ZCL: OpCreds: Fabric index 0x1 was removed [1739188306.405523][25013:25013] CHIP:DIS: Updating services using commissioning mode 0 [1739188306.430817][25013:25013] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188306.518602][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97bc [1739188306.518708][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 654f97bd [1739188306.518768][25013:25013] CHIP:ZCL: general-commissioning-server: Last Fabric index 0x1 was removed [1739188306.527843][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.528116][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4be [1739188306.528189][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4bf [1739188306.528247][25013:25013] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to ee25e4c0 [1739188306.547711][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.567597][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.587390][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.607433][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.627378][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.647359][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.667027][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.686927][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.706837][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188306.707018][25013:25013] CHIP:ZCL: OpCreds: RemoveFabric successful [1739188306.707149][25013:25013] CHIP:DMG: Command handler moving to [NewRespons] [1739188306.707210][25013:25013] CHIP:DMG: Command handler moving to [ Preparing] [1739188306.707277][25013:25013] CHIP:DMG: Command handler moving to [AddingComm] [1739188306.707346][25013:25013] CHIP:DMG: Command handler moving to [AddedComma] [1739188306.707418][25013:25013] CHIP:IN: Expiring all sessions for fabric 0x1!! [1739188306.707474][25013:25013] CHIP:IN: SecureSession[0xaaaae96316a0]: MarkForEviction Type:2 LSID:51914 [1739188306.707528][25013:25013] CHIP:SC: SecureSession[0xaaaae96316a0, LSID:51914]: State change 'kActive' --> 'kPendingEviction' [1739188306.707666][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188306.707724][25013:25013] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188306.707790][25013:25013] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188306.708198][25013:25013] CHIP:EM: <<< [E:31349r S:51914 M:239055671 (Ack:81193559)] (S) Msg TX from 0000000012344321 to 1:000000000001B669 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188306.708583][25013:25013] CHIP:EM: ??1 [E:31349r S:51914 M:239055671] (S) Msg Retransmission to 1:000000000001B669 scheduled for 377ms from now [State:Active II:500 AI:300 AT:4000] [1739188306.708694][25013:25013] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188306.762532][25013:25013] CHIP:EM: >>> [E:31349r S:51914 M:81193560 (Ack:239055671)] (S) Msg RX from 1:000000000001B669 [0000] to 0000000012344321 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188306.762629][25013:25013] CHIP:EM: Found matching exchange: 31349r, Delegate: (nil) [1739188306.762710][25013:25013] CHIP:EM: Rxd Ack; Removing MessageCounter:239055671 from Retrans Table on exchange 31349r [1739188306.762783][25013:25013] CHIP:IN: SecureSession[0xaaaae96316a0]: Released - Type:2 LSID:51914 [1739188307.112780][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.113079][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.113292][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.113497][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.113720][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.113940][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.114145][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.114365][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.116703][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.117010][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.117239][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.117446][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.117649][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.117851][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.118058][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.118260][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.118467][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.128183][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.128698][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.128908][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.129151][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.129353][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.129551][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.129752][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.131761][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.132024][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.132234][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.132444][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.132651][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.132857][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.133119][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.133329][25013:25013] CHIP:DIS: SRV record already actively processed. [1739188307.133545][25013:25013] CHIP:DIS: SRV record already actively processed. ^C[1739188311.455646][25013:25013] CHIP:DL: Select failed: src/system/SystemLayerImplSelect.cpp:728: OS Error 0x02000004: Interrupted system call [1739188311.455732][25013:25013] CHIP:ZCL: Emitting ShutDown event [1739188311.455878][25013:25013] CHIP:EVL: LogEvent event number: 0x0000000000000004 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x1 Epoch timestamp: 0x00000194EFB3959F [1739188311.455955][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188311.456053][25013:25013] CHIP:IN: SecureSession[0xaaaae964aac0]: Released - Type:2 LSID:51915 [1739188311.471794][25013:25013] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188311.471944][25013:25013] CHIP:DMG: AccessControl: finishing [1739188311.471964][25013:25013] CHIP:DMG: Examples::AccessControlDelegate::Finish [1739188311.482454][25013:25013] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188311.482607][25013:25013] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1739188311.482668][25013:25013] CHIP:DL: Inet Layer shutdown [1739188311.482719][25013:25013] CHIP:DL: BLE Layer shutdown [1739188311.485208][25013:25013] CHIP:DL: System Layer shutdown ubuntu@raspberrypi:~/Feb_cntr/connectedhomeip/examples/terms-and-conditions-app/linux/out/terms-and-conditions-app$ ./chip-terms-and-conditions-app --tc-min-required-version 1 --tc-required-acknowledgements 1 --custom-flow 2 --capabilities 6 [1739188314.412546][25020:25020] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1739188314.413637][25020:25020] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1739188314.421442][25020:25020] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1739188314.422041][25020:25020] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1739188314.422372][25020:25020] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1739188314.431001][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_counters.ini [1739188314.431152][25020:25020] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1739188314.433223][25020:25020] CHIP:DL: Got Ethernet interface: eth0 [1739188314.434700][25020:25020] CHIP:DL: Found the primary Ethernet interface:eth0 [1739188314.436232][25020:25020] CHIP:DL: Got WiFi interface: wlan0 [1739188314.440806][25020:25020] CHIP:DL: Found the primary WiFi interface:wlan0 [1739188314.440987][25020:25020] 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. *** [1739188314.441055][25020:25020] 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. *** [1739188314.441109][25020:25020] CHIP:SPT: PASE PBKDF iterations set to 1000 [1739188314.441169][25020:25020] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one. [1739188314.457897][25020:25020] CHIP:DL: Device Configuration: [1739188314.458031][25020:25020] CHIP:DL: Serial Number: TEST_SN [1739188314.458119][25020:25020] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1739188314.458204][25020:25020] CHIP:DL: Product Id: 32769 (0x8001) [1739188314.458260][25020:25020] CHIP:DL: Product Name: TEST_PRODUCT [1739188314.458329][25020:25020] CHIP:DL: Hardware Version: 0 [1739188314.458382][25020:25020] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1739188314.458430][25020:25020] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1739188314.458498][25020:25020] CHIP:DL: Manufacturing Date: (not set) [1739188314.458550][25020:25020] CHIP:DL: Device Type: 65535 (0xFFFF) [1739188314.458596][25020:25020] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ==== [1739188314.458673][25020:25020] CHIP:SVR: SetupQRCode: [MT:-24J08M.00KA0648G00] [1739188314.458736][25020:25020] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1739188314.458784][25020:25020] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J08M.00KA0648G00 [1739188314.458864][25020:25020] CHIP:SVR: Manual pairing code: [749701123365521327694] [1739188314.459128][25020:25020] CHIP:SVR: Initializing subscription resumption storage... [1739188314.467695][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188314.467928][25020:25020] CHIP:SVR: Server initializing... [1739188314.468002][25020:25020] CHIP:FP: Initializing FabricTable from persistent storage [1739188314.468199][25020:25020] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1739188314.468363][25020:25020] CHIP:DMG: AccessControl: initializing [1739188314.468420][25020:25020] CHIP:DMG: Examples::AccessControlDelegate::Init [1739188314.468496][25020:25020] CHIP:DMG: AccessControl: setting [1739188314.468546][25020:25020] CHIP:DMG: DefaultAclStorage: initializing [1739188314.468592][25020:25020] CHIP:DMG: DefaultAclStorage: 0 entries loaded [1739188314.468655][25020:25020] CHIP:IN: UDP::Init bind&listen port=5540 [1739188314.469080][25020:25020] CHIP:IN: UDP::Init bound to port=5540 [1739188314.469144][25020:25020] CHIP:IN: BLEBase::Init - setting/overriding transport [1739188314.469339][25020:25020] CHIP:IN: TCP server listening on port 5540 for incoming connections [1739188314.469396][25020:25020] CHIP:IN: TransportMgr initialized [1739188314.487481][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188314.507376][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188314.539361][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188314.539529][25020:25020] CHIP:DMG: Ember attribute persistence requires setting up [1739188314.539587][25020:25020] CHIP:ZCL: Using ZAP configuration... [1739188314.539817][25020:25020] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1739188314.539932][25020:25020] CHIP:DMG: AccessControlCluster: initializing [1739188314.539987][25020:25020] CHIP:ZCL: Initiating Admin Commissioning cluster. [1739188314.540121][25020:25020] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot [1739188314.540188][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to 214a3130 [1739188314.540344][25020:25020] CHIP:EVL: LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Epoch timestamp: 0x00000194EFB3A1AC [1739188314.540434][25020:25020] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 558a75d0 [1739188314.540498][25020:25020] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 558a75d1 [1739188314.540827][25020:25020] CHIP:IN: SecureSession[0xaaaaeef68610]: Allocated Type:1 LSID:54724 [1739188314.540910][25020:25020] CHIP:SC: Assigned local session key ID 54724 [1739188314.541025][25020:25020] CHIP:SC: Waiting for PBKDF param request [1739188314.541105][25020:25020] CHIP:DIS: Updating services using commissioning mode 1 [1739188314.564640][25020:25020] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188314.605921][25020:25020] CHIP:DL: Using WiFi MAC for hostname [1739188314.606151][25020:25020] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188314.606262][25020:25020] CHIP:DIS: Responding with _matterc._udp.local [1739188314.606322][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.606375][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.606426][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.606497][25020:25020] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188314.606558][25020:25020] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188314.606617][25020:25020] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188314.606676][25020:25020] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188314.606748][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.606799][25020:25020] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B1AC1D44F754B5C5. [1739188314.653760][25020:25020] CHIP:DIS: mDNS service published: _matterc._udp [1739188314.653863][25020:25020] CHIP:DIS: Updating services using commissioning mode 1 [1739188314.679633][25020:25020] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188314.773811][25020:25020] CHIP:DL: Using WiFi MAC for hostname [1739188314.774040][25020:25020] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188314.774151][25020:25020] CHIP:DIS: Responding with _matterc._udp.local [1739188314.774210][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.774263][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.774314][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.774375][25020:25020] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188314.774449][25020:25020] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188314.774509][25020:25020] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188314.774568][25020:25020] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188314.774639][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.774689][25020:25020] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B1AC1D44F754B5C5. [1739188314.820709][25020:25020] CHIP:DIS: mDNS service published: _matterc._udp [1739188314.820823][25020:25020] CHIP:IN: CASE Server enabling CASE session setups [1739188314.821345][25020:25020] CHIP:IN: SecureSession[0xaaaaeef68bc0]: Allocated Type:2 LSID:54725 [1739188314.821443][25020:25020] CHIP:SC: Allocated SecureSession (0xaaaaeef68bc0) - waiting for Sigma1 msg [1739188314.821511][25020:25020] CHIP:SVR: Joining Multicast groups [1739188314.821574][25020:25020] CHIP:ZCL: Emitting StartUp event [1739188314.821719][25020:25020] CHIP:EVL: LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Epoch timestamp: 0x00000194EFB3A2C5 [1739188314.821794][25020:25020] CHIP:SVR: Server initialization complete [1739188314.821873][25020:25020] CHIP:SVR: Server Listening... [1739188314.821923][25020:25020] CHIP:DL: Device Configuration: [1739188314.822029][25020:25020] CHIP:DL: Serial Number: TEST_SN [1739188314.822137][25020:25020] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1739188314.822222][25020:25020] CHIP:DL: Product Id: 32769 (0x8001) [1739188314.822276][25020:25020] CHIP:DL: Product Name: TEST_PRODUCT [1739188314.822344][25020:25020] CHIP:DL: Hardware Version: 0 [1739188314.822397][25020:25020] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1739188314.822444][25020:25020] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00) [1739188314.822511][25020:25020] CHIP:DL: Manufacturing Date: (not set) [1739188314.822562][25020:25020] CHIP:DL: Device Type: 65535 (0xFFFF) [1739188314.822636][25020:25020] CHIP:SVR: SetupQRCode: [MT:-24J08M.00KA0648G00] [1739188314.822696][25020:25020] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1739188314.822742][25020:25020] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J08M.00KA0648G00 [1739188314.822819][25020:25020] CHIP:SVR: Manual pairing code: [749701123365521327694] [1739188314.852228][25020:25021] CHIP:DL: CREATE service object at /chipoble/61bc/service [1739188314.853333][25020:25021] CHIP:DL: Create characteristic object at /chipoble/61bc/service/c1 [1739188314.854164][25020:25021] CHIP:DL: Create characteristic object at /chipoble/61bc/service/c2 [1739188314.854561][25020:25021] CHIP:DL: CHIP BTP C1 /chipoble/61bc/service [1739188314.854627][25020:25021] CHIP:DL: CHIP BTP C2 /chipoble/61bc/service [1739188314.854678][25020:25021] CHIP:DL: CHIP_ENABLE_ADDITIONAL_DATA_ADVERTISING is FALSE [1739188314.855616][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1739188314.855708][25020:25020] CHIP:DIS: Updating services using commissioning mode 1 [1739188314.870413][25020:25021] CHIP:DL: GATT application registered successfully [1739188314.882546][25020:25020] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188314.975662][25020:25020] CHIP:DL: Using WiFi MAC for hostname [1739188314.975901][25020:25020] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0 [1739188314.976009][25020:25020] CHIP:DIS: Responding with _matterc._udp.local [1739188314.976069][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.976121][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.976171][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188314.976232][25020:25020] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1739188314.976287][25020:25020] CHIP:DIS: Responding with _S15._sub._matterc._udp.local [1739188314.976346][25020:25020] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local [1739188314.976404][25020:25020] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1739188314.976475][25020:25020] CHIP:DIS: Responding with B1AC1D44F754B5C5._matterc._udp.local [1739188314.976525][25020:25020] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B1AC1D44F754B5C5. [1739188315.022265][25020:25020] CHIP:DIS: mDNS service published: _matterc._udp [1739188315.022377][25020:25020] CHIP:DL: Long dispatch time: 167 ms, for event type 32786 [1739188315.022452][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 32790 [1739188315.023843][25020:25020] CHIP:IM: No subscriptions to resume [1739188315.023915][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 16394 [1739188315.024179][25020:25021] CHIP:DL: Create BLE adv object at /chipoble/61bc/advertising [1739188315.026174][25020:25020] CHIP:DL: SET service data to {'fff6': <[byte 0x00, 0x00, 0x0f, 0xf1, 0xff, 0x01, 0x80, 0x00]>} [1739188315.045678][25020:25021] CHIP:DL: BLE advertisement started successfully [1739188315.047392][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 16395 [1739188317.880656][25020:25020] CHIP:EM: >>> [E:31350r S:0 M:251017302] (U) Msg RX from 0:03C9A37656843DF2 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98) [1739188317.880792][25020:25020] CHIP:EM: Handling via exchange: 31350r, Delegate: 0xaaaacc5b19b8 [1739188317.880917][25020:25020] CHIP:SC: Received PBKDF param request [1739188317.881078][25020:25020] CHIP:SC: Peer assigned session ID 21998 [1739188317.881144][25020:25020] CHIP:SC: Found MRP parameters in the message [1739188317.881910][25020:25020] CHIP:EM: <<< [E:31350r S:0 M:91756202 (Ack:251017302)] (U) Msg TX from 0000000000000000 to 0:03C9A37656843DF2 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:174) [1739188317.882258][25020:25020] CHIP:EM: ??1 [E:31350r S:0 M:91756202] (U) Msg Retransmission to 0:0000000000000000 scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000] [1739188317.882359][25020:25020] CHIP:SC: Sent PBKDF param response [1739188317.882425][25020:25020] CHIP:SVR: Commissioning session establishment step started [1739188317.940065][25020:25020] CHIP:EM: >>> [E:31350r S:0 M:251017303 (Ack:91756202)] (U) Msg RX from 0:03C9A37656843DF2 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:96) [1739188317.940163][25020:25020] CHIP:EM: Found matching exchange: 31350r, Delegate: 0xaaaacc5b19b8 [1739188317.940248][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:91756202 from Retrans Table on exchange 31350r [1739188317.940367][25020:25020] CHIP:SC: Received spake2p msg1 [1739188317.945787][25020:25020] CHIP:EM: <<< [E:31350r S:0 M:91756203 (Ack:251017303)] (U) Msg TX from 0000000000000000 to 0:03C9A37656843DF2 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:131) [1739188317.946282][25020:25020] CHIP:EM: ??1 [E:31350r S:0 M:91756203] (U) Msg Retransmission to 0:0000000000000000 scheduled for 342ms from now [State:Active II:500 AI:300 AT:4000] [1739188317.946392][25020:25020] CHIP:SC: Sent spake2p msg2 [1739188318.016753][25020:25020] CHIP:EM: >>> [E:31350r S:0 M:251017304 (Ack:91756203)] (U) Msg RX from 0:03C9A37656843DF2 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:63) [1739188318.016858][25020:25020] CHIP:EM: Found matching exchange: 31350r, Delegate: 0xaaaacc5b19b8 [1739188318.016978][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:91756203 from Retrans Table on exchange 31350r [1739188318.017101][25020:25020] CHIP:SC: Received spake2p msg3 [1739188318.017329][25020:25020] CHIP:SC: Sending status report. Protocol code 0, exchange 31350 [1739188318.017646][25020:25020] CHIP:EM: <<< [E:31350r S:0 M:91756204 (Ack:251017304)] (U) Msg TX from 0000000000000000 to 0:03C9A37656843DF2 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:40 (SecureChannel:StatusReport) (B:34) [1739188318.017981][25020:25020] CHIP:EM: ??1 [E:31350r S:0 M:91756204] (U) Msg Retransmission to 0:0000000000000000 scheduled for 370ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.018441][25020:25020] CHIP:SC: SecureSession[0xaaaaeef68610, LSID:54724]: State change 'kEstablishing' --> 'kActive' [1739188318.018522][25020:25020] CHIP:IN: SecureSession[0xaaaaeef68610]: Activated - Type:1 LSID:54724 [1739188318.018573][25020:25020] CHIP:IN: New secure session activated for device , LSID:54724 PSID:21998! [1739188318.018648][25020:25020] CHIP:SVR: Commissioning completed session establishment step [1739188318.018760][25020:25020] CHIP:DIS: Updating services using commissioning mode 0 [1739188318.043877][25020:25020] CHIP:DIS: CHIP minimal mDNS started advertising. [1739188318.135001][25020:25020] CHIP:SVR: Device completed Rendezvous process [1739188318.135139][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 32792 [1739188318.136480][25020:25020] CHIP:EM: >>> [E:31351r S:54724 M:191657351] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:134) [1739188318.136622][25020:25020] CHIP:EM: Handling via exchange: 31351r, Delegate: 0xaaaacc5ae5c8 [1739188318.136720][25020:25020] CHIP:IM: Received Read request [1739188318.136868][25020:25020] CHIP:DMG: ReadRequestMessage = [1739188318.137018][25020:25020] CHIP:DMG: { [1739188318.137079][25020:25020] CHIP:DMG: AttributePathIBs = [1739188318.137145][25020:25020] CHIP:DMG: [ [1739188318.137203][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.137268][25020:25020] CHIP:DMG: { [1739188318.137334][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.137418][25020:25020] CHIP:DMG: Cluster = 0x30, [1739188318.137493][25020:25020] CHIP:DMG: Attribute = 0x0000_0004, [1739188318.137565][25020:25020] CHIP:DMG: } [1739188318.137637][25020:25020] CHIP:DMG: [1739188318.137698][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.137779][25020:25020] CHIP:DMG: { [1739188318.137843][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.137935][25020:25020] CHIP:DMG: Cluster = 0x30, [1739188318.138003][25020:25020] CHIP:DMG: Attribute = 0x0000_0000, [1739188318.138078][25020:25020] CHIP:DMG: } [1739188318.138159][25020:25020] CHIP:DMG: [1739188318.138231][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.138306][25020:25020] CHIP:DMG: { [1739188318.138383][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.138458][25020:25020] CHIP:DMG: Cluster = 0x30, [1739188318.138551][25020:25020] CHIP:DMG: Attribute = 0x0000_0001, [1739188318.138634][25020:25020] CHIP:DMG: } [1739188318.138713][25020:25020] CHIP:DMG: [1739188318.138779][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.138860][25020:25020] CHIP:DMG: { [1739188318.138937][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.139021][25020:25020] CHIP:DMG: Cluster = 0x30, [1739188318.139112][25020:25020] CHIP:DMG: Attribute = 0x0000_0002, [1739188318.139173][25020:25020] CHIP:DMG: } [1739188318.139307][25020:25020] CHIP:DMG: [1739188318.139374][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.139437][25020:25020] CHIP:DMG: { [1739188318.139501][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.139623][25020:25020] CHIP:DMG: Cluster = 0x30, [1739188318.139699][25020:25020] CHIP:DMG: Attribute = 0x0000_0003, [1739188318.139763][25020:25020] CHIP:DMG: } [1739188318.139833][25020:25020] CHIP:DMG: [1739188318.139893][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.139956][25020:25020] CHIP:DMG: { [1739188318.140019][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.140087][25020:25020] CHIP:DMG: Cluster = 0x28, [1739188318.140167][25020:25020] CHIP:DMG: Attribute = 0x0000_0002, [1739188318.140287][25020:25020] CHIP:DMG: } [1739188318.140364][25020:25020] CHIP:DMG: [1739188318.140425][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.140489][25020:25020] CHIP:DMG: { [1739188318.140553][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.140634][25020:25020] CHIP:DMG: Cluster = 0x28, [1739188318.140763][25020:25020] CHIP:DMG: Attribute = 0x0000_0004, [1739188318.141045][25020:25020] CHIP:DMG: } [1739188318.141130][25020:25020] CHIP:DMG: [1739188318.141192][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.141255][25020:25020] CHIP:DMG: { [1739188318.141468][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.141548][25020:25020] CHIP:DMG: Cluster = 0x38, [1739188318.141662][25020:25020] CHIP:DMG: } [1739188318.141891][25020:25020] CHIP:DMG: [1739188318.142129][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.142266][25020:25020] CHIP:DMG: { [1739188318.142436][25020:25020] CHIP:DMG: Cluster = 0x31, [1739188318.142590][25020:25020] CHIP:DMG: Attribute = 0x0000_FFFC, [1739188318.142730][25020:25020] CHIP:DMG: } [1739188318.142872][25020:25020] CHIP:DMG: [1739188318.143005][25020:25020] CHIP:DMG: ], [1739188318.141988][25020:25021] CHIP:DL: BLE advertisement stopped successfully [1739188318.143197][25020:25020] CHIP:DMG: [1739188318.143418][25020:25020] CHIP:DMG: isFabricFiltered = false, [1739188318.143474][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.143530][25020:25020] CHIP:DMG: }, [1739188318.144527][25020:25020] CHIP:DMG: IM RH moving to [CanStartReporting] [1739188318.146301][25020:25020] CHIP:DL: HandlePlatformSpecificBLEEvent 16396 [1739188318.146400][25020:25020] CHIP:DL: CHIPoBLE advertising stopped [1739188318.146616][25020:25020] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000 [1739188318.146766][25020:25020] CHIP:DMG: Cluster 31, Attribute fffc is dirty [1739188318.146867][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v r=r [1739188318.146929][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.146981][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0x0 AttributeId=0x0000_FFFC (expanded=1) [1739188318.147174][25020:25020] CHIP:DMG: Cluster 28, Attribute 4 is dirty [1739188318.147273][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v r=r [1739188318.147332][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.147381][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0x0 AttributeId=0x0000_0004 (expanded=0) [1739188318.147631][25020:25020] CHIP:DMG: Cluster 28, Attribute 2 is dirty [1739188318.147733][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v r=r [1739188318.147793][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.147842][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188318.148023][25020:25020] CHIP:DMG: Cluster 30, Attribute 3 is dirty [1739188318.148116][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188318.148174][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.148223][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0003 (expanded=0) [1739188318.148407][25020:25020] CHIP:DMG: Cluster 30, Attribute 2 is dirty [1739188318.148500][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188318.148558][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.148607][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188318.148778][25020:25020] CHIP:DMG: Cluster 30, Attribute 1 is dirty [1739188318.148869][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188318.148927][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.149017][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0001 (expanded=0) [1739188318.149168][25020:25020] CHIP:DMG: Cluster 30, Attribute 0 is dirty [1739188318.149260][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188318.149318][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.149366][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0000 (expanded=0) [1739188318.149513][25020:25020] CHIP:DMG: Cluster 30, Attribute 4 is dirty [1739188318.149602][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v r=r [1739188318.149658][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.149706][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0x0 AttributeId=0x0000_0004 (expanded=0) [1739188318.149837][25020:25020] CHIP:DMG: Sending report (payload has 227 bytes)... [1739188318.150326][25020:25020] CHIP:EM: <<< [E:31351r S:54724 M:110786434 (Ack:191657351)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:05 (IM:ReportData) (B:261) [1739188318.150688][25020:25020] CHIP:EM: ??1 [E:31351r S:54724 M:110786434] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 333ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.150810][25020:25020] CHIP:DMG: OnReportConfirm: NumReports = 0 [1739188318.150871][25020:25020] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1739188318.150923][25020:25020] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1739188318.152412][25020:25020] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188318.152693][25020:25020] CHIP:EM: >>> [E:31350r S:0 M:251017305 (Ack:91756204)] (U) Msg RX from 0:03C9A37656843DF2 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [1739188318.152765][25020:25020] CHIP:EM: Found matching exchange: 31350r, Delegate: (nil) [1739188318.152850][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:91756204 from Retrans Table on exchange 31350r [1739188318.219714][25020:25020] CHIP:EM: >>> [E:31352r S:54724 M:191657352] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:103) [1739188318.219844][25020:25020] CHIP:EM: Handling via exchange: 31352r, Delegate: 0xaaaacc5ae5c8 [1739188318.219942][25020:25020] CHIP:IM: Received Read request [1739188318.220073][25020:25020] CHIP:DMG: ReadRequestMessage = [1739188318.220133][25020:25020] CHIP:DMG: { [1739188318.220183][25020:25020] CHIP:DMG: AttributePathIBs = [1739188318.220244][25020:25020] CHIP:DMG: [ [1739188318.220301][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.220385][25020:25020] CHIP:DMG: { [1739188318.220456][25020:25020] CHIP:DMG: Cluster = 0x31, [1739188318.220595][25020:25020] CHIP:DMG: Attribute = 0x0000_0003, [1739188318.220730][25020:25020] CHIP:DMG: } [1739188318.220806][25020:25020] CHIP:DMG: [1739188318.220874][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.220980][25020:25020] CHIP:DMG: { [1739188318.221050][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.221119][25020:25020] CHIP:DMG: Cluster = 0x46, [1739188318.221249][25020:25020] CHIP:DMG: Attribute = 0x0000_0006, [1739188318.221377][25020:25020] CHIP:DMG: } [1739188318.221451][25020:25020] CHIP:DMG: [1739188318.221513][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.221640][25020:25020] CHIP:DMG: { [1739188318.221709][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.221840][25020:25020] CHIP:DMG: Cluster = 0x46, [1739188318.221920][25020:25020] CHIP:DMG: Attribute = 0x0000_0007, [1739188318.222039][25020:25020] CHIP:DMG: } [1739188318.222175][25020:25020] CHIP:DMG: [1739188318.222239][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.222365][25020:25020] CHIP:DMG: { [1739188318.222431][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.222561][25020:25020] CHIP:DMG: Cluster = 0x46, [1739188318.222633][25020:25020] CHIP:DMG: Attribute = 0x0000_0000, [1739188318.222705][25020:25020] CHIP:DMG: } [1739188318.222774][25020:25020] CHIP:DMG: [1739188318.222885][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.222952][25020:25020] CHIP:DMG: { [1739188318.223022][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.223143][25020:25020] CHIP:DMG: Cluster = 0x46, [1739188318.223223][25020:25020] CHIP:DMG: Attribute = 0x0000_0001, [1739188318.223287][25020:25020] CHIP:DMG: } [1739188318.223351][25020:25020] CHIP:DMG: [1739188318.223409][25020:25020] CHIP:DMG: AttributePathIB = [1739188318.223471][25020:25020] CHIP:DMG: { [1739188318.223587][25020:25020] CHIP:DMG: Endpoint = 0x0, [1739188318.223659][25020:25020] CHIP:DMG: Cluster = 0x46, [1739188318.223789][25020:25020] CHIP:DMG: Attribute = 0x0000_0002, [1739188318.223863][25020:25020] CHIP:DMG: } [1739188318.223981][25020:25020] CHIP:DMG: [1739188318.224045][25020:25020] CHIP:DMG: ], [1739188318.224139][25020:25020] CHIP:DMG: [1739188318.224200][25020:25020] CHIP:DMG: isFabricFiltered = false, [1739188318.224258][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.224312][25020:25020] CHIP:DMG: }, [1739188318.225019][25020:25020] CHIP:DMG: IM RH moving to [CanStartReporting] [1739188318.225281][25020:25020] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000 [1739188318.225406][25020:25020] CHIP:DMG: Cluster 46, Attribute 2 is dirty [1739188318.225477][25020:25020] CHIP:DMG: Read request on unknown cluster - no data version available [1739188318.225543][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188318.225601][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.225653][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0002 (expanded=0) [1739188318.225739][25020:25020] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188318.225812][25020:25020] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188318.225949][25020:25020] CHIP:DMG: Cluster 46, Attribute 1 is dirty [1739188318.226019][25020:25020] CHIP:DMG: Read request on unknown cluster - no data version available [1739188318.226077][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188318.226132][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.226180][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0001 (expanded=0) [1739188318.226248][25020:25020] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188318.226313][25020:25020] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188318.226428][25020:25020] CHIP:DMG: Cluster 46, Attribute 0 is dirty [1739188318.226496][25020:25020] CHIP:DMG: Read request on unknown cluster - no data version available [1739188318.226552][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188318.226607][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.226654][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0000 (expanded=0) [1739188318.226720][25020:25020] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188318.226783][25020:25020] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188318.226896][25020:25020] CHIP:DMG: Cluster 46, Attribute 7 is dirty [1739188318.226964][25020:25020] CHIP:DMG: Read request on unknown cluster - no data version available [1739188318.227021][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188318.227074][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.227121][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0007 (expanded=0) [1739188318.227186][25020:25020] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188318.227249][25020:25020] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188318.227358][25020:25020] CHIP:DMG: Cluster 46, Attribute 6 is dirty [1739188318.227426][25020:25020] CHIP:DMG: Read request on unknown cluster - no data version available [1739188318.227483][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0046 e=0 p=v r=r [1739188318.227538][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.227585][25020:25020] CHIP:DMG: Reading attribute: Cluster=0x0000_0046 Endpoint=0x0 AttributeId=0x0000_0006 (expanded=0) [1739188318.227650][25020:25020] CHIP:DMG: Failed to read attribute: UNSUPPORTED_CLUSTER(195) [1739188318.227714][25020:25020] CHIP:DMG: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = src/app/data-model-provider/ActionReturnStatus.cpp:104: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER) [1739188318.227888][25020:25020] CHIP:DMG: Sending report (payload has 125 bytes)... [1739188318.228352][25020:25020] CHIP:EM: <<< [E:31352r S:54724 M:110786435 (Ack:191657352)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:05 (IM:ReportData) (B:159) [1739188318.228724][25020:25020] CHIP:EM: ??1 [E:31352r S:54724 M:110786435] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 387ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.229185][25020:25020] CHIP:DMG: OnReportConfirm: NumReports = 0 [1739188318.229256][25020:25020] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1739188318.229308][25020:25020] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1739188318.230775][25020:25020] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1739188318.231104][25020:25020] CHIP:EM: >>> [E:31351r S:54724 M:191657353 (Ack:110786434)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.231320][25020:25020] CHIP:EM: Found matching exchange: 31351r, Delegate: (nil) [1739188318.231411][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786434 from Retrans Table on exchange 31351r [1739188318.261819][25020:25020] CHIP:EM: >>> [E:31353r S:54724 M:191657354] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65) [1739188318.261937][25020:25020] CHIP:EM: Handling via exchange: 31353r, Delegate: 0xaaaacc5ae5c8 [1739188318.262110][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.262174][25020:25020] CHIP:DMG: { [1739188318.262228][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.262290][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.262347][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.262424][25020:25020] CHIP:DMG: [ [1739188318.262481][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.262545][25020:25020] CHIP:DMG: { [1739188318.262606][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.262686][25020:25020] CHIP:DMG: { [1739188318.262757][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.262828][25020:25020] CHIP:DMG: ClusterId = 0x30, [1739188318.262904][25020:25020] CHIP:DMG: CommandId = 0x0, [1739188318.262976][25020:25020] CHIP:DMG: }, [1739188318.263048][25020:25020] CHIP:DMG: [1739188318.263106][25020:25020] CHIP:DMG: CommandFields = [1739188318.263180][25020:25020] CHIP:DMG: { [1739188318.263254][25020:25020] CHIP:DMG: 0x0 = 60 (unsigned), [1739188318.263343][25020:25020] CHIP:DMG: 0x1 = 3 (unsigned), [1739188318.263442][25020:25020] CHIP:DMG: }, [1739188318.263512][25020:25020] CHIP:DMG: }, [1739188318.263588][25020:25020] CHIP:DMG: [1739188318.263644][25020:25020] CHIP:DMG: ], [1739188318.263718][25020:25020] CHIP:DMG: [1739188318.263774][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.263829][25020:25020] CHIP:DMG: }, [1739188318.264138][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a r=i [1739188318.264204][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.264267][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1739188318.264352][25020:25020] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s) [1739188318.264450][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 424fe51c [1739188318.264554][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.264613][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.264677][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.264744][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.264845][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.264901][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.265005][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.265404][25020:25020] CHIP:EM: <<< [E:31353r S:54724 M:110786436 (Ack:191657354)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188318.265749][25020:25020] CHIP:EM: ??1 [E:31353r S:54724 M:110786436] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 410ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.265853][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.266263][25020:25020] CHIP:EM: >>> [E:31352r S:54724 M:191657355 (Ack:110786435)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.266336][25020:25020] CHIP:EM: Found matching exchange: 31352r, Delegate: (nil) [1739188318.266419][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786435 from Retrans Table on exchange 31352r [1739188318.281142][25020:25020] CHIP:EM: >>> [E:31354r S:54724 M:191657356] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70) [1739188318.281245][25020:25020] CHIP:EM: Handling via exchange: 31354r, Delegate: 0xaaaacc5ae5c8 [1739188318.281402][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.281464][25020:25020] CHIP:DMG: { [1739188318.281518][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.281579][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.281636][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.281715][25020:25020] CHIP:DMG: [ [1739188318.281771][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.281835][25020:25020] CHIP:DMG: { [1739188318.281895][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.281967][25020:25020] CHIP:DMG: { [1739188318.282037][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.282113][25020:25020] CHIP:DMG: ClusterId = 0x30, [1739188318.282187][25020:25020] CHIP:DMG: CommandId = 0x2, [1739188318.282258][25020:25020] CHIP:DMG: }, [1739188318.282331][25020:25020] CHIP:DMG: [1739188318.282394][25020:25020] CHIP:DMG: CommandFields = [1739188318.282463][25020:25020] CHIP:DMG: { [1739188318.282533][25020:25020] CHIP:DMG: 0x0 = 0 (unsigned), [1739188318.282615][25020:25020] CHIP:DMG: 0x1 = "XX" (2 chars), [1739188318.282692][25020:25020] CHIP:DMG: 0x2 = 4 (unsigned), [1739188318.282770][25020:25020] CHIP:DMG: }, [1739188318.282836][25020:25020] CHIP:DMG: }, [1739188318.282912][25020:25020] CHIP:DMG: [1739188318.282968][25020:25020] CHIP:DMG: ], [1739188318.283043][25020:25020] CHIP:DMG: [1739188318.283098][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.283153][25020:25020] CHIP:DMG: }, [1739188318.283460][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a r=i [1739188318.283530][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.283592][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [1739188318.291513][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188318.291661][25020:25020] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1739188318.311317][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_config.ini [1739188318.311456][25020:25020] CHIP:DL: NVS set: chip-config/country-code = "XX" [1739188318.311542][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 424fe51d [1739188318.311668][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.311727][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.311793][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.311863][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.311985][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.312043][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.312108][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.312526][25020:25020] CHIP:EM: <<< [E:31354r S:54724 M:110786437 (Ack:191657356)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188318.312895][25020:25020] CHIP:EM: ??1 [E:31354r S:54724 M:110786437] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 353ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.313108][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.313567][25020:25020] CHIP:EM: >>> [E:31353r S:54724 M:191657357 (Ack:110786436)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.313642][25020:25020] CHIP:EM: Found matching exchange: 31353r, Delegate: (nil) [1739188318.313726][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786436 from Retrans Table on exchange 31353r [1739188318.337392][25020:25020] CHIP:EM: >>> [E:31355r S:54724 M:191657358] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) [1739188318.337501][25020:25020] CHIP:EM: Handling via exchange: 31355r, Delegate: 0xaaaacc5ae5c8 [1739188318.337664][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.337726][25020:25020] CHIP:DMG: { [1739188318.337778][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.337839][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.337895][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.337976][25020:25020] CHIP:DMG: [ [1739188318.338033][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.338097][25020:25020] CHIP:DMG: { [1739188318.338157][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.338228][25020:25020] CHIP:DMG: { [1739188318.338303][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.338379][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.338454][25020:25020] CHIP:DMG: CommandId = 0x2, [1739188318.338525][25020:25020] CHIP:DMG: }, [1739188318.338598][25020:25020] CHIP:DMG: [1739188318.338660][25020:25020] CHIP:DMG: CommandFields = [1739188318.338730][25020:25020] CHIP:DMG: { [1739188318.338803][25020:25020] CHIP:DMG: 0x0 = 2 (unsigned), [1739188318.338878][25020:25020] CHIP:DMG: }, [1739188318.338943][25020:25020] CHIP:DMG: }, [1739188318.339011][25020:25020] CHIP:DMG: [1739188318.339061][25020:25020] CHIP:DMG: ], [1739188318.339142][25020:25020] CHIP:DMG: [1739188318.339203][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.339258][25020:25020] CHIP:DMG: }, [1739188318.339576][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.339643][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.339705][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1739188318.339788][25020:25020] CHIP:ZCL: OpCreds: Certificate Chain request received for PAI [1739188318.339891][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.339948][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.340011][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.340076][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.340171][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.340227][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.340288][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.340724][25020:25020] CHIP:EM: <<< [E:31355r S:54724 M:110786438 (Ack:191657358)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:531) [1739188318.341145][25020:25020] CHIP:EM: ??1 [E:31355r S:54724 M:110786438] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 399ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.341258][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.341673][25020:25020] CHIP:EM: >>> [E:31354r S:54724 M:191657359 (Ack:110786437)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.341746][25020:25020] CHIP:EM: Found matching exchange: 31354r, Delegate: (nil) [1739188318.341828][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786437 from Retrans Table on exchange 31354r [1739188318.361109][25020:25020] CHIP:EM: >>> [E:31356r S:54724 M:191657360] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62) [1739188318.361205][25020:25020] CHIP:EM: Handling via exchange: 31356r, Delegate: 0xaaaacc5ae5c8 [1739188318.361350][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.361411][25020:25020] CHIP:DMG: { [1739188318.361464][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.361525][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.361582][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.361657][25020:25020] CHIP:DMG: [ [1739188318.361713][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.361777][25020:25020] CHIP:DMG: { [1739188318.361837][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.361909][25020:25020] CHIP:DMG: { [1739188318.361982][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.362062][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.362137][25020:25020] CHIP:DMG: CommandId = 0x2, [1739188318.362208][25020:25020] CHIP:DMG: }, [1739188318.362282][25020:25020] CHIP:DMG: [1739188318.362344][25020:25020] CHIP:DMG: CommandFields = [1739188318.362413][25020:25020] CHIP:DMG: { [1739188318.362486][25020:25020] CHIP:DMG: 0x0 = 1 (unsigned), [1739188318.362561][25020:25020] CHIP:DMG: }, [1739188318.362627][25020:25020] CHIP:DMG: }, [1739188318.362698][25020:25020] CHIP:DMG: [1739188318.362753][25020:25020] CHIP:DMG: ], [1739188318.362825][25020:25020] CHIP:DMG: [1739188318.362880][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.362935][25020:25020] CHIP:DMG: }, [1739188318.363225][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.363289][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.363351][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1739188318.363433][25020:25020] CHIP:ZCL: OpCreds: Certificate Chain request received for DAC [1739188318.363527][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.363584][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.363647][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.363711][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.363807][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.363862][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.363924][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.364331][25020:25020] CHIP:EM: <<< [E:31356r S:54724 M:110786439 (Ack:191657360)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:559) [1739188318.364643][25020:25020] CHIP:EM: ??1 [E:31356r S:54724 M:110786439] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 368ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.364743][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.365192][25020:25020] CHIP:EM: >>> [E:31355r S:54724 M:191657361 (Ack:110786438)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.365265][25020:25020] CHIP:EM: Found matching exchange: 31355r, Delegate: (nil) [1739188318.365347][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786438 from Retrans Table on exchange 31355r [1739188318.384353][25020:25020] CHIP:EM: >>> [E:31357r S:54724 M:191657362] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) [1739188318.384478][25020:25020] CHIP:EM: Handling via exchange: 31357r, Delegate: 0xaaaacc5ae5c8 [1739188318.384652][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.384716][25020:25020] CHIP:DMG: { [1739188318.384771][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.384834][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.384968][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.385054][25020:25020] CHIP:DMG: [ [1739188318.385112][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.385200][25020:25020] CHIP:DMG: { [1739188318.385260][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.385357][25020:25020] CHIP:DMG: { [1739188318.385430][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.385508][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.385583][25020:25020] CHIP:DMG: CommandId = 0x0, [1739188318.385673][25020:25020] CHIP:DMG: }, [1739188318.385749][25020:25020] CHIP:DMG: [1739188318.385834][25020:25020] CHIP:DMG: CommandFields = [1739188318.385906][25020:25020] CHIP:DMG: { [1739188318.385976][25020:25020] CHIP:DMG: 0x0 = [ [1739188318.386096][25020:25020] CHIP:DMG: 0xd2, 0x0d, 0xda, 0xef, 0xf4, 0x34, 0x88, 0x6b, 0x89, 0x85, 0x58, 0x3e, 0x1b, 0x0f, 0x95, 0xd8, 0xf7, 0x73, 0x5b, 0xab, 0x68, 0xd5, 0x53, 0xe4, 0x89, 0x73, 0x2c, 0xe8, 0x6e, 0x6d, 0xc2, 0x32, [1739188318.386205][25020:25020] CHIP:DMG: ] (32 bytes) [1739188318.386321][25020:25020] CHIP:DMG: }, [1739188318.386395][25020:25020] CHIP:DMG: }, [1739188318.386492][25020:25020] CHIP:DMG: [1739188318.386549][25020:25020] CHIP:DMG: ], [1739188318.386624][25020:25020] CHIP:DMG: [1739188318.386701][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.386757][25020:25020] CHIP:DMG: }, [1739188318.387104][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.387169][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.387231][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [1739188318.387320][25020:25020] CHIP:ZCL: OpCreds: Received an AttestationRequest command [1739188318.387760][25020:25020] CHIP:EM: <<< [E:31357r S:54724 M:110786440 (Ack:191657362)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.388030][25020:25020] CHIP:EM: Flushed pending ack for MessageCounter:191657362 on exchange 31357r [1739188318.389103][25020:25020] CHIP:ZCL: OpCreds: AttestationRequest successful. [1739188318.389235][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.389294][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.389360][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.389427][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.389568][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.389628][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.389692][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.390214][25020:25020] CHIP:EM: <<< [E:31357r S:54724 M:110786441 (Ack:191657362)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:718) [1739188318.390543][25020:25020] CHIP:EM: ??1 [E:31357r S:54724 M:110786441] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 402ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.390679][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.391136][25020:25020] CHIP:EM: >>> [E:31356r S:54724 M:191657363 (Ack:110786439)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.391210][25020:25020] CHIP:EM: Found matching exchange: 31356r, Delegate: (nil) [1739188318.391293][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786439 from Retrans Table on exchange 31356r [1739188318.470907][25020:25020] CHIP:EM: >>> [E:31358r S:54724 M:191657364] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94) [1739188318.471023][25020:25020] CHIP:EM: Handling via exchange: 31358r, Delegate: 0xaaaacc5ae5c8 [1739188318.471189][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.471251][25020:25020] CHIP:DMG: { [1739188318.471304][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.471365][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.471421][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.471495][25020:25020] CHIP:DMG: [ [1739188318.471552][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.471616][25020:25020] CHIP:DMG: { [1739188318.471676][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.471743][25020:25020] CHIP:DMG: { [1739188318.471820][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.471896][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.471970][25020:25020] CHIP:DMG: CommandId = 0x4, [1739188318.472041][25020:25020] CHIP:DMG: }, [1739188318.472115][25020:25020] CHIP:DMG: [1739188318.472178][25020:25020] CHIP:DMG: CommandFields = [1739188318.472244][25020:25020] CHIP:DMG: { [1739188318.472316][25020:25020] CHIP:DMG: 0x0 = [ [1739188318.472491][25020:25020] CHIP:DMG: 0xad, 0x5c, 0x93, 0xb9, 0x67, 0xaf, 0x0b, 0x83, 0x5d, 0xea, 0x18, 0xd2, 0x6a, 0xbf, 0xab, 0xa3, 0x4b, 0xf0, 0x5c, 0x28, 0x1f, 0xc9, 0x3d, 0x55, 0xec, 0xcf, 0x7a, 0x2a, 0xfc, 0x53, 0x1a, 0x72, [1739188318.472599][25020:25020] CHIP:DMG: ] (32 bytes) [1739188318.472692][25020:25020] CHIP:DMG: }, [1739188318.472757][25020:25020] CHIP:DMG: }, [1739188318.472830][25020:25020] CHIP:DMG: [1739188318.472886][25020:25020] CHIP:DMG: ], [1739188318.473025][25020:25020] CHIP:DMG: [1739188318.473086][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.473142][25020:25020] CHIP:DMG: }, [1739188318.473443][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.473507][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.473568][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 [1739188318.473654][25020:25020] CHIP:ZCL: OpCreds: Received a CSRRequest command [1739188318.473716][25020:25020] CHIP:ZCL: OpCreds: Finding fabric with fabricIndex 0x0 [1739188318.474093][25020:25020] CHIP:EM: <<< [E:31358r S:54724 M:110786442 (Ack:191657364)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.474361][25020:25020] CHIP:EM: Flushed pending ack for MessageCounter:191657364 on exchange 31358r [1739188318.477411][25020:25020] CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded [1739188318.478181][25020:25020] CHIP:ZCL: OpCreds: CSRRequest successful. [1739188318.478302][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.478362][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.478426][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.478531][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.478641][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.478701][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.478763][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.479208][25020:25020] CHIP:EM: <<< [E:31358r S:54724 M:110786443 (Ack:191657364)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:378) [1739188318.479548][25020:25020] CHIP:EM: ??1 [E:31358r S:54724 M:110786443] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 361ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.479657][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.480101][25020:25020] CHIP:EM: >>> [E:31357r S:54724 M:191657365 (Ack:110786441)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.480174][25020:25020] CHIP:EM: Found matching exchange: 31357r, Delegate: (nil) [1739188318.480258][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786441 from Retrans Table on exchange 31357r [1739188318.569343][25020:25020] CHIP:EM: >>> [E:31359r S:54724 M:191657366] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:463) [1739188318.569469][25020:25020] CHIP:EM: Handling via exchange: 31359r, Delegate: 0xaaaacc5ae5c8 [1739188318.569638][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.569701][25020:25020] CHIP:DMG: { [1739188318.569754][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.569815][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.569871][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.569947][25020:25020] CHIP:DMG: [ [1739188318.570003][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.570067][25020:25020] CHIP:DMG: { [1739188318.570126][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.570200][25020:25020] CHIP:DMG: { [1739188318.570274][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.570350][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.570426][25020:25020] CHIP:DMG: CommandId = 0xb, [1739188318.570497][25020:25020] CHIP:DMG: }, [1739188318.570571][25020:25020] CHIP:DMG: [1739188318.570633][25020:25020] CHIP:DMG: CommandFields = [1739188318.570702][25020:25020] CHIP:DMG: { [1739188318.570773][25020:25020] CHIP:DMG: 0x0 = [ [1739188318.571164][25020:25020] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x14, 0x01, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x49, 0x21, 0xf7, 0xc4, 0xea, 0x64, 0x44, 0x41, 0xb6, 0xe9, 0x1a, 0xcd, 0x9a, 0x68, 0x30, 0x33, 0x85, 0x1c, 0x58, 0x40, 0xa6, 0xe1, 0x06, 0xde, 0x5d, 0x68, 0x0d, 0xb2, 0xa0, 0xb2, 0xa1, 0x53, 0x7b, 0xfe, 0xda, 0x81, 0xe3, 0x43, 0xc3, 0xf9, 0x25, 0x0b, 0xb1, 0x8b, 0xa2, 0x36, 0x41, 0x40, 0x4e, 0x5a, 0xc5, 0x16, 0xd0, 0x20, 0x60, 0x6d, 0x86, 0x10, 0xee, 0xd2, 0xac, 0xd6, 0x24, 0x2a, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x05, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x06, 0xa6, 0x30, 0x81, 0xa3, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x81, 0x9b, 0x04, 0x81, 0x98, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188318.571362][25020:25020] CHIP:DMG: ] (400 bytes) [1739188318.571439][25020:25020] CHIP:DMG: }, [1739188318.571504][25020:25020] CHIP:DMG: }, [1739188318.571578][25020:25020] CHIP:DMG: [1739188318.571694][25020:25020] CHIP:DMG: ], [1739188318.571774][25020:25020] CHIP:DMG: [1739188318.571830][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.571886][25020:25020] CHIP:DMG: }, [1739188318.572194][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.572261][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.572324][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B [1739188318.572408][25020:25020] CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command [1739188318.572809][25020:25020] CHIP:EM: <<< [E:31359r S:54724 M:110786444 (Ack:191657366)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.573131][25020:25020] CHIP:EM: Flushed pending ack for MessageCounter:191657366 on exchange 31359r [1739188318.575504][25020:25020] CHIP:ZCL: OpCreds: AddTrustedRootCertificate successful. [1739188318.575638][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.575706][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.575773][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.575833][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.575939][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.575997][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.576061][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.576440][25020:25020] CHIP:EM: <<< [E:31359r S:54724 M:110786445 (Ack:191657366)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67) [1739188318.576778][25020:25020] CHIP:EM: ??1 [E:31359r S:54724 M:110786445] (S) Msg Retransmission to 0:FFFFFFFB00000000 scheduled for 392ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.576891][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.577376][25020:25020] CHIP:EM: >>> [E:31358r S:54724 M:191657367 (Ack:110786443)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.577450][25020:25020] CHIP:EM: Found matching exchange: 31358r, Delegate: (nil) [1739188318.577534][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786443 from Retrans Table on exchange 31358r [1739188318.602147][25020:25020] CHIP:EM: >>> [E:31360r S:54724 M:191657368] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:864) [1739188318.602252][25020:25020] CHIP:EM: Handling via exchange: 31360r, Delegate: 0xaaaacc5ae5c8 [1739188318.602415][25020:25020] CHIP:DMG: InvokeRequestMessage = [1739188318.602477][25020:25020] CHIP:DMG: { [1739188318.602531][25020:25020] CHIP:DMG: suppressResponse = false, [1739188318.602593][25020:25020] CHIP:DMG: timedRequest = false, [1739188318.602649][25020:25020] CHIP:DMG: InvokeRequests = [1739188318.602730][25020:25020] CHIP:DMG: [ [1739188318.602788][25020:25020] CHIP:DMG: CommandDataIB = [1739188318.602852][25020:25020] CHIP:DMG: { [1739188318.602912][25020:25020] CHIP:DMG: CommandPathIB = [1739188318.602986][25020:25020] CHIP:DMG: { [1739188318.603056][25020:25020] CHIP:DMG: EndpointId = 0x0, [1739188318.603132][25020:25020] CHIP:DMG: ClusterId = 0x3e, [1739188318.603208][25020:25020] CHIP:DMG: CommandId = 0x6, [1739188318.603282][25020:25020] CHIP:DMG: }, [1739188318.603356][25020:25020] CHIP:DMG: [1739188318.603418][25020:25020] CHIP:DMG: CommandFields = [1739188318.603488][25020:25020] CHIP:DMG: { [1739188318.603560][25020:25020] CHIP:DMG: 0x0 = [ [1739188318.603876][25020:25020] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x13, 0x02, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x15, 0x01, 0x26, 0x11, 0x21, 0x43, 0x34, 0x12, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x6c, 0x6e, 0xc1, 0x21, 0x87, 0x22, 0xe7, 0xa3, 0xdf, 0xb4, 0x34, 0xf5, 0x2f, 0x7f, 0x6e, 0x1c, 0x68, 0x62, 0x66, 0xbd, 0x45, 0x14, 0x01, 0xc1, 0x9c, 0x39, 0x53, 0x18, 0xd0, 0x02, 0x5f, 0x05, 0xa5, 0x25, 0xfe, 0x7b, 0x75, 0x9d, 0x1b, 0x58, 0x2e, 0x65, 0xbb, 0x0d, 0x93, 0x17, 0x68, 0x58, 0xfb, 0x6f, 0x34, 0x60, 0xfc, 0x6a, 0xd1, 0xa1, 0x2b, 0x51, 0x8b, 0x00, 0x03, 0x20, 0x65, 0x99, 0x37, 0x0a, 0x35, 0x01, 0x28, 0x01, 0x18, 0x24, 0x02, 0x01, 0x36, 0x03, 0x04, 0x02, 0x04, 0x01, 0x18, 0x30, 0x04, 0x14, 0xbd, 0xae, 0x37, 0xc6, 0xe9, 0xe7, 0x86, 0x79, 0x15, 0x95, 0x57, 0x64, 0xe4, 0x96, 0x03, 0x09, 0x61, 0xd4, 0x61, 0x6e, 0x30, 0x05, 0x14, 0x08, 0xd0, 0xd3, 0xbd, 0xfd, 0xa3, 0xd8, 0xe6, 0x1e, 0x4c, 0x1c, 0x9a, 0xe5, 0x5d, 0x84, 0x70, 0x75, 0x69, 0x44, 0xe0, 0x30, 0x06, 0x79, 0x30, 0x77, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x70, 0x04, 0x6e, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188318.604045][25020:25020] CHIP:DMG: ] (368 bytes) [1739188318.604119][25020:25020] CHIP:DMG: 0x1 = [ [1739188318.604433][25020:25020] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x13, 0x02, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0xb4, 0x15, 0xe1, 0x53, 0x3c, 0xa2, 0xcf, 0xe5, 0x82, 0xc7, 0x3a, 0xa1, 0x33, 0x22, 0x4d, 0x7c, 0x93, 0x83, 0x98, 0x9b, 0xa7, 0x84, 0xf3, 0xeb, 0xea, 0x7a, 0xe3, 0x42, 0x8e, 0x7d, 0xd6, 0xb7, 0x58, 0xbf, 0x3f, 0x62, 0x3a, 0x5b, 0x2f, 0x4c, 0xfd, 0x62, 0x3c, 0x6c, 0xac, 0xb1, 0x74, 0xb4, 0x42, 0x14, 0xf4, 0x18, 0x8f, 0x2c, 0xdd, 0xad, 0xc6, 0xa8, 0xf8, 0x90, 0x69, 0x57, 0x58, 0xc4, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x08, 0xd0, 0xd3, 0xbd, 0xfd, 0xa3, 0xd8, 0xe6, 0x1e, 0x4c, 0x1c, 0x9a, 0xe5, 0x5d, 0x84, 0x70, 0x75, 0x69, 0x44, 0xe0, 0x30, 0x05, 0x14, 0x27, 0x62, 0x0e, 0x32, 0x17, 0xa0, 0x14, 0x72, 0x0c, 0x14, 0x66, 0xc5, 0xa4, 0xf3, 0xcc, 0x2e, 0x0c, 0x82, 0x40, 0x4c, 0x30, 0x06, 0xa6, 0x30, 0x81, 0xa3, 0x06, 0x03, 0x55, 0x1d, 0x11, 0x04, 0x81, 0x9b, 0x04, 0x81, 0x98, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x41, 0x4 [1739188318.604600][25020:25020] CHIP:DMG: ] (400 bytes) [1739188318.604674][25020:25020] CHIP:DMG: 0x2 = [ [1739188318.604757][25020:25020] CHIP:DMG: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31, [1739188318.604841][25020:25020] CHIP:DMG: ] (16 bytes) [1739188318.604918][25020:25020] CHIP:DMG: 0x3 = 112233 (unsigned), [1739188318.605050][25020:25020] CHIP:DMG: 0x4 = 65521 (unsigned), [1739188318.605126][25020:25020] CHIP:DMG: }, [1739188318.605197][25020:25020] CHIP:DMG: }, [1739188318.605275][25020:25020] CHIP:DMG: [1739188318.605331][25020:25020] CHIP:DMG: ], [1739188318.605414][25020:25020] CHIP:DMG: [1739188318.605470][25020:25020] CHIP:DMG: InteractionModelRevision = 12 [1739188318.605524][25020:25020] CHIP:DMG: }, [1739188318.605870][25020:25020] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a r=i [1739188318.605937][25020:25020] CHIP:DMG: AccessControl: implicit admin (PASE) [1739188318.606001][25020:25020] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 [1739188318.606109][25020:25020] CHIP:ZCL: OpCreds: Received an AddNOC command [1739188318.606495][25020:25020] CHIP:EM: <<< [E:31360r S:54724 M:110786446 (Ack:191657368)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.606764][25020:25020] CHIP:EM: Flushed pending ack for MessageCounter:191657368 on exchange 31360r [1739188318.607304][25020:25020] CHIP:FP: Validating NOC chain [1739188318.611933][25020:25020] CHIP:FP: NOC chain validation successful [1739188318.612034][25020:25020] CHIP:FP: Added new fabric at index: 0x2 [1739188318.612081][25020:25020] CHIP:FP: Assigned compressed fabric ID: 0x29FF093EE9A85335, node ID: 0x0000000012344321 [1739188318.612137][25020:25020] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1739188318.612188][25020:25020] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1739188318.612236][25020:25020] CHIP:TS: Retaining current Last Known Good Time [1739188318.612302][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 55fc0c93 [1739188318.612362][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 55fc0c94 [1739188318.621555][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188318.641656][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188318.661548][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188318.661731][25020:25020] CHIP:DMG: AccessControl: validating f=2 p=a a=c s=1 t=0 [1739188318.661795][25020:25020] CHIP:DMG: validating subject 0x000000000001B669 [1739188318.681458][25020:25020] CHIP:DL: Wrote settings to /tmp/chip_kvs [1739188318.681782][25020:25020] CHIP:EVL: LogEvent event number: 0x0000000000010002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x00000194EFB3B1D9 [1739188318.681857][25020:25020] CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0x000000000001B669 [1739188318.683477][25020:25020] CHIP:DL: Using WiFi MAC for hostname [1739188318.683566][25020:25020] CHIP:DIS: Advertise operational node 29FF093EE9A85335-0000000012344321 [1739188318.683683][25020:25020] CHIP:DIS: Responding with _matter._tcp.local [1739188318.683744][25020:25020] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188318.683806][25020:25020] CHIP:DIS: Responding with 29FF093EE9A85335-0000000012344321._matter._tcp.local [1739188318.683861][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188318.683911][25020:25020] CHIP:DIS: Responding with E45F010F1A010000.local [1739188318.683989][25020:25020] CHIP:DIS: Responding with _I29FF093EE9A85335._sub._matter._tcp.local [1739188318.684039][25020:25020] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 29FF093EE9A85335-0000000012344321. [1739188318.727145][25020:25020] CHIP:DIS: mDNS service published: _matter._tcp [1739188318.727257][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 55fc0c95 [1739188318.727320][25020:25020] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 55fc0c96 [1739188318.727433][25020:25020] CHIP:DMG: Command handler moving to [NewRespons] [1739188318.727496][25020:25020] CHIP:DMG: Command handler moving to [ Preparing] [1739188318.727561][25020:25020] CHIP:DMG: Command handler moving to [AddingComm] [1739188318.727630][25020:25020] CHIP:DMG: Command handler moving to [AddedComma] [1739188318.727683][25020:25020] CHIP:ZCL: OpCreds: successfully created fabric index 0x2 via AddNOC [1739188318.727812][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 1 [1739188318.727870][25020:25020] CHIP:DMG: Decreasing reference count for CommandHandlerImpl, remaining 0 [1739188318.727934][25020:25020] CHIP:DMG: Command handler moving to [AwaitingDe] [1739188318.728343][25020:25020] CHIP:EM: <<< [E:31360r S:54724 M:110786447 (Ack:191657368)] (S) Msg TX from 0000000000000000 to 2:FFFFFFFB00000000 [5335] [UDP:[fe80::cc09:8c5a:dd45:43c2%wlan0]:45004] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70) [1739188318.728721][25020:25020] CHIP:EM: ??1 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 scheduled for 361ms from now [State:Active II:500 AI:300 AT:4000] [1739188318.728904][25020:25020] CHIP:DMG: Command response sender moving to [AllInvokeR] [1739188318.730259][25020:25020] CHIP:EM: >>> [E:31359r S:54724 M:191657369 (Ack:110786445)] (S) Msg RX from 2:FFFFFFFB00000000 [5335] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [1739188318.730337][25020:25020] CHIP:EM: Found matching exchange: 31359r, Delegate: (nil) [1739188318.730425][25020:25020] CHIP:EM: Rxd Ack; Removing MessageCounter:110786445 from Retrans Table on exchange 31359r [1739188318.758753][25020:25020] CHIP:IN: Data received on an unknown session (LSID=51914). Dropping it! [1739188319.090436][25020:25020] CHIP:EM: <<1 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 [1739188319.090640][25020:25020] CHIP:EM: ??2 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 scheduled for 402ms from now [State:Active II:500 AI:300 AT:4000] [1739188319.428595][25020:25020] CHIP:IN: Data received on an unknown session (LSID=51914). Dropping it! [1739188319.493084][25020:25020] CHIP:EM: <<2 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 [1739188319.493272][25020:25020] CHIP:EM: ??3 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 scheduled for 546ms from now [State:Active II:500 AI:300 AT:4000] [1739188320.040497][25020:25020] CHIP:EM: <<3 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 [1739188320.040702][25020:25020] CHIP:EM: ??4 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 scheduled for 953ms from now [State:Active II:500 AI:300 AT:4000] [1739188320.079060][25020:25020] CHIP:IN: Data received on an unknown session (LSID=51914). Dropping it! [1739188320.988054][25020:25020] CHIP:IN: Data received on an unknown session (LSID=51914). Dropping it! [1739188320.993428][25020:25020] CHIP:EM: <<4 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 [1739188320.993600][25020:25020] CHIP:EM: ??5 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 scheduled for 1362ms from now [State:Active II:500 AI:300 AT:4000] [1739188322.357556][25020:25020] CHIP:EM: <<5 [E:31360r S:54724 M:110786447] (S) Msg Retransmission to 2:FFFFFFFB00000000 failure (max retries:4) [1739188322.601905][25020:25020] CHIP:IN: Data received on an unknown session (LSID=51914). Dropping it!