Zwave binding and "NodeID not set"

[dakkar]

Hello

I want to configure my zwave items the “manual” way
I followed this guide: ZWave Manual Thing Configuration

In fact this is my things file:

Bridge zwave:serial_zstick:Razberry "ZWave Razberry2 Controller" @ "Wohnzimmer" [
  port="/dev/ttyAMA0",
  controller_softreset="false",
  controller_master="true",
  heal_enable="true",
  security_networkkey="xxxxxxxxxxxxxxxxxxxxx",
  inclusion_mode="1"
] {
  Thing zwave:fibaro_fgwp102_03_002:Razberry:node2 "ZWave Node2: Fibario Steckdose" (zwave:serial_zstick:Razberry) [node_id=2]
}

But this does not seem to work: in paperUi I can see this thing:

and the logs looks fine except this:

==> /var/log/openhab2/openhab.log <==
2017-11-28 22:39:18.189 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:fibaro_fgwp102_03_002:Razberry:node2

I also tried the latest SNAPSHOT, same result.
Any idea how to fix that?

Complete log when saving the thing file:

2017-11-28 22:48:58.207 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-11-28 22:48:58.299 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'zwave.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2017-11-28 22:48:58.305 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zwave.things'
2017-11-28 22:48:58.481 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2017-11-28 22:48:58.490 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-11-28 22:48:58.491 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-11-28 22:48:58.493 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-11-28 22:48:58.495 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-11-28 22:48:58.609 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:fibaro_fgwp102_03_002:Razberry:node2
2017-11-28 22:48:58.632 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'zwave.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2017-11-28 22:48:58.643 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'zwave.things'
2017-11-28 22:49:01.769 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-11-28 22:49:01.786 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2017-11-28 22:49:01.796 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-11-28 22:49:01.800 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-11-28 22:49:01.804 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-11-28 22:49:01.807 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-11-28 22:49:01.828 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:fibaro_fgwp102_03_002:Razberry:node2
2017-11-28 22:49:01.879 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'zwave.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2017-11-28 22:49:01.882 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'zwave.things'
2017-11-28 22:49:05.081 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2017-11-28 22:49:05.143 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2017-11-28 22:49:05.164 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-11-28 22:49:05.167 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-11-28 22:49:05.170 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-11-28 22:49:05.173 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-11-28 22:49:05.194 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:fibaro_fgwp102_03_002:Razberry:node2
2017-11-28 22:49:08.581 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:08.582 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:08.585 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:08.587 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:08.589 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:08.592 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:08.594 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:08.796 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:Razberry:node2' to inbox.
2017-11-28 22:49:41.880 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:41.883 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:41.887 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:41.890 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:41.893 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:41.897 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:41.900 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:41.906 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:41.909 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:45.240 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:45.243 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:45.247 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:45.249 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:45.252 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:45.264 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:45.267 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:45.272 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:45.272 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:46.910 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:46.934 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:46.937 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:46.939 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:46.940 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:46.943 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:46.944 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:46.949 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:46.955 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:50.270 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:50.272 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:50.274 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:50.276 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:50.278 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:50.279 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:50.281 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:50.285 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:50.287 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:51.939 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:51.941 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:51.945 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:51.948 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:51.949 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:51.951 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:51.953 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:51.966 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:51.966 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:55.301 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:55.303 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:55.305 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:55.307 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:55.310 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:55.312 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:55.315 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:55.320 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:55.322 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:49:56.970 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:49:56.979 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:49:56.983 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:49:56.985 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:49:56.988 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:49:56.990 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:49:56.993 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:49:56.998 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:49:56.998 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists
2017-11-28 22:50:00.335 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2017-11-28 22:50:00.338 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2017-11-28 22:50:00.341 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2017-11-28 22:50:00.344 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2017-11-28 22:50:00.348 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2017-11-28 22:50:00.351 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2017-11-28 22:50:00.354 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2017-11-28 22:50:00.361 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 1: Attempting to add node that already exists
2017-11-28 22:50:00.364 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 2: Attempting to add node that already exists

[chris (Chris Jackson)]

@dakkar

I also tried the latest SNAPSHOT, same result.

This feature is only available in the development binding -:

OH2 Z-Wave refactoring and testing... and SECURITY

The latest version of the development binding dated 8th Sep 2018 is here. Toward the end of last year I spent some time doing some initial refactoring of the ZWave binding in OH2. This focussed on rewriting the way transactions work as this is an enabler for other areas of the code. At the same time I also restructured the different layers of the binding to make things cleaner, and done some changes to support a system of autocoding the command classes directly from the Z-Wave standard which s…

[dakkar]

thats it. Wall plug is deteced now and the switch works fine

[dakkar]

a little problem remains:

2017-11-29 18:57:27.920 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'zwave.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>

I don’t know if this is a serious problem as this is logged on INFO level.