Matter Binding

I have a very simple network setup, no vlans, one single network.
It also took me a very long time and many, many attempts until the meross device was integrated into OH.
My approach was this: I first integrated the device into the Google Home app. It wasn’t until much later that I came up with the idea of testing the new Matter add-on.
I generated a paring code in the Google Home app, entered it in OH in the “Scan Input” field and clicked Scan. This scan took many attempts. At some point, the device was found.
I later carried out an FW update via the Meross app. However, the old FW version is still displayed in the Google Home app and in OH.

Maybe it helps, I still have 2 old log files, unfortunately only with level DEBUG

UID: matter:node:4349669167:10513313403245052043
label: "Matter Device: Meross Smart Plug Mini"
thingTypeUID: matter:node_10513313403245052043
configuration:
  nodeId: "10513313403245052043"
bridgeUID: matter:controller:4349669167
channels:
  - id: 0#wifinetworkdiagnostics-rssi
    channelTypeUID: matter:wifinetworkdiagnostics-rssi
    label: Signal Strength
    configuration: {}
  - id: 1#onoffcontrol-onoff
    channelTypeUID: matter:onoffcontrol-onoff
    label: On Off
    configuration: {}
  - id: 2#electricalpowermeasurement-activecurrent
    channelTypeUID: matter:electricalpowermeasurement-activecurrent
    label: Active Current
    configuration: {}
  - id: 2#electricalpowermeasurement-activepower
    channelTypeUID: matter:electricalpowermeasurement-activepower
    label: Active Power
    configuration: {}
  - id: 2#electricalpowermeasurement-voltage
    channelTypeUID: matter:electricalpowermeasurement-voltage
    label: Voltage
    configuration: {}

openhab.log (368.8 KB)
openhab.log.7.7z.txt (126.1 KB) → remove txt!

1 Like

Same issue here, re-installing does fix

Nor do I , this is likely a network issue

It should not matter which system requested a code from a device, the device generates the code (i believe), homekit is just displaying that value. Also if the code was corrupt, its would fail with another error and would not attempt to actually connect to the device.

Matter uses unicast UDP for communications. While IPV6 is used the vast majority of the time, IPV4 is technically supported and can be used instead (but its not common, and i don’t have any devices that are IPV4 connected).

None, once homekit requests the device setup code and puts the device in commissioning mode, openHAB talks directly to the device, homekit or google or alexa is no longer involved in the process, which is one of the great strengths of Matter. You can safely remove the device from Homekit for example, and it would still be connected to other matter networks it paired with

Our Matter MDNS client actually picked up the device before you entered a code, so the device was advertising itself which we picked up first, and the fact you can ping the advertised device, but not setup a valid matter connection makes wonder about the code. In fact, after it failed with IPV6, you can see it tried connecting to the IPV4 addrees (10.x.x.x), which also failed. Maybe try a few more times? Other issues i have seen, some devices seem to not like being paired to more then a couple different fabrics , although this sounds like you have only added to homekit, and only once, so probably not an issue (you can see in apple home which other matter fabrics its connected to, and remove ones). Its definitely a bit of a mystery still why it can’t complete the setup.

I couldn’t find a way to check which fabrics the device is connected to, is it in Apple’s Home App?

Edit: some more experiment, looks like it’s not due to wrong pairing code. When I enter wrong code I actually got the checksum error like below:

2025-02-05 20:42:44.710 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error name: Error
2025-02-05 20:42:44.710 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Full error object: {"stack":"Error: Invalid checksum\n    at ManualPairingCodeSchema.decodeInternal (webpack://matter-server/./node_modules/@matter/types/dist/cjs/schema/PairingCodeSchema.js?:176:13)\n    at ManualPairingCodeSchema.decode (webpack://matter-server/./node_modules/@matter/types/dist/cjs/schema/Schema.js?:37:25)\n    at Nodes.pairNode (webpack://matter-server/./src/client/namespaces/Nodes.ts?:69:120)\n    at ClientController.executeCommand (webpack://matter-server/./src/client/ClientController.ts?:60:40)\n    at ClientController.handleRequest (webpack://matter-server/./src/Controller.ts?:22:33)\n    at WebSocket.eval (webpack://matter-server/./src/app.ts?:85:28)\n    at WebSocket.emit (node:events:519:28)\n    at Receiver.receiverOnMessage (webpack://matter-server/./node_modules/ws/lib/websocket.js?:1220:20)\n    at Receiver.emit (node:events:519:28)\n    at Receiver.dataMessage (webpack://matter-server/./node_modules/ws/lib/receiver.js?:596:14)","message":"Invalid checksum"}
2025-02-05 20:42:44.711 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Invalid checksum
2025-02-05 20:42:44.711 [TRACE] [ternal.client.MatterWebsocketService] - none:   at ManualPairingCodeSchema.decodeInternal (webpack://matter-server/./node_modules/@matter/types/dist/cjs/schema/PairingCodeSchema.js?:176:13)
2025-02-05 20:42:44.711 [TRACE] [ternal.client.MatterWebsocketService] - none:   at ManualPairingCodeSchema.decode (webpack://matter-server/./node_modules/@matter/types/dist/cjs/schema/Schema.js?:37:25)
2025-02-05 20:42:44.711 [TRACE] [ternal.client.MatterWebsocketService] - matter: Sending response: {"type":"response","message":{"type":"resultError","id":"35ac6613-5123-417c-8801-61b1fd8635c4","result":"undefined","error":"Invalid checksum"}}

Right, as i said if the code is corrupted, it throws an error before trying to setup. What i’m curious about is if the code just is not being recognized for some reason by the device, like its no longer valid. This can happen if the device fails the pairing process late in the setup (so it partially commissioned), if the code times out (2-15 mins typically), if the device already has x number of connections, etc… I have just seen some weirdness here, especially with my Hue light where is does not take a code, but eventually the next one or one after works.

Look for “connected services”, also i think you have to be inside your network to have this show up, if you are outside your lan, i think its not available (like accessing on the road).

1 Like

Ok, thanks! Interestingly I don’t have the “Connected Services” - anyways I also tried to reset the device and set it up from scratch without luck. I guess either something wrong with the device or my network doesn’t allow it. For now I think I will just use Homekit for automations.
Thanks a lot for the help!

Hi Dan,

Recently tried to pair a couple of new devices from Alexa - OpenHAB never finds the device but the Alexa App, after trying to pair, shows openHAB: controller. I did an update of the binding today, cleaned the cache etc. My other matter devices are working fine.

Here is Chat’s summary of the long list of logs: Here are the key findings from your openHAB Matter pairing logs:

1. Device Discovery Fails Initially

  • The system attempts to commission the device but reports:
    No device discovered using identifier {"shortDiscriminator":2}! Please check that the relevant device is online.
    
    This suggests that the device might not be in pairing mode or the controller is unable to find it on the network.

2. Device is Found Later with a Different Discriminator

  • A subsequent pairing attempt succeeds:
    Found 1 devices using identifier {"shortDiscriminator":6}
    
    • The system finds a device and attempts to communicate with it over multiple IPv6 and IPv4 addresses.

3. Commissioning Process Begins

  • The logs show a successful commissioning process, including:
    • PASE (Password Authenticated Session Establishment) exchange.
    • NOC (Node Operational Credentials) being issued.
    • Fabric index assigned (which is crucial for adding a Matter device).

4. Successful Secure Session Creation

  • The device successfully moves into an operational state:
    Case client: Paired successfully with udp://fd3a:77cd:2952:1:3613:43ff:fe95:f6b0:5540.
    
    • This confirms that the device was added to the Matter fabric.

5. “Node Not Connected” Error

  • Despite pairing successfully, the system throws an error:
    Controller: Error executing function pairNode: Node 5934114607320928725 not connected
    
    • The node appears to be added but is not responding as expected.

Possible Causes & Fixes

1. Ensure the Device is Online

  • Verify that the Matter device has power and is in an operational state.
  • Try rebooting the device and re-attempting the pairing process.

2. Check IPv6 Connectivity

  • Matter devices prefer IPv6. Ensure your openHAB instance has IPv6 properly enabled.

3. Remove and Retry Pairing

  • Remove the device from the Matter fabric and re-add it:
    log:set TRACE org.openhab.binding.matter
    
    • Try pairing again while monitoring logs.

4. Debug Controller Issues

  • If the node is added but “not connected,” the issue could be with the controller fabric.
  • Run:
    log:tail
    
    • Look for errors related to fabric index mismatches.

Let me know if you’d like to check specific aspects of your setup!
Mike

Its sounds like it did find them and attempt to pair, but maybe failed? I have seen this twice , the problem is the device now thinks its paired to the existing openHAB fabirc, but openHAB is not aware. The only way to fix is to remove openHAB from the device using Alexa (or another system its paired with), or factory reset it.

Hmm, thats odd, i don’t use the UI for setting mine, but it does show up for me, i wonder if thats related to the marketplace install? If you are getting a blank screen, then thats a marketplace issue, sounds like restarting openHAB fixes it, or i have clear my browser storage which fixes it for me when this happens after i manually install. In the mean time can you use the cli to enable in the console ? Also What device is this?

log:set TRACE org.openhab.binding.matter

Thanks for the AI summary, but i would need to see the log to understand the issue, if you could PM that to me that would be helpful

1 Like

I updated post after setting the log level in the console. Here is my config page

Thanks for the AI summary, but i would need to see the log to understand the issue, if you could PM that to me that would be helpful

Apologies for the double post, i’m on a plane with super crappy internet.

1 Like

The device is a GE Cync downlight - I have 2 working and was adding another.

There’s a new jar posted, this upgrades to the latest matter.js sdk which has fixes that might help with connection issues to troublesome devices as well as tweaks to support Aqara hubs.

I grabbed the new jar, but it appears to be an older one, specifically 4.3.0.202412311956

You are right, i uploaded an old jar, apologies. Please update to the latest jar i just posted. I hope this did not screw things up for people.

1 Like

304 │ Active │ 80 │ 4.3.0.202502060735 │ openHAB Add-ons :: Bundles :: Matter Binding

openHAB 4.3.2

The devices I try to pair with openHAB are Nanoleaf Matter Thread GU10 Smart Bulbs.

Start up binding:

==> /var/log/openhab/events.log <==
2025-02-07 14:40:28.663 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'matter:controller:a2c935be15' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING

==> /var/log/openhab/openhab.log <==
2025-02-07 14:40:28.665 [DEBUG] [r.internal.handler.ControllerHandler] - initialize
2025-02-07 14:40:28.665 [DEBUG] [r.internal.handler.ControllerHandler] - connect
2025-02-07 14:40:28.665 [DEBUG] [r.internal.handler.ControllerHandler] - matter config: /var/lib/openhab/matter
2025-02-07 14:40:32.446 [DEBUG] [r.internal.bridge.MatterBridgeClient] - onNodeReady port 41187
2025-02-07 14:40:32.447 [DEBUG] [r.internal.bridge.MatterBridgeClient] - Connecting ws://localhost:41187?productId=0001&port=5540&service=bridge&vendorId=65521&storagePath=%2Fvar%2Flib%2Fopenhab%2Fmatter&vendorName=openHAB&deviceName=Bridge+Device&uniqueId=bridge-0&productName=openHAB&passcode=20202021&discriminator=281
2025-02-07 14:40:32.469 [DEBUG] [ternal.client.MatterWebsocketService] - DeviceNode: Device Node Storage location: /var/lib/openhab/matter (Directory)
2025-02-07 14:40:32.476 [DEBUG] [ternal.client.MatterWebsocketService] - ServerNodeStore: Opened bridge-0 storage at /var/lib/openhab/matter/bridge-0
2025-02-07 14:40:32.478 [DEBUG] [al.controller.MatterControllerClient] - onNodeReady port 41187
2025-02-07 14:40:32.478 [DEBUG] [al.controller.MatterControllerClient] - Connecting ws://localhost:41187?nodeId=0&controllerName=controller-a2c935be15&storagePath=%2Fvar%2Flib%2Fopenhab%2Fmatter
2025-02-07 14:40:32.479 [DEBUG] [ternal.client.MatterWebsocketService] - StorageBac~DiskAsync: Failed to parse storage value for key resumptionRecords in context sessions
2025-02-07 14:40:32.491 [DEBUG] [ternal.client.MatterWebsocketService] - BasicInfor~ionServer: Using development values for some BasicInformation attributes: hardwareVersion: 0 softwareVersion: 0
2025-02-07 14:40:32.548 [DEBUG] [ternal.client.MatterWebsocketService] - BaseEventStore: Initialized new volatile event store
2025-02-07 14:40:32.551 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerNode: Storage location: /var/lib/openhab/matter (Directory)
2025-02-07 14:40:32.552 [DEBUG] [r.internal.handler.ControllerHandler] - Websocket connected
2025-02-07 14:40:32.554 [DEBUG] [ternal.client.MatterWebsocketService] - Endpoint: bridge-0 ready endpoint#: 0 type: RootNode (0x16) behaviors: 💤parts ✓index ✓basicInformation ✓accessControl ✓groupKeyManagement ✓generalCommissioning ✓administratorCommissioning ✓operationalCredentials ✓generalDiagnostics ✓commissioning ✓network 💤productDescription 💤sessions ✓events 💤controller ✓descriptor
2025-02-07 14:40:32.554 [DEBUG] [ternal.client.MatterWebsocketService] - DeviceNode: ServerNode created with ID: bridge-0
2025-02-07 14:40:32.558 [DEBUG] [ternal.client.MatterWebsocketService] - Endpoint: bridge-0.aggregator ready endpoint#: 1 type: Aggregator (0xe) behaviors: 💤parts ✓index ✓descriptor
2025-02-07 14:40:32.559 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerStore: Opened controller-a2c935be15-0 storage at /var/lib/openhab/matter/controller-a2c935be15-0
2025-02-07 14:40:32.559 [DEBUG] [r.internal.bridge.MatterBridgeClient] - onWebSocketText {"type":"event","message":{"type":"ready","data":"Controller initialized"}}
2025-02-07 14:40:32.562 [DEBUG] [ternal.client.MatterWebsocketService] - Commission~ontroller: BLE is not supported on this platform
2025-02-07 14:40:32.564 [INFO ] [.matter.internal.bridge.MatterBridge] - No devices found to register with bridge, not starting bridge
2025-02-07 14:40:32.568 [DEBUG] [ternal.client.MatterWebsocketService] - CertificateAuthority: Created new credentials with ID 0
2025-02-07 14:40:32.568 [DEBUG] [ternal.client.MatterWebsocketService] - MatterController: Creating new fabric
2025-02-07 14:40:32.578 [DEBUG] [ternal.client.MatterWebsocketService] - ClientController: Started Node
2025-02-07 14:40:32.578 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketText {"type":"event","message":{"type":"ready","data":"Controller initialized"}}
2025-02-07 14:40:32.579 [DEBUG] [r.internal.handler.ControllerHandler] - websocket ready

==> /var/log/openhab/events.log <==
2025-02-07 14:40:32.579 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'matter:controller:a2c935be15' changed from INITIALIZING to ONLINE

Pairing through the Nanoleaf app. Pairing is only possible for 1 minute.

==> /var/log/openhab/openhab.log <==
2025-02-07 14:41:14.365 [DEBUG] [al.controller.MatterControllerClient] - sendMessage: {"id":"ff573014-b7cd-4651-b16e-67c1fe4ab4df","namespace":"nodes","function":"pairNode","args":["25120155444"]}
2025-02-07 14:41:14.372 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device with identifier {"shortDiscriminator":11} and 1 scanners and knownAddress "undefined"
2025-02-07 14:41:14.372 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Start Discovering devices using identifier {"shortDiscriminator":11} ...
2025-02-07 14:41:14.639 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Found 1 devices using identifier {"shortDiscriminator":11}
2025-02-07 14:41:14.640 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device SII: 800 SAI: 800 SAT: 4000 T: 0 PH: 36 ICD: 0 VP: 4442+54 RI: 280070F987CCBEFA2C2B4318DB9F6994B98F PI: 
2025-02-07 14:41:14.979 [DEBUG] [ternal.client.MatterWebsocketService] - PaseClient: Pase client: Paired successfully with udp://[fdf8:ce8d:df55:1:9d6f:9bcd:1c84:dc05]:5540.
2025-02-07 14:41:14.980 [DEBUG] [ternal.client.MatterWebsocketService] - InsecureSession: End insecure session insecure/16456575291682953339
2025-02-07 14:41:14.980 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Start commissioning of node 83856276965044294 into fabric 1 (index 1)
2025-02-07 14:41:14.980 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Skipping NetworkCommissioning steps because the device is already on IP network (udp)
2025-02-07 14:41:14.981 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 0.1: GetInitialData
2025-02-07 14:41:15.385 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 4.1: GeneralCommissioning.ArmFailsafe
2025-02-07 14:41:15.560 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.1: GeneralCommissioning.ConfigureRegulatoryInformation
2025-02-07 14:41:15.663 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.2: TimeSynchronization.SynchronizeTime
2025-02-07 14:41:15.663 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 6.1: OperationalCredentials.DeviceAttestation
2025-02-07 14:41:15.933 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 7.1: OperationalCredentials.Certificates
2025-02-07 14:41:16.255 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 11.1: AccessControl
2025-02-07 14:41:16.255 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 14.1: Reconnect
2025-02-07 14:41:46.314 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Re-Arm Failsafe Timer during reconnect with device. Time left: 869s
2025-02-07 14:42:03.049 [DEBUG] [ternal.client.MatterWebsocketService] - InsecureSession: End insecure session insecure/9346905908613134590
2025-02-07 14:42:03.052 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error executing function pairNode: Failed to connect on any discovered server
2025-02-07 14:42:03.052 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Stack trace: Error: Failed to connect on any discovered server
2025-02-07 14:42:03.052 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error name: Error
2025-02-07 14:42:03.052 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Full error object: {"stack":"Error: Failed to connect on any discovered server\n    at ControllerDiscovery.iterateServerAddresses (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerDiscovery.js?:192:15)\n    at async eval (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/PeerSet.js?:396:26)","message":"Failed to connect on any discovered server"}
2025-02-07 14:42:03.052 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Failed to connect on any discovered server
2025-02-07 14:42:03.053 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketText {"type":"response","message":{"type":"resultError","id":"ff573014-b7cd-4651-b16e-67c1fe4ab4df","result":"undefined","error":"Failed to connect on any discovered server"}}
2025-02-07 14:42:03.054 [DEBUG] [al.controller.MatterControllerClient] - result type: resultError 
2025-02-07 14:42:03.055 [DEBUG] [nal.discovery.MatterDiscoveryService] - startScan complete
2025-02-07 14:42:05.092 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Error while re-arming failsafe during reconnect Unexpected end of stream

Pairing 2 differenent devices through the Samsung SmartThings app, pairing possible for 15 minutes.

2025-02-07 14:45:57.080 [DEBUG] [al.controller.MatterControllerClient] - sendMessage: {"id":"9722baa5-57e6-4664-b63b-675dd14f25b0","namespace":"nodes","function":"pairNode","args":["10246752649"]}
2025-02-07 14:45:57.082 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device with identifier {"shortDiscriminator":4} and 1 scanners and knownAddress "undefined"
2025-02-07 14:45:57.082 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Start Discovering devices using identifier {"shortDiscriminator":4} ...
2025-02-07 14:45:57.083 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Found 2 devices using identifier {"shortDiscriminator":4}
2025-02-07 14:45:57.083 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device SII: 800 SAI: 800 SAT: 4000 T: 0 PH: 36 ICD: 0 VP: 4442+54 RI: 0400D8451AA27462DF19B2FF631D4CC036C6 PI: 
2025-02-07 14:46:08.365 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error executing function pairNode: Failed to connect on any discovered server
2025-02-07 14:46:08.365 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Stack trace: Error: Failed to connect on any discovered server
2025-02-07 14:46:08.365 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error name: Error
2025-02-07 14:46:08.365 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketText {"type":"response","message":{"type":"resultError","id":"9722baa5-57e6-4664-b63b-675dd14f25b0","result":"undefined","error":"Failed to connect on any discovered server"}}
2025-02-07 14:46:08.365 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Full error object: {"stack":"Error: Failed to connect on any discovered server\n    at ControllerDiscovery.iterateServerAddresses (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerDiscovery.js?:192:15)\n    at async ControllerCommissioner.commissionWithDiscovery (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioner.js?:134:26)\n    at async MatterController.commission (webpack://matter-server/./node_modules/@project-chip/matter.js/dist/cjs/MatterController.js?:271:21)\n    at async CommissioningController.commissionNode (webpack://matter-server/./node_modules/@project-chip/matter.js/dist/cjs/CommissioningController.js?:139:20)\n    at async Nodes.pairNode (webpack://matter-server/./src/client/namespaces/Nodes.ts?:119:36)","message":"Failed to connect on any discovered server"}
2025-02-07 14:46:08.366 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Failed to connect on any discovered server
2025-02-07 14:46:08.366 [DEBUG] [al.controller.MatterControllerClient] - result type: resultError 
2025-02-07 14:46:08.366 [DEBUG] [nal.discovery.MatterDiscoveryService] - startScan complete
2025-02-07 14:47:20.712 [DEBUG] [al.controller.MatterControllerClient] - sendMessage: {"id":"84514414-24d1-4e3e-81c1-6e677c19d8d1","namespace":"nodes","function":"pairNode","args":["31057502015"]}
2025-02-07 14:47:20.714 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device with identifier {"shortDiscriminator":12} and 1 scanners and knownAddress "undefined"
2025-02-07 14:47:20.714 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Start Discovering devices using identifier {"shortDiscriminator":12} ...
2025-02-07 14:47:20.814 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Found 1 devices using identifier {"shortDiscriminator":12}
2025-02-07 14:47:20.814 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device SII: 800 SAI: 800 SAT: 4000 T: 0 PH: 36 ICD: 0 VP: 4442+54 RI: 0500EDA100B4A25CBC945470F3093C087146 PI: 
2025-02-07 14:47:21.168 [DEBUG] [ternal.client.MatterWebsocketService] - PaseClient: Pase client: Paired successfully with udp://[fdf8:ce8d:df55:1:b535:94bf:d507:ff0]:5540.
2025-02-07 14:47:21.168 [DEBUG] [ternal.client.MatterWebsocketService] - InsecureSession: End insecure session insecure/7745880324090514532
2025-02-07 14:47:21.168 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Start commissioning of node 9983892506643462910 into fabric 1 (index 1)
2025-02-07 14:47:21.168 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Skipping NetworkCommissioning steps because the device is already on IP network (udp)
2025-02-07 14:47:21.169 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 0.1: GetInitialData
2025-02-07 14:47:21.585 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 4.1: GeneralCommissioning.ArmFailsafe
2025-02-07 14:47:21.706 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.1: GeneralCommissioning.ConfigureRegulatoryInformation
2025-02-07 14:47:21.893 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.2: TimeSynchronization.SynchronizeTime
2025-02-07 14:47:21.894 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 6.1: OperationalCredentials.DeviceAttestation
2025-02-07 14:47:22.206 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 7.1: OperationalCredentials.Certificates
2025-02-07 14:47:22.567 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 11.1: AccessControl
2025-02-07 14:47:22.567 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 14.1: Reconnect
2025-02-07 14:47:29.038 [DEBUG] [ternal.client.MatterWebsocketService] - CaseClient: Case client: Paired successfully with udp://[fdf8:ce8d:df55:1:b535:94bf:d507:ff0]:5540 and parameters SII: 800 SAI: 800 SAT: 4000 DMRev: 17 IMRev: 11 spec: 0x0 maxPaths: 1 CATs: 
2025-02-07 14:47:29.039 [DEBUG] [ternal.client.MatterWebsocketService] - InsecureSession: End insecure session insecure/1895324188922594775
2025-02-07 14:47:29.041 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 16.1: GeneralCommissioning.Complete
2025-02-07 14:47:29.141 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 17.1: OperationalCredentials.UpdateFabricLabel
2025-02-07 14:47:29.222 [DEBUG] [ternal.client.MatterWebsocketService] - PairedNode: Node 9983892506643462910: Created paired node with device data undefined
2025-02-07 14:47:30.739 [DEBUG] [ternal.client.MatterWebsocketService] - InteractionClient: Subscription successfully initialized with ID 3799917101 and maxInterval 60s.
2025-02-07 14:47:30.912 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error executing function pairNode: Node 9983892506643462910 not connected
2025-02-07 14:47:30.912 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Stack trace: Error: Node 9983892506643462910 not connected
2025-02-07 14:47:30.912 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error name: Error
2025-02-07 14:47:30.912 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Full error object: {"stack":"Error: Node 9983892506643462910 not connected\n    at ControllerNode.getNode (webpack://matter-server/./src/client/ControllerNode.ts?:149:19)\n    at Nodes.pairNode (webpack://matter-server/./src/client/namespaces/Nodes.ts?:121:48)","message":"Node 9983892506643462910 not connected"}
2025-02-07 14:47:30.913 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Node 9983892506643462910 not connected
2025-02-07 14:47:30.914 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketText {"type":"response","message":{"type":"resultError","id":"84514414-24d1-4e3e-81c1-6e677c19d8d1","result":"undefined","error":"Node 9983892506643462910 not connected"}}
2025-02-07 14:47:30.914 [DEBUG] [al.controller.MatterControllerClient] - result type: resultError 
2025-02-07 14:47:30.915 [DEBUG] [nal.discovery.MatterDiscoveryService] - startScan complete

Pairing seems succesfull at first, but eventually fails. When I try to add them again it says they are already paired, and I need to remove them from /var/lib/openhab/matter.

2025-02-07 15:03:38.838 [DEBUG] [al.controller.MatterControllerClient] - sendMessage: {"id":"763a30f1-0bbb-4081-929d-7ee67e342474","namespace":"nodes","function":"pairNode","args":["31113043828"]}
2025-02-07 15:03:38.840 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device with identifier {"shortDiscriminator":12} and 1 scanners and knownAddress "undefined"
2025-02-07 15:03:38.840 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Start Discovering devices using identifier {"shortDiscriminator":12} ...
2025-02-07 15:03:39.023 [DEBUG] [ternal.client.MatterWebsocketService] - ControllerDiscovery: Found 1 devices using identifier {"shortDiscriminator":12}
2025-02-07 15:03:39.023 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Commissioning device SII: 800 SAI: 800 SAT: 4000 T: 0 PH: 36 ICD: 0 VP: 4442+54 RI: 2A00EC3E9FA5460137EB1104CEE64E4296F3 PI: 
2025-02-07 15:03:39.290 [DEBUG] [ternal.client.MatterWebsocketService] - PaseClient: Pase client: Paired successfully with udp://[fdf8:ce8d:df55:1:9d6f:9bcd:1c84:dc05]:5540.
2025-02-07 15:03:39.290 [DEBUG] [ternal.client.MatterWebsocketService] - InsecureSession: End insecure session insecure/1525000478377402973
2025-02-07 15:03:39.290 [DEBUG] [ternal.client.MatterWebsocketService] - PeerCommissioner: Start commissioning of node 3305332048357018778 into fabric 1 (index 1)
2025-02-07 15:03:39.290 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Skipping NetworkCommissioning steps because the device is already on IP network (udp)
2025-02-07 15:03:39.291 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 0.1: GetInitialData
2025-02-07 15:03:39.698 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 4.1: GeneralCommissioning.ArmFailsafe
2025-02-07 15:03:39.873 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.1: GeneralCommissioning.ConfigureRegulatoryInformation
2025-02-07 15:03:39.984 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 5.2: TimeSynchronization.SynchronizeTime
2025-02-07 15:03:39.984 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 6.1: OperationalCredentials.DeviceAttestation
2025-02-07 15:03:40.249 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Executing commissioning step 7.1: OperationalCredentials.Certificates
2025-02-07 15:03:40.557 [DEBUG] [ternal.client.MatterWebsocketService] - Controller~missioner: Commissioning step 7.1: OperationalCredentials.Certificates failed with error: Commission error: This device is already commissioned into this fabric. You can not commission it again. ... Aborting commissioning
2025-02-07 15:03:40.616 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error executing function pairNode: Commission error: This device is already commissioned into this fabric. You can not commission it again.
2025-02-07 15:03:40.616 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Stack trace: Error: Commission error: This device is already commissioned into this fabric. You can not commission it again.
2025-02-07 15:03:40.616 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Error name: Error
2025-02-07 15:03:40.616 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Full error object: {"stack":"Error: Commission error: This device is already commissioned into this fabric. You can not commission it again.\n    at #ensureOperationalCredentialsSuccess (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioningFlow.js?:278:13)\n    at #certificates (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioningFlow.js?:545:46)\n    at process.processTicksAndRejections (node:internal/process/task_queues:105:5)\n    at async ControllerCommissioningFlow.executeCommissioning (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioningFlow.js?:95:24)\n    at async #commissionConnectedNode (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioner.js?:258:7)\n    at async ControllerCommissioner.commissionWithDiscovery (webpack://matter-server/./node_modules/@matter/protocol/dist/cjs/peer/ControllerCommissioner.js?:146:12)\n    at async MatterController.commission (webpack://matter-server/./node_modules/@project-chip/matter.js/dist/cjs/MatterController.js?:271:21)\n    at async CommissioningController.commissionNode (webpack://matter-server/./node_modules/@project-chip/matter.js/dist/cjs/CommissioningController.js?:139:20)\n    at async Nodes.pairNode (webpack://matter-server/./src/client/namespaces/Nodes.ts?:119:36)","message":"Commission error: This device is already commissioned into this fabric. You can not commission it again."}
2025-02-07 15:03:40.617 [DEBUG] [ternal.client.MatterWebsocketService] - Controller: Commission error: This device is already commissioned into this fabric. You can not commission it again.
2025-02-07 15:03:40.617 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketText {"type":"response","message":{"type":"resultError","id":"763a30f1-0bbb-4081-929d-7ee67e342474","result":"undefined","error":"Commission error: This device is already commissioned into this fabric. You can not commission it again."}}
2025-02-07 15:03:40.617 [DEBUG] [al.controller.MatterControllerClient] - result type: resultError 
2025-02-07 15:03:40.618 [DEBUG] [nal.discovery.MatterDiscoveryService] - startScan complete

Hi, before i look at this more in depth, can you confirm the version of the matter binding you are using? I screwed up and uploaded an old jar yesterday (i’m on the road and messed up working on a remote machine). It should list as 4.3.0.202502060735 in the openHAB cli.

Sorry i just saw you listed the jar version ;-).

I’m on OH 4.3.2 I’ve been using a version of the binding from December. When I try to upgrade to the latest I get a Matter controller communication error.

247 x Active x  80 x 4.3.0.202502060735    x openHAB Add-ons :: Bundles :: Matter Binding

The error message is: “MatterController unavailable due to initialization error”

I see this in the log - does it give any clues as to the problem? I did a clean cache before swapping to the new version.

This line in particular doesn’t look good:

2025-02-07 14:07:24.160 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mmatter: ESC[0;31mreturning error MatterController unavailable due to initialization errorESC[0m

However, it doesn’t give a clue to me as to what is wrong.

2025-02-07 14:07:23.721 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : ServiceFactory.getService()
2025-02-07 14:07:23.724 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Checking constructor public org.openhab.binding.matter.internal.actions.MatterControllerActions()
2025-02-07 14:07:23.727 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Found constructor with 0 arguments : public org.openhab.binding.matter.internal.actions.MatterControllerActions(
)
2025-02-07 14:07:23.729 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : This thread collected dependencies
2025-02-07 14:07:23.730 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : getService (ServiceFactory) dependencies collected.
2025-02-07 14:07:23.730 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Querying state satisfied
2025-02-07 14:07:23.730 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condit
ion.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] serv
ice: [null]]]
2025-02-07 14:07:23.736 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : getting activate: activate
2025-02-07 14:07:23.738 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Locating method activate in class org.openhab.binding.matter.internal.actions.MatterControllerActions
2025-02-07 14:07:23.739 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Declared Method org.openhab.binding.matter.internal.actions.MatterControllerActions.activate([interface org.osgi
.service.component.ComponentContext]) not found
2025-02-07 14:07:23.739 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Locating method activate in class java.lang.Object
2025-02-07 14:07:23.740 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2025-02-07 14:07:23.740 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : activate method [activate] not found, ignoring
2025-02-07 14:07:23.740 [DEBUG] [rnal.actions.MatterControllerActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.i
nternal.actions.MatterControllerActions(327)] : Changed state from satisfied to active
2025-02-07 14:07:23.779 [DEBUG] [r.internal.handler.ControllerHandler] - initialize
2025-02-07 14:07:23.779 [DEBUG] [r.internal.handler.ControllerHandler] - connect
2025-02-07 14:07:23.780 [DEBUG] [r.internal.handler.ControllerHandler] - matter config: /var/lib/openhab/matter
2025-02-07 14:07:23.781 [DEBUG] [al.controller.MatterControllerClient] - onNodeReady port 46189
2025-02-07 14:07:23.781 [DEBUG] [al.controller.MatterControllerClient] - Connecting ws://localhost:46189?storagePath=%2Fvar%2Flib%2Fopenhab%2Fmatter&controllerName=controller-MatterController&nodeId=1
2025-02-07 14:07:23.850 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mControllerNode: ESC[0mStorage location: /var/lib/openhab/matter (Directory)
ESC[0m
2025-02-07 14:07:23.851 [DEBUG] [r.internal.handler.ControllerHandler] - Websocket connected
2025-02-07 14:07:23.858 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mControllerStore: ESC[0mOpened ESC[1mcontroller-MatterController-1 ESC[0mstorage at /var/lib/openhab/matter/controller-MatterController-1ESC[0m
2025-02-07 14:07:23.875 [TRACE] [ternal.client.MatterWebsocketService] - ESC[0;1;90mNodejsChannel: ESC[0;90mSocket created and bound ESC[34mremoteAddress: ESC[2;39mundefined:undefined ESC[0;34mlocalAddress: ESC[2;39m:::51001ESC[0m
2025-02-07 14:07:23.879 [TRACE] [ternal.client.MatterWebsocketService] - ESC[0;1;90mNodejsChannel: ESC[0;90mSocket created and bound ESC[34mremoteAddress: ESC[2;39mundefined:51001 ESC[0;34mlocalAddress: ESC[2;39m0.0.0.0:51001ESC[0m
2025-02-07 14:07:23.881 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mCommission~ontroller: ESC[0;33mBLE is not supported on this platformESC[0m
2025-02-07 14:07:24.026 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mCertificateAuthority: ESC[0mLoaded stored credentials with ID 0ESC[0m
2025-02-07 14:07:24.099 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mMatterController: ESC[0mLoaded existing fabric from storageESC[0m
2025-02-07 14:07:24.118 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mSessionManager: ESC[0mrestoring resumption record for node 11025932627052469060 and peer node 11025932627052469060 for fabric index 1ESC[0m
2025-02-07 14:07:24.118 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mSessionManager: ESC[0mrestoring resumption record for node 892562079574155892 and peer node 892562079574155892 for fabric index 1ESC[0m
2025-02-07 14:07:24.118 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mSessionManager: ESC[0mrestoring resumption record for node 9575081537530680964 and peer node 9575081537530680964 for fabric index 1ESC[0m
2025-02-07 14:07:24.160 [DEBUG] [ternal.client.MatterWebsocketService] - ESC[0;1;90mmatter: ESC[0;31mreturning error MatterController unavailable due to initialization errorESC[0m
2025-02-07 14:07:24.164 [DEBUG] [al.controller.MatterControllerClient] - onWebSocketClose 1002 MatterController unavailable due to initialization error
2025-02-07 14:07:24.165 [DEBUG] [r.internal.handler.ControllerHandler] - websocket disconnected
2025-02-07 14:07:24.165 [DEBUG] [r.internal.handler.ControllerHandler] - setOffline MatterController unavailable due to initialization error
2025-02-07 14:07:24.173 [DEBUG] [r.internal.actions.MatterNodeActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.internal.actions.MatterNodeActions(328)] : ServiceFactory.getService()
2025-02-07 14:07:24.175 [DEBUG] [r.internal.actions.MatterNodeActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.internal.actions.MatterNodeActions(328)] : Checking constructor public org.openhab.binding.matter.internal.actions.MatterNodeActions()
2025-02-07 14:07:24.177 [DEBUG] [r.internal.handler.ControllerHandler] - reconnect!
2025-02-07 14:07:24.177 [DEBUG] [r.internal.actions.MatterNodeActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.internal.actions.MatterNodeActions(328)] : Found constructor with 0 arguments : public org.openhab.binding.matter.internal.actions.MatterNodeActions()
2025-02-07 14:07:24.179 [DEBUG] [r.internal.actions.MatterNodeActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.internal.actions.MatterNodeActions(328)] : This thread collected dependencies
2025-02-07 14:07:24.183 [DEBUG] [r.internal.actions.MatterNodeActions] - bundle org.openhab.binding.matter:4.3.0.202502060735 (247)[org.openhab.binding.matter.internal.actions.MatterNodeActions(328)] : getService (ServiceFactory) dependencies collected.

That is an odd log, i don’t see why its erroring out, it seems like something at the OSGI level with the MatterWebsocketService can’t activate, but yet we see it start and other parts of the binding connect to it, so i don’t yet see what exactly is throwing this.

Just out of curiosity, how are you installing this, through the marketplace or by adding the jar to the addons folder? Has this changed how you are installing it? Also did you just trying installing the latest version, or did you also try installing the bad one i posted yesterday first? ( the one you listed is the correct version).

I installed by putting it in the addons folder. I didn’t try the bad one from yesterday, but I have installed various versions in the past as your development proceeded. Is there anything else I can provide? I have more logging from earlier - I didn’t see anything interesting, but maybe you can spot something.