entry 0x40080694 I (29) boot: ESP-IDF v4.4 2nd stage bootloader I (29) boot: compile time 11:13:50 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=37948h (227656) map I (221) esp_image: segment 1: paddr=00057970 vaddr=3ffbdb60 size=08508h ( 34056) load I (235) esp_image: segment 2: paddr=0005fe80 vaddr=40080000 size=00198h ( 408) load I (235) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=fe1e4h (1040868) map I (617) esp_image: segment 4: paddr=0015e20c vaddr=40080198 size=1e480h (124032) load I (668) esp_image: segment 5: paddr=0017c694 vaddr=50000000 size=00010h ( 16) load I (684) boot: Loaded app from partition at offset 0x20000 I (728) boot: Set actual ota_seq=1 in otadata[0] I (728) boot: Disabling RNG early entropy source... I (739) cpu_start: Pro cpu up. I (739) cpu_start: Starting app cpu, entry point is 0x400814e0 0x400814e0: call_start_cpu1 at /Users/priyankahonnakasturi/tools/esp-idf/components/esp_system/port/cpu_start.c:156 I (0) cpu_start: App cpu up. I (755) cpu_start: Pro cpu start user code I (755) cpu_start: cpu freq: 160000000 I (756) cpu_start: Application information: I (760) cpu_start: Project name: chip-all-clusters-app I (766) cpu_start: App version: TE8/rc3-747-g1fb590017-dirty I (773) cpu_start: Compile time: Apr 5 2022 11:20:55 I (779) cpu_start: ELF file SHA256: f5205049376d4578... I (785) cpu_start: ESP-IDF: v4.4 I (790) heap_init: Initializing. RAM available for dynamic allocation: I (797) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (803) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (809) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (815) heap_init: At 3FFD6BE8 len 00009418 (37 KiB): DRAM I (821) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (828) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (834) heap_init: At 4009E618 len 000019E8 (6 KiB): IRAM I (842) spi_flash: detected chip: generic I (845) spi_flash: flash io: dio W (849) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. I (865) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (1010) all-clusters-app: ================================================== I (1010) all-clusters-app: chip-esp32-all-cluster-demo starting I (1010) all-clusters-app: ================================================== I (1200) wifi:wifi driver task: 3ffdeafc, prio:23, stack:6656, core=0 > I (1200) system_api: Base MAC address is not set I (1200) system_api: read default base MAC address from EFUSE I (1220) wifi:wifi firmware version: 7679c42 I (1220) wifi:wifi certification version: v7.0 I (1220) wifi:config NVS flash: enabled I (1220) wifi:config nano formating: disabled I (1230) wifi:Init data frame dynamic rx buffer num: 32 I (1230) wifi:Init management frame dynamic rx buffer num: 32 I (1240) wifi:Init management short buffer num: 32 I (1250) wifi:Init dynamic tx buffer num: 32 I (1250) wifi:Init static rx buffer size: 1600 I (1250) wifi:Init static rx buffer num: 10 I (1260) wifi:Init dynamic rx buffer num: 32 I (1260) wifi_init: rx ba win: 6 I (1260) wifi_init: tcpip mbox: 32 I (1270) wifi_init: udp mbox: 6 I (1270) wifi_init: tcp mbox: 6 I (1270) wifi_init: tcp tx win: 5744 I (1290) wifi_init: tcp rx win: 5744 I (1290) wifi_init: tcp mss: 1440 I (1290) wifi_init: WiFi IRAM OP enabled I (1300) wifi_init: WiFi RX IRAM OP enabled I (1330) chip[DL]: NVS set: chip-counters/reboot-count = 9 (0x9) I (1330) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (1330) all-clusters-app: ------------------------Starting App Task--------------------------- I (1330) BTDM_INIT: BT controller compile version [6a07b06] I (1350) app-task: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (1360) app-task: silicon revision 3, I (1360) app-task: 4MB external flash I (1350) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (1370) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (1380) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (1380) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (1400) chip[SVR]: Manual pairing code: [34970112332] I (1760) CHIP[DL]: BLE host-controller synced I (2270) all-clusters-app: Display initialized (height 240, width 320) I (2280) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2280) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2290) NimBLE: GAP procedure initiated: advertise; I (2300) NimBLE: disc_mode=2 I (2300) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2310) NimBLE: I (2290) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2320) chip[DL]: CHIPoBLE advertising started I (2330) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 E (2330) chip[DL]: Long dispatch time: 995 ms, for event type 2 I (2350) chip[DL]: Starting ESP WiFi layer I (2340) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2360) wifi:mode : sta (08:3a:f2:67:b5:0c) I (2370) wifi:enable tsf W (2370) wifi:Haven't to connect to a suitable AP now! I (2380) chip[DL]: Attempting to connect WiFi station interface I (2390) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1 I (2390) wifi:state: init -> auth (b0) I (2400) chip[DL]: WiFi station state change: NotConnected -> Connecting I (2400) chip[DL]: Done driving station state, nothing else to do... I (2410) chip[ZCL]: Using ZAP configuration... I (2420) wifi:state: auth -> assoc (0) I (2420) wifi:state: assoc -> run (10) I (2440) wifi:connected with HOME-2.4, aid = 8, channel 11, BW20, bssid = c0:94:35:d6:14:55 I (2440) wifi:security: WPA2-PSK, phy: bgn, rssi: -51 I (2460) wifi:pm start, type: 1 I (2470) chip[DMG]: AccessControlCluster: initializing I (2470) chip[ZCL]: Initiating Admin Commissioning cluster. I (2470) chip[ZCL]: Door Lock server initialized I (2490) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. I (2490) app-task: App Task started I (2490) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (2510) wifi:I (2510) app-devicecallbacks: Current free heap: 75444 AP's beacon interval = 102400 us, DTIM period = 1 I (2510) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2530) app-devicecallbacks: Unhandled cluster ID: 4 I (2540) app-devicecallbacks: Current free heap: 77140 E (2540) chip[ZCL]: DeviceInfoProvider is not registered E (2550) chip[ZCL]: Trying to write invalid Calendar Type E (2550) chip[ZCL]: Failed to write calendar type with error: 0x87 I (2560) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2580) app-devicecallbacks: Current free heap: 77140 I (2580) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2590) app-devicecallbacks: Unhandled cluster ID: 4 I (2600) app-devicecallbacks: Current free heap: 77140 I (2600) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2620) app-devicecallbacks: Unhandled cluster ID: 5 I (2630) app-devicecallbacks: Current free heap: 77140 I (2630) chip[ZCL]: On/Off set value: 1 0 I (2630) chip[ZCL]: On/off already set to new value I (2640) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2650) app-devicecallbacks: Current free heap: 77140 I (2670) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2680) app-devicecallbacks: Current free heap: 77140 I (2690) chip[ZCL]: Window Covering Cluster init I (2690) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (2700) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2710) app-devicecallbacks: Unhandled cluster ID: 768 I (2710) app-devicecallbacks: Current free heap: 77140 I (2730) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2730) app-devicecallbacks: Unhandled cluster ID: 768 I (2740) app-devicecallbacks: Current free heap: 77140 I (2740) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2750) app-devicecallbacks: Unhandled cluster ID: 768 I (2760) app-devicecallbacks: Current free heap: 77140 I (2770) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2780) app-devicecallbacks: Unhandled cluster ID: 1030 I (2790) app-devicecallbacks: Current free heap: 77140 I (2790) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2800) app-devicecallbacks: Unhandled cluster ID: 1030 I (2820) app-devicecallbacks: Current free heap: 77140 I (2820) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (2830) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (2830) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2840) app-devicecallbacks: Unhandled cluster ID: 1280 I (2850) app-devicecallbacks: Current free heap: 77140 I (2850) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2870) app-devicecallbacks: Unhandled cluster ID: 1280 I (2870) app-devicecallbacks: Current free heap: 77140 I (2880) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (2880) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (2890) app-devicecallbacks: Unhandled cluster ID: 4 I (2900) app-devicecallbacks: Current free heap: 77140 I (2910) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (2920) app-devicecallbacks: Unhandled cluster ID: 1030 I (2930) app-devicecallbacks: Current free heap: 77140 I (2930) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2940) app-devicecallbacks: Unhandled cluster ID: 1030 I (2950) app-devicecallbacks: Current free heap: 77140 I (2960) chip[IN]: Loading from storage for fabric index 1 I (2970) chip[DIS]: Fabric (1) loaded from storage I (2970) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000001, NodeId 0x000000000000000B, VendorId 0xFFF1 I (2980) chip[ZCL]: OpCreds: Call to fabricListChanged I (2990) chip[DIS]: Fabric (1) loaded from storage I (3000) chip[DMG]: AccessControl: initializing I (3000) chip[DMG]: Examples::AccessControlDelegate::Init I (3030) chip[DMG]: AccessControl: setting I (3050) chip[DL]: NVS set: chip-counters/GlobalMCTR = 9000 (0x2328) I (3070) chip[DL]: NVS set: chip-counters/global-eidc = 589824 (0x90000) I (3070) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement I (3080) chip[IN]: CASE Server enabling CASE session setups I (3080) chip[SVR]: Joining Multicast groups I (3090) chip[SVR]: Server Listening... I (3100) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3110) app-devicecallbacks: Unhandled cluster ID: 1026 I (3110) app-devicecallbacks: Current free heap: 69380 I (3120) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3130) app-devicecallbacks: Unhandled cluster ID: 257 I (3140) app-devicecallbacks: Current free heap: 69260 I (3150) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3150) app-devicecallbacks: Unhandled cluster ID: 1030 I (3160) app-devicecallbacks: Current free heap: 68308 I (3160) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3180) app-devicecallbacks: Unhandled cluster ID: 69 I (3190) app-devicecallbacks: Current free heap: 67784 I (3190) esp_netif_handlers: sta ip: 10.0.0.164, mask: 255.255.255.0, gw: 10.0.0.1 I (3190) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3210) app-devicecallbacks: Unhandled cluster ID: 1026 I (3210) app-devicecallbacks: Current free heap: 67072 I (3230) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3240) app-devicecallbacks: Unhandled cluster ID: 513 I (3240) app-devicecallbacks: Current free heap: 67604 I (3250) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (3250) app-devicecallbacks: Unhandled cluster ID: 513 I (3270) app-devicecallbacks: Current free heap: 67544 I (3270) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011' I (3280) app-devicecallbacks: Unhandled cluster ID: 513 I (3290) app-devicecallbacks: Current free heap: 67484 I (3290) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012' I (3310) app-devicecallbacks: Unhandled cluster ID: 513 I (3320) app-devicecallbacks: Current free heap: 67380 I (3320) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3330) app-devicecallbacks: Unhandled cluster ID: 1029 I (3330) app-devicecallbacks: Current free heap: 67252 I (3340) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3360) app-devicecallbacks: Unhandled cluster ID: 1024 I (3360) app-devicecallbacks: Current free heap: 67108 I (3370) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3370) app-devicecallbacks: Current free heap: 66976 I (3400) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3410) app-devicecallbacks: Current free heap: 66884 I (3420) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3430) app-devicecallbacks: Unhandled cluster ID: 768 I (3430) app-devicecallbacks: Current free heap: 66764 I (3440) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0001' I (3460) app-devicecallbacks: Unhandled cluster ID: 768 I (3460) app-devicecallbacks: Current free heap: 66684 E (3470) chip[DL]: Long dispatch time: 1055 ms, for event type 2 I (3470) app-devicecallbacks: Current free heap: 66684 I (3480) chip[DL]: WIFI_EVENT_STA_START I (3480) chip[DL]: Done driving station state, nothing else to do... I (3480) app-devicecallbacks: Current free heap: 66684 I (3500) chip[DL]: WIFI_EVENT_STA_CONNECTED I (3500) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (3510) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (3510) chip[DL]: WiFi station interface connected I (3520) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (3520) chip[DL]: Done driving station state, nothing else to do... I (3530) app-devicecallbacks: Current free heap: 66684 I (3540) app-devicecallbacks: Current free heap: 66684 I (3550) NimBLE: GAP procedure initiated: stop advertising. I (3550) chip[DL]: CHIPoBLE advertising stopped I (3560) chip[SVR]: Cannot load binding table: a0 I (3560) chip[DL]: IP_EVENT_STA_GOT_IP I (3570) chip[DL]: IPv4 address changed on WiFi station interface: 10.0.0.164/255.255.255.0 gateway 10.0.0.1 I (3580) app-devicecallbacks: Current free heap: 66684 I (3580) chip[DL]: Updating advertising data I (3590) app-devicecallbacks: Current free heap: 66684 I (3590) app-devicecallbacks: Server ready at: 10.0.0.164:5540 I (3600) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (3610) chip[DIS]: Updating services using commissioning mode 0 I (3620) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000B I (3630) app-devicecallbacks: Current free heap: 66168 I (3630) app-devicecallbacks: Current free heap: 66168 I (3630) chip[DIS]: Updating services using commissioning mode 0 I (3640) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000B I (3660) app-devicecallbacks: Current free heap: 66172 I (5190) chip[DL]: IP_EVENT_GOT_IP6 I (5190) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:0a3a:f2ff:fe67:b50c I (5200) app-devicecallbacks: Current free heap: 65860 I (5200) chip[DIS]: Updating services using commissioning mode 0 I (5220) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000B I (5230) app-devicecallbacks: Current free heap: 65512 I (5790) ROUTE_HOOK: Received RIO I (5790) ROUTE_HOOK: prefix :: lifetime 180 I (7190) chip[DL]: IP_EVENT_GOT_IP6 I (7190) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2601:0647:4501:0560:0a3a:f2ff:fe67:b50c I (7200) chip[DL]: IPv6 Internet connectivity ESTABLISHED I (7200) app-devicecallbacks: Current free heap: 65600 I (7210) app-devicecallbacks: IPv6 Server ready... I (7210) chip[DIS]: Updating services using commissioning mode 0 I (7220) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000B I (7240) app-devicecallbacks: Current free heap: 65576 I (7240) chip[DIS]: Updating services using commissioning mode 0 I (7240) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000B I (7270) ROUTE_HOOK: Hook already installed on netif, skip... I (7270) app-devicecallbacks: Current free heap: 65580 I (8760) ROUTE_HOOK: Received RIO I (8760) ROUTE_HOOK: prefix :: lifetime 180 I (14800) ROUTE_HOOK: Received RIO I (14800) ROUTE_HOOK: prefix :: lifetime 180 I (17770) ROUTE_HOOK: Received RIO I (17770) ROUTE_HOOK: prefix :: lifetime 180 I (20840) ROUTE_HOOK: Received RIO I (20840) ROUTE_HOOK: prefix :: lifetime 180 I (20840) ROUTE_HOOK: Received RIO I (20840) ROUTE_HOOK: prefix :: lifetime 180 I (23910) ROUTE_HOOK: Received RIO I (23910) ROUTE_HOOK: prefix :: lifetime 180 I (26880) ROUTE_HOOK: Received RIO I (26880) ROUTE_HOOK: prefix :: lifetime 180 I (29850) ROUTE_HOOK: Received RIO I (29850) ROUTE_HOOK: prefix :: lifetime 180 I (32920) ROUTE_HOOK: Received RIO I (32920) ROUTE_HOOK: prefix :: lifetime 180 I (33600) all-clusters-app: Display going to sleep... I (35890) ROUTE_HOOK: Received RIO I (35890) ROUTE_HOOK: prefix :: lifetime 180 I (38860) ROUTE_HOOK: Received RIO I (38860) ROUTE_HOOK: prefix :: lifetime 180 I (41930) ROUTE_HOOK: Received RIO I (41930) ROUTE_HOOK: prefix :: lifetime 180 I (44900) ROUTE_HOOK: Received RIO I (44900) ROUTE_HOOK: prefix :: lifetime 180 I (47870) ROUTE_HOOK: Received RIO I (47870) ROUTE_HOOK: prefix :: lifetime 180 I (50950) ROUTE_HOOK: Received RIO I (50950) ROUTE_HOOK: prefix :: lifetime 180 I (53910) ROUTE_HOOK: Received RIO I (53920) ROUTE_HOOK: prefix :: lifetime 180 I (56890) ROUTE_HOOK: Received RIO I (56890) ROUTE_HOOK: prefix :: lifetime 180 I (59850) ROUTE_HOOK: Received RIO I (59850) ROUTE_HOOK: prefix :: lifetime 180 I (62930) ROUTE_HOOK: Received RIO I (62930) ROUTE_HOOK: prefix :: lifetime 180 I (65900) ROUTE_HOOK: Received RIO I (65900) ROUTE_HOOK: prefix :: lifetime 180 I (68860) ROUTE_HOOK: Received RIO I (68860) ROUTE_HOOK: prefix :: lifetime 180 I (71940) ROUTE_HOOK: Received RIO I (71940) ROUTE_HOOK: prefix :: lifetime 180 I (74910) ROUTE_HOOK: Received RIO I (74910) ROUTE_HOOK: prefix :: lifetime 180 I (77880) ROUTE_HOOK: Received RIO I (77880) ROUTE_HOOK: prefix :: lifetime 180 I (80950) ROUTE_HOOK: Received RIO I (80950) ROUTE_HOOK: prefix :: lifetime 180 I (83920) ROUTE_HOOK: Received RIO I (83920) ROUTE_HOOK: prefix :: lifetime 180 I (86890) ROUTE_HOOK: Received RIO I (86890) ROUTE_HOOK: prefix :: lifetime 180 I (89960) ROUTE_HOOK: Received RIO I (89960) ROUTE_HOOK: prefix :: lifetime 180 I (92930) ROUTE_HOOK: Received RIO I (92930) ROUTE_HOOK: prefix :: lifetime 180 I (95900) ROUTE_HOOK: Received RIO I (95900) ROUTE_HOOK: prefix :: lifetime 180 I (98970) ROUTE_HOOK: Received RIO I (98970) ROUTE_HOOK: prefix :: lifetime 180 I (99380) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (101940) ROUTE_HOOK: Received RIO I (101940) ROUTE_HOOK: prefix :: lifetime 180 I (104910) ROUTE_HOOK: Received RIO I (104910) ROUTE_HOOK: prefix :: lifetime 180 E (107420) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (107780) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (107980) ROUTE_HOOK: Received RIO I (107980) ROUTE_HOOK: prefix :: lifetime 180 E (108190) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (109420) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (110950) ROUTE_HOOK: Received RIO I (110950) ROUTE_HOOK: prefix :: lifetime 180 I (113920) ROUTE_HOOK: Received RIO I (113920) ROUTE_HOOK: prefix :: lifetime 180 E (114640) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (114950) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (115360) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (116990) ROUTE_HOOK: Received RIO I (116990) ROUTE_HOOK: prefix :: lifetime 180 E (118430) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (119960) ROUTE_HOOK: Received RIO I (119960) ROUTE_HOOK: prefix :: lifetime 180 I (122930) ROUTE_HOOK: Received RIO I (122930) ROUTE_HOOK: prefix :: lifetime 180 E (123550) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (124470) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (124780) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (125090) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (126010) ROUTE_HOOK: Received RIO I (126010) ROUTE_HOOK: prefix :: lifetime 180 E (127440) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (128970) ROUTE_HOOK: Received RIO I (128970) ROUTE_HOOK: prefix :: lifetime 180 E (129320) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (129380) all-clusters-app: Display going to sleep... E (129690) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! E (130000) chip[IN]: Data received on an unknown session (LSID=53129). Dropping it! I (131940) ROUTE_HOOK: Received RIO I (131950) ROUTE_HOOK: prefix :: lifetime 180 I (134910) ROUTE_HOOK: Received RIO I (134910) ROUTE_HOOK: prefix :: lifetime 180 I (136650) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (137460) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (137990) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (138000) ROUTE_HOOK: Received RIO I (138000) ROUTE_HOOK: prefix :: lifetime 180 I (138760) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (139220) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (139220) DeviceWithDisplay: Opening Setup list I (139740) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (140120) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (140120) DeviceWithDisplay: Opening options 1: Reset to factory I (140180) chip[DIS]: Fabric (1) deleted. Calling OnFabricDeletedFromStorage I (140240) chip[DMG]: AccessControl: removing fabric 1 I (140260) chip[ZCL]: OpCreds: Fabric 0x1 was deleted from fabric storage. I (140260) chip[ZCL]: OpCreds: Call to fabricListChanged E (140290) chip[DL]: Long dispatch time: 163 ms, for event type 2 I (140290) chip[DL]: Performing factory reset I (140330) wifi:state: run -> init (0) I (140330) wifi:pm stop, total sleep time: 124157336 us / 137874835 us I (140330) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1 W (140350) wifi:hmac tx: ifx0 stop, discard I (140380) wifi:flush txq I (140380) wifi:stop sw txq I (140380) wifi:lmac stop hw txq I (140520) 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 11:13:50 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=37948h (227656) map I (216) esp_image: segment 1: paddr=00057970 vaddr=3ffbdb60 size=08508h ( 34056) load I (230) esp_image: segment 2: paddr=0005fe80 vaddr=40080000 size=00198h ( 408) load I (230) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=fe1e4h (1040868) map I (612) esp_image: segment 4: paddr=0015e20c vaddr=40080198 size=1e480h (124032) load I (663) esp_image: segment 5: paddr=0017c694 vaddr=50000000 size=00010h ( 16) load I (679) boot: Loaded app from partition at offset 0x20000 I (679) boot: Disabling RNG early entropy source... I (691) cpu_start: Pro cpu up. I (691) cpu_start: Starting app cpu, entry point is 0x400814e0 0x400814e0: call_start_cpu1 at /Users/priyankahonnakasturi/tools/esp-idf/components/esp_system/port/cpu_start.c:156 I (677) cpu_start: App cpu up. I (707) cpu_start: Pro cpu start user code I (707) cpu_start: cpu freq: 160000000 I (707) cpu_start: Application information: I (712) cpu_start: Project name: chip-all-clusters-app I (718) cpu_start: App version: TE8/rc3-747-g1fb590017-dirty I (725) cpu_start: Compile time: Apr 5 2022 11:20:55 I (731) cpu_start: ELF file SHA256: f5205049376d4578... I (737) cpu_start: ESP-IDF: v4.4 I (742) heap_init: Initializing. RAM available for dynamic allocation: I (749) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (755) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (761) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (767) heap_init: At 3FFD6BE8 len 00009418 (37 KiB): DRAM I (773) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (780) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (786) heap_init: At 4009E618 len 000019E8 (6 KiB): IRAM I (793) spi_flash: detected chip: generic I (797) spi_flash: flash io: dio W (801) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. I (817) 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 (921) all-clusters-app: ================================================== I (1101) wifi:wifi driver task: 3ffde9f8, prio:23, stack:6656, core=0 I (1101) system_api: Base MAC address is not set I (1101) system_api: read default base MAC address from EFUSE > I (1131) wifi:wifi firmware version: 7679c42 I (1131) wifi:wifi certification version: v7.0 I (1131) wifi:config NVS flash: enabled I (1131) 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 (1161) wifi:Init dynamic tx buffer num: 32 I (1161) wifi:Init static rx buffer size: 1600 I (1161) wifi:Init static rx buffer num: 10 I (1171) wifi:Init dynamic rx buffer num: 32 I (1171) wifi_init: rx ba win: 6 I (1171) wifi_init: tcpip mbox: 32 I (1181) wifi_init: udp mbox: 6 I (1181) wifi_init: tcp mbox: 6 I (1181) wifi_init: tcp tx win: 5744 I (1191) wifi_init: tcp rx win: 5744 I (1201) wifi_init: tcp mss: 1440 I (1201) wifi_init: WiFi IRAM OP enabled I (1211) wifi_init: WiFi RX IRAM OP enabled I (1231) chip[DL]: NVS set: chip-counters/reboot-count = 10 (0xA) 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 (1251) 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 (1271) app-task: silicon revision 3, I (1281) app-task: 4MB external flash I (1281) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (1291) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (1271) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (1291) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (1311) chip[SVR]: Manual pairing code: [34970112332] I (1701) CHIP[DL]: BLE host-controller synced I (2221) 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 (2241) NimBLE: GAP procedure initiated: advertise; I (2251) NimBLE: disc_mode=2 I (2251) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2241) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2271) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2271) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2261) NimBLE: I (2341) chip[DL]: CHIPoBLE advertising started E (2341) chip[DL]: Long dispatch time: 1093 ms, for event type 2 I (2361) chip[DL]: Starting ESP WiFi layer I (2361) wifi:mode : sta (08:3a:f2:67:b5:0c) I (2361) wifi:enable tsf W (2361) wifi:Haven't to connect to a suitable AP now! I (2361) chip[DL]: Done driving station state, nothing else to do... W (2381) wifi:Haven't to connect to a suitable AP now! I (2381) chip[DL]: Done driving station state, nothing else to do... I (2381) chip[ZCL]: Using ZAP configuration... I (2401) app-task: App Task started I (2411) chip[DMG]: AccessControlCluster: initializing I (2411) chip[ZCL]: Initiating Admin Commissioning cluster. I (2421) chip[ZCL]: Door Lock server initialized I (2431) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. I (2441) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (2441) app-devicecallbacks: Current free heap: 78088 I (2451) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2471) app-devicecallbacks: Unhandled cluster ID: 4 I (2471) app-devicecallbacks: Current free heap: 78088 E (2481) chip[ZCL]: DeviceInfoProvider is not registered E (2481) chip[ZCL]: Trying to write invalid Calendar Type E (2491) chip[ZCL]: Failed to write calendar type with error: 0x87 I (2491) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2511) app-devicecallbacks: Current free heap: 78088 I (2521) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2521) app-devicecallbacks: Unhandled cluster ID: 4 I (2531) app-devicecallbacks: Current free heap: 78088 I (2531) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2551) app-devicecallbacks: Unhandled cluster ID: 5 I (2561) app-devicecallbacks: Current free heap: 78088 I (2561) chip[ZCL]: On/Off set value: 1 0 I (2571) chip[ZCL]: On/off already set to new value I (2571) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2591) app-devicecallbacks: Current free heap: 78088 I (2591) chip[ZCL]: Window Covering Cluster init I (2591) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (2601) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2621) app-devicecallbacks: Unhandled cluster ID: 768 I (2621) app-devicecallbacks: Current free heap: 78088 I (2631) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2631) app-devicecallbacks: Unhandled cluster ID: 768 I (2641) app-devicecallbacks: Current free heap: 78088 I (2641) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2661) app-devicecallbacks: Unhandled cluster ID: 768 I (2671) app-devicecallbacks: Current free heap: 78088 I (2671) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2681) app-devicecallbacks: Unhandled cluster ID: 1030 I (2691) app-devicecallbacks: Current free heap: 78088 I (2691) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2711) app-devicecallbacks: Unhandled cluster ID: 1030 I (2711) app-devicecallbacks: Current free heap: 78088 I (2721) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (2731) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (2731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2751) app-devicecallbacks: Unhandled cluster ID: 1280 I (2751) app-devicecallbacks: Current free heap: 78088 I (2761) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2771) app-devicecallbacks: Unhandled cluster ID: 1280 I (2771) app-devicecallbacks: Current free heap: 78088 I (2781) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (2791) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (2801) app-devicecallbacks: Unhandled cluster ID: 4 I (2811) app-devicecallbacks: Current free heap: 78088 I (2811) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (2821) app-devicecallbacks: Unhandled cluster ID: 1030 I (2821) app-devicecallbacks: Current free heap: 78088 I (2841) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2851) app-devicecallbacks: Unhandled cluster ID: 1030 I (2851) app-devicecallbacks: Current free heap: 78088 I (2861) chip[DMG]: AccessControl: initializing I (2861) chip[DMG]: Examples::AccessControlDelegate::Init I (2881) chip[DMG]: AccessControl: unable to load stored ACL entries; using empty list instead I (2881) chip[DMG]: AccessControl: setting I (2901) chip[DL]: NVS set: chip-counters/GlobalMCTR = 10000 (0x2710) I (2911) chip[DL]: NVS set: chip-counters/global-eidc = 655360 (0xA0000) 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]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (2951) chip[IN]: CASE Server enabling CASE session setups I (2951) chip[SVR]: Joining Multicast groups I (2951) chip[SVR]: Server Listening... I (2961) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2971) app-devicecallbacks: Unhandled cluster ID: 1026 I (2971) app-devicecallbacks: Current free heap: 71160 I (2981) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2991) app-devicecallbacks: Unhandled cluster ID: 257 I (3001) app-devicecallbacks: Current free heap: 71032 I (3011) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3021) app-devicecallbacks: Unhandled cluster ID: 1030 I (3021) app-devicecallbacks: Current free heap: 70080 I (3021) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3041) app-devicecallbacks: Unhandled cluster ID: 69 I (3051) app-devicecallbacks: Current free heap: 69960 I (3051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3061) app-devicecallbacks: Unhandled cluster ID: 1026 I (3071) app-devicecallbacks: Current free heap: 69600 I (3071) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3091) app-devicecallbacks: Unhandled cluster ID: 513 I (3091) app-devicecallbacks: Current free heap: 69600 I (3101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (3111) app-devicecallbacks: Unhandled cluster ID: 513 I (3111) app-devicecallbacks: Current free heap: 69552 I (3131) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011' I (3141) app-devicecallbacks: Unhandled cluster ID: 513 I (3141) app-devicecallbacks: Current free heap: 69480 I (3151) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012' I (3151) app-devicecallbacks: Unhandled cluster ID: 513 I (3171) app-devicecallbacks: Current free heap: 69356 I (3171) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3181) app-devicecallbacks: Unhandled cluster ID: 1029 I (3191) app-devicecallbacks: Current free heap: 69216 I (3191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3211) app-devicecallbacks: Unhandled cluster ID: 1024 I (3211) app-devicecallbacks: Current free heap: 69072 I (3221) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3241) app-devicecallbacks: Current free heap: 68824 I (3251) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3251) app-devicecallbacks: Current free heap: 68720 I (3261) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3271) app-devicecallbacks: Unhandled cluster ID: 768 I (3281) app-devicecallbacks: Current free heap: 68600 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: 68532 E (3311) chip[DL]: Long dispatch time: 933 ms, for event type 2 I (3311) app-devicecallbacks: Current free heap: 68532 I (3321) chip[DL]: WIFI_EVENT_STA_START W (3331) wifi:Haven't to connect to a suitable AP now! I (3331) chip[DL]: Done driving station state, nothing else to do... I (3341) app-devicecallbacks: Current free heap: 68532 I (3341) chip[DIS]: Updating services using commissioning mode 1 I (3351) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (3371) app-devicecallbacks: Current free heap: 68524 I (3371) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (3371) chip[DL]: Device already advertising, stop active advertisement and restart I (3381) NimBLE: GAP procedure initiated: stop advertising. I (3391) NimBLE: GAP procedure initiated: advertise; I (3401) NimBLE: disc_mode=2 I (3401) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (3411) NimBLE: I (3421) chip[SVR]: Cannot load binding table: a0 I (7791) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8101) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8471) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8471) DeviceWithDisplay: Opening QR code screen I (8481) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (8481) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (8491) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (8501) chip[SVR]: Manual pairing code: [34970112332] I (13881) chip[DL]: BLE GAP connection established (con 0) I (13881) chip[DL]: CHIPoBLE advertising stopped I (13881) app-devicecallbacks: Current free heap: 68336 I (14501) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (14501) chip[BLE]: local and remote recv window sizes = 5 I (14511) chip[BLE]: selected BTP version 4 I (14521) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (14681) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1 I (14681) chip[DL]: CHIPoBLE subscribe received I (14681) NimBLE: GATT procedure initiated: notify; I (14701) NimBLE: att_handle=14 I (14701) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (14711) app-devicecallbacks: CHIPoBLE connection established I (14711) app-devicecallbacks: Current free heap: 68336 I (14741) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (14751) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:4058969083 on exchange 21762r I (14761) chip[IN]: Prepared unauthenticated message 0x3ffe7024 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 21762r with MessageCounter:351024947. I (14781) chip[IN]: Sending unauthenticated msg 0x3ffe7024 with MessageCounter:351024947 to 0x0000000000000000 at monotonic time: 0000000000003673 msec I (14791) NimBLE: GATT procedure initiated: notify; I (14791) NimBLE: att_handle=14 I (14801) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (14861) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (14871) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:4058969084 on exchange 21762r I (17541) chip[IN]: Prepared unauthenticated message 0x3ffe6fa4 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 21762r with MessageCounter:351024948. I (17561) chip[IN]: Sending unauthenticated msg 0x3ffe6fa4 with MessageCounter:351024948 to 0x0000000000000000 at monotonic time: 0000000000004150 msec I (17571) NimBLE: GATT procedure initiated: notify; I (17571) NimBLE: att_handle=14 I (17591) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (17591) chip[DL]: Long dispatch time: 2725 ms, for event type 7 I (17651) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (17661) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:4058969085 on exchange 21762r I (17671) chip[IN]: Prepared unauthenticated message 0x3ffe7024 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 21762r with MessageCounter:351024949. I (17681) chip[IN]: Sending unauthenticated msg 0x3ffe7024 with MessageCounter:351024949 to 0x0000000000000000 at monotonic time: 00000000000041CE msec I (17701) NimBLE: GATT procedure initiated: notify; I (17701) NimBLE: att_handle=14 I (17711) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (17721) chip[SVR]: Commissioning completed session establishment step I (17731) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (17731) chip[DIS]: Updating services using commissioning mode 0 I (17741) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (17751) chip[DL]: NVS set: chip-config/fail-safe-armed = true I (17751) chip[SVR]: Device completed Rendezvous process E (17761) chip[DL]: Long dispatch time: 110 ms, for event type 7 I (19481) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19491) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:3383907 on exchange 21763r I (19511) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v I (19511) chip[DMG]: AccessControl: implicit admin (PASE) I (19521) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v I (19521) chip[DMG]: AccessControl: implicit admin (PASE) I (19541) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v I (19541) chip[DMG]: AccessControl: implicit admin (PASE) I (19551) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v I (19561) chip[DMG]: AccessControl: implicit admin (PASE) I (19561) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v I (19581) chip[DMG]: AccessControl: implicit admin (PASE) I (19581) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v I (19591) chip[DMG]: AccessControl: implicit admin (PASE) I (19591) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v I (19601) chip[DMG]: AccessControl: implicit admin (PASE) I (19611) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v I (19621) chip[DMG]: AccessControl: implicit admin (PASE) I (19631) chip[IN]: Prepared secure message 0x3ffe72a4 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 21763r with MessageCounter:16436067. I (19651) chip[IN]: Sending encrypted msg 0x3ffe72a4 with MessageCounter:16436067 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004978 msec I (19661) NimBLE: GATT procedure initiated: notify; I (19661) NimBLE: att_handle=14 I (19671) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (19681) chip[DL]: Long dispatch time: 175 ms, for event type 3 I (19681) NimBLE: GATT procedure initiated: notify; I (19691) NimBLE: att_handle=14 I (19691) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19751) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19761) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383908 on exchange 21764r I (19771) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a I (19771) chip[DMG]: AccessControl: implicit admin (PASE) I (19791) chip[DL]: NVS set: chip-config/fail-safe-armed = true I (19791) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21764r with MessageCounter:16436068. I (19811) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436068 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004A18 msec I (19821) NimBLE: GATT procedure initiated: notify; I (19821) NimBLE: att_handle=14 I (19831) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19871) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19881) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383909 on exchange 21765r I (19891) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a I (19891) chip[DMG]: AccessControl: implicit admin (PASE) I (19911) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (19911) chip[DL]: NVS set: chip-config/country-code = "XX" I (19911) chip[DL]: NVS set: chip-config/breadcrumb = 4 (0x4) I (19931) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21765r with MessageCounter:16436069. I (19941) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436069 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004AA1 msec I (19961) NimBLE: GATT procedure initiated: notify; I (19961) NimBLE: att_handle=14 I (19961) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20021) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (20031) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383910 on exchange 21766r I (20041) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (20041) chip[DMG]: AccessControl: implicit admin (PASE) I (20061) chip[ZCL]: OpCreds: Certificate Chain request received for PAI I (20061) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21766r with MessageCounter:16436070. I (20071) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436070 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004B24 msec I (20091) NimBLE: GATT procedure initiated: notify; I (20091) NimBLE: att_handle=14 I (20101) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20111) NimBLE: GATT procedure initiated: notify; I (20121) NimBLE: att_handle=14 I (20121) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20121) NimBLE: GATT procedure initiated: notify; I (20131) NimBLE: att_handle=14 I (20141) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20201) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (20211) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383911 on exchange 21767r I (20221) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (20221) chip[DMG]: AccessControl: implicit admin (PASE) I (20241) chip[ZCL]: OpCreds: Certificate Chain request received for DAC I (20241) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21767r with MessageCounter:16436071. I (20251) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436071 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004BD7 msec I (20271) NimBLE: GATT procedure initiated: notify; I (20281) NimBLE: att_handle=14 I (20281) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20281) NimBLE: GATT procedure initiated: notify; I (20301) NimBLE: att_handle=14 I (20301) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20301) NimBLE: GATT procedure initiated: notify; I (20311) NimBLE: att_handle=14 I (20321) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (20381) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (20391) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383912 on exchange 21768r I (20401) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (20401) chip[DMG]: AccessControl: implicit admin (PASE) I (20421) chip[ZCL]: OpCreds: received an AttestationRequest I (20971) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21768r with MessageCounter:16436072. I (20981) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436072 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000004EB1 msec I (21001) NimBLE: GATT procedure initiated: notify; I (21001) NimBLE: att_handle=14 I (21001) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (21021) chip[DL]: Long dispatch time: 631 ms, for event type 7 I (21021) NimBLE: GATT procedure initiated: notify; I (21031) NimBLE: att_handle=14 I (21031) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21041) NimBLE: GATT procedure initiated: notify; I (21051) NimBLE: att_handle=14 I (21051) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21191) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (21201) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383913 on exchange 21769r I (21211) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (21211) chip[DMG]: AccessControl: implicit admin (PASE) I (21231) chip[ZCL]: OpCreds: commissioner has requested a CSR I (22841) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0 I (23391) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21769r with MessageCounter:16436073. I (23401) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436073 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000005823 msec I (23411) NimBLE: GATT procedure initiated: notify; I (23421) NimBLE: att_handle=14 I (23421) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (23431) chip[DL]: Long dispatch time: 2238 ms, for event type 7 I (23431) NimBLE: GATT procedure initiated: notify; I (23451) NimBLE: att_handle=14 I (23451) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (23531) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (23591) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (23601) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383914 on exchange 21770r I (23611) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (23611) chip[DMG]: AccessControl: implicit admin (PASE) I (23631) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert I (23631) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 21770r with MessageCounter:16436074. I (23641) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436074 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000005915 msec I (23661) NimBLE: GATT procedure initiated: notify; I (23671) NimBLE: att_handle=14 I (23671) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (23711) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (23771) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (23781) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383915 on exchange 21771r I (23791) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a I (23791) chip[DMG]: AccessControl: implicit admin (PASE) I (23811) chip[ZCL]: OpCreds: commissioner has added a NOC I (23811) chip[DIS]: Verifying the received credentials I (24891) chip[DIS]: Added new fabric at index: 1, Initialized: 1 I (24901) chip[DIS]: Assigned compressed fabric ID: 0x2AA47CB2A9EB1C63, node ID: 0x000000000000000C I (24941) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I (24941) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000001, NodeId 000000000000000C, VendorId 0xFFF1 I (24951) chip[ZCL]: OpCreds: Call to fabricListChanged I (24991) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I (24991) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000001, NodeId 000000000000000C, VendorId 0xFFF1 I (25001) chip[ZCL]: OpCreds: Call to fabricListChanged I (25031) chip[DMG]: AccessControl: validating f=1 p=a a=c s=1 t=0 I (25031) chip[DMG]: validating subject 0x804C3FB50B91215E I (25131) chip[ZCL]: OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x804C3FB50B91215E I (25151) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (25171) chip[ZCL]: OpCreds: successfully added a NOC I (25171) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 21771r with MessageCounter:16436075. I (25181) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436075 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000005F19 msec I (25201) NimBLE: GATT procedure initiated: notify; I (25201) NimBLE: att_handle=14 I (25211) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (25211) chip[DL]: Long dispatch time: 1439 ms, for event type 7 I (25271) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (25281) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383916 on exchange 21772r I (25291) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o I (25291) chip[DMG]: AccessControl: implicit admin (PASE) I (25311) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 21772r with MessageCounter:16436076. I (25321) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:16436076 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000005FA4 msec I (25341) NimBLE: GATT procedure initiated: notify; I (25341) NimBLE: att_handle=14 I (25341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (25391) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (25401) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3383917 on exchange 21773r I (25411) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o I (25411) chip[DMG]: AccessControl: implicit admin (PASE) I (25431) chip[NP]: ESP NetworkCommissioningDelegate: SSID: HOME-2.4 I (25431) chip[DL]: WiFi station mode change: Enabled -> Disabled I (25481) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (25481) wifi:mode : sta (08:3a:f2:67:b5:0c) + softAP (5c:69:61:15:25:48) I (25481) wifi:Total power save buffer number: 16 I (25491) wifi:Init max length of beacon: 752/752 I (25501) wifi:Init max length of beacon: 752/752 I (25511) chip[DL]: WiFi station mode change: Disabled -> Enabled E (25511) chip[DL]: Long dispatch time: 115 ms, for event type 7 W (25511) wifi:Haven't to connect to a suitable AP now! I (25521) chip[DL]: Attempting to connect WiFi station interface I (25531) chip[DL]: WiFi station state change: NotConnected -> Connecting I (25531) chip[DL]: Done driving station state, nothing else to do... W (25551) wifi:Haven't to connect to a suitable AP now! I (25551) chip[DL]: Attempting to connect WiFi station interface E (25551) wifi:sta is connecting, return error E (25561) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (25561) wifi:Haven't to connect to a suitable AP now! I (25571) chip[DL]: Attempting to connect WiFi station interface E (25571) wifi:sta is connecting, return error E (25581) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN I (25591) chip[DL]: WIFI_EVENT_AP_START I (25591) chip[DL]: WiFi AP state change: NotActive -> Active I (25601) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (25601) wifi:mode : sta (08:3a:f2:67:b5:0c) I (25621) chip[DL]: WiFi AP state change: Active -> Deactivating I (25621) app-devicecallbacks: Current free heap: 65052 W (25621) wifi:Haven't to connect to a suitable AP now! E (25631) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F I (25641) chip[DL]: WIFI_EVENT_AP_STOP I (25641) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (25651) app-devicecallbacks: Current free heap: 65052 I (27891) NimBLE: GATT procedure initiated: notify; I (27901) NimBLE: att_handle=14 I (27901) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (27951) wifi:new:<11,0>, old:<1,1>, ap:<255,255>, sta:<11,0>, prof:1 I (28721) wifi:state: init -> auth (b0) I (28731) wifi:state: auth -> assoc (0) I (28741) wifi:state: assoc -> run (10) I (28761) wifi:connected with HOME-2.4, aid = 8, channel 11, BW20, bssid = c0:94:35:d6:14:55 I (28761) wifi:security: WPA2-PSK, phy: bgn, rssi: -50 I (28771) wifi:pm start, type: 1 I (28781) chip[DL]: WIFI_EVENT_STA_CONNECTED I (28781) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (28781) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (28801) chip[DL]: WiFi station interface connected I (28801) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C E (28811) chip[SVR]: Operational advertising enabled I (28811) app-devicecallbacks: Current free heap: 64072 I (28831) chip[IN]: Prepared secure message 0x3ffe7294 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 21773r with MessageCounter:16436077. I (28841) chip[IN]: Sending encrypted msg 0x3ffe7294 with MessageCounter:16436077 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000006D62 msec I (28851) NimBLE: GATT procedure initiated: notify; I (28851) NimBLE: att_handle=14 I (28841) wifi:AP's beacon interval = 102400 us, DTIM period = 1 I (28861) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (28881) chip[DL]: Done driving station state, nothing else to do... I (28881) app-devicecallbacks: Current free heap: 62728 E (28881) chip[DL]: Long dispatch time: 107 ms, for event type 49152 I (28901) chip[DL]: Updating advertising data I (28901) app-devicecallbacks: Current free heap: 64248 I (29591) esp_netif_handlers: sta ip: 10.0.0.164, mask: 255.255.255.0, gw: 10.0.0.1 I (29591) chip[DL]: IP_EVENT_STA_GOT_IP I (29591) chip[DL]: IPv4 address changed on WiFi station interface: 10.0.0.164/255.255.255.0 gateway 10.0.0.1 I (29611) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (29611) app-devicecallbacks: Current free heap: 63860 I (29621) app-devicecallbacks: Server ready at: 10.0.0.164:5540 I (29621) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (29641) chip[DIS]: Updating services using commissioning mode 0 I (29651) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (29661) app-devicecallbacks: Current free heap: 63736 I (29661) chip[DIS]: Updating services using commissioning mode 0 I (29661) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (29691) app-devicecallbacks: Current free heap: 63848 I (30091) chip[DL]: IP_EVENT_GOT_IP6 I (30091) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:0a3a:f2ff:fe67:b50c I (30101) app-devicecallbacks: Current free heap: 63548 I (30101) chip[DIS]: Updating services using commissioning mode 0 I (30111) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (30131) app-devicecallbacks: Current free heap: 63264 I (30431) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (32091) chip[DL]: IP_EVENT_GOT_IP6 I (32091) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2601:0647:4501:0560:0a3a:f2ff:fe67:b50c I (32101) chip[DL]: IPv6 Internet connectivity ESTABLISHED I (32101) app-devicecallbacks: Current free heap: 63208 I (32121) app-devicecallbacks: IPv6 Server ready... I (32121) chip[DIS]: Updating services using commissioning mode 0 I (32121) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (32141) app-devicecallbacks: Current free heap: 63464 I (32141) chip[DIS]: Updating services using commissioning mode 0 I (32151) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (32161) ROUTE_HOOK: Hook already installed on netif, skip... I (32161) app-devicecallbacks: Current free heap: 63344 I (32941) NimBLE: GATT procedure initiated: notify; I (32941) NimBLE: att_handle=14 I (32941) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (33461) ROUTE_HOOK: Received RIO I (33461) ROUTE_HOOK: prefix :: lifetime 180 I (33481) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:4058969086 on exchange 21774r I (33491) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffca500 I (33501) chip[DIS]: CASE handshake initiated, closing all BLE Connections I (33501) chip[BLE]: Releasing end point's BLE connection back to application. I (33521) chip[IN]: CASE Server disabling CASE session setups I (33521) chip[SC]: Received Sigma1 msg I (33541) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x000000000000000C I (35311) chip[IN]: Prepared unauthenticated message 0x3ffca41c to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 21774r with MessageCounter:351024950. I (35331) chip[IN]: Sending unauthenticated msg 0x3ffca41c with MessageCounter:351024950 to 0x0000000000000000 at monotonic time: 00000000000086B6 msec I (35341) chip[SC]: Sent Sigma2 msg E (35351) chip[DL]: Long dispatch time: 1862 ms, for event type 3 I (35471) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (35471) chip[BLE]: Releasing end point's BLE connection back to application. E (35481) chip[BLE]: HandleChipConnectionReceived failed, err = d E (35491) chip[BLE]: failed handle new chip BLE connection, status = d I (36221) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:4058969087 on exchange 21774r I (36221) chip[SC]: Received Sigma3 msg I (36521) ROUTE_HOOK: Received RIO I (36521) ROUTE_HOOK: prefix :: lifetime 180 I (38671) chip[IN]: Prepared unauthenticated message 0x3ffca41c to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 21774r with MessageCounter:351024951. I (38691) chip[IN]: Sending unauthenticated msg 0x3ffca41c with MessageCounter:351024951 to 0x0000000000000000 at monotonic time: 00000000000093D9 msec I (38701) chip[IN]: CASE Session established. Setting up the secure channel. I (38711) chip[IN]: CASE secure channel is available now. I (38711) chip[IN]: CASE Server enabling CASE session setups E (38721) chip[DL]: Long dispatch time: 2504 ms, for event type 3 I (38771) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124011 on exchange 21775r I (38781) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_0030 e=0 p=a I (38791) chip[DMG]: AccessControl: allowed I (38801) chip[DL]: NVS set: chip-config/fail-safe-armed = false I (38821) chip[IN]: Prepared secure message 0x3ffca434 to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21775r with MessageCounter:9610797. I (38831) chip[IN]: Sending encrypted msg 0x3ffca434 with MessageCounter:9610797 to 0x804C3FB50B91215E (1) at monotonic time: 000000000000946A msec I (38851) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4058969088 on exchange 21774r I (38851) chip[SVR]: Commissioning completed successfully I (38861) chip[DIS]: Updating services using commissioning mode 0 I (38871) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (38951) app-devicecallbacks: Commissioning complete I (38951) NimBLE: GAP procedure initiated: stop advertising. I (38951) NimBLE: GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19 I (39011) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0 I (39011) chip[DL]: CHIPoBLE unsubscribe received I (39031) chip[DL]: BLE GAP connection terminated (con 0 reason 0x216) W (39031) Timer: Timer not stopped W (39041) Timer: Timer not stopped W (39041) Timer: Timer not stopped I (39051) app-devicecallbacks: BLE deinit successful and memory reclaimed I (39051) app-devicecallbacks: Current free heap: 110380 E (39061) chip[DL]: Long dispatch time: 209 ms, for event type 32784 I (39061) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124012 on exchange 21775r E (39081) chip[BLE]: no endpoint for unsub recvd I (39081) app-devicecallbacks: CHIPoBLE disconnected I (39081) app-devicecallbacks: Current free heap: 113788 I (39501) ROUTE_HOOK: Received RIO I (39501) ROUTE_HOOK: prefix :: lifetime 180 I (42561) ROUTE_HOOK: Received RIO I (42561) ROUTE_HOOK: prefix :: lifetime 180 I (45531) ROUTE_HOOK: Received RIO I (45541) ROUTE_HOOK: prefix :: lifetime 180 I (48501) ROUTE_HOOK: Received RIO I (48501) ROUTE_HOOK: prefix :: lifetime 180 I (51571) ROUTE_HOOK: Received RIO I (51571) ROUTE_HOOK: prefix :: lifetime 180 I (54541) ROUTE_HOOK: Received RIO I (54541) ROUTE_HOOK: prefix :: lifetime 180 I (57511) ROUTE_HOOK: Received RIO I (57511) ROUTE_HOOK: prefix :: lifetime 180 I (59621) all-clusters-app: Display going to sleep... I (60581) ROUTE_HOOK: Received RIO I (60591) ROUTE_HOOK: prefix :: lifetime 180 I (62331) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124013 on exchange 21776r I (62341) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_0006 e=1 p=o I (62351) chip[DMG]: AccessControl: allowed I (62351) chip[ZCL]: On/Off set value: 1 1 I (62361) chip[ZCL]: Toggle on/off from 0 to 1 I (62361) chip[ZCL]: On Command - OffWaitTime : 0 I (62361) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002' I (62381) app-devicecallbacks: Unhandled Attribute ID: '0x4002 I (62391) app-devicecallbacks: Current free heap: 112776 I (62391) chip[ZCL]: On/Toggle Command - Stop Timer I (62401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000' I (62411) app-devicecallbacks: Unhandled Attribute ID: '0x4000 I (62411) app-devicecallbacks: Current free heap: 112776 I (62441) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (62441) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (62451) app-devicecallbacks: Current free heap: 112776 I (62481) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (62481) app-devicecallbacks: Current free heap: 112776 I (62491) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (62511) app-devicecallbacks: Unhandled cluster ID: 5 I (62511) app-devicecallbacks: Current free heap: 112776 I (62521) chip[IN]: Prepared secure message 0x3ffca41c to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21776r with MessageCounter:9610798. I (62541) chip[IN]: Sending encrypted msg 0x3ffca41c with MessageCounter:9610798 to 0x804C3FB50B91215E (1) at monotonic time: 000000000000F101 msec E (62551) chip[DL]: Long dispatch time: 222 ms, for event type 3 I (62551) chip[ZCL]: Event: move from 1 I (62551) chip[ZCL]: to 254 I (62571) chip[ZCL]: (diff +1) I (62581) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (62581) app-devicecallbacks: Current free heap: 112512 I (62591) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (62611) app-devicecallbacks: Unhandled cluster ID: 5 I (62611) app-devicecallbacks: Current free heap: 112776 I (62621) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001' I (62631) app-devicecallbacks: Unhandled Attribute ID: '0x0001 I (62631) app-devicecallbacks: Current free heap: 112776 I (63471) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124015 on exchange 21777r I (63471) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_0006 e=1 p=o I (63481) chip[DMG]: AccessControl: allowed I (63491) chip[ZCL]: On/Off set value: 1 0 I (63501) chip[ZCL]: Toggle on/off from 1 to 0 I (63501) chip[ZCL]: Off Command - OnTime : 0 I (63501) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4001' I (63511) app-devicecallbacks: Unhandled Attribute ID: '0x4001 I (63521) app-devicecallbacks: Current free heap: 111256 I (63541) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (63541) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (63551) app-devicecallbacks: Current free heap: 111256 I (63561) ROUTE_HOOK: Received RIO I (63571) ROUTE_HOOK: prefix :: lifetime 180 I (63571) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (63581) app-devicecallbacks: Unhandled cluster ID: 5 I (63591) app-devicecallbacks: Current free heap: 111256 I (63601) chip[IN]: Prepared secure message 0x3ffca434 to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21777r with MessageCounter:9610799. I (63611) chip[IN]: Sending encrypted msg 0x3ffca434 with MessageCounter:9610799 to 0x804C3FB50B91215E (1) at monotonic time: 000000000000F532 msec E (63621) chip[DL]: Long dispatch time: 159 ms, for event type 3 I (63631) chip[ZCL]: Event: move from 254 I (63631) chip[ZCL]: to 1 I (63641) chip[ZCL]: (diff -1) I (63651) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (63651) app-devicecallbacks: Current free heap: 111256 I (63661) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (63681) app-devicecallbacks: Unhandled cluster ID: 5 I (63681) app-devicecallbacks: Current free heap: 109536 I (63701) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (63701) app-devicecallbacks: Current free heap: 109536 I (63711) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001' I (63731) app-devicecallbacks: Unhandled Attribute ID: '0x0001 I (63731) app-devicecallbacks: Current free heap: 109536 I (63741) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124016 on exchange 21777r I (64481) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124017 on exchange 21778r I (64481) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_0006 e=1 p=o I (64501) chip[DMG]: AccessControl: allowed I (64501) chip[ZCL]: On/Off set value: 1 2 I (64511) chip[ZCL]: Toggle on/off from 0 to 1 I (64511) chip[ZCL]: On Command - OffWaitTime : 0 I (64511) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002' I (64521) app-devicecallbacks: Unhandled Attribute ID: '0x4002 I (64531) app-devicecallbacks: Current free heap: 111272 I (64541) chip[ZCL]: On/Toggle Command - Stop Timer I (64551) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000' I (64561) app-devicecallbacks: Unhandled Attribute ID: '0x4000 I (64561) app-devicecallbacks: Current free heap: 111272 I (64581) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (64581) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (64591) app-devicecallbacks: Current free heap: 111272 I (64621) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (64621) app-devicecallbacks: Current free heap: 111272 I (64631) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (64651) app-devicecallbacks: Unhandled cluster ID: 5 I (64651) app-devicecallbacks: Current free heap: 111272 I (64661) chip[IN]: Prepared secure message 0x3ffca434 to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21778r with MessageCounter:9610800. I (64681) chip[IN]: Sending encrypted msg 0x3ffca434 with MessageCounter:9610800 to 0x804C3FB50B91215E (1) at monotonic time: 000000000000F95D msec E (64691) chip[DL]: Long dispatch time: 213 ms, for event type 3 I (64691) chip[ZCL]: Event: move from 1 I (64691) chip[ZCL]: to 254 I (64711) chip[ZCL]: (diff +1) I (64721) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (64721) app-devicecallbacks: Current free heap: 111144 I (64731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (64751) app-devicecallbacks: Unhandled cluster ID: 5 I (64751) app-devicecallbacks: Current free heap: 111144 I (64761) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001' I (64771) app-devicecallbacks: Unhandled Attribute ID: '0x0001 I (64771) app-devicecallbacks: Current free heap: 111144 I (64891) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124018 on exchange 21778r I (65511) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124019 on exchange 21779r I (65511) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_0006 e=1 p=o I (65531) chip[DMG]: AccessControl: allowed I (65531) chip[ZCL]: On/Off set value: 1 2 I (65541) chip[ZCL]: Toggle on/off from 1 to 0 I (65541) chip[ZCL]: Off Command - OnTime : 0 I (65541) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4001' I (65551) app-devicecallbacks: Unhandled Attribute ID: '0x4001 I (65571) app-devicecallbacks: Current free heap: 111144 I (65581) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (65581) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (65591) app-devicecallbacks: Current free heap: 111144 I (65611) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (65611) app-devicecallbacks: Unhandled cluster ID: 5 I (65621) app-devicecallbacks: Current free heap: 111144 I (65621) chip[IN]: Prepared secure message 0x3ffca434 to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21779r with MessageCounter:9610801. I (65641) chip[IN]: Sending encrypted msg 0x3ffca434 with MessageCounter:9610801 to 0x804C3FB50B91215E (1) at monotonic time: 000000000000FD1F msec E (65651) chip[DL]: Long dispatch time: 144 ms, for event type 3 I (65671) chip[ZCL]: Event: move from 254 I (65671) chip[ZCL]: to 1 I (65671) chip[ZCL]: (diff -1) I (65681) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (65681) app-devicecallbacks: Current free heap: 111144 I (65691) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (65711) app-devicecallbacks: Unhandled cluster ID: 5 I (65711) app-devicecallbacks: Current free heap: 111144 I (65731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (65731) app-devicecallbacks: Current free heap: 111144 I (65741) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001' I (65761) app-devicecallbacks: Unhandled Attribute ID: '0x0001 I (65761) app-devicecallbacks: Current free heap: 111144 I (65811) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124020 on exchange 21779r I (66521) ROUTE_HOOK: Received RIO I (66521) ROUTE_HOOK: prefix :: lifetime 180 I (68351) chip[IN]: Sending encrypted msg 0x3ffca41c with MessageCounter:9610798 to 0x804C3FB50B91215E (1) at monotonic time: 00000000000107B4 msec I (68581) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124021 on exchange 21776r I (69491) ROUTE_HOOK: Received RIO I (69491) ROUTE_HOOK: prefix :: lifetime 180 I (72571) ROUTE_HOOK: Received RIO I (72571) ROUTE_HOOK: prefix :: lifetime 180 I (75541) ROUTE_HOOK: Received RIO I (75541) ROUTE_HOOK: prefix :: lifetime 180 I (78501) ROUTE_HOOK: Received RIO I (78511) ROUTE_HOOK: prefix :: lifetime 180 I (78821) chip[EM]: Received message of type 0xa with protocolId (0, 1) and MessageCounter:12124022 on exchange 21780r I (78821) chip[IN]: Prepared secure message 0x3ffca41c to 0x804C3FB50B91215E (1) of type 0x1 and protocolId (0, 1) on exchange 21780r with MessageCounter:9610802. I (78841) chip[IN]: Sending encrypted msg 0x3ffca41c with MessageCounter:9610802 to 0x804C3FB50B91215E (1) at monotonic time: 00000000000130AD msec I (79031) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:12124023 on exchange 21780r I (79031) chip[DMG]: AccessControl: checking f=1 a=c s=0x804C3FB50B91215E t= c=0x0000_003C e=0 p=a I (79041) chip[DMG]: AccessControl: allowed I (79041) chip[ZCL]: Received command to open commissioning window I (79061) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (79061) chip[DIS]: Updating services using commissioning mode 2 I (79071) chip[DIS]: Advertise operational node 2AA47CB2A9EB1C63-000000000000000C I (79091) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (79101) chip[ZCL]: Commissioning window is now open I (79101) chip[IN]: Prepared secure message 0x3ffca41c to 0x804C3FB50B91215E (1) of type 0x9 and protocolId (0, 1) on exchange 21780r with MessageCounter:9610803. I (79111) chip[IN]: Sending encrypted msg 0x3ffca41c with MessageCounter:9610803 to 0x804C3FB50B91215E (1) at monotonic time: 00000000000131C3 msec E (79131) chip[DL]: Long dispatch time: 105 ms, for event type 3 I (79311) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:12124024 on exchange 21780r I (81581) ROUTE_HOOK: Received RIO I (81581) ROUTE_HOOK: prefix :: lifetime 180 I (84551) ROUTE_HOOK: Received RIO I (84551) ROUTE_HOOK: prefix :: lifetime 180 I (87521) ROUTE_HOOK: Received RIO I (87521) ROUTE_HOOK: prefix :: lifetime 180 I (90591) ROUTE_HOOK: Received RIO I (90591) ROUTE_HOOK: prefix :: lifetime 180 I (93561) ROUTE_HOOK: Received RIO I (93561) ROUTE_HOOK: prefix :: lifetime 180 I (96531) ROUTE_HOOK: Received RIO I (96531) ROUTE_HOOK: prefix :: lifetime 180 I (99601) ROUTE_HOOK: Received RIO I (99611) ROUTE_HOOK: prefix :: lifetime 180 I (102581) ROUTE_HOOK: Received RIO I (102581) ROUTE_HOOK: prefix :: lifetime 180 I (105541) ROUTE_HOOK: Received RIO I (105541) ROUTE_HOOK: prefix :: lifetime 180 I (108611) ROUTE_HOOK: Received RIO I (108611) ROUTE_HOOK: prefix :: lifetime 180 I (109061) all-clusters-app: Display going to sleep... I (111581) ROUTE_HOOK: Received RIO I (111581) ROUTE_HOOK: prefix :: lifetime 180 I (114561) ROUTE_HOOK: Received RIO I (114561) ROUTE_HOOK: prefix :: lifetime 180 I (120591) ROUTE_HOOK: Received RIO I (120591) ROUTE_HOOK: prefix :: lifetime 180 I (123561) ROUTE_HOOK: Received RIO I (123561) ROUTE_HOOK: prefix :: lifetime 180 I (126631) ROUTE_HOOK: Received RIO I (126631) ROUTE_HOOK: prefix :: lifetime 180 I (129601) ROUTE_HOOK: Received RIO I (129601) ROUTE_HOOK: prefix :: lifetime 180 I (132571) ROUTE_HOOK: Received RIO I (132571) ROUTE_HOOK: prefix :: lifetime 180 I (135651) ROUTE_HOOK: Received RIO I (135651) ROUTE_HOOK: prefix :: lifetime 180 I (138611) ROUTE_HOOK: Received RIO I (138611) ROUTE_HOOK: prefix :: lifetime 180 I (141581) ROUTE_HOOK: Received RIO I (141581) ROUTE_HOOK: prefix :: lifetime 180