Google Home App - Matter commissioning fails

Hi - I am trying to commission my NRF5340DK board with NRF Connect SDK v.2.1.1 using Google Home App over Matter using the Matter light bulb sample.

My OTBR is a Google Nest Hub 2 running Chrome OS

My smartphone is Motorola Pure G running Android 11; Google Home Assistant app (GHA) version: 2.60.1.19

The GHA app is able to connect and begin the matter commissioning process. See the log from the NRF5340DK below. But after a few moments, while waiting to connect, the GHA "Connecting to Device Screen" abruptly closes (crashes?) and brings me back to my GHA home settings screen with nothing added.

Welcome any suggestions or advice. I am excited and eager to get my Nordic device to be controllable with GHA.

Thanks! Dan.

uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 1, e20
I: data wra: 1, 310
*** Booting Zephyr OS build v3.1.99-ncs1  ***
I: Init CHIP stack
I: 173 [DL]BLE address: D0:50:98:AB:07:E6
I: 199 [DL]OpenThread started: OK
I: 202 [DL]Setting OpenThread device type to ROUTER
I: 207 [SVR]Server initializing...
D: 210 [FP]Initializing FabricTable from persistent storage
I: 216 [TS]Last Known Good Time: 2022-11-04T17:19:10
I: 221 [DMG]AccessControl: initializing
I: 225 [DMG]Examples::AccessControlDelegate::Init
I: 229 [DMG]AccessControl: setting
I: 232 [DMG]DefaultAclStorage: initializing
I: 236 [DMG]DefaultAclStorage: 0 entries loaded
D: 240 [IN]UDP::Init bind&listen port=5540
E: 244 [IN]SO_REUSEPORT failed: 109
D: 248 [IN]UDP::Init bound to port=5540
D: 251 [IN]BLEBase::Init - setting/overriding transport
D: 256 [IN]TransportMgr initialized
D: 262 [DL]Using Thread extended MAC for hostname.
I: 267 [ZCL]Using ZAP configuration...
D: 272 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 280 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 287 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 294 [DMG]AccessControlCluster: initializing
D: 298 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b3226524
D: 305 [DL]Boot reason: 1
D: 307 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 311 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 79b42976
D: 318 [EVL]LogEvent event number: 0x00000000000B0000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000013D
I: 331 [ZCL]Initiating Admin Commissioning cluster.
D: 336 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to d7cb0a04
D: 343 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 7add5022
D: 349 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 7add5023
I: 355 [ZCL]On/Off set value: 1 0
I: 358 [ZCL]On/off already set to new value
D: 363 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 74ff3545
I: 369 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 375 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 385 [IN]SecureSession[0x20004440]: Allocated Type:1 LSID:3920
D: 390 [SC]Assigned local session key ID 3920
D: 394 [SC]Waiting for PBKDF param request
D: 398 [DL]CHIPoBLE advertising set to on
I: 402 [DIS]Updating services using commissioning mode 1
D: 407 [DL]Using Thread extended MAC for hostname.
D: 412 [DL]Using Thread extended MAC for hostname.
I: 417 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 426 [DIS]Failed to advertise commissionable node: 3
E: 431 [DIS]Failed to finalize service update: 1c
I: 435 [DIS]Updating services using commissioning mode 1
D: 440 [DL]Using Thread extended MAC for hostname.
D: 445 [DL]Using Thread extended MAC for hostname.
I: 450 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 459 [DIS]Failed to advertise commissionable node: 3
E: 464 [DIS]Failed to finalize service update: 1c
I: 469 [DIS]Delaying proxy of operational discovery: missing delegate
I: 475 [IN]CASE Server enabling CASE session setups
D: 480 [IN]SecureSession[0x200044f8]: Allocated Type:2 LSID:3921
D: 486 [SC]Allocated SecureSession (0x200044f8) - waiting for Sigma1 msg
I: 492 [SVR]Joining Multicast groups
D: 495 [ZCL]Emitting StartUp event
D: 499 [EVL]LogEvent event number: 0x00000000000B0001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000000001F2
I: 512 [SVR]Server Listening...
I: 515 [DL]Device Configuration:
I: 519 [DL]  Serial Number: 11223344556677889900
I: 523 [DL]  Vendor Id: 65521 (0xFFF1)
I: 526 [DL]  Product Id: 32773 (0x8005)
I: 530 [DL]  Hardware Version: 0
I: 534 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 539 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 546 [DL]  Manufacturing Date: (not set)
I: 550 [DL]  Device Type: 65535 (0xFFFF)
I: 555 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 559 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 565 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 574 [SVR]Manual pairing code: [34970112332]
I: 579 [DL]CHIP task running
I: 586 [DL]CHIPoBLE advertising started
D: 590 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 9cf20249
I: 596 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 602 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 74ff3546
I: 608 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 614 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 622 [DL]NFC Tag emulation started
I: 30590 [DL]CHIPoBLE advertising mode changed to slow
I: BLE advertising is already enabled
I: 58026 [DL]BLE connection established (ConnId: 0x00)
I: 58031 [DL]Current number of connections: 1/1
I: 58035 [DL]CHIPoBLE advertising stopped
I: 58039 [DL]NFC Tag emulation stopped
D: 58899 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 58906 [BLE]local and remote recv window sizes = 5
I: 58911 [BLE]selected BTP version 4
I: 58915 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 58920 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 58925 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 58932 [IN]BLE EndPoint 0x200127e0 Connection Complete
I: 58937 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 59076 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 59125 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 59132 [EM]>>> [E:50320r M:135532235] (U) Msg RX from 0:6C981F11760AF692 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 59144 [EM]Handling via exchange: 50320r, Delegate: 0x20006624
D: 59150 [SC]Received PBKDF param request
D: 59153 [SC]Peer assigned session ID 8013
D: 59157 [SC]Found MRP parameters in the message
D: 59162 [SC]Including MRP parameters in PBKDF param response
I: 59168 [EM]<<< [E:50320r M:215290337] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 59180 [IN](U) Sending msg 215290337 to IP address 'BLE'
D: 59185 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 59192 [SC]Sent PBKDF param response
D: 59271 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 59278 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 59368 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 59376 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 59384 [EM]>>> [E:50320r M:135532236] (U) Msg RX from 0:6C981F11760AF692 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 59395 [EM]Found matching exchange: 50320r, Delegate: 0x20006624
D: 59401 [SC]Received spake2p msg1
I: 60867 [EM]<<< [E:50320r M:215290338] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 60878 [IN](U) Sending msg 215290338 to IP address 'BLE'
D: 60883 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 60891 [SC]Sent spake2p msg2
E: 60894 [DL]Long dispatch time: 1518 ms, for event type 16388
D: 60977 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 60984 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 61074 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61082 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61090 [EM]>>> [E:50320r M:135532237] (U) Msg RX from 0:6C981F11760AF692 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 61101 [EM]Found matching exchange: 50320r, Delegate: 0x20006624
D: 61107 [SC]Received spake2p msg3
D: 61110 [SC]Sending status report. Protocol code 0, exchange 50320
I: 61117 [EM]<<< [E:50320r M:215290339] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 61128 [IN](U) Sending msg 215290339 to IP address 'BLE'
D: 61133 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 61141 [SC]SecureSession[0x20004440]: Moving from state 'kEstablishing' --> 'kActive'
D: 61149 [IN]SecureSession[0x20004440]: Activated - Type:1 LSID:3920
D: 61155 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:3920 PSID:8013!
I: 61164 [SVR]Commissioning completed session establishment step
I: 61170 [DIS]Updating services using commissioning mode 0
D: 61175 [DL]Using Thread extended MAC for hostname.
D: 61181 [DL]Using Thread extended MAC for hostname.
I: 61186 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 61195 [DIS]Failed to advertise extended commissionable node: 3
D: 61201 [DIS]Scheduling extended discovery timeout in 900s
E: 61206 [DIS]Failed to finalize service update: 1c
D: 61211 [DL]CHIPoBLE advertising set to off
I: 61215 [SVR]Device completed Rendezvous process
E: 61219 [DL]Long dispatch time: 137 ms, for event type 16388
D: 61226 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61233 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61241 [EM]>>> [E:50321r M:236387520] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 61251 [EM]Handling via exchange: 50321r, Delegate: 0x200101ac
D: 61257 [IM]Received Read request
D: 61261 [DMG]IM RH moving to [GeneratingReports]
D: 61265 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 61274 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 61279 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 61288 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 61294 [EM]<<< [E:50321r M:133502508] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 61304 [IN](S) Sending msg 133502508 on secure session with LSID: 3920
D: 61310 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 61318 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 61323 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 61330 [DMG]IM RH moving to [AwaitingDestruction]
D: 61335 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 61416 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61424 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61432 [EM]>>> [E:50322r M:236387521] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 61442 [EM]Handling via exchange: 50322r, Delegate: 0x200101ac
D: 61447 [IM]Received Read request
D: 61451 [DMG]IM RH moving to [GeneratingReports]
D: 61456 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 61464 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 61469 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 61478 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 61484 [EM]<<< [E:50322r M:133502509] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 61494 [IN](S) Sending msg 133502509 on secure session with LSID: 3920
D: 61501 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 61508 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 61513 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 61520 [DMG]IM RH moving to [AwaitingDestruction]
D: 61525 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 61562 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61570 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61578 [EM]>>> [E:50323r M:236387522] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 61588 [EM]Handling via exchange: 50323r, Delegate: 0x200101ac
D: 61594 [IM]Received Read request
D: 61598 [DMG]IM RH moving to [GeneratingReports]
D: 61602 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 61611 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty
D: 61616 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 61625 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 61631 [EM]<<< [E:50323r M:133502510] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 61641 [IN](S) Sending msg 133502510 on secure session with LSID: 3920
D: 61647 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 61655 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 61659 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 61667 [DMG]IM RH moving to [AwaitingDestruction]
D: 61671 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 61708 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61716 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61724 [EM]>>> [E:50324r M:236387523] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 61734 [EM]Handling via exchange: 50324r, Delegate: 0x200101ac
D: 61740 [IM]Received Read request
D: 61744 [DMG]IM RH moving to [GeneratingReports]
D: 61748 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 61757 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty
D: 61762 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 61771 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 61777 [EM]<<< [E:50324r M:133502511] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 61787 [IN](S) Sending msg 133502511 on secure session with LSID: 3920
D: 61793 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 61801 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 61806 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 61813 [DMG]IM RH moving to [AwaitingDestruction]
D: 61818 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 61854 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 61862 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 61870 [EM]>>> [E:50325r M:236387524] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 61881 [EM]Handling via exchange: 50325r, Delegate: 0x200101ac
D: 61886 [IM]Received Read request
D: 61890 [DMG]IM RH moving to [GeneratingReports]
D: 61895 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 61903 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 61908 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 61917 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 61923 [EM]<<< [E:50325r M:133502512] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 61933 [IN](S) Sending msg 133502512 on secure session with LSID: 3920
D: 61940 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 61947 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 61952 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 61959 [DMG]IM RH moving to [AwaitingDestruction]
D: 61964 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 62001 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62009 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 62017 [EM]>>> [E:50326r M:236387525] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 62027 [EM]Handling via exchange: 50326r, Delegate: 0x200101ac
D: 62032 [IM]Received Read request
D: 62036 [DMG]IM RH moving to [GeneratingReports]
D: 62041 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 62049 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 62054 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 62064 [DMG]<RE> Sending report (payload has 372 bytes)...
I: 62071 [EM]<<< [E:50326r M:133502513] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 62082 [IN](S) Sending msg 133502513 on secure session with LSID: 3920
D: 62088 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62096 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 62100 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 62108 [DMG]IM RH moving to [AwaitingDestruction]
D: 62112 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 62147 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62154 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62244 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62252 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 62342 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62349 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 29)
D: 62440 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 62448 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 62927 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 62935 [EM]>>> [E:50327r M:236387526] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 62945 [EM]Handling via exchange: 50327r, Delegate: 0x200101ac
D: 62951 [DMG]Got Timed Request with timeout 10000: handler 0x200105a8 exchange 50327r
I: 62959 [EM]<<< [E:50327r M:133502514] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 62970 [IN](S) Sending msg 133502514 on secure session with LSID: 3920
D: 62976 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 62984 [DMG]Timed Request time limit 0x0000000000011D18: handler 0x200105a8 exchange 50327r
D: 63073 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63081 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63089 [EM]>>> [E:50327r M:236387527] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 63100 [EM]Found matching exchange: 50327r, Delegate: 0x200105a8
D: 63106 [DMG]Timed following action arrived at 0x000000000000F682: handler 0x200105a8 exchange 50327r
D: 63115 [DMG]Handing timed invoke to IM engine: handler 0x200105a8 exchange 50327r
D: 63123 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 63131 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
D: 63136 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b3226525
D: 63143 [DMG]Command handler moving to [ Preparing]
D: 63148 [DMG]Command handler moving to [AddingComm]
D: 63152 [DMG]Command handler moving to [AddedComma]
D: 63157 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 63164 [EM]<<< [E:50327r M:133502515] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 63176 [IN](S) Sending msg 133502515 on secure session with LSID: 3920
D: 63182 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 63190 [DMG]Command handler moving to [CommandSen]
D: 63194 [DMG]Command handler moving to [AwaitingDe]
E: 63199 [DL]Long dispatch time: 118 ms, for event type 16388
D: 63268 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63276 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63284 [EM]>>> [E:50328r M:236387528] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 63294 [EM]Handling via exchange: 50328r, Delegate: 0x200101ac
D: 63300 [IM]Received Read request
D: 63304 [DMG]IM RH moving to [GeneratingReports]
D: 63308 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 63317 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 63322 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 63331 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 63337 [EM]<<< [E:50328r M:133502516] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 63347 [IN](S) Sending msg 133502516 on secure session with LSID: 3920
D: 63353 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 63361 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 63366 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 63373 [DMG]IM RH moving to [AwaitingDestruction]
D: 63378 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 63415 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63422 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63430 [EM]>>> [E:50329r M:236387529] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 63441 [EM]Handling via exchange: 50329r, Delegate: 0x200101ac
D: 63446 [DMG]Got Timed Request with timeout 10000: handler 0x200105a8 exchange 50329r
I: 63455 [EM]<<< [E:50329r M:133502517] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 63465 [IN](S) Sending msg 133502517 on secure session with LSID: 3920
D: 63472 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 63479 [DMG]Timed Request time limit 0x0000000000011F07: handler 0x200105a8 exchange 50329r
D: 63564 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63572 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63580 [EM]>>> [E:50329r M:236387530] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 63591 [EM]Found matching exchange: 50329r, Delegate: 0x200105a8
D: 63598 [DMG]Timed following action arrived at 0x000000000000F86D: handler 0x200105a8 exchange 50329r
D: 63607 [DMG]Handing timed invoke to IM engine: handler 0x200105a8 exchange 50329r
D: 63614 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 63624 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b3226526
D: 63630 [DMG]Command handler moving to [ Preparing]
D: 63635 [DMG]Command handler moving to [AddingComm]
D: 63640 [DMG]Command handler moving to [AddedComma]
D: 63645 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 63652 [EM]<<< [E:50329r M:133502518] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 63663 [IN](S) Sending msg 133502518 on secure session with LSID: 3920
D: 63669 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 63677 [DMG]Command handler moving to [CommandSen]
D: 63682 [DMG]Command handler moving to [AwaitingDe]
E: 63686 [DL]Long dispatch time: 114 ms, for event type 16388
D: 63744 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63752 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63760 [EM]>>> [E:50330r M:236387531] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 63771 [EM]Handling via exchange: 50330r, Delegate: 0x200101ac
D: 63778 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 63785 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 63791 [DMG]Command handler moving to [ Preparing]
D: 63796 [DMG]Command handler moving to [AddingComm]
D: 63801 [DMG]Command handler moving to [AddedComma]
D: 63805 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 63815 [EM]<<< [E:50330r M:133502519] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 63826 [IN](S) Sending msg 133502519 on secure session with LSID: 3920
D: 63832 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 63840 [DMG]Command handler moving to [CommandSen]
D: 63845 [DMG]Command handler moving to [AwaitingDe]
D: 63924 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63932 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64014 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64022 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64104 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64112 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64195 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64203 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64210 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 64284 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64330 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 64338 [EM]>>> [E:50331r M:236387532] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 64349 [EM]Handling via exchange: 50331r, Delegate: 0x200101ac
D: 64355 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 64363 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 64368 [DMG]Command handler moving to [ Preparing]
D: 64373 [DMG]Command handler moving to [AddingComm]
D: 64378 [DMG]Command handler moving to [AddedComma]
D: 64383 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 64392 [EM]<<< [E:50331r M:133502520] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 64403 [IN](S) Sending msg 133502520 on secure session with LSID: 3920
D: 64410 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64417 [DMG]Command handler moving to [CommandSen]
D: 64422 [DMG]Command handler moving to [AwaitingDe]
D: 64464 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64472 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64554 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64562 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64644 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64652 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64735 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64743 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 64750 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28)
D: 64824 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64832 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 64841 [EM]>>> [E:50332r M:236387533] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 64852 [EM]Handling via exchange: 50332r, Delegate: 0x200101ac
D: 64858 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 64865 [ZCL]OpCreds: Received an AttestationRequest command
I: 64900 [ZCL]OpCreds: AttestationRequest successful.
D: 64905 [DMG]Command handler moving to [ Preparing]
D: 64910 [DMG]Command handler moving to [AddingComm]
D: 64915 [DMG]Command handler moving to [AddedComma]
D: 64920 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 64930 [EM]<<< [E:50332r M:133502521] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 64941 [IN](S) Sending msg 133502521 on secure session with LSID: 3920
D: 64948 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 64955 [DMG]Command handler moving to [CommandSen]
D: 64960 [DMG]Command handler moving to [AwaitingDe]
E: 64965 [DL]Long dispatch time: 133 ms, for event type 16388
D: 65004 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65012 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65139 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65147 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65229 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65237 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65320 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65328 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 65335 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65409 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65417 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 91)
D: 65499 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65507 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 65516 [EM]>>> [E:50333r M:236387534] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 65527 [EM]Handling via exchange: 50333r, Delegate: 0x200101ac
D: 65533 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 65540 [ZCL]OpCreds: Received a CSRRequest command
D: 65545 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 65703 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 65738 [ZCL]OpCreds: CSRRequest successful.
D: 65742 [DMG]Command handler moving to [ Preparing]
D: 65747 [DMG]Command handler moving to [AddingComm]
D: 65751 [DMG]Command handler moving to [AddedComma]
D: 65756 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 65765 [EM]<<< [E:50333r M:133502522] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 65776 [IN](S) Sending msg 133502522 on secure session with LSID: 3920
D: 65782 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65790 [DMG]Command handler moving to [CommandSen]
D: 65795 [DMG]Command handler moving to [AwaitingDe]
E: 65799 [DL]Long dispatch time: 292 ms, for event type 16388
D: 65859 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65867 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 65949 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65957 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 66039 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66047 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 66130 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66138 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67165 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67255 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67345 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67352 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
I: 67362 [EM]>>> [E:50334r M:236387535] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 67373 [EM]Handling via exchange: 50334r, Delegate: 0x200101ac
D: 67379 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 67387 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 67449 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 67454 [DMG]Command handler moving to [ Preparing]
D: 67459 [DMG]Command handler moving to [AddingComm]
D: 67464 [DMG]Command handler moving to [AddedComma]
D: 67469 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 67476 [EM]<<< [E:50334r M:133502523] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 67487 [IN](S) Sending msg 133502523 on secure session with LSID: 3920
D: 67493 [DMG]Command handler moving to [CommandSen]
D: 67498 [DMG]Command handler moving to [AwaitingDe]
E: 67503 [DL]Long dispatch time: 157 ms, for event type 16388
D: 67508 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67516 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 67)
D: 67614 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67622 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67705 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67840 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67930 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 67937 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 68019 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 68027 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 68200 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 68211 [EM]>>> [E:50335r M:236387536] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 68222 [EM]Handling via exchange: 50335r, Delegate: 0x200101ac
D: 68228 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 68236 [ZCL]OpCreds: Received an AddNOC command
I: 68243 [FP]Validating NOC chain
I: 68357 [FP]NOC chain validation successful
I: 68361 [FP]Added new fabric at index: 0x1
I: 68365 [FP]Assigned compressed fabric ID: 0x92E031A4919A5BB7, node ID: 0x00000000976BBA25
I: 68373 [TS]Last Known Good Time: 2022-11-04T17:19:10
I: 68378 [TS]New proposed Last Known Good Time: 2022-11-05T01:44:49
I: 68384 [TS]Updating pending Last Known Good Time to 2022-11-05T01:44:49
D: 68391 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bec
D: 68397 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bed
D: 68412 [EVL]LogEvent event number: 0x00000000000B0002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000010B3B
I: 68426 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
D: 68435 [DL]Using Thread extended MAC for hostname.
I: 68439 [DIS]Advertise operational node 92E031A4919A5BB7-00000000976BBA25
D: 68446 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bee
D: 68453 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bef
D: 68459 [DMG]Command handler moving to [ Preparing]
D: 68464 [DMG]Command handler moving to [AddingComm]
D: 68468 [DMG]Command handler moving to [AddedComma]
I: 68473 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 68480 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 68487 [EM]<<< [E:50335r M:133502524] (S) Msg TX to 1:FFFFFFFB00000000 [5BB7] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 68498 [IN](S) Sending msg 133502524 on secure session with LSID: 3920
D: 68504 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 68512 [DMG]Command handler moving to [CommandSen]
D: 68516 [DMG]Command handler moving to [AwaitingDe]
E: 68521 [DL]Long dispatch time: 321 ms, for event type 16388
D: 68559 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 71079 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 73586 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 73644 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 76164 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 78672 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 78819 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 81249 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 83757 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 83814 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 86784 [DL]BLE GAP connection terminated (reason 0x13)
D: 86790 [IN]Clearing BLE pending packets.
I: 86794 [DL]Current number of connections: 0/1
I: 183136 [FS]Fail-safe timer expired
E: 183140 [SVR]Failsafe timer expired
D: 183143 [IN]SecureSession[0x20004440]: MarkForEviction Type:1 LSID:3920
I: 183150 [SC]SecureSession[0x20004440]: Moving from state 'kActive' --> 'kPendingEviction'
D: 183158 [IN]SecureSession[0x20004440]: Released - Type:1 LSID:3920
E: 183164 [SVR]Commissioning failed (attempt 1): 32
D: 183170 [IN]SecureSession[0x20004440]: Allocated Type:1 LSID:3922
D: 183176 [SC]Assigned local session key ID 3922
D: 183181 [SC]Waiting for PBKDF param request
D: 183185 [DL]CHIPoBLE advertising set to on
I: 183189 [DIS]Updating services using commissioning mode 1
D: 183194 [DL]Using Thread extended MAC for hostname.
D: 183199 [DL]Using Thread extended MAC for hostname.
I: 183204 [DIS]Advertise operational node 92E031A4919A5BB7-00000000976BBA25
E: 183211 [DIS]Failed to advertise operational node: 3
D: 183216 [DL]Using Thread extended MAC for hostname.
I: 183221 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 183230 [DIS]Failed to advertise commissionable node: 3
E: 183235 [DIS]Failed to finalize service update: 1c
E: 183240 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 183245 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 183251 [IN]Expiring all sessions for fabric 0x1!!
E: 183256 [FP]Reverting pending fabric data for fabric 0x1
D: 183261 [EVL]LogEvent event number: 0x00000000000B0003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000002CBDD
D: 183275 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 183282 [FP]Warning: metadata not found during delete of fabric 0x1
I: 183292 [FP]Fabric (0x1) deleted.
I: 183295 [ZCL]OpCreds: Fabric index 0x1 was removed
D: 183300 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bf0
D: 183307 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 7f479bf1
I: 183323 [TS]Pending Last Known Good Time: 2022-11-05T01:44:49
I: 183329 [TS]Previous Last Known Good Time: 2022-11-04T17:19:10
I: 183335 [TS]Reverted Last Known Good Time to previous value
D: 183341 [EVL]LogEvent event number: 0x00000000000B0004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000002CC2D
D: 183355 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
E: 183361 [FP]Warning: metadata not found during delete of fabric 0x1
E: 183369 [ZCL]OpCreds: failed to delete fabric at index 1: d8
D: 183374 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to b3226527
D: 183381 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 183389 [DL]Long dispatch time: 249 ms, for event type 32782
I: 183394 [FS]Fail-safe cleanly disarmed
I: 183402 [DL]CHIPoBLE advertising started
I: 183406 [DL]NFC Tag emulation started
I: 213405 [DL]CHIPoBLE advertising mode changed to slow

Parents
  • Hi Dan,

    At this time point, Google doesn't publicly support Matter yet, so it is not possible to test it without accessing the special beta firmware called Google Early Access Program. Here is the instruction how to test Nordic examples with Google ecosystem: https://developers.home.google.com/matter/vendors/nordic-semiconductor. Do you have followed this document?

    Best regards,

    Charlie

  • Hi Charlie - I did read through it, but it seemed like it was written a while ago since it initially installs NRF v1.7.1

    west init -m github.com/.../sdk-nrf --mr v1.7.1

    (and then later updates to the most recent version).

    The essence of it seems to be applying google's patch in step 9 to the matter/connectedhomeip repo, which I did. What wasn't clear to me, is what is the cleanest way to get NRF Connect to build with the google-patched version of matter/connectedhomeip vs the one that NRF includes in its own repo?

    Thanks, Dan.

  • Hi Dan,

    Google's public guidance was released in July - it is pretty out-of-date. It still uses old test event branch of Matter upstream repo, which only works with very old NCS v1.7.1. If you don't have access to goolge nest's developer preview software and want to test your Nest Hub 2nd gen with current production software, follow the guide to patch your cloned connectedhomeip and build the examples such as examples/lighting-app/nrfconnect. The FW should work.

    The NCS 2.1.1 already supports Matter v1.0, IMHO there is no point to follow this guide. Supposedly this guide should be updated soon. There are also quite some alternatives that publicly support Matter - for example Apple HomePod mini/Samsung SmartThings hub v3. These devices works quite well with NCS v2.1.1.

    Best Regards,

    Larry

Reply
  • Hi Dan,

    Google's public guidance was released in July - it is pretty out-of-date. It still uses old test event branch of Matter upstream repo, which only works with very old NCS v1.7.1. If you don't have access to goolge nest's developer preview software and want to test your Nest Hub 2nd gen with current production software, follow the guide to patch your cloned connectedhomeip and build the examples such as examples/lighting-app/nrfconnect. The FW should work.

    The NCS 2.1.1 already supports Matter v1.0, IMHO there is no point to follow this guide. Supposedly this guide should be updated soon. There are also quite some alternatives that publicly support Matter - for example Apple HomePod mini/Samsung SmartThings hub v3. These devices works quite well with NCS v2.1.1.

    Best Regards,

    Larry

Children
  • Larry - bless you! Just forced an update to iOS16.1.1 (despite having auto updates, my iPhone was still on a previous version) and was able to scan a QR code and successfully commission an NRF5340DK device using my Apple Home app and issue voice commands to turn it on and off. Thank you for taking the time to read and respond to my question - much appreciated!

  • Hi Dan,  have you been able to test this aswell with GHA?  After Goolgle announced support for Matter 1.0

    I'm able do perform full commissioning but  just after it I'm getting information that the device is offline and I cannot control it. My device is nRF5340 with SDK 2.1.2    OTBR Nest Hu2. All software upgraded to the latest announced by google soft releases.  Anybody was successful to commission and control devices with Google Home App?

  • Michal - just seeing this now - I was working on another project and wasn't checking here -  sorry for the delay in responding to you.

    I recently updated to NRF Connect SDK 2.2.0 and seem to have lost the ability to commission the light_bulb sample over Matter using the Apple Home app, and still cannot commission it using the Google Home App.

    If you or anyone else has been able to successfully commission an NRF DK with either google home or apple homepod, I would welcome hearing about it. Or if the Nordic team can try and provide us with suggestions/best practices for doing so, that would also be welcome. Thanks!

    Here is the log output from the NRF5340 DK:

    uart:~$ I: nRF5 802154 radio initialized
    I: 4 Sectors of 4096 bytes
    I: alloc wra: 1, f80
    I: data wra: 1, 48
    *** Booting Zephyr OS build v3.2.99-ncs1 ***
    I: Init CHIP stack
    I: 183 [DL]BLE address: F9:0E:36:CD:F5:F4
    I: 210 [DL]OpenThread started: OK
    I: 213 [DL]Setting OpenThread device type to ROUTER
    I: 218 [SVR]Server initializing...
    D: 221 [FP]Initializing FabricTable from persistent storage
    I: 228 [TS]Last Known Good Time: 2023-02-27T14:46:47
    I: 234 [DMG]AccessControl: initializing
    I: 237 [DMG]Examples::AccessControlDelegate::Init
    I: 242 [DMG]AccessControl: setting
    I: 245 [DMG]DefaultAclStorage: initializing
    I: 249 [DMG]DefaultAclStorage: 0 entries loaded
    D: 253 [IN]UDP::Init bind&listen port=5540
    E: 257 [IN]SO_REUSEPORT failed: 109
    D: 260 [IN]UDP::Init bound to port=5540
    D: 264 [IN]BLEBase::Init - setting/overriding transport
    D: 269 [IN]TransportMgr initialized
    D: 276 [DL]Using Thread extended MAC for hostname.
    I: 283 [ZCL]Using ZAP configuration...
    D: 288 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
    D: 297 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
    D: 305 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
    I: 312 [DMG]AccessControlCluster: initializing
    D: 316 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98803
    D: 323 [DL]Boot reason: 1
    D: 325 [ZCL]GeneralDiagnostics: OnDeviceReboot
    D: 329 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to aa5052f3
    D: 336 [EVL]LogEvent event number: 0x0000000000080000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000014F
    I: 349 [ZCL]Initiating Admin Commissioning cluster.
    D: 354 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to c0de0572
    D: 361 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 42512c54
    D: 367 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 42512c55
    I: 373 [ZCL]On/Off set value: 1 0
    I: 376 [ZCL]On/off already set to new value
    D: 381 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 24109943
    I: 388 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
    D: 394 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
    D: 405 [IN]SecureSession[0x20004450]: Allocated Type:1 LSID:24566
    D: 411 [SC]Assigned local session key ID 24566
    D: 415 [SC]Waiting for PBKDF param request
    D: 418 [DL]CHIPoBLE advertising set to on
    I: 422 [DIS]Updating services using commissioning mode 1
    D: 427 [DL]Using Thread extended MAC for hostname.
    D: 432 [DL]Using Thread extended MAC for hostname.
    I: 438 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
    E: 447 [DIS]Failed to advertise commissionable node: 3
    E: 452 [DIS]Failed to finalize service update: 1c
    I: 456 [DIS]Updating services using commissioning mode 1
    D: 461 [DL]Using Thread extended MAC for hostname.
    D: 466 [DL]Using Thread extended MAC for hostname.
    I: 472 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
    E: 481 [DIS]Failed to advertise commissionable node: 3
    E: 485 [DIS]Failed to finalize service update: 1c
    I: 490 [DIS]Delaying proxy of operational discovery: missing delegate
    I: 496 [IN]CASE Server enabling CASE session setups
    D: 501 [IN]SecureSession[0x20004508]: Allocated Type:2 LSID:24567
    D: 507 [SC]Allocated SecureSession (0x20004508) - waiting for Sigma1 msg
    I: 513 [SVR]Joining Multicast groups
    D: 517 [ZCL]Emitting StartUp event
    D: 520 [EVL]LogEvent event number: 0x0000000000080001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000208
    I: 534 [SVR]Server Listening...
    I: 537 [DL]Device Configuration:
    I: 540 [DL]  Serial Number: 11223344556677889900
    I: 545 [DL]  Vendor Id: 65521 (0xFFF1)
    I: 548 [DL]  Product Id: 32773 (0x8005)
    I: 553 [DL]  Hardware Version: 0
    I: 556 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
    I: 563 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
    I: 570 [DL]  Manufacturing Date: (not set)
    I: 574 [DL]  Device Type: 65535 (0xFFFF)
    I: 579 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
    I: 584 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    I: 590 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
    I: 599 [SVR]Manual pairing code: [34970112332]
    I: 604 [DL]CHIP task running
    I: 611 [DL]CHIPoBLE advertising started
    D: 616 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to 846353d1
    I: 622 [ZCL]Cluster OnOff: attribute OnOff set to 0
    D: 627 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to 24109944
    I: 633 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
    D: 639 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
    I: 648 [DL]NFC Tag emulation started
    I: 19629 [DL]BLE connection established (ConnId: 0x00)
    I: 19634 [DL]Current number of connections: 1/2
    I: 19638 [DL]CHIPoBLE advertising stopped
    I: 19642 [DL]NFC Tag emulation stopped
    W: Ignoring data for unknown channel ID 0x003a
    D: 21014 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 21021 [BLE]local and remote recv window sizes = 5
    I: 21026 [BLE]selected BTP version 4
    I: 21029 [BLE]using BTP fragment sizes rx 244 / tx 244.
    D: 21134 [DL]ConnId: 0x00, New CCCD value: 0x0002
    D: 21138 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
    D: 21146 [IN]BLE EndPoint 0x20012d78 Connection Complete
    I: 21151 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
    D: 21223 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 21232 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 21239 [EM]>>> [E:7160r M:195566401] (U) Msg RX from 0:F697D9E8F3BB4A39 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
    D: 21251 [EM]Handling via exchange: 7160r, Delegate: 0x20006634
    D: 21256 [SC]Received PBKDF param request
    D: 21260 [SC]Peer assigned session ID 10114
    D: 21264 [SC]Found MRP parameters in the message
    D: 21269 [SC]Including MRP parameters in PBKDF param response
    I: 21275 [EM]<<< [E:7160r M:64742957] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
    I: 21287 [IN](U) Sending msg 64742957 to IP address 'BLE'
    D: 21292 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
    D: 21299 [SC]Sent PBKDF param response
    D: 21343 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 21374 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 21381 [EM]>>> [E:7160r M:195566402] (U) Msg RX from 0:F697D9E8F3BB4A39 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
    D: 21392 [EM]Found matching exchange: 7160r, Delegate: 0x20006634
    D: 21398 [SC]Received spake2p msg1
    I: 22866 [EM]<<< [E:7160r M:64742958] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
    I: 22877 [IN](U) Sending msg 64742958 to IP address 'BLE'
    D: 22882 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
    D: 22890 [SC]Sent spake2p msg2
    E: 22893 [DL]Long dispatch time: 1519 ms, for event type 16388
    D: 22933 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 22994 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 23001 [EM]>>> [E:7160r M:195566403] (U) Msg RX from 0:F697D9E8F3BB4A39 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
    D: 23012 [EM]Found matching exchange: 7160r, Delegate: 0x20006634
    D: 23018 [SC]Received spake2p msg3
    D: 23021 [SC]Sending status report. Protocol code 0, exchange 7160
    I: 23028 [EM]<<< [E:7160r M:64742959] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
    I: 23039 [IN](U) Sending msg 64742959 to IP address 'BLE'
    D: 23044 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
    I: 23052 [SC]SecureSession[0x20004450]: Moving from state 'kEstablishing' --> 'kActive'
    D: 23060 [IN]SecureSession[0x20004450]: Activated - Type:1 LSID:24566
    D: 23067 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:24566 PSID:10114!
    I: 23075 [SVR]Commissioning completed session establishment step
    I: 23081 [DIS]Updating services using commissioning mode 0
    D: 23087 [DL]Using Thread extended MAC for hostname.
    D: 23093 [DL]Using Thread extended MAC for hostname.
    I: 23098 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
    E: 23107 [DIS]Failed to advertise extended commissionable node: 3
    D: 23113 [DIS]Scheduling extended discovery timeout in 900s
    E: 23119 [DIS]Failed to finalize service update: 1c
    D: 23123 [DL]CHIPoBLE advertising set to off
    I: 23127 [SVR]Device completed Rendezvous process
    E: 23132 [DL]Long dispatch time: 138 ms, for event type 16388
    D: 23137 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 23145 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 23153 [EM]>>> [E:7161r M:104542089] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 23163 [EM]Handling via exchange: 7161r, Delegate: 0x20010744
    D: 23169 [IM]Received Read request
    D: 23172 [DMG]IM RH moving to [GeneratingReports]
    D: 23177 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
    D: 23186 [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
    D: 23191 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
    D: 23200 [DMG]<RE> Sending report (payload has 64 bytes)...
    I: 23206 [EM]<<< [E:7161r M:58016507] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 23216 [IN](S) Sending msg 58016507 on secure session with LSID: 24566
    D: 23222 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 99)
    D: 23230 [DMG]<RE> OnReportConfirm: NumReports = 0
    D: 23234 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
    D: 23242 [DMG]IM RH moving to [AwaitingDestruction]
    D: 23246 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    D: 23263 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 23272 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 23280 [EM]>>> [E:7162r M:104542090] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 23290 [EM]Handling via exchange: 7162r, Delegate: 0x20010744
    D: 23295 [IM]Received Read request
    D: 23299 [DMG]IM RH moving to [GeneratingReports]
    D: 23304 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
    D: 23312 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
    D: 23317 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
    D: 23327 [DMG]<RE> Sending report (payload has 400 bytes)...
    I: 23335 [EM]<<< [E:7162r M:58016508] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 23345 [IN](S) Sending msg 58016508 on secure session with LSID: 24566
    D: 23351 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 23359 [DMG]<RE> OnReportConfirm: NumReports = 0
    D: 23363 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
    D: 23371 [DMG]IM RH moving to [AwaitingDestruction]
    D: 23375 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    D: 23413 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 23421 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 193)
    D: 23473 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 23482 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 23489 [EM]>>> [E:7163r M:104542091] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 23500 [EM]Handling via exchange: 7163r, Delegate: 0x20010744
    D: 23505 [IM]Received Read request
    D: 23509 [DMG]IM RH moving to [GeneratingReports]
    D: 23514 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
    D: 23522 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
    D: 23527 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
    D: 23536 [DMG]<RE> Sending report (payload has 37 bytes)...
    I: 23542 [EM]<<< [E:7163r M:58016509] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 23552 [IN](S) Sending msg 58016509 on secure session with LSID: 24566
    D: 23559 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
    D: 23567 [DMG]<RE> OnReportConfirm: NumReports = 0
    D: 23571 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
    D: 23578 [DMG]IM RH moving to [AwaitingDestruction]
    D: 23583 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    D: 23623 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 26137 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 28645 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 28717 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 28964 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 28973 [EM]>>> [E:7164r M:104542092] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
    D: 28983 [EM]Handling via exchange: 7164r, Delegate: 0x20010744
    D: 28988 [IM]Received Read request
    D: 28994 [DMG]IM RH moving to [GeneratingReports]
    D: 28998 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
    D: 29007 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
    D: 29012 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
    D: 29021 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
    D: 29026 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
    D: 29035 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
    D: 29040 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
    D: 29049 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
    D: 29054 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
    D: 29063 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
    D: 29068 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
    D: 29077 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
    D: 29082 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
    D: 29091 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
    D: 29096 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
    D: 29105 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
    D: 29110 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
    D: 29119 [DMG]<RE> Sending report (payload has 228 bytes)...
    I: 29126 [EM]<<< [E:7164r M:58016510] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
    I: 29136 [IN](S) Sending msg 58016510 on secure session with LSID: 24566
    D: 29143 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 29150 [DMG]<RE> OnReportConfirm: NumReports = 0
    D: 29155 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
    D: 29162 [DMG]IM RH moving to [AwaitingDestruction]
    D: 29167 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    D: 29264 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 29271 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
    D: 29383 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 29392 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 29400 [EM]>>> [E:7165r M:104542093] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 29411 [EM]Handling via exchange: 7165r, Delegate: 0x20010744
    D: 29417 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
    I: 29424 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
    D: 29430 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98804
    D: 29436 [DMG]Command handler moving to [ Preparing]
    D: 29441 [DMG]Command handler moving to [AddingComm]
    D: 29446 [DMG]Command handler moving to [AddedComma]
    D: 29450 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 29458 [EM]<<< [E:7165r M:58016511] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 29468 [IN](S) Sending msg 58016511 on secure session with LSID: 24566
    D: 29475 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
    D: 29483 [DMG]Command handler moving to [CommandSen]
    D: 29487 [DMG]Command handler moving to [AwaitingDe]
    D: 29563 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 29572 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 29580 [EM]>>> [E:7166r M:104542094] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 29591 [EM]Handling via exchange: 7166r, Delegate: 0x20010744
    D: 29597 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
    D: 29606 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98805
    D: 29612 [DMG]Command handler moving to [ Preparing]
    D: 29617 [DMG]Command handler moving to [AddingComm]
    D: 29622 [DMG]Command handler moving to [AddedComma]
    D: 29627 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 29634 [EM]<<< [E:7166r M:58016512] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 29645 [IN](S) Sending msg 58016512 on secure session with LSID: 24566
    D: 29651 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
    D: 29659 [DMG]Command handler moving to [CommandSen]
    D: 29663 [DMG]Command handler moving to [AwaitingDe]
    D: 29743 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 29752 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 29760 [EM]>>> [E:7167r M:104542095] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 29771 [EM]Handling via exchange: 7167r, Delegate: 0x20010744
    D: 29777 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
    I: 29784 [ZCL]OpCreds: Certificate Chain request received for PAI
    D: 29790 [DMG]Command handler moving to [ Preparing]
    D: 29795 [DMG]Command handler moving to [AddingComm]
    D: 29800 [DMG]Command handler moving to [AddedComma]
    D: 29804 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 29814 [EM]<<< [E:7167r M:58016513] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 29825 [IN](S) Sending msg 58016513 on secure session with LSID: 24566
    D: 29831 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 29839 [DMG]Command handler moving to [CommandSen]
    D: 29843 [DMG]Command handler moving to [AwaitingDe]
    D: 29984 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 29991 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 30104 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30111 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
    D: 30223 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30232 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 30240 [EM]>>> [E:7168r M:104542096] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 30251 [EM]Handling via exchange: 7168r, Delegate: 0x20010744
    D: 30257 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
    I: 30264 [ZCL]OpCreds: Certificate Chain request received for DAC
    D: 30270 [DMG]Command handler moving to [ Preparing]
    D: 30275 [DMG]Command handler moving to [AddingComm]
    D: 30280 [DMG]Command handler moving to [AddedComma]
    D: 30284 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 30294 [EM]<<< [E:7168r M:58016514] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 30305 [IN](S) Sending msg 58016514 on secure session with LSID: 24566
    D: 30311 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 30319 [DMG]Command handler moving to [CommandSen]
    D: 30324 [DMG]Command handler moving to [AwaitingDe]
    D: 30403 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30411 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 30524 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30531 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
    D: 30643 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30652 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 30660 [EM]>>> [E:7169r M:104542097] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 30671 [EM]Handling via exchange: 7169r, Delegate: 0x20010744
    D: 30677 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
    I: 30684 [ZCL]OpCreds: Received an AttestationRequest command
    I: 30720 [ZCL]OpCreds: AttestationRequest successful.
    D: 30724 [DMG]Command handler moving to [ Preparing]
    D: 30729 [DMG]Command handler moving to [AddingComm]
    D: 30734 [DMG]Command handler moving to [AddedComma]
    D: 30739 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 30749 [EM]<<< [E:7169r M:58016515] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 30760 [IN](S) Sending msg 58016515 on secure session with LSID: 24566
    D: 30766 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 30774 [DMG]Command handler moving to [CommandSen]
    D: 30779 [DMG]Command handler moving to [AwaitingDe]
    E: 30784 [DL]Long dispatch time: 132 ms, for event type 16388
    D: 30884 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 30891 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 31004 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 31011 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235)
    D: 31123 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 31132 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 31140 [EM]>>> [E:7170r M:104542098] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 31151 [EM]Handling via exchange: 7170r, Delegate: 0x20010744
    D: 31157 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
    I: 31164 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
    D: 31170 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98806
    D: 31176 [DMG]Command handler moving to [ Preparing]
    D: 31181 [DMG]Command handler moving to [AddingComm]
    D: 31186 [DMG]Command handler moving to [AddedComma]
    D: 31191 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 31198 [EM]<<< [E:7170r M:58016516] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 31208 [IN](S) Sending msg 58016516 on secure session with LSID: 24566
    D: 31215 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
    D: 31223 [DMG]Command handler moving to [CommandSen]
    D: 31227 [DMG]Command handler moving to [AwaitingDe]
    D: 31304 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 33224 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 33232 [EM]>>> [E:7171r M:104542099] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 33243 [EM]Handling via exchange: 7171r, Delegate: 0x20010744
    D: 33249 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
    I: 33257 [ZCL]OpCreds: Received a CSRRequest command
    D: 33261 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
    I: 33418 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
    I: 33453 [ZCL]OpCreds: CSRRequest successful.
    D: 33457 [DMG]Command handler moving to [ Preparing]
    D: 33462 [DMG]Command handler moving to [AddingComm]
    D: 33467 [DMG]Command handler moving to [AddedComma]
    D: 33471 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 33480 [EM]<<< [E:7171r M:58016517] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 33491 [IN](S) Sending msg 58016517 on secure session with LSID: 24566
    D: 33497 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
    D: 33505 [DMG]Command handler moving to [CommandSen]
    D: 33510 [DMG]Command handler moving to [AwaitingDe]
    E: 33515 [DL]Long dispatch time: 290 ms, for event type 16388
    D: 33584 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 33591 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138)
    D: 33703 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 33712 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 33824 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 33833 [EM]>>> [E:7172r M:104542100] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 33844 [EM]Handling via exchange: 7172r, Delegate: 0x20010744
    D: 33851 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
    I: 33858 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
    I: 33920 [ZCL]OpCreds: AddTrustedRootCertificate successful.
    D: 33925 [DMG]Command handler moving to [ Preparing]
    D: 33930 [DMG]Command handler moving to [AddingComm]
    D: 33934 [DMG]Command handler moving to [AddedComma]
    D: 33939 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 33947 [EM]<<< [E:7172r M:58016518] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 33957 [IN](S) Sending msg 58016518 on secure session with LSID: 24566
    D: 33964 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
    D: 33971 [DMG]Command handler moving to [CommandSen]
    D: 33976 [DMG]Command handler moving to [AwaitingDe]
    E: 33981 [DL]Long dispatch time: 157 ms, for event type 16388
    D: 34063 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 34072 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 34184 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 34194 [EM]>>> [E:7173r M:104542101] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 34205 [EM]Handling via exchange: 7173r, Delegate: 0x20010744
    D: 34211 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
    I: 34218 [ZCL]OpCreds: Received an AddNOC command
    I: 34226 [FP]Validating NOC chain
    I: 34285 [FP]NOC chain validation successful
    I: 34289 [FP]Added new fabric at index: 0x1
    I: 34293 [FP]Assigned compressed fabric ID: 0x7FCB547C65239FBB, node ID: 0x000000009684B094
    I: 34301 [TS]Last Known Good Time: 2023-02-27T14:46:47
    I: 34307 [TS]New proposed Last Known Good Time: 2023-02-27T23:17:21
    I: 34313 [TS]Updating pending Last Known Good Time to 2023-02-27T23:17:21
    D: 34319 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c6c
    D: 34326 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c6d
    D: 34342 [EVL]LogEvent event number: 0x0000000000080002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000008626
    I: 34356 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x726F18663821C3E7
    D: 34365 [DL]Using Thread extended MAC for hostname.
    I: 34370 [DIS]Advertise operational node 7FCB547C65239FBB-000000009684B094
    D: 34377 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c6e
    D: 34383 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c6f
    D: 34390 [DMG]Command handler moving to [ Preparing]
    D: 34394 [DMG]Command handler moving to [AddingComm]
    D: 34399 [DMG]Command handler moving to [AddedComma]
    I: 34404 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
    D: 34410 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 34417 [EM]<<< [E:7173r M:58016519] (S) Msg TX to 1:FFFFFFFB00000000 [9FBB] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 34428 [IN](S) Sending msg 58016519 on secure session with LSID: 24566
    D: 34435 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
    D: 34442 [DMG]Command handler moving to [CommandSen]
    D: 34447 [DMG]Command handler moving to [AwaitingDe]
    E: 34452 [DL]Long dispatch time: 268 ms, for event type 16388
    D: 34543 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 34552 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 34560 [EM]>>> [E:7174r M:104542102] (S) Msg RX from 1:FFFFFFFB00000000 [9FBB] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 34571 [EM]Handling via exchange: 7174r, Delegate: 0x20010744
    D: 34577 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
    D: 34587 [DMG]Command handler moving to [ Preparing]
    D: 34591 [DMG]Command handler moving to [AddingComm]
    D: 34596 [DMG]Command handler moving to [AddedComma]
    D: 34601 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98807
    D: 34607 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 34615 [EM]<<< [E:7174r M:58016520] (S) Msg TX to 1:FFFFFFFB00000000 [9FBB] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 34625 [IN](S) Sending msg 58016520 on secure session with LSID: 24566
    D: 34632 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
    D: 34640 [DMG]Command handler moving to [CommandSen]
    D: 34644 [DMG]Command handler moving to [AwaitingDe]
    D: 34723 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 34732 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 34740 [EM]>>> [E:7175r M:104542103] (S) Msg RX from 1:FFFFFFFB00000000 [9FBB] --- Type 0001:08 (IM:InvokeCommandRequest)
    D: 34751 [EM]Handling via exchange: 7175r, Delegate: 0x20010744
    D: 34757 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
    D: 34782 [DMG]Decreasing reference count for CommandHandler, remaining 1
    D: 34789 [DL]OpenThread State Changed (Flags: 0x100fc100)
    D: 34794 [DL]   Network Name: MyHome24
    D: 34798 [DL]   PAN Id: 0x61E2
    D: 34801 [DL]   Extended PAN Id: 0x7B8B834C15EF43F5
    D: 34806 [DL]   Channel: 25
    D: 34808 [DL]   Mesh Prefix: fdde:ad00:beef::/64
    D: 34815 [DL]OpenThread State Changed (Flags: 0x0100103d)
    D: 34820 [DL]   Device Role: DETACHED
    D: 34823 [DL]   Thread Unicast Addresses:
    D: 34827 [DL]        fdde:ad00:beef::ff:fe00:6c00/64 valid rloc
    D: 34833 [DL]        fdde:ad00:beef:0:b324:7958:7eb7:99df/64 valid
    D: 34839 [DL]        fe80::58e4:fc23:6593:5fe9/64 valid preferred
    D: 36735 [DL]OpenThread State Changed (Flags: 0x10000040)
    D: 37026 [DL]OpenThread State Changed (Flags: 0x00000100)
    D: 37239 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 37364 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    I: 39724 [DL]SRP Client was started, detected server: fd86:d57c:7973:0000:761d:d0d6:97a3:e2bc
    D: 39733 [DL]OpenThread State Changed (Flags: 0x301032b7)
    D: 39738 [DL]   Device Role: CHILD
    D: 39741 [DL]   Partition Id: 0x46B397F6
    D: 39745 [DL]   Thread Unicast Addresses:
    D: 39749 [DL]        fd86:d57c:7973:0:c333:268b:d0c:93f1/64 valid preferred
    D: 39756 [DL]        fd7b:8b83:4c15::ff:fe00:3403/64 valid rloc
    D: 39761 [DL]        fd7b:8b83:4c15:0:b324:7958:7eb7:99df/64 valid
    D: 39767 [DL]        fe80::58e4:fc23:6593:5fe9/64 valid preferred
    D: 39775 [DL]OpenThread State Changed (Flags: 0x00000001)
    D: 39780 [DL]   Thread Unicast Addresses:
    D: 39784 [DL]        fd86:d57c:7973:0:c333:268b:d0c:93f1/64 valid preferred
    D: 39791 [DL]        fd7b:8b83:4c15::ff:fe00:3403/64 valid rloc
    D: 39796 [DL]        fd7b:8b83:4c15:0:b324:7958:7eb7:99df/64 valid
    D: 39802 [DL]        fe80::58e4:fc23:6593:5fe9/64 valid preferred
    D: 39810 [DMG]Command handler moving to [ Preparing]
    D: 39815 [DMG]Command handler moving to [AddingComm]
    D: 39820 [DMG]Command handler moving to [AddedComma]
    D: 39825 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98808
    D: 39831 [DMG]Decreasing reference count for CommandHandler, remaining 0
    I: 39839 [EM]<<< [E:7175r M:58016521] (S) Msg TX to 1:FFFFFFFB00000000 [9FBB] --- Type 0001:09 (IM:InvokeCommandResponse)
    I: 39849 [IN](S) Sending msg 58016521 on secure session with LSID: 24566
    D: 39856 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 69)
    D: 39863 [DMG]Command handler moving to [CommandSen]
    D: 39868 [DMG]Command handler moving to [AwaitingDe]
    D: 39873 [DL]Using Thread extended MAC for hostname.
    I: 39877 [DIS]Advertise operational node 7FCB547C65239FBB-000000009684B094
    I: 39884 [SVR]Operational advertising enabled
    D: 39888 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 39944 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 40319 [DL]SRP update succeeded
    I: 40322 [DIS]Setting operational delegate post init
    I: 40332 [SWU]Stopping the watchdog timer
    I: 40335 [SWU]Starting the periodic query timer, timeout: 86400 seconds
    I: 40342 [DIS]Updating services using commissioning mode 0
    D: 40347 [DL]Using Thread extended MAC for hostname.
    I: 40352 [DIS]Advertise operational node 7FCB547C65239FBB-000000009684B094
    I: 40359 [DL]advertising srp service: 7FCB547C65239FBB-000000009684B094._matter._tcp
    D: 40366 [DL]Using Thread extended MAC for hostname.
    I: 40372 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
    I: 40381 [DL]advertising srp service: 04405505B195D759._matterc._udp
    D: 40388 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 6861a9b7
    D: 40394 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 6861a9b8
    E: 41073 [DL]SRP update error: internal server error
    D: 42396 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 42404 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 42524 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    E: 42891 [DL]SRP update error: internal server error
    D: 44911 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 44984 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 44992 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    E: 45999 [DL]SRP update error: internal server error
    D: 47500 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 47624 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 50084 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    E: 51229 [DL]SRP update error: internal server error
    D: 52591 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 52664 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 55124 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 57631 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 57704 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    E: 60119 [DL]SRP update error: internal server error
    D: 60224 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 62731 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 62804 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 65264 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 67771 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 67844 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 70304 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 72811 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 72884 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    E: 75194 [DL]SRP update error: internal server error
    D: 75344 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 77851 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 77924 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 80444 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 82951 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 83024 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 85484 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    D: 87991 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
    D: 88064 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
    D: 90524 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
    I: 91170 [FS]Fail-safe timer expired
    E: 91174 [SVR]Failsafe timer expired
    D: 91177 [IN]SecureSession[0x20004450]: MarkForEviction Type:1 LSID:24566
    I: 91184 [SC]SecureSession[0x20004450]: Moving from state 'kActive' --> 'kPendingEviction'
    D: 91192 [IN]SecureSession[0x20004450]: Released - Type:1 LSID:24566
    E: 91198 [SVR]Commissioning failed (attempt 1): 32
    D: 91202 [IN]Clearing BLE pending packets.
    I: 91206 [BLE]Releasing end point's BLE connection back to application.
    I: 91212 [DL]Closing BLE GATT connection (ConnId 00)
    D: 91221 [IN]SecureSession[0x20004450]: Allocated Type:1 LSID:24568
    D: 91227 [SC]Assigned local session key ID 24568
    D: 91231 [SC]Waiting for PBKDF param request
    D: 91235 [DL]CHIPoBLE advertising set to on
    I: 91239 [DIS]Updating services using commissioning mode 1
    D: 91244 [DL]Using Thread extended MAC for hostname.
    I: 91249 [DIS]Advertise operational node 7FCB547C65239FBB-000000009684B094
    D: 91256 [DL]Using Thread extended MAC for hostname.
    I: 91262 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
    I: 91271 [DL]advertising srp service: 04405505B195D759._matterc._udp
    E: 91278 [ZCL]OpCreds: Got FailSafeTimerExpired
    E: 91282 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
    D: 91288 [IN]Expiring all sessions for fabric 0x1!!
    E: 91293 [FP]Reverting pending fabric data for fabric 0x1
    D: 91298 [EVL]LogEvent event number: 0x0000000000080003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x00000000000164A2
    D: 91313 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    E: 91319 [FP]Warning: metadata not found during delete of fabric 0x1
    I: 91332 [FP]Fabric (0x1) deleted.
    I: 91336 [ZCL]OpCreds: Fabric index 0x1 was removed
    D: 91341 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c70
    D: 91347 [DMG]Endpoint 0, Cluster 0x0000_003E update version to 9b458c71
    I: 91371 [TS]Pending Last Known Good Time: 2023-02-27T23:17:21
    I: 91378 [TS]Previous Last Known Good Time: 2023-02-27T14:46:47
    I: 91383 [TS]Reverted Last Known Good Time to previous value
    D: 91389 [EVL]LogEvent event number: 0x0000000000080004 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x00000000000164FD
    D: 91403 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
    E: 91410 [FP]Warning: metadata not found during delete of fabric 0x1
    E: 91419 [ZCL]OpCreds: failed to delete fabric at index 1: d8
    D: 91425 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to f8c98809
    D: 91431 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
    I: 91439 [NP]Reverting Thread operational dataset
    E: 91451 [DL]Long dispatch time: 277 ms, for event type 32782
    I: 91456 [FS]Fail-safe cleanly disarmed
    D: 91460 [DL]OpenThread State Changed (Flags: 0x11002046)
    D: 91465 [DL]   Device Role: DISABLED
    D: 91468 [DL]   Thread Unicast Addresses:
    D: 91472 [DL]        fd86:d57c:7973:0:c333:268b:d0c:93f1/64 valid preferred
    D: 91481 [DL]OpenThread State Changed (Flags: 0x10000000)
    I: 91487 [DL]BLE GAP connection terminated (reason 0x16)
    I: 91492 [DL]Current number of connections: 0/2
    I: 91500 [DL]CHIPoBLE advertising started
    I: 91506 [DL]NFC Tag emulation started

  • Hi Dan

    I was able to comission with GHA and nRF Connect 2.2.0 (further detail here: https://issuetracker.google.com/issues/262773689), with a pristine build an a full flash erase before programming.

Related