I (2263) chip[DL]: CHIPoBLE advertising started
E (2263) chip[DL]: Long dispatch time: 1050 ms, for event type 2
I (2263) chip[DL]: Starting ESP WiFi layer
I (2283) wifi:mode : sta (b8:f0:09:c4:82:74)
I (2283) wifi:enable tsf
W (2283) wifi:Haven't to connect to a suitable AP now!
I (2283) chip[DL]: Attempting to connect WiFi station interface
I (2303) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (2303) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (2313) wifi:state: init -> auth (b0)
I (2313) chip[DL]: Done driving station state, nothing else to do...
I (2323) chip[ZCL]: Using ZAP configuration...
I (2333) chip[SVR]: Retrieved from server storage: a/1/8/0
I (2343) wifi:state: auth -> assoc (0)
I (2353) chip[ZCL]: Initiating Admin Commissioning cluster.
I (2353) chip[ZCL]: Door Lock server initialized
I (2353) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (2373) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2383) app-devicecallbacks: Current free heap: 71072

I (2383) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (2393) app-devicecallbacks: Unhandled cluster ID: 4
I (2403) app-devicecallbacks: Current free heap: 71072

E (2413) chip[ZCL]: Trying to write invalid Calendar Type
E (2423) chip[ZCL]: Failed to write calendar type with error: 0x87
I (2423) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2433) app-devicecallbacks: Current free heap: 71072

I (2433) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2453) app-devicecallbacks: Unhandled cluster ID: 4
I (2463) app-devicecallbacks: Current free heap: 71060

I (2463) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2473) app-devicecallbacks: Unhandled cluster ID: 5
I (2483) app-devicecallbacks: Current free heap: 71060

I (2363) wifi:state: assoc -> run (10)
I (2503) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2503) app-devicecallbacks: Current free heap: 72204

I (2513) chip[ZCL]: Window Covering Cluster init
I (2513) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (2533) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (2543) app-devicecallbacks: Unhandled cluster ID: 768
I (2543) app-devicecallbacks: Current free heap: 71888

I (2543) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2563) app-devicecallbacks: Unhandled cluster ID: 768
I (2573) app-devicecallbacks: Current free heap: 71888

I (2573) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2583) app-devicecallbacks: Unhandled cluster ID: 768
I (2593) app-devicecallbacks: Current free heap: 71876

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

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

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

I (2503) wifi:connected with Desk1, aid = 1, channel 1, BW20, bssid = 18:90:88:4b:6f:66
I (2693) wifi:security: WPA2-PSK, phy: bgn, rssi: -36
I (2693) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2703) app-devicecallbacks: Unhandled cluster ID: 1280
I (2713) app-devicecallbacks: Current free heap: 71928

I (2713) chip[ZCL]: Failed to send IAS Zone update. Err 0x70
I (2703) wifi:pm start, type: 1

I (2733) wifi:AP's beacon interval = 102400 us, DTIM period = 2
I (2733) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (2743) app-devicecallbacks: Unhandled cluster ID: 4
I (2763) app-devicecallbacks: Current free heap: 72140

I (2763) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2773) app-devicecallbacks: Unhandled cluster ID: 1030
I (2773) app-devicecallbacks: Current free heap: 72140

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

I (2823) chip[SVR]: Retrieved from server storage: Fabric1
I (2823) chip[IN]: Loading certs from storage
I (2823) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (2843) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000004, VendorId 0x0000
I (2853) chip[ZCL]: OpCreds: Call to fabricListChanged
I (2853) chip[DMG]: AccessControl: initializing
I (2853) chip[DMG]: Examples::AccessControlDelegate::Init
I (2873) chip[SVR]: Retrieved from server storage: acl
I (2873) chip[SVR]: Retrieved from server storage: acl/0
I (2873) chip[SVR]: Retrieved from server storage: acl/1
I (2883) chip[SVR]: Retrieved from server storage: acl/2
I (2893) chip[SVR]: Retrieved from server storage: acl/3
I (2893) chip[SVR]: Retrieved from server storage: acl/4
I (2903) chip[SVR]: Retrieved from server storage: acl/5
I (2913) chip[SVR]: Retrieved from server storage: acl/6
I (2913) chip[SVR]: Retrieved from server storage: acl/7
I (2923) chip[SVR]: Retrieved from server storage: acl/8
I (2933) chip[SVR]: Retrieved from server storage: acl/9
I (2933) chip[SVR]: Retrieved from server storage: acl/a
I (2933) chip[SVR]: Retrieved from server storage: acl/b
I (2953) chip[SVR]: Retrieved from server storage: acl/c
I (2953) chip[SVR]: Retrieved from server storage: acl/d
I (2953) chip[SVR]: Retrieved from server storage: acl/e
I (2963) chip[DMG]: AccessControl: setting
I (2373) all-clusters-app: Display initialized (height 240, width 320)
I (2973) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (2983) chip[DL]: NVS set: chip-counters/GlobalMCTR = 150000 (0x249F0)
I (2993) chip[DL]: NVS set: chip-counters/global-eidc = 3735552 (0x390000)
I (2993) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (3003) chip[IN]: CASE Server enabling CASE session setups
I (3013) chip[SVR]: Adding Multicast groups
I (3013) chip[SVR]: Server Listening...
I (3033) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3033) app-devicecallbacks: Unhandled cluster ID: 1026
I (3043) app-devicecallbacks: Current free heap: 66044

I (3043) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3063) app-devicecallbacks: Unhandled cluster ID: 257
I (3073) app-devicecallbacks: Current free heap: 66324

I (3073) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3083) app-devicecallbacks: Unhandled cluster ID: 1030
I (3093) app-devicecallbacks: Current free heap: 65384

I (3103) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3113) app-devicecallbacks: Unhandled cluster ID: 69
I (3113) app-devicecallbacks: Current free heap: 65264

I (3123) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3133) app-devicecallbacks: Unhandled cluster ID: 1026
I (3143) app-devicecallbacks: Current free heap: 65772

I (3143) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3153) app-devicecallbacks: Unhandled cluster ID: 513
I (3163) app-devicecallbacks: Current free heap: 66768

I (3173) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x001c'
I (3183) app-devicecallbacks: Unhandled cluster ID: 513
I (3183) app-devicecallbacks: Current free heap: 66720

I (3193) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0011'
I (3213) app-devicecallbacks: Unhandled cluster ID: 513
I (3213) app-devicecallbacks: Current free heap: 66524

I (3223) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0201', EndPoint ID: '0x01', Attribute ID: '0x0012'
I (3223) app-devicecallbacks: Unhandled cluster ID: 513
I (3233) app-devicecallbacks: Current free heap: 66516

I (3243) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0405', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3253) app-devicecallbacks: Unhandled cluster ID: 1029
I (3263) app-devicecallbacks: Current free heap: 66396

I (3263) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0400', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (3283) app-devicecallbacks: Unhandled cluster ID: 1024
I (3283) app-devicecallbacks: Current free heap: 66252

E (3293) chip[DL]: Long dispatch time: 969 ms, for event type 2
I (3293) app-devicecallbacks: Current free heap: 66252

I (3303) chip[DL]: WIFI_EVENT_STA_START
I (3303) chip[DL]: Done driving station state, nothing else to do...
I (3323) app-devicecallbacks: Current free heap: 66092

I (3323) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (3323) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (3333) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (3333) chip[DL]: WiFi station interface connected
I (3343) chip[DL]: Done driving station state, nothing else to do...
I (3353) app-devicecallbacks: Current free heap: 66092

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

I (3363) chip[DL]: CHIPoBLE advertising stopped
I (3373) chip[DL]: Updating advertising data
I (3373) app-devicecallbacks: Current free heap: 66272

I (3383) app-devicecallbacks: Current free heap: 66272

W (3793) wifi:<ba-add>idx:0 (ifx:0, 18:90:88:4b:6f:66), tid:0, ssn:2, winSize:64
I (4573) esp_netif_handlers: sta ip: 192.168.7.152, mask: 255.255.252.0, gw: 192.168.4.1
I (4573) chip[DL]: IP_EVENT_STA_GOT_IP
I (4573) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.7.152/255.255.252.0 gateway 192.168.4.1
I (4583) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (4593) app-devicecallbacks: Current free heap: 66180

I (4603) app-devicecallbacks: Server ready at: 192.168.7.152:5540
I (4613) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (4613) chip[DIS]: CHIP minimal mDNS started advertising.
I (4623) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (4633) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (4643) chip[DIS]: mDNS service published: _matter._tcp
I (4643) chip[DIS]: Have operational credentials
I (4643) app-devicecallbacks: Current free heap: 65320

I (4663) chip[DIS]: CHIP minimal mDNS started advertising.
I (4663) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (4673) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (4683) chip[DIS]: mDNS service published: _matter._tcp
I (4683) chip[DIS]: Have operational credentials
I (4683) app-devicecallbacks: Current free heap: 65320

I (5073) chip[DL]: IP_EVENT_GOT_IP6
I (5073) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:baf0:09ff:fec4:8274
I (5083) app-devicecallbacks: Current free heap: 65744

I (5083) chip[DIS]: CHIP minimal mDNS started advertising.
I (5093) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (5093) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (5113) chip[DIS]: mDNS service published: _matter._tcp
I (5113) chip[DIS]: Have operational credentials
I (5123) app-devicecallbacks: Current free heap: 64496

I (6243) ROUTE_HOOK: Received RIO
I (6243) ROUTE_HOOK: prefix FD3D:F5B:D0DB:: lifetime 1800

I (8073) chip[DL]: IP_EVENT_GOT_IP6
I (8073) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fdcd:8e50:7bf1:48a2:baf0:09ff:fec4:8274
I (8083) app-devicecallbacks: Current free heap: 65624

I (8083) chip[DIS]: CHIP minimal mDNS started advertising.
I (8093) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (8103) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (8113) chip[DIS]: mDNS service published: _matter._tcp
I (8113) chip[DIS]: Have operational credentials
I (8113) ROUTE_HOOK: Hook already installed on netif, skip...
I (8123) app-devicecallbacks: Current free heap: 65616

I (11153) ROUTE_HOOK: Received RIO
I (11163) ROUTE_HOOK: prefix FD3D:F5B:D0DB:: lifetime 1800

I (15353) ROUTE_HOOK: Received RIO
I (15353) ROUTE_HOOK: prefix FD3D:F5B:D0DB:: lifetime 1800

I (15973) chip[EM]: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:2794959428 on exchange 27875r
I (15973) chip[IN]: CASE Server received Sigma1 message. Starting handshake. EC 0x3ffca1c8
I (15983) chip[DIS]: CASE handshake initiated, closing all BLE Connections
I (15993) chip[IN]: CASE Server disabling CASE session setups
I (16003) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (16013) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (16013) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000004, VendorId 0x0000
I (16023) chip[ZCL]: OpCreds: Call to fabricListChanged
I (16043) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (16043) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (16053) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000004, VendorId 0x0000
I (16063) chip[ZCL]: OpCreds: Call to fabricListChanged
I (17493) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 27875r with MessageCounter:389034824.
I (17513) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:389034824 to 0x0000000000000000 at monotonic time: 16730 msec
E (17523) chip[DL]: Long dispatch time: 1559 ms, for event type 3
I (17883) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:2794959429 on exchange 27875r
I (19363) ROUTE_HOOK: Received RIO
I (19363) ROUTE_HOOK: prefix FD3D:F5B:D0DB:: lifetime 1800

I (19843) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 27875r with MessageCounter:389034825.
I (19863) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:389034825 to 0x0000000000000000 at monotonic time: 19080 msec
I (19873) chip[IN]: CASE Session established. Setting up the secure channel.
I (19883) chip[IN]: CASE secure channel is available now.
I (19883) chip[IN]: CASE Server enabling CASE session setups
E (19893) chip[DL]: Long dispatch time: 2009 ms, for event type 3
I (19933) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2794959430 on exchange 27875r
I (19933) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809621 on exchange 27876r
I (19953) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=1 p=o
I (19963) chip[ZCL]: On/Off set value: 1 2
I (19963) chip[ZCL]: Toggle on/off from 0 to 1
I (19963) chip[ZCL]: On Command - OffWaitTime :  0
I (19983) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002'
I (19983) app-devicecallbacks: Unhandled Attribute ID: '0x4002
I (19993) app-devicecallbacks: Current free heap: 62068

I (19993) chip[ZCL]: On/Toggle Command - Stop Timer
I (20003) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000'
I (20023) app-devicecallbacks: Unhandled Attribute ID: '0x4000
I (20023) app-devicecallbacks: Current free heap: 62068

I (20033) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (20043) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (20043) app-devicecallbacks: Current free heap: 62068

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

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

I (20113) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27876r with MessageCounter:14779869.
I (20133) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779869 to 0x5718CCD8A24DCA05 (1) at monotonic time: 19347 msec
E (20143) chip[DL]: Long dispatch time: 207 ms, for event type 3
I (20143) chip[ZCL]: Event: move from 1
I (20143) chip[ZCL]:  to 254 
I (20153) chip[ZCL]: (diff +1)
I (20173) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (20173) app-devicecallbacks: Current free heap: 62068

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

I (20213) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (20223) app-devicecallbacks: Unhandled Attribute ID: '0x0001
I (20223) app-devicecallbacks: Current free heap: 62068

I (20243) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809622 on exchange 27876r
I (21293) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809623 on exchange 27877r
I (21303) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=1 p=o
I (21313) chip[ZCL]: On/Off set value: 1 2
I (21313) chip[ZCL]: Toggle on/off from 1 to 0
I (21323) chip[ZCL]: Off Command - OnTime :  0
I (21323) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (21343) app-devicecallbacks: Unhandled Attribute ID: '0x4001
I (21343) app-devicecallbacks: Current free heap: 62068

I (21353) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (21363) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (21363) app-devicecallbacks: Current free heap: 62068

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

I (21403) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27877r with MessageCounter:14779870.
I (21423) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779870 to 0x5718CCD8A24DCA05 (1) at monotonic time: 20640 msec
E (21433) chip[DL]: Long dispatch time: 142 ms, for event type 3
I (21433) chip[ZCL]: Event: move from 254
I (21443) chip[ZCL]:  to 1 
I (21443) chip[ZCL]: (diff -1)
I (21463) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (21463) app-devicecallbacks: Current free heap: 62068

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

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

I (21633) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (21653) app-devicecallbacks: Unhandled Attribute ID: '0x0001
I (21653) app-devicecallbacks: Current free heap: 61784

I (21663) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809624 on exchange 27877r
I (22113) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809625 on exchange 27878r
I (22123) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=2 p=o
I (22133) chip[ZCL]: On/Off set value: 2 2
I (22133) chip[ZCL]: Toggle on/off from 0 to 1
I (22143) chip[ZCL]: On Command - OffWaitTime :  0
I (22153) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4002'
I (22163) app-devicecallbacks: Unhandled Attribute ID: '0x4002
I (22163) app-devicecallbacks: Current free heap: 62068

I (22173) chip[ZCL]: On/Toggle Command - Stop Timer
I (22173) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4000'
I (22183) app-devicecallbacks: Unhandled Attribute ID: '0x4000
I (22203) app-devicecallbacks: Current free heap: 62068

I (22203) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (22213) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (22223) app-devicecallbacks: Current free heap: 62068

I (22233) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27878r with MessageCounter:14779871.
I (22243) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779871 to 0x5718CCD8A24DCA05 (1) at monotonic time: 21462 msec
E (22253) chip[DL]: Long dispatch time: 143 ms, for event type 3
I (22293) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809626 on exchange 27878r
I (22933) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809627 on exchange 27879r
I (22943) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=2 p=o
I (22953) chip[ZCL]: On/Off set value: 2 2
I (22953) chip[ZCL]: Toggle on/off from 1 to 0
I (22963) chip[ZCL]: Off Command - OnTime :  0
I (22963) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4001'
I (22983) app-devicecallbacks: Unhandled Attribute ID: '0x4001
I (22983) app-devicecallbacks: Current free heap: 62068

I (22993) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (23003) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (23003) app-devicecallbacks: Current free heap: 62068

I (23023) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27879r with MessageCounter:14779872.
I (23033) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779872 to 0x5718CCD8A24DCA05 (1) at monotonic time: 22254 msec
E (23053) chip[DL]: Long dispatch time: 116 ms, for event type 3
I (23103) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809628 on exchange 27879r
I (24163) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809629 on exchange 27880r
I (24163) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=1 p=o
I (24183) chip[ZCL]: On/Off set value: 1 2
I (24183) chip[ZCL]: Toggle on/off from 0 to 1
I (24193) chip[ZCL]: On Command - OffWaitTime :  0
I (24193) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4002'
I (24203) app-devicecallbacks: Unhandled Attribute ID: '0x4002
I (24213) app-devicecallbacks: Current free heap: 62068

I (24223) chip[ZCL]: On/Toggle Command - Stop Timer
I (24223) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4000'
I (24233) app-devicecallbacks: Unhandled Attribute ID: '0x4000
I (24243) app-devicecallbacks: Current free heap: 62068

I (24243) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (24263) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (24273) app-devicecallbacks: Current free heap: 62068

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

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

I (24323) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27880r with MessageCounter:14779873.
I (24343) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779873 to 0x5718CCD8A24DCA05 (1) at monotonic time: 23557 msec
E (24353) chip[DL]: Long dispatch time: 191 ms, for event type 3
I (24353) chip[ZCL]: Event: move from 1
I (24353) chip[ZCL]:  to 254 
I (24363) chip[ZCL]: (diff +1)
I (24383) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (24383) app-devicecallbacks: Current free heap: 62068

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

I (24423) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (24433) app-devicecallbacks: Unhandled Attribute ID: '0x0001
I (24433) app-devicecallbacks: Current free heap: 62068

I (24453) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809630 on exchange 27880r
I (24883) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809631 on exchange 27881r
I (24883) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=1 p=o
I (24903) chip[ZCL]: On/Off set value: 1 2
I (24903) chip[ZCL]: Toggle on/off from 1 to 0
I (24913) chip[ZCL]: Off Command - OnTime :  0
I (24913) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (24923) app-devicecallbacks: Unhandled Attribute ID: '0x4001
I (24923) app-devicecallbacks: Current free heap: 62068

I (24943) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (24953) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (24953) app-devicecallbacks: Current free heap: 62068

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

I (24993) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27881r with MessageCounter:14779874.
I (25013) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779874 to 0x5718CCD8A24DCA05 (1) at monotonic time: 24227 msec
E (25023) chip[DL]: Long dispatch time: 143 ms, for event type 3
I (25023) chip[ZCL]: Event: move from 254
I (25023) chip[ZCL]:  to 1 
I (25033) chip[ZCL]: (diff -1)
I (25053) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (25053) app-devicecallbacks: Current free heap: 62068

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

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

I (25113) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (25133) app-devicecallbacks: Unhandled Attribute ID: '0x0001
I (25133) app-devicecallbacks: Current free heap: 61940

I (25183) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809632 on exchange 27881r
I (27443) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809633 on exchange 27882r
I (27443) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=2 p=o
I (27463) chip[ZCL]: On/Off set value: 2 2
I (27463) chip[ZCL]: Toggle on/off from 0 to 1
I (27473) chip[ZCL]: On Command - OffWaitTime :  0
I (27473) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4002'
I (27483) app-devicecallbacks: Unhandled Attribute ID: '0x4002
I (27483) app-devicecallbacks: Current free heap: 61940

I (27493) chip[ZCL]: On/Toggle Command - Stop Timer
I (27503) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4000'
I (27513) app-devicecallbacks: Unhandled Attribute ID: '0x4000
I (27523) app-devicecallbacks: Current free heap: 61940

I (27523) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (27533) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (27553) app-devicecallbacks: Current free heap: 61940

I (27553) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27882r with MessageCounter:14779875.
I (27573) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779875 to 0x5718CCD8A24DCA05 (1) at monotonic time: 26788 msec
E (27583) chip[DL]: Long dispatch time: 145 ms, for event type 3
I (27613) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809634 on exchange 27882r
I (28153) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809635 on exchange 27883r
I (28163) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_0006 e=2 p=o
I (28173) chip[ZCL]: On/Off set value: 2 2
I (28173) chip[ZCL]: Toggle on/off from 1 to 0
I (28183) chip[ZCL]: Off Command - OnTime :  0
I (28193) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x4001'
I (28203) app-devicecallbacks: Unhandled Attribute ID: '0x4001
I (28203) app-devicecallbacks: Current free heap: 61940

I (28213) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0006', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (28223) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (28233) app-devicecallbacks: Current free heap: 61940

I (28243) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27883r with MessageCounter:14779876.
I (28253) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779876 to 0x5718CCD8A24DCA05 (1) at monotonic time: 27476 msec
E (28273) chip[DL]: Long dispatch time: 116 ms, for event type 3
I (28333) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809636 on exchange 27883r
I (34303) chip[EM]: Received message of type 0xa with protocolId (0, 1) and MessageCounter:7809637 on exchange 27884r
I (34313) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x1 and protocolId (0, 1) on exchange 27884r with MessageCounter:14779877.
I (34323) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779877 to 0x5718CCD8A24DCA05 (1) at monotonic time: 33540 msec
I (34503) chip[EM]: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:7809638 on exchange 27884r
I (34513) chip[DMG]: AccessControl: checking f=1 a=c s=0x5718CCD8A24DCA05 t= c=0x0000_003C e=0 p=o
I (34523) chip[ZCL]: Received command to open commissioning window
I (34523) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (34533) chip[DIS]: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I (34543) chip[ZCL]: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000004, VendorId 0x0000
I (34563) chip[ZCL]: OpCreds: Call to fabricListChanged
I (34563) chip[DL]: NVS set: chip-factory/discriminator = 3840 (0xF00)
I (34573) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (34583) chip[DIS]: CHIP minimal mDNS started advertising.
I (34593) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (34593) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (34613) chip[DIS]: mDNS service published: _matter._tcp
I (34613) chip[DIS]: Have operational credentials
I (34623) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
I (34633) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (34653) chip[DIS]: mDNS service published: _matterc._udp
I (34663) chip[ZCL]: Commissioning window is now open
I (34663) chip[IN]: Prepared secure message 0x3ffca0e4 to 0x5718CCD8A24DCA05 (1)  of type 0x9 and protocolId (0, 1) on exchange 27884r with MessageCounter:14779878.
I (34673) chip[IN]: Sending encrypted msg 0x3ffca0e4 with MessageCounter:14779878 to 0x5718CCD8A24DCA05 (1) at monotonic time: 33896 msec
E (34693) chip[DL]: Long dispatch time: 189 ms, for event type 3
I (34783) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:7809639 on exchange 27884r
I (57443) ROUTE_HOOK: Received RIO
I (57443) ROUTE_HOOK: prefix FD3D:F5B:D0DB:: lifetime 1800

I (57643) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:3262651592 on exchange 17263r
I (57653) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 17263r with MessageCounter:389034826.
I (57663) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:389034826 to 0x0000000000000000 at monotonic time: 56883 msec
E (57683) chip[SC]: Failed during PASE session setup. Error CHIP:0x00000038
E (57693) chip[SVR]: Commissioning failed (attempt 1): Error CHIP:0x00000038
I (57693) chip[DL]: NVS set: chip-factory/discriminator = 3840 (0xF00)
I (57713) chip[DIS]: CHIP minimal mDNS started advertising.
I (57733) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (57733) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (57743) chip[DIS]: mDNS service published: _matter._tcp
I (57753) chip[DIS]: Have operational credentials
I (57753) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
I (57763) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (57793) chip[DIS]: mDNS service published: _matterc._udp
E (57793) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x00000038
E (57793) chip[DL]: Long dispatch time: 151 ms, for event type 3
I (57963) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:3262651593 on exchange 17263r
I (64573) all-clusters-app: Display going to sleep...
I (96563) chip[EM]: Received message of type 0x20 with protocolId (0, 0) and MessageCounter:2837883340 on exchange 53941r
I (96563) chip[IN]: Prepared unauthenticated message 0x3ffca0e4 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 53941r with MessageCounter:389034827.
I (96583) chip[IN]: Sending unauthenticated msg 0x3ffca0e4 with MessageCounter:389034827 to 0x0000000000000000 at monotonic time: 95798 msec
E (96593) chip[SC]: Failed during PASE session setup. Error CHIP:0x00000038
E (96603) chip[SVR]: Commissioning failed (attempt 2): Error CHIP:0x00000038
I (96613) chip[DL]: NVS set: chip-factory/discriminator = 3840 (0xF00)
I (96623) chip[DIS]: CHIP minimal mDNS started advertising.
I (96643) chip[DIS]: Advertise operational node 9910A89490FA5F61-0000000000000004
I (96653) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'.
I (96673) chip[DIS]: mDNS service published: _matter._tcp
I (96673) chip[DIS]: Have operational credentials
I (96673) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15
I (96693) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (96713) chip[DIS]: mDNS service published: _matterc._udp
E (96713) chip[EM]: OnMessageReceived failed, err = Error CHIP:0x00000038
E (96713) chip[DL]: Long dispatch time: 156 ms, for event type 3
I (96733) chip[EM]: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:2837883341 on exchange 53941r