Bootloader start...
OTA header pointer is NULL.
OTA image not pending
License: 0x1001f400
Application has been found at 0x1001f400 address
Application validate correctly
Bo--- PBM Config ---
0) 3 x 40 bytes
1) 14 x 128 bytes
2) 14 x 268 bytes
Total # PBMs: 31
# Reserved: 3, Tx: 21, Rx: 7
qvCHIP v1.4.32.1 ROMv0/0 (CL:0) r:3
t: 1
ResetCount[0]
[00:00:00.438][P][DL] BLEManagerImpl::Init() complete
[00:00:00.438][P][-] Initializing OpenThread stack
Stack register: OTHR
Unknown stack, register 0! new stackId: 0x0
[00:00:00.486][P][DL] OpenThread started: OK
[00:00:00.493][P][DL] Setting OpenThread device type to SLEEPY END DEVICE
[00:00:00.496][P][-] Starting OpenThread task
[00:00:00.500][P][-] Starting Platform Manager Event Loop
[00:00:00.505][P][-] ============================
[00:00:00.509][P][-] Qorvo DoorWindow-Sensor-app Launching
[00:00:00.513][P][-] ============================
[00:00:00.519][P][-] Current Software Version: 1.4-2.0.1
[00:00:00.524][P][DL] Device Configuration:
[00:00:00.528][P][DL]   Serial Number: 12345678
[00:00:00.532][P][DL]   Vendor Id: 65521 (0xFFF1)
[00:00:00.536][P][DL]   Product Id: 32775 (0x8007)
[00:00:00.541][P][DL]   Product Name: Qorvo QPG6200 DK Matter Contact
[00:00:00.546][P][DL]   Hardware Version: 1
[00:00:00.552][P][DL]   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[00:00:00.556][P][DL]   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[00:00:00.562][P][DL]   Manufacturing Date: 2022-12-13
[00:00:00.570][P][DL]   Device Type: 65535 (0xFFFF)
[00:00:00.575][P][SVR] SetupQRCode: [MT:ALG0242C00KA0648G00]
[00:00:00.579][P][SVR] Copy/paste the below URL in a browser to see the QR Code:
[00:00:00.585][P][SVR] https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AALG0242C00KA0648G00
[00:00:00.592][P][SVR] Manual pairing code: [34970112332]
[00:00:00.602][D][DL] DM event 32: status 0
Initiated -> True
[00:00:00.607][D][DL] ATT event 21: status 0
[00:00:00.612][D][DL] Thread task running
[00:00:00.624][D][DL] CHIP event task running
[00:00:00.624][P][-] UpdateClusterState StateValue::Set : 1
[00:00:00.628][P][ZCL] 0x100d9600 ep 1 clus 0x0000_0045 attr 0x0000_0000 not supported
[00:00:00.633][E][-] ERR: updating boolean status value 7f
[00:00:00.641][P][SVR] Initializing subscription resumption storage...
[00:00:00.649][P][SVR] Initializing subscription resumption storage...
[00:00:00.655][P][SVR] Server initializing...
[00:00:00.659][D][FP] Initializing FabricTable from persistent storage
[00:00:00.665][P][TS] Last Known Good Time: 2023-10-14T01:16:48
[00:00:00.674][P][DMG] AccessControl: initializing
[00:00:00.675][P][DMG] Examples::AccessControlDelegate::Init
[00:00:00.680][P][DMG] AccessControl: setting
[00:00:00.685][P][DMG] DefaultAclStorage: initializing
[00:00:00.690][P][DMG] DefaultAclStorage: 0 entries loaded
[00:00:00.694][D][IN] UDP::Init bind&listen port=5540
[00:00:00.700][D][IN] UDP::Init bound to port=5540
[00:00:00.705][D][IN] BLEBase::Init - setting/overriding transport
[00:00:00.709][D][IN] TransportMgr initialized
[00:00:00.725][D][DL] Using Thread extended MAC for hostname.
[00:00:00.731][P][ZCL] Using ZAP configuration...
[00:00:00.735][D][DMG] Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
[00:00:00.738][D][DMG] Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0
[00:00:00.745][P][DMG] AccessControlCluster: initializing
[00:00:00.751][P][ZCL] Initiating Admin Commissioning cluster.
[00:00:00.757][D][ZCL] GeneralDiagnostics: OnDeviceReboot
[00:00:00.762][D][DMG] Endpoint 0, Cluster 0x0000_0033 update version to e8b1120c
[00:00:00.768][D][EVL] LogEvent event number: 0x0000000000070000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000006D
[00:00:00.775][P][-] Setting log provider.
[00:00:00.790][P][ZCL] BooleanStateClusterInitCallback
[00:00:00.794][P][DIS] Updating services using commissioning mode 0
[00:00:00.798][E][DIS] Failed to remove advertised services: 3
[00:00:00.805][D][DL] Using Thread extended MAC for hostname.
[00:00:00.811][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:00.816][E][DIS] Failed to advertise extended commissionable node: 3
[00:00:00.826][D][DIS] Scheduling extended discovery timeout in 900s
[00:00:00.833][E][DIS] Failed to finalize service update: 3
[00:00:00.839][P][IN] CASE Server enabling CASE session setups
[00:00:00.845][D][IN] SecureSession[0x2000a108]: Allocated Type:2 LSID:16552
[00:00:00.850][D][SC] Allocated SecureSession (0x2000a108) - waiting for Sigma1 msg
[00:00:00.862][D][ZCL] Emitting StartUp event
[00:00:00.865][D][EVL] LogEvent event number: 0x0000000000070001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000000CD
[00:00:00.868][P][SVR] Server Listening...
[00:00:00.887][D][DIS] Setting extended discovery timeout to 20s
[00:00:00.887][D][DIS] Scheduling extended discovery timeout in 20s
[00:00:00.893][P][-] No fabrics, starting commissioning.
[00:00:00.899][E][DL] Long dispatch time: 258 ms, for event type 2
[00:00:00.904][P][-] StateValue::Get : 0
[00:00:00.910][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:00.914][D][DL] OpenThread State Changed (Flags: 0x00038210)
[00:00:00.920][D][DL]    Network Name: OpenThread
[00:00:00.926][D][DL]    PAN Id: 0xFFFF
[00:00:00.931][D][DL]    Extended PAN Id: 0xDEAD00BEEF00CAFE
[00:00:00.934][D][DL]    Channel: 11
[00:00:00.940][D][DL]    Mesh Prefix: fdde:ad00:beef:0:0:0:0:0/64
[00:00:00.946][P][-] UpdateClusterState StateValue::Set : 1
[00:00:00.949][D][DMG] Endpoint 1, Cluster 0x0000_0045 update version to 815e5a8d
[00:00:00.954][P][ZCL] Cluster BooleanState: attribute StateValue set to 1
[00:00:00.963][D][IN] SecureSession[0x2000a1e0]: Allocated Type:1 LSID:16553
[00:00:00.968][D][SC] Assigned local session key ID 16553
[00:00:00.975][D][SC] Waiting for PBKDF param request
[00:00:00.984][P][DIS] Updating services using commissioning mode 1
[00:00:00.985][E][DIS] Failed to remove advertised services: 3
[00:00:00.991][D][DL] Using Thread extended MAC for hostname.
[00:00:00.997][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=1 cp=0
[00:00:01.002][E][DIS] Failed to advertise commissionable node: 3
[00:00:01.008][E][DIS] Failed to finalize service update: 3
[00:00:01.018][P][-] BLE advertising started. Waiting for Pairing.
[00:00:01.024][P][DL] CHIPoBLE start advertising
[00:00:01.037][D][DL] DM event 33: status 0
[00:00:01.038][P][DL] CHIPoBLE advertising started
[00:00:01.041][P][DL] _OnPlatformEvent default:  event->Type = 32781
[00:00:01.047][P][-] DoorWindow state changed to CLOSED
[00:00:01.597][D][DMG] Endpoint 0, Cluster 0x0000_002F update version to fb1bf11b
[00:00:01.598][D][DMG] Endpoint 0, Cluster 0x0000_002F update version to fb1bf11c
1 resets so far
[00:00:04.254][D][DL] DM event 39: status 0
[00:00:04.254][P][DL] BLE GATT connection established (con 1)
[00:00:04.259][P][DL] CHIPoBLE advertising stopped
[00:00:04.264][P][DL] _OnPlatformEvent default:  event->Type = 32781
[00:00:04.430][D][DL] ATT event 22: status 0
[00:00:05.209][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 9)
[00:00:05.210][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:05.218][P][BLE] local and remote recv window sizes = 5
[00:00:05.224][P][BLE] selected BTP version 4
[00:00:05.229][P][BLE] using BTP fragment sizes rx 182 / tx 182.
[00:00:05.389][P][DL] Write request received for CHIPoBLE TX characteristic CCCD (con 1, len 0)
[00:00:05.389][P][DL] CHIPoBLE subscribe received
[00:00:05.399][D][DL] _OnPlatformEvent kCHIPoBLESubscribe
[00:00:05.402][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 6)
[00:00:05.409][D][IN] BLE EndPoint 0x2000d290 Connection Complete
[00:00:05.415][P][DL] _OnPlatformEvent default:  event->Type = 32774
[00:00:05.451][D][DL] ATT event 18: status 0
[00:00:05.453][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:05.479][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 103)
[00:00:05.480][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:05.489][P][EM] >>> [E:60954r S:0 M:153612522] (U) Msg RX from 0:D11E3E32972BF0A7 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
[00:00:05.494][D][EM] Handling via exchange: 60954r, Delegate: 0x2000c3b8
[00:00:05.509][D][SC] Received PBKDF param request
[00:00:05.516][D][SC] Peer assigned session ID 2398
[00:00:05.520][D][SC] Found MRP parameters in the message
[00:00:05.528][P][EM] <<< [E:60954r S:0 M:121417603] (U) Msg TX from 0000000000000000 to 0:D11E3E32972BF0A7 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:170)
[00:00:05.530][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 175)
[00:00:05.549][D][SC] Sent PBKDF param response
[00:00:05.553][P][SVR] Commissioning session establishment step started
[00:00:05.630][D][DL] ATT event 18: status 0
[00:00:05.631][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:05.661][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 97)
[00:00:05.662][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:05.670][P][EM] >>> [E:60954r S:0 M:153612523] (U) Msg RX from 0:D11E3E32972BF0A7 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
[00:00:05.674][D][EM] Found matching exchange: 60954r, Delegate: 0x2000c3b8
[00:00:05.690][D][SC] Received spake2p msg1
[00:00:05.775][P][EM] <<< [E:60954r S:0 M:121417604] (U) Msg TX from 0000000000000000 to 0:D11E3E32972BF0A7 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
[00:00:05.776][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 132)
[00:00:05.793][D][SC] Sent spake2p msg2
[00:00:05.798][E][DL] Long dispatch time: 136 ms, for event type 7
[00:00:05.840][D][DL] ATT event 18: status 0
[00:00:05.842][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:05.868][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 64)
[00:00:05.870][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:05.878][P][EM] >>> [E:60954r S:0 M:153612524] (U) Msg RX from 0:D11E3E32972BF0A7 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
[00:00:05.883][D][EM] Found matching exchange: 60954r, Delegate: 0x2000c3b8
[00:00:05.898][D][SC] Received spake2p msg3
[00:00:05.906][D][SC] Sending status report. Protocol code 0, exchange 60954
[00:00:05.909][P][EM] <<< [E:60954r S:0 M:121417605] (U) Msg TX from 0000000000000000 to 0:D11E3E32972BF0A7 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
[00:00:05.916][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 35)
[00:00:05.937][P][SC] SecureSession[0x2000a1e0, LSID:16553]: State change 'kEstablishing' --> 'kActive'
[00:00:05.938][D][IN] SecureSession[0x2000a1e0]: Activated - Type:1 LSID:16553
[00:00:05.947][D][IN] New secure session activated for device , LSID:16553 PSID:2398!
[00:00:05.954][P][SVR] Commissioning completed session establishment step
[00:00:05.964][P][DIS] Updating services using commissioning mode 0
[00:00:05.970][E][DIS] Failed to remove advertised services: 3
[00:00:05.976][D][DL] Using Thread extended MAC for hostname.
[00:00:05.983][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:05.988][E][DIS] Failed to advertise extended commissionable node: 3
[00:00:05.998][D][DIS] Scheduling extended discovery timeout in 20s
[00:00:06.005][E][DIS] Failed to finalize service update: 3
[00:00:06.011][P][SVR] Device completed Rendezvous process
[00:00:06.016][E][DL] Long dispatch time: 146 ms, for event type 7
[00:00:06.021][P][DL] _OnPlatformEvent default:  event->Type = 32792
[00:00:06.030][D][DL] ATT event 18: status 0
[00:00:06.034][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:06.048][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 56)
[00:00:06.050][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:06.058][P][EM] >>> [E:60955r S:16553 M:96802241] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:06.063][D][EM] Handling via exchange: 60955r, Delegate: 0x20018784
[00:00:06.075][D][IM] Received Read request
[00:00:06.085][D][DMG] IM RH moving to [CanStartReporting]
[00:00:06.088][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:06.093][D][DMG]  Cluster 1d, Attribute 3 is dirty
[00:00:06.105][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[00:00:06.111][D][DMG]  Sending report (payload has 38 bytes)...
[00:00:06.122][P][EM] <<< [E:60955r S:16553 M:227232129] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:68)
[00:00:06.127][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 73)
[00:00:06.144][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:06.148][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:06.154][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:06.206][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:06.207][E][DL] Long dispatch time: 119 ms, for event type 3
[00:00:06.216][D][DL] ATT event 18: status 0
[00:00:06.220][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:06.228][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 56)
[00:00:06.230][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:06.239][P][EM] >>> [E:60956r S:16553 M:96802242] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:06.243][D][EM] Handling via exchange: 60956r, Delegate: 0x20018784
[00:00:06.250][D][IM] Received Read request
[00:00:06.265][D][DMG] IM RH moving to [CanStartReporting]
[00:00:06.268][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:06.273][D][DMG]  Cluster 1d, Attribute 1 is dirty
[00:00:06.285][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:06.292][D][DMG]  Sending report (payload has 70 bytes)...
[00:00:06.302][P][EM] <<< [E:60956r S:16553 M:227232130] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:100)
[00:00:06.307][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 105)
[00:00:06.324][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:06.329][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:06.334][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:06.387][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:06.387][E][DL] Long dispatch time: 119 ms, for event type 3
[00:00:06.410][D][DL] ATT event 18: status 0
[00:00:06.411][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:06.438][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 57)
[00:00:06.439][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:06.448][P][EM] >>> [E:60957r S:16553 M:96802243] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:52)
[00:00:06.453][D][EM] Handling via exchange: 60957r, Delegate: 0x20018784
[00:00:06.467][D][IM] Received Read request
[00:00:06.475][D][DMG] IM RH moving to [CanStartReporting]
[00:00:06.478][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:06.483][D][DMG]  Cluster 31, Attribute fffc is dirty
[00:00:06.495][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
[00:00:06.501][D][DMG]  Sending report (payload has 37 bytes)...
[00:00:06.512][P][EM] <<< [E:60957r S:16553 M:227232131] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:67)
[00:00:06.517][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 72)
[00:00:06.534][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:06.539][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:06.544][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:06.597][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:06.597][E][DL] Long dispatch time: 119 ms, for event type 3
[00:00:06.606][D][DL] ATT event 18: status 0
[00:00:06.610][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:06.618][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 56)
[00:00:06.620][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:06.628][P][EM] >>> [E:60958r S:16553 M:96802244] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:06.634][D][EM] Handling via exchange: 60958r, Delegate: 0x20018784
[00:00:06.648][D][IM] Received Read request
[00:00:06.655][D][DMG] IM RH moving to [CanStartReporting]
[00:00:06.658][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:06.664][D][DMG]  Cluster 31, Attribute 2 is dirty
[00:00:06.676][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:00:06.682][D][DMG]  Sending report (payload has 36 bytes)...
[00:00:06.692][P][EM] <<< [E:60958r S:16553 M:227232132] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:66)
[00:00:06.698][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:06.714][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:06.719][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:06.725][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:06.777][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:06.778][E][DL] Long dispatch time: 119 ms, for event type 3
[00:00:06.800][D][DL] ATT event 18: status 0
[00:00:06.801][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:06.828][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 64)
[00:00:06.829][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:06.831][P][EM] >>> [E:60959r S:16553 M:96802245] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[00:00:06.843][D][EM] Handling via exchange: 60959r, Delegate: 0x20018784
[00:00:06.860][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0000
[00:00:06.864][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 3
[00:00:06.877][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 2
[00:00:06.880][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:06.889][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:06.897][D][DL] OpenThread State Changed (Flags: 0x01009009)
[00:00:06.903][D][DL]    Network Name: OpenThread
[00:00:06.909][D][DL]    PAN Id: 0x9961
[00:00:06.914][D][DL]    Extended PAN Id: 0xDEAD00BEEF00CAFE
[00:00:06.917][D][DL]    Channel: 11
[00:00:06.923][D][DL]    Mesh Prefix: fdde:ad00:beef:0:0:0:0:0/64
[00:00:06.926][D][DL]    Thread Unicast Addresses:
[00:00:06.932][D][DL]         fe80:0:0:0:90c8:d0bf:2d02:c8a9/64 valid preferred
[00:00:06.957][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -71 LQI 178 Version 5
[00:00:06.960][P][DL] Thread Network: AMZN-Thread-0d7d Panid 0xd7d Channel 11 RSSI -69 LQI 195 Version 4
[00:00:06.989][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -50 LQI 255 Version 5
[00:00:06.995][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -41 LQI 255 Version 5
[00:00:07.003][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -61 LQI 255 Version 5
[00:00:07.012][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -56 LQI 255 Version 5
[00:00:07.019][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -47 LQI 255 Version 5
[00:00:07.029][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -49 LQI 255 Version 5
[00:00:07.038][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -46 LQI 255 Version 5
[00:00:07.047][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -51 LQI 255 Version 5
[00:00:07.057][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -56 LQI 255 Version 5
[00:00:07.066][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -41 LQI 255 Version 5
[00:00:07.076][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -43 LQI 255 Version 5
[00:00:07.085][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -45 LQI 255 Version 5
[00:00:07.094][P][DL] Thread Network: AMZN-Thread-0d7d Panid 0xd7d Channel 11 RSSI -59 LQI 255 Version 2
[00:00:07.104][P][DL] Thread Network: DEMO Panid 0x1234 Channel 11 RSSI -41 LQI 255 Version 4
[00:00:07.113][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -56 LQI 255 Version 5
[00:00:07.122][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -57 LQI 255 Version 5
[00:00:07.173][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -59 LQI 255 Version 5
[00:00:07.182][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -52 LQI 255 Version 5
[00:00:07.187][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -47 LQI 255 Version 5
[00:00:07.194][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -51 LQI 255 Version 5
[00:00:07.203][P][DL] Thread Network: AMZN-Thread-f2c4 Panid 0xf2c4 Channel 11 RSSI -72 LQI 170 Version 2
[00:00:07.213][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -51 LQI 255 Version 5
[00:00:07.222][P][DL] Thread Network: gw2-f6283e9eda91 Panid 0xae42 Channel 11 RSSI -51 LQI 255 Version 5
[00:00:08.532][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -83 LQI 76 Version 4
[00:00:08.558][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -79 LQI 110 Version 4
[00:00:08.579][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -79 LQI 110 Version 4
[00:00:08.593][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -95 LQI 0 Version 4
[00:00:08.606][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -86 LQI 51 Version 4
[00:00:08.614][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -73 LQI 161 Version 5
[00:00:08.643][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -92 LQI 0 Version 4
[00:00:08.651][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -83 LQI 76 Version 4
[00:00:08.665][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -88 LQI 34 Version 4
[00:00:08.683][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -95 LQI 0 Version 4
[00:00:08.700][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -90 LQI 17 Version 4
[00:00:08.739][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -85 LQI 59 Version 4
[00:00:08.755][P][DL] Thread Network: gw2-6567315802df Panid 0xdcb9 Channel 16 RSSI -82 LQI 85 Version 4
[00:00:09.174][P][DL] Thread Network: 5b45 Panid 0x5b45 Channel 18 RSSI -59 LQI 255 Version 4
[00:00:09.265][P][DL] Thread Network: 5b45 Panid 0x5b45 Channel 18 RSSI -60 LQI 255 Version 4
[00:00:09.330][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 3)
[00:00:09.406][D][DL] ATT event 18: status 0
[00:00:09.407][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:09.731][P][DL] Thread Network: ST-0K26 Panid 0x429f Channel 20 RSSI -45 LQI 255 Version 5
[00:00:09.773][P][DL] Thread Network: ST-0K26 Panid 0x429f Channel 20 RSSI -50 LQI 255 Version 5
[00:00:09.836][P][DL] Thread Network: ST-0K26 Panid 0x429f Channel 20 RSSI -62 LQI 255 Version 5
[00:00:09.851][P][DL] Thread Network: ST-0K26 Panid 0x90ae Channel 20 RSSI -87 LQI 42 Version 5
[00:00:09.872][P][DL] Thread Network: ST-0K26 Panid 0x429f Channel 20 RSSI -60 LQI 255 Version 4
[00:00:10.969][P][DL] Thread Network: ST-0K26 Panid 0xaa6d Channel 24 RSSI -54 LQI 255 Version 5
[00:00:11.167][P][DL] Thread Network: ST-0K26 Panid 0xaa6d Channel 24 RSSI -48 LQI 255 Version 5
[00:00:11.172][P][DL] Thread Network: ST-0K26 Panid 0xaa6d Channel 24 RSSI -48 LQI 255 Version 5
[00:00:11.178][P][DL] Thread Network: ST-0K26 Panid 0xaa6d Channel 24 RSSI -51 LQI 255 Version 5
[00:00:11.266][P][DL] Thread Network: MyHome393191637 Panid 0x43dc Channel 25 RSSI -49 LQI 255 Version 4
[00:00:11.418][P][DL] Thread Network: MyHome393191637 Panid 0x43dc Channel 25 RSSI -39 LQI 255 Version 4
[00:00:11.863][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:11.865][D][DL] OpenThread State Changed (Flags: 0x00008000)
[00:00:11.870][D][DL]    Network Name: OpenThread
[00:00:11.876][D][DL]    PAN Id: 0xFFFF
[00:00:11.881][D][DL]    Extended PAN Id: 0xDEAD00BEEF00CAFE
[00:00:11.884][D][DL]    Channel: 11
[00:00:11.893][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 3)
[00:00:11.890][D][DL]    Mesh Prefix: fdde:ad00:beef:0:0:0:0:0/64
[00:00:11.906][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:11.908][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6bb
[00:00:11.916][D][DMG] Command handler moving to [NewRespons]
[00:00:11.923][D][DMG] Command handler moving to [ Preparing]
[00:00:11.929][D][DMG] Command handler moving to [AddingComm]
[00:00:11.936][D][DMG] Command handler moving to [AddedComma]
[00:00:11.940][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:11.943][D][DMG] Command handler moving to [AwaitingDe]
[00:00:11.954][P][EM] <<< [E:60959r S:16553 M:227232133] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:594)
[00:00:11.959][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:11.977][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:11.982][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:11.988][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:11.993][D][DL] OpenThread State Changed (Flags: 0x01002002)
[00:00:11.999][D][DL]    Thread Unicast Addresses:
[00:00:12.073][D][DL] ATT event 18: status 0
[00:00:12.074][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:12.077][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:12.223][D][DL] ATT event 18: status 0
[00:00:12.224][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:12.227][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:12.312][D][DL] ATT event 18: status 0
[00:00:12.313][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:12.317][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 59)
[00:00:12.403][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 3)
[00:00:12.404][D][DL] ATT event 18: status 0
[00:00:12.412][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:12.416][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:12.553][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 58)
[00:00:12.554][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:12.563][P][EM] >>> [E:60960r S:16553 M:96802246] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:54)
[00:00:12.568][D][EM] Handling via exchange: 60960r, Delegate: 0x20018784
[00:00:12.582][D][IM] Received Read request
[00:00:12.590][D][DMG] IM RH moving to [CanStartReporting]
[00:00:12.593][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:12.598][D][DMG]  Cluster 1349fc00, Attribute 1 is dirty
[00:00:12.610][D][DMG] Reading attribute: Cluster=0x1349_FC00 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:12.617][E][DMG] Fail to retrieve data, roll back and encode status on clusterId: 0x1349_FC00, attributeId: 0x0000_0001err = 5c3
[00:00:12.627][D][DMG]  Sending report (payload has 36 bytes)...
[00:00:12.642][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 55)
[00:00:12.639][P][EM] <<< [E:60960r S:16553 M:227232134] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:66)
[00:00:12.654][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:12.670][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:12.675][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:12.680][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:12.726][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:12.727][E][DL] Long dispatch time: 134 ms, for event type 3
[00:00:12.733][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:12.740][P][EM] >>> [E:60961r S:16553 M:96802247] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:12.745][D][EM] Handling via exchange: 60961r, Delegate: 0x20018784
[00:00:12.759][D][IM] Received Read request
[00:00:12.767][D][DMG] IM RH moving to [CanStartReporting]
[00:00:12.770][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:12.775][D][DMG]  Cluster 33, Attribute 0 is dirty
[00:00:12.787][D][DMG] Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[00:00:12.793][D][DMG]  Sending report (payload has 77 bytes)...
[00:00:12.804][P][EM] <<< [E:60961r S:16553 M:227232135] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:107)
[00:00:12.809][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:12.823][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:12.829][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:12.881][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:12.882][E][DL] Long dispatch time: 112 ms, for event type 3
[00:00:12.913][D][DL] ATT event 18: status 0
[00:00:12.914][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:12.917][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 112)
[00:00:12.974][D][DL] ATT event 18: status 0
[00:00:12.976][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:13.001][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 141)
[00:00:13.003][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:13.012][P][EM] >>> [E:60962r S:16553 M:96802248] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:136)
[00:00:13.016][D][EM] Handling via exchange: 60962r, Delegate: 0x20018784
[00:00:13.030][D][IM] Received Read request
[00:00:13.044][D][DMG] IM RH moving to [CanStartReporting]
[00:00:13.045][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:13.049][D][DMG]  Cluster 28, Attribute 4 is dirty
[00:00:13.062][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[00:00:13.068][D][DMG]  Cluster 28, Attribute 2 is dirty
[00:00:13.077][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:00:13.083][D][DMG]  Cluster 30, Attribute c is dirty
[00:00:13.093][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_000C (expanded=0)
[00:00:13.099][E][DMG] Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0030, attributeId: 0x0000_000Cerr = 586
[00:00:13.108][D][DMG]  Cluster 30, Attribute 3 is dirty
[00:00:13.120][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[00:00:13.126][D][DMG]  Cluster 30, Attribute 2 is dirty
[00:00:13.136][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:00:13.153][D][DMG]  Cluster 30, Attribute 1 is dirty
[00:00:13.153][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:13.159][D][DMG]  Cluster 30, Attribute 0 is dirty
[00:00:13.169][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[00:00:13.175][D][DMG]  Cluster 30, Attribute 4 is dirty
[00:00:13.184][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[00:00:13.190][D][DMG]  Sending report (payload has 223 bytes)...
[00:00:13.201][P][EM] <<< [E:60962r S:16553 M:227232136] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:253)
[00:00:13.206][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:13.224][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:13.228][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:13.233][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:13.287][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:13.287][E][DL] Long dispatch time: 243 ms, for event type 3
[00:00:13.362][D][DL] ATT event 18: status 0
[00:00:13.362][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:13.366][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 78)
[00:00:13.423][D][DL] ATT event 18: status 0
[00:00:13.425][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:13.451][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 117)
[00:00:13.452][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:13.461][P][EM] >>> [E:60963r S:16553 M:96802249] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:112)
[00:00:13.466][D][EM] Handling via exchange: 60963r, Delegate: 0x20018784
[00:00:13.480][D][IM] Received Read request
[00:00:13.492][D][DMG] IM RH moving to [CanStartReporting]
[00:00:13.493][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:13.497][D][DMG]  Cluster 46, Attribute 2 is dirty
[00:00:13.510][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:00:13.516][D][DMG]  Cluster 46, Attribute 1 is dirty
[00:00:13.525][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:13.532][D][DMG]  Cluster 46, Attribute 0 is dirty
[00:00:13.541][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[00:00:13.547][D][DMG]  Cluster 46, Attribute 7 is dirty
[00:00:13.557][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_0007 (expanded=0)
[00:00:13.563][D][DMG]  Cluster 46, Attribute 6 is dirty
[00:00:13.572][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_0006 (expanded=0)
[00:00:13.578][D][DMG]  Cluster 31, Attribute 3 is dirty
[00:00:13.588][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:13.594][D][DMG]  Cluster 31, Attribute fffc is dirty
[00:00:13.603][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:13.610][D][DMG]  Sending report (payload has 218 bytes)...
[00:00:13.620][P][EM] <<< [E:60963r S:16553 M:227232137] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:248)
[00:00:13.626][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:13.643][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:13.647][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:13.653][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:13.706][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:13.706][E][DL] Long dispatch time: 213 ms, for event type 3
[00:00:13.781][D][DL] ATT event 18: status 0
[00:00:13.782][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:13.785][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 73)
[00:00:13.843][D][DL] ATT event 18: status 0
[00:00:13.844][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:13.871][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 70)
[00:00:13.872][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:13.881][P][EM] >>> [E:60964r S:16553 M:96802250] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
[00:00:13.886][D][EM] Handling via exchange: 60964r, Delegate: 0x20018784
[00:00:13.903][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:00:13.907][P][FS] GeneralCommissioning: Received ArmFailSafe (60s)
[00:00:13.916][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29a
[00:00:13.922][D][DMG] Command handler moving to [NewRespons]
[00:00:13.929][D][DMG] Command handler moving to [ Preparing]
[00:00:13.935][D][DMG] Command handler moving to [AddingComm]
[00:00:13.940][D][DMG] Command handler moving to [AddedComma]
[00:00:13.946][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:13.951][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:13.959][D][DMG] Command handler moving to [AwaitingDe]
[00:00:13.968][P][EM] <<< [E:60964r S:16553 M:227232138] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:13.972][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:13.985][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:13.995][E][DL] Long dispatch time: 123 ms, for event type 7
[00:00:14.023][D][DL] ATT event 18: status 0
[00:00:14.024][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.051][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 75)
[00:00:14.053][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:14.061][P][EM] >>> [E:60965r S:16553 M:96802251] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
[00:00:14.066][D][EM] Handling via exchange: 60965r, Delegate: 0x20018784
[00:00:14.083][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
[00:00:14.099][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29b
[00:00:14.100][D][DMG] Command handler moving to [NewRespons]
[00:00:14.107][D][DMG] Command handler moving to [ Preparing]
[00:00:14.113][D][DMG] Command handler moving to [AddingComm]
[00:00:14.118][D][DMG] Command handler moving to [AddedComma]
[00:00:14.124][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:14.129][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:14.137][D][DMG] Command handler moving to [AwaitingDe]
[00:00:14.146][P][EM] <<< [E:60965r S:16553 M:227232139] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:14.150][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:14.159][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:14.173][E][DL] Long dispatch time: 120 ms, for event type 7
[00:00:14.203][D][DL] ATT event 18: status 0
[00:00:14.204][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.230][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 67)
[00:00:14.232][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:14.241][P][EM] >>> [E:60966r S:16553 M:96802252] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
[00:00:14.245][D][EM] Handling via exchange: 60966r, Delegate: 0x20018784
[00:00:14.263][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:00:14.267][P][ZCL] OpCreds: Certificate Chain request received for PAI
[00:00:14.275][D][DMG] Command handler moving to [NewRespons]
[00:00:14.282][D][DMG] Command handler moving to [ Preparing]
[00:00:14.287][D][DMG] Command handler moving to [AddingComm]
[00:00:14.293][D][DMG] Command handler moving to [AddedComma]
[00:00:14.299][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:14.304][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:14.312][D][DMG] Command handler moving to [AwaitingDe]
[00:00:14.320][P][EM] <<< [E:60966r S:16553 M:227232140] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:507)
[00:00:14.325][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:14.331][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:14.348][E][DL] Long dispatch time: 116 ms, for event type 7
[00:00:14.441][D][DL] ATT event 18: status 0
[00:00:14.442][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.445][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:14.531][D][DL] ATT event 18: status 0
[00:00:14.531][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.535][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 152)
[00:00:14.591][D][DL] ATT event 18: status 0
[00:00:14.593][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.620][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 67)
[00:00:14.622][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:14.630][P][EM] >>> [E:60967r S:16553 M:96802253] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
[00:00:14.635][D][EM] Handling via exchange: 60967r, Delegate: 0x20018784
[00:00:14.652][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:00:14.657][P][ZCL] OpCreds: Certificate Chain request received for DAC
[00:00:14.666][D][DMG] Command handler moving to [NewRespons]
[00:00:14.672][D][DMG] Command handler moving to [ Preparing]
[00:00:14.678][D][DMG] Command handler moving to [AddingComm]
[00:00:14.683][D][DMG] Command handler moving to [AddedComma]
[00:00:14.689][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:14.694][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:14.702][D][DMG] Command handler moving to [AwaitingDe]
[00:00:14.711][P][EM] <<< [E:60967r S:16553 M:227232141] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:547)
[00:00:14.715][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:14.733][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:14.738][E][DL] Long dispatch time: 116 ms, for event type 7
[00:00:14.830][D][DL] ATT event 18: status 0
[00:00:14.831][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.835][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:14.921][D][DL] ATT event 18: status 0
[00:00:14.922][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:14.925][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:15.010][D][DL] ATT event 18: status 0
[00:00:15.011][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:15.014][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 12)
[00:00:15.071][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 3)
[00:00:15.072][D][DL] ATT event 18: status 0
[00:00:15.080][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:15.084][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:15.132][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 98)
[00:00:15.133][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:15.142][P][EM] >>> [E:60968r S:16553 M:96802254] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
[00:00:15.147][D][EM] Handling via exchange: 60968r, Delegate: 0x20018784
[00:00:15.163][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
[00:00:15.168][P][ZCL] OpCreds: Received an AttestationRequest command
[00:00:15.191][P][ZCL] OpCreds: AttestationRequest successful.
[00:00:15.192][D][DMG] Command handler moving to [NewRespons]
[00:00:15.197][D][DMG] Command handler moving to [ Preparing]
[00:00:15.203][D][DMG] Command handler moving to [AddingComm]
[00:00:15.208][D][DMG] Command handler moving to [AddedComma]
[00:00:15.214][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:15.219][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:15.227][D][DMG] Command handler moving to [AwaitingDe]
[00:00:15.236][P][EM] <<< [E:60968r S:16553 M:227232142] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:408)
[00:00:15.240][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:15.258][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:15.263][E][DL] Long dispatch time: 130 ms, for event type 7
[00:00:15.370][D][DL] ATT event 18: status 0
[00:00:15.371][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:15.374][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:15.460][D][DL] ATT event 18: status 0
[00:00:15.461][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:15.464][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 53)
[00:00:15.520][D][DL] ATT event 18: status 0
[00:00:15.523][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:15.549][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 70)
[00:00:15.551][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:15.559][P][EM] >>> [E:60969r S:16553 M:96802255] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
[00:00:15.564][D][EM] Handling via exchange: 60969r, Delegate: 0x20018784
[00:00:15.581][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:00:15.586][P][FS] GeneralCommissioning: Received ArmFailSafe (60s)
[00:00:15.594][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29c
[00:00:15.601][D][DMG] Command handler moving to [NewRespons]
[00:00:15.608][D][DMG] Command handler moving to [ Preparing]
[00:00:15.613][D][DMG] Command handler moving to [AddingComm]
[00:00:15.619][D][DMG] Command handler moving to [AddedComma]
[00:00:15.625][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:15.630][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:15.633][D][DMG] Command handler moving to [AwaitingDe]
[00:00:15.646][P][EM] <<< [E:60969r S:16553 M:227232143] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:15.651][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:15.669][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:15.674][E][DL] Long dispatch time: 123 ms, for event type 7
[00:00:15.730][D][DL] ATT event 18: status 0
[00:00:15.731][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:16.780][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 99)
[00:00:16.782][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:16.790][P][EM] >>> [E:60970r S:16553 M:96802256] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
[00:00:16.795][D][EM] Handling via exchange: 60970r, Delegate: 0x20018784
[00:00:16.812][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
[00:00:16.817][P][ZCL] OpCreds: Received a CSRRequest command
[00:00:16.825][D][ZCL] OpCreds: Finding fabric with fabricIndex 0x0
[00:00:16.864][P][ZCL] OpCreds: AllocatePendingOperationalKey succeeded
[00:00:16.879][P][ZCL] OpCreds: CSRRequest successful.
[00:00:16.880][D][DMG] Command handler moving to [NewRespons]
[00:00:16.884][D][DMG] Command handler moving to [ Preparing]
[00:00:16.890][D][DMG] Command handler moving to [AddingComm]
[00:00:16.896][D][DMG] Command handler moving to [AddedComma]
[00:00:16.902][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:16.907][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:16.914][D][DMG] Command handler moving to [AwaitingDe]
[00:00:16.923][P][EM] <<< [E:60970r S:16553 M:227232144] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:374)
[00:00:16.928][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:16.946][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:16.951][E][DL] Long dispatch time: 169 ms, for event type 7
[00:00:17.019][D][DL] ATT event 18: status 0
[00:00:17.020][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:17.023][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 182)
[00:00:17.109][D][DL] ATT event 18: status 0
[00:00:17.110][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:17.113][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 19)
[00:00:17.169][D][DL] ATT event 18: status 0
[00:00:17.170][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:17.258][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 182)
[00:00:17.259][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:17.321][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 138)
[00:00:17.322][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:17.327][P][EM] >>> [E:60971r S:16553 M:96802257] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:313)
[00:00:17.336][D][EM] Handling via exchange: 60971r, Delegate: 0x20018784
[00:00:17.353][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
[00:00:17.357][P][ZCL] OpCreds: Received an AddTrustedRootCertificate command
[00:00:17.385][P][ZCL] OpCreds: AddTrustedRootCertificate successful.
[00:00:17.385][D][DMG] Command handler moving to [NewRespons]
[00:00:17.391][D][DMG] Command handler moving to [ Preparing]
[00:00:17.397][D][DMG] Command handler moving to [AddingComm]
[00:00:17.403][D][DMG] Command handler moving to [AddedComma]
[00:00:17.409][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:17.414][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:17.421][D][DMG] Command handler moving to [AwaitingDe]
[00:00:17.430][P][EM] <<< [E:60971r S:16553 M:227232145] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
[00:00:17.435][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 68)
[00:00:17.452][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:17.457][E][DL] Long dispatch time: 135 ms, for event type 7
[00:00:17.498][D][DL] ATT event 18: status 0
[00:00:17.500][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:17.527][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 182)
[00:00:17.529][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:17.617][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 174)
[00:00:17.619][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:17.627][P][EM] >>> [E:60972r S:16553 M:96802258] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:349)
[00:00:17.632][D][EM] Handling via exchange: 60972r, Delegate: 0x20018784
[00:00:17.650][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
[00:00:17.654][P][ZCL] OpCreds: Received an AddNOC command
[00:00:17.672][P][FP] Validating NOC chain
[00:00:17.693][P][FP] NOC chain validation successful
[00:00:17.694][P][FP] Added new fabric at index: 0x1
[00:00:17.698][P][FP] Assigned compressed fabric ID: 0x7C0E543D6704ADD1, node ID: 0x000000004B8824AB
[00:00:17.703][P][TS] Last Known Good Time: 2023-10-14T01:16:48
[00:00:17.712][P][TS] New proposed Last Known Good Time: 2025-12-10T04:04:28
[00:00:17.718][P][TS] Updating pending Last Known Good Time to 2025-12-10T04:04:28
[00:00:17.725][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b13
[00:00:17.732][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b14
[00:00:17.799][D][EVL] LogEvent event number: 0x0000000000070002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000000042F4
[00:00:17.800][P][ZCL] OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x23C50D4337BF9971
[00:00:17.808][D][DL] Using Thread extended MAC for hostname.
[00:00:17.825][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:17.830][E][SVR] Operational advertising failed: 3
[00:00:17.837][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b15
[00:00:17.843][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b16
[00:00:17.850][D][DMG] Command handler moving to [NewRespons]
[00:00:17.857][D][DMG] Command handler moving to [ Preparing]
[00:00:17.863][D][DMG] Command handler moving to [AddingComm]
[00:00:17.868][D][DMG] Command handler moving to [AddedComma]
[00:00:17.874][P][ZCL] OpCreds: successfully created fabric index 0x1 via AddNOC
[00:00:17.880][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:17.887][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:17.894][D][DMG] Command handler moving to [AwaitingDe]
[00:00:17.903][P][EM] <<< [E:60972r S:16553 M:227232146] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [ADD1] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:17.908][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:17.925][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:17.930][E][DL] Long dispatch time: 312 ms, for event type 7
[00:00:17.979][D][DL] ATT event 18: status 0
[00:00:17.980][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:18.037][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 176)
[00:00:18.039][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:18.048][P][EM] >>> [E:60973r S:16553 M:96802259] (S) Msg RX from 1:FFFFFFFB00000000 [ADD1] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:171)
[00:00:18.052][D][EM] Handling via exchange: 60973r, Delegate: 0x20018784
[00:00:18.069][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
[00:00:18.074][D][DMG] Command handler moving to [NewRespons]
[00:00:18.082][D][DMG] Command handler moving to [ Preparing]
[00:00:18.088][D][DMG] Command handler moving to [AddingComm]
[00:00:18.093][D][DMG] Command handler moving to [AddedComma]
[00:00:18.099][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6bc
[00:00:18.105][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29d
[00:00:18.112][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:18.119][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:18.127][D][DMG] Command handler moving to [AwaitingDe]
[00:00:18.136][P][EM] <<< [E:60973r S:16553 M:227232147] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [ADD1] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:18.140][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:18.158][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:18.163][E][DL] Long dispatch time: 124 ms, for event type 7
[00:00:18.248][D][DL] ATT event 18: status 0
[00:00:18.250][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:18.277][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 70)
[00:00:18.278][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:18.287][P][EM] >>> [E:60974r S:16553 M:96802260] (S) Msg RX from 1:FFFFFFFB00000000 [ADD1] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
[00:00:18.291][D][EM] Handling via exchange: 60974r, Delegate: 0x20018784
[00:00:18.309][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:00:18.313][P][FS] GeneralCommissioning: Received ArmFailSafe (164s)
[00:00:18.321][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29e
[00:00:18.328][D][DMG] Command handler moving to [NewRespons]
[00:00:18.335][D][DMG] Command handler moving to [ Preparing]
[00:00:18.341][D][DMG] Command handler moving to [AddingComm]
[00:00:18.346][D][DMG] Command handler moving to [AddedComma]
[00:00:18.352][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:18.357][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:18.365][D][DMG] Command handler moving to [AwaitingDe]
[00:00:18.373][P][EM] <<< [E:60974r S:16553 M:227232148] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [ADD1] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
[00:00:18.378][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 71)
[00:00:18.393][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:18.401][E][DL] Long dispatch time: 123 ms, for event type 7
[00:00:18.458][D][DL] ATT event 18: status 0
[00:00:18.460][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:18.487][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 78)
[00:00:18.489][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:18.497][P][EM] >>> [E:60975r S:16553 M:96802261] (S) Msg RX from 1:FFFFFFFB00000000 [ADD1] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
[00:00:18.502][D][EM] Handling via exchange: 60975r, Delegate: 0x20018784
[00:00:18.519][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
[00:00:18.524][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 3
[00:00:18.577][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 2
[00:00:18.578][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:18.605][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:18.606][D][DL] OpenThread State Changed (Flags: 0x1117d11d)
[00:00:18.612][D][DL]    Device Role: DETACHED
[00:00:18.618][D][DL]    Network Name: MyHome393191637
[00:00:18.622][D][DL]    PAN Id: 0x43DC
[00:00:18.627][D][DL]    Extended PAN Id: 0xFCDD50B9E62246DD
[00:00:18.631][D][DL]    Channel: 25
[00:00:18.636][D][DL]    Mesh Prefix: fd14:e564:87a4:0:0:0:0:0/64
[00:00:18.639][D][DL]    Thread Unicast Addresses:
[00:00:18.643][D][DL]         fd14:e564:87a4:0:e3fc:de61:a301:451/64 valid preferred
[00:00:18.650][D][DL]         fe80:0:0:0:90c8:d0bf:2d02:c8a9/64 valid preferred
[00:00:18.689][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6bd
[00:00:18.689][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6be
[00:00:18.696][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6bf
[00:00:19.061][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:19.062][D][DL] OpenThread State Changed (Flags: 0x00000100)
[00:00:19.682][P][DL] SRP Client was started, detected server: fd14:e564:87a4:0000:0000:00ff:fe00:fc10
[00:00:19.684][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:19.692][P][ZCL] ThreadDiagnosticsDelegate: OnConnectionStatusChanged
[00:00:19.699][D][EVL] LogEvent event number: 0x0000000000070003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0035 event id: 0x0 Sys timestamp: 0x0000000000004A5F
[00:00:19.705][D][DL] OpenThread State Changed (Flags: 0x200002a4)
[00:00:19.720][D][DL]    Device Role: CHILD
[00:00:19.726][D][DL]    Partition Id: 0x7E3E985A
[00:00:19.746][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6c0
[00:00:19.747][D][DMG] Endpoint 0, Cluster 0x0000_0031 update version to 4226b6c1
[00:00:19.754][P][DL] _OnPlatformEvent default:  event->Type = 32779
[00:00:19.761][D][DL] OpenThread State Changed (Flags: 0x00000001)
[00:00:19.767][D][DL]    Thread Unicast Addresses:
[00:00:19.774][D][DL]         fd21:3339:d223:0:b59f:104f:4a2e:55de/64 valid preferred
[00:00:19.774][D][DL]         fd14:e564:87a4:0:0:ff:fe00:380c/64 valid preferred rloc
[00:00:19.778][D][DL]         fd14:e564:87a4:0:e3fc:de61:a301:451/64 valid preferred
[00:00:19.793][D][DL]         fe80:0:0:0:90c8:d0bf:2d02:c8a9/64 valid preferred
[00:00:19.817][P][DL] _OnPlatformEvent default:  event->Type = 32769
[00:00:19.817][D][DL] Thread Attached updating Multicast address
[00:00:19.823][P][SVR] Joining Multicast groups
[00:00:19.832][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:19.834][D][DMG] Command handler moving to [NewRespons]
[00:00:19.841][D][DMG] Command handler moving to [ Preparing]
[00:00:19.847][D][DMG] Command handler moving to [AddingComm]
[00:00:19.852][D][DMG] Command handler moving to [AddedComma]
[00:00:19.858][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a29f
[00:00:19.863][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:19.871][D][DMG] Command handler moving to [AwaitingDe]
[00:00:19.879][P][EM] <<< [E:60975r S:16553 M:227232149] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [ADD1] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
[00:00:19.884][D][DL] Sending indication for CHIPoBLE Client TX (con 1, len 70)
[00:00:19.904][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:19.906][P][DL] _OnPlatformEvent default:  event->Type = 32785
[00:00:19.913][D][DL] Using Thread extended MAC for hostname.
[00:00:19.918][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:19.924][E][SVR] Operational advertising failed: 3
[00:00:19.985][D][DL] ATT event 18: status 0
[00:00:19.986][D][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
[00:00:20.425][D][DL] SRP update succeeded
[00:00:20.426][P][DL] _OnPlatformEvent default:  event->Type = 32786
[00:00:20.429][P][SVR] Server initialization complete
[00:00:20.435][P][DIS] Updating services using commissioning mode 0
[00:00:20.440][D][DL] Using Thread extended MAC for hostname.
[00:00:20.446][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:20.453][P][DL] advertising srp service: 7C0E543D6704ADD1-000000004B8824AB._matter._tcp
[00:00:20.460][D][DL] Using Thread extended MAC for hostname.
[00:00:20.468][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:20.474][P][DL] advertising srp service: 445042FFFE8C17A6._matterc._udp
[00:00:20.498][P][DL] Initialising OTA Requestor
[00:00:20.498][P][SWU] Stopping the watchdog timer
[00:00:20.503][P][SWU] Starting the poweron query timer, timeout: 60 seconds
[00:00:20.507][P][DL] _OnPlatformEvent default:  event->Type = 32790
[00:00:20.565][P][IM] No subscriptions to resume
[00:00:20.566][D][DMG] Endpoint 0, Cluster 0x0000_002A update version to c189044c
[00:00:20.570][D][DMG] Endpoint 0, Cluster 0x0000_002A update version to c189044d
[00:00:21.118][D][DL] SRP update succeeded
[00:00:21.642][D][IN] UDP Message Received packet nb : 1 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 196
[00:00:21.644][P][EM] >>> [E:60976r S:0 M:153612525] (U) Msg RX from 0:C581F249DAF2B5FA [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
[00:00:21.659][D][EM] Handling via exchange: 60976r, Delegate: 0x2000af98
[00:00:21.674][P][IN] CASE Server received Sigma1 message . Starting handshake. EC 0x2000bb38
[00:00:21.681][P][EM] <<< [E:60976r S:0 M:121417606 (Ack:153612525)] (U) Msg TX from 0000000000000000 to 0:C581F249DAF2B5FA [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:21.689][D][EM] Flushed pending ack for MessageCounter:153612525 on exchange 60976r
[00:00:21.710][P][SC] Received Sigma1 msg
[00:00:21.718][D][SC] Found MRP parameters in the message
[00:00:21.724][D][SC] Peer assigned session key ID 2399
[00:00:21.743][P][SC] CASE matched destination ID: fabricIndex 1, NodeID 0x000000004B8824AB
[00:00:21.792][P][EM] <<< [E:60976r S:0 M:121417607 (Ack:153612525)] (U) Msg TX from 0000000000000000 to 0:C581F249DAF2B5FA [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:527)
[00:00:21.794][P][EM] ??1 [E:60976r S:0 M:121417607] (U) Msg Retransmission to 0:0000000000000000 in 2389ms [State:Active II:500 AI:300 AT:4000]
[00:00:21.814][P][SC] Sent Sigma2 msg
[00:00:21.827][E][DL] Long dispatch time: 184 ms, for event type 3
[00:00:22.441][D][DL] Write request received for CHIPoBLE Client RX characteristic (con 1, len 3)
[00:00:22.442][D][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
[00:00:22.900][D][IN] UDP Message Received packet nb : 2 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 375
[00:00:22.902][P][EM] >>> [E:60976r S:0 M:153612526 (Ack:121417607)] (U) Msg RX from 0:C581F249DAF2B5FA [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:375)
[00:00:22.917][D][EM] Found matching exchange: 60976r, Delegate: 0x2000afb4
[00:00:22.934][D][EM] Rxd Ack; Removing MessageCounter:121417607 from Retrans Table on exchange 60976r
[00:00:22.942][P][EM] <<< [E:60976r S:0 M:121417608 (Ack:153612526)] (U) Msg TX from 0000000000000000 to 0:C581F249DAF2B5FA [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:22.951][D][EM] Flushed pending ack for MessageCounter:153612526 on exchange 60976r
[00:00:22.971][P][SC] Received Sigma3 msg
[00:00:22.988][D][SC] Certificate's mNotBeforeTime (748076442) is after current time (22)
[00:00:22.989][D][SC] Certificate's mNotBeforeTime (731054858) is after current time (22)
[00:00:23.077][D][SC] Sending status report. Protocol code 0, exchange 60976
[00:00:23.078][P][EM] <<< [E:60976r S:0 M:121417609 (Ack:153612526)] (U) Msg TX from 0000000000000000 to 0:C581F249DAF2B5FA [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[00:00:23.085][P][EM] ??1 [E:60976r S:0 M:121417609] (U) Msg Retransmission to 0:0000000000000000 in 2333ms [State:Active II:500 AI:300 AT:4000]
[00:00:23.095][P][SC] SecureSession[0x2000a108, LSID:16552]: State change 'kEstablishing' --> 'kActive'
[00:00:23.118][D][IN] SecureSession[0x2000a108]: Activated - Type:2 LSID:16552
[00:00:23.127][D][IN] New secure session activated for device <23C50D4337BF9971, 1>, LSID:16552 PSID:2399!
[00:00:23.134][P][IN] CASE Session established to peer: <23C50D4337BF9971, 1>
[00:00:23.144][D][IN] SecureSession[0x2000a2b8]: Allocated Type:2 LSID:16554
[00:00:23.150][D][SC] Allocated SecureSession (0x2000a2b8) - waiting for Sigma1 msg
[00:00:23.158][E][DL] Long dispatch time: 127 ms, for event type 2
[00:00:23.165][P][DL] _OnPlatformEvent default:  event->Type = 32792
[00:00:23.401][D][IN] UDP Message Received packet nb : 3 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 59
[00:00:23.405][P][EM] >>> [E:60977r S:16552 M:250376654] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[00:00:23.428][D][IN] UDP Message Received packet nb : 4 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 26
[00:00:23.418][D][EM] Handling via exchange: 60977r, Delegate: 0x20018784
[00:00:23.452][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[00:00:23.456][P][FS] GeneralCommissioning: Received CommissioningComplete
[00:00:23.495][P][FP] Metadata for Fabric 0x1 persisted to storage.
[00:00:23.568][P][TS] Committing Last Known Good Time to storage: 2025-12-10T04:04:28
[00:00:23.591][P][ZCL] OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x7C0E543D6704ADD1, FabricId 0000000000000001, NodeId 000000004B8824AB, VendorId 0x1384
[00:00:23.602][P][FS] GeneralCommissioning: Successfully committed pending fabric data
[00:00:23.608][P][FS] Fail-safe cleanly disarmed
[00:00:23.616][D][DMG] Endpoint 0, Cluster 0x0000_0030 update version to f989a2a0
[00:00:23.621][D][DMG] Command handler moving to [NewRespons]
[00:00:23.628][D][DMG] Command handler moving to [ Preparing]
[00:00:23.633][D][DMG] Command handler moving to [AddingComm]
[00:00:23.639][D][DMG] Command handler moving to [AddedComma]
[00:00:23.645][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:23.650][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:23.658][D][DMG] Command handler moving to [AwaitingDe]
[00:00:23.667][P][EM] <<< [E:60977r S:16552 M:86659737 (Ack:250376654)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:23.672][P][EM] ??1 [E:60977r S:16552 M:86659737] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2388ms [State:Active II:500 AI:300 AT:4000]
[00:00:23.692][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:23.693][E][DL] Long dispatch time: 290 ms, for event type 3
[00:00:23.712][P][EM] >>> [E:60976r S:0 M:153612527 (Ack:121417609)] (U) Msg RX from 0:C581F249DAF2B5FA [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:23.717][D][EM] Found matching exchange: 60976r, Delegate: 0
[00:00:23.734][D][EM] Rxd Ack; Removing MessageCounter:121417609 from Retrans Table on exchange 60976r
[00:00:23.740][P][DL] _OnPlatformEvent default:  event->Type = 32783
[00:00:23.748][P][SWU] Device commissioned, schedule a default provider query
[00:00:23.755][P][SVR] Commissioning completed successfully
[00:00:23.762][P][DIS] Updating services using commissioning mode 0
[00:00:23.767][D][DL] Using Thread extended MAC for hostname.
[00:00:23.773][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:23.779][D][DL] Using Thread extended MAC for hostname.
[00:00:23.787][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:23.793][D][IN] Expiring all PASE sessions
[00:00:23.802][D][IN] SecureSession[0x2000a1e0]: MarkForEviction Type:1 LSID:16553
[00:00:23.806][P][SC] SecureSession[0x2000a1e0, LSID:16553]: State change 'kActive' --> 'kPendingEviction'
[00:00:23.814][D][IN] SecureSession[0x2000a1e0]: Released - Type:1 LSID:16553
[00:00:23.823][D][IN] Clearing BLE pending packets.
[00:00:23.828][P][BLE] Releasing end point's BLE connection back to application.
[00:00:23.835][D][ZCL] Commissioning complete, notify platform driver to persist network credentials.
[00:00:23.852][E][DL] Long dispatch time: 112 ms, for event type 32783
[00:00:23.852][D][DL] DM event 40: status 0
[00:00:23.858][P][DL] BLE GATT connection closed (con 1, reason 19)
[00:00:23.864][D][DL] _OnPlatformEvent kCHIPoBLEConnectionError
[00:00:23.869][D][BLE] No endpoint for connection error
[00:00:24.255][D][IN] UDP Message Received packet nb : 5 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:24.267][D][IN] UDP Message Received packet nb : 6 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:24.281][D][IN] UDP Message Received packet nb : 7 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:24.296][D][IN] UDP Message Received packet nb : 8 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:24.259][P][EM] >>> [E:60977r S:16552 M:250376655 (Ack:86659737)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:24.321][D][EM] Found matching exchange: 60977r, Delegate: 0
[00:00:24.338][D][EM] Rxd Ack; Removing MessageCounter:86659737 from Retrans Table on exchange 60977r
[00:00:24.341][P][EM] >>> [E:60978r S:16552 M:250376656] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:24.353][D][EM] Handling via exchange: 60978r, Delegate: 0x20018784
[00:00:24.367][D][IM] Received Read request
[00:00:24.375][D][DMG] IM RH moving to [CanStartReporting]
[00:00:24.379][P][EM] >>> [E:60979r S:16552 M:250376657] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:24.383][D][EM] Handling via exchange: 60979r, Delegate: 0x20018784
[00:00:24.397][D][IM] Received Read request
[00:00:24.405][D][DMG] IM RH moving to [CanStartReporting]
[00:00:24.408][P][EM] >>> [E:60980r S:16552 M:250376658] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:24.413][D][EM] Handling via exchange: 60980r, Delegate: 0x20018784
[00:00:24.427][D][IM] Received Read request
[00:00:24.435][D][DMG] IM RH moving to [CanStartReporting]
[00:00:24.438][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:24.443][D][DMG]  Cluster 28, Attribute f is dirty
[00:00:24.455][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000F (expanded=0)
[00:00:24.461][D][DMG]  Sending report (payload has 44 bytes)...
[00:00:24.472][P][EM] <<< [E:60978r S:16552 M:86659738 (Ack:250376656)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:05 (IM:ReportData) (B:78)
[00:00:24.476][P][EM] ??1 [E:60978r S:16552 M:86659738] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2356ms [State:Active II:500 AI:300 AT:4000]
[00:00:24.497][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:24.510][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:24.515][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:24.585][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:24.586][D][DMG]  Cluster 3e, Attribute 1 is dirty
[00:00:24.598][D][DMG] Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:24.604][D][DMG]  Sending report (payload has 125 bytes)...
[00:00:24.615][P][EM] <<< [E:60979r S:16552 M:86659739 (Ack:250376657)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:05 (IM:ReportData) (B:159)
[00:00:24.621][P][EM] ??1 [E:60979r S:16552 M:86659739] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2347ms [State:Active II:500 AI:300 AT:4000]
[00:00:24.640][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:24.653][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:24.658][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:24.728][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:24.729][D][DMG]  Cluster 1d, Attribute 0 is dirty
[00:00:24.741][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[00:00:24.747][D][DMG]  Sending report (payload has 60 bytes)...
[00:00:24.758][P][EM] <<< [E:60980r S:16552 M:86659740 (Ack:250376658)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:05 (IM:ReportData) (B:94)
[00:00:24.763][P][EM] ??1 [E:60980r S:16552 M:86659740] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2331ms [State:Active II:500 AI:300 AT:4000]
[00:00:24.783][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:24.796][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:24.801][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:24.871][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:24.871][E][DL] Long dispatch time: 433 ms, for event type 3
[00:00:25.292][D][IN] UDP Message Received packet nb : 9 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:25.303][D][IN] UDP Message Received packet nb : 10 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:25.318][D][IN] UDP Message Received packet nb : 11 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:25.330][D][IN] UDP Message Received packet nb : 12 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:25.295][P][EM] >>> [E:60978r S:16552 M:250376659 (Ack:86659738)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:25.358][D][EM] Found matching exchange: 60978r, Delegate: 0
[00:00:25.375][D][EM] Rxd Ack; Removing MessageCounter:86659738 from Retrans Table on exchange 60978r
[00:00:25.382][P][EM] >>> [E:60979r S:16552 M:250376660 (Ack:86659739)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:25.390][D][EM] Found matching exchange: 60979r, Delegate: 0
[00:00:25.406][D][EM] Rxd Ack; Removing MessageCounter:86659739 from Retrans Table on exchange 60979r
[00:00:25.413][P][EM] >>> [E:60980r S:16552 M:250376661 (Ack:86659740)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:25.421][D][EM] Found matching exchange: 60980r, Delegate: 0
[00:00:25.438][D][EM] Rxd Ack; Removing MessageCounter:86659740 from Retrans Table on exchange 60980r
[00:00:25.445][P][EM] >>> [E:60981r S:16552 M:250376662] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:25.453][D][EM] Handling via exchange: 60981r, Delegate: 0x20018784
[00:00:25.458][D][IM] Received Read request
[00:00:25.475][D][DMG] IM RH moving to [CanStartReporting]
[00:00:25.478][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:25.483][D][DMG]  Cluster 1d, Attribute 0 is dirty
[00:00:25.495][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
[00:00:25.501][D][DMG]  Sending report (payload has 44 bytes)...
[00:00:25.512][P][EM] <<< [E:60981r S:16552 M:86659741 (Ack:250376662)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:05 (IM:ReportData) (B:78)
[00:00:25.518][P][EM] ??1 [E:60981r S:16552 M:86659741] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2341ms [State:Active II:500 AI:300 AT:4000]
[00:00:25.537][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:25.550][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:25.555][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:25.625][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:25.625][E][DL] Long dispatch time: 147 ms, for event type 3
[00:00:26.005][D][DIS] Extended discovery timed out
[00:00:26.005][P][DIS] Updating services using commissioning mode 0
[00:00:26.010][D][DL] Using Thread extended MAC for hostname.
[00:00:26.016][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:26.017][P][DL] removing srp service: 445042FFFE8C17A6._matterc._udp
[00:00:26.324][D][IN] UDP Message Received packet nb : 13 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:26.326][P][EM] >>> [E:60981r S:16552 M:250376663 (Ack:86659741)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:26.341][D][EM] Found matching exchange: 60981r, Delegate: 0
[00:00:26.358][D][EM] Rxd Ack; Removing MessageCounter:86659741 from Retrans Table on exchange 60981r
[00:00:26.510][D][DL] SRP update succeeded
[00:00:27.005][D][IN] UDP Message Received packet nb : 14 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 39
[00:00:27.007][P][EM] >>> [E:60982r S:16552 M:250376664] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:0A (IM:TimedRequest) (B:39)
[00:00:27.022][D][EM] Handling via exchange: 60982r, Delegate: 0x20018784
[00:00:27.036][D][DMG] Got Timed Request with timeout 9999: handler 0x20018a78 exchange 60982r
[00:00:27.044][P][EM] <<< [E:60982r S:16552 M:86659742 (Ack:250376664)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:01 (IM:StatusResponse) (B:42)
[00:00:27.052][P][EM] ??1 [E:60982r S:16552 M:86659742] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2342ms [State:Active II:500 AI:300 AT:4000]
[00:00:27.069][D][DMG] Timed Request time limit 0x00000000000090CC: handler 0x20018a78 exchange 60982r
[00:00:28.007][D][IN] UDP Message Received packet nb : 15 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 63
[00:00:28.009][P][EM] >>> [E:60982r S:16552 M:250376665 (Ack:86659742)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:08 (IM:InvokeCommandRequest) (B:63)
[00:00:28.024][D][EM] Found matching exchange: 60982r, Delegate: 0x20018a78
[00:00:28.040][D][EM] Rxd Ack; Removing MessageCounter:86659742 from Retrans Table on exchange 60982r
[00:00:28.047][D][DMG] Timed following action arrived at 0x0000000000006D8F: handler 0x20018a78 exchange 60982r
[00:00:28.056][D][DMG] Handing timed invoke to IM engine: handler 0x20018a78 exchange 60982r
[00:00:28.068][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0002
[00:00:28.074][P][ZCL] Received command to close commissioning window
[00:00:28.083][E][ZCL] Commissioning window is currently not open
[00:00:28.089][E][DMG] Endpoint=0 Cluster=0x0000_003C Command=0x0000_0002 status 0x01 ClusterSpecificCode=4 (no additional context)
[00:00:28.095][D][DMG] Command handler moving to [NewRespons]
[00:00:28.107][D][DMG] Command handler moving to [ Preparing]
[00:00:28.112][D][DMG] Command handler moving to [AddingComm]
[00:00:28.118][D][DMG] Command handler moving to [AddedComma]
[00:00:28.124][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:28.129][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:28.136][D][DMG] Command handler moving to [AwaitingDe]
[00:00:28.146][P][EM] <<< [E:60982r S:16552 M:86659743 (Ack:250376665)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:28.151][P][EM] ??1 [E:60982r S:16552 M:86659743] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2343ms [State:Active II:500 AI:300 AT:4000]
[00:00:28.171][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:28.184][E][DL] Long dispatch time: 176 ms, for event type 3
[00:00:28.705][D][IN] UDP Message Received packet nb : 16 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:28.719][D][IN] UDP Message Received packet nb : 17 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 39
[00:00:28.707][P][EM] >>> [E:60982r S:16552 M:250376666 (Ack:86659743)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:28.738][D][EM] Found matching exchange: 60982r, Delegate: 0
[00:00:28.755][D][EM] Rxd Ack; Removing MessageCounter:86659743 from Retrans Table on exchange 60982r
[00:00:28.762][P][EM] >>> [E:60983r S:16552 M:250376667] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:0A (IM:TimedRequest) (B:39)
[00:00:28.770][D][EM] Handling via exchange: 60983r, Delegate: 0x20018784
[00:00:28.784][D][DMG] Got Timed Request with timeout 10000: handler 0x20018a78 exchange 60983r
[00:00:28.792][P][EM] <<< [E:60983r S:16552 M:86659744 (Ack:250376667)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:01 (IM:StatusResponse) (B:42)
[00:00:28.800][P][EM] ??1 [E:60983r S:16552 M:86659744] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2363ms [State:Active II:500 AI:300 AT:4000]
[00:00:28.820][D][DMG] Timed Request time limit 0x00000000000097A4: handler 0x20018a78 exchange 60983r
[00:00:29.737][D][IN] UDP Message Received packet nb : 18 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 210
[00:00:29.740][P][EM] >>> [E:60983r S:16552 M:250376668 (Ack:86659744)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0001:08 (IM:InvokeCommandRequest) (B:210)
[00:00:29.755][D][EM] Found matching exchange: 60983r, Delegate: 0x20018a78
[00:00:29.771][D][EM] Rxd Ack; Removing MessageCounter:86659744 from Retrans Table on exchange 60983r
[00:00:29.778][D][DMG] Timed following action arrived at 0x0000000000007452: handler 0x20018a78 exchange 60983r
[00:00:29.787][D][DMG] Handing timed invoke to IM engine: handler 0x20018a78 exchange 60983r
[00:00:29.795][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000
[00:00:29.805][P][ZCL] Received command to open commissioning window
[00:00:29.814][D][IN] SecureSession[0x2000a1e0]: Allocated Type:1 LSID:16555
[00:00:29.820][D][SC] Assigned local session key ID 16555
[00:00:29.826][D][SC] Waiting for PBKDF param request
[00:00:29.835][P][DIS] Updating services using commissioning mode 2
[00:00:29.836][D][DL] Using Thread extended MAC for hostname.
[00:00:29.843][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:29.849][D][DL] Using Thread extended MAC for hostname.
[00:00:29.856][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=2404/09 cm=2 cp=0
[00:00:29.862][P][DL] advertising srp service: CFD1D6B207672765._matterc._udp
[00:00:29.872][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03223
[00:00:29.878][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03224
[00:00:29.886][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03225
[00:00:29.893][P][ZCL] Commissioning window is now open
[00:00:29.900][D][DMG] Command handler moving to [NewRespons]
[00:00:29.905][D][DMG] Command handler moving to [ Preparing]
[00:00:29.911][D][DMG] Command handler moving to [AddingComm]
[00:00:29.916][D][DMG] Command handler moving to [AddedComma]
[00:00:29.922][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:29.927][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:29.928][D][DMG] Command handler moving to [AwaitingDe]
[00:00:29.944][P][EM] <<< [E:60983r S:16552 M:86659745 (Ack:250376668)] (S) Msg TX from 000000004B8824AB to 1:23C50D4337BF9971 [ADD1] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:58284] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
[00:00:29.949][P][EM] ??1 [E:60983r S:16552 M:86659745] (S) Msg Retransmission to 1:23C50D4337BF9971 in 2330ms [State:Active II:500 AI:300 AT:4000]
[00:00:29.969][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:29.982][E][DL] Long dispatch time: 243 ms, for event type 3
[00:00:29.989][P][DL] _OnPlatformEvent default:  event->Type = 32793
[00:00:30.200][D][IN] UDP Message Received packet nb : 19 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[58284] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:30.212][D][DL] SRP update succeeded
[00:00:30.203][P][EM] >>> [E:60983r S:16552 M:250376669 (Ack:86659745)] (S) Msg RX from 1:23C50D4337BF9971 [ADD1] to 000000004B8824AB --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:30.221][D][EM] Found matching exchange: 60983r, Delegate: 0
[00:00:30.238][D][EM] Rxd Ack; Removing MessageCounter:86659745 from Retrans Table on exchange 60983r
[00:00:30.733][D][IN] UDP Message Received packet nb : 20 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 98
[00:00:30.734][P][EM] >>> [E:56618r S:0 M:122706419] (U) Msg RX from 0:2403737F38279DBE [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
[00:00:30.744][D][EM] Handling via exchange: 56618r, Delegate: 0x2000c3b8
[00:00:30.766][P][EM] <<< [E:56618r S:0 M:121417610 (Ack:122706419)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:30.772][D][EM] Flushed pending ack for MessageCounter:122706419 on exchange 56618r
[00:00:30.792][D][SC] Received PBKDF param request
[00:00:30.801][D][SC] Peer assigned session ID 23056
[00:00:30.805][D][SC] Found MRP parameters in the message
[00:00:30.813][P][EM] <<< [E:56618r S:0 M:121417611 (Ack:122706419)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:174)
[00:00:30.816][P][EM] ??1 [E:56618r S:0 M:121417611] (U) Msg Retransmission to 0:0000000000000000 in 2354ms [State:Active II:500 AI:300 AT:4000]
[00:00:30.837][D][SC] Sent PBKDF param response
[00:00:30.849][P][SVR] Commissioning session establishment step started
[00:00:30.854][E][DL] Long dispatch time: 120 ms, for event type 3
[00:00:31.242][D][IN] UDP Message Received packet nb : 21 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 96
[00:00:31.243][P][EM] >>> [E:56618r S:0 M:122706420 (Ack:121417611)] (U) Msg RX from 0:2403737F38279DBE [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:96)
[00:00:31.254][D][EM] Found matching exchange: 56618r, Delegate: 0x2000c3b8
[00:00:31.275][D][EM] Rxd Ack; Removing MessageCounter:121417611 from Retrans Table on exchange 56618r
[00:00:31.283][P][EM] <<< [E:56618r S:0 M:121417612 (Ack:122706420)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:31.291][D][EM] Flushed pending ack for MessageCounter:122706420 on exchange 56618r
[00:00:31.311][D][SC] Received spake2p msg1
[00:00:31.386][P][EM] <<< [E:56618r S:0 M:121417613 (Ack:122706420)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:131)
[00:00:31.388][P][EM] ??1 [E:56618r S:0 M:121417613] (U) Msg Retransmission to 0:0000000000000000 in 2399ms [State:Active II:500 AI:300 AT:4000]
[00:00:31.408][D][SC] Sent spake2p msg2
[00:00:31.421][E][DL] Long dispatch time: 178 ms, for event type 3
[00:00:31.722][D][IN] UDP Message Received packet nb : 22 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 63
[00:00:31.724][P][EM] >>> [E:56618r S:0 M:122706421 (Ack:121417613)] (U) Msg RX from 0:2403737F38279DBE [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:63)
[00:00:31.739][D][EM] Found matching exchange: 56618r, Delegate: 0x2000c3b8
[00:00:31.745][D][EM] Rxd Ack; Removing MessageCounter:121417613 from Retrans Table on exchange 56618r
[00:00:31.763][P][EM] <<< [E:56618r S:0 M:121417614 (Ack:122706421)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:31.772][D][EM] Flushed pending ack for MessageCounter:122706421 on exchange 56618r
[00:00:31.792][D][SC] Received spake2p msg3
[00:00:31.802][D][SC] Sending status report. Protocol code 0, exchange 56618
[00:00:31.805][P][EM] <<< [E:56618r S:0 M:121417615 (Ack:122706421)] (U) Msg TX from 0000000000000000 to 0:2403737F38279DBE [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[00:00:31.812][P][EM] ??1 [E:56618r S:0 M:121417615] (U) Msg Retransmission to 0:0000000000000000 in 2352ms [State:Active II:500 AI:300 AT:4000]
[00:00:31.836][P][SC] SecureSession[0x2000a1e0, LSID:16555]: State change 'kEstablishing' --> 'kActive'
[00:00:31.845][D][IN] SecureSession[0x2000a1e0]: Activated - Type:1 LSID:16555
[00:00:31.854][D][IN] New secure session activated for device , LSID:16555 PSID:23056!
[00:00:31.861][P][SVR] Commissioning completed session establishment step
[00:00:31.871][P][DIS] Updating services using commissioning mode 0
[00:00:31.877][D][DL] Using Thread extended MAC for hostname.
[00:00:31.880][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:31.890][D][DL] Using Thread extended MAC for hostname.
[00:00:31.897][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:31.903][P][DL] advertising srp service: CFD1D6B207672765._matterc._udp
[00:00:31.913][D][DIS] Scheduling extended discovery timeout in 20s
[00:00:31.919][P][SVR] Device completed Rendezvous process
[00:00:31.925][E][DL] Long dispatch time: 202 ms, for event type 3
[00:00:31.931][P][DL] _OnPlatformEvent default:  event->Type = 32792
[00:00:32.174][D][DL] SRP update succeeded
[00:00:32.675][D][IN] UDP Message Received packet nb : 23 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 26
[00:00:32.688][D][IN] UDP Message Received packet nb : 24 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:32.677][P][EM] >>> [E:56618r S:0 M:122706422 (Ack:121417615)] (U) Msg RX from 0:2403737F38279DBE [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:32.708][D][EM] Found matching exchange: 56618r, Delegate: 0
[00:00:32.725][D][EM] Rxd Ack; Removing MessageCounter:121417615 from Retrans Table on exchange 56618r
[00:00:32.732][P][EM] >>> [E:56619r S:16555 M:1531955] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:32.740][D][EM] Handling via exchange: 56619r, Delegate: 0x20018784
[00:00:32.744][D][IM] Received Read request
[00:00:32.762][D][DMG] IM RH moving to [CanStartReporting]
[00:00:32.764][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:32.770][D][DMG]  Cluster 30, Attribute 1 is dirty
[00:00:32.782][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:00:32.788][D][DMG]  Sending report (payload has 43 bytes)...
[00:00:32.799][P][EM] <<< [E:56619r S:16555 M:154028311 (Ack:1531955)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:77)
[00:00:32.804][P][EM] ??1 [E:56619r S:16555 M:154028311] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2342ms [State:Active II:500 AI:300 AT:4000]
[00:00:32.824][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:32.837][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:32.842][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:32.912][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:32.912][E][DL] Long dispatch time: 148 ms, for event type 3
[00:00:33.185][D][IN] UDP Message Received packet nb : 25 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:33.196][D][IN] UDP Message Received packet nb : 26 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 65
[00:00:33.188][P][EM] >>> [E:56619r S:16555 M:1531956 (Ack:154028311)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:33.218][D][EM] Found matching exchange: 56619r, Delegate: 0
[00:00:33.235][D][EM] Rxd Ack; Removing MessageCounter:154028311 from Retrans Table on exchange 56619r
[00:00:33.242][P][EM] >>> [E:56620r S:16555 M:1531957] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
[00:00:33.250][D][EM] Handling via exchange: 56620r, Delegate: 0x20018784
[00:00:33.266][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:00:33.271][P][FS] GeneralCommissioning: Received ArmFailSafe (120s)
[00:00:33.280][D][DMG] Command handler moving to [NewRespons]
[00:00:33.286][D][DMG] Command handler moving to [ Preparing]
[00:00:33.292][D][DMG] Command handler moving to [AddingComm]
[00:00:33.297][D][DMG] Command handler moving to [AddedComma]
[00:00:33.303][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:33.308][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:33.316][D][DMG] Command handler moving to [AwaitingDe]
[00:00:33.325][P][EM] <<< [E:56620r S:16555 M:154028312 (Ack:1531957)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:33.330][P][EM] ??1 [E:56620r S:16555 M:154028312] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2332ms [State:Active II:500 AI:300 AT:4000]
[00:00:33.350][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:33.363][E][DL] Long dispatch time: 122 ms, for event type 3
[00:00:33.694][D][IN] UDP Message Received packet nb : 27 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:33.697][P][EM] >>> [E:56620r S:16555 M:1531958 (Ack:154028312)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:33.711][D][EM] Found matching exchange: 56620r, Delegate: 0
[00:00:33.728][D][EM] Rxd Ack; Removing MessageCounter:154028312 from Retrans Table on exchange 56620r
[00:00:35.201][D][IN] UDP Message Received packet nb : 28 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 94
[00:00:35.203][P][EM] >>> [E:56621r S:16555 M:1531959] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
[00:00:35.218][D][EM] Handling via exchange: 56621r, Delegate: 0x20018784
[00:00:35.235][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
[00:00:35.240][P][ZCL] OpCreds: Received an AttestationRequest command
[00:00:35.245][P][EM] <<< [E:56621r S:16555 M:154028313 (Ack:1531959)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:35.255][D][EM] Flushed pending ack for MessageCounter:1531959 on exchange 56621r
[00:00:35.288][P][ZCL] OpCreds: AttestationRequest successful.
[00:00:35.288][D][DMG] Command handler moving to [NewRespons]
[00:00:35.294][D][DMG] Command handler moving to [ Preparing]
[00:00:35.299][D][DMG] Command handler moving to [AddingComm]
[00:00:35.305][D][DMG] Command handler moving to [AddedComma]
[00:00:35.311][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:35.316][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:35.324][D][DMG] Command handler moving to [AwaitingDe]
[00:00:35.333][P][EM] <<< [E:56621r S:16555 M:154028314 (Ack:1531959)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:412)
[00:00:35.338][P][EM] ??1 [E:56621r S:16555 M:154028314] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2367ms [State:Active II:500 AI:300 AT:4000]
[00:00:35.358][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:35.371][E][DL] Long dispatch time: 169 ms, for event type 3
[00:00:35.695][D][IN] UDP Message Received packet nb : 29 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:35.698][P][EM] >>> [E:56621r S:16555 M:1531960 (Ack:154028314)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:35.721][D][IN] UDP Message Received packet nb : 30 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 62
[00:00:35.712][D][EM] Found matching exchange: 56621r, Delegate: 0
[00:00:35.745][D][EM] Rxd Ack; Removing MessageCounter:154028314 from Retrans Table on exchange 56621r
[00:00:35.752][P][EM] >>> [E:56622r S:16555 M:1531961] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
[00:00:35.760][D][EM] Handling via exchange: 56622r, Delegate: 0x20018784
[00:00:35.777][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:00:35.782][P][ZCL] OpCreds: Certificate Chain request received for DAC
[00:00:35.790][D][DMG] Command handler moving to [NewRespons]
[00:00:35.797][D][DMG] Command handler moving to [ Preparing]
[00:00:35.802][D][DMG] Command handler moving to [AddingComm]
[00:00:35.808][D][DMG] Command handler moving to [AddedComma]
[00:00:35.814][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:35.819][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:35.827][D][DMG] Command handler moving to [AwaitingDe]
[00:00:35.832][P][EM] <<< [E:56622r S:16555 M:154028315 (Ack:1531961)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:551)
[00:00:35.841][P][EM] ??1 [E:56622r S:16555 M:154028315] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2390ms [State:Active II:500 AI:300 AT:4000]
[00:00:35.861][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:35.874][E][DL] Long dispatch time: 123 ms, for event type 3
[00:00:36.199][D][IN] UDP Message Received packet nb : 31 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:36.212][D][IN] UDP Message Received packet nb : 32 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 62
[00:00:36.202][P][EM] >>> [E:56622r S:16555 M:1531962 (Ack:154028315)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:36.232][D][EM] Found matching exchange: 56622r, Delegate: 0
[00:00:36.249][D][EM] Rxd Ack; Removing MessageCounter:154028315 from Retrans Table on exchange 56622r
[00:00:36.256][P][EM] >>> [E:56623r S:16555 M:1531963] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
[00:00:36.264][D][EM] Handling via exchange: 56623r, Delegate: 0x20018784
[00:00:36.281][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:00:36.285][P][ZCL] OpCreds: Certificate Chain request received for PAI
[00:00:36.294][D][DMG] Command handler moving to [NewRespons]
[00:00:36.300][D][DMG] Command handler moving to [ Preparing]
[00:00:36.306][D][DMG] Command handler moving to [AddingComm]
[00:00:36.312][D][DMG] Command handler moving to [AddedComma]
[00:00:36.317][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:36.323][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:36.330][D][DMG] Command handler moving to [AwaitingDe]
[00:00:36.339][P][EM] <<< [E:56623r S:16555 M:154028316 (Ack:1531963)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:511)
[00:00:36.345][P][EM] ??1 [E:56623r S:16555 M:154028316] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2354ms [State:Active II:500 AI:300 AT:4000]
[00:00:36.365][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:36.378][E][DL] Long dispatch time: 123 ms, for event type 3
[00:00:36.703][D][IN] UDP Message Received packet nb : 33 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:36.715][D][IN] UDP Message Received packet nb : 34 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:36.706][P][EM] >>> [E:56623r S:16555 M:1531964 (Ack:154028316)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:36.728][D][EM] Found matching exchange: 56623r, Delegate: 0
[00:00:36.753][D][EM] Rxd Ack; Removing MessageCounter:154028316 from Retrans Table on exchange 56623r
[00:00:36.760][P][EM] >>> [E:56624r S:16555 M:1531965] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:36.769][D][EM] Handling via exchange: 56624r, Delegate: 0x20018784
[00:00:36.783][D][IM] Received Read request
[00:00:36.791][D][DMG] IM RH moving to [CanStartReporting]
[00:00:36.793][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:36.798][D][DMG]  Cluster 28, Attribute 2 is dirty
[00:00:36.811][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:00:36.817][D][DMG]  Sending report (payload has 37 bytes)...
[00:00:36.828][P][EM] <<< [E:56624r S:16555 M:154028317 (Ack:1531965)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:71)
[00:00:36.833][P][EM] ??1 [E:56624r S:16555 M:154028317] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2374ms [State:Active II:500 AI:300 AT:4000]
[00:00:36.853][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:36.862][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:36.871][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:36.940][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:36.941][E][DL] Long dispatch time: 148 ms, for event type 3
[00:00:37.215][D][IN] UDP Message Received packet nb : 35 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:37.226][D][IN] UDP Message Received packet nb : 36 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:37.218][P][EM] >>> [E:56624r S:16555 M:1531966 (Ack:154028317)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:37.248][D][EM] Found matching exchange: 56624r, Delegate: 0
[00:00:37.265][D][EM] Rxd Ack; Removing MessageCounter:154028317 from Retrans Table on exchange 56624r
[00:00:37.272][P][EM] >>> [E:56625r S:16555 M:1531967] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:37.280][D][EM] Handling via exchange: 56625r, Delegate: 0x20018784
[00:00:37.294][D][IM] Received Read request
[00:00:37.302][D][DMG] IM RH moving to [CanStartReporting]
[00:00:37.305][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:37.310][D][DMG]  Cluster 28, Attribute 4 is dirty
[00:00:37.316][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[00:00:37.328][D][DMG]  Sending report (payload has 37 bytes)...
[00:00:37.339][P][EM] <<< [E:56625r S:16555 M:154028318 (Ack:1531967)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:71)
[00:00:37.345][P][EM] ??1 [E:56625r S:16555 M:154028318] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2377ms [State:Active II:500 AI:300 AT:4000]
[00:00:37.364][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:37.377][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:37.382][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:37.452][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:37.452][E][DL] Long dispatch time: 147 ms, for event type 3
[00:00:37.725][D][IN] UDP Message Received packet nb : 37 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:37.736][D][IN] UDP Message Received packet nb : 38 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 51
[00:00:37.728][P][EM] >>> [E:56625r S:16555 M:1531968 (Ack:154028318)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:37.758][D][EM] Found matching exchange: 56625r, Delegate: 0
[00:00:37.768][D][EM] Rxd Ack; Removing MessageCounter:154028318 from Retrans Table on exchange 56625r
[00:00:37.782][P][EM] >>> [E:56626r S:16555 M:1531969] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
[00:00:37.790][D][EM] Handling via exchange: 56626r, Delegate: 0x20018784
[00:00:37.804][D][IM] Received Read request
[00:00:37.812][D][DMG] IM RH moving to [CanStartReporting]
[00:00:37.815][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:37.820][D][DMG]  Cluster 28, Attribute 3 is dirty
[00:00:37.832][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[00:00:37.838][D][DMG]  Sending report (payload has 67 bytes)...
[00:00:37.849][P][EM] <<< [E:56626r S:16555 M:154028319 (Ack:1531969)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:101)
[00:00:37.855][P][EM] ??1 [E:56626r S:16555 M:154028319] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2334ms [State:Active II:500 AI:300 AT:4000]
[00:00:37.874][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:37.887][D][DMG]  ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:00:37.892][D][DMG] IM RH moving to [AwaitingDestruction]
[00:00:37.962][D][DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[00:00:37.962][E][DL] Long dispatch time: 147 ms, for event type 3
[00:00:38.234][D][IN] UDP Message Received packet nb : 39 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:38.237][P][EM] >>> [E:56626r S:16555 M:1531970 (Ack:154028319)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:38.257][D][IN] UDP Message Received packet nb : 40 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 94
[00:00:38.251][D][EM] Found matching exchange: 56626r, Delegate: 0
[00:00:38.284][D][EM] Rxd Ack; Removing MessageCounter:154028319 from Retrans Table on exchange 56626r
[00:00:38.291][P][EM] >>> [E:56627r S:16555 M:1531971] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
[00:00:38.299][D][EM] Handling via exchange: 56627r, Delegate: 0x20018784
[00:00:38.315][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
[00:00:38.320][P][ZCL] OpCreds: Received a CSRRequest command
[00:00:38.328][D][ZCL] OpCreds: Finding fabric with fabricIndex 0x0
[00:00:38.335][P][EM] <<< [E:56627r S:16555 M:154028320 (Ack:1531971)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:38.341][D][EM] Flushed pending ack for MessageCounter:1531971 on exchange 56627r
[00:00:38.382][P][ZCL] OpCreds: AllocatePendingOperationalKey succeeded
[00:00:38.395][P][ZCL] OpCreds: CSRRequest successful.
[00:00:38.395][D][DMG] Command handler moving to [NewRespons]
[00:00:38.400][D][DMG] Command handler moving to [ Preparing]
[00:00:38.405][D][DMG] Command handler moving to [AddingComm]
[00:00:38.411][D][DMG] Command handler moving to [AddedComma]
[00:00:38.417][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:38.422][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:38.430][D][DMG] Command handler moving to [AwaitingDe]
[00:00:38.439][P][EM] <<< [E:56627r S:16555 M:154028321 (Ack:1531971)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:380)
[00:00:38.444][P][EM] ??1 [E:56627r S:16555 M:154028321] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2395ms [State:Active II:500 AI:300 AT:4000]
[00:00:38.464][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:38.477][E][DL] Long dispatch time: 187 ms, for event type 3
[00:00:38.755][D][IN] UDP Message Received packet nb : 41 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:38.757][P][EM] >>> [E:56627r S:16555 M:1531972 (Ack:154028321)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:38.772][D][EM] Found matching exchange: 56627r, Delegate: 0
[00:00:38.773][D][EM] Rxd Ack; Removing MessageCounter:154028321 from Retrans Table on exchange 56627r
[00:00:40.291][D][IN] UDP Message Received packet nb : 42 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 367
[00:00:40.293][P][EM] >>> [E:56628r S:16555 M:1531973] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:367)
[00:00:40.308][D][EM] Handling via exchange: 56628r, Delegate: 0x20018784
[00:00:40.325][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
[00:00:40.330][P][ZCL] OpCreds: Received an AddTrustedRootCertificate command
[00:00:40.339][P][EM] <<< [E:56628r S:16555 M:154028322 (Ack:1531973)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:40.345][D][EM] Flushed pending ack for MessageCounter:1531973 on exchange 56628r
[00:00:40.387][P][ZCL] OpCreds: AddTrustedRootCertificate successful.
[00:00:40.387][D][DMG] Command handler moving to [NewRespons]
[00:00:40.393][D][DMG] Command handler moving to [ Preparing]
[00:00:40.399][D][DMG] Command handler moving to [AddingComm]
[00:00:40.404][D][DMG] Command handler moving to [AddedComma]
[00:00:40.409][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:40.415][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:40.423][D][DMG] Command handler moving to [AwaitingDe]
[00:00:40.432][P][EM] <<< [E:56628r S:16555 M:154028323 (Ack:1531973)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:67)
[00:00:40.437][P][EM] ??1 [E:56628r S:16555 M:154028323] (S) Msg Retransmission to 0:FFFFFFFB00000000 in 2404ms [State:Active II:500 AI:300 AT:4000]
[00:00:40.457][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:40.470][E][DL] Long dispatch time: 178 ms, for event type 3
[00:00:40.792][D][IN] UDP Message Received packet nb : 43 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:40.795][P][EM] >>> [E:56628r S:16555 M:1531974 (Ack:154028323)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:40.809][D][EM] Found matching exchange: 56628r, Delegate: 0
[00:00:40.826][D][EM] Rxd Ack; Removing MessageCounter:154028323 from Retrans Table on exchange 56628r
[00:00:40.901][D][IN] UDP Message Received packet nb : 44 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 713
[00:00:40.904][P][EM] >>> [E:56629r S:16555 M:1531975] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:713)
[00:00:40.915][D][EM] Handling via exchange: 56629r, Delegate: 0x20018784
[00:00:40.936][D][DMG] Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
[00:00:40.940][P][ZCL] OpCreds: Received an AddNOC command
[00:00:40.950][P][EM] <<< [E:56629r S:16555 M:154028324 (Ack:1531975)] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:40.954][D][EM] Flushed pending ack for MessageCounter:1531975 on exchange 56629r
[00:00:40.988][P][FP] Validating NOC chain
[00:00:41.026][P][FP] NOC chain validation successful
[00:00:41.026][P][FP] Added new fabric at index: 0x2
[00:00:41.031][P][FP] Assigned compressed fabric ID: 0x066F15BDCCBD6A2D, node ID: 0x000000006029D15D
[00:00:41.036][P][TS] Last Known Good Time: 2025-12-10T04:04:28
[00:00:41.045][P][TS] New proposed Last Known Good Time: 2025-12-10T02:34:51
[00:00:41.050][P][TS] Retaining current Last Known Good Time
[00:00:41.057][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b17
[00:00:41.063][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b18
[00:00:41.147][D][EVL] Copy Event to next buffer with priority 1
[00:00:41.148][D][EVL] LogEvent event number: 0x0000000000070004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000009E27
[00:00:41.153][P][ZCL] OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0xFFFFFFFD00010001
[00:00:41.160][D][DL] Using Thread extended MAC for hostname.
[00:00:41.178][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:41.184][D][DL] Using Thread extended MAC for hostname.
[00:00:41.191][P][DIS] Advertise operational node 066F15BDCCBD6A2D-000000006029D15D
[00:00:41.197][P][DL] advertising srp service: 066F15BDCCBD6A2D-000000006029D15D._matter._tcp
[00:00:41.205][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b19
[00:00:41.212][D][DMG] Endpoint 0, Cluster 0x0000_003E update version to 1e859b1a
[00:00:41.220][D][DMG] Command handler moving to [NewRespons]
[00:00:41.227][D][DMG] Command handler moving to [ Preparing]
[00:00:41.233][D][DMG] Command handler moving to [AddingComm]
[00:00:41.238][D][DMG] Command handler moving to [AddedComma]
[00:00:41.244][P][ZCL] OpCreds: successfully created fabric index 0x2 via AddNOC
[00:00:41.250][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:41.256][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:41.264][D][DMG] Command handler moving to [AwaitingDe]
[00:00:41.273][P][EM] <<< [E:56629r S:16555 M:154028325 (Ack:1531975)] (S) Msg TX from 0000000000000000 to 2:FFFFFFFB00000000 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:41.278][P][EM] ??1 [E:56629r S:16555 M:154028325] (S) Msg Retransmission to 2:FFFFFFFB00000000 in 2384ms [State:Active II:500 AI:300 AT:4000]
[00:00:41.295][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:41.311][E][DL] Long dispatch time: 409 ms, for event type 3
[00:00:41.394][D][IN] UDP Message Received packet nb : 45 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:41.407][D][IN] UDP Message Received packet nb : 46 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 65
[00:00:41.397][P][EM] >>> [E:56629r S:16555 M:1531976 (Ack:154028325)] (S) Msg RX from 2:FFFFFFFB00000000 [6A2D] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:41.428][D][EM] Found matching exchange: 56629r, Delegate: 0
[00:00:41.444][D][EM] Rxd Ack; Removing MessageCounter:154028325 from Retrans Table on exchange 56629r
[00:00:41.451][P][EM] >>> [E:56630r S:16555 M:1531977] (S) Msg RX from 2:FFFFFFFB00000000 [6A2D] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
[00:00:41.459][D][EM] Handling via exchange: 56630r, Delegate: 0x20018784
[00:00:41.476][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:00:41.481][P][FS] GeneralCommissioning: Received ArmFailSafe (180s)
[00:00:41.489][D][DMG] Command handler moving to [NewRespons]
[00:00:41.495][D][DMG] Command handler moving to [ Preparing]
[00:00:41.501][D][DMG] Command handler moving to [AddingComm]
[00:00:41.507][D][DMG] Command handler moving to [AddedComma]
[00:00:41.512][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:41.518][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:41.525][D][DMG] Command handler moving to [AwaitingDe]
[00:00:41.534][P][EM] <<< [E:56630r S:16555 M:154028326 (Ack:1531977)] (S) Msg TX from 0000000000000000 to 2:FFFFFFFB00000000 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:41.539][P][EM] ??1 [E:56630r S:16555 M:154028326] (S) Msg Retransmission to 2:FFFFFFFB00000000 in 2384ms [State:Active II:500 AI:300 AT:4000]
[00:00:41.559][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:41.573][E][DL] Long dispatch time: 123 ms, for event type 3
[00:00:41.668][D][IN] UDP Message Received packet nb : 47 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:41.670][P][EM] >>> [E:56630r S:16555 M:1531978 (Ack:154028326)] (S) Msg RX from 2:FFFFFFFB00000000 [6A2D] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:41.685][D][EM] Found matching exchange: 56630r, Delegate: 0
[00:00:41.702][D][EM] Rxd Ack; Removing MessageCounter:154028326 from Retrans Table on exchange 56630r
[00:00:41.859][D][DL] SRP update succeeded
[00:00:43.376][D][IN] UDP Message Received packet nb : 48 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 196
[00:00:43.377][P][EM] >>> [E:56631r S:0 M:122706423] (U) Msg RX from 0:9BA4545738F4AD02 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
[00:00:43.393][D][EM] Handling via exchange: 56631r, Delegate: 0x2000af98
[00:00:43.408][P][IN] CASE Server received Sigma1 message . Starting handshake. EC 0x2000bb38
[00:00:43.415][P][EM] <<< [E:56631r S:0 M:121417616 (Ack:122706423)] (U) Msg TX from 0000000000000000 to 0:9BA4545738F4AD02 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:43.423][D][EM] Flushed pending ack for MessageCounter:122706423 on exchange 56631r
[00:00:43.443][P][SC] Received Sigma1 msg
[00:00:43.452][D][SC] Found MRP parameters in the message
[00:00:43.456][D][SC] Peer assigned session key ID 23057
[00:00:43.492][P][SC] CASE matched destination ID: fabricIndex 2, NodeID 0x000000006029D15D
[00:00:43.534][P][EM] <<< [E:56631r S:0 M:121417617 (Ack:122706423)] (U) Msg TX from 0000000000000000 to 0:9BA4545738F4AD02 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:894)
[00:00:43.537][P][EM] ??1 [E:56631r S:0 M:121417617] (U) Msg Retransmission to 0:0000000000000000 in 2363ms [State:Active II:500 AI:300 AT:4000]
[00:00:43.556][P][SC] Sent Sigma2 msg
[00:00:43.569][E][DL] Long dispatch time: 192 ms, for event type 3
[00:00:44.449][D][IN] UDP Message Received packet nb : 49 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 744
[00:00:44.451][P][EM] >>> [E:56631r S:0 M:122706424 (Ack:121417617)] (U) Msg RX from 0:9BA4545738F4AD02 [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:744)
[00:00:44.466][D][EM] Found matching exchange: 56631r, Delegate: 0x2000afb4
[00:00:44.483][D][EM] Rxd Ack; Removing MessageCounter:121417617 from Retrans Table on exchange 56631r
[00:00:44.491][P][EM] <<< [E:56631r S:0 M:121417618 (Ack:122706424)] (U) Msg TX from 0000000000000000 to 0:9BA4545738F4AD02 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:44.499][D][EM] Flushed pending ack for MessageCounter:122706424 on exchange 56631r
[00:00:44.519][P][SC] Received Sigma3 msg
[00:00:44.538][D][SC] Certificate's mNotBeforeTime (809587413) is after current time (44)
[00:00:44.539][D][SC] Certificate's mNotBeforeTime (692310848) is after current time (44)
[00:00:44.547][D][SC] Certificate's mNotBeforeTime (692310655) is after current time (44)
[00:00:44.654][D][SC] Sending status report. Protocol code 0, exchange 56631
[00:00:44.655][P][EM] <<< [E:56631r S:0 M:121417619 (Ack:122706424)] (U) Msg TX from 0000000000000000 to 0:9BA4545738F4AD02 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[00:00:44.661][P][EM] ??1 [E:56631r S:0 M:121417619] (U) Msg Retransmission to 0:0000000000000000 in 2403ms [State:Active II:500 AI:300 AT:4000]
[00:00:44.681][P][SC] SecureSession[0x2000a2b8, LSID:16554]: State change 'kEstablishing' --> 'kActive'
[00:00:44.695][D][IN] SecureSession[0x2000a2b8]: Activated - Type:2 LSID:16554
[00:00:44.704][D][IN] New secure session activated for device <00000000F36C72E8, 2>, LSID:16554 PSID:23057!
[00:00:44.711][P][IN] CASE Session established to peer: <00000000F36C72E8, 2>
[00:00:44.721][D][IN] SecureSession[0x2000a390]: Allocated Type:2 LSID:16556
[00:00:44.727][D][SC] Allocated SecureSession (0x2000a390) - waiting for Sigma1 msg
[00:00:44.734][E][DL] Long dispatch time: 133 ms, for event type 2
[00:00:44.742][P][DL] _OnPlatformEvent default:  event->Type = 32792
[00:00:45.453][D][IN] UDP Message Received packet nb : 50 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 58
[00:00:45.463][D][IN] UDP Message Received packet nb : 51 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 26
[00:00:45.456][P][EM] >>> [E:56632r S:16554 M:113082177] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:03 (IM:SubscribeRequest) (B:58)
[00:00:45.487][D][EM] Handling via exchange: 56632r, Delegate: 0x20018784
[00:00:45.501][D][IM] Received Subscribe request
[00:00:45.510][P][DMG] Final negotiated min/max parameters: Min = 0s, Max = 1800s
[00:00:45.512][D][DMG] IM RH moving to [CanStartReporting]
[00:00:45.608][E][DL] Long dispatch time: 153 ms, for event type 3
[00:00:45.609][P][EM] >>> [E:56631r S:0 M:122706425 (Ack:121417619)] (U) Msg RX from 0:9BA4545738F4AD02 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:45.614][D][EM] Found matching exchange: 56631r, Delegate: 0
[00:00:45.631][D][EM] Rxd Ack; Removing MessageCounter:121417619 from Retrans Table on exchange 56631r
[00:00:45.637][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:45.646][D][DMG]  Cluster 1d, Attribute 0 is dirty
[00:00:45.658][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:45.665][D][DMG]  Cluster 1d, Attribute 1 is dirty
[00:00:45.674][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:45.680][D][DMG]  Cluster 1d, Attribute 2 is dirty
[00:00:45.689][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:45.695][D][DMG]  Cluster 1d, Attribute 3 is dirty
[00:00:45.705][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:45.711][D][DMG]  Cluster 1d, Attribute fffc is dirty
[00:00:45.720][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:45.727][D][DMG]  Cluster 1d, Attribute fffd is dirty
[00:00:45.730][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:45.743][D][DMG]  Cluster 1d, Attribute fff8 is dirty
[00:00:45.752][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:45.758][D][DMG]  Cluster 1d, Attribute fff9 is dirty
[00:00:45.768][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:45.774][D][DMG]  Cluster 1d, Attribute fffb is dirty
[00:00:45.784][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:45.790][D][DMG]  Cluster 1f, Attribute 0 is dirty
[00:00:45.800][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:45.806][D][DMG]  Cluster 1f, Attribute 2 is dirty
[00:00:45.815][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:45.821][D][DMG]  Cluster 1f, Attribute 3 is dirty
[00:00:45.831][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:45.837][D][DMG]  Cluster 1f, Attribute 4 is dirty
[00:00:45.846][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0004 (expanded=1)
[00:00:45.852][D][DMG]  Cluster 1f, Attribute fffc is dirty
[00:00:45.862][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:45.865][D][DMG]  Cluster 1f, Attribute fffd is dirty
[00:00:45.878][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:45.884][D][DMG]  Cluster 1f, Attribute fff8 is dirty
[00:00:45.893][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:45.900][D][DMG]  Cluster 1f, Attribute fff9 is dirty
[00:00:45.909][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:45.916][D][DMG]  Cluster 1f, Attribute fffb is dirty
[00:00:45.925][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:45.932][D][DMG]  Cluster 28, Attribute 0 is dirty
[00:00:45.941][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:45.947][D][DMG]  Cluster 28, Attribute 1 is dirty
[00:00:45.957][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:45.962][D][DMG]  Cluster 28, Attribute 2 is dirty
[00:00:45.972][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:45.978][D][DMG]  Cluster 28, Attribute 3 is dirty
[00:00:45.988][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:45.994][D][DMG]  Cluster 28, Attribute 4 is dirty
[00:00:46.000][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=1)
[00:00:46.009][D][DMG]  Cluster 28, Attribute 5 is dirty
[00:00:46.019][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0005 (expanded=1)
[00:00:46.025][D][DMG]  Cluster 28, Attribute 6 is dirty
[00:00:46.034][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0006 (expanded=1)
[00:00:46.043][D][DMG]  Cluster 28, Attribute 7 is dirty
[00:00:46.050][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0007 (expanded=1)
[00:00:46.056][D][DMG]  Cluster 28, Attribute 8 is dirty
[00:00:46.065][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0008 (expanded=1)
[00:00:46.072][D][DMG]  Cluster 28, Attribute 9 is dirty
[00:00:46.081][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0009 (expanded=1)
[00:00:46.087][D][DMG]  Cluster 28, Attribute a is dirty
[00:00:46.097][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000A (expanded=1)
[00:00:46.103][D][DMG]  Cluster 28, Attribute b is dirty
[00:00:46.112][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000B (expanded=1)
[00:00:46.118][D][DMG]  Cluster 28, Attribute c is dirty
[00:00:46.128][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000C (expanded=1)
[00:00:46.134][D][DMG]  Cluster 28, Attribute d is dirty
[00:00:46.135][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000D (expanded=1)
[00:00:46.149][D][DMG]  Cluster 28, Attribute e is dirty
[00:00:46.159][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000E (expanded=1)
[00:00:46.165][D][DMG]  Cluster 28, Attribute f is dirty
[00:00:46.174][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000F (expanded=1)
[00:00:46.180][D][DMG]  Cluster 28, Attribute 10 is dirty
[00:00:46.190][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0010 (expanded=1)
[00:00:46.196][D][DMG]  Cluster 28, Attribute 12 is dirty
[00:00:46.205][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0012 (expanded=1)
[00:00:46.212][D][DMG] Next attribute value does not fit in packet, roll back on clusterId: 0x0000_0028, attributeId: 0x0000_0012, err = b
[00:00:46.221][D][DMG]  We cannot put more chunks into this report. Enable chunking.
[00:00:46.234][D][DMG]  first cluster event is too big so that it fails to fit in the packet!
[00:00:46.242][D][DMG] Fetched 0 events
[00:00:46.251][D][DMG]  Sending report (payload has 1175 bytes)...
[00:00:46.256][P][EM] <<< [E:56632r S:16554 M:260512640 (Ack:113082177)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:1209)
[00:00:46.263][P][EM] ??1 [E:56632r S:16554 M:260512640] (S) Msg Retransmission to 2:00000000F36C72E8 in 2386ms [State:Active II:500 AI:300 AT:4000]
[00:00:46.270][D][DMG] IM RH moving to [AwaitingReportResponse]
[00:00:46.294][D][DMG]  ReportsInFlight = 1 with readHandler 0, RE has more messages
[00:00:46.300][E][DL] Long dispatch time: 663 ms, for event type 3
[00:00:46.951][D][IN] UDP Message Received packet nb : 52 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 42
[00:00:46.963][D][IN] UDP Message Received packet nb : 53 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 59
[00:00:46.954][P][EM] >>> [E:56632r S:16554 M:113082178 (Ack:260512640)] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:01 (IM:StatusResponse) (B:42)
[00:00:46.984][D][EM] Found matching exchange: 56632r, Delegate: 0x2001a034
[00:00:47.000][D][EM] Rxd Ack; Removing MessageCounter:260512640 from Retrans Table on exchange 56632r
[00:00:47.007][P][IM] Received status response, status is 0x00
[00:00:47.016][D][DMG]  OnReportConfirm: NumReports = 0
[00:00:47.021][D][DMG] IM RH moving to [CanStartReporting]
[00:00:47.028][P][EM] >>> [E:56633r S:16554 M:113082179] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[00:00:47.032][D][EM] Handling via exchange: 56633r, Delegate: 0x20018784
[00:00:47.044][D][DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[00:00:47.054][P][FS] GeneralCommissioning: Received CommissioningComplete
[00:00:47.108][P][FP] Metadata for Fabric 0x2 persisted to storage.
[00:00:47.249][P][TS] Committing Last Known Good Time to storage: 2025-12-10T04:04:28
[00:00:47.259][P][ZCL] OpCreds: Fabric index 0x2 was committed to storage. Compressed Fabric Id 0x066F15BDCCBD6A2D, FabricId C752AA73E5FA4660, NodeId 000000006029D15D, VendorId 0x6006
[00:00:47.273][P][FS] GeneralCommissioning: Successfully committed pending fabric data
[00:00:47.276][P][FS] Fail-safe cleanly disarmed
[00:00:47.284][D][DMG] Command handler moving to [NewRespons]
[00:00:47.288][D][DMG] Command handler moving to [ Preparing]
[00:00:47.293][D][DMG] Command handler moving to [AddingComm]
[00:00:47.299][D][DMG] Command handler moving to [AddedComma]
[00:00:47.305][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[00:00:47.310][D][DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[00:00:47.318][D][DMG] Command handler moving to [AwaitingDe]
[00:00:47.327][P][EM] <<< [E:56633r S:16554 M:260512641 (Ack:113082179)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
[00:00:47.332][P][EM] ??1 [E:56633r S:16554 M:260512641] (S) Msg Retransmission to 2:00000000F36C72E8 in 2346ms [State:Active II:500 AI:300 AT:4000]
[00:00:47.352][D][DMG] Command response sender moving to [AllInvokeR]
[00:00:47.354][E][DL] Long dispatch time: 327 ms, for event type 3
[00:00:47.372][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:47.377][D][DMG]  Cluster 28, Attribute 12 is dirty
[00:00:47.390][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0012 (expanded=1)
[00:00:47.396][D][DMG]  Cluster 28, Attribute 13 is dirty
[00:00:47.405][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0013 (expanded=1)
[00:00:47.412][D][DMG]  Cluster 28, Attribute 15 is dirty
[00:00:47.421][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0015 (expanded=1)
[00:00:47.427][D][DMG]  Cluster 28, Attribute 16 is dirty
[00:00:47.437][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0016 (expanded=1)
[00:00:47.443][D][DMG]  Cluster 28, Attribute fffc is dirty
[00:00:47.452][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:47.459][D][DMG]  Cluster 28, Attribute fffd is dirty
[00:00:47.469][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:47.475][D][DMG]  Cluster 28, Attribute fff8 is dirty
[00:00:47.484][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:47.490][D][DMG]  Cluster 28, Attribute fff9 is dirty
[00:00:47.500][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:47.507][D][DMG]  Cluster 28, Attribute fffb is dirty
[00:00:47.516][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:47.523][D][DMG]  Cluster 2a, Attribute 0 is dirty
[00:00:47.532][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:47.538][D][DMG]  Cluster 2a, Attribute 1 is dirty
[00:00:47.547][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:47.554][D][DMG]  Cluster 2a, Attribute 2 is dirty
[00:00:47.563][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:47.569][D][DMG]  Cluster 2a, Attribute 3 is dirty
[00:00:47.579][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:47.585][D][DMG]  Cluster 2a, Attribute fffc is dirty
[00:00:47.594][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:47.600][D][DMG]  Cluster 2a, Attribute fffd is dirty
[00:00:47.610][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:47.616][D][DMG]  Cluster 2a, Attribute fff8 is dirty
[00:00:47.625][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:47.632][D][DMG]  Cluster 2a, Attribute fff9 is dirty
[00:00:47.642][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:47.648][D][DMG]  Cluster 2a, Attribute fffb is dirty
[00:00:47.657][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:47.664][D][DMG]  Cluster 2f, Attribute 0 is dirty
[00:00:47.673][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:47.679][D][DMG]  Cluster 2f, Attribute 1 is dirty
[00:00:47.689][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:47.695][D][DMG]  Cluster 2f, Attribute 2 is dirty
[00:00:47.704][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:47.710][D][DMG]  Cluster 2f, Attribute b is dirty
[00:00:47.720][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000B (expanded=1)
[00:00:47.726][D][DMG]  Cluster 2f, Attribute c is dirty
[00:00:47.735][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000C (expanded=1)
[00:00:47.742][D][DMG]  Cluster 2f, Attribute e is dirty
[00:00:47.751][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000E (expanded=1)
[00:00:47.757][D][DMG]  Cluster 2f, Attribute f is dirty
[00:00:47.760][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000F (expanded=1)
[00:00:47.773][D][DMG]  Cluster 2f, Attribute 10 is dirty
[00:00:47.782][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0010 (expanded=1)
[00:00:47.788][D][DMG]  Cluster 2f, Attribute 13 is dirty
[00:00:47.798][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0013 (expanded=1)
[00:00:47.804][D][DMG]  Cluster 2f, Attribute 14 is dirty
[00:00:47.813][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0014 (expanded=1)
[00:00:47.820][D][DMG]  Cluster 2f, Attribute 19 is dirty
[00:00:47.829][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0019 (expanded=1)
[00:00:47.835][D][DMG]  Cluster 2f, Attribute 1f is dirty
[00:00:47.845][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_001F (expanded=1)
[00:00:47.851][D][DMG]  Cluster 2f, Attribute fffc is dirty
[00:00:47.860][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:47.867][D][DMG]  Cluster 2f, Attribute fffd is dirty
[00:00:47.876][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:47.883][D][DMG]  Cluster 2f, Attribute fff8 is dirty
[00:00:47.892][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:47.895][D][DMG]  Cluster 2f, Attribute fff9 is dirty
[00:00:47.908][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:47.914][D][DMG]  Cluster 2f, Attribute fffb is dirty
[00:00:47.924][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:47.930][D][DMG]  Cluster 30, Attribute 0 is dirty
[00:00:47.939][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:47.946][D][DMG]  Cluster 30, Attribute 1 is dirty
[00:00:47.964][D][IN] UDP Message Received packet nb : 54 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[61490] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:47.955][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:47.965][D][DMG]  Cluster 30, Attribute 2 is dirty
[00:00:47.980][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:47.999][D][DMG]  Cluster 30, Attribute 3 is dirty
[00:00:48.006][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:48.012][D][DMG] Next attribute value does not fit in packet, roll back on clusterId: 0x0000_0030, attributeId: 0x0000_0003, err = b
[00:00:48.021][D][DMG]  We cannot put more chunks into this report. Enable chunking.
[00:00:48.034][D][DMG]  first cluster event is too big so that it fails to fit in the packet!
[00:00:48.042][D][DMG] Fetched 0 events
[00:00:48.051][D][DMG]  Sending report (payload has 1170 bytes)...
[00:00:48.057][P][EM] <<< [E:56632r S:16554 M:260512642 (Ack:113082178)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:61490] --- Type 0001:05 (IM:ReportData) (B:1204)
[00:00:48.063][P][EM] ??1 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 in 2344ms [State:Active II:500 AI:300 AT:4000]
[00:00:48.082][D][DMG] IM RH moving to [AwaitingReportResponse]
[00:00:48.095][D][DMG]  ReportsInFlight = 1 with readHandler 0, RE has more messages
[00:00:48.100][E][DL] Long dispatch time: 729 ms, for event type 3
[00:00:48.108][P][DL] _OnPlatformEvent default:  event->Type = 32783
[00:00:48.114][P][SVR] Commissioning completed successfully
[00:00:48.120][P][DIS] Updating services using commissioning mode 0
[00:00:48.126][D][DL] Using Thread extended MAC for hostname.
[00:00:48.132][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:48.138][D][DL] Using Thread extended MAC for hostname.
[00:00:48.145][P][DIS] Advertise operational node 066F15BDCCBD6A2D-000000006029D15D
[00:00:48.151][D][DL] Using Thread extended MAC for hostname.
[00:00:48.158][P][DIS] Advertise commission parameter vendorID=65521 productID=32775 discriminator=3840/15 cm=0 cp=0
[00:00:48.164][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03226
[00:00:48.168][D][DMG] Cannot merge the new path into any existing path, create one.
[00:00:48.181][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03227
[00:00:48.189][D][DMG] Cannot merge the new path into any existing path, create one.
[00:00:48.196][D][DMG] Endpoint 0, Cluster 0x0000_003C update version to 92b03228
[00:00:48.204][D][DMG] Cannot merge the new path into any existing path, create one.
[00:00:48.211][D][IN] Expiring all PASE sessions
[00:00:48.218][D][IN] SecureSession[0x2000a1e0]: MarkForEviction Type:1 LSID:16555
[00:00:48.223][P][SC] SecureSession[0x2000a1e0, LSID:16555]: State change 'kActive' --> 'kPendingEviction'
[00:00:48.230][D][IN] SecureSession[0x2000a1e0]: Released - Type:1 LSID:16555
[00:00:48.240][P][SWU] Device commissioned, schedule a default provider query
[00:00:48.247][D][ZCL] Commissioning complete, notify platform driver to persist network credentials.
[00:00:48.258][E][DL] Long dispatch time: 150 ms, for event type 32783
[00:00:48.264][P][EM] >>> [E:56633r S:16554 M:113082180 (Ack:260512641)] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:48.269][D][EM] Found matching exchange: 56633r, Delegate: 0
[00:00:48.286][D][EM] Rxd Ack; Removing MessageCounter:260512641 from Retrans Table on exchange 56633r
[00:00:50.407][P][EM] <<1 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8
[00:00:50.408][P][EM] ??2 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 in 2357ms [State:Active II:500 AI:300 AT:4000]
[00:00:51.919][D][DIS] Extended discovery timed out
[00:00:51.919][P][DIS] Updating services using commissioning mode 0
[00:00:51.923][D][DL] Using Thread extended MAC for hostname.
[00:00:51.930][P][DIS] Advertise operational node 7C0E543D6704ADD1-000000004B8824AB
[00:00:51.936][D][DL] Using Thread extended MAC for hostname.
[00:00:51.943][P][DIS] Advertise operational node 066F15BDCCBD6A2D-000000006029D15D
[00:00:51.949][P][DL] removing srp service: CFD1D6B207672765._matterc._udp
[00:00:52.090][D][IN] UDP Message Received packet nb : 55 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 196
[00:00:52.091][P][EM] >>> [E:1210r S:0 M:241405047] (U) Msg RX from 0:AE9A1719716DFA50 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
[00:00:52.107][D][EM] Handling via exchange: 1210r, Delegate: 0x2000af98
[00:00:52.122][P][IN] CASE Server received Sigma1 message . Starting handshake. EC 0x2000bb38
[00:00:52.129][P][EM] <<< [E:1210r S:0 M:121417620 (Ack:241405047)] (U) Msg TX from 0000000000000000 to 0:AE9A1719716DFA50 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:52.137][D][EM] Flushed pending ack for MessageCounter:241405047 on exchange 1210r
[00:00:52.157][P][SC] Received Sigma1 msg
[00:00:52.162][D][SC] Found MRP parameters in the message
[00:00:52.169][D][SC] Peer assigned session key ID 49675
[00:00:52.205][P][SC] CASE matched destination ID: fabricIndex 2, NodeID 0x000000006029D15D
[00:00:52.263][P][EM] <<< [E:1210r S:0 M:121417621 (Ack:241405047)] (U) Msg TX from 0000000000000000 to 0:AE9A1719716DFA50 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:894)
[00:00:52.278][D][DL] SRP update succeeded
[00:00:52.268][P][EM] ??1 [E:1210r S:0 M:121417621] (U) Msg Retransmission to 0:0000000000000000 in 2335ms [State:Active II:500 AI:300 AT:4000]
[00:00:52.291][P][SC] Sent Sigma2 msg
[00:00:52.304][E][DL] Long dispatch time: 213 ms, for event type 3
[00:00:52.765][P][EM] <<2 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8
[00:00:52.766][P][EM] ??3 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 in 2637ms [State:Idle II:500 AI:300 AT:4000]
[00:00:52.952][D][IN] UDP Message Received packet nb : 56 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 744
[00:00:52.954][P][EM] >>> [E:1210r S:0 M:241405048 (Ack:121417621)] (U) Msg RX from 0:AE9A1719716DFA50 [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:744)
[00:00:52.969][D][EM] Found matching exchange: 1210r, Delegate: 0x2000afb4
[00:00:52.986][D][EM] Rxd Ack; Removing MessageCounter:121417621 from Retrans Table on exchange 1210r
[00:00:52.994][P][EM] <<< [E:1210r S:0 M:121417622 (Ack:241405048)] (U) Msg TX from 0000000000000000 to 0:AE9A1719716DFA50 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:53.002][D][EM] Flushed pending ack for MessageCounter:241405048 on exchange 1210r
[00:00:53.022][P][SC] Received Sigma3 msg
[00:00:53.047][D][SC] Certificate's mNotBeforeTime (809587413) is after current time (52)
[00:00:53.047][D][SC] Certificate's mNotBeforeTime (692310848) is after current time (52)
[00:00:53.055][D][SC] Certificate's mNotBeforeTime (692310655) is after current time (52)
[00:00:53.161][D][SC] Sending status report. Protocol code 0, exchange 1210
[00:00:53.162][P][EM] <<< [E:1210r S:0 M:121417623 (Ack:241405048)] (U) Msg TX from 0000000000000000 to 0:AE9A1719716DFA50 [0000] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[00:00:53.169][P][EM] ??1 [E:1210r S:0 M:121417623] (U) Msg Retransmission to 0:0000000000000000 in 2389ms [State:Active II:500 AI:300 AT:4000]
[00:00:53.192][P][SC] SecureSession[0x2000a390, LSID:16556]: State change 'kEstablishing' --> 'kActive'
[00:00:53.202][D][IN] SecureSession[0x2000a390]: Activated - Type:2 LSID:16556
[00:00:53.211][D][IN] New secure session activated for device <00000000F36C72E8, 2>, LSID:16556 PSID:49675!
[00:00:53.218][P][IN] CASE Session established to peer: <00000000F36C72E8, 2>
[00:00:53.228][D][IN] SecureSession[0x2000a1e0]: Allocated Type:2 LSID:16557
[00:00:53.231][D][SC] Allocated SecureSession (0x2000a1e0) - waiting for Sigma1 msg
[00:00:53.241][E][DL] Long dispatch time: 131 ms, for event type 2
[00:00:53.249][P][DL] _OnPlatformEvent default:  event->Type = 32792
[00:00:54.139][D][IN] UDP Message Received packet nb : 57 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 58
[00:00:54.151][D][IN] UDP Message Received packet nb : 58 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 26
[00:00:54.143][P][EM] >>> [E:1211r S:16556 M:29220751] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:03 (IM:SubscribeRequest) (B:58)
[00:00:54.173][D][EM] Handling via exchange: 1211r, Delegate: 0x20018784
[00:00:54.187][D][IM] Received Subscribe request
[00:00:54.196][P][DMG] Final negotiated min/max parameters: Min = 0s, Max = 1800s
[00:00:54.199][D][DMG] IM RH moving to [CanStartReporting]
[00:00:54.308][E][DL] Long dispatch time: 166 ms, for event type 3
[00:00:54.309][P][EM] >>> [E:1210r S:0 M:241405049 (Ack:121417623)] (U) Msg RX from 0:AE9A1719716DFA50 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[00:00:54.314][D][EM] Found matching exchange: 1210r, Delegate: 0
[00:00:54.330][D][EM] Rxd Ack; Removing MessageCounter:121417623 from Retrans Table on exchange 1210r
[00:00:54.336][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:54.343][D][DMG]  Cluster 1d, Attribute 0 is dirty
[00:00:54.358][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:54.364][D][DMG]  Cluster 1d, Attribute 1 is dirty
[00:00:54.373][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:54.380][D][DMG]  Cluster 1d, Attribute 2 is dirty
[00:00:54.389][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:54.395][D][DMG]  Cluster 1d, Attribute 3 is dirty
[00:00:54.404][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:54.410][D][DMG]  Cluster 1d, Attribute fffc is dirty
[00:00:54.420][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:54.426][D][DMG]  Cluster 1d, Attribute fffd is dirty
[00:00:54.436][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:54.442][D][DMG]  Cluster 1d, Attribute fff8 is dirty
[00:00:54.451][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:54.458][D][DMG]  Cluster 1d, Attribute fff9 is dirty
[00:00:54.467][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:54.474][D][DMG]  Cluster 1d, Attribute fffb is dirty
[00:00:54.477][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:54.490][D][DMG]  Cluster 1f, Attribute 0 is dirty
[00:00:54.499][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:54.505][D][DMG]  Cluster 1f, Attribute 2 is dirty
[00:00:54.514][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:54.520][D][DMG]  Cluster 1f, Attribute 3 is dirty
[00:00:54.530][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:54.536][D][DMG]  Cluster 1f, Attribute 4 is dirty
[00:00:54.546][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_0004 (expanded=1)
[00:00:54.552][D][DMG]  Cluster 1f, Attribute fffc is dirty
[00:00:54.561][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:54.567][D][DMG]  Cluster 1f, Attribute fffd is dirty
[00:00:54.577][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:54.583][D][DMG]  Cluster 1f, Attribute fff8 is dirty
[00:00:54.593][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:54.599][D][DMG]  Cluster 1f, Attribute fff9 is dirty
[00:00:54.609][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:54.613][D][DMG]  Cluster 1f, Attribute fffb is dirty
[00:00:54.624][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:54.631][D][DMG]  Cluster 28, Attribute 0 is dirty
[00:00:54.641][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:54.646][D][DMG]  Cluster 28, Attribute 1 is dirty
[00:00:54.656][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:54.662][D][DMG]  Cluster 28, Attribute 2 is dirty
[00:00:54.672][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:54.678][D][DMG]  Cluster 28, Attribute 3 is dirty
[00:00:54.687][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:54.693][D][DMG]  Cluster 28, Attribute 4 is dirty
[00:00:54.703][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=1)
[00:00:54.709][D][DMG]  Cluster 28, Attribute 5 is dirty
[00:00:54.718][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0005 (expanded=1)
[00:00:54.724][D][DMG]  Cluster 28, Attribute 6 is dirty
[00:00:54.734][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0006 (expanded=1)
[00:00:54.742][D][DMG]  Cluster 28, Attribute 7 is dirty
[00:00:54.748][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0007 (expanded=1)
[00:00:54.755][D][DMG]  Cluster 28, Attribute 8 is dirty
[00:00:54.765][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0008 (expanded=1)
[00:00:54.771][D][DMG]  Cluster 28, Attribute 9 is dirty
[00:00:54.780][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0009 (expanded=1)
[00:00:54.787][D][DMG]  Cluster 28, Attribute a is dirty
[00:00:54.796][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000A (expanded=1)
[00:00:54.802][D][DMG]  Cluster 28, Attribute b is dirty
[00:00:54.812][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000B (expanded=1)
[00:00:54.818][D][DMG]  Cluster 28, Attribute c is dirty
[00:00:54.827][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000C (expanded=1)
[00:00:54.833][D][DMG]  Cluster 28, Attribute d is dirty
[00:00:54.843][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000D (expanded=1)
[00:00:54.849][D][DMG]  Cluster 28, Attribute e is dirty
[00:00:54.858][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000E (expanded=1)
[00:00:54.864][D][DMG]  Cluster 28, Attribute f is dirty
[00:00:54.874][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000F (expanded=1)
[00:00:54.880][D][DMG]  Cluster 28, Attribute 10 is dirty
[00:00:54.883][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0010 (expanded=1)
[00:00:54.896][D][DMG]  Cluster 28, Attribute 12 is dirty
[00:00:54.905][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0012 (expanded=1)
[00:00:54.912][D][DMG] Next attribute value does not fit in packet, roll back on clusterId: 0x0000_0028, attributeId: 0x0000_0012, err = b
[00:00:54.921][D][DMG]  We cannot put more chunks into this report. Enable chunking.
[00:00:54.933][D][DMG]  first cluster event is too big so that it fails to fit in the packet!
[00:00:54.941][D][DMG] Fetched 0 events
[00:00:54.950][D][DMG]  Sending report (payload has 1175 bytes)...
[00:00:54.956][P][EM] <<< [E:1211r S:16556 M:86392051 (Ack:29220751)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0001:05 (IM:ReportData) (B:1209)
[00:00:54.962][P][EM] ??1 [E:1211r S:16556 M:86392051] (S) Msg Retransmission to 2:00000000F36C72E8 in 2407ms [State:Active II:500 AI:300 AT:4000]
[00:00:54.980][D][DMG] IM RH moving to [AwaitingReportResponse]
[00:00:54.993][D][DMG]  ReportsInFlight = 2 with readHandler 1, RE has more messages
[00:00:54.999][E][DL] Long dispatch time: 663 ms, for event type 3
[00:00:55.403][P][EM] <<3 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8
[00:00:55.404][P][EM] ??4 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 in 2989ms [State:Idle II:500 AI:300 AT:4000]
[00:00:55.433][D][IN] UDP Message Received packet nb : 59 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 42
[00:00:55.435][P][EM] >>> [E:1211r S:16556 M:29220752 (Ack:86392051)] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:01 (IM:StatusResponse) (B:42)
[00:00:55.450][D][EM] Found matching exchange: 1211r, Delegate: 0x2001a0d4
[00:00:55.465][D][EM] Rxd Ack; Removing MessageCounter:86392051 from Retrans Table on exchange 1211r
[00:00:55.475][D][IN] UDP Message Received packet nb : 60 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 79
[00:00:55.472][P][IM] Received status response, status is 0x00
[00:00:55.498][D][DMG]  OnReportConfirm: NumReports = 1
[00:00:55.503][D][DMG] IM RH moving to [CanStartReporting]
[00:00:55.510][P][EM] >>> [E:1212r S:16556 M:29220753] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0001:02 (IM:ReadRequest) (B:79)
[00:00:55.514][D][EM] Handling via exchange: 1212r, Delegate: 0x20018784
[00:00:55.528][D][IM] Received Read request
[00:00:55.539][D][DMG] IM RH moving to [CanStartReporting]
[00:00:55.539][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:00:55.544][D][DMG]  Cluster 28, Attribute 12 is dirty
[00:00:55.552][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0012 (expanded=1)
[00:00:55.563][D][DMG]  Cluster 28, Attribute 13 is dirty
[00:00:55.572][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0013 (expanded=1)
[00:00:55.578][D][DMG]  Cluster 28, Attribute 15 is dirty
[00:00:55.588][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0015 (expanded=1)
[00:00:55.594][D][DMG]  Cluster 28, Attribute 16 is dirty
[00:00:55.603][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0016 (expanded=1)
[00:00:55.610][D][DMG]  Cluster 28, Attribute fffc is dirty
[00:00:55.619][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:55.626][D][DMG]  Cluster 28, Attribute fffd is dirty
[00:00:55.635][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:55.641][D][DMG]  Cluster 28, Attribute fff8 is dirty
[00:00:55.651][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:55.657][D][DMG]  Cluster 28, Attribute fff9 is dirty
[00:00:55.667][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:55.673][D][DMG]  Cluster 28, Attribute fffb is dirty
[00:00:55.682][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:55.687][D][DMG]  Cluster 2a, Attribute 0 is dirty
[00:00:55.698][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:55.704][D][DMG]  Cluster 2a, Attribute 1 is dirty
[00:00:55.714][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:55.720][D][DMG]  Cluster 2a, Attribute 2 is dirty
[00:00:55.729][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:55.735][D][DMG]  Cluster 2a, Attribute 3 is dirty
[00:00:55.745][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:55.751][D][DMG]  Cluster 2a, Attribute fffc is dirty
[00:00:55.760][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:55.767][D][DMG]  Cluster 2a, Attribute fffd is dirty
[00:00:55.776][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:55.783][D][DMG]  Cluster 2a, Attribute fff8 is dirty
[00:00:55.792][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:55.798][D][DMG]  Cluster 2a, Attribute fff9 is dirty
[00:00:55.808][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:55.814][D][DMG]  Cluster 2a, Attribute fffb is dirty
[00:00:55.822][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:55.830][D][DMG]  Cluster 2f, Attribute 0 is dirty
[00:00:55.840][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:55.846][D][DMG]  Cluster 2f, Attribute 1 is dirty
[00:00:55.855][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:55.861][D][DMG]  Cluster 2f, Attribute 2 is dirty
[00:00:55.871][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:55.877][D][DMG]  Cluster 2f, Attribute b is dirty
[00:00:55.886][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000B (expanded=1)
[00:00:55.892][D][DMG]  Cluster 2f, Attribute c is dirty
[00:00:55.902][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000C (expanded=1)
[00:00:55.908][D][DMG]  Cluster 2f, Attribute e is dirty
[00:00:55.917][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000E (expanded=1)
[00:00:55.923][D][DMG]  Cluster 2f, Attribute f is dirty
[00:00:55.933][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_000F (expanded=1)
[00:00:55.939][D][DMG]  Cluster 2f, Attribute 10 is dirty
[00:00:55.948][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0010 (expanded=1)
[00:00:55.955][D][DMG]  Cluster 2f, Attribute 13 is dirty
[00:00:55.957][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0013 (expanded=1)
[00:00:55.970][D][DMG]  Cluster 2f, Attribute 14 is dirty
[00:00:55.980][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0014 (expanded=1)
[00:00:55.986][D][DMG]  Cluster 2f, Attribute 19 is dirty
[00:00:55.995][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_0019 (expanded=1)
[00:00:56.002][D][DMG]  Cluster 2f, Attribute 1f is dirty
[00:00:56.011][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_001F (expanded=1)
[00:00:56.017][D][DMG]  Cluster 2f, Attribute fffc is dirty
[00:00:56.027][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:00:56.033][D][DMG]  Cluster 2f, Attribute fffd is dirty
[00:00:56.042][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:00:56.049][D][DMG]  Cluster 2f, Attribute fff8 is dirty
[00:00:56.058][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFF8 (expanded=1)
[00:00:56.065][D][DMG]  Cluster 2f, Attribute fff9 is dirty
[00:00:56.074][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFF9 (expanded=1)
[00:00:56.080][D][DMG]  Cluster 2f, Attribute fffb is dirty
[00:00:56.090][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:00:56.092][D][DMG]  Cluster 30, Attribute 0 is dirty
[00:00:56.106][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=1)
[00:00:56.112][D][DMG]  Cluster 30, Attribute 1 is dirty
[00:00:56.121][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=1)
[00:00:56.127][D][DMG]  Cluster 30, Attribute 2 is dirty
[00:00:56.137][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=1)
[00:00:56.145][D][DMG]  Cluster 30, Attribute 3 is dirty
[00:00:56.152][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:00:56.158][D][DMG] Next attribute value does not fit in packet, roll back on clusterId: 0x0000_0030, attributeId: 0x0000_0003, err = b
[00:00:56.168][D][DMG]  We cannot put more chunks into this report. Enable chunking.
[00:00:56.181][D][DMG]  first cluster event is too big so that it fails to fit in the packet!
[00:00:56.189][D][DMG] Fetched 0 events
[00:00:56.198][D][DMG]  Sending report (payload has 1170 bytes)...
[00:00:56.203][P][EM] <<< [E:1211r S:16556 M:86392052 (Ack:29220752)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0001:05 (IM:ReportData) (B:1204)
[00:00:56.210][P][EM] ??1 [E:1211r S:16556 M:86392052] (S) Msg Retransmission to 2:00000000F36C72E8 in 2339ms [State:Active II:500 AI:300 AT:4000]
[00:00:56.227][D][DMG] IM RH moving to [AwaitingReportResponse]
[00:00:56.241][D][DMG]  ReportsInFlight = 2 with readHandler 1, RE has more messages
[00:00:56.246][E][DL] Long dispatch time: 707 ms, for event type 3
[00:00:56.256][P][EM] <<< [E:1212r S:16556 M:86392053 (Ack:29220753)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:58.393][P][EM] <<4 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8
[00:00:58.394][P][EM] ??5 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 in 3418ms [State:Idle II:500 AI:300 AT:4000]
[00:00:58.549][P][EM] <<1 [E:1211r S:16556 M:86392052] (S) Msg Retransmission to 2:00000000F36C72E8
[00:00:58.550][P][EM] ??2 [E:1211r S:16556 M:86392052] (S) Msg Retransmission to 2:00000000F36C72E8 in 2408ms [State:Active II:500 AI:300 AT:4000]
[00:00:58.743][D][IN] UDP Message Received packet nb : 61 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:58.745][P][EM] >>> [E:1211r S:16556 M:29220754 (Ack:86392052)] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:58.760][D][EM] Found matching exchange: 1211r, Delegate: 0x2001a0d4
[00:00:58.776][D][EM] Rxd Ack; Removing MessageCounter:86392052 from Retrans Table on exchange 1211r
[00:00:59.890][D][IN] UDP Message Received packet nb : 62 SrcAddr : fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70[59557] DestAddr : fd21:3339:d223:0:b59f:104f:4a2e:55de[5540] Payload Length 34
[00:00:59.892][P][EM] >>> [E:1211r S:16556 M:29220755 (Ack:86392052)] (S) Msg RX from 2:00000000F36C72E8 [6A2D] to 000000006029D15D --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[00:00:59.907][D][EM] Found matching exchange: 1211r, Delegate: 0x2001a0d4
[00:00:59.924][D][EM] CHIP MessageCounter:86392052 not in RetransTable on exchange 1211r
[00:01:01.812][E][EM] <<5 [E:56632r S:16554 M:260512642] (S) Msg Retransmission to 2:00000000F36C72E8 failure (max retries:4)
[00:01:18.247][E][SWU] No suitable OTA Provider candidate found
[00:01:18.247][P][SWU] No provider available
[00:01:20.507][P][SWU] Default Provider timer handler is invoked
[00:01:20.507][E][SWU] No suitable OTA Provider candidate found
[00:01:20.513][P][SWU] Stopping the watchdog timer
[00:01:20.518][P][SWU] Starting the periodic query timer, timeout: 86400 seconds
[00:02:49.046][D][IN] SecureSession[0x2000a2b8]: MarkAsDefunct Type:2 LSID:16554
[00:02:49.046][P][SC] SecureSession[0x2000a2b8, LSID:16554]: State change 'kActive' --> 'kDefunct'
[00:02:49.053][E][DMG] Time out! failed to receive status response from Exchange: 56632r
[00:02:49.062][P][DMG] Subscription id 0xbbe01c58 from node <00000000F36C72E8, 2> torn down
[00:02:49.070][D][DMG]  OnReportConfirm: NumReports = 1
[00:02:49.077][D][DMG] IM RH moving to [AwaitingDestruction]
[00:02:49.089][P][IM] Schedule subscription resumption when failing to establish session, Retries: 1
[00:02:49.090][D][DMG] Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
[00:02:49.098][D][DMG]  Cluster 1d, Attribute fffd is dirty
[00:02:49.111][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.117][D][DMG]  Cluster 1f, Attribute fffd is dirty
[00:02:49.126][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.133][D][DMG]  Cluster 28, Attribute fffd is dirty
[00:02:49.142][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.149][D][DMG]  Cluster 2a, Attribute fffd is dirty
[00:02:49.158][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.164][D][DMG]  Cluster 2f, Attribute fffd is dirty
[00:02:49.174][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.180][D][DMG]  Cluster 30, Attribute fffd is dirty
[00:02:49.190][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.196][D][DMG]  Cluster 31, Attribute fffd is dirty
[00:02:49.206][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.212][D][DMG]  Cluster 32, Attribute fffd is dirty
[00:02:49.212][D][DMG] Reading attribute: Cluster=0x0000_0032 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.228][D][DMG]  Cluster 33, Attribute fffd is dirty
[00:02:49.237][D][DMG] Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.244][D][DMG]  Cluster 34, Attribute fffd is dirty
[00:02:49.253][D][DMG] Reading attribute: Cluster=0x0000_0034 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.259][D][DMG]  Cluster 35, Attribute fffd is dirty
[00:02:49.269][D][DMG] Reading attribute: Cluster=0x0000_0035 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.275][D][DMG]  Cluster 3c, Attribute fffd is dirty
[00:02:49.285][D][DMG] Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.291][D][DMG]  Cluster 3e, Attribute fffd is dirty
[00:02:49.300][D][DMG] Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.307][D][DMG]  Cluster 3f, Attribute fffd is dirty
[00:02:49.316][D][DMG] Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.323][D][DMG]  Cluster 40, Attribute fffd is dirty
[00:02:49.332][D][DMG] Reading attribute: Cluster=0x0000_0040 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.339][D][DMG]  Cluster 41, Attribute fffd is dirty
[00:02:49.347][D][DMG] Reading attribute: Cluster=0x0000_0041 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.354][D][DMG]  Cluster 46, Attribute fffd is dirty
[00:02:49.364][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.370][D][DMG]  Cluster 3, Attribute fffd is dirty
[00:02:49.380][D][DMG] Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.386][D][DMG]  Cluster 1d, Attribute fffd is dirty
[00:02:49.395][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.402][D][DMG]  Cluster 45, Attribute fffd is dirty
[00:02:49.411][D][DMG] Reading attribute: Cluster=0x0000_0045 Endpoint=1 AttributeId=0x0000_FFFD (expanded=1)
[00:02:49.417][D][DMG]  Cluster 1d, Attribute fffc is dirty
[00:02:49.427][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.433][D][DMG]  Cluster 1f, Attribute fffc is dirty
[00:02:49.443][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.449][D][DMG]  Cluster 28, Attribute fffc is dirty
[00:02:49.459][D][DMG] Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.465][D][DMG]  Cluster 2a, Attribute fffc is dirty
[00:02:49.474][D][DMG] Reading attribute: Cluster=0x0000_002A Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.481][D][DMG]  Cluster 2f, Attribute fffc is dirty
[00:02:49.482][D][DMG] Reading attribute: Cluster=0x0000_002F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.497][D][DMG]  Cluster 30, Attribute fffc is dirty
[00:02:49.506][D][DMG] Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.512][D][DMG]  Cluster 31, Attribute fffc is dirty
[00:02:49.522][D][DMG] Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.528][D][DMG]  Cluster 32, Attribute fffc is dirty
[00:02:49.538][D][DMG] Reading attribute: Cluster=0x0000_0032 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.544][D][DMG]  Cluster 33, Attribute fffc is dirty
[00:02:49.553][D][DMG] Reading attribute: Cluster=0x0000_0033 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.560][D][DMG]  Cluster 34, Attribute fffc is dirty
[00:02:49.569][D][DMG] Reading attribute: Cluster=0x0000_0034 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.576][D][DMG]  Cluster 35, Attribute fffc is dirty
[00:02:49.585][D][DMG] Reading attribute: Cluster=0x0000_0035 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.593][D][DMG]  Cluster 3c, Attribute fffc is dirty
[00:02:49.602][D][DMG] Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.609][D][DMG]  Cluster 3e, Attribute fffc is dirty
[00:02:49.618][D][DMG] Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.619][D][DMG]  Cluster 3f, Attribute fffc is dirty
[00:02:49.624][D][DMG] Reading attribute: Cluster=0x0000_003F Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.640][D][DMG]  Cluster 40, Attribute fffc is dirty
[00:02:49.650][D][DMG] Reading attribute: Cluster=0x0000_0040 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.656][D][DMG]  Cluster 41, Attribute fffc is dirty
[00:02:49.666][D][DMG] Reading attribute: Cluster=0x0000_0041 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.672][D][DMG]  Cluster 46, Attribute fffc is dirty
[00:02:49.681][D][DMG] Reading attribute: Cluster=0x0000_0046 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.688][D][DMG]  Cluster 3, Attribute fffc is dirty
[00:02:49.697][D][DMG] Reading attribute: Cluster=0x0000_0003 Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.703][D][DMG]  Cluster 1d, Attribute fffc is dirty
[00:02:49.713][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.719][D][DMG]  Cluster 45, Attribute fffc is dirty
[00:02:49.729][D][DMG] Reading attribute: Cluster=0x0000_0045 Endpoint=1 AttributeId=0x0000_FFFC (expanded=1)
[00:02:49.735][D][DMG]  Cluster 1d, Attribute fffb is dirty
[00:02:49.745][D][DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:02:49.751][D][DMG]  Cluster 1f, Attribute fffb is dirty
[00:02:49.754][D][DMG] Reading attribute: Cluster=0x0000_001F Endpoint=0 AttributeId=0x0000_FFFB (expanded=1)
[00:02:49.767][D][DMG] List does not fit in packet, chunk between list items for clusterId: 0x0000_001F, attributeId: 0x0000_FFFB
[00:02:49.776][D][DMG]  We cannot put more chunks into this report. Enable chunking.
[00:02:49.788][D][DMG]  Sending report (payload has 1175 bytes)...
[00:02:49.798][P][EM] <<< [E:1212r S:16556 M:86392054 (Ack:29220753)] (S) Msg TX from 000000006029D15D to 2:00000000F36C72E8 [6A2D] [UDP:[fd1d:4018:af18:38e4:1c9a:2531:43ff:7b70]:59557] --- Type 0001:05 (IM:ReportData) (B:1209)
[00:02:49.804][P][EM] ??1 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 in 2387ms [State:Idle II:500 AI:300 AT:4000]
[00:02:49.823][D][DMG] IM RH moving to [AwaitingReportResponse]
[00:02:49.835][D][DMG]  ReportsInFlight = 2 with readHandler 1, RE has more messages
[00:02:49.841][E][DL] Long dispatch time: 752 ms, for event type 3
[00:02:52.192][P][EM] <<1 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8
[00:02:52.193][P][EM] ??2 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 in 2392ms [State:Idle II:500 AI:300 AT:4000]
[00:02:54.585][P][EM] <<2 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8
[00:02:54.586][P][EM] ??3 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 in 2537ms [State:Idle II:500 AI:300 AT:4000]
[00:02:57.123][P][EM] <<3 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8
[00:02:57.124][P][EM] ??4 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 in 2870ms [State:Idle II:500 AI:300 AT:4000]
[00:02:57.192][E][DMG] Time out! failed to receive status response from Exchange: 1211r
[00:02:57.192][P][DMG] Subscription id 0xe2508a66 from node <00000000F36C72E8, 2> torn down
[00:02:57.201][D][DMG]  OnReportConfirm: NumReports = 1
[00:02:57.209][D][DMG] IM RH moving to [AwaitingDestruction]
[00:02:59.994][P][EM] <<4 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8
[00:02:59.995][P][EM] ??5 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 in 3529ms [State:Idle II:500 AI:300 AT:4000]
[00:03:03.524][E][EM] <<5 [E:1212r S:16556 M:86392054] (S) Msg Retransmission to 2:00000000F36C72E8 failure (max retries:4)
[00:04:51.335][D][IN] SecureSession[0x2000a390]: MarkAsDefunct Type:2 LSID:16556
[00:04:51.335][P][SC] SecureSession[0x2000a390, LSID:16556]: State change 'kActive' --> 'kDefunct'
[00:04:51.342][E][DMG] Time out! failed to receive status response from Exchange: 1212r
[00:04:51.351][D][DMG]  OnReportConfirm: NumReports = 0
[00:04:51.359][D][DMG] IM RH moving to [AwaitingDestruction]
[00:07:49.094][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:07:49.094][D][CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[00:07:49.101][D][DIS] OperationalSessionSetup[2:00000000F36C72E8]: State change 1 --> 2
[00:07:49.104][P][DIS] Resolving 066F15BDCCBD6A2D:00000000F36C72E8 ...
[00:07:49.120][P][DIS] Lookup started for 066F15BDCCBD6A2D-00000000F36C72E8
[00:07:49.130][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:07:49.304][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 200 ms
[00:08:34.104][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 45000 ms
[00:08:34.104][E][DIS] OperationalSessionSetup[2:00000000F36C72E8]: operational discovery failed: 32
[00:08:34.113][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:08:34.128][P][IM] Schedule subscription resumption when failing to establish session, Retries: 2
[00:08:34.244][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:18:34.133][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:18:34.133][D][CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[00:18:34.140][D][DIS] OperationalSessionSetup[2:00000000F36C72E8]: State change 1 --> 2
[00:18:34.149][P][DIS] Resolving 066F15BDCCBD6A2D:00000000F36C72E8 ...
[00:18:34.159][P][DIS] Lookup started for 066F15BDCCBD6A2D-00000000F36C72E8
[00:18:34.169][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:18:34.349][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 200 ms
[00:19:19.149][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 45000 ms
[00:19:19.149][E][DIS] OperationalSessionSetup[2:00000000F36C72E8]: operational discovery failed: 32
[00:19:19.158][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:19:19.173][P][IM] Schedule subscription resumption when failing to establish session, Retries: 3
[00:19:19.288][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:29:19.179][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:29:19.179][D][CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[00:29:19.186][D][DIS] OperationalSessionSetup[2:00000000F36C72E8]: State change 1 --> 2
[00:29:19.195][P][DIS] Resolving 066F15BDCCBD6A2D:00000000F36C72E8 ...
[00:29:19.205][P][DIS] Lookup started for 066F15BDCCBD6A2D-00000000F36C72E8
[00:29:19.214][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:29:19.395][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 200 ms
[00:30:04.195][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 45000 ms
[00:30:04.195][E][DIS] OperationalSessionSetup[2:00000000F36C72E8]: operational discovery failed: 32
[00:30:04.204][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:30:04.219][P][IM] Schedule subscription resumption when failing to establish session, Retries: 4
[00:30:04.334][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:45:04.224][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:45:04.224][D][CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[00:45:04.231][D][DIS] OperationalSessionSetup[2:00000000F36C72E8]: State change 1 --> 2
[00:45:04.240][P][DIS] Resolving 066F15BDCCBD6A2D:00000000F36C72E8 ...
[00:45:04.250][P][DIS] Lookup started for 066F15BDCCBD6A2D-00000000F36C72E8
[00:45:04.260][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[00:45:04.440][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 200 ms
[00:45:49.240][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 45000 ms
[00:45:49.240][E][DIS] OperationalSessionSetup[2:00000000F36C72E8]: operational discovery failed: 32
[00:45:49.249][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[00:45:49.264][P][IM] Schedule subscription resumption when failing to establish session, Retries: 5
[00:45:49.378][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[01:00:00.596][P][-] HourlyTimer
[01:05:49.269][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[01:05:49.269][D][CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[01:05:49.276][D][DIS] OperationalSessionSetup[2:00000000F36C72E8]: State change 1 --> 2
[01:05:49.285][P][DIS] Resolving 066F15BDCCBD6A2D:00000000F36C72E8 ...
[01:05:49.295][P][DIS] Lookup started for 066F15BDCCBD6A2D-00000000F36C72E8
[01:05:49.302][D][CSM] FindOrEstablishSession: PeerId = [2:00000000F36C72E8]
[01:05:49.485][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 200 ms
[01:06:34.285][P][DIS] Checking node lookup status for 066F15BDCCBD6A2D-00000000F36C72E8 after 45000 ms
[01:06:34.285][E][DIS] OperationalSessionSetup[2:00000000F36C72E8]: operational discovery failed: 32
[01:06:34.294][E][DMG] Failed to establish CASE for subscription-resumption with error '32'
[01:06:34.309][P][IM] Schedule subscription resumption when failing to establish session, Retries: 6
[01:06:34.423][E][DMG] Failed to establish CASE for subscription-resumption with error '32'