Executing action: flash Running ninja in directory /Users/ajaygantayet/Documents/Projects/Matter/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/connectedhomeip/examples/all-clusters-app/esp32/build/bootloader/esp-idf/esptool_py && /Users/ajaygantayet/Documents/Projects/Matter/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/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/connectedhomeip/examp...nectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.bin 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/es...ocuments/Projects/Matter/esp-idf/components/esptool_py/run_serial_tool.cmake esptool.py esp32c3 -p /dev/tty.usbserial-1110 -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-1110 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 11998... Writing at 0x00000000... (100 %) Wrote 19840 bytes (11998 compressed) at 0x00000000 in 0.6 seconds (effective 256.2 kbit/s)... Hash of data verified. Compressed 1278480 bytes to 749132... Writing at 0x00020000... (2 %) Writing at 0x0002dbbe... (4 %) Writing at 0x0003959e... (6 %) Writing at 0x00042be8... (8 %) Writing at 0x0004efd9... (10 %) Writing at 0x000586b7... (13 %) Writing at 0x0005df9a... (15 %) Writing at 0x00064280... (17 %) Writing at 0x0006b366... (19 %) Writing at 0x000710c7... (21 %) Writing at 0x00077404... (23 %) Writing at 0x0007dbe4... (26 %) Writing at 0x0008504e... (28 %) Writing at 0x0008ce64... (30 %) Writing at 0x00093517... (32 %) Writing at 0x00099609... (34 %) Writing at 0x0009f47e... (36 %) Writing at 0x000a5178... (39 %) Writing at 0x000ab242... (41 %) Writing at 0x000b0eee... (43 %) Writing at 0x000b73b3... (45 %) Writing at 0x000bda6e... (47 %) Writing at 0x000c3938... (50 %) Writing at 0x000c9a47... (52 %) Writing at 0x000d067b... (54 %) Writing at 0x000d6da5... (56 %) Writing at 0x000dceb2... (58 %) Writing at 0x000e3a80... (60 %) Writing at 0x000e93ed... (63 %) Writing at 0x000f02b6... (65 %) Writing at 0x000f6472... (67 %) Writing at 0x000fc48e... (69 %) Writing at 0x001025f9... (71 %) Writing at 0x0010820e... (73 %) Writing at 0x0010e537... (76 %) Writing at 0x0011422e... (78 %) Writing at 0x0011a3c0... (80 %) Writing at 0x00120a1d... (82 %) Writing at 0x00126f95... (84 %) Writing at 0x0012d2c2... (86 %) Writing at 0x00132990... (89 %) Writing at 0x00138b54... (91 %) Writing at 0x0013ebd3... (93 %) Writing at 0x0014544e... (95 %) Writing at 0x0014cac0... (97 %) Writing at 0x0015399e... (100 %) Wrote 1278480 bytes (749132 compressed) at 0x00020000 in 22.7 seconds (effective 450.9 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 346.2 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 568.6 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/connectedhomeip/examples/all-clusters-app/esp32 Executing "/Users/ajaygantayet/Documents/Projects/Matter/connectedhomeip/.environment/pigweed-venv/bin/python /Users/ajaygantayet/Documents/Projects/Matter/esp-idf/tools/idf_monitor.py -p /dev/tty.usbserial-1110 -b 115200 --toolchain-prefix riscv32-esp-elf- --target esp32c3 --decode-panic backtrace /Users/ajaygantayet/Documents/Projects/Matter/connectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.elf -m '/Users/ajaygantayet/Documents/Projects/Matter/connectedhomeip/.environment/pigweed-venv/bin/python' '/Users/ajaygantayet/Documents/Projects/Matter/esp-idf/tools/idf.py' '-p' '/dev/tty.usbserial-1110'"... --- WARNING: Serial ports accessed as /dev/tty.* will hang gdb if launched. --- Using /dev/cu.usbserial-1110 instead... --- idf_monitor on /dev/cu.usbserial-1110 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 17:17:10 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 (369) boot: Disabling RNG early entropy source... I (380) 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 (391) 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 17 2022 17:17:02 I (410) cpu_start: ELF file SHA256: eb3724b5fbeb9ac3... I (416) 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 (434) 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 (452) 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 (470) 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 (910) BTDM_INIT: Bluetooth MAC: 7c:df:a1:a4:9f:9e I (920) NimBLE: GAP procedure initiated: stop advertising. I (920) CHIP[DL]: BLE host-controller synced I (1420) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (1420) NimBLE: GAP procedure initiated: advertise; I (1430) NimBLE: disc_mode=2 I (1430) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (1440) NimBLE: I (1440) chip[DL]: CHIPoBLE advertising started E (1450) chip[DL]: Long dispatch time: 646 ms, for event type 2 I (1450) chip[DL]: Starting ESP WiFi layer I (1460) wifi:mode : sta (7c:df:a1:a4:9f:9c) I (1470) wifi:enable tsf W (1470) wifi:Haven't to connect to a suitable AP now! I (1470) 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 (1500) wifi:Haven't to connect to a suitable AP now! I (1510) 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 (1540) chip[ZCL]: Using ZAP configuration... I (1560) chip[ZCL]: Initiating Admin Commissioning cluster. I (1560) chip[ZCL]: Door Lock server initialized I (1560) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. I (1570) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001' I (1580) app-devicecallbacks: Current free heap: 119536 I (1590) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000' I (1610) app-devicecallbacks: Unhandled cluster ID: 4 I (1610) app-devicecallbacks: Current free heap: 119536 E (1620) chip[ZCL]: Trying to write invalid Calendar Type E (1620) chip[ZCL]: Failed to write calendar type with error: 0x87 I (1630) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1640) app-devicecallbacks: Current free heap: 119536 I (1640) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1650) app-devicecallbacks: Unhandled cluster ID: 4 I (1670) app-devicecallbacks: Current free heap: 119528 I (1670) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1680) app-devicecallbacks: Unhandled cluster ID: 5 I (1690) app-devicecallbacks: Current free heap: 119528 I (1690) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1700) app-devicecallbacks: Current free heap: 119500 I (1710) chip[ZCL]: Window Covering Cluster init I (1720) chip[ZCL]: Initialize PCC Server Cluster [EP:1] I (1730) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (1740) app-devicecallbacks: Unhandled AttributeId ID: '0x0007 I (1740) app-devicecallbacks: Current free heap: 119500 I (1750) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (1760) app-devicecallbacks: Unhandled AttributeId ID: '0x0008 I (1760) app-devicecallbacks: Current free heap: 119500 I (1770) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (1790) app-devicecallbacks: Unhandled AttributeId ID: '0x4001 I (1790) app-devicecallbacks: Current free heap: 119500 I (1800) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1810) app-devicecallbacks: Unhandled cluster ID: 1030 I (1810) app-devicecallbacks: Current free heap: 119500 I (1820) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1830) app-devicecallbacks: Unhandled cluster ID: 1030 I (1830) app-devicecallbacks: Current free heap: 119500 I (1850) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (1850) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (1860) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1870) app-devicecallbacks: Unhandled cluster ID: 1280 I (1880) app-devicecallbacks: Current free heap: 119500 I (1880) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1890) app-devicecallbacks: Unhandled cluster ID: 1280 I (1900) app-devicecallbacks: Current free heap: 119500 I (1910) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (1920) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000' I (1930) app-devicecallbacks: Unhandled cluster ID: 4 I (1930) app-devicecallbacks: Current free heap: 119500 I (1940) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (1950) app-devicecallbacks: Unhandled cluster ID: 1030 I (1950) app-devicecallbacks: Current free heap: 119500 I (1960) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (1980) app-devicecallbacks: Unhandled cluster ID: 1030 I (1980) app-devicecallbacks: Current free heap: 119500 I (1990) chip[DL]: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) I (1990) chip[DL]: NVS set: chip-counters/global-eidc = 65536 (0x10000) I (2010) chip[DIS]: CHIP minimal mDNS started advertising. I (2010) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown I (2020) chip[DIS]: Start dns-sd server - no current nodeId I (2020) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 I (2030) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (2050) chip[DIS]: mDNS service published: _matterc._udp I (2050) chip[IN]: CASE Server enabling CASE session setups I (2060) chip[SVR]: Adding Multicast groups I (2060) chip[SVR]: Server Listening... I (2060) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2070) app-devicecallbacks: Unhandled cluster ID: 1026 I (2080) app-devicecallbacks: Current free heap: 117476 I (2080) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2100) app-devicecallbacks: Unhandled cluster ID: 257 I (2110) app-devicecallbacks: Current free heap: 117356 I (2110) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2120) app-devicecallbacks: Unhandled cluster ID: 1030 I (2130) app-devicecallbacks: Current free heap: 116404 I (2130) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2140) app-devicecallbacks: Unhandled cluster ID: 69 I (2160) app-devicecallbacks: Current free heap: 116284 I (2160) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2170) app-devicecallbacks: Unhandled cluster ID: 1026 I (2180) app-devicecallbacks: Current free heap: 115924 I (2180) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2190) app-devicecallbacks: Unhandled cluster ID: 513 I (2200) app-devicecallbacks: Current free heap: 115924 I (2200) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c' I (2220) app-devicecallbacks: Unhandled cluster ID: 513 I (2230) app-devicecallbacks: Current free heap: 115876 I (2230) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011' I (2240) app-devicecallbacks: Unhandled cluster ID: 513 I (2250) app-devicecallbacks: Current free heap: 115796 I (2250) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012' I (2260) app-devicecallbacks: Unhandled cluster ID: 513 I (2280) app-devicecallbacks: Current free heap: 115676 I (2280) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2290) app-devicecallbacks: Unhandled cluster ID: 1029 I (2300) app-devicecallbacks: Current free heap: 115556 I (2300) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2310) app-devicecallbacks: Unhandled cluster ID: 1024 I (2320) app-devicecallbacks: Current free heap: 115400 E (2320) chip[DL]: Long dispatch time: 788 ms, for event type 2 I (2340) app-devicecallbacks: Current free heap: 115400 I (2340) 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 (2360) wifi:Haven't to connect to a suitable AP now! I (2380) chip[DL]: Done driving station state, nothing else to do... I (2380) app-devicecallbacks: Current free heap: 115400 I (2390) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2400) chip[DL]: Device already advertising, stop active advertisement and restart I (2410) NimBLE: GAP procedure initiated: stop advertising. I (2410) NimBLE: GAP procedure initiated: advertise; I (2420) NimBLE: disc_mode=2 I (2420) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2430) NimBLE: I (32010) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840) I (32010) chip[DL]: Device already advertising, stop active advertisement and restart I (32020) NimBLE: GAP procedure initiated: stop advertising. I (32030) NimBLE: GAP procedure initiated: advertise; I (32030) NimBLE: disc_mode=2 I (32030) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800 I (32040) NimBLE: I (68380) chip[DL]: BLE GAP connection established (con 1) I (68380) chip[DL]: CHIPoBLE advertising stopped I (68380) app-devicecallbacks: Current free heap: 115400 I (69300) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (69300) chip[BLE]: local and remote recv window sizes = 5 I (69310) chip[BLE]: selected BTP version 4 I (69310) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (69480) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 0 notify = 1 I (69480) chip[DL]: CHIPoBLE subscribe received I (69480) NimBLE: GATT procedure initiated: notify; I (69490) NimBLE: att_handle=14 I (69500) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (69500) app-devicecallbacks: CHIPoBLE connection established I (69520) app-devicecallbacks: Current free heap: 115400 I (69540) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (69540) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:3229576121 on exchange 46001r I (69550) chip[IN]: Prepared unauthenticated message 0x3fcb6b48 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 46001r with MessageCounter:868017161. I (69570) chip[IN]: Sending unauthenticated msg 0x3fcb6b48 with MessageCounter:868017161 to 0x0000000000000000 at monotonic time: 69572 msec I (69580) NimBLE: GATT procedure initiated: notify; I (69590) NimBLE: att_handle=14 I (69590) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (69660) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (69660) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:3229576122 on exchange 46001r I (70730) chip[IN]: Prepared unauthenticated message 0x3fcb6ab8 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 46001r with MessageCounter:868017162. I (70750) chip[IN]: Sending unauthenticated msg 0x3fcb6ab8 with MessageCounter:868017162 to 0x0000000000000000 at monotonic time: 70752 msec I (70760) NimBLE: GATT procedure initiated: notify; I (70760) NimBLE: att_handle=14 I (70770) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 E (70770) chip[DL]: Long dispatch time: 1114 ms, for event type 7 I (70860) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (70860) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:3229576123 on exchange 46001r I (70870) chip[IN]: Prepared unauthenticated message 0x3fcb6b48 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 46001r with MessageCounter:868017163. I (70890) chip[IN]: Sending unauthenticated msg 0x3fcb6b48 with MessageCounter:868017163 to 0x0000000000000000 at monotonic time: 70891 msec I (70900) NimBLE: GATT procedure initiated: notify; I (70910) NimBLE: att_handle=14 I (70910) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (70920) chip[SVR]: Commissioning completed session establishment step I (70930) chip[SVR]: Device completed Rendezvous process I (73440) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (75940) NimBLE: GATT procedure initiated: notify; I (75940) NimBLE: att_handle=14 I (75940) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (78480) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (80980) NimBLE: GATT procedure initiated: notify; I (80980) NimBLE: att_handle=14 I (80980) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (83520) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (86020) NimBLE: GATT procedure initiated: notify; I (86020) NimBLE: att_handle=14 I (86020) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (88560) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (91060) NimBLE: GATT procedure initiated: notify; I (91060) NimBLE: att_handle=14 I (91060) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (93600) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (96100) NimBLE: GATT procedure initiated: notify; I (96100) NimBLE: att_handle=14 I (96100) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (98640) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (101140) NimBLE: GATT procedure initiated: notify; I (101140) NimBLE: att_handle=14 I (101140) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (103680) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (106180) NimBLE: GATT procedure initiated: notify; I (106180) NimBLE: att_handle=14 I (106180) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (108720) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (111220) NimBLE: GATT procedure initiated: notify; I (111220) NimBLE: att_handle=14 I (111220) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (113760) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (116260) NimBLE: GATT procedure initiated: notify; I (116260) NimBLE: att_handle=14 I (116260) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (118800) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (121300) NimBLE: GATT procedure initiated: notify; I (121300) NimBLE: att_handle=14 I (121300) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (123840) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (126340) NimBLE: GATT procedure initiated: notify; I (126340) NimBLE: att_handle=14 I (126340) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (128880) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (131380) NimBLE: GATT procedure initiated: notify; I (131380) NimBLE: att_handle=14 I (131380) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (133920) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (136420) NimBLE: GATT procedure initiated: notify; I (136420) NimBLE: att_handle=14 I (136420) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (138960) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (141460) NimBLE: GATT procedure initiated: notify; I (141460) NimBLE: att_handle=14 I (141460) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (144000) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (146500) NimBLE: GATT procedure initiated: notify; I (146500) NimBLE: att_handle=14 I (146500) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (149040) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (151540) NimBLE: GATT procedure initiated: notify; I (151540) NimBLE: att_handle=14 I (151540) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (154080) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (156580) NimBLE: GATT procedure initiated: notify; I (156580) NimBLE: att_handle=14 I (156580) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (159120) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (161620) NimBLE: GATT procedure initiated: notify; I (161620) NimBLE: att_handle=14 I (161620) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (164160) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (166660) NimBLE: GATT procedure initiated: notify; I (166660) NimBLE: att_handle=14 I (166660) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (169200) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12 I (171700) NimBLE: GATT procedure initiated: notify; I (171700) NimBLE: att_handle=14 I (171700) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 0 I (174240) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 12