Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

For on network provisioning chip-tool is not calling the PersistDeviceList #9550

Closed
cjandhyala opened this issue Sep 8, 2021 · 19 comments
Closed
Assignees
Milestone

Comments

@cjandhyala
Copy link
Contributor

When chip tool is used with on network provisioning, its not calling the PersistDeviceList . So after pairing is complete, Device can not be controlled, since it fails retrieving the PariedDeviceList from the storage.

@cjandhyala
Copy link
Contributor Author

@pan-apple @cecille

@cecille cecille self-assigned this Sep 9, 2021
@franck-apple franck-apple added this to the Test Event 6 milestone Sep 9, 2021
@cecille
Copy link
Contributor

cecille commented Sep 16, 2021

Can you provide more details about the commands you are running? I'm having trouble reproducing this.

@cecille
Copy link
Contributor

cecille commented Sep 16, 2021

I'm attaching logs from my system. Controller side:

cecille@cecille-z2:~/chip/connectedhomeip/out/debug/standalone$ ./chip-tool pairing onnetwork 0 20202021 3840 fc00::a 5540
[1631806823.040014][1364087:1364087] CHIP:CTL: Read local id 0x000000000001B669, remote id 0xA70B41F97BCC2335
[1631806823.043102][1364087:1364087] CHIP:CTL: Generating NOC
[1631806823.043386][1364087:1364087] CHIP:CTL: Generating ICAC
[1631806823.049351][1364087:1364087] CHIP:IN: UDP::Init bind&listen port=5541
[1631806823.049445][1364087:1364087] CHIP:IN: UDP::Init bound to port=5541
[1631806823.049466][1364087:1364087] CHIP:IN: UDP::Init bind&listen port=5541
[1631806823.049522][1364087:1364087] CHIP:IN: UDP::Init bound to port=5541
[1631806823.049542][1364087:1364087] CHIP:IN: TransportMgr initialized
[1631806823.049555][1364087:1364087] CHIP:DIS: Init fabric pairing table with server storage
[1631806823.051915][1364087:1364087] CHIP:DL: MDNS failed to join multicast group on heth0 for address type IPv4: ../../src/inet/IPEndPointBasis.cpp:259: Inet Error 0x00000110: Address not found
[1631806823.051992][1364087:1364087] CHIP:ZCL: Using ZAP configuration...
[1631806823.052037][1364087:1364087] CHIP:ZCL: deactivate report event
[1631806823.052464][1364087:1364087] CHIP:DIS: Verifying the received credentials
[1631806823.053565][1364087:1364087] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1631806823.053588][1364087:1364087] CHIP:DIS: Assigned compressed fabric ID: 0x7F0FEE1620293FEA, node ID: 0x000000000001B669
[1631806823.053599][1364087:1364087] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x7F0FEE1620293FEA
[1631806823.053785][1364087:1364092] CHIP:DL: CHIP task running
[1631806823.053918][1364087:1364092] CHIP:CTL: Generated random node id: 0x989C34B92E9435E5
[1631806823.054368][1364087:1364092] CHIP:SC: Assigned local session key ID 5
[1631806823.054421][1364087:1364092] CHIP:IN: Build plaintext message 0x5623290f5d98 to 0x0000000000000000 of type 32 and protocolId 0 on exchange 19670 with MessageCounter 448395102.
[1631806823.054443][1364087:1364092] CHIP:IN: Sending plaintext msg 0x5623290f5d98 to 0x0000000000000000 at utc time: 2026543551 msec
[1631806823.054456][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.054558][1364087:1364092] CHIP:SC: Sent PBKDF param request
[1631806823.061921][1364087:1364092] CHIP:EM: Received message of type 0x21 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.061948][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:1AB9F75E from Retrans Table
[1631806823.061957][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:1AB9F75E from RetransTable
[1631806823.061969][1364087:1364092] CHIP:SC: Received PBKDF param response
[1631806823.061985][1364087:1364092] CHIP:SC: Peer assigned session ID 0
[1631806823.062609][1364087:1364092] CHIP:EM: Piggybacking Ack for MessageCounter:D5383B17 with msg
[1631806823.062626][1364087:1364092] CHIP:IN: Build plaintext message 0x5623290f5d98 to 0x0000000000000000 of type 34 and protocolId 0 on exchange 19670 with MessageCounter 448395103.
[1631806823.062638][1364087:1364092] CHIP:IN: Sending plaintext msg 0x5623290f5d98 to 0x0000000000000000 at utc time: 2026543559 msec
[1631806823.062646][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.062704][1364087:1364092] CHIP:SC: Sent spake2p msg1
[1631806823.063619][1364087:1364092] CHIP:EM: Received message of type 0x23 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.063646][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:1AB9F75F from Retrans Table
[1631806823.063657][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:1AB9F75F from RetransTable
[1631806823.063670][1364087:1364092] CHIP:SC: Received spake2p msg2
[1631806823.064181][1364087:1364092] CHIP:EM: Piggybacking Ack for MessageCounter:D5383B18 with msg
[1631806823.064201][1364087:1364092] CHIP:IN: Build plaintext message 0x5623290f5d98 to 0x0000000000000000 of type 36 and protocolId 0 on exchange 19670 with MessageCounter 448395104.
[1631806823.064215][1364087:1364092] CHIP:IN: Sending plaintext msg 0x5623290f5d98 to 0x0000000000000000 at utc time: 2026543561 msec
[1631806823.064225][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.064280][1364087:1364092] CHIP:SC: Sent spake2p msg3
[1631806823.064592][1364087:1364092] CHIP:EM: Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.064619][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:1AB9F760 from Retrans Table
[1631806823.064629][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:1AB9F760 from RetransTable
[1631806823.064645][1364087:1364092] CHIP:IN: New secure session created for device 0x989C34B92E9435E5, key 0!!
[1631806823.064674][1364087:1364092] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1631806823.064684][1364087:1364092] CHIP:CTL: Sending OpCSR request to 0x7ffcae15cf80 device
[1631806823.064708][1364087:1364092] CHIP:DMG: ICR moving to [Initialize]
[1631806823.064721][1364087:1364092] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.064765][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 0
[1631806823.064777][1364087:1364092] CHIP:IN: Build encrypted message 0x5623290f5d98 to 0x989C34B92E9435E5 of type 8 and protocolId 5 on exchange 19671 with MessageCounter 0.
[1631806823.064789][1364087:1364092] CHIP:IN: Sending encrypted msg 0x5623290f5d98 to 0x989C34B92E9435E5 at utc time: 2026543561 msec
[1631806823.064799][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.064850][1364087:1364092] CHIP:DMG: ICR moving to [   Sending]
[1631806823.064862][1364087:1364092] CHIP:CTL: Sent OpCSR request, waiting for the CSR
[1631806823.064871][1364087:1364092] CHIP:EM: Sending Standalone Ack for MessageCounter:D5383B19
[1631806823.064884][1364087:1364092] CHIP:IN: Build plaintext message 0x7ff8e2ffbcc8 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 19670 with MessageCounter 448395105.
[1631806823.064897][1364087:1364092] CHIP:IN: Sending plaintext msg 0x7ff8e2ffbcc8 to 0x0000000000000000 at utc time: 2026543561 msec
[1631806823.064906][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.064938][1364087:1364092] CHIP:EM: Flushed pending ack for MessageCounter:D5383B19
[1631806823.067552][1364087:1364092] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0005 on exchange 19671
[1631806823.067580][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table
[1631806823.067592][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable
[1631806823.067609][1364087:1364092] CHIP:DMG: InvokeCommand =
[1631806823.067620][1364087:1364092] CHIP:DMG: {
[1631806823.067629][1364087:1364092] CHIP:DMG: 	CommandList =
[1631806823.067640][1364087:1364092] CHIP:DMG: 	[
[1631806823.067649][1364087:1364092] CHIP:DMG: 		CommandDataElement =
[1631806823.067660][1364087:1364092] CHIP:DMG: 		{
[1631806823.067670][1364087:1364092] CHIP:DMG: 			CommandPath =
[1631806823.067681][1364087:1364092] CHIP:DMG: 			{
[1631806823.067691][1364087:1364092] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.067703][1364087:1364092] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.067713][1364087:1364092] CHIP:DMG: 				CommandId = 0x5,
[1631806823.067723][1364087:1364092] CHIP:DMG: 			},
[1631806823.067750][1364087:1364092] CHIP:DMG: 			
[1631806823.067764][1364087:1364092] CHIP:DMG: 			CommandData = 
[1631806823.067775][1364087:1364092] CHIP:DMG: 			{
[1631806823.067785][1364087:1364092] CHIP:DMG: 				0x0 = [
[1631806823.067803][1364087:1364092] CHIP:DMG: 					0x15, 0x30, 0x1, 0xca, 0x30, 0x81, 0xc7, 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,
[1631806823.067816][1364087:1364092] CHIP:DMG: 			]
[1631806823.067826][1364087:1364092] CHIP:DMG: 				0x1 = [
[1631806823.067835][1364087:1364092] CHIP:DMG: 					
[1631806823.067844][1364087:1364092] CHIP:DMG: 			]
[1631806823.067854][1364087:1364092] CHIP:DMG: 			},
[1631806823.067863][1364087:1364092] CHIP:DMG: 		},
[1631806823.067876][1364087:1364092] CHIP:DMG: 		
[1631806823.067885][1364087:1364092] CHIP:DMG: 	],
[1631806823.067897][1364087:1364092] CHIP:DMG: 	
[1631806823.067905][1364087:1364092] CHIP:DMG: }
[1631806823.067924][1364087:1364092] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=5 Endpoint=0
[1631806823.067936][1364087:1364092] CHIP:ZCL: OpCSRResponse:
[1631806823.067944][1364087:1364092] CHIP:ZCL:   NOCSRElements: 251
[1631806823.067952][1364087:1364092] CHIP:ZCL:   AttestationSignature: 0
[1631806823.067961][1364087:1364092] CHIP:CTL: Received certificate signing request from the device
[1631806823.067970][1364087:1364092] CHIP:CTL: Getting certificate chain for the device from the issuer
[1631806823.067979][1364087:1364092] CHIP:CTL: Verifying Certificate Signing Request
[1631806823.068361][1364087:1364092] CHIP:CTL: Generating NOC
[1631806823.068488][1364087:1364092] CHIP:CTL: Generating ICAC
[1631806823.068615][1364087:1364092] CHIP:CTL: Providing certificate chain to the commissioner
[1631806823.068628][1364087:1364092] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:182: Success
[1631806823.068681][1364087:1364092] CHIP:CTL: Sending root certificate to the device
[1631806823.068697][1364087:1364092] CHIP:DMG: ICR moving to [Initialize]
[1631806823.068709][1364087:1364092] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.068738][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 1
[1631806823.068749][1364087:1364092] CHIP:IN: Build encrypted message 0x5623290f5d98 to 0x989C34B92E9435E5 of type 8 and protocolId 5 on exchange 19672 with MessageCounter 1.
[1631806823.068762][1364087:1364092] CHIP:IN: Sending encrypted msg 0x5623290f5d98 to 0x989C34B92E9435E5 at utc time: 2026543565 msec
[1631806823.068772][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.068827][1364087:1364092] CHIP:DMG: ICR moving to [   Sending]
[1631806823.068838][1364087:1364092] CHIP:CTL: Sent root certificate to the device
[1631806823.068919][1364087:1364092] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.068930][1364087:1364092] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001
[1631806823.068949][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 2
[1631806823.068958][1364087:1364092] CHIP:IN: Build encrypted message 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 of type 16 and protocolId 0 on exchange 19671 with MessageCounter 2.
[1631806823.068970][1364087:1364092] CHIP:IN: Sending encrypted msg 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 at utc time: 2026543565 msec
[1631806823.068980][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.069017][1364087:1364092] CHIP:EM: Flushed pending ack for MessageCounter:00000001
[1631806823.069429][1364087:1364092] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0005 on exchange 19672
[1631806823.069455][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:00000001 from Retrans Table
[1631806823.069465][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:00000001 from RetransTable
[1631806823.069480][1364087:1364092] CHIP:DMG: InvokeCommand =
[1631806823.069490][1364087:1364092] CHIP:DMG: {
[1631806823.069498][1364087:1364092] CHIP:DMG: 	CommandList =
[1631806823.069508][1364087:1364092] CHIP:DMG: 	[
[1631806823.069517][1364087:1364092] CHIP:DMG: 		CommandDataElement =
[1631806823.069526][1364087:1364092] CHIP:DMG: 		{
[1631806823.069535][1364087:1364092] CHIP:DMG: 			CommandPath =
[1631806823.069545][1364087:1364092] CHIP:DMG: 			{
[1631806823.069557][1364087:1364092] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.069581][1364087:1364092] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.069597][1364087:1364092] CHIP:DMG: 				CommandId = 0xb,
[1631806823.069609][1364087:1364092] CHIP:DMG: 			},
[1631806823.069622][1364087:1364092] CHIP:DMG: 			
[1631806823.069631][1364087:1364092] CHIP:DMG: 			StatusElement =
[1631806823.069642][1364087:1364092] CHIP:DMG: 			{
[1631806823.069658][1364087:1364092] CHIP:DMG: 				GeneralCode = 0x0,
[1631806823.069672][1364087:1364092] CHIP:DMG: 				ProtocolId = 0x5,
[1631806823.069682][1364087:1364092] CHIP:DMG: 				protocolCode = 0x0,
[1631806823.069691][1364087:1364092] CHIP:DMG: 			},
[1631806823.069701][1364087:1364092] CHIP:DMG: 			
[1631806823.069710][1364087:1364092] CHIP:DMG: 		},
[1631806823.069722][1364087:1364092] CHIP:DMG: 		
[1631806823.069730][1364087:1364092] CHIP:DMG: 	],
[1631806823.069742][1364087:1364092] CHIP:DMG: 	
[1631806823.069751][1364087:1364092] CHIP:DMG: }
[1631806823.069770][1364087:1364092] CHIP:ZCL: DefaultResponse:
[1631806823.069778][1364087:1364092] CHIP:ZCL:   Transaction: 0x56232723f738
[1631806823.069786][1364087:1364092] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)
[1631806823.069796][1364087:1364092] CHIP:CTL: Device confirmed that it has received the root certificate
[1631806823.069805][1364087:1364092] CHIP:CTL: Sending operational certificate chain to the device
[1631806823.069817][1364087:1364092] CHIP:DMG: ICR moving to [Initialize]
[1631806823.069830][1364087:1364092] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.069859][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 3
[1631806823.069869][1364087:1364092] CHIP:IN: Build encrypted message 0x5623290f5d98 to 0x989C34B92E9435E5 of type 8 and protocolId 5 on exchange 19673 with MessageCounter 3.
[1631806823.069882][1364087:1364092] CHIP:IN: Sending encrypted msg 0x5623290f5d98 to 0x989C34B92E9435E5 at utc time: 2026543566 msec
[1631806823.069892][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.069946][1364087:1364092] CHIP:DMG: ICR moving to [   Sending]
[1631806823.069957][1364087:1364092] CHIP:CTL: Sent operational certificate to the device
[1631806823.069970][1364087:1364092] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.069979][1364087:1364092] CHIP:EM: Sending Standalone Ack for MessageCounter:00000002
[1631806823.069996][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 4
[1631806823.070004][1364087:1364092] CHIP:IN: Build encrypted message 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 of type 16 and protocolId 0 on exchange 19672 with MessageCounter 4.
[1631806823.070016][1364087:1364092] CHIP:IN: Sending encrypted msg 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 at utc time: 2026543566 msec
[1631806823.070025][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.070059][1364087:1364092] CHIP:EM: Flushed pending ack for MessageCounter:00000002
[1631806823.072859][1364087:1364092] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0005 on exchange 19673
[1631806823.072885][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:00000003 from Retrans Table
[1631806823.072895][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:00000003 from RetransTable
[1631806823.072910][1364087:1364092] CHIP:DMG: InvokeCommand =
[1631806823.072921][1364087:1364092] CHIP:DMG: {
[1631806823.072930][1364087:1364092] CHIP:DMG: 	CommandList =
[1631806823.072940][1364087:1364092] CHIP:DMG: 	[
[1631806823.072949][1364087:1364092] CHIP:DMG: 		CommandDataElement =
[1631806823.072960][1364087:1364092] CHIP:DMG: 		{
[1631806823.072969][1364087:1364092] CHIP:DMG: 			CommandPath =
[1631806823.072980][1364087:1364092] CHIP:DMG: 			{
[1631806823.072990][1364087:1364092] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.073001][1364087:1364092] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.073012][1364087:1364092] CHIP:DMG: 				CommandId = 0x8,
[1631806823.073022][1364087:1364092] CHIP:DMG: 			},
[1631806823.073034][1364087:1364092] CHIP:DMG: 			
[1631806823.073043][1364087:1364092] CHIP:DMG: 			CommandData = 
[1631806823.073054][1364087:1364092] CHIP:DMG: 			{
[1631806823.073065][1364087:1364092] CHIP:DMG: 				0x0 = 0, 
[1631806823.073076][1364087:1364092] CHIP:DMG: 				0x1 = 1, 
[1631806823.073086][1364087:1364092] CHIP:DMG: 				0x2 = [
[1631806823.073096][1364087:1364092] CHIP:DMG: 					
[1631806823.073107][1364087:1364092] CHIP:DMG: 			]
[1631806823.073117][1364087:1364092] CHIP:DMG: 			},
[1631806823.073126][1364087:1364092] CHIP:DMG: 		},
[1631806823.073140][1364087:1364092] CHIP:DMG: 		
[1631806823.073149][1364087:1364092] CHIP:DMG: 	],
[1631806823.073162][1364087:1364092] CHIP:DMG: 	
[1631806823.073171][1364087:1364092] CHIP:DMG: }
[1631806823.073194][1364087:1364092] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=8 Endpoint=0
[1631806823.073207][1364087:1364092] CHIP:ZCL: NOCResponse:
[1631806823.073216][1364087:1364092] CHIP:ZCL:   StatusCode: 0
[1631806823.073225][1364087:1364092] CHIP:ZCL:   FabricIndex: 1
[1631806823.073233][1364087:1364092] CHIP:ZCL:   DebugText: 0
[1631806823.073243][1364087:1364092] CHIP:CTL: Device returned status 0 on receiving the NOC
[1631806823.073252][1364087:1364092] CHIP:CTL: Operational credentials provisioned on device 0x7ffcae15cf80
[1631806823.073714][1364087:1364092] CHIP:TOO: Secure Pairing Success
[1631806823.074102][1364087:1364092] CHIP:TOO: Pairing Success
[1631806823.074118][1364087:1364092] CHIP:TOO: Mdns: Updating NodeId: 989c34b92e9435e5 Compressed FabricId: 7f0fee1620293fea ...
[1631806823.074228][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074308][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074366][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074413][1364087:1364092] CHIP:DIS: Attempt to mDNS broadcast failed:  OS Error 0x02000065: Network is unreachable
[1631806823.074469][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074528][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074581][1364087:1364092] CHIP:DIS: mDNS broadcast success
[1631806823.074600][1364087:1364092] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.074611][1364087:1364092] CHIP:EM: Sending Standalone Ack for MessageCounter:00000003
[1631806823.074634][1364087:1364092] CHIP:IN: Secure message was encrypted: Msg ID 5
[1631806823.074643][1364087:1364092] CHIP:IN: Build encrypted message 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 of type 16 and protocolId 0 on exchange 19673 with MessageCounter 5.
[1631806823.074657][1364087:1364092] CHIP:IN: Sending encrypted msg 0x7ff8e2ffbb68 to 0x989C34B92E9435E5 at utc time: 2026543571 msec
[1631806823.074667][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.074705][1364087:1364092] CHIP:EM: Flushed pending ack for MessageCounter:00000003
[1631806823.074958][1364087:1364092] CHIP:DIS: Node ID resolved for 0x989C34B92E9435E5 to [fe80::a4bf:e6ff:fe00:543e]:5540
[1631806823.075005][1364087:1364092] CHIP:IN: Marking old secure session for device 0x989C34B92E9435E5 as expired
[1631806823.075017][1364087:1364092] CHIP:CTL: OnConnectionExpired was called for unknown device, ignoring it.
[1631806823.075031][1364087:1364092] CHIP:IN: New secure session created for device 0x989C34B92E9435E5, key 0!!
[1631806823.075321][1364087:1364092] CHIP:TOO: OnAddressUpdateComplete: 989c34b92e9435e5: ../../src/controller/CHIPDevice.cpp:445: Success
[1631806823.075337][1364087:1364092] CHIP:CTL: OperationalDiscoveryComplete for device ID 10996722360086967781
[1631806823.075350][1364087:1364092] CHIP:CTL: Enabling CASE session establishment for the device
[1631806823.075588][1364087:1364092] CHIP:IN: Marking old secure session for device 0x989C34B92E9435E5 as expired
[1631806823.076274][1364087:1364092] CHIP:IN: Build plaintext message 0x5623290f5d98 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 19674 with MessageCounter 3195912063.
[1631806823.076296][1364087:1364092] CHIP:IN: Sending plaintext msg 0x5623290f5d98 to 0x0000000000000000 at utc time: 2026543573 msec
[1631806823.076309][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.076370][1364087:1364092] CHIP:SC: Sent SigmaR1 msg
[1631806823.076414][1364087:1364092] CHIP:DIS: Node ID resolved for 0x989C34B92E9435E5 to [fe80::a4bf:e6ff:fe00:543e]:5540
[1631806823.076659][1364087:1364092] CHIP:TOO: OnAddressUpdateComplete: 989c34b92e9435e5: ../../src/controller/CHIPDevice.cpp:439: Success
[1631806823.076672][1364087:1364092] CHIP:CTL: OperationalDiscoveryComplete for device ID 10996722360086967781
[1631806823.076685][1364087:1364092] CHIP:CTL: Operational certificates already provisioned for this device
[1631806823.077119][1364087:1364092] CHIP:DIS: Node ID resolved for 0x989C34B92E9435E5 to [fe80::a4bf:e6ff:fe00:543e]:5540
[1631806823.077340][1364087:1364092] CHIP:TOO: OnAddressUpdateComplete: 989c34b92e9435e5: ../../src/controller/CHIPDevice.cpp:439: Success
[1631806823.077354][1364087:1364092] CHIP:CTL: OperationalDiscoveryComplete for device ID 10996722360086967781
[1631806823.077363][1364087:1364092] CHIP:CTL: Operational certificates already provisioned for this device
[1631806823.077769][1364087:1364092] CHIP:DIS: Node ID resolved for 0x989C34B92E9435E5 to [fe80::a4bf:e6ff:fe00:543e]:5540
[1631806823.077984][1364087:1364092] CHIP:TOO: OnAddressUpdateComplete: 989c34b92e9435e5: ../../src/controller/CHIPDevice.cpp:439: Success
[1631806823.077998][1364087:1364092] CHIP:CTL: OperationalDiscoveryComplete for device ID 10996722360086967781
[1631806823.078011][1364087:1364092] CHIP:CTL: Operational certificates already provisioned for this device
[1631806823.078426][1364087:1364092] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 19674
[1631806823.078447][1364087:1364092] CHIP:EM: Rxd Ack; Removing MessageCounter:BE7DBF7F from Retrans Table
[1631806823.078456][1364087:1364092] CHIP:EM: Removed CHIP MessageCounter:BE7DBF7F from RetransTable
[1631806823.078470][1364087:1364092] CHIP:SC: Received SigmaR2 msg
[1631806823.078482][1364087:1364092] CHIP:SC: Peer assigned session key ID 1
[1631806823.079852][1364087:1364092] CHIP:SC: Sending SigmaR3
[1631806823.079996][1364087:1364092] CHIP:EM: Piggybacking Ack for MessageCounter:705E38BC with msg
[1631806823.080015][1364087:1364092] CHIP:IN: Build plaintext message 0x5623290f5d98 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 19674 with MessageCounter 3195912064.
[1631806823.080028][1364087:1364092] CHIP:IN: Sending plaintext msg 0x5623290f5d98 to 0x0000000000000000 at utc time: 2026543576 msec
[1631806823.080038][1364087:1364092] CHIP:IN: Sending msg on generic transport
[1631806823.080090][1364087:1364092] CHIP:SC: Sent SigmaR3 msg
[1631806823.080102][1364087:1364092] CHIP:IN: New secure session created for device 0x989C34B92E9435E5, key 1!!
[1631806823.080129][1364087:1364092] CHIP:TOO: Device commissioning completed with success
[1631806823.080251][1364087:1364087] CHIP:CTL: Shutting down the commissioner
[1631806823.080274][1364087:1364087] CHIP:CTL: Shutting down the controller
[1631806823.080793][1364087:1364087] CHIP:DL: Inet Layer shutdown
[1631806823.080829][1364087:1364087] CHIP:DL: BLE layer shutdown
[1631806823.080842][1364087:1364087] CHIP:DL: System Layer shutdown
cecille@cecille-z2:~/chip/connectedhomeip/out/debug/standalone$ ./chip-tool onoff on 1
[1631806890.128268][1364447:1364447] CHIP:CTL: Read local id 0x000000000001B669, remote id 0x989C34B92E9435E5
[1631806890.131320][1364447:1364447] CHIP:CTL: Generating NOC
[1631806890.131604][1364447:1364447] CHIP:CTL: Generating ICAC
[1631806890.137319][1364447:1364447] CHIP:IN: UDP::Init bind&listen port=5541
[1631806890.137414][1364447:1364447] CHIP:IN: UDP::Init bound to port=5541
[1631806890.137436][1364447:1364447] CHIP:IN: UDP::Init bind&listen port=5541
[1631806890.137495][1364447:1364447] CHIP:IN: UDP::Init bound to port=5541
[1631806890.137512][1364447:1364447] CHIP:IN: TransportMgr initialized
[1631806890.137531][1364447:1364447] CHIP:DIS: Init fabric pairing table with server storage
[1631806890.140013][1364447:1364447] CHIP:DL: MDNS failed to join multicast group on heth0 for address type IPv4: ../../src/inet/IPEndPointBasis.cpp:259: Inet Error 0x00000110: Address not found
[1631806890.140118][1364447:1364447] CHIP:ZCL: Using ZAP configuration...
[1631806890.140181][1364447:1364447] CHIP:ZCL: deactivate report event
[1631806890.140743][1364447:1364447] CHIP:DIS: Verifying the received credentials
[1631806890.142266][1364447:1364447] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1631806890.142295][1364447:1364447] CHIP:DIS: Assigned compressed fabric ID: 0x7F0FEE1620293FEA, node ID: 0x000000000001B669
[1631806890.142311][1364447:1364447] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x7F0FEE1620293FEA
[1631806890.143089][1364447:1364452] CHIP:DL: CHIP task running
[1631806890.143802][1364447:1364452] CHIP:IN: Build plaintext message 0x55eb1b4b5f58 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 2797 with MessageCounter 2025080255.
[1631806890.143847][1364447:1364452] CHIP:IN: Sending plaintext msg 0x55eb1b4b5f58 to 0x0000000000000000 at utc time: 2026610640 msec
[1631806890.143864][1364447:1364452] CHIP:IN: Sending msg on generic transport
[1631806890.144016][1364447:1364452] CHIP:SC: Sent SigmaR1 msg
[1631806890.145985][1364447:1364452] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 2797
[1631806890.146038][1364447:1364452] CHIP:EM: Rxd Ack; Removing MessageCounter:78B445BF from Retrans Table
[1631806890.146058][1364447:1364452] CHIP:EM: Removed CHIP MessageCounter:78B445BF from RetransTable
[1631806890.146084][1364447:1364452] CHIP:SC: Received SigmaR2 msg
[1631806890.146108][1364447:1364452] CHIP:SC: Peer assigned session key ID 2
[1631806890.148703][1364447:1364452] CHIP:SC: Sending SigmaR3
[1631806890.148976][1364447:1364452] CHIP:EM: Piggybacking Ack for MessageCounter:705E38BE with msg
[1631806890.149014][1364447:1364452] CHIP:IN: Build plaintext message 0x55eb1b4b5f58 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 2797 with MessageCounter 2025080256.
[1631806890.149037][1364447:1364452] CHIP:IN: Sending plaintext msg 0x55eb1b4b5f58 to 0x0000000000000000 at utc time: 2026610645 msec
[1631806890.149056][1364447:1364452] CHIP:IN: Sending msg on generic transport
[1631806890.149179][1364447:1364452] CHIP:SC: Sent SigmaR3 msg
[1631806890.149215][1364447:1364452] CHIP:IN: New secure session created for device 0x989C34B92E9435E5, key 2!!
[1631806890.149291][1364447:1364452] CHIP:TOO: Sending cluster (0x0006) command (0x01) on endpoint 1
[1631806890.149346][1364447:1364452] CHIP:DMG: ICR moving to [Initialize]
[1631806890.149367][1364447:1364452] CHIP:DMG: ICR moving to [AddCommand]
[1631806890.149423][1364447:1364452] CHIP:IN: Secure message was encrypted: Msg ID 0
[1631806890.149442][1364447:1364452] CHIP:IN: Build encrypted message 0x55eb1b4b5f70 to 0x989C34B92E9435E5 of type 8 and protocolId 5 on exchange 2798 with MessageCounter 0.
[1631806890.149463][1364447:1364452] CHIP:IN: Sending encrypted msg 0x55eb1b4b5f70 to 0x989C34B92E9435E5 at utc time: 2026610646 msec
[1631806890.149478][1364447:1364452] CHIP:IN: Sending msg on generic transport
[1631806890.149554][1364447:1364452] CHIP:DMG: ICR moving to [   Sending]
[1631806890.152084][1364447:1364452] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 2797
[1631806890.152134][1364447:1364452] CHIP:EM: Rxd Ack; Removing MessageCounter:78B445C0 from Retrans Table
[1631806890.152152][1364447:1364452] CHIP:EM: Removed CHIP MessageCounter:78B445C0 from RetransTable
[1631806890.152992][1364447:1364452] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0005 on exchange 2798
[1631806890.153044][1364447:1364452] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table
[1631806890.153060][1364447:1364452] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable
[1631806890.153096][1364447:1364452] CHIP:DMG: InvokeCommand =
[1631806890.153116][1364447:1364452] CHIP:DMG: {
[1631806890.153133][1364447:1364452] CHIP:DMG: 	CommandList =
[1631806890.153172][1364447:1364452] CHIP:DMG: 	[
[1631806890.153194][1364447:1364452] CHIP:DMG: 		CommandDataElement =
[1631806890.153220][1364447:1364452] CHIP:DMG: 		{
[1631806890.153241][1364447:1364452] CHIP:DMG: 			CommandPath =
[1631806890.153266][1364447:1364452] CHIP:DMG: 			{
[1631806890.153285][1364447:1364452] CHIP:DMG: 				EndpointId = 0x1,
[1631806890.153305][1364447:1364452] CHIP:DMG: 				ClusterId = 0x6,
[1631806890.153324][1364447:1364452] CHIP:DMG: 				CommandId = 0x1,
[1631806890.153342][1364447:1364452] CHIP:DMG: 			},
[1631806890.153364][1364447:1364452] CHIP:DMG: 			
[1631806890.153381][1364447:1364452] CHIP:DMG: 			StatusElement =
[1631806890.153399][1364447:1364452] CHIP:DMG: 			{
[1631806890.153418][1364447:1364452] CHIP:DMG: 				GeneralCode = 0x0,
[1631806890.153436][1364447:1364452] CHIP:DMG: 				ProtocolId = 0x5,
[1631806890.153454][1364447:1364452] CHIP:DMG: 				protocolCode = 0x0,
[1631806890.153472][1364447:1364452] CHIP:DMG: 			},
[1631806890.153492][1364447:1364452] CHIP:DMG: 			
[1631806890.153509][1364447:1364452] CHIP:DMG: 		},
[1631806890.153533][1364447:1364452] CHIP:DMG: 		
[1631806890.153549][1364447:1364452] CHIP:DMG: 	],
[1631806890.153577][1364447:1364452] CHIP:DMG: 	
[1631806890.153594][1364447:1364452] CHIP:DMG: }
[1631806890.153650][1364447:1364452] CHIP:ZCL: DefaultResponse:
[1631806890.153684][1364447:1364452] CHIP:ZCL:   Transaction: 0x55eb1a0405d8
[1631806890.153701][1364447:1364452] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)
[1631806890.153718][1364447:1364452] CHIP:TOO: Default Success Response
[1631806890.153752][1364447:1364452] CHIP:DMG: ICR moving to [Uninitiali]
[1631806890.153773][1364447:1364452] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001
[1631806890.153810][1364447:1364452] CHIP:IN: Secure message was encrypted: Msg ID 1
[1631806890.153839][1364447:1364452] CHIP:IN: Build encrypted message 0x7f6f63ffdb68 to 0x989C34B92E9435E5 of type 16 and protocolId 0 on exchange 2798 with MessageCounter 1.
[1631806890.153862][1364447:1364452] CHIP:IN: Sending encrypted msg 0x7f6f63ffdb68 to 0x989C34B92E9435E5 at utc time: 2026610650 msec
[1631806890.153880][1364447:1364452] CHIP:IN: Sending msg on generic transport
[1631806890.153980][1364447:1364452] CHIP:EM: Flushed pending ack for MessageCounter:00000001
[1631806890.154290][1364447:1364447] CHIP:CTL: Shutting down the commissioner
[1631806890.154324][1364447:1364447] CHIP:CTL: Shutting down the controller
[1631806890.155131][1364447:1364447] CHIP:DL: Inet Layer shutdown
[1631806890.155182][1364447:1364447] CHIP:DL: BLE layer shutdown
[1631806890.155196][1364447:1364447] CHIP:DL: System Layer shutdown

Device side:

heth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
Running out/debug/chip-lighting-app in namespace.
[1631806568.707715][1361870:1361870] CHIP:DL: Device Configuration:
[1631806568.707728][1361870:1361870] CHIP:DL:   Serial Number: TEST_SN
[1631806568.707732][1361870:1361870] CHIP:DL:   Vendor Id: 9050 (0x235A)
[1631806568.707739][1361870:1361870] CHIP:DL:   Product Id: 65279 (0xFEFF)
[1631806568.707745][1361870:1361870] CHIP:DL:   Product Revision: 0
[1631806568.707748][1361870:1361870] CHIP:DL:   Setup Pin Code: 20202021
[1631806568.707751][1361870:1361870] CHIP:DL:   Setup Discriminator: 3840 (0xF00)
[1631806568.707754][1361870:1361870] CHIP:DL:   Manufacturing Date: (not set)
[1631806568.707758][1361870:1361870] CHIP:DL:   Device Type: 257 (0x101)
[1631806568.707771][1361870:1361870] CHIP:SVR: SetupQRCode: [MT:YNJV7VSC00KA0648G00]
[1631806568.707775][1361870:1361870] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1631806568.707778][1361870:1361870] CHIP:SVR: https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AYNJV7VSC00KA0648G00
[1631806568.707785][1361870:1361870] CHIP:SVR: Manual pairing code: [34970112332]
[1631806568.707791][1361870:1361870] CHIP:ZCL: Using ZAP configuration...
[1631806568.707824][1361870:1361870] CHIP:ZCL: deactivate report event
[1631806568.707828][1361870:1361870] CHIP:ZCL: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
[1631806568.707831][1361870:1361870] CHIP:DIS: Set the fabric pairing table delegate
[1631806568.707834][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806568.707837][1361870:1361870] CHIP:ZCL: OpCreds: Stored 0 fabrics in fabrics list attribute.
[1631806568.707842][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707845][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806568.707848][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707851][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806568.707855][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707858][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707862][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707865][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707869][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707872][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707875][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707879][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707883][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707886][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707890][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707893][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707897][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707901][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707904][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707908][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0028
[1631806568.707913][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707917][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0300
[1631806568.707921][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707924][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0300
[1631806568.707928][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707931][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0300
[1631806568.707935][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707938][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0406
[1631806568.707942][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806568.707945][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0406
[1631806568.707986][1361870:1361870] CHIP:DL: writing settings to file (/tmp/chip_kvs-mc59tq)
[1631806568.708025][1361870:1361870] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1631806568.708044][1361870:1361870] CHIP:DIS: Init fabric pairing table with server storage
[1631806568.708050][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708055][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708058][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708061][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708064][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708067][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708070][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708073][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708076][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708079][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708083][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708086][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708090][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708093][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708097][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708100][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708105][1361870:1361870] CHIP:IN: UDP::Init bind&listen port=5540
[1631806568.708124][1361870:1361870] CHIP:IN: UDP::Init bound to port=5540
[1631806568.708128][1361870:1361870] CHIP:IN: UDP::Init bind&listen port=5540
[1631806568.708142][1361870:1361870] CHIP:IN: UDP::Init bound to port=5540
[1631806568.708146][1361870:1361870] CHIP:IN: TransportMgr initialized
[1631806568.708171][1361870:1361870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-afA3ds)
[1631806568.708243][1361870:1361870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1631806568.708252][1361870:1361870] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8)
[1631806568.708261][1361870:1361870] CHIP:DL: wpa_supplicant: _IsWiFiStationProvisioned: interface not connected
[1631806568.708266][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708270][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708275][1361870:1361870] CHIP:DIS: Fabric 1 is not yet configured
[1631806568.708278][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708283][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708287][1361870:1361870] CHIP:DIS: Fabric 2 is not yet configured
[1631806568.708290][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708294][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708298][1361870:1361870] CHIP:DIS: Fabric 3 is not yet configured
[1631806568.708301][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708305][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708308][1361870:1361870] CHIP:DIS: Fabric 4 is not yet configured
[1631806568.708312][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708316][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708319][1361870:1361870] CHIP:DIS: Fabric 5 is not yet configured
[1631806568.708323][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708326][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708330][1361870:1361870] CHIP:DIS: Fabric 6 is not yet configured
[1631806568.708333][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708337][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708340][1361870:1361870] CHIP:DIS: Fabric 7 is not yet configured
[1631806568.708344][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708347][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708351][1361870:1361870] CHIP:DIS: Fabric 8 is not yet configured
[1631806568.708354][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708358][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708362][1361870:1361870] CHIP:DIS: Fabric 9 is not yet configured
[1631806568.708365][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708369][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708372][1361870:1361870] CHIP:DIS: Fabric 10 is not yet configured
[1631806568.708376][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708379][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708383][1361870:1361870] CHIP:DIS: Fabric 11 is not yet configured
[1631806568.708386][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708390][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708394][1361870:1361870] CHIP:DIS: Fabric 12 is not yet configured
[1631806568.708397][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708401][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708404][1361870:1361870] CHIP:DIS: Fabric 13 is not yet configured
[1631806568.708408][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708411][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708415][1361870:1361870] CHIP:DIS: Fabric 14 is not yet configured
[1631806568.708418][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708422][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708425][1361870:1361870] CHIP:DIS: Fabric 15 is not yet configured
[1631806568.708429][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806568.708432][1361870:1361870] CHIP:SVR: Delete value in server storage
[1631806568.708436][1361870:1361870] CHIP:DIS: Fabric 16 is not yet configured
[1631806568.708450][1361870:1361870] CHIP:SC: Assigned local session key ID 0
[1631806568.708454][1361870:1361870] CHIP:SC: Waiting for PBKDF param request
[1631806568.708457][1361870:1361870] CHIP:DIS: Mdns StartServer mode=1
[1631806568.708583][1361870:1361870] CHIP:DL: MDNS failed to join multicast group on neth0 for address type IPv4: ../../third_party/connectedhomeip/src/inet/IPEndPointBasis.cpp:259: Inet Error 0x00000110: Address not found
[1631806568.708608][1361870:1361870] CHIP:DIS: CHIP minimal mDNS started advertising.
[1631806568.708651][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708656][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708659][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708663][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708666][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708669][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708673][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708686][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708690][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708693][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708696][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708699][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708703][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708706][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708711][1361870:1361870] CHIP:DIS: Failed to find a valid admin pairing. Node ID unknown
[1631806568.708715][1361870:1361870] CHIP:DIS: Start dns-sd server - no current nodeId
[1631806568.708745][1361870:1361870] CHIP:DIS: Using wifi MAC for hostname
[1631806568.708757][1361870:1361870] CHIP:DL: rotatingDeviceId: 00007C5F6E176CD40F68685D100A1CF8A98B
[1631806568.708761][1361870:1361870] CHIP:DIS: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00
[1631806568.708775][1361870:1361870] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'.
[1631806568.708778][1361870:1361870] CHIP:DIS: Scheduling Discovery timeout in secs=900
[1631806568.708783][1361870:1361870] CHIP:DIS: Mdns StartServer mode=0
[1631806568.708867][1361870:1361870] CHIP:DL: MDNS failed to join multicast group on neth0 for address type IPv4: ../../third_party/connectedhomeip/src/inet/IPEndPointBasis.cpp:259: Inet Error 0x00000110: Address not found
[1631806568.708886][1361870:1361870] CHIP:DIS: CHIP minimal mDNS started advertising.
[1631806568.708926][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708931][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708934][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708939][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708941][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708944][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708947][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708959][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708962][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708965][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708968][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708971][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708974][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708977][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806568.708981][1361870:1361870] CHIP:DIS: Failed to find a valid admin pairing. Node ID unknown
[1631806568.708984][1361870:1361870] CHIP:DIS: Start dns-sd server - no current nodeId
[1631806568.709013][1361870:1361870] CHIP:DIS: Using wifi MAC for hostname
[1631806568.709020][1361870:1361870] CHIP:DL: rotatingDeviceId: 00007C5F6E176CD40F68685D100A1CF8A98B
[1631806568.709024][1361870:1361870] CHIP:DIS: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00
[1631806568.709035][1361870:1361870] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'.
[1631806568.709038][1361870:1361870] CHIP:DIS: Scheduling Discovery timeout in secs=900
[1631806568.709044][1361870:1361870] CHIP:IN: CASE Server enabling CASE session setups
[1631806568.709047][1361870:1361870] CHIP:SVR: Server Listening...
[1631806568.709089][1361870:1361875] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1631806568.709182][1361870:1361873] CHIP:DL: TRACE: Bus acquired for name MATTER-3840
[1631806568.709236][1361870:1361873] CHIP:DL: CREATE service object at /chipoble/c7ce/service
[1631806568.709416][1361870:1361873] CHIP:DL: Create characteristic object at /chipoble/c7ce/service/c1
[1631806568.709526][1361870:1361873] CHIP:DL: Create characteristic object at /chipoble/c7ce/service/c2
[1631806568.709595][1361870:1361873] CHIP:DL: CHIP BTP C1 /chipoble/c7ce/service
[1631806568.709601][1361870:1361873] CHIP:DL: CHIP BTP C2 /chipoble/c7ce/service
[1631806568.709604][1361870:1361873] CHIP:DL: CHIP_ENABLE_ADDITIONAL_DATA_ADVERTISING is TRUE
[1631806568.709608][1361870:1361873] CHIP:DL: Create characteristic object at /chipoble/c7ce/service/c3
[1631806568.709671][1361870:1361873] CHIP:DL: rotatingDeviceId: 00007C5F6E176CD40F68685D100A1CF8A98B
[1631806568.709682][1361870:1361873] CHIP:DL: CHIP BTP C3 /chipoble/c7ce/service
[1631806568.711515][1361870:1361870] CHIP:DL: PlatformBlueZInit init success

** (process:1361870): WARNING **: 11:36:08.711: Error setting property 'Powered' on interface org.bluez.Adapter1: GDBus.Error:org.bluez.Error.Busy:  (g-io-error-quark, 36)
[1631806568.713399][1361870:1361873] CHIP:DL: BluezPeripheralRegisterAppDone done
[1631806568.713411][1361870:1361870] CHIP:DL: HandlePlatformSpecificBLEEvent 16392
[1631806568.713463][1361870:1361873] CHIP:DL: Create adv object at /chipoble/c7ce/advertising
[1631806568.713549][1361870:1361873] CHIP:DL: SET service data to {'0xFFF6': <[byte 0x00, 0x00, 0x0f, 0x5a, 0x23, 0xff, 0xfe]>}
[1631806568.713703][1361870:1361870] CHIP:DL: HandlePlatformSpecificBLEEvent 16393
[1631806568.713712][1361870:1361870] CHIP:DL: CHIPoBLE advertising config complete
[1631806568.715238][1361870:1361873] CHIP:DL: RegisterAdvertisement complete
[1631806568.715257][1361870:1361870] CHIP:DL: HandlePlatformSpecificBLEEvent 16394
[1631806806.165256][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165277][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165283][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165288][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165293][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165299][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165323][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806806.165353][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.276947][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.277110][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.277206][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.277307][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.277425][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806806.277511][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.166774][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166825][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166839][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166853][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166870][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166888][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166945][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806807.166966][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278403][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278593][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278704][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278789][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278871][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.278953][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.751462][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.751630][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806807.853129][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.167762][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167809][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167833][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167850][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167865][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167881][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167941][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806809.167964][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278638][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278720][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278781][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278838][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278888][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806809.278939][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.171783][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.171831][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.171855][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.171893][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.171924][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.171944][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.172011][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806813.172043][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.280541][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.280717][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.280808][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.280894][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.280992][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806813.281125][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806823.054647][1361870:1361870] CHIP:EM: Received message of type 0x20 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.054682][1361870:1361870] CHIP:EM: ec id: 19670, Delegate: 0x0x5642a07857d8
[1631806823.054704][1361870:1361870] CHIP:SC: Received PBKDF param request
[1631806823.054728][1361870:1361870] CHIP:SC: Peer assigned session ID 5
[1631806823.055373][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:1AB9F75E with msg
[1631806823.055401][1361870:1361870] CHIP:IN: Build plaintext message 0x5642a0784928 to 0x0000000000000000 of type 33 and protocolId 0 on exchange 19670 with MessageCounter 3577232151.
[1631806823.055417][1361870:1361870] CHIP:IN: Sending plaintext msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026543552 msec
[1631806823.055428][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.055512][1361870:1361870] CHIP:SC: Sent PBKDF param response
[1631806823.062769][1361870:1361870] CHIP:EM: Received message of type 0x22 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.062798][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:D5383B17 from Retrans Table
[1631806823.062807][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:D5383B17 from RetransTable
[1631806823.062821][1361870:1361870] CHIP:SC: Received spake2p msg1
[1631806823.063457][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:1AB9F75F with msg
[1631806823.063477][1361870:1361870] CHIP:IN: Build plaintext message 0x5642a0784928 to 0x0000000000000000 of type 35 and protocolId 0 on exchange 19670 with MessageCounter 3577232152.
[1631806823.063490][1361870:1361870] CHIP:IN: Sending plaintext msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026543560 msec
[1631806823.063498][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.063554][1361870:1361870] CHIP:SC: Sent spake2p msg2
[1631806823.064342][1361870:1361870] CHIP:EM: Received message of type 0x24 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.064370][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:D5383B18 from Retrans Table
[1631806823.064380][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:D5383B18 from RetransTable
[1631806823.064393][1361870:1361870] CHIP:SC: Received spake2p msg3
[1631806823.064425][1361870:1361870] CHIP:SC: Sending status report
[1631806823.064439][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:1AB9F760 with msg
[1631806823.064452][1361870:1361870] CHIP:IN: Build plaintext message 0x5642a0784928 to 0x0000000000000000 of type 64 and protocolId 0 on exchange 19670 with MessageCounter 3577232153.
[1631806823.064465][1361870:1361870] CHIP:IN: Sending plaintext msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026543561 msec
[1631806823.064475][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.064533][1361870:1361870] CHIP:IN: New secure session created for device 0x0000000000000000, key 5!!
[1631806823.064560][1361870:1361870] CHIP:SVR: Commissioning completed session establishment step
[1631806823.064573][1361870:1361870] CHIP:DIS: Mdns StartServer mode=0
[1631806823.064825][1361870:1361870] CHIP:DL: MDNS failed to join multicast group on neth0 for address type IPv4: ../../third_party/connectedhomeip/src/inet/IPEndPointBasis.cpp:259: Inet Error 0x00000110: Address not found
[1631806823.064879][1361870:1361870] CHIP:DIS: CHIP minimal mDNS started advertising.
[1631806823.064982][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.064995][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065004][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065012][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065021][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065029][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065037][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065071][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065081][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065088][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065094][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065101][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065107][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065114][1361870:1361870] CHIP:DIS: Replying to DNS-SD service listing request
[1631806823.065126][1361870:1361870] CHIP:DIS: Failed to find a valid admin pairing. Node ID unknown
[1631806823.065134][1361870:1361870] CHIP:DIS: Start dns-sd server - no current nodeId
[1631806823.065210][1361870:1361870] CHIP:DIS: Using wifi MAC for hostname
[1631806823.065233][1361870:1361870] CHIP:DL: rotatingDeviceId: 00007C5F6E176CD40F68685D100A1CF8A98B
[1631806823.065242][1361870:1361870] CHIP:DIS: Advertise commission parameter vendorID=9050 productID=65279 discriminator=3840/00
[1631806823.065271][1361870:1361870] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'.
[1631806823.065280][1361870:1361870] CHIP:DIS: Scheduling Discovery timeout in secs=900
[1631806823.065290][1361870:1361870] CHIP:SVR: Device completed Rendezvous process
[1631806823.065354][1361870:1361870] CHIP:EM: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 19671
[1631806823.065370][1361870:1361870] CHIP:EM: ec id: 19671, Delegate: 0x0x5642a077fea0
[1631806823.065387][1361870:1361870] CHIP:DMG: ICR moving to [Initialize]
[1631806823.065399][1361870:1361870] CHIP:DMG: InvokeCommand =
[1631806823.065409][1361870:1361870] CHIP:DMG: {
[1631806823.065418][1361870:1361870] CHIP:DMG: 	CommandList =
[1631806823.065428][1361870:1361870] CHIP:DMG: 	[
[1631806823.065438][1361870:1361870] CHIP:DMG: 		CommandDataElement =
[1631806823.065448][1361870:1361870] CHIP:DMG: 		{
[1631806823.065458][1361870:1361870] CHIP:DMG: 			CommandPath =
[1631806823.065468][1361870:1361870] CHIP:DMG: 			{
[1631806823.065479][1361870:1361870] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.065490][1361870:1361870] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.065500][1361870:1361870] CHIP:DMG: 				CommandId = 0x4,
[1631806823.065510][1361870:1361870] CHIP:DMG: 			},
[1631806823.065521][1361870:1361870] CHIP:DMG: 			
[1631806823.065530][1361870:1361870] CHIP:DMG: 			CommandData = 
[1631806823.065541][1361870:1361870] CHIP:DMG: 			{
[1631806823.065551][1361870:1361870] CHIP:DMG: 				0x0 = [
[1631806823.065566][1361870:1361870] CHIP:DMG: 					0x6e, 0x3c, 0x48, 0xff, 0x7d, 0xcb, 0x93, 0x4, 0x8c, 0x78, 0xa4, 0x9c, 0xec, 0x1c, 0xbe, 0x22, 0xae, 0x66, 0xde, 0x10, 0x34, 0xa9, 0xc0, 0x5a, 0x89, 0xcd, 0x80, 0xcc, 0xd0, 0x83, 0xb3, 0x1f, 
[1631806823.065580][1361870:1361870] CHIP:DMG: 			]
[1631806823.065590][1361870:1361870] CHIP:DMG: 			},
[1631806823.065599][1361870:1361870] CHIP:DMG: 		},
[1631806823.065612][1361870:1361870] CHIP:DMG: 		
[1631806823.065621][1361870:1361870] CHIP:DMG: 	],
[1631806823.065633][1361870:1361870] CHIP:DMG: 	
[1631806823.065641][1361870:1361870] CHIP:DMG: }
[1631806823.065659][1361870:1361870] CHIP:ZCL: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_0004 Endpoint=0
[1631806823.065672][1361870:1361870] CHIP:ZCL: OpCreds: commissioner has requested an OpCSR
[1631806823.066655][1361870:1361873] CHIP:DL: UnregisterAdvertisement complete
[1631806823.067318][1361870:1361870] CHIP:ZCL: OpCreds: NewCertificateSigningRequest returned -1602895960
[1631806823.067344][1361870:1361870] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.067365][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:00000000 with msg
[1631806823.067391][1361870:1361870] CHIP:IN: Secure message was encrypted: Msg ID 1
[1631806823.067401][1361870:1361870] CHIP:IN: Build encrypted message 0x5642a0784940 to 0x0000000000000000 of type 9 and protocolId 5 on exchange 19671 with MessageCounter 1.
[1631806823.067414][1361870:1361870] CHIP:IN: Sending encrypted msg 0x5642a0784940 to 0x0000000000000000 at utc time: 2026543564 msec
[1631806823.067423][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.067477][1361870:1361870] CHIP:DMG: ICR moving to [   Sending]
[1631806823.067488][1361870:1361870] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.067501][1361870:1361870] CHIP:DL: HandlePlatformSpecificBLEEvent 16395
[1631806823.067510][1361870:1361870] CHIP:DL: CHIPoBLE advertising stopped
[1631806823.067549][1361870:1361870] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 19670
[1631806823.067565][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:D5383B19 from Retrans Table
[1631806823.067573][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:D5383B19 from RetransTable
[1631806823.068896][1361870:1361870] CHIP:EM: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 19672
[1631806823.068920][1361870:1361870] CHIP:EM: ec id: 19672, Delegate: 0x0x5642a077fea0
[1631806823.068940][1361870:1361870] CHIP:DMG: ICR moving to [Initialize]
[1631806823.068953][1361870:1361870] CHIP:DMG: InvokeCommand =
[1631806823.068962][1361870:1361870] CHIP:DMG: {
[1631806823.068969][1361870:1361870] CHIP:DMG: 	CommandList =
[1631806823.068977][1361870:1361870] CHIP:DMG: 	[
[1631806823.068986][1361870:1361870] CHIP:DMG: 		CommandDataElement =
[1631806823.068996][1361870:1361870] CHIP:DMG: 		{
[1631806823.069005][1361870:1361870] CHIP:DMG: 			CommandPath =
[1631806823.069015][1361870:1361870] CHIP:DMG: 			{
[1631806823.069025][1361870:1361870] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.069034][1361870:1361870] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.069043][1361870:1361870] CHIP:DMG: 				CommandId = 0xb,
[1631806823.069051][1361870:1361870] CHIP:DMG: 			},
[1631806823.069062][1361870:1361870] CHIP:DMG: 			
[1631806823.069071][1361870:1361870] CHIP:DMG: 			CommandData = 
[1631806823.069081][1361870:1361870] CHIP:DMG: 			{
[1631806823.069091][1361870:1361870] CHIP:DMG: 				0x0 = [
[1631806823.069111][1361870:1361870] CHIP:DMG: 					0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x24, 0x15, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x14, 0x0, 0x24, 0x15, 0x0, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x3
[1631806823.069124][1361870:1361870] CHIP:DMG: 			]
[1631806823.069134][1361870:1361870] CHIP:DMG: 			},
[1631806823.069143][1361870:1361870] CHIP:DMG: 		},
[1631806823.069156][1361870:1361870] CHIP:DMG: 		
[1631806823.069165][1361870:1361870] CHIP:DMG: 	],
[1631806823.069177][1361870:1361870] CHIP:DMG: 	
[1631806823.069186][1361870:1361870] CHIP:DMG: }
[1631806823.069203][1361870:1361870] CHIP:ZCL: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_000B Endpoint=0
[1631806823.069216][1361870:1361870] CHIP:ZCL: OpCreds: commissioner has added a trusted root Cert
[1631806823.069230][1361870:1361870] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.069246][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:00000001 with msg
[1631806823.069265][1361870:1361870] CHIP:IN: Secure message was encrypted: Msg ID 2
[1631806823.069275][1361870:1361870] CHIP:IN: Build encrypted message 0x5642a0784928 to 0x0000000000000000 of type 9 and protocolId 5 on exchange 19672 with MessageCounter 2.
[1631806823.069288][1361870:1361870] CHIP:IN: Sending encrypted msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026543566 msec
[1631806823.069298][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.069354][1361870:1361870] CHIP:DMG: ICR moving to [   Sending]
[1631806823.069366][1361870:1361870] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.069404][1361870:1361870] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 19671
[1631806823.069420][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:00000001 from Retrans Table
[1631806823.069429][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:00000001 from RetransTable
[1631806823.070018][1361870:1361870] CHIP:EM: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 19673
[1631806823.070039][1361870:1361870] CHIP:EM: ec id: 19673, Delegate: 0x0x5642a077fea0
[1631806823.070062][1361870:1361870] CHIP:DMG: ICR moving to [Initialize]
[1631806823.070073][1361870:1361870] CHIP:DMG: InvokeCommand =
[1631806823.070084][1361870:1361870] CHIP:DMG: {
[1631806823.070093][1361870:1361870] CHIP:DMG: 	CommandList =
[1631806823.070103][1361870:1361870] CHIP:DMG: 	[
[1631806823.070112][1361870:1361870] CHIP:DMG: 		CommandDataElement =
[1631806823.070123][1361870:1361870] CHIP:DMG: 		{
[1631806823.070132][1361870:1361870] CHIP:DMG: 			CommandPath =
[1631806823.070143][1361870:1361870] CHIP:DMG: 			{
[1631806823.070153][1361870:1361870] CHIP:DMG: 				EndpointId = 0x0,
[1631806823.070164][1361870:1361870] CHIP:DMG: 				ClusterId = 0x3e,
[1631806823.070175][1361870:1361870] CHIP:DMG: 				CommandId = 0x6,
[1631806823.070185][1361870:1361870] CHIP:DMG: 			},
[1631806823.070197][1361870:1361870] CHIP:DMG: 			
[1631806823.070206][1361870:1361870] CHIP:DMG: 			CommandData = 
[1631806823.070217][1361870:1361870] CHIP:DMG: 			{
[1631806823.070228][1361870:1361870] CHIP:DMG: 				0x0 = [
[1631806823.070247][1361870:1361870] CHIP:DMG: 					0x15, 0x30, 0x1, 0x1, 0x1, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x13, 0x1, 0x24, 0x15, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x27, 0x11, 0xe5, 0x35, 0x94, 0x2e, 0xb9, 0x34, 0x9c, 0x98, 0x24, 0x15, 0x0
[1631806823.070262][1361870:1361870] CHIP:DMG: 			]
[1631806823.070272][1361870:1361870] CHIP:DMG: 				0x1 = [
[1631806823.070292][1361870:1361870] CHIP:DMG: 					0x15, 0x30, 0x1, 0x1, 0x0, 0x24, 0x2, 0x1, 0x37, 0x3, 0x24, 0x14, 0x0, 0x24, 0x15, 0x0, 0x18, 0x26, 0x4, 0x80, 0x22, 0x81, 0x27, 0x26, 0x5, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x6, 0x24, 0x13, 0x1, 0x24, 0x15, 0x0, 0x18, 0x24, 0x7, 0x1, 0x24, 0x8, 0x1, 0x3
[1631806823.070305][1361870:1361870] CHIP:DMG: 			]
[1631806823.070315][1361870:1361870] CHIP:DMG: 				0x2 = [
[1631806823.070325][1361870:1361870] CHIP:DMG: 					
[1631806823.070336][1361870:1361870] CHIP:DMG: 			]
[1631806823.070347][1361870:1361870] CHIP:DMG: 				0x3 = 112233, 
[1631806823.070358][1361870:1361870] CHIP:DMG: 				0x4 = 52096, 
[1631806823.070368][1361870:1361870] CHIP:DMG: 			},
[1631806823.070378][1361870:1361870] CHIP:DMG: 		},
[1631806823.070393][1361870:1361870] CHIP:DMG: 		
[1631806823.070402][1361870:1361870] CHIP:DMG: 	],
[1631806823.070415][1361870:1361870] CHIP:DMG: 	
[1631806823.070424][1361870:1361870] CHIP:DMG: }
[1631806823.070441][1361870:1361870] CHIP:ZCL: Received Cluster Command: Cluster=0x0000_003E Command=0x0000_0006 Endpoint=0
[1631806823.070457][1361870:1361870] CHIP:ZCL: OpCreds: commissioner has added an Op Cert
[1631806823.070478][1361870:1361870] CHIP:SVR: Retrieved value from server storage.
[1631806823.070591][1361870:1361870] CHIP:DIS: Verifying the received credentials
[1631806823.071430][1361870:1361870] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1631806823.071448][1361870:1361870] CHIP:DIS: Assigned compressed fabric ID: 0x7F0FEE1620293FEA, node ID: 0x989C34B92E9435E5
[1631806823.071458][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806823.071467][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806823.071477][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.071511][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.071525][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.071537][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.071545][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.071555][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.071563][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.071576][1361870:1361870] CHIP:SVR: Stored value in server storage
[1631806823.071716][1361870:1361870] CHIP:DL: writing settings to file (/tmp/chip_kvs-eO1DUp)
[1631806823.071914][1361870:1361870] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1631806823.071955][1361870:1361870] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
[1631806823.071965][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 1 was persisted to storage. FabricId 000000000989C34B9, NodeId 2e9435e50000CB80A0784E70, VendorId 0xA077CF98
[1631806823.071975][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.072013][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.072026][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.072037][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072045][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072054][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072063][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072071][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806823.072080][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806823.072089][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.072122][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.072133][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.072142][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072150][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072159][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072167][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072180][1361870:1361870] CHIP:SVR: Stored value in server storage
[1631806823.072268][1361870:1361870] CHIP:DL: writing settings to file (/tmp/chip_kvs-GWE4Ko)
[1631806823.072418][1361870:1361870] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1631806823.072441][1361870:1361870] CHIP:DIS: Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
[1631806823.072449][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 1 was persisted to storage. FabricId 000000000989C34B9, NodeId 2e9435e50000CB80A0784E70, VendorId 0xA077CF98
[1631806823.072458][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.072494][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.072506][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.072515][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072522][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072530][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.072536][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.072641][1361870:1361870] CHIP:DIS: Using wifi MAC for hostname
[1631806823.072653][1361870:1361870] CHIP:DIS: Advertise operational node 7F0FEE1620293FEA-989C34B92E9435E5
[1631806823.072670][1361870:1361870] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'.
[1631806823.072687][1361870:1361870] CHIP:DMG: ICR moving to [AddCommand]
[1631806823.072709][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:00000003 with msg
[1631806823.072730][1361870:1361870] CHIP:IN: Secure message was encrypted: Msg ID 3
[1631806823.072740][1361870:1361870] CHIP:IN: Build encrypted message 0x5642a0784940 to 0x0000000000000000 of type 9 and protocolId 5 on exchange 19673 with MessageCounter 3.
[1631806823.072753][1361870:1361870] CHIP:IN: Sending encrypted msg 0x5642a0784940 to 0x0000000000000000 at utc time: 2026543569 msec
[1631806823.072762][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.072819][1361870:1361870] CHIP:DMG: ICR moving to [   Sending]
[1631806823.072832][1361870:1361870] CHIP:DMG: ICR moving to [Uninitiali]
[1631806823.072874][1361870:1361870] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 19672
[1631806823.072891][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:00000002 from Retrans Table
[1631806823.072900][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:00000002 from RetransTable
[1631806823.074861][1361870:1361870] CHIP:DIS: Broadcasting mDns reply
[1631806823.074973][1361870:1361870] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 19673
[1631806823.074998][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:00000003 from Retrans Table
[1631806823.075009][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:00000003 from RetransTable
[1631806823.076386][1361870:1361870] CHIP:EM: Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 19674
[1631806823.076405][1361870:1361870] CHIP:EM: ec id: 19674, Delegate: 0x0x5642a0784478
[1631806823.076420][1361870:1361870] CHIP:IN: CASE Server received SigmaR1 message. Starting handshake. EC 0x5642a0784a30
[1631806823.076429][1361870:1361870] CHIP:IN: Marking old secure session for device 0x0000000000000000 as expired
[1631806823.076440][1361870:1361870] CHIP:DIS: CASE handshake initiated, closing all BLE Connections
[1631806823.076451][1361870:1361870] CHIP:SC: Waiting for SigmaR1 msg
[1631806823.076459][1361870:1361870] CHIP:IN: CASE Server disabling CASE session setups
[1631806823.076469][1361870:1361870] CHIP:SC: Received SigmaR1 msg
[1631806823.076483][1361870:1361870] CHIP:SC: Peer assigned session key ID 6
[1631806823.076493][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806823.076502][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806823.076512][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.076555][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.076569][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.076581][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.076589][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.076599][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.076607][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.076648][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806823.076658][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806823.076668][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806823.076700][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806823.076712][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806823.076722][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.076730][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.076738][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806823.076746][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806823.077224][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:BE7DBF7F with msg
[1631806823.077245][1361870:1361870] CHIP:IN: Build plaintext message 0x5642a0784928 to 0x0000000000000000 of type 49 and protocolId 0 on exchange 19674 with MessageCounter 1885223100.
[1631806823.077258][1361870:1361870] CHIP:IN: Sending plaintext msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026543574 msec
[1631806823.077268][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.077321][1361870:1361870] CHIP:SC: Sent SigmaR2 msg
[1631806823.080144][1361870:1361870] CHIP:EM: Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 19674
[1631806823.080180][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:705E38BC from Retrans Table
[1631806823.080194][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:705E38BC from RetransTable
[1631806823.080216][1361870:1361870] CHIP:SC: Received SigmaR3 msg
[1631806823.082076][1361870:1361870] CHIP:IN: CASE Session established. Setting up the secure channel.
[1631806823.082111][1361870:1361870] CHIP:IN: New secure session created for device 0x000000000001B669, key 6!!
[1631806823.082153][1361870:1361870] CHIP:IN: CASE secure channel is available now.
[1631806823.082167][1361870:1361870] CHIP:IN: CASE Server enabling CASE session setups
[1631806823.082183][1361870:1361870] CHIP:EM: Sending Standalone Ack for MessageCounter:BE7DBF80
[1631806823.082201][1361870:1361870] CHIP:IN: Build plaintext message 0x7ffe8348f158 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 19674 with MessageCounter 1885223101.
[1631806823.082220][1361870:1361870] CHIP:IN: Sending plaintext msg 0x7ffe8348f158 to 0x0000000000000000 at utc time: 2026543579 msec
[1631806823.082234][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806823.082326][1361870:1361870] CHIP:EM: Flushed pending ack for MessageCounter:BE7DBF80
[1631806890.144115][1361870:1361870] CHIP:EM: Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 2797
[1631806890.144161][1361870:1361870] CHIP:EM: ec id: 2797, Delegate: 0x0x5642a0784478
[1631806890.144191][1361870:1361870] CHIP:IN: CASE Server received SigmaR1 message. Starting handshake. EC 0x5642a0784a30
[1631806890.144211][1361870:1361870] CHIP:DIS: CASE handshake initiated, closing all BLE Connections
[1631806890.144233][1361870:1361870] CHIP:SC: Waiting for SigmaR1 msg
[1631806890.144249][1361870:1361870] CHIP:IN: CASE Server disabling CASE session setups
[1631806890.144267][1361870:1361870] CHIP:SC: Received SigmaR1 msg
[1631806890.144296][1361870:1361870] CHIP:SC: Peer assigned session key ID 8
[1631806890.144315][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806890.144333][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806890.144352][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806890.144434][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806890.144461][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806890.144484][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.144500][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806890.144519][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.144535][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806890.144615][1361870:1361870] CHIP:DIS: Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
[1631806890.144633][1361870:1361870] CHIP:ZCL: OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x989C34B92E9435E5, VendorId 0xCB80
[1631806890.144651][1361870:1361870] CHIP:ZCL: OpCreds: Call to writeFabricsIntoFabricsListAttribute
[1631806890.144709][1361870:1361870] CHIP:ZCL: OpCreds: Writing fabric into attribute store at index 0: fabricId 0x0000000000000000, nodeId 0x989C34B92E9435E5 vendorId 0xCB80
[1631806890.144731][1361870:1361870] CHIP:ZCL: OpCreds: Stored 1 fabrics in fabrics list attribute.
[1631806890.144750][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.144765][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806890.144783][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.144799][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_003E
[1631806890.145670][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:78B445BF with msg
[1631806890.145707][1361870:1361870] CHIP:IN: Build plaintext message 0x5642a0784928 to 0x0000000000000000 of type 49 and protocolId 0 on exchange 2797 with MessageCounter 1885223102.
[1631806890.145732][1361870:1361870] CHIP:IN: Sending plaintext msg 0x5642a0784928 to 0x0000000000000000 at utc time: 2026610642 msec
[1631806890.145751][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806890.145867][1361870:1361870] CHIP:SC: Sent SigmaR2 msg
[1631806890.149281][1361870:1361870] CHIP:EM: Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 2797
[1631806890.149334][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:705E38BE from Retrans Table
[1631806890.149351][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:705E38BE from RetransTable
[1631806890.149379][1361870:1361870] CHIP:SC: Received SigmaR3 msg
[1631806890.151603][1361870:1361870] CHIP:IN: CASE Session established. Setting up the secure channel.
[1631806890.151640][1361870:1361870] CHIP:IN: Marking old secure session for device 0x000000000001B669 as expired
[1631806890.151666][1361870:1361870] CHIP:IN: New secure session created for device 0x000000000001B669, key 8!!
[1631806890.151714][1361870:1361870] CHIP:IN: CASE secure channel is available now.
[1631806890.151731][1361870:1361870] CHIP:IN: CASE Server enabling CASE session setups
[1631806890.151792][1361870:1361870] CHIP:EM: Sending Standalone Ack for MessageCounter:78B445C0
[1631806890.151820][1361870:1361870] CHIP:IN: Build plaintext message 0x7ffe8348f158 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 2797 with MessageCounter 1885223103.
[1631806890.151846][1361870:1361870] CHIP:IN: Sending plaintext msg 0x7ffe8348f158 to 0x0000000000000000 at utc time: 2026610648 msec
[1631806890.151864][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806890.151969][1361870:1361870] CHIP:EM: Flushed pending ack for MessageCounter:78B445C0
[1631806890.152054][1361870:1361870] CHIP:EM: Received message of type 0x08 with vendorId 0x0000 and protocolId 0x0005 on exchange 2798
[1631806890.152082][1361870:1361870] CHIP:EM: ec id: 2798, Delegate: 0x0x5642a077fea0
[1631806890.152112][1361870:1361870] CHIP:DMG: ICR moving to [Initialize]
[1631806890.152134][1361870:1361870] CHIP:DMG: InvokeCommand =
[1631806890.152152][1361870:1361870] CHIP:DMG: {
[1631806890.152168][1361870:1361870] CHIP:DMG: 	CommandList =
[1631806890.152187][1361870:1361870] CHIP:DMG: 	[
[1631806890.152204][1361870:1361870] CHIP:DMG: 		CommandDataElement =
[1631806890.152223][1361870:1361870] CHIP:DMG: 		{
[1631806890.152239][1361870:1361870] CHIP:DMG: 			CommandPath =
[1631806890.152258][1361870:1361870] CHIP:DMG: 			{
[1631806890.152277][1361870:1361870] CHIP:DMG: 				EndpointId = 0x1,
[1631806890.152295][1361870:1361870] CHIP:DMG: 				ClusterId = 0x6,
[1631806890.152314][1361870:1361870] CHIP:DMG: 				CommandId = 0x1,
[1631806890.152331][1361870:1361870] CHIP:DMG: 			},
[1631806890.152352][1361870:1361870] CHIP:DMG: 			
[1631806890.152368][1361870:1361870] CHIP:DMG: 			CommandData = 
[1631806890.152387][1361870:1361870] CHIP:DMG: 			{
[1631806890.152406][1361870:1361870] CHIP:DMG: 			},
[1631806890.152424][1361870:1361870] CHIP:DMG: 		},
[1631806890.152446][1361870:1361870] CHIP:DMG: 		
[1631806890.152462][1361870:1361870] CHIP:DMG: 	],
[1631806890.152484][1361870:1361870] CHIP:DMG: 	
[1631806890.152500][1361870:1361870] CHIP:DMG: }
[1631806890.152532][1361870:1361870] CHIP:ZCL: Received Cluster Command: Cluster=0x0000_0006 Command=0x0000_0001 Endpoint=1
[1631806890.152551][1361870:1361870] CHIP:ZCL: On/Off set value: 1 1
[1631806890.152568][1361870:1361870] CHIP:ZCL: Toggle on/off from 0 to 1
[1631806890.152587][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.152603][1361870:1361870] CHIP:SVR: LightingManager::InitiateAction(ON_ACTION)
[1631806890.152622][1361870:1361870] CHIP:DMG: AttributePath is not interested
[1631806890.152638][1361870:1361870] CHIP:ZCL: Unknown cluster ID: 0x0000_0008
[1631806890.152664][1361870:1361870] CHIP:DMG: ICR moving to [AddCommand]
[1631806890.152694][1361870:1361870] CHIP:EM: Piggybacking Ack for MessageCounter:00000000 with msg
[1631806890.152738][1361870:1361870] CHIP:IN: Secure message was encrypted: Msg ID 1
[1631806890.152759][1361870:1361870] CHIP:IN: Build encrypted message 0x5642a0784928 to 0x000000000001B669 of type 9 and protocolId 5 on exchange 2798 with MessageCounter 1.
[1631806890.152780][1361870:1361870] CHIP:IN: Sending encrypted msg 0x5642a0784928 to 0x000000000001B669 at utc time: 2026610649 msec
[1631806890.152795][1361870:1361870] CHIP:IN: Sending msg on generic transport
[1631806890.152882][1361870:1361870] CHIP:DMG: ICR moving to [   Sending]
[1631806890.152903][1361870:1361870] CHIP:DMG: ICR moving to [Uninitiali]
[1631806890.154076][1361870:1361870] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 2798
[1631806890.154132][1361870:1361870] CHIP:EM: Rxd Ack; Removing MessageCounter:00000001 from Retrans Table
[1631806890.154153][1361870:1361870] CHIP:EM: Removed CHIP MessageCounter:00000001 from RetransTable

@cecille
Copy link
Contributor

cecille commented Sep 17, 2021

Is this just the open commissining window command that is failing?

If so, it's probably because chip tool generates a new random node id for all pairing commands. Can you confirm whether this is the command you're having problems running?

cecille added a commit to cecille/connectedhomeip that referenced this issue Sep 17, 2021
It looks like the previous version would generate a random nodeid
and then attempt to open the pairing window on that. Issue project-chip#9550
indicates a general failure to send commands after provisioning,
but it actually looks like the open pairing window command is the
only one affected. Issue speculates that PersistDevice was not
called, but confirmed that PersistDevice IS called. However,
the data for a randomly generated node id would not be present
so the symptoms may match.

We also need to connect to the device before sending the open
pairing windo command as it is a standard cluster command. Added
calls to connect to the device before opening the pairing window.

Test:
./chip-tool pairing onnetwork 0 20202021 3840 fc00::a 5540
./chip-tool onoff on 1
./chip-tool pairing open-commissioning-window 0 5000 1 3840
./chip-tool pairing onnetwork 0 20202021 3840 fc00::a 5540
./chip-tool onoff on 1
@cecille
Copy link
Contributor

cecille commented Sep 17, 2021

#9806 - Does this work for what you're trying to do?

woody-apple pushed a commit that referenced this issue Sep 20, 2021
It looks like the previous version would generate a random nodeid
and then attempt to open the pairing window on that. Issue #9550
indicates a general failure to send commands after provisioning,
but it actually looks like the open pairing window command is the
only one affected. Issue speculates that PersistDevice was not
called, but confirmed that PersistDevice IS called. However,
the data for a randomly generated node id would not be present
so the symptoms may match.

We also need to connect to the device before sending the open
pairing windo command as it is a standard cluster command. Added
calls to connect to the device before opening the pairing window.

Test:
./chip-tool pairing onnetwork 0 20202021 3840 fc00::a 5540
./chip-tool onoff on 1
./chip-tool pairing open-commissioning-window 0 5000 1 3840
./chip-tool pairing onnetwork 0 20202021 3840 fc00::a 5540
./chip-tool onoff on 1
@cecille
Copy link
Contributor

cecille commented Sep 21, 2021

If you wipe the chip_* files in /tmp, does it work?

@woody-apple
Copy link
Contributor

SW Dev Bug Review: Closing this, as doesn't appear needed anymore and/or is complete, please reopen if needed.

@mossmgr
Copy link

mossmgr commented Nov 18, 2022

This issue still persists, I am getting the same error.

2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] WARNING Initializing persistent storage from file: /tmp/chip-device-ctrl-storage.json
2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] WARNING Loading configuration from /tmp/chip-device-ctrl-storage.json...
2022-11-18 15:06:18 Beeta-67376B chip.TS[20157] INFO Last Known Good Time: 2022-11-18T12:09:17
2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] INFO SetSdkKey: g/gcc = b'\xa0\x0f\x00\x00'
2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] INFO Committing...
2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] INFO SetSdkKey: g/gdc = b'\xa0\x0f\x00\x00'
2022-11-18 15:06:18 Beeta-67376B PersistentStorage[20157] INFO Committing...
2022-11-18 15:06:18 Beeta-67376B chip.ZCL[20157] INFO Using ZAP configuration...
2022-11-18 15:06:18 Beeta-67376B chip.DL[20157] ERROR MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
2022-11-18 15:06:18 Beeta-67376B chip.DL[20157] ERROR MDNS failed to join multicast group on wlan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
2022-11-18 15:06:18 Beeta-67376B chip.IN[20157] INFO CASE Server enabling CASE session setups
2022-11-18 15:06:18 Beeta-67376B chip.DIS[20157] INFO Updating services using commissioning mode 0
2022-11-18 15:06:18 Beeta-67376B chip.DL[20157] ERROR MDNS failed to join multicast group on eth0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
2022-11-18 15:06:18 Beeta-67376B chip.DL[20157] ERROR MDNS failed to join multicast group on wlan0 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
2022-11-18 15:06:18 Beeta-67376B chip.DIS[20157] INFO CHIP minimal mDNS started advertising.
2022-11-18 15:06:18 Beeta-67376B chip.DIS[20157] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=0
2022-11-18 15:06:18 Beeta-67376B chip.DIS[20157] INFO CHIP minimal mDNS configured as 'Commissioner device'; instance name: 684C32FF0F97EB99.
2022-11-18 15:06:18 Beeta-67376B chip.DIS[20157] INFO mDNS service published: _matterd._udp
Exception ignored in: <function FabricAdmin.del at 0xb5a9c028>
Traceback (most recent call last):
File "/root/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 125, in del
self.Shutdown()
File "/root/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 118, in Shutdown
if (self._isActive):
AttributeError: 'FabricAdmin' object has no attribute '_isActive'
init() missing 1 required positional argument: 'vendorId'`

`

@cecille
Copy link
Contributor

cecille commented Nov 22, 2022

Can you elaborate more on the problem you're having? I'm seeing a couple of errors here, but it doesn't appear to be related to persisting the device list.

Can you indicate:

  1. what device are these logs from?
  2. what command are you running that's failing - what do you expect to happen, what's the actual behaviour?
  3. What interfaces are available on this device? Logs list eth0 and wlan0 - are there others?

@mossmgr
Copy link

mossmgr commented Nov 22, 2022

Yes of course. These logs are from a custom hardware running Linux debian armhf (bullseye).
The device has Z-Wave chip support and BLE support and has wlan and ethernet. wlan0 is the intended interface for running Matter over IP protocol. The device is connected to the local network via ethernet cable and wlan0 is active.

I am following the guide located at https://github.com/project-chip/connectedhomeip/blob/master/docs/guides/python_chip_controller_building.md

when I run this command in my python_env with root privileges i get the above mentioned error.
out/python_env/bin/chip-device-ctrl

What I expect is running chip-device-ctrl > ble-scan and get a list of available commissionee devices.

Thanks.

@cecille
Copy link
Contributor

cecille commented Nov 22, 2022

I'm still not totally sure what the setup is here. The logs look like they're coming from the python code (chip-device-ctrl), which is the controller side. Is that what's running on the custom hardware? Or do you have a device application running there and these are the host side logs?

Either way, you've hit a documentation bug - chip-device-ctrl is deprecated. PR up here to add a documentation warning: #23724. If you want to use a python-based controller tool, matter-repl is the one that's currently being maintained. The other option is chip-tool, which is what is mostly used by the certification group.

Can you specify:

  1. what specifically is running on your custom hardware? is it an example application (which one), something custom, or is the custom hardware acting as the controller/commissioner?
  2. what is the other side of the connection? Is it a separate piece of hardware or are you trying to run the device and the controller on the same hardware? If so, what's the setup there?

If you're a CSA member, I would also suggest getting onto the slack.

@mossmgr
Copy link

mossmgr commented Nov 23, 2022

Yes the logs are coming from the python code. I tried to follow the documentation and I noticed that chip-repl has replaced chip-device-ctrl but I needed the device to act as a commissioner and there were some features in chip-repl which as of now do not exist in chip-repl. In any case I had a problem with MDNS, as the logs show.

  1. I am trying to run a commissioner on my Device to discover Matter devices(via BLE ). The device should act as a controller/commissioner.
  2. The other side of the connection as of now is nothing, I either have to create a dummy device to simulate a matter compatible device (client) or buy a raspberry pie. But currently i have no end device ( just want to test if commissioner runs on my Edge computer)

Thank you.

@cecille
Copy link
Contributor

cecille commented Nov 23, 2022

Which features do you need that are not available in chip-repl? Commissioning is definitely supported.

When you start the repl, an object called devCtrl is created. You can call a number of different commissioning options there. The code offers commissioning helpers at several granularities. For the most part, if you're just looking to commission a device, you would just call either CommissionWifi or CommissionWithCode, depending on what you wanted to do.

To do the equivalent using chip-tool (C++ tool):
build it using:
./gn_build.sh
then if you're sure you definitely want to set up with ble:
./out/debug/standalone/chip-tool pairing ble-wifi <nodeid> <ssid> <password> <setup-pin-code> <discriminator>
or if you prefer using the code (commissioner will look on the network as well):
./out/debug/standalone/chip-tool pairing code-wifi <node-id> <ssid> <password> <payload>
where payload is the QR or manual setup code.

If you're simulating a matter device, you're talking about the server side (mostly). The commissioner/controller is the client side. You won't be able to test any of the actual commissioning code without an end device. Both the repl and chip-tool will fail out saying they can't find the device, so you're not going to be testing much. If you're using linux, you can run a simulated device on the same system as the commissioner. Most people use either the all-cluster or lighting example for basic testing. You can build that either using the scripts/build/build_examples.py script, or just using ninja directly. If you run that in a separate terminal, you can commission between them. The caveat here is that you will NOT be using BLE commissioning - you will be using on-network commissioning. If you want to test BLE, you need a separate BLE-capable device.

@mossmgr
Copy link

mossmgr commented Nov 24, 2022

Thanks for the comprehensive answer. Now logically i have a clear idea about my test scenario. However the issue that i originally had persists. I followed the python guide on building python_env for testing, when i try to run chip-device-ctrl > ble-scan the result is not a logical error ( the chip controller can not find a matter accessory because it does not exist), the result is a programming error which is written below:

Exception ignored in: <function FabricAdmin.__del__ at 0xb5a47028> Traceback (most recent call last): File "/root/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 125, in __del__ self.Shutdown() File "/root/connectedhomeip/out/python_env/lib/python3.9/site-packages/chip/FabricAdmin.py", line 118, in Shutdown if (self._isActive): AttributeError: 'FabricAdmin' object has no attribute '_isActive'

and If i run the chip-device-ctrl without any arguments I get this python error:
__init__() missing 1 required positional argument: 'vendorId' Failed to bringup CHIPDeviceController CLI

Now according to your suggestions I can just use chip-repl instead of chip-device-ctrl ... i get that but it would be nice to either change the guide or fix the issues with the chip-device-ctrl code.

@mossmgr
Copy link

mossmgr commented Nov 24, 2022

Update: I build the 'chip-all-clusters-app' on my Macbook (intel) and i am running the executable. It is advertising on the local network. I also compiled the chip-tool for my arm device and try to commission over WIFI the chip-all-clusters-app .

When i run ./chip-tool pairing onnetwork 333221 20202021 I expect that the all clusters app would be commissioned into the network. however this does not happen. instead i receive Timeout waiting for mDNS resolution.

and finally the last log i receive from the chip-tool is this:
CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:513: CHIP Error 0x00000032: Timeout

P.S: the chip-repl tool gives me no CommissionableNode (empty arrary) when i run devCtrl.DiscoverCommissionableNodes()

@cecille
Copy link
Contributor

cecille commented Nov 24, 2022

The guide has been updated to indicate that chip-device-ctrl is deprecated.

Can you post the logs from both sides, and indicate how you determined that all-clusters was advertising?

@mossmgr
Copy link

mossmgr commented Nov 24, 2022

Yes. After a system shutdown, I tried the chip-all-clusters project again and now I am able to see the listed device in the output of the chip-tool discover commissionables however the last output log of chip-tool is still Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:513: CHIP Error 0x00000032: Timeout

The output of chip-all-clusters-app running on my Macbook.

[1669303867834] [6383:43091] CHIP: [DL] KVS will be written to: file:///tmp/chip_kvs
[1669303867855] [6383:43091] CHIP: [SPT] *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. ***
[1669303867855] [6383:43091] CHIP: [SPT] *** WARNING: Using temporary test discriminator 3840 due to --discriminator not given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure discriminator. ***
[1669303867855] [6383:43091] CHIP: [SPT] PASE PBKDF iterations set to 1000
[1669303867855] [6383:43091] CHIP: [SPT] LinuxCommissionableDataProvider didn't get a PASE salt, generating one.
[1669303867859] [6383:43091] CHIP: [DL] Device Configuration:
[1669303867860] [6383:43091] CHIP: [DL] Serial Number: TEST_SN
[1669303867860] [6383:43091] CHIP: [DL] Vendor Id: 65521 (0xFFF1)
[1669303867861] [6383:43091] CHIP: [DL] Product Id: 32769 (0x8001)
[1669303867861] [6383:43091] CHIP: [DL] Hardware Version: 0
[1669303867861] [6383:43091] CHIP: [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1669303867861] [6383:43091] CHIP: [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1669303867862] [6383:43091] CHIP: [DL] Manufacturing Date: (not set)
[1669303867862] [6383:43091] CHIP: [DL] Device Type: 65535 (0xFFFF)
[1669303867862] [6383:43091] CHIP: [-] ==== Onboarding payload for Standard Commissioning Flow ====
[1669303867863] [6383:43091] CHIP: [SVR] SetupQRCode: [MT:-24J0AFN00KA0648G00]
[1669303867863] [6383:43091] CHIP: [SVR] Copy/paste the below URL in a browser to see the QR Code:
[1669303867863] [6383:43091] CHIP: [SVR] https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0AFN00KA0648G00
[1669303867863] [6383:43091] CHIP: [SVR] Manual pairing code: [34970112332]
[1669303867863] [6383:43091] CHIP: [SVR] Server initializing...
[1669303867863] [6383:43091] CHIP: [FP] Initializing FabricTable from persistent storage
[1669303867864] [6383:43091] CHIP: [TS] Last Known Good Time: 2022-11-24T11:51:28
[1669303867864] [6383:43091] CHIP: [DMG] AccessControl: initializing
[1669303867864] [6383:43091] CHIP: [DMG] Examples::AccessControlDelegate::Init
[1669303867864] [6383:43091] CHIP: [DMG] AccessControl: setting
[1669303867864] [6383:43091] CHIP: [DMG] DefaultAclStorage: initializing
[1669303867865] [6383:43091] CHIP: [DMG] DefaultAclStorage: 0 entries loaded
[1669303867865] [6383:43091] CHIP: [IN] UDP::Init bind&listen port=5540
[1669303867865] [6383:43091] CHIP: [IN] UDP::Init bound to port=5540
[1669303867865] [6383:43091] CHIP: [IN] UDP::Init bind&listen port=5540
[1669303867865] [6383:43091] CHIP: [IN] UDP::Init bound to port=5540
[1669303867865] [6383:43091] CHIP: [IN] TransportMgr initialized
[1669303867871] [6383:43091] CHIP: [ZCL] Using ZAP configuration...
[1669303867871] [6383:43091] CHIP: [DMG] Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867872] [6383:43091] CHIP: [DMG] Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867873] [6383:43091] CHIP: [DMG] Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867873] [6383:43091] CHIP: [DMG] Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867873] [6383:43091] CHIP: [DMG] Failed to read stored attribute (0, 0x0000_002D, 0x0000_0000: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867874] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867874] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867875] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867875] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0050, 0x0000_0003: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867876] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0050, 0x0000_0004: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867876] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0050, 0x0000_0005: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867876] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0003: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867877] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0004: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867877] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0005: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867878] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0006: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867879] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0008: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867879] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0009: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867880] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_000E: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867880] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_000F: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867880] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0010: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867881] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0011: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867883] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0012: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867884] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0013: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867884] [6383:43091] CHIP: [DMG] Failed to read stored attribute (1, 0x0000_0102, 0x0000_0017: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867884] [6383:43091] CHIP: [DMG] AccessControlCluster: initializing
[1669303867884] [6383:43091] CHIP: [ZCL] Initiating Admin Commissioning cluster.
[1669303867884] [6383:43091] CHIP: [ZCL] Door Lock server initialized
[1669303867884] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_0030 update version to 7790c9be
[1669303867885] [6383:43091] CHIP: [ZCL] GeneralDiagnostics: OnDeviceReboot
[1669303867885] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_0033 update version to 574c26d6
[1669303867885] [6383:43091] CHIP: [EVL] LogEvent event number: 0x0000000000020000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x00000000002D95AF
[1669303867885] [6383:43091] CHIP: [ZCL] Initialize PCC Plugin Server Cluster.
[1669303867885] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_0003 update version to 5f38da8e
[1669303867885] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_0004 update version to 4eddf02e
[1669303867885] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_0004 update version to 4eddf02f
[1669303867886] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_002B update version to 61a21bf
[1669303867886] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0003 update version to cd2554f2
[1669303867886] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0004 update version to 4e939539
[1669303867886] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0004 update version to 4e93953a
[1669303867886] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0005 update version to 550ae119
[1669303867886] [6383:43091] CHIP: [ZCL] On/Off set value: 1 0
[1669303867886] [6383:43091] CHIP: [ZCL] On/off already set to new value
[1669303867887] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0008 update version to 9f916193
[1669303867888] [6383:43091] CHIP: [ZCL] Door Lock cluster initialized at endpoint #1
[1669303867888] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0101 update version to f453a6e7
[1669303867888] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0101 update version to f453a6e8
[1669303867888] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0101 update version to f453a6e9
[1669303867888] [6383:43091] CHIP: [EVL] LogEvent event number: 0x0000000000020001 priority: 2, endpoint id: 0x1 cluster id: 0x0000_0101 event id: 0x1 Sys timestamp: 0x00000000002D95B2
[1669303867888] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0101 update version to f453a6ea
[1669303867888] [6383:43091] CHIP: [ZCL] Initialized new lock door endpoint [id=1,users=10,credentials=10,weekDaySchedulesPerUser=10,yearDaySchedulesPerUser=10,numberOfCredentialsSupportedPerUser=5,holidaySchedules=0]
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0102 update version to 69be7417
[1669303867889] [6383:43091] CHIP: [ZCL] WC POST ATTRIBUTE=7
[1669303867889] [6383:43091] CHIP: [ZCL] ConfigStatus 0x1B Operational=1 OnlineReserved=1
[1669303867889] [6383:43091] CHIP: [ZCL] Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
[1669303867889] [6383:43091] CHIP: [ZCL] Initialize PCC Server Cluster [EP:1]
[1669303867889] [6383:43091] CHIP: [ZCL] Constant Pressure Supported
[1669303867889] [6383:43091] CHIP: [ZCL] PCC Server: Constant Proportional Pressure Supported
[1669303867889] [6383:43091] CHIP: [ZCL] PCC Server: Constant Flow Supported
[1669303867889] [6383:43091] CHIP: [ZCL] PCC Server: Constant Temperature Supported
[1669303867889] [6383:43091] CHIP: [ZCL] PCC Server: Constant Speed Supported
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0300 update version to 9c380f4a
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0300 update version to 9c380f4b
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0300 update version to 9c380f4c
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0406 update version to cd5f0598
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 1, Cluster 0x0000_0406 update version to cd5f0599
[1669303867889] [6383:43091] CHIP: [-] Setting LowPower default delegate to global manager
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 2, Cluster 0x0000_0004 update version to a9684eb7
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 2, Cluster 0x0000_0004 update version to a9684eb8
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 2, Cluster 0x0000_0406 update version to 850108a1
[1669303867889] [6383:43091] CHIP: [DMG] Endpoint 2, Cluster 0x0000_0406 update version to 850108a2
[1669303867894] [6383:43091] CHIP: [IN] SecureSession[0x611000028040]: Allocated Type:1 LSID:43963
[1669303867896] [6383:43091] CHIP: [SC] Assigned local session key ID 43963
[1669303867896] [6383:43091] CHIP: [SC] Waiting for PBKDF param request
[1669303867897] [6383:43091] CHIP: [DIS] Updating services using commissioning mode 1
[1669303867899] [6383:43091] CHIP: [DL] Using wifi MAC for hostname
[1669303867900] [6383:43091] CHIP: [DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1669303867903] [6383:43091] CHIP: [DIS] Registering service 34F44373E5AA4D0E on host F40F241B821A.local. with port 5540 and type: _matterc._udp,_V65521,_S15,_L3840,_CM on interface id: 0
[1669303867904] [6383:43091] CHIP: [DIS] Updating services using commissioning mode 1
[1669303867905] [6383:43091] CHIP: [DL] Using wifi MAC for hostname
[1669303867906] [6383:43091] CHIP: [DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1669303867906] [6383:43091] CHIP: [DIS] Registering service 34F44373E5AA4D0E on host F40F241B821A.local. with port 5540 and type: _matterc._udp,_V65521,_S15,_L3840,_CM on interface id: 0
[1669303867907] [6383:43091] CHIP: [IN] CASE Server enabling CASE session setups
[1669303867908] [6383:43091] CHIP: [IN] SecureSession[0x611000029800]: Allocated Type:2 LSID:43964
[1669303867909] [6383:43091] CHIP: [SC] Allocated SecureSession (0x611000029800) - waiting for Sigma1 msg
[1669303867909] [6383:43091] CHIP: [SVR] Joining Multicast groups
[1669303867909] [6383:43091] CHIP: [ZCL] Emitting StartUp event
[1669303867911] [6383:43091] CHIP: [EVL] LogEvent event number: 0x0000000000020002 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x00000000002D95C8
[1669303867911] [6383:43091] CHIP: [SVR] Server Listening...
[1669303867911] [6383:43091] CHIP: [DL] Device Configuration:
[1669303867911] [6383:43091] CHIP: [DL] Serial Number: TEST_SN
[1669303867912] [6383:43091] CHIP: [DL] Vendor Id: 65521 (0xFFF1)
[1669303867912] [6383:43091] CHIP: [DL] Product Id: 32769 (0x8001)
[1669303867913] [6383:43091] CHIP: [DL] Hardware Version: 0
[1669303867913] [6383:43091] CHIP: [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1669303867913] [6383:43091] CHIP: [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1669303867914] [6383:43091] CHIP: [DL] Manufacturing Date: (not set)
[1669303867914] [6383:43091] CHIP: [DL] Device Type: 65535 (0xFFFF)
[1669303867914] [6383:43091] CHIP: [SVR] SetupQRCode: [MT:-24J0AFN00KA0648G00]
[1669303867914] [6383:43091] CHIP: [SVR] Copy/paste the below URL in a browser to see the QR Code:
[1669303867914] [6383:43091] CHIP: [SVR] https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0AFN00KA0648G00
[1669303867914] [6383:43091] CHIP: [SVR] Manual pairing code: [34970112332]
[1669303867914] [6383:43091] CHIP: [DMG] Endpoint 0, Cluster 0x0000_001D update version to 1ecfdd3a
[1669303867916] [6383:43097] CHIP: [SVR] Cannot load binding table: ../../examples/all-clusters-app/linux/third_party/connectedhomeip/src/platform/Darwin/KeyValueStoreManagerImpl.mm:222: CHIP Error 0x000000A0: Value not found in the persisted storage
[1669303867916] [6383:43097] CHIP: [DIS] Updating services using commissioning mode 1
[1669303867916] [6383:43097] CHIP: [DL] Using wifi MAC for hostname
[1669303867917] [6383:43097] CHIP: [DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1669303867917] [6383:43097] CHIP: [DIS] Registering service 34F44373E5AA4D0E on host F40F241B821A.local. with port 5540 and type: _matterc._udp,_V65521,_S15,_L3840,_CM on interface id: 0
[1669303868641] [6383:43097] CHIP: [DIS] Mdns: OnRegister name: 34F44373E5AA4D0E, type: _matterc._udp., domain: local., flags: 2
[1669303868641] [6383:43097] CHIP: [DIS] mDNS service published: _matterc._udp; instance name: 34F44373E5AA4D0E
[1669303868646] [6383:43097] CHIP: [DIS] Status: Satisfied
[1669303868647] [6383:43097] CHIP: [DIS] lo0 (1)
[1669303868647] [6383:43097] CHIP: [DIS] * ipv4: 127.0.0.1
[1669303868648] [6383:43097] CHIP: [DIS] * ipv6: ::1
[1669303868648] [6383:43097] CHIP: [DIS] * ipv6: fe80::1
[1669303868650] [6383:43097] CHIP: [DIS] en0 (6 / WiFi)
[1669303868650] [6383:43097] CHIP: [DIS] * ipv4: 192.168.1.32
[1669303868650] [6383:43097] CHIP: [DIS] * ipv6: fe80::414:6ef1:239d:c35
[1669303868650] [6383:43097] CHIP: [DIS] * ipv6: fd00::4ed:e765:9a04:db1d
[1669303868650] [6383:43097] CHIP: [DIS] * ipv6: fd00:aaab::cb4:8baa:43a:6dac
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 1
[1669303868651] [6383:43097] CHIP: [DIS] Mdns: OnRegisterRecord flags: 0

and the output of the chip-tool discover commissionables command running on my Edge Computer.

[1669303884.439016][6781:6781] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1669303884.440838][6781:6781] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1669303884.441259][6781:6781] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1669303884.441602][6781:6781] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1669303884.442252][6781:6781] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-x6U26Y)
[1669303884.442763][6781:6781] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1669303884.442877][6781:6781] CHIP:DL: NVS set: chip-counters/reboot-count = 83 (0x53)
[1669303884.444013][6781:6781] CHIP:DL: Got Ethernet interface: eth0
[1669303884.444698][6781:6781] CHIP:DL: Found the primary Ethernet interface:eth0
[1669303884.445334][6781:6781] CHIP:DL: Got WiFi interface: wlan0
[1669303884.446007][6781:6781] CHIP:DL: Found the primary WiFi interface:wlan0
[1669303884.446248][6781:6781] CHIP:IN: UDP::Init bind&listen port=0
[1669303884.446493][6781:6781] CHIP:IN: UDP::Init bound to port=52033
[1669303884.446559][6781:6781] CHIP:IN: UDP::Init bind&listen port=0
[1669303884.446709][6781:6781] CHIP:IN: UDP::Init bound to port=51233
[1669303884.446753][6781:6781] CHIP:IN: BLEBase::Init - setting/overriding transport
[1669303884.446800][6781:6781] CHIP:IN: TransportMgr initialized
[1669303884.446876][6781:6781] CHIP:FP: Initializing FabricTable from persistent storage
[1669303884.447307][6781:6781] CHIP:TS: Last Known Good Time: 2022-11-03T15:31:22
[1669303884.448199][6781:6781] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xB172374CF9917A01, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1669303884.449832][6781:6781] CHIP:ZCL: Using ZAP configuration...
[1669303884.453289][6781:6781] CHIP:CTL: System State Initialized...
[1669303884.453458][6781:6781] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1669303884.453514][6781:6781] CHIP:CTL: Setting attestation nonce to random value
[1669303884.453650][6781:6781] CHIP:CTL: Setting CSR nonce to random value
[1669303884.454174][6781:6786] CHIP:DL: CHIP task running
[1669303884.455066][6781:6786] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1669303884.455295][6781:6786] CHIP:CTL: Setting attestation nonce to random value
[1669303884.455970][6781:6786] CHIP:CTL: Setting CSR nonce to random value
[1669303884.465251][6781:6786] CHIP:CTL: Generating NOC
[1669303884.467758][6781:6786] CHIP:FP: Validating NOC chain
[1669303884.477898][6781:6786] CHIP:FP: NOC chain validation successful
[1669303884.479152][6781:6786] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1669303884.479509][6781:6786] CHIP:TS: Last Known Good Time: 2022-11-03T15:31:22
[1669303884.479580][6781:6786] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1669303884.479743][6781:6786] CHIP:TS: Retaining current Last Known Good Time
[1669303884.481229][6781:6786] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1669303884.482592][6781:6786] CHIP:TS: Committing Last Known Good Time to storage: 2022-11-03T15:31:22
[1669303884.483999][6781:6786] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1669303884.703001][6781:6786] CHIP:DIS: Discovered node:
[1669303884.703221][6781:6786] CHIP:DIS: Hostname: F40F241B821A
[1669303884.703690][6781:6786] CHIP:DIS: IP Address #1: fd00::4ed:e765:9a04:db1d
[1669303884.703764][6781:6786] CHIP:DIS: IP Address #2: fd00:aaab::cb4:8baa:43a:6dac
[1669303884.703810][6781:6786] CHIP:DIS: IP Address #3: fe80::414:6ef1:239d:c35
[1669303884.703848][6781:6786] CHIP:DIS: IP Address #4: 192.168.1.32
[1669303884.703871][6781:6786] CHIP:DIS: Port: 5540
[1669303884.703890][6781:6786] CHIP:DIS: Mrp Interval idle: not present
[1669303884.703909][6781:6786] CHIP:DIS: Mrp Interval active: not present
[1669303884.703929][6781:6786] CHIP:DIS: TCP Supported: 1
[1669303884.703955][6781:6786] CHIP:DIS: Vendor ID: 65521
[1669303884.703975][6781:6786] CHIP:DIS: Product ID: 32769
[1669303884.703992][6781:6786] CHIP:DIS: Long Discriminator: 3840
[1669303884.704010][6781:6786] CHIP:DIS: Pairing Hint: 33
[1669303884.704028][6781:6786] CHIP:DIS: Instance Name: 34F44373E5AA4D0E
[1669303884.704047][6781:6786] CHIP:DIS: Commissioning Mode: 1
[1669303884.706817][6781:6786] CHIP:DIS: Discovered node:
[1669303884.706924][6781:6786] CHIP:DIS: Hostname: F40F241B821A
[1669303884.706985][6781:6786] CHIP:DIS: IP Address #1: fd00::4ed:e765:9a04:db1d
[1669303884.707029][6781:6786] CHIP:DIS: IP Address #2: fd00:aaab::cb4:8baa:43a:6dac
[1669303884.707059][6781:6786] CHIP:DIS: IP Address #3: fe80::414:6ef1:239d:c35
[1669303884.707153][6781:6786] CHIP:DIS: IP Address #4: 192.168.1.32
[1669303884.707176][6781:6786] CHIP:DIS: Port: 5540
[1669303884.707195][6781:6786] CHIP:DIS: Mrp Interval idle: not present
[1669303884.707227][6781:6786] CHIP:DIS: Mrp Interval active: not present
[1669303884.707256][6781:6786] CHIP:DIS: TCP Supported: 1
[1669303884.707277][6781:6786] CHIP:DIS: Vendor ID: 65521
[1669303884.707295][6781:6786] CHIP:DIS: Product ID: 32769
[1669303884.707312][6781:6786] CHIP:DIS: Long Discriminator: 3840
[1669303884.707331][6781:6786] CHIP:DIS: Pairing Hint: 33
[1669303884.707348][6781:6786] CHIP:DIS: Instance Name: 34F44373E5AA4D0E
[1669303884.707366][6781:6786] CHIP:DIS: Commissioning Mode: 1
[1669303884.709944][6781:6786] CHIP:DIS: Discovered node:
[1669303884.710049][6781:6786] CHIP:DIS: Hostname: F40F241B821A
[1669303884.710107][6781:6786] CHIP:DIS: IP Address #1: fd00::4ed:e765:9a04:db1d
[1669303884.710154][6781:6786] CHIP:DIS: IP Address #2: fd00:aaab::cb4:8baa:43a:6dac
[1669303884.710182][6781:6786] CHIP:DIS: IP Address #3: fe80::414:6ef1:239d:c35
[1669303884.710204][6781:6786] CHIP:DIS: IP Address #4: 192.168.1.32
[1669303884.710224][6781:6786] CHIP:DIS: Port: 5540
[1669303884.710244][6781:6786] CHIP:DIS: Mrp Interval idle: not present
[1669303884.710281][6781:6786] CHIP:DIS: Mrp Interval active: not present
[1669303884.710309][6781:6786] CHIP:DIS: TCP Supported: 1
[1669303884.710328][6781:6786] CHIP:DIS: Vendor ID: 65521
[1669303884.710346][6781:6786] CHIP:DIS: Product ID: 32769
[1669303884.710363][6781:6786] CHIP:DIS: Long Discriminator: 3840
[1669303884.710381][6781:6786] CHIP:DIS: Pairing Hint: 33
[1669303884.710399][6781:6786] CHIP:DIS: Instance Name: 34F44373E5AA4D0E
[1669303884.710417][6781:6786] CHIP:DIS: Commissioning Mode: 1
[1669303884.761054][6781:6786] CHIP:DIS: Discovered node:
[1669303884.761166][6781:6786] CHIP:DIS: Hostname: F40F241B821A
[1669303884.761221][6781:6786] CHIP:DIS: IP Address #1: fd00::4ed:e765:9a04:db1d
[1669303884.761265][6781:6786] CHIP:DIS: IP Address #2: fd00:aaab::cb4:8baa:43a:6dac
[1669303884.761295][6781:6786] CHIP:DIS: IP Address #3: fe80::414:6ef1:239d:c35
[1669303884.761319][6781:6786] CHIP:DIS: IP Address #4: 192.168.1.32
[1669303884.761338][6781:6786] CHIP:DIS: Port: 5540
[1669303884.761357][6781:6786] CHIP:DIS: Mrp Interval idle: not present
[1669303884.761375][6781:6786] CHIP:DIS: Mrp Interval active: not present
[1669303884.761392][6781:6786] CHIP:DIS: TCP Supported: 1
[1669303884.761421][6781:6786] CHIP:DIS: Vendor ID: 65521
[1669303884.761449][6781:6786] CHIP:DIS: Product ID: 32769
[1669303884.761467][6781:6786] CHIP:DIS: Long Discriminator: 3840
[1669303884.761485][6781:6786] CHIP:DIS: Pairing Hint: 33
[1669303884.761503][6781:6786] CHIP:DIS: Instance Name: 34F44373E5AA4D0E
[1669303884.761522][6781:6786] CHIP:DIS: Commissioning Mode: 1
[1669303914.456131][6781:6781] CHIP:CTL: Shutting down the commissioner
[1669303914.456487][6781:6781] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1669303914.456693][6781:6781] CHIP:CTL: Shutting down the controller
[1669303914.456829][6781:6781] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1669303914.456961][6781:6781] CHIP:FP: Forgetting fabric 0x1
[1669303914.457164][6781:6781] CHIP:TS: Pending Last Known Good Time: 2022-11-03T15:31:22
[1669303914.458156][6781:6781] CHIP:TS: Previous Last Known Good Time: 2022-11-03T15:31:22
[1669303914.458531][6781:6781] CHIP:TS: Reverted Last Known Good Time to previous value
[1669303914.459030][6781:6781] CHIP:CTL: Shutting down the commissioner
[1669303914.459575][6781:6781] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1669303914.459872][6781:6781] CHIP:CTL: Shutting down the controller
[1669303914.460114][6781:6781] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1669303914.462152][6781:6781] CHIP:DMG: IM WH moving to [Uninitialized]
[1669303914.462431][6781:6781] CHIP:DMG: IM WH moving to [Uninitialized]
[1669303914.462729][6781:6781] CHIP:DMG: IM WH moving to [Uninitialized]
[1669303914.463012][6781:6781] CHIP:DMG: IM WH moving to [Uninitialized]
[1669303914.463422][6781:6781] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1669303914.464428][6781:6781] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1669303914.465253][6781:6781] CHIP:FP: Shutting down FabricTable
[1669303914.465636][6781:6781] CHIP:TS: Pending Last Known Good Time: 2022-11-03T15:31:22
[1669303914.466588][6781:6781] CHIP:TS: Previous Last Known Good Time: 2022-11-03T15:31:22
[1669303914.466825][6781:6781] CHIP:TS: Reverted Last Known Good Time to previous value
[1669303914.468327][6781:6781] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vQ1LuV)
[1669303914.470003][6781:6781] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1669303914.470391][6781:6781] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1669303914.470698][6781:6781] CHIP:DL: Inet Layer shutdown
[1669303914.470881][6781:6781] CHIP:DL: BLE shutdown
[1669303914.471042][6781:6781] CHIP:DL: System Layer shutdown
[1669303914.471740][6781:6781] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:513: CHIP Error 0x00000032: Timeout

Update: Chip-tool pairing works. :) and I was able to send an onoff toggle command to the (chip-all-cluster) app.

Thank you for the help. Only issue is the time out error with the discovery command of the chip-tool. The last line of the above mentioned Console log.

@cecille
Copy link
Contributor

cecille commented Nov 24, 2022

Good to hear. If you check the logs, it looks like the discover command was able to find things. Not sure why it's giving a timeout at the end, but if you're able to commission then the commissioner and device are both fine.

@tunm1228
Copy link

tunm1228 commented Oct 3, 2023

Good to hear. If you check the logs, it looks like the discover command was able to find things. Not sure why it's giving a timeout at the end, but if you're able to commission then the commissioner and device are both fine.

Pair devices via IP. Specifically the KNX device. It has a control address of "1/1/1". I don't know how to put it together. Please guide me

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants