esptool.py v3.3-dev Serial port /dev/cu.usbserial-14430 Connecting.... Chip is ESP32-D0WD-V3 (revision 3) Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None Crystal is 40MHz MAC: c4:dd:57:5b:f6:d4 Uploading stub... Running stub... Stub running... Changing baud rate to 460800 Changed. Erasing flash (this may take a while)... Chip erase completed successfully in 15.4s Hard resetting via RTS pin... [1/10] Performing build step for 'chip_gn' ninja: no work to do. [2/6] Performing build step for 'bootloader' [1/1] cd /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/bootloader/esp-idf/esptool_py && /Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python /Users/rohitjadhav/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 bootloader 0x1000 /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/bootloader/bootloader.bin Bootloader binary size 0x62c0 bytes. 0xd40 bytes (12%) free. [3/4] cd /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/esp-idf/esptool_py && /Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python /Users/rohitjadhav/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 partition --type app /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/partition_table/partition-table.bin /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/chip-ota-requestor-app.bin chip-ota-requestor-app.bin binary size 0x123b50 bytes. Smallest app partition is 0x17d000 bytes. 0x594b0 bytes (23%) free. [3/4] cd /Users/rohitjadhav/esp-idf/components/esptool_py && /Users/rohitjadhav/connectedhomeip/.environment/cipd/packages/python/bin/cmake -D IDF_PATH="/Users/rohitjadhav/esp-idf" -D SERIAL_TOOL="/Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python /Users/rohitjadhav/esp-idf/components/esptool_py/esptool/esptool.py --chip esp32" -D SERIAL_TOOL_ARGS="--before=default_reset --after=hard_reset write_flash @flash_args" -D WORKING_DIRECTORY="/Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build" -P /Users/rohitjadhav/esp-idf/components/esptool_py/run_serial_tool.cmake esptool.py esp32 -p /dev/cu.usbserial-14430 -b 460800 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 40m --flash_size 4MB 0x1000 bootloader/bootloader.bin 0x20000 chip-ota-requestor-app.bin 0x8000 partition_table/partition-table.bin 0xf000 ota_data_initial.bin esptool.py v3.3-dev Serial port /dev/cu.usbserial-14430 Connecting............ Chip is ESP32-D0WD-V3 (revision 3) Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None Crystal is 40MHz MAC: c4:dd:57:5b:f6:d4 Uploading stub... Running stub... Stub running... Changing baud rate to 460800 Changed. Configuring flash size... Flash will be erased from 0x00001000 to 0x00007fff... Flash will be erased from 0x00020000 to 0x00143fff... Flash will be erased from 0x00008000 to 0x00008fff... Flash will be erased from 0x0000f000 to 0x00010fff... Compressed 25280 bytes to 15806... Writing at 0x00001000... (100 %) Wrote 25280 bytes (15806 compressed) at 0x00001000 in 0.8 seconds (effective 247.6 kbit/s)... Hash of data verified. Compressed 1194832 bytes to 775182... Writing at 0x00020000... (2 %) Writing at 0x0002a7c2... (4 %) Writing at 0x0003493b... (6 %) Writing at 0x000404f9... (8 %) Writing at 0x0004df3a... (10 %) Writing at 0x00055183... (12 %) Writing at 0x0005a34f... (14 %) Writing at 0x0005fade... (16 %) Writing at 0x0006580c... (18 %) Writing at 0x0006b475... (20 %) Writing at 0x0007080d... (22 %) Writing at 0x0007602d... (25 %) Writing at 0x0007bead... (27 %) Writing at 0x000821fe... (29 %) Writing at 0x00087ecd... (31 %) Writing at 0x0008db10... (33 %) Writing at 0x00093a9f... (35 %) Writing at 0x000991c1... (37 %) Writing at 0x0009e5d9... (39 %) Writing at 0x000a38f0... (41 %) Writing at 0x000a8e01... (43 %) Writing at 0x000ae1b7... (45 %) Writing at 0x000b3940... (47 %) Writing at 0x000b92d8... (50 %) Writing at 0x000bee56... (52 %) Writing at 0x000c4450... (54 %) Writing at 0x000c99fb... (56 %) Writing at 0x000cf285... (58 %) Writing at 0x000d42ba... (60 %) Writing at 0x000d92ee... (62 %) Writing at 0x000de2bb... (64 %) Writing at 0x000e3861... (66 %) Writing at 0x000e89b6... (68 %) Writing at 0x000edd78... (70 %) Writing at 0x000f3192... (72 %) Writing at 0x000f86c1... (75 %) Writing at 0x000fdf89... (77 %) Writing at 0x0010386e... (79 %) Writing at 0x001088ed... (81 %) Writing at 0x0010e2dd... (83 %) Writing at 0x00114c3f... (85 %) Writing at 0x0011f022... (87 %) Writing at 0x001254dc... (89 %) Writing at 0x0012c0ff... (91 %) Writing at 0x00131abe... (93 %) Writing at 0x00137345... (95 %) Writing at 0x0013cba2... (97 %) Writing at 0x00141da5... (100 %) Wrote 1194832 bytes (775182 compressed) at 0x00020000 in 19.0 seconds (effective 503.6 kbit/s)... Hash of data verified. Compressed 3072 bytes to 129... Writing at 0x00008000... (100 %) Wrote 3072 bytes (129 compressed) at 0x00008000 in 0.1 seconds (effective 351.5 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 593.4 kbit/s)... Hash of data verified. Leaving... Hard resetting via RTS pin... ets Jul 29 2019 12:21:46 rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:6608 load:0x40078000,len:14788 ho 0 tail 12 room 4 load:0x40080400,len:3792 entry 0x40080694 I (29) boot: ESP-IDF v4.4.1 2nd stage bootloader I (29) boot: compile time 13:09:53 I (29) boot: chip revision: 3 I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (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 0017d000 I (99) boot: 4 ota_1 OTA app 00 11 001a0000 0017d000 I (106) boot: End of partition table I (111) boot: No factory image, trying OTA 0 I (116) boot_comm: chip revision: 3, min. application chip revision: 0 I (123) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=2c6a0h (181920) map I (197) esp_image: segment 1: paddr=0004c6c8 vaddr=3ffbdb60 size=03950h ( 14672) load I (203) esp_image: segment 2: paddr=00050020 vaddr=400d0020 size=d62e0h (877280) map I (521) esp_image: segment 3: paddr=00126308 vaddr=3ffc14b0 size=01c30h ( 7216) load I (524) esp_image: segment 4: paddr=00127f40 vaddr=40080000 size=1bbd4h (113620) load I (573) esp_image: segment 5: paddr=00143b1c vaddr=50000000 size=00010h ( 16) load I (587) boot: Loaded app from partition at offset 0x20000 I (625) boot: Set actual ota_seq=1 in otadata[0] I (625) boot: Disabling RNG early entropy source... I (636) cpu_start: Pro cpu up. D (636) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 15 bit D (636) efuse: In EFUSE_BLK0__DATA5_REG is used 1 bits starting with 20 bit D (644) efuse: In EFUSE_BLK0__DATA3_REG is used 3 bits starting with 9 bit D (651) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 2 bit I (658) cpu_start: Starting app cpu, entry point is 0x400812cc I (0) cpu_start: App cpu up. D (673) clk: RTC_SLOW_CLK calibration value: 3581594 I (685) cpu_start: Pro cpu start user code I (685) cpu_start: cpu freq: 160000000 I (685) cpu_start: Application information: I (690) cpu_start: Project name: chip-ota-requestor-app I (696) cpu_start: App version: TE9-416-g425f1fb91 I (702) cpu_start: Compile time: Jun 6 2022 16:01:51 I (708) cpu_start: ELF file SHA256: 67fbe8db28f37f1d... I (714) cpu_start: ESP-IDF: v4.4.1 D (719) memory_layout: Checking 11 reserved memory ranges: D (724) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0 D (731) memory_layout: Reserved memory range 0x3ffae6e0 - 0x3ffaff10 D (737) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb6388 D (744) memory_layout: Reserved memory range 0x3ffb8000 - 0x3ffb9a20 D (750) memory_layout: Reserved memory range 0x3ffbdb28 - 0x3ffbdb5c D (756) memory_layout: Reserved memory range 0x3ffbdb60 - 0x3ffd2978 D (763) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440 D (769) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350 D (776) memory_layout: Reserved memory range 0x40070000 - 0x40078000 D (782) memory_layout: Reserved memory range 0x40078000 - 0x40080000 D (789) memory_layout: Reserved memory range 0x40080000 - 0x4009bbd4 D (795) memory_layout: Building list of available memory regions: D (801) memory_layout: Available memory region 0x3ffaff10 - 0x3ffb0000 D (808) memory_layout: Available memory region 0x3ffb6388 - 0x3ffb8000 D (814) memory_layout: Available memory region 0x3ffb9a20 - 0x3ffbdb28 D (821) memory_layout: Available memory region 0x3ffd2978 - 0x3ffd4000 D (828) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000 D (834) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000 D (841) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000 D (847) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000 D (854) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000 D (861) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000 D (867) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20 D (874) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000 D (880) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000 D (887) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000 D (894) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000 D (900) memory_layout: Available memory region 0x3fffc000 - 0x40000000 D (907) memory_layout: Available memory region 0x4009bbd4 - 0x4009c000 D (913) memory_layout: Available memory region 0x4009c000 - 0x4009e000 D (920) memory_layout: Available memory region 0x4009e000 - 0x400a0000 I (927) heap_init: Initializing. RAM available for dynamic allocation: I (934) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM D (940) heap_init: New heap initialised at 0x3ffb6388 I (945) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM D (951) heap_init: New heap initialised at 0x3ffb9a20 I (956) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM D (962) heap_init: New heap initialised at 0x3ffd2978 I (967) heap_init: At 3FFD2978 len 0000D688 (53 KiB): DRAM I (974) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (980) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM D (986) heap_init: New heap initialised at 0x4009bbd4 I (991) heap_init: At 4009BBD4 len 0000442C (17 KiB): IRAM D (998) intr_alloc: Connected src 46 to int 2 (cpu 0) D (1003) FLASH_HAL: extra_dummy: 1 D (1006) spi_flash: trying chip: issi D (1010) spi_flash: trying chip: gd D (1014) spi_flash: trying chip: mxic D (1017) spi_flash: trying chip: winbond D (1021) spi_flash: trying chip: generic I (1025) spi_flash: detected chip: generic I (1030) spi_flash: flash io: dio D (1034) cpu_start: calling init function: 0x40190150 D (1039) cpu_start: calling init function: 0x4018fbac D (1044) cpu_start: calling init function: 0x4014fb98 D (1049) cpu_start: calling init function: 0x40145ecc D (1055) cpu_start: calling init function: 0x40135bcc D (1060) cpu_start: calling init function: 0x40120ea8 D (1065) cpu_start: calling init function: 0x4011ff78 D (1070) cpu_start: calling init function: 0x4011f660 D (1075) cpu_start: calling init function: 0x4011f32c D (1080) cpu_start: calling init function: 0x4011e498 D (1085) cpu_start: calling init function: 0x4011a540 D (1091) cpu_start: calling init function: 0x401193ac D (1096) cpu_start: calling init function: 0x4010aee8 D (1101) cpu_start: calling init function: 0x40109df8 D (1106) cpu_start: calling init function: 0x400e5d40 D (1111) cpu_start: calling init function: 0x400e0988 D (1116) cpu_start: calling init function: 0x400e033c D (1121) cpu_start: calling init function: 0x400ddec0 D (1126) cpu_start: calling init function: 0x400dd988 D (1131) cpu_start: calling init function: 0x400dd6b4 D (1136) cpu_start: calling init function: 0x400dd56c D (1142) cpu_start: calling init function: 0x400dd370 D (1147) cpu_start: calling init function: 0x400dd08c D (1152) cpu_start: calling init function: 0x400dc9dc D (1157) cpu_start: calling init function: 0x400dc6c8 D (1162) cpu_start: calling init function: 0x400d81b8 D (1167) cpu_start: calling init function: 0x400d6b4c D (1172) cpu_start: calling init function: 0x400d2af8 D (1177) cpu_start: calling init function: 0x400d1fe8 D (1183) intr_alloc: Connected src 17 to int 3 (cpu 0) D (1188) intr_alloc: Connected src 24 to int 9 (cpu 0) I (1193) cpu_start: Starting scheduler on PRO CPU. D (0) intr_alloc: Connected src 25 to int 2 (cpu 1) I (0) cpu_start: Starting scheduler on APP CPU. D (1219) heap_init: New heap initialised at 0x3ffe0440 D (1219) heap_init: New heap initialised at 0x3ffe4350 D (1229) intr_alloc: Connected src 16 to int 12 (cpu 0) I (1229) ota-requester-app: OTA Requester! D (1239) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 15 bit D (1239) efuse: In EFUSE_BLK0__DATA5_REG is used 1 bits starting with 20 bit D (1249) efuse: In EFUSE_BLK0__DATA3_REG is used 3 bits starting with 9 bit D (1259) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 2 bit I (1259) ota-requester-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE,  I (1269) ota-requester-app: silicon revision 3,  I (1279) ota-requester-app: 4MB external flash  D (1279) partition: Loading the partition table D (1289) partition: Partition table MD5 verified D (1299) esp_netif_lwip: LwIP stack has been initialized D (1309) esp_netif_lwip: esp-netif has been successfully initialized D (1309) event: running task for loop 0x3ffd4550 D (1309) event: created task for loop 0x3ffd4550 D (1319) event: created event loop 0x3ffd4550 D (1319) esp_netif_objects: esp_netif_add_to_list 0x3ffd547c D (1329) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1) D (1329) esp_netif_objects: esp_netif_add_to_list 0x3ffd5828 D (1339) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 2) D (1349) nvs: nvs_open_from_partition misc 1 I (1359) wifi:wifi driver task: 3ffd7db4, prio:23, stack:6656, core=0 I (1359) system_api: Base MAC address is not set I (1359) system_api: read default base MAC address from EFUSE D (1369) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit D (1379) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit D (1379) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit D (1389) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit D (1399) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit D (1409) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit D (1409) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit D (1419) nvs: nvs_open_from_partition nvs.net80211 1 D (1429) nvs: nvs_get opmode 1 D (1429) nvs: nvs_get_str_or_blob sta.ssid D (1429) nvs: nvs_get sta.authmode 1 D (1439) nvs: nvs_get_str_or_blob sta.pswd D (1439) nvs: nvs_get_str_or_blob sta.pmk D (1439) nvs: nvs_get sta.chan 1 D (1449) nvs: nvs_get auto.conn 1 D (1449) nvs: nvs_get bssid.set 1 D (1449) nvs: nvs_get_str_or_blob sta.bssid D (1459) nvs: nvs_get sta.lis_intval 2 D (1459) nvs: nvs_get sta.phym 1 D (1469) nvs: nvs_get sta.phybw 1 D (1469) nvs: nvs_get_str_or_blob sta.apsw D (1469) nvs: nvs_get_str_or_blob sta.apinfo D (1479) nvs: nvs_get sta.scan_method 1 D (1479) nvs: nvs_get sta.sort_method 1 D (1489) nvs: nvs_get sta.minrssi 1 D (1489) nvs: nvs_get sta.minauth 1 D (1489) nvs: nvs_get sta.pmf_e 1 D (1499) nvs: nvs_get sta.pmf_r 1 D (1499) nvs: nvs_get sta.btm_e 1 D (1499) nvs: nvs_get sta.rrm_e 1 D (1509) nvs: nvs_get sta.mbo_e 1 D (1509) nvs: nvs_get_str_or_blob ap.ssid D (1509) nvs: nvs_get_str_or_blob ap.passwd D (1519) nvs: nvs_get_str_or_blob ap.pmk D (1519) nvs: nvs_get ap.chan 1 D (1519) nvs: nvs_get ap.authmode 1 D (1529) nvs: nvs_get ap.hidden 1 D (1529) nvs: nvs_get ap.max.conn 1 D (1539) nvs: nvs_get bcn.interval 2 D (1539) nvs: nvs_get ap.phym 1 D (1539) nvs: nvs_get ap.phybw 1 D (1549) nvs: nvs_get ap.sndchan 1 D (1549) nvs: nvs_get ap.pmf_e 1 D (1549) nvs: nvs_get ap.pmf_r 1 D (1559) nvs: nvs_get ap.p_cipher 1 D (1559) nvs: nvs_get lorate 1 D (1559) nvs: nvs_get_str_or_blob country D (1569) nvs: nvs_get ap.ftm_r 1 D (1569) nvs: nvs_set ap.sndchan 1 1 I (1569) wifi:wifi firmware version: 63017e0 I (1579) wifi:wifi certification version: v7.0 I (1579) wifi:config NVS flash: enabled I (1579) wifi:config nano formating: disabled I (1589) wifi:Init data frame dynamic rx buffer num: 32 I (1589) wifi:Init management frame dynamic rx buffer num: 32 I (1599) wifi:Init management short buffer num: 32 I (1599) wifi:Init dynamic tx buffer num: 32 I (1609) wifi:Init static rx buffer size: 1600 I (1609) wifi:Init static rx buffer num: 10 I (1619) wifi:Init dynamic rx buffer num: 32 I (1619) wifi_init: rx ba win: 6 I (1619) wifi_init: tcpip mbox: 32 I (1629) wifi_init: udp mbox: 6 I (1629) wifi_init: tcp mbox: 6 I (1639) wifi_init: tcp tx win: 5744 I (1639) wifi_init: tcp rx win: 5744 I (1639) wifi_init: tcp mss: 1440 I (1649) wifi_init: WiFi IRAM OP enabled I (1649) wifi_init: WiFi RX IRAM OP enabled D (1659) nvs: nvs_open_from_partition chip-factory 0 D (1659) nvs: nvs_open_from_partition chip-factory 1 D (1669) nvs: nvs_close 3 D (1669) nvs: nvs_open_from_partition chip-config 0 D (1679) nvs: nvs_open_from_partition chip-config 1 D (1679) nvs: nvs_close 4 D (1679) nvs: nvs_open_from_partition chip-counters 0 D (1689) nvs: nvs_open_from_partition chip-counters 1 D (1689) nvs: nvs_close 5 D (1699) nvs: nvs_open_from_partition chip-counters 1 D (1699) nvs: nvs_set reboot-count 4 1 I (1709) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1) D (1709) nvs: nvs_close 6 D (1719) nvs: nvs_open_from_partition chip-counters 1 D (1719) nvs: nvs_set total-hours 4 0 I (1729) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0) D (1729) nvs: nvs_close 7 D (1729) nvs: nvs_open_from_partition chip-factory 0 D (1739) nvs: nvs_get_str_or_blob unique-id D (1739) nvs: nvs_close 8 D (1739) nvs: nvs_open_from_partition chip-factory 1 D (1749) nvs: nvs_set_str unique-id 6A597CC3D15E7BA4 I (1759) chip[DL]: NVS set: chip-factory/unique-id = "6A597CC3D15E7BA4" D (1759) nvs: nvs_close 9 D (1759) nvs: nvs_open_from_partition chip-config 0 D (1769) nvs: nvs_get fail-safe-armed 4 D (1769) nvs: nvs_close 10 I (1779) chip[DL]: Changing ESP WiFi mode: AP -> STA+AP D (1779) nvs: nvs_set opmode 1 3 I (1789) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA D (1789) nvs: nvs_set opmode 1 1 I (1799) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) D (1799) chip[DL]: CHIP task running D (1809) BTDM_INIT: Release DRAM [0x3ffb2730] - [0x3ffb6388] D (1809) intr_alloc: Connected src -5 to int 29 (cpu 0) I (1809) BTDM_INIT: BT controller compile version [5688ed5] D (1819) BTDM_INIT: .data initialise [0x3ffae6e0] <== [0x4000d890] D (1829) BTDM_INIT: .bss initialise [0x3ffb0000] - [0x3ffb09a8] D (1839) BTDM_INIT: .bss initialise [0x3ffb09a8] - [0x3ffb1ddc] D (1839) BTDM_INIT: .bss initialise [0x3ffb1ddc] - [0x3ffb2730] D (1849) BTDM_INIT: .bss initialise [0x3ffb8000] - [0x3ffb9a20] D (1849) BTDM_INIT: .bss initialise [0x3ffbdb28] - [0x3ffbdb5c] I (1859) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 D (1869) phy_init: loading PHY init data from application binary D (1869) nvs: nvs_open_from_partition phy 0 D (1879) phy_init: esp_phy_load_cal_data_from_nvs: failed to open NVS namespace (0x1102) W (1879) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration D (1889) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit D (1899) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit D (1909) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit D (1919) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit D (1919) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit D (1929) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit D (1939) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit D (2099) nvs: nvs_open_from_partition phy 1 D (2099) nvs: nvs_set_blob cal_data 1904 D (2109) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit D (2109) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit D (2109) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit D (2119) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit D (2129) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit D (2139) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit D (2139) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit D (2149) nvs: nvs_set_blob cal_mac 6 D (2159) nvs: nvs_set cal_version 4 4670 D (2159) nvs: nvs_close 11 D (2389) CHIP[DL]: BLE Host Task Started I (2429) CHIP[DL]: BLE host-controller synced D (2939) nvs: nvs_open_from_partition chip-factory 0 D (2939) nvs: nvs_get discriminator 4 D (2939) nvs: nvs_close 12 D (2939) nvs: nvs_open_from_partition chip-factory 0 D (2939) nvs: nvs_get discriminator 4 D (2939) nvs: nvs_close 13 D (2949) CHIP[DL]: NimBLE start advertising... I (2949) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2959) NimBLE: GAP procedure initiated: advertise;  I (2969) NimBLE: disc_mode=2 I (2969) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2979) NimBLE:  I (2989) chip[DL]: CHIPoBLE advertising started E (2989) chip[DL]: Long dispatch time: 1184 ms, for event type 2 I (2999) chip[DL]: Starting ESP WiFi layer D (2999) ADC: Wi-Fi takes adc2 lock. D (3009) wifi:filter: set rx policy=0 I (3009) wifi:mode : sta (c4:dd:57:5b:f6:d4) I (3009) wifi:enable tsf D (3009) wifi:filter: set rx policy=1 D (3019) wifi:connect status 0 -> 0 W (3019) wifi:Haven't to connect to a suitable AP now! D (3029) event: running post WIFI_EVENT:2 with handler 0x4014ff04 and context 0x3ffd56d4 on loop 0x3ffd4550 I (3029) chip[DL]: Done driving station state, nothing else to do... D (3039) wifi_init_default: wifi_start esp-netif:0x3ffd5828 event-id2 D (3049) wifi_init_default: WIFI mac address: c4 dd 57 5b f6 d4 W (3039) wifi:Haven't to connect to a suitable AP now! I (3059) chip[DL]: Done driving station state, nothing else to do... D (3059) esp_netif_handlers: esp_netif action has started with netif0x3ffd5828 from event_id=2 I (3069) chip[SVR]: Server initializing... D (3079) esp_netif_lwip: check: remote, if=0x3ffd5828 fn=0x4014deec  D (3079) chip[DIS]: Init fabric pairing table with server storage D (3089) esp_netif_lwip: esp_netif_start_api 0x3ffd5828 D (3089) nvs: nvs_open_from_partition CHIP_KVS 0 D (3099) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3ffd5828 I (3099) chip[DMG]: AccessControl: initializing D (3109) esp_netif_lwip: check: local, if=0x3ffd5828 fn=0x4014e7ec  I (3109) chip[DMG]: Examples::AccessControlDelegate::Init D (3119) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd5828 I (3129) chip[DMG]: AccessControl: setting D (3129) esp_netif_lwip: call api in lwip: ret=0x0, give sem I (3139) chip[DMG]: DefaultAclStorage: initializing D (3139) event: running post WIFI_EVENT:2 with handler 0x4011fbb0 and context 0x3ffd5a0c on loop 0x3ffd4550 I (3149) chip[DMG]: DefaultAclStorage: 0 entries loaded I (3169) chip[ZCL]: Using ZAP configuration... D (3169) nvs: nvs_open_from_partition CHIP_KVS 0 D (3179) chip[DMG]: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0 D (3179) nvs: nvs_open_from_partition CHIP_KVS 0 D (3189) chip[DMG]: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0 D (3199) nvs: nvs_open_from_partition CHIP_KVS 0 D (3199) chip[DMG]: Failed to read stored attribute (0, 0x0000_002B, 0x0000_0000: a0 D (3209) nvs: nvs_open_from_partition CHIP_KVS 0 D (3209) chip[DMG]: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0 D (3219) nvs: nvs_open_from_partition CHIP_KVS 0 D (3229) chip[DMG]: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: a0 I (3229) chip[DMG]: AccessControlCluster: initializing I (3239) chip[ZCL]: Initiating Admin Commissioning cluster. D (3249) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120d5 I (3249) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (3269) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (3269) echo-devicecallbacks: Current free heap: 111780  E (3279) chip[ZCL]: DeviceInfoProvider is not registered E (3279) chip[ZCL]: Trying to write invalid Calendar Type E (3289) chip[ZCL]: Failed to write calendar type with error: 0x87 D (3299) chip[IN]: UDP::Init bind&listen port=5540 D (3299) chip[IN]: UDP::Init bound to port=5540 D (3309) chip[IN]: UDP::Init bind&listen port=5540 D (3309) chip[IN]: UDP::Init bound to port=5540 D (3319) chip[IN]: BLEBase::Init - setting/overriding transport D (3319) chip[IN]: TransportMgr initialized D (3329) nvs: nvs_open_from_partition CHIP_KVS 0 D (3329) nvs: nvs_open_from_partition CHIP_KVS 0 D (3339) nvs: nvs_open_from_partition CHIP_KVS 1 D (3339) nvs: nvs_set_blob g/gcc 4 D (3349) nvs: nvs_close 14 D (3349) nvs: nvs_open_from_partition CHIP_KVS 1 D (3349) nvs: nvs_set_blob g/gdc 4 D (3359) nvs: nvs_close 15 D (3359) nvs: nvs_open_from_partition CHIP_KVS 0 D (3359) nvs: nvs_get_str_or_blob g/im/ec D (3369) nvs: nvs_close 16 D (3369) nvs: nvs_open_from_partition CHIP_KVS 1 D (3369) nvs: nvs_set_blob g/im/ec 8 D (3379) nvs: nvs_close 17 D (3379) nvs: nvs_open_from_partition chip-factory 0 D (3389) nvs: nvs_get iteration-count 4 D (3389) nvs: nvs_close 18 D (3389) nvs: nvs_open_from_partition chip-factory 0 D (3399) nvs: nvs_get_str_or_blob salt D (3399) nvs: nvs_close 19 D (3399) nvs: nvs_open_from_partition chip-factory 0 D (3409) nvs: nvs_get_str_or_blob verifier D (3409) nvs: nvs_close 20 D (3419) chip[IN]: SecureSession Allocated 0x3ffc5738 Type:1 LSID:34531 D (3419) chip[SC]: Assigned local session key ID 34531 D (3429) chip[SC]: Waiting for PBKDF param request I (3429) chip[DIS]: Updating services using commissioning mode 1 I (3439) chip[DIS]: CHIP minimal mDNS started advertising. D (3449) chip[DL]: Using wifi MAC for hostname D (3449) nvs: nvs_open_from_partition chip-factory 0 D (3459) nvs: nvs_get discriminator 4 D (3459) nvs: nvs_close 21 I (3459) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32776 discriminator=3840/15 I (3469) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (3479) chip[DIS]: mDNS service published: _matterc._udp D (3489) chip[DIS]: Scheduling discovery timeout in 900s I (3489) chip[IN]: CASE Server enabling CASE session setups I (3499) chip[SVR]: Joining Multicast groups D (3499) chip[ZCL]: Emitting StartUp event D (3509) chip[EVL]: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000009C6 I (3519) chip[SVR]: Server Listening... D (3529) nvs: nvs_open_from_partition CHIP_KVS 0 D (3529) nvs: nvs_get_str_or_blob wifi-pass D (3529) nvs: nvs_close 22 D (3539) nvs: nvs_open_from_partition CHIP_KVS 0 D (3539) nvs: nvs_get_str_or_blob wifi-ssid D (3549) nvs: nvs_close 23 E (3549) chip[DL]: Long dispatch time: 482 ms, for event type 2 I (3559) app-devicecallbacks: Current free heap: 110856  I (3559) chip[DL]: WIFI_EVENT_STA_START W (3569) wifi:Haven't to connect to a suitable AP now! I (3569) chip[DL]: Done driving station state, nothing else to do... I (3579) app-devicecallbacks: Current free heap: 110856  D (3579) nvs: nvs_open_from_partition chip-factory 0 D (3589) nvs: nvs_get discriminator 4 D (3589) nvs: nvs_close 24 D (3599) nvs: nvs_open_from_partition chip-factory 0 D (3599) nvs: nvs_get discriminator 4 D (3599) nvs: nvs_close 25 D (3609) CHIP[DL]: NimBLE start advertising... I (3609) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (3619) chip[DL]: Device already advertising, stop active advertisement and restart I (3629) NimBLE: GAP procedure initiated: stop advertising.  I (3639) NimBLE: GAP procedure initiated: advertise;  I (3639) NimBLE: disc_mode=2 I (3649) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (3659) NimBLE:  D (33439) nvs: nvs_open_from_partition chip-factory 0 D (33439) nvs: nvs_get discriminator 4 D (33439) nvs: nvs_close 26 D (33439) nvs: nvs_open_from_partition chip-factory 0 D (33439) nvs: nvs_get discriminator 4 D (33439) nvs: nvs_close 27 D (33449) CHIP[DL]: NimBLE start advertising... I (33449) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840) I (33459) chip[DL]: Device already advertising, stop active advertisement and restart I (33469) NimBLE: GAP procedure initiated: stop advertising.  I (33479) NimBLE: GAP procedure initiated: advertise;  I (33479) NimBLE: disc_mode=2 I (33489) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800 I (33499) NimBLE:  I (256669) chip[DL]: BLE GAP connection established (con 0) I (256669) chip[DL]: CHIPoBLE advertising stopped I (256669) app-devicecallbacks: Current free heap: 110856  D (256699) CHIP[DL]: BLE_GAP_EVENT_MTU = 256 channel id = 4 I (256929) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (256929) chip[BLE]: local and remote recv window sizes = 5 I (256939) chip[BLE]: selected BTP version 4 I (256939) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (257049) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1 I (257049) chip[DL]: CHIPoBLE subscribe received D (257049) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 6) I (257069) NimBLE: GATT procedure initiated: notify;  I (257069) NimBLE: att_handle=14  I (257079) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (257089) chip[IN]: BLE EndPoint 0x3ffcc758 Connection Complete I (257089) app-devicecallbacks: CHIPoBLE connection established I (257099) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (257099) app-devicecallbacks: Current free heap: 110856  I (257109) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:1680037404 on exchange 32755r D (257129) chip[EM]: Handling via exchange: 32755r, Delegate: 0x3ffc7c28 D (257129) chip[SC]: Received PBKDF param request D (257139) chip[SC]: Peer assigned session ID 12091 D (257139) chip[SC]: Found MRP parameters in the message D (257149) chip[SC]: Including MRP parameters in PBKDF param response I (257159) chip[IN]: Prepared unauthenticated message 0x3ffdec44 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 32755r with MessageCounter:1513960815. I (257169) chip[IN]: Sending unauthenticated msg 0x3ffdec44 with MessageCounter:1513960815 to 0x0000000000000000 at monotonic time: 000000000003E8A6 msec D (257179) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 140) I (257189) NimBLE: GATT procedure initiated: notify;  I (257199) NimBLE: att_handle=14  I (257199) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (257209) chip[SC]: Sent PBKDF param response E (257219) chip[DL]: Long dispatch time: 103 ms, for event type 7 I (257249) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (257249) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:1680037405 on exchange 32755r D (257259) chip[EM]: Found matching exchange: 32755r, Delegate: 0x3ffc7c28 D (257259) chip[SC]: Received spake2p msg1 I (258809) chip[IN]: Prepared unauthenticated message 0x3ffdebc4 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 32755r with MessageCounter:1513960816. I (258809) chip[IN]: Sending unauthenticated msg 0x3ffdebc4 with MessageCounter:1513960816 to 0x0000000000000000 at monotonic time: 000000000003EF11 msec D (258829) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 132) I (258839) NimBLE: GATT procedure initiated: notify;  I (258839) NimBLE: att_handle=14  I (258849) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (258859) chip[SC]: Sent spake2p msg2 E (258859) chip[DL]: Long dispatch time: 1611 ms, for event type 7 I (258869) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (258879) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:1680037406 on exchange 32755r D (258889) chip[EM]: Found matching exchange: 32755r, Delegate: 0x3ffc7c28 D (258889) chip[SC]: Received spake2p msg3 D (258899) chip[SC]: Sending status report. Protocol code 0, exchange 32755 I (258909) chip[IN]: Prepared unauthenticated message 0x3ffdec54 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 32755r with MessageCounter:1513960817. I (258919) chip[IN]: Sending unauthenticated msg 0x3ffdec54 with MessageCounter:1513960817 to 0x0000000000000000 at monotonic time: 000000000003EF7D msec D (258939) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 35) I (258939) NimBLE: GATT procedure initiated: notify;  I (258949) NimBLE: att_handle=14  I (258949) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (258959) chip[IN]: SecureSession Active 0x3ffc5738 Type:1 LSID:34531 D (258969) chip[IN]: New secure session created for device , LSID:34531 PSID:12091! I (258969) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (258979) chip[SVR]: Commissioning completed session establishment step I (258999) chip[DIS]: Updating services using commissioning mode 0 I (258999) chip[DIS]: CHIP minimal mDNS started advertising. D (259009) nvs: nvs_open_from_partition CHIP_KVS 1 D (259009) nvs: nvs_set_blob g/fs/c 9 D (259019) nvs: nvs_close 28 D (259019) nvs: nvs_open_from_partition chip-config 1 D (259019) nvs: nvs_set fail-safe-armed 4 1 I (259029) chip[DL]: NVS set: chip-config/fail-safe-armed = true D (259039) nvs: nvs_close 29 I (259039) chip[SVR]: Device completed Rendezvous process E (259049) chip[DL]: Long dispatch time: 170 ms, for event type 7 I (259049) chip[EM]: Received message of type 0x2 with protocolId (0, 1) and MessageCounter:15309152 on exchange 32756r D (259059) chip[EM]: Handling via exchange: 32756r, Delegate: 0x3ffca8cc D (259069) chip[IM]: Received Read request D (259069) chip[DMG]: ReadRequestMessage = D (259079) chip[DMG]: { D (259079) chip[DMG]: AttributePathIBs = D (259079) chip[DMG]: [ D (259089) chip[DMG]: AttributePathIB = D (259089) chip[DMG]: { D (259089) chip[DMG]: Cluster = 0x31, D (259099) chip[DMG]: Attribute = 0x0000_FFFC, D (259099) chip[DMG]: } D (259109) chip[DMG]:  D (259109) chip[DMG]: AttributePathIB = D (259109) chip[DMG]: { D (259109) chip[DMG]: Endpoint = 0x0, D (259119) chip[DMG]: Cluster = 0x30, D (259119) chip[DMG]: Attribute = 0x0000_0000, D (259129) chip[DMG]: } D (259129) chip[DMG]:  D (259129) chip[DMG]: AttributePathIB = D (259139) chip[DMG]: { D (259139) chip[DMG]: Endpoint = 0x0, D (259139) chip[DMG]: Cluster = 0x30, D (259149) chip[DMG]: Attribute = 0x0000_0001, D (259149) chip[DMG]: } D (259159) chip[DMG]:  D (259159) chip[DMG]: AttributePathIB = D (259159) chip[DMG]: { D (259159) chip[DMG]: Endpoint = 0x0, D (259169) chip[DMG]: Cluster = 0x30, D (259169) chip[DMG]: Attribute = 0x0000_0002, D (259179) chip[DMG]: } D (259179) chip[DMG]:  D (259179) chip[DMG]: AttributePathIB = D (259189) chip[DMG]: { D (259189) chip[DMG]: Endpoint = 0x0, D (259189) chip[DMG]: Cluster = 0x30, D (259199) chip[DMG]: Attribute = 0x0000_0003, D (259199) chip[DMG]: } D (259209) chip[DMG]:  D (259209) chip[DMG]: AttributePathIB = D (259209) chip[DMG]: { D (259209) chip[DMG]: Endpoint = 0x0, D (259219) chip[DMG]: Cluster = 0x28, D (259219) chip[DMG]: Attribute = 0x0000_0002, D (259229) chip[DMG]: } D (259229) chip[DMG]:  D (259229) chip[DMG]: AttributePathIB = D (259239) chip[DMG]: { D (259239) chip[DMG]: Endpoint = 0x0, D (259239) chip[DMG]: Cluster = 0x28, D (259249) chip[DMG]: Attribute = 0x0000_0004, D (259249) chip[DMG]: } D (259249) chip[DMG]:  D (259259) chip[DMG]: AttributePathIB = D (259259) chip[DMG]: { D (259259) chip[DMG]: Cluster = 0x31, D (259269) chip[DMG]: Attribute = 0x0000_0003, D (259269) chip[DMG]: } D (259279) chip[DMG]:  D (259279) chip[DMG]: ], D (259279) chip[DMG]:  D (259279) chip[DMG]: isFabricFiltered = true,  D (259289) chip[DMG]: InteractionModelRevision = 1 D (259289) chip[DMG]: }, D (259299) chip[DMG]: IM RH moving to [GeneratingReports] E (259299) chip[DL]: Long dispatch time: 250 ms, for event type 7 D (259309) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 D (259319) chip[DMG]: Cluster 31, Attribute 3 is dirty D (259319) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) D (259329) chip[DMG]: Cluster 28, Attribute 4 is dirty D (259339) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) D (259349) chip[DMG]: Cluster 28, Attribute 2 is dirty D (259359) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D (259369) chip[DMG]: Cluster 30, Attribute 3 is dirty D (259369) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) D (259379) chip[DMG]: Cluster 30, Attribute 2 is dirty D (259389) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) D (259399) chip[DMG]: Cluster 30, Attribute 1 is dirty D (259399) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) D (259409) chip[DMG]: Cluster 30, Attribute 0 is dirty D (259419) chip[DMG]: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) D (259429) chip[DMG]: Cluster 31, Attribute fffc is dirty D (259439) chip[DMG]: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) D (259449) chip[DMG]: Sending report (payload has 224 bytes)... I (259449) chip[IN]: Prepared secure message 0x3ffdeed4 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 32756r with MessageCounter:15075960. I (259469) chip[IN]: Sending encrypted msg 0x3ffdeed4 with MessageCounter:15075960 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F19F msec D (259479) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (259489) NimBLE: GATT procedure initiated: notify;  I (259489) NimBLE: att_handle=14  I (259499) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (259509) chip[DMG]: OnReportConfirm: NumReports = 0 D (259509) chip[DMG]: ReportsInFlight = 0 with readHandler 0, RE has no more messages D (259519) chip[DMG]: IM RH moving to [AwaitingDestruction] D (259529) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet E (259529) chip[DL]: Long dispatch time: 226 ms, for event type 3 D (259539) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 17) I (259549) NimBLE: GATT procedure initiated: notify;  I (259559) NimBLE: att_handle=14  I (259559) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  I (259589) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (259589) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309153 on exchange 32757r D (259599) chip[EM]: Handling via exchange: 32757r, Delegate: 0x3ffca8cc D (259599) chip[DMG]: InvokeRequestMessage = D (259609) chip[DMG]: { D (259609) chip[DMG]: suppressResponse = false,  D (259619) chip[DMG]: timedRequest = false,  D (259619) chip[DMG]: InvokeRequests = D (259619) chip[DMG]: [ D (259629) chip[DMG]: CommandDataIB = D (259629) chip[DMG]: { D (259629) chip[DMG]: CommandPathIB = D (259639) chip[DMG]: { D (259639) chip[DMG]: EndpointId = 0x0, D (259639) chip[DMG]: ClusterId = 0x30, D (259649) chip[DMG]: CommandId = 0x0, D (259649) chip[DMG]: }, D (259659) chip[DMG]:  D (259659) chip[DMG]: CommandData =  D (259659) chip[DMG]: { D (259659) chip[DMG]: 0x0 = 60,  D (259669) chip[DMG]: 0x1 = 3,  D (259669) chip[DMG]: }, D (259669) chip[DMG]: }, D (259679) chip[DMG]:  D (259679) chip[DMG]: ], D (259679) chip[DMG]:  D (259689) chip[DMG]: InteractionModelRevision = 1 D (259689) chip[DMG]: }, D (259689) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 D (259699) nvs: nvs_open_from_partition CHIP_KVS 1 D (259709) nvs: nvs_set_blob g/fs/c 9 D (259709) nvs: nvs_close 30 D (259709) nvs: nvs_open_from_partition chip-config 1 D (259719) nvs: nvs_set fail-safe-armed 4 1 I (259719) chip[DL]: NVS set: chip-config/fail-safe-armed = true D (259729) nvs: nvs_close 31 D (259729) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120d6 I (259739) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (259749) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (259759) echo-devicecallbacks: Current free heap: 109848  D (259769) chip[DMG]: ICR moving to [ Preparing] D (259769) chip[DMG]: ICR moving to [AddingComm] D (259779) chip[DMG]: ICR moving to [AddedComma] D (259779) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (259789) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32757r with MessageCounter:15075961. I (259799) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075961 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F2EE msec D (259819) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71) I (259819) NimBLE: GATT procedure initiated: notify;  I (259829) NimBLE: att_handle=14  I (259839) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (259839) chip[DMG]: ICR moving to [CommandSen] D (259849) chip[DMG]: ICR moving to [AwaitingDe] E (259849) chip[DL]: Long dispatch time: 265 ms, for event type 7 I (259859) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (259869) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309154 on exchange 32758r D (259879) chip[EM]: Handling via exchange: 32758r, Delegate: 0x3ffca8cc D (259889) chip[DMG]: InvokeRequestMessage = D (259889) chip[DMG]: { D (259889) chip[DMG]: suppressResponse = false,  D (259899) chip[DMG]: timedRequest = false,  D (259899) chip[DMG]: InvokeRequests = D (259909) chip[DMG]: [ D (259909) chip[DMG]: CommandDataIB = D (259909) chip[DMG]: { D (259919) chip[DMG]: CommandPathIB = D (259919) chip[DMG]: { D (259919) chip[DMG]: EndpointId = 0x0, D (259929) chip[DMG]: ClusterId = 0x30, D (259929) chip[DMG]: CommandId = 0x2, D (259939) chip[DMG]: }, D (259939) chip[DMG]:  D (259939) chip[DMG]: CommandData =  D (259939) chip[DMG]: { D (259949) chip[DMG]: 0x0 = 0,  D (259949) chip[DMG]: 0x1 = "XX",  D (259959) chip[DMG]: 0x2 = 4,  D (259959) chip[DMG]: }, D (259959) chip[DMG]: }, D (259959) chip[DMG]:  D (259969) chip[DMG]: ], D (259969) chip[DMG]:  D (259969) chip[DMG]: InteractionModelRevision = 1 D (259979) chip[DMG]: }, D (259979) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D (259989) nvs: nvs_open_from_partition chip-config 1 D (259989) nvs: nvs_set reg-location 4 0 I (259999) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) D (259999) nvs: nvs_close 32 D (260009) nvs: nvs_open_from_partition chip-config 1 D (260009) nvs: nvs_set_str country-code XX I (260019) chip[DL]: NVS set: chip-config/country-code = "XX" D (260019) nvs: nvs_close 33 D (260029) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120d7 I (260029) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (260049) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (260049) echo-devicecallbacks: Current free heap: 109848  D (260059) chip[DMG]: ICR moving to [ Preparing] D (260059) chip[DMG]: ICR moving to [AddingComm] D (260069) chip[DMG]: ICR moving to [AddedComma] D (260069) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (260079) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32758r with MessageCounter:15075962. I (260099) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075962 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F414 msec D (260109) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71) I (260119) NimBLE: GATT procedure initiated: notify;  I (260119) NimBLE: att_handle=14  I (260129) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (260139) chip[DMG]: ICR moving to [CommandSen] D (260139) chip[DMG]: ICR moving to [AwaitingDe] E (260149) chip[DL]: Long dispatch time: 279 ms, for event type 7 I (260159) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (260159) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309155 on exchange 32759r D (260169) chip[EM]: Handling via exchange: 32759r, Delegate: 0x3ffca8cc D (260179) chip[DMG]: InvokeRequestMessage = D (260189) chip[DMG]: { D (260189) chip[DMG]: suppressResponse = false,  D (260189) chip[DMG]: timedRequest = false,  D (260199) chip[DMG]: InvokeRequests = D (260199) chip[DMG]: [ D (260199) chip[DMG]: CommandDataIB = D (260209) chip[DMG]: { D (260209) chip[DMG]: CommandPathIB = D (260209) chip[DMG]: { D (260219) chip[DMG]: EndpointId = 0x0, D (260219) chip[DMG]: ClusterId = 0x3e, D (260229) chip[DMG]: CommandId = 0x2, D (260229) chip[DMG]: }, D (260229) chip[DMG]:  D (260229) chip[DMG]: CommandData =  D (260239) chip[DMG]: { D (260239) chip[DMG]: 0x0 = 2,  D (260249) chip[DMG]: }, D (260249) chip[DMG]: }, D (260249) chip[DMG]:  D (260249) chip[DMG]: ], D (260259) chip[DMG]:  D (260259) chip[DMG]: InteractionModelRevision = 1 D (260259) chip[DMG]: }, D (260269) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I (260269) chip[ZCL]: OpCreds: Certificate Chain request received for PAI D (260279) chip[DMG]: ICR moving to [ Preparing] D (260289) chip[DMG]: ICR moving to [AddingComm] D (260289) chip[DMG]: ICR moving to [AddedComma] D (260299) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (260309) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32759r with MessageCounter:15075963. I (260319) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075963 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F4F3 msec D (260329) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (260339) NimBLE: GATT procedure initiated: notify;  I (260349) NimBLE: att_handle=14  I (260349) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (260359) chip[DMG]: ICR moving to [CommandSen] D (260369) chip[DMG]: ICR moving to [AwaitingDe] E (260369) chip[DL]: Long dispatch time: 208 ms, for event type 7 D (260379) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (260379) NimBLE: GATT procedure initiated: notify;  I (260389) NimBLE: att_handle=14  I (260399) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (260399) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 48) I (260409) NimBLE: GATT procedure initiated: notify;  I (260419) NimBLE: att_handle=14  I (260419) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  I (260459) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (260459) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309156 on exchange 32760r D (260469) chip[EM]: Handling via exchange: 32760r, Delegate: 0x3ffca8cc D (260469) chip[DMG]: InvokeRequestMessage = D (260479) chip[DMG]: { D (260479) chip[DMG]: suppressResponse = false,  D (260489) chip[DMG]: timedRequest = false,  D (260489) chip[DMG]: InvokeRequests = D (260489) chip[DMG]: [ D (260499) chip[DMG]: CommandDataIB = D (260499) chip[DMG]: { D (260499) chip[DMG]: CommandPathIB = D (260509) chip[DMG]: { D (260509) chip[DMG]: EndpointId = 0x0, D (260509) chip[DMG]: ClusterId = 0x3e, D (260519) chip[DMG]: CommandId = 0x2, D (260519) chip[DMG]: }, D (260529) chip[DMG]:  D (260529) chip[DMG]: CommandData =  D (260529) chip[DMG]: { D (260529) chip[DMG]: 0x0 = 1,  D (260539) chip[DMG]: }, D (260539) chip[DMG]: }, D (260539) chip[DMG]:  D (260549) chip[DMG]: ], D (260549) chip[DMG]:  D (260549) chip[DMG]: InteractionModelRevision = 1 D (260559) chip[DMG]: }, D (260559) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I (260569) chip[ZCL]: OpCreds: Certificate Chain request received for DAC D (260579) chip[DMG]: ICR moving to [ Preparing] D (260579) chip[DMG]: ICR moving to [AddingComm] D (260579) chip[DMG]: ICR moving to [AddedComma] D (260589) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (260599) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32760r with MessageCounter:15075964. I (260609) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075964 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F618 msec D (260629) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (260629) NimBLE: GATT procedure initiated: notify;  I (260639) NimBLE: att_handle=14  I (260649) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (260649) chip[DMG]: ICR moving to [CommandSen] D (260659) chip[DMG]: ICR moving to [AwaitingDe] E (260659) chip[DL]: Long dispatch time: 205 ms, for event type 7 D (260669) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (260679) NimBLE: GATT procedure initiated: notify;  I (260679) NimBLE: att_handle=14  I (260689) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (260699) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 77) I (260709) NimBLE: GATT procedure initiated: notify;  I (260709) NimBLE: att_handle=14  I (260719) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  I (260739) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (260749) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309157 on exchange 32761r D (260749) chip[EM]: Handling via exchange: 32761r, Delegate: 0x3ffca8cc D (260759) chip[DMG]: InvokeRequestMessage = D (260759) chip[DMG]: { D (260769) chip[DMG]: suppressResponse = false,  D (260769) chip[DMG]: timedRequest = false,  D (260779) chip[DMG]: InvokeRequests = D (260779) chip[DMG]: [ D (260779) chip[DMG]: CommandDataIB = D (260789) chip[DMG]: { D (260789) chip[DMG]: CommandPathIB = D (260789) chip[DMG]: { D (260799) chip[DMG]: EndpointId = 0x0, D (260799) chip[DMG]: ClusterId = 0x3e, D (260799) chip[DMG]: CommandId = 0x0, D (260809) chip[DMG]: }, D (260809) chip[DMG]:  D (260809) chip[DMG]: CommandData =  D (260819) chip[DMG]: { D (260819) chip[DMG]: 0x0 = [ D (260819) chip[DMG]: 0xaa, 0x8e, 0x94, 0x6, 0x4e, 0x6, 0x56, 0x5, 0xc0, 0x9c, 0xb9, 0xd0, 0x3b, 0x44, 0x87, 0x59, 0x6, 0x76, 0x1a, 0x53, 0xd7, 0xee, 0x28, 0xc0, 0x78, 0x35, 0xf, 0x29, 0x25, 0x23, 0xd4, 0xef,  D (260839) chip[DMG]: ] D (260849) chip[DMG]: }, D (260849) chip[DMG]: }, D (260849) chip[DMG]:  D (260849) chip[DMG]: ], D (260859) chip[DMG]:  D (260859) chip[DMG]: InteractionModelRevision = 1 D (260859) chip[DMG]: }, D (260869) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I (260879) chip[ZCL]: OpCreds: Received an AttestationRequest command D (261189) chip[DMG]: ICR moving to [ Preparing] D (261189) chip[DMG]: ICR moving to [AddingComm] D (261189) chip[DMG]: ICR moving to [AddedComma] D (261199) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (261209) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32761r with MessageCounter:15075965. I (261219) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075965 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003F877 msec D (261229) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (261239) NimBLE: GATT procedure initiated: notify;  I (261249) NimBLE: att_handle=14  I (261249) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (261259) chip[DMG]: ICR moving to [CommandSen] D (261269) chip[DMG]: ICR moving to [AwaitingDe] E (261269) chip[DL]: Long dispatch time: 527 ms, for event type 7 D (261279) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (261289) NimBLE: GATT procedure initiated: notify;  I (261289) NimBLE: att_handle=14  I (261299) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (261309) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 237) I (261309) NimBLE: GATT procedure initiated: notify;  I (261319) NimBLE: att_handle=14  I (261319) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  I (261389) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (261389) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309158 on exchange 32762r D (261399) chip[EM]: Handling via exchange: 32762r, Delegate: 0x3ffca8cc D (261399) chip[DMG]: InvokeRequestMessage = D (261409) chip[DMG]: { D (261409) chip[DMG]: suppressResponse = false,  D (261419) chip[DMG]: timedRequest = false,  D (261419) chip[DMG]: InvokeRequests = D (261419) chip[DMG]: [ D (261429) chip[DMG]: CommandDataIB = D (261429) chip[DMG]: { D (261429) chip[DMG]: CommandPathIB = D (261439) chip[DMG]: { D (261439) chip[DMG]: EndpointId = 0x0, D (261439) chip[DMG]: ClusterId = 0x3e, D (261449) chip[DMG]: CommandId = 0x4, D (261449) chip[DMG]: }, D (261459) chip[DMG]:  D (261459) chip[DMG]: CommandData =  D (261459) chip[DMG]: { D (261459) chip[DMG]: 0x0 = [ D (261469) chip[DMG]: 0xa2, 0x76, 0x25, 0xdc, 0x6f, 0xc1, 0xb8, 0xe5, 0x1e, 0x2, 0xbd, 0xf0, 0xb3, 0x63, 0x1d, 0xf9, 0x61, 0xfb, 0xd, 0xd3, 0xb8, 0x15, 0xab, 0xa5, 0x61, 0x8d, 0x22, 0x7b, 0xb5, 0x81, 0xa2, 0xf3,  D (261489) chip[DMG]: ] D (261489) chip[DMG]: }, D (261489) chip[DMG]: }, D (261499) chip[DMG]:  D (261499) chip[DMG]: ], D (261499) chip[DMG]:  D (261499) chip[DMG]: InteractionModelRevision = 1 D (261509) chip[DMG]: }, D (261509) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I (261519) chip[ZCL]: OpCreds: Received a CSRRequest command I (262139) chip[ZCL]: OpCreds: NewCertificateSigningRequest succeeded D (262449) chip[DMG]: ICR moving to [ Preparing] D (262449) chip[DMG]: ICR moving to [AddingComm] D (262449) chip[DMG]: ICR moving to [AddedComma] D (262449) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (262459) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32762r with MessageCounter:15075966. I (262479) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075966 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003FD61 msec D (262489) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 244) I (262499) NimBLE: GATT procedure initiated: notify;  I (262509) NimBLE: att_handle=14  I (262509) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (262519) chip[DMG]: ICR moving to [CommandSen] D (262519) chip[DMG]: ICR moving to [AwaitingDe] E (262529) chip[DL]: Long dispatch time: 1140 ms, for event type 7 D (262539) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 138) I (262539) NimBLE: GATT procedure initiated: notify;  I (262549) NimBLE: att_handle=14  I (262549) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  I (262589) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (262619) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (262619) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309159 on exchange 32763r D (262629) chip[EM]: Handling via exchange: 32763r, Delegate: 0x3ffca8cc D (262629) chip[DMG]: InvokeRequestMessage = D (262639) chip[DMG]: { D (262639) chip[DMG]: suppressResponse = false,  D (262649) chip[DMG]: timedRequest = false,  D (262649) chip[DMG]: InvokeRequests = D (262649) chip[DMG]: [ D (262659) chip[DMG]: CommandDataIB = D (262659) chip[DMG]: { D (262659) chip[DMG]: CommandPathIB = D (262669) chip[DMG]: { D (262669) chip[DMG]: EndpointId = 0x0, D (262669) chip[DMG]: ClusterId = 0x3e, D (262679) chip[DMG]: CommandId = 0xb, D (262679) chip[DMG]: }, D (262689) chip[DMG]:  D (262689) chip[DMG]: CommandData =  D (262689) chip[DMG]: { D (262689) chip[DMG]: 0x0 = [ D (262699) chip[DMG]: 0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x14, 0x0, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x41, 0x4, 0x45, 0x1, 0x77 D (262719) chip[DMG]: ] D (262729) chip[DMG]: }, D (262729) chip[DMG]: }, D (262729) chip[DMG]:  D (262729) chip[DMG]: ], D (262739) chip[DMG]:  D (262739) chip[DMG]: InteractionModelRevision = 1 D (262739) chip[DMG]: }, D (262749) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I (262759) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command D (262759) chip[DMG]: ICR moving to [ Preparing] D (262769) chip[DMG]: ICR moving to [AddingComm] D (262769) chip[DMG]: ICR moving to [AddedComma] D (262779) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 319b18c9 D (262779) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (262789) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 32763r with MessageCounter:15075967. I (262809) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075967 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003FEAB msec D (262819) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 68) I (262829) NimBLE: GATT procedure initiated: notify;  I (262829) NimBLE: att_handle=14  I (262839) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (262849) chip[DMG]: ICR moving to [CommandSen] D (262849) chip[DMG]: ICR moving to [AwaitingDe] E (262859) chip[DL]: Long dispatch time: 240 ms, for event type 7 I (262859) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (262899) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (262929) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (262939) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309160 on exchange 32764r D (262939) chip[EM]: Handling via exchange: 32764r, Delegate: 0x3ffca8cc D (262949) chip[DMG]: InvokeRequestMessage = D (262949) chip[DMG]: { D (262959) chip[DMG]: suppressResponse = false,  D (262959) chip[DMG]: timedRequest = false,  D (262969) chip[DMG]: InvokeRequests = D (262969) chip[DMG]: [ D (262969) chip[DMG]: CommandDataIB = D (262979) chip[DMG]: { D (262979) chip[DMG]: CommandPathIB = D (262979) chip[DMG]: { D (262989) chip[DMG]: EndpointId = 0x0, D (262989) chip[DMG]: ClusterId = 0x3e, D (262989) chip[DMG]: CommandId = 0x6, D (262999) chip[DMG]: }, D (262999) chip[DMG]:  D (262999) chip[DMG]: CommandData =  D (263009) chip[DMG]: { D (263009) chip[DMG]: 0x0 = [ D (263009) chip[DMG]: 0x15, 0x30, 0x1, 0x1, 0x1, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x13, 0x1, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x15, 0x1, 0x25, 0x11, 0x3a, 0x30, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x D (263039) chip[DMG]: ] D (263039) chip[DMG]: 0x1 = [ D (263039) chip[DMG]: 0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x13, 0x1, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x30, 0x9, 0x41, 0x4, 0xec, 0x88, 0xf D (263069) chip[DMG]: ] D (263069) chip[DMG]: 0x2 = [ D (263069) chip[DMG]: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31,  D (263089) chip[DMG]: ] D (263089) chip[DMG]: 0x3 = 112233,  D (263089) chip[DMG]: 0x4 = 65521,  D (263099) chip[DMG]: }, D (263099) chip[DMG]: }, D (263099) chip[DMG]:  D (263099) chip[DMG]: ], D (263109) chip[DMG]:  D (263109) chip[DMG]: InteractionModelRevision = 1 D (263119) chip[DMG]: }, D (263119) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I (263129) chip[ZCL]: OpCreds: Received an AddNOC command I (263129) chip[DIS]: Verifying the received credentials I (264389) chip[DIS]: Added new fabric at index: 0x1, Initialized: 1 I (264389) chip[DIS]: Assigned compressed fabric ID: 0x07B51EA90DA2AA54, node ID: 0x000000000000303A D (264399) nvs: nvs_open_from_partition CHIP_KVS 1 D (264399) nvs: nvs_set_blob f/1/r 231 D (264409) nvs: nvs_close 34 D (264409) nvs: nvs_open_from_partition CHIP_KVS 1 D (264409) nvs: nvs_set_blob f/1/i 231 D (264419) nvs: nvs_close 35 D (264419) nvs: nvs_open_from_partition CHIP_KVS 1 D (264419) nvs: nvs_set_blob f/1/n 242 D (264449) nvs: nvs_close 36 D (264449) nvs: nvs_open_from_partition CHIP_KVS 1 D (264449) nvs: nvs_set_blob f/1/o 105 D (264449) nvs: nvs_close 37 D (264449) nvs: nvs_open_from_partition CHIP_KVS 1 D (264459) nvs: nvs_set_blob f/1/m 9 D (264459) nvs: nvs_close 38 I (264459) chip[DIS]: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage I (264469) chip[ZCL]: OpCreds: Fabric index 0x1 was persisted to storage. FabricId 0000000000000001, NodeId 000000000000303A, VendorId 0xFFF1 D (264489) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 319b18ca D (264489) chip[DMG]: Endpoint 0, Cluster 0x0000_003E update version to 319b18cb D (264499) nvs: nvs_open_from_partition CHIP_KVS 1 D (264509) nvs: nvs_set_blob g/fidx 10 D (264509) nvs: nvs_close 39 D (264509) nvs: nvs_open_from_partition CHIP_KVS 1 D (264519) nvs: nvs_set_blob g/fs/c 9 D (264519) nvs: nvs_close 40 D (264529) nvs: nvs_open_from_partition CHIP_KVS 0 D (264529) nvs: nvs_get_str_or_blob f/1/g D (264529) nvs: nvs_close 41 D (264539) nvs: nvs_open_from_partition CHIP_KVS 1 D (264539) nvs: nvs_set_blob f/1/k/0 110 D (264549) nvs: nvs_close 42 D (264549) nvs: nvs_open_from_partition CHIP_KVS 0 D (264549) nvs: nvs_get_str_or_blob g/gfl D (264559) nvs: nvs_close 43 D (264559) nvs: nvs_open_from_partition CHIP_KVS 1 D (264559) nvs: nvs_set_blob g/gfl 8 D (264569) nvs: nvs_close 44 D (264569) nvs: nvs_open_from_partition CHIP_KVS 1 D (264579) nvs: nvs_set_blob f/1/g 23 D (264579) nvs: nvs_close 45 D (264579) nvs: nvs_open_from_partition CHIP_KVS 1 D (264589) nvs: nvs_set_blob f/1/ac/0/0 18 D (264589) nvs: nvs_close 46 D (264599) chip[EVL]: LogEvent event number: 0x0000000000000001 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000000405A6 I (264609) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 D (264619) chip[DL]: Using wifi MAC for hostname I (264619) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (264629) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (264639) chip[DIS]: mDNS service published: _matter._tcp D (264649) chip[DMG]: ICR moving to [ Preparing] D (264649) chip[DMG]: ICR moving to [AddingComm] D (264659) chip[DMG]: ICR moving to [AddedComma] I (264659) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC D (264669) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (264679) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 32764r with MessageCounter:15075968. I (264689) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075968 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000040607 msec D (264709) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71) I (264709) NimBLE: GATT procedure initiated: notify;  I (264719) NimBLE: att_handle=14  I (264729) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (264729) chip[DMG]: ICR moving to [CommandSen] D (264739) chip[DMG]: ICR moving to [AwaitingDe] E (264739) chip[DL]: Long dispatch time: 1809 ms, for event type 7 I (264749) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (264759) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309161 on exchange 32765r D (264769) chip[EM]: Handling via exchange: 32765r, Delegate: 0x3ffca8cc D (264779) chip[DMG]: InvokeRequestMessage = D (264779) chip[DMG]: { D (264779) chip[DMG]: suppressResponse = false,  D (264789) chip[DMG]: timedRequest = false,  D (264789) chip[DMG]: InvokeRequests = D (264799) chip[DMG]: [ D (264799) chip[DMG]: CommandDataIB = D (264799) chip[DMG]: { D (264799) chip[DMG]: CommandPathIB = D (264809) chip[DMG]: { D (264809) chip[DMG]: EndpointId = 0x0, D (264819) chip[DMG]: ClusterId = 0x31, D (264819) chip[DMG]: CommandId = 0x2, D (264819) chip[DMG]: }, D (264829) chip[DMG]:  D (264829) chip[DMG]: CommandData =  D (264829) chip[DMG]: { D (264839) chip[DMG]: 0x0 = [ D (264839) chip[DMG]: 0x46, 0x54, 0x54, 0x48, 0x2d, 0x31, 0x30, 0x46, 0x37,  D (264849) chip[DMG]: ] D (264849) chip[DMG]: 0x1 = [ D (264849) chip[DMG]: 0x57, 0x6f, 0x51, 0x47, 0x53, 0x4f, 0x50, 0x43, 0x40, 0x32, 0x35, 0x32, 0x30,  D (264859) chip[DMG]: ] D (264869) chip[DMG]: 0x2 = 14,  D (264869) chip[DMG]: }, D (264869) chip[DMG]: }, D (264879) chip[DMG]:  D (264879) chip[DMG]: ], D (264879) chip[DMG]:  D (264879) chip[DMG]: InteractionModelRevision = 1 D (264889) chip[DMG]: }, D (264889) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0002 D (264899) chip[DMG]: ICR moving to [ Preparing] D (264899) chip[DMG]: ICR moving to [AddingComm] D (264909) chip[DMG]: ICR moving to [AddedComma] D (264909) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120d8 I (264919) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (264929) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (264939) echo-devicecallbacks: Current free heap: 105828  D (264949) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (264959) chip[IN]: Prepared secure message 0x3ffdecc4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 32765r with MessageCounter:15075969. I (264969) chip[IN]: Sending encrypted msg 0x3ffdecc4 with MessageCounter:15075969 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000004071E msec D (264979) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 71) I (264989) NimBLE: GATT procedure initiated: notify;  I (264999) NimBLE: att_handle=14  I (264999) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (265009) chip[DMG]: ICR moving to [CommandSen] D (265019) chip[DMG]: ICR moving to [AwaitingDe] E (265019) chip[DL]: Long dispatch time: 263 ms, for event type 7 I (265029) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (265039) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:15309162 on exchange 32766r D (265049) chip[EM]: Handling via exchange: 32766r, Delegate: 0x3ffca8cc D (265049) chip[DMG]: InvokeRequestMessage = D (265059) chip[DMG]: { D (265059) chip[DMG]: suppressResponse = false,  D (265069) chip[DMG]: timedRequest = false,  D (265069) chip[DMG]: InvokeRequests = D (265069) chip[DMG]: [ D (265079) chip[DMG]: CommandDataIB = D (265079) chip[DMG]: { D (265079) chip[DMG]: CommandPathIB = D (265089) chip[DMG]: { D (265089) chip[DMG]: EndpointId = 0x0, D (265089) chip[DMG]: ClusterId = 0x31, D (265099) chip[DMG]: CommandId = 0x6, D (265099) chip[DMG]: }, D (265109) chip[DMG]:  D (265109) chip[DMG]: CommandData =  D (265109) chip[DMG]: { D (265119) chip[DMG]: 0x0 = [ D (265119) chip[DMG]: 0x46, 0x54, 0x54, 0x48, 0x2d, 0x31, 0x30, 0x46, 0x37,  D (265129) chip[DMG]: ] D (265129) chip[DMG]: 0x1 = 16,  D (265129) chip[DMG]: }, D (265139) chip[DMG]: }, D (265139) chip[DMG]:  D (265139) chip[DMG]: ], D (265139) chip[DMG]:  D (265149) chip[DMG]: InteractionModelRevision = 1 D (265149) chip[DMG]: }, D (265149) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 I (265159) chip[NP]: ESP NetworkCommissioningDelegate: SSID: FTTH-10F7 I (265169) chip[DL]: WiFi station mode change: Enabled -> Disabled D (265179) wifi:clear blacklist D (265179) nvs: nvs_set_blob sta.ssid 36 D (265189) nvs: nvs_set_blob sta.pswd 65 D (265189) nvs: nvs_set bssid.set 1 0 D (265189) nvs: nvs_set sta.lis_intval 2 3 D (265199) nvs: nvs_set sta.chan 1 0 D (265199) nvs: nvs_set sta.scan_method 1 0 D (265199) nvs: nvs_set sta.sort_method 1 0 D (265219) nvs: nvs_set sta.minrssi 1 -127 D (265219) nvs: nvs_set sta.minauth 1 0 D (265219) nvs: nvs_set_blob sta.apsw 2 D (265219) nvs: nvs_set sta.pmf_e 1 1 D (265219) nvs: nvs_set sta.pmf_r 1 0 D (265229) nvs: nvs_set sta.rrm_e 1 0 D (265229) nvs: nvs_set sta.btm_e 1 0 D (265229) nvs: nvs_set sta.mbo_e 1 0 D (265249) nvs: nvs_set_blob sta.apinfo 700 I (265249) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (265249) wifi:mode : sta (c4:dd:57:5b:f6:d4) + softAP (ac:7f:ed:6d:01:fd) D (265249) wifi:filter: set rx policy=9 I (265259) wifi:Total power save buffer number: 16 I (265259) wifi:Init max length of beacon: 752/752 I (265269) wifi:Init max length of beacon: 752/752 D (265269) nvs: nvs_set opmode 1 3 D (265279) event: running post WIFI_EVENT:12 with handler 0x4014feec and context 0x3ffd5794 on loop 0x3ffd4550 D (265289) wifi_init_default: wifi_start esp-netif:0x3ffd547c event-id12 I (265289) chip[DL]: WiFi station mode change: Disabled -> Enabled D (265289) wifi_init_default: WIFI mac address: ac 7f ed 6d 1 fd D (265299) chip[DMG]: Decreasing reference count for CommandHandler, remaining 1 D (265309) esp_netif_handlers: esp_netif action has started with netif0x3ffd547c from event_id=12 E (265309) chip[DL]: Long dispatch time: 277 ms, for event type 7 D (265319) esp_netif_lwip: check: remote, if=0x3ffd547c fn=0x4014deec  W (265329) wifi:Haven't to connect to a suitable AP now! D (265339) esp_netif_lwip: esp_netif_start_api 0x3ffd547c I (265339) chip[DL]: Attempting to connect WiFi station interface D (265349) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3ffd547c D (265349) wifi:Start wifi connect D (265359) esp_netif_lwip: esp_netif_start_api Setting the lwip netif0x3ffd54fc UP D (265359) wifi:connect status 0 -> 0 D (265369) esp_netif_lwip: DHCP server started successfully D (265369) wifi:D (265379) esp_netif_lwip: check: local, if=0x3ffd547c fn=0x4014e7ec  connect chan=0D (265389) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd547c D (265389) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (265389) wifi:first chan=1 D (265399) wifi:connect status 0 -> 1 D (265409) wifi:filter: set rx policy=3 D (265409) wifi:clear scan ap list D (265409) wifi:start scan: type=0x50f, priority=2, cb=0x401770b0, arg=0x0, ss_state=0x1, time=262994233, index=0 D (265419) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120> D (265399) event: running post WIFI_EVENT:12 with handler 0x4011fbb0 and context 0x3ffd5a0c on loop 0x3ffd4550 I (265439) chip[DL]: WiFi station state change: NotConnected -> Connecting I (265449) chip[DL]: Done driving station state, nothing else to do... E (265449) chip[DL]: Long dispatch time: 125 ms, for event type 3 W (265459) wifi:Haven't to connect to a suitable AP now! I (265469) chip[DL]: Attempting to connect WiFi station interface D (265469) wifi:Start wifi connect E (265479) wifi:sta is connecting, return error E (265479) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (265489) wifi:Haven't to connect to a suitable AP now! I (265489) chip[DL]: Attempting to connect WiFi station interface D (265499) wifi:Start wifi connect E (265499) wifi:sta is connecting, return error E (265509) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN I (265509) chip[DL]: WIFI_EVENT_AP_START I (265519) chip[DL]: WiFi AP state change: NotActive -> Active I (265519) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA D (265529) wifi:filter: set rx policy=10 I (265529) wifi:mode : sta (c4:dd:57:5b:f6:d4) D (265539) nvs: nvs_set opmode 1 1 D (265539) event: running post WIFI_EVENT:13 with handler 0x4014fdc0 and context 0x3ffd57c4 on loop 0x3ffd4550 I (265549) chip[DL]: WiFi AP state change: Active -> Deactivating D (265549) esp_netif_handlers: esp_netif action stopped with netif0x3ffd547c from event_id=13 I (265559) app-devicecallbacks: Current free heap: 106920  D (265569) esp_netif_lwip: check: remote, if=0x3ffd547c fn=0x4014e140  W (265579) wifi:Haven't to connect to a suitable AP now! D (265579) esp_netif_lwip: check: local, if=0x3ffd547c fn=0x4014e7ec  E (265589) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F D (265589) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd547c D (265609) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (265609) event: running post WIFI_EVENT:13 with handler 0x4011fbb0 and context 0x3ffd5a0c on loop 0x3ffd4550 I (265619) chip[DL]: WIFI_EVENT_AP_STOP I (265629) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (265639) app-devicecallbacks: Current free heap: 107012  D (265679) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (265679) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120> D (265919) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (265919) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120> D (266159) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (266159) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120> D (266399) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (266399) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120> D (266639) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (266639) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120> D (266889) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (266889) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120> D (267129) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (267129) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120> D (267369) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (267369) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120> D (267549) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 3) I (267549) NimBLE: GATT procedure initiated: notify;  I (267549) NimBLE: att_handle=14  I (267549) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (267609) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (267609) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120> D (267849) wifi:scan end: arg=0x0, status=0, ss_state=0x3 D (267859) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120> D (267859) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 D (267859) wifi:profile match: ss_state=0x7 D (267859) wifi:scan end: arg=0x0, status=0, ss_state=0x7 D (267869) wifi:find first mathched ssid, scan done D (267869) wifi:filter: set rx policy=4 D (267879) wifi:first chan=1 D (267879) wifi:handoff_cb: status=0 D (267879) wifi:ap found, mac=4c:ae:1c:72:10:f7 D (267889) wifi:new_bss=0x3ffd1510, cur_bss=0x0, new_chan=<11,2>, cur_chan=1 D (267889) wifi:filter: set rx policy=5 I (267899) wifi:new:<11,2>, old:<1,1>, ap:<255,255>, sta:<11,2>, prof:1 D (267899) wifi:connect_op: status=0, auth=5, cipher=3 D (269259) nvs: nvs_set_blob sta.apinfo 700 D (269269) wifi:auth mode is not none D (269269) wifi:connect_bss: auth=1, reconnect=0 I (269269) wifi:state: init -> auth (b0) D (269269) wifi:start 1s AUTH timer D (269269) wifi:clear scan ap list D (269279) wifi:recv auth: seq=2, status=0 I (269279) wifi:state: auth -> assoc (0) D (269289) wifi:restart connect 1s timer for assoc D (269289) wifi:recv assoc: type=0x10 D (269289) wifi:filter: set rx policy=6 I (269299) wifi:state: assoc -> run (10) D (269299) wifi:start 10s connect timer for 4 way handshake I (269309) wifi:connected with FTTH-10F7, aid = 3, channel 11, 40D, bssid = 4c:ae:1c:72:10:f7 I (269319) wifi:security: WPA2-PSK, phy: bgn, rssi: -58 D (269319) wifi:remove all except 4c:ae:1c:72:10:f7 from rc list D (269319) wifi:clear blacklist D (269329) nvs: nvs_set sta.chan 1 11 D (269339) nvs: nvs_set_blob sta.apinfo 700 D (269349) wifi:filter: set rx policy=7 I (269349) wifi:pm start, type: 1 D (269349) wifi:Send sta connected event D (269349) wifi:connect status 1 -> 5 D (269349) wifi:obss scan is disabled D (269349) wifi:start obss scan: obss scan is stopped D (269359) event: running post WIFI_EVENT:4 with handler 0x4014ff8c and context 0x3ffd5734 on loop 0x3ffd4550 D (269369) esp_netif_handlers: esp_netif action connected with netif0x3ffd5828 from event_id=4 D (269379) esp_netif_lwip: check: remote, if=0x3ffd5828 fn=0x4014dd78  D (269379) esp_netif_lwip: esp_netif_up_api esp_netif:0x3ffd5828 D (269389) esp_netif_lwip: check: local, if=0x3ffd5828 fn=0x4014e7ec  D (269399) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd5828 D (269399) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (269409) esp_netif_lwip: check: remote, if=0x3ffd5828 fn=0x4014db24  D (269419) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3ffd5828 I (269409) wifi:D (269419) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd5828 AP's beacon interval = 102400 us, DTIM period = 1D (269429) esp_netif_lwip: if0x3ffd5828 start ip lost tmr: no need start because netif=0x3ffd58a8 interval=120 ip=0 D (269439) esp_netif_lwip: starting dhcp client D (269449) wifi:set max rate: from to D (269449) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (269459) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144 D (269469) wifi:update trc D (269469) event: running post WIFI_EVENT:4 with handler 0x4011fbb0 and context 0x3ffd5a0c on loop 0x3ffd4550 I (269479) chip[DL]: WIFI_EVENT_STA_CONNECTED I (269489) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (269499) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (269499) chip[DL]: WiFi station interface connected D (269509) esp_netif_lwip: check: remote, if=0x3ffd5828 fn=0x4014de5c  D (269519) esp_netif_lwip: call api in lwip: ret=0x0, give sem D (269519) chip[DL]: Using wifi MAC for hostname I (269529) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (269539) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (269539) chip[DIS]: mDNS service published: _matter._tcp I (269549) chip[SVR]: Operational advertising enabled I (269549) app-devicecallbacks: Current free heap: 106200  D (269559) chip[DMG]: ICR moving to [ Preparing] D (269569) chip[DMG]: ICR moving to [AddingComm] D (269569) chip[DMG]: ICR moving to [AddedComma] D (269569) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120d9 I (269579) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (269599) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (269599) echo-devicecallbacks: Current free heap: 104680  D (269609) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 I (269619) chip[IN]: Prepared secure message 0x3ffdeec4 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 32766r with MessageCounter:15075970. I (269629) chip[IN]: Sending encrypted msg 0x3ffdeec4 with MessageCounter:15075970 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000041953 msec D (269649) CHIP[DL]: Sending indication for CHIPoBLE TX characteristic (con 0, len 69) I (269649) NimBLE: GATT procedure initiated: notify;  I (269659) NimBLE: att_handle=14  I (269659) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0  D (269669) chip[DMG]: ICR moving to [CommandSen] D (269679) chip[DMG]: ICR moving to [AwaitingDe] I (269679) chip[DL]: Done driving station state, nothing else to do... I (269689) app-devicecallbacks: Current free heap: 104680  E (269699) chip[DL]: Long dispatch time: 214 ms, for event type 49152 I (269699) chip[DL]: Updating advertising data I (269709) app-devicecallbacks: Current free heap: 106200  W (269819) wifi:idx:0 (ifx:0, 4c:ae:1c:72:10:f7), tid:0, ssn:0, winSize:64 I (270069) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 D (271299) esp_netif_lwip: esp_netif_nd6_cb lwip-netif:0x3ffd58a8 D (271299) event: running post IP_EVENT:3 with handler 0x4011fbb0 and context 0x3ffd5a40 on loop 0x3ffd4550 I (271299) chip[DL]: IP_EVENT_GOT_IP6 I (271309) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:c6dd:57ff:fe5b:f6d4 I (271319) app-devicecallbacks: Current free heap: 106088  I (271319) chip[DIS]: Updating services using commissioning mode 0 I (271329) chip[DIS]: CHIP minimal mDNS started advertising. D (271339) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (271349) chip[DL]: Using wifi MAC for hostname I (271349) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (271359) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. D (271369) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 I (271369) chip[DIS]: mDNS service published: _matter._tcp I (271379) app-devicecallbacks: Current free heap: 105524  I (271469) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:1680037407 on exchange 32767r D (271469) chip[EM]: Handling via exchange: 32767r, Delegate: 0x3ffc6318 I (271479) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffc7598 D (271489) chip[IN]: SecureSession Allocated 0x3ffc57f0 Type:2 LSID:34532 D (271499) chip[SC]: Waiting for Sigma1 msg I (271499) chip[IN]: CASE Server disabling CASE session setups I (271509) chip[SC]: Received Sigma1 msg D (271509) chip[SC]: Found MRP parameters in the message D (271519) chip[SC]: Peer assigned session key ID 12092 D (271519) nvs: nvs_open_from_partition CHIP_KVS 0 D (271529) chip[DL]: Using hash:cf75c7ac4a24fbf for nvs key:g/s/XtXFV0STJZ3dbrWh2e7qrg== D (271539) nvs: nvs_get_str_or_blob cf75c7ac4a24fbf D (271539) nvs: nvs_close 47 D (271539) nvs: nvs_open_from_partition CHIP_KVS 0 D (271549) nvs: nvs_get_str_or_blob f/1/g D (271549) nvs: nvs_close 48 D (271559) nvs: nvs_open_from_partition CHIP_KVS 0 D (271559) nvs: nvs_get_str_or_blob f/1/k/0 D (271569) nvs: nvs_close 49 I (271569) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x000000000000303A D (272299) esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffd58a8 D (272299) esp_netif_lwip: if0x3ffd5828 ip changed=1 D (272299) event: running post IP_EVENT:0 with handler 0x4014ff34 and context 0x3ffd5808 on loop 0x3ffd4550 D (272309) wifi_init_default: Got IP wifi default handler entered D (272319) esp_netif_handlers: esp_netif action got_ip with netif0x3ffd5828 from event_id=0 I (272319) esp_netif_handlers: sta ip: 192.168.1.6, mask: 255.255.255.0, gw: 192.168.1.1 D (272329) event: running post IP_EVENT:0 with handler 0x4011fbb0 and context 0x3ffd5a40 on loop 0x3ffd4550 D (272509) chip[SC]: Including MRP parameters D (272509) chip[EM]: Piggybacking Ack for MessageCounter:1680037407 on exchange: 32767r I (272509) chip[IN]: Prepared unauthenticated message 0x3ffc784c to 0x0000000000000000 (0) of type 0x31 and protocolId (0, 0) on exchange 32767r with MessageCounter:1513960818. I (272519) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960818 to 0x0000000000000000 at monotonic time: 000000000004249F msec I (272539) chip[SC]: Sent Sigma2 msg E (272539) chip[DL]: Long dispatch time: 1071 ms, for event type 3 I (272549) chip[DL]: IP_EVENT_STA_GOT_IP I (272549) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.6/255.255.255.0 gateway 192.168.1.1 D (272559) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3ffd5828 I (272569) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (272579) app-devicecallbacks: Current free heap: 101428  I (272579) app-devicecallbacks: IPv4 Server ready... I (272589) chip[DIS]: Updating services using commissioning mode 0 I (272599) chip[DIS]: CHIP minimal mDNS started advertising. D (272599) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (272609) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 D (272619) chip[DL]: Using wifi MAC for hostname I (272619) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (272629) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. D (272639) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (272649) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 I (272649) chip[DIS]: mDNS service published: _matter._tcp I (272659) app-devicecallbacks: Current free heap: 100712  I (272669) chip[DIS]: Updating services using commissioning mode 0 I (272669) chip[DIS]: CHIP minimal mDNS started advertising. D (272679) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (272689) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 D (272689) chip[DL]: Using wifi MAC for hostname I (272699) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (272709) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. D (272719) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (272719) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 I (272729) chip[DIS]: mDNS service published: _matter._tcp I (272729) app-devicecallbacks: Current free heap: 101744  I (272739) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1680037408 on exchange 32767r D (272749) chip[EM]: Found matching exchange: 32767r, Delegate: 0x3ffc632c D (272759) chip[EM]: Rxd Ack; Removing MessageCounter:1513960818 from Retrans Table on exchange 32767r D (272769) chip[EM]: Removed CHIP MessageCounter:1513960818 from RetransTable on exchange 32767r I (272779) chip[SC]: Received Sigma3 msg D (274669) nvs: nvs_open_from_partition CHIP_KVS 0 D (274669) nvs: nvs_get_str_or_blob g/sri D (274669) nvs: nvs_close 50 D (274679) nvs: nvs_open_from_partition CHIP_KVS 1 D (274679) chip[DL]: Using hash:151d909fd5cb785 for nvs key:f/1/s/000000000001B669 D (274689) nvs: nvs_set_blob 151d909fd5cb785 71 D (274699) nvs: nvs_close 51 D (274699) nvs: nvs_open_from_partition CHIP_KVS 1 D (274699) chip[DL]: Using hash:56a4aacc7f50602 for nvs key:g/s/cLeUEjJaNIBGbj82K98Rkg== D (274709) nvs: nvs_set_blob 56a4aacc7f50602 11 D (274709) nvs: nvs_close 52 D (274719) nvs: nvs_open_from_partition CHIP_KVS 1 D (274719) nvs: nvs_set_blob g/sri 13 D (274729) nvs: nvs_close 53 D (274729) chip[SC]: Sending status report. Protocol code 0, exchange 32767 D (274729) chip[EM]: Piggybacking Ack for MessageCounter:1680037408 on exchange: 32767r I (274739) chip[IN]: Prepared unauthenticated message 0x3ffc784c to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 32767r with MessageCounter:1513960819. I (274759) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960819 to 0x0000000000000000 at monotonic time: 0000000000042D5A msec D (274779) chip[IN]: SecureSession Active 0x3ffc57f0 Type:2 LSID:34532 D (274779) chip[IN]: New secure session created for device <000000000001B669, 1>, LSID:34532 PSID:12092! I (274789) chip[IN]: CASE Session established to peer: <000000000001B669, 1> I (274799) chip[IN]: CASE Server enabling CASE session setups E (274799) chip[DL]: Long dispatch time: 2063 ms, for event type 3 D (274809) chip[IN]: Received a duplicate message with MessageCounter:1680037408 on exchange 32767r I (274819) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1680037408 on exchange 32767r D (274829) chip[EM]: Found matching exchange: 32767r, Delegate: 0x0 D (274839) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1680037408 on exchange 32767r D (274849) chip[EM]: Sending Standalone Ack for MessageCounter:1680037408 on exchange 32767r I (274859) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 32767r with MessageCounter:1513960820. I (274869) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960820 to 0x0000000000000000 at monotonic time: 0000000000042DCB msec D (274889) chip[IN]: Received a duplicate message with MessageCounter:1680037408 on exchange 32767r I (274899) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1680037408 on exchange 32767r D (274909) chip[EM]: Found matching exchange: 32767r, Delegate: 0x0 D (274909) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1680037408 on exchange 32767r D (274919) chip[EM]: Sending Standalone Ack for MessageCounter:1680037408 on exchange 32767r I (274929) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 32767r with MessageCounter:1513960821. I (274949) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960821 to 0x0000000000000000 at monotonic time: 0000000000042E18 msec D (274959) chip[IN]: Received a duplicate message with MessageCounter:1680037408 on exchange 32767r I (274969) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1680037408 on exchange 32767r D (274979) chip[EM]: Found matching exchange: 32767r, Delegate: 0x0 D (274989) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1680037408 on exchange 32767r D (274999) chip[EM]: Sending Standalone Ack for MessageCounter:1680037408 on exchange 32767r I (275009) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 32767r with MessageCounter:1513960822. I (275019) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960822 to 0x0000000000000000 at monotonic time: 0000000000042E64 msec I (275039) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:11548195 on exchange 32768r D (275049) chip[EM]: Handling via exchange: 32768r, Delegate: 0x3ffca8cc D (275059) chip[DMG]: InvokeRequestMessage = D (275059) chip[DMG]: { D (275059) chip[DMG]: suppressResponse = false,  D (275069) chip[DMG]: timedRequest = false,  D (275069) chip[DMG]: InvokeRequests = D (275079) chip[DMG]: [ D (275079) chip[DMG]: CommandDataIB = D (275079) chip[DMG]: { D (275089) chip[DMG]: CommandPathIB = D (275089) chip[DMG]: { D (275089) chip[DMG]: EndpointId = 0x0, D (275099) chip[DMG]: ClusterId = 0x30, D (275099) chip[DMG]: CommandId = 0x4, D (275109) chip[DMG]: }, D (275109) chip[DMG]:  D (275109) chip[DMG]: CommandData =  D (275119) chip[DMG]: { D (275119) chip[DMG]: }, D (275119) chip[DMG]: }, D (275119) chip[DMG]:  D (275129) chip[DMG]: ], D (275129) chip[DMG]:  D (275129) chip[DMG]: InteractionModelRevision = 1 D (275139) chip[DMG]: }, D (275139) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 D (275149) nvs: nvs_open_from_partition chip-config 1 D (275149) nvs: nvs_set fail-safe-armed 4 0 I (275179) chip[DL]: NVS set: chip-config/fail-safe-armed = false D (275179) nvs: nvs_close 54 D (275179) nvs: nvs_open_from_partition CHIP_KVS 1 D (275179) nvs: nvs_erase_key g/fs/c  D (275189) nvs: nvs_close 55 D (275189) chip[DMG]: Endpoint 0, Cluster 0x0000_0030 update version to 595120da I (275189) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_0030', EndPoint ID: '0x00', Attribute ID: '0x0000_0000' I (275209) echo-devicecallbacks: Unhandled cluster ID: 0x0000_0030 I (275209) echo-devicecallbacks: Current free heap: 101256  D (275219) chip[DMG]: ICR moving to [ Preparing] D (275229) chip[DMG]: ICR moving to [AddingComm] D (275229) chip[DMG]: ICR moving to [AddedComma] D (275239) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 D (275239) chip[EM]: Piggybacking Ack for MessageCounter:11548195 on exchange: 32768r I (275249) chip[IN]: Prepared secure message 0x3ffc7864 to 0x000000000001B669 (1) of type 0x9 and protocolId (0, 1) on exchange 32768r with MessageCounter:15667476. I (275269) chip[IN]: Sending encrypted msg 0x3ffc7864 with MessageCounter:15667476 to 0x000000000001B669 (1) at monotonic time: 0000000000042F55 msec D (275279) chip[DMG]: ICR moving to [CommandSen] D (275279) chip[DMG]: ICR moving to [AwaitingDe] E (275289) chip[DL]: Long dispatch time: 249 ms, for event type 3 I (275299) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1680037409 on exchange 32767r D (275309) chip[EM]: Found matching exchange: 32767r, Delegate: 0x0 D (275309) chip[EM]: Rxd Ack; Removing MessageCounter:1513960819 from Retrans Table on exchange 32767r D (275319) chip[EM]: Removed CHIP MessageCounter:1513960819 from RetransTable on exchange 32767r I (275319) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0 I (275329) chip[SVR]: Commissioning completed successfully I (275349) chip[DIS]: Updating services using commissioning mode 0 I (275339) chip[DL]: CHIPoBLE unsubscribe received I (275359) chip[DIS]: CHIP minimal mDNS started advertising. I (275359) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213) D (275369) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (275389) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 D (275389) chip[DL]: Using wifi MAC for hostname I (275399) chip[DIS]: Advertise operational node 07B51EA90DA2AA54-000000000000303A I (275399) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. D (275409) chip[DIS]: Broadcasting mDns reply for query from FE80::C6DD:57FF:FE5B:F6D4 D (275419) chip[DIS]: Broadcasting mDns reply for query from 192.168.1.6 I (275429) chip[DIS]: mDNS service published: _matter._tcp D (275429) chip[IN]: Expiring all PASE pairings D (275439) chip[IN]: SecureSession MarkForRemoval 0x3ffc5738 Type:1 LSID:34531 D (275439) chip[IN]: SecureSession Released 0x3ffc5738 Type:1 LSID:34531 D (275449) chip[IN]: Clearing BLE pending packets. I (275459) chip[BLE]: Releasing end point's BLE connection back to application. D (275459) chip[ZCL]: Commissioning complete, notify platform driver to persist network credentials. D (275469) nvs: nvs_open_from_partition CHIP_KVS 1 D (275479) nvs: nvs_set_blob wifi-ssid 9 D (275479) nvs: nvs_close 56 D (275479) nvs: nvs_open_from_partition CHIP_KVS 1 D (275489) nvs: nvs_set_blob wifi-pass 13 D (275499) nvs: nvs_close 57 I (275499) app-devicecallbacks: Commissioning complete I (275499) NimBLE: GAP procedure initiated: stop advertising.  W (275509) Timer: Timer not stopped W (275509) Timer: Timer not stopped W (275519) Timer: Timer not stopped D (275529) BTDM_INIT: Release DRAM [0x3ffae6e0] - [0x3ffaff10] D (275529) BTDM_INIT: Release DRAM [0x3ffb0000] - [0x3ffb2730] D (275529) BTDM_INIT: Release DRAM [0x3ffb8000] - [0x3ffb9a20] D (275539) BTDM_INIT: Release DRAM [0x3ffbdb28] - [0x3ffbdb5c] I (275539) app-devicecallbacks: BLE deinit successful and memory reclaimed I (275549) app-devicecallbacks: Current free heap: 154720  E (275559) chip[DL]: Long dispatch time: 226 ms, for event type 32784 D (275569) chip[IN]: Received a duplicate message with MessageCounter:11548195 on exchange 32768r I (275569) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:11548195 on exchange 32768r D (275589) chip[EM]: Found matching exchange: 32768r, Delegate: 0x0 D (275589) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:11548195 on exchange 32768r D (275599) chip[EM]: Sending Standalone Ack for MessageCounter:11548195 on exchange 32768r I (275609) chip[IN]: Prepared secure message 0x3ffded54 to 0x000000000001B669 (1) of type 0x10 and protocolId (0, 0) on exchange 32768r with MessageCounter:15667477. I (275629) chip[IN]: Sending encrypted msg 0x3ffded54 with MessageCounter:15667477 to 0x000000000001B669 (1) at monotonic time: 00000000000430BD msec E (275639) chip[BLE]: no endpoint for unsub recvd I (275649) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:11548196 on exchange 32768r D (275659) chip[EM]: Found matching exchange: 32768r, Delegate: 0x0 D (275659) chip[EM]: Rxd Ack; Removing MessageCounter:15667476 from Retrans Table on exchange 32768r D (275669) chip[EM]: Removed CHIP MessageCounter:15667476 from RetransTable on exchange 32768r I (275679) app-devicecallbacks: CHIPoBLE disconnected I (275689) app-devicecallbacks: Current free heap: 156856  D (275689) nvs: nvs_open_from_partition CHIP_KVS 0 D (275699) nvs: nvs_get_str_or_blob g/o/dp D (275699) nvs: nvs_close 58 D (275709) nvs: nvs_open_from_partition CHIP_KVS 0 D (275709) nvs: nvs_get_str_or_blob g/o/cp D (275709) nvs: nvs_close 59 D (275719) nvs: nvs_open_from_partition CHIP_KVS 0 D (275719) nvs: nvs_get_str_or_blob g/o/ut D (275729) nvs: nvs_close 60 D (275729) nvs: nvs_open_from_partition CHIP_KVS 0 D (275729) nvs: nvs_get_str_or_blob g/o/us D (275739) nvs: nvs_close 61 D (275739) nvs: nvs_open_from_partition CHIP_KVS 0 D (275749) nvs: nvs_get_str_or_blob g/o/tv D (275749) nvs: nvs_close 62 I (275749) chip[SWU]: Stopping the watchdog timer I (275759) chip[SWU]: Starting the periodic query timer, timeout: 86400 seconds D (275769) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to 7fe5fa3 I (275769) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_002A', EndPoint ID: '0x00', Attribute ID: '0x0000_0002' I (275789) echo-devicecallbacks: Unhandled cluster ID: 0x0000_002A I (275789) echo-devicecallbacks: Current free heap: 156844  D (275799) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to 7fe5fa4 I (275809) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_002A', EndPoint ID: '0x00', Attribute ID: '0x0000_0003' I (275819) echo-devicecallbacks: Unhandled cluster ID: 0x0000_002A I (275829) echo-devicecallbacks: Current free heap: 156852  I (297779) chip[DIS]: Discovered node without a pending query I (297779) chip[DIS]: Discovery does not require any more timeouts I (297779) chip[DIS]: Discovered node without a pending query I (297789) chip[DIS]: Discovery does not require any more timeouts I (298079) chip[DIS]: Discovered node without a pending query I (298079) chip[DIS]: Discovery does not require any more timeouts I (300129) chip[DIS]: Discovered node without a pending query I (300129) chip[DIS]: Discovery does not require any more timeouts I (300139) chip[DIS]: Discovered node without a pending query I (300139) chip[DIS]: Discovery does not require any more timeouts I (300149) chip[DIS]: Discovered node without a pending query I (300149) chip[DIS]: Discovery does not require any more timeouts I (300159) chip[DIS]: Discovered node without a pending query I (300169) chip[DIS]: Discovery does not require any more timeouts I (300179) chip[DIS]: Discovered node without a pending query I (300179) chip[DIS]: Discovery does not require any more timeouts I (300189) chip[DIS]: Discovered node without a pending query I (300189) chip[DIS]: Discovery does not require any more timeouts I (300199) chip[DIS]: Discovered node without a pending query I (300209) chip[DIS]: Discovery does not require any more timeouts I (300219) chip[DIS]: Discovered node without a pending query I (300219) chip[DIS]: Discovery does not require any more timeouts I (300339) chip[DIS]: Discovered node without a pending query I (300339) chip[DIS]: Discovery does not require any more timeouts I (300339) chip[DIS]: Discovered node without a pending query I (300349) chip[DIS]: Discovery does not require any more timeouts I (300349) chip[DIS]: Discovered node without a pending query I (300359) chip[DIS]: Discovery does not require any more timeouts I (300369) chip[DIS]: Discovered node without a pending query I (300369) chip[DIS]: Discovery does not require any more timeouts I (309859) chip[DIS]: Discovered node without a pending query I (309859) chip[DIS]: Discovery does not require any more timeouts I (309859) chip[DIS]: Discovered node without a pending query I (309869) chip[DIS]: Discovery does not require any more timeouts I (311399) chip[DIS]: Discovered node without a pending query I (311399) chip[DIS]: Discovery does not require any more timeouts I (311399) chip[DIS]: Discovered node without a pending query I (311409) chip[DIS]: Discovery does not require any more timeouts I (311409) chip[DIS]: Discovered node without a pending query I (311419) chip[DIS]: Discovery does not require any more timeouts I (311429) chip[DIS]: Discovered node without a pending query I (311429) chip[DIS]: Discovery does not require any more timeouts I (311439) chip[DIS]: Discovered node without a pending query I (311449) chip[DIS]: Discovery does not require any more timeouts I (311449) chip[DIS]: Discovered node without a pending query I (311459) chip[DIS]: Discovery does not require any more timeouts I (311469) chip[DIS]: Discovered node without a pending query I (311469) chip[DIS]: Discovery does not require any more timeouts I (311479) chip[DIS]: Discovered node without a pending query I (311489) chip[DIS]: Discovery does not require any more timeouts I (329729) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:4084378110 on exchange 18403r D (329729) chip[EM]: Handling via exchange: 18403r, Delegate: 0x3ffc6318 I (329729) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffc7598 D (329739) chip[IN]: SecureSession Allocated 0x3ffc5738 Type:2 LSID:34533 D (329749) chip[SC]: Waiting for Sigma1 msg I (329749) chip[IN]: CASE Server disabling CASE session setups I (329759) chip[SC]: Received Sigma1 msg D (329769) chip[SC]: Found MRP parameters in the message D (329769) chip[SC]: Peer assigned session key ID 29125 D (329779) nvs: nvs_open_from_partition CHIP_KVS 0 D (329779) chip[DL]: Using hash:56a4aacc7f50602 for nvs key:g/s/cLeUEjJaNIBGbj82K98Rkg== D (329789) nvs: nvs_get_str_or_blob 56a4aacc7f50602 D (329799) nvs: nvs_close 63 D (329799) nvs: nvs_open_from_partition CHIP_KVS 0 D (329799) chip[DL]: Using hash:151d909fd5cb785 for nvs key:f/1/s/000000000001B669 D (329809) nvs: nvs_get_str_or_blob 151d909fd5cb785 D (329819) nvs: nvs_close 64 D (329819) chip[SC]: Including MRP parameters D (329819) chip[EM]: Piggybacking Ack for MessageCounter:4084378110 on exchange: 18403r I (329829) chip[IN]: Prepared unauthenticated message 0x3ffc784c to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 18403r with MessageCounter:1513960823. I (329849) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960823 to 0x0000000000000000 at monotonic time: 000000000005048A msec D (329859) chip[SC]: Sent Sigma2Resume msg E (329869) chip[DL]: Long dispatch time: 140 ms, for event type 3 I (330029) chip[EM]: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4084378111 on exchange 18403r D (330029) chip[EM]: Found matching exchange: 18403r, Delegate: 0x3ffc632c D (330039) chip[EM]: Rxd Ack; Removing MessageCounter:1513960823 from Retrans Table on exchange 18403r D (330049) chip[EM]: Removed CHIP MessageCounter:1513960823 from RetransTable on exchange 18403r I (330059) chip[SC]: Success status report received. Session was established D (330069) nvs: nvs_open_from_partition CHIP_KVS 0 D (330069) nvs: nvs_get_str_or_blob g/sri D (330079) nvs: nvs_close 65 D (330079) nvs: nvs_open_from_partition CHIP_KVS 1 D (330079) chip[DL]: Using hash:151d909fd5cb785 for nvs key:f/1/s/000000000001B669 D (330089) nvs: nvs_set_blob 151d909fd5cb785 71 D (330119) nvs: nvs_close 66 D (330119) nvs: nvs_open_from_partition CHIP_KVS 1 D (330119) chip[DL]: Using hash:dba44b5d99f0d04 for nvs key:g/s/2iu/QrESTJzOSStwpOv/Tw== D (330119) nvs: nvs_set_blob dba44b5d99f0d04 11 D (330129) nvs: nvs_close 67 D (330129) nvs: nvs_open_from_partition CHIP_KVS 1 D (330139) nvs: nvs_set_blob g/sri 24 D (330159) nvs: nvs_close 68 D (330159) chip[IN]: Expired/released previous local session ID 34532 for peer <000000000001B669, 1> D (330159) chip[IN]: SecureSession MarkForRemoval 0x3ffc57f0 Type:2 LSID:34532 D (330169) chip[IN]: SecureSession Released 0x3ffc57f0 Type:2 LSID:34532 D (330169) chip[IN]: SecureSession Active 0x3ffc5738 Type:2 LSID:34533 D (330179) chip[IN]: New secure session created for device <000000000001B669, 1>, LSID:34533 PSID:29125! I (330189) chip[IN]: CASE Session established to peer: <000000000001B669, 1> I (330199) chip[IN]: CASE Server enabling CASE session setups D (330199) chip[EM]: Sending Standalone Ack for MessageCounter:4084378111 on exchange 18403r I (330209) chip[IN]: Prepared unauthenticated message 0x3ffded04 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 18403r with MessageCounter:1513960824. I (330229) chip[IN]: Sending unauthenticated msg 0x3ffded04 with MessageCounter:1513960824 to 0x0000000000000000 at monotonic time: 0000000000050608 msec D (330239) chip[EM]: Flushed pending ack for MessageCounter:4084378111 on exchange 18403r E (330249) chip[DL]: Long dispatch time: 220 ms, for event type 3 I (330259) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:14816124 on exchange 18404r D (330269) chip[EM]: Handling via exchange: 18404r, Delegate: 0x3ffca8cc D (330279) chip[DMG]: InvokeRequestMessage = D (330279) chip[DMG]: { D (330279) chip[DMG]: suppressResponse = false,  D (330289) chip[DMG]: timedRequest = false,  D (330289) chip[DMG]: InvokeRequests = D (330299) chip[DMG]: [ D (330299) chip[DMG]: CommandDataIB = D (330299) chip[DMG]: { D (330309) chip[DMG]: CommandPathIB = D (330309) chip[DMG]: { D (330309) chip[DMG]: EndpointId = 0x0, D (330319) chip[DMG]: ClusterId = 0x2a, D (330319) chip[DMG]: CommandId = 0x0, D (330319) chip[DMG]: }, D (330329) chip[DMG]:  D (330329) chip[DMG]: CommandData =  D (330329) chip[DMG]: { D (330339) chip[DMG]: 0x0 = 12345,  D (330339) chip[DMG]: 0x1 = 65521,  D (330349) chip[DMG]: 0x2 = 0,  D (330349) chip[DMG]: 0x4 = 0,  D (330349) chip[DMG]: }, D (330349) chip[DMG]: }, D (330359) chip[DMG]:  D (330359) chip[DMG]: ], D (330359) chip[DMG]:  D (330369) chip[DMG]: InteractionModelRevision = 1 D (330369) chip[DMG]: }, D (330369) chip[DMG]: Received command for Endpoint=0 Cluster=0x0000_002A Command=0x0000_0000 I (330379) chip[SWU]: OTA Requestor received AnnounceOTAProvider D (330389) chip[SWU]: FabricIndex: 1 D (330389) chip[SWU]: ProviderNodeID: 0x0000000000003039 D (330399) chip[SWU]: VendorID: 0xfff1 D (330399) chip[SWU]: AnnouncementReason: 0 D (330409) chip[SWU]: Endpoint: 0 D (330409) chip[DMG]: ICR moving to [ Preparing] D (330409) chip[DMG]: ICR moving to [AddingComm] D (330419) chip[DMG]: ICR moving to [AddedComma] D (330419) chip[DMG]: Decreasing reference count for CommandHandler, remaining 0 D (330429) chip[EM]: Piggybacking Ack for MessageCounter:14816124 on exchange: 18404r I (330439) chip[IN]: Prepared secure message 0x3ffc784c to 0x000000000001B669 (1) of type 0x9 and protocolId (0, 1) on exchange 18404r with MessageCounter:8306509. I (330449) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:8306509 to 0x000000000001B669 (1) at monotonic time: 00000000000506EA msec D (330469) chip[DMG]: ICR moving to [CommandSen] D (330469) chip[DMG]: ICR moving to [AwaitingDe] E (330479) chip[DL]: Long dispatch time: 220 ms, for event type 3 D (330489) chip[IN]: Received a duplicate message with MessageCounter:4084378111 on exchange 18403r I (330489) chip[EM]: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:4084378111 on exchange 18403r D (330509) chip[EM]: Handling via exchange: 18403r, Delegate: 0x0 E (330509) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x0000002A D (330519) chip[IN]: Received a duplicate message with MessageCounter:14816124 on exchange 18404r I (330529) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:14816124 on exchange 18404r D (330539) chip[EM]: Found matching exchange: 18404r, Delegate: 0x0 D (330549) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:14816124 on exchange 18404r D (330559) chip[EM]: Sending Standalone Ack for MessageCounter:14816124 on exchange 18404r I (330559) chip[IN]: Prepared secure message 0x3ffded54 to 0x000000000001B669 (1) of type 0x10 and protocolId (0, 0) on exchange 18404r with MessageCounter:8306510. I (330579) chip[IN]: Sending encrypted msg 0x3ffded54 with MessageCounter:8306510 to 0x000000000001B669 (1) at monotonic time: 0000000000050767 msec I (330599) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14816125 on exchange 18404r D (330599) chip[EM]: Found matching exchange: 18404r, Delegate: 0x0 D (330609) chip[EM]: Rxd Ack; Removing MessageCounter:8306509 from Retrans Table on exchange 18404r D (330619) chip[EM]: Removed CHIP MessageCounter:8306509 from RetransTable on exchange 18404r D (330629) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to 7fe5fa5 I (330639) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_002A', EndPoint ID: '0x00', Attribute ID: '0x0000_0002' I (330649) echo-devicecallbacks: Unhandled cluster ID: 0x0000_002A I (330659) echo-devicecallbacks: Current free heap: 156856  D (330659) chip[EVL]: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_002A event id: 0x0 Sys timestamp: 0x00000000000507BA I (330679) chip[SWU]: Stopping the Periodic Query timer I (330679) chip[SWU]: Starting the watchdog timer, timeout: 21600 seconds D (330689) chip[SWU]: Establishing session to provider node ID 0x0000000000003039 on fabric index 1 D (330699) chip[CSM]: FindOrEstablishSession: PeerId = 07B51EA90DA2AA54:0000000000003039 D (330709) chip[CSM]: FindOrEstablishSession: No existing OperationalDeviceProxy instance found D (330719) chip[CTL]: OperationalDeviceProxy[07B51EA90DA2AA54:0000000000003039]: State change 1 --> 2 I (330759) chip[DIS]: UDP:[FE80::7EDF:A1FF:FEC2:19FC%st1]:5540: new best score: 3 I (330759) chip[DIS]: UDP:192.168.1.7%st1:5540: score has not improved: 2 I (330759) chip[DIS]: Checking node lookup status after 37 ms I (330769) chip[DIS]: Keeping DNSSD lookup active I (330939) chip[DIS]: Checking node lookup status after 208 ms D (330939) chip[CTL]: Updating device address to UDP:[FE80::7EDF:A1FF:FEC2:19FC%st1]:5540 while in state 2 D (330939) chip[CTL]: OperationalDeviceProxy[07B51EA90DA2AA54:0000000000003039]: State change 2 --> 3 D (330949) chip[IN]: SecureSession Allocated 0x3ffc57f0 Type:2 LSID:34534 I (330959) chip[SC]: Initiating session on local FabricIndex 1 from 0x000000000000303A -> 0x0000000000003039 D (331199) nvs: nvs_open_from_partition CHIP_KVS 0 D (331199) nvs: nvs_get_str_or_blob f/1/g D (331199) nvs: nvs_close 69 D (331199) nvs: nvs_open_from_partition CHIP_KVS 0 D (331209) nvs: nvs_get_str_or_blob f/1/k/0 D (331209) nvs: nvs_close 70 D (331219) nvs: nvs_open_from_partition CHIP_KVS 0 D (331219) chip[DL]: Using hash:ce7bb01efddbac8 for nvs key:f/1/s/0000000000003039 D (331229) nvs: nvs_get_str_or_blob ce7bb01efddbac8 D (331229) nvs: nvs_close 71 I (331239) chip[IN]: Prepared unauthenticated message 0x3ffc784c to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960825. I (331249) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960825 to 0x0000000000000000 at monotonic time: 0000000000050A07 msec I (331269) chip[SC]: Sent Sigma1 msg D (331269) chip[CTL]: OperationalDeviceProxy[07B51EA90DA2AA54:0000000000003039]: State change 3 --> 4 I (331279) chip[DIS]: Discovery does not require any more timeouts I (331289) chip[DIS]: Discovered node without a pending query I (331289) chip[DIS]: Discovery does not require any more timeouts I (331979) chip[EM]: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1722417837 on exchange 65102i D (331979) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (331989) chip[EM]: Rxd Ack; Removing MessageCounter:1513960825 from Retrans Table on exchange 65102i D (331999) chip[EM]: Removed CHIP MessageCounter:1513960825 from RetransTable on exchange 65102i I (331999) chip[SC]: Received Sigma2 msg D (332009) chip[SC]: Peer assigned session session ID 51011 D (333739) chip[SC]: Found MRP parameters in the message D (333739) chip[SC]: Sending Sigma3 D (333979) chip[EM]: Piggybacking Ack for MessageCounter:1722417837 on exchange: 65102i I (333979) chip[IN]: Prepared unauthenticated message 0x3ffc784c to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960826. I (333999) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960826 to 0x0000000000000000 at monotonic time: 00000000000514C1 msec I (334009) chip[SC]: Sent Sigma3 msg E (334019) chip[DL]: Long dispatch time: 2039 ms, for event type 3 D (334019) chip[IN]: Received a duplicate message with MessageCounter:1722417837 on exchange 65102i I (334029) chip[EM]: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1722417837 on exchange 65102i D (334039) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (334049) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1722417837 on exchange 65102i D (334059) chip[EM]: Sending Standalone Ack for MessageCounter:1722417837 on exchange 65102i I (334069) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960827. I (334089) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960827 to 0x0000000000000000 at monotonic time: 0000000000051519 msec D (334099) chip[IN]: Received a duplicate message with MessageCounter:1722417837 on exchange 65102i I (334109) chip[EM]: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1722417837 on exchange 65102i D (334119) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (334129) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1722417837 on exchange 65102i D (334139) chip[EM]: Sending Standalone Ack for MessageCounter:1722417837 on exchange 65102i I (334149) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960828. I (334159) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960828 to 0x0000000000000000 at monotonic time: 0000000000051566 msec D (334179) chip[IN]: Received a duplicate message with MessageCounter:1722417837 on exchange 65102i I (334189) chip[EM]: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1722417837 on exchange 65102i D (334199) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (334209) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1722417837 on exchange 65102i D (334209) chip[EM]: Sending Standalone Ack for MessageCounter:1722417837 on exchange 65102i I (334219) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960829. I (334239) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960829 to 0x0000000000000000 at monotonic time: 00000000000515B3 msec D (334259) chip[IN]: Received a duplicate message with MessageCounter:1722417837 on exchange 65102i I (334259) chip[EM]: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1722417837 on exchange 65102i D (334269) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (334279) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:1722417837 on exchange 65102i D (334289) chip[EM]: Sending Standalone Ack for MessageCounter:1722417837 on exchange 65102i I (334299) chip[IN]: Prepared unauthenticated message 0x3ffded24 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960830. I (334319) chip[IN]: Sending unauthenticated msg 0x3ffded24 with MessageCounter:1513960830 to 0x0000000000000000 at monotonic time: 0000000000051600 msec D (334329) chip[EM]: Retransmitting MessageCounter:1513960826 on exchange 65102i Send Cnt 1 I (334339) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960826 to 0x0000000000000000 at monotonic time: 0000000000051617 msec D (334679) chip[EM]: Retransmitting MessageCounter:1513960826 on exchange 65102i Send Cnt 2 I (334679) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960826 to 0x0000000000000000 at monotonic time: 0000000000051768 msec D (335259) chip[EM]: Retransmitting MessageCounter:1513960826 on exchange 65102i Send Cnt 3 I (335259) chip[IN]: Sending unauthenticated msg 0x3ffc784c with MessageCounter:1513960826 to 0x0000000000000000 at monotonic time: 00000000000519AC msec I (335269) chip[EM]: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1722417838 on exchange 65102i D (335279) chip[EM]: Found matching exchange: 65102i, Delegate: 0x3ffc67e4 D (335289) chip[EM]: Rxd Ack; Removing MessageCounter:1513960826 from Retrans Table on exchange 65102i D (335299) chip[EM]: Removed CHIP MessageCounter:1513960826 from RetransTable on exchange 65102i I (335299) chip[SC]: Success status report received. Session was established D (335309) nvs: nvs_open_from_partition CHIP_KVS 0 D (335319) nvs: nvs_get_str_or_blob g/sri D (335319) nvs: nvs_close 72 D (335319) nvs: nvs_open_from_partition CHIP_KVS 1 D (335329) chip[DL]: Using hash:ce7bb01efddbac8 for nvs key:f/1/s/0000000000003039 D (335339) nvs: nvs_set_blob ce7bb01efddbac8 71 D (335339) nvs: nvs_close 73 D (335339) nvs: nvs_open_from_partition CHIP_KVS 1 D (335349) chip[DL]: Using hash:439094912b46752 for nvs key:g/s/wcpcEa70TnYMScds0rl7tA== D (335359) nvs: nvs_set_blob 439094912b46752 9 D (335359) nvs: nvs_close 74 D (335359) nvs: nvs_open_from_partition CHIP_KVS 1 D (335369) nvs: nvs_set_blob g/sri 33 D (335379) nvs: nvs_close 75 D (335379) chip[IN]: SecureSession Active 0x3ffc57f0 Type:2 LSID:34534 D (335379) chip[IN]: New secure session created for device <0000000000003039, 1>, LSID:34534 PSID:51011! D (335389) chip[CTL]: OperationalDeviceProxy[07B51EA90DA2AA54:0000000000003039]: State change 4 --> 5 D (335399) nvs: nvs_open_from_partition chip-factory 0 D (335409) nvs: nvs_get hardware-ver 4 D (335409) nvs: nvs_close 76 D (335409) nvs: nvs_open_from_partition chip-config 0 D (335419) nvs: nvs_get_str_or_blob country-code D (335419) nvs: nvs_close 77 D (335429) chip[DMG]: ICR moving to [AddingComm] D (335429) chip[DMG]: ICR moving to [AddedComma] I (335439) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x8 and protocolId (0, 1) on exchange 65103i with MessageCounter:13794512. I (335449) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794512 to 0x0000000000003039 (1) at monotonic time: 0000000000051A6F msec D (335469) chip[DMG]: ICR moving to [CommandSen] D (335469) chip[EM]: Sending Standalone Ack for MessageCounter:1722417838 on exchange 65102i I (335479) chip[IN]: Prepared unauthenticated message 0x3ffded04 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 65102i with MessageCounter:1513960831. I (335499) chip[IN]: Sending unauthenticated msg 0x3ffded04 with MessageCounter:1513960831 to 0x0000000000000000 at monotonic time: 0000000000051A9A msec D (335509) chip[EM]: Flushed pending ack for MessageCounter:1722417838 on exchange 65102i E (335519) chip[DL]: Long dispatch time: 249 ms, for event type 3 I (335519) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1722417839 on exchange 65102i E (335539) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x00000070 I (335539) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1722417840 on exchange 65102i E (335559) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x00000070 I (335559) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1722417841 on exchange 65102i E (335569) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x00000070 D (335579) chip[IN]: Received a duplicate message with MessageCounter:1722417838 on exchange 65102i I (335589) chip[EM]: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1722417838 on exchange 65102i D (335599) chip[EM]: Handling via exchange: 65102i, Delegate: 0x0 E (335609) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x0000002A I (335669) chip[EM]: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:7030131 on exchange 65103i D (335669) chip[EM]: Found matching exchange: 65103i, Delegate: 0x3ffb8928 D (335669) chip[EM]: Rxd Ack; Removing MessageCounter:13794512 from Retrans Table on exchange 65103i D (335679) chip[EM]: Removed CHIP MessageCounter:13794512 from RetransTable on exchange 65103i D (335689) chip[DMG]: ICR moving to [ResponseRe] D (335699) chip[DMG]: InvokeResponseMessage = D (335699) chip[DMG]: { D (335699) chip[DMG]: suppressResponse = false,  D (335709) chip[DMG]: InvokeResponseIBs = D (335709) chip[DMG]: [ D (335709) chip[DMG]: InvokeResponseIB = D (335719) chip[DMG]: { D (335719) chip[DMG]: CommandDataIB = D (335729) chip[DMG]: { D (335729) chip[DMG]: CommandPathIB = D (335729) chip[DMG]: { D (335739) chip[DMG]: EndpointId = 0x0, D (335739) chip[DMG]: ClusterId = 0x29, D (335739) chip[DMG]: CommandId = 0x1, D (335749) chip[DMG]: }, D (335749) chip[DMG]:  D (335749) chip[DMG]: CommandData =  D (335759) chip[DMG]: { D (335759) chip[DMG]: 0x0 = 0,  D (335759) chip[DMG]: 0x1 = 0,  D (335769) chip[DMG]: 0x2 = "bdx://0000000000003039//fs/chip-otar-ota.bin",  D (335779) chip[DMG]: 0x3 = 2,  D (335779) chip[DMG]: 0x4 = "v2.0",  D (335779) chip[DMG]: 0x5 = [ D (335789) chip[DMG]: 0x61, 0x46, 0x9c, 0xb6, 0x34, 0x6c, 0xd1, 0x3c, 0x96, 0xb3, 0xc3, 0x7e, 0x29, 0x6c, 0xd7, 0x5d, 0x6, 0xed, 0xef, 0xa7, 0xa5, 0x92, 0xca, 0x57, 0xc3, 0x4a, 0x3a, 0x55, 0x4e, 0xd, 0x9c, 0xed,  D (335809) chip[DMG]: ] D (335809) chip[DMG]: 0x6 = false,  D (335809) chip[DMG]: 0x7 = [ D (335819) chip[DMG]:  D (335819) chip[DMG]: ] D (335819) chip[DMG]: }, D (335829) chip[DMG]: }, D (335829) chip[DMG]:  D (335829) chip[DMG]: }, D (335829) chip[DMG]:  D (335839) chip[DMG]: ], D (335839) chip[DMG]:  D (335839) chip[DMG]: InteractionModelRevision = 1 D (335849) chip[DMG]: }, I (335849) chip[DMG]: Received Command Response Data, Endpoint=0 Cluster=0x0000_0029 Command=0x0000_0001 D (335859) chip[SWU]: QueryImageResponse: D (335859) chip[SWU]: status: 0 D (335869) chip[SWU]: delayedActionTime: 0 seconds D (335869) chip[SWU]: imageURI: bdx://0000000000003039//fs/chip-otar-ota.bin D (335879) chip[SWU]: softwareVersion: 2 D (335879) chip[SWU]: softwareVersionString: v2.0 D (335889) chip[SWU]: updateToken: 32 D (335889) chip[SWU]: userConsentNeeded: 0 D (335899) chip[SWU]: metadataForRequestor: 0 D (335899) chip[SWU]: Update available from version 1 to 2 D (335909) chip[DMG]: ICR moving to [AwaitingDe] D (335909) chip[EM]: Sending Standalone Ack for MessageCounter:7030131 on exchange 65103i I (335919) chip[IN]: Prepared secure message 0x3ffded34 to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 0) on exchange 65103i with MessageCounter:13794513. I (335939) chip[IN]: Sending encrypted msg 0x3ffded34 with MessageCounter:13794513 to 0x0000000000003039 (1) at monotonic time: 0000000000051C52 msec D (335949) chip[EM]: Flushed pending ack for MessageCounter:7030131 on exchange 65103i E (335959) chip[DL]: Long dispatch time: 292 ms, for event type 3 D (335959) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to 7fe5fa6 I (335969) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_002A', EndPoint ID: '0x00', Attribute ID: '0x0000_0002' I (335979) echo-devicecallbacks: Unhandled cluster ID: 0x0000_002A I (335989) echo-devicecallbacks: Current free heap: 156856  D (335999) chip[EVL]: LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_002A event id: 0x0 Sys timestamp: 0x0000000000051C91 D (336009) chip[SWU]: Establishing session to provider node ID 0x0000000000003039 on fabric index 1 D (336019) chip[CSM]: FindOrEstablishSession: PeerId = 07B51EA90DA2AA54:0000000000003039 I (336029) chip[ATM]: Sending BDX Message I (336029) chip[ATM]: ReceiveInit I (336039) chip[ATM]: Proposed Transfer Control: 0x20 I (336039) chip[ATM]: Range Control: 0x0 I (336049) chip[ATM]: Proposed Max Block Size: 1024 I (336049) chip[ATM]: Start Offset: 0x0000000000000000 I (336059) chip[ATM]: Proposed Max Length: 0x0000000000000000 I (336069) chip[ATM]: File Designator Length: 21 I (336069) chip[ATM]: File Designator: /fs/chip-otar-ota.bin D (336079) chip[SWU]: BDX::SendMessage I (336079) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x4 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794514. I (336099) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794514 to 0x0000000000003039 (1) at monotonic time: 0000000000051CF6 msec I (336339) chip[EM]: Received message of type 0x5 with protocolId (0, 2) and MessageCounter:7030132 on exchange 65104i D (336339) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (336349) chip[EM]: Rxd Ack; Removing MessageCounter:13794514 from Retrans Table on exchange 65104i D (336359) chip[EM]: Removed CHIP MessageCounter:13794514 from RetransTable on exchange 65104i I (336369) chip[ATM]: Handling received BDX Message I (336369) chip[ATM]: ReceiveAccept I (336379) chip[ATM]: Transfer Control: 0x20 I (336379) chip[ATM]: Range Control: 0x0 I (336389) chip[ATM]: Max Block Size: 1024 I (336389) chip[ATM]: Length: 0x0000000000000000 I (336399) chip[ATM]: Sending BDX Message I (336399) chip[ATM]: BlockQuery I (336399) chip[ATM]: Block Counter: 0 D (336409) chip[SWU]: BDX::SendMessage D (336409) chip[EM]: Piggybacking Ack for MessageCounter:7030132 on exchange: 65104i I (336419) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794515. I (336439) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794515 to 0x0000000000003039 (1) at monotonic time: 0000000000051E48 msec E (336449) chip[DL]: Long dispatch time: 114 ms, for event type 3 I (336689) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030133 on exchange 65104i D (336689) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (336699) chip[EM]: Rxd Ack; Removing MessageCounter:13794515 from Retrans Table on exchange 65104i D (336709) chip[EM]: Removed CHIP MessageCounter:13794515 from RetransTable on exchange 65104i I (336719) chip[ATM]: Handling received BDX Message I (336719) chip[ATM]: Block I (336729) chip[ATM]: Block Counter: 0 I (336729) chip[ATM]: Data Length: 1024 I (336789) chip[ATM]: Sending BDX Message I (336789) chip[ATM]: BlockQuery I (336789) chip[ATM]: Block Counter: 1 D (336789) chip[SWU]: BDX::SendMessage D (336799) chip[EM]: Piggybacking Ack for MessageCounter:7030133 on exchange: 65104i I (336799) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794516. I (336819) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794516 to 0x0000000000003039 (1) at monotonic time: 0000000000051FC6 msec I (337099) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030134 on exchange 65104i D (337099) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (337109) chip[EM]: Rxd Ack; Removing MessageCounter:13794516 from Retrans Table on exchange 65104i D (337119) chip[EM]: Removed CHIP MessageCounter:13794516 from RetransTable on exchange 65104i I (337129) chip[ATM]: Handling received BDX Message I (337129) chip[ATM]: Block I (337139) chip[ATM]: Block Counter: 1 I (337139) chip[ATM]: Data Length: 1024 D (337149) chip[DMG]: Endpoint 0, Cluster 0x0000_002A update version to 7fe5fa7 I (337149) echo-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0000_002A', EndPoint ID: '0x00', Attribute ID: '0x0000_0003' I (337159) echo-devicecallbacks: Unhandled cluster ID: 0x0000_002A I (337169) echo-devicecallbacks: Current free heap: 154268  I (337179) chip[ATM]: Sending BDX Message I (337179) chip[ATM]: BlockQuery I (337189) chip[ATM]: Block Counter: 2 D (337189) chip[SWU]: BDX::SendMessage D (337199) chip[EM]: Piggybacking Ack for MessageCounter:7030134 on exchange: 65104i I (337199) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794517. I (337219) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794517 to 0x0000000000003039 (1) at monotonic time: 0000000000052156 msec I (337509) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030135 on exchange 65104i D (337509) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (337519) chip[EM]: Rxd Ack; Removing MessageCounter:13794517 from Retrans Table on exchange 65104i D (337529) chip[EM]: Removed CHIP MessageCounter:13794517 from RetransTable on exchange 65104i I (337539) chip[ATM]: Handling received BDX Message I (337539) chip[ATM]: Block I (337549) chip[ATM]: Block Counter: 2 I (337549) chip[ATM]: Data Length: 1024 I (337559) chip[ATM]: Sending BDX Message I (337559) chip[ATM]: BlockQuery I (337559) chip[ATM]: Block Counter: 3 D (337569) chip[SWU]: BDX::SendMessage D (337569) chip[EM]: Piggybacking Ack for MessageCounter:7030135 on exchange: 65104i I (337579) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794518. I (337599) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794518 to 0x0000000000003039 (1) at monotonic time: 00000000000522CF msec I (337919) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030136 on exchange 65104i D (337919) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (337929) chip[EM]: Rxd Ack; Removing MessageCounter:13794518 from Retrans Table on exchange 65104i D (337939) chip[EM]: Removed CHIP MessageCounter:13794518 from RetransTable on exchange 65104i I (337949) chip[ATM]: Handling received BDX Message I (337949) chip[ATM]: Block I (337949) chip[ATM]: Block Counter: 3 I (337959) chip[ATM]: Data Length: 1024 I (337969) chip[ATM]: Sending BDX Message I (337969) chip[ATM]: BlockQuery I (337969) chip[ATM]: Block Counter: 4 D (337979) chip[SWU]: BDX::SendMessage D (337979) chip[EM]: Piggybacking Ack for MessageCounter:7030136 on exchange: 65104i I (337989) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794519. I (337999) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794519 to 0x0000000000003039 (1) at monotonic time: 0000000000052468 msec I (338329) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030137 on exchange 65104i D (338329) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (338339) chip[EM]: Rxd Ack; Removing MessageCounter:13794519 from Retrans Table on exchange 65104i D (338349) chip[EM]: Removed CHIP MessageCounter:13794519 from RetransTable on exchange 65104i I (338359) chip[ATM]: Handling received BDX Message I (338359) chip[ATM]: Block I (338359) chip[ATM]: Block Counter: 4 I (338369) chip[ATM]: Data Length: 1024 I (338439) chip[ATM]: Sending BDX Message I (338439) chip[ATM]: BlockQuery I (338439) chip[ATM]: Block Counter: 5 D (338439) chip[SWU]: BDX::SendMessage D (338439) chip[EM]: Piggybacking Ack for MessageCounter:7030137 on exchange: 65104i I (338449) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794520. I (338469) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794520 to 0x0000000000003039 (1) at monotonic time: 0000000000052637 msec E (338479) chip[DL]: Long dispatch time: 110 ms, for event type 2 D (338839) chip[EM]: Retransmitting MessageCounter:13794520 on exchange 65104i Send Cnt 1 I (338839) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794520 to 0x0000000000003039 (1) at monotonic time: 00000000000527A9 msec I (338849) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030138 on exchange 65104i D (338859) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (338869) chip[EM]: Rxd Ack; Removing MessageCounter:13794520 from Retrans Table on exchange 65104i D (338879) chip[EM]: Removed CHIP MessageCounter:13794520 from RetransTable on exchange 65104i I (338879) chip[ATM]: Handling received BDX Message I (338889) chip[ATM]: Block I (338889) chip[ATM]: Block Counter: 5 I (338899) chip[ATM]: Data Length: 1024 I (338909) chip[ATM]: Sending BDX Message I (338909) chip[ATM]: BlockQuery I (338909) chip[ATM]: Block Counter: 6 D (338919) chip[SWU]: BDX::SendMessage D (338919) chip[EM]: Piggybacking Ack for MessageCounter:7030138 on exchange: 65104i I (338929) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794521. I (338939) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794521 to 0x0000000000003039 (1) at monotonic time: 0000000000052813 msec I (338979) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7030139 on exchange 65104i D (338989) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (338989) chip[EM]: CHIP MessageCounter:13794520 not in RetransTable on exchange 65104i I (339249) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030140 on exchange 65104i D (339249) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (339259) chip[EM]: Rxd Ack; Removing MessageCounter:13794521 from Retrans Table on exchange 65104i D (339269) chip[EM]: Removed CHIP MessageCounter:13794521 from RetransTable on exchange 65104i I (339279) chip[ATM]: Handling received BDX Message I (339279) chip[ATM]: Block I (339279) chip[ATM]: Block Counter: 6 I (339289) chip[ATM]: Data Length: 1024 I (339299) chip[ATM]: Sending BDX Message I (339299) chip[ATM]: BlockQuery I (339299) chip[ATM]: Block Counter: 7 D (339309) chip[SWU]: BDX::SendMessage D (339309) chip[EM]: Piggybacking Ack for MessageCounter:7030140 on exchange: 65104i I (339319) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794522. I (339329) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794522 to 0x0000000000003039 (1) at monotonic time: 000000000005299A msec I (339659) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030141 on exchange 65104i D (339659) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (339669) chip[EM]: Rxd Ack; Removing MessageCounter:13794522 from Retrans Table on exchange 65104i D (339679) chip[EM]: Removed CHIP MessageCounter:13794522 from RetransTable on exchange 65104i I (339689) chip[ATM]: Handling received BDX Message I (339689) chip[ATM]: Block I (339699) chip[ATM]: Block Counter: 7 I (339699) chip[ATM]: Data Length: 1024 I (339709) chip[ATM]: Sending BDX Message I (339709) chip[ATM]: BlockQuery I (339709) chip[ATM]: Block Counter: 8 D (339719) chip[SWU]: BDX::SendMessage D (339719) chip[EM]: Piggybacking Ack for MessageCounter:7030141 on exchange: 65104i I (339729) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794523. I (339739) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794523 to 0x0000000000003039 (1) at monotonic time: 0000000000052B34 msec I (340069) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030142 on exchange 65104i D (340069) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (340079) chip[EM]: Rxd Ack; Removing MessageCounter:13794523 from Retrans Table on exchange 65104i D (340089) chip[EM]: Removed CHIP MessageCounter:13794523 from RetransTable on exchange 65104i I (340099) chip[ATM]: Handling received BDX Message I (340099) chip[ATM]: Block I (340109) chip[ATM]: Block Counter: 8 I (340109) chip[ATM]: Data Length: 1024 I (340169) chip[ATM]: Sending BDX Message I (340169) chip[ATM]: BlockQuery I (340169) chip[ATM]: Block Counter: 9 D (340169) chip[SWU]: BDX::SendMessage D (340179) chip[EM]: Piggybacking Ack for MessageCounter:7030142 on exchange: 65104i I (340179) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794524. I (340199) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794524 to 0x0000000000003039 (1) at monotonic time: 0000000000052CFA msec D (340549) chip[EM]: Retransmitting MessageCounter:13794524 on exchange 65104i Send Cnt 1 I (340549) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794524 to 0x0000000000003039 (1) at monotonic time: 0000000000052E57 msec I (340559) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030143 on exchange 65104i D (340569) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (340579) chip[EM]: Rxd Ack; Removing MessageCounter:13794524 from Retrans Table on exchange 65104i D (340589) chip[EM]: Removed CHIP MessageCounter:13794524 from RetransTable on exchange 65104i I (340589) chip[ATM]: Handling received BDX Message I (340599) chip[ATM]: Block I (340599) chip[ATM]: Block Counter: 9 I (340609) chip[ATM]: Data Length: 1024 I (340619) chip[ATM]: Sending BDX Message I (340619) chip[ATM]: BlockQuery I (340619) chip[ATM]: Block Counter: 10 D (340629) chip[SWU]: BDX::SendMessage D (340629) chip[EM]: Piggybacking Ack for MessageCounter:7030143 on exchange: 65104i I (340639) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794525. I (340649) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794525 to 0x0000000000003039 (1) at monotonic time: 0000000000052EC1 msec I (340789) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7030144 on exchange 65104i D (340789) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (340789) chip[EM]: CHIP MessageCounter:13794524 not in RetransTable on exchange 65104i I (340989) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030145 on exchange 65104i D (340989) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (340999) chip[EM]: Rxd Ack; Removing MessageCounter:13794525 from Retrans Table on exchange 65104i D (341009) chip[EM]: Removed CHIP MessageCounter:13794525 from RetransTable on exchange 65104i I (341019) chip[ATM]: Handling received BDX Message I (341019) chip[ATM]: Block I (341029) chip[ATM]: Block Counter: 10 I (341029) chip[ATM]: Data Length: 1024 I (341039) chip[ATM]: Sending BDX Message I (341039) chip[ATM]: BlockQuery I (341039) chip[ATM]: Block Counter: 11 D (341049) chip[SWU]: BDX::SendMessage D (341049) chip[EM]: Piggybacking Ack for MessageCounter:7030145 on exchange: 65104i I (341059) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794526. I (341079) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794526 to 0x0000000000003039 (1) at monotonic time: 0000000000053067 msec D (341399) chip[EM]: Retransmitting MessageCounter:13794526 on exchange 65104i Send Cnt 1 I (341399) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794526 to 0x0000000000003039 (1) at monotonic time: 00000000000531AC msec I (341419) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030146 on exchange 65104i D (341419) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (341429) chip[EM]: Rxd Ack; Removing MessageCounter:13794526 from Retrans Table on exchange 65104i D (341439) chip[EM]: Removed CHIP MessageCounter:13794526 from RetransTable on exchange 65104i I (341449) chip[ATM]: Handling received BDX Message I (341449) chip[ATM]: Block I (341459) chip[ATM]: Block Counter: 11 I (341459) chip[ATM]: Data Length: 1024 I (341469) chip[ATM]: Sending BDX Message I (341469) chip[ATM]: BlockQuery I (341469) chip[ATM]: Block Counter: 12 D (341479) chip[SWU]: BDX::SendMessage D (341479) chip[EM]: Piggybacking Ack for MessageCounter:7030146 on exchange: 65104i I (341489) chip[IN]: Prepared secure message 0x3ffc784c to 0x0000000000003039 (1) of type 0x10 and protocolId (0, 2) on exchange 65104i with MessageCounter:13794527. I (341509) chip[IN]: Sending encrypted msg 0x3ffc784c with MessageCounter:13794527 to 0x0000000000003039 (1) at monotonic time: 0000000000053216 msec I (341539) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7030147 on exchange 65104i D (341549) chip[EM]: Found matching exchange: 65104i, Delegate: 0x3ffc8d5c D (341549) chip[EM]: CHIP MessageCounter:13794526 not in RetransTable on exchange 65104i I (341709) chip[EM]: Received message of type 0x11 with protocolId (0, 2) and MessageCounter:7030148 on exchange 65104i Executing action: erase-flash Running esptool.py in directory /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build Executing "/Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python /Users/rohitjadhav/esp-idf/components/esptool_py/esptool/esptool.py -p /dev/cu.usbserial-14430 -b 460800 --before default_reset --after hard_reset --chip esp32 erase_flash"... Executing action: flash Running ninja in directory /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build Executing "ninja flash"... Executing action: monitor Running idf_monitor in directory /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32 Executing "/Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python /Users/rohitjadhav/esp-idf/tools/idf_monitor.py -p /dev/cu.usbserial-14430 -b 115200 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 0 /Users/rohitjadhav/connectedhomeip/examples/ota-requestor-app/esp32/build/chip-ota-requestor-app.elf -m '/Users/rohitjadhav/connectedhomeip/.environment/pigweed-venv/bin/python' '/Users/rohitjadhav/esp-idf/tools/idf.py' '-p' '/dev/cu.usbserial-14430'"... Done