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:0x18d0 load:0x403ce000,len:0x8d4 load:0x403d0000,len:0x2d80 entry 0x403ce000 I (30) boot: ESP-IDF v4.3.3 2nd stage bootloader I (30) boot: compile time 08:57: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 : 2MB I (46) boot: Enabling RNG early entropy source... I (51) 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 phy_init RF data 01 01 0000f000 00001000 I (77) boot: 2 factory factory app 00 00 00010000 001e6400 I (85) boot: End of partition table I (89) esp_image: segment 0: paddr=00010020 vaddr=3c0d0020 size=30054h (196692) map I (129) esp_image: segment 1: paddr=0004007c vaddr=3fc8fa00 size=03ec4h ( 16068) load I (132) esp_image: segment 2: paddr=00043f48 vaddr=40380000 size=0c0d0h ( 49360) load I (144) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=ca794h (829332) map I (276) esp_image: segment 4: paddr=0011a7bc vaddr=4038c0d0 size=03838h ( 14392) load I (279) esp_image: segment 5: paddr=0011dffc vaddr=50000010 size=00010h ( 16) load I (287) boot: Loaded app from partition at offset 0x10000 I (288) boot: Disabling RNG early entropy source... I (305) cpu_start: Pro cpu up. I (317) cpu_start: Pro cpu start user code I (317) cpu_start: cpu freq: 160000000 I (317) cpu_start: Application information: I (320) cpu_start: Project name: chip-all-clusters-app I (326) cpu_start: App version: test_event_4_2021_07_06-dirty I (333) cpu_start: Compile time: Jul 8 2022 08:56:58 I (339) cpu_start: ELF file SHA256: fc356446d42bdca2... I (345) cpu_start: ESP-IDF: v4.3.3 I (350) heap_init: Initializing. RAM available for dynamic allocation: I (357) heap_init: At 3FCA2790 len 0001D870 (118 KiB): DRAM I (364) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM I (370) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM I (377) spi_flash: detected chip: generic I (381) spi_flash: flash io: dio W (385) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (399) sleep: Configure to isolate all GPIO pins in sleep state I (405) sleep: Enable automatic switching of GPIO sleep configuration I (412) cpu_start: Starting scheduler. I (417) all-clusters-app: All Clusters Demo! I (417) all-clusters-app: This is ESP32 chip with 1 CPU cores, WiFi/BLE, I (427) all-clusters-app: silicon revision 3, I (427) all-clusters-app: 2MB external flash I (447) coexist: coexist rom version 9387209 I (447) pp: pp rom version: 9387209 I (447) net80211: net80211 rom version: 9387209 I (467) wifi:wifi driver task: 3fcae5e4, prio:23, stack:6656, core=0 I (467) system_api: Base MAC address is not set I (467) system_api: read default base MAC address from EFUSE I (477) wifi:wifi firmware version: 1603484 I (477) wifi:wifi certification version: v7.0 I (477) wifi:config NVS flash: enabled I (487) wifi:config nano formating: disabled I (487) wifi:Init data frame dynamic rx buffer num: 32 I (497) wifi:Init management frame dynamic rx buffer num: 32 I (497) wifi:Init management short buffer num: 32 I (497) wifi:Init dynamic tx buffer num: 32 I (507) wifi:Init static tx FG buffer num: 2 I (517) wifi:Init static rx buffer size: 1600 I (517) wifi:Init static rx buffer num: 10 I (527) wifi:Init dynamic rx buffer num: 32 I (527) wifi_init: rx ba win: 6 I (537) wifi_init: tcpip mbox: 32 I (537) wifi_init: udp mbox: 6 I (537) wifi_init: tcp mbox: 6 I (547) wifi_init: tcp tx win: 5744 I (547) wifi_init: tcp rx win: 5744 I (547) wifi_init: tcp mss: 1440 I (557) wifi_init: WiFi IRAM OP enabled I (557) wifi_init: WiFi RX IRAM OP enabled I (567) chip[ZCL]: Using ZAP configuration... I (567) chip[ZCL]: deactivate report event I (567) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0002' > I (597) app-devicecallbacks: Unhandled cluster ID: 257 I (597) app-devicecallbacks: Current free heap: 172232 I (597) chip[ZCL]: 0x3c0da244ep 1 clus 101 attr 3 not supported I (607) chip[ZCL]: Failed to write DoorState attribute: 0x86 I (617) chip[ZCL]: 0x3c0da244ep 1 clus 101 attr 21 not supported I (617) chip[ZCL]: Failed to write Language attribute: 0x86 I (627) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from admin pairing table. V (627) chip[DIS]: Set the admin pairing table delegate I (647) chip[ZCL]: OpCreds: Call to writeAdminsIntoFabricsListAttribute I (647) chip[ZCL]: OpCreds: Stored 0 admins in fabrics list attribute. I (657) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001' I (667) app-devicecallbacks: Unhandled cluster ID: 40 I (677) app-devicecallbacks: Current free heap: 172232 I (677) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002' I (687) app-devicecallbacks: Unhandled cluster ID: 40 I (697) app-devicecallbacks: Current free heap: 172232 I (697) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0003' I (717) app-devicecallbacks: Unhandled cluster ID: 40 I (727) app-devicecallbacks: Current free heap: 172232 I (727) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0004' I (737) app-devicecallbacks: Unhandled cluster ID: 40 I (747) app-devicecallbacks: Current free heap: 172232 I (747) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0008' I (757) app-devicecallbacks: Unhandled cluster ID: 40 I (767) app-devicecallbacks: Current free heap: 172232 V (567) chip[DL]: CHIP task running W (777) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK I (787) BTDM_INIT: BT controller compile version [d913766] I (797) coexist: coexist rom version 9387209 I (797) phy_init: phy_version 909,aa05aec,Apr 16 2022,13:42:08 I (777) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0007' I (817) app-devicecallbacks: Unhandled cluster ID: 40 I (837) app-devicecallbacks: Current free heap: 170024 I (837) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x000a' I (857) app-devicecallbacks: Unhandled cluster ID: 40 I (877) app-devicecallbacks: Current free heap: 170024 I (877) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0009' I (897) app-devicecallbacks: Unhandled cluster ID: 40 I (917) app-devicecallbacks: Current free heap: 170024 I (917) chip[ZCL]: Start identify callback on endpoint 1 time 0 I (917) chip[ZCL]: Stop identify callback on endpoint 1 I (937) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (937) BTDM_INIT: Bluetooth MAC: 84:f7:03:60:fb:e6 I (947) app-devicecallbacks: Unhandled cluster ID: 4 I (947) NimBLE: GAP procedure initiated: stop advertising. I (957) CHIP[DL]: BLE host-controller synced I (957) app-devicecallbacks: Current free heap: 120596 I (967) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (987) app-devicecallbacks: Unhandled cluster ID: 5 I (997) app-devicecallbacks: Current free heap: 120596 I (997) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (1007) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (1017) app-devicecallbacks: Unhandled cluster ID: 768 I (1017) app-devicecallbacks: Current free heap: 120596 I (1027) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (1037) app-devicecallbacks: Unhandled cluster ID: 768 I (1047) app-devicecallbacks: Current free heap: 120596 I (1057) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (1067) app-devicecallbacks: Unhandled cluster ID: 768 I (1067) app-devicecallbacks: Current free heap: 120596 I (1077) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (1077) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (1087) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1097) app-devicecallbacks: Unhandled cluster ID: 1280 I (1097) app-devicecallbacks: Current free heap: 120596 I (1117) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1127) app-devicecallbacks: Unhandled cluster ID: 1280 I (1137) app-devicecallbacks: Current free heap: 120596 I (1137) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (1147) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (1157) app-devicecallbacks: Unhandled cluster ID: 1030 I (1157) app-devicecallbacks: Current free heap: 120596 I (1167) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (1187) app-devicecallbacks: Unhandled cluster ID: 1030 I (1187) app-devicecallbacks: Current free heap: 120596 V (1197) chip[DIS]: Init admin pairing table with server storage V (1197) chip[IN]: TransportMgr initialized I (1217) chip[DL]: NVS set: chip-counters/GlobalMCTR = 2000 (0x7D0) I (1217) chip[IN]: local node id is 0x0000000000BC5C01 V (1217) chip[SC]: Assigned local session key ID 0 V (1227) chip[SC]: Waiting for PBKDF param request I (1227) chip[SVR]: Server Listening... I (1237) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1237) app-devicecallbacks: Unhandled cluster ID: 1026 I (1247) app-devicecallbacks: Current free heap: 119176 I (1267) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1277) app-devicecallbacks: Unhandled cluster ID: 257 I (1277) app-devicecallbacks: Current free heap: 119044 I (1287) chip[ZCL]: Failed to read AutoRelockTime attribute: 0x86 I (1287) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1297) app-devicecallbacks: Current free heap: 118216 I (1307) chip[ZCL]: 0x3c0da244ep 2 clus 8 attr 0 not supported I (1317) all-clusters-app: Setup discriminator: 3840 (0xf00) I (1327) all-clusters-app: Setup PIN code: 20202021 (0x1344225) I (1327) all-clusters-app: Short Manual(decimal) setup code: 34970112332 I (1337) all-clusters-app: Long Manual(decimal) setup code: 749701123309050177298 I (1337) all-clusters-app: QR CODE Text: 'MT:C8XA0SRB00KA0648G00' I (1347) all-clusters-app: Copy/paste the below URL in a browser to see the QR CODE: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AC8XA0SRB00KA0648G00 I (1447) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (1447) NimBLE: GAP procedure initiated: advertise; I (1457) NimBLE: disc_mode=2 I (1457) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (1467) NimBLE: I (1467) chip[DL]: CHIPoBLE advertising started E (1477) chip[DL]: Long dispatch time: 707 ms I (1477) chip[DL]: Starting ESP WiFi layer I (1487) wifi:set rx active PTI: 0, rx ack PTI: 12, and default PTI: 1 I (1497) wifi:mode : sta (84:f7:03:60:fb:e4) I (1497) wifi:enable tsf W (1497) wifi:Haven't to connect to a suitable AP now! I (1507) chip[DL]: Done driving station state, nothing else to do... I (1507) phy: chan:1,max_power:80 I (1507) phy: chan:2,max_power:80 I (1517) phy: chan:3,max_power:80 I (1517) phy: chan:4,max_power:80 I (1517) phy: chan:5,max_power:80 I (1527) phy: chan:6,max_power:80 I (1527) phy: chan:7,max_power:80 I (1547) phy: chan:8,max_power:80 I (1547) phy: chan:9,max_power:80 I (1547) phy: chan:10,max_power:80 I (1557) phy: chan:11,max_power:80 I (1557) phy: chan:12,max_power:80 I (1557) phy: chan:13,max_power:80 I (1567) phy: chan:14,max_power:80 W (1567) wifi:Haven't to connect to a suitable AP now! I (1567) chip[DL]: Done driving station state, nothing else to do... I (1577) phy: chan:1,max_power:80 I (1577) phy: chan:2,max_power:80 I (1587) phy: chan:3,max_power:80 I (1587) phy: chan:4,max_power:80 I (1587) phy: chan:5,max_power:80 I (1597) phy: chan:6,max_power:80 I (1607) phy: chan:7,max_power:80 I (1607) phy: chan:8,max_power:80 I (1617) phy: chan:9,max_power:80 I (1617) phy: chan:10,max_power:80 I (1617) phy: chan:11,max_power:80 I (1627) phy: chan:12,max_power:80 I (1627) phy: chan:13,max_power:80 I (1627) phy: chan:14,max_power:80 I (1637) app-devicecallbacks: Current free heap: 116280 I (1637) chip[DL]: WIFI_EVENT_STA_START I (1647) phy: chan:1,max_power:80 I (1647) phy: chan:2,max_power:80 I (1647) phy: chan:3,max_power:80 I (1657) phy: chan:4,max_power:80 I (1657) phy: chan:5,max_power:80 I (1657) phy: chan:6,max_power:80 I (1677) phy: chan:7,max_power:80 I (1677) phy: chan:8,max_power:80 I (1677) phy: chan:9,max_power:80 I (1687) phy: chan:10,max_power:80 I (1687) phy: chan:11,max_power:80 I (1687) phy: chan:12,max_power:80 I (1697) phy: chan:13,max_power:80 I (1697) phy: chan:14,max_power:80 W (1697) wifi:Haven't to connect to a suitable AP now! I (1707) chip[DL]: Done driving station state, nothing else to do... I (1707) app-devicecallbacks: Current free heap: 116280 I (23827) chip[DL]: BLE GAP connection established (con 1) I (23827) chip[DL]: CHIPoBLE advertising stopped I (23827) app-devicecallbacks: Current free heap: 116280 I (25127) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25137) chip[BLE]: local and remote recv window sizes = 3 I (25147) chip[BLE]: selected BTP version 3 I (25147) chip[BLE]: using BTP fragment sizes rx 128 / tx 20. I (25227) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 notify = 1 I (25237) chip[DL]: CHIPoBLE subscribe received I (25237) NimBLE: GATT procedure initiated: notify; I (25247) NimBLE: att_handle=14 I (25257) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 V (25257) chip[IN]: BLE EndPoint 0x3fc9e808 Connection Complete I (25267) app-devicecallbacks: Current free heap: 116232 I (25337) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25337) chip[EM]: Received message of type 32 and protocolId 0 on exchange 56401 V (25347) chip[EM]: ec id: 56401, Delegate: 0x0x3fc971f0 V (25347) chip[SC]: Received PBKDF param request I (25547) NimBLE: GATT procedure initiated: notify; I (25547) NimBLE: att_handle=14 I (25547) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 V (25557) chip[SC]: Sent PBKDF param response E (25557) chip[DL]: Long dispatch time: 225 ms I (25567) NimBLE: GATT procedure initiated: notify; I (25567) NimBLE: att_handle=14 I (25587) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25677) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25687) NimBLE: GATT procedure initiated: notify; I (25697) NimBLE: att_handle=14 I (25697) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25707) NimBLE: GATT procedure initiated: notify; I (25707) NimBLE: att_handle=14 I (25707) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25777) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25787) NimBLE: GATT procedure initiated: notify; I (25797) NimBLE: att_handle=14 I (25797) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25887) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (25887) NimBLE: GATT procedure initiated: notify; I (25897) NimBLE: att_handle=14 I (25897) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (25907) chip[EM]: Received message of type 34 and protocolId 0 on exchange 56401 V (25907) chip[SC]: Received spake2p msg1 V (26257) chip[SC]: Peer assigned session key ID 1 V (26767) chip[SC]: Sent spake2p msg2 E (26767) chip[DL]: Long dispatch time: 879 ms I (26767) NimBLE: GATT procedure initiated: notify; I (26777) NimBLE: att_handle=14 I (26777) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (26827) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (26837) NimBLE: GATT procedure initiated: notify; I (26847) NimBLE: att_handle=14 I (26847) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (26857) NimBLE: GATT procedure initiated: notify; I (26857) NimBLE: att_handle=14 I (26857) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (26927) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (26937) NimBLE: GATT procedure initiated: notify; I (26947) NimBLE: att_handle=14 I (26947) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (26957) NimBLE: GATT procedure initiated: notify; I (26957) NimBLE: att_handle=14 I (26957) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27027) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27037) NimBLE: GATT procedure initiated: notify; I (27047) NimBLE: att_handle=14 I (27047) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27057) NimBLE: GATT procedure initiated: notify; I (27057) NimBLE: att_handle=14 I (27057) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27127) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27237) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27237) NimBLE: GATT procedure initiated: notify; I (27247) NimBLE: att_handle=14 I (27247) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27257) chip[EM]: Received message of type 36 and protocolId 0 on exchange 56401 V (27257) chip[SC]: Received spake2p msg3 V (27267) chip[IN]: New secure session created for device 0x0000000000000000, key 1!! I (27277) chip[SVR]: Device completed SPAKE2+ handshake I (27287) chip[SVR]: Persisting admin ID 0, next available 1 I (27337) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27437) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27457) chip[SVR]: Stored value in server storage I (27457) chip[DIS]: Admin (0) persisted to storage. Calling OnAdminPersistedToStorage I (27467) chip[ZCL]: OpCreds: Admin 0 was persisted to storage. FabricId 00000000000000000, NodeId 0000000003FCA22B0, VendorId 0xFB6C I (27477) chip[ZCL]: OpCreds: Call to writeAdminsIntoFabricsListAttribute I (27487) chip[ZCL]: OpCreds: Skipping over unitialized admin with fabricId 0x0000000000000000, nodeId 0x0000000000000000 vendorId 0x0000 I (27497) chip[ZCL]: OpCreds: Stored 0 admins in fabrics list attribute. I (27507) chip[SVR]: Persisting admin ID successfully I (27507) chip[SVR]: Device completed Rendezvous process I (27507) chip[SVR]: Stored value in server storage I (27527) chip[SVR]: Stored value in server storage E (27527) chip[DL]: Long dispatch time: 291 ms I (27537) NimBLE: GATT procedure initiated: notify; I (27537) NimBLE: att_handle=14 I (27537) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (27637) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (27637) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 0 I (27647) chip[IN]: Setting nodeID 2104E on admin. I (27647) chip[IN]: Setting fabricID 1B669 on admin. I (27657) chip[IN]: Since admin was modified, persisting changes to KVS I (27827) chip[SVR]: Stored value in server storage I (27837) chip[DIS]: Admin (0) persisted to storage. Calling OnAdminPersistedToStorage I (27837) chip[ZCL]: OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 2104e000000003FCA22B0, VendorId 0xFB6C I (27847) chip[ZCL]: OpCreds: Call to writeAdminsIntoFabricsListAttribute I (27857) chip[ZCL]: OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x000000000002104E vendorId 0x0000 I (27877) chip[ZCL]: OpCreds: Stored 0 admins in fabrics list attribute. I (27887) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56402 V (27887) chip[EM]: ec id: 56402, Delegate: 0x0x3fc9c4a0 V (27897) chip[DMG]: ICR moving to [Initialize] V (27897) chip[ZCL]: Received Cluster Command: Cluster=3e Command=a1 Endpoint=0 I (27907) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert I (27907) chip[ZCL]: OpCreds: Finding admin with fabricId 0x000000000001B669. I (27927) chip[DIS]: Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x000000000002104E vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0] I (27937) chip[DIS]: Found a match! I (28107) chip[SVR]: Stored value in server storage I (28117) chip[DIS]: Admin (0) persisted to storage. Calling OnAdminPersistedToStorage I (28117) chip[ZCL]: OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 2104e000000003FCA22B0, VendorId 0xFB6C I (28127) chip[ZCL]: OpCreds: Call to writeAdminsIntoFabricsListAttribute I (28137) chip[ZCL]: OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x000000000002104E vendorId 0x0000 I (28157) chip[ZCL]: OpCreds: Stored 0 admins in fabrics list attribute. V (28167) chip[DMG]: ICR moving to [AddCommand] V (28167) chip[IN]: Secure message was encrypted: Msg ID 1 I (28167) chip[IN]: Encrypted message 0x3fcb5b58 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56402. I (28177) chip[IN]: Sending msg 0x3fcb5b58 to 0x000000000001B669 at utc time: 28185 msec I (28187) chip[IN]: Sending secure msg on generic transport I (28207) NimBLE: GATT procedure initiated: notify; I (28207) NimBLE: att_handle=14 I (28207) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28217) chip[IN]: Secure msg send status No Error V (28227) chip[DMG]: ICR moving to [ Sending] V (28227) chip[DMG]: ICR moving to [Uninitiali] E (28227) chip[DL]: Long dispatch time: 594 ms I (28277) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (28287) NimBLE: GATT procedure initiated: notify; I (28297) NimBLE: att_handle=14 I (28297) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28307) NimBLE: GATT procedure initiated: notify; I (28307) NimBLE: att_handle=14 I (28307) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28377) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (28387) NimBLE: GATT procedure initiated: notify; I (28397) NimBLE: att_handle=14 I (28397) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28407) NimBLE: GATT procedure initiated: notify; I (28407) NimBLE: att_handle=14 I (28407) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28477) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (28587) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (28587) NimBLE: GATT procedure initiated: notify; I (28597) NimBLE: att_handle=14 I (28597) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (28607) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 0 I (28617) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56403 V (28627) chip[EM]: ec id: 56403, Delegate: 0x0x3fc9c4a0 V (28627) chip[DMG]: ICR moving to [Initialize] V (28637) chip[ZCL]: Received Cluster Command: Cluster=3e Command=4 Endpoint=0 I (28637) chip[ZCL]: OpCreds: commissioner has requested an OpCSR I (28647) chip[ZCL]: OpCreds: Finding admin with fabricId 0x000000000001B669. I (28657) chip[DIS]: Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x000000000002104E vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0] I (28677) chip[DIS]: Found a match! I (29007) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0 V (29007) chip[DMG]: ICR moving to [AddCommand] V (29007) chip[IN]: Secure message was encrypted: Msg ID 2 I (29017) chip[IN]: Encrypted message 0x3fcb5b58 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56403. I (29037) chip[IN]: Sending msg 0x3fcb5b58 to 0x000000000001B669 at utc time: 29038 msec I (29047) chip[IN]: Sending secure msg on generic transport I (29047) chip[IN]: Secure msg send status No Error V (29057) chip[DMG]: ICR moving to [ Sending] V (29057) chip[DMG]: ICR moving to [Uninitiali] E (29057) chip[DL]: Long dispatch time: 472 ms I (29067) NimBLE: GATT procedure initiated: notify; I (29067) NimBLE: att_handle=14 I (29067) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29127) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29137) NimBLE: GATT procedure initiated: notify; I (29147) NimBLE: att_handle=14 I (29147) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29157) NimBLE: GATT procedure initiated: notify; I (29157) NimBLE: att_handle=14 I (29157) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29227) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29237) NimBLE: GATT procedure initiated: notify; I (29247) NimBLE: att_handle=14 I (29247) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29257) NimBLE: GATT procedure initiated: notify; I (29257) NimBLE: att_handle=14 I (29257) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29327) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29337) NimBLE: GATT procedure initiated: notify; I (29347) NimBLE: att_handle=14 I (29347) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29357) NimBLE: GATT procedure initiated: notify; I (29357) NimBLE: att_handle=14 I (29357) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29427) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29437) NimBLE: GATT procedure initiated: notify; I (29447) NimBLE: att_handle=14 I (29447) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29457) NimBLE: GATT procedure initiated: notify; I (29457) NimBLE: att_handle=14 I (29457) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29527) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29537) NimBLE: GATT procedure initiated: notify; I (29547) NimBLE: att_handle=14 I (29547) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29557) NimBLE: GATT procedure initiated: notify; I (29557) NimBLE: att_handle=14 I (29557) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29627) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29637) NimBLE: GATT procedure initiated: notify; I (29647) NimBLE: att_handle=14 I (29647) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29657) NimBLE: GATT procedure initiated: notify; I (29657) NimBLE: att_handle=14 I (29657) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29727) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29737) NimBLE: GATT procedure initiated: notify; I (29747) NimBLE: att_handle=14 I (29747) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29757) NimBLE: GATT procedure initiated: notify; I (29757) NimBLE: att_handle=14 I (29757) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29827) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29837) NimBLE: GATT procedure initiated: notify; I (29847) NimBLE: att_handle=14 I (29847) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29857) NimBLE: GATT procedure initiated: notify; I (29857) NimBLE: att_handle=14 I (29857) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29927) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (29937) NimBLE: GATT procedure initiated: notify; I (29947) NimBLE: att_handle=14 I (29947) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (29957) NimBLE: GATT procedure initiated: notify; I (29957) NimBLE: att_handle=14 I (29957) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30027) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30137) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30137) NimBLE: GATT procedure initiated: notify; I (30147) NimBLE: att_handle=14 I (30147) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30237) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30337) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30337) NimBLE: GATT procedure initiated: notify; I (30347) NimBLE: att_handle=14 I (30347) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30437) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30537) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30537) NimBLE: GATT procedure initiated: notify; I (30547) NimBLE: att_handle=14 I (30547) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30557) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 0 I (30567) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56404 V (30577) chip[EM]: ec id: 56404, Delegate: 0x0x3fc9c4a0 V (30577) chip[DMG]: ICR moving to [Initialize] V (30587) chip[ZCL]: Received Cluster Command: Cluster=3e Command=6 Endpoint=0 I (30587) chip[ZCL]: OpCreds: commissioner has added an Op Cert I (30597) chip[ZCL]: OpCreds: Finding admin with fabricId 0x000000000001B669. I (30597) chip[DIS]: Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x000000000002104E vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0] I (30627) chip[DIS]: Found a match! I (30627) chip[SVR]: Stored value in server storage I (30647) chip[DIS]: Admin (0) persisted to storage. Calling OnAdminPersistedToStorage I (30647) chip[ZCL]: OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 2104e000000003FCA22B0, VendorId 0xFB6C I (30657) chip[ZCL]: OpCreds: Call to writeAdminsIntoFabricsListAttribute I (30667) chip[ZCL]: OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x000000000002104E vendorId 0x0000 I (30687) chip[ZCL]: OpCreds: Stored 0 admins in fabrics list attribute. I (30697) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (30697) chip[DIS]: Using wifi MAC for hostname I (30707) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (30707) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. V (30717) chip[DMG]: ICR moving to [AddCommand] V (30727) chip[IN]: Secure message was encrypted: Msg ID 3 I (30737) chip[IN]: Encrypted message 0x3fcb5b58 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56404. I (30747) chip[IN]: Sending msg 0x3fcb5b58 to 0x000000000001B669 at utc time: 30750 msec I (30757) chip[IN]: Sending secure msg on generic transport I (30757) chip[IN]: Secure msg send status No Error V (30767) chip[DMG]: ICR moving to [ Sending] V (30767) chip[DMG]: ICR moving to [Uninitiali] E (30767) chip[DL]: Long dispatch time: 235 ms I (30777) NimBLE: GATT procedure initiated: notify; I (30787) NimBLE: att_handle=14 I (30787) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30877) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30887) NimBLE: GATT procedure initiated: notify; I (30897) NimBLE: att_handle=14 I (30897) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30907) NimBLE: GATT procedure initiated: notify; I (30907) NimBLE: att_handle=14 I (30907) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (30977) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (30987) NimBLE: GATT procedure initiated: notify; I (30997) NimBLE: att_handle=14 I (30997) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (31007) NimBLE: GATT procedure initiated: notify; I (31007) NimBLE: att_handle=14 I (31007) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (31077) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (33587) NimBLE: GATT procedure initiated: notify; I (33587) NimBLE: att_handle=14 I (33587) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (36377) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (38737) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (38737) NimBLE: GATT procedure initiated: notify; I (38747) NimBLE: att_handle=14 I (38747) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (38757) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 0 I (38767) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56405 V (38777) chip[EM]: ec id: 56405, Delegate: 0x0x3fc9c4a0 V (38777) chip[DMG]: ICR moving to [Initialize] V (38787) chip[ZCL]: Received Cluster Command: Cluster=31 Command=2 Endpoint=0 V (38787) chip[ZCL]: WiFi provisioning data: SSID: TESTSSID V (38797) chip[ZCL]: AddWiFiNetwork: 0 V (38797) chip[DMG]: ICR moving to [AddCommand] V (38807) chip[IN]: Secure message was encrypted: Msg ID 4 I (38817) chip[IN]: Encrypted message 0x3fcb5b58 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56405. I (38827) chip[IN]: Sending msg 0x3fcb5b58 to 0x000000000001B669 at utc time: 38829 msec I (38837) chip[IN]: Sending secure msg on generic transport I (38837) chip[IN]: Secure msg send status No Error V (38847) chip[DMG]: ICR moving to [ Sending] V (38847) chip[DMG]: ICR moving to [Uninitiali] E (38857) chip[DL]: Long dispatch time: 123 ms I (38857) NimBLE: GATT procedure initiated: notify; I (38857) NimBLE: att_handle=14 I (38877) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (38927) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (38937) NimBLE: GATT procedure initiated: notify; I (38947) NimBLE: att_handle=14 I (38947) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (38957) NimBLE: GATT procedure initiated: notify; I (38957) NimBLE: att_handle=14 I (38957) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (39027) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (39037) NimBLE: GATT procedure initiated: notify; I (39047) NimBLE: att_handle=14 I (39047) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (39057) NimBLE: GATT procedure initiated: notify; I (39057) NimBLE: att_handle=14 I (39057) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (39127) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (41637) NimBLE: GATT procedure initiated: notify; I (41637) NimBLE: att_handle=14 I (41637) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (44427) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (46637) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (46637) NimBLE: GATT procedure initiated: notify; I (46647) NimBLE: att_handle=14 I (46647) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (46657) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 0 I (46657) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56406 V (46677) chip[EM]: ec id: 56406, Delegate: 0x0x3fc9c4a0 V (46677) chip[DMG]: ICR moving to [Initialize] V (46687) chip[ZCL]: Received Cluster Command: Cluster=31 Command=c Endpoint=0 I (46687) chip[NP]: ESP32NetworkProvisioningDelegate: SSID: TESTSSID I (46697) chip[DL]: WiFi station mode change: Enabled -> Disabled I (46717) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (46717) wifi:mode : sta (84:f7:03:60:fb:e4) + softAP (84:f7:03:60:fb:e5) I (46717) wifi:Total power save buffer number: 16 I (46727) wifi:Init max length of beacon: 752/752 I (46727) phy: chan:1,max_power:80 I (46737) phy: chan:2,max_power:80 I (46747) phy: chan:3,max_power:80 I (46747) phy: chan:4,max_power:80 I (46747) phy: chan:5,max_power:80 I (46757) phy: chan:6,max_power:80 I (46757) phy: chan:7,max_power:80 I (46767) phy: chan:8,max_power:80 I (46767) phy: chan:9,max_power:80 I (46767) phy: chan:10,max_power:80 I (46777) phy: chan:11,max_power:80 I (46777) phy: chan:12,max_power:80 I (46777) phy: chan:13,max_power:80 I (46787) phy: chan:14,max_power:80 I (46787) wifi:Init max length of beacon: 752/752 I (46797) chip[DL]: WiFi station mode change: Disabled -> Enabled I (46807) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (46807) chip[DIS]: Using wifi MAC for hostname I (46817) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (46817) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. E (46827) chip[DIS]: Operational advertising enabled I (46827) app-devicecallbacks: Current free heap: 103024 V (46847) chip[DMG]: ICR moving to [AddCommand] V (46847) chip[IN]: Secure message was encrypted: Msg ID 5 I (46857) chip[IN]: Encrypted message 0x3fcb5b58 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56406. I (46867) chip[IN]: Sending msg 0x3fcb5b58 to 0x000000000001B669 at utc time: 46872 msec I (46867) chip[IN]: Sending secure msg on generic transport I (46877) chip[IN]: Secure msg send status No Error V (46877) chip[DMG]: ICR moving to [ Sending] V (46887) chip[DMG]: ICR moving to [Uninitiali] E (46897) chip[DL]: Long dispatch time: 257 ms I (46907) NimBLE: GATT procedure initiated: notify; I (46907) NimBLE: att_handle=14 I (46907) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (46917) phy: chan:1,max_power:80 I (46917) phy: chan:2,max_power:80 I (46927) phy: chan:3,max_power:80 I (46927) phy: chan:4,max_power:80 I (46937) phy: chan:5,max_power:80 I (46937) phy: chan:6,max_power:80 I (46937) phy: chan:7,max_power:80 I (46947) phy: chan:8,max_power:80 I (46957) phy: chan:9,max_power:80 I (46957) phy: chan:10,max_power:80 I (46967) phy: chan:11,max_power:80 I (46967) phy: chan:12,max_power:80 I (46967) phy: chan:13,max_power:80 I (46977) phy: chan:14,max_power:80 W (46977) wifi:Haven't to connect to a suitable AP now! I (46977) chip[DL]: Attempting to connect WiFi station interface I (46977) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (46987) chip[DL]: WiFi station state change: NotConnected -> Connecting I (47007) chip[DL]: Done driving station state, nothing else to do... I (47017) phy: chan:1,max_power:80 I (47017) phy: chan:2,max_power:80 I (47017) phy: chan:3,max_power:80 I (47027) phy: chan:4,max_power:80 I (47027) phy: chan:5,max_power:80 I (47027) phy: chan:6,max_power:80 I (47037) phy: chan:7,max_power:80 I (47037) phy: chan:8,max_power:80 I (47037) phy: chan:9,max_power:80 I (47047) phy: chan:10,max_power:80 I (47047) phy: chan:11,max_power:80 I (47057) phy: chan:12,max_power:80 I (47057) phy: chan:13,max_power:80 I (47057) phy: chan:14,max_power:80 W (47077) wifi:Haven't to connect to a suitable AP now! I (47077) chip[DL]: Attempting to connect WiFi station interface E (47087) wifi:sta is connecting, return error E (47087) chip[DL]: esp_wifi_connect() failed: Error 12295 (0x00003007) I (47087) chip[DL]: Done driving station state, nothing else to do... I (47097) chip[DL]: WIFI_EVENT_AP_START I (47097) chip[DL]: WiFi AP state change: NotActive -> Active I (47107) phy: chan:1,max_power:80 I (47107) phy: chan:2,max_power:80 I (47117) phy: chan:3,max_power:80 I (47127) phy: chan:4,max_power:80 I (47127) phy: chan:5,max_power:80 I (47137) phy: chan:6,max_power:80 I (47137) phy: chan:7,max_power:80 I (47137) phy: chan:8,max_power:80 I (47147) phy: chan:9,max_power:80 I (47147) phy: chan:10,max_power:80 I (47147) phy: chan:11,max_power:80 I (47157) phy: chan:12,max_power:80 I (47157) phy: chan:13,max_power:80 I (47157) phy: chan:14,max_power:80 I (47167) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (47167) wifi:mode : sta (84:f7:03:60:fb:e4) I (47187) chip[DL]: WiFi AP state change: Active -> Deactivating I (47187) app-devicecallbacks: Current free heap: 105976 I (47197) phy: chan:1,max_power:80 I (47197) phy: chan:2,max_power:80 I (47197) phy: chan:3,max_power:80 I (47207) phy: chan:4,max_power:80 I (47207) phy: chan:5,max_power:80 I (47207) phy: chan:6,max_power:80 I (47217) phy: chan:7,max_power:80 I (47217) phy: chan:8,max_power:80 I (47217) phy: chan:9,max_power:80 I (47227) phy: chan:10,max_power:80 I (47227) phy: chan:11,max_power:80 I (47237) phy: chan:12,max_power:80 I (47247) phy: chan:13,max_power:80 I (47247) phy: chan:14,max_power:80 W (47247) wifi:Haven't to connect to a suitable AP now! I (47257) chip[DL]: Attempting to connect WiFi station interface E (47257) wifi:sta is connecting, return error E (47267) chip[DL]: esp_wifi_connect() failed: Error 12295 (0x00003007) I (47267) chip[DL]: Done driving station state, nothing else to do... I (47277) NimBLE: GATT procedure initiated: notify; I (47277) NimBLE: att_handle=14 I (47297) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (47297) chip[DL]: WIFI_EVENT_AP_STOP I (47307) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (47307) phy: chan:1,max_power:80 I (47317) phy: chan:2,max_power:80 I (47317) phy: chan:3,max_power:80 I (47317) phy: chan:4,max_power:80 I (47327) phy: chan:5,max_power:80 I (47327) phy: chan:6,max_power:80 I (47327) phy: chan:7,max_power:80 I (47337) phy: chan:8,max_power:80 I (47337) phy: chan:9,max_power:80 I (47337) phy: chan:10,max_power:80 I (47347) phy: chan:11,max_power:80 I (47357) phy: chan:12,max_power:80 I (47357) phy: chan:13,max_power:80 I (47367) phy: chan:14,max_power:80 I (47367) app-devicecallbacks: Current free heap: 107464 I (47377) NimBLE: GATT procedure initiated: notify; I (47377) NimBLE: att_handle=14 I (47377) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (47427) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (47437) NimBLE: GATT procedure initiated: notify; I (47447) NimBLE: att_handle=14 I (47447) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (47457) NimBLE: GATT procedure initiated: notify; I (47457) NimBLE: att_handle=14 I (47457) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (47627) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (50117) wifi:new:<1,0>, old:<1,1>, ap:<255,255>, sta:<1,0>, prof:1 I (50657) NimBLE: GATT procedure initiated: notify; I (50667) NimBLE: att_handle=14 I (50667) wifi:state: init -> auth (b0) I (50667) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (50667) wifi:state: auth -> assoc (0) I (50687) wifi:state: assoc -> run (10) I (50717) wifi:connected with TESTSSID, aid = 1, channel 1, BW20, bssid = 16:66:82:fa:9e:c5 I (50717) wifi:security: WPA2-PSK, phy: bgn, rssi: -59 I (50737) wifi:pm start, type: 1 I (50737) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000 I (50737) chip[DL]: WIFI_EVENT_STA_CONNECTED I (50747) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (50747) phy: chan:1,max_power:80 I (50757) phy: chan:2,max_power:80 I (50767) phy: chan:3,max_power:80 I (50767) phy: chan:4,max_power:80 I (50777) phy: chan:5,max_power:80 I (50777) phy: chan:6,max_power:80 I (50777) phy: chan:7,max_power:80 I (50787) phy: chan:8,max_power:80 I (50787) phy: chan:9,max_power:80 I (50787) phy: chan:10,max_power:80 I (50797) phy: chan:11,max_power:80 I (50797) phy: chan:12,max_power:80 I (50797) phy: chan:13,max_power:80 I (50807) phy: chan:14,max_power:80 I (50807) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (50817) chip[DL]: WiFi station interface connected I (50827) chip[DL]: Done driving station state, nothing else to do... I (50837) app-devicecallbacks: Current free heap: 108432 I (50837) chip[DL]: Updating advertising data I (50847) app-devicecallbacks: Current free heap: 108432 I (50887) wifi:BcnInt:102400, DTIM:1 W (52007) wifi:idx:0 (ifx:0, 16:66:82:fa:9e:c5), tid:6, ssn:2, winSize:64 I (52447) chip[DL]: IP_EVENT_GOT_IP6 I (52447) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:86f7:03ff:fe60:fbe4 I (52457) app-devicecallbacks: Current free heap: 108292 I (52457) chip[DIS]: Start dns-sd server I (52467) chip[DIS]: CHIP minimal mDNS started advertising. I (52467) chip[DIS]: Replying to DNS-SD service listing request I (52477) chip[DIS]: Replying to DNS-SD service listing request I (52487) chip[DIS]: Replying to DNS-SD service listing request I (52497) chip[DIS]: Broadcasting mDns reply I (52497) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (52507) chip[DIS]: Using wifi MAC for hostname I (52507) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (52517) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (52517) app-devicecallbacks: Current free heap: 106368 I (52947) esp_netif_handlers: sta ip: 192.168.1.26, mask: 255.255.255.0, gw: 192.168.1.1 I (52947) chip[DL]: IP_EVENT_STA_GOT_IP I (52957) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.26/255.255.255.0 gateway 192.168.1.1 I (52957) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (52967) app-devicecallbacks: Current free heap: 108032 I (52967) app-devicecallbacks: Server ready at: 192.168.1.26:11097 I (52977) chip[DIS]: Start dns-sd server I (52987) chip[DIS]: CHIP minimal mDNS started advertising. I (52997) chip[DIS]: Replying to DNS-SD service listing request I (52997) chip[DIS]: Replying to DNS-SD service listing request I (53007) chip[DIS]: Replying to DNS-SD service listing request I (53007) chip[DIS]: Broadcasting mDns reply I (53017) chip[DIS]: Replying to DNS-SD service listing request I (53017) chip[DIS]: Replying to DNS-SD service listing request I (53037) chip[DIS]: Replying to DNS-SD service listing request I (53037) chip[DIS]: Broadcasting mDns reply I (53047) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (53047) chip[DIS]: Using wifi MAC for hostname I (53057) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (53057) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (53067) app-devicecallbacks: Current free heap: 108056 E (53067) chip[DL]: Long dispatch time: 102 ms I (53087) chip[DIS]: Start dns-sd server I (53087) chip[DIS]: CHIP minimal mDNS started advertising. I (53097) chip[DIS]: Replying to DNS-SD service listing request I (53097) chip[DIS]: Replying to DNS-SD service listing request I (53107) chip[DIS]: Replying to DNS-SD service listing request I (53107) chip[DIS]: Broadcasting mDns reply I (53117) chip[DIS]: Replying to DNS-SD service listing request I (53127) chip[DIS]: Replying to DNS-SD service listing request I (53137) chip[DIS]: Replying to DNS-SD service listing request I (53137) chip[DIS]: Broadcasting mDns reply I (53137) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (53147) chip[DIS]: Using wifi MAC for hostname I (53147) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (53157) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (53177) app-devicecallbacks: Current free heap: 108056 I (53327) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 notify = 0 I (53337) chip[DL]: CHIPoBLE unsubscribe received V (53337) chip[IN]: Clearing BLE pending packets. I (53347) chip[BLE]: Releasing end point's BLE connection back to application. I (55427) chip[DL]: BLE GAP connection terminated (con 1 reason 0x13) I (55447) chip[DL]: IP_EVENT_GOT_IP6 I (55447) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2400:4050:27e2:8b00:86f7:03ff:fe60:fbe4 I (55457) chip[DL]: IPv6 Internet connectivity ESTABLISHED I (55457) app-devicecallbacks: Current free heap: 107844 I (55467) app-devicecallbacks: IPv6 Server ready... I (55467) chip[DIS]: Start dns-sd server I (55477) chip[DIS]: CHIP minimal mDNS started advertising. I (55477) chip[DIS]: Replying to DNS-SD service listing request I (55497) chip[DIS]: Replying to DNS-SD service listing request I (55497) chip[DIS]: Replying to DNS-SD service listing request I (55507) chip[DIS]: Broadcasting mDns reply I (55507) chip[DIS]: Replying to DNS-SD service listing request I (55507) chip[DIS]: Replying to DNS-SD service listing request I (55517) chip[DIS]: Replying to DNS-SD service listing request I (55527) chip[DIS]: Broadcasting mDns reply I (55537) chip[DIS]: Replying to DNS-SD service listing request I (55537) chip[DIS]: Replying to DNS-SD service listing request I (55547) chip[DIS]: Replying to DNS-SD service listing request I (55547) chip[DIS]: Broadcasting mDns reply I (55557) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (55557) chip[DIS]: Using wifi MAC for hostname I (55567) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (55577) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (55587) app-devicecallbacks: Current free heap: 108036 E (55597) chip[DL]: Long dispatch time: 127 ms I (55597) chip[DIS]: Start dns-sd server I (55597) chip[DIS]: CHIP minimal mDNS started advertising. I (55607) chip[DIS]: Replying to DNS-SD service listing request I (55607) chip[DIS]: Replying to DNS-SD service listing request I (55617) chip[DIS]: Replying to DNS-SD service listing request I (55617) chip[DIS]: Broadcasting mDns reply I (55637) chip[DIS]: Replying to DNS-SD service listing request I (55637) chip[DIS]: Replying to DNS-SD service listing request I (55647) chip[DIS]: Replying to DNS-SD service listing request I (55647) chip[DIS]: Broadcasting mDns reply I (55657) chip[DIS]: Replying to DNS-SD service listing request I (55657) chip[DIS]: Replying to DNS-SD service listing request I (55677) chip[DIS]: Replying to DNS-SD service listing request I (55677) chip[DIS]: Broadcasting mDns reply I (55687) chip[DIS]: Found admin pairing for admin 0, node 0x000000000002104E V (55687) chip[DIS]: Using wifi MAC for hostname I (55687) chip[DIS]: Advertise operational node 0000000000000000-000000000002104E I (55697) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (55707) app-devicecallbacks: Current free heap: 108036 E (55707) chip[DL]: Long dispatch time: 115 ms W (77327) wifi:idx:1 (ifx:0, 16:66:82:fa:9e:c5), tid:0, ssn:0, winSize:64 I (77327) chip[EM]: Received message of type 48 and protocolId 0 on exchange 56407 V (77337) chip[EM]: ec id: 56407, Delegate: 0x0x3fc95724 I (77337) chip[IN]: CASE Server received SigmaR1 message. Starting handshake. EC 0x3fc969a8 V (77357) chip[SC]: Waiting for SigmaR1 msg V (77357) chip[SC]: Received SigmaR1 msg V (77357) chip[SC]: Peer assigned session key ID 2 V (77867) chip[SC]: Sent SigmaR2 msg E (77867) chip[DL]: Long dispatch time: 539 ms I (77957) chip[EM]: Received message of type 50 and protocolId 0 on exchange 56407 V (77957) chip[SC]: Received SigmaR3 msg I (78997) chip[IN]: CASE Session established. Setting up the secure channel. V (78997) chip[IN]: New secure session created for device 0x0000000000000000, key 2!! I (79017) chip[IN]: CASE secure channel is available now. E (79017) chip[DL]: Long dispatch time: 1055 ms I (91637) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 1 I (91647) chip[EM]: Received message of type 8 and protocolId 5 on exchange 56408 V (91657) chip[EM]: ec id: 56408, Delegate: 0x0x3fc9c4a0 V (91657) chip[DMG]: ICR moving to [Initialize] V (91667) chip[ZCL]: Received Cluster Command: Cluster=6 Command=1 Endpoint=1 I (91667) chip[ZCL]: On/Off set value: 1 1 I (91677) chip[ZCL]: Toggle on/off from 0 to 1 I (91677) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (91697) app-devicecallbacks: Current free heap: 103544 I (91707) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (91717) app-devicecallbacks: Current free heap: 103544 I (91717) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (91727) app-devicecallbacks: Unhandled cluster ID: 5 I (91737) app-devicecallbacks: Current free heap: 103544 V (91737) chip[DMG]: ICR moving to [AddCommand] V (91757) chip[IN]: Secure message was encrypted: Msg ID 1 I (91757) chip[IN]: Encrypted message 0x3fc96920 from 0x000000000002104E to 0x000000000001B669 of type 9 and protocolId 5 on exchange 56408. I (91767) chip[IN]: Sending msg 0x3fc96920 to 0x000000000001B669 at utc time: 91771 msec I (91777) chip[IN]: Sending secure msg on generic transport I (91777) chip[IN]: Secure msg send status No Error V (91787) chip[DMG]: ICR moving to [ Sending] V (91787) chip[DMG]: ICR moving to [Uninitiali] E (91797) chip[DL]: Long dispatch time: 151 ms I (91807) chip[ZCL]: Event: move from 0 I (91807) chip[ZCL]: to 255 I (91807) chip[ZCL]: (diff +1) I (91817) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (91827) app-devicecallbacks: Current free heap: 106592 I (91827) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (91837) app-devicecallbacks: Unhandled cluster ID: 5 I (91847) app-devicecallbacks: Current free heap: 106592 I (91877) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 1 I (91877) chip[EM]: Received message of type 16 and protocolId 0 on exchange 56408 I (101677) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 1 I (101677) chip[EM]: Received message of type 2 and protocolId 5 on exchange 56409 V (101687) chip[EM]: ec id: 56409, Delegate: 0x0x3fc9c4a0 V (101687) chip[DMG]: Receive Read request V (101707) chip[DMG]: IM RH moving to [Initialized] V (101707) chip[DMG]: IM RH moving to [Reportable] V (101707) chip[DMG]: Cluster 402, Field 0 is dirty V (101717) chip[DMG]: Received Cluster Command: Cluster=402 NodeId=0x000000000002104E Endpoint=1 FieldId=0 ListIndex=0 V (101727) chip[DMG]: Sending report... V (101727) chip[IN]: Secure message was encrypted: Msg ID 2 I (101727) chip[IN]: Encrypted message 0x3fc96920 from 0x000000000002104E to 0x000000000001B669 of type 5 and protocolId 5 on exchange 56409. I (101757) chip[IN]: Sending msg 0x3fc96920 to 0x000000000001B669 at utc time: 101758 msec I (101757) chip[IN]: Sending secure msg on generic transport I (101767) chip[IN]: Secure msg send status No Error V (101767) chip[DMG]: IM RH moving to [Uninitialized] V (101777) chip[DMG]: ReportsInFlight = 1 with readHandler 0, RE has no more messages V (101777) chip[DMG]: OnReportConfirm: NumReports = 0 V (101787) chip[DMG]: IM RH moving to [Uninitialized] I (101817) chip[IN]: Secure transport received message destined to fabric 0, node 0x000000000002104E. Key ID 1 I (101817) chip[EM]: Received message of type 16 and protocolId 0 on exchange 56409