search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.42k stars 1.99k forks source link

matter m5stack(all-clusters-app) disconnects few seconds after successful commissioning in apple home app #11181

Closed bndkk closed 2 years ago

bndkk commented 2 years ago

After setting up an m5stack according to the enable matter pdf (https://download.developer.apple.com/iOS/iOS_Logs/EnableMatter_Instructions.pdf) and commissioning it with the home app on a matter enabled iPad, the device is working fine for about 5 seconds when it disconnects saying the device is not available. This happens when we use version 4.3 of the esp-idf tool to flash the device. If we use version 4.2 like specified in the instructions that is linked in the enable matter pdf(https://github.com/project-chip/connectedhomeip/tree/c5fff8531346609d3e4e75ea4ab7efba2d90a7f0/examples/all-clusters-app/esp32) the m5stack won’t even boot normally and gets stuck in a panic_abort loop. -> see logs

We have also tested this with the all-clusters-app from the master branch of the chip project, which we could successfully launch on the device but then the connection to the home app didn’t work at all.

Logs ——— LOG chip project commit 5ed637736e231abc5e75f3ddc96e0e73501877a1 with esp-idf release/v4.3 ——— Executing action: flash Running ninja in directory /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build Executing "ninja flash"... [1/9] Performing build step for 'bootloader' ninja: no work to do. [2/7] Performing build step for 'chip_gn' ninja: no work to do. [2/3] cd /Users/benedek.kaman/smoca/matter/espv4.3/components/e...moca/matter/espv4.3/components/esptool_py/run_serial_tool.cmak esptool.py esp32 -p /dev/tty.usbserial-0252EF6C -b 460800 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 40m --flash_size 2MB 0x8000 partition_table/partition-table.bin 0x1000 bootloader/bootloader.bin 0x10000 chip-all-clusters-app.bin esptool.py v3.2-dev Serial port /dev/tty.usbserial-0252EF6C Connecting.... Chip is ESP32-D0WDQ6-V3 (revision 3) Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None Crystal is 40MHz MAC: 08:3a:f2:6a:45:88 Uploading stub... Running stub... Stub running... Changing baud rate to 460800 Changed. Configuring flash size... Flash will be erased from 0x00008000 to 0x00008fff... Flash will be erased from 0x00001000 to 0x00007fff... Flash will be erased from 0x00010000 to 0x00138fff... Compressed 3072 bytes to 106... Writing at 0x00008000... (100 %) Wrote 3072 bytes (106 compressed) at 0x00008000 in 0.1 seconds (effective 391.8 kbit/s)... Hash of data verified. Compressed 25296 bytes to 15477... Writing at 0x00001000... (100 %) Wrote 25296 bytes (15477 compressed) at 0x00001000 in 0.8 seconds (effective 265.5 kbit/s)... Hash of data verified. Compressed 1213232 bytes to 779341... Writing at 0x00010000... (2 %) Writing at 0x0001e7b6... (4 %) Writing at 0x000283e4... (6 %) Writing at 0x000305d4... (8 %) Writing at 0x0003c869... (10 %) Writing at 0x00047315... (12 %) Writing at 0x0004d091... (14 %) Writing at 0x00052e54... (16 %) Writing at 0x000583d7... (18 %) Writing at 0x0005db38... (20 %) Writing at 0x0006300a... (22 %) Writing at 0x000689d4... (25 %) Writing at 0x0006e0cd... (27 %) Writing at 0x00073552... (29 %) Writing at 0x00078981... (31 %) Writing at 0x0007de47... (33 %) Writing at 0x000837a0... (35 %) Writing at 0x0008917e... (37 %) Writing at 0x0008e7d1... (39 %) Writing at 0x0009412e... (41 %) Writing at 0x00099f45... (43 %) Writing at 0x000a021f... (45 %) Writing at 0x000a5da6... (47 %) Writing at 0x000acb6a... (50 %) Writing at 0x000b26f1... (52 %) Writing at 0x000b83e7... (54 %) Writing at 0x000bd886... (56 %) Writing at 0x000c2e0e... (58 %) Writing at 0x000c7ff5... (60 %) Writing at 0x000cd468... (62 %) Writing at 0x000d22eb... (64 %) Writing at 0x000d731d... (66 %) Writing at 0x000dc467... (68 %) Writing at 0x000e1a82... (70 %) Writing at 0x000e6d46... (72 %) Writing at 0x000ec057... (75 %) Writing at 0x000f1554... (77 %) Writing at 0x000f6c0e... (79 %) Writing at 0x000fc4d8... (81 %) Writing at 0x00102390... (83 %) Writing at 0x00107b9d... (85 %) Writing at 0x0010e5ba... (87 %) Writing at 0x00116c49... (89 %) Writing at 0x0011f12b... (91 %) Writing at 0x00125074... (93 %) Writing at 0x0012a77a... (95 %) Writing at 0x0012fc9f... (97 %) Writing at 0x001350d0... (100 %) Wrote 1213232 bytes (779341 compressed) at 0x00010000 in 19.0 seconds (effective 512.1 kbit/s)... Hash of data verified.

Leaving... Hard resetting via RTS pin... Executing action: monitor Running idf_monitor in directory /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32 Executing "/Users/benedek.kaman/smoca/matter/connectedhomeip/.environment/pigweed-venv/bin/python /Users/benedek.kaman/smoca/matter/espv4.3/tools/idf_monitor.py -p /dev/tty.usbserial-0252EF6C -b 115200 --toolchain-prefix xtensa-esp32-elf- /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.elf -m '/Users/benedek.kaman/smoca/matter/connectedhomeip/.environment/pigweed-venv/bin/python' '/Users/benedek.kaman/smoca/matter/espv4.3/tools/idf.py' '-p' '/dev/tty.usbserial-0252EF6C'"... --- WARNING: Serial ports accessed as /dev/tty.* will hang gdb if launched. --- Using /dev/cu.usbserial-0252EF6C instead... --- idf_monitor on /dev/cu.usbserial-0252EF6C 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ? ?????}???с RF data 01 01ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:7136 load:0x40078000,len:14356 ho 0 tail 12 room 4 load:0x40080400,len:3716 0x40080400: _init at ??:?

entry 0x40080680 I (29) boot: ESP-IDF v4.3.1-245-gba15ac8634 2nd stage bootloader I (29) boot: compile time 18:56:27 I (29) boot: chip revision: 3 I (33) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (40) boot.esp32: SPI Speed : 40MHz I (45) boot.esp32: SPI Mode : DIO I (50) boot.esp32: SPI Flash Size : 2MB I (54) boot: Enabling RNG early entropy source... I (60) boot: Partition Table: I (63) boot: ## Label Usage Type ST Offset Length I (70) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (78) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (85) boot: 2 factory factory app 00 00 00010000 001e6400 I (93) boot: End of partition table I (97) boot_comm: chip revision: 3, min. application chip revision: 0 I (104) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=3008ch (196748) map I (184) esp_image: segment 1: paddr=000400b4 vaddr=3ffbdb60 size=07b40h ( 31552) load I (196) esp_image: segment 2: paddr=00047bfc vaddr=40080000 size=0841ch ( 33820) load I (211) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=d243ch (861244) map I (522) esp_image: segment 4: paddr=00122464 vaddr=4008841c size=15e8ch ( 89740) load I (560) esp_image: segment 5: paddr=001382f8 vaddr=50000000 size=00010h ( 16) load I (575) boot: Loaded app from partition at offset 0x10000 I (575) boot: Disabling RNG early entropy source... I (587) cpu_start: Pro cpu up. I (587) cpu_start: Starting app cpu, entry point is 0x4008150c 0x4008150c: call_start_cpu1 at /Users/benedek.kaman/smoca/matter/espv4.3/components/esp_system/port/cpu_start.c:140

I (0) cpu_start: App cpu up. I (603) cpu_start: Pro cpu start user code I (603) cpu_start: cpu freq: 160000000 I (604) cpu_start: Application information: I (608) cpu_start: Project name: chip-all-clusters-app I (614) cpu_start: App version: test_event_4_2021_07_06-519-g5e I (621) cpu_start: Compile time: Oct 28 2021 18:56:28 I (627) cpu_start: ELF file SHA256: 23517498eadc35c9... I (633) cpu_start: ESP-IDF: v4.3.1-245-gba15ac8634 I (640) heap_init: Initializing. RAM available for dynamic allocation: I (647) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (653) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (659) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (665) heap_init: At 3FFD5EF0 len 0000A110 (40 KiB): DRAM I (671) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (677) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (684) heap_init: At 4009E2A8 len 00001D58 (7 KiB): IRAM I (691) spi_flash: detected chip: generic I (695) spi_flash: flash io: dio W (699) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (715) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (723) all-clusters-app: All Clusters Demo! I (733) all-clusters-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (733) all-clusters-app: silicon revision 3, I (743) all-clusters-app: 2MB external flash

I (803) wifi:wifi driver task: 3ffde248, prio:23, stack:6656, core=0 I (803) system_api: Base MAC address is not set I (803) system_api: read default base MAC address from EFUSE I (833) wifi:wifi firmware version: 88c8747 I (833) wifi:wifi certification version: v7.0 I (833) wifi:config NVS flash: enabled I (833) wifi:config nano formating: disabled I (843) wifi:Init data frame dynamic rx buffer num: 32 I (853) wifi:Init management frame dynamic rx buffer num: 32 I (853) wifi:Init management short buffer num: 32 I (863) wifi:Init dynamic tx buffer num: 32 I (863) wifi:Init static rx buffer size: 1600 I (863) wifi:Init static rx buffer num: 10

I (873) wifi:Init dynamic rx buffer num: 32 I (873) wifi_init: rx ba win: 6 I (883) wifi_init: tcpip mbox: 32 I (883) wifi_init: udp mbox: 6 I (883) wifi_init: tcp mbox: 6 I (883) wifi_init: tcp tx win: 5744 I (903) wifi_init: tcp rx win: 5744 I (903) wifi_init: tcp mss: 1440 I (903) wifi_init: WiFi IRAM OP enabled I (913) wifi_init: WiFi RX IRAM OP enabled V (913) chip[DL]: CHIP task running I (913) chip[ZCL]: Using ZAP configuration... I (913) BTDM_INIT: BT controller compile version [1e3e264] I (923) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (933) chip[ZCL]: deactivate report event I (943) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0002' I (953) app-devicecallbacks: Unhandled cluster ID: 257 I (963) app-devicecallbacks: Current free heap: 101808

I (963) chip[ZCL]: 0x3f40b869ep 1 clus 101 attr 3 not supported I (973) chip[ZCL]: Failed to write DoorState attribute: 0x86 I (973) chip[ZCL]: 0x3f40b869ep 1 clus 101 attr 21 not supported I (983) chip[ZCL]: Failed to write Language attribute: 0x86 I (993) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. V (1003) chip[DIS]: Set the fabric pairing table delegate I (1003) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (1013) chip[ZCL]: OpCreds: Stored 0 fabrics in fabrics list attribute. I (1013) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (1023) app-devicecallbacks: Unhandled cluster ID: 62 I (1043) app-devicecallbacks: Current free heap: 101808

I (1043) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (1283) app-devicecallbacks: Unhandled cluster ID: 62 I (1293) app-devicecallbacks: Current free heap: 88152

I (1293) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001' I (1313) CHIP[DL]: BLE host-controller synced I (1313) app-devicecallbacks: Unhandled cluster ID: 40 I (1323) app-devicecallbacks: Current free heap: 88152

I (1323) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002' I (1333) app-devicecallbacks: Unhandled cluster ID: 40 I (1343) app-devicecallbacks: Current free heap: 88152

I (1353) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0003' I (1363) app-devicecallbacks: Unhandled cluster ID: 40 I (1363) app-devicecallbacks: Current free heap: 88152

I (1373) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0004' I (1383) app-devicecallbacks: Unhandled cluster ID: 40 I (1383) app-devicecallbacks: Current free heap: 88152

I (1403) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0008' I (1413) app-devicecallbacks: Unhandled cluster ID: 40 I (1413) app-devicecallbacks: Current free heap: 88152

I (1423) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0007' I (1433) app-devicecallbacks: Unhandled cluster ID: 40 I (1433) app-devicecallbacks: Current free heap: 88152

I (1443) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x000a' I (1463) app-devicecallbacks: Unhandled cluster ID: 40 I (1463) app-devicecallbacks: Current free heap: 88152

I (1473) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0009' I (1483) app-devicecallbacks: Unhandled cluster ID: 40 I (1483) app-devicecallbacks: Current free heap: 88152

I (1493) chip[ZCL]: Start identify callback on endpoint 1 time 0 I (1503) chip[ZCL]: Stop identify callback on endpoint 1 I (1503) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1513) app-devicecallbacks: Unhandled cluster ID: 4 I (1523) app-devicecallbacks: Current free heap: 88152

I (1523) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000' I (1533) app-devicecallbacks: Unhandled cluster ID: 5 I (1543) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (1553) app-devicecallbacks: Current free heap: 88152

GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40I (1563) chip[ZCL]: Initialize PCC Server Cluster [EP:1]

I (1573) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007' I (1583) chip[DL]: CHIPoBLE advertising started I (1593) app-devicecallbacks: Unhandled cluster ID: 768 E (1603) chip[DL]: Long dispatch time: 690 ms, for event type 2 I (1603) app-devicecallbacks: Current free heap: 88120

I (1613) chip[DL]: Starting ESP WiFi layer I (1613) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008' I (1623) wifi:mode : sta (08:3a:f2:6a:45:88) I (1643) wifi:enable tsf W (1643) wifi:Haven't to connect to a suitable AP now! I (1643) chip[DL]: Done driving station state, nothing else to do... I (1633) app-devicecallbacks: Unhandled cluster ID: 768 W (1653) wifi:Haven't to connect to a suitable AP now! I (1653) app-devicecallbacks: Current free heap: 85216

I (1663) chip[DL]: Done driving station state, nothing else to do... I (1673) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001' I (1673) app-devicecallbacks: Current free heap: 85216

I (1683) app-devicecallbacks: Unhandled cluster ID: 768 I (1693) chip[DL]: WIFI_EVENT_STA_START I (1693) app-devicecallbacks: Current free heap: 85216

W (1703) wifi:Haven't to connect to a suitable AP now! I (1703) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1723) chip[DL]: Done driving station state, nothing else to do... I (1733) app-devicecallbacks: Unhandled cluster ID: 1030 I (1733) app-devicecallbacks: Current free heap: 85216

I (1743) app-devicecallbacks: Current free heap: 85216

I (1753) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1763) app-devicecallbacks: Unhandled cluster ID: 1030 I (1773) app-devicecallbacks: Current free heap: 85216

I (1783) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! I (1783) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!! I (1793) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001' I (1803) app-devicecallbacks: Unhandled cluster ID: 1280 I (1803) app-devicecallbacks: Current free heap: 85216

I (1813) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002' I (1833) app-devicecallbacks: Unhandled cluster ID: 1280 I (1833) app-devicecallbacks: Current free heap: 85216

I (1843) chip[ZCL]: Failed to send IAS Zone update. Err 0x70 I (1843) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001' I (1853) app-devicecallbacks: Unhandled cluster ID: 1030 I (1863) app-devicecallbacks: Current free heap: 85216

I (1873) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002' I (1883) app-devicecallbacks: Unhandled cluster ID: 1030 I (1883) app-devicecallbacks: Current free heap: 85216

V (1893) chip[DIS]: Init fabric pairing table with server storage I (1893) chip[SVR]: Retrieved value from server storage. I (1903) chip[SVR]: Retrieved value from server storage. I (1903) chip[SVR]: Retrieved value from server storage. I (1923) chip[SVR]: Retrieved value from server storage. I (1923) chip[SVR]: Retrieved value from server storage. I (1933) chip[SVR]: Retrieved value from server storage. I (1933) chip[SVR]: Retrieved value from server storage. I (1943) chip[SVR]: Retrieved value from server storage. I (1943) chip[SVR]: Retrieved value from server storage. I (1953) chip[SVR]: Retrieved value from server storage. I (1963) chip[SVR]: Retrieved value from server storage. I (1963) chip[SVR]: Retrieved value from server storage. I (1973) chip[SVR]: Retrieved value from server storage. I (1973) chip[SVR]: Retrieved value from server storage. I (1983) chip[SVR]: Retrieved value from server storage. I (1983) chip[SVR]: Retrieved value from server storage. V (1993) chip[IN]: UDP::Init bind&listen port=5540 V (2003) chip[IN]: UDP::Init bind&listen port=5540 V (2003) chip[IN]: TransportMgr initialized I (2023) chip[DL]: NVS set: chip-counters/GlobalMCTR = 10000 (0x2710) I (2023) chip[SVR]: Retrieved value from server storage. I (2023) chip[SVR]: Delete value in server storage V (2043) chip[DIS]: Fabric 1 is not yet configured I (2043) chip[SVR]: Retrieved value from server storage. I (2043) chip[SVR]: Delete value in server storage V (2063) chip[DIS]: Fabric 2 is not yet configured I (2063) chip[SVR]: Retrieved value from server storage. I (2073) chip[SVR]: Delete value in server storage V (2093) chip[DIS]: Fabric 3 is not yet configured I (2093) chip[SVR]: Retrieved value from server storage. I (2093) chip[SVR]: Delete value in server storage V (2113) chip[DIS]: Fabric 4 is not yet configured I (2113) chip[SVR]: Retrieved value from server storage. I (2113) chip[SVR]: Delete value in server storage V (2133) chip[DIS]: Fabric 5 is not yet configured I (2133) chip[SVR]: Retrieved value from server storage. I (2133) chip[SVR]: Delete value in server storage V (2153) chip[DIS]: Fabric 6 is not yet configured I (2153) chip[SVR]: Retrieved value from server storage. I (2163) chip[SVR]: Delete value in server storage V (2183) chip[DIS]: Fabric 7 is not yet configured I (2183) chip[SVR]: Retrieved value from server storage. I (2183) chip[SVR]: Delete value in server storage V (2203) chip[DIS]: Fabric 8 is not yet configured I (2203) chip[SVR]: Retrieved value from server storage. I (2203) chip[SVR]: Delete value in server storage V (2223) chip[DIS]: Fabric 9 is not yet configured I (2223) chip[SVR]: Retrieved value from server storage. I (2223) chip[SVR]: Delete value in server storage V (2243) chip[DIS]: Fabric 10 is not yet configured I (2243) chip[SVR]: Retrieved value from server storage. I (2243) chip[SVR]: Delete value in server storage V (2263) chip[DIS]: Fabric 11 is not yet configured I (2273) chip[SVR]: Retrieved value from server storage. I (2273) chip[SVR]: Delete value in server storage V (2293) chip[DIS]: Fabric 12 is not yet configured I (2293) chip[SVR]: Retrieved value from server storage. I (2293) chip[SVR]: Delete value in server storage V (2313) chip[DIS]: Fabric 13 is not yet configured I (2313) chip[SVR]: Retrieved value from server storage. I (2313) chip[SVR]: Delete value in server storage V (2333) chip[DIS]: Fabric 14 is not yet configured I (2333) chip[SVR]: Retrieved value from server storage. I (2333) chip[SVR]: Delete value in server storage V (2353) chip[DIS]: Fabric 15 is not yet configured I (2363) chip[SVR]: Retrieved value from server storage. I (2363) chip[SVR]: Delete value in server storage V (2383) chip[DIS]: Fabric 16 is not yet configured I (2383) chip[SVR]: Retrieved value from server storage. I (2383) chip[SVR]: Retrieved value from server storage. I (2393) chip[SVR]: Retrieved value from server storage. I (2393) chip[SVR]: Retrieved value from server storage. I (2403) chip[SVR]: Retrieved value from server storage. I (2413) chip[SVR]: Retrieved value from server storage. I (2423) chip[SVR]: Retrieved value from server storage. I (2423) chip[SVR]: Retrieved value from server storage. I (2423) chip[SVR]: Retrieved value from server storage. I (2433) chip[SVR]: Retrieved value from server storage. I (2433) chip[SVR]: Retrieved value from server storage. I (2443) chip[SVR]: Retrieved value from server storage. I (2453) chip[SVR]: Retrieved value from server storage. I (2463) chip[SVR]: Retrieved value from server storage. I (2463) chip[SVR]: Retrieved value from server storage. I (2473) chip[SVR]: Retrieved value from server storage. I (2473) chip[DIS]: WaitForPairing(): HasAdvertisementDelegate 1 I (2483) chip[DIS]: CHIP minimal mDNS started advertising. I (2483) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown I (2493) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840) I (2503) chip[DIS]: Start dns-sd server - no current nodeId I (2503) chip[DL]: Device already advertising, stop active advertisement and restart V (2513) chip[DIS]: Using wifi MAC for hostname GAP procedure initiated: stop advertising. V (2523) chip[DL]: rotatingDeviceId: 04006AB8F19A652A9F4D0A7F40585E288EEE GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40I (2533) chip[DIS]: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00

I (2563) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. V (2563) chip[SC]: Assigned local session key ID 0 V (2563) chip[SC]: Waiting for PBKDF param request I (2583) chip[IN]: CASE Server enabling CASE session setups I (2583) chip[SVR]: Server Listening... I (2593) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2593) app-devicecallbacks: Unhandled cluster ID: 1026 I (2603) app-devicecallbacks: Current free heap: 83116

I (2603) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2623) app-devicecallbacks: Unhandled cluster ID: 257 I (2633) app-devicecallbacks: Current free heap: 82996

I (2633) chip[ZCL]: Failed to read AutoRelockTime attribute: 0x86 I (2643) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000' I (2653) app-devicecallbacks: Current free heap: 82216

I (2663) chip[ZCL]: 0x3f40b869ep 2 clus 8 attr 0 not supported I (2673) all-clusters-app: Setup discriminator: 3840 (0xf00) I (2673) all-clusters-app: Setup PIN code: 20202021 (0x1344225) I (2683) all-clusters-app: Short Manual(decimal) setup code: 34970112332 I (2683) all-clusters-app: Long Manual(decimal) setup code: 749701123309050652796 I (2693) all-clusters-app: QR CODE Text: 'MT:YNJV7VSC00KA0648G00' I (2703) all-clusters-app: Copy/paste the below URL in a browser to see the QR CODE: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AYNJV7VSC00KA0648G00 I (3593) all-clusters-app: Display initialized (height 240, width 320) I (3603) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (3703) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (7463) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (7653) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (7953) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8143) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8493) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (8493) all-clusters-app: Opening QR code screen I (8503) all-clusters-app: QR CODE Text: 'MT:YNJV7VSC00KA0648G00' I (8503) all-clusters-app: Setup discriminator: 3840 (0xf00) I (8513) all-clusters-app: Setup PIN code: 20202021 (0x1344225) I (8783) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (15153) chip[DL]: BLE GAP connection established (con 0) I (15153) chip[DL]: CHIPoBLE advertising stopped I (15153) app-devicecallbacks: Current free heap: 81092

I (15903) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (15903) chip[BLE]: local and remote recv window sizes = 3 I (15903) chip[BLE]: selected BTP version 3 I (15913) chip[BLE]: using BTP fragment sizes rx 128 / tx 20. I (16173) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1 I (16173) chip[DL]: CHIPoBLE subscribe received GATT procedure initiated: notify; att_handle=14 I (16183) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 V (16193) chip[IN]: BLE EndPoint 0x3ffd19f0 Connection Complete I (16203) app-devicecallbacks: CHIPoBLE connection established I (16213) app-devicecallbacks: Current free heap: 81092

I (16233) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (16233) chip[EM]: Received message of type 0x20 with vendorId 0x0000 and protocolId 0x0000 on exchange 1101 V (16243) chip[EM]: ec id: 1101, Delegate: 0x0x3ffc84c8 V (16243) chip[SC]: Received PBKDF param request GATT procedure initiated: notify; att_handle=14 I (16803) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 V (16803) chip[SC]: Sent PBKDF param response E (16813) chip[DL]: Long dispatch time: 580 ms, for event type 6 GATT procedure initiated: notify; att_handle=14 I (16823) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16863) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (16863) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (16883) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (16923) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (16923) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (17013) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (17013) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (17023) chip[EM]: Received message of type 0x22 with vendorId 0x0000 and protocolId 0x0000 on exchange 1101 V (17043) chip[SC]: Received spake2p msg1 V (18063) chip[SC]: Peer assigned session key ID 5 I (19563) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 V (19583) chip[SC]: Sent spake2p msg2 E (19583) chip[DL]: Long dispatch time: 2570 ms, for event type 6 GATT procedure initiated: notify; att_handle=14 I (19603) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (19603) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19653) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (19653) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (19673) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19713) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (19713) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (19733) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19773) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (19773) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19893) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (19893) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (19903) chip[EM]: Received message of type 0x24 with vendorId 0x0000 and protocolId 0x0000 on exchange 1101 V (19923) chip[SC]: Received spake2p msg3 V (19923) chip[IN]: New secure session created for device 0x0000000000000000, key 5!! I (19933) chip[SVR]: Device completed SPAKE2+ handshake I (19933) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (19943) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (19953) chip[DIS]: CHIP minimal mDNS started advertising. I (19953) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (19963) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown I (19973) chip[DIS]: Start dns-sd server - no current nodeId V (19983) chip[DIS]: Using wifi MAC for hostname V (19983) chip[DL]: rotatingDeviceId: 04006AB8F19A652A9F4D0A7F40585E288EEE I (19983) chip[DIS]: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00 I (20003) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'. I (20013) chip[SVR]: Device completed Rendezvous process E (20013) chip[DL]: Long dispatch time: 120 ms, for event type 6 I (20023) chip[EM]: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 1102 V (20033) chip[EM]: ec id: 1102, Delegate: 0x0x3ffcedf0 V (20043) chip[DMG]: ICR moving to [Initialize] V (20043) chip[ZCL]: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_0004 Endpoint=0 I (20053) chip[ZCL]: OpCreds: commissioner has requested an OpCSR I (21103) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0 V (21113) chip[DMG]: ICR moving to [AddCommand] V (21113) chip[IN]: Secure message was encrypted: Msg ID 1 I (21123) chip[IN]: Encrypted message 0x3ffe63fc to 0x0000000000000000 of type 9 and protocolId 5 on exchange 1102. I (21123) chip[IN]: Sending msg 0x3ffe63fc to 0x0000000000000000 at utc time: 20400 msec I (21133) chip[IN]: Sending secure msg on generic transport GATT procedure initiated: notify; att_handle=14 I (21153) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21163) chip[IN]: Secure msg send status Success V (21163) chip[DMG]: ICR moving to [ Sending] V (21163) chip[DMG]: ICR moving to [Uninitiali] E (21173) chip[DL]: Long dispatch time: 1150 ms, for event type 6 I (21213) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21213) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21233) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21303) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21303) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21323) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21363) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21363) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21383) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21423) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21423) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21443) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21483) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21483) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21503) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21543) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21543) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21563) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21603) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21603) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21623) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21663) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21663) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (21683) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21723) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21723) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21813) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21813) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21873) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (21933) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (21933) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (21953) chip[EM]: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 1103 V (21963) chip[EM]: ec id: 1103, Delegate: 0x0x3ffcedf0 V (21963) chip[DMG]: ICR moving to [Initialize] V (21963) chip[ZCL]: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_000B Endpoint=0 I (21973) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert V (21993) chip[DMG]: ICR moving to [AddCommand] V (21993) chip[IN]: Secure message was encrypted: Msg ID 2 I (21993) chip[IN]: Encrypted message 0x3ffe63fc to 0x0000000000000000 of type 9 and protocolId 5 on exchange 1103. I (22003) chip[IN]: Sending msg 0x3ffe63fc to 0x0000000000000000 at utc time: 21280 msec I (22013) chip[IN]: Sending secure msg on generic transport I (22013) chip[IN]: Secure msg send status Success V (22023) chip[DMG]: ICR moving to [ Sending] V (22033) chip[DMG]: ICR moving to [Uninitiali] GATT procedure initiated: notify; att_handle=14 I (22043) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (22083) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (22083) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (22103) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (22143) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (22143) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (22203) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (22203) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (22263) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (22353) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (22353) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (22373) chip[EM]: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 1104 V (22383) chip[EM]: ec id: 1104, Delegate: 0x0x3ffcedf0 V (22383) chip[DMG]: ICR moving to [Initialize] V (22383) chip[ZCL]: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_0006 Endpoint=0 I (22393) chip[ZCL]: OpCreds: commissioner has added an Op Cert I (22403) chip[SVR]: Retrieved value from server storage. I (22413) chip[DIS]: Verifying the received credentials I (23453) chip[DIS]: Added new fabric at index: 1, Initialized: 1 I (23453) chip[DIS]: Assigned compressed fabric ID: 0x9BA870629BCC9203, node ID: 0x0000000000000003 I (23463) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I (23463) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000003, VendorId 0x1700 I (23483) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (23483) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (23503) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (23513) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (23523) app-devicecallbacks: Unhandled cluster ID: 62 I (23523) app-devicecallbacks: Current free heap: 69540

I (23533) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (23553) app-devicecallbacks: Unhandled cluster ID: 62 I (23553) app-devicecallbacks: Current free heap: 69540

I (23563) chip[SVR]: Stored value in server storage I (23623) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I (23623) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 00000000000000000, NodeId 3000017000000000C, VendorId 0x0000 I (23643) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (23653) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (23663) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (23673) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (23673) app-devicecallbacks: Unhandled cluster ID: 62 I (23693) app-devicecallbacks: Current free heap: 69412

I (23693) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (23703) app-devicecallbacks: Unhandled cluster ID: 62 I (23713) app-devicecallbacks: Current free heap: 69412

I (23713) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I (23723) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000003, VendorId 0x1700 I (23743) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (23753) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (23763) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (23773) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (23783) app-devicecallbacks: Unhandled cluster ID: 62 I (23783) app-devicecallbacks: Current free heap: 69412

I (23803) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (23813) app-devicecallbacks: Unhandled cluster ID: 62 I (23813) app-devicecallbacks: Current free heap: 69412

I (23823) chip[SVR]: Stored value in server storage I (23833) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I (23833) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 00000000000000000, NodeId 3000017000000000C, VendorId 0x0000 I (23843) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (23853) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (23873) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (23883) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (23893) app-devicecallbacks: Unhandled cluster ID: 62 I (23893) app-devicecallbacks: Current free heap: 69412

I (23903) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (23903) app-devicecallbacks: Unhandled cluster ID: 62 I (23913) app-devicecallbacks: Current free heap: 69412

V (23923) chip[DIS]: Using wifi MAC for hostname I (23933) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (23933) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. V (23943) chip[DMG]: ICR moving to [AddCommand] V (23943) chip[IN]: Secure message was encrypted: Msg ID 3 I (23953) chip[IN]: Encrypted message 0x3ffe63fc to 0x0000000000000000 of type 9 and protocolId 5 on exchange 1104. I (23973) chip[IN]: Sending msg 0x3ffe63fc to 0x0000000000000000 at utc time: 23250 msec I (23973) chip[IN]: Sending secure msg on generic transport I (23983) chip[IN]: Secure msg send status Success V (23983) chip[DMG]: ICR moving to [ Sending] V (23993) chip[DMG]: ICR moving to [Uninitiali] E (23993) chip[DL]: Long dispatch time: 1640 ms, for event type 6 GATT procedure initiated: notify; att_handle=14 I (24013) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24063) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24063) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (24083) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24123) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24123) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24213) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24213) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24233) chip[EM]: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 1105 V (24243) chip[EM]: ec id: 1105, Delegate: 0x0x3ffcedf0 V (24243) chip[DMG]: ICR moving to [Initialize] V (24243) chip[ZCL]: Received Cluster Command: Cluster=0x0000_0031 Command=0x0000_0002 Endpoint=0 V (24253) chip[ZCL]: WiFi provisioning data: SSID: smoca V (24253) chip[ZCL]: AddWiFiNetwork: 0 V (24263) chip[DMG]: ICR moving to [AddCommand] V (24273) chip[IN]: Secure message was encrypted: Msg ID 4 I (24273) chip[IN]: Encrypted message 0x3ffe63fc to 0x0000000000000000 of type 9 and protocolId 5 on exchange 1105. I (24283) chip[IN]: Sending msg 0x3ffe63fc to 0x0000000000000000 at utc time: 23560 msec I (24293) chip[IN]: Sending secure msg on generic transport I (24303) chip[IN]: Secure msg send status Success V (24303) chip[DMG]: ICR moving to [ Sending] V (24303) chip[DMG]: ICR moving to [Uninitiali] E (24323) chip[DL]: Long dispatch time: 110 ms, for event type 6 GATT procedure initiated: notify; att_handle=14 I (24333) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24393) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24393) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (24413) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24483) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24483) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24543) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24543) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24563) chip[EM]: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 1106 V (24573) chip[EM]: ec id: 1106, Delegate: 0x0x3ffcedf0 V (24573) chip[DMG]: ICR moving to [Initialize] V (24573) chip[ZCL]: Received Cluster Command: Cluster=0x0000_0031 Command=0x0000_000C Endpoint=0 I (24583) chip[NP]: ESP32NetworkProvisioningDelegate: SSID: smoca I (24593) chip[DL]: WiFi station mode change: Enabled -> Disabled I (24623) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP I (24623) wifi:mode : sta (08:3a:f2:6a:45:88) + softAP (08:3a:f2:6a:45:89) I (24633) wifi:Total power save buffer number: 16 I (24633) wifi:Init max length of beacon: 752/752 I (24643) wifi:Init max length of beacon: 752/752 I (24653) chip[DL]: WiFi station mode change: Disabled -> Enabled V (24653) chip[DIS]: Using wifi MAC for hostname I (24653) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (24663) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. E (24673) chip[DIS]: Operational advertising enabled I (24683) app-devicecallbacks: Current free heap: 68872

V (24683) chip[DMG]: ICR moving to [AddCommand] V (24693) chip[IN]: Secure message was encrypted: Msg ID 5 I (24693) chip[IN]: Encrypted message 0x3ffe63fc to 0x0000000000000000 of type 9 and protocolId 5 on exchange 1106. I (24703) chip[IN]: Sending msg 0x3ffe63fc to 0x0000000000000000 at utc time: 23980 msec I (24713) chip[IN]: Sending secure msg on generic transport I (24723) chip[IN]: Secure msg send status Success V (24733) chip[DMG]: ICR moving to [ Sending] V (24733) chip[DMG]: ICR moving to [Uninitiali] E (24733) chip[DL]: Long dispatch time: 190 ms, for event type 6 GATT procedure initiated: notify; att_handle=14 I (24743) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 W (24753) wifi:Haven't to connect to a suitable AP now! I (24763) chip[DL]: Attempting to connect WiFi station interface I (24773) chip[DL]: WiFi station state change: NotConnected -> Connecting I (24773) chip[DL]: Done driving station state, nothing else to do... W (24783) wifi:Haven't to connect to a suitable AP now! I (24783) chip[DL]: Attempting to connect WiFi station interface E (24803) wifi:sta is connecting, return error E (24803) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (24803) wifi:Haven't to connect to a suitable AP now! I (24813) chip[DL]: Attempting to connect WiFi station interface E (24813) wifi:sta is connecting, return error I (24813) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (24823) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN I (24833) chip[DL]: WIFI_EVENT_AP_START I (24833) chip[DL]: WiFi AP state change: NotActive -> Active I (24853) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA I (24853) wifi:mode : sta (08:3a:f2:6a:45:88) I (24863) chip[DL]: WiFi AP state change: Active -> Deactivating I (24863) app-devicecallbacks: Current free heap: 71804

GATT procedure initiated: notify; att_handle=14 I (24873) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24883) chip[DL]: WIFI_EVENT_AP_STOP I (24893) chip[DL]: WiFi AP state change: Deactivating -> NotActive I (24893) app-devicecallbacks: Current free heap: 73324

GATT procedure initiated: notify; att_handle=14 I (24903) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (24963) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 GATT procedure initiated: notify; att_handle=14 I (24963) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 GATT procedure initiated: notify; att_handle=14 I (27473) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (27543) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (27913) wifi:new:<11,0>, old:<1,1>, ap:<255,255>, sta:<11,0>, prof:1 I (28643) wifi:state: init -> auth (b0) I (28653) wifi:state: auth -> assoc (0) I (28663) wifi:state: assoc -> run (10) I (28703) wifi:connected with smoca, aid = 6, channel 11, BW20, bssid = 44:d9:e7:fd:f7:00 I (28703) wifi:security: WPA2-PSK, phy: bgn, rssi: -43 I (28713) wifi:pm start, type: 1

I (28723) chip[DL]: WIFI_EVENT_STA_CONNECTED I (28723) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded W (28723) wifi:idx:0 (ifx:0, 44:d9:e7:fd:f7:00), tid:0, ssn:0, winSize:64 I (28733) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (28743) chip[DL]: WiFi station interface connected I (28753) chip[DL]: Done driving station state, nothing else to do... I (28763) app-devicecallbacks: Current free heap: 74124

I (28763) chip[DL]: Updating advertising data I (28763) app-devicecallbacks: Current free heap: 74124

I (28783) wifi:AP's beacon interval = 102400 us, DTIM period = 3 I (29793) chip[DL]: IP_EVENT_GOT_IP6 I (29793) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:0a3a:f2ff:fe6a:4588 I (29803) app-devicecallbacks: Current free heap: 73592

I (29803) chip[DIS]: CHIP minimal mDNS started advertising. I (29813) chip[DIS]: Replying to DNS-SD service listing request I (29823) chip[DIS]: Replying to DNS-SD service listing request I (29823) chip[DIS]: Replying to DNS-SD service listing request I (29833) chip[DIS]: Replying to DNS-SD service listing request I (29833) chip[DIS]: Replying to DNS-SD service listing request I (29843) chip[DIS]: Replying to DNS-SD service listing request I (29853) chip[DIS]: Replying to DNS-SD service listing request I (29863) chip[DIS]: Broadcasting mDns reply V (29863) chip[DIS]: Using wifi MAC for hostname I (29863) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (29873) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (29883) app-devicecallbacks: Current free heap: 70828

GATT procedure initiated: notify; att_handle=14 I (30043) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 I (30313) chip[EM]: Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 1107 V (30313) chip[EM]: ec id: 1107, Delegate: 0x0x3ffc80a4 I (30323) chip[IN]: CASE Server received SigmaR1 message. Starting handshake. EC 0x3ffc7dc0 V (30333) chip[IN]: Marking old secure session for device 0x0000000000000000 as expired I (30343) chip[DIS]: CASE handshake initiated, closing all BLE Connections V (30353) chip[IN]: Clearing BLE pending packets. I (30353) chip[BLE]: Releasing end point's BLE connection back to application. V (30363) chip[SC]: Waiting for SigmaR1 msg I (30363) chip[IN]: CASE Server disabling CASE session setups V (30373) chip[SC]: Received SigmaR1 msg V (30383) chip[SC]: Peer assigned session key ID 6 I (30383) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I (30393) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000003, VendorId 0x1700 I (30403) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (30413) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (30423) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (30433) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (30443) app-devicecallbacks: Unhandled cluster ID: 62 I (30453) app-devicecallbacks: Current free heap: 72188

I (30453) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (30463) app-devicecallbacks: Unhandled cluster ID: 62 I (30473) app-devicecallbacks: Current free heap: 72188

I (30483) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I (30493) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000003, VendorId 0x1700 I (30503) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (30513) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x0000000000000003 vendorId 0x1700 I (30523) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute. I (30533) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (30543) app-devicecallbacks: Unhandled cluster ID: 62 I (30553) app-devicecallbacks: Current free heap: 72188

I (30553) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (30563) app-devicecallbacks: Unhandled cluster ID: 62 I (30573) app-devicecallbacks: Current free heap: 72188

I (30793) esp_netif_handlers: sta ip: 192.168.2.253, mask: 255.255.254.0, gw: 192.168.2.1 V (32163) chip[SC]: Sent SigmaR2 msg E (32163) chip[DL]: Long dispatch time: 1850 ms, for event type 3 I (32163) chip[DL]: IP_EVENT_STA_GOT_IP I (32173) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.2.253/255.255.254.0 gateway 192.168.2.1 I (32193) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (32193) chip[DL]: IPv6 Internet connectivity ESTABLISHED I (32193) app-devicecallbacks: Current free heap: 70384

I (32203) chip[DL]: IP_EVENT_GOT_IP6 I (32203) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: 2a02:0168:7ea3:0002:0a3a:f2ff:fe6a:4588 I (32213) app-devicecallbacks: Current free heap: 70384

I (32223) app-devicecallbacks: Server ready at: 192.168.2.253:5540 I (32233) all-clusters-app: Display awake but will switch off automatically in 30 seconds I (32243) chip[DIS]: CHIP minimal mDNS started advertising. I (32243) chip[DIS]: Replying to DNS-SD service listing request I (32253) chip[DIS]: Replying to DNS-SD service listing request I (32253) chip[DIS]: Replying to DNS-SD service listing request I (32263) chip[DIS]: Replying to DNS-SD service listing request I (32273) chip[DIS]: Replying to DNS-SD service listing request I (32283) chip[DIS]: Replying to DNS-SD service listing request I (32283) chip[DIS]: Replying to DNS-SD service listing request I (32293) chip[DIS]: Broadcasting mDns reply I (32293) chip[DIS]: Broadcasting mDns reply I (32293) chip[DIS]: Replying to DNS-SD service listing request I (32313) chip[DIS]: Replying to DNS-SD service listing request I (32313) chip[DIS]: Replying to DNS-SD service listing request I (32323) chip[DIS]: Replying to DNS-SD service listing request I (32323) chip[DIS]: Replying to DNS-SD service listing request I (32333) chip[DIS]: Replying to DNS-SD service listing request I (32343) chip[DIS]: Replying to DNS-SD service listing request I (32343) chip[DIS]: Broadcasting mDns reply I (32353) chip[DIS]: Broadcasting mDns reply I (32363) chip[DIS]: Replying to DNS-SD service listing request I (32363) chip[DIS]: Replying to DNS-SD service listing request I (32373) chip[DIS]: Replying to DNS-SD service listing request I (32373) chip[DIS]: Replying to DNS-SD service listing request I (32383) chip[DIS]: Replying to DNS-SD service listing request I (32393) chip[DIS]: Replying to DNS-SD service listing request I (32403) chip[DIS]: Replying to DNS-SD service listing request I (32403) chip[DIS]: Broadcasting mDns reply I (32413) chip[DIS]: Broadcasting mDns reply V (32413) chip[DIS]: Using wifi MAC for hostname I (32413) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (32433) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (32433) app-devicecallbacks: IPv6 Server ready... I (32443) chip[DIS]: CHIP minimal mDNS started advertising. I (32443) chip[DIS]: Replying to DNS-SD service listing request I (32453) chip[DIS]: Replying to DNS-SD service listing request I (32453) chip[DIS]: Replying to DNS-SD service listing request I (32473) chip[DIS]: Replying to DNS-SD service listing request I (32473) chip[DIS]: Replying to DNS-SD service listing request I (32483) chip[DIS]: Replying to DNS-SD service listing request I (32483) chip[DIS]: Replying to DNS-SD service listing request I (32493) chip[DIS]: Broadcasting mDns reply I (32493) chip[DIS]: Broadcasting mDns reply I (32503) chip[DIS]: Replying to DNS-SD service listing request I (32513) chip[DIS]: Replying to DNS-SD service listing request I (32513) chip[DIS]: Replying to DNS-SD service listing request I (32523) chip[DIS]: Replying to DNS-SD service listing request I (32523) chip[DIS]: Replying to DNS-SD service listing request I (32533) chip[DIS]: Replying to DNS-SD service listing request I (32543) chip[DIS]: Replying to DNS-SD service listing request I (32543) chip[DIS]: Broadcasting mDns reply I (32553) chip[DIS]: Broadcasting mDns reply I (32563) chip[DIS]: Replying to DNS-SD service listing request I (32563) chip[DIS]: Replying to DNS-SD service listing request I (32573) chip[DIS]: Replying to DNS-SD service listing request I (32573) chip[DIS]: Replying to DNS-SD service listing request I (32593) chip[DIS]: Replying to DNS-SD service listing request I (32593) chip[DIS]: Replying to DNS-SD service listing request I (32603) chip[DIS]: Replying to DNS-SD service listing request I (32603) chip[DIS]: Broadcasting mDns reply I (32613) chip[DIS]: Broadcasting mDns reply V (32613) chip[DIS]: Using wifi MAC for hostname I (32623) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (32633) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (32633) app-devicecallbacks: Current free heap: 63172

I (32643) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 E (32643) chip[DL]: Long dispatch time: 420 ms, for event type 32770 E (32653) chip[IN]: UDP endpoint pool FULL V (32653) chip[DIS]: Using wifi MAC for hostname I (32673) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (32673) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (32683) app-devicecallbacks: Current free heap: 65544

E (32683) chip[IN]: UDP endpoint pool FULL V (32693) chip[DIS]: Using wifi MAC for hostname I (32693) chip[DIS]: Advertise operational node 9BA870629BCC9203-0000000000000003 I (32703) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'. I (32703) app-devicecallbacks: Current free heap: 65544

I (32723) chip[EM]: Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 1107 V (32733) chip[SC]: Received SigmaR3 msg I (34833) chip[IN]: CASE Session established. Setting up the secure channel. V (34833) chip[IN]: New secure session created for device 0x8FB13FDCC48DA881, key 6!! I (34843) chip[IN]: CASE secure channel is available now. I (34843) chip[IN]: CASE Server enabling CASE session setups E (34863) chip[DL]: Long dispatch time: 2140 ms, for event type 3 I (34863) chip[EM]: Received message of type 0x02 with vendorId 0x0000 and protocolId 0x0005 on exchange 1108 V (34873) chip[EM]: ec id: 1108, Delegate: 0x0x3ffcedf0 V (34873) chip[-]: Receive Read request V (34883) chip[DMG]: IM RH moving to [Initialized] V (34893) chip[DMG]: IM RH moving to [Reportable] V (34893) chip[IN]: Clearing BLE pending packets. I (34893) chip[BLE]: Releasing end point's BLE connection back to application. E (34903) chip[BLE]: HandleChipConnectionReceived failed, err = d E (34913) chip[BLE]: failed handle new chip BLE connection, status = d I (34923) chip[EM]: Received message of type 0x02 with vendorId 0x0000 and protocolId 0x0005 on exchange 1109 V (34933) chip[EM]: ec id: 1109, Delegate: 0x0x3ffcedf0 V (34933) chip[-]: Receive Read request V (34943) chip[DMG]: IM RH moving to [Initialized] V (34943) chip[DMG]: IM RH moving to [Reportable] V (34943) chip[DMG]: Cluster 6, Field 0 is dirty V (34953) chip[DMG]: Received Cluster Command: Cluster=0x0000_0006 NodeId=0x0000000000000003 Endpoint=1 AttributeId=0 ListIndex=0 V (34973) chip[DMG]: Sending report... V (34973) chip[DMG]: IM RH moving to [Reporting] V (34973) chip[IN]: Secure message was encrypted: Msg ID 1 I (34983) chip[IN]: Encrypted message 0x3ffc7d38 to 0x8FB13FDCC48DA881 of type 5 and protocolId 5 on exchange 1108. I (34993) chip[IN]: Sending msg 0x3ffc7d38 to 0x8FB13FDCC48DA881 at utc time: 34270 msec I (34993) chip[IN]: Sending secure msg on generic transport I (35013) chip[IN]: Secure msg send status Success V (35013) chip[DMG]: ReportsInFlight = 1 with readHandler 0, RE has no more messages V (35023) chip[DMG]: Cluster 8, Field 0 is dirty V (35023) chip[DMG]: Received Cluster Command: Cluster=0x0000_0008 NodeId=0x0000000000000003 Endpoint=1 AttributeId=0 ListIndex=0 V (35033) chip[DMG]: Sending report... V (35033) chip[DMG]: IM RH moving to [Reporting] V (35053) chip[IN]: Secure message was encrypted: Msg ID 2 I (35053) chip[IN]: Encrypted message 0x3ffc7d44 to 0x8FB13FDCC48DA881 of type 5 and protocolId 5 on exchange 1109. I (35063) chip[IN]: Sending msg 0x3ffc7d44 to 0x8FB13FDCC48DA881 at utc time: 34340 msec I (35073) chip[IN]: Sending secure msg on generic transport I (35073) chip[IN]: Secure msg send status Success V (35083) chip[DMG]: ReportsInFlight = 2 with readHandler 1, RE has no more messages E (35093) chip[DL]: Long dispatch time: 150 ms, for event type 3 I (35123) chip[EM]: Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 1108 I (35123) chip[DMG]: in state Reporting, receive status report, protocol id is 5, protocol code is 0 V (35143) chip[DMG]: OnReportConfirm: NumReports = 1 V (35143) chip[DMG]: IM RH moving to [Uninitialized] V (35153) chip[IN]: Secure message was encrypted: Msg ID 3 I (35153) chip[IN]: Encrypted message 0x3ffe637c to 0x8FB13FDCC48DA881 of type 16 and protocolId 0 on exchange 1108. I (35163) chip[IN]: Sending msg 0x3ffe637c to 0x8FB13FDCC48DA881 at utc time: 34440 msec I (35173) chip[IN]: Sending secure msg on generic transport I (35183) chip[IN]: Secure msg send status Success I (35243) chip[EM]: Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 1109 I (35243) chip[DMG]: in state Reporting, receive status report, protocol id is 5, protocol code is 0 V (35253) chip[DMG]: OnReportConfirm: NumReports = 0 V (35253) chip[DMG]: IM RH moving to [Uninitialized] V (35273) chip[IN]: Secure message was encrypted: Msg ID 4 I (35273) chip[IN]: Encrypted message 0x3ffe637c to 0x8FB13FDCC48DA881 of type 16 and protocolId 0 on exchange 1109. I (35283) chip[IN]: Sending msg 0x3ffe637c to 0x8FB13FDCC48DA881 at utc time: 34560 msec I (35293) chip[IN]: Sending secure msg on generic transport I (35293) chip[IN]: Secure msg send status Success I (42573) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0 I (42573) chip[DL]: CHIPoBLE unsubscribe received E (42573) chip[BLE]: no endpoint for unsub recvd I (42583) chip[DL]: BLE GAP connection terminated (con 0 reason 0x13) I (42593) app-devicecallbacks: CHIPoBLE disconnected I (42593) app-devicecallbacks: Current free heap: 72028

I (62233) all-clusters-app: Display going to sleep... ——— END OF LOG chip project commit 5ed637736e231abc5e75f3ddc96e0e73501877a1 with esp-idf release/v4.3 ———

——— LOG chip project commit 5ed637736e231abc5e75f3ddc96e0e73501877a1 with esp-idf release/v4.2 ——— esptool.py esp32 -p /dev/cu.usbserial-0252EF6C -b 460800 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 40m --flash_size 2MB 0x8000 partition_table/partition-table.bin 0x1000 bootloader/bootloader.bin 0x10000 chip-all-clusters-app.bin esptool.py v3.1-dev Serial port /dev/cu.usbserial-0252EF6C Connecting.... Chip is ESP32-D0WDQ6-V3 (revision 3) Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None Crystal is 40MHz MAC: 08:3a:f2:6a:45:88 Uploading stub... Running stub... Stub running... Changing baud rate to 460800 Changed. Configuring flash size... Flash will be erased from 0x00008000 to 0x00008fff... Flash will be erased from 0x00001000 to 0x00007fff... Flash will be erased from 0x00010000 to 0x0013efff... Compressed 3072 bytes to 106... Writing at 0x00008000... (100 %) Wrote 3072 bytes (106 compressed) at 0x00008000 in 0.1 seconds (effective 388.7 kbit/s)... Hash of data verified. Compressed 25136 bytes to 15299... Writing at 0x00001000... (100 %) Wrote 25136 bytes (15299 compressed) at 0x00001000 in 0.8 seconds (effective 263.7 kbit/s)... Hash of data verified. Compressed 1237648 bytes to 800327... Writing at 0x00010000... (2 %) Writing at 0x0001cd33... (4 %) Writing at 0x00025d83... (6 %) Writing at 0x0002f306... (8 %) Writing at 0x0003ae91... (10 %) Writing at 0x00046100... (12 %) Writing at 0x0004ccc6... (14 %) Writing at 0x0005289d... (16 %) Writing at 0x00057f9d... (18 %) Writing at 0x0005d415... (20 %) Writing at 0x00062f68... (22 %) Writing at 0x00067f78... (24 %) Writing at 0x0006d79c... (26 %) Writing at 0x00072af1... (28 %) Writing at 0x00077fb9... (30 %) Writing at 0x0007d7bd... (32 %) Writing at 0x00082e03... (34 %) Writing at 0x00088826... (36 %) Writing at 0x0008defd... (38 %) Writing at 0x000939a3... (40 %) Writing at 0x00099780... (42 %) Writing at 0x0009fa3f... (44 %) Writing at 0x000a560f... (46 %) Writing at 0x000ac47e... (48 %) Writing at 0x000b240d... (51 %) Writing at 0x000b7e4f... (53 %) Writing at 0x000bd46a... (55 %) Writing at 0x000c2b24... (57 %) Writing at 0x000c7e10... (59 %) Writing at 0x000ccf40... (61 %) Writing at 0x000d1e41... (63 %) Writing at 0x000d736e... (65 %) Writing at 0x000dcbd3... (67 %) Writing at 0x000e1ea4... (69 %) Writing at 0x000e7361... (71 %) Writing at 0x000eca23... (73 %) Writing at 0x000f1f83... (75 %) Writing at 0x000f76bd... (77 %) Writing at 0x000fd32a... (79 %) Writing at 0x00102d0a... (81 %) Writing at 0x00107cac... (83 %) Writing at 0x0010d4b6... (85 %) Writing at 0x00113d53... (87 %) Writing at 0x0011b5dc... (89 %) Writing at 0x00123739... (91 %) Writing at 0x00129699... (93 %) Writing at 0x0012ed31... (95 %) Writing at 0x00133faa... (97 %) Writing at 0x001392d1... (100 %) Wrote 1237648 bytes (800327 compressed) at 0x00010000 in 19.5 seconds (effective 508.6 kbit/s)... Hash of data verified.

Leaving... Hard resetting via RTS pin... Executing action: monitor Running idf_monitor in directory /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32 Executing "/Users/benedek.kaman/smoca/matter/connectedhomeip/.environment/pigweed-venv/bin/python /Users/benedek.kaman/smoca/matter/esp-idf/tools/idf_monitor.py -p /dev/cu.usbserial-0252EF6C -b 115200 --toolchain-prefix xtensa-esp32-elf- /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.elf -m '/Users/benedek.kaman/smoca/matter/connectedhomeip/.environment/pigweed-venv/bin/python' '/Users/benedek.kaman/smoca/matter/esp-idf/tools/idf.py' '-p' '/dev/cu.usbserial-0252EF6C'"... --- idf_monitor on /dev/cu.usbserial-0252EF6C 115200 --- --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H --- ??data 01 01 0000f000 00?ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:7224 load:0x40078000,len:13232 load:0x40080400,len:4584 0x40080400: _init at ??:?

entry 0x400806f4 I (27) boot: ESP-IDF v4.2.2-358-g5f46abd281 2nd stage bootloader I (27) boot: compile time 09:00:14 I (27) boot: chip revision: 3 I (31) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (43) boot.esp32: SPI Mode : DIO I (48) boot.esp32: SPI Flash Size : 2MB I (52) boot: Enabling RNG early entropy source... I (58) boot: Partition Table: I (61) boot: ## Label Usage Type ST Offset Length I (69) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (76) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (83) boot: 2 factory factory app 00 00 00010000 001e6400 I (91) boot: End of partition table I (95) boot_comm: chip revision: 3, min. application chip revision: 0 I (102) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x31f24 (204580) map I (189) esp_image: segment 1: paddr=0x00041f4c vaddr=0x3ffbdb60 size=0x07048 ( 28744) load I (201) esp_image: segment 2: paddr=0x00048f9c vaddr=0x40080000 size=0x0707c ( 28796) load 0x40080000: _WindowOverflow4 at /Users/benedek.kaman/smoca/matter/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1730

I (214) esp_image: segment 3: paddr=0x00050020 vaddr=0x400d0020 size=0xd6198 (876952) map 0x400d0020: _stext at ??:?

I (549) esp_image: segment 4: paddr=0x001261c0 vaddr=0x4008707c size=0x180a0 ( 98464) load 0x4008707c: should_request_high at lld_evt.c:?

I (609) boot: Loaded app from partition at offset 0x10000 I (609) boot: Disabling RNG early entropy source... I (610) cpu_start: Pro cpu up. I (613) cpu_start: Application information: I (618) cpu_start: Project name: chip-all-clusters-app I (624) cpu_start: App version: test_event_4_2021_07_06-519-g5e I (631) cpu_start: Compile time: Oct 29 2021 09:00:04 I (638) cpu_start: ELF file SHA256: 1bb0af844ab44d80... I (644) cpu_start: ESP-IDF: v4.2.2-358-g5f46abd281 I (650) cpu_start: Starting app cpu, entry point is 0x400819f4 0x400819f4: call_start_cpu1 at /Users/benedek.kaman/smoca/matter/esp-idf/components/esp32/cpu_start.c:287

I (0) cpu_start: App cpu up. I (660) heap_init: Initializing. RAM available for dynamic allocation: I (667) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (673) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (679) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (685) heap_init: At 3FFD5CA0 len 0000A360 (40 KiB): DRAM I (692) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (698) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (704) heap_init: At 4009F11C len 00000EE4 (3 KiB): IRAM I (710) cpu_start: Pro cpu start user code I (731) spi_flash: detected chip: generic I (731) spi_flash: flash io: dio W (731) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (742) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (753) all-clusters-app: All Clusters Demo! I (763) all-clusters-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, I (763) all-clusters-app: silicon revision 3, I (773) all-clusters-app: 2MB external flash

I (833) wifi:wifi driver task: 3ffdcd58, prio:23, stack:6656, core=0 I (833) system_api: Base MAC address is not set I (833) system_api: read default base MAC address from EFUSE I (863) wifi:wifi firmware version: df5b09d I (863) wifi:wifi certification version: v7.0 I (863) wifi:config NVS flash: enabled I (863) wifi:config nano formating: disabled I (873) wifi:Init data frame dynamic rx buffer num: 32 I (873) wifi:Init management frame dynamic rx buffer num: 32 I (883) wifi:Init management short buffer num: 32 I (893) wifi:Init dynamic tx buffer num: 32 I (893) wifi:Init static rx buffer size: 1600 I (893) wifi:Init static rx buffer num: 10 I (903) wifi:Init dynamic rx buffer num: 32

I (903) wifi_init: rx ba win: 6 I (903) wifi_init: tcpip mbox: 32 I (913) wifi_init: udp mbox: 6 I (913) wifi_init: tcp mbox: 6 I (913) wifi_init: tcp tx win: 5744 I (923) wifi_init: tcp rx win: 5744 I (933) wifi_init: tcp mss: 1440 I (933) wifi_init: WiFi IRAM OP enabled I (943) wifi_init: WiFi RX IRAM OP enabled V (943) chip[DL]: CHIP task running I (943) chip[ZCL]: Using ZAP configuration... I (953) BTDM_INIT: BT controller compile version [7972edf] I (953) chip[ZCL]: deactivate report event I (963) phy_init: phy_version 4660,0162888,Dec 23 2020 W (963) phy_init: failed to load RF calibration data (0xffffffff), falling back to full calibration I (963) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0002' I (993) app-devicecallbacks: Unhandled cluster ID: 257 I (993) app-devicecallbacks: Current free heap: 111496

I (1003) chip[ZCL]: 0x3f408a55ep 1 clus 101 attr 3 not supported I (1003) chip[ZCL]: Failed to write DoorState attribute: 0x86 I (1013) chip[ZCL]: 0x3f408a55ep 1 clus 101 attr 21 not supported I (1013) chip[ZCL]: Failed to write Language attribute: 0x86 I (1033) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table. V (1033) chip[DIS]: Set the fabric pairing table delegate I (1043) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute I (1053) chip[ZCL]: OpCreds: Stored 0 fabrics in fabrics list attribute. I (1053) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003' I (1073) app-devicecallbacks: Unhandled cluster ID: 62 I (1083) app-devicecallbacks: Current free heap: 111496

I (1083) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002' I (1093) app-devicecallbacks: Unhandled cluster ID: 62 I (1093) app-devicecallbacks: Current free heap: 111496

I (1103) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001' I (1123) app-devicecallbacks: Unhandled cluster ID: 40 I (1123) app-devicecallbacks: Current free heap: 111496

I (1133) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002' I (1153) app-devicecallbacks: Unhandled cluster ID: 40 assertion "rc == 0" failed: file "/Users/benedek.kaman/smoca/matter/esp-idf/components/bt/host/nimble/nimble/nimble/host/serviceI (1453) app-devicecallbacks: Current free heap: 102292 s/gap/src/ble_svc_gap.c", line 297, function: ble_svc_gap_init

abort() was called at PC 0x4018c0eb on core 0 0x4018c0eb: __assert_func at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdlib/assert.c:62 (discriminator 8)

Backtrace:0x40090d6e:0x3ffe60a0 0x40091331:0x3ffe60c0 0x40097a22:0x3ffe60e0 0x4018c0eb:0x3ffe6150 0x40102cbe:0x3ffe6180 0x400f4ab6:0x3ffe61a0 0x400f510b:0x3ffe61c0 0x400f5306:0x3ffe6220 0x400f4315:0x3ffe6240 0x400f452b:0x3ffe6260 0x400f4555:0x3ffe62c0 0x40091339:0x3ffe62e0 0x40090d6e: panic_abort at /Users/benedek.kaman/smoca/matter/esp-idf/components/esp_system/panic.c:353

0x40091331: esp_system_abort at /Users/benedek.kaman/smoca/matter/esp-idf/components/esp_system/system_api.c:106

0x40097a22: abort at /Users/benedek.kaman/smoca/matter/esp-idf/components/newlib/abort.c:46

0x4018c0eb: __assert_func at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdlib/assert.c:62 (discriminator 8)

0x40102cbe: ble_svc_gap_init at /Users/benedek.kaman/smoca/matter/esp-idf/components/bt/host/nimble/nimble/nimble/host/services/gap/src/ble_svc_gap.c:297 (discriminator 1)

0x400f4ab6: chip::DeviceLayer::Internal::BLEManagerImpl::InitESPBleLayer() at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:638

0x400f510b: chip::DeviceLayer::Internal::BLEManagerImpl::DriveBLEState() at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:477

0x400f5306: chip::DeviceLayer::Internal::BLEManagerImpl::DriveBLEState(int) at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/platform/ESP32/nimble/BLEManagerImpl.cpp:1149

0x400f4315: chip::DeviceLayer::Internal::GenericPlatformManagerImpl::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.cpp:222

0x400f452b: chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS::_RunEventLoop() at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:364 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS::_RunEventLoop() at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.cpp:179

0x400f4555: chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS::EventLoopTaskMain(void) at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:296 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS::EventLoopTaskMain(void) at /Users/benedek.kaman/smoca/matter/connectedhomeip/examples/all-clusters-app/esp32/build/esp-idf/chip/../../../../../../config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.cpp:204

0x40091339: vPortTaskWrapper at /Users/benedek.kaman/smoca/matter/esp-idf/components/freertos/xtensa/port.c:143

ELF file SHA256: 1bb0af844ab44d80

Rebooting... ets Jul 29 2019 12:21:46

… this gets repeated endlessly until the device is turned off ——— END OF LOG chip project commit 5ed637736e231abc5e75f3ddc96e0e73501877a1 with esp-idf release/v4.2 ———

Configuration matter enabled device: ipad 6. generation, iPadOS 15.1 (getting the same results with an iPhone 7 Plus running the latest beta iOS 15.2) m5stack device: m5stack basic core, FCC ID: 2AN3WM5Stack-CORE device used to flash the m5stack: MacBook Pro (13-inch, M1, 2020) (getting the same results with a MacBook Pro (15-inch, 2017), MacOS version 11.6 and with using a rosetta 2 terminal on the M1 MacBook) MacOS version: 11.4 (20F71) Python3 version: 3.9.7 Clang version: 13

Steps to Reproduce

  1. Build the esp-idf tool following the instructions on (https://github.com/project-chip/connectedhomeip/tree/c5fff8531346609d3e4e75ea4ab7efba2d90a7f0/examples/all-clusters-app/esp32) with either version 4.2 or 4.3
  2. Build the chip project following the instructions on (https://github.com/project-chip/connectedhomeip/blob/5ed637736e231abc5e75f3ddc96e0e73501877a1/docs/guides/BUILDING.md)
  3. Install matter profile on iPhone or IPad and configure M5Stack with idf.py menuconfig following the instructions in the enable matter pdf(https://download.developer.apple.com/iOS/iOS_Logs/EnableMatter_Instructions.pdf)
  4. Build and flash all-clusters-app on m5stack
  5. Scan QR-Code of the device with the Home App on iPhone or iPad and go through the setup steps
bzbarsky-apple commented 2 years ago

@bndkk Is this still an issue?

woody-apple commented 2 years ago

Issue Review: Closing old issues prior to PreSVE, please re-test with a newer SDK and let us know if this is still happening.