try 0x40080694 I (27) boot: ESP-IDF v4.4-beta1-177-ge104dd7f27 2nd stage bootloader I (27) boot: compile time 11:03:39 I (27) boot: chip revision: 3 I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (44) 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=37ef8h (229112) map I (222) esp_image: segment 1: paddr=00057f20 vaddr=3ffbdb60 size=080f8h ( 33016) load I (235) esp_image: segment 2: paddr=00060020 vaddr=400d0020 size=100414h (1049620) map I (615) esp_image: segment 3: paddr=0016043c vaddr=3ffc5c58 size=003f0h ( 1008) load I (615) esp_image: segment 4: paddr=00160834 vaddr=40080000 size=1e5b8h (124344) load I (672) esp_image: segment 5: paddr=0017edf4 vaddr=50000000 size=00010h ( 16) load I (688) boot: Loaded app from partition at offset 0x20000 I (752) boot: Set actual ota_seq=1 in otadata[0] I (752) boot: Disabling RNG early entropy source... I (763) cpu_start: Pro cpu up. I (763) cpu_start: Starting app cpu, entry point is 0x400814e0 0x400814e0: call_start_cpu1 at /Users/keanhinlim/tools/esp-idf/components/esp_system/port/cpu_start.c:156 I (0) cpu_start: App cpu up. I (779) cpu_start: Pro cpu start user code I (779) cpu_start: cpu freq: 160000000 I (779) cpu_start: Application information: I (784) cpu_start: Project name: chip-all-clusters-app I (790) cpu_start: App version: TE8/rc3-717-g7ab6653ec-dirty I (797) cpu_start: Compile time: Apr 4 2022 12:19:42 I (803) cpu_start: ELF file SHA256: 0e764e84deeb8e24... I (809) cpu_start: ESP-IDF: v4.4-beta1-177-ge104dd7f27 I (816) heap_init: Initializing. RAM available for dynamic allocation: I (823) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (829) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (835) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (841) heap_init: At 3FFD6CB0 len 00009350 (36 KiB): DRAM I (847) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (853) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (860) heap_init: At 4009E5B8 len 00001A48 (6 KiB): IRAM I (867) spi_flash: detected chip: generic I (871) spi_flash: flash io: dio W (875) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. I (891) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (922) all-clusters-app: ================================================== I (922) all-clusters-app: chip-esp32-all-cluster-demo starting I (932) all-clusters-app: ================================================== I (1112) wifi:wifi driver task: 3ffde864, prio:23, stack:6656, core=0 I (1112) system_api: Base MAC address is not set > I (1112) system_api: read default base MAC address from EFUSE I (1122) wifi:wifi firmware version: 7e67c79 I (1132) wifi:wifi certification version: v7.0 I (1132) wifi:config NVS flash: enabled I (1132) wifi:config nano formating: disabled I (1132) wifi:Init data frame dynamic rx buffer num: 32 I (1142) wifi:Init management frame dynamic rx buffer num: 32 I (1152) wifi:Init management short buffer num: 32 I (1152) wifi:Init dynamic tx buffer num: 32 I (1162) wifi:Init static rx buffer size: 1600 I (1162) wifi:Init static rx buffer num: 10 I (1162) wifi:Init dynamic rx buffer num: 32 I (1172) wifi_init: rx ba win: 6 I (1172) wifi_init: tcpip mbox: 32 I (1172) wifi_init: udp mbox: 6 I (1172) wifi_init: tcp mbox: 6 I (1182) wifi_init: tcp tx win: 5744 I (1192) wifi_init: tcp rx win: 5744 I (1192) wifi_init: tcp mss: 1440 I (1202) wifi_init: WiFi IRAM OP enabled I (1202) wifi_init: WiFi RX IRAM OP enabled E (1212) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1) E (1212) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0) E (1222) chip[DL]: NVS set: chip-factory/unique-id = "32A9836711C29E9F" E (1222) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP E (1242) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA E (1242) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (1242) all-clusters-app: ------------------------Starting App Task--------------------------- E (1242) chip[DL]: CHIP task running I (1252) app-task: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (1272) app-task: silicon revision 3, I (1272) app-task: 4MB external flash I (1262) BTDM_INIT: BT controller compile version [6a07b06] E (1282) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] E (1282) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: E (1292) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 E (1312) chip[SVR]: Manual pairing code: [34970112332] I (1292) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 W (1322) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration I (1772) CHIP[DL]: BLE host-controller synced I (2182) all-clusters-app: Display initialized (height 240, width 320) I (2192) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (2202) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2202) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 I (2222) gpio: GPIO[37]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2 E (2312) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2312) NimBLE: GAP procedure initiated: advertise; I (2322) NimBLE: disc_mode=2 I (2322) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2332) NimBLE: I (2342) app-task: App Task started E (2342) chip[DL]: CHIPoBLE advertising started E (2342) chip[DL]: Long dispatch time: 1084 ms, for event type 2 E (2352) chip[DL]: Starting ESP WiFi layer I (2362) wifi:mode : sta (8c:aa:b5:80:4b:4c) I (2362) wifi:enable tsf W (2362) wifi:Haven't to connect to a suitable AP now! E (2362) chip[DL]: Done driving station state, nothing else to do... W (2372) wifi:Haven't to connect to a suitable AP now! E (2372) chip[DL]: Done driving station state, nothing else to do... E (2392) chip[ZCL]: Using ZAP configuration... E (2392) chip[DMG]: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 E (2402) chip[DMG]: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0 E (2402) chip[DMG]: Failed to read stored attribute (0, 0x0000_002B, 0x0000_0001: a0 E (2422) chip[DMG]: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0 E (2432) chip[DMG]: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: a0 E (2432) chip[DMG]: Failed to read stored attribute (0, 0x0000_002D, 0x0000_0000: a0 E (2442) chip[DMG]: Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: a0 E (2452) chip[DMG]: Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0 E (2462) chip[DMG]: Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: a0 E (2472) chip[DMG]: Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0 E (2472) chip[DMG]: Failed to read stored attribute (1, 0x0000_0050, 0x0000_0003: a0 E (2482) chip[DMG]: Failed to read stored attribute (1, 0x0000_0050, 0x0000_0004: a0 E (2492) chip[DMG]: Failed to read stored attribute (1, 0x0000_0050, 0x0000_0005: a0 E (2502) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0003: a0 E (2512) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0004: a0 E (2512) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0007: a0 E (2522) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0008: a0 E (2542) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0009: a0 E (2542) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_000E: a0 E (2552) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_000F: a0 E (2562) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0010: a0 E (2562) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0011: a0 E (2582) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0012: a0 E (2582) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0013: a0 E (2592) chip[DMG]: Failed to read stored attribute (1, 0x0000_0102, 0x0000_0017: a0 E (2612) chip[ZCL]: Initiating Admin Commissioning cluster. E (2612) chip[ZCL]: Door Lock server initialized E (2612) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. E (2622) chip[DIS]: Add fabric pairing table delegate E (2632) chip[DMG]: Endpoint 0, Cluster 0x0000_0003 update version to b6eacf06 I (2642) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (2652) app-devicecallbacks: Current free heap: 78300 E (2652) chip[DMG]: Endpoint 0, Cluster 0x0000_0004 update version to cc0d9a5 I (2662) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (2672) app-devicecallbacks: Unhandled cluster ID: 4 I (2682) app-devicecallbacks: Current free heap: 78300 E (2692) chip[ZCL]: DeviceInfoProvider is not registered E (2692) chip[ZCL]: Trying to write invalid Calendar Type E (2702) chip[ZCL]: Failed to write calendar type with error: 0x87 E (2702) chip[DMG]: Endpoint 1, Cluster 0x0000_0003 update version to 9b4d9832 I (2712) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2732) app-devicecallbacks: Current free heap: 78300 E (2732) chip[DMG]: Endpoint 1, Cluster 0x0000_0004 update version to 2d172b5 I (2742) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2752) app-devicecallbacks: Unhandled cluster ID: 4 I (2752) app-devicecallbacks: Current free heap: 78300 E (2762) chip[DMG]: Endpoint 1, Cluster 0x0000_0005 update version to 524754c8 I (2782) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2782) app-devicecallbacks: Unhandled cluster ID: 5 I (2792) app-devicecallbacks: Current free heap: 78300 E (2792) chip[ZCL]: On/Off set value: 1 0 E (2802) chip[ZCL]: On/off already set to new value E (2812) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to fac791f3 I (2812) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2822) app-devicecallbacks: Current free heap: 78272 E (2832) chip[ZCL]: Window Covering Cluster init E (2832) chip[ZCL]: Initialize PCC Server Cluster [EP:1] E (2852) chip[DMG]: Endpoint 1, Cluster 0x0000_0300 update version to 2a03b0d6 I (2852) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (2862) app-devicecallbacks: Unhandled cluster ID: 768 I (2872) app-devicecallbacks: Current free heap: 78272 E (2872) chip[DMG]: Endpoint 1, Cluster 0x0000_0300 update version to 2a03b0d7 I (2892) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (2902) app-devicecallbacks: Unhandled cluster ID: 768 I (2902) app-devicecallbacks: Current free heap: 78272 E (2902) chip[DMG]: Endpoint 1, Cluster 0x0000_0300 update version to 2a03b0d8 I (2912) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (2922) app-devicecallbacks: Unhandled cluster ID: 768 I (2932) app-devicecallbacks: Current free heap: 78272 E (2942) chip[DMG]: Endpoint 1, Cluster 0x0000_0406 update version to 495fe3eb I (2952) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (2962) app-devicecallbacks: Unhandled cluster ID: 1030 I (2962) app-devicecallbacks: Current free heap: 78272 E (2962) chip[DMG]: Endpoint 1, Cluster 0x0000_0406 update version to 495fe3ec I (2982) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (2992) app-devicecallbacks: Unhandled cluster ID: 1030 I (3002) app-devicecallbacks: Current free heap: 78272 E (3002) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! E (3012) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! E (3012) chip[DMG]: Endpoint 1, Cluster 0x0000_0500 update version to cc978fee I (3032) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (3042) app-devicecallbacks: Unhandled cluster ID: 1280 I (3042) app-devicecallbacks: Current free heap: 78272 E (3052) chip[DMG]: Endpoint 1, Cluster 0x0000_0500 update version to cc978fef I (3052) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (3072) app-devicecallbacks: Unhandled cluster ID: 1280 I (3082) app-devicecallbacks: Current free heap: 78272 E (3082) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 E (3092) chip[DMG]: Endpoint 2, Cluster 0x0000_0004 update version to f04f1ab3 I (3092) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (3102) app-devicecallbacks: Unhandled cluster ID: 4 I (3122) app-devicecallbacks: Current free heap: 78272 E (3122) chip[DMG]: Endpoint 2, Cluster 0x0000_0406 update version to f78ad678 I (3132) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (3142) app-devicecallbacks: Unhandled cluster ID: 1030 I (3142) app-devicecallbacks: Current free heap: 78272 E (3152) chip[DMG]: Endpoint 2, Cluster 0x0000_0406 update version to f78ad679 I (3162) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (3172) app-devicecallbacks: Unhandled cluster ID: 1030 I (3182) app-devicecallbacks: Current free heap: 78272 E (3182) chip[DIS]: Init fabric pairing table with server storage E (3182) chip[DMG]: AccessControl: initializing E (3192) chip[DMG]: Examples::AccessControlDelegate::Init E (3202) chip[DMG]: AccessControl: unable to load stored ACL entries; using empty list instead E (3212) chip[DMG]: AccessControl: setting E (3212) chip[IN]: UDP::Init bind&listen port=5540 E (3222) chip[IN]: UDP::Init bound to port=5540 E (3222) chip[IN]: UDP::Init bind&listen port=5540 E (3232) chip[IN]: UDP::Init bound to port=5540 E (3232) chip[IN]: BLEBase::Init - setting/overriding transport E (3242) chip[IN]: TransportMgr initialized E (3252) chip[DL]: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) E (3262) chip[DIS]: Add fabric pairing table delegate E (3262) chip[DL]: NVS set: chip-counters/global-eidc = 65536 (0x10000) E (3262) chip[SC]: Assigned local session key ID 4521 E (3282) chip[SC]: Waiting for PBKDF param request I (3282) all-clusters-app: Display awake but will switch off automatically in 30 seconds E (3292) chip[DIS]: Updating services using commissioning mode 1 E (3292) chip[DL]: Using wifi MAC for hostname E (3292) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 E (3322) chip[DIS]: Scheduling discovery timeout in 900s E (3322) chip[IN]: CASE Server enabling CASE session setups E (3322) chip[SVR]: Joining Multicast groups E (3332) chip[ZCL]: Emitting StartUp event E (3332) chip[EVL]: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000995 E (3352) chip[ZCL]: GeneralDiagnosticsDelegate: OnDeviceRebooted E (3362) chip[DMG]: Endpoint 0, Cluster 0x0000_0033 update version to 76a896f4 E (3362) chip[EVL]: LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x00000000000009B1 E (3372) chip[SVR]: Server Listening... E (3392) chip[DMG]: Endpoint 0, Cluster 0x0000_001D update version to 7fc47ba3 E (3392) chip[DMG]: Endpoint 1, Cluster 0x0000_0402 update version to fcd15fb2 I (3402) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3402) app-devicecallbacks: Unhandled cluster ID: 1026 I (3422) app-devicecallbacks: Current free heap: 71340 E (3422) chip[DMG]: Endpoint 1, Cluster 0x0000_0101 update version to e1ce6a4 I (3432) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3442) app-devicecallbacks: Unhandled cluster ID: 257 I (3442) app-devicecallbacks: Current free heap: 71220 E (3462) chip[DMG]: Endpoint 1, Cluster 0x0000_0406 update version to 495fe3ed I (3462) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3472) app-devicecallbacks: Unhandled cluster ID: 1030 I (3482) app-devicecallbacks: Current free heap: 70280 E (3482) chip[DMG]: Endpoint 1, Cluster 0x0000_0045 update version to f8d4ea6f I (3492) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3512) app-devicecallbacks: Unhandled cluster ID: 69 I (3512) app-devicecallbacks: Current free heap: 70160 E (3522) chip[DMG]: Endpoint 1, Cluster 0x0000_0402 update version to fcd15fb3 I (3522) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3532) app-devicecallbacks: Unhandled cluster ID: 1026 I (3552) app-devicecallbacks: Current free heap: 69800 E (3552) chip[DMG]: Endpoint 1, Cluster 0x0000_0201 update version to 12e3af5c I (3562) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3572) app-devicecallbacks: Unhandled cluster ID: 513 I (3572) app-devicecallbacks: Current free heap: 69800 E (3582) chip[DMG]: Endpoint 1, Cluster 0x0000_0201 update version to 12e3af5d I (3592) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (3602) app-devicecallbacks: Unhandled cluster ID: 513 I (3612) app-devicecallbacks: Current free heap: 69752 E (3612) chip[DMG]: Endpoint 1, Cluster 0x0000_0201 update version to 12e3af5e I (3622) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011' I (3642) app-devicecallbacks: Unhandled cluster ID: 513 I (3642) app-devicecallbacks: Current free heap: 69672 E (3652) chip[DMG]: Endpoint 1, Cluster 0x0000_0201 update version to 12e3af5f I (3652) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012' I (3662) app-devicecallbacks: Unhandled cluster ID: 513 I (3672) app-devicecallbacks: Current free heap: 69544 E (3682) chip[DMG]: Endpoint 1, Cluster 0x0000_0405 update version to 8e65d13d I (3692) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3702) app-devicecallbacks: Unhandled cluster ID: 1029 I (3702) app-devicecallbacks: Current free heap: 69424 E (3712) chip[DMG]: Endpoint 1, Cluster 0x0000_0400 update version to e8d8ff77 I (3712) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3732) app-devicecallbacks: Unhandled cluster ID: 1024 I (3732) app-devicecallbacks: Current free heap: 69268 E (3742) chip[DMG]: Endpoint 1, Cluster 0x0000_0006 update version to e0627f1 I (3752) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3762) app-devicecallbacks: Current free heap: 69148 E (3782) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to fac791f4 I (3782) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3792) app-devicecallbacks: Current free heap: 68916 E (3792) chip[DMG]: Endpoint 1, Cluster 0x0000_0300 update version to 2a03b0d9 I (3812) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0000' I (3822) app-devicecallbacks: Unhandled cluster ID: 768 I (3822) app-devicecallbacks: Current free heap: 68796 E (3832) chip[DMG]: Endpoint 1, Cluster 0x0000_0300 update version to 2a03b0da I (3832) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0001' I (3852) app-devicecallbacks: Unhandled cluster ID: 768 I (3862) app-devicecallbacks: Current free heap: 68728 E (3862) chip[DL]: Long dispatch time: 1473 ms, for event type 2 I (3872) app-devicecallbacks: Current free heap: 68728 E (3872) chip[DL]: WIFI_EVENT_STA_START W (3882) wifi:Haven't to connect to a suitable AP now! E (3882) chip[DL]: Done driving station state, nothing else to do... I (3902) app-devicecallbacks: Current free heap: 68728 E (3902) chip[DIS]: Updating services using commissioning mode 1 E (3902) chip[DL]: Using wifi MAC for hostname E (3912) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 E (3942) chip[DIS]: Scheduling discovery timeout in 900s I (3942) app-devicecallbacks: Current free heap: 68712 E (3942) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) E (3952) chip[DL]: Device already advertising, stop active advertisement and restart I (3962) NimBLE: GAP procedure initiated: stop advertising. I (3972) NimBLE: GAP procedure initiated: advertise; I (3972) NimBLE: disc_mode=2 I (3982) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (3982) NimBLE: E (4002) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet E (4002) chip[DIS]: Add fabric pairing table delegate E (4002) chip[SVR]: Cannot load binding table: a0 I (33282) all-clusters-app: Display going to sleep... E (33282) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840) E (33292) chip[DL]: Device already advertising, stop active advertisement and restart I (33292) NimBLE: GAP procedure initiated: stop advertising. I (33312) NimBLE: GAP procedure initiated: advertise; I (33312) NimBLE: disc_mode=2 I (33322) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800 I (33322) NimBLE: I (70712) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (71202) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (71472) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (71862) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (71862) DeviceWithDisplay: Opening QR code screen E (71872) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] E (71872) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: E (71882) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 E (71882) chip[SVR]: Manual pairing code: [34970112332] E (85882) chip[DL]: BLE GAP connection established (con 0) E (85892) chip[DL]: CHIPoBLE advertising stopped I (85892) app-devicecallbacks: Current free heap: 68524 I (86572) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (86582) chip[BLE]: local and remote recv window sizes = 5 E (86582) chip[BLE]: selected BTP version 4 E (86592) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. E (86762) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1 E (86762) chip[DL]: CHIPoBLE subscribe received I (86762) NimBLE: GATT procedure initiated: notify; I (86772) NimBLE: att_handle=14 E (86772) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (86792) chip[IN]: BLE EndPoint 0x3ffd02a0 Connection Complete I (86792) app-devicecallbacks: CHIPoBLE connection established I (86802) app-devicecallbacks: Current free heap: 68524 I (86822) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (86822) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:2296838078 on exchange 7840r E (86832) chip[EM]: Handling via exchange: 7840r, Delegate: 0x3ffca840 E (86832) chip[SC]: Received PBKDF param request E (86852) chip[SC]: Peer assigned session ID 28759 E (86852) chip[SC]: Found MRP parameters in the message E (86852) chip[SC]: Including MRP parameters in PBKDF param response E (86862) chip[IN]: Prepared unauthenticated message 0x3ffe7024 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 7840r with MessageCounter:430980894. E (86882) chip[IN]: Sending unauthenticated msg 0x3ffe7024 with MessageCounter:430980894 to 0x0000000000000000 at monotonic time: 0000000000014FEE msec I (86892) NimBLE: GATT procedure initiated: notify; I (86902) NimBLE: att_handle=14 E (86902) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (86912) chip[SC]: Sent PBKDF param response I (87002) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (87002) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:2296838079 on exchange 7840r E (87012) chip[EM]: Found matching exchange: 7840r, Delegate: 0x3ffca840 E (87012) chip[SC]: Received spake2p msg1 E (89472) chip[IN]: Prepared unauthenticated message 0x3ffe6fa4 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 7840r with MessageCounter:430980895. E (89492) chip[IN]: Sending unauthenticated msg 0x3ffe6fa4 with MessageCounter:430980895 to 0x0000000000000000 at monotonic time: 0000000000015A20 msec I (89502) NimBLE: GATT procedure initiated: notify; I (89502) NimBLE: att_handle=14 E (89512) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (89522) chip[SC]: Sent spake2p msg2 E (89522) chip[DL]: Long dispatch time: 2519 ms, for event type 7 I (89632) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (89642) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:2296838080 on exchange 7840r E (89652) chip[EM]: Found matching exchange: 7840r, Delegate: 0x3ffca840 E (89652) chip[SC]: Received spake2p msg3 E (89672) chip[SC]: Sending status report. Protocol code 0, exchange 7840 E (89672) chip[IN]: Prepared unauthenticated message 0x3ffe7024 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 7840r with MessageCounter:430980896. E (89682) chip[IN]: Sending unauthenticated msg 0x3ffe7024 with MessageCounter:430980896 to 0x0000000000000000 at monotonic time: 0000000000015AE4 msec I (89702) NimBLE: GATT procedure initiated: notify; I (89712) NimBLE: att_handle=14 E (89712) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (89722) chip[IN]: New secure session created for device 0xFFFFFFFB00000000, LSID:4521 PSID:28759! E (89732) chip[SVR]: Commissioning completed session establishment step I (89742) all-clusters-app: Display awake but will switch off automatically in 30 seconds E (89742) chip[DIS]: Updating services using commissioning mode 0 I (89762) all-clusters-app: Display awake but will switch off automatically in 30 seconds E (89762) chip[SVR]: Device completed Rendezvous process E (89772) chip[DL]: Long dispatch time: 132 ms, for event type 7 I (92242) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (94752) NimBLE: GATT procedure initiated: notify; I (94752) NimBLE: att_handle=14 E (94752) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (97342) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (99852) NimBLE: GATT procedure initiated: notify; I (99852) NimBLE: att_handle=14 E (99852) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (102412) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (104922) NimBLE: GATT procedure initiated: notify; I (104922) NimBLE: att_handle=14 E (104922) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (107452) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (109962) NimBLE: GATT procedure initiated: notify; I (109962) NimBLE: att_handle=14 E (109962) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (110372) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (110372) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:4827431 on exchange 7841r E (110382) chip[EM]: Handling via exchange: 7841r, Delegate: 0x3ffcf4c8 E (110392) chip[IM]: Received Read request E (110392) chip[DMG]: ReadRequestMessage = E (110402) chip[DMG]: { E (110402) chip[DMG]: AttributePathIBs = E (110402) chip[DMG]: [ E (110412) chip[DMG]: AttributePathIB = E (110412) chip[DMG]: { E (110412) chip[DMG]: Cluster = 0x31, E (110422) chip[DMG]: Attribute = 0x0000_FFFC, E (110432) chip[DMG]: } E (110432) chip[DMG]: E (110432) chip[DMG]: AttributePathIB = E (110442) chip[DMG]: { E (110442) chip[DMG]: Endpoint = 0x0, E (110442) chip[DMG]: Cluster = 0x30, E (110452) chip[DMG]: Attribute = 0x0000_0000, E (110452) chip[DMG]: } E (110452) chip[DMG]: E (110472) chip[DMG]: AttributePathIB = E (110472) chip[DMG]: { E (110472) chip[DMG]: Endpoint = 0x0, E (110482) chip[DMG]: Cluster = 0x30, E (110482) chip[DMG]: Attribute = 0x0000_0001, E (110482) chip[DMG]: } E (110492) chip[DMG]: E (110492) chip[DMG]: AttributePathIB = E (110492) chip[DMG]: { E (110492) chip[DMG]: Endpoint = 0x0, E (110512) chip[DMG]: Cluster = 0x30, E (110512) chip[DMG]: Attribute = 0x0000_0002, E (110522) chip[DMG]: } E (110522) chip[DMG]: E (110522) chip[DMG]: AttributePathIB = E (110522) chip[DMG]: { E (110532) chip[DMG]: Endpoint = 0x0, E (110532) chip[DMG]: Cluster = 0x30, E (110532) chip[DMG]: Attribute = 0x0000_0003, E (110542) chip[DMG]: } E (110552) chip[DMG]: E (110552) chip[DMG]: AttributePathIB = E (110562) chip[DMG]: { E (110562) chip[DMG]: Endpoint = 0x0, E (110562) chip[DMG]: Cluster = 0x28, E (110572) chip[DMG]: Attribute = 0x0000_0002, E (110572) chip[DMG]: } E (110572) chip[DMG]: E (110572) chip[DMG]: AttributePathIB = E (110582) chip[DMG]: { E (110582) chip[DMG]: Endpoint = 0x0, E (110592) chip[DMG]: Cluster = 0x28, E (110602) chip[DMG]: Attribute = 0x0000_0004, E (110602) chip[DMG]: } E (110602) chip[DMG]: E (110612) chip[DMG]: AttributePathIB = E (110612) chip[DMG]: { E (110612) chip[DMG]: Cluster = 0x31, E (110622) chip[DMG]: Attribute = 0x0000_0003, E (110622) chip[DMG]: } E (110622) chip[DMG]: E (110642) chip[DMG]: ], E (110642) chip[DMG]: E (110642) chip[DMG]: isFabricFiltered = true, E (110642) chip[DMG]: InteractionModelRevision = 1 E (110652) chip[DMG]: }, E (110652) chip[DMG]: IM RH moving to [GeneratingReports] E (110662) chip[DL]: Long dispatch time: 296 ms, for event type 7 E (110672) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 E (110682) chip[DMG]: Cluster 31, Attribute 3 is dirty E (110682) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) E (110692) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v E (110712) chip[DMG]: AccessControl: implicit admin (PASE) E (110712) chip[DMG]: Cluster 28, Attribute 4 is dirty E (110722) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) E (110722) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v E (110732) chip[DMG]: AccessControl: implicit admin (PASE) E (110752) chip[DMG]: Cluster 28, Attribute 2 is dirty E (110752) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) E (110762) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v E (110772) chip[DMG]: AccessControl: implicit admin (PASE) E (110772) chip[DMG]: Cluster 30, Attribute 3 is dirty E (110782) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) E (110802) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v E (110802) chip[DMG]: AccessControl: implicit admin (PASE) E (110812) chip[DMG]: Cluster 30, Attribute 2 is dirty E (110812) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) E (110822) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v E (110842) chip[DMG]: AccessControl: implicit admin (PASE) E (110842) chip[DMG]: Cluster 30, Attribute 1 is dirty E (110852) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) E (110862) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v E (110862) chip[DMG]: AccessControl: implicit admin (PASE) E (110882) chip[DMG]: Cluster 30, Attribute 0 is dirty E (110882) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) E (110892) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v E (110902) chip[DMG]: AccessControl: implicit admin (PASE) E (110902) chip[DMG]: Cluster 31, Attribute fffc is dirty E (110922) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) E (110932) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v E (110932) chip[DMG]: AccessControl: implicit admin (PASE) E (110942) chip[DMG]: Sending report (payload has 224 bytes)... E (110952) chip[IN]: Prepared secure message 0x3ffe72a4 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 7841r with MessageCounter:4919741. E (110962) chip[IN]: Sending encrypted msg 0x3ffe72a4 with MessageCounter:4919741 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001AE02 msec I (110972) NimBLE: GATT procedure initiated: notify; I (110982) NimBLE: att_handle=14 E (110992) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (110992) chip[DMG]: OnReportConfirm: NumReports = 0 E (111002) chip[DMG]: ReportsInFlight = 0 with readHandler 0, RE has no more messages E (111012) chip[DMG]: IM RH moving to [AwaitingDestruction] E (111022) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet E (111032) chip[DL]: Long dispatch time: 361 ms, for event type 3 I (111032) NimBLE: GATT procedure initiated: notify; I (111042) NimBLE: att_handle=14 E (111042) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (111112) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (111122) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827432 on exchange 7842r E (111132) chip[EM]: Handling via exchange: 7842r, Delegate: 0x3ffcf4c8 E (111142) chip[DMG]: InvokeRequestMessage = E (111142) chip[DMG]: { E (111152) chip[DMG]: suppressResponse = false, E (111152) chip[DMG]: timedRequest = false, E (111162) chip[DMG]: InvokeRequests = E (111162) chip[DMG]: [ E (111162) chip[DMG]: CommandDataIB = E (111162) chip[DMG]: { E (111172) chip[DMG]: CommandPathIB = E (111172) chip[DMG]: { E (111182) chip[DMG]: EndpointId = 0x0, E (111192) chip[DMG]: ClusterId = 0x30, E (111192) chip[DMG]: CommandId = 0x0, E (111192) chip[DMG]: }, E (111202) chip[DMG]: E (111202) chip[DMG]: CommandData = E (111202) chip[DMG]: { E (111202) chip[DMG]: 0x0 = 60, E (111212) chip[DMG]: 0x1 = 3, E (111222) chip[DMG]: }, E (111222) chip[DMG]: }, E (111232) chip[DMG]: E (111232) chip[DMG]: ], E (111232) chip[DMG]: E (111232) chip[DMG]: InteractionModelRevision = 1 E (111242) chip[DMG]: }, E (111242) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a E (111252) chip[DMG]: AccessControl: implicit admin (PASE) E (111262) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 E (111272) chip[DL]: NVS set: chip-config/fail-safe-armed = true E (111272) chip[DMG]: ICR moving to [ Preparing] E (111272) chip[DMG]: ICR moving to [AddingComm] E (111292) chip[DMG]: ICR moving to [AddedComma] E (111292) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (111302) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7842r with MessageCounter:4919742. E (111312) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919742 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001AF64 msec I (111332) NimBLE: GATT procedure initiated: notify; I (111332) NimBLE: att_handle=14 E (111342) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (111342) chip[DMG]: ICR moving to [CommandSen] E (111362) chip[DMG]: ICR moving to [AwaitingDe] E (111362) chip[DL]: Long dispatch time: 240 ms, for event type 7 I (111392) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (111392) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827433 on exchange 7843r E (111402) chip[EM]: Handling via exchange: 7843r, Delegate: 0x3ffcf4c8 E (111412) chip[DMG]: InvokeRequestMessage = E (111412) chip[DMG]: { E (111422) chip[DMG]: suppressResponse = false, E (111422) chip[DMG]: timedRequest = false, E (111432) chip[DMG]: InvokeRequests = E (111432) chip[DMG]: [ E (111432) chip[DMG]: CommandDataIB = E (111432) chip[DMG]: { E (111442) chip[DMG]: CommandPathIB = E (111452) chip[DMG]: { E (111452) chip[DMG]: EndpointId = 0x0, E (111462) chip[DMG]: ClusterId = 0x30, E (111462) chip[DMG]: CommandId = 0x2, E (111462) chip[DMG]: }, E (111472) chip[DMG]: E (111472) chip[DMG]: CommandData = E (111472) chip[DMG]: { E (111472) chip[DMG]: 0x0 = 0, E (111492) chip[DMG]: 0x1 = "XX", E (111492) chip[DMG]: 0x2 = 4, E (111492) chip[DMG]: }, E (111502) chip[DMG]: }, E (111502) chip[DMG]: E (111502) chip[DMG]: ], E (111502) chip[DMG]: E (111512) chip[DMG]: InteractionModelRevision = 1 E (111512) chip[DMG]: }, E (111522) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a E (111532) chip[DMG]: AccessControl: implicit admin (PASE) E (111532) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 E (111542) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) E (111552) chip[DL]: NVS set: chip-config/country-code = "XX" E (111562) chip[DL]: NVS set: chip-config/breadcrumb = 4 (0x4) E (111562) chip[DMG]: ICR moving to [ Preparing] E (111572) chip[DMG]: ICR moving to [AddingComm] E (111572) chip[DMG]: ICR moving to [AddedComma] E (111572) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (111592) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7843r with MessageCounter:4919743. E (111602) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919743 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001B082 msec I (111612) NimBLE: GATT procedure initiated: notify; I (111622) NimBLE: att_handle=14 E (111632) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (111632) chip[DMG]: ICR moving to [CommandSen] E (111642) chip[DMG]: ICR moving to [AwaitingDe] E (111642) chip[DL]: Long dispatch time: 255 ms, for event type 7 I (111692) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (111692) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827434 on exchange 7844r E (111702) chip[EM]: Handling via exchange: 7844r, Delegate: 0x3ffcf4c8 E (111712) chip[DMG]: InvokeRequestMessage = E (111712) chip[DMG]: { E (111722) chip[DMG]: suppressResponse = false, E (111722) chip[DMG]: timedRequest = false, E (111732) chip[DMG]: InvokeRequests = E (111732) chip[DMG]: [ E (111732) chip[DMG]: CommandDataIB = E (111732) chip[DMG]: { E (111742) chip[DMG]: CommandPathIB = E (111752) chip[DMG]: { E (111752) chip[DMG]: EndpointId = 0x0, E (111762) chip[DMG]: ClusterId = 0x3e, E (111762) chip[DMG]: CommandId = 0x2, E (111762) chip[DMG]: }, E (111772) chip[DMG]: E (111772) chip[DMG]: CommandData = E (111772) chip[DMG]: { E (111772) chip[DMG]: 0x0 = 2, E (111792) chip[DMG]: }, E (111792) chip[DMG]: }, E (111792) chip[DMG]: E (111792) chip[DMG]: ], E (111802) chip[DMG]: E (111802) chip[DMG]: InteractionModelRevision = 1 E (111802) chip[DMG]: }, E (111812) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (111812) chip[DMG]: AccessControl: implicit admin (PASE) E (111832) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 E (111832) chip[ZCL]: OpCreds: Certificate Chain request received for PAI E (111842) chip[DMG]: ICR moving to [ Preparing] E (111842) chip[DMG]: ICR moving to [AddingComm] E (111852) chip[DMG]: ICR moving to [AddedComma] E (111852) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (111872) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7844r with MessageCounter:4919744. E (111882) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919744 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001B19B msec I (111892) NimBLE: GATT procedure initiated: notify; I (111902) NimBLE: att_handle=14 E (111912) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (111912) chip[DMG]: ICR moving to [CommandSen] E (111922) chip[DMG]: ICR moving to [AwaitingDe] E (111932) chip[DL]: Long dispatch time: 238 ms, for event type 7 I (111932) NimBLE: GATT procedure initiated: notify; I (111942) NimBLE: att_handle=14 E (111942) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (111962) NimBLE: GATT procedure initiated: notify; I (111962) NimBLE: att_handle=14 E (111962) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (112022) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (112022) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827435 on exchange 7845r E (112032) chip[EM]: Handling via exchange: 7845r, Delegate: 0x3ffcf4c8 E (112042) chip[DMG]: InvokeRequestMessage = E (112042) chip[DMG]: { E (112052) chip[DMG]: suppressResponse = false, E (112052) chip[DMG]: timedRequest = false, E (112062) chip[DMG]: InvokeRequests = E (112062) chip[DMG]: [ E (112062) chip[DMG]: CommandDataIB = E (112062) chip[DMG]: { E (112072) chip[DMG]: CommandPathIB = E (112082) chip[DMG]: { E (112082) chip[DMG]: EndpointId = 0x0, E (112092) chip[DMG]: ClusterId = 0x3e, E (112092) chip[DMG]: CommandId = 0x2, E (112092) chip[DMG]: }, E (112102) chip[DMG]: E (112102) chip[DMG]: CommandData = E (112102) chip[DMG]: { E (112102) chip[DMG]: 0x0 = 1, E (112112) chip[DMG]: }, E (112122) chip[DMG]: }, E (112122) chip[DMG]: E (112122) chip[DMG]: ], E (112132) chip[DMG]: E (112132) chip[DMG]: InteractionModelRevision = 1 E (112132) chip[DMG]: }, E (112142) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (112142) chip[DMG]: AccessControl: implicit admin (PASE) E (112162) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 E (112162) chip[ZCL]: OpCreds: Certificate Chain request received for DAC E (112172) chip[DMG]: ICR moving to [ Preparing] E (112172) chip[DMG]: ICR moving to [AddingComm] E (112182) chip[DMG]: ICR moving to [AddedComma] E (112182) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (112202) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7845r with MessageCounter:4919745. E (112212) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919745 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001B2E4 msec I (112222) NimBLE: GATT procedure initiated: notify; I (112232) NimBLE: att_handle=14 E (112242) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (112242) chip[DMG]: ICR moving to [CommandSen] E (112252) chip[DMG]: ICR moving to [AwaitingDe] E (112262) chip[DL]: Long dispatch time: 238 ms, for event type 7 I (112262) NimBLE: GATT procedure initiated: notify; I (112272) NimBLE: att_handle=14 E (112272) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (112292) NimBLE: GATT procedure initiated: notify; I (112292) NimBLE: att_handle=14 E (112292) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (112352) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (112352) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827436 on exchange 7846r E (112362) chip[EM]: Handling via exchange: 7846r, Delegate: 0x3ffcf4c8 E (112372) chip[DMG]: InvokeRequestMessage = E (112372) chip[DMG]: { E (112382) chip[DMG]: suppressResponse = false, E (112382) chip[DMG]: timedRequest = false, E (112392) chip[DMG]: InvokeRequests = E (112392) chip[DMG]: [ E (112392) chip[DMG]: CommandDataIB = E (112392) chip[DMG]: { E (112402) chip[DMG]: CommandPathIB = E (112412) chip[DMG]: { E (112412) chip[DMG]: EndpointId = 0x0, E (112422) chip[DMG]: ClusterId = 0x3e, E (112422) chip[DMG]: CommandId = 0x0, E (112422) chip[DMG]: }, E (112432) chip[DMG]: E (112432) chip[DMG]: CommandData = E (112432) chip[DMG]: { E (112432) chip[DMG]: 0x0 = [ E (112442) chip[DMG]: 0xa6, 0x7, 0xe, 0xb9, 0x4a, 0x6d, 0xa3, 0x53, 0xa4, 0xbf, 0xf5, 0xcb, 0xf5, 0x59, 0xf0, 0x8d, 0xb, 0x13, 0x1, 0xa4, 0x89, 0xcd, 0x5c, 0x25, 0xe4, 0xff, 0x48, 0xb3, 0x29, 0xaf, 0xb3, 0xbe, E (112462) chip[DMG]: ] E (112472) chip[DMG]: }, E (112472) chip[DMG]: }, E (112472) chip[DMG]: E (112472) chip[DMG]: ], E (112482) chip[DMG]: E (112482) chip[DMG]: InteractionModelRevision = 1 E (112482) chip[DMG]: }, E (112492) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (112502) chip[DMG]: AccessControl: implicit admin (PASE) E (112512) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 E (112512) chip[ZCL]: OpCreds: received an AttestationRequest E (113022) chip[DMG]: ICR moving to [ Preparing] E (113022) chip[DMG]: ICR moving to [AddingComm] E (113022) chip[DMG]: ICR moving to [AddedComma] E (113042) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (113042) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7846r with MessageCounter:4919746. E (113052) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919746 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001B630 msec I (113072) NimBLE: GATT procedure initiated: notify; I (113082) NimBLE: att_handle=14 E (113082) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (113092) chip[DMG]: ICR moving to [CommandSen] E (113102) chip[DMG]: ICR moving to [AwaitingDe] E (113102) chip[DL]: Long dispatch time: 751 ms, for event type 7 I (113112) NimBLE: GATT procedure initiated: notify; I (113112) NimBLE: att_handle=14 E (113122) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (113132) NimBLE: GATT procedure initiated: notify; I (113132) NimBLE: att_handle=14 E (113142) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (113282) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (113282) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827437 on exchange 7847r E (113292) chip[EM]: Handling via exchange: 7847r, Delegate: 0x3ffcf4c8 E (113302) chip[DMG]: InvokeRequestMessage = E (113302) chip[DMG]: { E (113312) chip[DMG]: suppressResponse = false, E (113312) chip[DMG]: timedRequest = false, E (113322) chip[DMG]: InvokeRequests = E (113322) chip[DMG]: [ E (113322) chip[DMG]: CommandDataIB = E (113322) chip[DMG]: { E (113332) chip[DMG]: CommandPathIB = E (113342) chip[DMG]: { E (113342) chip[DMG]: EndpointId = 0x0, E (113352) chip[DMG]: ClusterId = 0x3e, E (113352) chip[DMG]: CommandId = 0x4, E (113352) chip[DMG]: }, E (113362) chip[DMG]: E (113362) chip[DMG]: CommandData = E (113362) chip[DMG]: { E (113362) chip[DMG]: 0x0 = [ E (113382) chip[DMG]: 0xf0, 0x41, 0x38, 0xae, 0x82, 0xf5, 0xb, 0x93, 0xe2, 0x56, 0xe8, 0x87, 0x83, 0xd8, 0xb8, 0x6c, 0x9e, 0x6b, 0xaa, 0x29, 0x1e, 0x93, 0x92, 0xba, 0xc4, 0xfa, 0x6a, 0x95, 0x43, 0x98, 0xd1, 0x3c, E (113392) chip[DMG]: ] E (113392) chip[DMG]: }, E (113402) chip[DMG]: }, E (113402) chip[DMG]: E (113402) chip[DMG]: ], E (113412) chip[DMG]: E (113412) chip[DMG]: InteractionModelRevision = 1 E (113422) chip[DMG]: }, E (113422) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (113432) chip[DMG]: AccessControl: implicit admin (PASE) E (113442) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 E (113442) chip[ZCL]: OpCreds: commissioner has requested a CSR E (114902) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0 E (115402) chip[DMG]: ICR moving to [ Preparing] E (115412) chip[DMG]: ICR moving to [AddingComm] E (115412) chip[DMG]: ICR moving to [AddedComma] E (115422) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (115422) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7847r with MessageCounter:4919747. E (115442) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919747 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001BF7D msec I (115452) NimBLE: GATT procedure initiated: notify; I (115462) NimBLE: att_handle=14 E (115462) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (115482) chip[DMG]: ICR moving to [CommandSen] E (115482) chip[DMG]: ICR moving to [AwaitingDe] E (115482) chip[DL]: Long dispatch time: 2199 ms, for event type 7 I (115492) NimBLE: GATT procedure initiated: notify; I (115492) NimBLE: att_handle=14 E (115502) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (115592) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (115652) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (115652) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827438 on exchange 7848r E (115662) chip[EM]: Handling via exchange: 7848r, Delegate: 0x3ffcf4c8 E (115672) chip[DMG]: InvokeRequestMessage = E (115672) chip[DMG]: { E (115682) chip[DMG]: suppressResponse = false, E (115682) chip[DMG]: timedRequest = false, E (115692) chip[DMG]: InvokeRequests = E (115692) chip[DMG]: [ E (115692) chip[DMG]: CommandDataIB = E (115692) chip[DMG]: { E (115702) chip[DMG]: CommandPathIB = E (115712) chip[DMG]: { E (115712) chip[DMG]: EndpointId = 0x0, E (115722) chip[DMG]: ClusterId = 0x3e, E (115722) chip[DMG]: CommandId = 0xb, E (115722) chip[DMG]: }, E (115732) chip[DMG]: E (115732) chip[DMG]: CommandData = E (115732) chip[DMG]: { E (115732) chip[DMG]: 0x0 = [ E (115752) chip[DMG]: 0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x25, 0x14, 0xd2, 0x4, 0x24, 0x15, 0x1, 0x18, 0x26, 0x4, 0xb4, 0xd4, 0xdd, 0x29, 0x26, 0x5, 0x34, 0x8, 0xbf, 0x2b, 0x37, 0x6, 0x25, 0x14, 0xd2, 0x4, 0x24, 0x15, 0x1, 0x18, 0x24, 0x7, 0x1, 0x24, 0x E (115772) chip[DMG]: ] E (115772) chip[DMG]: }, E (115772) chip[DMG]: }, E (115772) chip[DMG]: E (115782) chip[DMG]: ], E (115782) chip[DMG]: E (115792) chip[DMG]: InteractionModelRevision = 1 E (115802) chip[DMG]: }, E (115802) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (115812) chip[DMG]: AccessControl: implicit admin (PASE) E (115812) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B E (115822) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert E (115832) chip[DMG]: ICR moving to [ Preparing] E (115842) chip[DMG]: ICR moving to [AddingComm] E (115842) chip[DMG]: ICR moving to [AddedComma] E (115842) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 10b5c48a E (115852) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (115872) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 7848r with MessageCounter:4919748. E (115882) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919748 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C139 msec I (115892) NimBLE: GATT procedure initiated: notify; I (115892) NimBLE: att_handle=14 E (115902) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (115912) chip[DMG]: ICR moving to [CommandSen] E (115912) chip[DMG]: ICR moving to [AwaitingDe] E (115922) chip[DL]: Long dispatch time: 276 ms, for event type 7 E (115922) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet I (115952) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (116012) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (116012) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827439 on exchange 7849r E (116022) chip[EM]: Handling via exchange: 7849r, Delegate: 0x3ffcf4c8 E (116032) chip[DMG]: InvokeRequestMessage = E (116032) chip[DMG]: { E (116042) chip[DMG]: suppressResponse = false, E (116042) chip[DMG]: timedRequest = false, E (116052) chip[DMG]: InvokeRequests = E (116052) chip[DMG]: [ E (116052) chip[DMG]: CommandDataIB = E (116052) chip[DMG]: { E (116072) chip[DMG]: CommandPathIB = E (116072) chip[DMG]: { E (116072) chip[DMG]: EndpointId = 0x0, E (116082) chip[DMG]: ClusterId = 0x3e, E (116082) chip[DMG]: CommandId = 0x6, E (116082) chip[DMG]: }, E (116092) chip[DMG]: E (116092) chip[DMG]: CommandData = E (116092) chip[DMG]: { E (116092) chip[DMG]: 0x0 = [ E (116112) chip[DMG]: 0x15, 0x30, 0x1, 0x1, 0x1, 0x24, 0x2, 0x1, 0x37, 0x3, 0x25, 0x14, 0xd2, 0x4, 0x24, 0x15, 0x1, 0x18, 0x26, 0x4, 0xdd, 0xd4, 0xdd, 0x29, 0x26, 0x5, 0x5d, 0x8, 0xbf, 0x2b, 0x37, 0x6, 0x24, 0x15, 0x1, 0x24, 0x11, 0x1, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1 E (116132) chip[DMG]: ] E (116132) chip[DMG]: 0x1 = [ E (116132) chip[DMG]: E (116132) chip[DMG]: ] E (116142) chip[DMG]: 0x2 = [ E (116142) chip[DMG]: 0x5, 0x68, 0x63, 0xb0, 0x8, 0x98, 0xc9, 0x7, 0x86, 0xfd, 0x54, 0x48, 0x53, 0x83, 0x6d, 0x91, E (116162) chip[DMG]: ] E (116162) chip[DMG]: 0x3 = 7416021550484092751, E (116172) chip[DMG]: 0x4 = 65521, E (116172) chip[DMG]: }, E (116172) chip[DMG]: }, E (116172) chip[DMG]: E (116182) chip[DMG]: ], E (116182) chip[DMG]: E (116192) chip[DMG]: InteractionModelRevision = 1 E (116202) chip[DMG]: }, E (116202) chip[DMG]: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a E (116212) chip[DMG]: AccessControl: implicit admin (PASE) E (116212) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 E (116222) chip[ZCL]: OpCreds: commissioner has added a NOC E (116232) chip[DIS]: Verifying the received credentials E (117222) chip[DIS]: Added new fabric at index: 1, Initialized: 1 E (117222) chip[DIS]: Assigned compressed fabric ID: 0x4CC38A20E3FAA9D1, node ID: 0x0000000000000001 E (117252) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage E (117252) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000001, NodeId 0000000000000001, VendorId 0xFFF1 E (117262) chip[ZCL]: OpCreds: Call to fabricListChanged E (117282) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 10b5c48b E (117282) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 10b5c48c E (117302) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage E (117312) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000001, NodeId 0000000000000001, VendorId 0xFFF1 E (117322) chip[ZCL]: OpCreds: Call to fabricListChanged E (117332) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 10b5c48d E (117332) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 10b5c48e E (117362) chip[DMG]: AccessControl: validating f=1 p=a a=c s=1 t=0 E (117362) chip[DMG]: validating subject 0x66EB004EF33EF74F E (117422) chip[ZCL]: OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x66EB004EF33EF74F E (117432) chip[DL]: Using wifi MAC for hostname E (117432) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 E (117452) chip[DMG]: ICR moving to [ Preparing] E (117452) chip[DMG]: ICR moving to [AddingComm] E (117452) chip[DMG]: ICR moving to [AddedComma] E (117462) chip[ZCL]: OpCreds: successfully added a NOC E (117462) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (117472) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 7849r with MessageCounter:4919749. E (117492) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919749 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001C782 msec I (117502) NimBLE: GATT procedure initiated: notify; I (117502) NimBLE: att_handle=14 E (117522) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (117522) chip[DMG]: ICR moving to [CommandSen] E (117532) chip[DMG]: ICR moving to [AwaitingDe] E (117532) chip[DL]: Long dispatch time: 1524 ms, for event type 7 E (117532) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet I (117572) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (117572) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827440 on exchange 7850r E (117582) chip[EM]: Handling via exchange: 7850r, Delegate: 0x3ffcf4c8 E (117592) chip[DMG]: InvokeRequestMessage = E (117592) chip[DMG]: { E (117602) chip[DMG]: suppressResponse = false, E (117602) chip[DMG]: timedRequest = false, E (117612) chip[DMG]: InvokeRequests = E (117612) chip[DMG]: [ E (117612) chip[DMG]: CommandDataIB = E (117612) chip[DMG]: { E (117622) chip[DMG]: CommandPathIB = E (117632) chip[DMG]: { E (117632) chip[DMG]: EndpointId = 0x0, E (117642) chip[DMG]: ClusterId = 0x31, E (117642) chip[DMG]: CommandId = 0x2, E (117642) chip[DMG]: }, E (117652) chip[DMG]: E (117652) chip[DMG]: CommandData = E (117652) chip[DMG]: { E (117652) chip[DMG]: 0x0 = [ E (117672) chip[DMG]: 0x43, 0x61, 0x73, 0x61, 0x20, 0x4c, 0x69, 0x6d, E (117672) chip[DMG]: ] E (117682) chip[DMG]: 0x1 = [ E (117682) chip[DMG]: 0x43, 0x6f, 0x48, 0x61, 0x62, 0x5f, 0x31, 0x30, 0x32, 0x30, 0x21, E (117692) chip[DMG]: ] E (117692) chip[DMG]: 0x2 = 14, E (117692) chip[DMG]: }, E (117692) chip[DMG]: }, E (117702) chip[DMG]: E (117712) chip[DMG]: ], E (117712) chip[DMG]: E (117712) chip[DMG]: InteractionModelRevision = 1 E (117722) chip[DMG]: }, E (117722) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o E (117732) chip[DMG]: AccessControl: implicit admin (PASE) E (117732) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0002 E (117752) chip[DMG]: ICR moving to [ Preparing] E (117752) chip[DMG]: ICR moving to [AddingComm] E (117762) chip[DMG]: ICR moving to [AddedComma] E (117762) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (117772) chip[IN]: Prepared secure message 0x3ffe7094 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 7850r with MessageCounter:4919750. E (117792) chip[IN]: Sending encrypted msg 0x3ffe7094 with MessageCounter:4919750 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001C8AD msec I (117802) NimBLE: GATT procedure initiated: notify; I (117802) NimBLE: att_handle=14 E (117802) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (117822) chip[DMG]: ICR moving to [CommandSen] E (117822) chip[DMG]: ICR moving to [AwaitingDe] E (117832) chip[DL]: Long dispatch time: 262 ms, for event type 7 I (117872) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (117872) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4827441 on exchange 7851r E (117882) chip[EM]: Handling via exchange: 7851r, Delegate: 0x3ffcf4c8 E (117892) chip[DMG]: InvokeRequestMessage = E (117892) chip[DMG]: { E (117902) chip[DMG]: suppressResponse = false, E (117902) chip[DMG]: timedRequest = false, E (117912) chip[DMG]: InvokeRequests = E (117912) chip[DMG]: [ E (117912) chip[DMG]: CommandDataIB = E (117912) chip[DMG]: { E (117922) chip[DMG]: CommandPathIB = E (117932) chip[DMG]: { E (117932) chip[DMG]: EndpointId = 0x0, E (117942) chip[DMG]: ClusterId = 0x31, E (117942) chip[DMG]: CommandId = 0x6, E (117942) chip[DMG]: }, E (117952) chip[DMG]: E (117952) chip[DMG]: CommandData = E (117952) chip[DMG]: { E (117952) chip[DMG]: 0x0 = [ E (117972) chip[DMG]: 0x43, 0x61, 0x73, 0x61, 0x20, 0x4c, 0x69, 0x6d, E (117972) chip[DMG]: ] E (117982) chip[DMG]: 0x1 = 16, E (117982) chip[DMG]: }, E (117982) chip[DMG]: }, E (117982) chip[DMG]: E (117992) chip[DMG]: ], E (117992) chip[DMG]: E (117992) chip[DMG]: InteractionModelRevision = 1 E (118002) chip[DMG]: }, E (118012) chip[DMG]: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=o E (118012) chip[DMG]: AccessControl: implicit admin (PASE) E (118022) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 E (118032) chip[NP]: ESP NetworkCommissioningDelegate: SSID: Casa Lim E (118032) chip[DL]: WiFi station mode change: Enabled -> Disabled E (118062) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (118072) wifi:mode : sta (8c:aa:b5:80:4b:4c) + softAP (dc:83:e5:2f:a1:1a) I (118072) wifi:Total power save buffer number: 16 I (118082) wifi:Init max length of beacon: 752/752 I (118082) wifi:Init max length of beacon: 752/752 E (118092) chip[DL]: WiFi station mode change: Disabled -> Enabled E (118092) chip[DMG]: Decreasing reference count for CommandHandler, remaining 1 E (118102) chip[DL]: Long dispatch time: 233 ms, for event type 7 W (118102) wifi:Haven't to connect to a suitable AP now! E (118122) chip[DL]: Attempting to connect WiFi station interface E (118122) chip[DL]: WiFi station state change: NotConnected -> Connecting E (118122) chip[DL]: Done driving station state, nothing else to do... I (118132) wifi:new:<1,1>, old:<1,1>, ap:<1,1>, sta:<1,0>, prof:1 I (118902) wifi:state: init -> auth (b0) E (118902) chip[DL]: Done driving station state, nothing else to do... E (118912) chip[DL]: Long dispatch time: 771 ms, for event type 3 E (118912) chip[DL]: Done driving station state, nothing else to do... E (118922) chip[DL]: WIFI_EVENT_AP_START E (118922) chip[DL]: WiFi AP state change: NotActive -> Active E (118942) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (118942) wifi:mode : sta (8c:aa:b5:80:4b:4c) E (118952) chip[DL]: WiFi AP state change: Active -> Deactivating I (118952) app-devicecallbacks: Current free heap: 63168 I (118952) wifi:state: auth -> assoc (0) E (118962) chip[DL]: WIFI_EVENT_AP_STOP E (118972) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (118972) app-devicecallbacks: Current free heap: 64472 I (118972) wifi:state: assoc -> run (10) I (118992) wifi:connected with Casa Lim, aid = 1, channel 1, BW20, bssid = 4c:01:43:da:16:c6 I (119002) wifi:security: WPA2-PSK, phy: bgn, rssi: -24 I (119012) wifi:pm start, type: 1 E (119022) chip[DL]: WIFI_EVENT_STA_CONNECTED E (119022) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded W (119022) wifi:idx:0 (ifx:0, 4c:01:43:da:16:c6), tid:0, ssn:0, winSize:64 E (119042) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected E (119042) chip[DL]: WiFi station interface connected E (119052) chip[DMG]: ICR moving to [ Preparing] E (119052) chip[DMG]: ICR moving to [AddingComm] E (119062) chip[DMG]: ICR moving to [AddedComma] E (119062) chip[DL]: Using wifi MAC for hostname E (119062) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 I (119072) wifi:AP's beacon interval = 102400 us, DTIM period = 2 E (119082) chip[SVR]: Operational advertising enabled I (119082) app-devicecallbacks: Current free heap: 62544 E (119102) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (119102) chip[IN]: Prepared secure message 0x3ffe72a4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 7851r with MessageCounter:4919751. E (119112) chip[IN]: Sending encrypted msg 0x3ffe72a4 with MessageCounter:4919751 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001CDDA msec I (119132) NimBLE: GATT procedure initiated: notify; I (119142) NimBLE: att_handle=14 E (119142) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (119152) chip[DMG]: ICR moving to [CommandSen] E (119162) chip[DMG]: ICR moving to [AwaitingDe] E (119162) chip[DL]: Done driving station state, nothing else to do... I (119172) app-devicecallbacks: Current free heap: 62672 E (119172) chip[DL]: Long dispatch time: 153 ms, for event type 49152 E (119182) chip[DL]: Updating advertising data I (119192) app-devicecallbacks: Current free heap: 64192 I (119762) all-clusters-app: Display going to sleep... E (120102) chip[DL]: IP_EVENT_GOT_IP6 E (120102) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:8eaa:b5ff:fe80:4b4c I (120102) app-devicecallbacks: Current free heap: 64172 E (120122) chip[DIS]: Updating services using commissioning mode 0 E (120122) chip[DL]: Using wifi MAC for hostname E (120122) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 I (120142) app-devicecallbacks: Current free heap: 63528 I (121682) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (123102) esp_netif_handlers: sta ip: 192.168.7.145, mask: 255.255.252.0, gw: 192.168.4.1 E (123102) chip[DL]: IP_EVENT_STA_GOT_IP E (123102) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.7.145/255.255.252.0 gateway 192.168.4.1 E (123122) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (123132) app-devicecallbacks: Current free heap: 62348 I (123132) app-devicecallbacks: Server ready at: 192.168.7.145:5540 I (123142) all-clusters-app: Display awake but will switch off automatically in 30 seconds E (123152) chip[DIS]: Updating services using commissioning mode 0 E (123162) chip[DL]: Using wifi MAC for hostname E (123162) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 I (123192) app-devicecallbacks: Current free heap: 62316 E (123192) chip[DIS]: Updating services using commissioning mode 0 E (123192) chip[DL]: Using wifi MAC for hostname E (123202) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 I (123212) app-devicecallbacks: Current free heap: 62332 I (124182) NimBLE: GATT procedure initiated: notify; I (124182) NimBLE: att_handle=14 E (124182) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 E (124722) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:2296838081 on exchange 7852r E (124722) chip[EM]: Handling via exchange: 7852r, Delegate: 0x3ffc8ecc E (124732) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffca2a0 E (124742) chip[DIS]: CASE handshake initiated, closing all BLE Connections E (124742) chip[IN]: Clearing BLE pending packets. E (124762) chip[BLE]: Releasing end point's BLE connection back to application. E (124762) chip[SC]: Waiting for Sigma1 msg E (124762) chip[IN]: CASE Server disabling CASE session setups E (124772) chip[SC]: Received Sigma1 msg E (124772) chip[SC]: Found MRP parameters in the message E (124782) chip[SC]: Peer assigned session key ID 28760 E (124792) chip[SVR]: Retrieved from server storage: f/1/g E (124792) chip[SVR]: Retrieved from server storage: f/1/k/0 E (124802) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000001 I (126172) ROUTE_HOOK: Received RIO I (126172) ROUTE_HOOK: prefix FDB7:92FF:3249:: lifetime 1800 I (126352) ROUTE_HOOK: Received RIO I (126352) ROUTE_HOOK: prefix FD17:C208:4EDB:: lifetime 1800 I (126352) ROUTE_HOOK: Received RIO I (126352) ROUTE_HOOK: prefix FDE4:B950:2EE9:: lifetime 1800 E (126452) chip[SC]: Including MRP parameters E (126452) chip[EM]: Piggybacking Ack for MessageCounter:2296838081 on exchange: 7852r E (126452) chip[IN]: Prepared unauthenticated message 0x3ffca1bc to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 7852r with MessageCounter:430980897. E (126472) chip[IN]: Sending unauthenticated msg 0x3ffca1bc with MessageCounter:430980897 to 0x0000000000000000 at monotonic time: 000000000001EA93 msec E (126492) chip[SC]: Sent Sigma2 msg E (126492) chip[DL]: Long dispatch time: 1778 ms, for event type 3 E (126652) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:2296838082 on exchange 7852r E (126662) chip[EM]: Found matching exchange: 7852r, Delegate: 0x3ffc8ed8 E (126672) chip[EM]: Rxd Ack; Removing MessageCounter:430980897 from Retrans Table on exchange 7852r E (126672) chip[EM]: Removed CHIP MessageCounter:430980897 from RetransTable on exchange 7852r E (126682) chip[SC]: Received Sigma3 msg I (126742) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (128912) chip[SC]: Sending status report. Protocol code 0, exchange 7852 E (128912) chip[EM]: Piggybacking Ack for MessageCounter:2296838082 on exchange: 7852r E (128932) chip[IN]: Prepared unauthenticated message 0x3ffca1bc to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 7852r with MessageCounter:430980898. E (128942) chip[IN]: Sending unauthenticated msg 0x3ffca1bc with MessageCounter:430980898 to 0x0000000000000000 at monotonic time: 000000000001F43D msec E (128962) chip[IN]: CASE Session established. Setting up the secure channel. E (128962) chip[IN]: New secure session created for device 0x66EB004EF33EF74F, LSID:4522 PSID:28760! E (128972) chip[IN]: CASE secure channel is available now. E (128972) chip[IN]: CASE Server enabling CASE session setups E (128992) chip[DL]: Long dispatch time: 2336 ms, for event type 3 E (128992) chip[IN]: Clearing BLE pending packets. E (129002) chip[BLE]: Releasing end point's BLE connection back to application. E (129002) chip[BLE]: HandleChipConnectionReceived failed, err = d E (129012) chip[BLE]: failed handle new chip BLE connection, status = d E (129012) chip[DL]: IP_EVENT_GOT_IP6 E (129032) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fdb4:e776:c3de:4c6e:8eaa:b5ff:fe80:4b4c I (129032) app-devicecallbacks: Current free heap: 60012 E (129042) chip[DIS]: Updating services using commissioning mode 0 E (129042) chip[DL]: Using wifi MAC for hostname E (129052) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 I (129072) ROUTE_HOOK: Hook already installed on netif, skip... I (129072) app-devicecallbacks: Current free heap: 59876 E (129322) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:184182 on exchange 7853r E (129322) chip[EM]: Handling via exchange: 7853r, Delegate: 0x3ffcf4c8 E (129342) chip[DMG]: InvokeRequestMessage = E (129342) chip[DMG]: { E (129342) chip[DMG]: suppressResponse = false, E (129352) chip[DMG]: timedRequest = false, E (129352) chip[DMG]: InvokeRequests = E (129352) chip[DMG]: [ E (129362) chip[DMG]: CommandDataIB = E (129372) chip[DMG]: { E (129372) chip[DMG]: CommandPathIB = E (129382) chip[DMG]: { E (129382) chip[DMG]: EndpointId = 0x0, E (129382) chip[DMG]: ClusterId = 0x30, E (129382) chip[DMG]: CommandId = 0x4, E (129392) chip[DMG]: }, E (129392) chip[DMG]: E (129392) chip[DMG]: CommandData = E (129412) chip[DMG]: { E (129412) chip[DMG]: }, E (129412) chip[DMG]: }, E (129412) chip[DMG]: E (129422) chip[DMG]: ], E (129422) chip[DMG]: E (129422) chip[DMG]: InteractionModelRevision = 1 E (129422) chip[DMG]: }, E (129442) chip[DMG]: AccessControl: checking f=1 a=c s=0x66EB004EF33EF74F t= c=0x0000_0030 e=0 p=a E (129442) chip[DMG]: AccessControl: allowed E (129442) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 E (129462) chip[DL]: NVS set: chip-config/fail-safe-armed = false E (129472) chip[DMG]: ICR moving to [ Preparing] E (129472) chip[DMG]: ICR moving to [AddingComm] E (129472) chip[DMG]: ICR moving to [AddedComma] E (129482) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (129492) chip[EM]: Piggybacking Ack for MessageCounter:184182 on exchange: 7853r E (129502) chip[IN]: Prepared secure message 0x3ffca1d4 to 0x66EB004EF33EF74F (1) of type 0x9 and protocolId (0, 1) on exchange 7853r with MessageCounter:1014978. E (129522) chip[IN]: Sending encrypted msg 0x3ffca1d4 with MessageCounter:1014978 to 0x66EB004EF33EF74F (1) at monotonic time: 000000000001F67F msec E (129522) chip[DMG]: ICR moving to [CommandSen] E (129532) chip[DMG]: ICR moving to [AwaitingDe] E (129542) chip[DL]: Long dispatch time: 221 ms, for event type 3 E (129542) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2296838083 on exchange 7852r E (129552) chip[EM]: Found matching exchange: 7852r, Delegate: 0x0 E (129572) chip[EM]: Rxd Ack; Removing MessageCounter:430980898 from Retrans Table on exchange 7852r E (129572) chip[EM]: Removed CHIP MessageCounter:430980898 from RetransTable on exchange 7852r E (129582) chip[SVR]: Commissioning completed successfully E (129592) chip[DIS]: Updating services using commissioning mode 0 E (129592) chip[DL]: Using wifi MAC for hostname E (129602) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 E (129622) chip[ZCL]: Commissioning complete, notify platform driver to persist network credentials. I (129622) app-devicecallbacks: Commissioning complete I (129622) NimBLE: GAP procedure initiated: stop advertising. I (129642) NimBLE: GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19 E (129692) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0 E (129692) chip[DL]: CHIPoBLE unsubscribe received E (129702) chip[DL]: BLE GAP connection terminated (con 0 reason 0x216) W (129702) Timer: Timer not stopped I (129722) app-devicecallbacks: BLE deinit successful and memory reclaimed I (129722) app-devicecallbacks: Current free heap: 111720 E (129732) chip[DL]: Long dispatch time: 151 ms, for event type 32784 E (129732) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:184183 on exchange 7853r E (129752) chip[EM]: Found matching exchange: 7853r, Delegate: 0x0 E (129752) chip[EM]: Rxd Ack; Removing MessageCounter:1014978 from Retrans Table on exchange 7853r E (129762) chip[EM]: Removed CHIP MessageCounter:1014978 from RetransTable on exchange 7853r E (129772) chip[BLE]: no endpoint for unsub recvd I (129782) app-devicecallbacks: CHIPoBLE disconnected I (129782) app-devicecallbacks: Current free heap: 113620 I (131062) ROUTE_HOOK: Received RIO I (131062) ROUTE_HOOK: prefix FDB7:92FF:3249:: lifetime 1800 I (131472) ROUTE_HOOK: Received RIO I (131472) ROUTE_HOOK: prefix FD17:C208:4EDB:: lifetime 1800 I (131472) ROUTE_HOOK: Received RIO I (131482) ROUTE_HOOK: prefix FDE4:B950:2EE9:: lifetime 1800 E (134752) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:184184 on exchange 7854r E (134752) chip[EM]: Handling via exchange: 7854r, Delegate: 0x3ffcf4c8 E (134762) chip[DMG]: InvokeRequestMessage = E (134762) chip[DMG]: { E (134762) chip[DMG]: suppressResponse = false, E (134772) chip[DMG]: timedRequest = false, E (134782) chip[DMG]: InvokeRequests = E (134792) chip[DMG]: [ E (134792) chip[DMG]: CommandDataIB = E (134792) chip[DMG]: { E (134792) chip[DMG]: CommandPathIB = E (134802) chip[DMG]: { E (134802) chip[DMG]: EndpointId = 0x1, E (134802) chip[DMG]: ClusterId = 0x6, E (134812) chip[DMG]: CommandId = 0x1, E (134812) chip[DMG]: }, E (134822) chip[DMG]: E (134832) chip[DMG]: CommandData = E (134832) chip[DMG]: { E (134832) chip[DMG]: }, E (134842) chip[DMG]: }, E (134842) chip[DMG]: E (134842) chip[DMG]: ], E (134842) chip[DMG]: E (134852) chip[DMG]: InteractionModelRevision = 1 E (134852) chip[DMG]: }, E (134852) chip[DMG]: AccessControl: checking f=1 a=c s=0x66EB004EF33EF74F t= c=0x0000_0006 e=1 p=o E (134872) chip[DMG]: AccessControl: allowed E (134872) chip[DMG]: Received command for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0001 E (134882) chip[ZCL]: On/Off set value: 1 1 E (134882) chip[ZCL]: Toggle on/off from 0 to 1 E (134892) chip[ZCL]: On Command - OffWaitTime : 0 E (134892) chip[DMG]: Endpoint 1, Cluster 0x0000_0006 update version to e0627f2 I (134912) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002' I (134922) app-devicecallbacks: Unhandled Attribute ID: '0x4002 I (134922) app-devicecallbacks: Current free heap: 112636 E (134932) chip[ZCL]: On/Toggle Command - Stop Timer E (134932) chip[DMG]: Endpoint 1, Cluster 0x0000_0006 update version to e0627f3 I (134942) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000' I (134962) app-devicecallbacks: Unhandled Attribute ID: '0x4000 I (134962) app-devicecallbacks: Current free heap: 112636 E (134982) chip[DMG]: Endpoint 1, Cluster 0x0000_0006 update version to e0627f4 I (134982) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000' I (134992) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (135012) app-devicecallbacks: Current free heap: 112636 E (135022) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to fac791f5 I (135022) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (135032) app-devicecallbacks: Current free heap: 112636 E (135042) chip[DMG]: Endpoint 1, Cluster 0x0000_0005 update version to 524754c9 I (135052) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (135062) app-devicecallbacks: Unhandled cluster ID: 5 I (135072) app-devicecallbacks: Current free heap: 112636 E (135072) chip[DMG]: ICR moving to [ Preparing] E (135072) chip[DMG]: ICR moving to [AddingComm] E (135082) chip[DMG]: ICR moving to [AddedComma] E (135092) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (135102) chip[EM]: Piggybacking Ack for MessageCounter:184184 on exchange: 7854r E (135102) chip[IN]: Prepared secure message 0x3ffca1bc to 0x66EB004EF33EF74F (1) of type 0x9 and protocolId (0, 1) on exchange 7854r with MessageCounter:1014979. E (135122) chip[IN]: Sending encrypted msg 0x3ffca1bc with MessageCounter:1014979 to 0x66EB004EF33EF74F (1) at monotonic time: 0000000000020C66 msec E (135142) chip[DMG]: ICR moving to [CommandSen] E (135142) chip[DMG]: ICR moving to [AwaitingDe] E (135142) chip[DL]: Long dispatch time: 397 ms, for event type 3 I (135152) ROUTE_HOOK: Received RIO E (135152) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet I (135152) ROUTE_HOOK: prefix FDB7:92FF:3249:: lifetime 1800 E (135172) chip[ZCL]: Event: move from 1 E (135172) chip[ZCL]: to 254 E (135182) chip[ZCL]: (diff +1) E (135192) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to fac791f6 I (135192) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (135202) app-devicecallbacks: Current free heap: 112352 E (135212) chip[DMG]: Endpoint 1, Cluster 0x0000_0005 update version to 524754ca I (135222) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003' I (135232) app-devicecallbacks: Unhandled cluster ID: 5 I (135242) app-devicecallbacks: Current free heap: 112352 E (135242) chip[DMG]: Endpoint 1, Cluster 0x0000_0008 update version to fac791f7 I (135252) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001' I (135272) app-devicecallbacks: Unhandled Attribute ID: '0x0001 I (135272) app-devicecallbacks: Current free heap: 112352 E (135282) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:184185 on exchange 7854r E (135282) chip[EM]: Found matching exchange: 7854r, Delegate: 0x0 E (135292) chip[EM]: Rxd Ack; Removing MessageCounter:1014979 from Retrans Table on exchange 7854r E (135312) chip[EM]: Removed CHIP MessageCounter:1014979 from RetransTable on exchange 7854r E (135312) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet I (136182) ROUTE_HOOK: Received RIO I (136182) ROUTE_HOOK: prefix FDE4:B950:2EE9:: lifetime 1800 I (136182) ROUTE_HOOK: Received RIO I (136192) ROUTE_HOOK: prefix FD17:C208:4EDB:: lifetime 1800 E (137612) chip[EM]: Received message of type 0xa with protocolId (0, 1) and MessageCounter:184186 on exchange 7855r E (137622) chip[EM]: Handling via exchange: 7855r, Delegate: 0x3ffcf4c8 E (137632) chip[DMG]: TimedRequestMessage = E (137632) chip[DMG]: { E (137632) chip[DMG]: TimeoutMs = 0x2710, E (137642) chip[DMG]: InteractionModelRevision = 1 E (137642) chip[DMG]: } E (137642) chip[DMG]: Got Timed Request with timeout 10000: handler 0x3ffcf8b8 exchange 7855r E (137662) chip[EM]: Piggybacking Ack for MessageCounter:184186 on exchange: 7855r E (137672) chip[IN]: Prepared secure message 0x3ffca1bc to 0x66EB004EF33EF74F (1) of type 0x1 and protocolId (0, 1) on exchange 7855r with MessageCounter:1014980. E (137682) chip[IN]: Sending encrypted msg 0x3ffca1bc with MessageCounter:1014980 to 0x66EB004EF33EF74F (1) at monotonic time: 0000000000021665 msec E (137702) chip[DMG]: Timed Request time limit 0x0000000000023D84: handler 0x3ffcf8b8 exchange 7855r E (137712) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:184187 on exchange 7855r E (137722) chip[EM]: Found matching exchange: 7855r, Delegate: 0x3ffcf8b8 E (137732) chip[EM]: Rxd Ack; Removing MessageCounter:1014980 from Retrans Table on exchange 7855r E (137742) chip[EM]: Removed CHIP MessageCounter:1014980 from RetransTable on exchange 7855r E (137742) chip[DMG]: Timed following action arrived at 0x000000000002169F: handler 0x3ffcf8b8 exchange 7855r E (137752) chip[DMG]: Handing timed invoke to IM engine: handler 0x3ffcf8b8 exchange 7855r E (137772) chip[DMG]: InvokeRequestMessage = E (137772) chip[DMG]: { E (137772) chip[DMG]: suppressResponse = false, E (137782) chip[DMG]: timedRequest = true, E (137782) chip[DMG]: InvokeRequests = E (137792) chip[DMG]: [ E (137792) chip[DMG]: CommandDataIB = E (137792) chip[DMG]: { E (137792) chip[DMG]: CommandPathIB = E (137812) chip[DMG]: { E (137812) chip[DMG]: EndpointId = 0x0, E (137812) chip[DMG]: ClusterId = 0x3c, E (137822) chip[DMG]: CommandId = 0x0, E (137822) chip[DMG]: }, E (137822) chip[DMG]: E (137832) chip[DMG]: CommandData = E (137832) chip[DMG]: { E (137832) chip[DMG]: 0x0 = 900, E (137842) chip[DMG]: 0x1 = [ E (137852) chip[DMG]: 0xf4, 0x92, 0xfa, 0xaf, 0x33, 0x61, 0x71, 0x9d, 0x58, 0xb9, 0xab, 0x25, 0x25, 0xc8, 0xd, 0x79, 0x8f, 0x32, 0xf, 0x72, 0xf3, 0xb5, 0x77, 0x59, 0xc7, 0x9d, 0x72, 0xe4, 0xbb, 0x33, 0x9d, 0x2e, 0x4, 0xca, 0x8c, 0x8b, 0x50, 0xe0, 0x79, 0x3e, 0xd1, 0x23, 0 E (137872) chip[DMG]: ] E (137872) chip[DMG]: 0x2 = 3840, E (137872) chip[DMG]: 0x3 = 1000, E (137882) chip[DMG]: 0x4 = [ E (137882) chip[DMG]: 0x18, 0x97, 0x9f, 0x34, 0x4d, 0xb7, 0x7a, 0x7a, 0x1f, 0xa9, 0xd6, 0xd1, 0xc2, 0xa8, 0xd4, 0xfb, 0x88, 0x2a, 0x33, 0x94, 0x82, 0x20, 0x4, 0xe3, 0xca, 0xc9, 0x4c, 0xf4, 0xb3, 0xa0, 0xd1, 0xcc, E (137912) chip[DMG]: ] E (137912) chip[DMG]: }, E (137912) chip[DMG]: }, E (137912) chip[DMG]: E (137922) chip[DMG]: ], E (137922) chip[DMG]: E (137922) chip[DMG]: InteractionModelRevision = 1 E (137932) chip[DMG]: }, E (137942) chip[DMG]: AccessControl: checking f=1 a=c s=0x66EB004EF33EF74F t= c=0x0000_003C e=0 p=a E (137952) chip[DMG]: AccessControl: allowed E (137952) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 E (137962) chip[ZCL]: Received command to open commissioning window E (137962) chip[SC]: Assigned local session key ID 4523 E (137972) chip[SC]: Waiting for PBKDF param request I (137982) all-clusters-app: Display awake but will switch off automatically in 30 seconds E (137992) chip[DIS]: Updating services using commissioning mode 2 E (137992) chip[DL]: Using wifi MAC for hostname E (137992) chip[DIS]: Advertise operational node 4CC38A20E3FAA9D1-0000000000000001 E (138022) chip[DL]: Using wifi MAC for hostname E (138022) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 E (138042) chip[ZCL]: Commissioning window is now open E (138042) chip[DMG]: ICR moving to [ Preparing] E (138042) chip[DMG]: ICR moving to [AddingComm] E (138052) chip[DMG]: ICR moving to [AddedComma] E (138052) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 E (138062) chip[EM]: Piggybacking Ack for MessageCounter:184187 on exchange: 7855r E (138072) chip[IN]: Prepared secure message 0x3ffca1bc to 0x66EB004EF33EF74F (1) of type 0x9 and protocolId (0, 1) on exchange 7855r with MessageCounter:1014981. E (138082) chip[IN]: Sending encrypted msg 0x3ffca1bc with MessageCounter:1014981 to 0x66EB004EF33EF74F (1) at monotonic time: 00000000000217F1 msec E (138092) chip[DMG]: ICR moving to [CommandSen] E (138102) chip[DMG]: ICR moving to [AwaitingDe] E (138112) chip[DL]: Long dispatch time: 400 ms, for event type 3 E (138112) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:184188 on exchange 7855r E (138132) chip[EM]: Found matching exchange: 7855r, Delegate: 0x0 E (138132) chip[EM]: Rxd Ack; Removing MessageCounter:1014981 from Retrans Table on exchange 7855r E (138142) chip[EM]: Removed CHIP MessageCounter:1014981 from RetransTable on exchange 7855r I (139302) ROUTE_HOOK: Received RIO I (139302) ROUTE_HOOK: prefix FDB7:92FF:3249:: lifetime 1800 I (140482) ROUTE_HOOK: Received RIO I (140482) ROUTE_HOOK: prefix FDE4:B950:2EE9:: lifetime 1800 I (140482) ROUTE_HOOK: Received RIO I (140492) ROUTE_HOOK: prefix FD17:C208:4EDB:: lifetime 1800 I (167982) all-clusters-app: Display going to sleep... I (178772) ROUTE_HOOK: Received RIO I (178782) ROUTE_HOOK: prefix FD17:C208:4EDB:: lifetime 1800 I (234892) ROUTE_HOOK: Received RIO I (234892) ROUTE_HOOK: prefix FDB7:92FF:3249:: lifetime 1800