entry 0x40080694 I (29) boot: ESP-IDF v4.4 2nd stage bootloader I (29) boot: compile time 09:36:03 I (29) boot: chip revision: 3 I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (43) boot.esp32: SPI Mode : DIO I (48) boot.esp32: SPI Flash Size : 4MB I (53) boot: Enabling RNG early entropy source... I (58) boot: Partition Table: I (62) boot: ## Label Usage Type ST Offset Length I (69) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (76) boot: 1 otadata OTA data 01 00 0000f000 00002000 I (84) boot: 2 phy_init RF data 01 01 00011000 00001000 I (91) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (99) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (106) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000 I (114) boot: End of partition table I (118) boot: No factory image, trying OTA 0 I (123) boot_comm: chip revision: 3, min. application chip revision: 0 I (130) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=3be1ch (245276) map I (227) esp_image: segment 1: paddr=0005be44 vaddr=3ffbdb60 size=041d4h ( 16852) load I (234) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=106948h (1075528) map I (624) esp_image: segment 3: paddr=00166970 vaddr=3ffc1d34 size=0438ch ( 17292) load I (631) esp_image: segment 4: paddr=0016ad04 vaddr=40080000 size=1e4e4h (124132) load I (682) esp_image: segment 5: paddr=001891f0 vaddr=50000000 size=00010h ( 16) load I (698) boot: Loaded app from partition at offset 0x20000 I (753) boot: Set actual ota_seq=1 in otadata[0] I (753) boot: Disabling RNG early entropy source... I (764) cpu_start: Pro cpu up. I (764) cpu_start: Starting app cpu, entry point is 0x400814d8 0x400814d8: call_start_cpu1 at /Users/priyankahonnakasturi/new_test/tools/esp-idf/components/esp_system/port/cpu_start.c:156 I (0) cpu_start: App cpu up. I (780) cpu_start: Pro cpu start user code I (781) cpu_start: cpu freq: 160000000 I (781) cpu_start: Application information: I (785) cpu_start: Project name: chip-all-clusters-app I (791) cpu_start: App version: TE9-1022-g770a2e247-dirty I (798) cpu_start: Compile time: Jul 5 2022 09:39:51 I (804) cpu_start: ELF file SHA256: c015dc443eede6f1... I (810) cpu_start: ESP-IDF: v4.4 I (815) heap_init: Initializing. RAM available for dynamic allocation: I (822) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (828) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (834) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (840) heap_init: At 3FFD8808 len 000077F8 (29 KiB): DRAM I (846) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (853) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (859) heap_init: At 4009E4E4 len 00001B1C (6 KiB): IRAM I (866) spi_flash: detected chip: generic I (870) spi_flash: flash io: dio W (874) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. I (890) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (921) all-clusters-app: ================================================== I (921) all-clusters-app: chip-esp32-all-cluster-demo starting I (931) all-clusters-app: ================================================== I (1111) wifi:wifi driver task: 3ffde9dc, prio:23, stack:6656, core=0 I (1111) system_api: Base MAC address is not set I (1111) system_api: read default base MAC address from EFUSE > I (1121) wifi:wifi firmware version: 7679c42 I (1131) wifi:wifi certification version: v7.0 I (1131) wifi:config NVS flash: enabled I (1141) wifi:config nano formating: disabled I (1141) wifi:Init data frame dynamic rx buffer num: 32 I (1141) wifi:Init management frame dynamic rx buffer num: 32 I (1151) wifi:Init management short buffer num: 32 I (1151) wifi:Init dynamic tx buffer num: 32 I (1151) wifi:Init static rx buffer size: 1600 I (1161) wifi:Init static rx buffer num: 10 I (1161) wifi:Init dynamic rx buffer num: 32 I (1161) wifi_init: rx ba win: 6 I (1181) wifi_init: tcpip mbox: 32 I (1181) wifi_init: udp mbox: 6 I (1181) wifi_init: tcp mbox: 6 I (1191) wifi_init: tcp tx win: 5744 I (1191) wifi_init: tcp rx win: 5744 I (1191) wifi_init: tcp mss: 1440 I (1201) wifi_init: WiFi IRAM OP enabled I (1201) wifi_init: WiFi RX IRAM OP enabled I (1211) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1) I (1211) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0) I (1231) chip[DL]: NVS set: chip-factory/unique-id = "7F6B775517C83AC2" I (1231) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP I (1231) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (1241) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (1241) all-clusters-app: ------------------------Starting App Task--------------------------- I (1251) BTDM_INIT: BT controller compile version [6a07b06] I (1261) app-task: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (1261) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 W (1271) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration I (1271) app-task: silicon revision 3, I (1291) app-task: 4MB external flash I (1301) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (1301) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (1311) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (1321) chip[SVR]: Manual pairing code: [34970112332] I (1721) CHIP[DL]: BLE host-controller synced I (2201) all-clusters-app: Display initialized (height 240, width 320) I (2211) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2221) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2221) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2241) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2231) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2261) NimBLE: GAP procedure initiated: advertise; I (2271) NimBLE: disc_mode=2 I (2271) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2281) NimBLE: I (2291) chip[DL]: CHIPoBLE advertising started E (2291) chip[DL]: Long dispatch time: 1044 ms, for event type 2 I (2291) chip[DL]: Starting ESP WiFi layer I (2311) wifi:mode : sta (08:3a:f2:67:b5:0c) I (2311) wifi:enable tsf W (2311) wifi:Haven't to connect to a suitable AP now! I (2311) chip[DL]: Done driving station state, nothing else to do... W (2321) wifi:Haven't to connect to a suitable AP now! I (2321) chip[DL]: Done driving station state, nothing else to do... I (2331) chip[SVR]: Server initializing... I (2341) chip[TS]: Last Known Good Time: [unknown] I (2341) chip[TS]: Setting Last Known Good Time to firmware build time 2022-07-05T09:41:15 I (2351) app-task: App Task started I (2361) chip[DMG]: AccessControl: initializing I (2361) chip[DMG]: Examples::AccessControlDelegate::Init I (2371) chip[DMG]: AccessControl: setting I (2371) chip[DMG]: DefaultAclStorage: initializing I (2371) chip[DMG]: DefaultAclStorage: 0 entries loaded I (2381) chip[ZCL]: Using ZAP configuration... I (2411) chip[DMG]: AccessControlCluster: initializing I (2421) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2431) app-devicecallbacks: Unhandled cluster ID: 48 I (2431) app-devicecallbacks: Current free heap: 71308 E (2441) chip[ZCL]: GeneralDiagnostics: Failed to record BootReason event: 3 I (2451) chip[ZCL]: Initiating Admin Commissioning cluster. I (2461) chip[ZCL]: Door Lock server initialized I (2461) chip[ZCL]: Initialize PCC Plugin Server Cluster. I (2461) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (2471) app-devicecallbacks: Current free heap: 71260 I (2481) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2501) app-devicecallbacks: Unhandled cluster ID: 4 I (2501) app-devicecallbacks: Current free heap: 71260 I (2511) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002b', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2521) app-devicecallbacks: Unhandled cluster ID: 43 I (2531) app-devicecallbacks: Current free heap: 71260 I (2531) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2541) app-devicecallbacks: Current free heap: 71260 I (2551) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2571) app-devicecallbacks: Unhandled cluster ID: 4 I (2571) app-devicecallbacks: Current free heap: 71260 I (2581) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2581) app-devicecallbacks: Unhandled cluster ID: 5 I (2591) app-devicecallbacks: Current free heap: 71260 I (2591) chip[ZCL]: On/Off set value: 1 0 I (2601) chip[ZCL]: On/off already set to new value I (2611) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2621) app-devicecallbacks: Current free heap: 71260 I (2621) chip[ZCL]: Window Covering Cluster init I (2631) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2641) app-devicecallbacks: Unhandled cluster ID: 258 I (2651) app-devicecallbacks: Current free heap: 71260 I (2651) chip[ZCL]: WC POST ATTRIBUTE=7 I (2661) chip[ZCL]: ConfigStatus 0x1B Operational=1 OnlineReserved=1 I (2671) chip[ZCL]: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0) I (2671) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (2681) chip[ZCL]: Constant Pressure Supported I (2681) chip[ZCL]: PCC Server: Constant Proportional Pressure Supported I (2691) chip[ZCL]: PCC Server: Constant Flow Supported I (2701) chip[ZCL]: PCC Server: Constant Temperature Supported I (2711) chip[ZCL]: PCC Server: Constant Speed Supported I (2711) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2721) app-devicecallbacks: Unhandled cluster ID: 768 I (2731) app-devicecallbacks: Current free heap: 71260 I (2731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2751) app-devicecallbacks: Unhandled cluster ID: 768 I (2751) app-devicecallbacks: Current free heap: 71260 I (2761) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2771) app-devicecallbacks: Unhandled cluster ID: 768 I (2771) app-devicecallbacks: Current free heap: 71260 I (2791) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2801) app-devicecallbacks: Unhandled cluster ID: 1030 I (2801) app-devicecallbacks: Current free heap: 71260 I (2811) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2811) app-devicecallbacks: Unhandled cluster ID: 1030 I (2821) app-devicecallbacks: Current free heap: 71260 I (2831) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (2841) app-devicecallbacks: Unhandled cluster ID: 4 I (2851) app-devicecallbacks: Current free heap: 71260 I (2851) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (2861) app-devicecallbacks: Unhandled cluster ID: 1030 I (2871) app-devicecallbacks: Current free heap: 71260 I (2881) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2891) app-devicecallbacks: Unhandled cluster ID: 1030 I (2901) app-devicecallbacks: Current free heap: 71260 I (2911) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2921) chip[DIS]: Updating services using commissioning mode 1 I (2931) chip[DIS]: CHIP minimal mDNS started advertising. I (2931) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (2941) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (2951) chip[DIS]: mDNS service published: _matterc._udp I (2961) chip[IN]: CASE Server enabling CASE session setups I (2961) chip[SVR]: Joining Multicast groups I (2961) chip[SVR]: Server Listening... I (2981) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2981) app-devicecallbacks: Unhandled cluster ID: 1026 I (2991) app-devicecallbacks: Current free heap: 69120 I (2991) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3011) app-devicecallbacks: Unhandled cluster ID: 257 I (3021) app-devicecallbacks: Current free heap: 69000 I (3021) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3031) app-devicecallbacks: Unhandled cluster ID: 1030 I (3031) app-devicecallbacks: Current free heap: 68048 I (3051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3061) app-devicecallbacks: Unhandled cluster ID: 69 I (3061) app-devicecallbacks: Current free heap: 67928 I (3071) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3081) app-devicecallbacks: Unhandled cluster ID: 1026 I (3081) app-devicecallbacks: Current free heap: 67568 I (3101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3101) app-devicecallbacks: Unhandled cluster ID: 513 I (3111) app-devicecallbacks: Current free heap: 67568 I (3111) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (3131) app-devicecallbacks: Unhandled cluster ID: 513 I (3141) app-devicecallbacks: Current free heap: 67520 I (3141) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001e' I (3151) app-devicecallbacks: Unhandled cluster ID: 513 I (3151) app-devicecallbacks: Current free heap: 67376 I (3171) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3181) app-devicecallbacks: Unhandled cluster ID: 1029 I (3181) app-devicecallbacks: Current free heap: 67256 I (3191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3201) app-devicecallbacks: Unhandled cluster ID: 1024 I (3211) app-devicecallbacks: Current free heap: 67104 I (3221) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3221) app-devicecallbacks: Current free heap: 66984 I (3251) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3251) app-devicecallbacks: Current free heap: 66880 I (3261) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3271) app-devicecallbacks: Unhandled cluster ID: 768 I (3271) app-devicecallbacks: Current free heap: 66760 I (3291) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0001' I (3301) app-devicecallbacks: Unhandled cluster ID: 768 I (3301) app-devicecallbacks: Current free heap: 66692 I (3311) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000e' I (3321) app-devicecallbacks: Unhandled cluster ID: 258 I (3331) app-devicecallbacks: Current free heap: 66560 I (3331) chip[ZCL]: WC POST ATTRIBUTE=14 I (3341) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000f' I (3351) app-devicecallbacks: Unhandled cluster ID: 258 I (3361) app-devicecallbacks: Current free heap: 66512 I (3361) chip[ZCL]: WC POST ATTRIBUTE=15 I (3371) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000a' I (3381) app-devicecallbacks: Unhandled cluster ID: 258 I (3381) app-devicecallbacks: Current free heap: 66416 I (3401) chip[ZCL]: WC POST ATTRIBUTE=10 I (3401) chip[ZCL]: 0x3f412e63ep 1 clus 0x0000_002F attr 0x0000_000C not supported I (3401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002f', EndPoint ID: '0x01', Attribute ID: '0x000e' I (3411) app-devicecallbacks: Unhandled cluster ID: 47 I (3421) app-devicecallbacks: Current free heap: 66248 E (3421) chip[DL]: Long dispatch time: 1098 ms, for event type 2 I (3441) app-devicecallbacks: Current free heap: 66248 I (3441) chip[DL]: WIFI_EVENT_STA_START W (3451) wifi:Haven't to connect to a suitable AP now! I (3451) chip[DL]: Done driving station state, nothing else to do... I (3451) app-devicecallbacks: Current free heap: 66248 I (3471) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (3471) chip[DL]: Device already advertising, stop active advertisement and restart I (3481) NimBLE: GAP procedure initiated: stop advertising. I (3491) NimBLE: GAP procedure initiated: advertise; I (3491) NimBLE: disc_mode=2 I (3501) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (3511) NimBLE: I (3511) chip[SVR]: Cannot load binding table: a0 I (22191) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (22451) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (22781) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (23311) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (23311) DeviceWithDisplay: Opening Setup list I (23761) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (24111) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (24111) DeviceWithDisplay: Opening options 1: Reset to factory I (24121) chip[TS]: Pending Last Known Good Time: 2022-07-05T09:41:15 I (24121) chip[TS]: Previous Last Known Good Time: 2022-07-05T09:41:15 I (24121) chip[TS]: Reverted Last Known Good Time to previous value I (24141) chip[DL]: Performing factory reset I (24151) wifi:flush txq I (24151) wifi:stop sw txq I (24151) wifi:lmac stop hw txq I (24291) chip[DL]: System restarting ets Jul 29 2019 12:21:46 rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:6604 ho 0 tail 12 room 4 load:0x40078000,len:14780 load:0x40080400,len:3792 0x40080400: _init at ??:? entry 0x40080694 I (29) boot: ESP-IDF v4.4 2nd stage bootloader I (29) boot: compile time 09:36:03 I (29) boot: chip revision: 3 I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (43) boot.esp32: SPI Mode : DIO I (48) boot.esp32: SPI Flash Size : 4MB I (52) boot: Enabling RNG early entropy source... I (58) boot: Partition Table: I (61) boot: ## Label Usage Type ST Offset Length I (69) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (76) boot: 1 otadata OTA data 01 00 0000f000 00002000 I (84) boot: 2 phy_init RF data 01 01 00011000 00001000 I (91) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (99) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (106) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000 I (114) boot: End of partition table I (118) boot_comm: chip revision: 3, min. application chip revision: 0 I (125) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=3be1ch (245276) map I (222) esp_image: segment 1: paddr=0005be44 vaddr=3ffbdb60 size=041d4h ( 16852) load I (229) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=106948h (1075528) map I (619) esp_image: segment 3: paddr=00166970 vaddr=3ffc1d34 size=0438ch ( 17292) load I (626) esp_image: segment 4: paddr=0016ad04 vaddr=40080000 size=1e4e4h (124132) load I (677) esp_image: segment 5: paddr=001891f0 vaddr=50000000 size=00010h ( 16) load I (693) boot: Loaded app from partition at offset 0x20000 I (693) boot: Disabling RNG early entropy source... I (705) cpu_start: Pro cpu up. I (705) cpu_start: Starting app cpu, entry point is 0x400814d8 0x400814d8: call_start_cpu1 at /Users/priyankahonnakasturi/new_test/tools/esp-idf/components/esp_system/port/cpu_start.c:156 I (691) cpu_start: App cpu up. I (721) cpu_start: Pro cpu start user code I (721) cpu_start: cpu freq: 160000000 I (721) cpu_start: Application information: I (726) cpu_start: Project name: chip-all-clusters-app I (732) cpu_start: App version: TE9-1022-g770a2e247-dirty I (738) cpu_start: Compile time: Jul 5 2022 09:39:51 I (744) cpu_start: ELF file SHA256: c015dc443eede6f1... I (750) cpu_start: ESP-IDF: v4.4 I (755) heap_init: Initializing. RAM available for dynamic allocation: I (762) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (768) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (774) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (781) heap_init: At 3FFD8808 len 000077F8 (29 KiB): DRAM I (787) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (793) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (800) heap_init: At 4009E4E4 len 00001B1C (6 KiB): IRAM I (807) spi_flash: detected chip: generic I (810) spi_flash: flash io: dio W (814) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. I (831) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (941) all-clusters-app: ================================================== I (941) all-clusters-app: chip-esp32-all-cluster-demo starting I (951) all-clusters-app: ================================================== I (1131) wifi:wifi driver task: 3ffdebb0, prio:23, stack:6656, core=0 I (1131) system_api: Base MAC address is not set I (1131) system_api: read default base MAC address from EFUSE > I (1161) wifi:wifi firmware version: 7679c42 I (1161) wifi:wifi certification version: v7.0 I (1161) wifi:config NVS flash: enabled I (1161) wifi:config nano formating: disabled I (1171) wifi:Init data frame dynamic rx buffer num: 32 I (1171) wifi:Init management frame dynamic rx buffer num: 32 I (1181) wifi:Init management short buffer num: 32 I (1191) wifi:Init dynamic tx buffer num: 32 I (1191) wifi:Init static rx buffer size: 1600 I (1191) wifi:Init static rx buffer num: 10 I (1201) wifi:Init dynamic rx buffer num: 32 I (1201) wifi_init: rx ba win: 6 I (1201) wifi_init: tcpip mbox: 32 I (1211) wifi_init: udp mbox: 6 I (1211) wifi_init: tcp mbox: 6 I (1211) wifi_init: tcp tx win: 5744 I (1231) wifi_init: tcp rx win: 5744 I (1231) wifi_init: tcp mss: 1440 I (1231) wifi_init: WiFi IRAM OP enabled I (1241) wifi_init: WiFi RX IRAM OP enabled I (1251) chip[DL]: NVS set: chip-counters/reboot-count = 2 (0x2) I (1251) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP I (1251) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (1261) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (1271) all-clusters-app: ------------------------Starting App Task--------------------------- I (1271) BTDM_INIT: BT controller compile version [6a07b06] I (1281) app-task: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (1291) app-task: silicon revision 3, I (1301) app-task: 4MB external flash I (1301) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (1311) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (1291) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (1311) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (1331) chip[SVR]: Manual pairing code: [34970112332] I (1701) CHIP[DL]: BLE host-controller synced I (2211) all-clusters-app: Display initialized (height 240, width 320) I (2221) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2221) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2231) NimBLE: GAP procedure initiated: advertise; I (2241) NimBLE: disc_mode=2 I (2241) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2251) NimBLE: I (2231) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2261) chip[DL]: CHIPoBLE advertising started I (2271) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 E (2271) chip[DL]: Long dispatch time: 998 ms, for event type 2 I (2291) chip[DL]: Starting ESP WiFi layer I (2281) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2291) wifi:mode : sta (08:3a:f2:67:b5:0c) I (2301) wifi:enable tsf W (2311) wifi:Haven't to connect to a suitable AP now! I (2321) chip[DL]: Done driving station state, nothing else to do... W (2321) wifi:Haven't to connect to a suitable AP now! I (2341) chip[DL]: Done driving station state, nothing else to do... I (2341) chip[SVR]: Server initializing... I (2341) chip[TS]: Last Known Good Time: [unknown] I (2361) chip[TS]: Setting Last Known Good Time to firmware build time 2022-07-05T09:41:15 I (2411) app-task: App Task started I (2411) chip[DMG]: AccessControl: initializing I (2411) chip[DMG]: Examples::AccessControlDelegate::Init I (2431) chip[DMG]: AccessControl: setting I (2431) chip[DMG]: DefaultAclStorage: initializing I (2431) chip[DMG]: DefaultAclStorage: 0 entries loaded I (2441) chip[ZCL]: Using ZAP configuration... I (2471) chip[DMG]: AccessControlCluster: initializing I (2471) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2481) app-devicecallbacks: Unhandled cluster ID: 48 I (2481) app-devicecallbacks: Current free heap: 71044 E (2501) chip[ZCL]: GeneralDiagnostics: Failed to record BootReason event: 3 I (2501) chip[ZCL]: Initiating Admin Commissioning cluster. I (2511) chip[ZCL]: Door Lock server initialized I (2511) chip[ZCL]: Initialize PCC Plugin Server Cluster. I (2521) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (2541) app-devicecallbacks: Current free heap: 70996 I (2541) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2551) app-devicecallbacks: Unhandled cluster ID: 4 I (2551) app-devicecallbacks: Current free heap: 70996 I (2571) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002b', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2571) app-devicecallbacks: Unhandled cluster ID: 43 I (2581) app-devicecallbacks: Current free heap: 70996 I (2581) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2591) app-devicecallbacks: Current free heap: 70996 I (2601) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2621) app-devicecallbacks: Unhandled cluster ID: 4 I (2621) app-devicecallbacks: Current free heap: 70996 I (2631) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2641) app-devicecallbacks: Unhandled cluster ID: 5 I (2641) app-devicecallbacks: Current free heap: 70996 I (2651) chip[ZCL]: On/Off set value: 1 0 I (2661) chip[ZCL]: On/off already set to new value I (2661) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2671) app-devicecallbacks: Current free heap: 70996 I (2671) chip[ZCL]: Window Covering Cluster init I (2691) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2691) app-devicecallbacks: Unhandled cluster ID: 258 I (2701) app-devicecallbacks: Current free heap: 70996 I (2701) chip[ZCL]: WC POST ATTRIBUTE=7 I (2721) chip[ZCL]: ConfigStatus 0x1B Operational=1 OnlineReserved=1 I (2721) chip[ZCL]: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0) I (2731) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (2731) chip[ZCL]: Constant Pressure Supported I (2741) chip[ZCL]: PCC Server: Constant Proportional Pressure Supported I (2741) chip[ZCL]: PCC Server: Constant Flow Supported I (2751) chip[ZCL]: PCC Server: Constant Temperature Supported I (2761) chip[ZCL]: PCC Server: Constant Speed Supported I (2771) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2771) app-devicecallbacks: Unhandled cluster ID: 768 I (2781) app-devicecallbacks: Current free heap: 70996 I (2781) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2791) app-devicecallbacks: Unhandled cluster ID: 768 I (2811) app-devicecallbacks: Current free heap: 70996 I (2811) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2821) app-devicecallbacks: Unhandled cluster ID: 768 I (2831) app-devicecallbacks: Current free heap: 70996 I (2831) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2851) app-devicecallbacks: Unhandled cluster ID: 1030 I (2861) app-devicecallbacks: Current free heap: 70996 I (2861) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2871) app-devicecallbacks: Unhandled cluster ID: 1030 I (2871) app-devicecallbacks: Current free heap: 70996 I (2881) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (2901) app-devicecallbacks: Unhandled cluster ID: 4 I (2901) app-devicecallbacks: Current free heap: 70996 I (2911) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (2921) app-devicecallbacks: Unhandled cluster ID: 1030 I (2921) app-devicecallbacks: Current free heap: 70996 I (2931) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2951) app-devicecallbacks: Unhandled cluster ID: 1030 I (2951) app-devicecallbacks: Current free heap: 70996 I (2971) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2971) chip[DIS]: Updating services using commissioning mode 1 I (2991) chip[DIS]: CHIP minimal mDNS started advertising. I (2991) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (3001) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (3001) chip[DIS]: mDNS service published: _matterc._udp I (3011) chip[IN]: CASE Server enabling CASE session setups I (3021) chip[SVR]: Joining Multicast groups I (3021) chip[SVR]: Server Listening... I (3031) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3041) app-devicecallbacks: Unhandled cluster ID: 1026 I (3051) app-devicecallbacks: Current free heap: 68856 I (3051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3061) app-devicecallbacks: Unhandled cluster ID: 257 I (3071) app-devicecallbacks: Current free heap: 68736 I (3081) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3091) app-devicecallbacks: Unhandled cluster ID: 1030 I (3101) app-devicecallbacks: Current free heap: 67784 I (3101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3111) app-devicecallbacks: Unhandled cluster ID: 69 I (3111) app-devicecallbacks: Current free heap: 67664 I (3131) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3141) app-devicecallbacks: Unhandled cluster ID: 1026 I (3141) app-devicecallbacks: Current free heap: 67304 I (3151) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3161) app-devicecallbacks: Unhandled cluster ID: 513 I (3161) app-devicecallbacks: Current free heap: 67304 I (3181) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (3181) app-devicecallbacks: Unhandled cluster ID: 513 I (3191) app-devicecallbacks: Current free heap: 67256 I (3191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001e' I (3211) app-devicecallbacks: Unhandled cluster ID: 513 I (3221) app-devicecallbacks: Current free heap: 67112 I (3221) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3231) app-devicecallbacks: Unhandled cluster ID: 1029 I (3241) app-devicecallbacks: Current free heap: 66992 I (3241) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3261) app-devicecallbacks: Unhandled cluster ID: 1024 I (3261) app-devicecallbacks: Current free heap: 66840 I (3271) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3271) app-devicecallbacks: Current free heap: 66720 I (3301) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3301) app-devicecallbacks: Current free heap: 66616 I (3321) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3331) app-devicecallbacks: Unhandled cluster ID: 768 I (3331) app-devicecallbacks: Current free heap: 66496 I (3341) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0001' I (3351) app-devicecallbacks: Unhandled cluster ID: 768 I (3351) app-devicecallbacks: Current free heap: 66428 I (3371) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000e' I (3371) app-devicecallbacks: Unhandled cluster ID: 258 I (3381) app-devicecallbacks: Current free heap: 66296 I (3381) chip[ZCL]: WC POST ATTRIBUTE=14 I (3401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000f' I (3401) app-devicecallbacks: Unhandled cluster ID: 258 I (3411) app-devicecallbacks: Current free heap: 66248 I (3411) chip[ZCL]: WC POST ATTRIBUTE=15 I (3421) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x000a' I (3441) app-devicecallbacks: Unhandled cluster ID: 258 I (3441) app-devicecallbacks: Current free heap: 66152 I (3451) chip[ZCL]: WC POST ATTRIBUTE=10 I (3451) chip[ZCL]: 0x3f412e63ep 1 clus 0x0000_002F attr 0x0000_000C not supported I (3451) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002f', EndPoint ID: '0x01', Attribute ID: '0x000e' I (3461) app-devicecallbacks: Unhandled cluster ID: 47 I (3481) app-devicecallbacks: Current free heap: 65984 E (3481) chip[DL]: Long dispatch time: 1136 ms, for event type 2 I (3491) app-devicecallbacks: Current free heap: 65984 I (3491) chip[DL]: WIFI_EVENT_STA_START W (3501) wifi:Haven't to connect to a suitable AP now! I (3501) chip[DL]: Done driving station state, nothing else to do... I (3511) app-devicecallbacks: Current free heap: 65984 I (3521) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (3531) chip[DL]: Device already advertising, stop active advertisement and restart I (3531) NimBLE: GAP procedure initiated: stop advertising. I (3541) NimBLE: GAP procedure initiated: advertise; I (3541) NimBLE: disc_mode=2 I (3551) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (3561) NimBLE: I (3561) chip[SVR]: Cannot load binding table: a0 I (5331) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (5631) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (5981) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (5981) DeviceWithDisplay: Opening QR code screen I (5991) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (5991) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (6001) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (6001) chip[SVR]: Manual pairing code: [34970112332] I (9201) chip[DL]: BLE GAP connection established (con 0) I (9201) chip[DL]: CHIPoBLE advertising stopped I (9201) app-devicecallbacks: Current free heap: 65804 I (9981) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (9981) chip[BLE]: local and remote recv window sizes = 5 I (9981) chip[BLE]: selected BTP version 4 I (9991) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (10161) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1 I (10161) chip[DL]: CHIPoBLE subscribe received I (10161) NimBLE: GATT procedure initiated: notify; I (10171) NimBLE: att_handle=14 I (10181) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (10191) app-devicecallbacks: CHIPoBLE connection established I (10191) app-devicecallbacks: Current free heap: 65796 I (10221) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (10221) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:153416947 on exchange 55575r I (10241) chip[IN]: Prepared unauthenticated message 0x3ffe8f94 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 55575r with MessageCounter:102198248. I (10251) chip[IN]: Sending unauthenticated msg 0x3ffe8f94 with MessageCounter:102198248 to 0x0000000000000000 at monotonic time: 00000000000024B2 msec I (10271) NimBLE: GATT procedure initiated: notify; I (10271) NimBLE: att_handle=14 I (10281) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (10371) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (10371) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:153416948 on exchange 55575r I (13571) chip[IN]: Prepared unauthenticated message 0x3ffe8f14 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 55575r with MessageCounter:102198249. I (13591) chip[IN]: Sending unauthenticated msg 0x3ffe8f14 with MessageCounter:102198249 to 0x0000000000000000 at monotonic time: 00000000000031B8 msec I (13601) NimBLE: GATT procedure initiated: notify; I (13601) NimBLE: att_handle=14 I (13611) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (13621) chip[DL]: Long dispatch time: 3245 ms, for event type 7 I (13701) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (13701) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:153416949 on exchange 55575r I (13721) chip[IN]: Prepared unauthenticated message 0x3ffe8fa4 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 55575r with MessageCounter:102198250. I (13731) chip[IN]: Sending unauthenticated msg 0x3ffe8fa4 with MessageCounter:102198250 to 0x0000000000000000 at monotonic time: 0000000000003248 msec I (13741) NimBLE: GATT procedure initiated: notify; I (13741) NimBLE: att_handle=14 I (13761) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (13761) chip[SC]: SecureSession[0x3ffc87a8]: Moving from state 'kEstablishing' --> 'kActive' I (13771) chip[SVR]: Commissioning completed session establishment step I (13781) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (13791) chip[DIS]: Updating services using commissioning mode 0 I (13801) chip[DIS]: CHIP minimal mDNS started advertising. I (13801) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (13811) chip[SVR]: Device completed Rendezvous process E (13811) chip[DL]: Long dispatch time: 114 ms, for event type 7 I (15561) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (15561) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:160349193 on exchange 55576r I (15591) chip[IN]: Prepared secure message 0x3ffe9214 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 55576r with MessageCounter:20192386. I (15601) chip[IN]: Sending encrypted msg 0x3ffe9214 with MessageCounter:20192386 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003999 msec I (15621) NimBLE: GATT procedure initiated: notify; I (15621) NimBLE: att_handle=14 I (15621) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (15631) NimBLE: GATT procedure initiated: notify; I (15641) NimBLE: att_handle=14 I (15651) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (15711) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (15711) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349194 on exchange 55577r I (15731) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s) I (15731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (15741) app-devicecallbacks: Unhandled cluster ID: 48 I (15741) app-devicecallbacks: Current free heap: 64792 I (15761) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55577r with MessageCounter:20192387. I (15771) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192387 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003A42 msec I (15791) NimBLE: GATT procedure initiated: notify; I (15791) NimBLE: att_handle=14 I (15801) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (15951) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (15951) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349195 on exchange 55578r I (15971) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (15971) chip[DL]: NVS set: chip-config/country-code = "XX" I (15981) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (15991) app-devicecallbacks: Unhandled cluster ID: 48 I (16001) app-devicecallbacks: Current free heap: 64792 I (16001) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55578r with MessageCounter:20192388. I (16021) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192388 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003B36 msec I (16031) NimBLE: GATT procedure initiated: notify; I (16041) NimBLE: att_handle=14 I (16041) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (16061) chip[DL]: Long dispatch time: 106 ms, for event type 7 I (16101) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (16101) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349196 on exchange 55579r I (16121) chip[ZCL]: OpCreds: Certificate Chain request received for PAI I (16121) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55579r with MessageCounter:20192389. I (16141) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192389 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003BAF msec I (16151) NimBLE: GATT procedure initiated: notify; I (16151) NimBLE: att_handle=14 I (16161) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16171) NimBLE: GATT procedure initiated: notify; I (16181) NimBLE: att_handle=14 I (16181) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16181) NimBLE: GATT procedure initiated: notify; I (16201) NimBLE: att_handle=14 I (16201) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16281) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (16281) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349197 on exchange 55580r I (16301) chip[ZCL]: OpCreds: Certificate Chain request received for DAC I (16301) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55580r with MessageCounter:20192390. I (16321) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192390 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003C62 msec I (16331) NimBLE: GATT procedure initiated: notify; I (16331) NimBLE: att_handle=14 I (16341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16351) NimBLE: GATT procedure initiated: notify; I (16361) NimBLE: att_handle=14 I (16361) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16361) NimBLE: GATT procedure initiated: notify; I (16381) NimBLE: att_handle=14 I (16381) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16491) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (16491) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349198 on exchange 55581r I (16511) chip[ZCL]: OpCreds: Received an AttestationRequest command I (17151) chip[ZCL]: OpCreds: AttestationRequest successful. I (17161) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55581r with MessageCounter:20192391. I (17171) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192391 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000003FB8 msec I (17181) NimBLE: GATT procedure initiated: notify; I (17181) NimBLE: att_handle=14 I (17201) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (17201) chip[DL]: Long dispatch time: 710 ms, for event type 7 I (17211) NimBLE: GATT procedure initiated: notify; I (17211) NimBLE: att_handle=14 I (17221) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (17231) NimBLE: GATT procedure initiated: notify; I (17231) NimBLE: att_handle=14 I (17241) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (17421) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (17421) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349199 on exchange 55582r I (17441) chip[ZCL]: OpCreds: Received a CSRRequest command I (18691) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded I (19311) chip[ZCL]: OpCreds: CSRRequest successful. I (19321) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55582r with MessageCounter:20192392. I (19331) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192392 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000000482A msec I (19351) NimBLE: GATT procedure initiated: notify; I (19351) NimBLE: att_handle=14 I (19361) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (19361) chip[DL]: Long dispatch time: 1942 ms, for event type 7 I (19371) NimBLE: GATT procedure initiated: notify; I (19381) NimBLE: att_handle=14 I (19381) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19461) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19521) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19521) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349200 on exchange 55583r I (19541) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command I (19541) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful. I (19551) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 55583r with MessageCounter:20192393. I (19561) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192393 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000000490D msec I (19581) NimBLE: GATT procedure initiated: notify; I (19581) NimBLE: att_handle=14 I (19591) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19641) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19701) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19701) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349201 on exchange 55584r I (19721) chip[ZCL]: OpCreds: Received an AddNOC command I (19731) chip[FP]: Validating NOC chain I (21011) chip[FP]: NOC chain validation successful I (21011) chip[FP]: Added new fabric at index: 0x1 I (21011) chip[FP]: Assigned compressed fabric ID: 0x0DCA55FB14F3E843, node ID: 0x000000000000000D I (21021) chip[TS]: Last Known Good Time: 2022-07-05T09:41:15 I (21031) chip[TS]: New proposed Last Known Good Time: 2022-07-05T11:17:43 I (21031) chip[TS]: Updating pending Last Known Good Time to 2022-07-05T11:17:43 I (21061) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x4027AF6A66E6FFFE I (21061) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (21081) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (21081) chip[DIS]: mDNS service published: _matter._tcp I (21091) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC I (21091) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 55584r with MessageCounter:20192394. I (21111) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192394 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000004F19 msec I (21121) NimBLE: GATT procedure initiated: notify; I (21131) NimBLE: att_handle=14 I (21131) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (21151) chip[DL]: Long dispatch time: 1446 ms, for event type 7 I (21171) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (21171) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349202 on exchange 55585r I (21191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (21191) app-devicecallbacks: Unhandled cluster ID: 48 I (21201) app-devicecallbacks: Current free heap: 59360 I (21211) chip[IN]: Prepared secure message 0x3ffe8ff4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 55585r with MessageCounter:20192395. I (21221) chip[IN]: Sending encrypted msg 0x3ffe8ff4 with MessageCounter:20192395 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000004F8B msec I (21241) NimBLE: GATT procedure initiated: notify; I (21251) NimBLE: att_handle=14 I (21251) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21321) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (21321) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:160349203 on exchange 55586r I (21341) chip[NP]: ESP NetworkCommissioningDelegate: SSID: HOME-2.4 I (21341) chip[DL]: WiFi station mode change: Enabled -> Disabled I (21381) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (21381) wifi:mode : sta (08:3a:f2:67:b5:0c) + softAP (02:8c:9a:5a:52:c2) I (21381) wifi:Total power save buffer number: 16 I (21381) wifi:Init max length of beacon: 752/752 I (21391) wifi:Init max length of beacon: 752/752 I (21411) chip[DL]: WiFi station mode change: Disabled -> Enabled W (21411) wifi:Haven't to connect to a suitable AP now! I (21411) chip[DL]: Attempting to connect WiFi station interface I (21431) chip[DL]: WiFi station state change: NotConnected -> Connecting I (21431) chip[DL]: Done driving station state, nothing else to do... W (21441) wifi:Haven't to connect to a suitable AP now! I (21441) chip[DL]: Attempting to connect WiFi station interface E (21441) wifi:sta is connecting, return error E (21451) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (21461) wifi:Haven't to connect to a suitable AP now! I (21471) chip[DL]: Attempting to connect WiFi station interface E (21471) wifi:sta is connecting, return error E (21471) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN I (21481) chip[DL]: WIFI_EVENT_AP_START I (21481) chip[DL]: WiFi AP state change: NotActive -> Active I (21491) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (21491) wifi:mode : sta (08:3a:f2:67:b5:0c) I (21511) chip[DL]: WiFi AP state change: Active -> Deactivating I (21511) app-devicecallbacks: Current free heap: 60672 W (21511) wifi:Haven't to connect to a suitable AP now! E (21521) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F I (21531) chip[DL]: WIFI_EVENT_AP_STOP I (21531) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (21551) app-devicecallbacks: Current free heap: 60672 I (23821) NimBLE: GATT procedure initiated: notify; I (23821) NimBLE: att_handle=14 I (23831) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (23841) wifi:new:<11,0>, old:<1,1>, ap:<255,255>, sta:<11,0>, prof:1 I (24621) wifi:state: init -> auth (b0) I (24631) wifi:state: auth -> assoc (0) I (24641) wifi:state: assoc -> run (10) I (24651) wifi:connected with HOME-2.4, aid = 5, channel 11, BW20, bssid = c0:94:35:d6:14:55 I (24651) wifi:security: WPA2-PSK, phy: bgn, rssi: -50 I (24671) wifi:pm start, type: 1 I (24681) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (24681) chip[DL]: WIFI_EVENT_STA_CONNECTED I (24681) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (24701) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (24701) chip[DL]: WiFi station interface connected I (24711) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (24711) app-devicecallbacks: Unhandled cluster ID: 48 I (24721) app-devicecallbacks: Current free heap: 58492 I (24731) chip[IN]: Prepared secure message 0x3ffe9204 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 55586r with MessageCounter:20192396. I (24741) chip[IN]: Sending encrypted msg 0x3ffe9204 with MessageCounter:20192396 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000005D4B msec I (24761) NimBLE: GATT procedure initiated: notify; I (24771) NimBLE: att_handle=14 I (24771) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24781) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged I (24781) chip[DL]: Done driving station state, nothing else to do... I (24801) app-devicecallbacks: Current free heap: 58492 E (24801) chip[DL]: Long dispatch time: 116 ms, for event type 49152 I (24811) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (24811) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (24821) chip[DIS]: mDNS service published: _matter._tcp I (24831) chip[SVR]: Operational advertising enabled I (24841) app-devicecallbacks: Current free heap: 58508 I (24841) chip[DL]: Updating advertising data I (24841) app-devicecallbacks: Current free heap: 60028 I (25621) esp_netif_handlers: sta ip: 10.0.0.164, mask: 255.255.255.0, gw: 10.0.0.1 I (25621) chip[DL]: IP_EVENT_STA_GOT_IP I (25621) chip[DL]: IPv4 address changed on WiFi station interface: 10.0.0.164/255.255.255.0 gateway 10.0.0.1 I (25631) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (25651) app-devicecallbacks: Current free heap: 59996 I (25651) app-devicecallbacks: IPv4 Server ready... I (25661) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (25661) chip[DIS]: Updating services using commissioning mode 0 I (25671) chip[DIS]: CHIP minimal mDNS started advertising. I (25681) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (25681) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (25701) chip[DIS]: mDNS service published: _matter._tcp I (25701) app-devicecallbacks: Current free heap: 58696 I (25701) chip[DIS]: Updating services using commissioning mode 0 I (25711) chip[DIS]: CHIP minimal mDNS started advertising. I (25721) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (25721) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (25741) chip[DIS]: mDNS service published: _matter._tcp I (25741) app-devicecallbacks: Current free heap: 58044 I (25751) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:153416950 on exchange 55587r I (25751) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffca018 I (25771) chip[IN]: CASE Server disabling CASE session setups I (25771) chip[IN]: Prepared unauthenticated message 0x3ffe9074 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 55587r with MessageCounter:102198251. I (25791) chip[IN]: Sending unauthenticated msg 0x3ffe9074 with MessageCounter:102198251 to 0x0000000000000000 at monotonic time: 0000000000006165 msec I (25811) chip[SC]: Received Sigma1 msg I (25811) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x000000000000000D I (26361) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (27771) chip[IN]: Prepared unauthenticated message 0x3ffca2cc to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 55587r with MessageCounter:102198252. I (27781) chip[IN]: Sending unauthenticated msg 0x3ffca2cc with MessageCounter:102198252 to 0x0000000000000000 at monotonic time: 000000000000692C msec I (27801) chip[SC]: Sent Sigma2 msg E (27801) chip[DL]: Long dispatch time: 2048 ms, for event type 3 I (27801) chip[DL]: IP_EVENT_GOT_IP6 I (27811) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:0a3a:f2ff:fe67:b50c I (27821) chip[DL]: IPv6 Internet connectivity ESTABLISHED I (27831) app-devicecallbacks: Current free heap: 53512 I (27841) chip[DL]: IP_EVENT_GOT_IP6 I (27841) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2601:0647:4500:1f20:0a3a:f2ff:fe67:b50c I (27851) app-devicecallbacks: Current free heap: 55716 I (27851) app-devicecallbacks: IPv6 Server ready... I (27861) chip[DIS]: Updating services using commissioning mode 0 I (27871) chip[DIS]: CHIP minimal mDNS started advertising. I (27881) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (27881) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (27901) chip[DIS]: mDNS service published: _matter._tcp I (27901) app-devicecallbacks: Current free heap: 54236 I (27901) chip[DIS]: Updating services using commissioning mode 0 I (27921) chip[DIS]: CHIP minimal mDNS started advertising. I (27931) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (27931) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (27951) chip[DIS]: mDNS service published: _matter._tcp I (27951) app-devicecallbacks: Current free heap: 50208 I (27951) chip[DIS]: Updating services using commissioning mode 0 I (27971) chip[DIS]: CHIP minimal mDNS started advertising. I (27981) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (27981) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (28001) chip[DIS]: mDNS service published: _matter._tcp I (28001) ROUTE_HOOK: Hook already installed on netif, skip... I (28001) app-devicecallbacks: Current free heap: 52888 I (28021) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:153416951 on exchange 55587r I (28031) chip[IN]: Prepared unauthenticated message 0x3ffe9054 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 55587r with MessageCounter:102198253. I (28041) chip[IN]: Sending unauthenticated msg 0x3ffe9054 with MessageCounter:102198253 to 0x0000000000000000 at monotonic time: 0000000000006A32 msec I (28061) chip[SC]: Received Sigma3 msg E (28061) chip[SC]: The device does not support GetClock_RealTimeMS() API: 6c. Falling back to Last Known Good UTC Time I (28881) ROUTE_HOOK: Received RIO I (28881) ROUTE_HOOK: prefix :: lifetime 180 I (30691) chip[IN]: Prepared unauthenticated message 0x3ffca2cc to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 55587r with MessageCounter:102198254. I (30701) chip[IN]: Sending unauthenticated msg 0x3ffca2cc with MessageCounter:102198254 to 0x0000000000000000 at monotonic time: 0000000000007495 msec I (30721) chip[SC]: SecureSession[0x3ffc8860]: Moving from state 'kEstablishing' --> 'kActive' I (30721) chip[IN]: CASE Session established to peer: <4027AF6A66E6FFFE, 1> I (30731) chip[IN]: CASE Server enabling CASE session setups E (30741) chip[DL]: Long dispatch time: 2721 ms, for event type 3 I (30751) NimBLE: GATT procedure initiated: notify; I (30751) NimBLE: att_handle=14 I (30751) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (31031) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177028 on exchange 55588r I (31041) chip[FS]: GeneralCommissioning: Received CommissioningComplete I (31051) chip[FP]: Metadata for Fabric 0x1 persisted to storage. I (31091) chip[TS]: Committing Last Known Good Time to storage: 2022-07-05T11:17:43 I (31101) chip[ZCL]: OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x0DCA55FB14F3E843, FabricId 0000000000000001, NodeId 000000000000000D, VendorId 0xFFF1 I (31141) chip[FS]: GeneralCommissioning: Successfully commited pending fabric data I (31141) chip[FS]: Fail-safe cleanly disarmed I (31141) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000' I (31161) app-devicecallbacks: Unhandled cluster ID: 48 I (31171) app-devicecallbacks: Current free heap: 58996 I (31171) chip[IN]: Prepared secure message 0x3ffca2e4 to 0x4027AF6A66E6FFFE (1) of type 0x9 and protocolId (0, 1) on exchange 55588r with MessageCounter:77741098. I (31191) chip[IN]: Sending encrypted msg 0x3ffca2e4 with MessageCounter:77741098 to 0x4027AF6A66E6FFFE (1) at monotonic time: 0000000000007677 msec E (31201) chip[DL]: Long dispatch time: 173 ms, for event type 3 I (31211) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:153416952 on exchange 55587r I (31221) chip[SVR]: Commissioning completed successfully I (31231) chip[DIS]: Updating services using commissioning mode 0 I (31231) chip[DIS]: CHIP minimal mDNS started advertising. I (31251) chip[DIS]: Advertise operational node 0DCA55FB14F3E843-000000000000000D I (31261) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (31281) chip[DIS]: mDNS service published: _matter._tcp I (31281) chip[SC]: SecureSession[0x3ffc87a8]: Moving from state 'kActive' --> 'kPendingEviction' I (31281) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0 I (31291) chip[BLE]: Releasing end point's BLE connection back to application. I (31291) chip[DL]: CHIPoBLE unsubscribe received I (31311) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213) I (31311) app-devicecallbacks: Commissioning complete I (31321) NimBLE: GAP procedure initiated: stop advertising. W (31331) Timer: Timer not stopped W (31341) Timer: Timer not stopped W (31341) Timer: Timer not stopped I (31351) app-devicecallbacks: BLE deinit successful and memory reclaimed I (31351) app-devicecallbacks: Current free heap: 108544 E (31361) chip[DL]: Long dispatch time: 147 ms, for event type 32781 E (31371) chip[BLE]: no endpoint for unsub recvd I (31371) app-devicecallbacks: CHIPoBLE disconnected I (31381) app-devicecallbacks: Current free heap: 112984 I (31951) ROUTE_HOOK: Received RIO I (31951) ROUTE_HOOK: prefix :: lifetime 180 I (33461) chip[IN]: Sending encrypted msg 0x3ffca2e4 with MessageCounter:77741098 to 0x4027AF6A66E6FFFE (1) at monotonic time: 0000000000007F56 msec I (33491) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:84177030 on exchange 55588r I (34921) ROUTE_HOOK: Received RIO I (34921) ROUTE_HOOK: prefix :: lifetime 180 I (35031) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177031 on exchange 55589r I (35031) chip[ZCL]: On/Off set value: 1 1 I (35031) chip[ZCL]: Toggle on/off from 0 to 1 I (35051) chip[ZCL]: On Command - OffWaitTime : 0 I (35051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002' I (35061) app-devicecallbacks: Unhandled Attribute ID: '0x4002 I (35071) app-devicecallbacks: Current free heap: 113004 I (35071) chip[ZCL]: On/Toggle Command - Stop Timer I (35071) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000' I (35091) app-devicecallbacks: Unhandled Attribute ID: '0x4000 I (35101) app-devicecallbacks: Current free heap: 113004 I (35111) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (35121) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (35131) app-devicecallbacks: Current free heap: 113004 I (35151) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (35161) app-devicecallbacks: Current free heap: 113004 I (35171) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (35181) app-devicecallbacks: Unhandled cluster ID: 5 I (35181) app-devicecallbacks: Current free heap: 113004 I (35201) chip[IN]: Prepared secure message 0x3ffca2cc to 0x4027AF6A66E6FFFE (1) of type 0x9 and protocolId (0, 1) on exchange 55589r with MessageCounter:77741099. I (35211) chip[IN]: Sending encrypted msg 0x3ffca2cc with MessageCounter:77741099 to 0x4027AF6A66E6FFFE (1) at monotonic time: 000000000000862F msec E (35221) chip[DL]: Long dispatch time: 199 ms, for event type 3 I (35331) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177031 on exchange 55589r I (35331) chip[IN]: Prepared secure message 0x3ffe90a4 to 0x4027AF6A66E6FFFE (1) of type 0x10 and protocolId (0, 0) on exchange 55589r with MessageCounter:77741100. I (35351) chip[IN]: Sending encrypted msg 0x3ffe90a4 with MessageCounter:77741100 to 0x4027AF6A66E6FFFE (1) at monotonic time: 00000000000086B8 msec I (35371) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:84177032 on exchange 55589r I (36251) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177033 on exchange 55590r I (36261) chip[ZCL]: On/Off set value: 1 2 I (36261) chip[ZCL]: Toggle on/off from 1 to 0 I (36271) chip[ZCL]: Off Command - OnTime : 0 I (36271) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4001' I (36281) app-devicecallbacks: Unhandled Attribute ID: '0x4001 I (36291) app-devicecallbacks: Current free heap: 113004 I (36311) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (36321) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (36331) app-devicecallbacks: Current free heap: 113004 I (36341) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (36341) app-devicecallbacks: Unhandled cluster ID: 5 I (36351) app-devicecallbacks: Current free heap: 113004 I (36361) chip[IN]: Prepared secure message 0x3ffca2cc to 0x4027AF6A66E6FFFE (1) of type 0x9 and protocolId (0, 1) on exchange 55590r with MessageCounter:77741101. I (36371) chip[IN]: Sending encrypted msg 0x3ffca2cc with MessageCounter:77741101 to 0x4027AF6A66E6FFFE (1) at monotonic time: 0000000000008AB9 msec E (36391) chip[DL]: Long dispatch time: 137 ms, for event type 3 I (36561) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177033 on exchange 55590r I (36561) chip[IN]: Prepared secure message 0x3ffe90a4 to 0x4027AF6A66E6FFFE (1) of type 0x10 and protocolId (0, 0) on exchange 55590r with MessageCounter:77741102. I (36581) chip[IN]: Sending encrypted msg 0x3ffe90a4 with MessageCounter:77741102 to 0x4027AF6A66E6FFFE (1) at monotonic time: 0000000000008B85 msec I (36971) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:84177033 on exchange 55590r I (36971) chip[IN]: Prepared secure message 0x3ffe90a4 to 0x4027AF6A66E6FFFE (1) of type 0x10 and protocolId (0, 0) on exchange 55590r with MessageCounter:77741103. I (36991) chip[IN]: Sending encrypted msg 0x3ffe90a4 with MessageCounter:77741103 to 0x4027AF6A66E6FFFE (1) at monotonic time: 0000000000008D20 msec I (37481) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:84177034 on exchange 55590r I (37891) ROUTE_HOOK: Received RIO I (37891) ROUTE_HOOK: prefix :: lifetime 180 I (40961) ROUTE_HOOK: Received RIO I (40961) ROUTE_HOOK: prefix :: lifetime 180 I (43931) ROUTE_HOOK: Received RIO I (43931) ROUTE_HOOK: prefix :: lifetime 180 I (46901) ROUTE_HOOK: Received RIO I (46901) ROUTE_HOOK: prefix :: lifetime 180 I (49871) ROUTE_HOOK: Received RIO I (49871) ROUTE_HOOK: prefix :: lifetime 180 I (52941) ROUTE_HOOK: Received RIO I (52941) ROUTE_HOOK: prefix :: lifetime 180 I (55941) ROUTE_HOOK: Received RIO I (55941) ROUTE_HOOK: prefix :: lifetime 180 I (58881) ROUTE_HOOK: Received RIO I (58881) ROUTE_HOOK: prefix :: lifetime 180 I