I (22614) chip[DL]: System restarting
I (26) boot: ESP-IDF v5.2.1 2nd stage bootloader
I (26) boot: compile time Aug 13 2024 18:07:10
I (26) boot: chip revision: v0.3
I (29) boot.esp32c3: SPI Speed      : 80MHz
I (34) boot.esp32c3: SPI Mode       : DIO
I (38) boot.esp32c3: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (49) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (59) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (67) boot:  1 nvs              WiFi data        01 02 00010000 0000c000
I (74) boot:  2 nvs_keys         NVS keys         01 04 0001c000 00001000
I (82) boot:  3 otadata          OTA data         01 00 0001d000 00002000
I (89) boot:  4 phy_init         RF data          01 01 0001f000 00001000
I (97) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (104) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (112) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (119) boot: End of partition table
I (124) esp_image: segment 0: paddr=00020020 vaddr=3c110020 size=39fd8h (237528) map
I (169) esp_image: segment 1: paddr=0005a000 vaddr=3fc94400 size=03638h ( 13880) load
I (172) esp_image: segment 2: paddr=0005d640 vaddr=40380000 size=029d8h ( 10712) load
I (177) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=106328h (1073960) map
I (351) esp_image: segment 4: paddr=00166350 vaddr=403829d8 size=118ech ( 71916) load
I (372) boot: Loaded app from partition at offset 0x20000
I (372) boot: Disabling RNG early entropy source...
I (384) cpu_start: Unicore app
I (393) cpu_start: Pro cpu start user code
I (393) cpu_start: cpu freq: 160000000 Hz
I (393) cpu_start: Application information:
I (396) cpu_start: Project name:     chip-energy-management-app
I (403) cpu_start: App version:      v1.0
I (407) cpu_start: Compile time:     Aug 13 2024 18:07:02
I (414) cpu_start: ELF file SHA256:  ffa4c53ca...
I (419) cpu_start: ESP-IDF:          v5.2.1
I (424) cpu_start: Min chip rev:     v0.3
I (428) cpu_start: Max chip rev:     v1.99 
I (433) cpu_start: Chip rev:         v0.3
I (438) heap_init: Initializing. RAM available for dynamic allocation:
I (445) heap_init: At 3FCAB0D0 len 00014F30 (83 KiB): RAM
I (451) heap_init: At 3FCC0000 len 0001C710 (113 KiB): Retention RAM
I (458) heap_init: At 3FCDC710 len 00002950 (10 KiB): Retention RAM
I (465) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM
I (472) spi_flash: detected chip: generic
I (476) spi_flash: flash io: dio
I (482) sleep: Configure to isolate all GPIO pins in sleep state
I (487) sleep: Enable automatic switching of GPIO sleep configuration
I (494) coexist: coex firmware version: 77cd7f8
I (499) coexist: coexist rom version 9387209
I (505) main_task: Started on CPU0
I (505) main_task: Calling app_main()
I (515) energy-management-app: ==================================================
I (515) energy-management-app: chip-esp32-energy-management-example starting
I (525) energy-management-app: ==================================================
I (645) pp: pp rom version: 9387209
I (645) net80211: net80211 rom version: 9387209
I (655) wifi:wifi driver task: 3fcb6aa4, prio:23, stack:6656, core=0
I (655) wifi:wifi firmware version: a9f5b59
I (665) wifi:wifi certification version: v7.0
I (665) wifi:config NVS flash: enabled
I (665) wifi:config nano formating: disabled
I (675) wifi:Init data frame dynamic rx buffer num: 32
I (675) wifi:Init static rx mgmt buffer num: 5
I (685) wifi:Init management short buffer num: 32
I (685) wifi:Init dynamic tx buffer num: 32
I (685) wifi:Init static tx FG buffer num: 2
I (695) wifi:Init static rx buffer size: 1600
I (695) wifi:Init static rx buffer num: 10
I (695) wifi:Init dynamic rx buffer num: 32
                                                                                                                      I (715) wifi_init: rx ba win: 6
I (715) wifi_init: tcpip mbox: 32
I (715) wifi_init: udp mbox: 6
I (715) wifi_init: tcp mbox: 6
> I (725) wifi_init: tcp tx win: 5760
I (725) wifi_init: tcp rx win: 5760
I (725) wifi_init: tcp mss: 1440
I (725) wifi_init: WiFi IRAM OP enabled
I (735) wifi_init: WiFi RX IRAM OP enabled
I (755) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1)
I (755) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0)
I (755) chip[DL]: NVS set: chip-config/unique-id = "9BC7895C7FF06492"
I (765) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (765) BLE_INIT: BT controller compile version [30b57c4]
I (775) main_task: Returned from app_main()
I (785) BLE_INIT: Bluetooth MAC: 7c:df:a1:c2:19:fe
I (795) phy_init: phy_version 1150,7c3c08f,Jan 24 2024,17:32:21
I (895) NimBLE: GAP procedure initiated: stop advertising.

I (895) NimBLE: Failed to restore IRKs from store; status=8

I (895) CHIP[DL]: BLE host-controller synced
I (1405) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1405) NimBLE: GAP procedure initiated: advertise; 
I (1415) NimBLE: disc_mode=2
I (1415) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1425) NimBLE: 

I (1425) chip[DL]: CHIPoBLE advertising started
I (1425) chip[DL]: Starting ESP WiFi layer
I (1435) wifi:mode : sta (7c:df:a1:c2:19:fc)
I (1435) wifi:enable tsf
I (1435) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 40
W (1445) wifi:Haven't to connect to a suitable AP now!
I (1455) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 2
I (1455) chip[DL]: Done driving station state, nothing else to do...
W (1465) wifi:Haven't to connect to a suitable AP now!
I (1475) chip[DL]: Done driving station state, nothing else to do...
I (1475) chip[SVR]: SetupQRCode: [MT:Y.K9042C00KA0648G00]
I (1485) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
I (1495) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I (1505) chip[SVR]: Manual pairing code: [34970112332]
################## initParams.testEventTriggerDelegate: 0x3fc984c8 #########
I (1525) chip[SVR]: Initializing subscription resumption storage...
I (1525) chip[SVR]: Server initializing...
I (1525) chip[TS]: Last Known Good Time: [unknown]
I (1535) chip[TS]: Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48
I (1545) chip[DMG]: AccessControl: initializing
I (1555) chip[DMG]: Examples::AccessControlDelegate::Init
I (1555) chip[DMG]: AccessControl: setting
I (1565) chip[DMG]: DefaultAclStorage: initializing
I (1565) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1575) chip[ZCL]: Using ZAP configuration...
I (1585) chip[DMG]: AccessControlCluster: initializing
I (1585) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1595) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2b', EndPoint ID: '0x0', Attribute ID: '0x0'
I (1605) energy-management-app-callbacks: Current free heap: 76744

I (1615) chip[DIS]: Updating services using commissioning mode 1
I (1625) chip[DIS]: CHIP minimal mDNS started advertising.
I (1625) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 cp=0
I (1635) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 2478C6D46DEFEF77.
I (1645) chip[DIS]: mDNS service published: _matterc._udp
I (1645) chip[IN]: CASE Server enabling CASE session setups
I (1665) chip[SVR]: Joining Multicast groups
I (1665) chip[SVR]: Server Listening...
I (1665) chip[SVR]: EVSE: Initializing EvseTargetsDelegate
E (1675) chip[SVR]: EVSE: Unable to restore persisted ChargingEnabledUntil value
E (1685) chip[SVR]: EVSE: Unable to restore persisted DischargingEnabledUntil value
E (1685) chip[SVR]: EVSE: Unable to restore persisted UserMaximumChargeCurrent value
E (1695) chip[SVR]: EVSE: Unable to restore persisted RandomizationDelayWindow value
E (1715) chip[SVR]: EVSE: Unable to restore persisted ApproximateEVEfficiency value
I (1715) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2f', EndPoint ID: '0x0', Attribute ID: '0x0'
I (1725) energy-management-app-callbacks: Current free heap: 74244

I (1735) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2f', EndPoint ID: '0x0', Attribute ID: '0xfffc'
I (1745) energy-management-app-callbacks: Current free heap: 74244

I (1755) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2f', EndPoint ID: '0x0', Attribute ID: '0x7'
I (1765) energy-management-app-callbacks: Current free heap: 74244

I (1765) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2f', EndPoint ID: '0x0', Attribute ID: '0x8'
I (1795) energy-management-app-callbacks: Current free heap: 74244

I (1795) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x2f', EndPoint ID: '0x0', Attribute ID: '0x2'
I (1805) energy-management-app-callbacks: Current free heap: 74244

I (1815) chip[DL]: Initializing SNTP. Using the SNTP server: pool.ntp.org
I (1815) app-devicecallbacks: Current free heap: 74124

I (1825) app-devicecallbacks: Current free heap: 74124

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

I (1855) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1865) chip[DL]: Device already advertising, stop active advertisement and restart
I (1875) NimBLE: GAP procedure initiated: stop advertising.

I (1875) NimBLE: GAP procedure initiated: advertise; 
I (1885) NimBLE: disc_mode=2
I (1885) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1895) NimBLE: 

I (17015) chip[DL]: BLE GAP connection established (con 1)
I (17015) chip[DL]: CHIPoBLE advertising stopped
I (17015) app-devicecallbacks: Current free heap: 74124

I (18685) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (18685) chip[BLE]: local and remote recv window sizes = 5
I (18695) chip[BLE]: selected BTP version 4
I (18705) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (18785) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1
I (18785) chip[DL]: CHIPoBLE subscribe received
I (18785) NimBLE: GATT procedure initiated: indicate; 
I (18795) NimBLE: att_handle=18

I (18805) app-devicecallbacks: CHIPoBLE connection established
I (18815) app-devicecallbacks: Current free heap: 72548

I (18885) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (18885) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (18895) chip[EM]: >>> [E:29977r S:0 M:100641730] (U) Msg RX from 0:5D5942A9F6BC3993 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
I (18915) chip[EM]: <<< [E:29977r S:0 M:94140592] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:154)
I (18925) NimBLE: GATT procedure initiated: indicate; 
I (18935) NimBLE: att_handle=18

I (18935) chip[SVR]: Commissioning session establishment step started
I (19075) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (19125) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (19125) chip[EM]: >>> [E:29977r S:0 M:100641731] (U) Msg RX from 0:5D5942A9F6BC3993 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
I (19735) chip[EM]: <<< [E:29977r S:0 M:94140593] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
I (19745) NimBLE: GATT procedure initiated: indicate; 
I (19745) NimBLE: att_handle=18

I (19855) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (19905) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (19905) chip[EM]: >>> [E:29977r S:0 M:100641732] (U) Msg RX from 0:5D5942A9F6BC3993 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
I (19925) chip[EM]: <<< [E:29977r S:0 M:94140594] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
I (19935) NimBLE: GATT procedure initiated: indicate; 
I (19945) NimBLE: att_handle=18

I (19945) chip[SC]: SecureSession[0x3fc9acd8, LSID:54003]: State change 'kEstablishing' --> 'kActive'
I (19955) chip[SVR]: Commissioning completed session establishment step
I (19965) chip[DIS]: Updating services using commissioning mode 0
I (19975) chip[DIS]: CHIP minimal mDNS started advertising.
I (19975) chip[SVR]: Device completed Rendezvous process
I (19985) app-devicecallbacks: Current free heap: 73216

I (20005) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (20055) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (20055) chip[EM]: >>> [E:29978r S:54003 M:45014711] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) (B:131)
I (20075) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (20075) chip[EM]: <<< [E:29978r S:54003 M:27103622] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:232)
I (20085) NimBLE: GATT procedure initiated: indicate; 
I (20085) NimBLE: att_handle=18

I (20245) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (20345) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (20345) chip[EM]: >>> [E:29979r S:54003 M:45014712] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) (B:106)
E (20365) chip[DMG]: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = 5c3
E (20375) chip[DMG]: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = 5c3
E (20385) chip[DMG]: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = 5c3
E (20395) chip[DMG]: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 5c3
E (20415) chip[DMG]: Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 5c3
I (20425) chip[EM]: <<< [E:29979r S:54003 M:27103623] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:180)
I (20435) NimBLE: GATT procedure initiated: indicate; 
I (20435) NimBLE: att_handle=18

I (20585) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (20635) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (20645) chip[EM]: >>> [E:29980r S:54003 M:45014713] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I (20655) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s)
I (20665) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (20675) energy-management-app-callbacks: Current free heap: 73200

I (20685) chip[EM]: <<< [E:29980r S:54003 M:27103624] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (20695) NimBLE: GATT procedure initiated: indicate; 
I (20705) NimBLE: att_handle=18

I (20785) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (20835) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (20835) chip[EM]: >>> [E:29981r S:54003 M:45014714] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I (20845) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0)
I (20865) chip[DL]: NVS set: chip-config/country-code = "XX"
I (20865) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (20875) energy-management-app-callbacks: Current free heap: 73200

I (20885) chip[EM]: <<< [E:29981r S:54003 M:27103625] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (20895) NimBLE: GATT procedure initiated: indicate; 
I (20895) NimBLE: att_handle=18

I (21025) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (21025) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (21045) chip[EM]: >>> [E:29982r S:54003 M:45014715] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I (21055) chip[ZCL]: OpCreds: Certificate Chain request received for PAI
I (21065) chip[EM]: <<< [E:29982r S:54003 M:27103626] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:527)
I (21075) NimBLE: GATT procedure initiated: indicate; 
I (21085) NimBLE: att_handle=18

I (21275) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (21275) NimBLE: GATT procedure initiated: indicate; 
I (21285) NimBLE: att_handle=18

I (21465) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (21465) NimBLE: GATT procedure initiated: indicate; 
I (21475) NimBLE: att_handle=18

I (21565) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (21615) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (21615) chip[EM]: >>> [E:29983r S:54003 M:45014716] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I (21625) chip[ZCL]: OpCreds: Certificate Chain request received for DAC
I (21645) chip[EM]: <<< [E:29983r S:54003 M:27103627] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:557)
I (21655) NimBLE: GATT procedure initiated: indicate; 
I (21655) NimBLE: att_handle=18

I (21855) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (21855) NimBLE: GATT procedure initiated: indicate; 
I (21865) NimBLE: att_handle=18

I (22055) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (22055) NimBLE: GATT procedure initiated: indicate; 
I (22065) NimBLE: att_handle=18

I (22145) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (22195) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (22205) chip[EM]: >>> [E:29984r S:54003 M:45014717] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I (22215) chip[ZCL]: OpCreds: Received an AttestationRequest command
I (22285) chip[ZCL]: OpCreds: AttestationRequest successful.
I (22285) chip[EM]: <<< [E:29984r S:54003 M:27103628] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:714)
I (22305) NimBLE: GATT procedure initiated: indicate; 
I (22305) NimBLE: att_handle=18

I (22485) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (22495) NimBLE: GATT procedure initiated: indicate; 
I (22505) NimBLE: att_handle=18

I (22685) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (22685) NimBLE: GATT procedure initiated: indicate; 
I (22695) NimBLE: att_handle=18

I (22875) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (22975) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (22985) chip[EM]: >>> [E:29985r S:54003 M:45014718] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I (22995) chip[ZCL]: OpCreds: Received a CSRRequest command
I (23105) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded
I (23165) chip[ZCL]: OpCreds: CSRRequest successful.
I (23165) chip[EM]: <<< [E:29985r S:54003 M:27103629] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:373)
I (23175) NimBLE: GATT procedure initiated: indicate; 
I (23175) NimBLE: att_handle=18

I (23365) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (23365) NimBLE: GATT procedure initiated: indicate; 
I (23375) NimBLE: att_handle=18

I (23515) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (23615) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (23715) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (23715) chip[EM]: >>> [E:29986r S:54003 M:45014719] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:463)
I (23725) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command
I (23925) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful.
I (23925) chip[EM]: <<< [E:29986r S:54003 M:27103630] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
I (23935) NimBLE: GATT procedure initiated: indicate; 
I (23945) NimBLE: att_handle=18

I (24005) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (24055) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (24145) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (24295) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (24395) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (24395) NimBLE: GATT procedure initiated: indicate; 
I (24405) NimBLE: att_handle=18

I (24415) chip[EM]: >>> [E:29987r S:54003 M:45014720] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) (B:865)
I (24425) chip[ZCL]: OpCreds: Received an AddNOC command
I (24425) chip[FP]: Validating NOC chain
I (24485) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (24815) chip[FP]: NOC chain validation successful
I (24815) chip[FP]: Added new fabric at index: 0x1
I (24815) chip[FP]: Assigned compressed fabric ID: 0x5E26C669C0C1AE85, node ID: 0x0000000012344321
I (24825) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (24835) chip[TS]: New proposed Last Known Good Time: 2021-01-01T00:00:00
I (24835) chip[TS]: Retaining current Last Known Good Time
I (24855) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
I (24855) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (24875) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (24885) chip[DIS]: mDNS service published: _matter._tcp
I (24895) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC
I (24895) chip[EM]: <<< [E:29987r S:54003 M:27103631] (S) Msg TX to 1:FFFFFFFB00000000 [AE85] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (24905) NimBLE: GATT procedure initiated: indicate; 
I (24925) NimBLE: att_handle=18

I (24975) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (25025) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (25025) chip[EM]: >>> [E:29988r S:54003 M:45014721] (S) Msg RX from 1:FFFFFFFB00000000 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:85)
I (25045) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (25055) energy-management-app-callbacks: Current free heap: 68640

I (25065) chip[EM]: <<< [E:29988r S:54003 M:27103632] (S) Msg TX to 1:FFFFFFFB00000000 [AE85] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (25075) NimBLE: GATT procedure initiated: indicate; 
I (25085) NimBLE: att_handle=18

I (25175) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (25225) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (25225) chip[EM]: >>> [E:29989r S:54003 M:45014722] (S) Msg RX from 1:FFFFFFFB00000000 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I (25235) chip[FS]: GeneralCommissioning: Received ArmFailSafe (73s)
I (25245) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (25255) energy-management-app-callbacks: Current free heap: 70176

I (25265) chip[EM]: <<< [E:29989r S:54003 M:27103633] (S) Msg TX to 1:FFFFFFFB00000000 [AE85] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
I (25275) NimBLE: GATT procedure initiated: indicate; 
I (25285) NimBLE: att_handle=18

I (25365) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (25415) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (25415) chip[EM]: >>> [E:29990r S:54003 M:45014723] (S) Msg RX from 1:FFFFFFFB00000000 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I (25435) chip[NP]: ESP NetworkCommissioningDelegate: SSID: ES_Staff
W (25445) wifi:Haven't to connect to a suitable AP now!
I (25445) chip[DL]: WiFi station mode change: Enabled -> Disabled
I (25515) chip[DL]: WiFi station mode change: Disabled -> Enabled
W (25515) wifi:Haven't to connect to a suitable AP now!
I (25515) chip[DL]: Attempting to connect WiFi station interface
I (25525) chip[DL]: WiFi station state change: NotConnected -> Connecting
W (25525) wifi:Haven't to connect to a suitable AP now!
I (25545) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (25545) wifi:state: init -> auth (b0)
E (25545) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (25555) chip[DL]: Done driving station state, nothing else to do...
I (25845) chip[DL]: Attempting to connect WiFi station interface
E (25845) wifi:sta is connecting, return error
E (25845) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (25855) chip[DL]: Attempting to connect WiFi station interface
E (25855) wifi:sta is connecting, return error
E (25865) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (26255) wifi:state: auth -> assoc (0)
I (27255) wifi:state: assoc -> init (2700)
I (27255) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (27255) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 5
I (27265) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
I (27265) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (27275) wifi:Haven't to connect to a suitable AP now!
E (27285) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
W (27295) wifi:Haven't to connect to a suitable AP now!
I (27305) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected
W (27305) wifi:Haven't to connect to a suitable AP now!
E (27315) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (27325) chip[DL]: Next WiFi station reconnect in 100 ms
I (27325) chip[DL]: Done driving station state, nothing else to do...
I (27335) app-devicecallbacks: Current free heap: 71332

W (27425) wifi:Haven't to connect to a suitable AP now!
I (27425) chip[DL]: Attempting to connect WiFi station interface
I (27425) chip[DL]: WiFi station state change: NotConnected -> Connecting
W (27445) wifi:Haven't to connect to a suitable AP now!
E (27445) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (27455) chip[DL]: Done driving station state, nothing else to do...
I (27655) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (27655) wifi:state: init -> auth (b0)
I (27955) NimBLE: GATT procedure initiated: indicate; 
I (27955) NimBLE: att_handle=18

I (28375) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (28395) wifi:state: auth -> assoc (0)
I (29395) wifi:state: assoc -> init (2700)
I (29395) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (29395) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 5
I (29405) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
I (29405) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (29415) wifi:Haven't to connect to a suitable AP now!
E (29415) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
W (29435) wifi:Haven't to connect to a suitable AP now!
I (29445) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected
W (29445) wifi:Haven't to connect to a suitable AP now!
E (29455) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (29465) chip[DL]: Next WiFi station reconnect in 100 ms
I (29465) chip[DL]: Done driving station state, nothing else to do...
I (29475) app-devicecallbacks: Current free heap: 71176

W (29565) wifi:Haven't to connect to a suitable AP now!
I (29565) chip[DL]: Attempting to connect WiFi station interface
I (29565) chip[DL]: WiFi station state change: NotConnected -> Connecting
W (29585) wifi:Haven't to connect to a suitable AP now!
E (29585) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
I (29595) chip[DL]: Done driving station state, nothing else to do...
I (30585) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (30775) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
I (30785) wifi:state: init -> auth (b0)
I (30785) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 40
I (30795) app-devicecallbacks: Current free heap: 70160

I (31605) wifi:state: auth -> assoc (0)
I (31615) wifi:state: assoc -> run (10)
I (31675) wifi:connected with ES_Staff, aid = 5, channel 6, BW20, bssid = 68:d7:9a:7d:6c:24
I (31675) wifi:security: WPA3-SAE, phy: bgn, rssi: -54
I (31695) wifi:pm start, type: 1

I (31695) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (31695) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (31705) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 4
I (31715) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (31725) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (31735) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (31735) chip[DL]: WiFi station interface connected
I (31745) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (31755) energy-management-app-callbacks: Current free heap: 68856

I (31755) chip[EM]: <<< [E:29990r S:54003 M:27103634] (S) Msg TX to 1:FFFFFFFB00000000 [AE85] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
I (31775) NimBLE: GATT procedure initiated: indicate; 
I (31785) NimBLE: att_handle=18

I (31785) chip[DL]: Done driving station state, nothing else to do...
I (31795) app-devicecallbacks: Current free heap: 68644

I (31795) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (31805) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (31815) chip[DIS]: mDNS service published: _matter._tcp
I (31825) chip[SVR]: Operational advertising enabled
I (31835) app-devicecallbacks: Current free heap: 68580

I (31835) chip[DL]: Updating advertising data
I (31845) app-devicecallbacks: Current free heap: 68580

I (31765) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (31945) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14 
I (32275) wifi:<ba-add>idx:0 (ifx:0, 68:d7:9a:7d:6c:24), tid:6, ssn:2, winSize:64
I (33205) esp_netif_handlers: sta ip: 192.168.20.35, mask: 255.255.254.0, gw: 192.168.20.1
I (33205) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 0
I (33215) chip[DL]: IP_EVENT_STA_GOT_IP
I (33215) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.20.35/255.255.254.0 gateway 192.168.20.1
I (33225) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (33235) app-devicecallbacks: Current free heap: 70096

I (33235) app-devicecallbacks: IPv4 Server ready...
I (33245) chip[DIS]: Updating services using commissioning mode 0
I (33255) chip[DIS]: CHIP minimal mDNS started advertising.
I (33265) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (33265) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (33285) chip[DIS]: mDNS service published: _matter._tcp
I (33285) app-devicecallbacks: Current free heap: 68880

I (33295) chip[DIS]: Updating services using commissioning mode 0
I (33305) chip[DIS]: CHIP minimal mDNS started advertising.
I (33315) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (33315) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (33325) chip[DIS]: mDNS service published: _matter._tcp
I (33325) app-devicecallbacks: Current free heap: 68204

I (33415) wifi:<ba-add>idx:1 (ifx:0, 68:d7:9a:7d:6c:24), tid:0, ssn:0, winSize:64
I (33645) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (33645) chip[DL]: IP_EVENT_GOT_IP6
I (33645) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:7edf:a1ff:fec2:19fc
I (33655) app-devicecallbacks: Current free heap: 69572

I (33665) chip[DIS]: Updating services using commissioning mode 0
I (33665) chip[DIS]: CHIP minimal mDNS started advertising.
I (33685) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (33685) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (33705) chip[DIS]: mDNS service published: _matter._tcp
I (33705) app-devicecallbacks: Current free heap: 66816

I (33715) chip[SVR]: Server initialization complete
I (33715) chip[DIS]: Updating services using commissioning mode 0
I (33735) chip[DIS]: CHIP minimal mDNS started advertising.
I (33735) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (33745) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (33755) chip[DIS]: mDNS service published: _matter._tcp
I (33755) app-devicecallbacks: Current free heap: 68892

I (33775) chip[IM]: No subscriptions to resume
I (33775) app-devicecallbacks: Current free heap: 68892

I (34345) chip[EM]: >>> [E:29991r S:0 M:100641733] (U) Msg RX from 0:FB2C6C2655E4922B [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
I (34355) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3fc9c708
I (34365) chip[EM]: <<< [E:29991r S:0 M:94140595 (Ack:100641733)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:46902] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (34385) chip[SC]: Received Sigma1 msg
I (34385) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000012344321
I (34635) chip[EM]: <<< [E:29991r S:0 M:94140596 (Ack:100641733)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:46902] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:1050)
I (34655) chip[SC]: Sent Sigma2 msg
I (34645) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (34845) chip[EM]: >>> [E:29991r S:0 M:100641734 (Ack:94140596)] (U) Msg RX from 0:FB2C6C2655E4922B [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:874)
I (34865) chip[EM]: <<< [E:29991r S:0 M:94140597 (Ack:100641734)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:46902] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (34875) chip[SC]: Received Sigma3 msg
I (35465) chip[EM]: <<< [E:29991r S:0 M:94140598 (Ack:100641734)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:46902] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I (35485) chip[SC]: SecureSession[0x3fc9adb0, LSID:54004]: State change 'kEstablishing' --> 'kActive'
I (35495) chip[IN]: CASE Session established to peer: <000000000001B669, 1>
I (35495) app-devicecallbacks: Current free heap: 68060

I (35565) chip[EM]: >>> [E:29992r S:54004 M:169563405] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I (35575) chip[FS]: GeneralCommissioning: Received CommissioningComplete
I (35585) chip[FP]: Metadata for Fabric 0x1 persisted to storage.
I (35595) chip[TS]: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
I (35595) chip[ZCL]: OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x5E26C669C0C1AE85, FabricId 0000000000000001, NodeId 0000000012344321, VendorId 0xFFF1
I (35615) chip[FS]: GeneralCommissioning: Successfully commited pending fabric data
I (35625) chip[FS]: Fail-safe cleanly disarmed
I (35625) energy-management-app-callbacks: PostAttributeChangeCallback - Cluster ID: '0x30', EndPoint ID: '0x0', Attribute ID: '0x0'
I (35635) energy-management-app-callbacks: Current free heap: 66736

I (35645) chip[EM]: <<< [E:29992r S:54004 M:266741568 (Ack:169563405)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:46902] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I (35665) chip[EM]: >>> [E:29991r S:0 M:100641735 (Ack:94140598)] (U) Msg RX from 0:FB2C6C2655E4922B [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (35675) chip[SVR]: Commissioning completed successfully
I (35685) chip[DIS]: Updating services using commissioning mode 0
I (35685) chip[DIS]: CHIP minimal mDNS started advertising.
I (35705) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (35705) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (35725) chip[DIS]: mDNS service published: _matter._tcp
I (35725) chip[SC]: SecureSession[0x3fc9acd8, LSID:54003]: State change 'kActive' --> 'kPendingEviction'
I (35735) chip[BLE]: Releasing end point's BLE connection back to application.
I (35745) chip[DL]: Closing BLE GATT connection (con 1)
I (35745) NimBLE: GAP procedure initiated: terminate connection; conn_handle=1 hci_reason=19

I (35765) app-devicecallbacks: Commissioning complete
I (35765) app-devicecallbacks: Current free heap: 63752

I (35775) NimBLE: GAP procedure initiated: stop advertising.

E (35775) NimBLE: ble_hs_stop: failed to terminate connection; rc=2

I (36055) chip[EM]: Retransmitting MessageCounter:266741568 on exchange 29992r Send Cnt 1
I (36235) chip[EM]: >>> [E:29992r S:54004 M:169563406 (Ack:266741568)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (36255) chip[EM]: >>> [E:29992r S:54004 M:169563407 (Ack:266741568)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (37785) chip[DL]: BLE deinit successful and memory reclaimed
I (37795) app-devicecallbacks: BLE is deinitialized
I (37795) app-devicecallbacks: Current free heap: 137440

I (47635) ROUTE_HOOK: Ignore invalid ICMP packet
I (47945) ROUTE_HOOK: Received RIO
I (47945) ROUTE_HOOK: prefix FD77:D8D2:6A41:1:: lifetime 1800
I (53455) ROUTE_HOOK: Received RIO
I (53455) ROUTE_HOOK: prefix FD77:D8D2:6A41:1:: lifetime 1800
I (54645) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (54645) chip[DL]: IP_EVENT_GOT_IP6
I (54645) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fd3b:07a7:57d2:fdb7:7edf:a1ff:fec2:19fc
I (54655) ROUTE_HOOK: Hook already installed on netif, skip...
I (54665) app-devicecallbacks: Current free heap: 137228

I (54665) chip[DIS]: Updating services using commissioning mode 0
I (54675) chip[DIS]: CHIP minimal mDNS started advertising.
I (54685) chip[DIS]: Advertise operational node 5E26C669C0C1AE85-0000000012344321
I (54685) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5E26C669C0C1AE85-0000000012344321.
I (54705) chip[DIS]: mDNS service published: _matter._tcp
I (54705) app-devicecallbacks: Current free heap: 135032

I (56725) ROUTE_HOOK: Received RIO
I (56725) ROUTE_HOOK: prefix FD09:B09C:A6A6:1:: lifetime 1800
I (91835) ROUTE_HOOK: Ignore invalid ICMP packet
I (91935) ROUTE_HOOK: Received RIO
I (91935) ROUTE_HOOK: prefix FD09:B09C:A6A6:1:: lifetime 1800
I (91945) ROUTE_HOOK: Received RIO
I (91945) ROUTE_HOOK: prefix FD77:D8D2:6A41:1:: lifetime 1800
I (92055) chip[EM]: >>> [E:35948r S:0 M:170853233] (U) Msg RX from 0:8358254820B90B92 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
I (92075) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3fc9c708
I (92075) chip[EM]: <<< [E:35948r S:0 M:94140599 (Ack:170853233)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:53017] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (92095) chip[SC]: Received Sigma1 msg
I (92095) chip[SC]: CASE matched destination ID: fabricIndex 1, NodeID 0x0000000012344321
I (92345) chip[EM]: <<< [E:35948r S:0 M:94140600 (Ack:170853233)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:53017] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:1050)
I (92365) chip[SC]: Sent Sigma2 msg
I (92485) chip[EM]: >>> [E:35948r S:0 M:170853234 (Ack:94140600)] (U) Msg RX from 0:8358254820B90B92 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:774)
I (92495) chip[EM]: <<< [E:35948r S:0 M:94140601 (Ack:170853234)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:53017] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (92505) chip[SC]: Received Sigma3 msg
I (93145) chip[EM]: <<< [E:35948r S:0 M:94140602 (Ack:170853234)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:192.168.21.23:53017] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I (93155) chip[SC]: SecureSession[0x3fc9ae88, LSID:54005]: State change 'kEstablishing' --> 'kActive'
I (93175) chip[IN]: CASE Session established to peer: <000000000001B669, 1>
I (93175) app-devicecallbacks: Current free heap: 135240

I (93225) chip[EM]: >>> [E:35948r S:0 M:170853235 (Ack:94140602)] (U) Msg RX from 0:8358254820B90B92 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I (93245) chip[EM]: >>> [E:35949r S:54005 M:265728818] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:03 (IM:SubscribeRequest) (B:58)
I (93255) chip[DMG]: Final negotiated min/max parameters: Min = 0s, Max = 30s
I (93275) chip[EM]: <<< [E:35949r S:54005 M:75326082 (Ack:265728818)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:05 (IM:ReportData) (B:45)
I (93485) chip[EM]: >>> [E:35949r S:54005 M:265728819 (Ack:75326082)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:01 (IM:StatusResponse) (B:42)
I (93495) chip[IM]: Received status response, status is 0x00
I (93505) chip[EM]: <<< [E:35949r S:54005 M:75326083 (Ack:265728819)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:04 (IM:SubscribeResponse) (B:48)
I (93515) chip[DMG]: Registered a ReadHandler that will schedule a report between system Timestamp: 0x0000000000016D50 and system Timestamp 0x000000000001E280.
I (93605) chip[EM]: >>> [E:35949r S:54005 M:265728820 (Ack:75326083)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (93625) chip[EM]: >>> [E:35950r S:54005 M:265728821] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:02 (IM:ReadRequest) (B:51)
############### enableKey:00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ###############
############### mEnableKey:00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f ###############
I (93655) chip[EM]: <<< [E:35950r S:54005 M:75326084 (Ack:265728821)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:05 (IM:ReportData) (B:69)
I (93815) chip[EM]: >>> [E:35950r S:54005 M:265728822 (Ack:75326084)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (93825) chip[EM]: >>> [E:35951r S:54005 M:265728823] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:88)
############### enableKey:00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f ###############
############### mEnableKey:00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f ###############
I (93855) chip[SPT]: [ForecastAdjustment-Test-Event] => Simulate a forecast power usage with at least 2 and at most 4 slots
I (93865) chip[EM]: <<< [E:35951r S:54005 M:75326085 (Ack:265728823)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I (94015) chip[EM]: >>> [E:35951r S:54005 M:265728824 (Ack:75326085)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (94025) chip[EM]: >>> [E:35952r S:54005 M:265728825] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:02 (IM:ReadRequest) (B:51)
I (94045) chip[EM]: <<< [E:35952r S:54005 M:75326086 (Ack:265728825)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:05 (IM:ReportData) (B:70)
I (94425) chip[EM]: Retransmitting MessageCounter:75326086 on exchange 35952r Send Cnt 1
I (94825) chip[EM]: Retransmitting MessageCounter:75326086 on exchange 35952r Send Cnt 2
I (95195) chip[EM]: >>> [E:35952r S:54005 M:265728828 (Ack:75326086)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (95205) chip[EM]: >>> [E:35953r S:54005 M:265728827] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:02 (IM:ReadRequest) (B:51)
I (95225) chip[EM]: <<< [E:35953r S:54005 M:75326087 (Ack:265728827)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:05 (IM:ReportData) (B:199)
I (95525) chip[EM]: >>> [E:35953r S:54005 M:265728829 (Ack:75326087)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (95545) chip[EM]: >>> [E:35954r S:54005 M:265728830] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:02 (IM:ReadRequest) (B:51)
I (95555) chip[EM]: <<< [E:35954r S:54005 M:75326088 (Ack:265728830)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:05 (IM:ReportData) (B:70)
I (95665) chip[EM]: >>> [E:35954r S:54005 M:265728831 (Ack:75326088)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I (95685) chip[EM]: >>> [E:35955r S:54005 M:265728832] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:0A (IM:TimedRequest) (B:39)
I (95695) chip[EM]: <<< [E:35955r S:54005 M:75326089 (Ack:265728832)] (S) Msg TX to 1:000000000001B669 [AE85] [UDP:192.168.21.23:53017] --- Type 0001:01 (IM:StatusResponse) (B:42)
I (95775) chip[EM]: >>> [E:35955r S:54005 M:265728833 (Ack:75326089)] (S) Msg RX from 1:000000000001B669 [AE85] --- Type 0001:08 (IM:InvokeCommandRequest) (B:80)
I (95795) chip[ZCL]: DEM: OptOutState = kNoOptOut

abort() was called at PC 0x42015c89 on core 0
0x42015c89: chip::Span<chip::app::Clusters::DeviceEnergyManagement::Structs::SlotStruct::Type const>::operator[](unsigned int) const at /Users/rohitjadhav/esp/connectedhomeip/src/lib/support/Span.h:127 (discriminator 2)
 (inlined by) chip::app::Clusters::DeviceEnergyManagement::Instance::HandleModifyForecastRequest(chip::app::CommandHandlerInterface::HandlerContext&, chip::app::Clusters::DeviceEnergyManagement::Commands::ModifyForecastRequest::DecodableType const&) at /Users/rohitjadhav/esp/connectedhomeip/examples/energy-management-app/esp32/third_party/connectedhomeip/src/app/clusters/device-energy-management-server/device-energy-management-server.cpp:694 (discriminator 2)

Stack dump detected
Core  0 register dump:
MEPC    : 0x40380698  RA      : 0x40389bc2  SP      : 0x3fcbf520  GP      : 0x3fc94c00  
0x40380698: panic_abort at /Users/rohitjadhav/esp/esp-idf/components/esp_system/panic.c:472

0x40389bc2: __ubsan_include at /Users/rohitjadhav/esp/esp-idf/components/esp_system/ubsan.c:313

TP      : 0x3fc86af8  T0      : 0x37363534  T1      : 0x7271706f  T2      : 0x33323130  
S0/FP   : 0x3fcbf55c  S1      : 0x3fcbf55c  A0      : 0x3fcbf55c  A1      : 0x3fcbf53e  
A2      : 0x00000000  A3      : 0x3fcbf589  A4      : 0x00000001  A5      : 0x3fca9000  
A6      : 0x7a797877  A7      : 0x76757473  S2      : 0x3fcbf540  S3      : 0x00000001  
S4      : 0xffffffff  S5      : 0x000000b0  S6      : 0x3fcbfd7c  S7      : 0x00000000  
S8      : 0x3fc9c738  S9      : 0x00000000  S10     : 0x00000000  S11     : 0x0001b669  
T3      : 0x6e6d6c6b  T4      : 0x6a696867  T5      : 0x66656463  T6      : 0x62613938  
MSTATUS : 0x00001801  MTVEC   : 0x40380001  MCAUSE  : 0x00000007  MTVAL   : 0x00000000  
0x40380001: _vector_table at ??:?

MHARTID : 0x00000000  


Backtrace:


panic_abort (details=details@entry=0x3fcbf55c "abor") at /Users/rohitjadhav/esp/esp-idf/components/esp_system/panic.c:472
472	    *((volatile int *) 0) = 0; // NOLINT(clang-analyzer-core.NullDereference) should be an invalid operation on targets
#0  panic_abort (details=details@entry=0x3fcbf55c "abor") at /Users/rohitjadhav/esp/esp-idf/components/esp_system/panic.c:472
#1  0x40389bc2 in esp_system_abort (details=details@entry=0x3fcbf55c "abor") at /Users/rohitjadhav/esp/esp-idf/components/esp_system/port/esp_system_chip.c:93
#2  0x40390580 in abort () at /Users/rohitjadhav/esp/esp-idf/components/newlib/abort.c:38
#3  0x00000000 in ?? ()
Backtrace stopped: frame did not save the PC
ELF file SHA256: ffa4c53ca

Rebooting...