The lock-app has been successfully built and flashed. The Thread Network details are as follows:
Channel: 18
Channel Mask: 0x07fff800
Ext PAN ID: 36d96a4bdd18dd8b
Network Name: Openthread-6592
PAN ID: 0x6592
Commissioning via CHIP Tool always yields the same result. Any help debugging this is greatly appreciated:
OpenThread started: OK
Setting OpenThread device type to MINIMAL END DEVICE
Initialize Server
Subscription persistence not supported
Server initializing...
Last Known Good Time: [unknown]
Setting Last Known Good Time to firmware build time 2023-02-15T08:35:16
AccessControl: initializing
Examples::AccessControlDelegate::Init
AccessControl: setting
DefaultAclStorage: initializing
DefaultAclStorage: 0 entries loaded
Using ZAP configuration...
AccessControlCluster: initializing
Initiating Admin Commissioning cluster.
Door Lock server initialized
Updating services using commissioning mode 0
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
Failed to advertise extended commissionable node: 3
Failed to finalize service update: 1c
Delaying proxy of operational discovery: missing delegate
CASE Server enabling CASE session setups
Joining Multicast groups
Server Listening...
Initialize LEDs
Initialize buttons
Initialize BoltLock
Device Configuration:
Serial Number: TEST_SN
Vendor Id: 65521 (0xFFF1)
Product Id: 32774 (0x8006)
Hardware Version: 0
Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
Manufacturing Date: (not set)
Device Type: 65535 (0xFFFF)
Stopping the watchdog timer
Starting the periodic query timer, timeout: 86400 seconds
SetupQRCode: [MT:8IXS142C00KA0648G00]
Copy/paste the below URL in a browser to see the QR Code:
project-chip.github.io/.../qrcode.html
Manual pairing code: [34970112332]
Updating services using commissioning mode 1
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
Failed to advertise commissionable node: 3
Failed to finalize service update: 1c
Enabled BLE Advertisements
local and remote recv window sizes = 6
selected BTP version 4
using BTP fragment sizes rx 244 / tx 244.
>>> [E:35929r M:240493127] (U) Msg RX from 0:DA9323AFA2BA8E74 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
<<< [E:35929r M:101590028] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
(U) Sending msg 101590028 to IP address 'BLE'
>>> [E:35929r M:240493128] (U) Msg RX from 0:DA9323AFA2BA8E74 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
<<< [E:35929r M:101590029] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
(U) Sending msg 101590029 to IP address 'BLE'
Long dispatch time: 5148 ms, for event type 7
>>> [E:35929r M:240493129] (U) Msg RX from 0:DA9323AFA2BA8E74 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
<<< [E:35929r M:101590030] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
(U) Sending msg 101590030 to IP address 'BLE'
SecureSession[0x20010d80]: Moving from state 'kEstablishing' --> 'kActive'
Commissioning completed session establishment step
Updating services using commissioning mode 0
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
Failed to advertise extended commissionable node: 3
Failed to finalize service update: 1c
Device completed Rendezvous process
>>> [E:35930r M:250305679] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
<<< [E:35930r M:171812196] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(S) Sending msg 171812196 on secure session with LSID: 6516
>>> [E:35931r M:250305680] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
GeneralCommissioning: Received ArmFailSafe (30s)
<<< [E:35931r M:171812197] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812197 on secure session with LSID: 6516
>>> [E:35932r M:250305681] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
<<< [E:35932r M:171812198] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812198 on secure session with LSID: 6516
>>> [E:35933r M:250305682] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Certificate Chain request received for PAI
<<< [E:35933r M:171812199] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812199 on secure session with LSID: 6516
>>> [E:35934r M:250305683] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Certificate Chain request received for DAC
<<< [E:35934r M:171812200] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812200 on secure session with LSID: 6516
>>> [E:35935r M:250305684] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Received an AttestationRequest command
OpCreds: AttestationRequest successful.
<<< [E:35935r M:171812201] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812201 on secure session with LSID: 6516
Long dispatch time: 158 ms, for event type 7
>>> [E:35936r M:250305685] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Received a CSRRequest command
OpCreds: AllocatePendingOperationalKey succeeded
OpCreds: CSRRequest successful.
<<< [E:35936r M:171812202] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812202 on secure session with LSID: 6516
Long dispatch time: 1291 ms, for event type 7
>>> [E:35937r M:250305686] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Received an AddTrustedRootCertificate command
OpCreds: AddTrustedRootCertificate successful.
<<< [E:35937r M:171812203] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812203 on secure session with LSID: 6516
Long dispatch time: 275 ms, for event type 7
>>> [E:35938r M:250305687] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
OpCreds: Received an AddNOC command
Validating NOC chain
NOC chain validation successful
Added new fabric at index: 0x1
Assigned compressed fabric ID: 0x79EDA5A4C757BF16, node ID: 0x000000000000001C
Last Known Good Time: 2023-02-15T08:35:16
New proposed Last Known Good Time: 2021-06-10T00:00:00
Retaining current Last Known Good Time
OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
Advertise operational node 79EDA5A4C757BF16-000000000000001C
OpCreds: successfully created fabric index 0x1 via AddNOC
<<< [E:35938r M:171812204] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812204 on secure session with LSID: 6516
Long dispatch time: 352 ms, for event type 7
>>> [E:35939r M:250305688] (S) Msg RX from 1:FFFFFFFB00000000 [BF16] --- Type 0001:08 (IM:InvokeCommandRequest)
<<< [E:35939r M:171812205] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812205 on secure session with LSID: 6516
>>> [E:35940r M:250305689] (S) Msg RX from 1:FFFFFFFB00000000 [BF16] --- Type 0001:08 (IM:InvokeCommandRequest)
SRP Client was started, detected server: fd2a:1418:61ab:d82c:05cb:7fe9:006b:fd63
<<< [E:35940r M:171812206] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 171812206 on secure session with LSID: 6516
Advertise operational node 79EDA5A4C757BF16-000000000000001C
Operational advertising enabled
Setting operational delegate post init
Updating services using commissioning mode 0
Advertise operational node 79EDA5A4C757BF16-000000000000001C
advertising srp service: 79EDA5A4C757BF16-000000000000001C._matter._tcp
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
advertising srp service: 4D7B32324939092B._matterc._udp
Fail-safe timer expired
Failsafe timer expired
SecureSession[0x20010d80]: Moving from state 'kActive' --> 'kPendingEviction'
Commissioning failed (attempt 1): 32
Releasing end point's BLE connection back to application.
Updating services using commissioning mode 1
Advertise operational node 79EDA5A4C757BF16-000000000000001C
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
advertising srp service: 4D7B32324939092B._matterc._udp
OpCreds: Got FailSafeTimerExpired
OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
Reverting pending fabric data for fabric 0x1
Warning: metadata not found during delete of fabric 0x1
Fabric (0x1) deleted.
UserLabel: Last Fabric index 0x1 was removed
OpCreds: Fabric index 0x1 was removed
Updating services using commissioning mode 1
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
advertising srp service: 4D7B32324939092B._matterc._udp
removing srp service: 79EDA5A4C757BF16-000000000000001C._matter._tcp
[OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=1]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=2]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=3]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=4]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=5]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=6]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=7]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=8]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=9]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=10]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=1,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=2,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=3,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=4,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=5,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=6,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=7,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=8,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=9,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=10,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=1,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=2,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=3,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=4,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=5,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=6,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=7,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=8,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=9,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=10,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1]
Pending Last Known Good Time: 2023-02-15T08:35:16
Previous Last Known Good Time: 2023-02-15T08:35:16
Reverted Last Known Good Time to previous value
Warning: metadata not found during delete of fabric 0x1
OpCreds: failed to delete fabric at index 1: d8
Reverting Thread operational dataset
Long dispatch time: 637 ms, for event type 32782
Fail-safe cleanly disarmed
Releasing end point's BLE connection back to application.
HandleChipConnectionReceived failed, err = d
failed handle new chip BLE connection, status = d
no endpoint for unsub recvd
---------------------- with additional logging enabled ------------------------------
Server Listening...
Initialize LEDs
Initialize buttons
Initialize BoltLock
Device Configuration:
Serial Number: TEST_SN
Vendor Id: 65521 (0xFFF1)
Product Id: 32774 (0x8006)
Hardware Version: 0
Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
Manufacturing Date: (not set)
Device Type: 65535 (0xFFFF)
Stopping the watchdog timer
Starting the periodic query timer, timeout: 86400 seconds
SetupQRCode: [MT:8IXS142C00KA0648G00]
Copy/paste the below URL in a browser to see the QR Code:
project-chip.github.io/.../qrcode.html
Manual pairing code: [34970112332]
SecureSession[0x20010b88]: Allocated Type:1 LSID:21883
Assigned local session key ID 21883
Waiting for PBKDF param request
Updating services using commissioning mode 1
Using Thread extended MAC for hostname.
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
Failed to advertise commissionable node: 3
Failed to finalize service update: 1c
Enabled BLE Advertisements
local and remote recv window sizes = 6
selected BTP version 4
using BTP fragment sizes rx 244 / tx 244.
BLE EndPoint 0x20013f20 Connection Complete
>>> [E:26667r M:49025330] (U) Msg RX from 0:A9EB6EA8880BD901 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
Handling via exchange: 26667r, Delegate: 0x20012d34
Received PBKDF param request
Peer assigned session ID 22325
Found MRP parameters in the message
Including MRP parameters in PBKDF param response
<<< [E:26667r M:85179937] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
(U) Sending msg 85179937 to IP address 'BLE'
Sent PBKDF param response
>>> [E:26667r M:49025331] (U) Msg RX from 0:A9EB6EA8880BD901 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
Found matching exchange: 26667r, Delegate: 0x20012d34
Received spake2p msg1
<<< [E:26667r M:85179938] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
(U) Sending msg 85179938 to IP address 'BLE'
Sent spake2p msg2
Long dispatch time: 5173 ms, for event type 7
>>> [E:26667r M:49025332] (U) Msg RX from 0:A9EB6EA8880BD901 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
Found matching exchange: 26667r, Delegate: 0x20012d34
Received spake2p msg3
Sending status report. Protocol code 0, exchange 26667
<<< [E:26667r M:85179939] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
(U) Sending msg 85179939 to IP address 'BLE'
SecureSession[0x20010b88]: Moving from state 'kEstablishing' --> 'kActive'
SecureSession[0x20010b88]: Activated - Type:1 LSID:21883
New secure session activated for device <FFFFFFFB00000000, 0>, LSID:21883 PSID:22325!
Commissioning completed session establishment step
Updating services using commissioning mode 0
Using Thread extended MAC for hostname.
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
Failed to advertise extended commissionable node: 3
Scheduling extended discovery timeout in 900s
Failed to finalize service update: 1c
Device completed Rendezvous process
>>> [E:26668r M:196824439] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
Handling via exchange: 26668r, Delegate: 0x20009694
Received Read request
IM RH moving to [GeneratingReports]
Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<RE:Run> Cluster 31, Attribute 3 is dirty
Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
<RE:Run> Cluster 28, Attribute 4 is dirty
Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
<RE:Run> Cluster 28, Attribute 2 is dirty
Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
<RE:Run> Cluster 30, Attribute 3 is dirty
Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
<RE:Run> Cluster 30, Attribute 2 is dirty
Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
<RE:Run> Cluster 30, Attribute 1 is dirty
Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
<RE:Run> Cluster 30, Attribute 0 is dirty
Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
<RE:Run> Cluster 31, Attribute fffc is dirty
Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
<RE> Sending report (payload has 228 bytes)...
<<< [E:26668r M:100549327] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
(S) Sending msg 100549327 on secure session with LSID: 21883
<RE> OnReportConfirm: NumReports = 0
<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
IM RH moving to [AwaitingDestruction]
All ReadHandler-s are clean, clear GlobalDirtySet
Long dispatch time: 145 ms, for event type 3
>>> [E:26669r M:196824440] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26669r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
GeneralCommissioning: Received ArmFailSafe (30s)
Endpoint 0, Cluster 0x0000_0030 update version to d70b44e7
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26669r M:100549328] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549328 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
>>> [E:26670r M:196824441] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26670r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
Endpoint 0, Cluster 0x0000_0030 update version to d70b44e8
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26670r M:100549329] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549329 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
>>> [E:26671r M:196824442] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26671r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
OpCreds: Certificate Chain request received for PAI
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26671r M:100549330] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549330 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
>>> [E:26672r M:196824443] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26672r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
OpCreds: Certificate Chain request received for DAC
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26672r M:100549331] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549331 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
>>> [E:26673r M:196824444] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26673r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
OpCreds: Received an AttestationRequest command
OpCreds: AttestationRequest successful.
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26673r M:100549332] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549332 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
Long dispatch time: 194 ms, for event type 7
>>> [E:26674r M:196824445] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26674r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
OpCreds: Received a CSRRequest command
OpCreds: Finding fabric with fabricIndex 0x0
OpCreds: AllocatePendingOperationalKey succeeded
OpCreds: CSRRequest successful.
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26674r M:100549333] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549333 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
Long dispatch time: 1329 ms, for event type 7
>>> [E:26675r M:196824446] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26675r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
OpCreds: Received an AddTrustedRootCertificate command
OpCreds: AddTrustedRootCertificate successful.
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26675r M:100549334] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549334 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
Long dispatch time: 309 ms, for event type 7
>>> [E:26676r M:196824447] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26676r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
OpCreds: Received an AddNOC command
Validating NOC chain
NOC chain validation successful
Added new fabric at index: 0x1
Assigned compressed fabric ID: 0x79EDA5A4C757BF16, node ID: 0x000000000000001D
Last Known Good Time: 2023-02-21T12:21:22
New proposed Last Known Good Time: 2021-06-10T00:00:00
Retaining current Last Known Good Time
Endpoint 0, Cluster 0x0000_003E update version to 66d94909
Endpoint 0, Cluster 0x0000_003E update version to 66d9490a
LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000000098C2
OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
Using Thread extended MAC for hostname.
Advertise operational node 79EDA5A4C757BF16-000000000000001D
Endpoint 0, Cluster 0x0000_003E update version to 66d9490b
Endpoint 0, Cluster 0x0000_003E update version to 66d9490c
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
OpCreds: successfully created fabric index 0x1 via AddNOC
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26676r M:100549335] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549335 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
Long dispatch time: 425 ms, for event type 7
>>> [E:26677r M:196824448] (S) Msg RX from 1:FFFFFFFB00000000 [BF16] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26677r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Endpoint 0, Cluster 0x0000_0030 update version to d70b44e9
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26677r M:100549336] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549336 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
>>> [E:26678r M:196824449] (S) Msg RX from 1:FFFFFFFB00000000 [BF16] --- Type 0001:08 (IM:InvokeCommandRequest)
Handling via exchange: 26678r, Delegate: 0x20009694
Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
Decreasing reference count for CommandHandler, remaining 1
OpenThread State Changed (Flags: 0x1106d11d)
Device Role: DETACHED
Network Name: OpenThread
PAN Id: 0x6592
Extended PAN Id: 0x36D96A4BDD18DD8B
Channel: 15
Mesh Prefix: FDDE:AD00:BEEF::/64
Thread Unicast Addresses:
FDDE:AD00:BEEF:0:DE37:D4AF:FB13:9A1A/64 valid
FE80::58CD:3D94:1A3A:19ED/64 valid preferred
LwIP Thread interface UP
LwIP Thread interface addresses updated
FE80::58CD:3D94:1A3A:19ED IPv6 link-local address, preferred)
FDDE:AD00:BEEF:0:DE37:D4AF:FB13:9A1A Thread mesh-local address)
OpenThread State Changed (Flags: 0x00007017)
Device Role: DETACHED
Network Name: OpenThread
PAN Id: 0x6592
Extended PAN Id: 0x36D96A4BDD18DD8B
Channel: 18
Mesh Prefix: FDDE:AD00:BEEF::/64
Thread Unicast Addresses:
FDDE:AD00:BEEF:0:DE37:D4AF:FB13:9A1A/64 valid
FE80::58CD:3D94:1A3A:19ED/64 valid preferred
LwIP Thread interface addresses updated
FE80::58CD:3D94:1A3A:19ED IPv6 link-local address, preferred)
FDDE:AD00:BEEF:0:DE37:D4AF:FB13:9A1A Thread mesh-local address)
SRP Client was started, detected server: fd2a:1418:61ab:d82c:05cb:7fe9:006b:fd63
OpenThread State Changed (Flags: 0x301132b7)
Device Role: CHILD
Network Name: OpenThread-6592
PAN Id: 0x6592
Extended PAN Id: 0x36D96A4BDD18DD8B
Channel: 18
Mesh Prefix: FD2A:1418:61AB:D82C::/64
Partition Id: 0x11AFACC9
Thread Unicast Addresses:
FDF6:F394:5AF1:1:3B2A:81EF:E827:73DE/64 valid preferred
FD2A:1418:61AB:D82C:0:FF:FE00:5003/64 valid rloc
FD2A:1418:61AB:D82C:DE37:D4AF:FB13:9A1A/64 valid
FE80::58CD:3D94:1A3A:19ED/64 valid preferred
LwIP Thread interface addresses updated
FE80::58CD:3D94:1A3A:19ED IPv6 link-local address, preferred)
FDF6:F394:5AF1:1:3B2A:81EF:E827:73DE IPv6 unique local address, preferred)
FD2A:1418:61AB:D82C:DE37:D4AF:FB13:9A1A Thread mesh-local address)
OpenThread State Changed (Flags: 0x00000001)
Thread Unicast Addresses:
FDF6:F394:5AF1:1:3B2A:81EF:E827:73DE/64 valid preferred
FD2A:1418:61AB:D82C:0:FF:FE00:5003/64 valid rloc
FD2A:1418:61AB:D82C:DE37:D4AF:FB13:9A1A/64 valid
FE80::58CD:3D94:1A3A:19ED/64 valid preferred
LwIP Thread interface addresses updated
FE80::58CD:3D94:1A3A:19ED IPv6 link-local address, preferred)
FDF6:F394:5AF1:1:3B2A:81EF:E827:73DE IPv6 unique local address, preferred)
FD2A:1418:61AB:D82C:DE37:D4AF:FB13:9A1A Thread mesh-local address)
Command handler moving to [ Preparing]
Command handler moving to [AddingComm]
Command handler moving to [AddedComma]
Endpoint 0, Cluster 0x0000_0030 update version to d70b44ea
Decreasing reference count for CommandHandler, remaining 0
<<< [E:26678r M:100549337] (S) Msg TX to 1:FFFFFFFB00000000 [BF16] --- Type 0001:09 (IM:InvokeCommandResponse)
(S) Sending msg 100549337 on secure session with LSID: 21883
Command handler moving to [CommandSen]
Command handler moving to [AwaitingDe]
Using Thread extended MAC for hostname.
Advertise operational node 79EDA5A4C757BF16-000000000000001D
Operational advertising enabled
SRP update succeeded
Setting operational delegate post init
Updating services using commissioning mode 0
Using Thread extended MAC for hostname.
Advertise operational node 79EDA5A4C757BF16-000000000000001D
advertising srp service: 79EDA5A4C757BF16-000000000000001D._matter._tcp
Using Thread extended MAC for hostname.
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=0
advertising srp service: 909DFF42EB99D855._matterc._udp
SRP update succeeded
Fail-safe timer expired
Failsafe timer expired
SecureSession[0x20010b88]: MarkForEviction Type:1 LSID:21883
SecureSession[0x20010b88]: Moving from state 'kActive' --> 'kPendingEviction'
SecureSession[0x20010b88]: Released - Type:1 LSID:21883
Commissioning failed (attempt 1): 32
Clearing BLE pending packets.
Releasing end point's BLE connection back to application.
SecureSession[0x20010b88]: Allocated Type:1 LSID:21884
Assigned local session key ID 21884
Waiting for PBKDF param request
Updating services using commissioning mode 1
Using Thread extended MAC for hostname.
Advertise operational node 79EDA5A4C757BF16-000000000000001D
Using Thread extended MAC for hostname.
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
advertising srp service: 909DFF42EB99D855._matterc._udp
OpCreds: Got FailSafeTimerExpired
OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
Expiring all sessions for fabric 0x1!!
Reverting pending fabric data for fabric 0x1
LogEvent event number: 0x0000000000000003 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000000FF2F
All ReadHandler-s are clean, clear GlobalDirtySet
Warning: metadata not found during delete of fabric 0x1
Fabric (0x1) deleted.
UserLabel: Last Fabric index 0x1 was removed
OpCreds: Fabric index 0x1 was removed
Updating services using commissioning mode 1
Using Thread extended MAC for hostname.
Advertise commission parameter vendorID=65521 productID=32774 discriminator=3840/15 cm=1
advertising srp service: 909DFF42EB99D855._matterc._udp
removing srp service: 79EDA5A4C757BF16-000000000000001D._matter._tcp
Endpoint 0, Cluster 0x0000_003E update version to 66d9490d
Endpoint 0, Cluster 0x0000_003E update version to 66d9490e
[OnFabricRemoved] Handling a fabric removal from the door lock server [endpointId=1,fabricIndex=1]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=1]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=2]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=3]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=4]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=5]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=6]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=7]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=8]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=9]
[OnFabricRemoved] Unable to get the user - internal error [endpointId=1,fabricIndex=1,userIndex=10]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=1,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=2,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=3,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=4,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=5,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=6,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=7,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=8,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=9,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=2,credentialIndex=10,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=1,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=2,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=3,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=4,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=5,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=6,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=7,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=8,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=9,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=1,credentialIndex=10,fabricIdToRemove=1]
[clearFabricFromCredentials] Unable to clear fabric from credential - couldn't read credential from database [endpointId=1,credentialType=0,credentialIndex=0,fabricIdToRemove=1]
Pending Last Known Good Time: 2023-02-21T12:21:22
Previous Last Known Good Time: 2023-02-21T12:21:22
Reverted Last Known Good Time to previous value
LogEvent event number: 0x0000000000000004 priority: 1, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000001016F
All ReadHandler-s are clean, clear GlobalDirtySet
Warning: metadata not found during delete of fabric 0x1
OpCreds: failed to delete fabric at index 1: d8
Endpoint 0, Cluster 0x0000_0030 update version to d70b44eb
Failsafe timeout, tell platform driver to revert network credentials.
Reverting Thread operational dataset
Long dispatch time: 733 ms, for event type 32782
Fail-safe cleanly disarmed
OpenThread State Changed (Flags: 0x11002046)
Device Role: DISABLED
Thread Unicast Addresses:
FDF6:F394:5AF1:1:3B2A:81EF:E827:73DE/64 valid preferred
LwIP Thread interface DOWN
LwIP Thread interface addresses cleared
Clearing BLE pending packets.
Releasing end point's BLE connection back to application.
HandleChipConnectionReceived failed, err = d
failed handle new chip BLE connection, status = d
no endpoint for unsub recvd
