search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.33k stars 1.97k forks source link

[BUG] FailSafe timer fails commissioning early, "Can't reach Google," network works anyway #30151

Closed emmby closed 10 months ago

emmby commented 10 months ago

Reproduction steps

I have an ESP32 using Matter 08b13661b6 (July 19 2023). Whenever I try to commission a test device onto Google Home, the FailSafeTimer expires well before 60 seconds (from section 5.5 of the 1.0 spec) have elapsed. See below where it expires in less than 45 seconds. When this happens, Google Home reports "Can't reach Google" and aborts the commissioning after the "Generating Matter Credentials," "Testing Network Connectivity", and "Connecting device to Google Home" steps.

Troubleshooting for that error says to check that I've create the proper PID/VID on the developer console, which I have and was working previously.

The funny thing is that even though commissioning has failed, the device can access the network just fine. chip::DeviceLayer::ConfigurationMgr().IsFullyProvisioned() reports true and sntp network requests go through. But FabricTable.FabricCount() still reports 0.

The Google Home error message is new, I was not seeing that behavior previously even for the same device codebase. I'm wondering whether I got my fabric into a weird state somehow but I'm also not sure how to reset it. Clearing NVS on the device and re-installing the Google Home app didn't resolve the problem.

Why won't this device commission onto the fabric?

07:58:51.646 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
07:58:51.646 -> configsip: 271414342, SPIWP:0xee
07:58:51.646 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
07:58:51.683 -> mode:DIO, clock div:1
07:58:51.683 -> load:0x3fff0030,len:1184
07:58:51.683 -> load:0x40078000,len:13260
07:58:51.683 -> load:0x40080400,len:3028
07:58:51.683 -> entry 0x400805e4
07:58:53.656 -> E (1301) esp_matter_providers: custom_dac_provider cannot be NULL
07:58:54.457 -> E (3862) chip[DL]: Long dispatch time: 780 ms, for event type 2
07:58:54.488 -> E (3908) chip[ZCL]: Duplicate attribute override registration failed
07:59:15.070 -> E (24482) chip[DL]: Long dispatch time: 1514 ms, for event type 7
07:59:19.728 -> E (29125) chip[DL]: Long dispatch time: 979 ms, for event type 7
07:59:23.659 -> E (33047) chip[DL]: Long dispatch time: 1345 ms, for event type 7
07:59:24.027 -> E (33447) wifi:sta is connecting, return error
07:59:24.027 -> E (33448) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
07:59:24.059 -> E (33455) wifi:sta is connecting, return error
07:59:24.059 -> E (33459) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
07:59:24.059 -> E (33466) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
07:59:25.643 -> E (35037) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
07:59:25.643 -> E (35044) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
07:59:25.742 -> E (35140) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
07:59:28.703 -> E (38097) chip[DL]: Long dispatch time: 923 ms, for event type 3
07:59:28.802 -> E (38222) chip[SC]: The device does not support GetClock_RealTimeMS() API: 6c.  Falling back to Last Known Good UTC Time
07:59:30.150 -> E (39576) chip[DL]: Long dispatch time: 1323 ms, for event type 2
07:59:33.011 -> E (42422) chip[DMG]: Error retrieving data from clusterId: 0x0000_0031, err = b
07:59:33.172 -> E (42580) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = b
07:59:33.334 -> E (42751) chip[DMG]: Error retrieving data from clusterId: 0x0000_001D, err = b
07:59:35.713 -> E (45133) chip[SVR]: Failsafe timer expired
07:59:35.713 -> E (45134) chip[SVR]: Commissioning failed (attempt 1): 32
07:59:35.745 -> E (45138) chip[BLE]: CancelBleIncompleteConnection() failed, err = 3
07:59:35.810 -> E (45205) chip[ZCL]: OpCreds: Got FailSafeTimerExpired
07:59:35.810 -> E (45207) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
07:59:35.810 -> E (45222) chip[FP]: Reverting pending fabric data for fabric 0x1
07:59:35.810 -> E (45240) chip[FP]: Warning: metadata not found during delete of fabric 0x1
07:59:35.980 -> E (45397) chip[FP]: Warning: metadata not found during delete of fabric 0x1
07:59:35.980 -> E (45405) chip[ZCL]: OpCreds: failed to delete fabric at index 1: d8
07:59:35.980 -> E (45406) chip[DL]: ble_gap_adv_set_data failed: Error ESP32:0x05B0001E 3840
07:59:36.013 -> E (45411) chip[DL]: Configure Adv Data failed: Error ESP32:0x05B0001E
07:59:36.013 -> E (45417) chip[DL]: Disabling CHIPoBLE service due to error: Error ESP32:0x05B0001E
07:59:43.318 -> E (52746) esp_matter_core: Node already exists
07:59:43.351 -> E (52767) esp_matter_core: esp_matter has started

Bug prevalence

Every time recently, never previously

GitHub hash of the SDK that was being used

08b13661b6

Platform

esp32

Platform Version(s)

esp-matter 603296a

Anything else?

Screenshot_20231101-081624

bzbarsky-apple commented 10 months ago

@emmby That's not much to go on in the way of logs... In particular: creating a PASE session arms a fail-safe for 60 seconds, but the client can then re-arm it for a different value. The log is not showing any incoming commands; are there none, or are they just not being logged?

emmby commented 10 months ago

Sorry, better logs:

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 271414342, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:1184
load:0x40078000,len:13260
load:0x40080400,len:3028
entry 0x400805e4
Wakeup was not caused by deep sleep: 0
Found PCT2075 temperature chip
State: entered main_region_HardwareInitialized
D (1251) esp_matter_core: Set val called with string with size 0
D (1252) esp_matter_core: Set val called with string with size 0
D (1255) esp_matter_core: Set val called with string with size 0
D (1261) esp_matter_core: Set val called with string with size 0
D (1267) esp_matter_core: Set val called with string with size 0
D (1273) esp_matter_core: Set val called with string with size 0
D (1279) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x6
D (1287) esp_matter_core: Set val called with string with size 0
D (1293) esp_matter_core: Set val called with string with size 0
D (1299) esp_matter_core: Set val called with string with size 0
D (1304) esp_matter_core: Set val called with string with size 0
D (1310) esp_matter_core: Set val called with string with size 0
D (1316) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x5
D (1325) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x28, attribute_id-0x5
D (1335) esp_matter_core: Set val called with string with size 0
D (1340) esp_matter_core: Set val called with string with size 0
D (1345) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x31, attribute_id-0x4
D (1354) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x31, attribute_id-0x4
D (1364) esp_matter_core: Set val called with string with size 0
D (1369) esp_matter_core: Set val called with string with size 0
D (1374) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x33, attribute_id-0x1
D (1383) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x33, attribute_id-0x1
D (1394) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x0
D (1401) esp_matter_core: Set val called with string with size 0
D (1407) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x0
D (1416) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x3
D (1425) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x3
D (1435) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x1
D (1442) esp_matter_core: Set val called with string with size 0
D (1448) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x1
D (1457) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x4
D (1466) esp_matter_core: Set val called with string with size 0
D (1472) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x3e, attribute_id-0x4
D (1481) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x3f, attribute_id-0x0
D (1489) esp_matter_core: Set val called with string with size 0
D (1495) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x3f, attribute_id-0x0
D (1504) esp_matter_core: Set val called with string with size 0
D (1510) esp_matter_core: Set val called with string with size 0
D (1517) esp_matter_core: Set val called with string with size 0
D (1521) esp_matter_core: Set val called with string with size 0
D (1527) esp_matter_core: Set val called with string with size 0
D (1533) esp_matter_core: Set val called with string with size 0
D (1548) esp_matter_core: read attribute from nvs: endpoint_id-0x0, cluster_id-0x2a, attribute_id-0x0
D (1548) esp_matter_core: Set val called with string with size 0
D (1553) esp_matter_core: Store attribute in nvs: endpoint_id-0x0, cluster_id-0x2a, attribute_id-0x0
I (1568) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1)
I (1571) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0)
I (1575) chip[DL]: NVS set: chip-config/unique-id = "916F2021C37FA817"
I (1580) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP
I (1585) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (1591) chip[DL]: Real time clock set to 946684800 (0099/11/31 16:00:00 UTC)
E (1596) esp_matter_providers: custom_dac_provider cannot be NULL
D (3682) chip[DL]: CHIP event task running
D (4007) CHIP[DL]: BLE Host Task Started
I (4033) CHIP[DL]: BLE host-controller synced
D (4539) CHIP[DL]: NimBLE start advertising...
I (4540) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (4540) NimBLE: GAP procedure initiated: advertise; 
I (4544) NimBLE: disc_mode=2
I (4547) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (4556) NimBLE: 

I (4560) chip[DL]: CHIPoBLE advertising started
E (4562) chip[DL]: Long dispatch time: 876 ms, for event type 2
I (4568) chip[DL]: Starting ESP WiFi layer
I (4574) chip[DL]: Done driving station state, nothing else to do...
I (4578) chip[DL]: Done driving station state, nothing else to do...
I (4584) chip[SVR]: Initializing subscription resumption storage...
I (4592) chip[SVR]: Server initializing...
D (4594) chip[FP]: Initializing FabricTable from persistent storage
I (4600) chip[TS]: Last Known Good Time: [unknown]
I (4604) chip[TS]: Setting Last Known Good Time to firmware build time 2023-07-24T23:38:47
I (4614) chip[DMG]: AccessControl: initializing
I (4616) chip[DMG]: Examples::AccessControlDelegate::Init
I (4622) chip[DMG]: AccessControl: setting
I (4625) chip[DMG]: DefaultAclStorage: initializing
I (4630) chip[DMG]: DefaultAclStorage: 0 entries loaded
D (4635) chip[IN]: UDP::Init bind&listen port=5540
D (4640) chip[IN]: UDP::Init bound to port=5540
D (4644) chip[IN]: UDP::Init bind&listen port=5540
D (4648) chip[IN]: UDP::Init bound to port=5540
D (4652) chip[IN]: BLEBase::Init - setting/overriding transport
D (4658) chip[IN]: TransportMgr initialized
I (4669) chip[ZCL]: Using ZAP configuration...
I (4669) esp_matter_cluster: Cluster plugin init common callback
I (4672) chip[DMG]: AccessControlCluster: initializing
I (4677) chip[ZCL]: 0x3f437745ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
D (4684) chip[ZCL]: GeneralDiagnostics: OnDeviceReboot
I (4689) chip[ZCL]: Initiating Admin Commissioning cluster.
E (4694) chip[ZCL]: Duplicate attribute override registration failed
D (4702) chip[IN]: SecureSession[0x3ffd20c8]: Allocated Type:1 LSID:45560
D (4707) chip[SC]: Assigned local session key ID 45560
D (4712) chip[SC]: Waiting for PBKDF param request
I (4716) chip[DIS]: Updating services using commissioning mode 1
I (4722) chip[DIS]: CHIP minimal mDNS started advertising.
D (4727) chip[DL]: Using wifi MAC for hostname
I (4732) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
D (4741) chip[DIS]: Responding with _matterc._udp.local
D (4746) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
D (4752) chip[DIS]: Responding with 0C8B9596B688.local
D (4757) chip[DIS]: Responding with 0C8B9596B688.local
D (4762) chip[DIS]: Responding with _V65521._sub._matterc._udp.local
D (4768) chip[DIS]: Responding with _S15._sub._matterc._udp.local
D (4774) chip[DIS]: Responding with _L3840._sub._matterc._udp.local
D (4780) chip[DIS]: Responding with _CM._sub._matterc._udp.local
D (4786) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
I (4792) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 347AFFA93E947DD7.
I (4802) chip[DIS]: mDNS service published: _matterc._udp
I (4807) chip[IN]: CASE Server enabling CASE session setups
D (4813) chip[IN]: SecureSession[0x3ffd2180]: Allocated Type:2 LSID:45561
D (4819) chip[SC]: Allocated SecureSession (0x3ffd2180) - waiting for Sigma1 msg
I (4826) chip[SVR]: Joining Multicast groups
D (4830) chip[ZCL]: Emitting StartUp event
I (4834) chip[SVR]: Server Listening...
D (4839) chip[DMG]: Endpoint 0, Cluster 0x0000_001D update version to 9de7bc01
I (4844) esp_matter_core: Dynamic endpoint 0 added
I (4849) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
D (4860) chip[DMG]: Endpoint 1, Cluster 0x0000_0003 update version to 41f697b
D (4867) chip[DMG]: Endpoint 0, Cluster 0x0000_001D update version to 9de7bc02
I (4873) esp_matter_core: Dynamic endpoint 1 added
D (4878) chip[ZCL]: Emitting StartUp event
D (4882) chip[EVL]: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000121
D (4896) chip[ZCL]: GeneralDiagnostics: OnDeviceReboot
D (4901) chip[DMG]: Endpoint 0, Cluster 0x0000_0033 update version to 13e3d846
D (4908) chip[EVL]: LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000013B
I (4923) chip[DL]: WIFI_EVENT_STA_START
I (4925) esp_matter_core: Cannot find the node nvs namespace
I (4927) chip[DL]: Done driving station state, nothing else to do...
D (4942) CHIP[DL]: NimBLE start advertising...
I (4942) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (4949) chip[DL]: Device already advertising, stop active advertisement and restart
I (4956) NimBLE: GAP procedure initiated: stop advertising.

I (4963) NimBLE: GAP procedure initiated: advertise; 
I (4966) NimBLE: disc_mode=2
I (4969) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (4978) NimBLE: 

Commissioning window opened
State: entered main_region_ConnectToNetwork
I (12654) chip[DL]: BLE GAP connection established (con 0)
I (12657) chip[DL]: CHIPoBLE advertising stopped
D (13508) CHIP[DL]: BLE_GAP_EVENT_MTU = 256 channel id = 4
I (13530) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (13532) chip[BLE]: local and remote recv window sizes = 5
I (13532) chip[BLE]: selected BTP version 4
I (13536) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (13552) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 1
I (13553) chip[DL]: CHIPoBLE subscribe received
D (13554) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 6)
I (13563) NimBLE: GATT procedure initiated: indicate; 
I (13567) NimBLE: att_handle=14

D (13575) chip[IN]: BLE EndPoint 0x3ffcb560 Connection Complete
I (13635) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (13637) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (13642) chip[EM]: >>> [E:62755r S:0 M:219517855] (U) Msg RX from 0:388FC9E3792413FF [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D (13653) chip[EM]: Handling via exchange: 62755r, Delegate: 0x3ffd41e8
D (13660) chip[SC]: Received PBKDF param request
D (13664) chip[SC]: Peer assigned session ID 61556
I (13670) chip[EM]: <<< [E:62755r S:0 M:93728563] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I (13680) chip[IN]: (U) Sending msg 93728563 to IP address 'BLE'
D (13686) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 129)
I (13694) NimBLE: GATT procedure initiated: indicate; 
I (13698) NimBLE: att_handle=14

D (13706) chip[SC]: Sent PBKDF param response
I (13771) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (13771) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (13778) chip[EM]: >>> [E:62755r S:0 M:219517856] (U) Msg RX from 0:388FC9E3792413FF [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D (13788) chip[EM]: Found matching exchange: 62755r, Delegate: 0x3ffd41e8
D (13795) chip[SC]: Received spake2p msg1
I (16814) chip[EM]: <<< [E:62755r S:0 M:93728564] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I (16817) chip[IN]: (U) Sending msg 93728564 to IP address 'BLE'
D (16822) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 132)
I (16830) NimBLE: GATT procedure initiated: indicate; 
I (16835) NimBLE: att_handle=14

D (16841) chip[SC]: Sent spake2p msg2
E (16842) chip[DL]: Long dispatch time: 3063 ms, for event type 7
I (16920) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (16921) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (16927) chip[EM]: >>> [E:62755r S:0 M:219517857] (U) Msg RX from 0:388FC9E3792413FF [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D (16938) chip[EM]: Found matching exchange: 62755r, Delegate: 0x3ffd41e8
D (16945) chip[SC]: Received spake2p msg3
D (16949) chip[SC]: Sending status report. Protocol code 0, exchange 62755
I (16955) chip[EM]: <<< [E:62755r S:0 M:93728565] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (16967) chip[IN]: (U) Sending msg 93728565 to IP address 'BLE'
D (16973) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 35)
I (16980) NimBLE: GATT procedure initiated: indicate; 
I (16985) NimBLE: att_handle=14

I (16994) chip[SC]: SecureSession[0x3ffd20c8, LSID:45560]: State change 'kEstablishing' --> 'kActive'
D (16996) chip[IN]: SecureSession[0x3ffd20c8]: Activated - Type:1 LSID:45560
D (17004) chip[IN]: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:45560 PSID:61556!
I (17012) chip[SVR]: Commissioning completed session establishment step
I (17020) chip[DIS]: Updating services using commissioning mode 0
I (17026) chip[DIS]: CHIP minimal mDNS started advertising.
I (17030) chip[SVR]: Device completed Rendezvous process
Commissioning session started
Commissioning window closed
I (17055) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (17056) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (17064) chip[EM]: >>> [E:62756r S:45560 M:146367017] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (17072) chip[EM]: Handling via exchange: 62756r, Delegate: 0x3ffcd4d4
D (17078) chip[IM]: Received Read request
D (17082) chip[DMG]: ReadRequestMessage =
D (17086) chip[DMG]: {
D (17088) chip[DMG]:    AttributePathIBs =
D (17092) chip[DMG]:    [
D (17094) chip[DMG]:        AttributePathIB =
D (17098) chip[DMG]:        {
D (17100) chip[DMG]:            Endpoint = 0x0,
D (17104) chip[DMG]:            Cluster = 0x1d,
D (17108) chip[DMG]:            Attribute = 0x0000_0001,
D (17112) chip[DMG]:        }
D (17114) chip[DMG]:            
D (17116) chip[DMG]:    ],
D (17118) chip[DMG]:        
D (17120) chip[DMG]:    isFabricFiltered = true, 
D (17124) chip[DMG]:    InteractionModelRevision = 11
D (17130) chip[DMG]: },
D (17132) chip[DMG]: IM RH moving to [GeneratingReports]
D (17137) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (17146) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (17151) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D (17161) chip[DMG]: <RE> Sending report (payload has 58 bytes)...
I (17168) chip[EM]: <<< [E:62756r S:45560 M:171200270] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (17178) chip[IN]: (S) Sending msg 171200270 on secure session with LSID: 45560
D (17184) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 93)
I (17192) NimBLE: GATT procedure initiated: indicate; 
I (17198) NimBLE: att_handle=14

D (17204) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (17206) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (17214) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (17218) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (17280) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (17281) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (17289) chip[EM]: >>> [E:62757r S:45560 M:146367018] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (17297) chip[EM]: Handling via exchange: 62757r, Delegate: 0x3ffcd4d4
D (17303) chip[IM]: Received Read request
D (17307) chip[DMG]: ReadRequestMessage =
D (17311) chip[DMG]: {
D (17313) chip[DMG]:    AttributePathIBs =
D (17317) chip[DMG]:    [
D (17319) chip[DMG]:        AttributePathIB =
D (17323) chip[DMG]:        {
D (17325) chip[DMG]:            Endpoint = 0x0,
D (17329) chip[DMG]:            Cluster = 0x31,
D (17333) chip[DMG]:            Attribute = 0x0000_FFFC,
D (17337) chip[DMG]:        }
D (17339) chip[DMG]:            
D (17341) chip[DMG]:    ],
D (17343) chip[DMG]:        
D (17345) chip[DMG]:    isFabricFiltered = true, 
D (17349) chip[DMG]:    InteractionModelRevision = 11
D (17355) chip[DMG]: },
D (17357) chip[DMG]: IM RH moving to [GeneratingReports]
D (17362) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (17371) chip[DMG]: <RE:Run> Cluster 31, Attribute fffc is dirty
D (17377) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D (17387) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (17393) chip[EM]: <<< [E:62757r S:45560 M:171200271] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (17403) chip[IN]: (S) Sending msg 171200271 on secure session with LSID: 45560
D (17411) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 72)
I (17417) NimBLE: GATT procedure initiated: indicate; 
I (17423) NimBLE: att_handle=14

D (17429) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (17431) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (17439) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (17443) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (17505) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (17506) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (17514) chip[EM]: >>> [E:62758r S:45560 M:146367019] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (17522) chip[EM]: Handling via exchange: 62758r, Delegate: 0x3ffcd4d4
D (17528) chip[IM]: Received Read request
D (17532) chip[DMG]: ReadRequestMessage =
D (17536) chip[DMG]: {
D (17538) chip[DMG]:    AttributePathIBs =
D (17542) chip[DMG]:    [
D (17544) chip[DMG]:        AttributePathIB =
D (17548) chip[DMG]:        {
D (17550) chip[DMG]:            Endpoint = 0x0,
D (17554) chip[DMG]:            Cluster = 0x28,
D (17558) chip[DMG]:            Attribute = 0x0000_0002,
D (17562) chip[DMG]:        }
D (17564) chip[DMG]:            
D (17566) chip[DMG]:    ],
D (17568) chip[DMG]:        
D (17570) chip[DMG]:    isFabricFiltered = true, 
D (17574) chip[DMG]:    InteractionModelRevision = 11
D (17580) chip[DMG]: },
D (17582) chip[DMG]: IM RH moving to [GeneratingReports]
D (17587) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (17596) chip[DMG]: <RE:Run> Cluster 28, Attribute 2 is dirty
D (17602) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D (17611) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (17618) chip[EM]: <<< [E:62758r S:45560 M:171200272] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (17628) chip[IN]: (S) Sending msg 171200272 on secure session with LSID: 45560
D (17635) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 72)
I (17642) NimBLE: GATT procedure initiated: indicate; 
I (17648) NimBLE: att_handle=14

D (17654) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (17656) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (17664) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (17668) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (17730) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (17731) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (17739) chip[EM]: >>> [E:62759r S:45560 M:146367020] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (17747) chip[EM]: Handling via exchange: 62759r, Delegate: 0x3ffcd4d4
D (17753) chip[IM]: Received Read request
D (17757) chip[DMG]: ReadRequestMessage =
D (17761) chip[DMG]: {
D (17763) chip[DMG]:    AttributePathIBs =
D (17767) chip[DMG]:    [
D (17769) chip[DMG]:        AttributePathIB =
D (17773) chip[DMG]:        {
D (17775) chip[DMG]:            Endpoint = 0x0,
D (17779) chip[DMG]:            Cluster = 0x28,
D (17783) chip[DMG]:            Attribute = 0x0000_0004,
D (17787) chip[DMG]:        }
D (17789) chip[DMG]:            
D (17791) chip[DMG]:    ],
D (17793) chip[DMG]:        
D (17795) chip[DMG]:    isFabricFiltered = true, 
D (17799) chip[DMG]:    InteractionModelRevision = 11
D (17805) chip[DMG]: },
D (17807) chip[DMG]: IM RH moving to [GeneratingReports]
D (17812) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (17821) chip[DMG]: <RE:Run> Cluster 28, Attribute 4 is dirty
D (17826) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D (17836) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (17843) chip[EM]: <<< [E:62759r S:45560 M:171200273] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (17853) chip[IN]: (S) Sending msg 171200273 on secure session with LSID: 45560
D (17859) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 72)
I (17867) NimBLE: GATT procedure initiated: indicate; 
I (17873) NimBLE: att_handle=14

D (17879) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (17881) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (17889) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (17893) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (17955) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (17956) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (17964) chip[EM]: >>> [E:62760r S:45560 M:146367021] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (17972) chip[EM]: Handling via exchange: 62760r, Delegate: 0x3ffcd4d4
D (17978) chip[IM]: Received Read request
D (17982) chip[DMG]: ReadRequestMessage =
D (17986) chip[DMG]: {
D (17988) chip[DMG]:    AttributePathIBs =
D (17992) chip[DMG]:    [
D (17994) chip[DMG]:        AttributePathIB =
D (17998) chip[DMG]:        {
D (18000) chip[DMG]:            Endpoint = 0x0,
D (18004) chip[DMG]:            Cluster = 0x3e,
D (18008) chip[DMG]:            Attribute = 0x0000_0002,
D (18012) chip[DMG]:        }
D (18014) chip[DMG]:            
D (18016) chip[DMG]:    ],
D (18018) chip[DMG]:        
D (18020) chip[DMG]:    isFabricFiltered = true, 
D (18024) chip[DMG]:    InteractionModelRevision = 11
D (18030) chip[DMG]: },
D (18032) chip[DMG]: IM RH moving to [GeneratingReports]
D (18037) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (18046) chip[DMG]: <RE:Run> Cluster 3e, Attribute 2 is dirty
D (18052) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D (18061) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (18068) chip[EM]: <<< [E:62760r S:45560 M:171200274] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (18078) chip[IN]: (S) Sending msg 171200274 on secure session with LSID: 45560
D (18085) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (18092) NimBLE: GATT procedure initiated: indicate; 
I (18098) NimBLE: att_handle=14

D (18104) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (18106) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (18114) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (18118) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (18180) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (18181) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18189) chip[EM]: >>> [E:62761r S:45560 M:146367022] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (18197) chip[EM]: Handling via exchange: 62761r, Delegate: 0x3ffcd4d4
D (18203) chip[IM]: Received Read request
D (18207) chip[DMG]: ReadRequestMessage =
D (18211) chip[DMG]: {
D (18213) chip[DMG]:    AttributePathIBs =
D (18217) chip[DMG]:    [
D (18219) chip[DMG]:        AttributePathIB =
D (18223) chip[DMG]:        {
D (18225) chip[DMG]:            Endpoint = 0x0,
D (18229) chip[DMG]:            Cluster = 0x3e,
D (18233) chip[DMG]:            Attribute = 0x0000_0003,
D (18237) chip[DMG]:        }
D (18239) chip[DMG]:            
D (18241) chip[DMG]:    ],
D (18243) chip[DMG]:        
D (18245) chip[DMG]:    isFabricFiltered = true, 
D (18249) chip[DMG]:    InteractionModelRevision = 11
D (18255) chip[DMG]: },
D (18257) chip[DMG]: IM RH moving to [GeneratingReports]
D (18262) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (18271) chip[DMG]: <RE:Run> Cluster 3e, Attribute 3 is dirty
D (18276) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (18286) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (18293) chip[EM]: <<< [E:62761r S:45560 M:171200275] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (18303) chip[IN]: (S) Sending msg 171200275 on secure session with LSID: 45560
D (18309) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (18317) NimBLE: GATT procedure initiated: indicate; 
I (18323) NimBLE: att_handle=14

D (18329) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (18331) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (18339) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (18343) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (18405) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (18406) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18414) chip[EM]: >>> [E:62762r S:45560 M:146367023] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (18422) chip[EM]: Handling via exchange: 62762r, Delegate: 0x3ffcd4d4
D (18428) chip[IM]: Received Read request
D (18432) chip[DMG]: ReadRequestMessage =
D (18436) chip[DMG]: {
D (18438) chip[DMG]:    AttributePathIBs =
D (18442) chip[DMG]:    [
D (18444) chip[DMG]:        AttributePathIB =
D (18448) chip[DMG]:        {
D (18450) chip[DMG]:            Endpoint = 0x0,
D (18454) chip[DMG]:            Cluster = 0x1d,
D (18458) chip[DMG]:            Attribute = 0x0000_0001,
D (18462) chip[DMG]:        }
D (18464) chip[DMG]:            
D (18466) chip[DMG]:    ],
D (18468) chip[DMG]:        
D (18470) chip[DMG]:    isFabricFiltered = true, 
D (18474) chip[DMG]:    InteractionModelRevision = 11
D (18480) chip[DMG]: },
D (18482) chip[DMG]: IM RH moving to [GeneratingReports]
D (18487) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (18496) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (18502) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D (18511) chip[DMG]: <RE> Sending report (payload has 58 bytes)...
I (18518) chip[EM]: <<< [E:62762r S:45560 M:171200276] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (18528) chip[IN]: (S) Sending msg 171200276 on secure session with LSID: 45560
D (18535) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 93)
I (18542) NimBLE: GATT procedure initiated: indicate; 
I (18548) NimBLE: att_handle=14

D (18554) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (18556) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (18564) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (18568) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (18630) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (18631) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18639) chip[EM]: >>> [E:62763r S:45560 M:146367024] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (18647) chip[EM]: Handling via exchange: 62763r, Delegate: 0x3ffcd4d4
D (18653) chip[IM]: Received Read request
D (18657) chip[DMG]: ReadRequestMessage =
D (18661) chip[DMG]: {
D (18663) chip[DMG]:    AttributePathIBs =
D (18667) chip[DMG]:    [
D (18669) chip[DMG]:        AttributePathIB =
D (18673) chip[DMG]:        {
D (18675) chip[DMG]:            Endpoint = 0x0,
D (18679) chip[DMG]:            Cluster = 0x31,
D (18683) chip[DMG]:            Attribute = 0x0000_FFFC,
D (18687) chip[DMG]:        }
D (18689) chip[DMG]:            
D (18691) chip[DMG]:    ],
D (18693) chip[DMG]:        
D (18695) chip[DMG]:    isFabricFiltered = true, 
D (18699) chip[DMG]:    InteractionModelRevision = 11
D (18705) chip[DMG]: },
D (18707) chip[DMG]: IM RH moving to [GeneratingReports]
D (18712) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (18721) chip[DMG]: <RE:Run> Cluster 31, Attribute fffc is dirty
D (18727) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D (18737) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (18743) chip[EM]: <<< [E:62763r S:45560 M:171200277] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (18753) chip[IN]: (S) Sending msg 171200277 on secure session with LSID: 45560
D (18761) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 72)
I (18767) NimBLE: GATT procedure initiated: indicate; 
I (18773) NimBLE: att_handle=14

D (18779) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (18781) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (18789) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (18793) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (18855) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (18856) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (18864) chip[EM]: >>> [E:62764r S:45560 M:146367025] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (18872) chip[EM]: Handling via exchange: 62764r, Delegate: 0x3ffcd4d4
D (18878) chip[IM]: Received Read request
D (18882) chip[DMG]: ReadRequestMessage =
D (18886) chip[DMG]: {
D (18888) chip[DMG]:    AttributePathIBs =
D (18892) chip[DMG]:    [
D (18894) chip[DMG]:        AttributePathIB =
D (18898) chip[DMG]:        {
D (18900) chip[DMG]:            Endpoint = 0x0,
D (18904) chip[DMG]:            Cluster = 0x3e,
D (18908) chip[DMG]:            Attribute = 0x0000_0001,
D (18912) chip[DMG]:        }
D (18914) chip[DMG]:            
D (18916) chip[DMG]:    ],
D (18918) chip[DMG]:        
D (18920) chip[DMG]:    isFabricFiltered = false, 
D (18924) chip[DMG]:    InteractionModelRevision = 11
D (18930) chip[DMG]: },
D (18932) chip[DMG]: IM RH moving to [GeneratingReports]
D (18938) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (18946) chip[DMG]: <RE:Run> Cluster 3e, Attribute 1 is dirty
D (18952) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D (18962) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (18968) chip[EM]: <<< [E:62764r S:45560 M:171200278] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (18978) chip[IN]: (S) Sending msg 171200278 on secure session with LSID: 45560
D (18985) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (18992) NimBLE: GATT procedure initiated: indicate; 
I (18998) NimBLE: att_handle=14

D (19004) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (19006) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (19014) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (19018) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (19079) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (19485) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (19489) chip[EM]: >>> [E:62765r S:45560 M:146367026] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D (19493) chip[EM]: Handling via exchange: 62765r, Delegate: 0x3ffcd4d4
D (19499) chip[DMG]: TimedRequestMessage =
D (19503) chip[DMG]: {
D (19505) chip[DMG]:    TimeoutMs = 0x2710,
D (19509) chip[DMG]:    InteractionModelRevision = 11
D (19513) chip[DMG]: }
D (19515) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3ffcd8f0 exchange 62765r
I (19526) chip[EM]: <<< [E:62765r S:45560 M:171200279] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I (19535) chip[IN]: (S) Sending msg 171200279 on secure session with LSID: 45560
D (19543) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 43)
I (19551) NimBLE: GATT procedure initiated: indicate; 
I (19555) NimBLE: att_handle=14

D (19561) chip[DMG]: Timed Request time limit 0x0000000000006B5E: handler 0x3ffcd8f0 exchange 62765r
I (19620) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (19621) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (19629) chip[EM]: >>> [E:62765r S:45560 M:146367027] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (19639) chip[EM]: Found matching exchange: 62765r, Delegate: 0x3ffcd8f0
D (19645) chip[DMG]: Timed following action arrived at 0x00000000000044A2: handler 0x3ffcd8f0 exchange 62765r
D (19655) chip[DMG]: Handing timed invoke to IM engine: handler 0x3ffcd8f0 exchange 62765r
D (19663) chip[DMG]: InvokeRequestMessage =
D (19667) chip[DMG]: {
D (19669) chip[DMG]:    suppressResponse = false, 
D (19673) chip[DMG]:    timedRequest = true, 
D (19677) chip[DMG]:    InvokeRequests =
D (19680) chip[DMG]:    [
D (19683) chip[DMG]:        CommandDataIB =
D (19685) chip[DMG]:        {
D (19688) chip[DMG]:            CommandPathIB =
D (19691) chip[DMG]:            {
D (19694) chip[DMG]:                EndpointId = 0x0,
D (19697) chip[DMG]:                ClusterId = 0x30,
D (19701) chip[DMG]:                CommandId = 0x0,
D (19705) chip[DMG]:            },
D (19707) chip[DMG]:            
D (19710) chip[DMG]:            CommandFields = 
D (19713) chip[DMG]:            {
D (19716) chip[DMG]:                0x0 = 120, 
D (19719) chip[DMG]:                0x1 = 1, 
D (19723) chip[DMG]:            },
D (19725) chip[DMG]:        },
D (19727) chip[DMG]:        
D (19729) chip[DMG]:    ],
D (19731) chip[DMG]:    
D (19733) chip[DMG]:    InteractionModelRevision = 11
D (19739) chip[DMG]: },
D (19741) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I (19749) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (19757) chip[FS]: GeneralCommissioning: Received ArmFailSafe (120s)
I (19763) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
D (19775) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86201
D (19781) chip[DMG]: Command handler moving to [ Preparing]
D (19787) chip[DMG]: Command handler moving to [AddingComm]
D (19791) chip[DMG]: Command handler moving to [AddedComma]
D (19797) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (19806) chip[EM]: <<< [E:62765r S:45560 M:171200280] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (19817) chip[IN]: (S) Sending msg 171200280 on secure session with LSID: 45560
D (19823) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (19831) NimBLE: GATT procedure initiated: indicate; 
I (19835) NimBLE: att_handle=14

D (19841) chip[DMG]: Command handler moving to [CommandSen]
D (19845) chip[DMG]: Command handler moving to [AwaitingDe]
I (19890) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (19891) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (19899) chip[EM]: >>> [E:62766r S:45560 M:146367028] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (19907) chip[EM]: Handling via exchange: 62766r, Delegate: 0x3ffcd4d4
D (19913) chip[IM]: Received Read request
D (19917) chip[DMG]: ReadRequestMessage =
D (19921) chip[DMG]: {
D (19923) chip[DMG]:    AttributePathIBs =
D (19927) chip[DMG]:    [
D (19929) chip[DMG]:        AttributePathIB =
D (19933) chip[DMG]:        {
D (19935) chip[DMG]:            Endpoint = 0x0,
D (19939) chip[DMG]:            Cluster = 0x30,
D (19943) chip[DMG]:            Attribute = 0x0000_0003,
D (19947) chip[DMG]:        }
D (19949) chip[DMG]:            
D (19951) chip[DMG]:    ],
D (19953) chip[DMG]:        
D (19955) chip[DMG]:    isFabricFiltered = true, 
D (19959) chip[DMG]:    InteractionModelRevision = 11
D (19965) chip[DMG]: },
D (19967) chip[DMG]: IM RH moving to [GeneratingReports]
D (19972) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (19981) chip[DMG]: <RE:Run> Cluster 30, Attribute 3 is dirty
D (19987) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (19996) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (20003) chip[EM]: <<< [E:62766r S:45560 M:171200281] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I (20013) chip[IN]: (S) Sending msg 171200281 on secure session with LSID: 45560
D (20020) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (20027) NimBLE: GATT procedure initiated: indicate; 
I (20033) NimBLE: att_handle=14

D (20039) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (20041) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (20049) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (20053) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (20115) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (20116) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (20124) chip[EM]: >>> [E:62767r S:45560 M:146367029] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D (20132) chip[EM]: Handling via exchange: 62767r, Delegate: 0x3ffcd4d4
D (20140) chip[DMG]: TimedRequestMessage =
D (20142) chip[DMG]: {
D (20144) chip[DMG]:    TimeoutMs = 0x2710,
D (20148) chip[DMG]:    InteractionModelRevision = 11
D (20153) chip[DMG]: }
D (20156) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3ffcd8f0 exchange 62767r
I (20166) chip[EM]: <<< [E:62767r S:45560 M:171200282] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I (20176) chip[IN]: (S) Sending msg 171200282 on secure session with LSID: 45560
D (20182) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 43)
I (20190) NimBLE: GATT procedure initiated: indicate; 
I (20194) NimBLE: att_handle=14

D (20202) chip[DMG]: Timed Request time limit 0x0000000000006DDF: handler 0x3ffcd8f0 exchange 62767r
I (20295) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (20296) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (20304) chip[EM]: >>> [E:62767r S:45560 M:146367030] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (20314) chip[EM]: Found matching exchange: 62767r, Delegate: 0x3ffcd8f0
D (20320) chip[DMG]: Timed following action arrived at 0x0000000000004745: handler 0x3ffcd8f0 exchange 62767r
D (20330) chip[DMG]: Handing timed invoke to IM engine: handler 0x3ffcd8f0 exchange 62767r
D (20338) chip[DMG]: InvokeRequestMessage =
D (20342) chip[DMG]: {
D (20344) chip[DMG]:    suppressResponse = false, 
D (20348) chip[DMG]:    timedRequest = true, 
D (20352) chip[DMG]:    InvokeRequests =
D (20355) chip[DMG]:    [
D (20358) chip[DMG]:        CommandDataIB =
D (20360) chip[DMG]:        {
D (20363) chip[DMG]:            CommandPathIB =
D (20366) chip[DMG]:            {
D (20369) chip[DMG]:                EndpointId = 0x0,
D (20372) chip[DMG]:                ClusterId = 0x30,
D (20376) chip[DMG]:                CommandId = 0x2,
D (20380) chip[DMG]:            },
D (20382) chip[DMG]:            
D (20385) chip[DMG]:            CommandFields = 
D (20388) chip[DMG]:            {
D (20391) chip[DMG]:                0x0 = 0, 
D (20394) chip[DMG]:                0x1 = "US" (2 chars), 
D (20398) chip[DMG]:                0x2 = 1, 
D (20402) chip[DMG]:            },
D (20404) chip[DMG]:        },
D (20406) chip[DMG]:        
D (20408) chip[DMG]:    ],
D (20410) chip[DMG]:    
D (20412) chip[DMG]:    InteractionModelRevision = 11
D (20418) chip[DMG]: },
D (20420) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
I (20428) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x00000030
I (20437) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (20447) chip[DL]: NVS set: chip-config/country-code = "US"
I (20447) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
D (20459) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86202
D (20465) chip[DMG]: Command handler moving to [ Preparing]
D (20471) chip[DMG]: Command handler moving to [AddingComm]
D (20475) chip[DMG]: Command handler moving to [AddedComma]
D (20481) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (20490) chip[EM]: <<< [E:62767r S:45560 M:171200283] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (20501) chip[IN]: (S) Sending msg 171200283 on secure session with LSID: 45560
D (20507) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (20515) NimBLE: GATT procedure initiated: indicate; 
I (20519) NimBLE: att_handle=14

D (20528) chip[DMG]: Command handler moving to [CommandSen]
D (20529) chip[DMG]: Command handler moving to [AwaitingDe]
I (20611) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (20611) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (20619) chip[EM]: >>> [E:62768r S:45560 M:146367031] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (20629) chip[EM]: Handling via exchange: 62768r, Delegate: 0x3ffcd4d4
D (20635) chip[DMG]: InvokeRequestMessage =
D (20639) chip[DMG]: {
D (20641) chip[DMG]:    suppressResponse = false, 
D (20645) chip[DMG]:    timedRequest = false, 
D (20649) chip[DMG]:    InvokeRequests =
D (20653) chip[DMG]:    [
D (20655) chip[DMG]:        CommandDataIB =
D (20658) chip[DMG]:        {
D (20661) chip[DMG]:            CommandPathIB =
D (20663) chip[DMG]:            {
D (20667) chip[DMG]:                EndpointId = 0x0,
D (20670) chip[DMG]:                ClusterId = 0x3e,
D (20673) chip[DMG]:                CommandId = 0x2,
D (20677) chip[DMG]:            },
D (20680) chip[DMG]:            
D (20683) chip[DMG]:            CommandFields = 
D (20685) chip[DMG]:            {
D (20689) chip[DMG]:                0x0 = 1, 
D (20691) chip[DMG]:            },
D (20693) chip[DMG]:        },
D (20697) chip[DMG]:        
D (20699) chip[DMG]:    ],
D (20701) chip[DMG]:    
D (20703) chip[DMG]:    InteractionModelRevision = 11
D (20707) chip[DMG]: },
D (20709) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I (20717) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E
I (20727) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
D (20733) chip[DMG]: Command handler moving to [ Preparing]
D (20738) chip[DMG]: Command handler moving to [AddingComm]
D (20743) chip[DMG]: Command handler moving to [AddedComma]
D (20749) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (20759) chip[EM]: <<< [E:62768r S:45560 M:171200284] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (20767) chip[IN]: (S) Sending msg 171200284 on secure session with LSID: 45560
D (20775) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (20783) NimBLE: GATT procedure initiated: indicate; 
I (20787) NimBLE: att_handle=14

D (20795) chip[DMG]: Command handler moving to [CommandSen]
D (20795) chip[DMG]: Command handler moving to [AwaitingDe]
I (20879) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (20881) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (20885) NimBLE: GATT procedure initiated: indicate; 
I (20890) NimBLE: att_handle=14

I (20969) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (20971) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 78)
I (20975) NimBLE: GATT procedure initiated: indicate; 
I (20979) NimBLE: att_handle=14

I (21060) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (21061) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (21069) chip[EM]: >>> [E:62769r S:45560 M:146367032] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (21079) chip[EM]: Handling via exchange: 62769r, Delegate: 0x3ffcd4d4
D (21085) chip[DMG]: InvokeRequestMessage =
D (21089) chip[DMG]: {
D (21091) chip[DMG]:    suppressResponse = false, 
D (21095) chip[DMG]:    timedRequest = false, 
D (21099) chip[DMG]:    InvokeRequests =
D (21103) chip[DMG]:    [
D (21105) chip[DMG]:        CommandDataIB =
D (21108) chip[DMG]:        {
D (21111) chip[DMG]:            CommandPathIB =
D (21113) chip[DMG]:            {
D (21117) chip[DMG]:                EndpointId = 0x0,
D (21120) chip[DMG]:                ClusterId = 0x3e,
D (21123) chip[DMG]:                CommandId = 0x2,
D (21127) chip[DMG]:            },
D (21130) chip[DMG]:            
D (21133) chip[DMG]:            CommandFields = 
D (21135) chip[DMG]:            {
D (21139) chip[DMG]:                0x0 = 2, 
D (21141) chip[DMG]:            },
D (21143) chip[DMG]:        },
D (21146) chip[DMG]:        
D (21149) chip[DMG]:    ],
D (21151) chip[DMG]:    
D (21153) chip[DMG]:    InteractionModelRevision = 11
D (21157) chip[DMG]: },
D (21159) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I (21167) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E
I (21177) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
D (21183) chip[DMG]: Command handler moving to [ Preparing]
D (21188) chip[DMG]: Command handler moving to [AddingComm]
D (21193) chip[DMG]: Command handler moving to [AddedComma]
D (21199) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (21209) chip[EM]: <<< [E:62769r S:45560 M:171200285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (21217) chip[IN]: (S) Sending msg 171200285 on secure session with LSID: 45560
D (21225) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (21233) NimBLE: GATT procedure initiated: indicate; 
I (21237) NimBLE: att_handle=14

D (21245) chip[DMG]: Command handler moving to [CommandSen]
D (21245) chip[DMG]: Command handler moving to [AwaitingDe]
I (21374) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (21376) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (21380) NimBLE: GATT procedure initiated: indicate; 
I (21385) NimBLE: att_handle=14

I (21464) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (21466) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 48)
I (21470) NimBLE: GATT procedure initiated: indicate; 
I (21474) NimBLE: att_handle=14

I (21556) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (21556) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (21564) chip[EM]: >>> [E:62770r S:45560 M:146367033] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (21574) chip[EM]: Handling via exchange: 62770r, Delegate: 0x3ffcd4d4
D (21580) chip[DMG]: InvokeRequestMessage =
D (21584) chip[DMG]: {
D (21586) chip[DMG]:    suppressResponse = false, 
D (21590) chip[DMG]:    timedRequest = false, 
D (21594) chip[DMG]:    InvokeRequests =
D (21598) chip[DMG]:    [
D (21600) chip[DMG]:        CommandDataIB =
D (21603) chip[DMG]:        {
D (21606) chip[DMG]:            CommandPathIB =
D (21608) chip[DMG]:            {
D (21612) chip[DMG]:                EndpointId = 0x0,
D (21615) chip[DMG]:                ClusterId = 0x3e,
D (21618) chip[DMG]:                CommandId = 0x0,
D (21622) chip[DMG]:            },
D (21625) chip[DMG]:            
D (21628) chip[DMG]:            CommandFields = 
D (21630) chip[DMG]:            {
D (21634) chip[DMG]:                0x0 = [
D (21636) chip[DMG]:                        0x2d, 0xe6, 0x17, 0x0c, 0x99, 0x26, 0x70, 0x79, 0x00, 0x00, 0x01, 0x8b, 0x8d, 0x2e, 0x58, 0x74, 0x01, 0xfb, 0x54, 0x10, 0xf0, 0x19, 0xd1, 0xee, 0x08, 0xfa, 0x4e, 0x34, 0xf8, 0x66, 0xf2, 0x37, 
D (21656) chip[DMG]:                ] (32 bytes)
D (21658) chip[DMG]:            },
D (21662) chip[DMG]:        },
D (21664) chip[DMG]:        
D (21666) chip[DMG]:    ],
D (21668) chip[DMG]:    
D (21670) chip[DMG]:    InteractionModelRevision = 11
D (21674) chip[DMG]: },
D (21678) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I (21685) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E
I (21694) chip[ZCL]: OpCreds: Received an AttestationRequest command
I (22314) chip[ZCL]: OpCreds: AttestationRequest successful.
D (22316) chip[DMG]: Command handler moving to [ Preparing]
D (22316) chip[DMG]: Command handler moving to [AddingComm]
D (22320) chip[DMG]: Command handler moving to [AddedComma]
D (22325) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (22334) chip[EM]: <<< [E:62770r S:45560 M:171200286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (22344) chip[IN]: (S) Sending msg 171200286 on secure session with LSID: 45560
D (22351) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (22359) NimBLE: GATT procedure initiated: indicate; 
I (22363) NimBLE: att_handle=14

D (22368) chip[DMG]: Command handler moving to [CommandSen]
D (22372) chip[DMG]: Command handler moving to [AwaitingDe]
E (22377) chip[DL]: Long dispatch time: 815 ms, for event type 7
I (22499) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (22501) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (22505) NimBLE: GATT procedure initiated: indicate; 
I (22510) NimBLE: att_handle=14

I (22589) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (22591) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 235)
I (22595) NimBLE: GATT procedure initiated: indicate; 
I (22600) NimBLE: att_handle=14

I (22681) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (22681) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (22689) chip[EM]: >>> [E:62771r S:45560 M:146367034] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (22699) chip[EM]: Handling via exchange: 62771r, Delegate: 0x3ffcd4d4
D (22705) chip[DMG]: InvokeRequestMessage =
D (22709) chip[DMG]: {
D (22711) chip[DMG]:    suppressResponse = false, 
D (22715) chip[DMG]:    timedRequest = false, 
D (22719) chip[DMG]:    InvokeRequests =
D (22723) chip[DMG]:    [
D (22725) chip[DMG]:        CommandDataIB =
D (22728) chip[DMG]:        {
D (22731) chip[DMG]:            CommandPathIB =
D (22733) chip[DMG]:            {
D (22737) chip[DMG]:                EndpointId = 0x0,
D (22740) chip[DMG]:                ClusterId = 0x3e,
D (22743) chip[DMG]:                CommandId = 0x4,
D (22747) chip[DMG]:            },
D (22750) chip[DMG]:            
D (22753) chip[DMG]:            CommandFields = 
D (22755) chip[DMG]:            {
D (22759) chip[DMG]:                0x0 = [
D (22761) chip[DMG]:                        0x7a, 0x14, 0x67, 0x55, 0x72, 0x85, 0x7f, 0x2b, 0x00, 0x00, 0x01, 0x8b, 0x8d, 0x2e, 0x58, 0x74, 0x01, 0xfb, 0x54, 0x10, 0xf0, 0xc5, 0x34, 0x0e, 0x5e, 0xf2, 0x6c, 0x7c, 0xe6, 0xd5, 0xa0, 0xc1, 
D (22781) chip[DMG]:                ] (32 bytes)
D (22783) chip[DMG]:                0x1 = false, 
D (22787) chip[DMG]:            },
D (22789) chip[DMG]:        },
D (22792) chip[DMG]:        
D (22795) chip[DMG]:    ],
D (22797) chip[DMG]:    
D (22799) chip[DMG]:    InteractionModelRevision = 11
D (22803) chip[DMG]: },
D (22805) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I (22813) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x0000003E
I (22823) chip[ZCL]: OpCreds: Received a CSRRequest command
D (22827) chip[ZCL]: OpCreds: Finding fabric with fabricIndex 0x0
I (24045) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
I (24662) chip[ZCL]: OpCreds: CSRRequest successful.
D (24663) chip[DMG]: Command handler moving to [ Preparing]
D (24663) chip[DMG]: Command handler moving to [AddingComm]
D (24667) chip[DMG]: Command handler moving to [AddedComma]
D (24673) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (24683) chip[EM]: <<< [E:62771r S:45560 M:171200287] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (24692) chip[IN]: (S) Sending msg 171200287 on secure session with LSID: 45560
D (24699) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244)
I (24707) NimBLE: GATT procedure initiated: indicate; 
I (24711) NimBLE: att_handle=14

D (24719) chip[DMG]: Command handler moving to [CommandSen]
D (24719) chip[DMG]: Command handler moving to [AwaitingDe]
E (24725) chip[DL]: Long dispatch time: 2038 ms, for event type 7
I (24839) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
D (24841) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 138)
I (24845) NimBLE: GATT procedure initiated: indicate; 
I (24850) NimBLE: att_handle=14

I (24929) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (26057) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (26146) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (26151) chip[EM]: >>> [E:62772r S:45560 M:146367035] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (26155) chip[EM]: Handling via exchange: 62772r, Delegate: 0x3ffcd4d4
D (26162) chip[DMG]: InvokeRequestMessage =
D (26165) chip[DMG]: {
D (26168) chip[DMG]:    suppressResponse = false, 
D (26172) chip[DMG]:    timedRequest = false, 
D (26176) chip[DMG]:    InvokeRequests =
D (26179) chip[DMG]:    [
D (26182) chip[DMG]:        CommandDataIB =
D (26184) chip[DMG]:        {
D (26186) chip[DMG]:            CommandPathIB =
D (26190) chip[DMG]:            {
D (26192) chip[DMG]:                EndpointId = 0x0,
D (26196) chip[DMG]:                ClusterId = 0x3e,
D (26200) chip[DMG]:                CommandId = 0xb,
D (26204) chip[DMG]:            },
D (26206) chip[DMG]:            
D (26208) chip[DMG]:            CommandFields = 
D (26212) chip[DMG]:            {
D (26214) chip[DMG]:                0x0 = [
D (26218) chip[DMG]:                        ... (byte string too long) ...
D (26223) chip[DMG]:                ] (304 bytes)
D (26226) chip[DMG]:            },
D (26228) chip[DMG]:        },
D (26232) chip[DMG]:        
D (26234) chip[DMG]:    ],
D (26236) chip[DMG]:    
D (26238) chip[DMG]:    InteractionModelRevision = 11
D (26242) chip[DMG]: },
D (26244) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I (26252) esp_matter_command: Received command 0x0000000B for endpoint 0x0000's cluster 0x0000003E
I (26262) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command
I (27496) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful.
D (27497) chip[DMG]: Command handler moving to [ Preparing]
D (27498) chip[DMG]: Command handler moving to [AddingComm]
D (27502) chip[DMG]: Command handler moving to [AddedComma]
D (27508) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (27516) chip[EM]: <<< [E:62772r S:45560 M:171200288] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I (27526) chip[IN]: (S) Sending msg 171200288 on secure session with LSID: 45560
D (27534) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 68)
I (27542) NimBLE: GATT procedure initiated: indicate; 
I (27546) NimBLE: att_handle=14

D (27554) chip[DMG]: Command handler moving to [CommandSen]
D (27555) chip[DMG]: Command handler moving to [AwaitingDe]
E (27560) chip[DL]: Long dispatch time: 1412 ms, for event type 7
I (27631) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (27633) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (27723) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (27855) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (27861) chip[EM]: >>> [E:62773r S:45560 M:146367036] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D (27864) chip[EM]: Handling via exchange: 62773r, Delegate: 0x3ffcd4d4
D (27871) chip[DMG]: InvokeRequestMessage =
D (27875) chip[DMG]: {
D (27877) chip[DMG]:    suppressResponse = false, 
D (27881) chip[DMG]:    timedRequest = false, 
D (27885) chip[DMG]:    InvokeRequests =
D (27889) chip[DMG]:    [
D (27891) chip[DMG]:        CommandDataIB =
D (27893) chip[DMG]:        {
D (27896) chip[DMG]:            CommandPathIB =
D (27899) chip[DMG]:            {
D (27902) chip[DMG]:                EndpointId = 0x0,
D (27905) chip[DMG]:                ClusterId = 0x3e,
D (27909) chip[DMG]:                CommandId = 0x6,
D (27913) chip[DMG]:            },
D (27915) chip[DMG]:            
D (27918) chip[DMG]:            CommandFields = 
D (27921) chip[DMG]:            {
D (27924) chip[DMG]:                0x0 = [
D (27927) chip[DMG]:                        ... (byte string too long) ...
D (27932) chip[DMG]:                ] (305 bytes)
D (27935) chip[DMG]:                0x1 = [
D (27939) chip[DMG]:                        ... (byte string too long) ...
D (27943) chip[DMG]:                ] (308 bytes)
D (27947) chip[DMG]:                0x2 = [
D (27951) chip[DMG]:                        0x5f, 0x41, 0x47, 0x69, 0xf0, 0xc0, 0xf3, 0xee, 0x42, 0xef, 0xcc, 0x2f, 0x6b, 0x14, 0x07, 0xda, 
D (27961) chip[DMG]:                ] (16 bytes)
D (27965) chip[DMG]:                0x3 = 18446744060824715265, 
D (27969) chip[DMG]:                0x4 = 24582, 
D (27973) chip[DMG]:            },
D (27975) chip[DMG]:        },
D (27977) chip[DMG]:        
D (27979) chip[DMG]:    ],
D (27981) chip[DMG]:    
D (27983) chip[DMG]:    InteractionModelRevision = 11
D (27989) chip[DMG]: },
D (27991) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I (27999) esp_matter_command: Received command 0x00000006 for endpoint 0x0000's cluster 0x0000003E
I (28007) chip[ZCL]: OpCreds: Received an AddNOC command
I (28017) chip[FP]: Validating NOC chain
I (30463) chip[FP]: NOC chain validation successful
I (30463) chip[FP]: Added new fabric at index: 0x1
I (30464) chip[FP]: Assigned compressed fabric ID: 0x1C45FDE78A95CE1D, node ID: 0x0000000075EBCF97
I (30471) chip[TS]: Last Known Good Time: 2023-07-24T23:38:47
I (30475) chip[TS]: New proposed Last Known Good Time: 2023-11-01T23:18:28
I (30483) chip[TS]: Updating pending Last Known Good Time to 2023-11-01T23:18:28
D (30489) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719a
D (30497) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719b
D (30545) chip[EVL]: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000655F
I (30550) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
D (30560) chip[DL]: Using wifi MAC for hostname
I (30564) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (30572) chip[DIS]: Responding with _matter._tcp.local
D (30576) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (30584) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (30592) chip[DIS]: Responding with 0C8B9596B688.local
D (30596) chip[DIS]: Responding with 0C8B9596B688.local
D (30602) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (30608) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (30620) chip[DIS]: mDNS service published: _matter._tcp
D (30624) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719c
D (30632) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719d
D (30638) chip[DMG]: Command handler moving to [ Preparing]
D (30644) chip[DMG]: Command handler moving to [AddingComm]
D (30649) chip[DMG]: Command handler moving to [AddedComma]
I (30654) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC
D (30662) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (30670) chip[EM]: <<< [E:62773r S:45560 M:171200289] (S) Msg TX to 1:FFFFFFFB00000000 [CE1D] --- Type 0001:09 (IM:InvokeCommandResponse)
I (30680) chip[IN]: (S) Sending msg 171200289 on secure session with LSID: 45560
D (30688) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (30696) NimBLE: GATT procedure initiated: indicate; 
I (30700) NimBLE: att_handle=14

D (30709) chip[DMG]: Command handler moving to [CommandSen]
D (30709) chip[DMG]: Command handler moving to [AwaitingDe]
E (30713) chip[DL]: Long dispatch time: 2856 ms, for event type 7
Fabric is updated
I (30781) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (30781) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (30790) chip[EM]: >>> [E:62774r S:45560 M:146367037] (S) Msg RX from 1:FFFFFFFB00000000 [CE1D] --- Type 0001:08 (IM:InvokeCommandRequest)
D (30798) chip[EM]: Handling via exchange: 62774r, Delegate: 0x3ffcd4d4
D (30806) chip[DMG]: InvokeRequestMessage =
D (30808) chip[DMG]: {
D (30810) chip[DMG]:    suppressResponse = false, 
D (30816) chip[DMG]:    timedRequest = false, 
D (30820) chip[DMG]:    InvokeRequests =
D (30822) chip[DMG]:    [
D (30824) chip[DMG]:        CommandDataIB =
D (30828) chip[DMG]:        {
D (30830) chip[DMG]:            CommandPathIB =
D (30834) chip[DMG]:            {
D (30836) chip[DMG]:                EndpointId = 0x0,
D (30840) chip[DMG]:                ClusterId = 0x31,
D (30844) chip[DMG]:                CommandId = 0x2,
D (30848) chip[DMG]:            },
D (30850) chip[DMG]:            
D (30852) chip[DMG]:            CommandFields = 
D (30856) chip[DMG]:            {
D (30858) chip[DMG]:                0x0 = [
D (30862) chip[DMG]:                        0x70, 0x69, 0x6e, 0x67, 
D (30866) chip[DMG]:                ] (4 bytes)
D (30870) chip[DMG]:                0x1 = [
D (30872) chip[DMG]:                        0x73, 0x61, 0x79, 0x20, 0x70, 0x6c, 0x65, 0x61, 0x73, 0x65, 
D (30880) chip[DMG]:                ] (10 bytes)
D (30884) chip[DMG]:                0x2 = 1, 
D (30886) chip[DMG]:            },
D (30889) chip[DMG]:        },
D (30892) chip[DMG]:        
D (30894) chip[DMG]:    ],
D (30896) chip[DMG]:    
D (30898) chip[DMG]:    InteractionModelRevision = 11
D (30902) chip[DMG]: },
D (30905) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0002
D (30914) chip[DMG]: Command handler moving to [ Preparing]
D (30918) chip[DMG]: Command handler moving to [AddingComm]
D (30924) chip[DMG]: Command handler moving to [AddedComma]
I (30928) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
D (30940) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86203
D (30946) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (30955) chip[EM]: <<< [E:62774r S:45560 M:171200290] (S) Msg TX to 1:FFFFFFFB00000000 [CE1D] --- Type 0001:09 (IM:InvokeCommandResponse)
I (30966) chip[IN]: (S) Sending msg 171200290 on secure session with LSID: 45560
D (30973) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (30980) NimBLE: GATT procedure initiated: indicate; 
I (30986) NimBLE: att_handle=14

D (30992) chip[DMG]: Command handler moving to [CommandSen]
D (30994) chip[DMG]: Command handler moving to [AwaitingDe]
I (31095) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (31096) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (31104) chip[EM]: >>> [E:62775r S:45560 M:146367038] (S) Msg RX from 1:FFFFFFFB00000000 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (31112) chip[EM]: Handling via exchange: 62775r, Delegate: 0x3ffcd4d4
D (31118) chip[IM]: Received Read request
D (31122) chip[DMG]: ReadRequestMessage =
D (31126) chip[DMG]: {
D (31128) chip[DMG]:    AttributePathIBs =
D (31132) chip[DMG]:    [
D (31134) chip[DMG]:        AttributePathIB =
D (31138) chip[DMG]:        {
D (31140) chip[DMG]:            Endpoint = 0x0,
D (31143) chip[DMG]:            Cluster = 0x31,
D (31146) chip[DMG]:            Attribute = 0x0000_0003,
D (31150) chip[DMG]:        }
D (31153) chip[DMG]:            
D (31156) chip[DMG]:    ],
D (31158) chip[DMG]:        
D (31160) chip[DMG]:    isFabricFiltered = true, 
D (31164) chip[DMG]:    InteractionModelRevision = 11
D (31168) chip[DMG]: },
D (31172) chip[DMG]: IM RH moving to [GeneratingReports]
D (31176) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (31185) chip[DMG]: <RE:Run> Cluster 31, Attribute 3 is dirty
D (31190) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (31200) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (31207) chip[EM]: <<< [E:62775r S:45560 M:171200291] (S) Msg TX to 1:FFFFFFFB00000000 [CE1D] --- Type 0001:05 (IM:ReportData)
I (31218) chip[IN]: (S) Sending msg 171200291 on secure session with LSID: 45560
D (31224) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71)
I (31232) NimBLE: GATT procedure initiated: indicate; 
I (31236) NimBLE: att_handle=14

D (31244) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (31245) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (31252) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (31258) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (31321) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (31321) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (31330) chip[EM]: >>> [E:62776r S:45560 M:146367039] (S) Msg RX from 1:FFFFFFFB00000000 [CE1D] --- Type 0001:08 (IM:InvokeCommandRequest)
D (31338) chip[EM]: Handling via exchange: 62776r, Delegate: 0x3ffcd4d4
D (31346) chip[DMG]: InvokeRequestMessage =
D (31348) chip[DMG]: {
D (31350) chip[DMG]:    suppressResponse = false, 
D (31356) chip[DMG]:    timedRequest = false, 
D (31360) chip[DMG]:    InvokeRequests =
D (31362) chip[DMG]:    [
D (31364) chip[DMG]:        CommandDataIB =
D (31368) chip[DMG]:        {
D (31370) chip[DMG]:            CommandPathIB =
D (31374) chip[DMG]:            {
D (31376) chip[DMG]:                EndpointId = 0x0,
D (31380) chip[DMG]:                ClusterId = 0x31,
D (31384) chip[DMG]:                CommandId = 0x6,
D (31388) chip[DMG]:            },
D (31390) chip[DMG]:            
D (31392) chip[DMG]:            CommandFields = 
D (31396) chip[DMG]:            {
D (31398) chip[DMG]:                0x0 = [
D (31402) chip[DMG]:                        0x70, 0x69, 0x6e, 0x67, 
D (31406) chip[DMG]:                ] (4 bytes)
D (31410) chip[DMG]:                0x1 = 1, 
D (31412) chip[DMG]:            },
D (31415) chip[DMG]:        },
D (31418) chip[DMG]:        
D (31420) chip[DMG]:    ],
D (31422) chip[DMG]:    
D (31424) chip[DMG]:    InteractionModelRevision = 11
D (31428) chip[DMG]: },
D (31431) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
I (31438) chip[NP]: ESP NetworkCommissioningDelegate: SSID: ping
I (31446) chip[DL]: WiFi station mode change: Enabled -> Disabled
I (31470) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP
I (31476) chip[DL]: WiFi station mode change: Disabled -> Enabled
D (31476) chip[DMG]: Decreasing reference count for CommandHandler, remaining 1
I (31480) chip[DL]: Attempting to connect WiFi station interface
I (31487) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (31491) chip[DL]: Done driving station state, nothing else to do...
I (32091) chip[DL]: Done driving station state, nothing else to do...
I (32091) chip[DL]: Done driving station state, nothing else to do...
I (32092) chip[DL]: WIFI_EVENT_AP_START
I (32095) chip[DL]: WiFi AP state change: NotActive -> Active
I (32101) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (32110) chip[DL]: WiFi AP state change: Active -> Deactivating
I (32113) chip[DL]: WIFI_EVENT_AP_STOP
I (32115) chip[DL]: WiFi AP state change: Deactivating -> NotActive
syncing network time
State: entered main_region_SyncNetworkTime
I (32191) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (32191) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (32193) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (32199) chip[DL]: WiFi station interface connected
D (32205) chip[DMG]: Command handler moving to [ Preparing]
D (32209) chip[DMG]: Command handler moving to [AddingComm]
D (32213) chip[DMG]: Command handler moving to [AddedComma]
I (32219) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
D (32230) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86204
D (32237) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (32245) chip[EM]: <<< [E:62776r S:45560 M:171200292] (S) Msg TX to 1:FFFFFFFB00000000 [CE1D] --- Type 0001:09 (IM:InvokeCommandResponse)
I (32257) chip[IN]: (S) Sending msg 171200292 on secure session with LSID: 45560
D (32263) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 70)
I (32271) NimBLE: GATT procedure initiated: indicate; 
I (32275) NimBLE: att_handle=14

D (32282) chip[DMG]: Command handler moving to [CommandSen]
D (32284) chip[DMG]: Command handler moving to [AwaitingDe]
I (32290) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
D (32297) chip[EVL]: LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0036 event id: 0x2 Sys timestamp: 0x0000000000006C37
I (32310) chip[DL]: Done driving station state, nothing else to do...
D (32317) chip[DL]: Using wifi MAC for hostname
I (32320) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (32328) chip[DIS]: Responding with _matter._tcp.local
D (32332) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (32340) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (32348) chip[DIS]: Responding with 0C8B9596B688.local
D (32353) chip[DIS]: Responding with 0C8B9596B688.local
D (32358) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (32365) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (32376) chip[DIS]: mDNS service published: _matter._tcp
I (32381) chip[SVR]: Operational advertising enabled
I (32386) chip[DL]: Updating advertising data
I (32490) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 
I (32739) chip[DL]: IP_EVENT_STA_GOT_IP
I (32739) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.86.61/255.255.255.0 gateway 192.168.86.1
I (32743) chip[DL]: IPv4 Internet connectivity ESTABLISHED
Interface IP Address changed
I (32757) chip[DIS]: Updating services using commissioning mode 0
I (32761) chip[DIS]: CHIP minimal mDNS started advertising.
D (32768) chip[DL]: Using wifi MAC for hostname
I (32769) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (32773) chip[DIS]: Responding with _matter._tcp.local
D (32777) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (32785) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (32793) chip[DIS]: Responding with 0C8B9596B688.local
D (32798) chip[DIS]: Responding with 0C8B9596B688.local
D (32803) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (32810) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (32822) chip[DIS]: mDNS service published: _matter._tcp
I (33025) chip[EM]: >>> [E:62777r S:0 M:219517858] (U) Msg RX from 0:A97FCE2608A0EDDA [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D (33027) chip[EM]: Handling via exchange: 62777r, Delegate: 0x3ffd2d38
I (33033) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3ffd3980
I (33041) chip[EM]: <<< [E:62777r S:0 M:93728566 (Ack:219517858)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (33055) chip[IN]: (U) Sending msg 93728566 to IP address 'UDP:192.168.86.20%st1:50803'
D (33065) chip[EM]: Flushed pending ack for MessageCounter:219517858 on exchange 62777r
I (33071) chip[SC]: Received Sigma1 msg
D (33074) chip[SC]: Peer assigned session key ID 61557
I (33092) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000075EBCF97
I (33527) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0
I (33528) chip[DL]: CHIPoBLE unsubscribe received
I (33531) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213)
I (34589) chip[EM]: <<< [E:62777r S:0 M:93728567 (Ack:219517858)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I (34592) chip[IN]: (U) Sending msg 93728567 to IP address 'UDP:192.168.86.20%st1:50803'
I (34601) chip[SC]: Sent Sigma2 msg
E (34603) chip[DL]: Long dispatch time: 1578 ms, for event type 3
I (34609) chip[DL]: IP_EVENT_GOT_IP6
I (34611) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:0e8b:95ff:fe96:b688
D (34623) chip[IN]: Clearing BLE pending packets.
I (34627) chip[BLE]: Releasing end point's BLE connection back to application.
I (34633) NimBLE: GAP procedure initiated: stop advertising.

D (34746) Timer: Timer not stopped
D (34746) Timer: Timer not stopped
D (34746) Timer: Timer not stopped
I (34754) esp_matter_core: BLE deinit successful and memory reclaimed
Interface IP Address changed
I (34756) chip[DIS]: Updating services using commissioning mode 0
I (34763) chip[DIS]: CHIP minimal mDNS started advertising.
D (34770) chip[DL]: Using wifi MAC for hostname
I (34770) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (34776) chip[DIS]: Responding with _matter._tcp.local
D (34780) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (34788) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (34796) chip[DIS]: Responding with 0C8B9596B688.local
D (34801) chip[DIS]: Responding with 0C8B9596B688.local
D (34806) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (34813) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (34827) chip[DIS]: mDNS service published: _matter._tcp
I (34830) chip[SVR]: Server initialization complete
I (34834) chip[DIS]: Updating services using commissioning mode 0
I (34840) chip[DIS]: CHIP minimal mDNS started advertising.
D (34850) chip[DL]: Using wifi MAC for hostname
I (34850) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (34857) chip[DIS]: Responding with _matter._tcp.local
D (34861) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (34869) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (34877) chip[DIS]: Responding with 0C8B9596B688.local
D (34882) chip[DIS]: Responding with 0C8B9596B688.local
D (34887) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (34894) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (34908) chip[DIS]: mDNS service published: _matter._tcp
I (34913) chip[IM]: No subscriptions to resume
I (34916) chip[EM]: >>> [E:62777r S:0 M:219517859 (Ack:93728567)] (U) Msg RX from 0:A97FCE2608A0EDDA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (34928) chip[EM]: Found matching exchange: 62777r, Delegate: 0x3ffd2d54
D (34934) chip[EM]: Rxd Ack; Removing MessageCounter:93728567 from Retrans Table on exchange 62777r
I (34943) chip[EM]: >>> [E:62777r S:0 M:219517860 (Ack:93728567)] (U) Msg RX from 0:A97FCE2608A0EDDA [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D (34956) chip[EM]: Found matching exchange: 62777r, Delegate: 0x3ffd2d54
D (34963) chip[EM]: CHIP MessageCounter:93728567 not in RetransTable on exchange 62777r
I (34971) chip[EM]: <<< [E:62777r S:0 M:93728568 (Ack:219517860)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (34984) chip[IN]: (U) Sending msg 93728568 to IP address 'UDP:192.168.86.20%st1:50803'
D (34993) chip[EM]: Flushed pending ack for MessageCounter:219517860 on exchange 62777r
I (35000) chip[SC]: Received Sigma3 msg
E (35007) chip[SC]: The device does not support GetClock_RealTimeMS() API: 6c.  Falling back to Last Known Good UTC Time
E (36349) chip[DL]: Long dispatch time: 1334 ms, for event type 2
D (36360) chip[DL]: Using hash:accaec5f6ac0c34 for nvs key:f/1/s/000000005356B4C2
D (36364) chip[DL]: Using hash:00f9871538fa9e7 for nvs key:g/s/BQpIEH30QHsT48nD/AY49A==
D (36368) chip[SC]: Sending status report. Protocol code 0, exchange 62777
I (36372) chip[EM]: <<< [E:62777r S:0 M:93728569 (Ack:219517860)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (36385) chip[IN]: (U) Sending msg 93728569 to IP address 'UDP:192.168.86.20%st1:50803'
I (36395) chip[SC]: SecureSession[0x3ffd2180, LSID:45561]: State change 'kEstablishing' --> 'kActive'
D (36401) chip[IN]: SecureSession[0x3ffd2180]: Activated - Type:2 LSID:45561
D (36408) chip[IN]: New secure session activated for device <000000005356B4C2, 1>, LSID:45561 PSID:61557!
I (36417) chip[IN]: CASE Session established to peer: <000000005356B4C2, 1>
D (36425) chip[IN]: SecureSession[0x3ffd2238]: Allocated Type:2 LSID:45562
D (36431) chip[SC]: Allocated SecureSession (0x3ffd2238) - waiting for Sigma1 msg
Got time adjustment from NTP: 1698880723
I (36632) chip[EM]: >>> [E:62777r S:0 M:219517861 (Ack:93728569)] (U) Msg RX from 0:A97FCE2608A0EDDA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (36636) chip[EM]: Found matching exchange: 62777r, Delegate: 0x0
D (36642) chip[EM]: Rxd Ack; Removing MessageCounter:93728569 from Retrans Table on exchange 62777r
I (36652) chip[EM]: >>> [E:62778r S:45561 M:43933025] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (36662) chip[EM]: Handling via exchange: 62778r, Delegate: 0x3ffcd4d4
D (36668) chip[IM]: Received Read request
D (36672) chip[DMG]: ReadRequestMessage =
D (36676) chip[DMG]: {
D (36678) chip[DMG]:    AttributePathIBs =
D (36680) chip[DMG]:    [
D (36683) chip[DMG]:        AttributePathIB =
D (36686) chip[DMG]:        {
D (36689) chip[DMG]:            Endpoint = 0x0,
D (36692) chip[DMG]:            Cluster = 0x3c,
D (36696) chip[DMG]:            Attribute = 0x0000_0000,
D (36700) chip[DMG]:        }
D (36702) chip[DMG]:            
D (36704) chip[DMG]:    ],
D (36708) chip[DMG]:        
D (36710) chip[DMG]:    isFabricFiltered = true, 
D (36714) chip[DMG]:    InteractionModelRevision = 11
D (36718) chip[DMG]: },
D (36721) chip[DMG]: IM RH moving to [GeneratingReports]
D (36726) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (36734) chip[DMG]: <RE:Run> Cluster 3c, Attribute 0 is dirty
D (36740) chip[DMG]: Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D (36750) chip[DMG]: <RE> Sending report (payload has 36 bytes)...
I (36758) chip[EM]: <<< [E:62778r S:45561 M:226895683 (Ack:43933025)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (36768) chip[IN]: (S) Sending msg 226895683 on secure session with LSID: 45561
D (36778) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (36780) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (36788) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (36794) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (36802) chip[EM]: >>> [E:62778r S:45561 M:43933026 (Ack:226895683)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (36814) chip[EM]:Def Found matching exchange: 62778r, Delegate: 0x0
D (36819) chip[EM]: Rxd Ack; Removing MessageCounter:226895683 from Retrans Table on exchange 62778r
erring first firmware check until at least 24h from now
State: entered main_region_FirmwareCheck
Setting temperature attribute to 2350 (23.5C)
I (36851) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x00000000 is 2350 **********
D (36852) chip[DMG]: Endpoint 1, Cluster 0x0000_0402 update version to a95f8837
State: entered main_region_TemperatureSynced
State: entered main_region_SyncToRTC
I (36911) chip[SWU]: Stopping the watchdog timer
I (36911) chip[SWU]: Starting the periodic query timer, timeout: 86400 seconds
I (36911) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 0 **********
I (36922) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000002 is 1 **********
D (36933) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to cfd4380b
I (36940) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000003 is 0 **********
I (36950) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x00000003 is null **********
D (36961) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to cfd4380c
I (37316) chip[DL]: IP_EVENT_GOT_IP6
I (37316) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fd1f:f9eb:b31b:9b2c:0e8b:95ff:fe96:b688
Interface IP Address changed
I (37329) chip[DIS]: Updating services using commissioning mode 0
I (37330) chip[DIS]: CHIP minimal mDNS started advertising.
D (37339) chip[DL]: Using wifi MAC for hostname
I (37339) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (37344) chip[DIS]: Responding with _matter._tcp.local
D (37349) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (37356) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (37364) chip[DIS]: Responding with 0C8B9596B688.local
D (37369) chip[DIS]: Responding with 0C8B9596B688.local
D (37374) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (37381) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (37395) chip[DIS]: mDNS service published: _matter._tcp
State: entered main_region_DisplayClock
D (37642) chip[DIS]: SRV record already actively processed.
D (37644) chip[DIS]: SRV record already actively processed.
State: entered main_region_Sleep
E (37867) esp_matter_core: Node already exists
D (37871) esp_matter_core: Set val called with string with size 0
D (37871) esp_matter_core: Set val called with string with size 0
D (37874) esp_matter_core: Set val called with string with size 0
D (37880) esp_matter_core: Set val called with string with size 0
D (37886) esp_matter_core: Set val called with string with size 0
D (37892) esp_matter_core: Set val called with string with size 0
D (37898) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x28, attribute_id-0x6
D (37907) esp_matter_core: Set val called with string with size 0
D (37912) esp_matter_core: Set val called with string with size 0
D (37918) esp_matter_core: Set val called with string with size 0
D (37924) esp_matter_core: Set val called with string with size 0
D (37930) esp_matter_core: Set val called with string with size 0
D (37936) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x28, attribute_id-0x5
D (37945) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x28, attribute_id-0x5
D (37956) esp_matter_core: Set val called with string with size 0
D (37960) esp_matter_core: Set val called with string with size 0
D (37966) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x31, attribute_id-0x4
D (37974) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x31, attribute_id-0x4
D (37985) esp_matter_core: Set val called with string with size 0
D (37989) esp_matter_core: Set val called with string with size 0
D (37995) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x33, attribute_id-0x1
D (38004) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x33, attribute_id-0x1
D (38015) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x0
D (38022) esp_matter_core: Set val called with string with size 0
D (38028) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x0
D (38037) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x3
D (38048) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x3
D (38057) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x1
D (38064) esp_matter_core: Set val called with string with size 0
D (38070) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x1
D (38079) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x4
D (38087) esp_matter_core: Set val called with string with size 0
D (38093) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x3e, attribute_id-0x4
D (38103) esp_matter_core: read attribute from nvs: endpoint_id-0x2, cluster_id-0x3f, attribute_id-0x0
D (38111) esp_matter_core: Set val called with string with size 0
D (38117) esp_matter_core: Store attribute in nvs: endpoint_id-0x2, cluster_id-0x3f, attribute_id-0x0
D (38126) esp_matter_core: Set val called with string with size 0
D (38132) esp_matter_core: Set val called with string with size 0
D (38142) esp_matter_core: Set val called with string with size 0
D (38143) esp_matter_core: Set val called with string with size 0
D (38149) esp_matter_core: Set val called with string with size 0
D (38155) esp_matter_core: Set val called with string with size 0
E (38161) esp_matter_core: esp_matter has started
State: entered main_region_ConnectToNetwork
State: entered main_region_SyncNetworkTime
State: entered main_region_FirmwareCheck
Setting temperature attribute to 2362 (23.6C)
State: entered main_region_TemperatureSynced
State: entered main_region_SyncToRTC
I (38459) chip[EM]: >>> [E:62779r S:45561 M:43933027] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (38460) chip[EM]: Handling via exchange: 62779r, Delegate: 0x3ffcd4d4
D (38466) chip[IM]: Received Read request
D (38470) chip[DMG]: ReadRequestMessage =
D (38473) chip[DMG]: {
D (38475) chip[DMG]:    AttributePathIBs =
D (38479) chip[DMG]:    [
D (38481) chip[DMG]:        AttributePathIB =
D (38485) chip[DMG]:        {
D (38487) chip[DMG]:            Endpoint = 0x0,
D (38491) chip[DMG]:            Cluster = 0x28,
D (38494) chip[DMG]:            Attribute = 0x0000_000F,
D (38498) chip[DMG]:        }
D (38501) chip[DMG]:            
D (38503) chip[DMG]:    ],
D (38505) chip[DMG]:        
D (38507) chip[DMG]:    isFabricFiltered = true, 
D (38512) chip[DMG]:    InteractionModelRevision = 11
D (38516) chip[DMG]: },
D (38519) chip[DMG]: IM RH moving to [GeneratingReports]
D (38524) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (38533) chip[DMG]: <RE:Run> Cluster 28, Attribute f is dirty
D (38538) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000F (expanded=0)
D (38548) chip[DMG]: <RE> Sending report (payload has 33 bytes)...
I (38554) chip[EM]: <<< [E:62779r S:45561 M:226895684 (Ack:43933027)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (38566) chip[IN]: (S) Sending msg 226895684 on secure session with LSID: 45561
D (38574) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (38578) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (38586) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (38591) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (38599) chip[EM]: >>> [E:62779r S:45561 M:43933028 (Ack:226895684)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (38612) chip[EM]: Found matching exchange: 62779r, Delegate: 0x0
D (38618) chip[EM]: Rxd Ack; Removing MessageCounter:226895684 from Retrans Table on exchange 62779r
State: entered main_region_DisplayClock
I (39090) chip[EM]: >>> [E:62780r S:45561 M:43933029] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (39091) chip[EM]: Handling via exchange: 62780r, Delegate: 0x3ffcd4d4
D (39097) chip[IM]: Received Read request
D (39101) chip[DMG]: ReadRequestMessage =
D (39104) chip[DMG]: {
D (39106) chip[DMG]:    AttributePathIBs =
D (39110) chip[DMG]:    [
D (39112) chip[DMG]:        AttributePathIB =
D (39116) chip[DMG]:        {
D (39118) chip[DMG]:            Cluster = 0x1d,
D (39122) chip[DMG]:        }
D (39124) chip[DMG]:            
D (39126) chip[DMG]:        AttributePathIB =
D (39130) chip[DMG]:        {
D (39132) chip[DMG]:            Cluster = 0x28,
D (39136) chip[DMG]:        }
D (39138) chip[DMG]:            
D (39140) chip[DMG]:        AttributePathIB =
D (39144) chip[DMG]:        {
D (39146) chip[DMG]:            Cluster = 0x39,
D (39150) chip[DMG]:        }
D (39152) chip[DMG]:            
D (39154) chip[DMG]:        AttributePathIB =
D (39158) chip[DMG]:        {
D (39160) chip[DMG]:            Attribute = 0x0000_FFF9,
D (39164) chip[DMG]:        }
D (39167) chip[DMG]:            
D (39169) chip[DMG]:        AttributePathIB =
D (39173) chip[DMG]:        {
D (39175) chip[DMG]:            Attribute = 0x0000_FFFB,
D (39179) chip[DMG]:        }
D (39182) chip[DMG]:            
D (39184) chip[DMG]:        AttributePaStthIB =
D (39188) chip[DMG]:        {
D (39190) chip[DMG]:            Attribute = 0x0000_FFFC,
D (39194) chip[DMG]:        }
D (39196) chip[DMG]:            
D (39199) chip[DMG]:        AttributePathIB =
D (39202) chip[DMG]:        {
D (39205) chip[DMG]:            Attribute = 0x0000_FFFD,
D (39209) chip[DMG]:        }
D (39211) chip[DMG]:            
D (39213) chip[DMG]:    ],
D (39216) chip[DMG]:        
D (39218) chip[DMG]:    isFabricFiltered = true, 
D (39222) chip[DMG]:    InteractionModelRevision = 11
D (39227) chip[DMG]: },
D (39230) chip[DMG]: IM RH moving to [GeneratingReports]
D (39234) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (39243) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffd is dirty
D (39249) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
D (39259) chip[DMG]: <RE:Run> Cluster 1f, Attribute fffd is dirty
D (39264) chip[DMG]: Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
D (39274) chip[DMG]: <RE:Run> Cluster 28, Attribute fffd is dirty
D (39279) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39289) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000028's Attribute 0x0000FFFD is 1 **********
D (39300) chip[DMG]: <RE:Run> Cluster 30, Attribute fffd is dirty
D (39305) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39315) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x0000FFFD is 1 **********
D (39326) chip[DMG]: <RE:Run> Cluster 31, Attribute fffd is dirty
D (39331) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39341) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000031's Attribute 0x0000FFFD is 1 **********
D (39352) chip[DMG]: <RE:Run> Cluster 33, Attribute fffd is dirty
D (39358) chip[DMG]: Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39367) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000033's Attribute 0x0000FFFD is 1 **********
D (39378) chip[DMG]: <RE:Run> Cluster 3c, Attribute fffd is dirty
D (39384) chip[DMG]: Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39393) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000003C's Attribute 0x0000FFFD is 1 **********
D (39404) chip[DMG]: <RE:Run> Cluster 3e, Attribute fffd is dirty
D (39410) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39419) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000003E's Attribute 0x0000FFFD is 1 **********
D (39430) chip[DMG]: <RE:Run> Cluster 3f, Attribute fffd is dirty
D (39436) chip[DMG]: Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
D (39445) chip[DMG]: <RE:Run> Cluster 36, Attribute fffd is dirty
D (39451) chip[DMG]: Reading attribute: Cluster=0x0000_0036 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39461) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000036's Attribute 0x0000FFFD is 1 **********
D (39471) chip[DMG]: <RE:Run> Cluster 2a, Attribute fffd is dirty
D (39477) chip[DMG]: Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (39487) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x0000FFFD is 1 **********
D (39497) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffd is dirty
D (39503) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
D (39513) chip[DMG]: <RE:Run> Cluster 3, Attribute fffd is dirty
D (39518) chip[DMG]: Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
I (39528) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x0000FFFD is 4 **********
D (39539) chip[DMG]: <RE:Run> Cluster 402, Attribute fffd is dirty
D (39544) chip[DMG]: Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
I (39554) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x0000FFFD is 4 **********
D (39565) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffc is dirty
D (39570) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39580) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000001D's Attribute 0x0000FFFC is 0 **********
D (39591) chip[DMG]: <RE:Run> Cluster 1f, Attribute fffc is dirty
D (39596) chip[DMG]: Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39606) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000001F's Attribute 0x0000FFFC is 0 **********
D (39617) chip[DMG]: <RE:Run> Cluster 28, Attribute fffc is dirty
D (39622) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39632) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000028's Attribute 0x0000FFFC is 0 **********
D (39643) chip[DMG]: <RE:Run> Cluster 30, Attribute fffc is dirty
D (39648) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39658) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x0000FFFC is 0 **********
D (39669) chip[DMG]: <RE:Run> Cluster 31, Attribute fffc is dirty
D (39675) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D (39684) chip[DMG]: <RE:Run> Cluster 33, Attribute fffc is dirty
D (39690) chip[DMG]: Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39699) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000033's Attribute 0x0000FFFC is 0 **********
D (39710) chip[DMG]: <RE:Run> Cluster 3c, Attribute fffc is dirty
D (39716) chip[DMG]: Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39725) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000003C's Attribute 0x0000FFFC is 0 **********
D (39736) chip[DMG]: <RE:Run> Cluster 3e, Attribute fffc is dirty
D (39742) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39752) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000003E's Attribute 0x0000FFFC is 0 **********
D (39762) chip[DMG]: <RE:Run> Cluster 3f, Attribute fffc is dirty
D (39768) chip[DMG]: Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D (39778) chip[DMG]: <RE:Run> Cluster 36, Attribute fffc is dirty
D (39783) chip[DMG]: Reading attribute: Cluster=0x0000_0036 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39793) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000036's Attribute 0x0000FFFC is 0 **********
D (39804) chip[DMG]: <RE:Run> Cluster 2a, Attribute fffc is dirty
D (39809) chip[DMG]: Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (39819) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000002A's Attribute 0x0000FFFC is 0 **********
D (39830) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffc is dirty
D (39835) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
I (39845) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x0000001D's Attribute 0x0000FFFC is 0 **********
D (39856) chip[DMG]: <RE:Run> Cluster 3, Attribute fffc is dirty
D (39861) chip[DMG]: Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
I (39871) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x0000FFFC is 0 **********
D (39882) chip[DMG]: <RE:Run> Cluster 402, Attribute fffc is dirty
D (39887) chip[DMG]: Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
I (39897) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000402's Attribute 0x0000FFFC is 0 **********
D (39908) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffb is dirty
D (39913) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (39923) chip[DMG]: <RE:Run> Cluster 1f, Attribute fffb is dirty
D (39929) chip[DMG]: Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (39938) chip[DMG]: <RE:Run> Cluster 28, Attribute fffb is dirty
D (39944) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (39954) chip[DMG]: <RE:Run> Cluster 30, Attribute fffb is dirty
D (39959) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (39969) chip[DMG]: <RE:Run> Cluster 31, Attribute fffb is dirty
D (39975) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
E (39984) chip[DMG]: Error retrieving data from clusterId: 0x0000_0031, err = b
D (39991) chip[DMG]: <RE:Run> We cannot put more chunks into this report. Enable chunking.
D (39999) chip[DMG]: <RE> Sending report (payload has 998 bytes)...
I (40008) chip[EM]: <<< [E:62780r S:45561 M:226895685 (Ack:43933029)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (40018) chip[IN]: (S) Sending msg 226895685 on secure session with LSID: 45561
D (40026) chip[DMG]: IM RH moving to [AwaitingReportResponse]
D (40030) chip[DMG]: <RE> ReportsInFlight = 1 with readHandler 0, RE has more messages
E (40038) chip[DL]: Long dispatch time: 804 ms, for event type 3
D (40044) chip[IN]: Received a duplicate message with MessageCounter:43933029 on exchange 62780r
I (40052) chip[EM]: >>> [E:62780r S:45561 M:43933029] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (40063) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (40070) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933029 on exchange 62780r
I (40080) chip[EM]: <<< [E:62780r S:45561 M:226895686 (Ack:43933029)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (40093) chip[IN]: (S) Sending msg 226895686 on secure session with LSID: 45561
D (40102) chip[IN]: Received a duplicate message with MessageCounter:43933029 on exchange 62780r
I (40108) chip[EM]: >>> [E:62780r S:45561 M:43933029] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:02 (IM:ReadRequest)
D (40120) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (40126) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933029 on exchange 62780r
I (40136) chip[EM]: <<< [E:62780r S:45561 M:226895687 (Ack:43933029)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (40149) chip[IN]: (S) Sending msg 226895687 on secure session with LSID: 45561
I (40158) chip[EM]: >>> [E:62780r S:45561 M:43933030 (Ack:226895685)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (40169) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (40176) chip[EM]: Rxd Ack; Removing MessageCounter:226895685 from Retrans Table on exchange 62780r
D (40185) chip[DMG]: StatusResponseMessage =
D (40189) chip[DMG]: {
D (40191) chip[DMG]:    Status = 0x00,
D (40194) chip[DMG]:    InteractionModelRevision = 11
D (40198) chip[DMG]: }
I (40201) chip[IM]: Received status response, status is 0x00
D (40206) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (40211) chip[DMG]: IM RH moving to [GeneratingReports]
D (40217) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (40225) chip[DMG]: <RE:Run> Cluster 31, Attribute fffb is dirty
D (40231) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40241) chip[DMG]: <RE:Run> Cluster 33, Attribute fffb is dirty
D (40246) chip[DMG]: Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40256) chip[DMG]: <RE:Run> Cluster 3c, Attribute fffb is dirty
D (40262) chip[DMG]: Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40271) chip[DMG]: <RE:Run> Cluster 3e, Attribute fffb is dirty
D (40277) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40287) chip[DMG]: <RE:Run> Cluster 3f, Attribute fffb is dirty
D (40292) chip[DMG]: Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40302) chip[DMG]: <RE:Run> Cluster 36, Attribute fffb is dirty
D (40307) chip[DMG]: Reading attribute: Cluster=0x0000_0036 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40317) chip[DMG]: <RE:Run> Cluster 2a, Attribute fffb is dirty
D (40323) chip[DMG]: Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (40332) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffb is dirty
D (40338) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFB (expanded=1)
D (40348) chip[DMG]: <RE:Run> Cluster 3, Attribute fffb is dirty
D (40353) chip[DMG]: Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFFB (expanded=1)
D (40363) chip[DMG]: <RE:Run> Cluster 402, Attribute fffb is dirty
D (40369) chip[DMG]: Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFFB (expanded=1)
D (40378) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff9 is dirty
D (40384) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40393) chip[DMG]: <RE:Run> Cluster 1f, Attribute fff9 is dirty
D (40399) chip[DMG]: Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40409) chip[DMG]: <RE:Run> Cluster 28, Attribute fff9 is dirty
D (40414) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40424) chip[DMG]: <RE:Run> Cluster 30, Attribute fff9 is dirty
D (40430) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40439) chip[DMG]: <RE:Run> Cluster 31, Attribute fff9 is dirty
D (40445) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40455) chip[DMG]: <RE:Run> Cluster 33, Attribute fff9 is dirty
D (40460) chip[DMG]: Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40470) chip[DMG]: <RE:Run> Cluster 3c, Attribute fff9 is dirty
D (40475) chip[DMG]: Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40485) chip[DMG]: <RE:Run> Cluster 3e, Attribute fff9 is dirty
D (40491) chip[DMG]: Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40501) chip[DMG]: <RE:Run> Cluster 3f, Attribute fff9 is dirty
D (40506) chip[DMG]: Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40516) chip[DMG]: <RE:Run> Cluster 36, Attribute fff9 is dirty
D (40521) chip[DMG]: Reading attribute: Cluster=0x0000_0036 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40531) chip[DMG]: <RE:Run> Cluster 2a, Attribute fff9 is dirty
D (40537) chip[DMG]: Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (40546) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff9 is dirty
D (40552) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFF9 (expanded=1)
D (40562) chip[DMG]: <RE:Run> Cluster 3, Attribute fff9 is dirty
D (40567) chip[DMG]: Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFF9 (expanded=1)
D (40577) chip[DMG]: <RE:Run> Cluster 402, Attribute fff9 is dirty
D (40582) chip[DMG]: Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFF9 (expanded=1)
D (40592) chip[DMG]: <RE:Run> Cluster 28, Attribute fffc is dirty
D (40598) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (40607) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000028's Attribute 0x0000FFFC is 0 **********
D (40618) chip[DMG]: <RE:Run> Cluster 28, Attribute 0 is dirty
D (40623) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
E (40633) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = b
D (40640) chip[DMG]: <RE:Run> We cannot put more chunks into this report. Enable chunking.
D (40648) chip[DMG]: <RE> Sending report (payload has 1003 bytes)...
I (40657) chip[EM]: <<< [E:62780r S:45561 M:226895688 (Ack:43933030)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (40667) chip[IN]: (S) Sending msg 226895688 on secure session with LSID: 45561
D (40675) chip[DMG]: IM RH moving to [AwaitingReportResponse]
D (40679) chip[DMG]: <RE> ReportsInFlight = 1 with readHandler 0, RE has more messages
D (40688) chip[IN]: Received a duplicate message with MessageCounter:43933030 on exchange 62780r
I (40695) chip[EM]: >>> [E:62780r S:45561 M:43933030 (Ack:226895685)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (40708) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (40715) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933030 on exchange 62780r
I (40725) chip[EM]: <<< [E:62780r S:45561 M:226895689 (Ack:43933030)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (40738) chip[IN]: (S) Sending msg 226895689 on secure session with LSID: 45561
ate: entered main_region_Sleep
Setting temperature attribute to 2350 (23.5C)
State: entered main_region_TemperatureSynced
State: entered main_region_SyncToRTC
D (41062) chip[EM]: Retransmitting MessageCounter:226895688 on exchange 62780r Send Cnt 1
I (41063) chip[IN]: (S) Sending msg 226895688 on secure session with LSID: 45561
D (41395) chip[EM]: Retransmitting MessageCounter:226895688 on exchange 62780r Send Cnt 2
I (41395) chip[IN]: (S) Sending msg 226895688 on secure session with LSID: 45561
State: entered main_region_DisplayClock
I (41523) chip[EM]: >>> [E:62780r S:45561 M:43933031 (Ack:226895688)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (41525) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (41532) chip[EM]: Rxd Ack; Removing MessageCounter:226895688 from Retrans Table on exchange 62780r
D (41541) chip[DMG]: StatusResponseMessage =
D (41545) chip[DMG]: {
D (41547) chip[DMG]:    Status = 0x00,
D (41550) chip[DMG]:    InteractionModelRevision = 11
D (41555) chip[DMG]: }
I (41557) chip[IM]: Received status response, status is 0x00
D (41562) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (41567) chip[DMG]: IM RH moving to [GeneratingReports]
D (41573) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (41581) chip[DMG]: <RE:Run> Cluster 28, Attribute 0 is dirty
D (41587) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
D (41597) chip[DMG]: <RE:Run> Cluster 28, Attribute 6 is dirty
D (41602) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0006 (expanded=1)
D (41613) chip[DMG]: <RE:Run> Cluster 28, Attribute 1 is dirty
D (41617) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
D (41627) chip[DMG]: <RE:Run> Cluster 28, Attribute 2 is dirty
D (41632) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
D (41642) chip[DMG]: <RE:Run> Cluster 28, Attribute 3 is dirty
D (41647) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D (41657) chip[DMG]: <RE:Run> Cluster 28, Attribute 4 is dirty
D (41662) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=1)
D (41672) chip[DMG]: <RE:Run> Cluster 28, Attribute 7 is dirty
D (41677) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0007 (expanded=1)
D (41687) chip[DMG]: <RE:Run> Cluster 28, Attribute 8 is dirty
D (41692) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0008 (expanded=1)
D (41702) chip[DMG]: <RE:Run> Cluster 28, Attribute 9 is dirty
D (41707) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0009 (expanded=1)
D (41717) chip[DMG]: <RE:Run> Cluster 28, Attribute a is dirty
D (41722) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000A (expanded=1)
D (41732) chip[DMG]: <RE:Run> Cluster 28, Attribute 13 is dirty
D (41737) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0013 (expanded=1)
D (41747) chip[DMG]: <RE:Run> Cluster 28, Attribute fffd is dirty
D (41752) chip[DMG]: Reading attribute: Cluster=0x0000_0028 StaEndpoint=0 AttributeId=0x0000_FFFD (expanded=1)
I (41762) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000028's Attribute 0x0000FFFD is 1 **********
D (41773) chip[DMG]: <RE:Run> Cluster 28, Attribute 5 is dirty
D (41779) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0005 (expanded=1)
I (41788) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000028's Attribute 0x00000005 is  **********
D (41799) chip[DMG]: <RE:Run> Cluster 28, Attribute fff8 is dirty
D (41804) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
D (41814) chip[DMG]: <RE:Run> Cluster 28, Attribute fff9 is dirty
D (41820) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (41829) chip[DMG]: <RE:Run> Cluster 28, Attribute fffa is dirty
D (41835) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFA (expanded=1)
D (41845) chip[DMG]: <RE:Run> Cluster 28, Attribute fffb is dirty
D (41850) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (41860) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffd is dirty
D (41866) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
D (41875) chip[DMG]: <RE:Run> Cluster 1d, Attribute 0 is dirty
D (41881) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
D (41890) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (41896) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
D (41905) chip[DMG]: <RE:Run> Cluster 1d, Attribute 2 is dirty
D (41911) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
D (41920) chip[DMG]: <RE:Run> Cluster 1d, Attribute 3 is dirty
D (41926) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D (41935) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffc is dirty
D (41941) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
I (41951) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x0000001D's Attribute 0x0000FFFC is 0 **********
D (41961) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff8 is dirty
D (41967) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
D (41977) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff9 is dirty
D (41982) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
D (41992) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffa is dirty
D (41998) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFA (expanded=1)
D (42007) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffb is dirty
D (42013) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
D (42022) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffd is dirty
D (42028) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
D (42038) chip[DMG]: <RE:Run> Cluster 1d, Attribute 0 is dirty
D (42043) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=1)
D (42053) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (42058) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=1)
E (42068) chip[DMG]: Error retrieving data from clusterId: 0x0000_001D, err = b
D (42075) chip[DMG]: <RE:Run> We cannot put more chunks into this report. Enable chunking.
D (42083) chip[DMG]: <RE> Sending report (payload has 992 bytes)...
I (42092) chip[EM]: <<< [E:62780r S:45561 M:226895690 (Ack:43933031)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (42101) chip[IN]: (S) Sending msg 226895690 on secure session with LSID: 45561
D (42110) chip[DMG]: IM RH moving to [AwaitingReportResponse]
D (42114) chip[DMG]: <RE> ReportsInFlight = 1 with readHandler 0, RE has more messages
D (42122) chip[IN]: Received a duplicate message with MessageCounter:43933031 on exchange 62780r
I (42130) chip[EM]: >>> [E:62780r S:45561 M:43933031 (Ack:226895688)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (42143) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (42149) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933031 on exchange 62780r
I (42159) chip[EM]: <<< [E:62780r S:45561 M:226895691 (Ack:43933031)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (42172) chip[IN]: (S) Sending msg 226895691 on secure session with LSID: 45561
te: entered main_region_Sleep
D (42346) chip[IN]: Received a duplicate message with MessageCounter:43933031 on exchange 62780r
I (42347) chip[EM]: >>> [E:62780r S:45561 M:43933031 (Ack:226895688)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (42357) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (42365) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933031 on exchange 62780r
I (42375) chip[EM]: <<< [E:62780r S:45561 M:226895692 (Ack:43933031)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (42387) chip[IN]: (S) Sending msg 226895692 on secure session with LSID: 45561
D (42494) chip[EM]: Retransmitting MessageCounter:226895690 on exchange 62780r Send Cnt 1
I (42495) chip[IN]: (S) Sending msg 226895690 on secure session with LSID: 45561
I (42526) chip[EM]: >>> [E:62780r S:45561 M:43933032 (Ack:226895690)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (42528) chip[EM]: Found matching exchange: 62780r, Delegate: 0x3ffcef9c
D (42535) chip[EM]: Rxd Ack; Removing MessageCounter:226895690 from Retrans Table on exchange 62780r
D (42544) chip[DMG]: StatusResponseMessage =
D (42548) chip[DMG]: {
D (42550) chip[DMG]:    Status = 0x00,
D (42554) chip[DMG]:    InteractionModelRevision = 11
D (42558) chip[DMG]: }
I (42560) chip[IM]: Received status response, status is 0x00
D (42566) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (42570) chip[DMG]: IM RH moving to [GeneratingReports]
D (42576) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D (42584) chip[DMG]: <RE:Run> Cluster 1d, Attribute 1 is dirty
D (42590) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=1)
D (42600) chip[DMG]: <RE:Run> Cluster 1d, Attribute 2 is dirty
D (42605) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0002 (expanded=1)
D (42614) chip[DMG]: <RE:Run> Cluster 1d, Attribute 3 is dirty
D (42620) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=1)
D (42630) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffc is dirty
D (42636) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
I (42645) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x0000001D's Attribute 0x0000FFFC is 0 **********
D (42656) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff8 is dirty
D (42662) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFF8 (expanded=1)
D (42672) chip[DMG]: <RE:Run> Cluster 1d, Attribute fff9 is dirty
D (42676) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFF9 (expanded=1)
D (42686) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffa is dirty
D (42692) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFA (expanded=1)
D (42702) chip[DMG]: <RE:Run> Cluster 1d, Attribute fffb is dirty
D (42708) chip[DMG]: Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFB (expanded=1)
D (42718) chip[DMG]: <RE> Sending report (payload has 256 bytes)...
I (42726) chip[EM]: <<< [E:62780r S:45561 M:226895693 (Ack:43933032)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:05 (IM:ReportData)
I (42736) chip[IN]: (S) Sending msg 226895693 on secure session with LSID: 45561
D (42744) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (42748) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (42756) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (42760) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
D (42979) chip[IN]: Received a duplicate message with MessageCounter:43933032 on exchange 62780r
I (42980) chip[EM]: >>> [E:62780r S:45561 M:43933032 (Ack:226895690)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
D (42990) chip[EM]: Found matching exchange: 62780r, Delegate: 0x0
D (42996) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:43933032 on exchange 62780r
I (43006) chip[EM]: <<< [E:62780r S:45561 M:226895694 (Ack:43933032)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (43020) chip[IN]: (S) Sending msg 226895694 on secure session with LSID: 45561
D (43088) chip[EM]: Retransmitting MessageCounter:226895693 on exchange 62780r Send Cnt 1
I (43088) chip[IN]: (S) Sending msg 226895693 on secure session with LSID: 45561
D (43434) chip[EM]: Retransmitting MessageCounter:226895693 on exchange 62780r Send Cnt 2
I (43434) chip[IN]: (S) Sending msg 226895693 on secure session with LSID: 45561
I (43573) chip[EM]: >>> [E:62780r S:45561 M:43933033 (Ack:226895693)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (43578) chip[EM]: Found matching exchange: 62780r, Delegate: 0x0
D (43584) chip[EM]: Rxd Ack; Removing MessageCounter:226895693 from Retrans Table on exchange 62780r
I (44599) chip[EM]: >>> [E:62781r S:45561 M:43933034] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:0a (IM:TimedRequest)
D (44601) chip[EM]: Handling via exchange: 62781r, Delegate: 0x3ffcd4d4
D (44608) chip[DMG]: TimedRequestMessage =
D (44611) chip[DMG]: {
D (44614) chip[DMG]:    TimeoutMs = 0x2710,
D (44616) chip[DMG]:    InteractionModelRevision = 11
D (44622) chip[DMG]: }
D (44624) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3ffcd8f0 exchange 62781r
I (44634) chip[EM]: <<< [E:62781r S:45561 M:226895695 (Ack:43933034)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:01 (IM:StatusResponse)
I (44644) chip[IN]: (S) Sending msg 226895695 on secure session with LSID: 45561
D (44654) chip[DMG]: Timed Request time limit 0x000000000000CD63: handler 0x3ffcd8f0 exchange 62781r
I (44686) chip[EM]: >>> [E:62781r S:45561 M:43933035 (Ack:226895695)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0001:08 (IM:InvokeCommandRequest)
D (44689) chip[EM]: Found matching exchange: 62781r, Delegate: 0x3ffcd8f0
D (44696) chip[EM]: Rxd Ack; Removing MessageCounter:226895695 from Retrans Table on exchange 62781r
D (44704) chip[DMG]: Timed following action arrived at 0x000000000000A685: handler 0x3ffcd8f0 exchange 62781r
D (44714) chip[DMG]: Handing timed invoke to IM engine: handler 0x3ffcd8f0 exchange 62781r
D (44722) chip[DMG]: InvokeRequestMessage =
D (44726) chip[DMG]: {
D (44728) chip[DMG]:    suppressResponse = false, 
D (44732) chip[DMG]:    timedRequest = true, 
D (44736) chip[DMG]:    InvokeRequests =
D (44740) chip[DMG]:    [
D (44742) chip[DMG]:        CommandDataIB =
D (44746) chip[DMG]:        {
D (44748) chip[DMG]:            CommandPathIB =
D (44751) chip[DMG]:            {
D (44754) chip[DMG]:                EndpointId = 0x0,
D (44758) chip[DMG]:                ClusterId = 0x30,
D (44761) chip[DMG]:                CommandId = 0x0,
D (44764) chip[DMG]:            },
D (44768) chip[DMG]:            
D (44770) chip[DMG]:            CommandFields = 
D (44774) chip[DMG]:            {
D (44776) chip[DMG]:                0x0 = 1, 
D (44778) chip[DMG]:                0x1 = 1, 
D (44782) chip[DMG]:            },
D (44784) chip[DMG]:        },
D (44786) chip[DMG]:        
D (44788) chip[DMG]:    ],
D (44791) chip[DMG]:    
D (44793) chip[DMG]:    InteractionModelRevision = 11
D (44798) chip[DMG]: },
D (44800) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I (44808) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (44816) chip[FS]: GeneralCommissioning: Received ArmFailSafe (1s)
I (44822) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 1 **********
D (44834) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86205
D (44840) chip[DMG]: Command handler moving to [ Preparing]
D (44846) chip[DMG]: Command handler moving to [AddingComm]
D (44851) chip[DMG]: Command handler moving to [AddedComma]
D (44856) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0
I (44865) chip[EM]: <<< [E:62781r S:45561 M:226895696 (Ack:43933035)] (S) Msg TX to 1:000000005356B4C2 [CE1D] --- Type 0001:09 (IM:InvokeCommandResponse)
I (44876) chip[IN]: (S) Sending msg 226895696 on secure session with LSID: 45561
D (44886) chip[DMG]: Command handler moving to [CommandSen]
D (44890) chip[DMG]: Command handler moving to [AwaitingDe]
I (45009) chip[EM]: >>> [E:62781r S:45561 M:43933036 (Ack:226895696)] (S) Msg RX from 1:000000005356B4C2 [CE1D] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (45014) chip[EM]: Found matching exchange: 62781r, Delegate: 0x0
D (45020) chip[EM]: Rxd Ack; Removing MessageCounter:226895696 from Retrans Table on exchange 62781r
I (45823) chip[FS]: Fail-safe timer expired
E (45823) chip[SVR]: Failsafe timer expired
D (45823) chip[IN]: SecureSession[0x3ffd20c8]: MarkForEviction Type:1 LSID:45560
I (45827) chip[SC]: SecureSession[0x3ffd20c8, LSID:45560]: State change 'kActive' --> 'kPendingEviction'
D (45837) chip[IN]: SecureSession[0x3ffd20c8]: Released - Type:1 LSID:45560
E (45843) chip[SVR]: Commissioning failed (attempt 1): 32
E (45849) chip[BLE]: CancelBleIncompleteConnection() failed, err = 3
D (45857) chip[IN]: SecureSession[0x3ffd20c8]: Allocated Type:1 LSID:45563
D (45861) chip[SC]: Assigned local session key ID 45563
D (45865) chip[SC]: Waiting for PBKDF param request
I (45871) chip[DIS]: Updating services using commissioning mode 1
I (45878) chip[DIS]: CHIP minimal mDNS started advertising.
D (45894) chip[DL]: Using wifi MAC for hostname
I (45895) chip[DIS]: Advertise operational node 1C45FDE78A95CE1D-0000000075EBCF97
D (45896) chip[DIS]: Responding with _matter._tcp.local
D (45901) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (45909) chip[DIS]: Responding with 1C45FDE78A95CE1D-0000000075EBCF97._matter._tcp.local
D (45917) chip[DIS]: Responding with 0C8B9596B688.local
D (45921) chip[DIS]: Responding with 0C8B9596B688.local
D (45927) chip[DIS]: Responding with _I1C45FDE78A95CE1D._sub._matter._tcp.local
I (45933) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 1C45FDE78A95CE1D-0000000075EBCF97.
I (45951) chip[DIS]: mDNS service published: _matter._tcp
D (45951) chip[DL]: Using wifi MAC for hostname
I (45954) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
D (45963) chip[DIS]: Responding with _matterc._udp.local
D (45969) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
D (45975) chip[DIS]: Responding with 0C8B9596B688.local
D (45979) chip[DIS]: Responding with 0C8B9596B688.local
D (45985) chip[DIS]: Responding with _V65521._sub._matterc._udp.local
D (45991) chip[DIS]: Responding with _S15._sub._matterc._udp.local
D (45997) chip[DIS]: Responding with _L3840._sub._matterc._udp.local
D (46003) chip[DIS]: Responding with _CM._sub._matterc._udp.local
D (46009) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
I (46015) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 347AFFA93E947DD7.
I (46039) chip[DIS]: mDNS service published: _matterc._udp
D (46039) chip[ZCL]: Failsafe timeout, tell platform driver to revert network credentials.
E (46041) chip[ZCL]: OpCreds: Got FailSafeTimerExpired
E (46047) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D (46053) chip[IN]: Expiring all sessions for fabric 0x1!!
D (46059) chip[IN]: SecureSession[0x3ffd2180]: MarkForEviction Type:2 LSID:45561
I (46066) chip[SC]: SecureSession[0x3ffd2180, LSID:45561]: State change 'kActive' --> 'kPendingEviction'
D (46075) chip[IN]: SecureSession[0x3ffd2180]: Released - Type:2 LSID:45561
E (46081) chip[FP]: Reverting pending fabric data for fabric 0x1
D (46088) chip[EVL]: LogEvent event number: 0x0000000000000004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000000A216
D (46102) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
E (46199) chip[FP]: Warning: metadata not found during delete of fabric 0x1
I (46553) chip[FP]: Fabric (0x1) deleted.
I (46553) chip[ZCL]: OpCreds: Fabric index 0x1 was removed
I (46553) chip[DIS]: Updating services using commissioning mode 1
I (46558) chip[DIS]: CHIP minimal mDNS started advertising.
D (46589) chip[DL]: Using wifi MAC for hostname
I (46591) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
D (46595) chip[DIS]: Responding with _matterc._udp.local
D (46599) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
D (46605) chip[DIS]: Responding with 0C8B9596B688.local
D (46611) chip[DIS]: Responding with 0C8B9596B688.local
D (46615) chip[DIS]: Responding with _V65521._sub._matterc._udp.local
D (46621) chip[DIS]: Responding with _S15._sub._matterc._udp.local
D (46627) chip[DIS]: Responding with _L3840._sub._matterc._udp.local
D (46633) chip[DIS]: Responding with _CM._sub._matterc._udp.local
D (46639) chip[DIS]: Responding with 347AFFA93E947DD7._matterc._udp.local
I (46645) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 347AFFA93E947DD7.
I (46665) chip[DIS]: mDNS service published: _matterc._udp
D (46667) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719e
D (46669) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 5b3c719f
D (46681) chip[DL]: Using hash:accaec5f6ac0c34 for nvs key:f/1/s/000000005356B4C2
D (46691) chip[DL]: Using hash:00f9871538fa9e7 for nvs key:g/s/BQpIEH30QHsT48nD/AY49A==
D (46778) chip[DL]: Using hash:accaec5f6ac0c34 for nvs key:f/1/s/000000005356B4C2
I (47298) chip[TS]: Pending Last Known Good Time: 2023-11-01T23:18:28
I (47299) chip[TS]: Previous Last Known Good Time: 2023-07-24T23:38:47
I (47300) chip[TS]: Reverted Last Known Good Time to previous value
D (47307) chip[EVL]: LogEvent event number: 0x0000000000000005 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000000A6DA
D (47321) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
E (47407) chip[FP]: Warning: metadata not found during delete of fabric 0x1
E (47487) chip[ZCL]: OpCreds: failed to delete fabric at index 1: d8
I (47488) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
D (47493) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 72c86206
Commissioning failed, fail safe timer expired
E (47511) chip[DL]: Long dispatch time: 1688 ms, for event type 32783
I (47512) chip[FS]: Fail-safe cleanly disarmed
E (47515) chip[DL]: ble_gap_adv_set_data failed: Error ESP32:0x05B0001E 3840
E (47521) chip[DL]: Configure Adv Data failed: Error ESP32:0x05B0001E
E (47528) chip[DL]: Disabling CHIPoBLE service due to error: Error ESP32:0x05B0001E
Commissioning window opened
Fabric will be removed
Fabric removed successfully
Fabric will be removed
bzbarsky-apple commented 10 months ago

OK, so that log makes it clear what happened:

I (44816) chip[FS]: GeneralCommissioning: Received ArmFailSafe (1s)

Why did the client decide to arm a 1-second failsafe? Sounds like an issue you should raise with them, not a core Matter issue.

KEEPHEADU commented 3 weeks ago

Hi @emmby , I met the same problem, may I ask how you finally solved it? 

[00:00:17.348][info  ][FS] GeneralCommissioning: Received ArmFailSafe (1s)

[00:00:17.348][detail][DMG] Endpoint 0, Cluster 0x0000_0030 update version to 57ce0b7d

[00:00:17.349[00:00:17.349][detail][DMG] Command handler moving to [AddedComma]

[00:00:17.349][detail][DMG] Decreasing reference count for CommandHandler, remaining 0

[00:00:17.350][info  ][EM] <<< [E:48972r S:52584 M:211344138] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommand[00:00:17.442][info  ][DL] Tx Confirmation received

[00:00:17.442][info  ][DL]  stop soft timer

[00:00:17.443][info  ][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm

[00:00:18.348][info  ][FS] Fail-safe timer expired

[00:00:18.348][info  ][DL] _OnPlatformEvent default:  event->Type = 32784

[00:00:18.348][error ][SVR] Failsafe timer expired

[00:00:18.348][detail][IN] SecureSession[0x20004e30]: MarkForEviction Type:1 LSID:52584

[00:00:18.348][info  ][SC] SecureSession[0x20004e30, LSID:52584]: State change 'kActive' --> 'kPendingEviction'

[00:00:18.348][detail][IN] SecureSession[0x20004e30]: Released - Type:1 LSID:52584

[00:00:18.348][error ][SVR] Commissioning failed (attempt 1): 32