No Z-Wave communication after trying update to OH 2.1

Hello Community

I’ve tried to update from my OH 2.0 to OH 2.1 stable.
My environment:

  • Physical Server with Ubuntu 16.04 LTS
  • repository installation of OH 2
  • AEON Stick Gen5 Controller
  • 100 zWave Devices

I did an apt-get update and apt-get upgrade and updated to OH 2.1
Everything looked fine. My controller went up and I saw the usual initiallation communication.
But no device communicate (receive commands, send status updates e.g.).
I checked the userrights, the Port-Config, my Java Settings… but nothing was wrong.

I deceided to switch back to OH2 (from backup as descriped in the docs) the same error occurs.
I let the system time for more than 4 hours. Now, all initializings are done. An no communication.

When I activate the DEBUG Log I receive this messages for many devices:

21:59:36.507 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling...
21:59:36.507 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling zwave:device:215577f7:node21:switch_binary
21:59:36.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling aborted as no converter found for zwave:device:215577f7:node21:switch_binary

At a try to send a command manually the log shows tis:
Item:

Dimmer			EG_Wohnen_DIM_Licht_2		"Spots [%.0f %%]"						<dimmablelight>	(gEG_Wohnen, gDimmers, gLights)								{channel="zwave:device:xxx:node38:switch_dimmer"}
22:07:39.454 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'EG_Wohnen_DIM_Licht_2' received command 25
22:07:39.456 [INFO ] [ome.event.GroupItemStateChangedEvent] - gDimmers changed from 0 to UNDEF through EG_Wohnen_DIM_Licht_2
22:07:39.458 [INFO ] [marthome.event.ItemStateChangedEvent] - EG_Wohnen_DIM_Licht_2 changed from 0 to 25
22:07:39.704 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, callback=0, payload=22 00 00 03
22:07:39.704 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 486
22:07:39.704 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 26 00 00 03 5D
22:07:39.705 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 07 00 80 26 00 00 03 5D
22:07:44.705 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
22:07:44.705 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 487. Queue={}
22:07:44.705 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 486
22:07:44.706 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 26 00 00 03 5D
22:07:44.706 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 07 00 80 26 00 00 03 5D
22:07:46.823 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 61 0A 32 02 21 34 00 00 00 00 00 00 A5
22:07:46.824 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:07:46.825 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 61 0A 32 02 21 34 00 00 00 00 00 00 A5
22:07:46.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 61 0A 32 02 21 34 00 00 00 00 00 00 A5
22:07:46.826 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 61 0A 32 02 21 34 00 00 00 00 00 00
22:07:46.826 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 97: Application Command Request (ALIVE:DONE)
22:07:46.826 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 97: Starting initialisation from DONE
22:07:46.826 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1a0953c2 already registered
22:07:46.826 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 97: Incoming command class METER
22:07:46.826 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 97: Received METER command V3
22:07:46.826 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 97: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
22:07:46.827 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
22:07:46.827 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got an event from Z-Wave network: ZWaveMeterValueEvent
22:07:46.827 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0E+1
22:07:46.827 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 72: Transaction not completed: node address inconsistent.  lastSent=72, incoming=255

Do you have any ideas to fix it?
What further information do you may need?

Thanks
Michael

Just a guess: do you have 2 zwave binding versions installed? Check through karaf console and bundle:list

Hello @sihui

I thought if it neither work with OH 2.0 nor OH 2.1 I can try to get it run with OH 2.1 and did the upgrade again.

No, I only see 1 binding:
> openhab> bundle:list | grep ZWave
> 209 | Active | 80 | 2.1.0 | ZWave Binding

A lot of problems (although different issues than yours) were fixed by deleting tmp and cache folder (only content, no folder deletion!) and restarting.
It’s worth a try and does not harm … only takes a little longer for the system to start.

I cleaned up the directories and now I see this error:

22:49:10.421 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.ArrayIndexOutOfBoundsException: 3
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.isSecurityNonceReportMessage(ZWaveSecurityCommandClass.java:1067)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.SerialMessage$SerialMessageComparator.compare(SerialMessage.java:692)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.SerialMessage$SerialMessageComparator.compare(SerialMessage.java:1)[209:org.openhab.binding.zwave:2.1.0]
    at java.util.concurrent.PriorityBlockingQueue.siftUpUsingComparator(PriorityBlockingQueue.java:374)[:1.8.0_131]
    at java.util.concurrent.PriorityBlockingQueue.offer(PriorityBlockingQueue.java:491)[:1.8.0_131]
    at java.util.concurrent.PriorityBlockingQueue.add(PriorityBlockingQueue.java:463)[:1.8.0_131]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:546)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.sendMessage(ZWaveNodeInitStageAdvancer.java:260)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.addToQueue(ZWaveNodeInitStageAdvancer.java:1170)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:1082)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1306)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:250)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208)[209:org.openhab.binding.zwave:2.1.0]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324)[209:org.openhab.binding.zwave:2.1.0]
22:49:13.945 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'zwave:device:215577f7:node4' takes more than 5000ms.
22:49:13.948 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
22:49:13.948 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:215577f7:node4' has been updated.
22:49:13.990 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:49:13.991 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:49:13.992 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
22:49:18.989 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'zwave:device:215577f7:node2' takes more than 5000ms.
22:49:18.992 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
22:49:18.992 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:215577f7:node2' has been updated.
22:49:19.039 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node95' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:49:19.042 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node95' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:49:19.044 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node95' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
22:49:22.694 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node97' changed from ONLINE: Node initialising: RETURN_ROUTES to ONLINE: Node initialising: NEIGHBORS
22:49:22.709 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node97' changed from ONLINE: Node initialising: NEIGHBORS to ONLINE
22:49:24.041 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'zwave:device:215577f7:node95' takes more than 5000ms.
22:49:24.044 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
22:49:24.046 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:215577f7:node95' has been updated.
22:49:24.083 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
22:49:24.084 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:49:24.086 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:215577f7:node7' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
22:49:29.085 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'zwave:device:215577f7:node7' takes more than 5000ms.

When I do the same test again (now with OH2.1)

the log looks like

22:57:06.089 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'EG_Wohnen_DIM_Licht_2' received command 20
22:57:06.094 [INFO ] [marthome.event.ItemStateChangedEvent] - EG_Wohnen_DIM_Licht_2 changed from 0 to 20
22:57:09.240 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 26 06 31 05 04 22 00 00 C5
22:57:09.241 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
22:57:09.242 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 26 06 31 05 04 22 00 00 C5
22:57:09.242 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 26 06 31 05 04 22 00 00 C5
22:57:09.242 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 26 06 31 05 04 22 00 00
22:57:09.243 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 38: Application Command Request (ALIVE:DONE)
22:57:09.243 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 38: Starting initialisation from DONE
22:57:09.243 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@76a20ab7 already registered
22:57:09.243 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 38: Incoming command class SENSOR_MULTILEVEL
22:57:09.244 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 38: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V4
22:57:09.244 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 38: Sensor Multi Level REPORT received
22:57:09.244 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 38: Sensor Type = Power(4), Scale = 0
22:57:09.244 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 38: Sensor Value = 0E+1
22:57:09.244 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
22:57:09.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 38: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
22:57:09.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 38: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 0E+1
22:57:09.246 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent.  lastSent=255, incoming=255

I guess it don’t depend on the OH Version :frowning:

After testing and analysing until 2am, I decided to do a fresh installation.
Thanks to @ThomDietrich for the Openhabian. It worked great on ubuntu 16.04 LTS :slight_smile:

So Now I’m up’n’running with OH 2.1 :slight_smile:

1 Like