samples/matter/light_bulb joining but not responding with HomePod mini

[jahess]

Decided it was more economical for me to purchase a COTS border router in the form of a HomePod mini than keep trying to deal with OTBR.

Besides, this is what end users would have and it is the devices I'm interested in developing and not getting a prototype border router working.

The HomePod mini was easy to setup and I immediately updated its software to version 16.2.

Wow!  The nfc setup vision for matter appears to have worked.  Just had to "Add anyway" past an "uncertified device" warning (understandable given developmental nature).

Unfortunately, the iOS and MacOS Home apps always show the "light bulb" as "not responding."

Doh!  Stuck again but much further than ever before.

Any suggestions?

Anyone else with success with a HomePod mini functioning as a border router?

Building with sdk 2.2.0 with matching toolchain on an Intel MacOS 13.1.

For what it is worth, the HomePod mini and Home apps work with the only other commercial matter device that I currently have -- an Eve energy plug.  Even with "Hey Siri, turn on Eve energy."

[Charlie]

Hi Jonathan,

Thanks for sharing your experience with the Matter device. Eve Matter smart home accessories are actually based on the NCS Matter solution. I am not sure why this "not responding" issue happens, but I can help you debug this problem.

I will try to update and test the same versions you are using. Could you share any log printouts from "light bulb" devices?

Best regards,

Charlie

[jahess]

I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 377537 [TS]Pending Last Known Good Time: 2023-01-23T12:2
[1;32muart:~$ [mI: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 3, c38
I: data wra: 3, 454
[m

[1;32muart:~$ [m*** Booting Zephyr OS build v3.2.99-ncs1 ***
I: Init CHIP stack
I: 231 [DL]BLE address: F4:C8:0F:D2:DF:88
I: SoftDevice Controller build revision:
I: 6d 90 41 2a 38 e8 ad 17 |m.A*8...
I: 29 a5 03 38 39 27 d7 85 |)..89'..
I: 1f 85 d8 e1 |....
I: 257 [DL]OpenThread started: OK
I: 261 [DL]Setting OpenThread device type to ROUTER
I: 265 [SVR]Server initializing...
D: 269 [FP]Initializing FabricTable from persistent storage
I: 275 [TS]Last Known Good Time: 2023-01-04T13:36:05
I: 281 [DMG]AccessControl: initializing
I: 285 [DMG]Examples::AccessControlDelegate::Init
I: 289 [DMG]AccessControl: setting
I: 292 [DMG]DefaultAclStorage: initializing
I: 296 [DMG]DefaultAclStorage: 0 entries loaded
D: 301 [IN]UDP::Init bind&listen port=5540
E: 305 [IN]SO_REUSEPORT failed: 109
D: 308 [IN]UDP::Init bound to port=5540
D: 311 [IN]BLEBase::Init - setting/overriding transport
D: 316 [IN]TransportMgr initialized
D: 325 [DL]Using Thread extended MAC for hostname.
I: 332 [ZCL]Using ZAP configuration...
D: 337 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 346 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 354 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 361 [DMG]AccessControlCluster: initializing
D: 366 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf03
D: 372 [DL]Boot reason: 1
D: 374 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 378 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 1977b2ef
D: 385 [EVL]LogEvent event number: 0x0000000000010000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000000000181
I: 399 [ZCL]Initiating Admin Commissioning cluster.
D: 404 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 4bc8caad
D: 410 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 192f2790
D: 416 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 192f2791
I: 423 [ZCL]On/Off set value: 1 0
I: 426 [ZCL]On/off already set to new value
D: 430 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to ce364bd3
I: 437 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 443 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 453 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:47263
D: 459 [SC]Assigned local session key ID 47263
D: 463 [SC]Waiting for PBKDF param request
D: 467 [DL]CHIPoBLE advertising set to on
I: 471 [DIS]Updating services using commissioning mode 1
D: 476 [DL]Using Thread extended MAC for hostname.
D: 481 [DL]Using Thread extended MAC for hostname.
I: 486 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 496 [DIS]Failed to advertise commissionable node: 3
E: 500 [DIS]Failed to finalize service update: 1c
I: 505 [DIS]Updating services using commissioning mode 1
D: 510 [DL]Using Thread extended MAC for hostname.
D: 515 [DL]Using Thread extended MAC for hostname.
I: 520 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 529 [DIS]Failed to advertise commissionable node: 3
E: 534 [DIS]Failed to finalize service update: 1c
I: 539 [DIS]Delaying proxy of operational discovery: missing delegate
I: 545 [IN]CASE Server enabling CASE session setups
D: 550 [IN]SecureSession[0x20003708]: Allocated Type:2 LSID:47264
D: 556 [SC]Allocated SecureSession (0x20003708) - waiting for Sigma1 msg
I: 562 [SVR]Joining Multicast groups
D: 565 [ZCL]Emitting StartUp event
D: 569 [EVL]LogEvent event number: 0x0000000000010001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000239
I: 583 [SVR]Server Listening...
I: 586 [DL]Device Configuration:
I: 589 [DL] Serial Number: 11223344556677889900
I: 594 [DL] Vendor Id: 65521 (0xFFF1)
I: 597 [DL] Product Id: 32773 (0x8005)
I: 602 [DL] Hardware Version: 0
I: 606 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 612 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 619 [DL] Manufacturing Date: (not set)
I: 623 [DL] Device Type: 65535 (0xFFFF)
I: 628 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 633 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 639 [SVR]project-chip.github.io/.../qrcode.html
I: 648 [SVR]Manual pairing code: [34970112332]
I: 653 [DL]CHIP task running
I: 658 [DL]CHIPoBLE advertising started
D: 662 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to c5d50f12
I: 669 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 674 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to ce364bd4
I: 680 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 686 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 696 [DL]NFC Tag emulation started
I: 16914 [DL]BLE connection established (ConnId: 0x00)
I: 16919 [DL]Current number of connections: 1/2
I: 16923 [DL]CHIPoBLE advertising stopped
I: 16927 [DL]NFC Tag emulation stopped
W: Ignoring data for unknown channel ID 0x003a
D: 17948 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17955 [BLE]local and remote recv window sizes = 5
I: 17960 [BLE]selected BTP version 4
I: 17963 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 18068 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 18073 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 18080 [IN]BLE EndPoint 0x20012270 Connection Complete
I: 18085 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 18128 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18136 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18144 [EM]>>> [E:35976r M:143324286] (U) Msg RX from 0:2ABAD00BDC6B9A41 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 18156 [EM]Handling via exchange: 35976r, Delegate: 0x20005834
D: 18161 [SC]Received PBKDF param request
D: 18165 [SC]Peer assigned session ID 25942
D: 18169 [SC]Found MRP parameters in the message
D: 18174 [SC]Including MRP parameters in PBKDF param response
I: 18180 [EM]<<< [E:35976r M:143534042] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 18192 [IN](U) Sending msg 143534042 to IP address 'BLE'
D: 18197 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 18205 [SC]Sent PBKDF param response
D: 18248 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 18338 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 18346 [EM]>>> [E:35976r M:143324287] (U) Msg RX from 0:2ABAD00BDC6B9A41 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 18357 [EM]Found matching exchange: 35976r, Delegate: 0x20005834
D: 18363 [SC]Received spake2p msg1
I: 20306 [EM]<<< [E:35976r M:143534043] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 20317 [IN](U) Sending msg 143534043 to IP address 'BLE'
D: 20322 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
D: 20330 [SC]Sent spake2p msg2
E: 20333 [DL]Long dispatch time: 1995 ms, for event type 16388
D: 20378 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20438 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20446 [EM]>>> [E:35976r M:143324288] (U) Msg RX from 0:2ABAD00BDC6B9A41 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 20457 [EM]Found matching exchange: 35976r, Delegate: 0x20005834
D: 20463 [SC]Received spake2p msg3
D: 20466 [SC]Sending status report. Protocol code 0, exchange 35976
I: 20473 [EM]<<< [E:35976r M:143534044] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 20484 [IN](U) Sending msg 143534044 to IP address 'BLE'
D: 20489 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 20498 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive'
D: 20506 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:47263
D: 20512 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:47263 PSID:25942!
I: 20521 [SVR]Commissioning completed session establishment step
I: 20528 [DIS]Updating services using commissioning mode 0
D: 20534 [DL]Using Thread extended MAC for hostname.
D: 20539 [DL]Using Thread extended MAC for hostname.
I: 20544 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 20554 [DIS]Failed to advertise extended commissionable node: 3
D: 20560 [DIS]Scheduling extended discovery timeout in 900s
E: 20565 [DIS]Failed to finalize service update: 1c
D: 20570 [DL]CHIPoBLE advertising set to off
I: 20574 [SVR]Device completed Rendezvous process
E: 20578 [DL]Long dispatch time: 140 ms, for event type 16388
D: 20584 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20592 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20600 [EM]>>> [E:35977r M:250937964] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 20610 [EM]Handling via exchange: 35977r, Delegate: 0x2000fc3c
D: 20616 [IM]Received Read request
D: 20620 [DMG]IM RH moving to [GeneratingReports]
D: 20624 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 20633 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 20638 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 20647 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 20654 [EM]<<< [E:35977r M:62829970] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 20663 [IN](S) Sending msg 62829970 on secure session with LSID: 47263
D: 20670 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
D: 20678 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 20682 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 20690 [DMG]IM RH moving to [AwaitingDestruction]
D: 20694 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 20739 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20746 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20754 [EM]>>> [E:35978r M:250937965] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 20765 [EM]Handling via exchange: 35978r, Delegate: 0x2000fc3c
D: 20771 [IM]Received Read request
D: 20774 [DMG]IM RH moving to [GeneratingReports]
D: 20779 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 20788 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 20793 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 20803 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 20810 [EM]<<< [E:35978r M:62829971] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 20820 [IN](S) Sending msg 62829971 on secure session with LSID: 47263
D: 20827 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20835 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 20839 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 20846 [DMG]IM RH moving to [AwaitingDestruction]
D: 20851 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 20888 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20896 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 193)
D: 20949 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20956 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20964 [EM]>>> [E:35979r M:250937966] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 20975 [EM]Handling via exchange: 35979r, Delegate: 0x2000fc3c
D: 20981 [IM]Received Read request
D: 20984 [DMG]IM RH moving to [GeneratingReports]
D: 20989 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 20998 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 21003 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 21012 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 21018 [EM]<<< [E:35979r M:62829972] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 21028 [IN](S) Sending msg 62829972 on secure session with LSID: 47263
D: 21035 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 21042 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 21047 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 21054 [DMG]IM RH moving to [AwaitingDestruction]
D: 21059 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 21099 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21106 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21114 [EM]>>> [E:35980r M:250937967] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 21124 [EM]Handling via exchange: 35980r, Delegate: 0x2000fc3c
D: 21130 [IM]Received Read request
D: 21134 [DMG]IM RH moving to [GeneratingReports]
D: 21139 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 21147 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 21152 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 21162 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 21168 [EM]<<< [E:35980r M:62829973] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 21178 [IN](S) Sending msg 62829973 on secure session with LSID: 47263
D: 21185 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
D: 21192 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 21197 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 21204 [DMG]IM RH moving to [AwaitingDestruction]
D: 21209 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 21249 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21256 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21264 [EM]>>> [E:35981r M:250937968] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 21275 [EM]Handling via exchange: 35981r, Delegate: 0x2000fc3c
D: 21281 [IM]Received Read request
D: 21284 [DMG]IM RH moving to [GeneratingReports]
D: 21289 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 21298 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 21303 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 21313 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 21320 [EM]<<< [E:35981r M:62829974] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 21330 [IN](S) Sending msg 62829974 on secure session with LSID: 47263
D: 21337 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21345 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 21349 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 21356 [DMG]IM RH moving to [AwaitingDestruction]
D: 21361 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 21398 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21406 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 193)
D: 21459 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21466 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21474 [EM]>>> [E:35982r M:250937969] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 21485 [EM]Handling via exchange: 35982r, Delegate: 0x2000fc3c
D: 21491 [IM]Received Read request
D: 21494 [DMG]IM RH moving to [GeneratingReports]
D: 21499 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 21508 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 21513 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 21522 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 21528 [EM]<<< [E:35982r M:62829975] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 21538 [IN](S) Sending msg 62829975 on secure session with LSID: 47263
D: 21545 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 21553 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 21557 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 21564 [DMG]IM RH moving to [AwaitingDestruction]
D: 21569 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 21608 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22261 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22269 [EM]>>> [E:35983r M:250937970] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 22280 [EM]Handling via exchange: 35983r, Delegate: 0x2000fc3c
D: 22285 [IM]Received Read request
D: 22291 [DMG]IM RH moving to [GeneratingReports]
D: 22296 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 22305 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 22310 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 22319 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 22324 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 22333 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 22338 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 22347 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 22352 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 22361 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 22366 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 22375 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 22380 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 22389 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 22394 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 22403 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 22409 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 22418 [DMG]<RE> Sending report (payload has 228 bytes)...
I: 22425 [EM]<<< [E:35983r M:62829976] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 22435 [IN](S) Sending msg 62829976 on secure session with LSID: 47263
D: 22441 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 22449 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 22454 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 22461 [DMG]IM RH moving to [AwaitingDestruction]
D: 22465 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 22560 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22568 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 22681 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22689 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22697 [EM]>>> [E:35984r M:250937971] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 22708 [EM]Handling via exchange: 35984r, Delegate: 0x2000fc3c
D: 22714 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 22722 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 22727 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf04
D: 22734 [DMG]Command handler moving to [ Preparing]
D: 22739 [DMG]Command handler moving to [AddingComm]
D: 22744 [DMG]Command handler moving to [AddedComma]
D: 22748 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 22756 [EM]<<< [E:35984r M:62829977] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22766 [IN](S) Sending msg 62829977 on secure session with LSID: 47263
D: 22773 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22781 [DMG]Command handler moving to [CommandSen]
D: 22785 [DMG]Command handler moving to [AwaitingDe]
E: 22790 [DL]Long dispatch time: 101 ms, for event type 16388
D: 22861 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22869 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22877 [EM]>>> [E:35985r M:250937972] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 22888 [EM]Handling via exchange: 35985r, Delegate: 0x2000fc3c
D: 22894 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 22910 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf05
D: 22916 [DMG]Command handler moving to [ Preparing]
D: 22921 [DMG]Command handler moving to [AddingComm]
D: 22926 [DMG]Command handler moving to [AddedComma]
D: 22931 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 22938 [EM]<<< [E:35985r M:62829978] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22949 [IN](S) Sending msg 62829978 on secure session with LSID: 47263
D: 22955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22963 [DMG]Command handler moving to [CommandSen]
D: 22968 [DMG]Command handler moving to [AwaitingDe]
E: 22972 [DL]Long dispatch time: 103 ms, for event type 16388
D: 23041 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23049 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 23057 [EM]>>> [E:35986r M:250937973] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 23068 [EM]Handling via exchange: 35986r, Delegate: 0x2000fc3c
D: 23074 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 23082 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 23088 [DMG]Command handler moving to [ Preparing]
D: 23092 [DMG]Command handler moving to [AddingComm]
D: 23097 [DMG]Command handler moving to [AddedComma]
D: 23102 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 23111 [EM]<<< [E:35986r M:62829979] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 23122 [IN](S) Sending msg 62829979 on secure session with LSID: 47263
D: 23129 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 23136 [DMG]Command handler moving to [CommandSen]
D: 23141 [DMG]Command handler moving to [AwaitingDe]
D: 23220 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23228 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 23340 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23348 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 23461 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23469 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 23477 [EM]>>> [E:35987r M:250937974] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 23488 [EM]Handling via exchange: 35987r, Delegate: 0x2000fc3c
D: 23494 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 23502 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 23508 [DMG]Command handler moving to [ Preparing]
D: 23512 [DMG]Command handler moving to [AddingComm]
D: 23517 [DMG]Command handler moving to [AddedComma]
D: 23522 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 23531 [EM]<<< [E:35987r M:62829980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 23542 [IN](S) Sending msg 62829980 on secure session with LSID: 47263
D: 23549 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 23557 [DMG]Command handler moving to [CommandSen]
D: 23561 [DMG]Command handler moving to [AwaitingDe]
D: 23640 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23648 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 23760 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23768 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
D: 23880 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 23889 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 23897 [EM]>>> [E:35988r M:250937975] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 23908 [EM]Handling via exchange: 35988r, Delegate: 0x2000fc3c
D: 23914 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 23922 [ZCL]OpCreds: Received an AttestationRequest command
I: 23958 [ZCL]OpCreds: AttestationRequest successful.
D: 23963 [DMG]Command handler moving to [ Preparing]
D: 23968 [DMG]Command handler moving to [AddingComm]
D: 23972 [DMG]Command handler moving to [AddedComma]
D: 23977 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 23987 [EM]<<< [E:35988r M:62829981] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 23998 [IN](S) Sending msg 62829981 on secure session with LSID: 47263
D: 24005 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 24013 [DMG]Command handler moving to [CommandSen]
D: 24018 [DMG]Command handler moving to [AwaitingDe]
E: 24022 [DL]Long dispatch time: 133 ms, for event type 16388
D: 24120 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 24128 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 24240 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 24248 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235)
D: 24361 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 24369 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 24377 [EM]>>> [E:35989r M:250937976] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 24388 [EM]Handling via exchange: 35989r, Delegate: 0x2000fc3c
D: 24394 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 24402 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 24407 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf06
D: 24414 [DMG]Command handler moving to [ Preparing]
D: 24419 [DMG]Command handler moving to [AddingComm]
D: 24424 [DMG]Command handler moving to [AddedComma]
D: 24428 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 24436 [EM]<<< [E:35989r M:62829982] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24446 [IN](S) Sending msg 62829982 on secure session with LSID: 47263
D: 24453 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 24460 [DMG]Command handler moving to [CommandSen]
D: 24465 [DMG]Command handler moving to [AwaitingDe]
E: 24470 [DL]Long dispatch time: 101 ms, for event type 16388
D: 24540 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 26641 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 26649 [EM]>>> [E:35990r M:250937977] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 26660 [EM]Handling via exchange: 35990r, Delegate: 0x2000fc3c
D: 26667 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 26674 [ZCL]OpCreds: Received a CSRRequest command
D: 26679 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 26875 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 26911 [ZCL]OpCreds: CSRRequest successful.
D: 26915 [DMG]Command handler moving to [ Preparing]
D: 26920 [DMG]Command handler moving to [AddingComm]
D: 26924 [DMG]Command handler moving to [AddedComma]
D: 26929 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 26938 [EM]<<< [E:35990r M:62829983] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 26949 [IN](S) Sending msg 62829983 on secure session with LSID: 47263
D: 26955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 26963 [DMG]Command handler moving to [CommandSen]
D: 26968 [DMG]Command handler moving to [AwaitingDe]
E: 26972 [DL]Long dispatch time: 331 ms, for event type 16388
D: 27060 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 27068 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138)
D: 27180 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 27241 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 27361 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 27370 [EM]>>> [E:35991r M:250937978] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 27381 [EM]Handling via exchange: 35991r, Delegate: 0x2000fc3c
D: 27387 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 27395 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 27458 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 27464 [DMG]Command handler moving to [ Preparing]
D: 27468 [DMG]Command handler moving to [AddingComm]
D: 27473 [DMG]Command handler moving to [AddedComma]
D: 27478 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 27486 [EM]<<< [E:35991r M:62829984] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27497 [IN](S) Sending msg 62829984 on secure session with LSID: 47263
D: 27503 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 27511 [DMG]Command handler moving to [CommandSen]
D: 27515 [DMG]Command handler moving to [AwaitingDe]
E: 27520 [DL]Long dispatch time: 159 ms, for event type 16388
D: 27600 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 27609 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 27721 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 27730 [EM]>>> [E:35992r M:250937979] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 27741 [EM]Handling via exchange: 35992r, Delegate: 0x2000fc3c
D: 27748 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 27755 [ZCL]OpCreds: Received an AddNOC command
I: 27764 [FP]Validating NOC chain
I: 27825 [FP]NOC chain validation successful
I: 27829 [FP]Added new fabric at index: 0x1
I: 27833 [FP]Assigned compressed fabric ID: 0x7FE9B764118685EB, node ID: 0x0000000073B72630
I: 27841 [TS]Last Known Good Time: 2023-01-04T13:36:05
I: 27846 [TS]New proposed Last Known Good Time: 2023-01-23T12:35:13
I: 27852 [TS]Updating pending Last Known Good Time to 2023-01-23T12:35:13
D: 27859 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d2
D: 27865 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d3
D: 27904 [EVL]LogEvent event number: 0x0000000000010002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000006CFF
I: 27918 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x4925A783D435A3C5
D: 27926 [DL]Using Thread extended MAC for hostname.
I: 27931 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 27938 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d4
D: 27945 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d5
D: 27951 [DMG]Command handler moving to [ Preparing]
D: 27956 [DMG]Command handler moving to [AddingComm]
D: 27961 [DMG]Command handler moving to [AddedComma]
I: 27965 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 27972 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 27979 [EM]<<< [E:35992r M:62829985] (S) Msg TX to 1:FFFFFFFB00000000 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27990 [IN](S) Sending msg 62829985 on secure session with LSID: 47263
D: 27996 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 28004 [DMG]Command handler moving to [CommandSen]
D: 28009 [DMG]Command handler moving to [AwaitingDe]
E: 28013 [DL]Long dispatch time: 292 ms, for event type 16388
D: 28080 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 28089 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 28097 [EM]>>> [E:35993r M:250937980] (S) Msg RX from 1:FFFFFFFB00000000 [85EB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 28108 [EM]Handling via exchange: 35993r, Delegate: 0x2000fc3c
D: 28114 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 28127 [DMG]Command handler moving to [ Preparing]
D: 28132 [DMG]Command handler moving to [AddingComm]
D: 28137 [DMG]Command handler moving to [AddedComma]
D: 28142 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf07
D: 28149 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 28156 [EM]<<< [E:35993r M:62829986] (S) Msg TX to 1:FFFFFFFB00000000 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28167 [IN](S) Sending msg 62829986 on secure session with LSID: 47263
D: 28173 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 28181 [DMG]Command handler moving to [CommandSen]
D: 28185 [DMG]Command handler moving to [AwaitingDe]
E: 28190 [DL]Long dispatch time: 102 ms, for event type 16388
D: 28261 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 28269 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 28277 [EM]>>> [E:35994r M:250937981] (S) Msg RX from 1:FFFFFFFB00000000 [85EB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 28288 [EM]Handling via exchange: 35994r, Delegate: 0x2000fc3c
D: 28294 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 28315 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 28322 [DL]OpenThread State Changed (Flags: 0x100fc100)
D: 28327 [DL] Network Name: MyHome1212256466
D: 28331 [DL] PAN Id: 0xC9B7
D: 28334 [DL] Extended PAN Id: 0xE280D9BD16C84864
D: 28339 [DL] Channel: 25
D: 28341 [DL] Mesh Prefix: fdde:ad00:beef::/64
D: 28348 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 28353 [DL] Device Role: DETACHED
D: 28356 [DL] Thread Unicast Addresses:
D: 28360 [DL] fdde:ad00:beef:0:50f1:9351:882b:6308/64 valid
D: 28366 [DL] fe80::90a3:51e8:3d74:19c3/64 valid preferred
D: 28869 [DL]OpenThread State Changed (Flags: 0x00000100)
I: 29564 [DL]SRP Client was started, detected server: fd26:1a58:8ce6:0000:cb01:06b5:af6a:ab28
D: 29573 [DL]OpenThread State Changed (Flags: 0x301032b7)
D: 29578 [DL] Device Role: CHILD
D: 29582 [DL] Partition Id: 0x54318714
D: 29585 [DL] Thread Unicast Addresses:
D: 29589 [DL] fd26:1a58:8ce6:0:835:5ef3:8280:7d54/64 valid preferred
D: 29596 [DL] fde2:80d9:bd16::ff:fe00:1407/64 valid rloc
D: 29602 [DL] fde2:80d9:bd16:0:50f1:9351:882b:6308/64 valid
D: 29608 [DL] fe80::90a3:51e8:3d74:19c3/64 valid preferred
D: 29616 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 29621 [DL] Thread Unicast Addresses:
D: 29624 [DL] fd26:1a58:8ce6:0:835:5ef3:8280:7d54/64 valid preferred
D: 29631 [DL] fde2:80d9:bd16::ff:fe00:1407/64 valid rloc
D: 29637 [DL] fde2:80d9:bd16:0:50f1:9351:882b:6308/64 valid
D: 29643 [DL] fe80::90a3:51e8:3d74:19c3/64 valid preferred
D: 29651 [DMG]Command handler moving to [ Preparing]
D: 29656 [DMG]Command handler moving to [AddingComm]
D: 29661 [DMG]Command handler moving to [AddedComma]
D: 29666 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf08
D: 29672 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 29680 [EM]<<< [E:35994r M:62829987] (S) Msg TX to 1:FFFFFFFB00000000 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 29690 [IN](S) Sending msg 62829987 on secure session with LSID: 47263
D: 29697 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 29705 [DMG]Command handler moving to [CommandSen]
D: 29710 [DMG]Command handler moving to [AwaitingDe]
D: 29714 [DL]Using Thread extended MAC for hostname.
I: 29719 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
I: 29726 [SVR]Operational advertising enabled
D: 29820 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 30340 [DL]SRP update succeeded
I: 30343 [DIS]Setting operational delegate post init
I: 30353 [SWU]Stopping the watchdog timer
I: 30356 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 30363 [DIS]Updating services using commissioning mode 0
D: 30368 [DL]Using Thread extended MAC for hostname.
I: 30373 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
I: 30380 [DL]advertising srp service: 7FE9B764118685EB-0000000073B72630._matter._tcp
D: 30388 [DL]Using Thread extended MAC for hostname.
I: 30394 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 30403 [DL]advertising srp service: 1FF399984299BA94._matterc._udp
D: 30409 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2b3b1fbd
D: 30416 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2b3b1fbe
D: 31668 [DL]SRP update succeeded
D: 32280 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 33101 [EM]>>> [E:35995r M:143324289] (U) Msg RX from 0:C66B2FB33195AB06 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 33112 [EM]Handling via exchange: 35995r, Delegate: 0x200042c0
I: 33118 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004fd0
I: 33125 [IN]CASE Server disabling CASE session setups
I: 33131 [EM]<<< [E:35995r M:143534045 (Ack:143324289)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 33143 [IN](U) Sending msg 143534045 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:51757'
D: 33154 [EM]Flushed pending ack for MessageCounter:143324289 on exchange 35995r
I: 33161 [SC]Received Sigma1 msg
D: 33164 [SC]Found MRP parameters in the message
D: 33169 [SC]Peer assigned session key ID 25943
I: 33177 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000073B72630
D: 33401 [SC]Including MRP parameters
I: 33405 [EM]<<< [E:35995r M:143534046 (Ack:143324289)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 33417 [IN](U) Sending msg 143534046 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:51757'
I: 33429 [SC]Sent Sigma2 msg
I: 33666 [EM]>>> [E:35995r M:143324290 (Ack:143534046)] (U) Msg RX from 0:C66B2FB33195AB06 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D: 33678 [EM]Found matching exchange: 35995r, Delegate: 0x200042dc
D: 33684 [EM]Rxd Ack; Removing MessageCounter:143534046 from Retrans Table on exchange 35995r
I: 33693 [EM]<<< [E:35995r M:143534047 (Ack:143324290)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 33706 [IN](U) Sending msg 143534047 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:51757'
D: 33716 [EM]Flushed pending ack for MessageCounter:143324290 on exchange 35995r
I: 33724 [SC]Received Sigma3 msg
E: 33730 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time
D: 34027 [SC]Sending status report. Protocol code 0, exchange 35995
I: 34034 [EM]<<< [E:35995r M:143534048 (Ack:143324290)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 34046 [IN](U) Sending msg 143534048 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:51757'
I: 34058 [SC]SecureSession[0x20003708]: Moving from state 'kEstablishing' --> 'kActive'
D: 34066 [IN]SecureSession[0x20003708]: Activated - Type:2 LSID:47264
D: 34072 [IN]New secure session activated for device <4925A783D435A3C5, 1>, LSID:47264 PSID:25943!
I: 34082 [IN]CASE Session established to peer: <4925A783D435A3C5, 1>
I: 34088 [IN]CASE Server enabling CASE session setups
D: 34093 [IN]SecureSession[0x200037c0]: Allocated Type:2 LSID:47265
D: 34101 [SC]Allocated SecureSession (0x200037c0) - waiting for Sigma1 msg
I: 34110 [EM]>>> [E:35996r M:80920496] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 34121 [EM]Handling via exchange: 35996r, Delegate: 0x2000fc3c
D: 34127 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
I: 34135 [FS]GeneralCommissioning: Received CommissioningComplete
I: 34241 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 34417 [TS]Committing Last Known Good Time to storage: 2023-01-23T12:35:13
I: 34672 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x7FE9B764118685EB, FabricId 0000000000000001, NodeId 0000000073B72630, VendorId 0x1349
I: 34713 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 34720 [FS]Fail-safe cleanly disarmed
D: 34724 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf09
D: 34730 [DMG]Command handler moving to [ Preparing]
D: 34735 [DMG]Command handler moving to [AddingComm]
D: 34740 [DMG]Command handler moving to [AddedComma]
D: 34745 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 34752 [EM]<<< [E:35996r M:67722829 (Ack:80920496)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 34764 [IN](S) Sending msg 67722829 on secure session with LSID: 47264
D: 34772 [DMG]Command handler moving to [CommandSen]
D: 34777 [DMG]Command handler moving to [AwaitingDe]
I: 34781 [SWU]Device commissioned, schedule a default provider query
I: 34788 [SVR]Commissioning completed successfully
I: 34793 [DIS]Updating services using commissioning mode 0
D: 34798 [DL]Using Thread extended MAC for hostname.
I: 34803 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 34810 [DL]Using Thread extended MAC for hostname.
I: 34816 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
D: 34825 [IN]Expiring all PASE sessions
D: 34829 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:47263
I: 34836 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction'
D: 34844 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:47263
D: 34850 [IN]Clearing BLE pending packets.
I: 34854 [BLE]Releasing end point's BLE connection back to application.
I: 34860 [DL]Closing BLE GATT connection (ConnId 00)
D: 34865 [ZCL]Commissioning complete, notify platform driver to persist network credentials.
E: 34900 [DL]Long dispatch time: 119 ms, for event type 32781
D: 34908 [EM]Retransmitting MessageCounter:143534048 on exchange 35995r Send Cnt 1
I: 34915 [IN](U) Sending msg 143534048 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:51757'
I: 34926 [EM]>>> [E:35995r M:143324291 (Ack:143534048)] (U) Msg RX from 0:C66B2FB33195AB06 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 34939 [EM]Found matching exchange: 35995r, Delegate: (nil)
D: 34944 [EM]Rxd Ack; Removing MessageCounter:143534048 from Retrans Table on exchange 35995r
I: 34955 [EM]>>> [E:35996r M:80920497 (Ack:67722829)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 34968 [EM]Found matching exchange: 35996r, Delegate: (nil)
D: 34973 [EM]Rxd Ack; Removing MessageCounter:67722829 from Retrans Table on exchange 35996r
I: 34981 [DL]BLE GAP connection terminated (reason 0x13)
I: 34987 [DL]Current number of connections: 0/2
I: 34999 [EM]>>> [E:35995r M:143324292 (Ack:143534048)] (U) Msg RX from 0:C66B2FB33195AB06 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 35019 [EM]>>> [E:35997r M:80920498] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 35029 [EM]Handling via exchange: 35997r, Delegate: 0x2000fc3c
D: 35035 [IM]Received Read request
D: 35038 [DMG]IM RH moving to [GeneratingReports]
D: 35043 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 35052 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 35057 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 35066 [DMG]<RE> Sending report (payload has 151 bytes)...
I: 35073 [EM]<<< [E:35997r M:67722830 (Ack:80920498)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 35084 [IN](S) Sending msg 67722830 on secure session with LSID: 47264
D: 35091 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 35096 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 35104 [DMG]IM RH moving to [AwaitingDestruction]
D: 35109 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 35208 [EM]>>> [E:35997r M:80920499 (Ack:67722830)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 35220 [EM]Found matching exchange: 35997r, Delegate: (nil)
D: 35226 [EM]Rxd Ack; Removing MessageCounter:67722830 from Retrans Table on exchange 35997r
I: 35245 [EM]>>> [E:35998r M:80920500] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 35255 [EM]Handling via exchange: 35998r, Delegate: 0x2000fc3c
D: 35261 [IM]Received Read request
D: 35265 [DMG]IM RH moving to [GeneratingReports]
D: 35269 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 35278 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 35283 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 35292 [DMG]<RE> Sending report (payload has 64 bytes)...
I: 35298 [EM]<<< [E:35998r M:67722831 (Ack:80920500)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 35309 [IN](S) Sending msg 67722831 on secure session with LSID: 47264
D: 35317 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 35322 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 35330 [DMG]IM RH moving to [AwaitingDestruction]
D: 35335 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 35412 [EM]>>> [E:35998r M:80920501 (Ack:67722831)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 35426 [EM]Found matching exchange: 35998r, Delegate: (nil)
D: 35432 [EM]Rxd Ack; Removing MessageCounter:67722831 from Retrans Table on exchange 35998r
I: 35441 [EM]>>> [E:35999r M:80920502] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 35451 [EM]Handling via exchange: 35999r, Delegate: 0x2000fc3c
D: 35457 [IM]Received Read request
D: 35461 [DMG]IM RH moving to [GeneratingReports]
D: 35465 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 35474 [DMG]<RE:Run> Cluster 1d, Attribute 0 is dirty
D: 35479 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
D: 35488 [DMG]<RE> Sending report (payload has 71 bytes)...
I: 35494 [EM]<<< [E:35999r M:67722832 (Ack:80920502)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 35505 [IN](S) Sending msg 67722832 on secure session with LSID: 47264
D: 35513 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 35518 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 35526 [DMG]IM RH moving to [AwaitingDestruction]
D: 35531 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 35619 [EM]>>> [E:35999r M:80920503 (Ack:67722832)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 35633 [EM]Found matching exchange: 35999r, Delegate: (nil)
D: 35639 [EM]Rxd Ack; Removing MessageCounter:67722832 from Retrans Table on exchange 35999r
I: 35648 [EM]>>> [E:36000r M:80920504] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 35658 [EM]Handling via exchange: 36000r, Delegate: 0x2000fc3c
D: 35664 [IM]Received Read request
D: 35667 [DMG]IM RH moving to [GeneratingReports]
D: 35672 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 35681 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
D: 35686 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0)
D: 35695 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 35701 [EM]<<< [E:36000r M:67722833 (Ack:80920504)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 35712 [IN](S) Sending msg 67722833 on secure session with LSID: 47264
D: 35720 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 35725 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 35732 [DMG]IM RH moving to [AwaitingDestruction]
D: 35737 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 35821 [EM]>>> [E:36000r M:80920505 (Ack:67722833)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 35836 [EM]Found matching exchange: 36000r, Delegate: (nil)
D: 35841 [EM]Rxd Ack; Removing MessageCounter:67722833 from Retrans Table on exchange 36000r
I: 35850 [EM]>>> [E:36001r M:80920506] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 35860 [EM]Handling via exchange: 36001r, Delegate: 0x2000fc3c
D: 35866 [IM]Received Read request
D: 35870 [DMG]IM RH moving to [GeneratingReports]
D: 35875 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 35883 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 35888 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
D: 35897 [DMG]<RE> Sending report (payload has 176 bytes)...
I: 35904 [EM]<<< [E:36001r M:67722834 (Ack:80920506)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 35915 [IN](S) Sending msg 67722834 on secure session with LSID: 47264
D: 35923 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 35928 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 35936 [DMG]IM RH moving to [AwaitingDestruction]
D: 35941 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 36032 [EM]>>> [E:36001r M:80920507 (Ack:67722834)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 36046 [EM]Found matching exchange: 36001r, Delegate: (nil)
D: 36052 [EM]Rxd Ack; Removing MessageCounter:67722834 from Retrans Table on exchange 36001r
I: 36061 [EM]>>> [E:36002r M:80920508] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 36071 [EM]Handling via exchange: 36002r, Delegate: 0x2000fc3c
D: 36077 [IM]Received Read request
D: 36081 [DMG]IM RH moving to [GeneratingReports]
D: 36085 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 36094 [DMG]<RE:Run> Cluster 8, Attribute fffc is dirty
D: 36099 [DMG]Reading attribute: Cluster=0x0000_0008 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
D: 36108 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 36114 [EM]<<< [E:36002r M:67722835 (Ack:80920508)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 36125 [IN](S) Sending msg 67722835 on secure session with LSID: 47264
D: 36133 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 36138 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 36145 [DMG]IM RH moving to [AwaitingDestruction]
D: 36150 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 36204 [EM]>>> [E:36002r M:80920509 (Ack:67722835)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 36218 [EM]Found matching exchange: 36002r, Delegate: (nil)
D: 36223 [EM]Rxd Ack; Removing MessageCounter:67722835 from Retrans Table on exchange 36002r
I: 36232 [EM]>>> [E:36003r M:80920510] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 36243 [EM]Handling via exchange: 36003r, Delegate: 0x2000fc3c
D: 36248 [IM]Received Read request
D: 36252 [DMG]IM RH moving to [GeneratingReports]
D: 36257 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 36265 [DMG]<RE:Run> Cluster 6, Attribute fffc is dirty
D: 36270 [DMG]Reading attribute: Cluster=0x0000_0006 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
D: 36279 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 36286 [EM]<<< [E:36003r M:67722836 (Ack:80920510)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 36297 [IN](S) Sending msg 67722836 on secure session with LSID: 47264
D: 36304 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 36309 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 36317 [DMG]IM RH moving to [AwaitingDestruction]
D: 36322 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 36337 [EM]>>> [E:36003r M:80920511 (Ack:67722836)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 36352 [EM]Found matching exchange: 36003r, Delegate: (nil)
D: 36357 [EM]Rxd Ack; Removing MessageCounter:67722836 from Retrans Table on exchange 36003r
I: 36366 [EM]>>> [E:36004r M:80920512] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:02 (IM:ReadRequest)
D: 36377 [EM]Handling via exchange: 36004r, Delegate: 0x2000fc3c
D: 36382 [IM]Received Read request
D: 36386 [DMG]IM RH moving to [GeneratingReports]
D: 36391 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 36399 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 36404 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 36413 [DMG]<RE> Sending report (payload has 151 bytes)...
I: 36420 [EM]<<< [E:36004r M:67722837 (Ack:80920512)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:05 (IM:ReportData)
I: 36431 [IN](S) Sending msg 67722837 on secure session with LSID: 47264
D: 36439 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 36444 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 36452 [DMG]IM RH moving to [AwaitingDestruction]
D: 36457 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 36498 [EM]>>> [E:36004r M:80920513 (Ack:67722837)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 36511 [EM]Found matching exchange: 36004r, Delegate: (nil)
D: 36516 [EM]Rxd Ack; Removing MessageCounter:67722837 from Retrans Table on exchange 36004r
I: 36612 [EM]>>> [E:36005r M:80920514] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:0a (IM:TimedRequest)
D: 36624 [EM]Handling via exchange: 36005r, Delegate: 0x2000fc3c
D: 36630 [DMG]Got Timed Request with timeout 10000: handler 0x20010038 exchange 36005r
I: 36638 [EM]<<< [E:36005r M:67722838 (Ack:80920514)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:01 (IM:StatusResponse)
I: 36650 [IN](S) Sending msg 67722838 on secure session with LSID: 47264
D: 36658 [DMG]Timed Request time limit 0x000000000000B642: handler 0x20010038 exchange 36005r
I: 36707 [EM]>>> [E:36005r M:80920515 (Ack:67722838)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 36719 [EM]Found matching exchange: 36005r, Delegate: 0x20010038
D: 36725 [EM]Rxd Ack; Removing MessageCounter:67722838 from Retrans Table on exchange 36005r
D: 36734 [DMG]Timed following action arrived at 0x0000000000008F7D: handler 0x20010038 exchange 36005r
D: 36743 [DMG]Handing timed invoke to IM engine: handler 0x20010038 exchange 36005r
D: 36751 [DMG]Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000
I: 36758 [ZCL]Received command to open commissioning window
D: 36764 [IN]SecureSession[0x20003650]: Allocated Type:1 LSID:47266
D: 36770 [SC]Assigned local session key ID 47266
D: 36774 [SC]Waiting for PBKDF param request
I: 36778 [DIS]Updating services using commissioning mode 2
D: 36784 [DL]Using Thread extended MAC for hostname.
I: 36788 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 36795 [DL]Using Thread extended MAC for hostname.
I: 36801 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=1584/06 cm=2
I: 36811 [DL]advertising srp service: BBBE10F08F15CD18._matterc._udp
I: 36817 [DL]removing srp service: 1FF399984299BA94._matterc._udp
I: 36823 [ZCL]Commissioning window is now open
D: 36827 [DMG]Command handler moving to [ Preparing]
D: 36832 [DMG]Command handler moving to [AddingComm]
D: 36837 [DMG]Command handler moving to [AddedComma]
D: 36841 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 36849 [EM]<<< [E:36005r M:67722839 (Ack:80920515)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 36861 [IN](S) Sending msg 67722839 on secure session with LSID: 47264
D: 36869 [DMG]Command handler moving to [CommandSen]
D: 36873 [DMG]Command handler moving to [AwaitingDe]
I: 36898 [EM]>>> [E:36005r M:80920516 (Ack:67722839)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 36911 [EM]Found matching exchange: 36005r, Delegate: (nil)
D: 36917 [EM]Rxd Ack; Removing MessageCounter:67722839 from Retrans Table on exchange 36005r
D: 38052 [DL]SRP update succeeded
I: 41172 [EM]>>> [E:50806r M:205993253] (U) Msg RX from 0:785B27F217FBAAA1 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 41184 [EM]Handling via exchange: 50806r, Delegate: 0x20005834
I: 41190 [EM]<<< [E:50806r M:143534049 (Ack:205993253)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 41202 [IN](U) Sending msg 143534049 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 41213 [EM]Flushed pending ack for MessageCounter:205993253 on exchange 50806r
D: 41220 [SC]Received PBKDF param request
D: 41224 [SC]Peer assigned session ID 55745
D: 41228 [SC]Found MRP parameters in the message
D: 41233 [SC]Including MRP parameters in PBKDF param response
I: 41239 [EM]<<< [E:50806r M:143534050 (Ack:205993253)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 41252 [IN](U) Sending msg 143534050 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 41263 [SC]Sent PBKDF param response
I: 41525 [EM]>>> [E:50806r M:205993254 (Ack:143534050)] (U) Msg RX from 0:785B27F217FBAAA1 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 41537 [EM]Found matching exchange: 50806r, Delegate: 0x20005834
D: 41543 [EM]Rxd Ack; Removing MessageCounter:143534050 from Retrans Table on exchange 50806r
I: 41552 [EM]<<< [E:50806r M:143534051 (Ack:205993254)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 41565 [IN](U) Sending msg 143534051 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 41575 [EM]Flushed pending ack for MessageCounter:205993254 on exchange 50806r
D: 41582 [SC]Received spake2p msg1
I: 43506 [EM]<<< [E:50806r M:143534052 (Ack:205993254)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 43519 [IN](U) Sending msg 143534052 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 43529 [SC]Sent spake2p msg2
I: 43666 [EM]>>> [E:50806r M:205993255 (Ack:143534052)] (U) Msg RX from 0:785B27F217FBAAA1 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 43679 [EM]Found matching exchange: 50806r, Delegate: 0x20005834
D: 43685 [EM]Rxd Ack; Removing MessageCounter:143534052 from Retrans Table on exchange 50806r
I: 43693 [EM]<<< [E:50806r M:143534053 (Ack:205993255)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 43706 [IN](U) Sending msg 143534053 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 43716 [EM]Flushed pending ack for MessageCounter:205993255 on exchange 50806r
D: 43723 [SC]Received spake2p msg3
D: 43728 [SC]Sending status report. Protocol code 0, exchange 50806
I: 43734 [EM]<<< [E:50806r M:143534054 (Ack:205993255)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 43746 [IN](U) Sending msg 143534054 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
I: 43758 [SC]SecureSession[0x20003650]: Moving from state 'kEstablishing' --> 'kActive'
D: 43767 [IN]SecureSession[0x20003650]: Activated - Type:1 LSID:47266
D: 43773 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:47266 PSID:55745!
I: 43782 [SVR]Commissioning completed session establishment step
I: 43788 [DIS]Updating services using commissioning mode 0
D: 43793 [DL]Using Thread extended MAC for hostname.
I: 43798 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 43806 [DL]Using Thread extended MAC for hostname.
I: 43814 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 43825 [DL]advertising srp service: BBBE10F08F15CD18._matterc._udp
D: 43831 [DIS]Scheduling extended discovery timeout in 900s
I: 43836 [SVR]Device completed Rendezvous process
I: 43841 [EM]>>> [E:50806r M:205993256 (Ack:143534054)] (U) Msg RX from 0:785B27F217FBAAA1 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 43854 [EM]Found matching exchange: 50806r, Delegate: (nil)
D: 43859 [EM]Rxd Ack; Removing MessageCounter:143534054 from Retrans Table on exchange 50806r
I: 43869 [EM]>>> [E:50807r M:190603305] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 43879 [EM]Handling via exchange: 50807r, Delegate: 0x2000fc3c
D: 43885 [IM]Received Read request
D: 43891 [DMG]IM RH moving to [GeneratingReports]
D: 43896 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 43904 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 43909 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 43918 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 43923 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 43932 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 43937 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 43946 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 43951 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 43960 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 43965 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 43974 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 43979 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 43988 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 43993 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 44002 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 44007 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 44016 [DMG]<RE> Sending report (payload has 228 bytes)...
I: 44023 [EM]<<< [E:50807r M:32623934 (Ack:190603305)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 44035 [IN](S) Sending msg 32623934 on secure session with LSID: 47266
D: 44043 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 44047 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 44055 [DMG]IM RH moving to [AwaitingDestruction]
D: 44060 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 44122 [EM]>>> [E:50808r M:190603306] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44135 [EM]Handling via exchange: 50808r, Delegate: 0x2000fc3c
D: 44141 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 44149 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 44155 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf0a
D: 44161 [DMG]Command handler moving to [ Preparing]
D: 44166 [DMG]Command handler moving to [AddingComm]
D: 44170 [DMG]Command handler moving to [AddedComma]
D: 44175 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44219 [EM]<<< [E:50808r M:32623935 (Ack:190603306)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44231 [IN](S) Sending msg 32623935 on secure session with LSID: 47266
D: 44240 [DMG]Command handler moving to [CommandSen]
D: 44245 [DMG]Command handler moving to [AwaitingDe]
I: 44251 [EM]>>> [E:50807r M:190603307 (Ack:32623934)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 44265 [EM]Found matching exchange: 50807r, Delegate: (nil)
D: 44270 [EM]Rxd Ack; Removing MessageCounter:32623934 from Retrans Table on exchange 50807r
I: 44428 [EM]>>> [E:50809r M:190603308] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44440 [EM]Handling via exchange: 50809r, Delegate: 0x2000fc3c
D: 44447 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 44456 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf0b
D: 44462 [DMG]Command handler moving to [ Preparing]
D: 44467 [DMG]Command handler moving to [AddingComm]
D: 44473 [DL]SRP update succeeded
D: 44476 [DMG]Command handler moving to [AddedComma]
D: 44481 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44488 [EM]<<< [E:50809r M:32623936 (Ack:190603308)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44500 [IN](S) Sending msg 32623936 on secure session with LSID: 47266
D: 44508 [DMG]Command handler moving to [CommandSen]
D: 44513 [DMG]Command handler moving to [AwaitingDe]
I: 44519 [EM]>>> [E:50808r M:190603309 (Ack:32623935)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 44531 [EM]Found matching exchange: 50808r, Delegate: (nil)
D: 44537 [EM]Rxd Ack; Removing MessageCounter:32623935 from Retrans Table on exchange 50808r
I: 44628 [EM]>>> [E:50810r M:190603310] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44640 [EM]Handling via exchange: 50810r, Delegate: 0x2000fc3c
D: 44647 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 44654 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 44660 [DMG]Command handler moving to [ Preparing]
D: 44665 [DMG]Command handler moving to [AddingComm]
D: 44670 [DMG]Command handler moving to [AddedComma]
D: 44675 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44684 [EM]<<< [E:50810r M:32623937 (Ack:190603310)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44696 [IN](S) Sending msg 32623937 on secure session with LSID: 47266
D: 44704 [DMG]Command handler moving to [CommandSen]
D: 44709 [DMG]Command handler moving to [AwaitingDe]
I: 44716 [EM]>>> [E:50809r M:190603311 (Ack:32623936)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 44729 [EM]Found matching exchange: 50809r, Delegate: (nil)
D: 44735 [EM]Rxd Ack; Removing MessageCounter:32623936 from Retrans Table on exchange 50809r
I: 44838 [EM]>>> [E:50811r M:190603312] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 44851 [EM]Handling via exchange: 50811r, Delegate: 0x2000fc3c
D: 44857 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 44864 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 44870 [DMG]Command handler moving to [ Preparing]
D: 44875 [DMG]Command handler moving to [AddingComm]
D: 44880 [DMG]Command handler moving to [AddedComma]
D: 44885 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 44894 [EM]<<< [E:50811r M:32623938 (Ack:190603312)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 44906 [IN](S) Sending msg 32623938 on secure session with LSID: 47266
D: 44914 [DMG]Command handler moving to [CommandSen]
D: 44919 [DMG]Command handler moving to [AwaitingDe]
I: 44925 [EM]>>> [E:50810r M:190603313 (Ack:32623937)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 44938 [EM]Found matching exchange: 50810r, Delegate: (nil)
D: 44944 [EM]Rxd Ack; Removing MessageCounter:32623937 from Retrans Table on exchange 50810r
I: 45047 [EM]>>> [E:50812r M:190603314] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 45060 [EM]Handling via exchange: 50812r, Delegate: 0x2000fc3c
D: 45066 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 45074 [ZCL]OpCreds: Received an AttestationRequest command
I: 45080 [EM]<<< [E:50812r M:32623939 (Ack:190603314)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 45092 [IN](S) Sending msg 32623939 on secure session with LSID: 47266
D: 45100 [EM]Flushed pending ack for MessageCounter:190603314 on exchange 50812r
I: 45139 [ZCL]OpCreds: AttestationRequest successful.
D: 45143 [DMG]Command handler moving to [ Preparing]
D: 45148 [DMG]Command handler moving to [AddingComm]
D: 45153 [DMG]Command handler moving to [AddedComma]
D: 45158 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 45168 [EM]<<< [E:50812r M:32623940 (Ack:190603314)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45180 [IN](S) Sending msg 32623940 on secure session with LSID: 47266
D: 45188 [DMG]Command handler moving to [CommandSen]
D: 45193 [DMG]Command handler moving to [AwaitingDe]
I: 45199 [EM]>>> [E:50811r M:190603315 (Ack:32623938)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 45212 [EM]Found matching exchange: 50811r, Delegate: (nil)
D: 45218 [EM]Rxd Ack; Removing MessageCounter:32623938 from Retrans Table on exchange 50811r
I: 45395 [EM]>>> [E:50813r M:190603316] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 45408 [EM]Handling via exchange: 50813r, Delegate: 0x2000fc3c
D: 45414 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 45421 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 45427 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf0c
D: 45434 [DMG]Command handler moving to [ Preparing]
D: 45438 [DMG]Command handler moving to [AddingComm]
D: 45443 [DMG]Command handler moving to [AddedComma]
D: 45448 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 45455 [EM]<<< [E:50813r M:32623941 (Ack:190603316)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45467 [IN](S) Sending msg 32623941 on secure session with LSID: 47266
D: 45475 [DMG]Command handler moving to [CommandSen]
D: 45480 [DMG]Command handler moving to [AwaitingDe]
I: 45486 [EM]>>> [E:50812r M:190603317 (Ack:32623940)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 45498 [EM]Found matching exchange: 50812r, Delegate: (nil)
D: 45504 [EM]Rxd Ack; Removing MessageCounter:32623940 from Retrans Table on exchange 50812r
I: 45550 [EM]>>> [E:50813r M:190603318 (Ack:32623941)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 45565 [EM]Found matching exchange: 50813r, Delegate: (nil)
D: 45571 [EM]Rxd Ack; Removing MessageCounter:32623941 from Retrans Table on exchange 50813r
I: 45580 [EM]>>> [E:50814r M:190603319] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 45591 [EM]Handling via exchange: 50814r, Delegate: 0x2000fc3c
D: 45597 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 45605 [ZCL]OpCreds: Received a CSRRequest command
D: 45610 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 45616 [EM]<<< [E:50814r M:32623942 (Ack:190603319)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 45628 [IN](S) Sending msg 32623942 on secure session with LSID: 47266
D: 45635 [EM]Flushed pending ack for MessageCounter:190603319 on exchange 50814r
I: 45834 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 45869 [ZCL]OpCreds: CSRRequest successful.
D: 45873 [DMG]Command handler moving to [ Preparing]
D: 45878 [DMG]Command handler moving to [AddingComm]
D: 45883 [DMG]Command handler moving to [AddedComma]
D: 45888 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 45896 [EM]<<< [E:50814r M:32623943 (Ack:190603319)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45909 [IN](S) Sending msg 32623943 on secure session with LSID: 47266
D: 45916 [DMG]Command handler moving to [CommandSen]
D: 45921 [DMG]Command handler moving to [AwaitingDe]
I: 46134 [EM]>>> [E:50815r M:190603320] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 46146 [EM]Handling via exchange: 50815r, Delegate: 0x2000fc3c
D: 46153 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 46160 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 46167 [EM]<<< [E:50815r M:32623944 (Ack:190603320)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 46179 [IN](S) Sending msg 32623944 on secure session with LSID: 47266
D: 46187 [EM]Flushed pending ack for MessageCounter:190603320 on exchange 50815r
I: 46252 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 46258 [DMG]Command handler moving to [ Preparing]
D: 46262 [DMG]Command handler moving to [AddingComm]
D: 46267 [DMG]Command handler moving to [AddedComma]
D: 46272 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 46279 [EM]<<< [E:50815r M:32623945 (Ack:190603320)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 46292 [IN](S) Sending msg 32623945 on secure session with LSID: 47266
D: 46299 [DMG]Command handler moving to [CommandSen]
D: 46304 [DMG]Command handler moving to [AwaitingDe]
D: 46309 [EM]Retransmitting MessageCounter:32623943 on exchange 50814r Send Cnt 1
I: 46317 [IN](S) Sending msg 32623943 on secure session with LSID: 47266
I: 46325 [EM]>>> [E:50814r M:190603321 (Ack:32623943)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 46338 [EM]Found matching exchange: 50814r, Delegate: (nil)
D: 46345 [EM]Rxd Ack; Removing MessageCounter:32623943 from Retrans Table on exchange 50814r
I: 46400 [EM]>>> [E:50816r M:190603322] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 46413 [EM]Handling via exchange: 50816r, Delegate: 0x2000fc3c
D: 46421 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 46429 [ZCL]OpCreds: Received an AddNOC command
I: 46434 [EM]<<< [E:50816r M:32623946 (Ack:190603322)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 46446 [IN](S) Sending msg 32623946 on secure session with LSID: 47266
D: 46454 [EM]Flushed pending ack for MessageCounter:190603322 on exchange 50816r
I: 46466 [FP]Validating NOC chain
I: 46527 [FP]NOC chain validation successful
I: 46531 [FP]Added new fabric at index: 0x2
I: 46535 [FP]Assigned compressed fabric ID: 0x900546F7F75D5541, node ID: 0x00000000445EB8EE
I: 46543 [TS]Last Known Good Time: 2023-01-23T12:35:13
I: 46548 [TS]New proposed Last Known Good Time: 2023-01-23T12:35:32
I: 46554 [TS]Updating pending Last Known Good Time to 2023-01-23T12:35:32
D: 46561 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d6
D: 46568 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d7
D: 46733 [EVL]LogEvent event number: 0x0000000000010003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000000B68C
I: 46747 [ZCL]OpCreds: ACL entry created for Fabric index 0x2 CASE Admin Subject 0x7B0E2B9DBC3CE547
D: 46755 [DL]Using Thread extended MAC for hostname.
I: 46760 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 46767 [DL]Using Thread extended MAC for hostname.
I: 46772 [DIS]Advertise operational node 900546F7F75D5541-00000000445EB8EE
I: 46779 [DL]advertising srp service: 900546F7F75D5541-00000000445EB8EE._matter._tcp
D: 46787 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d8
D: 46793 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717d9
D: 46800 [DMG]Command handler moving to [ Preparing]
D: 46804 [DMG]Command handler moving to [AddingComm]
D: 46809 [DMG]Command handler moving to [AddedComma]
I: 46814 [ZCL]OpCreds: successfully created fabric index 0x2 via AddNOC
D: 46820 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 46828 [EM]<<< [E:50816r M:32623947 (Ack:190603322)] (S) Msg TX to 2:FFFFFFFB00000000 [5541] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 46840 [IN](S) Sending msg 32623947 on secure session with LSID: 47266
D: 46847 [DMG]Command handler moving to [CommandSen]
D: 46852 [DMG]Command handler moving to [AwaitingDe]
D: 46858 [EM]Retransmitting MessageCounter:32623945 on exchange 50815r Send Cnt 1
I: 46865 [IN](S) Sending msg 32623945 on secure session with LSID: 47266
I: 46874 [EM]>>> [E:50815r M:190603323 (Ack:32623945)] (S) Msg RX from 2:FFFFFFFB00000000 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 46887 [EM]Found matching exchange: 50815r, Delegate: (nil)
D: 46892 [EM]Rxd Ack; Removing MessageCounter:32623945 from Retrans Table on exchange 50815r
I: 46902 [EM]>>> [E:50814r M:190603324 (Ack:32623943)] (S) Msg RX from 2:FFFFFFFB00000000 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 46990 [EM]>>> [E:50816r M:190603325 (Ack:32623947)] (S) Msg RX from 2:FFFFFFFB00000000 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 47004 [EM]Found matching exchange: 50816r, Delegate: (nil)
D: 47009 [EM]Rxd Ack; Removing MessageCounter:32623947 from Retrans Table on exchange 50816r
I: 47018 [EM]>>> [E:50815r M:190603326 (Ack:32623945)] (S) Msg RX from 2:FFFFFFFB00000000 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 48103 [DL]SRP update succeeded
I: 48548 [EM]>>> [E:50817r M:205993257] (U) Msg RX from 0:5714B5DEA12309EF [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 48560 [EM]Handling via exchange: 50817r, Delegate: 0x200042c0
I: 48565 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004fd0
I: 48573 [IN]CASE Server disabling CASE session setups
I: 48578 [EM]<<< [E:50817r M:143534055 (Ack:205993257)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 48591 [IN](U) Sending msg 143534055 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 48601 [EM]Flushed pending ack for MessageCounter:205993257 on exchange 50817r
I: 48608 [SC]Received Sigma1 msg
D: 48611 [SC]Found MRP parameters in the message
D: 48616 [SC]Peer assigned session key ID 55746
I: 48628 [SC]CASE matched destination ID: fabricIndex 2, NodeID 0x00000000445EB8EE
D: 48852 [SC]Including MRP parameters
I: 48856 [EM]<<< [E:50817r M:143534056 (Ack:205993257)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 48868 [IN](U) Sending msg 143534056 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
I: 48879 [SC]Sent Sigma2 msg
I: 49269 [EM]>>> [E:50817r M:205993258 (Ack:143534056)] (U) Msg RX from 0:5714B5DEA12309EF [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D: 49282 [EM]Found matching exchange: 50817r, Delegate: 0x200042dc
D: 49288 [EM]Rxd Ack; Removing MessageCounter:143534056 from Retrans Table on exchange 50817r
I: 49296 [EM]<<< [E:50817r M:143534057 (Ack:205993258)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 49309 [IN](U) Sending msg 143534057 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
D: 49319 [EM]Flushed pending ack for MessageCounter:205993258 on exchange 50817r
I: 49326 [SC]Received Sigma3 msg
E: 49333 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time
D: 49584 [SC]Sending status report. Protocol code 0, exchange 50817
I: 49590 [EM]<<< [E:50817r M:143534058 (Ack:205993258)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 49603 [IN](U) Sending msg 143534058 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
I: 49614 [SC]SecureSession[0x200037c0]: Moving from state 'kEstablishing' --> 'kActive'
D: 49622 [IN]SecureSession[0x200037c0]: Activated - Type:2 LSID:47265
D: 49629 [IN]New secure session activated for device <7B0E2B9DBC3CE547, 2>, LSID:47265 PSID:55746!
I: 49637 [IN]CASE Session established to peer: <7B0E2B9DBC3CE547, 2>
I: 49644 [IN]CASE Server enabling CASE session setups
D: 49649 [IN]SecureSession[0x20003878]: Allocated Type:2 LSID:47267
D: 49655 [SC]Allocated SecureSession (0x20003878) - waiting for Sigma1 msg
I: 49772 [EM]>>> [E:50818r M:194313572] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 49784 [EM]Handling via exchange: 50818r, Delegate: 0x2000fc3c
D: 49791 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
I: 49798 [FS]GeneralCommissioning: Received CommissioningComplete
I: 49904 [FP]Metadata for Fabric 0x2 persisted to storage.
I: 50081 [TS]Committing Last Known Good Time to storage: 2023-01-23T12:35:32
I: 50128 [ZCL]OpCreds: Fabric index 0x2 was committed to storage. Compressed Fabric Id 0x900546F7F75D5541, FabricId 0000000000000002, NodeId 00000000445EB8EE, VendorId 0x1384
I: 50161 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 50168 [FS]Fail-safe cleanly disarmed
D: 50172 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 1e1adf0d
D: 50178 [DMG]Command handler moving to [ Preparing]
D: 50183 [DMG]Command handler moving to [AddingComm]
D: 50188 [DMG]Command handler moving to [AddedComma]
D: 50192 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 50200 [EM]<<< [E:50818r M:15482061 (Ack:194313572)] (S) Msg TX to 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 50212 [IN](S) Sending msg 15482061 on secure session with LSID: 47265
D: 50220 [DMG]Command handler moving to [CommandSen]
D: 50224 [DMG]Command handler moving to [AwaitingDe]
I: 50229 [SWU]Device commissioned, schedule a default provider query
I: 50236 [SVR]Commissioning completed successfully
I: 50240 [DIS]Updating services using commissioning mode 0
D: 50245 [DL]Using Thread extended MAC for hostname.
I: 50250 [DIS]Advertise operational node 7FE9B764118685EB-0000000073B72630
D: 50257 [DL]Using Thread extended MAC for hostname.
I: 50262 [DIS]Advertise operational node 900546F7F75D5541-00000000445EB8EE
D: 50269 [DL]Using Thread extended MAC for hostname.
I: 50275 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
D: 50284 [IN]Expiring all PASE sessions
D: 50288 [IN]SecureSession[0x20003650]: MarkForEviction Type:1 LSID:47266
I: 50295 [SC]SecureSession[0x20003650]: Moving from state 'kActive' --> 'kPendingEviction'
D: 50303 [IN]SecureSession[0x20003650]: Released - Type:1 LSID:47266
D: 50309 [ZCL]Commissioning complete, notify platform driver to persist network credentials.
D: 50320 [EM]Retransmitting MessageCounter:143534058 on exchange 50817r Send Cnt 1
I: 50329 [IN](U) Sending msg 143534058 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:61749'
I: 50341 [EM]>>> [E:50817r M:205993259 (Ack:143534058)] (U) Msg RX from 0:5714B5DEA12309EF [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 50354 [EM]Found matching exchange: 50817r, Delegate: (nil)
D: 50359 [EM]Rxd Ack; Removing MessageCounter:143534058 from Retrans Table on exchange 50817r
I: 50370 [EM]>>> [E:50818r M:194313573 (Ack:15482061)] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 50383 [EM]Found matching exchange: 50818r, Delegate: (nil)
D: 50388 [EM]Rxd Ack; Removing MessageCounter:15482061 from Retrans Table on exchange 50818r
I: 50397 [EM]>>> [E:50819r M:194313574] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:02 (IM:ReadRequest)
D: 50408 [EM]Handling via exchange: 50819r, Delegate: 0x2000fc3c
D: 50413 [IM]Received Read request
D: 50417 [DMG]IM RH moving to [GeneratingReports]
D: 50422 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 50430 [DMG]<RE:Run> Cluster 28, Attribute f is dirty
D: 50435 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_000F (expanded=0)
D: 50445 [DMG]<RE> Sending report (payload has 56 bytes)...
I: 50452 [EM]<<< [E:50819r M:15482062 (Ack:194313574)] (S) Msg TX to 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:05 (IM:ReportData)
I: 50463 [IN](S) Sending msg 15482062 on secure session with LSID: 47265
D: 50471 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 50475 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 50483 [DMG]IM RH moving to [AwaitingDestruction]
D: 50488 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 50495 [EM]>>> [E:50817r M:205993260 (Ack:143534058)] (U) Msg RX from 0:5714B5DEA12309EF [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 50515 [EM]>>> [E:50819r M:194313575 (Ack:15482062)] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 50529 [EM]Found matching exchange: 50819r, Delegate: (nil)
D: 50535 [EM]Rxd Ack; Removing MessageCounter:15482062 from Retrans Table on exchange 50819r
I: 50544 [EM]>>> [E:50820r M:194313576] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:02 (IM:ReadRequest)
D: 50554 [EM]Handling via exchange: 50820r, Delegate: 0x2000fc3c
D: 50560 [IM]Received Read request
D: 50563 [DMG]IM RH moving to [GeneratingReports]
D: 50568 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 50577 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 50582 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 50591 [DMG]<RE> Sending report (payload has 151 bytes)...
I: 50598 [EM]<<< [E:50820r M:15482063 (Ack:194313576)] (S) Msg TX to 2:7B0E2B9DBC3CE547 [5541] --- Type 0001:05 (IM:ReportData)
I: 50609 [IN](S) Sending msg 15482063 on secure session with LSID: 47265
D: 50617 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 50621 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 50629 [DMG]IM RH moving to [AwaitingDestruction]
D: 50634 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 50675 [EM]>>> [E:50820r M:194313577 (Ack:15482063)] (S) Msg RX from 2:7B0E2B9DBC3CE547 [5541] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 50687 [EM]Found matching exchange: 50820r, Delegate: (nil)
D: 50693 [EM]Rxd Ack; Removing MessageCounter:15482063 from Retrans Table on exchange 50820r
I: 51431 [EM]>>> [E:54885r M:142649066] (U) Msg RX from 0:B4A448358E32F6ED [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 51442 [EM]Handling via exchange: 54885r, Delegate: 0x200042c0
I: 51448 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004fd0
I: 51455 [IN]CASE Server disabling CASE session setups
I: 51460 [EM]<<< [E:54885r M:143534059 (Ack:142649066)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 51473 [IN](U) Sending msg 143534059 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:54789'
D: 51483 [EM]Flushed pending ack for MessageCounter:142649066 on exchange 54885r
I: 51491 [SC]Received Sigma1 msg
D: 51494 [SC]Found MRP parameters in the message
D: 51499 [SC]Peer assigned session key ID 58147
I: 51507 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000073B72630
D: 51733 [SC]Including MRP parameters
I: 51737 [EM]<<< [E:54885r M:143534060 (Ack:142649066)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 51750 [IN](U) Sending msg 143534060 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:54789'
I: 51761 [SC]Sent Sigma2 msg
I: 51928 [EM]>>> [E:54885r M:142649067 (Ack:143534060)] (U) Msg RX from 0:B4A448358E32F6ED [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D: 51941 [EM]Found matching exchange: 54885r, Delegate: 0x200042dc
D: 51947 [EM]Rxd Ack; Removing MessageCounter:143534060 from Retrans Table on exchange 54885r
I: 51955 [EM]<<< [E:54885r M:143534061 (Ack:142649067)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 51968 [IN](U) Sending msg 143534061 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:54789'
D: 51978 [EM]Flushed pending ack for MessageCounter:142649067 on exchange 54885r
I: 51986 [SC]Received Sigma3 msg
E: 51992 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time
D: 52217 [SC]Sending status report. Protocol code 0, exchange 54885
I: 52223 [EM]<<< [E:54885r M:143534062 (Ack:142649067)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 52236 [IN](U) Sending msg 143534062 to IP address 'UDP:[fd80:d9bd:16c8:4864:14e0:b63c:62d6:367c]:54789'
I: 52247 [SC]SecureSession[0x20003878]: Moving from state 'kEstablishing' --> 'kActive'
D: 52255 [IN]SecureSession[0x20003878]: Activated - Type:2 LSID:47267
D: 52262 [IN]New secure session activated for device <4925A783D435A3C5, 1>, LSID:47267 PSID:58147!
I: 52271 [IN]CASE Session established to peer: <4925A783D435A3C5, 1>
I: 52277 [IN]CASE Server enabling CASE session setups
D: 52282 [IN]SecureSession[0x20003650]: Allocated Type:2 LSID:47268
D: 52288 [SC]Allocated SecureSession (0x20003650) - waiting for Sigma1 msg
I: 52443 [EM]>>> [E:54885r M:142649068 (Ack:143534062)] (U) Msg RX from 0:B4A448358E32F6ED [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 52458 [EM]Found matching exchange: 54885r, Delegate: (nil)
D: 52464 [EM]Rxd Ack; Removing MessageCounter:143534062 from Retrans Table on exchange 54885r
I: 52473 [EM]>>> [E:54886r M:188583783] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 52484 [EM]Handling via exchange: 54886r, Delegate: 0x2000fc3c
D: 52490 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0009
I: 52498 [ZCL]OpCreds: Received an UpdateFabricLabel command
I: 52526 [FP]Metadata for Fabric 0x1 persisted to storage.
D: 52531 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 835717da
D: 52538 [DMG]Command handler moving to [ Preparing]
D: 52542 [DMG]Command handler moving to [AddingComm]
D: 52547 [DMG]Command handler moving to [AddedComma]
D: 52552 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 52559 [EM]<<< [E:54886r M:264982175 (Ack:188583783)] (S) Msg TX to 1:4925A783D435A3C5 [85EB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 52572 [IN](S) Sending msg 264982175 on secure session with LSID: 47267
D: 52579 [DMG]Command handler moving to [CommandSen]
D: 52584 [DMG]Command handler moving to [AwaitingDe]
I: 52610 [EM]>>> [E:54886r M:188583784 (Ack:264982175)] (S) Msg RX from 1:4925A783D435A3C5 [85EB] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 52622 [EM]Found matching exchange: 54886r, Delegate: (nil)
D: 52628 [EM]Rxd Ack; Removing MessageCounter:264982175 from Retrans Table on exchange 54886r
D: 61713 [DL]OpenThread State Changed (Flags: 0x00000064)
D: 61718 [DL] Device Role: ROUTER
E: 80237 [SWU]No suitable OTA Provider candidate found
I: 80241 [SWU]No provider available

[jahess]

FWIW, I also tried immediately renaming the device and letting the default stick -- both had same non-responsive result.