MATTER/Log all-cluster-app esp32 log
matter_log.all.success.txt
- (8/18) 성공한 로그
- python controller 에서 수행한 커맨드 내역
chip-device-ctrl > ble-scan
chip-device-ctrl > connect -ble 3840 20202021 135246
chip-device-ctrl > zcl NetworkCommissioning AddWiFiNetwork 135246 0 0 ssid=str:<<SSID>> credentials=str:<<passcode>> breadcrumb=0 timeoutMs=1000
chip-device-ctrl > zcl NetworkCommissioning EnableNetwork 135246 0 0 networkID=str:<<SSID>> breadcrumb=0 timeoutMs=1000
chip-device-ctrl > close-ble
chip-device-ctrl > resolve 135246
chip-device-ctrl > zcl OnOff Off 135246 1 1
chip-device-ctrl > zcl LevelControl MoveToLevel 135246 1 1 level=10 transitionTime=0 optionMask=0 optionOverride=0matter_log.all.failing.txt
- (8/18) success 이후, ESP32 보드에 temperature-measure app 설치 후 다시 ble-scan, connect 시도했는데 fail 됨
- 다시 all-cluster-app 으로 바꿔도 fail 되고, 로그를 비교해보니,
- 기존의 등록된 fabric 정보를 storage 에서 읽어오고, BLE advertising 을 disable 하고 CASE 세션을 enable 함
I (2511) chip[SVR]: Retrieved from server storage: Fabric1
I (2511) chip[IN]: Loading certs from storage
I (2521) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (2531) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (2541) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (2551) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (2561) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
...
I (2641) chip[DL]: NVS set: chip-counters/GlobalMCTR = 19000 (0x4A38)
I (2641) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (2661) chip[IN]: CASE Server enabling CASE session setups
I (2661) chip[SVR]: Server Listening...- partition 정보를 지우고 싶다면 idf.py erase-flash 실행 필요. 참조링크
matter_log.all.led_onoff.txt
- led on/off 실행 해본 로그
- zcl <cluster> <command> <nodeid> <endpoint> <groupid> [key=value] 에 따라
- zcl OnOff Off 135246 1 1 와 zcl OnOff On 135246 1 1 을 입력하면 GPIO D2 에 연결된 LED 가 토글됨
- all-cluster-app 의 zap config 파일을 보면 (MATTER 공통인듯 함) EndPoint 1 에, Cluster ID 0x0006 이 OnOff 이고, OnOff 상태를 나타내는 Attribute ID 는 0x0 OnOff 클러스터는 ID가 1이고 OnOff Attribute 는 0x000 이다.
- 참고로 Cluster ID 0x0008 은 Level Control 이고, 0x0005 는 Scene 이다.
I (113821) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2 on exchange 58519r
I (169201) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3 on exchange 58520r
I (169201) chip[ZCL]: On/Off set value: 1 1
I (169221) chip[ZCL]: Toggle on/off from 0 to 1
I (169221) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (169231) app-devicecallbacks: Current free heap: 91848
I (169231) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (169241) app-devicecallbacks: Current free heap: 91832
I (169251) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (169271) app-devicecallbacks: Unhandled cluster ID: 5
I (169271) app-devicecallbacks: Current free heap: 91848
I (169281) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 58520r with MessageCounter:2.
I (169291) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:2 to 0x000000000001B669 at monotonic time: 168590 msec
E (169311) chip[DL]: Long dispatch time: 110 ms, for event type 4
I (169311) chip[ZCL]: Event: move from 0
I (169311) chip[ZCL]: to 255
I (169321) chip[ZCL]: (diff +1)
I (169321) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (169341) app-devicecallbacks: Current free heap: 91848
I (169341) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (169351) app-devicecallbacks: Unhandled cluster ID: 5
I (169361) app-devicecallbacks: Current free heap: 91848
I (169411) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:4 on exchange 58520r
I (183441) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5 on exchange 58521r
I (183441) chip[ZCL]: On/Off set value: 1 0
I (183451) chip[ZCL]: Toggle on/off from 1 to 0
I (183451) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (183471) app-devicecallbacks: Current free heap: 91848
I (183471) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (183481) app-devicecallbacks: Unhandled cluster ID: 5
I (183491) app-devicecallbacks: Current free heap: 91848
I (183491) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 58521r with MessageCounter:3.
I (183511) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:3 to 0x000000000001B669 at monotonic time: 182810 msec
I (183521) chip[ZCL]: Event: move from 255
I (183521) chip[ZCL]: to 0
I (183531) chip[ZCL]: (diff -1)
I (183541) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (183551) app-devicecallbacks: Current free heap: 91848
I (183551) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (183561) app-devicecallbacks: Unhandled cluster ID: 5
I (183571) app-devicecallbacks: Current free heap: 91848
I (183571) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (183591) app-devicecallbacks: Current free heap: 91848
I (183851) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:6 on exchange 58521r=============== matter_log.all_success.txt
/home/gamja/esp/.espressif/python_env/idf4.4_py3.8_env/bin/python /home/gamja/esp/esp-idf/tools/idf.py -p /dev/ttyUSB0 monitor
gamja@gamja-14Z90P-GALGL:~/connectedhomeip/examples/all-clusters-app/esp32$ /home/gamja/esp/.espressif/python_env/idf4.4_py3.8_env/bin/python /home/gamja/esp/esp-idf/tools/idf.py -p /dev/ttyUSB0 monitor
Executing action: monitor
Running idf_monitor in directory /home/gamja/connectedhomeip/examples/all-clusters-app/esp32
Executing "/home/gamja/esp/.espressif/python_env/idf4.4_py3.8_env/bin/python /home/gamja/esp/esp-idf/tools/idf_monitor.py -p /dev/ttyUSB0 -b 115200 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 0 /home/gamja/connectedhomeip/examples/all-clusters-app/esp32/build/chip-all-clusters-app.elf -m '/home/gamja/esp/.espressif/python_env/idf4.4_py3.8_env/bin/python' '/home/gamja/esp/esp-idf/tools/idf.py' '-p' '/dev/ttyUSB0'"...
--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
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:6612
load:0x40078000,len:14788
load:0x40080400,len:3792
0x40080400: _init at ??:?
entry 0x40080694
I (27) boot: ESP-IDF v4.4.1-dirty 2nd stage bootloader
I (27) boot: compile time 22:16:35
I (27) boot: chip revision: 3
I (31) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (38) boot.esp32: SPI Speed : 40MHz
I (42) boot.esp32: SPI Mode : DIO
I (47) boot.esp32: SPI Flash Size : 4MB
I (51) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (60) boot: ## Label Usage Type ST Offset Length
I (68) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (75) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (83) boot: 2 factory factory app 00 00 00010000 001db000
I (90) boot: 3 ot_storage Unknown data 01 3a 001eb000 00002000
I (98) boot: End of partition table
I (102) boot_comm: chip revision: 3, min. application chip revision: 0
I (109) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2c50ch (181516) map
I (183) esp_image: segment 1: paddr=0003c534 vaddr=3ffbdb60 size=03ae4h ( 15076) load
I (189) esp_image: segment 2: paddr=00040020 vaddr=400d0020 size=d0b8ch (854924) map
I (499) esp_image: segment 3: paddr=00110bb4 vaddr=3ffc1644 size=01ae4h ( 6884) load
I (502) esp_image: segment 4: paddr=001126a0 vaddr=40080000 size=1c98ch (117132) load
I (553) esp_image: segment 5: paddr=0012f034 vaddr=50000000 size=00010h ( 16) load
I (567) boot: Loaded app from partition at offset 0x10000
I (567) boot: Disabling RNG early entropy source...
I (579) cpu_start: Pro cpu up.
I (579) cpu_start: Starting app cpu, entry point is 0x400813cc
0x400813cc: call_start_cpu1 at /home/gamja/esp/esp-idf/components/esp_system/port/cpu_start.c:160
I (0) cpu_start: App cpu up.
I (595) cpu_start: Pro cpu start user code
I (595) cpu_start: cpu freq: 160000000
I (595) cpu_start: Application information:
I (600) cpu_start: Project name: chip-all-clusters-app
I (606) cpu_start: App version: test_event_4_2021_07_06-1264-gf
I (613) cpu_start: Compile time: Aug 18 2022 22:16:30
I (619) cpu_start: ELF file SHA256: 1509a29a73e3ec10...
I (625) cpu_start: ESP-IDF: v4.4.1-dirty
I (631) heap_init: Initializing. RAM available for dynamic allocation:
I (638) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (644) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (650) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (656) heap_init: At 3FFD2108 len 0000DEF8 (55 KiB): DRAM
I (662) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (669) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (675) heap_init: At 4009C98C len 00003674 (13 KiB): IRAM
I (682) spi_flash: detected chip: generic
I (686) spi_flash: flash io: dio
I (693) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (701) all-clusters-app: All Clusters Demo!
I (711) all-clusters-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE,
I (711) all-clusters-app: silicon revision 3,
I (721) all-clusters-app: 4MB external flash
I (771) wifi:wifi driver task: 3ffd9610, prio:23, stack:6656, core=0
I (771) system_api: Base MAC address is not set
I (771) system_api: read default base MAC address from EFUSE
I (791) wifi:wifi firmware version: 63017e0
I (791) wifi:wifi certification version: v7.0
I (801) wifi:config NVS flash: enabled
I (801) wifi:config nano formating: disabled
I (811) wifi:Init data frame dynamic rx buffer num: 32
I (811) wifi:Init management frame dynamic rx buffer num: 32
I (811) wifi:Init management short buffer num: 32
I (821) wifi:Init dynamic tx buffer num: 32
I (821) wifi:Init static rx buffer size: 1600
I (821) wifi:Init static rx buffer num: 10
I (831) wifi:Init dynamic rx buffer num: 32
I (831) wifi_init: rx ba win: 6
I (841) wifi_init: tcpip mbox: 32
I (851) wifi_init: udp mbox: 6
I (851) wifi_init: tcp mbox: 6
I (851) wifi_init: tcp tx win: 5744
I (851) wifi_init: tcp rx win: 5744
I (861) wifi_init: tcp mss: 1440
I (861) wifi_init: WiFi IRAM OP enabled
I (861) wifi_init: WiFi RX IRAM OP enabled
I (871) chip[DL]: AUDIT: ===== RANDOM NUMBER GENERATOR AUDIT START ====
I (881) chip[DL]: AUDIT: * Validate buf1 and buf2 are <<<different every run/boot!>>>
I (891) chip[DL]: AUDIT: * Validate r1 and r2 are <<<different every run/boot!>>>
I (901) chip[DL]: AUDIT: * buf1: CC30BE396D75200D81EADD209D08D1AD
I (901) chip[DL]: AUDIT: * buf2: EA4F4BCDCC89EE31EA67932407760D46
I (911) chip[DL]: AUDIT: * r1: 0xC2FA3B42 r2: 0x0C7C6E26
I (911) chip[DL]: AUDIT: ===== RANDOM NUMBER GENERATOR AUDIT END ====
I (941) chip[DL]: NVS set: chip-counters/reboot-count = 81 (0x51)
I (941) all-clusters-app: Setup discriminator: 3840 (0xf00)
I (941) all-clusters-app: Setup PIN code: 20202021 (0x1344225)
I (941) BTDM_INIT: BT controller compile version [5688ed5]
I (961) all-clusters-app: Short Manual(decimal) setup code: 34970112332
I (961) all-clusters-app: Long Manual(decimal) setup code: 749701123309050177298
I (961) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (971) all-clusters-app: QR CODE Text: 'MT:C8XA0SRB00KA0648G00'
I (1001) 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%3AC8XA0SRB00KA0648G00
> I (1361) CHIP[DL]: BLE host-controller synced
I (1861) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1871) NimBLE: GAP procedure initiated: advertise;
I (1881) NimBLE: disc_mode=2
I (1881) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1891) NimBLE:
I (1891) chip[DL]: CHIPoBLE advertising started
E (1901) chip[DL]: Long dispatch time: 950 ms, for event type 2
I (1911) chip[DL]: Starting ESP WiFi layer
I (1911) wifi:mode : sta (78:21:84:b8:f1:74)
I (1911) wifi:enable tsf
W (1911) wifi:Haven't to connect to a suitable AP now!
I (1911) chip[DL]: Attempting to connect WiFi station interface
I (1931) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (1931) chip[DL]: Done driving station state, nothing else to do...
I (1941) chip[ZCL]: Using ZAP configuration...
I (1951) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (1961) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (1971) chip[ZCL]: OpCreds: Stored 0 fabrics in fabrics list attribute.
I (1971) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (1981) app-devicecallbacks: Unhandled cluster ID: 62
I (1991) app-devicecallbacks: Current free heap: 100220
I (1991) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (2011) app-devicecallbacks: Unhandled cluster ID: 62
I (2021) app-devicecallbacks: Current free heap: 100220
I (2021) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2031) app-devicecallbacks: Unhandled cluster ID: 40
I (2041) app-devicecallbacks: Current free heap: 100220
I (2041) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (2051) app-devicecallbacks: Unhandled cluster ID: 40
I (2071) app-devicecallbacks: Current free heap: 100220
I (2071) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (2081) app-devicecallbacks: Unhandled cluster ID: 40
I (2081) app-devicecallbacks: Current free heap: 100220
I (2091) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0004'
I (2101) app-devicecallbacks: Unhandled cluster ID: 40
I (2111) app-devicecallbacks: Current free heap: 100220
I (2121) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0008'
I (2131) app-devicecallbacks: Unhandled cluster ID: 40
I (2131) app-devicecallbacks: Current free heap: 100220
I (2141) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0007'
I (2151) app-devicecallbacks: Unhandled cluster ID: 40
I (2161) app-devicecallbacks: Current free heap: 100220
I (2171) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x000a'
I (2181) app-devicecallbacks: Unhandled cluster ID: 40
I (2181) app-devicecallbacks: Current free heap: 100220
I (2191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0007'
I (2201) app-devicecallbacks: Unhandled cluster ID: 40
I (2201) app-devicecallbacks: Current free heap: 100220
I (2211) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2221) app-devicecallbacks: Unhandled cluster ID: 4
I (2231) app-devicecallbacks: Current free heap: 100220
I (2231) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2241) app-devicecallbacks: Unhandled cluster ID: 5
I (2251) app-devicecallbacks: Current free heap: 100220
I (2261) chip[ZCL]: Window Covering Cluster init
I (2271) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (2271) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (2281) app-devicecallbacks: Unhandled cluster ID: 768
I (2291) app-devicecallbacks: Current free heap: 100220
I (2291) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2311) app-devicecallbacks: Unhandled cluster ID: 768
I (2311) app-devicecallbacks: Current free heap: 100220
I (2321) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2331) app-devicecallbacks: Unhandled cluster ID: 768
I (2331) app-devicecallbacks: Current free heap: 100220
I (2341) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2351) app-devicecallbacks: Unhandled cluster ID: 1030
I (2361) app-devicecallbacks: Current free heap: 100220
I (2371) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2381) app-devicecallbacks: Unhandled cluster ID: 1030
I (2381) app-devicecallbacks: Current free heap: 100220
I (2391) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH!
I (2391) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!!
I (2401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2421) app-devicecallbacks: Unhandled cluster ID: 1280
I (2421) app-devicecallbacks: Current free heap: 100220
I (2431) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2441) app-devicecallbacks: Unhandled cluster ID: 1280
I (2441) app-devicecallbacks: Current free heap: 100220
I (2451) chip[ZCL]: Failed to send IAS Zone update. Err 0x70
I (2461) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2471) app-devicecallbacks: Unhandled cluster ID: 1030
I (2481) app-devicecallbacks: Current free heap: 100220
I (2481) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2491) app-devicecallbacks: Unhandled cluster ID: 1030
I (2501) app-devicecallbacks: Current free heap: 100220
I (2521) chip[DL]: NVS set: chip-counters/GlobalMCTR = 2000 (0x7D0)
I (2651) chip[DIS]: CHIP minimal mDNS started advertising.
I (2651) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (2651) chip[DIS]: Start dns-sd server - no current nodeId
I (2671) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/00
I (2681) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2681) chip[IN]: CASE Server enabling CASE session setups
I (2691) chip[SVR]: Server Listening...
I (2701) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2711) app-devicecallbacks: Unhandled cluster ID: 1026
I (2711) app-devicecallbacks: Current free heap: 98088
I (2721) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2731) app-devicecallbacks: Unhandled cluster ID: 257
I (2741) app-devicecallbacks: Current free heap: 97968
I (2751) chip[ZCL]: Failed to read AutoRelockTime attribute: 0x86
I (2751) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2761) app-devicecallbacks: Current free heap: 97188
I (2761) chip[ZCL]: 0x3f408b33ep 2 clus 0x0000_0008 attr 0x0000_0000 not supported
E (2781) chip[DL]: Long dispatch time: 840 ms, for event type 2
I (2791) app-devicecallbacks: Current free heap: 97188
I (2791) chip[DL]: WIFI_EVENT_STA_START
W (2791) wifi:Haven't to connect to a suitable AP now!
I (2801) chip[DL]: Attempting to connect WiFi station interface
E (2801) wifi:sta is connecting, return error
E (2801) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (2821) app-devicecallbacks: Current free heap: 97188
I (2821) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (2831) chip[DL]: Device already advertising, stop active advertisement and restart
I (2841) NimBLE: GAP procedure initiated: stop advertising.
I (2851) NimBLE: GAP procedure initiated: advertise;
I (2851) NimBLE: disc_mode=2
I (2861) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2871) NimBLE:
I (5061) wifi:new:<9,1>, old:<1,0>, ap:<255,255>, sta:<9,1>, prof:1
I (5071) wifi:state: init -> auth (b0)
I (5071) wifi:state: auth -> assoc (0)
I (5081) wifi:state: assoc -> run (10)
I (5191) wifi:connected with MINDLES, aid = 3, channel 9, 40U, bssid = 88:36:6c:e0:45:6c
I (5191) wifi:security: WPA2-PSK, phy: bgn, rssi: -31
I (5201) wifi:pm start, type: 1
I (5201) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (5201) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (5221) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (5221) chip[DL]: WiFi station interface connected
I (5221) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (5231) chip[DL]: Done driving station state, nothing else to do...
I (5241) app-devicecallbacks: Current free heap: 96528
I (5241) chip[DL]: Updating advertising data
I (5261) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (5261) chip[DL]: Device already advertising, stop active advertisement and restart
I (5271) NimBLE: GAP procedure initiated: stop advertising.
I (5271) NimBLE: GAP procedure initiated: advertise;
I (5281) NimBLE: disc_mode=2
I (5281) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (5301) NimBLE:
I (5301) app-devicecallbacks: Current free heap: 96044
W (5771) wifi:<ba-add>idx:0 (ifx:0, 88:36:6c:e0:45:6c), tid:0, ssn:3, winSize:64
I (6261) esp_netif_handlers: sta ip: 192.168.0.18, mask: 255.255.255.0, gw: 192.168.0.1
I (6261) chip[DL]: IP_EVENT_STA_GOT_IP
I (6261) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.0.18/255.255.255.0 gateway 192.168.0.1
I (6271) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (6281) app-devicecallbacks: Current free heap: 96424
I (6291) app-devicecallbacks: Server ready at: 192.168.0.18:5540
I (6301) chip[DIS]: CHIP minimal mDNS started advertising.
I (6301) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (6311) chip[DIS]: Start dns-sd server - no current nodeId
I (6321) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/00
I (6321) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (6341) app-devicecallbacks: Current free heap: 93444
I (6341) chip[DIS]: CHIP minimal mDNS started advertising.
I (6351) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (6351) chip[DIS]: Start dns-sd server - no current nodeId
I (6361) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/00
I (6371) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (6381) app-devicecallbacks: Current free heap: 95020
I (6761) chip[DL]: IP_EVENT_GOT_IP6
I (6761) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:7a21:84ff:feb8:f174
I (6771) app-devicecallbacks: Current free heap: 96188
I (6781) chip[DIS]: CHIP minimal mDNS started advertising.
I (6781) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (6781) chip[DIS]: Start dns-sd server - no current nodeId
I (6801) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/00
I (6801) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (6821) app-devicecallbacks: Current free heap: 93728
I (32651) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840)
I (32651) chip[DL]: Device already advertising, stop active advertisement and restart
I (32671) NimBLE: GAP procedure initiated: stop advertising.
I (32671) NimBLE: GAP procedure initiated: advertise;
I (32681) NimBLE: disc_mode=2
I (32681) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (32691) NimBLE:
I (154451) chip[DL]: BLE GAP connection established (con 0)
I (154451) chip[DL]: CHIPoBLE advertising stopped
I (154461) app-devicecallbacks: Current free heap: 96232
I (155951) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (155961) chip[BLE]: local and remote recv window sizes = 5
I (155961) chip[BLE]: selected BTP version 4
I (155961) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (156091) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1
I (156091) chip[DL]: CHIPoBLE subscribe received
I (156091) NimBLE: GATT procedure initiated: notify;
I (156101) NimBLE: att_handle=14
I (156121) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (156121) app-devicecallbacks: CHIPoBLE connection established
I (156131) app-devicecallbacks: Current free heap: 96232
I (156181) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (156181) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:108135741 on exchange 57528r
I (156541) chip[IN]: Prepared plaintext message 0x3ffe2454 to 0x0000000000000000 of type 0x21 and protocolId (0, 0) on exchange 57528r with MessageCounter:2979804365.
I (156551) chip[IN]: Sending plaintext msg 0x3ffe2454 with MessageCounter:2979804365 to 0x0000000000000000 at monotonic time: 155850 msec
I (156571) NimBLE: GATT procedure initiated: notify;
I (156571) NimBLE: att_handle=14
I (156571) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (156581) chip[DL]: Long dispatch time: 400 ms, for event type 7
I (156631) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (156631) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:108135742 on exchange 57528r
I (158201) chip[IN]: Prepared plaintext message 0x3ffe23b4 to 0x0000000000000000 of type 0x23 and protocolId (0, 0) on exchange 57528r with MessageCounter:2979804366.
I (158211) chip[IN]: Sending plaintext msg 0x3ffe23b4 with MessageCounter:2979804366 to 0x0000000000000000 at monotonic time: 157510 msec
I (158221) NimBLE: GATT procedure initiated: notify;
I (158221) NimBLE: att_handle=14
I (158231) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (158241) chip[DL]: Long dispatch time: 1610 ms, for event type 7
I (158291) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (158301) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:108135743 on exchange 57528r
I (158311) chip[IN]: Prepared plaintext message 0x3ffe2434 to 0x0000000000000000 of type 0x40 and protocolId (0, 0) on exchange 57528r with MessageCounter:2979804367.
I (158321) chip[IN]: Sending plaintext msg 0x3ffe2434 with MessageCounter:2979804367 to 0x0000000000000000 at monotonic time: 157620 msec
I (158341) NimBLE: GATT procedure initiated: notify;
I (158341) NimBLE: att_handle=14
I (158351) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158361) chip[SVR]: Commissioning completed session establishment step
I (158371) chip[SVR]: Device completed Rendezvous process
I (158431) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (158431) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:0 on exchange 57529r
I (158451) chip[ZCL]: OpCreds: commissioner has requested Device Attestation Credentials
I (158451) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57529r with MessageCounter:1.
I (158461) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:1 to 0x0000000000000000 at monotonic time: 157760 msec
I (158481) NimBLE: GATT procedure initiated: notify;
I (158481) NimBLE: att_handle=14
I (158491) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158491) NimBLE: GATT procedure initiated: notify;
I (158511) NimBLE: att_handle=14
I (158511) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158511) NimBLE: GATT procedure initiated: notify;
I (158521) NimBLE: att_handle=14
I (158521) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158791) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (158791) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:1 on exchange 57530r
I (158811) chip[ZCL]: OpCreds: commissioner has requested Device Attestation Credentials
I (158811) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57530r with MessageCounter:2.
I (158821) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:2 to 0x0000000000000000 at monotonic time: 158120 msec
I (158841) NimBLE: GATT procedure initiated: notify;
I (158841) NimBLE: att_handle=14
I (158851) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158851) NimBLE: GATT procedure initiated: notify;
I (158871) NimBLE: att_handle=14
I (158871) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (158871) NimBLE: GATT procedure initiated: notify;
I (158881) NimBLE: att_handle=14
I (158891) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (159011) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (159021) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:2 on exchange 57531r
I (159031) chip[ZCL]: OpCreds: commissioner has requested Attestation
I (159351) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57531r with MessageCounter:3.
I (159371) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:3 to 0x0000000000000000 at monotonic time: 158670 msec
I (159381) NimBLE: GATT procedure initiated: notify;
I (159381) NimBLE: att_handle=14
I (159391) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (159401) chip[DL]: Long dispatch time: 390 ms, for event type 7
I (159401) NimBLE: GATT procedure initiated: notify;
I (159411) NimBLE: att_handle=14
I (159411) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (159461) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (159471) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3 on exchange 57532r
I (159481) chip[ZCL]: OpCreds: commissioner has requested an OpCSR
I (160111) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0
I (160111) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57532r with MessageCounter:4.
I (160131) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:4 to 0x0000000000000000 at monotonic time: 159430 msec
I (160141) NimBLE: GATT procedure initiated: notify;
I (160141) NimBLE: att_handle=14
I (160151) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (160161) chip[DL]: Long dispatch time: 700 ms, for event type 7
I (160171) NimBLE: GATT procedure initiated: notify;
I (160171) NimBLE: att_handle=14
I (160171) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (160271) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160411) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160411) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4 on exchange 57533r
I (160431) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert
I (160431) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57533r with MessageCounter:5.
I (160441) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:5 to 0x0000000000000000 at monotonic time: 159740 msec
I (160451) NimBLE: GATT procedure initiated: notify;
I (160461) NimBLE: att_handle=14
I (160471) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (160541) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160631) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160721) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160731) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5 on exchange 57534r
I (160741) chip[ZCL]: OpCreds: commissioner has added an Op Cert
I (160741) chip[DIS]: Verifying the received credentials
I (162011) chip[DIS]: Added new fabric at index: 1, Initialized: 1
I (162011) chip[DIS]: Assigned compressed fabric ID: 0xED72ACA7202EA4F8, node ID: 0x000000000002104E
I (162031) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (162031) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (162051) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (162051) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (162071) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (162081) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (162091) app-devicecallbacks: Unhandled cluster ID: 62
I (162091) app-devicecallbacks: Current free heap: 90808
I (162101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (162121) app-devicecallbacks: Unhandled cluster ID: 62
I (162121) app-devicecallbacks: Current free heap: 90808
I (162141) chip[SVR]: Saved into server storage: Fabric1
I (162141) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (162151) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 000000000002104E, VendorId 0xE400
I (162161) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (162161) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (162181) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (162191) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (162201) app-devicecallbacks: Unhandled cluster ID: 62
I (162201) app-devicecallbacks: Current free heap: 90808
I (162211) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (162231) app-devicecallbacks: Unhandled cluster ID: 62
I (162231) app-devicecallbacks: Current free heap: 90808
I (162241) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (162241) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (162261) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (162261) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (162281) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (162291) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (162301) app-devicecallbacks: Unhandled cluster ID: 62
I (162301) app-devicecallbacks: Current free heap: 90808
I (162311) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (162331) app-devicecallbacks: Unhandled cluster ID: 62
I (162331) app-devicecallbacks: Current free heap: 90808
I (162351) chip[SVR]: Saved into server storage: Fabric1
I (162351) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (162361) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 000000000002104E, VendorId 0xE400
I (162371) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (162371) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (162391) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (162401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (162411) app-devicecallbacks: Unhandled cluster ID: 62
I (162411) app-devicecallbacks: Current free heap: 90808
I (162421) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (162441) app-devicecallbacks: Unhandled cluster ID: 62
I (162441) app-devicecallbacks: Current free heap: 90808
I (162451) chip[DIS]: Advertise operational node ED72ACA7202EA4F8-000000000002104E
I (162451) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (162471) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57534r with MessageCounter:6.
I (162491) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:6 to 0x0000000000000000 at monotonic time: 161790 msec
I (162501) NimBLE: GATT procedure initiated: notify;
I (162501) NimBLE: att_handle=14
I (162511) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (162521) chip[DL]: Long dispatch time: 1800 ms, for event type 7
I (165311) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (167811) NimBLE: GATT procedure initiated: notify;
I (167811) NimBLE: att_handle=14
I (167811) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (170621) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (173121) NimBLE: GATT procedure initiated: notify;
I (173121) NimBLE: att_handle=14
I (173131) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (175891) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (178391) NimBLE: GATT procedure initiated: notify;
I (178391) NimBLE: att_handle=14
I (178391) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (181151) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (183651) NimBLE: GATT procedure initiated: notify;
I (183651) NimBLE: att_handle=14
I (183651) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (186461) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (188961) NimBLE: GATT procedure initiated: notify;
I (188961) NimBLE: att_handle=14
I (188961) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (191681) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (194181) NimBLE: GATT procedure initiated: notify;
I (194181) NimBLE: att_handle=14
I (194181) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (196951) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (199451) NimBLE: GATT procedure initiated: notify;
I (199451) NimBLE: att_handle=14
I (199451) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (202261) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (204761) NimBLE: GATT procedure initiated: notify;
I (204761) NimBLE: att_handle=14
I (204771) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (207521) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (210031) NimBLE: GATT procedure initiated: notify;
I (210031) NimBLE: att_handle=14
I (210031) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (212831) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (215341) NimBLE: GATT procedure initiated: notify;
I (215341) NimBLE: att_handle=14
I (215341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (218101) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (220601) NimBLE: GATT procedure initiated: notify;
I (220601) NimBLE: att_handle=14
I (220601) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (223451) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (225961) NimBLE: GATT procedure initiated: notify;
I (225961) NimBLE: att_handle=14
I (225961) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (228721) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (231221) NimBLE: GATT procedure initiated: notify;
I (231221) NimBLE: att_handle=14
I (231231) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (234031) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (236531) NimBLE: GATT procedure initiated: notify;
I (236531) NimBLE: att_handle=14
I (236531) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (239341) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (241841) NimBLE: GATT procedure initiated: notify;
I (241841) NimBLE: att_handle=14
I (241841) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (244601) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (247111) NimBLE: GATT procedure initiated: notify;
I (247111) NimBLE: att_handle=14
I (247111) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (249871) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (252371) NimBLE: GATT procedure initiated: notify;
I (252371) NimBLE: att_handle=14
I (252371) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (255131) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (257641) NimBLE: GATT procedure initiated: notify;
I (257641) NimBLE: att_handle=14
I (257641) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (260401) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (262901) NimBLE: GATT procedure initiated: notify;
I (262901) NimBLE: att_handle=14
I (262911) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (265661) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (268171) NimBLE: GATT procedure initiated: notify;
I (268171) NimBLE: att_handle=14
I (268171) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (271021) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (273521) NimBLE: GATT procedure initiated: notify;
I (273521) NimBLE: att_handle=14
I (273531) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (276281) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (278791) NimBLE: GATT procedure initiated: notify;
I (278791) NimBLE: att_handle=14
I (278791) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (281551) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (284051) NimBLE: GATT procedure initiated: notify;
I (284051) NimBLE: att_handle=14
I (284051) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (286861) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (289361) NimBLE: GATT procedure initiated: notify;
I (289361) NimBLE: att_handle=14
I (289371) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (292131) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (294631) NimBLE: GATT procedure initiated: notify;
I (294631) NimBLE: att_handle=14
I (294631) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (297391) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (299891) NimBLE: GATT procedure initiated: notify;
I (299891) NimBLE: att_handle=14
I (299891) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (302701) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (305201) NimBLE: GATT procedure initiated: notify;
I (305201) NimBLE: att_handle=14
I (305201) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (307971) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (310471) NimBLE: GATT procedure initiated: notify;
I (310471) NimBLE: att_handle=14
I (310471) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (313281) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (315781) NimBLE: GATT procedure initiated: notify;
I (315781) NimBLE: att_handle=14
I (315781) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (318541) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (321041) NimBLE: GATT procedure initiated: notify;
I (321041) NimBLE: att_handle=14
I (321041) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (323811) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (326311) NimBLE: GATT procedure initiated: notify;
I (326311) NimBLE: att_handle=14
I (326311) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (329071) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (330201) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (330201) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7 on exchange 57535r
I (330221) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57535r with MessageCounter:7.
I (330231) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:7 to 0x0000000000000000 at monotonic time: 329530 msec
I (330241) NimBLE: GATT procedure initiated: notify;
I (330251) NimBLE: att_handle=14
I (330251) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (332941) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (335441) NimBLE: GATT procedure initiated: notify;
I (335441) NimBLE: att_handle=14
I (335441) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (338251) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (340751) NimBLE: GATT procedure initiated: notify;
I (340751) NimBLE: att_handle=14
I (340751) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (343521) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (346021) NimBLE: GATT procedure initiated: notify;
I (346021) NimBLE: att_handle=14
I (346021) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (348831) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (351331) NimBLE: GATT procedure initiated: notify;
I (351331) NimBLE: att_handle=14
I (351341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (354091) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (356591) NimBLE: GATT procedure initiated: notify;
I (356591) NimBLE: att_handle=14
I (356591) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (359361) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (361861) NimBLE: GATT procedure initiated: notify;
I (361861) NimBLE: att_handle=14
I (361861) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (364621) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (367121) NimBLE: GATT procedure initiated: notify;
I (367121) NimBLE: att_handle=14
I (367131) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (369891) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (372391) NimBLE: GATT procedure initiated: notify;
I (372391) NimBLE: att_handle=14
I (372401) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (375151) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (377661) NimBLE: GATT procedure initiated: notify;
I (377661) NimBLE: att_handle=14
I (377661) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (380461) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (382971) NimBLE: GATT procedure initiated: notify;
I (382971) NimBLE: att_handle=14
I (382971) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (383251) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (383261) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8 on exchange 57536r
I (383271) chip[NP]: ESP32NetworkProvisioningDelegate: SSID: MINDLES
I (383271) chip[DL]: WiFi station mode change: Enabled -> Disabled
I (383291) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP
I (383291) wifi:mode : sta (78:21:84:b8:f1:74) + softAP (78:21:84:b8:f1:75)
I (383291) wifi:Total power save buffer number: 16
I (383301) wifi:Init max length of beacon: 752/752
I (383311) wifi:Init max length of beacon: 752/752
I (383321) chip[DL]: WiFi station mode change: Disabled -> Enabled
I (383321) chip[DIS]: Advertise operational node ED72ACA7202EA4F8-000000000002104E
I (383321) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
E (383341) chip[SVR]: Operational advertising enabled
I (383341) app-devicecallbacks: Current free heap: 85572
I (383351) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 57536r with MessageCounter:8.
I (383361) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:8 to 0x0000000000000000 at monotonic time: 382660 msec
I (383371) NimBLE: GATT procedure initiated: notify;
I (383391) NimBLE: att_handle=14
I (383391) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
E (383391) chip[DL]: Long dispatch time: 130 ms, for event type 7
I (383411) chip[DL]: Done driving station state, nothing else to do...
I (383411) chip[DL]: Done driving station state, nothing else to do...
I (383421) chip[DL]: Done driving station state, nothing else to do...
I (383421) chip[DL]: WIFI_EVENT_AP_START
I (383431) chip[DL]: WiFi AP state change: NotActive -> Active
I (383441) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (383451) wifi:mode : sta (78:21:84:b8:f1:74)
I (383461) chip[DL]: WiFi AP state change: Active -> Deactivating
I (383461) app-devicecallbacks: Current free heap: 91056
I (383461) chip[DL]: WIFI_EVENT_AP_STOP
I (383471) chip[DL]: WiFi AP state change: Deactivating -> NotActive
I (383471) app-devicecallbacks: Current free heap: 92576
I (386091) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (388591) NimBLE: GATT procedure initiated: notify;
I (388591) NimBLE: att_handle=14
I (388601) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0
I (390861) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0
I (390861) chip[DL]: CHIPoBLE unsubscribe received
I (390861) chip[BLE]: Releasing end point's BLE connection back to application.
I (393241) chip[DL]: BLE GAP connection terminated (con 0 reason 0x13)
I (393251) app-devicecallbacks: CHIPoBLE disconnected
I (393251) app-devicecallbacks: Current free heap: 92576
I (408001) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:3305705472 on exchange 57537r
I (408001) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffc4750
I (408011) chip[DIS]: CASE handshake initiated, closing all BLE Connections
I (408021) chip[IN]: CASE Server disabling CASE session setups
I (408031) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (408041) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (408051) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (408051) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (408071) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (408081) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (408091) app-devicecallbacks: Unhandled cluster ID: 62
I (408091) app-devicecallbacks: Current free heap: 92060
I (408101) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (408121) app-devicecallbacks: Unhandled cluster ID: 62
I (408121) app-devicecallbacks: Current free heap: 92048
I (408131) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (408131) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (408141) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (408161) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (408171) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (408181) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (408191) app-devicecallbacks: Unhandled cluster ID: 62
I (408201) app-devicecallbacks: Current free heap: 92060
I (408211) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (408221) app-devicecallbacks: Unhandled cluster ID: 62
I (408221) app-devicecallbacks: Current free heap: 92060
I (409161) chip[IN]: Prepared plaintext message 0x3ffc46c8 to 0x0000000000000000 of type 0x31 and protocolId (0, 0) on exchange 57537r with MessageCounter:2510115655.
I (409181) chip[IN]: Sending plaintext msg 0x3ffc46c8 with MessageCounter:2510115655 to 0x0000000000000000 at monotonic time: 408480 msec
E (409191) chip[DL]: Long dispatch time: 1190 ms, for event type 4
I (409341) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:3305705473 on exchange 57537r
I (411241) chip[IN]: Prepared plaintext message 0x3ffc46c8 to 0x0000000000000000 of type 0x40 and protocolId (0, 0) on exchange 57537r with MessageCounter:2510115656.
I (411251) chip[IN]: Sending plaintext msg 0x3ffc46c8 with MessageCounter:2510115656 to 0x0000000000000000 at monotonic time: 410550 msec
I (411271) chip[IN]: CASE Session established. Setting up the secure channel.
I (411271) chip[IN]: CASE secure channel is available now.
I (411271) chip[IN]: CASE Server enabling CASE session setups
E (411281) chip[DL]: Long dispatch time: 1940 ms, for event type 4
I (411561) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3305705474 on exchange 57537r
I (435931) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:0 on exchange 57538r
I (435941) chip[ZCL]: On/Off set value: 1 0
I (435951) chip[ZCL]: On/off already set to new value
I (435951) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 57538r with MessageCounter:1.
I (435961) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:1 to 0x000000000001B669 at monotonic time: 435260 msec
I (440921) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:1 to 0x000000000001B669 at monotonic time: 440220 msec
I (440941) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1 on exchange 57538r
I (441051) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2 on exchange 57538r
I (468191) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3 on exchange 57539r
I (468191) chip[ZCL]: 0x3f409069MOVE_TO_LEVEL a 0 0 0
I (468211) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 57539r with MessageCounter:2.
I (468221) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:2 to 0x000000000001B669 at monotonic time: 467520 msec
I (468231) chip[ZCL]: Event: move from 255
I (468231) chip[ZCL]: to 10
I (468241) chip[ZCL]: (diff -1)
I (468241) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (468251) app-devicecallbacks: Current free heap: 89652
I (468261) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (468271) app-devicecallbacks: Unhandled cluster ID: 5
I (468271) app-devicecallbacks: Current free heap: 89652
I (473181) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:2 to 0x000000000001B669 at monotonic time: 472480 msec
I (473201) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:5 on exchange 57539r