Matter commissioning fails - OnSrpClientNotification: Operation refused for security reasons

[Dan]

Hi - I have successfully built the Android Chiptool and Window Covering sample using NRF Connect SDK v2.0.2. I build them both using the same matter library that is installed with nrf v.2.0.2.

The Chiptool app runs on the phone, the Window Covering sample runs on the nrf3540 DK, but I am unable to successfully commission the device using the Chiptool app, using an EERO6 as a thread border router (which I had done in the past and it worked fine).

Looking at the logs from each side, the NRF device complains about "OnSrpClientNotification: Operation refused for security reasons"

From the Android side, it looks like it completes all the Thread commissioning steps up to and including "Successfully finished commissioning step 'ThreadNetworkEnable'", but then fails at FindOperational due to a timeout:

D/CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
D/CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
D/CTL: Performing next commissioning step 'FindOperational'
D/CSM: FindOrEstablishSession: PeerId = 3797F4780A8BC149:0000000000000071
D/CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found
D/DIS: Resolving 3797F4780A8BC149:0000000000000071 ...
D/NsdManagerServiceResolver: Starting service resolution for '3797F4780A8BC149-0000000000000071'
D/DIS: Operational node lookup already in progress. Will NOT start a new one.
D/DMG: ICR moving to [AwaitingDe]
D/DIS: Checking node lookup status after 201 ms
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/DIS: Checking node lookup status after 15002 ms
E/DIS: Operational discovery failed for 0x0000000000000071: 32
D/CTL: Device connection failed. Error ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
D/CTL: Error on commissioning step 'FindOperational': '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
E/CTL: Failed to perform commissioning step 18
D/CTL: Going from commissioning step 'FindOperational' with lastErr = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
D/CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
D/CTL: Successfully finished commissioning step 'Cleanup'

In case it is helpful, I provide below both the Chiptool logs as well as NRF device logs. 

Welcome any help! Thanks!

Android Chiptool Log

I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
D/BluetoothAdapter: isLeEnabled(): ON
I/DeviceProvisioningFragment: showMessage:Connecting to MatterWinCov
I/chip.BluetoothManager: Connecting
D/BluetoothGatt: connect() - device: E1:DB:2F:97:63:4C, auto: false
D/BluetoothGatt: registerApp()
D/BluetoothGatt: registerApp() - UUID=79a19d99-9206-4ebb-9238-0c79ba6a4e70
D/BluetoothGatt: onClientRegistered() - status=0 clientIf=8
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
I/chip.BluetoothManager: Bluetooth Device Scanned Addr: E1:DB:2F:97:63:4C, Name MatterWinCov
W/chip.BluetoothManager: Bluetooth device was scanned, but channel is already closed
D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=E1:DB:2F:97:63:4C
I/chip.BluetoothManager: MatterWinCov.onConnectionStateChange status = 0, newState=2
I/chip.BluetoothManager|onConnectionStateChange: Discovering Services...
D/BluetoothGatt: discoverServices() - device: E1:DB:2F:97:63:4C
D/BluetoothGatt: onConnectionUpdated() - Device=E1:DB:2F:97:63:4C interval=6 latency=0 timeout=500 status=0
D/BluetoothGatt: onPhyUpdate() - status=0 address=E1:DB:2F:97:63:4C txPhy=2 rxPhy=2
D/BluetoothGatt: onSearchComplete() = Device=E1:DB:2F:97:63:4C Status=0
D/chip.BluetoothManager: MatterWinCov.onServicesDiscovered status = 0
I/chip.BluetoothManager|onServicesDiscovered: Services Discovered
D/BluetoothGatt: configureMTU() - device: E1:DB:2F:97:63:4C mtu: 247
D/BluetoothGatt: onConfigureMTU() - Device=E1:DB:2F:97:63:4C mtu=247 status=0
D/chip.BluetoothManager: MatterWinCov.onMtuChanged: connecting to CHIP device
I/DeviceProvisioningFragment: showMessage:Pairing
D/ChipDeviceController: Bluetooth connection added with ID: 1
D/ChipDeviceController: Pairing device with ID: 113
D/CTL: pairDevice() called with device ID, connection object, and pincode
D/IN: BleConnectionComplete: endPoint 0x7fc6a700
D/DL: Received GetMTU
D/AndroidBleManager: Android Manufacturer: (motorola)
D/AndroidBleManager: Android Model: (moto g pure)
D/DL: Received SendWriteRequest
D/SC: Assigned local session key ID 6486
D/SC: Including MRP parameters in PBKDF param request
D/IN: Prepared unauthenticated message 0xbed20970 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 45216i with MessageCounter:212820841.
D/IN: Sending unauthenticated msg 0xbed20970 with MessageCounter:212820841 to 0x0000000000000000 at monotonic time: 000000000EDD3CF2 msec
D/IN: Message appended to BLE send queue
D/SC: Sent PBKDF param request
D/CTL: Setting thread operational dataset from parameters
D/CTL: Setting attestation nonce to random value
D/CTL: Setting CSR nonce to random value
D/CTL: Commission called for node ID 0x0000000000000071
D/BluetoothGatt: onConnectionUpdated() - Device=E1:DB:2F:97:63:4C interval=39 latency=0 timeout=500 status=0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/DL: Received SubscribeCharacteristic
D/BluetoothGatt: setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: true
D/chip.BluetoothManager: MatterWinCov.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 0
D/BLE: subscribe complete, ep = 0x7fc6a700
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/BLE: peripheral chose BTP version 4; central expected between 4 and 4
D/BLE: using BTP fragment sizes rx 244 / tx 244.
D/BLE: local and remote recv window size = 5
D/DL: Received SendWriteRequest
D/IN: BLE EndPoint 0x7fc6a700 Connection Complete
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:3631968069 on exchange 45216i
D/EM: Found matching exchange: 45216i, Delegate: 0x80700d48
D/SC: Received PBKDF param response
D/SC: Peer assigned session ID 57616
D/SC: Found MRP parameters in the message
D/IN: Prepared unauthenticated message 0x8354fc98 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 45216i with MessageCounter:212820842.
D/IN: Sending unauthenticated msg 0x8354fc98 with MessageCounter:212820842 to 0x0000000000000000 at monotonic time: 000000000EDD3EA5 msec
D/DL: Received SendWriteRequest
D/SC: Sent spake2p msg1
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:3631968070 on exchange 45216i
D/EM: Found matching exchange: 45216i, Delegate: 0x80700d48
D/SC: Received spake2p msg2
D/IN: Prepared unauthenticated message 0x8354ff30 to 0x0000000000000000 (0)  of type 0x24 and protocolId (0, 0) on exchange 45216i with MessageCounter:212820843.
D/IN: Sending unauthenticated msg 0x8354ff30 with MessageCounter:212820843 to 0x0000000000000000 at monotonic time: 000000000EDD458F msec
D/DL: Received SendWriteRequest
D/SC: Sent spake2p msg3
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:3631968071 on exchange 45216i
D/EM: Found matching exchange: 45216i, Delegate: 0x80700d48
D/IN: New secure session created for device <FFFFFFFB00000000, 0>, LSID:6486 PSID:57616!
D/CTL: Remote device completed SPAKE2+ handshake
D/DeviceProvisioningFragment: onPairingComplete: 0
D/CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
D/CTL: Performing next commissioning step 'ReadCommissioningInfo'
D/CTL: Sending request for commissioning information
D/DMG: SendReadRequest ReadClient[0x92ab1d00]: Sending Read Request
D/IN: Prepared secure message 0x8354ebb0 to 0xFFFFFFFB00000000 (0)  of type 0x2 and protocolId (0, 1) on exchange 45217i with MessageCounter:5726648.
D/IN: Sending encrypted msg 0x8354ebb0 with MessageCounter:5726648 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD4618 msec
D/DL: Received SendWriteRequest
D/DMG: MoveToState ReadClient[0x92ab1d00]: Moving to [AwaitingIn]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:11415863 on exchange 45217i
D/EM: Found matching exchange: 45217i, Delegate: 0x92ab1d00
D/DMG: ReportDataMessage =
D/DMG: {
D/DMG: 	AttributeReportIBs =
D/DMG: 	[
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x5948be21,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x31,
D/DMG: 					Attribute = 0x0000_0003,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 20, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0xe552cceb,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x28,
D/DMG: 					Attribute = 0x0000_0004,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 32784, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0xe552cceb,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x28,
D/DMG: 					Attribute = 0x0000_0002,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 65521, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x21f3d7dc,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x30,
D/DMG: 					Attribute = 0x0000_0003,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 0, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x21f3d7dc,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x30,
D/DMG: 					Attribute = 0x0000_0002,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 0, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x21f3d7dc,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x30,
D/DMG: 					Attribute = 0x0000_0001,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 
D/DMG: 					{
D/DMG: 						0x0 = 60, 
D/DMG: 					},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x21f3d7dc,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x30,
D/DMG: 					Attribute = 0x0000_0000,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 0, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 		AttributeReportIB =
D/DMG: 		{
D/DMG: 			AttributeDataIB =
D/DMG: 			{
D/DMG: 				DataVersion = 0x5948be21,
D/DMG: 				AttributePathIB =
D/DMG: 				{
D/DMG: 					Endpoint = 0x0,
D/DMG: 					Cluster = 0x31,
D/DMG: 					Attribute = 0x0000_FFFC,
D/DMG: 				}
D/DMG: 					
D/DMG: 					Data = 2, 
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	SuppressResponse = true, 
D/DMG: 	InteractionModelRevision = 1
D/DMG: }
D/CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
D/CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
D/CTL: Performing next commissioning step 'ArmFailSafe'
D/CTL: Arming failsafe (60 seconds)
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e958 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45218i with MessageCounter:5726649.
D/IN: Sending encrypted msg 0x8354e958 with MessageCounter:5726649 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD480A msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415864 on exchange 45218i
D/EM: Found matching exchange: 45218i, Delegate: 0x92ab1d00
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x30,
D/DMG: 					CommandId = 0x1,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = 0, 
D/DMG: 					0x1 = "", 
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
D/CTL: Received ArmFailSafe response errorCode=0
D/CTL: Successfully finished commissioning step 'ArmFailSafe'
D/CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
D/CTL: Performing next commissioning step 'ConfigRegulatory'
D/CTL: Setting Regulatory Config
D/CTL: Device does not support configurable regulatory location
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e408 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45219i with MessageCounter:5726650.
D/IN: Sending encrypted msg 0x8354e408 with MessageCounter:5726650 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD4896 msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415865 on exchange 45219i
D/EM: Found matching exchange: 45219i, Delegate: 0x92ab1dc0
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x30,
D/DMG: 					CommandId = 0x3,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = 0, 
D/DMG: 					0x1 = "", 
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
D/CTL: Received SetRegulatoryConfig response errorCode=0
D/CTL: Successfully finished commissioning step 'ConfigRegulatory'
D/CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
D/CTL: Performing next commissioning step 'SendPAICertificateRequest'
D/CTL: Sending request for PAI certificate
D/CTL: Sending Certificate Chain request to 0x80700d08 device
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e378 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45220i with MessageCounter:5726651.
D/IN: Sending encrypted msg 0x8354e378 with MessageCounter:5726651 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD495F msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
I/chatty: uid=10349(com.google.chip.chiptool) Binder:21956_4 identical 1 line
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415866 on exchange 45220i
D/EM: Found matching exchange: 45220i, Delegate: 0x92ab1d00
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0x3,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = [
D/DMG: 						... (byte string too long) ...
D/DMG: 				]
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
D/CTL: Received certificate chain from the device
D/CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
D/CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
D/CTL: Performing next commissioning step 'SendDACCertificateRequest'
D/CTL: Sending request for DAC certificate
D/CTL: Sending Certificate Chain request to 0x80700d08 device
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e380 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45221i with MessageCounter:5726652.
D/IN: Sending encrypted msg 0x8354e380 with MessageCounter:5726652 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD4AE2 msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
I/chatty: uid=10349(com.google.chip.chiptool) Binder:21956_4 identical 1 line
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415867 on exchange 45221i
D/EM: Found matching exchange: 45221i, Delegate: 0x92ab1dc0
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0x3,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = [
D/DMG: 						... (byte string too long) ...
D/DMG: 				]
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
D/CTL: Received certificate chain from the device
D/CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
D/CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
D/CTL: Performing next commissioning step 'SendAttestationRequest'
D/CTL: Sending Attestation Request to the device.
D/CTL: Sending Attestation request to 0x80700d08 device
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e370 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45222i with MessageCounter:5726653.
D/IN: Sending encrypted msg 0x8354e370 with MessageCounter:5726653 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD4C6B msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/CTL: Sent Attestation request, waiting for the Attestation Information
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
I/chatty: uid=10349(com.google.chip.chiptool) Binder:21956_4 identical 1 line
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415868 on exchange 45222i
D/EM: Found matching exchange: 45222i, Delegate: 0x92ab1d00
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0x1,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = [
D/DMG: 						... (byte string too long) ...
D/DMG: 				]
D/DMG: 					0x1 = [
D/DMG: 						0x41, 0x75, 0x10, 0x19, 0x29, 0x82, 0xa0, 0xa3, 0x8e, 0x5c, 0x34, 0xea, 0x64, 0xec, 0x32, 0x97, 0xf3, 0x77, 0x9f, 0xe7, 0x8c, 0x3c, 0x66, 0x7a, 0x22, 0x4, 0xa0, 0xa1, 0x82, 0xcb, 0x5a, 0x95, 0x3f, 0x86, 0xb6, 0x82, 0x97, 0xfc, 0x48, 0x7e, 0xa7, 0x77
D/DMG: 				]
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
D/CTL: Received Attestation Information from the device
D/CTL: Successfully finished commissioning step 'SendAttestationRequest'
D/CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
D/CTL: Performing next commissioning step 'AttestationVerification'
D/CTL: Verifying attestation
E/CR: mbedTLS error: ERROR - Generic error
D/CTL: Successfully validated 'Attestation Information' command received from the device.
D/CTL: Successfully finished commissioning step 'AttestationVerification'
D/CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
D/CTL: Performing next commissioning step 'SendOpCertSigningRequest'
D/CTL: Sending CSR request to 0x80700d08 device
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354c9c0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45223i with MessageCounter:5726654.
D/IN: Sending encrypted msg 0x8354c9c0 with MessageCounter:5726654 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD4F36 msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/CTL: Sent CSR request, waiting for the CSR
D/DMG: ICR moving to [AwaitingDe]
D/BluetoothGatt: onConnectionUpdated() - Device=E1:DB:2F:97:63:4C interval=36 latency=0 timeout=42 status=0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415869 on exchange 45223i
D/EM: Found matching exchange: 45223i, Delegate: 0x92ab1dc0
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0x5,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = [
D/DMG: 						0x15, 0x30, 0x1, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86
D/DMG: 				]
D/DMG: 					0x1 = [
D/DMG: 						0x65, 0x46, 0xba, 0x0, 0xf5, 0xdd, 0x44, 0xcd, 0x54, 0x2f, 0xc6, 0x72, 0x65, 0x63, 0xee, 0xc9, 0xec, 0xe0, 0x40, 0x53, 0x72, 0x4d, 0x3c, 0xa0, 0x19, 0x44, 0xd3, 0x22, 0xf6, 0x1a, 0xc2, 0x18, 0xed, 0xf7, 0x35, 0xff, 0xf3, 0x7d, 0x8d, 0x4e, 0x6e, 0x79
D/DMG: 				]
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
D/CTL: Received certificate signing request from the device
D/CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
D/CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
D/CTL: Performing next commissioning step 'ValidateCSR'
D/CTL: Successfully finished commissioning step 'ValidateCSR'
D/CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
D/CTL: Performing next commissioning step 'GenerateNOCChain'
D/CTL: Getting certificate chain for the device from the issuer
D/TOO: VerifyCertificateSigningRequest
D/TOO: KVS: Getting key AndroidCARootCert1
D/CTL: Generating NOC
D/CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/java/AndroidOperationalCredentialsIssuer.cpp:205: Success
D/CTL: Successfully finished commissioning step 'GenerateNOCChain'
D/CTL: Performing next commissioning step 'SendTrustedRootCert'
D/CTL: Sending root certificate to the device
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354b500 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45224i with MessageCounter:5726655.
D/IN: Sending encrypted msg 0x8354b500 with MessageCounter:5726655 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD520B msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/CTL: Sent root certificate to the device
D/DeviceProvisioningFragment: 0�0��0p��010
    U
    CSR0Y0*�H�=*�H�=B��uy
�n�H7$dY������[�%��O0�r���:$��>��	T|�q������p�D7���
���0*�H�=��H��0E %'�WU3��7�9lfd@�g�h̀c��wg�!����"�i��%��`�g�k|��rj��f��=0 ���l��x@IR���ӠY0F�l9j�:2r_	k�
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415870 on exchange 45224i
D/EM: Found matching exchange: 45224i, Delegate: 0x92ab1d00
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandStatusIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0xb,
D/DMG: 				},
D/DMG: 				
D/DMG: 				StatusIB =
D/DMG: 				{
D/DMG: 					status = 0x00,
D/DMG: 				},
D/DMG: 				
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
D/CTL: Device confirmed that it has received the root certificate
D/CTL: Successfully finished commissioning step 'SendTrustedRootCert'
D/CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
D/CTL: Performing next commissioning step 'SendNOC'
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e3d0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45225i with MessageCounter:5726656.
D/IN: Sending encrypted msg 0x8354e3d0 with MessageCounter:5726656 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD5321 msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/CTL: Sent operational certificate to the device
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415871 on exchange 45225i
D/EM: Found matching exchange: 45225i, Delegate: 0x92ab1dc0
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x3e,
D/DMG: 					CommandId = 0x8,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = 0, 
D/DMG: 					0x1 = 1, 
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
D/CTL: Device returned status 0 on receiving the NOC
D/CTL: Operational credentials provisioned on device 0x80700d08
D/DeviceProvisioningFragment: Pairing status update: 0
D/CTL: Successfully finished commissioning step 'SendNOC'
D/CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
D/CTL: Performing next commissioning step 'ThreadNetworkSetup'
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e370 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45226i with MessageCounter:5726657.
D/IN: Sending encrypted msg 0x8354e370 with MessageCounter:5726657 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD5515 msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415872 on exchange 45226i
D/EM: Found matching exchange: 45226i, Delegate: 0x92ab1d00
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x31,
D/DMG: 					CommandId = 0x5,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = 0, 
D/DMG: 					0x2 = 0, 
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
D/CTL: Received NetworkConfig response, networkingStatus=0
D/CTL: Successfully finished commissioning step 'ThreadNetworkSetup'
D/CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable'
D/CTL: Performing next commissioning step 'ThreadNetworkEnable'
D/DMG: ICR moving to [AddingComm]
D/DMG: ICR moving to [AddedComma]
D/IN: Prepared secure message 0x8354e400 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 45227i with MessageCounter:5726658.
D/IN: Sending encrypted msg 0x8354e400 with MessageCounter:5726658 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000EDD55CB msec
D/DL: Received SendWriteRequest
D/DMG: ICR moving to [CommandSen]
D/DMG: ICR moving to [AwaitingDe]
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:11415873 on exchange 45227i
D/EM: Found matching exchange: 45227i, Delegate: 0x92ab1dc0
D/DMG: ICR moving to [ResponseRe]
D/DMG: InvokeResponseMessage =
D/DMG: {
D/DMG: 	suppressResponse = false, 
D/DMG: 	InvokeResponseIBs =
D/DMG: 	[
D/DMG: 		InvokeResponseIB =
D/DMG: 		{
D/DMG: 			CommandDataIB =
D/DMG: 			{
D/DMG: 				CommandPathIB =
D/DMG: 				{
D/DMG: 					EndpointId = 0x0,
D/DMG: 					ClusterId = 0x31,
D/DMG: 					CommandId = 0x7,
D/DMG: 				},
D/DMG: 				
D/DMG: 				CommandData = 
D/DMG: 				{
D/DMG: 					0x0 = 0, 
D/DMG: 					0x2 = NULL
D/DMG: 				},
D/DMG: 			},
D/DMG: 			
D/DMG: 		},
D/DMG: 		
D/DMG: 	],
D/DMG: 	
D/DMG: 	InteractionModelRevision = 1
D/DMG: },
D/DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
D/CTL: Received ConnectNetwork response, networkingStatus=0
D/CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
D/CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
D/CTL: Performing next commissioning step 'FindOperational'
D/CSM: FindOrEstablishSession: PeerId = 3797F4780A8BC149:0000000000000071
D/CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found
D/DIS: Resolving 3797F4780A8BC149:0000000000000071 ...
D/NsdManagerServiceResolver: Starting service resolution for '3797F4780A8BC149-0000000000000071'
D/DIS: Operational node lookup already in progress. Will NOT start a new one.
D/DMG: ICR moving to [AwaitingDe]
D/DIS: Checking node lookup status after 201 ms
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/chip.BluetoothManager: MatterWinCov.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12
D/DL: Received SendWriteRequest
D/chip.BluetoothManager: MatterWinCov.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
D/DIS: Checking node lookup status after 15002 ms
E/DIS: Operational discovery failed for 0x0000000000000071: 32
D/CTL: Device connection failed. Error ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
D/CTL: Error on commissioning step 'FindOperational': '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
E/CTL: Failed to perform commissioning step 18
D/CTL: Going from commissioning step 'FindOperational' with lastErr = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
D/CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
D/CTL: Successfully finished commissioning step 'Cleanup'
D/DIS: Discovery does not require any more timeouts
I/DeviceProvisioningFragment: showMessage:Pairing failed

NRF Device Log

uart:~$ I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, b88
I: data wra: 0, 690
*** Booting Zephyr OS build v3.0.99-ncs1-1  ***
I: Init CHIP stack
I: Swap type: none
D: 109 [DL]Boot reason: 6
I: 178 [DL]BLE address: E1:DB:2F:97:63:4C
I: 204 [DL]OpenThread started: OK
I: 207 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 214 [SVR]Server initializing...
D: 217 [DIS]Init fabric pairing table with server storage
I: 223 [DMG]AccessControl: initializing
I: 226 [DMG]Examples::AccessControlDelegate::Init
I: 231 [DMG]AccessControl: setting
I: 234 [DMG]DefaultAclStorage: initializing
I: 238 [DMG]DefaultAclStorage: 0 entries loaded
I: 242 [ZCL]Using ZAP configuration...
D: 246 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 254 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: a0
D: 261 [DMG]Failed to read stored attribute (0, 0x0000_002B, 0x0000_0001: a0
D: 268 [DMG]Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0
D: 276 [DMG]Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: a0
D: 285 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0003: a0
D: 292 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0004: a0
D: 300 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0007: a0
D: 307 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0008: a0
D: 314 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0009: a0
D: 322 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_000E: a0
D: 329 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_000F: a0
D: 336 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0010: a0
D: 343 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0011: a0
D: 351 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0012: a0
D: 358 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0013: a0
D: 365 [DMG]Failed to read stored attribute (1, 0x0000_0102, 0x0000_0017: a0
D: 373 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0003: a0
D: 380 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0004: a0
D: 387 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0007: a0
D: 395 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0008: a0
D: 402 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0009: a0
D: 409 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_000E: a0
D: 417 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_000F: a0
D: 424 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0010: a0
D: 431 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0011: a0
D: 438 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0012: a0
D: 446 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0013: a0
D: 453 [DMG]Failed to read stored attribute (2, 0x0000_0102, 0x0000_0017: a0
I: 460 [DMG]AccessControlCluster: initializing
I: 464 [ZCL]Initiating Admin Commissioning cluster.
D: 469 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 21f3d7dc
I: 475 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 483 [DIS]Add fabric pairing table delegate
E: 487 [ZCL]DeviceInfoProvider is not registered
E: 491 [ZCL]Trying to write invalid Calendar Type
E: 496 [ZCL]Failed to write calendar type with error: 0x87
I: 501 [ZCL]Window Covering Cluster init
D: 506 [DMG]Endpoint 1, Cluster 0x0000_0102 update version to db01a687
I: 512 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
I: 519 [ZCL]Window Covering Cluster init
D: 524 [DMG]Endpoint 2, Cluster 0x0000_0102 update version to 127a8ee1
I: 530 [ZCL]Window covering cluster ID: 0x0000_0007 Type: 24 Value: 27, length: 1
D: 537 [IN]UDP::Init bind&listen port=5540
E: 541 [IN]SO_REUSEPORT failed: 109
D: 545 [IN]UDP::Init bound to port=5540
D: 548 [IN]BLEBase::Init - setting/overriding transport
D: 553 [IN]TransportMgr initialized
D: 560 [DIS]Add fabric pairing table delegate
D: 564 [DL]Using Thread extended MAC for hostname.
I: 571 [DIS]Updating services using commissioning mode 0
D: 576 [DL]Using Thread extended MAC for hostname.
D: 581 [DL]Using Thread extended MAC for hostname.
I: 586 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15
E: 594 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
D: 602 [DIS]Scheduling extended discovery timeout in 900s
E: 607 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 613 [DIS]Delaying proxy of operational discovery: missing delegate
I: 619 [IN]CASE Server enabling CASE session setups
I: 623 [SVR]Joining Multicast groups
D: 627 [ZCL]Emitting StartUp event
D: 630 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000276
D: 644 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
D: 649 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to c9d2853d
D: 655 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000028F
I: 669 [SVR]Server Listening...
I: 674 [SWU]Stopping the watchdog timer
I: 678 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 684 [DL]Device Configuration:
I: 687 [DL]  Serial Number: TEST_SN
I: 690 [DL]  Vendor Id: 65521 (0xFFF1)
I: 694 [DL]  Product Id: 32784 (0x8010)
I: 698 [DL]  Hardware Version: 0
I: 701 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 707 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 714 [DL]  Manufacturing Date: (not set)
I: 718 [DL]  Device Type: 65535 (0xFFFF)
I: 722 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
I: 727 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 733 [SVR]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
I: 741 [SVR]Manual pairing code: [34970112332]
I: 746 [DL]CHIP task running
I: 750 [ZCL]WC POST ATTRIBUTE=7 OpStatus global=0x00 lift=0x00 tilt=0x00
I: 756 [ZCL]ConfigStatus 0x1B Operational=1 OnlineReserved=1
I: 762 [ZCL]Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
D: 767 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 7811bab3
D: 774 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 7811bab4
D: 107099 [SC]Assigned local session key ID 57616
D: 107103 [SC]Waiting for PBKDF param request
D: 107108 [DL]CHIPoBLE advertising set to on
I: 107112 [DIS]Updating services using commissioning mode 1
D: 107117 [DL]Using Thread extended MAC for hostname.
D: 107122 [DL]Using Thread extended MAC for hostname.
I: 107128 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15
E: 107137 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 107143 [DIS]Scheduling discovery timeout in 900s
E: 107148 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 107159 [DL]CHIPoBLE advertising started
I: 107164 [DL]NFC Tag emulation started
I: 111973 [DL]BLE connection established (ConnId: 0x00)
I: 111979 [DL]Current number of connections: 1/1
I: 111983 [DL]CHIPoBLE advertising stopped
I: 111987 [DL]NFC Tag emulation stopped
D: 112922 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 112928 [BLE]local and remote recv window sizes = 5
I: 112933 [BLE]selected BTP version 4
I: 112936 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 113020 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 113024 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 113031 [IN]BLE EndPoint 0x2000fe10 Connection Complete
I: 113036 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 113118 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 113123 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 113129 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:212820841 on exchange 45216r
D: 113139 [EM]Handling via exchange: 45216r, Delegate: 0x20006918
D: 113145 [SC]Received PBKDF param request
D: 113149 [SC]Peer assigned session ID 6486
D: 113153 [SC]Found MRP parameters in the message
D: 113157 [SC]Including MRP parameters in PBKDF param response
I: 113164 [IN]Prepared unauthenticated message 0x2002bcb8 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 45216r with MessageCounter:3631968069.
I: 113179 [IN]Sending unauthenticated msg 0x2002bcb8 with MessageCounter:3631968069 to 0x0000000000000000 at monotonic time: 000000000001BA1A msec
D: 113191 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 140)
D: 113198 [SC]Sent PBKDF param response
D: 113263 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 113361 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 113367 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:212820842 on exchange 45216r
D: 113377 [EM]Found matching exchange: 45216r, Delegate: 0x20006918
D: 113383 [SC]Received spake2p msg1
I: 114840 [IN]Prepared unauthenticated message 0x2002bc48 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 45216r with MessageCounter:3631968070.
I: 114855 [IN]Sending unauthenticated msg 0x2002bc48 with MessageCounter:3631968070 to 0x0000000000000000 at monotonic time: 000000000001C0A7 msec
D: 114868 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 132)
D: 114875 [SC]Sent spake2p msg2
E: 114877 [DL]Long dispatch time: 1516 ms, for event type 16388
D: 114969 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 115116 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 115122 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:212820843 on exchange 45216r
D: 115132 [EM]Found matching exchange: 45216r, Delegate: 0x20006918
D: 115138 [SC]Received spake2p msg3
D: 115142 [SC]Sending status report. Protocol code 0, exchange 45216
I: 115148 [IN]Prepared unauthenticated message 0x2002bcd8 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 45216r with MessageCounter:3631968071.
I: 115163 [IN]Sending unauthenticated msg 0x2002bcd8 with MessageCounter:3631968071 to 0x0000000000000000 at monotonic time: 000000000001C1DB msec
D: 115176 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 35)
D: 115183 [IN]New secure session created for device <FFFFFFFB00000000, 0>, LSID:57616 PSID:6486!
I: 115192 [SVR]Commissioning completed session establishment step
I: 115198 [DIS]Updating services using commissioning mode 0
D: 115203 [DL]Using Thread extended MAC for hostname.
D: 115208 [DL]Using Thread extended MAC for hostname.
I: 115214 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15
E: 115223 [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
D: 115230 [DIS]Scheduling extended discovery timeout in 900s
E: 115236 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 115242 [DL]CHIPoBLE advertising set to off
I: 115249 [SVR]Device completed Rendezvous process
E: 115253 [DL]Long dispatch time: 137 ms, for event type 16388
D: 115263 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 115268 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 115275 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:5726648 on exchange 45217r
D: 115285 [EM]Handling via exchange: 45217r, Delegate: 0x2000dc04
D: 115291 [IM]Received Read request
D: 115296 [DMG]IM RH moving to [GeneratingReports]
D: 115301 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 115309 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 115314 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 115323 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 115328 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 115337 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 115342 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 115351 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 115356 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 115365 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 115370 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 115379 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 115384 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 115393 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 115398 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 115407 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 115413 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 115422 [DMG]<RE> Sending report (payload has 224 bytes)...
I: 115429 [IN]Prepared secure message 0x2002be80 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 45217r with MessageCounter:11415863.
I: 115443 [IN]Sending encrypted msg 0x2002be80 with MessageCounter:11415863 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C2F3 msec
D: 115455 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 115462 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 115466 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 115474 [DMG]IM RH moving to [AwaitingDestruction]
D: 115478 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 115652 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 115657 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
D: 115750 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 115756 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 115762 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726649 on exchange 45218r
D: 115772 [EM]Handling via exchange: 45218r, Delegate: 0x2000dc04
D: 115778 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
D: 115786 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 21f3d7dd
D: 115793 [DMG]ICR moving to [ Preparing]
D: 115797 [DMG]ICR moving to [AddingComm]
D: 115800 [DMG]ICR moving to [AddedComma]
D: 115804 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 115811 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45218r with MessageCounter:11415864.
I: 115825 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415864 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C471 msec
D: 115838 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 115844 [DMG]ICR moving to [CommandSen]
D: 115848 [DMG]ICR moving to [AwaitingDe]
D: 115896 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 115902 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 115908 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726650 on exchange 45219r
D: 115918 [EM]Handling via exchange: 45219r, Delegate: 0x2000dc04
D: 115924 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 115935 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 21f3d7de
D: 115941 [DMG]ICR moving to [ Preparing]
D: 115945 [DMG]ICR moving to [AddingComm]
D: 115949 [DMG]ICR moving to [AddedComma]
D: 115953 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 115960 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45219r with MessageCounter:11415865.
I: 115974 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415865 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C506 msec
D: 115986 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 115993 [DMG]ICR moving to [CommandSen]
D: 115997 [DMG]ICR moving to [AwaitingDe]
D: 116091 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116097 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 116103 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726651 on exchange 45220r
D: 116113 [EM]Handling via exchange: 45220r, Delegate: 0x2000dc04
D: 116119 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 116127 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 116133 [DMG]ICR moving to [ Preparing]
D: 116137 [DMG]ICR moving to [AddingComm]
D: 116140 [DMG]ICR moving to [AddedComma]
D: 116144 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 116154 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45220r with MessageCounter:11415866.
I: 116168 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415866 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C5C8 msec
D: 116180 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 116187 [DMG]ICR moving to [CommandSen]
D: 116191 [DMG]ICR moving to [AwaitingDe]
D: 116285 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116291 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 116383 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116388 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 48)
D: 116481 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116487 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 116493 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726652 on exchange 45221r
D: 116503 [EM]Handling via exchange: 45221r, Delegate: 0x2000dc04
D: 116509 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 116517 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 116523 [DMG]ICR moving to [ Preparing]
D: 116527 [DMG]ICR moving to [AddingComm]
D: 116530 [DMG]ICR moving to [AddedComma]
D: 116534 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 116544 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45221r with MessageCounter:11415867.
I: 116558 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415867 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C74E msec
D: 116570 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 116577 [DMG]ICR moving to [CommandSen]
D: 116581 [DMG]ICR moving to [AwaitingDe]
D: 116675 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116681 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 116773 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116778 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 76)
D: 116871 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 116877 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 116884 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726653 on exchange 45222r
D: 116894 [EM]Handling via exchange: 45222r, Delegate: 0x2000dc04
D: 116900 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 116907 [ZCL]OpCreds: received an AttestationRequest
D: 116942 [DMG]ICR moving to [ Preparing]
D: 116945 [DMG]ICR moving to [AddingComm]
D: 116949 [DMG]ICR moving to [AddedComma]
D: 116953 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 116964 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45222r with MessageCounter:11415868.
I: 116978 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415868 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001C8F2 msec
D: 116990 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 116997 [DMG]ICR moving to [CommandSen]
D: 117001 [DMG]ICR moving to [AwaitingDe]
E: 117004 [DL]Long dispatch time: 127 ms, for event type 16388
D: 117114 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 117120 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 117212 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 117217 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 237)
D: 117309 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 117606 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 117613 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726654 on exchange 45223r
D: 117623 [EM]Handling via exchange: 45223r, Delegate: 0x2000dc04
D: 117629 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 117637 [ZCL]OpCreds: commissioner has requested a CSR
I: 117913 [ZCL]OpCreds: NewCertificateSigningRequest returned 0
D: 117947 [DMG]ICR moving to [ Preparing]
D: 117951 [DMG]ICR moving to [AddingComm]
D: 117955 [DMG]ICR moving to [AddedComma]
D: 117959 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 117968 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45223r with MessageCounter:11415869.
I: 117981 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415869 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CCDD msec
D: 117994 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 118000 [DMG]ICR moving to [CommandSen]
D: 118004 [DMG]ICR moving to [AwaitingDe]
E: 118008 [DL]Long dispatch time: 402 ms, for event type 16388
D: 118055 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 118061 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 138)
D: 118145 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 118327 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 118416 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 118424 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726655 on exchange 45224r
D: 118434 [EM]Handling via exchange: 45224r, Delegate: 0x2000dc04
D: 118440 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 118448 [ZCL]OpCreds: commissioner has added a trusted root Cert
D: 118454 [DMG]ICR moving to [ Preparing]
D: 118457 [DMG]ICR moving to [AddingComm]
D: 118461 [DMG]ICR moving to [AddedComma]
D: 118465 [DMG]Endpoint 0, Cluster 0x0000_003E update version to ee8fb9c1
D: 118471 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 118479 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 45224r with MessageCounter:11415870.
I: 118493 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415870 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001CEDC msec
D: 118505 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
D: 118512 [DMG]ICR moving to [CommandSen]
D: 118515 [DMG]ICR moving to [AwaitingDe]
E: 118519 [DL]Long dispatch time: 103 ms, for event type 16388
D: 118597 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 118603 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 118686 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 118694 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726656 on exchange 45225r
D: 118704 [EM]Handling via exchange: 45225r, Delegate: 0x2000dc04
D: 118710 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 118718 [ZCL]OpCreds: Received AddNOC command
I: 118723 [DIS]Verifying the received credentials
I: 118783 [DIS]Added new fabric at index: 0x1, Initialized: 1
I: 118789 [DIS]Assigned compressed fabric ID: 0x3797F4780A8BC149, node ID: 0x0000000000000071
I: 118810 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I: 118817 [ZCL]OpCreds: Fabric  index 0x1 was persisted to storage. FabricId 0000000000000001, NodeId 0000000000000071, VendorId 0x0380
I: 118829 [ZCL]OpCreds: Call to fabricListChanged
D: 118833 [DMG]Endpoint 0, Cluster 0x0000_003E update version to ee8fb9c2
D: 118840 [DMG]Endpoint 0, Cluster 0x0000_003E update version to ee8fb9c3
D: 118946 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x000000000001D0A2
I: 118960 [ZCL]OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x000000000001B669
D: 118968 [DL]Using Thread extended MAC for hostname.
I: 118973 [DIS]Advertise operational node 3797F4780A8BC149-0000000000000071
D: 118980 [DMG]ICR moving to [ Preparing]
D: 118984 [DMG]ICR moving to [AddingComm]
D: 118987 [DMG]ICR moving to [AddedComma]
I: 118991 [ZCL]OpCreds: successfully created fabric index 1 via AddNOC
D: 118997 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 119005 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45225r with MessageCounter:11415871.
I: 119019 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415871 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001D0EA msec
D: 119031 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 119037 [DMG]ICR moving to [CommandSen]
D: 119041 [DMG]ICR moving to [AwaitingDe]
E: 119045 [DL]Long dispatch time: 359 ms, for event type 16388
D: 119092 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 119097 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 119104 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726657 on exchange 45226r
D: 119114 [EM]Handling via exchange: 45226r, Delegate: 0x2000dc04
D: 119120 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 119130 [DMG]ICR moving to [ Preparing]
D: 119133 [DMG]ICR moving to [AddingComm]
D: 119137 [DMG]ICR moving to [AddedComma]
D: 119141 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 119148 [IN]Prepared secure message 0x2002bd48 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45226r with MessageCounter:11415872.
I: 119162 [IN]Sending encrypted msg 0x2002bd48 with MessageCounter:11415872 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001D17A msec
D: 119175 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 119181 [DMG]ICR moving to [CommandSen]
D: 119185 [DMG]ICR moving to [AwaitingDe]
D: 119271 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 119277 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 119284 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5726658 on exchange 45227r
D: 119293 [EM]Handling via exchange: 45227r, Delegate: 0x2000dc04
D: 119300 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 119320 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 119327 [DL]OpenThread State Changed (Flags: 0x1006c100)
D: 119332 [DL]   Network Name: OpenThread
D: 119336 [DL]   PAN Id: 0x78E0
D: 119339 [DL]   Extended PAN Id: 0x1111111122222222
D: 119344 [DL]   Channel: 25
D: 119346 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 119351 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 119356 [DL]   Device Role: DETACHED
D: 119360 [DL]   Thread Unicast Addresses:
D: 119364 [DL]        fdde:ad00:beef:0:3d9f:ca4:16ce:1db3/64 valid
D: 119370 [DL]        fe80::e448:cdf4:c16b:c216/64 valid preferred
D: 120060 [DL]OpenThread State Changed (Flags: 0x00000100)
I: 120725 [DL]SRP Client was started, detected server: fd63:4474:e016:0000:1070:a3f1:7eef:eadb
D: 120895 [DL]OpenThread State Changed (Flags: 0x301332b7)
D: 120900 [DL]   Device Role: CHILD
D: 120903 [DL]   Network Name: eero-thread
D: 120907 [DL]   PAN Id: 0x78E0
D: 120910 [DL]   Extended PAN Id: 0xCD133347665770FE
D: 120915 [DL]   Channel: 25
D: 120917 [DL]   Mesh Prefix: fd63:4474:e016::/64
D: 120922 [DL]   Partition Id: 0x67FA55E
D: 120925 [DL]   Thread Unicast Addresses:
D: 120929 [DL]        fd62:1d09:d2a:1:8ac2:49d5:43cd:9156/64 valid preferred
D: 120936 [DL]        fd63:4474:e016::ff:fe00:240e/64 valid rloc
D: 120942 [DL]        fd63:4474:e016:0:3d9f:ca4:16ce:1db3/64 valid
D: 120947 [DL]        fe80::e448:cdf4:c16b:c216/64 valid preferred
D: 120957 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 120963 [DL]   Thread Unicast Addresses:
D: 120967 [DL]        fd62:1d09:d2a:1:8ac2:49d5:43cd:9156/64 valid preferred
D: 120974 [DL]        fd63:4474:e016::ff:fe00:240e/64 valid rloc
D: 120980 [DL]        fd63:4474:e016:0:3d9f:ca4:16ce:1db3/64 valid
D: 120985 [DL]        fe80::e448:cdf4:c16b:c216/64 valid preferred
D: 120996 [DL]Using Thread extended MAC for hostname.
I: 121001 [DIS]Advertise operational node 3797F4780A8BC149-0000000000000071
I: 121008 [SVR]Operational advertising enabled
D: 121013 [DMG]ICR moving to [ Preparing]
D: 121017 [DMG]ICR moving to [AddingComm]
D: 121021 [DMG]ICR moving to [AddedComma]
D: 121025 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 121034 [IN]Prepared secure message 0x2002bf28 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 45227r with MessageCounter:11415873.
I: 121048 [IN]Sending encrypted msg 0x2002bf28 with MessageCounter:11415873 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001D8D8 msec
D: 121062 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 70)
D: 121069 [DMG]ICR moving to [CommandSen]
D: 121073 [DMG]ICR moving to [AwaitingDe]
E: 121100 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 121115 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
E: 122811 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 123636 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
E: 125905 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 126143 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 126201 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 128721 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
E: 131135 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 131228 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 131286 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 133806 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 136312 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 136371 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 138891 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
E: 139997 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 141397 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 141501 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 144021 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 146527 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 146586 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 149151 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 151657 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 151761 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 154237 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
E: 155059 [DL]OnSrpClientNotification: Operation refused for security reasons
D: 156742 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 156801 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 159322 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 161828 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 161886 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 164407 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 166913 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 167016 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 169492 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 171998 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 172056 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 174577 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
E: 175787 [SVR]Failsafe timer expired
E: 175790 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032
D: 175796 [IN]Clearing BLE pending packets.
I: 175800 [BLE]Releasing end point's BLE connection back to application.
I: 175806 [DL]Closing BLE GATT connection (ConnId 00)
D: 175814 [SC]Assigned local session key ID 57617
D: 175819 [SC]Waiting for PBKDF param request
D: 175823 [DL]CHIPoBLE advertising set to on
I: 175827 [DIS]Updating services using commissioning mode 1
D: 175832 [DL]Using Thread extended MAC for hostname.
D: 175837 [DL]Using Thread extended MAC for hostname.
I: 175842 [DIS]Advertise operational node 3797F4780A8BC149-0000000000000071
E: 175849 [DIS]Failed to advertise operational node: Error CHIP:0x00000003
D: 175855 [DL]Using Thread extended MAC for hostname.
I: 175861 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15
E: 175870 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
E: 175877 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 175883 [ZCL]OpCreds: Call to FailSafeCleanup
D: 175887 [IN]Expiring all connections for fabric 1!!
I: 175897 [DIS]Fabric (0x1) deleted. Calling OnFabricDeletedFromStorage
I: 175912 [ZCL]OpCreds: Fabric index 0x1 was deleted from fabric storage.
I: 175918 [ZCL]OpCreds: Call to fabricListChanged
D: 175923 [DMG]Endpoint 0, Cluster 0x0000_003E update version to ee8fb9c4
D: 175929 [DMG]Endpoint 0, Cluster 0x0000_003E update version to ee8fb9c5
D: 175936 [EVL]LogEvent event number: 0x0000000000000003 priority: 1, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x2 Sys timestamp: 0x000000000002AF40
D: 175950 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 175958 [DIS]Updating services using commissioning mode 1
D: 175963 [DL]Using Thread extended MAC for hostname.
D: 175968 [DL]Using Thread extended MAC for hostname.
I: 175974 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15
E: 175982 [DIS]Failed to advertise commissionable node: Error CHIP:0x00000003
D: 175989 [DIS]Scheduling discovery timeout in 900s
E: 175994 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 176000 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 21f3d7df
D: 176007 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 176020 [DL]Long dispatch time: 234 ms, for event type 32785
D: 176027 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 176032 [DL]   Device Role: DISABLED
D: 176036 [DL]   Thread Unicast Addresses:
D: 176040 [DL]        fd62:1d09:d2a:1:8ac2:49d5:43cd:9156/64 valid preferred
D: 176049 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 176055 [DL]BLE GAP connection terminated (reason 0x16)
I: 176060 [DL]Current number of connections: 0/1
I: 176068 [DL]CHIPoBLE advertising started
I: 176073 [DL]NFC Tag emulation started

[Charlie]

Hi Dan,

I am working on your case now and will give you some feedback soon.

Best regards,

Charlie 

[Charlie]

Hi Dan,

"E: 121100 [DL]OnSrpClientNotification: Operation refused for security reasons" error messages in the device logs mean that OTBR refuses to register DNS-SD services on behalf of the device. It is worth using the newest OTBR revision to rule out numerous SRP bugs that have been fixed in the past. Are you able to test with RPI-based OTBR? It is not clear to us how EERO6 works as an OTBR.

Another (more probable) reason may be that you are trying to use an already-reserved nodeID to commission the device. A typical mistake is the following scenario:

1) Developer commissions device using node ID 1

2) Developer factory resets the device

3) Developer tries to commission the same device using node ID=1.

In such a case, OTBR won't allow to register the same service again because it thinks it's already reserved. Resetting OTBR can be a workaround.

Best regards,

Charlie

[Dan]

Thanks Charlie - resetting the OTBR/EERO6 worked!