MATTER/Log test7/ app

matter_log.test7.1success.20221010.esp32.txt

0.04MB

실행 명령 @ controller 

• connect -ble 3840 20202021 135246
• zcl NetworkCommissioning AddWiFiNetwork 135246 0 0 ssid=str:*** credentials=str:*** breadcrumb=0 timeoutMs=1000
• zcl NetworkCommissioning EnableNetwork 135246 0 0 networkID=str:*** breadcrumb=0 timeoutMs=1000
• close-ble
• resolve 135246
• zcl OnOff On 135246 1 1
• zcl OnOff On 135246 1 1
• zcl OnOff Off 135246 1 1

 

/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 ---
j%�(961) all-ets Jul 29 2019 12:21:46

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

entry 0x40080694
I (29) boot: ESP-IDF v4.4.1 2nd stage bootloader
I (29) boot: compile time 23:04:57
I (29) boot: chip revision: 3
I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (76) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 factory          factory app      00 00 00010000 001db000
I (91) boot:  3 ot_storage       Unknown data     01 3a 001eb000 00002000
I (99) boot: End of partition table
I (103) boot_comm: chip revision: 3, min. application chip revision: 0
I (110) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2c50ch (181516) map
I (185) esp_image: segment 1: paddr=0003c534 vaddr=3ffbdb60 size=03ae4h ( 15076) load
I (191) esp_image: segment 2: paddr=00040020 vaddr=400d0020 size=d0b8ch (854924) map
I (500) esp_image: segment 3: paddr=00110bb4 vaddr=3ffc1644 size=01ae4h (  6884) load
I (503) esp_image: segment 4: paddr=001126a0 vaddr=40080000 size=1c98ch (117132) load
I (554) esp_image: segment 5: paddr=0012f034 vaddr=50000000 size=00010h (    16) load
I (569) boot: Loaded app from partition at offset 0x10000
I (569) boot: Disabling RNG early entropy source...
I (580) cpu_start: Pro cpu up.
I (581) 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 (597) cpu_start: Pro cpu start user code
I (597) cpu_start: cpu freq: 160000000
I (597) cpu_start: Application information:
I (601) cpu_start: Project name:     chip-all-clusters-app
I (607) cpu_start: App version:      test_event_4_2021_07_06-1264-gf
I (614) cpu_start: Compile time:     Oct  9 2022 23:04:53
I (621) cpu_start: ELF file SHA256:  44c441f457cc9f36...
I (626) cpu_start: ESP-IDF:          v4.4.1
I (632) heap_init: Initializing. RAM available for dynamic allocation:
I (639) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (645) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (651) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (657) heap_init: At 3FFD2108 len 0000DEF8 (55 KiB): DRAM
I (663) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (669) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (676) heap_init: At 4009C98C len 00003674 (13 KiB): IRAM
I (683) spi_flash: detected chip: generic
I (687) 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 (761) wifi:wifi driver task: 3ffd93c0, prio:23, stack:6656, core=0
I (761) system_api: Base MAC address is not set
I (761) system_api: read default base MAC address from EFUSE
I (771) wifi:wifi firmware version: 63017e0
I (771) wifi:wifi certification version: v7.0
I (771) wifi:config NVS flash: enabled
I (781) wifi:config nano formating: disabled
I (791) wifi:Init data frame dynamic rx buffer num: 32
I (791) wifi:Init management frame dynamic rx buffer num: 32
I (791) wifi:Init management short buffer num: 32
I (801) wifi:Init dynamic tx buffer num: 32
I (801) wifi:Init static rx buffer size: 1600
I (801) wifi:Init static rx buffer num: 10
I (811) wifi:Init dynamic rx buffer num: 32
I (811) wifi_init: rx ba win: 6
I (811) wifi_init: tcpip mbox: 32
I (831) wifi_init: udp mbox: 6
I (831) wifi_init: tcp mbox: 6
I (831) wifi_init: tcp tx win: 5744
I (831) wifi_init: tcp rx win: 5744
I (841) wifi_init: tcp mss: 1440
I (841) wifi_init: WiFi IRAM OP enabled
I (851) wifi_init: WiFi RX IRAM OP enabled
I (851) chip[DL]: AUDIT: ===== RANDOM NUMBER GENERATOR AUDIT START ====
I (851) chip[DL]: AUDIT: * Validate buf1 and buf2 are <<<different every run/boot!>>>
I (871) chip[DL]: AUDIT: * Validate r1 and r2 are <<<different every run/boot!>>>
I (881) chip[DL]: AUDIT: * buf1: 8CEE79ABFD462D09330C3DDF6FFF14DD
I (881) chip[DL]: AUDIT: * buf2: 45BB8018BC17C2D3EABB5598DD529076
I (891) chip[DL]: AUDIT: * r1: 0x78ABC5CD r2: 0x8921ED77
I (891) chip[DL]: AUDIT: ===== RANDOM NUMBER GENERATOR AUDIT END ====
I (921) chip[DL]: NVS set: chip-counters/reboot-count = 2 (0x2)
I (921) all-clusters-app: Setup discriminator: 3840 (0xf00)
I (921) all-clusters-app: Setup PIN code: 20202021 (0x1344225)
I (921) BTDM_INIT: BT controller compile version [5688ed5]
I (941) all-clusters-app: Short Manual(decimal) setup code: 34970112332
I (941) all-clusters-app: Long Manual(decimal) setup code:  749701123309050177298
I (941) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (951) all-clusters-app: QR CODE Text: 'MT:C8XA0SRB00KA0648G00'
W (961) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (961) 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 (1401) CHIP[DL]: BLE host-controller synced
I (1901) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1911) NimBLE: GAP procedure initiated: advertise; 
I (1921) NimBLE: disc_mode=2
I (1921) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1931) NimBLE: 

I (1931) chip[DL]: CHIPoBLE advertising started
E (1931) chip[DL]: Long dispatch time: 1010 ms, for event type 2
I (1951) chip[DL]: Starting ESP WiFi layer
I (1951) wifi:mode : sta (78:21:84:b8:f1:74)
I (1951) wifi:enable tsf
W (1951) wifi:Haven't to connect to a suitable AP now!
I (1951) chip[DL]: Done driving station state, nothing else to do...
W (1971) wifi:Haven't to connect to a suitable AP now!
I (1971) chip[DL]: Done driving station state, nothing else to do...
I (1981) chip[ZCL]: Using ZAP configuration...
I (1991) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (1991) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (2001) chip[ZCL]: OpCreds: Stored 0 fabrics in fabrics list attribute.
I (2011) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (2021) app-devicecallbacks: Unhandled cluster ID: 62
I (2031) app-devicecallbacks: Current free heap: 100800

I (2031) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (2041) app-devicecallbacks: Unhandled cluster ID: 62
I (2051) app-devicecallbacks: Current free heap: 100800

I (2061) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2071) app-devicecallbacks: Unhandled cluster ID: 40
I (2081) app-devicecallbacks: Current free heap: 100800

I (2081) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (2091) app-devicecallbacks: Unhandled cluster ID: 40
I (2101) app-devicecallbacks: Current free heap: 100800

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

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

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

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

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

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

I (2251) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2251) app-devicecallbacks: Unhandled cluster ID: 4
I (2271) app-devicecallbacks: Current free heap: 100800

I (2271) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2281) app-devicecallbacks: Unhandled cluster ID: 5
I (2291) app-devicecallbacks: Current free heap: 100800

I (2291) chip[ZCL]: Window Covering Cluster init
I (2301) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (2311) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (2321) app-devicecallbacks: Unhandled cluster ID: 768
I (2331) app-devicecallbacks: Current free heap: 100800

I (2331) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2341) app-devicecallbacks: Unhandled cluster ID: 768
I (2351) app-devicecallbacks: Current free heap: 100800

I (2351) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2371) app-devicecallbacks: Unhandled cluster ID: 768
I (2371) app-devicecallbacks: Current free heap: 100800

I (2381) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2391) app-devicecallbacks: Unhandled cluster ID: 1030
I (2391) app-devicecallbacks: Current free heap: 100800

I (2401) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2421) app-devicecallbacks: Unhandled cluster ID: 1030
I (2421) app-devicecallbacks: Current free heap: 100800

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

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

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

I (2521) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2531) app-devicecallbacks: Unhandled cluster ID: 1030
I (2541) app-devicecallbacks: Current free heap: 100800

I (2551) chip[DL]: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8)
I (2601) chip[DIS]: CHIP minimal mDNS started advertising.
I (2601) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (2601) chip[DIS]: Start dns-sd server - no current nodeId
I (2611) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/00
I (2631) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2631) chip[IN]: CASE Server enabling CASE session setups
I (2641) chip[SVR]: Server Listening...
I (2641) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2651) app-devicecallbacks: Unhandled cluster ID: 1026
I (2661) app-devicecallbacks: Current free heap: 98648

I (2671) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2681) app-devicecallbacks: Unhandled cluster ID: 257
I (2681) app-devicecallbacks: Current free heap: 98528

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

I (2711) chip[ZCL]: 0x3f408b33ep 2 clus 0x0000_0008 attr 0x0000_0000 not supported
E (2721) chip[DL]: Long dispatch time: 740 ms, for event type 2
I (2731) app-devicecallbacks: Current free heap: 97748

I (2731) chip[DL]: WIFI_EVENT_STA_START
W (2731) wifi:Haven't to connect to a suitable AP now!
I (2741) chip[DL]: Done driving station state, nothing else to do...
I (2751) app-devicecallbacks: Current free heap: 97748

I (2761) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (2761) chip[DL]: Device already advertising, stop active advertisement and restart
I (2771) NimBLE: GAP procedure initiated: stop advertising.

I (2781) NimBLE: GAP procedure initiated: advertise; 
I (2791) NimBLE: disc_mode=2
I (2791) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2801) NimBLE: 

I (32601) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840)
I (32601) chip[DL]: Device already advertising, stop active advertisement and restart
I (32621) NimBLE: GAP procedure initiated: stop advertising.

I (32621) NimBLE: GAP procedure initiated: advertise; 
I (32631) NimBLE: disc_mode=2
I (32631) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (32641) NimBLE: 



> ==== connect -ble 3840 20202021 135246
> 
>
I (147801) chip[DL]: BLE GAP connection established (con 0)
I (147801) chip[DL]: CHIPoBLE advertising stopped
I (147801) app-devicecallbacks: Current free heap: 97712

I (148601) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (148611) chip[BLE]: local and remote recv window sizes = 5
I (148611) chip[BLE]: selected BTP version 4
I (148621) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (148691) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1
I (148701) chip[DL]: CHIPoBLE subscribe received
I (148701) NimBLE: GATT procedure initiated: notify; 
I (148711) NimBLE: att_handle=14

I (148721) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (148721) app-devicecallbacks: CHIPoBLE connection established
I (148741) app-devicecallbacks: Current free heap: 97712

I (148781) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (148791) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:4102266059 on exchange 41064r
I (149151) chip[IN]: Prepared plaintext message 0x3ffe2454 to 0x0000000000000000 of type 0x21 and protocolId (0, 0) on exchange 41064r with MessageCounter:3353863205.
I (149161) chip[IN]: Sending plaintext msg 0x3ffe2454 with MessageCounter:3353863205 to 0x0000000000000000 at monotonic time: 148460 msec
I (149171) NimBLE: GATT procedure initiated: notify; 
I (149171) NimBLE: att_handle=14

I (149181) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (149191) chip[DL]: Long dispatch time: 400 ms, for event type 7
I (149231) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (149241) chip[EM]: Received message of type 0x22 with protocolId (0, 0) and MessageCounter:4102266060 on exchange 41064r
I (150801) chip[IN]: Prepared plaintext message 0x3ffe23b4 to 0x0000000000000000 of type 0x23 and protocolId (0, 0) on exchange 41064r with MessageCounter:3353863206.
I (150811) chip[IN]: Sending plaintext msg 0x3ffe23b4 with MessageCounter:3353863206 to 0x0000000000000000 at monotonic time: 150110 msec
I (150821) NimBLE: GATT procedure initiated: notify; 
I (150821) NimBLE: att_handle=14

I (150831) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (150841) chip[DL]: Long dispatch time: 1600 ms, for event type 7
I (150941) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (150951) chip[EM]: Received message of type 0x24 with protocolId (0, 0) and MessageCounter:4102266061 on exchange 41064r
I (150961) chip[IN]: Prepared plaintext message 0x3ffe2434 to 0x0000000000000000 of type 0x40 and protocolId (0, 0) on exchange 41064r with MessageCounter:3353863207.
I (150981) chip[IN]: Sending plaintext msg 0x3ffe2434 with MessageCounter:3353863207 to 0x0000000000000000 at monotonic time: 150280 msec
I (150991) NimBLE: GATT procedure initiated: notify; 
I (150991) NimBLE: att_handle=14

I (151001) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151011) chip[SVR]: Commissioning completed session establishment step
I (151021) chip[SVR]: Device completed Rendezvous process
I (151081) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (151081) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:0 on exchange 41065r
I (151101) chip[ZCL]: OpCreds: commissioner has requested Device Attestation Credentials
I (151101) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41065r with MessageCounter:1.
I (151111) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:1 to 0x0000000000000000 at monotonic time: 150410 msec
I (151131) NimBLE: GATT procedure initiated: notify; 
I (151141) NimBLE: att_handle=14

I (151141) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151141) NimBLE: GATT procedure initiated: notify; 
I (151161) NimBLE: att_handle=14

I (151161) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151171) NimBLE: GATT procedure initiated: notify; 
I (151171) NimBLE: att_handle=14

I (151171) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151261) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (151261) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:1 on exchange 41066r
I (151281) chip[ZCL]: OpCreds: commissioner has requested Device Attestation Credentials
I (151281) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41066r with MessageCounter:2.
I (151291) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:2 to 0x0000000000000000 at monotonic time: 150590 msec
I (151311) NimBLE: GATT procedure initiated: notify; 
I (151321) NimBLE: att_handle=14

I (151321) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151321) NimBLE: GATT procedure initiated: notify; 
I (151341) NimBLE: att_handle=14

I (151341) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151351) NimBLE: GATT procedure initiated: notify; 
I (151351) NimBLE: att_handle=14

I (151351) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151441) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (151441) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:2 on exchange 41067r
I (151461) chip[ZCL]: OpCreds: commissioner has requested Attestation
I (151781) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41067r with MessageCounter:3.
I (151791) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:3 to 0x0000000000000000 at monotonic time: 151090 msec
I (151811) NimBLE: GATT procedure initiated: notify; 
I (151811) NimBLE: att_handle=14

I (151811) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (151821) chip[DL]: Long dispatch time: 380 ms, for event type 7
I (151821) NimBLE: GATT procedure initiated: notify; 
I (151841) NimBLE: att_handle=14

I (151841) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (151931) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (151941) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:3 on exchange 41068r
I (151951) chip[ZCL]: OpCreds: commissioner has requested an OpCSR
I (152581) chip[ZCL]: OpCreds: NewCertificateSigningRequest returned 0
I (152581) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41068r with MessageCounter:4.
I (152591) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:4 to 0x0000000000000000 at monotonic time: 151890 msec
I (152611) NimBLE: GATT procedure initiated: notify; 
I (152611) NimBLE: att_handle=14

I (152621) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (152621) chip[DL]: Long dispatch time: 680 ms, for event type 7
I (152641) NimBLE: GATT procedure initiated: notify; 
I (152641) NimBLE: att_handle=14

I (152641) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (152701) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (152881) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (152881) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4 on exchange 41069r
I (152901) chip[ZCL]: OpCreds: commissioner has added a trusted root Cert
I (152901) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41069r with MessageCounter:5.
I (152911) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:5 to 0x0000000000000000 at monotonic time: 152210 msec
I (152931) NimBLE: GATT procedure initiated: notify; 
I (152931) NimBLE: att_handle=14

I (152941) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (153111) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (153201) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (153371) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (153381) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5 on exchange 41070r
I (153391) chip[ZCL]: OpCreds: commissioner has added an Op Cert
I (153401) chip[DIS]: Verifying the received credentials
I (154661) chip[DIS]: Added new fabric at index: 1, Initialized: 1
I (154661) chip[DIS]: Assigned compressed fabric ID: 0xF83D483222B31918, node ID: 0x000000000002104E
I (154681) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (154681) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (154701) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (154701) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (154711) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (154731) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (154741) app-devicecallbacks: Unhandled cluster ID: 62
I (154741) app-devicecallbacks: Current free heap: 92312

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

I (154781) chip[SVR]: Saved into server storage: Fabric1
I (154791) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (154801) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 000000000002104E, VendorId 0xE400
I (154811) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (154811) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (154831) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (154841) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (154851) app-devicecallbacks: Unhandled cluster ID: 62
I (154851) app-devicecallbacks: Current free heap: 92312

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

I (154891) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (154891) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (154901) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (154911) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (154931) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (154941) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (154951) app-devicecallbacks: Unhandled cluster ID: 62
I (154951) app-devicecallbacks: Current free heap: 92312

I (154961) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (154971) app-devicecallbacks: Unhandled cluster ID: 62
I (154981) app-devicecallbacks: Current free heap: 92312

I (155001) chip[SVR]: Saved into server storage: Fabric1
I (155001) chip[DIS]: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I (155011) chip[ZCL]: OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 000000000002104E, VendorId 0xE400
I (155021) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (155021) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (155041) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (155051) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (155061) app-devicecallbacks: Unhandled cluster ID: 62
I (155061) app-devicecallbacks: Current free heap: 92312

I (155071) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (155081) app-devicecallbacks: Unhandled cluster ID: 62
I (155091) app-devicecallbacks: Current free heap: 92312

I (155101) chip[DIS]: Advertise operational node F83D483222B31918-000000000002104E
I (155101) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (155111) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41070r with MessageCounter:6.
I (155131) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:6 to 0x0000000000000000 at monotonic time: 154430 msec
I (155141) NimBLE: GATT procedure initiated: notify; 
I (155141) NimBLE: att_handle=14

I (155151) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (155161) chip[DL]: Long dispatch time: 1780 ms, for event type 7
I (157831) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (160331) NimBLE: GATT procedure initiated: notify; 
I (160331) NimBLE: att_handle=14

I (160331) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (163091) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (165601) NimBLE: GATT procedure initiated: notify; 
I (165601) NimBLE: att_handle=14

I (165601) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (168361) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (170861) NimBLE: GATT procedure initiated: notify; 
I (170861) NimBLE: att_handle=14

I (170861) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (173581) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (176081) NimBLE: GATT procedure initiated: notify; 
I (176081) NimBLE: att_handle=14

I (176081) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (177411) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
> === zcl NetworkCommissioning AddWiFiNetwork 135246 0 0 ssid=str:*** credentials=str:*** breadcrumb=0 timeoutMs=1000
> 
> 
I (177411) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7 on exchange 41071r
I (177431) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41071r with MessageCounter:7.
I (177441) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:7 to 0x0000000000000000 at monotonic time: 176740 msec
I (177451) NimBLE: GATT procedure initiated: notify; 
I (177451) NimBLE: att_handle=14

I (177461) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (180151) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (182651) NimBLE: GATT procedure initiated: notify; 
I (182651) NimBLE: att_handle=14

I (182651) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (185411) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (187921) NimBLE: GATT procedure initiated: notify; 
I (187921) NimBLE: att_handle=14

I (187921) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (190681) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (192751) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12


> === zcl NetworkCommissioning EnableNetwork 135246 0 0 networkID=str:*** breadcrumb=0 timeoutMs=1000
> 
>
I (192751) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8 on exchange 41072r
I (192771) chip[NP]: ESP32NetworkProvisioningDelegate: SSID: ***
I (192771) chip[DL]: WiFi station mode change: Enabled -> Disabled
I (192801) chip[DL]: Changing ESP WiFi mode: STA -> STA+AP
I (192801) wifi:mode : sta (78:21:84:b8:f1:74) + softAP (78:21:84:b8:f1:75)
I (192811) wifi:Total power save buffer number: 16
I (192821) wifi:Init max length of beacon: 752/752
I (192821) wifi:Init max length of beacon: 752/752
I (192831) chip[DL]: WiFi station mode change: Disabled -> Enabled
I (192831) chip[DIS]: Advertise operational node F83D483222B31918-000000000002104E
I (192831) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
E (192841) chip[SVR]: Operational advertising enabled
I (192851) app-devicecallbacks: Current free heap: 90976

I (192861) chip[IN]: Prepared encrypted message 0x3ffe24f4 to 0x0000000000000000 of type 0x9 and protocolId (0, 1) on exchange 41072r with MessageCounter:8.
I (192871) chip[IN]: Sending encrypted msg 0x3ffe24f4 with MessageCounter:8 to 0x0000000000000000 at monotonic time: 192170 msec
I (192891) NimBLE: GATT procedure initiated: notify; 
I (192891) NimBLE: att_handle=14

I (192891) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
E (192901) chip[DL]: Long dispatch time: 150 ms, for event type 7
W (192911) wifi:Haven't to connect to a suitable AP now!
I (192921) chip[DL]: Attempting to connect WiFi station interface
I (192921) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (192931) chip[DL]: Done driving station state, nothing else to do...
W (192931) wifi:Haven't to connect to a suitable AP now!
I (192941) chip[DL]: Attempting to connect WiFi station interface
E (192951) wifi:sta is connecting, return error
E (192951) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
W (192961) wifi:Haven't to connect to a suitable AP now!
I (192961) chip[DL]: Attempting to connect WiFi station interface
E (192971) wifi:sta is connecting, return error
E (192971) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (192981) chip[DL]: WIFI_EVENT_AP_START
I (192991) chip[DL]: WiFi AP state change: NotActive -> Active
I (193001) chip[DL]: Changing ESP WiFi mode: STA+AP -> STA
I (193001) wifi:mode : sta (78:21:84:b8:f1:74)
I (193011) chip[DL]: WiFi AP state change: Active -> Deactivating
I (193011) app-devicecallbacks: Current free heap: 92384

I (193021) chip[DL]: WIFI_EVENT_AP_STOP
I (193021) chip[DL]: WiFi AP state change: Deactivating -> NotActive
I (193031) app-devicecallbacks: Current free heap: 93904

I (195631) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (196061) wifi:new:<9,1>, old:<1,1>, ap:<255,255>, sta:<9,1>, prof:1
I (196801) wifi:state: init -> auth (b0)
I (196811) wifi:state: auth -> assoc (0)
I (196811) wifi:state: assoc -> run (10)
I (196941) wifi:connected with MINDLES, aid = 9, channel 9, 40U, bssid = 88:36:6c:e0:45:6c
I (196941) wifi:security: WPA2-PSK, phy: bgn, rssi: -65
I (196951) wifi:pm start, type: 1

I (196961) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (196961) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (196961) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (196971) chip[DL]: WiFi station interface connected
I (196981) chip[DL]: Done driving station state, nothing else to do...
I (196991) app-devicecallbacks: Current free heap: 93244

I (196991) wifi:I (197001) chip[DL]: Updating advertising data
AP's beacon interval = 102400 us, DTIM period = 1I (197001) app-devicecallbacks: Current free heap: 91548


I (197741) esp_netif_handlers: sta ip: 192.168.0.20, mask: 255.255.255.0, gw: 192.168.0.1
I (197751) chip[DL]: IP_EVENT_STA_GOT_IP
I (197751) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.0.20/255.255.255.0 gateway 192.168.0.1
I (197761) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (197771) app-devicecallbacks: Current free heap: 93192

I (197771) app-devicecallbacks: Server ready at: 192.168.0.20:5540
I (197791) chip[DIS]: CHIP minimal mDNS started advertising.
I (197791) chip[DIS]: Advertise operational node F83D483222B31918-000000000002104E
I (197801) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (197811) chip[DIS]: Have operational credentials
I (197811) app-devicecallbacks: Current free heap: 88976

I (197821) chip[DIS]: CHIP minimal mDNS started advertising.
I (197831) chip[DIS]: Advertise operational node F83D483222B31918-000000000002104E
I (197831) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (197851) chip[DIS]: Have operational credentials
I (197851) app-devicecallbacks: Current free heap: 92624

I (198131) NimBLE: GATT procedure initiated: notify; 
I (198131) NimBLE: att_handle=14

I (198141) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (198741) chip[DL]: IP_EVENT_GOT_IP6
I (198741) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:7a21:84ff:feb8:f174
I (198751) app-devicecallbacks: Current free heap: 93712

I (198751) chip[DIS]: CHIP minimal mDNS started advertising.
I (198761) chip[DIS]: Advertise operational node F83D483222B31918-000000000002104E
I (198771) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (198781) chip[DIS]: Have operational credentials
I (198781) app-devicecallbacks: Current free heap: 92144

W (199761) wifi:<ba-add>idx:0 (ifx:0, 88:36:6c:e0:45:6c), tid:0, ssn:11, winSize:64
I (200941) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (203441) NimBLE: GATT procedure initiated: notify; 
I (203441) NimBLE: att_handle=14

I (203451) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 


> === close-ble
> 
>
I (206211) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
W (206821) wifi:<ba-add>idx:1 (ifx:0, 88:36:6c:e0:45:6c), tid:6, ssn:0, winSize:64
I (208711) NimBLE: GATT procedure initiated: notify; 
I (208711) NimBLE: att_handle=14

I (208711) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 0 
I (210801) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0
I (210801) chip[DL]: CHIPoBLE unsubscribe received
I (210801) chip[BLE]: Releasing end point's BLE connection back to application.
I (213541) chip[DL]: BLE GAP connection terminated (con 0 reason 0x13)
I (213541) app-devicecallbacks: CHIPoBLE disconnected
I (213541) app-devicecallbacks: Current free heap: 93616



> === resolve 135246
> 
> 
I (226701) chip[DIS]: CASE handshake initiated, closing all BLE Connectionse. EC 0x3ffc4750ter:2956413057 on exchange 41073r
I (226721) chip[IN]: CASE Server disabling CASE session setups
I (226721) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (226731) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (226741) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (226751) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (226761) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (226771) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (226781) app-devicecallbacks: Unhandled cluster ID: 62
I (226781) app-devicecallbacks: Current free heap: 93108

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

I (226821) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (226821) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x000000000002104E, VendorId 0xE400
I (226841) chip[ZCL]: OpCreds: Call to writeFabricsIntoFabricsListAttribute
I (226851) chip[ZCL]: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x000000000002104E vendorId 0xE400
I (226861) chip[ZCL]: OpCreds: Stored 1 fabrics in fabrics list attribute.
I (226871) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x003e', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (226891) app-devicecallbacks: Unhandled cluster ID: 62
I (226891) app-devicecallbacks: Current free heap: 93228

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

I (227851) chip[IN]: Prepared plaintext message 0x3ffc46c8 to 0x0000000000000000 of type 0x31 and protocolId (0, 0) on exchange 41073r with MessageCounter:2565126161.
I (227871) chip[IN]: Sending plaintext msg 0x3ffc46c8 with MessageCounter:2565126161 to 0x0000000000000000 at monotonic time: 227170 msec
E (227881) chip[DL]: Long dispatch time: 1190 ms, for event type 4
I (228431) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:2956413058 on exchange 41073r
I (230331) chip[IN]: Prepared plaintext message 0x3ffc46c8 to 0x0000000000000000 of type 0x40 and protocolId (0, 0) on exchange 41073r with MessageCounter:2565126162.
I (230351) chip[IN]: Sending plaintext msg 0x3ffc46c8 with MessageCounter:2565126162 to 0x0000000000000000 at monotonic time: 229650 msec
I (230361) chip[IN]: CASE Session established. Setting up the secure channel.
I (230361) chip[IN]: CASE secure channel is available now.
I (230371) chip[IN]: CASE Server enabling CASE session setups
E (230381) chip[DL]: Long dispatch time: 1950 ms, for event type 4
I (230511) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2956413059 on exchange 41073r


> === zcl OnOff On 135246 1 1
> 
>
I (293661) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:0 on exchange 41074r
I (293671) chip[ZCL]: On/Off set value: 1 1
I (293681) chip[ZCL]: Toggle on/off from 0 to 1
I (293681) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (293691) app-devicecallbacks: Current free heap: 90924

I (293691) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (293701) app-devicecallbacks: Current free heap: 90924

I (293721) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (293731) app-devicecallbacks: Unhandled cluster ID: 5
I (293731) app-devicecallbacks: Current free heap: 90924

I (293741) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 41074r with MessageCounter:1.
I (293761) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:1 to 0x000000000001B669 at monotonic time: 293060 msec
E (293771) chip[DL]: Long dispatch time: 110 ms, for event type 4
I (293771) chip[ZCL]: Event: move from 0
I (293771) chip[ZCL]:  to 255 
I (293791) chip[ZCL]: (diff +1)
I (293791) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (293801) app-devicecallbacks: Current free heap: 90924

I (293801) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (293811) app-devicecallbacks: Unhandled cluster ID: 5
I (293821) app-devicecallbacks: Current free heap: 90924

I (293871) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1 on exchange 41074r


> === zcl OnOff On 135246 1 1
> 
>
I (311891) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:2 on exchange 41075r
I (311891) chip[ZCL]: On/Off set value: 1 1
I (311901) chip[ZCL]: On/off already set to new value
I (311911) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 41075r with MessageCounter:2.
I (311921) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:2 to 0x000000000001B669 at monotonic time: 311220 msec
I (312111) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3 on exchange 41075r


> === zcl OnOff Off 135246 1 1
> 
>
I (328581) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:4 on exchange 41076r
I (328581) chip[ZCL]: On/Off set value: 1 0
I (328591) chip[ZCL]: Toggle on/off from 1 to 0
I (328601) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (328611) app-devicecallbacks: Current free heap: 90924

I (328611) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (328621) app-devicecallbacks: Unhandled cluster ID: 5
I (328631) app-devicecallbacks: Current free heap: 90924

I (328641) chip[IN]: Prepared encrypted message 0x3ffc46c8 to 0x000000000001B669 of type 0x9 and protocolId (0, 1) on exchange 41076r with MessageCounter:3.
I (328651) chip[IN]: Sending encrypted msg 0x3ffc46c8 with MessageCounter:3 to 0x000000000001B669 at monotonic time: 327950 msec
I (328671) chip[ZCL]: Event: move from 255
I (328671) chip[ZCL]:  to 0 
I (328671) chip[ZCL]: (diff -1)
I (328681) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (328691) app-devicecallbacks: Current free heap: 90924

I (328691) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0003'
I (328701) app-devicecallbacks: Unhandled cluster ID: 5
I (328721) app-devicecallbacks: Current free heap: 90924

I (328721) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (328731) app-devicecallbacks: Current free heap: 90924

I (328791) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:5 on exchange 41076r