ESP-ROM:esp32c3-api1-20210207 Build:Feb 7 2021 rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd6100,len:0x16b4 load:0x403ce000,len:0x930 load:0x403d0000,len:0x2d28 entry 0x403ce000 I (30) boot: ESP-IDF v4.4.1 2nd stage bootloader I (30) boot: compile time 20:23:35 I (30) boot: chip revision: 3 I (32) boot.esp32c3: SPI Speed : 80MHz I (37) boot.esp32c3: SPI Mode : DIO I (41) boot.esp32c3: SPI Flash Size : 4MB I (46) boot: Enabling RNG early entropy source... I (52) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (70) boot: 1 otadata OTA data 01 00 0000f000 00002000 I (77) boot: 2 phy_init RF data 01 01 00011000 00001000 I (85) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (92) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (100) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000 I (107) boot: End of partition table I (112) esp_image: segment 0: paddr=00020020 vaddr=3c110020 size=37518h (226584) map I (155) esp_image: segment 1: paddr=00057540 vaddr=3fc8fa00 size=03918h ( 14616) load I (158) esp_image: segment 2: paddr=0005ae60 vaddr=40380000 size=051b8h ( 20920) load I (165) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=103000h (1060864) map I (336) esp_image: segment 4: paddr=00163028 vaddr=403851b8 size=0a7c8h ( 42952) load I (344) esp_image: segment 5: paddr=0016d7f8 vaddr=50000010 size=00010h ( 16) load I (349) boot: Loaded app from partition at offset 0x20000 I (349) boot: Disabling RNG early entropy source... I (365) cpu_start: Pro cpu up. I (373) cpu_start: Pro cpu start user code I (373) cpu_start: cpu freq: 160000000 I (373) cpu_start: Application information: I (376) cpu_start: Project name: chip-all-clusters-app I (382) cpu_start: App version: TE9-1143-ga903f5904 I (388) cpu_start: Compile time: Jul 13 2022 20:23:13 I (394) cpu_start: ELF file SHA256: d3eb13179054ac90... I (400) cpu_start: ESP-IDF: v4.4.1 I (405) heap_init: Initializing. RAM available for dynamic allocation: I (412) heap_init: At 3FCA5020 len 0001AFE0 (107 KiB): DRAM I (418) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM I (425) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM I (432) spi_flash: detected chip: generic I (436) spi_flash: flash io: dio I (441) sleep: Configure to isolate all GPIO pins in sleep state I (447) sleep: Enable automatic switching of GPIO sleep configuration I (454) coexist: coexist rom version 9387209 I (459) cpu_start: Starting scheduler. I (471) all-clusters-app: ================================================== I (471) all-clusters-app: chip-esp32-all-cluster-demo starting I (481) all-clusters-app: ================================================== I (661) pp: pp rom version: 9387209 I (661) net80211: net80211 rom version: 9387209 I (671) wifi:wifi driver task: 3fcb0154, prio:23, stack:6656, core=0 I (671) system_api: Base MAC address is not set I (681) system_api: read default base MAC address from EFUSE I (681) wifi:wifi firmware version: 63017e0 I (681) wifi:wifi certification version: v7.0 I (691) wifi:config NVS flash: enabled I (691) wifi:config nano formating: disabled I (691) wifi:Init data frame dynamic rx buffer num: 32 I (701) wifi:Init management frame dynamic rx buffer num: 32 I (701) wifi:Init management short buffer num: 32 I (701) wifi:Init dynamic tx buffer num: 32 I (711) wifi:Init static tx FG buffer num: 2 I (721) wifi:Init static rx buffer size: 1600 I (721) wifi:Init static rx buffer num: 10 I (731) wifi:Init dynamic rx buffer num: 32 I (741) wifi_init: rx ba win: 6 I (741) wifi_init: tcpip mbox: 32 I (741) wifi_init: udp mbox: 6 I (741) wifi_init: tcp mbox: 6 I (751) wifi_init: tcp tx win: 5744 I (751) wifi_init: tcp rx win: 5744 I (751) wifi_init: tcp mss: 1440 I (761) wifi_init: WiFi IRAM OP enabled I (761) wifi_init: WiFi RX IRAM OP enabled I (781) chip[DL]: NVS set: chip-counters/reboot-count = 4 (0x4) I (781) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (791) all-clusters-app: ------------------------Starting App Task--------------------------- W (791) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK I (811) BTDM_INIT: BT controller compile version [d913766] I (811) phy_init: phy_version 909,156dee4,Apr 7 2022,20:27:09 I (801) app-task: This is ESP32 chip with 1 CPU cores, WiFi/BLE, I (831) app-task: silicon revision 3, I (831) app-task: 4MB external flash > I (851) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (851) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (871) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (871) chip[SVR]: Manual pairing code: [34970112332] I (891) app-task: App Task started I (951) BTDM_INIT: Bluetooth MAC: 84:f7:03:60:fb:e6 I (951) NimBLE: GAP procedure initiated: stop advertising. I (951) CHIP[DL]: BLE host-controller synced I (1461) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (1461) NimBLE: GAP procedure initiated: advertise; I (1471) NimBLE: disc_mode=2 I (1471) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (1481) NimBLE: I (1481) chip[DL]: CHIPoBLE advertising started E (1491) chip[DL]: Long dispatch time: 706 ms, for event type 2 I (1491) chip[DL]: Starting ESP WiFi layer I (1501) wifi:mode : sta (84:f7:03:60:fb:e4) I (1511) wifi:enable tsf W (1511) wifi:Haven't to connect to a suitable AP now! I (1511) chip[DL]: Done driving station state, nothing else to do... I (1521) phy: chan:1,max_power:80 I (1521) phy: chan:2,max_power:80 I (1531) phy: chan:3,max_power:80 I (1531) phy: chan:4,max_power:80 I (1531) phy: chan:5,max_power:80 I (1541) phy: chan:6,max_power:80 I (1541) phy: chan:7,max_power:80 I (1541) phy: chan:8,max_power:80 I (1551) phy: chan:9,max_power:80 I (1551) phy: chan:10,max_power:80 I (1551) phy: chan:11,max_power:80 I (1571) phy: chan:12,max_power:80 I (1571) phy: chan:13,max_power:80 I (1571) phy: chan:14,max_power:80 W (1581) wifi:Haven't to connect to a suitable AP now! I (1581) chip[DL]: Done driving station state, nothing else to do... I (1591) phy: chan:1,max_power:80 I (1591) phy: chan:2,max_power:80 I (1591) phy: chan:3,max_power:80 I (1601) phy: chan:4,max_power:80 I (1601) phy: chan:5,max_power:80 I (1601) phy: chan:6,max_power:80 I (1611) phy: chan:7,max_power:80 I (1611) phy: chan:8,max_power:80 I (1611) phy: chan:9,max_power:80 I (1621) phy: chan:10,max_power:80 I (1621) phy: chan:11,max_power:80 I (1631) phy: chan:12,max_power:80 I (1641) phy: chan:13,max_power:80 I (1641) phy: chan:14,max_power:80 I (1651) chip[SVR]: Server initializing... I (1651) chip[TS]: Last Known Good Time: 2022-07-13T20:44:59 I (1651) chip[DMG]: AccessControl: initializing I (1661) chip[DMG]: Examples::AccessControlDelegate::Init I (1661) chip[DMG]: AccessControl: setting I (1671) chip[DMG]: DefaultAclStorage: initializing I (1671) chip[DMG]: DefaultAclStorage: 0 entries loaded I (1701) chip[ZCL]: Using ZAP configuration... I (1711) chip[DMG]: AccessControlCluster: initializing I (1721) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (1731) app-devicecallbacks: Unhandled cluster ID: 48 I (1731) app-devicecallbacks: Current free heap: 112532 I (1741) chip[ZCL]: Initiating Admin Commissioning cluster. I (1741) chip[ZCL]: Door Lock server initialized I (1751) chip[ZCL]: Initialize PCC Plugin Server Cluster. I (1751) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (1761) app-devicecallbacks: Current free heap: 112504 I (1781) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (1791) app-devicecallbacks: Unhandled cluster ID: 4 I (1791) app-devicecallbacks: Current free heap: 112504 I (1801) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0xfffc' I (1811) app-devicecallbacks: Unhandled cluster ID: 4 I (1811) app-devicecallbacks: Current free heap: 112504 I (1821) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002b', EndPoint ID: '0x00', Attribute ID: '0x0000' I (1841) app-devicecallbacks: Unhandled cluster ID: 43 I (1841) app-devicecallbacks: Current free heap: 112504 I (1851) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1861) app-devicecallbacks: Current free heap: 112504 I (1861) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1871) app-devicecallbacks: Unhandled cluster ID: 4 I (1881) app-devicecallbacks: Current free heap: 112504 I (1881) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0xfffc' I (1901) app-devicecallbacks: Unhandled cluster ID: 4 I (1911) app-devicecallbacks: Current free heap: 112504 I (1911) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1921) app-devicecallbacks: Unhandled cluster ID: 5 I (1931) app-devicecallbacks: Current free heap: 112504 I (1931) chip[ZCL]: On/Off set value: 1 0 I (1941) chip[ZCL]: On/off already set to new value I (1941) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1961) app-devicecallbacks: Current free heap: 112504 I (1971) chip[ZCL]: Window Covering Cluster init I (1971) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x0007' I (1981) app-devicecallbacks: Unhandled cluster ID: 258 I (1981) app-devicecallbacks: Current free heap: 112504 I (1991) chip[ZCL]: WC POST ATTRIBUTE=7 I (1991) chip[ZCL]: ConfigStatus 0x1B Operational=1 OnlineReserved=1 I (2001) chip[ZCL]: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0) I (2021) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (2021) chip[ZCL]: Constant Pressure Supported I (2021) chip[ZCL]: PCC Server: Constant Proportional Pressure Supported I (2031) chip[ZCL]: PCC Server: Constant Flow Supported I (2041) chip[ZCL]: PCC Server: Constant Temperature Supported I (2041) chip[ZCL]: PCC Server: Constant Speed Supported I (2051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2061) app-devicecallbacks: Unhandled AttributeId ID: '0x0007 I (2061) app-devicecallbacks: Current free heap: 112504 I (2081) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2091) app-devicecallbacks: Unhandled AttributeId ID: '0x0008 I (2091) app-devicecallbacks: Current free heap: 112504 I (2101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2111) app-devicecallbacks: Unhandled AttributeId ID: '0x4001 I (2111) app-devicecallbacks: Current free heap: 112504 I (2121) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2131) app-devicecallbacks: Unhandled cluster ID: 1030 I (2141) app-devicecallbacks: Current free heap: 112504 I (2151) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2161) app-devicecallbacks: Unhandled cluster ID: 1030 I (2161) app-devicecallbacks: Current free heap: 112504 I (2171) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (2181) app-devicecallbacks: Unhandled cluster ID: 4 I (2181) app-devicecallbacks: Current free heap: 112504 I (2191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0xfffc' I (2211) app-devicecallbacks: Unhandled cluster ID: 4 I (2211) app-devicecallbacks: Current free heap: 112504 I (2221) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (2231) app-devicecallbacks: Unhandled cluster ID: 1030 I (2231) app-devicecallbacks: Current free heap: 112504 I (2241) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2251) app-devicecallbacks: Unhandled cluster ID: 1030 I (2261) app-devicecallbacks: Current free heap: 112504 I (2271) chip[DIS]: Updating services using commissioning mode 1 I (2271) chip[DIS]: CHIP minimal mDNS started advertising. I (2281) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (2291) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (2291) chip[DIS]: mDNS service published: _matterc._udp I (2311) chip[IN]: CASE Server enabling CASE session setups I (2311) chip[SVR]: Joining Multicast groups I (2321) chip[SVR]: Server Listening... E (2321) chip[DL]: Long dispatch time: 674 ms, for event type 2 I (2321) app-devicecallbacks: Current free heap: 111776 I (2331) chip[DL]: WIFI_EVENT_STA_START I (2331) phy: chan:1,max_power:80 I (2341) phy: chan:2,max_power:80 I (2341) phy: chan:3,max_power:80 I (2351) phy: chan:4,max_power:80 I (2361) phy: chan:5,max_power:80 I (2361) phy: chan:6,max_power:80 I (2361) phy: chan:7,max_power:80 I (2371) phy: chan:8,max_power:80 I (2371) phy: chan:9,max_power:80 I (2371) phy: chan:10,max_power:80 I (2381) phy: chan:11,max_power:80 I (2381) phy: chan:12,max_power:80 I (2381) phy: chan:13,max_power:80 I (2391) phy: chan:14,max_power:80 W (2391) wifi:Haven't to connect to a suitable AP now! I (2391) chip[DL]: Done driving station state, nothing else to do... I (2401) app-devicecallbacks: Current free heap: 111776 I (2421) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2421) chip[DL]: Device already advertising, stop active advertisement and restart I (2431) NimBLE: GAP procedure initiated: stop advertising. I (2441) NimBLE: GAP procedure initiated: advertise; I (2441) NimBLE: disc_mode=2 I (2441) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2451) NimBLE: I (2451) chip[SVR]: Cannot load binding table: a0 I (23441) chip[DL]: BLE GAP connection established (con 1) I (23441) chip[DL]: CHIPoBLE advertising stopped I (23441) app-devicecallbacks: Current free heap: 111780 I (24891) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (24891) chip[BLE]: local and remote recv window sizes = 5 I (24901) chip[BLE]: selected BTP version 4 I (24901) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (24991) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1 notify = 1 I (24991) chip[DL]: CHIPoBLE subscribe received I (24991) NimBLE: GATT procedure initiated: notify; I (25001) NimBLE: att_handle=14 I (25011) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25021) app-devicecallbacks: CHIPoBLE connection established I (25031) app-devicecallbacks: Current free heap: 111748 I (25291) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25291) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:52219577 on exchange 21415r I (25311) chip[IN]: Prepared unauthenticated message 0x3fcb7798 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 21415r with MessageCounter:112259361. I (25321) chip[IN]: Sending unauthenticated msg 0x3fcb7798 with MessageCounter:112259361 to 0x0000000000000000 at monotonic time: 00000000000062E4 msec I (25331) NimBLE: GATT procedure initiated: notify; I (25341) NimBLE: att_handle=14 I (25341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25841) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25841) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:52219578 on exchange 21415r I (26701) chip[IN]: Prepared unauthenticated message 0x3fcb7718 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 21415r with MessageCounter:112259362. I (26721) chip[IN]: Sending unauthenticated msg 0x3fcb7718 with MessageCounter:112259362 to 0x0000000000000000 at monotonic time: 000000000000685A msec I (26731) NimBLE: GATT procedure initiated: notify; I (26741) NimBLE: att_handle=14 I (26741) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 E (26751) chip[DL]: Long dispatch time: 912 ms, for event type 7 I (26891) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (26891) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:52219579 on exchange 21415r I (26911) chip[IN]: Prepared unauthenticated message 0x3fcb77a8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 21415r with MessageCounter:112259363. I (26921) chip[IN]: Sending unauthenticated msg 0x3fcb77a8 with MessageCounter:112259363 to 0x0000000000000000 at monotonic time: 0000000000006924 msec I (26931) NimBLE: GATT procedure initiated: notify; I (26941) NimBLE: att_handle=14 I (26941) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (26951) chip[SC]: SecureSession[0x3fc945c8]: Moving from state 'kEstablishing' --> 'kActive' I (26971) chip[SVR]: Commissioning completed session establishment step I (26971) chip[DIS]: Updating services using commissioning mode 0 I (26981) chip[DIS]: CHIP minimal mDNS started advertising. I (26981) chip[SVR]: Device completed Rendezvous process E (26991) chip[DL]: Long dispatch time: 101 ms, for event type 7 I (27091) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27091) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:255649376 on exchange 21416r I (27121) chip[IN]: Prepared secure message 0x3fcb79d8 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 21416r with MessageCounter:87106217. I (27131) chip[IN]: Sending encrypted msg 0x3fcb79d8 with MessageCounter:87106217 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000069F7 msec I (27141) NimBLE: GATT procedure initiated: notify; I (27141) NimBLE: att_handle=14 I (27151) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27161) NimBLE: GATT procedure initiated: notify; I (27171) NimBLE: att_handle=14 I (27171) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27491) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27491) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:255649377 on exchange 21417r I (27511) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s) I (27511) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (27521) app-devicecallbacks: Unhandled cluster ID: 48 I (27531) app-devicecallbacks: Current free heap: 110852 I (27531) chip[IN]: Prepared secure message 0x3fcb77f8 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21417r with MessageCounter:87106218. I (27551) chip[IN]: Sending encrypted msg 0x3fcb77f8 with MessageCounter:87106218 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000006B97 msec I (27571) NimBLE: GATT procedure initiated: notify; I (27571) NimBLE: att_handle=14 I (27571) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27741) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27741) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:255649378 on exchange 21418r I (27761) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (27761) chip[DL]: NVS set: chip-config/country-code = "XX" I (27771) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (27781) app-devicecallbacks: Unhandled cluster ID: 48 I (27781) app-devicecallbacks: Current free heap: 110852 I (27801) chip[IN]: Prepared secure message 0x3fcb77f8 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21418r with MessageCounter:87106219. I (27811) chip[IN]: Sending encrypted msg 0x3fcb77f8 with MessageCounter:87106219 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000006C9F msec I (27821) NimBLE: GATT procedure initiated: notify; I (27821) NimBLE: att_handle=14 I (27831) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 E (27851) chip[DL]: Long dispatch time: 103 ms, for event type 7 I (27991) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27991) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:255649379 on exchange 21419r I (28011) chip[ZCL]: OpCreds: Certificate Chain request received for PAI I (28011) chip[IN]: Prepared secure message 0x3fcb77f8 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21419r with MessageCounter:87106220. I (28021) chip[IN]: Sending encrypted msg 0x3fcb77f8 with MessageCounter:87106220 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000006D76 msec I (28041) NimBLE: GATT procedure initiated: notify; I (28051) NimBLE: att_handle=14 I (28051) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28061) NimBLE: GATT procedure initiated: notify; I (28061) NimBLE: att_handle=14 I (28071) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28071) NimBLE: GATT procedure initiated: notify; I (28091) NimBLE: att_handle=14 I (28091) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28791) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (28791) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:255649380 on exchange 21420r I (28811) chip[ZCL]: OpCreds: Certificate Chain request received for DAC I (28811) chip[IN]: Prepared secure message 0x3fcb77f8 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21420r with MessageCounter:87106221. I (28821) chip[IN]: Sending encrypted msg 0x3fcb77f8 with MessageCounter:87106221 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000007096 msec I (28841) NimBLE: GATT procedure initiated: notify; I (28851) NimBLE: att_handle=14 I (28851) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28861) NimBLE: GATT procedure initiated: notify; I (28861) NimBLE: att_handle=14 I (28871) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28871) NimBLE: GATT procedure initiated: notify; I (28891) NimBLE: att_handle=14 I (28891) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29341) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 notify = 0 I (29341) chip[DL]: CHIPoBLE unsubscribe received I (29341) chip[BLE]: Releasing end point's BLE connection back to application. I (31691) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213) I (31691) app-devicecallbacks: CHIPoBLE disconnected I (31701) app-devicecallbacks: Current free heap: 112388 I (87511) chip[FS]: Fail-safe timer expired E (87511) chip[SVR]: Failsafe timer expired I (87511) chip[SC]: SecureSession[0x3fc945c8]: Moving from state 'kActive' --> 'kPendingEviction' E (87521) chip[SVR]: Commissioning failed (attempt 1): 32 I (87531) chip[DIS]: Updating services using commissioning mode 1 I (87531) chip[DIS]: CHIP minimal mDNS started advertising. I (87551) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (87551) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (87561) chip[DIS]: mDNS service published: _matterc._udp E (87561) chip[ZCL]: OpCreds: Got FailSafeTimerExpired E (87571) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! I (87581) chip[TS]: Pending Last Known Good Time: 2022-07-13T20:44:59 I (87581) chip[TS]: Previous Last Known Good Time: 2022-07-13T20:44:59 I (87591) chip[TS]: Reverted Last Known Good Time to previous value I (87601) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (87611) app-devicecallbacks: Unhandled cluster ID: 48 I (87621) app-devicecallbacks: Current free heap: 111696 I (87621) app-devicecallbacks: Current free heap: 111696 E (87631) chip[DL]: Long dispatch time: 123 ms, for event type 32782 I (87641) chip[FS]: Fail-safe cleanly disarmed I (87641) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (87661) NimBLE: GAP procedure initiated: advertise; I (87661) NimBLE: disc_mode=2 I (87661) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (87671) NimBLE: I (87681) chip[DL]: CHIPoBLE advertising started I (87681) app-devicecallbacks: Current free heap: 111696 I (117531) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840) I (117531) chip[DL]: Device already advertising, stop active advertisement and restart I (117551) NimBLE: GAP procedure initiated: stop advertising. I (117561) NimBLE: GAP procedure initiated: advertise; I (117561) NimBLE: disc_mode=2 I (117561) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800 I (117571) NimBLE: