Error on commissioning step 'FindOperational' while pairing matter sample over ble-thread

Hi,

I'm following this tutorial https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.0.0/nrf/ug_matter.html - I use the nrf52840 dongle as a co-processor connected to a raspberry pi running OTBR, nrf52840 DK flashed with matter door lock sample and I downloaded chip tool (release version 2.0.0) on my laptop with Linux. I want to connect the door lock sample to OTBR as described here. Unfortunately, step 6 causes the problem. When I execute this command:

./chip-tool-release pairing ble-thread 1000 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd05128ef262a22b051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840

I get the following error:

CHIP:DIS: Operational discovery failed for 0x00000000000003E8: ../../src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout

and I have no idea what should be wrong. (Does it mean there is something wrong with OTBR? But if I execute `service otbr-agent status` on raspberry pi I get otbr-agent is running and for command `ot-ctl state` the response is Leader.

Can anybody help me figure it out? Thank you.

If you want to see full output from the command, you can find it here.

Top Replies

Charlie over 2 years ago +1 suggested

Hi Filipmrazek, Here are some suggestions for your debugging: 1) Ensure that the chip-tool cache is cleaned after each unsuccessful command: rm -rf /tmp/chip_* 2) Ensure that the RPi OS is 64…

0 Charlie over 2 years ago

Hi Filipmrazek,

I got some explanation from our development team about your observation:

If the customer does not recommission the device after rebooting the PC which runs the chip-tool, it will not work. The default chip-tool caches all network data in `/tmp`which works like volatile memory and is cleaned with each reboot. There is not an out-of-the-box solution which would allow changing the storage type in chip-tool, and it's not possible to change the storage or the system path without altering the chip-tool source code. But note that chip-tool is more like a testing tool. In a real scenario, the ecosystem controller will most likely still be able to talk to the Matter device after it is rebooted.

Best regards,

Charlie
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 filipmrazek over 2 years ago in reply to Charlie

Hi Charlie,

thank you for your answer. If I understand your answer correctly, do I have to factory reset the nrf52840 dk and pair it again after reboot?
I understand that chip-tool is only a testing tool, but it would be nice if I could change the cache location. It's really annoying if developers want to test their network for a few days.

BTW: Is it possible to run chip-tool inside docker container with mounted volume (like -v /path/to/chache/:/tmp)? Then OS will not remove the cache. I can try it later and post the result if it's working.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 Charlie over 2 years ago

Hi Filipmrazek,

Matter is still in an active development stage. You can raise a request from here:

Issues · project-chip/connectedhomeip (github.com)

Best regards,

Charlie
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Varun2103 over 1 year ago in reply to filipmrazek

Hey hello, I'm trying to commission nanoleaf Matter bulb using OTBR in docker and chip-tool in my linux Ubuntu 22.04. Could you please look into my error and help me getting resolve of it

Tools :

1)Nanoleaf Matter Bulb A60

2)Chip-tool downloaded from https://github.com/nrfconnect/sdk-connectedhomeip/releases for ubuntu x64 machine

3)OTBR in docker, I followed this link

4)nRF52840 dongle programmed using this link https://developer.nordicsemi.com/nRF_Connect_SDK/doc/1.9.99-dev1/matter/openthread_rcp_nrf_dongle.html

The chip-tool log:

[1688390344.566519][22573:22575] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1688390344.566537][22573:22575] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1688390344.566549][22573:22575] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeThreadEnable'
[1688390344.566559][22573:22575] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeThreadEnable' -> 'ThreadNetworkEnable'
[1688390344.566570][22573:22575] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable'
[1688390344.566607][22573:22575] CHIP:DMG: ICR moving to [AddingComm]
[1688390344.566619][22573:22575] CHIP:DMG: ICR moving to [AddedComma]
[1688390344.566659][22573:22575] CHIP:EM: <<< [E:55451i S:3373 M:123627894] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1688390344.566674][22573:22575] CHIP:IN: (S) Sending msg 123627894 on secure session with LSID: 3373
[1688390344.566862][22573:22575] CHIP:DMG: ICR moving to [CommandSen]
[1688390344.566897][22573:22575] CHIP:DMG: ICR moving to [AwaitingDe]
[1688390344.655738][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390345.907482][22573:22575] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1688390345.916148][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390345.916236][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390345.916332][22573:22575] CHIP:EM: >>> [E:55451i S:3373 M:68425704] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1688390345.916348][22573:22575] CHIP:EM: Found matching exchange: 55451i, Delegate: 0x7fdab806f718
[1688390345.916361][22573:22575] CHIP:DMG: ICR moving to [ResponseRe]
[1688390345.916385][22573:22575] CHIP:DMG: InvokeResponseMessage =
[1688390345.916390][22573:22575] CHIP:DMG: {
[1688390345.916396][22573:22575] CHIP:DMG: 	suppressResponse = false, 
[1688390345.916404][22573:22575] CHIP:DMG: 	InvokeResponseIBs =
[1688390345.916421][22573:22575] CHIP:DMG: 	[
[1688390345.916430][22573:22575] CHIP:DMG: 		InvokeResponseIB =
[1688390345.916447][22573:22575] CHIP:DMG: 		{
[1688390345.916456][22573:22575] CHIP:DMG: 			CommandDataIB =
[1688390345.916468][22573:22575] CHIP:DMG: 			{
[1688390345.916477][22573:22575] CHIP:DMG: 				CommandPathIB =
[1688390345.916488][22573:22575] CHIP:DMG: 				{
[1688390345.916501][22573:22575] CHIP:DMG: 					EndpointId = 0x0,
[1688390345.916513][22573:22575] CHIP:DMG: 					ClusterId = 0x31,
[1688390345.916524][22573:22575] CHIP:DMG: 					CommandId = 0x7,
[1688390345.916535][22573:22575] CHIP:DMG: 				},
[1688390345.916549][22573:22575] CHIP:DMG: 				
[1688390345.916559][22573:22575] CHIP:DMG: 				CommandFields = 
[1688390345.916571][22573:22575] CHIP:DMG: 				{
[1688390345.916584][22573:22575] CHIP:DMG: 					0x0 = 0, 
[1688390345.916597][22573:22575] CHIP:DMG: 					0x2 = NULL
[1688390345.916609][22573:22575] CHIP:DMG: 				},
[1688390345.916617][22573:22575] CHIP:DMG: 			},
[1688390345.916628][22573:22575] CHIP:DMG: 			
[1688390345.916634][22573:22575] CHIP:DMG: 		},
[1688390345.916649][22573:22575] CHIP:DMG: 		
[1688390345.916656][22573:22575] CHIP:DMG: 	],
[1688390345.916673][22573:22575] CHIP:DMG: 	
[1688390345.916681][22573:22575] CHIP:DMG: 	InteractionModelRevision = 1
[1688390345.916689][22573:22575] CHIP:DMG: },
[1688390345.916725][22573:22575] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1688390345.916743][22573:22575] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1688390345.916756][22573:22575] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
[1688390345.916767][22573:22575] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
[1688390345.916780][22573:22575] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1688390345.916789][22573:22575] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000036]
[1688390345.916800][22573:22575] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1688390345.916817][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 1 --> 2
[1688390345.916829][22573:22575] CHIP:DIS: Resolving 75A6D801D66A1E10:0000000000000036 ...
[1688390345.917565][22573:22575] CHIP:DMG: ICR moving to [AwaitingDe]
[1688390346.117008][22573:22575] CHIP:DIS: Checking node lookup status after 200 ms
[1688390346.801105][22573:22575] CHIP:DL: Re-trying resolve
[1688390346.801749][22573:22575] CHIP:DL: Re-trying resolve
[1688390348.614817][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390348.784198][22573:22575] CHIP:DL: Avahi resolve found
[1688390348.784243][22573:22575] CHIP:DIS: Node ID resolved for 75A6D801D66A1E10:0000000000000036
[1688390348.784250][22573:22575] CHIP:DIS: 	Hostname: A6448819020DB534
[1688390348.784258][22573:22575] CHIP:DIS: 	IP Address #1: fd11:22::f222:7f86:5acf:da40
[1688390348.784263][22573:22575] CHIP:DIS: 	Port: 5540
[1688390348.784267][22573:22575] CHIP:DIS: 	Mrp Interval idle: 5000 ms
[1688390348.784273][22573:22575] CHIP:DIS: 	Mrp Interval active: 300 ms
[1688390348.784284][22573:22575] CHIP:DIS: 	TCP Supported: 0
[1688390348.784597][22573:22575] CHIP:DIS: Lookup clearing interface for non LL address
[1688390348.784634][22573:22575] CHIP:DIS: UDP:[fd11:22::f222:7f86:5acf:da40%otbr0]:5540: new best score: 4
[1688390348.784640][22573:22575] CHIP:DIS: Checking node lookup status after 2868 ms
[1688390348.784651][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: Updating device address to UDP:[fd11:22::f222:7f86:5acf:da40]:5540 while in state 2
[1688390348.784657][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 2 --> 3
[1688390348.784698][22573:22575] CHIP:IN: SecureSession[0x7fdab001bf80]: Allocated Type:2 LSID:3374
[1688390348.784719][22573:22575] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000036
[1688390348.791993][22573:22575] CHIP:EM: <<< [E:55452i S:0 M:98152631] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1688390348.792021][22573:22575] CHIP:IN: (U) Sending msg 98152631 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390348.794427][22573:22575] CHIP:SC: Sent Sigma1 msg
[1688390348.794448][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 3 --> 4
[1688390351.215770][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390351.215852][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390351.802651][22573:22575] CHIP:DL: Re-trying resolve
[1688390351.804072][22573:22575] CHIP:DL: Re-trying resolve
[1688390353.924665][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390354.538389][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152631 on exchange 55452i Send Cnt 1
[1688390354.538457][22573:22575] CHIP:IN: (U) Sending msg 98152631 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390356.484032][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390356.484113][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390356.806694][22573:22575] CHIP:DL: Avahi resolve failed
[1688390356.807345][22573:22575] CHIP:DL: Avahi resolve failed
[1688390359.188879][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390361.391289][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152631 on exchange 55452i Send Cnt 2
[1688390361.391341][22573:22575] CHIP:IN: (U) Sending msg 98152631 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390361.751860][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390361.751932][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390364.453044][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390367.055570][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390367.055640][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390369.762370][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390370.279025][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152631 on exchange 55452i Send Cnt 3
[1688390370.279088][22573:22575] CHIP:IN: (U) Sending msg 98152631 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390372.320182][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390372.320265][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390375.026790][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390377.583491][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390377.583634][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390380.290891][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390382.847408][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390382.847476][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390385.556185][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390386.483214][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152631 on exchange 55452i Send Cnt 4
[1688390386.483269][22573:22575] CHIP:IN: (U) Sending msg 98152631 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390388.110776][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390388.110817][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390390.820638][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390393.383445][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390393.383531][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390396.085136][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390398.643837][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390398.643961][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390401.349332][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390403.911652][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390403.911792][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390406.658059][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390409.215954][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390409.216083][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390411.920730][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390413.641632][22573:22575] CHIP:EM: Failed to Send CHIP MessageCounter:98152631 on exchange 55452i sendCount: 4 max retries: 4
[1688390414.523523][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390414.523598][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390417.228258][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390419.783832][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390419.783979][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390421.271661][22573:22575] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 1
[1688390421.271698][22573:22575] CHIP:IN: SecureSession[0x7fdab001bf80]: Released - Type:2 LSID:3374
[1688390421.271717][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 4 --> 2
[1688390421.271730][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 2 --> 1
[1688390421.271746][22573:22575] CHIP:DIS: OperationalSessionSetup:attempts done: 1, attempts left: 2, retry delay 1s, status src/system/SystemLayerImplSelect.cpp:167: Success
[1688390421.271753][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 1 --> 6
[1688390421.271771][22573:22575] CHIP:CTL: Session establishment failed for <0000000000000036, 1>, error: src/protocols/secure_channel/CASESession.cpp:485: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 8 seconds
[1688390421.271784][22573:22575] CHIP:CTL: Arming failsafe (68 seconds)
[1688390421.271825][22573:22575] CHIP:DMG: ICR moving to [AddingComm]
[1688390421.271838][22573:22575] CHIP:DMG: ICR moving to [AddedComma]
[1688390421.271890][22573:22575] CHIP:EM: <<< [E:55453i S:3373 M:123627895] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1688390421.271910][22573:22575] CHIP:IN: (S) Sending msg 123627895 on secure session with LSID: 3373
[1688390421.272269][22573:22575] CHIP:DMG: ICR moving to [CommandSen]
[1688390421.366506][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390421.412787][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390421.412874][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390421.412964][22573:22575] CHIP:EM: >>> [E:55453i S:3373 M:68425705] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1688390421.412980][22573:22575] CHIP:EM: Found matching exchange: 55453i, Delegate: 0x7fdab806f5b8
[1688390421.412992][22573:22575] CHIP:DMG: ICR moving to [ResponseRe]
[1688390421.413015][22573:22575] CHIP:DMG: InvokeResponseMessage =
[1688390421.413021][22573:22575] CHIP:DMG: {
[1688390421.413029][22573:22575] CHIP:DMG: 	suppressResponse = false, 
[1688390421.413035][22573:22575] CHIP:DMG: 	InvokeResponseIBs =
[1688390421.413047][22573:22575] CHIP:DMG: 	[
[1688390421.413053][22573:22575] CHIP:DMG: 		InvokeResponseIB =
[1688390421.413065][22573:22575] CHIP:DMG: 		{
[1688390421.413072][22573:22575] CHIP:DMG: 			CommandDataIB =
[1688390421.413080][22573:22575] CHIP:DMG: 			{
[1688390421.413086][22573:22575] CHIP:DMG: 				CommandPathIB =
[1688390421.413094][22573:22575] CHIP:DMG: 				{
[1688390421.413101][22573:22575] CHIP:DMG: 					EndpointId = 0x0,
[1688390421.413109][22573:22575] CHIP:DMG: 					ClusterId = 0x30,
[1688390421.413116][22573:22575] CHIP:DMG: 					CommandId = 0x1,
[1688390421.413122][22573:22575] CHIP:DMG: 				},
[1688390421.413133][22573:22575] CHIP:DMG: 				
[1688390421.413139][22573:22575] CHIP:DMG: 				CommandFields = 
[1688390421.413148][22573:22575] CHIP:DMG: 				{
[1688390421.413156][22573:22575] CHIP:DMG: 					0x0 = 0, 
[1688390421.413165][22573:22575] CHIP:DMG: 					0x1 = "" (0 chars), 
[1688390421.413173][22573:22575] CHIP:DMG: 				},
[1688390421.413178][22573:22575] CHIP:DMG: 			},
[1688390421.413187][22573:22575] CHIP:DMG: 			
[1688390421.413193][22573:22575] CHIP:DMG: 		},
[1688390421.413202][22573:22575] CHIP:DMG: 		
[1688390421.413208][22573:22575] CHIP:DMG: 	],
[1688390421.413219][22573:22575] CHIP:DMG: 	
[1688390421.413225][22573:22575] CHIP:DMG: 	InteractionModelRevision = 1
[1688390421.413230][22573:22575] CHIP:DMG: },
[1688390421.413257][22573:22575] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1688390421.413271][22573:22575] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1688390421.413286][22573:22575] CHIP:DMG: ICR moving to [AwaitingDe]
[1688390422.273282][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 6 --> 2
[1688390422.273321][22573:22575] CHIP:DIS: Resolving 75A6D801D66A1E10:0000000000000036 ...
[1688390422.274554][22573:22575] CHIP:DL: Avahi resolve found
[1688390422.274600][22573:22575] CHIP:DIS: Node ID resolved for 75A6D801D66A1E10:0000000000000036
[1688390422.274607][22573:22575] CHIP:DIS: 	Hostname: A6448819020DB534
[1688390422.274615][22573:22575] CHIP:DIS: 	IP Address #1: fd11:22::f222:7f86:5acf:da40
[1688390422.274619][22573:22575] CHIP:DIS: 	Port: 5540
[1688390422.274624][22573:22575] CHIP:DIS: 	Mrp Interval idle: 5000 ms
[1688390422.274628][22573:22575] CHIP:DIS: 	Mrp Interval active: 300 ms
[1688390422.274635][22573:22575] CHIP:DIS: 	TCP Supported: 0
[1688390422.274920][22573:22575] CHIP:DIS: Lookup clearing interface for non LL address
[1688390422.274949][22573:22575] CHIP:DIS: UDP:[fd11:22::f222:7f86:5acf:da40%otbr0]:5540: new best score: 4
[1688390422.274955][22573:22575] CHIP:DIS: Checking node lookup status after 2 ms
[1688390422.274960][22573:22575] CHIP:DIS: Keeping DNSSD lookup active
[1688390422.472919][22573:22575] CHIP:DIS: Checking node lookup status after 200 ms
[1688390422.472958][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: Updating device address to UDP:[fd11:22::f222:7f86:5acf:da40]:5540 while in state 2
[1688390422.472966][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 2 --> 3
[1688390422.473004][22573:22575] CHIP:IN: SecureSession[0x7fdab001bf80]: Allocated Type:2 LSID:3375
[1688390422.473020][22573:22575] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000036
[1688390422.479178][22573:22575] CHIP:EM: <<< [E:55454i S:0 M:98152632] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1688390422.479187][22573:22575] CHIP:IN: (U) Sending msg 98152632 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390422.481513][22573:22575] CHIP:SC: Sent Sigma1 msg
[1688390422.481518][22573:22575] CHIP:DIS: OperationalSessionSetup[1:0000000000000036]: State change 3 --> 4
[1688390424.110209][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390426.667809][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390426.667941][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390429.348639][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152632 on exchange 55454i Send Cnt 1
[1688390429.348692][22573:22575] CHIP:IN: (U) Sending msg 98152632 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390429.372749][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390431.935584][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390431.935706][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390434.680949][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390435.781223][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152632 on exchange 55454i Send Cnt 2
[1688390435.781274][22573:22575] CHIP:IN: (U) Sending msg 98152632 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390437.239768][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390437.239898][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390439.943621][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390442.499704][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390442.499787][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390444.945933][22573:22575] CHIP:EM: Retransmitting MessageCounter:98152632 on exchange 55454i Send Cnt 3
[1688390444.945987][22573:22575] CHIP:IN: (U) Sending msg 98152632 to IP address 'UDP:[fd11:22::f222:7f86:5acf:da40]:5540'
[1688390445.161771][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390447.719040][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390447.719091][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390450.424870][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390452.983724][22573:22574] CHIP:DL: Indication received, conn = 0x7fdab806d8c0
[1688390452.983847][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1688390455.688867][22573:22575] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1688390455.757115][22573:22573] CHIP:CTL: Shutting down the commissioner
[1688390455.757139][22573:22573] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1688390455.757146][22573:22573] CHIP:DIS: Closing all BLE connections
[1688390455.757157][22573:22573] CHIP:IN: Clearing BLE pending packets.
[1688390455.757348][22573:22573] CHIP:BLE: Auto-closing end point's BLE connection.
[1688390455.757359][22573:22573] CHIP:DL: Closing BLE GATT connection (con 0x7fdab806d8c0)
[1688390455.757395][22573:22574] CHIP:DL: BluezDisconnect peer=F0:82:C0:02:B4:7C
[1688390458.574152][22573:22573] CHIP:IN: SecureSession[0x7fdab000e600]: MarkForEviction Type:1 LSID:3373
[1688390458.574189][22573:22573] CHIP:SC: SecureSession[0x7fdab000e600]: Moving from state 'kActive' --> 'kPendingEviction'
[1688390458.574223][22573:22573] CHIP:IN: SecureSession[0x7fdab000e600]: Released - Type:1 LSID:3373
[1688390458.574239][22573:22573] CHIP:CTL: Shutting down the controller
[1688390458.574266][22573:22573] CHIP:IN: SecureSession[0x7fdab001bf80]: Released - Type:2 LSID:3375
[1688390458.574294][22573:22573] CHIP:CTL: Device connection failed. Error src/app/OperationalSessionSetup.cpp:438: CHIP Error 0x00000074: The operation has been cancelled
[1688390458.574305][22573:22573] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1688390458.574312][22573:22573] CHIP:FP: Forgetting fabric 0x1
[1688390458.574325][22573:22573] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1688390458.574437][22573:22574] CHIP:DL: Bluez disconnected
[1688390458.574453][22573:22574] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1688390458.574440][22573:22573] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1688390458.574484][22573:22573] CHIP:TS: Reverted Last Known Good Time to previous value
[1688390458.574501][22573:22573] CHIP:CTL: Shutting down the commissioner
[1688390458.574507][22573:22573] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1688390458.574516][22573:22573] CHIP:CTL: Shutting down the controller
[1688390458.574522][22573:22573] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1688390458.575125][22573:22573] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1688390458.575175][22573:22573] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1688390458.575198][22573:22573] CHIP:FP: Shutting down FabricTable
[1688390458.575214][22573:22573] CHIP:TS: Pending Last Known Good Time: 2023-06-01T07:38:45
[1688390458.575293][22573:22573] CHIP:TS: Previous Last Known Good Time: 2023-06-01T07:38:45
[1688390458.575301][22573:22573] CHIP:TS: Reverted Last Known Good Time to previous value
[1688390458.575463][22573:22573] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-0icr8m)
[1688390458.575750][22573:22573] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1688390458.575776][22573:22573] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1688390458.575787][22573:22573] CHIP:DL: Inet Layer shutdown
[1688390458.575795][22573:22573] CHIP:DL: BLE shutdown
[1688390458.576658][22573:22573] CHIP:DL: System Layer shutdown
[1688390458.576874][22573:22573] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:537: CHIP Error 0x00000032: Timeout

0 Varun2103 over 1 year ago in reply to filipmrazek

Hey how you got operational dataset by running the following command

sudo docker run --rm -it --privileged -d --network host --name otbr --volume /dev/ttyACM0:/dev/ttyACM0 nrfconnect/otbr:1813352 --radio-url spinel+hdlc+uart:///dev/ttyACM0 -B wlan0
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel