search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.34k stars 1.97k forks source link

[1.2] I can't add device to chip-tool #35663

Open yiwang103 opened 1 day ago

yiwang103 commented 1 day ago

Reproduction steps

I'm maybe first add device to chip-tool is success, and not delete device, but factory reset device. Then second add device to chip-tool is failed, and it has been a failure. I try factory reset device or gateway, still no use. But change gateway occasionally can success.

Bug prevalence

if appear, on once gateway, always

GitHub hash of the SDK that was being used

181b0cb14ff007ec912f2ba6627e05dfb066c008

Platform

freeRTOS

Platform Version(s)

No response

Type

Core SDK Interopability Issue

Anything else?

[1726197597.300182][45989:46000] CHIP:CTL: Setting thread operational dataset from parameters [1726197597.300264][45989:46000] CHIP:CTL: Setting attestation nonce to random value [1726197597.300395][45989:46000] CHIP:CTL: Setting CSR nonce to random value [1726197597.300544][45989:46000] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1726197597.300589][45989:46000] CHIP:CTL: Starting commissioning discovery over BLE [1726197597.300640][45989:46000] CHIP:CTL: Starting commissioning discovery over DNS-SD [2024-09-13 11:19:57.325] [info] topic: redbox-middlerware/report [2024-09-13 11:19:57.325] [info] payload: {"module":"redbox-middlerware","method":"reply","timestamp":1726197597286,"commandId":5151,"version":1,"manfName":"redbox","payload":{"type":"thread","open_network":"","status":0}} [2024-09-13 11:19:57.325] [info] web topic response or report [1726197597.340570][45989:45999] CHIP:BLE: BLE removing known devices. [1726197597.360335][45989:45999] CHIP:BLE: BLE initiating scan. [1726197597.974667][45989:46000] CHIP:DL: Long dispatch time: 673 ms, for event type 2 [1726197597.975172][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649969 on exchange 57720i Send Cnt 2 [1726197598.019010][45989:46000] CHIP:DMG: OnResubscribeTimerCallback: ForceCASE = 1 [1726197598.019212][45989:46000] CHIP:DMG: Trying to establish a CASE session for subscription [1726197598.019264][45989:46000] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1726197598.019323][45989:46000] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1726197598.019474][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1726197598.024548][45989:46000] CHIP:DIS: Lookup clearing interface for non LL address [1726197598.024792][45989:46000] CHIP:DIS: UDP:[fd7b:e51c:20f5:1:eab4:3de4:c014:c6e7%eth0]:5540: new best score: 5 [1726197598.024901][45989:46000] CHIP:DIS: Checking node lookup status after 5 ms [1726197598.024932][45989:46000] CHIP:DIS: Keeping DNSSD lookup active [1726197598.026541][45989:46000] CHIP:DIS: UDP:[fd7b:e51c:20f5:1:eab4:3de4:c014:c6e7%eth0]:5540: score has not improved: 5 [1726197598.026654][45989:46000] CHIP:DIS: Checking node lookup status after 7 ms [1726197598.026673][45989:46000] CHIP:DIS: Keeping DNSSD lookup active [1726197598.089368][45989:45999] CHIP:BLE: Device 6D:42:CF:95:9F:CB does not look like a CHIP device. [1726197598.175727][45989:45999] CHIP:BLE: New device scanned: E9:91:0E:20:AD:8B [1726197598.175867][45989:45999] CHIP:BLE: Device discriminator match. Attempting to connect. [1726197598.220633][45989:46000] CHIP:DIS: Checking node lookup status after 201 ms [1726197598.220901][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd7b:e51c:20f5:1:eab4:3de4:c014:c6e7]:5540 while in state 2 [1726197598.221044][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1726197598.221571][45989:46000] CHIP:IN: SecureSession[0x7f7c0db310]: Allocated Type:2 LSID:41948 [1726197598.221813][45989:46000] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1726197598.237151][45989:46000] CHIP:EM: <<< [E:57721i S:0 M:154649970] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd7b:e51c:20f5:1:eab4:3de4:c014:c6e7]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1726197598.237708][45989:46000] CHIP:SC: Sent Sigma1 msg [1726197598.237771][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1726197599.173903][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649970 on exchange 57721i Send Cnt 1 [1726197599.258589][45989:45999] CHIP:DL: ConnectDevice complete [1726197599.509173][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649969 on exchange 57720i Send Cnt 3 [1726197599.564506][45989:45999] CHIP:DL: Char /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a on service /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a [1726197599.564912][45989:45999] CHIP:DL: Char /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service0006 on service /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a [1726197599.564948][45989:45999] CHIP:DL: Char /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service0006 on service /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a [1726197599.565016][45989:45999] CHIP:DL: Char /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a on service /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a [1726197599.565039][45989:45999] CHIP:DL: Char /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a on service /org/bluez/hci0/dev_E9_91_0E_20_AD_8B/service000a [1726197599.565083][45989:45999] CHIP:DL: New BLE connection: conn 0x7f7806fc20, device E9:91:0E:20:AD:8B, path /org/bluez/hci0/dev_E9_91_0E_20_AD_8B [1726197599.565315][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1726197599.565352][45989:46000] CHIP:CTL: Discovered device to be commissioned over BLE [1726197599.565411][45989:46000] CHIP:CTL: Attempting PASE connection to BLE [1726197599.565525][45989:46000] CHIP:IN: BleConnectionComplete: endPoint 0x5560d66d78 [1726197599.566703][45989:46000] CHIP:IN: SecureSession[0x7f7c045ed0]: Allocated Type:1 LSID:41949 [1726197599.566820][45989:46000] CHIP:SC: Assigned local session key ID 41949 [1726197599.567100][45989:46000] CHIP:EM: <<< [E:57722i S:0 M:154649971] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1726197599.567189][45989:46000] CHIP:IN: Message appended to BLE send queue [1726197599.567216][45989:46000] CHIP:SC: Sent PBKDF param request [1726197599.567265][45989:46000] CHIP:CTL: Commissioning already in progress - not restarting [1726197599.567312][45989:46000] CHIP:-: src/controller/CHIPDeviceController.cpp:838: CHIP Error 0x00000003: Incorrect state at src/controller/SetUpCodePairer.cpp:280 [1726197599.885618][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197599.976032][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197599.976060][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1726197599.976308][45989:46000] CHIP:BLE: subscribe complete, ep = 0x5560d66d78 [1726197599.976348][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197599.976385][45989:46000] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1726197599.976406][45989:46000] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1726197599.976423][45989:46000] CHIP:BLE: local and remote recv window size = 5 [1726197599.977215][45989:46000] CHIP:IN: BLE EndPoint 0x5560d66d78 Connection Complete [1726197600.066232][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197600.068754][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649970 on exchange 57721i Send Cnt 2 [1726197600.115444][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197600.115996][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197600.116435][45989:46000] CHIP:EM: >>> [E:57722i S:0 M:191653140] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1726197600.116538][45989:46000] CHIP:EM: Found matching exchange: 57722i, Delegate: 0x7f7c16f000 [1726197600.116656][45989:46000] CHIP:SC: Received PBKDF param response [1726197600.116797][45989:46000] CHIP:SC: Peer assigned session ID 58912 [1726197600.116876][45989:46000] CHIP:SC: Found MRP parameters in the message [1726197600.210680][45989:46000] CHIP:EM: <<< [E:57722i S:0 M:154649972] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1726197600.212405][45989:46000] CHIP:SC: Sent spake2p msg1 [1726197600.289608][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 ^[[6~^[[5~-369[1726197600.472562][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197600.473038][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197600.473417][45989:46000] CHIP:EM: >>> [E:57722i S:0 M:191653141] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1726197600.473497][45989:46000] CHIP:EM: Found matching exchange: 57722i, Delegate: 0x7f7c16f000 [1726197600.473571][45989:46000] CHIP:SC: Received spake2p msg2 [1726197600.490369][45989:46000] CHIP:EM: <<< [E:57722i S:0 M:154649973] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1726197600.491502][45989:46000] CHIP:SC: Sent spake2p msg3 [1726197600.560219][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197600.608740][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197600.609323][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197600.610107][45989:46000] CHIP:EM: >>> [E:57722i S:0 M:191653142] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1726197600.610223][45989:46000] CHIP:EM: Found matching exchange: 57722i, Delegate: 0x7f7c16f000 [1726197600.611250][45989:46000] CHIP:SC: SecureSession[0x7f7c045ed0, LSID:41949]: State change 'kEstablishing' --> 'kActive' [1726197600.611371][45989:46000] CHIP:IN: SecureSession[0x7f7c045ed0]: Activated - Type:1 LSID:41949 [1726197600.611492][45989:46000] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:41949 PSID:58912! [1726197600.611569][45989:46000] CHIP:CTL: Remote device completed SPAKE2+ handshake [1726197600.611601][45989:46000] CHIP:TOO: Pairing Success [1726197600.611625][45989:46000] CHIP:TOO: PASE establishment successful [1726197601.682024][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649970 on exchange 57721i Send Cnt 3 [1726197602.017779][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649969 on exchange 57720i Send Cnt 4 [1726197603.215093][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197604.174733][45989:46000] CHIP:EM: Retransmitting MessageCounter:154649970 on exchange 57721i Send Cnt 4 ^[[5~9[1726197605.682099][45989:46000] CHIP:EM: Failed to Send CHIP MessageCounter:154649969 on exchange 57720i sendCount: 4 max retries: 4 [1726197605.690887][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197605.691298][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197607.771127][45989:46000] CHIP:DMG: OnResubscribeTimerCallback: ForceCASE = 1 [1726197607.771361][45989:46000] CHIP:DMG: Trying to establish a CASE session for subscription [1726197607.771411][45989:46000] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1726197608.255631][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197608.357409][45989:46000] CHIP:EM: Failed to Send CHIP MessageCounter:154649970 on exchange 57721i sendCount: 4 max retries: 4 [1726197609.110901][45989:46000] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 4 [1726197609.111138][45989:46000] CHIP:IN: SecureSession[0x7f7c0db210]: Released - Type:2 LSID:41947 [1726197609.111331][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 4 --> 2 [1726197609.111458][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 2 --> 1 [1726197609.111612][45989:46000] CHIP:DMG: Failed to establish CASE for re-subscription with error 'src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout' [1726197609.111795][45989:46000] CHIP:DMG: MoveToState ReadClient[0x7f7c0d83d0]: Moving to [ Idle] [1726197609.112049][45989:46000] CHIP:DMG: Will try to resubscribe to 01:0000000000000002 at retry index 5 after 38868ms due to error src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout [1726197609.112144][45989:46000] CHIP:IN: SecureSession[0x7f7c045dd0]: MarkAsDefunct Type:2 LSID:41932 [1726197609.112267][45989:46000] CHIP:DMG: Failed to establish CASE for re-subscription with error 'src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout' [1726197609.112343][45989:46000] CHIP:DMG: MoveToState ReadClient[0x7f7c0d8010]: Moving to [ Idle] [1726197609.112482][45989:46000] CHIP:DMG: Will try to resubscribe to 01:0000000000000002 at retry index 5 after 34319ms due to error src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout [1726197609.112570][45989:46000] CHIP:IN: SecureSession[0x7f7c045dd0]: MarkAsDefunct Type:2 LSID:41932 5b[1726197610.732486][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197610.732979][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197611.506465][45989:46000] CHIP:SC: CASESession timed out while waiting for a response from the peer. Current state was 4 [1726197611.506686][45989:46000] CHIP:IN: SecureSession[0x7f7c0db310]: Released - Type:2 LSID:41948 [1726197611.506885][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 2 [1726197611.507014][45989:46000] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 1 [1726197611.507166][45989:46000] CHIP:DMG: Failed to establish CASE for re-subscription with error 'src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout' [1726197611.507243][45989:46000] CHIP:DMG: MoveToState ReadClient[0x7f7c0403f0]: Moving to [ Idle] [1726197611.507491][45989:46000] CHIP:DMG: Will try to resubscribe to 01:0000000000000001 at retry index 7 after 70074ms due to error src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout [1726197611.507591][45989:46000] CHIP:IN: SecureSession[0x7f7c016a30]: MarkAsDefunct Type:2 LSID:41930 [1726197613.296094][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197615.769870][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197615.770271][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 ^[^[[24~^[a[1726197617.975512][45989:46000] CHIP:CTL: Commissioning discovery over BLE failed: src/platform/Linux/bluez/ChipDeviceScanner.cpp:173: CHIP Error 0x00000032: Timeout [1726197617.975724][45989:46000] CHIP:-: src/platform/Linux/bluez/ChipDeviceScanner.cpp:173: CHIP Error 0x00000032: Timeout at src/controller/SetUpCodePairer.cpp:324 [1726197617.975794][45989:46000] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:173: CHIP Error 0x00000032: Timeout [1726197618.336466][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 A[1726197620.812730][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197620.813376][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197623.376389][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1726197625.852422][45989:45999] CHIP:DL: Indication received, conn = 0x7f7806fc20 [1726197625.852914][45989:46000] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1726197627.301985][45989:46000] CHIP:CTL: Discovery timed out [1726197627.302112][45989:46000] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1726197627.302135][45989:46000] CHIP:TOO: Secure Pairing Failed [1726197627.302147][45989:46000] CHIP:TOO: LogJoinFail [1726197627.302350][45989:46000] CHIP:TOO: Command: {"join":{"error":1}} [2024-09-13 11:20:27.302] [info] error: 1

bzbarsky-apple commented 20 hours ago

When you commission the second time, are you trying to use the same node ID as before? If so, you might be running into cached DNS-SD advertisement issues....