Tool/software:
Hi,
We buy a plug which supports Matter and then we use CC2652R to connect it.
The connection is always error and the log is like below:
[1719904325.602106][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1719904325.602421][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_tool_kvs-IAFAOP) [1719904325.602575][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_tool_kvs) [1719904325.603438][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1719904325.603488][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1719904325.604033][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1719904325.604302][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-mCjonA) [1719904325.604441][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1719904325.604841][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1719904325.605065][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_config.ini-JIOKLg) [1719904325.605511][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1719904325.605764][11928:11928] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1719904325.606085][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ENLhEm) [1719904325.606232][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1719904325.606532][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-iihgpA) [1719904325.606972][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1719904325.607163][11928:11928] CHIP:DL: NVS set: chip-factory/unique-id = "576169336BF5CFFE" [1719904325.607478][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-DKKffH) [1719904325.607868][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1719904325.608138][11928:11928] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1719904325.608317][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-CdogKP) [1719904325.608704][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1719904325.608902][11928:11928] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1719904325.609141][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fFaPhe) [1719904325.609597][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1719904325.609845][11928:11928] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1719904325.610014][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GoGIBB) [1719904325.610368][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1719904325.610562][11928:11928] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1719904325.610757][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-MDPPkP) [1719904325.611130][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1719904325.611515][11928:11928] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1719904325.611650][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_config.ini-iAMmOO) [1719904325.611885][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1719904325.611928][11928:11928] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1719904325.612019][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_config.ini-BFPkGM) [1719904325.612364][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1719904325.612434][11928:11928] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2) [1719904325.614089][11928:11928] CHIP:DL: Got Ethernet interface: eth1 [1719904325.614965][11928:11928] CHIP:DL: Found the primary Ethernet interface:eth1 [1719904325.615785][11928:11928] CHIP:DL: Got WiFi interface: ra0 [1719904325.616596][11928:11928] CHIP:DL: Found the primary WiFi interface:ra0 [1719904325.616683][11928:11928] CHIP:IN: UDP::Init bind&listen port=0 [1719904325.616751][11928:11928] CHIP:IN: UDP::Init bound to port=56865 [1719904325.616769][11928:11928] CHIP:IN: UDP::Init bind&listen port=0 [1719904325.616911][11928:11928] CHIP:IN: UDP::Init bound to port=47871 [1719904325.616940][11928:11928] CHIP:IN: BLEBase::Init - setting/overriding transport [1719904325.616978][11928:11928] CHIP:IN: TransportMgr initialized [1719904325.617013][11928:11928] CHIP:FP: Initializing FabricTable from persistent storage [1719904325.617148][11928:11928] CHIP:TS: Last Known Good Time: [unknown] [1719904325.617179][11928:11928] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48 [1719904325.618010][11928:11928] CHIP:ZCL: Using ZAP configuration... [1719904325.624743][11928:11928] CHIP:CTL: System State Initialized... [1719904325.624894][11928:11928] CHIP:CTL: Setting attestation nonce to random value [1719904325.624968][11928:11928] CHIP:CTL: Setting CSR nonce to random value [1719904325.625020][11928:11928] CHIP:IN: UDP::Init bind&listen port=5550 [1719904325.625090][11928:11928] CHIP:IN: UDP::Init bound to port=5550 [1719904325.625112][11928:11928] CHIP:IN: UDP::Init bind&listen port=5550 [1719904325.625152][11928:11928] CHIP:IN: UDP::Init bound to port=5550 [1719904325.625171][11928:11928] CHIP:IN: TransportMgr initialized [1719904325.625759][11928:11930] CHIP:DL: CHIP task running [1719904325.625862][11928:11930] CHIP:DL: On BLE platform event 32786 [1719904325.626167][11928:11930] CHIP:CTL: Setting attestation nonce to random value [1719904325.626290][11928:11930] CHIP:CTL: Setting CSR nonce to random value [1719904325.626422][11928:11930] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: src/controller/ExamplePersistentStorage.cpp:106: CHIP Error 0x000000A0: Value not found in the persisted storage [1719904325.630669][11928:11930] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: src/controller/ExamplePersistentStorage.cpp:106: CHIP Error 0x000000A0: Value not found in the persisted storage [1719904325.632177][11928:11930] CHIP:CTL: Generating RCAC [1719904325.632950][11928:11930] CHIP:CTL: Generating ICAC [1719904325.633746][11928:11930] CHIP:CTL: Generating NOC [1719904325.634496][11928:11930] CHIP:FP: Validating NOC chain [1719904325.637536][11928:11930] CHIP:FP: NOC chain validation successful [1719904325.637950][11928:11930] CHIP:FP: Added new fabric at index: 0x1 [1719904325.637981][11928:11930] CHIP:FP: Assigned compressed fabric ID: 0x85D93A56475A6C84, node ID: 0x000000000001B669 [1719904325.638011][11928:11930] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1719904325.638033][11928:11930] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1719904325.638046][11928:11930] CHIP:TS: Retaining current Last Known Good Time [1719904325.638495][11928:11930] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1719904325.639002][11928:11930] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1719904325.639491][11928:11930] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 85D93A56475A6C84) [1719904325.639549][11928:11930] CHIP:IN: UDP::Init bind&listen port=5550 [1719904325.639619][11928:11930] CHIP:IN: UDP::Init bound to port=5550 [1719904325.639643][11928:11930] CHIP:IN: UDP::Init bind&listen port=5550 [1719904325.639748][11928:11930] CHIP:IN: UDP::Init bound to port=5550 [1719904325.639766][11928:11930] CHIP:IN: TransportMgr initialized [1719904325.648816][11928:11930] CHIP:DL: Connect and resetting CC2652 [1719904326.649307][11928:11930] CHIP:CTL: Setting wifi credentials from parameters [1719904326.649357][11928:11930] CHIP:CTL: Setting attestation nonce to random value [1719904326.649407][11928:11930] CHIP:CTL: Setting CSR nonce to random value [1719904326.649433][11928:11930] CHIP:CTL: Checking ICD registration parameters [1719904326.649476][11928:11930] CHIP:CTL: Commission called for node ID 0x0000000000000002 [1719904326.649497][11928:11930] CHIP:DL: Long dispatch time: 1024 ms, for event type 2 [1719904326.649515][11928:11930] CHIP:DL: CC2652 BLE Scanning [1719904326.653862][11928:11936] CHIP:DL: Command 0xfe00 Status 0 [1719904326.655078][11928:11936] CHIP:DL: Command 0xfe51 Status 0 [1719904326.687352][11928:11936] CHIP:DL: Address DE:5E:D4:90:60:FC match discriminator 1367 [1719904331.656218][11928:11930] CHIP:DL: CC2652 BLE Stop Scanning [1719904331.656281][11928:11930] CHIP:DL: Long dispatch time: 5006 ms, for event type 3 [1719904331.656300][11928:11930] CHIP:DL: CC2652 Connecting to DE:5E:D4:90:60:FC [1719904331.659928][11928:11936] CHIP:DL: Command 0xfe52 Status 18 [1719904331.661093][11928:11936] CHIP:DL: Command 0xfe62 Status 0 [1719904331.665374][11928:11930] CHIP:DL: On BLE platform event 16385 [1719904331.665415][11928:11930] CHIP:DIS: Closing all BLE connections [1719904331.665451][11928:11930] CHIP:IN: BleConnectionComplete: endPoint 0x5568870848 [1719904331.669627][11928:11936] CHIP:DL: Command 0xfd82 Status 0 [1719904331.867293][11928:11936] CHIP:DL: Command 0xfd84 Status 0 [1719904336.563355][11928:11930] CHIP:IN: SecureSession[0x55a2e42280]: Allocated Type:1 LSID:48388 [1719904336.563409][11928:11930] CHIP:SC: Assigned local session key ID 48388 [1719904336.563509][11928:11930] CHIP:EM: <<< [E:30834i S:0 M:167250977] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1719904336.563544][11928:11930] CHIP:IN: Message appended to BLE send queue [1719904336.563559][11928:11930] CHIP:SC: Sent PBKDF param request [1719904336.563575][11928:11930] CHIP:DL: Long dispatch time: 4898 ms, for event type 16385 [1719904336.566873][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904336.763265][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904336.766347][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904336.963038][11928:11930] CHIP:DL: On BLE platform event 16388 [1719904336.963089][11928:11930] CHIP:BLE: subscribe complete, ep = 0x5568870848 [1719904336.964599][11928:11930] CHIP:DL: On BLE platform event 16389 [1719904336.964639][11928:11930] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1719904336.964655][11928:11930] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1719904336.964670][11928:11930] CHIP:BLE: local and remote recv window size = 5 [1719904336.964934][11928:11930] CHIP:IN: BLE EndPoint 0x5568870848 Connection Complete [1719904336.970198][11928:11936] CHIP:DL: Command 0xfd1e Status 0 [1719904336.976809][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904337.162992][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904337.279551][11928:11930] CHIP:DL: On BLE platform event 16389 [1719904337.279655][11928:11930] CHIP:EM: >>> [E:30834i S:0 M:78272196] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1719904337.279686][11928:11930] CHIP:EM: Found matching exchange: 30834i, Delegate: 0x55a2e411d0 [1719904337.279713][11928:11930] CHIP:SC: Received PBKDF param response [1719904337.279742][11928:11930] CHIP:SC: Peer assigned session ID 36351 [1719904337.279761][11928:11930] CHIP:SC: Found MRP parameters in the message [1719904337.285339][11928:11936] CHIP:DL: Command 0xfd1e Status 0 [1719904337.344491][11928:11930] CHIP:EM: <<< [E:30834i S:0 M:167250978] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1719904337.344844][11928:11930] CHIP:SC: Sent spake2p msg1 [1719904337.356300][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904337.463289][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904339.875812][11928:11930] CHIP:DL: On BLE platform event 16389 [1719904339.875913][11928:11930] CHIP:EM: >>> [E:30834i S:0 M:78272197] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1719904339.875944][11928:11930] CHIP:EM: Found matching exchange: 30834i, Delegate: 0x55a2e411d0 [1719904339.875970][11928:11930] CHIP:SC: Received spake2p msg2 [1719904339.877927][11928:11930] CHIP:EM: <<< [E:30834i S:0 M:167250979] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1719904339.878323][11928:11936] CHIP:DL: Command 0xfd1e Status 0 [1719904339.878433][11928:11930] CHIP:SC: Sent spake2p msg3 [1719904339.886968][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904340.063077][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904340.067835][11928:11930] CHIP:DL: On BLE platform event 16389 [1719904340.068068][11928:11930] CHIP:EM: >>> [E:30834i S:0 M:78272198] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1719904340.068211][11928:11930] CHIP:EM: Found matching exchange: 30834i, Delegate: 0x55a2e411d0 [1719904340.068367][11928:11930] CHIP:SC: SecureSession[0x55a2e42280, LSID:48388]: State change 'kEstablishing' --> 'kActive' [1719904340.068489][11928:11930] CHIP:IN: SecureSession[0x55a2e42280]: Activated - Type:1 LSID:48388 [1719904340.068555][11928:11930] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:48388 PSID:36351! [1719904340.068625][11928:11930] CHIP:CTL: Remote device completed SPAKE2+ handshake [1719904340.068688][11928:11930] CHIP:TOO: Pairing Success [1719904340.068742][11928:11930] CHIP:TOO: PASE establishment successful [1719904340.068828][11928:11930] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1719904340.068920][11928:11930] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1719904340.068985][11928:11930] CHIP:CTL: Sending read request for commissioning information [1719904340.069060][11928:11930] CHIP:DMG: SendReadRequest ReadClient[0x55a2e42900]: Sending Read Request [1719904340.069280][11928:11930] CHIP:EM: <<< [E:30835i S:48388 M:156374583] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1719904340.069614][11928:11930] CHIP:DMG: MoveToState ReadClient[0x55a2e42900]: Moving to [AwaitingIn] [1719904340.070429][11928:11936] CHIP:DL: Command 0xfd1e Status 0 [1719904340.084191][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904340.263367][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904340.885423][11928:11930] CHIP:DL: On BLE platform event 16389 [1719904340.887916][11928:11936] CHIP:DL: Command 0xfd1e Status 0 [1719904343.391248][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904343.563924][11928:11930] CHIP:DL: On BLE platform event 16387 [1719904358.397371][11928:11930] CHIP:BLE: ack recv timeout, closing ep 0x5568870848 [1719904358.397428][11928:11930] CHIP:IN: Clearing BLE pending packets. [1719904358.400484][11928:11936] CHIP:DL: Command 0xfd92 Status 0 [1719904358.563866][11928:11930] CHIP:DL: On BLE platform event 16388 [1719904358.563915][11928:11930] CHIP:BLE: Auto-closing end point's BLE connection. [1719904358.566810][11928:11936] CHIP:DL: Command 0xfe0a Status 0 [1719904358.763013][11928:11936] CHIP:DL: Endpoint disconnected 22 [1719904358.763317][11928:11930] CHIP:DL: On BLE platform event 9 [1719904370.077419][11928:11930] CHIP:DMG: Time out! failed to receive report data from Exchange: 30835i [1719904370.077502][11928:11930] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1719904370.077520][11928:11930] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2' [1719904370.077542][11928:11930] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo2' [1719904370.077565][11928:11930] CHIP:DMG: SendReadRequest ReadClient[0x55a2e420e0]: Sending Read Request [1719904370.077686][11928:11930] CHIP:EM: <<< [E:30836i S:48388 M:156374584] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [1719904370.077738][11928:11930] CHIP:CTL: Failed to send read request: src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state [1719904370.077762][11928:11930] CHIP:CTL: Error on commissioning step 'ReadCommissioningInfo2': 'src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state' [1719904370.077779][11928:11930] CHIP:CTL: Failed to perform commissioning step 3 [1719904370.077798][11928:11930] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo2' with lastErr = 'src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state' -> 'Cleanup' [1719904370.077824][11928:11930] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state' [1719904370.077841][11928:11930] CHIP:CTL: Expiring failsafe on proxy 0x55a2e41180 [1719904370.077877][11928:11930] CHIP:DMG: ICR moving to [AddingComm] [1719904370.077920][11928:11930] CHIP:DMG: ICR moving to [AddedComma] [1719904370.077973][11928:11930] CHIP:EM: <<< [E:30837i S:48388 M:156374585] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [1719904370.078021][11928:11930] CHIP:CTL: Failed to send command to disarm fail-safe: src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state [1719904370.078040][11928:11930] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1719904370.078066][11928:11930] CHIP:TOO: Device commissioning Failure: src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state [1719904370.078097][11928:11930] CHIP:DIS: Closing all BLE connections [1719904370.078114][11928:11930] CHIP:IN: SecureSession[0x55a2e42280]: MarkForEviction Type:1 LSID:48388 [1719904370.078130][11928:11930] CHIP:SC: SecureSession[0x55a2e42280, LSID:48388]: State change 'kActive' --> 'kPendingEviction' [1719904370.078210][11928:11930] CHIP:IN: SecureSession[0x55a2e42280]: Released - Type:1 LSID:48388 [1719904370.078395][11928:11928] CHIP:CTL: Shutting down the commissioner [1719904370.078496][11928:11928] CHIP:CTL: Shutting down the controller [1719904370.078516][11928:11928] CHIP:IN: Expiring all sessions for fabric 0x1!! [1719904370.078531][11928:11928] CHIP:FP: Forgetting fabric 0x1 [1719904370.078556][11928:11928] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1719904370.078668][11928:11928] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1719904370.078689][11928:11928] CHIP:TS: Reverted Last Known Good Time to previous value [1719904370.078741][11928:11928] CHIP:CTL: Shutting down the commissioner [1719904370.078809][11928:11928] CHIP:CTL: Shutting down the controller [1719904370.078830][11928:11928] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1719904370.079077][11928:11928] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1719904370.079154][11928:11928] CHIP:FP: Shutting down FabricTable [1719904370.079183][11928:11928] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1719904370.079364][11928:11928] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1719904370.079388][11928:11928] CHIP:TS: Reverted Last Known Good Time to previous value [1719904370.079709][11928:11928] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GadpMg) [1719904370.079899][11928:11928] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1719904370.079949][11928:11928] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1719904370.079973][11928:11928] CHIP:DL: Inet Layer shutdown [1719904370.079986][11928:11928] CHIP:DL: BLE shutdown [1719904370.080001][11928:11928] CHIP:DL: System Layer shutdown [1719904370.080414][11928:11928] CHIP:TOO: Run command failure: src/transport/raw/BLE.cpp:102: CHIP Error 0x00000003: Incorrect state
Do you have any comment?
