Executing action: flash Running ninja in directory /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/examples/all-clusters-app/esp32/build Executing "ninja flash"... [1/10] Performing build step for 'chip_gn' ninja: no work to do. [2/6] Performing build step for 'bootloader' [1/1] cd /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/examples/all-clusters-app/esp32/build/bootloader/esp-idf/esptool_py && /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/.environment/pigweed-venv/bin/python /Users/ajaygantayet/Documents/Projects/Matter/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 bootloader 0x0 /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/examples/all-clusters-app/esp32/build/bootloader/bootloader.bin Bootloader binary size 0x4d80 bytes. 0x3280 bytes (39%) free. [3/4] cd /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/ex...nnectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.bi chip-all-clusters-app.bin binary size 0x138210 bytes. Smallest app partition is 0x177000 bytes. 0x3edf0 bytes (17%) free. [3/4] cd /Users/ajaygantayet/Documents/Projects/Matter/esp-idf/components/esp...Documents/Projects/Matter/esp-idf/components/esptool_py/run_serial_tool.cmak esptool.py esp32c3 -p /dev/tty.usbserial-110 -b 460800 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 80m --flash_size 4MB 0x0 bootloader/bootloader.bin 0x20000 chip-all-clusters-app.bin 0x8000 partition_table/partition-table.bin 0xf000 ota_data_initial.bin esptool.py v3.2-dev Serial port /dev/tty.usbserial-110 Connecting.... Chip is ESP32-C3 (revision 3) Features: Wi-Fi Crystal is 40MHz MAC: 7c:df:a1:a4:9f:9c Uploading stub... Running stub... Stub running... Changing baud rate to 460800 Changed. Configuring flash size... Flash will be erased from 0x00000000 to 0x00004fff... Flash will be erased from 0x00020000 to 0x00158fff... Flash will be erased from 0x00008000 to 0x00008fff... Flash will be erased from 0x0000f000 to 0x00010fff... Compressed 19840 bytes to 12000... Writing at 0x00000000... (100 %) Wrote 19840 bytes (12000 compressed) at 0x00000000 in 0.6 seconds (effective 258.9 kbit/s)... Hash of data verified. Compressed 1278480 bytes to 749130... Writing at 0x00020000... (2 %) Writing at 0x0002dbcf... (4 %) Writing at 0x0003959f... (6 %) Writing at 0x00042bea... (8 %) Writing at 0x0004efe9... (10 %) Writing at 0x000586b8... (13 %) Writing at 0x0005df9d... (15 %) Writing at 0x00064282... (17 %) Writing at 0x0006b36a... (19 %) Writing at 0x000710c8... (21 %) Writing at 0x00077409... (23 %) Writing at 0x0007dbe5... (26 %) Writing at 0x00085055... (28 %) Writing at 0x0008ce68... (30 %) Writing at 0x0009351b... (32 %) Writing at 0x0009960b... (34 %) Writing at 0x0009f488... (36 %) Writing at 0x000a5178... (39 %) Writing at 0x000ab242... (41 %) Writing at 0x000b0ef2... (43 %) Writing at 0x000b73b4... (45 %) Writing at 0x000bda70... (47 %) Writing at 0x000c393b... (50 %) Writing at 0x000c9a48... (52 %) Writing at 0x000d067b... (54 %) Writing at 0x000d6da6... (56 %) Writing at 0x000dceb4... (58 %) Writing at 0x000e3a82... (60 %) Writing at 0x000e93ef... (63 %) Writing at 0x000f02b6... (65 %) Writing at 0x000f6472... (67 %) Writing at 0x000fc4a0... (69 %) Writing at 0x001025f9... (71 %) Writing at 0x0010820e... (73 %) Writing at 0x0010e539... (76 %) Writing at 0x0011422e... (78 %) Writing at 0x0011a3ca... (80 %) Writing at 0x00120a1e... (82 %) Writing at 0x00126f97... (84 %) Writing at 0x0012d2c4... (86 %) Writing at 0x00132991... (89 %) Writing at 0x00138b58... (91 %) Writing at 0x0013ebd5... (93 %) Writing at 0x00145450... (95 %) Writing at 0x0014cac2... (97 %) Writing at 0x001539a4... (100 %) Wrote 1278480 bytes (749130 compressed) at 0x00020000 in 22.6 seconds (effective 451.7 kbit/s)... Hash of data verified. Compressed 3072 bytes to 144... Writing at 0x00008000... (100 %) Wrote 3072 bytes (144 compressed) at 0x00008000 in 0.1 seconds (effective 354.3 kbit/s)... Hash of data verified. Compressed 8192 bytes to 31... Writing at 0x0000f000... (100 %) Wrote 8192 bytes (31 compressed) at 0x0000f000 in 0.1 seconds (effective 582.9 kbit/s)... Hash of data verified. Leaving... Hard resetting via RTS pin... Executing action: monitor Running idf_monitor in directory /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/examples/all-clusters-app/esp32 Executing "/Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/.environment/pigweed-venv/bin/python /Users/ajaygantayet/Documents/Projects/Matter/esp-idf/tools/idf_monitor.py -p /dev/tty.usbserial-110 -b 115200 --toolchain-prefix riscv32-esp-elf- --target esp32c3 --decode-panic backtrace /Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.elf -m '/Users/ajaygantayet/Documents/Projects/Matter/new/connectedhomeip/.environment/pigweed-venv/bin/python' '/Users/ajaygantayet/Documents/Projects/Matter/esp-idf/tools/idf.py' '-p' '/dev/tty.usbserial-110'"... --- WARNING: Serial ports accessed as /dev/tty.* will hang gdb if launched. --- Using /dev/cu.usbserial-110 instead... --- idf_monitor on /dev/cu.usbserial-110 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ESP-ROM:esp32c3-api1-20210207 Build:Feb 7 2021 rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fcd6100,len:0x16b4 load:0x403ce000,len:0x930 load:0x403d0000,len:0x2d40 entry 0x403ce000 I (30) boot: ESP-IDF v4.4 2nd stage bootloader I (30) boot: compile time 13:04:55 I (30) boot: chip revision: 3 I (32) boot.esp32c3: SPI Speed : 80MHz I (36) boot.esp32c3: SPI Mode : DIO I (41) boot.esp32c3: SPI Flash Size : 4MB I (46) boot: Enabling RNG early entropy source... I (51) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (70) boot: 1 otadata OTA data 01 00 0000f000 00002000 I (77) boot: 2 phy_init RF data 01 01 00011000 00001000 I (85) boot: 3 ota_0 OTA app 00 10 00020000 00177000 I (92) boot: 4 ota_1 OTA app 00 11 001a0000 00177000 I (99) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000 I (107) boot: End of partition table I (111) boot: No factory image, trying OTA 0 I (116) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=33608h (210440) map I (158) esp_image: segment 1: paddr=00053630 vaddr=3fc8f800 size=03804h ( 14340) load I (160) esp_image: segment 2: paddr=00056e3c vaddr=40380000 size=091dch ( 37340) load I (170) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=f1d7ch (990588) map I (327) esp_image: segment 4: paddr=00151da4 vaddr=403891dc size=0642ch ( 25644) load I (332) esp_image: segment 5: paddr=001581d8 vaddr=50000010 size=00010h ( 16) load I (337) boot: Loaded app from partition at offset 0x20000 I (369) boot: Set actual ota_seq=1 in otadata[0] I (370) boot: Disabling RNG early entropy source... I (381) cpu_start: Pro cpu up. I (389) cpu_start: Pro cpu start user code I (389) cpu_start: cpu freq: 160000000 I (389) cpu_start: Application information: I (392) cpu_start: Project name: chip-all-clusters-app I (398) cpu_start: App version: TE8/rc2-53-gb03bc9fb0-dirty I (404) cpu_start: Compile time: Feb 19 2022 13:04:42 I (411) cpu_start: ELF file SHA256: 447f090f42829208... I (417) cpu_start: ESP-IDF: v4.4 I (421) heap_init: Initializing. RAM available for dynamic allocation: I (428) heap_init: At 3FCA44B0 len 0001BB50 (110 KiB): DRAM I (435) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM I (441) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM I (448) spi_flash: detected chip: generic I (453) spi_flash: flash io: dio I (458) sleep: Configure to isolate all GPIO pins in sleep state I (463) sleep: Enable automatic switching of GPIO sleep configuration I (471) coexist: coexist rom version 9387209 I (475) cpu_start: Starting scheduler. I (480) all-clusters-app: All Clusters Demo! I (480) all-clusters-app: This is ESP32 chip with 1 CPU cores, WiFi/BLE, I (490) all-clusters-app: silicon revision 3, I (490) all-clusters-app: 4MB external flash I (660) pp: pp rom version: 9387209 I (660) net80211: net80211 rom version: 9387209 I (670) wifi:wifi driver task: 3fcaf480, prio:23, stack:6656, core=0 I (670) system_api: Base MAC address is not set I (680) system_api: read default base MAC address from EFUSE I (680) wifi:wifi firmware version: 7679c42 I (680) wifi:wifi certification version: v7.0 I (690) wifi:config NVS flash: enabled I (690) wifi:config nano formating: disabled I (690) wifi:Init data frame dynamic rx buffer num: 32 I (700) wifi:Init management frame dynamic rx buffer num: 32 I (700) wifi:Init management short buffer num: 32 I (700) wifi:Init dynamic tx buffer num: 32 I (710) wifi:Init static tx FG buffer num: 2 I (720) wifi:Init static rx buffer size: 1600 I (720) wifi:Init static rx buffer num: 10 I (730) wifi:Init dynamic rx buffer num: 32 I (740) wifi_init: rx ba win: 6 I (740) wifi_init: tcpip mbox: 32 I (740) wifi_init: udp mbox: 6 I (740) wifi_init: tcp mbox: 6 I (750) wifi_init: tcp tx win: 5744 I (750) wifi_init: tcp rx win: 5744 I (750) wifi_init: tcp mss: 1440 I (750) wifi_init: WiFi IRAM OP enabled > I (770) wifi_init: WiFi RX IRAM OP enabled I (780) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1) I (780) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0) I (780) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP I (790) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (790) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (800) chip[SVR]: SetupQRCode: [MT:-24J042C00KA0648G00] I (810) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code: I (820) chip[SVR]: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00 I (830) chip[SVR]: Manual pairing code: [34970112332] I (830) chip[SVR]: Long manual pairing code: [749701123365521327694] W (810) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK I (840) BTDM_INIT: BT controller compile version [6881869] I (850) phy_init: phy_version 907,3369105-dirty,Dec 3 2021,14:55:12 W (860) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration I (930) BTDM_INIT: Bluetooth MAC: 7c:df:a1:a4:9f:9e I (930) NimBLE: GAP procedure initiated: stop advertising. I (930) CHIP[DL]: BLE host-controller synced I (1440) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (1440) NimBLE: GAP procedure initiated: advertise; I (1450) NimBLE: disc_mode=2 I (1450) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (1460) NimBLE: I (1460) chip[DL]: CHIPoBLE advertising started E (1470) chip[DL]: Long dispatch time: 666 ms, for event type 2 I (1470) chip[DL]: Starting ESP WiFi layer I (1480) wifi:mode : sta (7c:df:a1:a4:9f:9c) I (1490) wifi:enable tsf W (1490) wifi:Haven't to connect to a suitable AP now! I (1490) chip[DL]: Done driving station state, nothing else to do... chan:1,max_power:80 chan:2,max_power:80 chan:3,max_power:80 chan:4,max_power:80 chan:5,max_power:80 chan:6,max_power:80 chan:7,max_power:80 chan:8,max_power:80 chan:9,max_power:80 chan:10,max_power:80 chan:11,max_power:80 chan:12,max_power:80 chan:13,max_power:80 chan:14,max_power:80 W (1520) wifi:Haven't to connect to a suitable AP now! I (1530) chip[DL]: Done driving station state, nothing else to do... chan:1,max_power:80 chan:2,max_power:80 chan:3,max_power:80 chan:4,max_power:80 chan:5,max_power:80 chan:6,max_power:80 chan:7,max_power:80 chan:8,max_power:80 chan:9,max_power:80 chan:10,max_power:80 chan:11,max_power:80 chan:12,max_power:80 chan:13,max_power:80 chan:14,max_power:80 I (1560) chip[ZCL]: Using ZAP configuration... I (1580) chip[ZCL]: Initiating Admin Commissioning cluster. I (1580) chip[ZCL]: Door Lock server initialized I (1580) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. I (1590) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (1600) app-devicecallbacks: Current free heap: 119536 I (1610) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (1630) app-devicecallbacks: Unhandled cluster ID: 4 I (1630) app-devicecallbacks: Current free heap: 119536 E (1640) chip[ZCL]: Trying to write invalid Calendar Type E (1640) chip[ZCL]: Failed to write calendar type with error: 0x87 I (1650) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1660) app-devicecallbacks: Current free heap: 119528 I (1660) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1670) app-devicecallbacks: Unhandled cluster ID: 4 I (1690) app-devicecallbacks: Current free heap: 119528 I (1690) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1700) app-devicecallbacks: Unhandled cluster ID: 5 I (1710) app-devicecallbacks: Current free heap: 119528 I (1710) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1720) app-devicecallbacks: Current free heap: 119500 I (1740) chip[ZCL]: Window Covering Cluster init I (1740) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (1750) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (1760) app-devicecallbacks: Unhandled AttributeId ID: '0x0007 I (1760) app-devicecallbacks: Current free heap: 119500 I (1770) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (1780) app-devicecallbacks: Unhandled AttributeId ID: '0x0008 I (1780) app-devicecallbacks: Current free heap: 119500 I (1790) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (1810) app-devicecallbacks: Unhandled AttributeId ID: '0x4001 I (1810) app-devicecallbacks: Current free heap: 119500 I (1820) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1830) app-devicecallbacks: Unhandled cluster ID: 1030 I (1830) app-devicecallbacks: Current free heap: 119500 I (1840) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1850) app-devicecallbacks: Unhandled cluster ID: 1030 I (1850) app-devicecallbacks: Current free heap: 119500 I (1870) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (1870) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (1880) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1890) app-devicecallbacks: Unhandled cluster ID: 1280 I (1900) app-devicecallbacks: Current free heap: 119500 I (1900) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1910) app-devicecallbacks: Unhandled cluster ID: 1280 I (1920) app-devicecallbacks: Current free heap: 119500 I (1930) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (1940) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (1950) app-devicecallbacks: Unhandled cluster ID: 4 I (1950) app-devicecallbacks: Current free heap: 119500 I (1960) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (1970) app-devicecallbacks: Unhandled cluster ID: 1030 I (1970) app-devicecallbacks: Current free heap: 119500 I (1980) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (2000) app-devicecallbacks: Unhandled cluster ID: 1030 I (2000) app-devicecallbacks: Current free heap: 119500 I (2010) chip[DL]: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) I (2010) chip[DL]: NVS set: chip-counters/global-eidc = 65536 (0x10000) I (2030) chip[DIS]: CHIP minimal mDNS started advertising. I (2030) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown I (2040) chip[DIS]: Start dns-sd server - no current nodeId I (2040) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (2050) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (2070) chip[DIS]: mDNS service published: _matterc._udp I (2070) chip[IN]: CASE Server enabling CASE session setups I (2080) chip[SVR]: Adding Multicast groups I (2080) chip[SVR]: Server Listening... I (2080) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2090) app-devicecallbacks: Unhandled cluster ID: 1026 I (2100) app-devicecallbacks: Current free heap: 117476 I (2110) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2120) app-devicecallbacks: Unhandled cluster ID: 257 I (2130) app-devicecallbacks: Current free heap: 117356 I (2130) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2140) app-devicecallbacks: Unhandled cluster ID: 1030 I (2150) app-devicecallbacks: Current free heap: 116404 I (2150) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2170) app-devicecallbacks: Unhandled cluster ID: 69 I (2180) app-devicecallbacks: Current free heap: 116284 I (2180) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2190) app-devicecallbacks: Unhandled cluster ID: 1026 I (2200) app-devicecallbacks: Current free heap: 115924 I (2200) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2210) app-devicecallbacks: Unhandled cluster ID: 513 I (2220) app-devicecallbacks: Current free heap: 115924 I (2220) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (2240) app-devicecallbacks: Unhandled cluster ID: 513 I (2250) app-devicecallbacks: Current free heap: 115876 I (2250) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011' I (2260) app-devicecallbacks: Unhandled cluster ID: 513 I (2270) app-devicecallbacks: Current free heap: 115796 I (2270) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012' I (2280) app-devicecallbacks: Unhandled cluster ID: 513 I (2300) app-devicecallbacks: Current free heap: 115676 I (2300) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2310) app-devicecallbacks: Unhandled cluster ID: 1029 I (2320) app-devicecallbacks: Current free heap: 115556 I (2320) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2330) app-devicecallbacks: Unhandled cluster ID: 1024 I (2340) app-devicecallbacks: Current free heap: 115400 E (2340) chip[DL]: Long dispatch time: 788 ms, for event type 2 I (2360) app-devicecallbacks: Current free heap: 115400 I (2360) chip[DL]: WIFI_EVENT_STA_START chan:1,max_power:80 chan:2,max_power:80 chan:3,max_power:80 chan:4,max_power:80 chan:5,max_power:80 chan:6,max_power:80 chan:7,max_power:80 chan:8,max_power:80 chan:9,max_power:80 chan:10,max_power:80 chan:11,max_power:80 chan:12,max_power:80 chan:13,max_power:80 chan:14,max_power:80 W (2380) wifi:Haven't to connect to a suitable AP now! I (2400) chip[DL]: Done driving station state, nothing else to do... I (2400) app-devicecallbacks: Current free heap: 115400 I (2410) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2420) chip[DL]: Device already advertising, stop active advertisement and restart I (2430) NimBLE: GAP procedure initiated: stop advertising. I (2430) NimBLE: GAP procedure initiated: advertise; I (2440) NimBLE: disc_mode=2 I (2440) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2460) NimBLE: I (32030) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840) I (32030) chip[DL]: Device already advertising, stop active advertisement and restart I (32040) NimBLE: GAP procedure initiated: stop advertising. I (32050) NimBLE: GAP procedure initiated: advertise; I (32050) NimBLE: disc_mode=2 I (32050) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800 I (32060) NimBLE: I (71960) chip[DL]: BLE GAP connection established (con 1) I (71960) chip[DL]: CHIPoBLE advertising stopped I (71960) app-devicecallbacks: Current free heap: 115400 I (72890) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (72890) chip[BLE]: local and remote recv window sizes = 5 I (72900) chip[BLE]: selected BTP version 4 I (72910) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (73070) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 notify = 1 I (73070) chip[DL]: CHIPoBLE subscribe received I (73070) NimBLE: GATT procedure initiated: notify; I (73090) NimBLE: att_handle=14 I (73100) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (73100) app-devicecallbacks: CHIPoBLE connection established I (73110) app-devicecallbacks: Current free heap: 115400 I (73160) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (73160) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:3736839576 on exchange 11584r I (73180) chip[IN]: Prepared unauthenticated message 0x3fcb6b48 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 11584r with MessageCounter:2686964540. I (73190) chip[IN]: Sending unauthenticated msg 0x3fcb6b48 with MessageCounter:2686964540 to 0x0000000000000000 at monotonic time: 73196 msec I (73200) NimBLE: GATT procedure initiated: notify; I (73220) NimBLE: att_handle=14 I (73220) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (73280) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (73280) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:3736839577 on exchange 11584r I (74360) chip[IN]: Prepared unauthenticated message 0x3fcb6ab8 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 11584r with MessageCounter:2686964541. I (74380) chip[IN]: Sending unauthenticated msg 0x3fcb6ab8 with MessageCounter:2686964541 to 0x0000000000000000 at monotonic time: 74382 msec I (74390) NimBLE: GATT procedure initiated: notify; I (74390) NimBLE: att_handle=14 I (74400) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 E (74410) chip[DL]: Long dispatch time: 1130 ms, for event type 7 I (74480) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (74480) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:3736839578 on exchange 11584r I (74500) chip[IN]: Prepared unauthenticated message 0x3fcb6b48 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 11584r with MessageCounter:2686964542. I (74510) chip[IN]: Sending unauthenticated msg 0x3fcb6b48 with MessageCounter:2686964542 to 0x0000000000000000 at monotonic time: 74515 msec I (74520) NimBLE: GATT procedure initiated: notify; I (74530) NimBLE: att_handle=14 I (74530) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (74550) chip[SVR]: Commissioning completed session establishment step I (74550) chip[SVR]: Device completed Rendezvous process I (78770) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (81270) NimBLE: GATT procedure initiated: notify; I (81270) NimBLE: att_handle=14 I (81280) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (83810) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (86310) NimBLE: GATT procedure initiated: notify; I (86310) NimBLE: att_handle=14 I (86320) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (88850) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (91350) NimBLE: GATT procedure initiated: notify; I (91360) NimBLE: att_handle=14 I (91360) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (93900) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (96410) NimBLE: GATT procedure initiated: notify; I (96410) NimBLE: att_handle=14 I (96410) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (98940) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (101450) NimBLE: GATT procedure initiated: notify; I (101450) NimBLE: att_handle=14 I (101450) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (103980) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (106490) NimBLE: GATT procedure initiated: notify; I (106490) NimBLE: att_handle=14 I (106490) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (109020) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (111530) NimBLE: GATT procedure initiated: notify; I (111530) NimBLE: att_handle=14 I (111530) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (114090) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (116600) NimBLE: GATT procedure initiated: notify; I (116600) NimBLE: att_handle=14 I (116600) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (119130) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (121640) NimBLE: GATT procedure initiated: notify; I (121640) NimBLE: att_handle=14 I (121640) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0