Matter over WiFi: intermittent "No Response" and retransmission failures on nRF54LM20 DK + nRF7002 EB II (NCS v3.3.4)

[ncohen]

Hardware: nRF54LM20 DK + nRF7002 EB II shield SDK: NCS v3.3.4 Sample: Unmodified Matter light bulb sample

(nrf/samples/matter/light_bulb) Build command: west build -p -b nrf54lm20dk/nrf54lm20a/cpuapp -- -DSHIELD=nrf7002eb2 -DSB_CONFIG_WIFI_NRF70=y -DCONFIG_CHIP_WIFI=y Router: Eero (Apple-recommended, mDNS/Bonjour supported) Controller: Apple Home with HomePod Mini as home hub

Problem: After commissioning the unmodified Matter light bulb sample to Apple Home, the device works for a few commands (on/off, level control all succeed), then becomes unresponsive. Apple Home shows "No Response." The device does not recover unless reset.

Observed behavior:

1. Commissioning succeeds (PASE → WiFi → CASE all complete)
2. Light control works for 5-10 commands
3. Device starts failing retransmissions (max retries: 4 → failure)
4. Sessions go defunct, subscriptions torn down
5. Apple Home shows "No Response" permanently

Relevant log errors:

• E: [IN]IPV6_PKTINFO failed: 109 (on every mDNS advertisement)
• E: [DIS]Failed to advertise records: 46 (intermittent)
• E: [EM]<<5 Msg Retransmission failure (max retries:4) (device sends but HomePod doesn't receive)
• [SC]SecureSession State change 'kActive' --> 'kDefunct'

Analysis: The device sends UDP responses but they don't reach the controller. This appears to be WiFi-layer packet loss rather than a Matter stack issue. The retransmissions show the device is trying to respond but packets are being dropped.

I noticed commit ba4fc5cc1f in sdk-connectedhomeip reverted the MLDv2 join fix ("Enable MLDv2 join procedure for IPv6 Multicasts"). Related known issue: KRKNWK-19524.

Questions:

1. Is there a patch or workaround for the UDP packet loss on nRF7002 with Matter over WiFi?
2. Does NCS v3.4.0 resolve this?
3. Is the MLD fix being re-introduced in a future release?

Note: I'm aware the nRF7002 EB II dev guide states WiFi is "experimental" and "not optimized for performance" on this platform. However, the unmodified Nordic Matter light bulb sample is advertised as supporting this exact hardware combination (nrf54lm20dk/nrf54lm20a/cpuapp with nrf7002eb2 shield) in the official documentation. If this combination isn't stable enough for Matter over WiFi, the documentation should reflect that.

[Syed Maysum Abbas Zaidi]

Hi,

Thanks a lot for reaching out to us, your case is being discussed internally with the relevant team and I will get back to you by next week. Appreciate your patience. Thanks.

Best Regards,
Syed Maysum 

[Syed Maysum Abbas Zaidi]

Hi,

Thanks a lot for waiting. As per discussion up till now we are not aware of any known issue related to that, but I will double check it. Because of that it's rather hard for me to say is it going to be better with NCS 3.4.0.

We can try to reproduce it, but in the meantime I could propose a quick test to see if the issue could be related to setup or environment. Could you try enabling mobile hotspot on the smartphone and use it as Wi-Fi access point, instead of Wi-Fi router? There are two ways to do that:

1. Disable Wi-Fi router, name mobile hotspot with the same SSID and password, as it was for the Wi-Fi router. That should allow to test without re-configuring the Apple Home devices
2. Just enable mobile hotspot with any ssid and password, but then it is required to re-configure Apple devices to use new Wi-Fi network, not the one created by Wi-Fi router.

That test would allow us to troubleshoot if problems can be related to specific router (or its configuration).

Best Regards,
Syed Maysum

[ncohen]

Hi Syed,

I tested with a mobile hotspot (iPhone) as the access point — same SSID/password method so Apple Home didn't need reconfiguration. The issue persists identically:

• Commissioning succeeds
• 5-8 commands work
• Then retransmission failures and "No Response"

This rules out the Eero router as the cause. The problem reproduces regardless of the access point, which points to the nRF7002 WiFi driver or the Matter UDP transport layer.

Is there anything else I can provide to help reproduce on your side? I can share full RTT logs if needed.

[ncohen]

Hi Syed,

I tested with a mobile hotspot as you suggested — same issue occurs. This rules out the router.

I also re-flashed the unmodified Matter light bulb sample (nrf/samples/matter/light_bulb) to confirm this is not related to any custom code. Build command:

west build -p -b nrf54lm20dk/nrf54lm20a/cpuapp --build-dir C:\ncs\projects\matter_light_bulb_build -- -DSHIELD=nrf7002eb2 -DSB_CONFIG_WIFI_NRF70=y -DCONFIG_CHIP_WIFI=y

Reproduction steps:

1. Flash unmodified sample
2. Commission to Apple Home (HomePod Mini as hub, Eero router)
3. Toggle light on/off — first 4 commands succeed within ~1.3s round-trip
4. Wait ~30 seconds idle
5. Send 5th toggle — device processes command but response never reaches controller

Attached serial log shows the exact failure:

• t=80s–85s: Toggles 1–4 succeed (command → response → ACK, all within ~2s)
• t=122s: Toggle 5 — device sends InvokeCommandResponse but HomePod never receives it
• t=125s–138s: Retransmissions escalate (retry 1→2→3→4→5), exponential backoff
• HomePod also retransmits the original command, confirming packets are dropped in both directions at the WiFi layer
• After retry 5, session goes defunct → "No Response"

Additional observations:

• E: IPV6_PKTINFO failed: 109 appears on every mDNS advertisement from boot — this may be related
• E: Failed to advertise records: 46 occurs intermittently
• The failure happens after an idle period (~37s gap), suggesting the nRF7002 WiFi may be entering a low-power state or losing multicast group membership after inactivity
• Tested with both Eero router and iPhone mobile hotspot — identical behavior

Questions:

1. Is the IPV6_PKTINFO failed: 109 error expected on this platform? It appears from the very first UDP socket init.
2. Could this be related to WiFi power-save mode dropping buffered frames after idle?
3. Is there a config to disable WiFi power-save for testing (CONFIG_NRF_WIFI_LOW_POWER=n)?
4. Any update on whether NCS 3.4.0 addresses this?

Full serial log (from boot through failure) is attached below.

Thanks,

Netanel

uart:~$ *** Booting My Application v3.3.4-b096d30d893b ***
*** Using nRF Connect SDK v3.3.4-b096d30d893b ***
*** Using Zephyr OS v4.3.99-37e6c28576ee ***
I: 191 [DL]BLE address: C2:6D:5A:A4:24:AF
D: 199 [DL]WiFiManager has been initialized
I: 205 [DL]CHIP task running
I: Init CHIP stack
I: 221 [DL]The device does not support hardware protection against write.
D: Registered new test event: 0xffffffff00000000
D: Registered new test event: 0xffffffff10000000
I: 245 [SVR]Initializing subscription resumption storage...
I: 252 [SVR]Server initializing...
I: 255 [TS]Last Known Good Time: 2023-10-14T01:16:48
I: 260 [DMG]AccessControl: initializing
I: 263 [DMG]Examples::AccessControlDelegate::Init
I: 268 [DMG]AccessControl: setting
I: 271 [DMG]DefaultAclStorage: initializing
I: 275 [DMG]DefaultAclStorage: 0 entries loaded
D: 279 [IN]UDP::Init bind&listen port=5540
E: 283 [IN]IPV6_PKTINFO failed: 109
D: 286 [IN]UDP::Init bound to port=5540
D: 290 [IN]BLEBase::Init - setting/overriding transport
D: 295 [IN]TransportMgr initialized
I: 305 [ZCL]Using ZAP configuration...
D: 309 [DL]Boot reason: 1
I: 312 [ZCL]Endpoint 1 On/off already set to new value
I: 318 [DMG]AccessControlCluster: initializing
D: 324 [IN]SecureSession[0x2000fff8]: Allocated Type:1 LSID:62770
D: 330 [DL]CHIPoBLE advertising set to on
I: 333 [DIS]Updating services using commissioning mode 1
I: 339 [DIS]CHIP minimal mDNS started advertising.
D: 343 [DL]Using WiFi MAC for hostname
D: 347 [DIS]DNS-SD Pairing Instruction not set
I: 351 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 cp=0 jf=0
D: 361 [DIS]Responding with _matterc._udp.local
D: 365 [DIS]Responding with 0BE0B2081EA953AB._matterc._udp.local
D: 370 [DIS]Responding with F4CE3600B6C8.local
D: 375 [DIS]Responding with _V65521._sub._matterc._udp.local
D: 380 [DIS]Responding with _S15._sub._matterc._udp.local
D: 385 [DIS]Responding with _L3840._sub._matterc._udp.local
D: 390 [DIS]Responding with _CM._sub._matterc._udp.local
D: 396 [DIS]Responding with 0BE0B2081EA953AB._matterc._udp.local
I: 401 [DIS]CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 0BE0B2081EA953AB.
I: 411 [DIS]mDNS service published: _matterc._udp
I: 415 [DIS]Updating services using commissioning mode 1
I: 420 [DIS]CHIP minimal mDNS started advertising.
D: 425 [DL]Using WiFi MAC for hostname
D: 428 [DIS]DNS-SD Pairing Instruction not set
I: 432 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1 cp=0 jf=0
D: 442 [DIS]Responding with _matterc._udp.local
D: 446 [DIS]Responding with 0BE0B2081EA953AB._matterc._udp.local
D: 452 [DIS]Responding with F4CE3600B6C8.local
D: 456 [DIS]Responding with _V65521._sub._matterc._udp.local
D: 462 [DIS]Responding with _S15._sub._matterc._udp.local
D: 467 [DIS]Responding with _L3840._sub._matterc._udp.local
D: 472 [DIS]Responding with _CM._sub._matterc._udp.local
D: 477 [DIS]Responding with 0BE0B2081EA953AB._matterc._udp.local
I: 483 [DIS]CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 0BE0B2081EA953AB.
I: 492 [DIS]mDNS service published: _matterc._udp
I: 497 [IN]CASE Server enabling CASE session setups
D: 501 [IN]SecureSession[0x200100d0]: Allocated Type:2 LSID:62771
I: 507 [SVR]Joining Multicast groups
I: 511 [SVR]Server Listening...
I: 513 [DL]Device Configuration:
I: 516 [DL]  Serial Number: 11223344556677889900
I: 521 [DL]  Vendor Id: 65521 (0xFFF1)
I: 524 [DL]  Product Id: 32773 (0x8005)
I: 528 [DL]  Product Name: Matter Light Bulb
I: 532 [DL]  Hardware Version: 0
I: 535 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 540 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 547 [DL]  Manufacturing Date: 2022-01-01
I: 550 [DL]  Device Type: 65535 (0xFFFF)
I: 554 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 558 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 565 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 574 [SVR]Manual pairing code: [34970112332]
E: 578 [DL]Long dispatch time: 367 ms, for event type 2
I: 584 [DL]CHIPoBLE advertising started
I: 588 [DL]NFC Tag emulation started
I: 30587 [DL]CHIPoBLE advertising mode changed to slow
I: 30593 [DL]CHIPoBLE advertising started
I: 35679 [DL]Current number of connections: 1/1
I: 35683 [DL]BLE connection established (ConnId: 0x00)
I: 35688 [DL]CHIPoBLE advertising stopped
I: 35692 [DL]NFC Tag emulation stopped
D: 36502 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 36509 [BLE]local and remote recv window sizes = 5
I: 36513 [BLE]selected BTP version 4
I: 36517 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 36622 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 36626 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 36633 [IN]BLE EndPoint 0x2001dd84 Connection Complete
I: 36638 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 36681 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 36690 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 36697 [EM]>>> [E:31807r S:0 M:9487150] (U) Msg RX from 0:DDEF47DFA8674DA7 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
I: 36712 [EM]<<< [E:31807r S:0 M:168505790] (U) Msg TX from 0000000000000000 to 0:DDEF47DFA8674DA7 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:154)
D: 36727 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 159)
I: 36735 [SVR]Commissioning session establishment step started
D: 36771 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 36779 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 36787 [EM]>>> [E:31807r S:0 M:9487151] (U) Msg RX from 0:DDEF47DFA8674DA7 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
I: 37445 [EM]<<< [E:31807r S:0 M:168505791] (U) Msg TX from 0000000000000000 to 0:DDEF47DFA8674DA7 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
D: 37460 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
E: 37468 [DL]Long dispatch time: 689 ms, for event type 16388
D: 37581 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 37589 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 37597 [EM]>>> [E:31807r S:0 M:9487152] (U) Msg RX from 0:DDEF47DFA8674DA7 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
I: 37611 [EM]<<< [E:31807r S:0 M:168505792] (U) Msg TX from 0000000000000000 to 0:DDEF47DFA8674DA7 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
D: 37625 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 37634 [SC]SecureSession[0x2000fff8, LSID:62770]: State change 'kEstablishing' --> 'kActive'
D: 37643 [IN]SecureSession[0x2000fff8]: Activated - Type:1 LSID:62770
D: 37649 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:62770 PSID:45403!
I: 37657 [SVR]Commissioning completed session establishment step
I: 37663 [DIS]Updating services using commissioning mode 0
I: 37668 [DIS]CHIP minimal mDNS started advertising.
D: 37673 [DL]CHIPoBLE advertising set to off
I: 37677 [SVR]Device completed Rendezvous process
D: 37701 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 37709 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 37718 [EM]>>> [E:31808r S:62770 M:59240265] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:136)
D: 37731 [IM]Received Read request
E: 37739 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0030, attributeId: 0x0000_000Cerr = 586
I: 37776 [EM]<<< [E:31808r S:62770 M:43286508] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:253)
D: 37790 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 37881 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 37889 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 16)
D: 38001 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38009 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 38018 [EM]>>> [E:31809r S:62770 M:59240266] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:134)
D: 38032 [IM]Received Read request
E: 38037 [DMG]Read request on unknown cluster - no data version available
E: 38044 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x1349_FC00, attributeId: 0x0000_0001err = 5c3
E: 38055 [DMG]Read request on unknown cluster - no data version available
E: 38062 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = 5c3
E: 38074 [DMG]Read request on unknown cluster - no data version available
E: 38081 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = 5c3
E: 38092 [DMG]Read request on unknown cluster - no data version available
E: 38099 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = 5c3
E: 38111 [DMG]Read request on unknown cluster - no data version available
E: 38117 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 5c3
E: 38129 [DMG]Read request on unknown cluster - no data version available
E: 38136 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 5c3
I: 38153 [EM]<<< [E:31809r S:62770 M:43286509] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:260)
D: 38167 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 38301 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38309 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 23)
D: 38481 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38542 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 38550 [EM]>>> [E:31810r S:62770 M:59240267] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:59)
D: 38563 [IM]Received Read request
I: 38571 [EM]<<< [E:31810r S:62770 M:43286510] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:126)
D: 38584 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 131)
D: 38781 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38789 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 38798 [EM]>>> [E:31811r S:62770 M:59240268] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 38812 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 38819 [EM]<<< [E:31811r S:62770 M:43286511] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 38833 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 38901 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 38909 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 38917 [EM]>>> [E:31812r S:62770 M:59240269] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 38947 [EM]<<< [E:31812r S:62770 M:43286512] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 38962 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 39081 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39089 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 39098 [EM]>>> [E:31813r S:62770 M:59240270] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I: 39112 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 39123 [EM]<<< [E:31813r S:62770 M:43286513] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:527)
D: 39138 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 39261 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39269 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 39381 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39389 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 39501 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39509 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 39517 [EM]>>> [E:31814r S:62770 M:59240271] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
I: 39532 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 39544 [EM]<<< [E:31814r S:62770 M:43286514] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:556)
D: 39559 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 39681 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39689 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 39801 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39809 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
D: 39981 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 39989 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 39998 [EM]>>> [E:31815r S:62770 M:59240272] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I: 40012 [ZCL]OpCreds: Received an AttestationRequest command
I: 40045 [ZCL]OpCreds: AttestationRequest successful.
I: 40058 [EM]<<< [E:31815r S:62770 M:43286515] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:716)
D: 40072 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 40281 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40289 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 40401 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40409 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 237)
D: 40521 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 40529 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 40538 [EM]>>> [E:31816r S:62770 M:59240273] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 40552 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 40559 [EM]<<< [E:31816r S:62770 M:43286516] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 40573 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 40701 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 42502 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 42510 [EM]>>> [E:31817r S:62770 M:59240274] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I: 42525 [ZCL]OpCreds: Received a CSRRequest command
I: 42568 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 42600 [ZCL]OpCreds: CSRRequest successful.
I: 42608 [EM]<<< [E:31817r S:62770 M:43286517] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:391)
D: 42623 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
E: 42631 [DL]Long dispatch time: 129 ms, for event type 16388
D: 42741 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 42749 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 154)
D: 42861 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 42983 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 43102 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43112 [EM]>>> [E:31818r S:62770 M:59240275] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:308)
I: 43127 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 43160 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 43167 [EM]<<< [E:31818r S:62770 M:43286518] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
D: 43181 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 43281 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43289 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 43522 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43533 [EM]>>> [E:31819r S:62770 M:59240276] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:347)
I: 43548 [ZCL]OpCreds: Received an AddNOC command
I: 43553 [FP]Validating NOC chain
I: 43585 [FP]NOC chain validation successful
I: 43589 [FP]Added new fabric at index: 0x1
I: 43592 [FP]Assigned compressed fabric ID: 0xCCC10070EA402D1F, node ID: 0x00000000737613D4
I: 43601 [TS]Last Known Good Time: 2023-10-14T01:16:48
I: 43605 [TS]New proposed Last Known Good Time: 2026-08-12T16:50:56
I: 43611 [TS]Updating pending Last Known Good Time to 2026-08-12T16:50:56
I: 43677 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x00000000BCDA9022
D: 43685 [DL]Using WiFi MAC for hostname
I: 43689 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 43696 [DIS]Responding with _matter._tcp.local
D: 43700 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 43708 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 43715 [DIS]Responding with F4CE3600B6C8.local
D: 43719 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 43726 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 43736 [DIS]mDNS service published: _matter._tcp
I: 43741 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 43748 [EM]<<< [E:31819r S:62770 M:43286519] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [2D1F] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 43763 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
E: 43770 [DL]Long dispatch time: 248 ms, for event type 16388
D: 43881 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 43889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 43897 [EM]>>> [E:31820r S:62770 M:59240277] (S) Msg RX from 1:FFFFFFFB00000000 [2D1F] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
D: 43914 [DL]WiFi scanning started...
D: 46396 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 46521 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 48549 [DL]Wi-Fi scan done
I: 48558 [EM]<<< [E:31820r S:62770 M:43286520] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [2D1F] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:540)
D: 48573 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 48681 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48689 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 48801 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48809 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 60)
D: 48922 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 48929 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 49042 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49050 [EM]>>> [E:31821r S:62770 M:59240278] (S) Msg RX from 1:FFFFFFFB00000000 [2D1F] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:83)
I: 49066 [EM]<<< [E:31821r S:62770 M:43286521] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [2D1F] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 49080 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 49161 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49169 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49177 [EM]>>> [E:31822r S:62770 M:59240279] (S) Msg RX from 1:FFFFFFFB00000000 [2D1F] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 49192 [FS]GeneralCommissioning: Received ArmFailSafe (124s)
I: 49199 [EM]<<< [E:31822r S:62770 M:43286522] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [2D1F] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
D: 49213 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 49341 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 49349 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 49357 [EM]>>> [E:31823r S:62770 M:59240280] (S) Msg RX from 1:FFFFFFFB00000000 [2D1F] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:72)
D: 49372 [DL]Connecting to WiFi network: Netanel
D: 49378 [DL]WiFi scanning started...
D: 51856 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 51981 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 53518 [DL]Wi-Fi scan done
I: 54847 [DL]Connection to Netanel requested [RSSI=-38]
E: 54853 [DL]Long dispatch time: 1336 ms, for event type 3
D: 54859 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 57366 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 57441 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 59024 [DL]Connected to WiFi network
I: 59033 [EM]<<< [E:31823r S:62770 M:43286523] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [2D1F] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
D: 59048 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 69)
D: 59055 [DL]Using WiFi MAC for hostname
I: 59059 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 59066 [DIS]Responding with _matter._tcp.local
D: 59070 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59077 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59085 [DIS]Responding with F4CE3600B6C8.local
D: 59089 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 59096 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
E: 59107 [DIS]Failed to advertise records: 46
I: 59111 [DIS]mDNS service published: _matter._tcp
I: 59116 [SVR]Operational advertising enabled
I: 59120 [SVR]Server initialization complete
I: 59124 [DIS]Updating services using commissioning mode 0
E: 59130 [IN]IPV6_PKTINFO failed: 109
I: 59136 [DIS]CHIP minimal mDNS started advertising.
D: 59145 [DL]Using WiFi MAC for hostname
I: 59150 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 59159 [DIS]Responding with _matter._tcp.local
D: 59163 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59170 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59178 [DIS]Responding with F4CE3600B6C8.local
D: 59182 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 59188 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 59203 [DIS]mDNS service published: _matter._tcp
D: 59208 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 59218 [IM]No subscriptions to resume
I: 59222 [SWU]Stopping the watchdog timer
I: 59226 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 59232 [DIS]Updating services using commissioning mode 0
E: 59237 [IN]IPV6_PKTINFO failed: 109
I: 59241 [DIS]CHIP minimal mDNS started advertising.
D: 59250 [DL]Using WiFi MAC for hostname
I: 59255 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 59262 [DIS]Responding with _matter._tcp.local
D: 59266 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59277 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59286 [DIS]Responding with F4CE3600B6C8.local
D: 59291 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 59297 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 59309 [DIS]mDNS service published: _matter._tcp
I: 59315 [EM]>>> [E:31824r S:0 M:9487153] (U) Msg RX from 0:C51DEB06854C3A84 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
I: 59328 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20012cc0
I: 59336 [EM]<<< [E:31824r S:0 M:168505793 (Ack:9487153)] (U) Msg TX from 0000000000000000 to 0:C51DEB06854C3A84 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 59355 [SC]Received Sigma1 msg
I: 59362 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x00000000737613D4
I: 59540 [EM]<<< [E:31824r S:0 M:168505794 (Ack:9487153)] (U) Msg TX from 0000000000000000 to 0:C51DEB06854C3A84 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:529)
I: 59559 [EM]??1 [E:31824r S:0 M:168505794] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2284ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 59574 [SC]Sent Sigma2 msg
I: 59581 [EM]>>> [E:31824r S:0 M:9487154 (Ack:168505794)] (U) Msg RX from 0:C51DEB06854C3A84 [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:380)
I: 59606 [EM]<<< [E:31824r S:0 M:168505795 (Ack:9487154)] (U) Msg TX from 0000000000000000 to 0:C51DEB06854C3A84 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 59625 [SC]Received Sigma3 msg
E: 59634 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
I: 59644 [DIS]Updating services using commissioning mode 0
E: 59649 [IN]IPV6_PKTINFO failed: 109
I: 59652 [DIS]CHIP minimal mDNS started advertising.
D: 59663 [DL]Using WiFi MAC for hostname
I: 59667 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 59674 [DIS]Responding with _matter._tcp.local
D: 59678 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59687 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59694 [DIS]Responding with F4CE3600B6C8.local
D: 59699 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 59705 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 59717 [DIS]mDNS service published: _matter._tcp
I: 59723 [DIS]Updating services using commissioning mode 0
E: 59729 [IN]IPV6_PKTINFO failed: 109
I: 59732 [DIS]CHIP minimal mDNS started advertising.
D: 59742 [DL]Using WiFi MAC for hostname
I: 59746 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 59753 [DIS]Responding with _matter._tcp.local
D: 59757 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59765 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 59773 [DIS]Responding with F4CE3600B6C8.local
D: 59781 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 59788 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 59801 [DIS]mDNS service published: _matter._tcp
I: 59913 [EM]<<< [E:31824r S:0 M:168505796 (Ack:9487154)] (U) Msg TX from 0000000000000000 to 0:C51DEB06854C3A84 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I: 59935 [EM]??1 [E:31824r S:0 M:168505796] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2493ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 59950 [SC]SecureSession[0x200100d0, LSID:62771]: State change 'kEstablishing' --> 'kActive'
D: 59958 [IN]SecureSession[0x200100d0]: Activated - Type:2 LSID:62771
D: 59965 [IN]New secure session activated for device <00000000BCDA9022, 1>, LSID:62771 PSID:45404!
I: 59974 [IN]CASE Session established to peer: <00000000BCDA9022, 1>
D: 59986 [IN]SecureSession[0x200101a8]: Allocated Type:2 LSID:62772
E: 59993 [DL]Long dispatch time: 130 ms, for event type 2
D: 59998 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 60093 [EM]>>> [E:31825r S:62771 M:139499383] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 60108 [FS]GeneralCommissioning: Received CommissioningComplete
I: 60141 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 60201 [TS]Committing Last Known Good Time to storage: 2026-08-12T16:50:56
I: 60221 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0xCCC10070EA402D1F, FabricId 0000000090AE67A9, NodeId 00000000737613D4, VendorId 0x1349
I: 60247 [FS]GeneralCommissioning: Successfully committed pending fabric data
I: 60254 [FS]Fail-safe cleanly disarmed
I: 60259 [EM]<<< [E:31825r S:62771 M:123010868 (Ack:139499383)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 60279 [EM]??1 [E:31825r S:62771 M:123010868] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2441ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60294 [SWU]Device commissioned, schedule a default provider query
I: 60300 [SVR]Commissioning completed successfully
I: 60304 [DIS]Updating services using commissioning mode 0
E: 60311 [IN]IPV6_PKTINFO failed: 109
I: 60315 [DIS]CHIP minimal mDNS started advertising.
D: 60324 [DL]Using WiFi MAC for hostname
I: 60328 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 60335 [DIS]Responding with _matter._tcp.local
D: 60339 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 60346 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 60354 [DIS]Responding with F4CE3600B6C8.local
D: 60358 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 60364 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 60376 [DIS]mDNS service published: _matter._tcp
D: 60381 [DL]CHIPoBLE advertising set to off
D: 60385 [IN]Expiring all PASE sessions
D: 60388 [IN]SecureSession[0x2000fff8]: MarkForEviction Type:1 LSID:62770
I: 60395 [SC]SecureSession[0x2000fff8, LSID:62770]: State change 'kActive' --> 'kPendingEviction'
D: 60403 [IN]SecureSession[0x2000fff8]: Released - Type:1 LSID:62770
D: 60409 [IN]Clearing BLE pending packets.
I: 60413 [BLE]Releasing end point's BLE connection back to application.
I: 60420 [DL]Closing BLE GATT connection (ConnId 00)
E: 60444 [DL]Long dispatch time: 150 ms, for event type 32783
I: 60449 [DL]Current number of connections: 0/1
I: 60454 [EM]>>> [E:31824r S:0 M:9487155 (Ack:168505796)] (U) Msg RX from 0:C51DEB06854C3A84 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 60469 [DL]BLE GAP connection terminated (reason 0x13)
I: 60475 [EM]>>> [E:31825r S:62771 M:139499384 (Ack:123010868)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 60492 [EM]>>> [E:31826r S:62771 M:139499385] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:06 (IM:WriteRequest) (B:110)
D: 60506 [IM]Received Write request
I: 60532 [EM]<<< [E:31826r S:62771 M:123010869 (Ack:139499385)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:07 (IM:WriteResponse) (B:62)
I: 60551 [EM]??1 [E:31826r S:62771 M:123010869] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2676ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60571 [EM]>>> [E:31826r S:62771 M:139499386 (Ack:123010869)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 60588 [EM]>>> [E:31827r S:62771 M:139499387] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:03 (IM:SubscribeRequest) (B:58)
D: 60601 [IM]Received Subscribe request
I: 60606 [DMG]Final negotiated min/max parameters: Min = 0s, Max = 600s
I: 60650 [EM]<<< [E:31827r S:62771 M:123010870 (Ack:139499387)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1209)
I: 60668 [EM]??1 [E:31827r S:62771 M:123010870] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2508ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60686 [EM]>>> [E:31828r S:62771 M:139499388] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:02 (IM:ReadRequest) (B:51)
D: 60699 [IM]Received Read request
I: 60706 [EM]<<< [E:31828r S:62771 M:123010871 (Ack:139499388)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:162)
I: 60725 [EM]??1 [E:31828r S:62771 M:123010871] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2248ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60746 [EM]>>> [E:31827r S:62771 M:139499389 (Ack:123010870)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 60761 [IM]Received status response, status is 0x00
I: 60828 [EM]<<< [E:31827r S:62771 M:123010872 (Ack:139499389)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1198)
I: 60847 [EM]??1 [E:31827r S:62771 M:123010872] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2650ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60864 [EM]>>> [E:31828r S:62771 M:139499390 (Ack:123010871)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 60880 [EM]>>> [E:31827r S:62771 M:139499391 (Ack:123010872)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 60895 [IM]Received status response, status is 0x00
I: 60931 [EM]<<< [E:31827r S:62771 M:123010873 (Ack:139499391)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1176)
I: 60950 [EM]??1 [E:31827r S:62771 M:123010873] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2471ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 60967 [EM]>>> [E:31827r S:62771 M:139499392 (Ack:123010873)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 60982 [IM]Received status response, status is 0x00
I: 61016 [EM]<<< [E:31827r S:62771 M:123010874 (Ack:139499392)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1196)
I: 61035 [EM]??1 [E:31827r S:62771 M:123010874] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2699ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61052 [EM]>>> [E:31827r S:62771 M:139499393 (Ack:123010874)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 61067 [IM]Received status response, status is 0x00
I: 61105 [EM]<<< [E:31827r S:62771 M:123010875 (Ack:139499393)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1184)
I: 61123 [EM]??1 [E:31827r S:62771 M:123010875] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2581ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61141 [EM]>>> [E:31827r S:62771 M:139499394 (Ack:123010875)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 61156 [IM]Received status response, status is 0x00
I: 61194 [EM]<<< [E:31827r S:62771 M:123010876 (Ack:139499394)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1189)
I: 61213 [EM]??1 [E:31827r S:62771 M:123010876] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2493ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61231 [EM]>>> [E:31827r S:62771 M:139499395 (Ack:123010876)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 61246 [IM]Received status response, status is 0x00
I: 61274 [EM]<<< [E:31827r S:62771 M:123010877 (Ack:139499395)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1199)
I: 61293 [EM]??1 [E:31827r S:62771 M:123010877] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2239ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61311 [EM]>>> [E:31827r S:62771 M:139499396 (Ack:123010877)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 61325 [IM]Received status response, status is 0x00
I: 61348 [EM]<<< [E:31827r S:62771 M:123010878 (Ack:139499396)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:992)
I: 61367 [EM]??1 [E:31827r S:62771 M:123010878] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2424ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61385 [EM]>>> [E:31827r S:62771 M:139499397 (Ack:123010878)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 61400 [IM]Received status response, status is 0x00
I: 61406 [EM]<<< [E:31827r S:62771 M:123010879 (Ack:139499397)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:04 (IM:SubscribeResponse) (B:49)
I: 61425 [EM]??1 [E:31827r S:62771 M:123010879] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2559ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61443 [DMG]Registered a ReadHandler that will schedule a report between system Timestamp: 0x000000000000F003 and system Timestamp 0x00000000000A17C3.
I: 61457 [EM]>>> [E:31829r S:62771 M:139499398] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:02 (IM:ReadRequest) (B:51)
D: 61471 [IM]Received Read request
I: 61478 [EM]<<< [E:31829r S:62771 M:123010880 (Ack:139499398)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:162)
I: 61497 [EM]??1 [E:31829r S:62771 M:123010880] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2549ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61518 [EM]>>> [E:31827r S:62771 M:139499399 (Ack:123010879)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 61535 [EM]>>> [E:31829r S:62771 M:139499400 (Ack:123010880)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 61552 [EM]>>> [E:31830r S:62771 M:139499401] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
I: 61566 [FS]GeneralCommissioning: Received ArmFailSafe (30s)
I: 61573 [EM]<<< [E:31830r S:62771 M:123010881 (Ack:139499401)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 61593 [EM]??1 [E:31830r S:62771 M:123010881] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2547ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61612 [EM]>>> [E:31830r S:62771 M:139499402 (Ack:123010881)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 61629 [EM]>>> [E:31831r S:62771 M:139499403] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
I: 61643 [ZCL]OpCreds: Received a CSRRequest command
I: 61687 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 61718 [ZCL]OpCreds: CSRRequest successful.
I: 61727 [EM]<<< [E:31831r S:62771 M:123010882 (Ack:139499403)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:396)
I: 61747 [EM]??1 [E:31831r S:62771 M:123010882] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2216ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61766 [EM]>>> [E:31831r S:62771 M:139499404 (Ack:123010882)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 61785 [EM]>>> [E:31832r S:62771 M:139499405] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:310)
I: 61799 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 61833 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 61840 [EM]<<< [E:31832r S:62771 M:123010883 (Ack:139499405)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 61860 [EM]??1 [E:31832r S:62771 M:123010883] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2334ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 61877 [EM]>>> [E:31832r S:62771 M:139499406 (Ack:123010883)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 62051 [EM]>>> [E:31833r S:62771 M:139499407] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:346)
I: 62065 [ZCL]OpCreds: Received an AddNOC command
I: 62070 [FP]Validating NOC chain
I: 62102 [FP]NOC chain validation successful
I: 62106 [FP]Added new fabric at index: 0x2
I: 62110 [FP]Assigned compressed fabric ID: 0x3AF8C2CFA42EF81B, node ID: 0x00000000E7C2DE36
I: 62118 [TS]Last Known Good Time: 2026-08-12T16:50:56
I: 62123 [TS]New proposed Last Known Good Time: 2026-08-12T16:51:15
I: 62129 [TS]Updating pending Last Known Good Time to 2026-08-12T16:51:15
I: 62180 [ZCL]OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0x067A6201A87F9090
D: 62189 [DL]Using WiFi MAC for hostname
I: 62192 [DIS]Advertise operational node CCC10070EA402D1F-00000000737613D4
D: 62199 [DIS]Responding with _matter._tcp.local
D: 62203 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 62211 [DIS]Responding with CCC10070EA402D1F-00000000737613D4._matter._tcp.local
D: 62218 [DIS]Responding with F4CE3600B6C8.local
D: 62222 [DIS]Responding with _ICCC10070EA402D1F._sub._matter._tcp.local
I: 62229 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: CCC10070EA402D1F-00000000737613D4.
I: 62241 [DIS]mDNS service published: _matter._tcp
D: 62247 [DL]Using WiFi MAC for hostname
I: 62250 [DIS]Advertise operational node 3AF8C2CFA42EF81B-00000000E7C2DE36
D: 62257 [DIS]Responding with _matter._tcp.local
D: 62261 [DIS]Responding with 3AF8C2CFA42EF81B-00000000E7C2DE36._matter._tcp.local
D: 62269 [DIS]Responding with 3AF8C2CFA42EF81B-00000000E7C2DE36._matter._tcp.local
D: 62276 [DIS]Responding with F4CE3600B6C8.local
D: 62280 [DIS]Responding with _I3AF8C2CFA42EF81B._sub._matter._tcp.local
I: 62287 [DIS]CHIP minimal mDNS configured as 'Operational device'; instance name: 3AF8C2CFA42EF81B-00000000E7C2DE36.
I: 62300 [DIS]mDNS service published: _matter._tcp
I: 62306 [ZCL]OpCreds: successfully created fabric index 0x2 via AddNOC
I: 62314 [EM]<<< [E:31833r S:62771 M:123010884 (Ack:139499407)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 62334 [EM]??1 [E:31833r S:62771 M:123010884] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2355ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 62357 [EM]<<< [E:22471i S:62771 M:123010885] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:333)
I: 62374 [EM]??1 [E:22471i S:62771 M:123010885] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2456ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 62399 [EM]>>> [E:31833r S:62771 M:139499408 (Ack:123010884)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 62415 [EM]>>> [E:22471i S:62771 M:139499409 (Ack:123010885)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 62430 [IM]Received status response, status is 0x00
I: 62436 [EM]<<< [E:22471i S:62771 M:123010886 (Ack:139499409)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 62600 [EM]>>> [E:31834r S:0 M:9487156] (U) Msg RX from 0:FC951E40AA5D78AD [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
I: 62614 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20012cc0
I: 62621 [EM]<<< [E:31834r S:0 M:168505797 (Ack:9487156)] (U) Msg TX from 0000000000000000 to 0:FC951E40AA5D78AD [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 62640 [SC]Received Sigma1 msg
I: 62650 [SC]CASE matched destination ID: fabricIndex 2, NodeID 0x00000000E7C2DE36
I: 62828 [EM]<<< [E:31834r S:0 M:168505798 (Ack:9487156)] (U) Msg TX from 0000000000000000 to 0:FC951E40AA5D78AD [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:527)
I: 62849 [EM]??1 [E:31834r S:0 M:168505798] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2557ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 62863 [SC]Sent Sigma2 msg
I: 63017 [EM]>>> [E:31834r S:0 M:9487157 (Ack:168505798)] (U) Msg RX from 0:FC951E40AA5D78AD [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:379)
I: 63033 [EM]<<< [E:31834r S:0 M:168505799 (Ack:9487157)] (U) Msg TX from 0000000000000000 to 0:FC951E40AA5D78AD [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 63055 [SC]Received Sigma3 msg
E: 63064 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
I: 63179 [EM]<<< [E:31834r S:0 M:168505800 (Ack:9487157)] (U) Msg TX from 0000000000000000 to 0:FC951E40AA5D78AD [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I: 63198 [EM]??1 [E:31834r S:0 M:168505800] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2486ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 63217 [SC]SecureSession[0x200101a8, LSID:62772]: State change 'kEstablishing' --> 'kActive'
D: 63225 [IN]SecureSession[0x200101a8]: Activated - Type:2 LSID:62772
D: 63231 [IN]New secure session activated for device <067A6201A87F9090, 2>, LSID:62772 PSID:45405!
I: 63240 [IN]CASE Session established to peer: <067A6201A87F9090, 2>
D: 63246 [IN]SecureSession[0x2000fff8]: Allocated Type:2 LSID:62773
E: 63252 [DL]Long dispatch time: 123 ms, for event type 2
I: 63258 [EM]>>> [E:31835r S:62772 M:114043844] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0001:02 (IM:ReadRequest) (B:51)
D: 63272 [IM]Received Read request
I: 63277 [EM]<<< [E:31835r S:62772 M:133905607 (Ack:114043844)] (S) Msg TX from 00000000E7C2DE36 to 2:067A6201A87F9090 [F81B] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:70)
I: 63296 [EM]??1 [E:31835r S:62772 M:133905607] (S) Msg Retransmission to 2:067A6201A87F9090 scheduled for 2342ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 63315 [EM]>>> [E:31834r S:0 M:9487158 (Ack:168505800)] (U) Msg RX from 0:FC951E40AA5D78AD [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 63335 [EM]>>> [E:31836r S:62772 M:114043845] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 63349 [FS]GeneralCommissioning: Received CommissioningComplete
I: 63375 [FP]Metadata for Fabric 0x2 persisted to storage.
I: 63436 [TS]Committing Last Known Good Time to storage: 2026-08-12T16:51:15
I: 63449 [ZCL]OpCreds: Fabric index 0x2 was committed to storage. Compressed Fabric Id 0x3AF8C2CFA42EF81B, FabricId 0000000000000001, NodeId 00000000E7C2DE36, VendorId 0x1384
I: 63474 [FS]GeneralCommissioning: Successfully committed pending fabric data
I: 63481 [FS]Fail-safe cleanly disarmed
I: 63485 [EM]<<< [E:31836r S:62772 M:133905608 (Ack:114043845)] (S) Msg TX from 00000000E7C2DE36 to 2:067A6201A87F9090 [F81B] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 63505 [EM]??1 [E:31836r S:62772 M:133905608] (S) Msg Retransmission to 2:067A6201A87F9090 scheduled for 2643ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 63522 [SWU]Device commissioned, schedule a default provider query
I: 63533 [EM]>>> [E:31835r S:62772 M:114043846 (Ack:133905607)] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 63550 [EM]>>> [E:31836r S:62772 M:114043847 (Ack:133905608)] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 63567 [EM]>>> [E:31837r S:62772 M:114043848] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0001:02 (IM:ReadRequest) (B:51)
D: 63580 [IM]Received Read request
I: 63587 [EM]<<< [E:31837r S:62772 M:133905609 (Ack:114043848)] (S) Msg TX from 00000000E7C2DE36 to 2:067A6201A87F9090 [F81B] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:90)
I: 63608 [EM]??1 [E:31837r S:62772 M:133905609] (S) Msg Retransmission to 2:067A6201A87F9090 scheduled for 2418ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 63637 [EM]>>> [E:31837r S:62772 M:114043849 (Ack:133905609)] (S) Msg RX from 2:067A6201A87F9090 [F81B] to 00000000E7C2DE36 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 64315 [EM]>>> [E:31838r S:62771 M:139499410] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I: 64329 [ZCL]OpCreds: Received an UpdateFabricLabel command
I: 64343 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 64349 [EM]<<< [E:31838r S:62771 M:123010887 (Ack:139499410)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 64369 [EM]??1 [E:31838r S:62771 M:123010887] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2310ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 64391 [EM]<<< [E:22472i S:62771 M:123010888] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:262)
I: 64411 [EM]??1 [E:22472i S:62771 M:123010888] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2368ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 64447 [EM]>>> [E:31838r S:62771 M:139499411 (Ack:123010887)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 64463 [EM]>>> [E:22472i S:62771 M:139499412 (Ack:123010888)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 64478 [IM]Received status response, status is 0x00
I: 64484 [EM]<<< [E:22472i S:62771 M:123010889 (Ack:139499412)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 67760 [EM]>>> [E:31841r S:62771 M:139499413] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
I: 67774 [ZCL]OpCreds: Received an UpdateFabricLabel command
I: 67786 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 67792 [EM]<<< [E:31841r S:62771 M:123010890 (Ack:139499413)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 67812 [EM]??1 [E:31841r S:62771 M:123010890] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2663ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 67836 [EM]<<< [E:22473i S:62771 M:123010891] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:262)
I: 67853 [EM]??1 [E:22473i S:62771 M:123010891] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2602ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 67876 [EM]>>> [E:31841r S:62771 M:139499414 (Ack:123010890)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 67895 [EM]>>> [E:22473i S:62771 M:139499415 (Ack:123010891)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 67910 [IM]Received status response, status is 0x00
I: 67915 [EM]<<< [E:22473i S:62771 M:123010892 (Ack:139499415)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 80710 [EM]>>> [E:31842r S:62771 M:139499416] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 80725 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 80729 [ZCL]On Command - OffWaitTime :  0
I: 80733 [ZCL]On/Toggle Command - Stop Timer
I: 80747 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 80759 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 80775 [EM]<<< [E:31842r S:62771 M:123010893 (Ack:139499416)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 80795 [EM]??1 [E:31842r S:62771 M:123010893] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2467ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 80817 [EM]<<< [E:22474i S:62771 M:123010894] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:95)
I: 80835 [EM]??1 [E:22474i S:62771 M:123010894] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2669ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 80852 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 80868 [EM]>>> [E:31842r S:62771 M:139499417 (Ack:123010893)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 80884 [EM]>>> [E:22474i S:62771 M:139499418 (Ack:123010894)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 80899 [IM]Received status response, status is 0x00
I: 80905 [EM]<<< [E:22474i S:62771 M:123010895 (Ack:139499418)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 80930 [EM]<<< [E:22475i S:62771 M:123010896] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:70)
I: 80948 [EM]??1 [E:22475i S:62771 M:123010896] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2413ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 80966 [EM]>>> [E:22475i S:62771 M:139499419 (Ack:123010896)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 80980 [IM]Received status response, status is 0x00
I: 80986 [EM]<<< [E:22475i S:62771 M:123010897 (Ack:139499419)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 82077 [EM]>>> [E:31843r S:62771 M:139499420] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 82092 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 82097 [EM]<<< [E:31843r S:62771 M:123010898 (Ack:139499420)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 82117 [EM]??1 [E:31843r S:62771 M:123010898] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2600ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 82134 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 82149 [ZCL]Setting on/off to OFF due to level change
I: 82154 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 82161 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 82172 [ZCL]Off completed. reset OnTime to  0
I: 82177 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 82184 [EM]>>> [E:31843r S:62771 M:139499421 (Ack:123010898)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 82205 [EM]<<< [E:22476i S:62771 M:123010899] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:95)
I: 82223 [EM]??1 [E:22476i S:62771 M:123010899] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2585ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 82240 [EM]>>> [E:22476i S:62771 M:139499422 (Ack:123010899)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 82255 [IM]Received status response, status is 0x00
I: 82260 [EM]<<< [E:22476i S:62771 M:123010900 (Ack:139499422)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 83705 [EM]>>> [E:31844r S:62771 M:139499423] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 83720 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 83724 [ZCL]On Command - OffWaitTime :  0
I: 83728 [ZCL]On/Toggle Command - Stop Timer
I: 83735 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 83746 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 83753 [EM]<<< [E:31844r S:62771 M:123010901 (Ack:139499423)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 83773 [EM]??1 [E:31844r S:62771 M:123010901] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2725ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 83794 [EM]<<< [E:22477i S:62771 M:123010902] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:69)
I: 83812 [EM]??1 [E:22477i S:62771 M:123010902] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2493ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 83828 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 83845 [EM]>>> [E:31844r S:62771 M:139499424 (Ack:123010901)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 83862 [EM]>>> [E:22477i S:62771 M:139499425 (Ack:123010902)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 83877 [IM]Received status response, status is 0x00
I: 83882 [EM]<<< [E:22477i S:62771 M:123010903 (Ack:139499425)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 83907 [EM]<<< [E:22478i S:62771 M:123010904] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:70)
I: 83925 [EM]??1 [E:22478i S:62771 M:123010904] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2332ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 83942 [EM]>>> [E:22478i S:62771 M:139499426 (Ack:123010904)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 83957 [IM]Received status response, status is 0x00
I: 83963 [EM]<<< [E:22478i S:62771 M:123010905 (Ack:139499426)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 85072 [EM]>>> [E:31845r S:62771 M:139499427] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 85086 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 85092 [EM]<<< [E:31845r S:62771 M:123010906 (Ack:139499427)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 85112 [EM]??1 [E:31845r S:62771 M:123010906] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2635ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 85128 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 85144 [ZCL]Setting on/off to OFF due to level change
I: 85149 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 85155 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 85167 [ZCL]Off completed. reset OnTime to  0
I: 85171 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 85178 [EM]>>> [E:31845r S:62771 M:139499428 (Ack:123010906)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 85200 [EM]<<< [E:22479i S:62771 M:123010907] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:95)
I: 85217 [EM]??1 [E:22479i S:62771 M:123010907] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2663ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 85234 [EM]>>> [E:22479i S:62771 M:139499429 (Ack:123010907)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 85249 [IM]Received status response, status is 0x00
I: 85255 [EM]<<< [E:22479i S:62771 M:123010908 (Ack:139499429)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
E: 93528 [SWU]No suitable OTA Provider candidate found
I: 93533 [SWU]No provider available
I: 122873 [EM]>>> [E:31846r S:62771 M:139499430] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 122888 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 122892 [ZCL]On Command - OffWaitTime :  0
I: 122896 [ZCL]On/Toggle Command - Stop Timer
I: 122902 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 122914 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 122921 [EM]<<< [E:31846r S:62771 M:123010909 (Ack:139499430)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 122941 [EM]??1 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2463ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 122960 [EM]<<< [E:22480i S:62771 M:123010910] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:69)
I: 122977 [EM]??1 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2736ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 122992 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 125404 [EM]<<1 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022
I: 125413 [EM]??2 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2415ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 125713 [EM]<<1 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022
I: 125722 [EM]??2 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2579ms from now [State:Idle II:2000 AI:2000 AT:2000]
D: 125999 [IN]Received a duplicate message with MessageCounter:139499430 on exchange 31846r
I: 126007 [EM]>>> [E:31846r S:62771 M:139499430] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 126022 [EM]<<< [E:31846r S:62771 M:123010911 (Ack:139499430)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 127828 [EM]<<2 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022
I: 127837 [EM]??3 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 4229ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 128301 [EM]<<2 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022
I: 128310 [EM]??3 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 3923ms from now [State:Idle II:2000 AI:2000 AT:2000]
D: 129321 [IN]Received a duplicate message with MessageCounter:139499430 on exchange 31846r
I: 129331 [EM]>>> [E:31846r S:62771 M:139499430] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000737613D4 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 129346 [EM]<<< [E:31846r S:62771 M:123010912 (Ack:139499430)] (S) Msg TX from 00000000737613D4 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 132067 [EM]<<3 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022
I: 132075 [EM]??4 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 5667ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 132234 [EM]<<3 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022
I: 132242 [EM]??4 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 6470ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 137742 [EM]<<4 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022
I: 137751 [EM]??5 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 11180ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 138712 [EM]<<4 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022
I: 138721 [EM]??5 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 10036ms from now [State:Idle II:2000 AI:2000 AT:2000]
E: 148758 [EM]<<5 [E:22480i S:62771 M:123010910] (S) Msg Retransmission to 1:00000000BCDA9022 failure (max retries:4)
E: 148931 [EM]<<5 [E:31846r S:62771 M:123010909] (S) Msg Retransmission to 1:00000000BCDA9022 failure (max retries:4)
D: 148942 [IN]SecureSession[0x200100d0]: MarkAsDefunct Type:2 LSID:62771
I: 148948 [SC]SecureSession[0x200100d0, LSID:62771]: State change 'kActive' --> 'kDefunct'
D: 167236 [IN]SecureSession[0x200100d0]: MarkAsDefunct Type:2 LSID:62771
E: 167243 [DMG]Time out! failed to receive status response from Exchange: 22480i
I: 167250 [DMG]Subscription id 0xb8450265 from node <00000000BCDA9022, 1> torn down
I: 167258 [IM]Schedule subscription resumption when failing to establish session, Retries: 1
D: 187257 [DIS]OperationalSessionSetup[1:00000000BCDA9022]: State change 1 --> 2
I: 187265 [DIS]Lookup started for CCC10070EA402D1F-00000000BCDA9022
I: 187464 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000BCDA9022 after 200 ms
E: 218266 [DIS]Timeout waiting for mDNS resolution.
I: 232264 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000BCDA9022 after 45000 ms
E: 232272 [DIS]OperationalSessionSetup[1:00000000BCDA9022]: operational discovery failed: 32
E: 232280 [DMG]Failed to establish CASE for subscription-resumption with error '32'
I: 232288 [IM]Schedule subscription resumption when failing to establish session, Retries: 2

[ncohen]

Hi Syed,

Further testing with CONFIG_NRF_WIFI_LOW_POWER=n reveals the issue is more fundamental than initially thought.

Summary of findings:

After extended testing, both CASE sessions fail — the entire WiFi interface stops delivering packets regardless of IPv6 address type:

1. Apple TV session on link-local (fe80::1072:bae6:ad17:c34e) — fails at t=273s
2. Subscription resumption attempt on ULA (fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755) — also fails at t=313s

Detailed timeline:

• t=240–245s: Both sessions active and healthy. Apple TV getting instant ACKs (~330-400ms RTT), subscription data flowing normally
• t=243s: Device resumes subscription to HomePod — HomePod responds with status 0x7d (subscription invalid, torn down gracefully — this is expected after earlier defunct)
• t=273s: Device sends toggle response to Apple TV — no ACK received
• t=273–277s: Retransmissions 1→5 to Apple TV (link-local) — all fail
• t=277s: Apple TV session goes defunct
• t=313s: Subscription resumption attempted on Apple TV's ULA address — also no response
• t=313–320s: Retransmissions 1→5 on ULA — all fail
• t=337s: All sessions defunct — complete "No Response"

Conclusions:

Test	Result
Mobile hotspot instead of router	Same failure
CONFIG_NRF_WIFI_LOW_POWER=n	Same failure
Link-local only?	No — ULA also fails
WiFi radio issue?	Yes — all traffic stops simultaneously

The nRF7002 WiFi interface periodically stops delivering packets entirely. The behavior is:

• Works perfectly for 30–120 seconds (fast ACKs, no retransmissions)
• Abruptly stops — all outbound packets are dropped regardless of destination address
• The device does not recover the existing sessions (they go defunct)
• Eventually the device may re-establish connectivity (we observed it "working again" briefly before failing once more)

This appears to be a nRF7002 WiFi driver or firmware issue where the radio silently stops transmitting. The Matter stack is functioning correctly (it retransmits, escalates timeouts, and properly marks sessions as defunct). The problem is below the IP layer.

Questions:

1. Are there any known issues with nRF7002 firmware stability on NCS v3.3.4?
2. Is there a way to enable WiFi driver debug logging to see what happens at the radio level when packets stop being delivered?
3. Could this be related to the nRF7002 firmware watchdog or a DMA/QSPI issue between the nRF54LM20 and nRF7002?

Build: unmodified nrf/samples/matter/light_bulb, NCS v3.3.4, CONFIG_NRF_WIFI_LOW_POWER=n, nRF54LM20 DK + nRF7002 EB II.

After the device goes "No Response", pressing the DK reset button immediately recovers full functionality. The device then works perfectly with rapid consecutive toggles (20+ commands in 100 seconds, zero failures, ~350ms RTT consistently). This confirms the nRF7002 RPU enters a bad state and requires hardware reinitialization to recover — matching KRKNWK-19806.

After reset, the device remains stable for approximately 2-3 minutes of active use, then the RPU hangs again and the cycle repeats. The failure is fully reproducible: reset → works → fails after a few minutes → reset → works again.

Thanks,

Netanel

4)
I: 128292 [EM]<<< [E:11579i S:27419 M:65452698] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:95)
I: 128311 [EM]??1 [E:11579i S:27419 M:65452698] (S) Msg Retransmission to 1:00000000086809DB scheduled for 410ms from now [State:Active II:500 AI:300 AT:4000]
I: 128327 [EM]>>> [E:56302r S:27419 M:204082489] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 128343 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1 null 0 0
I: 128350 [EM]<<< [E:56302r S:27419 M:65452699 (Ack:204082489)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 128371 [EM]??1 [E:56302r S:27419 M:65452699] (S) Msg Retransmission to 1:00000000086809DB scheduled for 345ms from now [State:Active II:500 AI:300 AT:4000]
I: 128388 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 128394 [ZCL]Setting on/off to OFF due to level change
I: 128399 [ZCL]Endpoint 1 On/off already set to new value
I: 128405 [EM]>>> [E:11579i S:27419 M:204082490 (Ack:65452698)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 128420 [IM]Received status response, status is 0x00
I: 128426 [EM]<<< [E:11579i S:27419 M:65452700 (Ack:204082490)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 128448 [EM]>>> [E:56302r S:27419 M:204082491 (Ack:65452699)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 130536 [EM]>>> [E:56303r S:27419 M:204082492] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 130551 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1 null 0 0
I: 130557 [ZCL]Setting on/off to OFF due to level change
I: 130562 [ZCL]Endpoint 1 On/off already set to new value
I: 130568 [EM]<<< [E:56303r S:27419 M:65452701 (Ack:204082492)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 130590 [EM]??1 [E:56303r S:27419 M:65452701] (S) Msg Retransmission to 1:00000000086809DB scheduled for 332ms from now [State:Active II:500 AI:300 AT:4000]
I: 130636 [EM]>>> [E:56303r S:27419 M:204082493 (Ack:65452701)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 130782 [EM]>>> [E:56304r S:27419 M:204082494] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 130797 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 130801 [ZCL]On Command - OffWaitTime :  0
I: 130805 [ZCL]On/Toggle Command - Stop Timer
I: 130811 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 130824 [EM]<<< [E:56304r S:27419 M:65452702 (Ack:204082494)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 130845 [EM]??1 [E:56304r S:27419 M:65452702] (S) Msg Retransmission to 1:00000000086809DB scheduled for 401ms from now [State:Active II:500 AI:300 AT:4000]
I: 130866 [EM]<<< [E:11580i S:27419 M:65452703] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:69)
I: 130885 [EM]??1 [E:11580i S:27419 M:65452703] (S) Msg Retransmission to 1:00000000086809DB scheduled for 347ms from now [State:Active II:500 AI:300 AT:4000]
I: 130905 [EM]>>> [E:56304r S:27419 M:204082495 (Ack:65452702)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 130922 [EM]>>> [E:56305r S:27419 M:204082496] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 130937 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF e7 null 0 0
I: 130943 [ZCL]Setting on/off to ON due to level change
I: 130948 [ZCL]Endpoint 1 On/off already set to new value
I: 130954 [EM]<<< [E:56305r S:27419 M:65452704 (Ack:204082496)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 130975 [EM]??1 [E:56305r S:27419 M:65452704] (S) Msg Retransmission to 1:00000000086809DB scheduled for 355ms from now [State:Active II:500 AI:300 AT:4000]
I: 130992 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 231
I: Level Action has been initiated
I: Setting brightness level to 231
I: Level Action has been completed
I: 131007 [ZCL]Setting on/off to ON due to level change
I: 131012 [ZCL]Endpoint 1 On/off already set to new value
I: 131018 [EM]>>> [E:11580i S:27419 M:204082497 (Ack:65452703)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 131033 [IM]Received status response, status is 0x00
I: 131039 [EM]<<< [E:11580i S:27419 M:65452705 (Ack:204082497)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 131066 [EM]<<< [E:11581i S:27419 M:65452706] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 131087 [EM]??1 [E:11581i S:27419 M:65452706] (S) Msg Retransmission to 1:00000000086809DB scheduled for 353ms from now [State:Active II:500 AI:300 AT:4000]
I: 131104 [EM]>>> [E:56305r S:27419 M:204082498 (Ack:65452704)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 131120 [EM]>>> [E:56306r S:27419 M:204082499] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 131135 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 131141 [ZCL]Setting on/off to ON due to level change
I: 131146 [ZCL]Endpoint 1 On/off already set to new value
I: 131153 [EM]<<< [E:56306r S:27419 M:65452707 (Ack:204082499)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 131174 [EM]??1 [E:56306r S:27419 M:65452707] (S) Msg Retransmission to 1:00000000086809DB scheduled for 382ms from now [State:Active II:500 AI:300 AT:4000]
I: 131189 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 131205 [ZCL]Setting on/off to ON due to level change
I: 131210 [ZCL]Endpoint 1 On/off already set to new value
I: 131216 [EM]>>> [E:11581i S:27419 M:204082500 (Ack:65452706)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 131231 [IM]Received status response, status is 0x00
I: 131236 [EM]<<< [E:11581i S:27419 M:65452708 (Ack:204082500)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 131263 [EM]<<< [E:11582i S:27419 M:65452709] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 131282 [EM]??1 [E:11582i S:27419 M:65452709] (S) Msg Retransmission to 1:00000000086809DB scheduled for 403ms from now [State:Active II:500 AI:300 AT:4000]
I: 131307 [EM]>>> [E:56306r S:27419 M:204082501 (Ack:65452707)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 131325 [EM]>>> [E:11582i S:27419 M:204082502 (Ack:65452709)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 131340 [IM]Received status response, status is 0x00
I: 131346 [EM]<<< [E:11582i S:27419 M:65452710 (Ack:204082502)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 134520 [EM]>>> [E:56307r S:27419 M:204082503] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 134535 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF f1 null 0 0
I: 134542 [EM]<<< [E:56307r S:27419 M:65452711 (Ack:204082503)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 134563 [EM]??1 [E:56307r S:27419 M:65452711] (S) Msg Retransmission to 1:00000000086809DB scheduled for 332ms from now [State:Active II:500 AI:300 AT:4000]
I: 134579 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 241
I: Level Action has been initiated
I: Setting brightness level to 241
I: Level Action has been completed
I: 134595 [ZCL]Setting on/off to ON due to level change
I: 134600 [ZCL]Endpoint 1 On/off already set to new value
I: 134611 [EM]<<< [E:11583i S:27419 M:65452712] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 134630 [EM]??1 [E:11583i S:27419 M:65452712] (S) Msg Retransmission to 1:00000000086809DB scheduled for 373ms from now [State:Active II:500 AI:300 AT:4000]
I: 134645 [EM]>>> [E:56307r S:27419 M:204082504 (Ack:65452711)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 134663 [EM]>>> [E:11583i S:27419 M:204082505 (Ack:65452712)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 134681 [IM]Received status response, status is 0x00
I: 134687 [EM]<<< [E:11583i S:27419 M:65452713 (Ack:204082505)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 134713 [EM]>>> [E:56308r S:27419 M:204082506] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 134727 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 134734 [EM]<<< [E:56308r S:27419 M:65452714 (Ack:204082506)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 134755 [EM]??1 [E:56308r S:27419 M:65452714] (S) Msg Retransmission to 1:00000000086809DB scheduled for 408ms from now [State:Active II:500 AI:300 AT:4000]
I: 134773 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 134788 [ZCL]Setting on/off to OFF due to level change
I: 134793 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 134800 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 134811 [ZCL]Off completed. reset OnTime to  0
I: 134816 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 241
I: 134823 [EM]>>> [E:56308r S:27419 M:204082507 (Ack:65452714)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 134844 [EM]<<< [E:11584i S:27419 M:65452715] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:95)
I: 134863 [EM]??1 [E:11584i S:27419 M:65452715] (S) Msg Retransmission to 1:00000000086809DB scheduled for 353ms from now [State:Active II:500 AI:300 AT:4000]
I: 134879 [EM]>>> [E:56309r S:27419 M:204082508] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 134893 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1 null 0 0
I: 134901 [EM]<<< [E:56309r S:27419 M:65452716 (Ack:204082508)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 134922 [EM]??1 [E:56309r S:27419 M:65452716] (S) Msg Retransmission to 1:00000000086809DB scheduled for 330ms from now [State:Active II:500 AI:300 AT:4000]
I: 134937 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 134943 [ZCL]Setting on/off to OFF due to level change
I: 134948 [ZCL]Endpoint 1 On/off already set to new value
I: 134956 [EM]>>> [E:11584i S:27419 M:204082509 (Ack:65452715)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 134971 [IM]Received status response, status is 0x00
I: 134977 [EM]<<< [E:11584i S:27419 M:65452717 (Ack:204082509)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 134999 [EM]>>> [E:56309r S:27419 M:204082510 (Ack:65452716)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 136580 [EM]>>> [E:56310r S:27419 M:204082511] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 136594 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 136599 [ZCL]On Command - OffWaitTime :  0
I: 136603 [ZCL]On/Toggle Command - Stop Timer
I: 136609 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 136622 [EM]<<< [E:56310r S:27419 M:65452718 (Ack:204082511)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 136643 [EM]??1 [E:56310r S:27419 M:65452718] (S) Msg Retransmission to 1:00000000086809DB scheduled for 363ms from now [State:Active II:500 AI:300 AT:4000]
I: 136664 [EM]<<< [E:11585i S:27419 M:65452719] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:69)
I: 136683 [EM]??1 [E:11585i S:27419 M:65452719] (S) Msg Retransmission to 1:00000000086809DB scheduled for 399ms from now [State:Active II:500 AI:300 AT:4000]
I: 136705 [EM]>>> [E:56310r S:27419 M:204082512 (Ack:65452718)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 136722 [EM]>>> [E:56311r S:27419 M:204082513] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 136737 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 6 null 0 0
I: 136743 [ZCL]Setting on/off to ON due to level change
I: 136748 [ZCL]Endpoint 1 On/off already set to new value
I: 136754 [EM]<<< [E:56311r S:27419 M:65452720 (Ack:204082513)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 136775 [EM]??1 [E:56311r S:27419 M:65452720] (S) Msg Retransmission to 1:00000000086809DB scheduled for 374ms from now [State:Active II:500 AI:300 AT:4000]
I: 136790 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 6
I: Level Action has been initiated
I: Setting brightness level to 6
I: Level Action has been completed
I: 136807 [ZCL]Setting on/off to ON due to level change
I: 136812 [ZCL]Endpoint 1 On/off already set to new value
I: 136818 [EM]>>> [E:11585i S:27419 M:204082514 (Ack:65452719)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 136833 [IM]Received status response, status is 0x00
I: 136838 [EM]<<< [E:11585i S:27419 M:65452721 (Ack:204082514)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 136866 [EM]<<< [E:11586i S:27419 M:65452722] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 136885 [EM]??1 [E:11586i S:27419 M:65452722] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 136902 [EM]>>> [E:56311r S:27419 M:204082515 (Ack:65452720)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 136918 [EM]>>> [E:56312r S:27419 M:204082516] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 136935 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 136941 [ZCL]Setting on/off to ON due to level change
I: 136946 [ZCL]Endpoint 1 On/off already set to new value
I: 136952 [EM]<<< [E:56312r S:27419 M:65452723 (Ack:204082516)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 136973 [EM]??1 [E:56312r S:27419 M:65452723] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 136988 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 137004 [ZCL]Setting on/off to ON due to level change
I: 137009 [ZCL]Endpoint 1 On/off already set to new value
I: 137015 [EM]>>> [E:11586i S:27419 M:204082517 (Ack:65452722)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 137030 [IM]Received status response, status is 0x00
I: 137036 [EM]<<< [E:11586i S:27419 M:65452724 (Ack:204082517)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 137064 [EM]<<< [E:11587i S:27419 M:65452725] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 137083 [EM]??1 [E:11587i S:27419 M:65452725] (S) Msg Retransmission to 1:00000000086809DB scheduled for 400ms from now [State:Active II:500 AI:300 AT:4000]
I: 137100 [EM]>>> [E:56312r S:27419 M:204082518 (Ack:65452723)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 137117 [EM]>>> [E:11587i S:27419 M:204082519 (Ack:65452725)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 137132 [IM]Received status response, status is 0x00
I: 137137 [EM]<<< [E:11587i S:27419 M:65452726 (Ack:204082519)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 140065 [EM]>>> [E:56313r S:27419 M:204082520] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 140080 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 99 null 0 0
I: 140087 [EM]<<< [E:56313r S:27419 M:65452727 (Ack:204082520)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 140108 [EM]??1 [E:56313r S:27419 M:65452727] (S) Msg Retransmission to 1:00000000086809DB scheduled for 383ms from now [State:Active II:500 AI:300 AT:4000]
I: 140123 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 153
I: Level Action has been initiated
I: Setting brightness level to 153
I: Level Action has been completed
I: 140139 [ZCL]Setting on/off to ON due to level change
I: 140144 [ZCL]Endpoint 1 On/off already set to new value
I: 140154 [EM]<<< [E:11588i S:27419 M:65452728] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 140173 [EM]??1 [E:11588i S:27419 M:65452728] (S) Msg Retransmission to 1:00000000086809DB scheduled for 388ms from now [State:Active II:500 AI:300 AT:4000]
I: 140195 [EM]>>> [E:56313r S:27419 M:204082521 (Ack:65452727)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 140212 [EM]>>> [E:11588i S:27419 M:204082522 (Ack:65452728)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 140227 [IM]Received status response, status is 0x00
I: 140232 [EM]<<< [E:11588i S:27419 M:65452729 (Ack:204082522)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
D: 141660 [DIS]OperationalSessionSetup[1:00000000BCDA9022]: State change 1 --> 2
I: 141668 [DIS]Lookup started for CCC10070EA402D1F-00000000BCDA9022
I: 141676 [IM]Skip resuming live subscriptionId 2159917505
I: 141867 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000BCDA9022 after 200 ms
I: 143399 [EM]>>> [E:56314r S:27419 M:204082523] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 143414 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF cb null 0 0
I: 143420 [ZCL]Setting on/off to ON due to level change
I: 143425 [ZCL]Endpoint 1 On/off already set to new value
I: 143431 [EM]<<< [E:56314r S:27419 M:65452730 (Ack:204082523)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 143452 [EM]??1 [E:56314r S:27419 M:65452730] (S) Msg Retransmission to 1:00000000086809DB scheduled for 358ms from now [State:Active II:500 AI:300 AT:4000]
I: 143467 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 203
I: Level Action has been initiated
I: Setting brightness level to 203
I: Level Action has been completed
I: 143484 [ZCL]Setting on/off to ON due to level change
I: 143489 [ZCL]Endpoint 1 On/off already set to new value
I: 143500 [EM]<<< [E:11589i S:27419 M:65452731] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 143519 [EM]??1 [E:11589i S:27419 M:65452731] (S) Msg Retransmission to 1:00000000086809DB scheduled for 343ms from now [State:Active II:500 AI:300 AT:4000]
I: 143534 [EM]>>> [E:56314r S:27419 M:204082524 (Ack:65452730)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143553 [EM]>>> [E:56315r S:27419 M:204082525] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 143568 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF dd null 0 0
I: 143574 [ZCL]Setting on/off to ON due to level change
I: 143579 [ZCL]Endpoint 1 On/off already set to new value
I: 143586 [EM]<<< [E:56315r S:27419 M:65452732 (Ack:204082525)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 143607 [EM]??1 [E:56315r S:27419 M:65452732] (S) Msg Retransmission to 1:00000000086809DB scheduled for 383ms from now [State:Active II:500 AI:300 AT:4000]
I: 143623 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 221
I: Level Action has been initiated
I: Setting brightness level to 221
I: Level Action has been completed
I: 143639 [ZCL]Setting on/off to ON due to level change
I: 143644 [ZCL]Endpoint 1 On/off already set to new value
I: 143650 [EM]>>> [E:11589i S:27419 M:204082526 (Ack:65452731)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 143665 [IM]Received status response, status is 0x00
I: 143671 [EM]<<< [E:11589i S:27419 M:65452733 (Ack:204082526)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143698 [EM]<<< [E:11590i S:27419 M:65452734] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 143717 [EM]??1 [E:11590i S:27419 M:65452734] (S) Msg Retransmission to 1:00000000086809DB scheduled for 375ms from now [State:Active II:500 AI:300 AT:4000]
I: 143734 [EM]>>> [E:56315r S:27419 M:204082527 (Ack:65452732)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143751 [EM]>>> [E:11590i S:27419 M:204082528 (Ack:65452734)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 143766 [IM]Received status response, status is 0x00
I: 143772 [EM]<<< [E:11590i S:27419 M:65452735 (Ack:204082528)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143795 [EM]>>> [E:56316r S:27419 M:204082529] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 143810 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 143816 [ZCL]Setting on/off to ON due to level change
I: 143821 [ZCL]Endpoint 1 On/off already set to new value
I: 143827 [EM]<<< [E:56316r S:27419 M:65452736 (Ack:204082529)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 143848 [EM]??1 [E:56316r S:27419 M:65452736] (S) Msg Retransmission to 1:00000000086809DB scheduled for 334ms from now [State:Active II:500 AI:300 AT:4000]
I: 143863 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 143879 [ZCL]Setting on/off to ON due to level change
I: 143884 [ZCL]Endpoint 1 On/off already set to new value
I: 143899 [EM]<<< [E:11591i S:27419 M:65452737] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:70)
I: 143918 [EM]??1 [E:11591i S:27419 M:65452737] (S) Msg Retransmission to 1:00000000086809DB scheduled for 398ms from now [State:Active II:500 AI:300 AT:4000]
I: 143935 [EM]>>> [E:56316r S:27419 M:204082530 (Ack:65452736)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143952 [EM]>>> [E:11591i S:27419 M:204082531 (Ack:65452737)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 143968 [IM]Received status response, status is 0x00
I: 143974 [EM]<<< [E:11591i S:27419 M:65452738 (Ack:204082531)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 143996 [EM]>>> [E:56317r S:27419 M:204082532] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 144012 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 144018 [ZCL]Setting on/off to ON due to level change
I: 144023 [ZCL]Endpoint 1 On/off already set to new value
I: 144029 [EM]<<< [E:56317r S:27419 M:65452739 (Ack:204082532)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 144050 [EM]??1 [E:56317r S:27419 M:65452739] (S) Msg Retransmission to 1:00000000086809DB scheduled for 330ms from now [State:Active II:500 AI:300 AT:4000]
I: 144068 [EM]>>> [E:56317r S:27419 M:204082533 (Ack:65452739)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 159789 [EM]>>> [E:31890r S:0 M:9487168] (U) Msg RX from 0:5C2E322FD610A5C0 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234)
I: 159803 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20012cc0
I: 159810 [EM]<<< [E:31890r S:0 M:219472617 (Ack:9487168)] (U) Msg TX from 0000000000000000 to 0:5C2E322FD610A5C0 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 159830 [SC]Received Sigma1 msg
I: 159837 [EM]<<< [E:31890r S:0 M:219472618 (Ack:9487168)] (U) Msg TX from 0000000000000000 to 0:5C2E322FD610A5C0 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) (B:100)
I: 159857 [EM]??1 [E:31890r S:0 M:219472618] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2291ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 159872 [SC]Sent Sigma2Resume msg
I: 159912 [EM]>>> [E:31890r S:0 M:9487169 (Ack:219472618)] (U) Msg RX from 0:5C2E322FD610A5C0 [0000] to 0000000000000000 --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I: 159927 [SC]Success status report received. Session was established
I: 159965 [SC]SecureSession[0x20010280, LSID:27420]: State change 'kEstablishing' --> 'kActive'
D: 159974 [IN]SecureSession[0x20010280]: Activated - Type:2 LSID:27420
D: 159980 [IN]New secure session activated for device <00000000BCDA9022, 1>, LSID:27420 PSID:45409!
I: 159989 [IN]CASE Session established to peer: <00000000BCDA9022, 1>
D: 159995 [IN]SecureSession[0x20010358]: Allocated Type:2 LSID:27421
I: 160001 [EM]<<< [E:31890r S:0 M:219472619 (Ack:9487169)] (U) Msg TX from 0000000000000000 to 0:5C2E322FD610A5C0 [0000] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 160023 [EM]>>> [E:31891r S:27420 M:184507248] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 160037 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 160043 [EM]<<< [E:31891r S:27420 M:170611239 (Ack:184507248)] (S) Msg TX from 00000000407AC4A6 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 160063 [EM]??1 [E:31891r S:27420 M:170611239] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2626ms from now [State:Active II:2000 AI:2000 AT:2000]
I: 160078 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 160097 [ZCL]Setting on/off to OFF due to level change
I: 160102 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 160108 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 160120 [ZCL]Off completed. reset OnTime to  0
I: 160125 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 160137 [EM]<<< [E:11592i S:27419 M:65452740] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:95)
I: 160155 [EM]??1 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB scheduled for 646ms from now [State:Idle II:500 AI:300 AT:4000]
I: 160170 [EM]>>> [E:31891r S:27420 M:184507249 (Ack:170611239)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 160801 [EM]<<1 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB
I: 160810 [EM]??2 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB scheduled for 624ms from now [State:Idle II:500 AI:300 AT:4000]
I: 161434 [EM]<<2 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB
I: 161443 [EM]??3 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1002ms from now [State:Idle II:500 AI:300 AT:4000]
I: 162445 [EM]<<3 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB
I: 162454 [EM]??4 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1629ms from now [State:Idle II:500 AI:300 AT:4000]
I: 164083 [EM]<<4 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB
I: 164092 [EM]??5 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB scheduled for 2496ms from now [State:Idle II:500 AI:300 AT:4000]
E: 166588 [EM]<<5 [E:11592i S:27419 M:65452740] (S) Msg Retransmission to 1:00000000086809DB failure (max retries:4)
E: 172667 [DIS]Timeout waiting for mDNS resolution.
D: 183264 [IN]SecureSession[0x2000fff8]: MarkAsDefunct Type:2 LSID:27419
I: 183270 [SC]SecureSession[0x2000fff8, LSID:27419]: State change 'kActive' --> 'kDefunct'
E: 183278 [DMG]Time out! failed to receive status response from Exchange: 11592i
I: 183285 [DMG]Subscription id 0x80bdb9c1 from node <00000000086809DB, 1> torn down
I: 183293 [IM]Schedule subscription resumption when failing to establish session, Retries: 2
I: 186667 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000BCDA9022 after 45000 ms
E: 186676 [DIS]OperationalSessionSetup[1:00000000BCDA9022]: operational discovery failed: 32
E: 186684 [DMG]Failed to establish CASE for subscription-resumption with error '32'
I: 188244 [SC]SecureSession[0x2000fff8, LSID:27419]: State change 'kDefunct' --> 'kActive'
I: 188252 [EM]>>> [E:56318r S:27419 M:204082534] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 188267 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 66 null 0 0
I: 188274 [EM]<<< [E:56318r S:27419 M:65452741 (Ack:204082534)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 188295 [EM]??1 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB scheduled for 410ms from now [State:Active II:500 AI:300 AT:4000]
I: 188311 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 102
I: 188317 [ZCL]Setting on/off to ON due to level change
I: 188322 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 188326 [ZCL]On Command - OffWaitTime :  0
I: 188330 [ZCL]On/Toggle Command - Stop Timer
I: 188336 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 188706 [EM]<<1 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB
I: 188714 [EM]??2 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB scheduled for 367ms from now [State:Active II:500 AI:300 AT:4000]
I: 189081 [EM]<<2 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB
I: 189090 [EM]??3 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB scheduled for 634ms from now [State:Active II:500 AI:300 AT:4000]
D: 189575 [IN]Received a duplicate message with MessageCounter:204082534 on exchange 56318r
I: 189583 [EM]>>> [E:56318r S:27419 M:204082534] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 189598 [EM]<<< [E:56318r S:27419 M:65452742 (Ack:204082534)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 189724 [EM]<<3 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB
I: 189732 [EM]??4 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB scheduled for 894ms from now [State:Active II:500 AI:300 AT:4000]
I: 190627 [EM]<<4 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB
I: 190635 [EM]??5 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1556ms from now [State:Active II:500 AI:300 AT:4000]
D: 190736 [IN]Received a duplicate message with MessageCounter:204082534 on exchange 56318r
I: 190744 [EM]>>> [E:56318r S:27419 M:204082534] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 190759 [EM]<<< [E:56318r S:27419 M:65452743 (Ack:204082534)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
E: 192191 [EM]<<5 [E:56318r S:27419 M:65452741] (S) Msg Retransmission to 1:00000000086809DB failure (max retries:4)
D: 192201 [IN]SecureSession[0x2000fff8]: MarkAsDefunct Type:2 LSID:27419
I: 192208 [SC]SecureSession[0x2000fff8, LSID:27419]: State change 'kActive' --> 'kDefunct'
D: 192800 [IN]Received a duplicate message with MessageCounter:204082534 on exchange 56318r
I: 192808 [SC]SecureSession[0x2000fff8, LSID:27419]: State change 'kDefunct' --> 'kActive'
I: 192816 [EM]>>> [E:56318r S:27419 M:204082534] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 192831 [EM]<<< [E:56318r S:27419 M:65452744 (Ack:204082534)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
D: 196290 [IN]Received a duplicate message with MessageCounter:204082534 on exchange 56318r
I: 196298 [EM]>>> [E:56318r S:27419 M:204082534] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 196313 [EM]<<< [E:56318r S:27419 M:65452745 (Ack:204082534)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 208873 [EM]>>> [E:56319r S:0 M:78565332] (U) Msg RX from 0:35DCBCE7A815924B [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234)
I: 208886 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20012cc0
I: 208897 [EM]<<< [E:56319r S:0 M:219472620 (Ack:78565332)] (U) Msg TX from 0000000000000000 to 0:35DCBCE7A815924B [0000] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 208917 [SC]Received Sigma1 msg
I: 208924 [EM]<<< [E:56319r S:0 M:219472621 (Ack:78565332)] (U) Msg TX from 0000000000000000 to 0:35DCBCE7A815924B [0000] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) (B:100)
I: 208944 [EM]??1 [E:56319r S:0 M:219472621] (U) Msg Retransmission to 0:0000000000000000 scheduled for 409ms from now [State:Active II:500 AI:300 AT:4000]
I: 208958 [SC]Sent Sigma2Resume msg
I: 209118 [EM]>>> [E:56319r S:0 M:78565333 (Ack:219472621)] (U) Msg RX from 0:35DCBCE7A815924B [0000] to 0000000000000000 --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
I: 209133 [SC]Success status report received. Session was established
I: 209170 [SC]SecureSession[0x20010358, LSID:27421]: State change 'kEstablishing' --> 'kActive'
D: 209179 [IN]SecureSession[0x20010358]: Activated - Type:2 LSID:27421
D: 209185 [IN]New secure session activated for device <00000000086809DB, 1>, LSID:27421 PSID:37729!
I: 209194 [IN]CASE Session established to peer: <00000000086809DB, 1>
D: 209200 [IN]SecureSession[0x20010430]: Allocated Type:2 LSID:27422
I: 209206 [EM]<<< [E:56319r S:0 M:219472622 (Ack:78565333)] (U) Msg TX from 0000000000000000 to 0:35DCBCE7A815924B [0000] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
I: 209228 [EM]>>> [E:56320r S:27421 M:48796888] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209243 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 6e null 0 0
I: 209249 [ZCL]Setting on/off to ON due to level change
I: 209254 [ZCL]Endpoint 1 On/off already set to new value
I: 209260 [EM]<<< [E:56320r S:27421 M:63459747 (Ack:48796888)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209280 [EM]??1 [E:56320r S:27421 M:63459747] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 209298 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 110
I: Level Action has been initiated
I: Setting brightness level to 110
I: Level Action has been completed
I: 209314 [ZCL]Setting on/off to ON due to level change
I: 209319 [ZCL]Endpoint 1 On/off already set to new value
I: 209324 [EM]>>> [E:56320r S:27421 M:48796889 (Ack:63459747)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209341 [EM]>>> [E:56321r S:27421 M:48796890] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209356 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 209362 [ZCL]Setting on/off to ON due to level change
I: 209367 [ZCL]Endpoint 1 On/off already set to new value
I: 209374 [EM]<<< [E:56321r S:27421 M:63459748 (Ack:48796890)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209393 [EM]??1 [E:56321r S:27421 M:63459748] (S) Msg Retransmission to 1:00000000086809DB scheduled for 391ms from now [State:Active II:500 AI:300 AT:4000]
I: 209411 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 209426 [ZCL]Setting on/off to ON due to level change
I: 209431 [ZCL]Endpoint 1 On/off already set to new value
I: 209437 [EM]>>> [E:56321r S:27421 M:48796891 (Ack:63459748)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209454 [EM]>>> [E:56322r S:27421 M:48796892] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 209468 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 209474 [EM]<<< [E:56322r S:27421 M:63459749 (Ack:48796892)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209494 [EM]??1 [E:56322r S:27421 M:63459749] (S) Msg Retransmission to 1:00000000086809DB scheduled for 341ms from now [State:Active II:500 AI:300 AT:4000]
I: 209511 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 209527 [ZCL]Setting on/off to OFF due to level change
I: 209532 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 209538 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 209552 [ZCL]Off completed. reset OnTime to  0
I: 209556 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 209563 [EM]>>> [E:56322r S:27421 M:48796893 (Ack:63459749)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209580 [EM]>>> [E:56323r S:27421 M:48796894] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209595 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 34 null 0 0
I: 209602 [EM]<<< [E:56323r S:27421 M:63459750 (Ack:48796894)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209622 [EM]??1 [E:56323r S:27421 M:63459750] (S) Msg Retransmission to 1:00000000086809DB scheduled for 402ms from now [State:Active II:500 AI:300 AT:4000]
I: 209640 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 52
I: 209646 [ZCL]Setting on/off to ON due to level change
I: 209651 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 209655 [ZCL]On Command - OffWaitTime :  0
I: 209659 [ZCL]On/Toggle Command - Stop Timer
I: 209666 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 209678 [EM]>>> [E:56323r S:27421 M:48796895 (Ack:63459750)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209694 [EM]>>> [E:56324r S:27421 M:48796896] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209709 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 45 null 0 0
I: 209715 [ZCL]Setting on/off to ON due to level change
I: 209720 [ZCL]Endpoint 1 On/off already set to new value
I: 209727 [EM]<<< [E:56324r S:27421 M:63459751 (Ack:48796896)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209747 [EM]??1 [E:56324r S:27421 M:63459751] (S) Msg Retransmission to 1:00000000086809DB scheduled for 387ms from now [State:Active II:500 AI:300 AT:4000]
I: 209761 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 69
I: Level Action has been initiated
I: Setting brightness level to 69
I: Level Action has been completed
I: 209778 [ZCL]Setting on/off to ON due to level change
I: 209783 [ZCL]Endpoint 1 On/off already set to new value
I: 209791 [EM]>>> [E:56324r S:27421 M:48796897 (Ack:63459751)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209808 [EM]>>> [E:56325r S:27421 M:48796898] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209822 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 209828 [ZCL]Setting on/off to ON due to level change
I: 209833 [ZCL]Endpoint 1 On/off already set to new value
I: 209840 [EM]<<< [E:56325r S:27421 M:63459752 (Ack:48796898)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 209860 [EM]??1 [E:56325r S:27421 M:63459752] (S) Msg Retransmission to 1:00000000086809DB scheduled for 409ms from now [State:Active II:500 AI:300 AT:4000]
I: 209874 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 209890 [ZCL]Setting on/off to ON due to level change
I: 209895 [ZCL]Endpoint 1 On/off already set to new value
I: 209947 [EM]>>> [E:56325r S:27421 M:48796899 (Ack:63459752)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 209964 [EM]>>> [E:56326r S:27421 M:48796900] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 209979 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fb null 0 0
I: 209986 [EM]<<< [E:56326r S:27421 M:63459753 (Ack:48796900)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210006 [EM]??1 [E:56326r S:27421 M:63459753] (S) Msg Retransmission to 1:00000000086809DB scheduled for 341ms from now [State:Active II:500 AI:300 AT:4000]
I: 210024 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: Level Action has been initiated
I: Setting brightness level to 251
I: Level Action has been completed
I: 210039 [ZCL]Setting on/off to ON due to level change
I: 210044 [ZCL]Endpoint 1 On/off already set to new value
I: 210050 [EM]>>> [E:56326r S:27421 M:48796901 (Ack:63459753)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210067 [EM]>>> [E:56327r S:27421 M:48796902] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 210082 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 210088 [EM]<<< [E:56327r S:27421 M:63459754 (Ack:48796902)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210107 [EM]??1 [E:56327r S:27421 M:63459754] (S) Msg Retransmission to 1:00000000086809DB scheduled for 397ms from now [State:Active II:500 AI:300 AT:4000]
I: 210125 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 210140 [ZCL]Setting on/off to OFF due to level change
I: 210145 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 210152 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 210164 [ZCL]Off completed. reset OnTime to  0
I: 210168 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: 210175 [EM]>>> [E:56327r S:27421 M:48796903 (Ack:63459754)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210192 [EM]>>> [E:56328r S:27421 M:48796904] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 210206 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 210211 [ZCL]On Command - OffWaitTime :  0
I: 210215 [ZCL]On/Toggle Command - Stop Timer
I: 210221 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 210232 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 210240 [EM]<<< [E:56328r S:27421 M:63459755 (Ack:48796904)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210260 [EM]??1 [E:56328r S:27421 M:63459755] (S) Msg Retransmission to 1:00000000086809DB scheduled for 403ms from now [State:Active II:500 AI:300 AT:4000]
I: 210278 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: Level Action has been initiated
I: Setting brightness level to 251
I: Level Action has been completed
I: 210294 [EM]>>> [E:56328r S:27421 M:48796905 (Ack:63459755)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210311 [EM]>>> [E:56329r S:27421 M:48796906] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 210325 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF f4 null 0 0
I: 210333 [EM]<<< [E:56329r S:27421 M:63459756 (Ack:48796906)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210353 [EM]??1 [E:56329r S:27421 M:63459756] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 210367 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 244
I: Level Action has been initiated
I: Setting brightness level to 244
I: Level Action has been completed
I: 210383 [ZCL]Setting on/off to ON due to level change
I: 210388 [ZCL]Endpoint 1 On/off already set to new value
I: 210442 [EM]>>> [E:56329r S:27421 M:48796907 (Ack:63459756)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210459 [EM]>>> [E:56330r S:27421 M:48796908] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 210474 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 210480 [ZCL]Setting on/off to ON due to level change
I: 210485 [ZCL]Endpoint 1 On/off already set to new value
I: 210491 [EM]<<< [E:56330r S:27421 M:63459757 (Ack:48796908)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210511 [EM]??1 [E:56330r S:27421 M:63459757] (S) Msg Retransmission to 1:00000000086809DB scheduled for 366ms from now [State:Active II:500 AI:300 AT:4000]
I: 210531 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 210546 [ZCL]Setting on/off to ON due to level change
I: 210551 [ZCL]Endpoint 1 On/off already set to new value
I: 210557 [EM]>>> [E:56330r S:27421 M:48796909 (Ack:63459757)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210574 [EM]>>> [E:56331r S:27421 M:48796910] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 210589 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fb null 0 0
I: 210596 [EM]<<< [E:56331r S:27421 M:63459758 (Ack:48796910)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210616 [EM]??1 [E:56331r S:27421 M:63459758] (S) Msg Retransmission to 1:00000000086809DB scheduled for 351ms from now [State:Active II:500 AI:300 AT:4000]
I: 210634 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: Level Action has been initiated
I: Setting brightness level to 251
I: Level Action has been completed
I: 210649 [ZCL]Setting on/off to ON due to level change
I: 210654 [ZCL]Endpoint 1 On/off already set to new value
I: 210660 [EM]>>> [E:56331r S:27421 M:48796911 (Ack:63459758)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210677 [EM]>>> [E:56332r S:27421 M:48796912] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 210691 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 210697 [EM]<<< [E:56332r S:27421 M:63459759 (Ack:48796912)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210717 [EM]??1 [E:56332r S:27421 M:63459759] (S) Msg Retransmission to 1:00000000086809DB scheduled for 409ms from now [State:Active II:500 AI:300 AT:4000]
I: 210732 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 210750 [ZCL]Setting on/off to OFF due to level change
I: 210755 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 210761 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 210773 [ZCL]Off completed. reset OnTime to  0
I: 210777 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: 210784 [EM]>>> [E:56332r S:27421 M:48796913 (Ack:63459759)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210801 [EM]>>> [E:56333r S:27421 M:48796914] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 210815 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 210820 [ZCL]On Command - OffWaitTime :  0
I: 210824 [ZCL]On/Toggle Command - Stop Timer
I: 210830 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 210842 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 210849 [EM]<<< [E:56333r S:27421 M:63459760 (Ack:48796914)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 210869 [EM]??1 [E:56333r S:27421 M:63459760] (S) Msg Retransmission to 1:00000000086809DB scheduled for 394ms from now [State:Active II:500 AI:300 AT:4000]
I: 210883 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 251
I: Level Action has been initiated
I: Setting brightness level to 251
I: Level Action has been completed
I: 210974 [EM]>>> [E:56333r S:27421 M:48796915 (Ack:63459760)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 210991 [EM]>>> [E:56334r S:27421 M:48796916] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 211005 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 211012 [ZCL]Setting on/off to ON due to level change
I: 211017 [ZCL]Endpoint 1 On/off already set to new value
I: 211023 [EM]<<< [E:56334r S:27421 M:63459761 (Ack:48796916)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 211043 [EM]??1 [E:56334r S:27421 M:63459761] (S) Msg Retransmission to 1:00000000086809DB scheduled for 393ms from now [State:Active II:500 AI:300 AT:4000]
I: 211060 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 211076 [ZCL]Setting on/off to ON due to level change
I: 211081 [ZCL]Endpoint 1 On/off already set to new value
I: 211087 [EM]>>> [E:56334r S:27421 M:48796917 (Ack:63459761)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 211103 [EM]>>> [E:56335r S:27421 M:48796918] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 211118 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1 null 0 0
I: 211126 [EM]<<< [E:56335r S:27421 M:63459762 (Ack:48796918)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 211146 [EM]??1 [E:56335r S:27421 M:63459762] (S) Msg Retransmission to 1:00000000086809DB scheduled for 380ms from now [State:Active II:500 AI:300 AT:4000]
I: 211160 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 211178 [ZCL]Setting on/off to OFF due to level change
I: 211183 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 211190 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 211201 [ZCL]Off completed. reset OnTime to  0
I: 211206 [EM]>>> [E:56335r S:27421 M:48796919 (Ack:63459762)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 211223 [EM]>>> [E:56336r S:27421 M:48796920] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 211238 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1a null 0 0
I: 211244 [ZCL]Setting on/off to ON due to level change
I: 211249 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 211253 [ZCL]On Command - OffWaitTime :  0
I: 211257 [ZCL]On/Toggle Command - Stop Timer
I: 211263 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 211276 [EM]<<< [E:56336r S:27421 M:63459763 (Ack:48796920)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 211296 [EM]??1 [E:56336r S:27421 M:63459763] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 211314 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 26
I: Level Action has been initiated
I: Setting brightness level to 26
I: Level Action has been completed
I: 211329 [ZCL]Setting on/off to ON due to level change
I: 211334 [ZCL]Endpoint 1 On/off already set to new value
I: 211340 [EM]>>> [E:56336r S:27421 M:48796921 (Ack:63459763)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 211357 [EM]>>> [E:56337r S:27421 M:48796922] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 211372 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 1 null 0 0
I: 211379 [EM]<<< [E:56337r S:27421 M:63459764 (Ack:48796922)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 211399 [EM]??1 [E:56337r S:27421 M:63459764] (S) Msg Retransmission to 1:00000000086809DB scheduled for 335ms from now [State:Active II:500 AI:300 AT:4000]
I: 211414 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 211429 [ZCL]Setting on/off to OFF due to level change
I: 211434 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 211440 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 211452 [ZCL]Off completed. reset OnTime to  0
I: 211525 [EM]>>> [E:56337r S:27421 M:48796923 (Ack:63459764)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 211547 [EM]>>> [E:56338r S:27421 M:48796924] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 211562 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF e null 0 0
I: 211568 [ZCL]Setting on/off to ON due to level change
I: 211573 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 211577 [ZCL]On Command - OffWaitTime :  0
I: 211581 [ZCL]On/Toggle Command - Stop Timer
I: 211587 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 211600 [EM]<<< [E:56338r S:27421 M:63459765 (Ack:48796924)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 211620 [EM]??1 [E:56338r S:27421 M:63459765] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 211636 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 14
I: Level Action has been initiated
I: Setting brightness level to 14
I: Level Action has been completed
I: 211651 [ZCL]Setting on/off to ON due to level change
I: 211656 [ZCL]Endpoint 1 On/off already set to new value
I: 211662 [EM]>>> [E:56338r S:27421 M:48796925 (Ack:63459765)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 213096 [EM]>>> [E:56339r S:27421 M:48796926] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 213111 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 15 null 0 0
I: 213117 [ZCL]Setting on/off to ON due to level change
I: 213122 [ZCL]Endpoint 1 On/off already set to new value
I: 213129 [EM]<<< [E:56339r S:27421 M:63459766 (Ack:48796926)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 213148 [EM]??1 [E:56339r S:27421 M:63459766] (S) Msg Retransmission to 1:00000000086809DB scheduled for 349ms from now [State:Active II:500 AI:300 AT:4000]
I: 213163 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 21
I: Level Action has been initiated
I: Setting brightness level to 21
I: Level Action has been completed
I: 213180 [ZCL]Setting on/off to ON due to level change
I: 213185 [ZCL]Endpoint 1 On/off already set to new value
I: 213191 [EM]>>> [E:56339r S:27421 M:48796927 (Ack:63459766)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 213304 [EM]>>> [E:56340r S:27421 M:48796928] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 213319 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 213325 [ZCL]Setting on/off to ON due to level change
I: 213330 [ZCL]Endpoint 1 On/off already set to new value
I: 213337 [EM]<<< [E:56340r S:27421 M:63459767 (Ack:48796928)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 213356 [EM]??1 [E:56340r S:27421 M:63459767] (S) Msg Retransmission to 1:00000000086809DB scheduled for 335ms from now [State:Active II:500 AI:300 AT:4000]
I: 213373 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 213388 [ZCL]Setting on/off to ON due to level change
I: 213393 [ZCL]Endpoint 1 On/off already set to new value
I: 213399 [EM]>>> [E:56340r S:27421 M:48796929 (Ack:63459767)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 238401 [EM]>>> [E:56341r S:27421 M:48796930] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 238416 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF 66 null 0 0
I: 238423 [EM]<<< [E:56341r S:27421 M:63459768 (Ack:48796930)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 238443 [EM]??1 [E:56341r S:27421 M:63459768] (S) Msg Retransmission to 1:00000000086809DB scheduled for 332ms from now [State:Active II:500 AI:300 AT:4000]
I: 238458 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 102
I: Level Action has been initiated
I: Setting brightness level to 102
I: Level Action has been completed
I: 238475 [ZCL]Setting on/off to ON due to level change
I: 238480 [ZCL]Endpoint 1 On/off already set to new value
I: 238488 [EM]>>> [E:56341r S:27421 M:48796931 (Ack:63459768)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 239306 [EM]>>> [E:56342r S:27421 M:48796932] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 239321 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF cb null 0 0
I: 239327 [ZCL]Setting on/off to ON due to level change
I: 239332 [ZCL]Endpoint 1 On/off already set to new value
I: 239339 [EM]<<< [E:56342r S:27421 M:63459769 (Ack:48796932)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 239358 [EM]??1 [E:56342r S:27421 M:63459769] (S) Msg Retransmission to 1:00000000086809DB scheduled for 391ms from now [State:Active II:500 AI:300 AT:4000]
I: 239375 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 203
I: Level Action has been initiated
I: Setting brightness level to 203
I: Level Action has been completed
I: 239390 [ZCL]Setting on/off to ON due to level change
I: 239395 [ZCL]Endpoint 1 On/off already set to new value
I: 239401 [EM]>>> [E:56342r S:27421 M:48796933 (Ack:63459769)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 240055 [EM]>>> [E:56343r S:27421 M:48796934] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 240069 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF ce null 0 0
I: 240076 [ZCL]Setting on/off to ON due to level change
I: 240080 [ZCL]Endpoint 1 On/off already set to new value
I: 240087 [EM]<<< [E:56343r S:27421 M:63459770 (Ack:48796934)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 240107 [EM]??1 [E:56343r S:27421 M:63459770] (S) Msg Retransmission to 1:00000000086809DB scheduled for 331ms from now [State:Active II:500 AI:300 AT:4000]
I: 240123 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 206
I: Level Action has been initiated
I: Setting brightness level to 206
I: Level Action has been completed
I: 240138 [ZCL]Setting on/off to ON due to level change
I: 240143 [ZCL]Endpoint 1 On/off already set to new value
I: 240150 [EM]>>> [E:56343r S:27421 M:48796935 (Ack:63459770)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 240330 [EM]>>> [E:56344r S:27421 M:48796936] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
I: 240345 [ZCL]RX level-control: MOVE_TO_LEVEL_WITH_ON_OFF fe null 0 0
I: 240351 [ZCL]Setting on/off to ON due to level change
I: 240356 [ZCL]Endpoint 1 On/off already set to new value
I: 240363 [EM]<<< [E:56344r S:27421 M:63459771 (Ack:48796936)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 240382 [EM]??1 [E:56344r S:27421 M:63459771] (S) Msg Retransmission to 1:00000000086809DB scheduled for 383ms from now [State:Active II:500 AI:300 AT:4000]
I: 240399 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 240414 [ZCL]Setting on/off to ON due to level change
I: 240419 [ZCL]Endpoint 1 On/off already set to new value
I: 240425 [EM]>>> [E:56344r S:27421 M:48796937 (Ack:63459771)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 242175 [EM]>>> [E:56345r S:27421 M:48796938] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 242190 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 242196 [EM]<<< [E:56345r S:27421 M:63459772 (Ack:48796938)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 242215 [EM]??1 [E:56345r S:27421 M:63459772] (S) Msg Retransmission to 1:00000000086809DB scheduled for 348ms from now [State:Active II:500 AI:300 AT:4000]
I: 242232 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 242247 [ZCL]Setting on/off to OFF due to level change
I: 242252 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 242259 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 242270 [ZCL]Off completed. reset OnTime to  0
I: 242275 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 242281 [EM]>>> [E:56345r S:27421 M:48796939 (Ack:63459772)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 243293 [DIS]Found an existing secure session to [1:00000000BCDA9022]!
D: 243300 [DIS]OperationalSessionSetup[1:00000000BCDA9022]: State change 1 --> 5
I: 243307 [DMG]Registered a ReadHandler that will schedule a report between system Timestamp: 0x000000000003B66B and system Timestamp 0x00000000000CDE2B.
I: 243350 [DIS]Found an existing secure session to [1:00000000086809DB]!
D: 243356 [DIS]OperationalSessionSetup[1:00000000086809DB]: State change 1 --> 5
I: 243365 [DMG]Registered a ReadHandler that will schedule a report between system Timestamp: 0x000000000003B6A5 and system Timestamp 0x00000000000CDE65.
I: 243433 [EM]<<< [E:11593i S:27420 M:170611240] (S) Msg TX from 00000000407AC4A6 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0001:05 (IM:ReportData) (B:1175)
I: 243450 [EM]??1 [E:11593i S:27420 M:170611240] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2721ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 243484 [EM]<<< [E:11594i S:27421 M:63459773] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1175)
I: 243501 [EM]??1 [E:11594i S:27421 M:63459773] (S) Msg Retransmission to 1:00000000086809DB scheduled for 359ms from now [State:Active II:500 AI:300 AT:4000]
I: 243517 [EM]>>> [E:56346r S:27421 M:48796940] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 243532 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 243536 [ZCL]On Command - OffWaitTime :  0
I: 243542 [ZCL]On/Toggle Command - Stop Timer
I: 243548 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 243560 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 243567 [EM]<<< [E:56346r S:27421 M:63459774 (Ack:48796940)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 243587 [EM]??1 [E:56346r S:27421 M:63459774] (S) Msg Retransmission to 1:00000000086809DB scheduled for 399ms from now [State:Active II:500 AI:300 AT:4000]
I: 243602 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 243620 [EM]>>> [E:11594i S:27421 M:48796941 (Ack:63459773)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 243636 [IM]Received status response, status is 0x00
I: 243689 [EM]<<< [E:11594i S:27421 M:63459775 (Ack:48796941)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1193)
I: 243708 [EM]??1 [E:11594i S:27421 M:63459775] (S) Msg Retransmission to 1:00000000086809DB scheduled for 370ms from now [State:Active II:500 AI:300 AT:4000]
I: 243723 [EM]>>> [E:56346r S:27421 M:48796942 (Ack:63459774)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 243786 [EM]>>> [E:11594i S:27421 M:48796943 (Ack:63459775)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 243801 [IM]Received status response, status is 0x00
I: 243853 [EM]<<< [E:11594i S:27421 M:63459776 (Ack:48796943)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1184)
I: 243872 [EM]??1 [E:11594i S:27421 M:63459776] (S) Msg Retransmission to 1:00000000086809DB scheduled for 353ms from now [State:Active II:500 AI:300 AT:4000]
I: 244015 [EM]>>> [E:11594i S:27421 M:48796944 (Ack:63459776)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244030 [IM]Received status response, status is 0x00
I: 244065 [EM]<<< [E:11594i S:27421 M:63459777 (Ack:48796944)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1207)
I: 244084 [EM]??1 [E:11594i S:27421 M:63459777] (S) Msg Retransmission to 1:00000000086809DB scheduled for 409ms from now [State:Active II:500 AI:300 AT:4000]
I: 244101 [EM]>>> [E:11594i S:27421 M:48796945 (Ack:63459777)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244116 [IM]Received status response, status is 0x00
I: 244150 [EM]<<< [E:11594i S:27421 M:63459778 (Ack:48796945)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1187)
I: 244169 [EM]??1 [E:11594i S:27421 M:63459778] (S) Msg Retransmission to 1:00000000086809DB scheduled for 374ms from now [State:Active II:500 AI:300 AT:4000]
I: 244209 [EM]>>> [E:11594i S:27421 M:48796946 (Ack:63459778)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244224 [IM]Received status response, status is 0x00
I: 244262 [EM]<<< [E:11594i S:27421 M:63459779 (Ack:48796946)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1207)
I: 244281 [EM]??1 [E:11594i S:27421 M:63459779] (S) Msg Retransmission to 1:00000000086809DB scheduled for 355ms from now [State:Active II:500 AI:300 AT:4000]
I: 244327 [EM]>>> [E:11594i S:27421 M:48796947 (Ack:63459779)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244342 [IM]Received status response, status is 0x00
I: 244374 [EM]<<< [E:11594i S:27421 M:63459780 (Ack:48796947)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1202)
I: 244393 [EM]??1 [E:11594i S:27421 M:63459780] (S) Msg Retransmission to 1:00000000086809DB scheduled for 408ms from now [State:Active II:500 AI:300 AT:4000]
I: 244548 [EM]>>> [E:11594i S:27421 M:48796948 (Ack:63459780)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244563 [IM]Received status response, status is 0x00
I: 244590 [EM]<<< [E:11594i S:27421 M:63459781 (Ack:48796948)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1199)
I: 244609 [EM]??1 [E:11594i S:27421 M:63459781] (S) Msg Retransmission to 1:00000000086809DB scheduled for 338ms from now [State:Active II:500 AI:300 AT:4000]
I: 244632 [EM]>>> [E:11594i S:27421 M:48796949 (Ack:63459781)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244647 [IM]Received status response, status is 0x00
I: 244660 [EM]<<< [E:11594i S:27421 M:63459782 (Ack:48796949)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:482)
I: 244679 [EM]??1 [E:11594i S:27421 M:63459782] (S) Msg Retransmission to 1:00000000086809DB scheduled for 332ms from now [State:Active II:500 AI:300 AT:4000]
I: 244709 [EM]>>> [E:11594i S:27421 M:48796950 (Ack:63459782)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244724 [IM]Received status response, status is 0x00
I: 244730 [EM]<<< [E:11594i S:27421 M:63459783 (Ack:48796950)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 244769 [EM]<<< [E:11595i S:27421 M:63459784] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1140)
I: 244787 [EM]??1 [E:11595i S:27421 M:63459784] (S) Msg Retransmission to 1:00000000086809DB scheduled for 349ms from now [State:Active II:500 AI:300 AT:4000]
I: 244804 [EM]>>> [E:11595i S:27421 M:48796951 (Ack:63459784)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244819 [IM]Received status response, status is 0x00
I: 244873 [EM]<<< [E:11595i S:27421 M:63459785 (Ack:48796951)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1193)
I: 244892 [EM]??1 [E:11595i S:27421 M:63459785] (S) Msg Retransmission to 1:00000000086809DB scheduled for 402ms from now [State:Active II:500 AI:300 AT:4000]
I: 244945 [EM]>>> [E:11595i S:27421 M:48796952 (Ack:63459785)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 244960 [IM]Received status response, status is 0x00
I: 245014 [EM]<<< [E:11595i S:27421 M:63459786 (Ack:48796952)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1184)
I: 245032 [EM]??1 [E:11595i S:27421 M:63459786] (S) Msg Retransmission to 1:00000000086809DB scheduled for 332ms from now [State:Active II:500 AI:300 AT:4000]
I: 245054 [EM]>>> [E:11595i S:27421 M:48796953 (Ack:63459786)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245069 [IM]Received status response, status is 0x00
I: 245105 [EM]<<< [E:11595i S:27421 M:63459787 (Ack:48796953)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1207)
I: 245124 [EM]??1 [E:11595i S:27421 M:63459787] (S) Msg Retransmission to 1:00000000086809DB scheduled for 333ms from now [State:Active II:500 AI:300 AT:4000]
I: 245141 [EM]>>> [E:11595i S:27421 M:48796954 (Ack:63459787)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245156 [IM]Received status response, status is 0x00
I: 245192 [EM]<<< [E:11595i S:27421 M:63459788 (Ack:48796954)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1187)
I: 245211 [EM]??1 [E:11595i S:27421 M:63459788] (S) Msg Retransmission to 1:00000000086809DB scheduled for 339ms from now [State:Active II:500 AI:300 AT:4000]
I: 245228 [EM]>>> [E:11595i S:27421 M:48796955 (Ack:63459788)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245243 [IM]Received status response, status is 0x00
I: 245282 [EM]<<< [E:11595i S:27421 M:63459789 (Ack:48796955)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1207)
I: 245301 [EM]??1 [E:11595i S:27421 M:63459789] (S) Msg Retransmission to 1:00000000086809DB scheduled for 368ms from now [State:Active II:500 AI:300 AT:4000]
I: 245326 [EM]>>> [E:11595i S:27421 M:48796956 (Ack:63459789)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245341 [IM]Received status response, status is 0x00
I: 245375 [EM]<<< [E:11595i S:27421 M:63459790 (Ack:48796956)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1202)
I: 245394 [EM]??1 [E:11595i S:27421 M:63459790] (S) Msg Retransmission to 1:00000000086809DB scheduled for 379ms from now [State:Active II:500 AI:300 AT:4000]
I: 245411 [EM]>>> [E:11595i S:27421 M:48796957 (Ack:63459790)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245426 [IM]Received status response, status is 0x00
I: 245455 [EM]<<< [E:11595i S:27421 M:63459791 (Ack:48796957)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1158)
I: 245473 [EM]??1 [E:11595i S:27421 M:63459791] (S) Msg Retransmission to 1:00000000086809DB scheduled for 397ms from now [State:Active II:500 AI:300 AT:4000]
I: 245581 [EM]>>> [E:11595i S:27421 M:48796958 (Ack:63459791)] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 245596 [IM]Received status response, status is 0x00
I: 245601 [EM]<<< [E:11595i S:27421 M:63459792 (Ack:48796958)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 246171 [EM]<<1 [E:11593i S:27420 M:170611240] (S) Msg Retransmission to 1:00000000BCDA9022
I: 246180 [EM]??2 [E:11593i S:27420 M:170611240] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 2211ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 248391 [EM]<<2 [E:11593i S:27420 M:170611240] (S) Msg Retransmission to 1:00000000BCDA9022
I: 248400 [EM]??3 [E:11593i S:27420 M:170611240] (S) Msg Retransmission to 1:00000000BCDA9022 scheduled for 3696ms from now [State:Idle II:2000 AI:2000 AT:2000]
I: 248490 [EM]>>> [E:11593i S:27420 M:184507250 (Ack:170611240)] (S) Msg RX from 1:00000000BCDA9022 [2D1F] to 00000000407AC4A6 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 248505 [IM]Received status response, status is 0x7d
I: 248532 [DMG]Subscription id 0xb8d9d2da from node <00000000BCDA9022, 1> torn down
I: 248544 [EM]<<< [E:11593i S:27420 M:170611241 (Ack:184507250)] (S) Msg TX from 00000000407AC4A6 to 1:00000000BCDA9022 [2D1F] [UDP:[fe80::1ccc:bdf3:7f2d:d1c7]:49560] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 273412 [EM]>>> [E:56347r S:27421 M:48796959] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 273427 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 273432 [EM]<<< [E:56347r S:27421 M:63459793 (Ack:48796959)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
I: 273452 [EM]??1 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB scheduled for 378ms from now [State:Active II:500 AI:300 AT:4000]
I: 273466 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 273481 [ZCL]Setting on/off to OFF due to level change
I: 273486 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 273493 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 273505 [ZCL]Off completed. reset OnTime to  0
I: 273509 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 273535 [EM]<<< [E:11596i S:27421 M:63459794] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0001:05 (IM:ReportData) (B:1140)
I: 273552 [EM]??1 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB scheduled for 367ms from now [State:Active II:500 AI:300 AT:4000]
I: 273830 [EM]<<1 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB
I: 273839 [EM]??2 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB scheduled for 384ms from now [State:Active II:500 AI:300 AT:4000]
I: 273919 [EM]<<1 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB
I: 273928 [EM]??2 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB scheduled for 412ms from now [State:Active II:500 AI:300 AT:4000]
I: 274223 [EM]<<2 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB
I: 274232 [EM]??3 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB scheduled for 541ms from now [State:Active II:500 AI:300 AT:4000]
I: 274340 [EM]<<2 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB
I: 274349 [EM]??3 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB scheduled for 644ms from now [State:Active II:500 AI:300 AT:4000]
D: 274688 [IN]Received a duplicate message with MessageCounter:48796959 on exchange 56347r
I: 274696 [EM]>>> [E:56347r S:27421 M:48796959] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 274711 [EM]<<< [E:56347r S:27421 M:63459795 (Ack:48796959)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 274774 [EM]<<3 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB
I: 274782 [EM]??4 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB scheduled for 998ms from now [State:Active II:500 AI:300 AT:4000]
I: 274993 [EM]<<3 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB
I: 275002 [EM]??4 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1045ms from now [State:Active II:500 AI:300 AT:4000]
I: 275780 [EM]<<4 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB
I: 275789 [EM]??5 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1353ms from now [State:Active II:500 AI:300 AT:4000]
D: 275849 [IN]Received a duplicate message with MessageCounter:48796959 on exchange 56347r
I: 275857 [EM]>>> [E:56347r S:27421 M:48796959] (S) Msg RX from 1:00000000086809DB [2D1F] to 00000000407AC4A6 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
I: 275871 [EM]<<< [E:56347r S:27421 M:63459796 (Ack:48796959)] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fe80::1072:bae6:ad17:c34e]:60732] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
I: 276047 [EM]<<4 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB
I: 276056 [EM]??5 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1575ms from now [State:Active II:500 AI:300 AT:4000]
E: 277142 [EM]<<5 [E:56347r S:27421 M:63459793] (S) Msg Retransmission to 1:00000000086809DB failure (max retries:4)
D: 277153 [IN]SecureSession[0x20010358]: MarkAsDefunct Type:2 LSID:27421
I: 277159 [SC]SecureSession[0x20010358, LSID:27421]: State change 'kActive' --> 'kDefunct'
E: 277631 [EM]<<5 [E:11596i S:27421 M:63459794] (S) Msg Retransmission to 1:00000000086809DB failure (max retries:4)
D: 293835 [IN]SecureSession[0x20010358]: MarkAsDefunct Type:2 LSID:27421
E: 293842 [DMG]Time out! failed to receive status response from Exchange: 11596i
I: 293849 [DMG]Subscription id 0x80bdb9c1 from node <00000000086809DB, 1> torn down
I: 293857 [IM]Schedule subscription resumption when failing to establish session, Retries: 1
I: 313857 [DIS]Found an existing secure session to [1:00000000086809DB]!
D: 313864 [DIS]OperationalSessionSetup[1:00000000086809DB]: State change 1 --> 5
I: 313871 [DMG]Registered a ReadHandler that will schedule a report between system Timestamp: 0x000000000004CA0F and system Timestamp 0x00000000000DF1CF.
I: 313937 [EM]<<< [E:11597i S:27419 M:65452746] (S) Msg TX from 00000000407AC4A6 to 1:00000000086809DB [2D1F] [UDP:[fdc0:cb91:39c6:4fe0:1087:30bc:fda3:1755]:60732] --- Type 0001:05 (IM:ReportData) (B:1175)
I: 313955 [EM]??1 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB scheduled for 592ms from now [State:Idle II:500 AI:300 AT:4000]
I: 314547 [EM]<<1 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB
I: 314556 [EM]??2 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB scheduled for 572ms from now [State:Idle II:500 AI:300 AT:4000]
I: 315128 [EM]<<2 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB
I: 315137 [EM]??3 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1051ms from now [State:Idle II:500 AI:300 AT:4000]
I: 316188 [EM]<<3 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB
I: 316196 [EM]??4 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB scheduled for 1754ms from now [State:Idle II:500 AI:300 AT:4000]
I: 317950 [EM]<<4 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB
I: 317959 [EM]??5 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB scheduled for 2359ms from now [State:Idle II:500 AI:300 AT:4000]
E: 320318 [EM]<<5 [E:11597i S:27419 M:65452746] (S) Msg Retransmission to 1:00000000086809DB failure (max retries:4)
D: 337054 [IN]SecureSession[0x2000fff8]: MarkAsDefunct Type:2 LSID:27419
I: 337060 [SC]SecureSession[0x2000fff8, LSID:27419]: State change 'kActive' --> 'kDefunct'
E: 337068 [DMG]Time out! failed to receive status response from Exchange: 11597i
I: 337075 [DMG]Subscription id 0x80bdb9c1 from node <00000000086809DB, 1> torn down
I: 337083 [IM]Schedule subscription resumption when failing to establish session, Retries: 1
D: 357084 [DIS]OperationalSessionSetup[1:00000000086809DB]: State change 1 --> 2
I: 357092 [DIS]Lookup started for CCC10070EA402D1F-00000000086809DB
I: 357291 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000086809DB after 200 ms
E: 388092 [DIS]Timeout waiting for mDNS resolution.
I: 402091 [DIS]Checking node lookup status for CCC10070EA402D1F-00000000086809DB after 45000 ms
E: 402100 [DIS]OperationalSessionSetup[1:00000000086809DB]: operational discovery failed: 32
E: 402108 [DMG]Failed to establish CASE for subscription-resumption with error '32'
I: 402116 [IM]Schedule subscription resumption when failing to establish session, Retries: 2