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.

Sign up for GitHub

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

Jump to bottom

Troubleshooting Re-pairing Errors with Devices #1025

Closed
joehecn opened this issue Jul 17, 2024 · 6 comments · Fixed by #1030
Closed

Troubleshooting Re-pairing Errors with Devices #1025

joehecn opened this issue Jul 17, 2024 · 6 comments · Fixed by #1030
Labels
bug Something isn't working

Comments

@joehecn
Copy link

joehecn commented Jul 17, 2024 

(base) hemiao@hemiaodeMBP matter.js % npm run shell -- --ble

> shell
> matter-run packages/matter-node-shell.js/src/app.ts --ble

2024-07-17 18:15:48.607 INFO   Node                 Storage location: .matter-shell-0 (Directory)
Started Node #0 (Type: controller) with BLE
matter-node> commission pair --ble --pairingCode 1032-742-2419 --node-id 333
2024-07-17 18:16:27.453 INFO   Node                 matter.js shell controller started for node 0
2024-07-17 18:16:27.479 INFO   SessionManager       restoring resumption record for node 333
{"discovery":{"knownAddress":"undefined","identifierData":{"shortDiscriminator":4},"discoveryCapabilities":{"ble":true,"onIpNetwork":true}},"passcode":36719818,"commissioning":{"nodeId":"333","regulatoryLocation":1,"regulatoryCountryCode":"XX"}}
2024-07-17 18:16:27.491 INFO   MatterController     Commissioning device with identifier {"shortDiscriminator":4} and 2 scanners and knownAddress "undefined"
2024-07-17 18:16:27.491 INFO   ControllerDiscovery  Start Discovering devices using identifier {"shortDiscriminator":4} ...
2024-07-17 18:16:27.597 INFO   ControllerDiscovery  Found 1 devices using identifier {"shortDiscriminator":4}
2024-07-17 18:16:27.598 INFO   MatterController     Commissioning device SII: undefined SAI: undefined SAT: undefined T: undefined DT: undefined PH: undefined ICD: undefined VP: 5120+1004 DN: undefined RI: undefined PI: undefined
2024-07-17 18:16:27.965 INFO   NobleBleClient       Peripheral  is not connectable ... ignoring
2024-07-17 18:16:28.799 INFO   BleChannel           Received Matter handshake response: 656c04f40005.
2024-07-17 18:16:30.478 INFO   PaseClient           Pase client: Paired successfully with ble:https://.
2024-07-17 18:16:30.478 INFO   SessionManager       End insecure session insecure/3160189658975615273
2024-07-17 18:16:30.479 INFO   Controller~missioner Executing commissioning step 0.1: GetInitialData
2024-07-17 18:16:31.048 INFO   Controller~missioner Executing commissioning step 3.1: GeneralCommissioning.ArmFailsafe
2024-07-17 18:16:31.166 INFO   Controller~missioner Executing commissioning step 5.1: GeneralCommissioning.ConfigureRegulatoryInformation
2024-07-17 18:16:31.347 INFO   Controller~missioner Executing commissioning step 5.2: TimeSynchronization.SynchronizeTime
2024-07-17 18:16:31.348 INFO   Controller~missioner Executing commissioning step 6.1: OperationalCredentials.DeviceAttestation
2024-07-17 18:16:32.219 INFO   Controller~missioner Executing commissioning step 7.1: OperationalCredentials.Certificates
2024-07-17 18:16:34.769 INFO   Controller~missioner Executing commissioning step 10.1: AccessControl
2024-07-17 18:16:34.770 INFO   Controller~missioner Executing commissioning step 11.1: NetworkCommissioning.Validate
2024-07-17 18:16:34.770 INFO   Controller~missioner Executing commissioning step 11.2: NetworkCommissioning.Wifi
2024-07-17 18:16:45.030 INFO   Controller~missioner Executing commissioning step 12.1: Reconnect
2024-07-17 18:16:47.365 INFO   CaseClient           Case client: Paired successfully with udp:https://fe80::3a73:eaff:fee3:b3df%en0:5540 and parameters idleIntervalMs: 500 activeIntervalMs: 300 activeThresholdMs: 4000 dataModelRevision: 17 interactionModelRevision: 11 specificationVersion: 0 maxPathsPerInvoke: 1
2024-07-17 18:16:47.378 INFO   SessionManager       End insecure session insecure/16313807091872631793
2024-07-17 18:16:47.385 INFO   Controller~missioner Executing commissioning step 15.1: GeneralCommissioning.Complete
2024-07-17 18:16:48.171 INFO   InteractionClient    Subscription successfully initialized with ID 2863562396 and maxInterval 60s.
2024-07-17 18:16:48.172 INFO   ClusterHelper        Unknown cluster 0x5 requested: UnknownCluster instance added.
2024-07-17 18:16:48.179 INFO   ClusterClient        Added unknown attribute 0x0 to cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Added unknown attribute 0x1 to cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Added unknown attribute 0x2 to cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Added unknown attribute 0x3 to cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Added unknown attribute 0x4 to cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 0 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 1 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 2 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 3 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 4 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 5 at cluster 0x5
2024-07-17 18:16:48.180 INFO   ClusterClient        Ignoring unknown command 6 at cluster 0x5
stateInformationCallback Node 333 connected
Commissioned Node: 333n
[ { deviceType: 22, revision: 1 } ]
attributeChangedCallback 333: Attribute undefined/1/768/colorTemperatureMireds changed to 500
[
   4, 29, 31, 40, 42,
  48, 49, 51, 54, 60,
  62, 63
]
Smart Bulb
Done.
matter-node> 2024-07-17 18:16:50.387 INFO   ControllerDiscovery  Found 1 devices using identifier {"shortDiscriminator":4}

matter-node> commands onoff toggle 333 1
Command Toggle 333/1/6/2 invoked 
Done.
matter-node> attributeChangedCallback 333: Attribute undefined/1/5/Unknown (0x3) changed to false
attributeChangedCallback 333: Attribute undefined/1/6/globalSceneControl changed to true
attributeChangedCallback 333: Attribute undefined/1/6/onTime changed to 0
attributeChangedCallback 333: Attribute undefined/1/5/Unknown (0x3) changed to false
attributeChangedCallback 333: Attribute undefined/1/6/onOff changed to false
attributeChangedCallback 333: Attribute undefined/1/6/onTime changed to 0
attributeChangedCallback 333: Attribute undefined/1/8/currentLevel changed to 254
attributeChangedCallback 333: Attribute undefined/1/8/remainingTime changed to 0

matter-node> commission unpair 333
stateInformationCallback Node 333 disconnected
stateInformationCallback Node 333 decommissioned
2024-07-17 18:17:19.841 INFO   MatterController     Removing commissioned node 333 from controller.
2024-07-17 18:17:19.842 INFO   SessionManager       End CASE session secure/39627
2024-07-17 18:17:19.842 INFO   Commission~ontroller Session for peer node 333 disconnected ...
2024-07-17 18:17:19.842 INFO   PairedNode           Node 333: Session disconnected
Done.
matter-node> 2024-07-17 18:17:23.747 ERROR  ExchangeManager      RetransmissionLimitReachedError
    at MessageExchange.retransmitMessage (/Users/hemiao/matter/matter.js/packages/matter.js/src/protocol/MessageExchange.ts:434:45)
    at TimerNode.callback (/Users/hemiao/matter/matter.js/packages/matter.js/src/protocol/MessageExchange.ts:459:26)
    at Timeout._onTimeout (/Users/hemiao/matter/matter.js/packages/matter-node.js/src/time/TimeNode.ts:59:18)
    at listOnTimeout (node:internal/timers:573:17)
    at process.processTimers (node:internal/timers:514:7)

matter-node> commission pair --ble --pairingCode 1032-742-2419 --node-id 333
{"discovery":{"knownAddress":"undefined","identifierData":{"shortDiscriminator":4},"discoveryCapabilities":{"ble":true,"onIpNetwork":true}},"passcode":36719818,"commissioning":{"nodeId":"333","regulatoryLocation":1,"regulatoryCountryCode":"XX"}}
2024-07-17 18:17:50.229 INFO   MatterController     Commissioning device with identifier {"shortDiscriminator":4} and 1 scanners and knownAddress "undefined"
2024-07-17 18:17:50.229 INFO   ControllerDiscovery  Start Discovering devices using identifier {"shortDiscriminator":4} ...
2024-07-17 18:17:50.229 INFO   ControllerDiscovery  Found 1 devices using identifier {"shortDiscriminator":4}
2024-07-17 18:17:50.230 INFO   MatterController     Commissioning device SII: undefined SAI: undefined SAT: undefined T: 0 DT: undefined PH: 36 ICD: 0 VP: 5120+1004 DN: undefined RI: 010059C4188CB9C4F27DF63ECB634784F9BA PI: 
2024-07-17 18:17:56.508 INFO   MatterController     Commissioning device SII: undefined SAI: undefined SAT: undefined T: 0 DT: undefined PH: 36 ICD: 0 VP: 5120+1004 DN: undefined RI: 010059C4188CB9C4F27DF63ECB634784F9BA PI: 
Error happened during command: Error: Failed to connect on any discovered server
Error: Failed to connect on any discovered server
    at Function.iterateServerAddresses (/Users/hemiao/matter/matter.js/packages/matter.js/src/protocol/ControllerDiscovery.ts:228:23)
    at MatterController.commission (/Users/hemiao/matter/matter.js/packages/matter.js/src/MatterController.ts:482:32)
    at CommissioningController.commissionNode (/Users/hemiao/matter/matter.js/packages/matter.js/src/CommissioningController.ts:264:24)
    at Object.handler (/Users/hemiao/matter/matter.js/packages/matter-node-shell.js/src/shell/cmd_commission.ts:127:41)
matter-node> 
matter-node>

Development environment:

  • Apple M1 Max
  • macOS Sonoma 14.5
  • Node.js 20.15.1
  • npm 10.8.2
  • code version: 0.10.0-alpha.0-20240716-446c872f

Operation steps:

  1. Pair the device.
  2. Unpair the device.
  3. Re-pair the device.

My question is why is there an error when re-pairing in step 3? Thank you for your help!
@Apollon77
Copy link
Collaborator

can you please enable debug log or enable logfile for debug log and provide the debug log?

In fact he discovered the device correctly but was then not able to connect to the device. That also might bean issue of the devcie. What device is it?

@Apollon77 Apollon77 added the question Further information is requested label Jul 17, 2024
@joehecn
Copy link
Author

joehecn commented Jul 17, 2024

@Apollon77

This device is a color-adjustable light bulb.
device.md

For the debug log, please see the attached document.
console.md
debug.md

@Apollon77
Copy link
Collaborator

Ok ... interesting. It seems on one hand that the device did not properly expired it's MDNS announcements and so was still somehow discoverable on ip ... but also the controller did not started a BLE search. Ok I check

@Apollon77 Apollon77 added bug Something isn't working and removed question Further information is requested labels Jul 19, 2024
Apollon77 added a commit that referenced this issue Jul 19, 2024
@Apollon77
Makes sure to always use the BLE scanner when required
c023edf 
fixes #1025
@Apollon77 Apollon77 mentioned this issue Jul 19, 2024
Merged
@Apollon77
Copy link
Collaborator

fix is in merged PR .. should come into next nightly .. so in 10h+ or such please try again :-)

@mergify mergify bot closed this as completed in 4e066c5 Jul 19, 2024
@mergify mergify bot closed this as completed in #1030 Jul 19, 2024
@Apollon77
Copy link
Collaborator

PS: nightly did not went out because of a testcase change ... Will trigger one later

@Apollon77
Copy link
Collaborator

nightly released

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fixes for two Controller issues project-chip/matter.js
2 participants
@joehecn @Apollon77