Problems with Z-Wave binding and Aeon Z-Stick Gen5

Hi everyone

I’ve just recently bought a Gen5 Z-Stick and installed Openhab2 from the nightly build on the 14 July 2016.

I’ve paired one Z-Wave device with the stick, a Aeon multi-sensor.
I’m running openhab on a Gentoo box with amd64 architecture and kernel 4.4.8-hardened-r1.
The Z-Stick is mount as /dev/ttyACM0 and permissions seems to be correct.
I’ve also tried both Icedtea and Oracle 1.8 JVMs. The same issue is with both.

Unfortunately when I start openhab, I get loads of communication issues, such as:
2016-07-15 13:13:21.076 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-07-15 13:13:21.345 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-07-15 13:13:21.466 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-07-15 13:13:21.515 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-07-15 13:13:21.681 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-07-15 13:13:22.262 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0’
2016-07-15 13:13:22.291 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2016-07-15 13:13:22.294 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2016-07-15 13:13:22.301 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2016-07-15 13:13:22.302 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2016-07-15 13:13:25.449 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-07-15 13:13:25.450 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2016-07-15 13:13:25.450 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-07-15 13:13:25.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-07-15 13:13:25.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-07-15 13:13:25.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 2
2016-07-15 13:13:25.451 [INFO ] [age.SerialApiGetInitDataMessageClass] - ---------------------------------------------------------------------------
2016-07-15 13:13:25.474 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node…
2016-07-15 13:13:25.746 [WARN ] [l.serialmessage.SendDataMessageClass] - NODE 2: Already processed another send data request for this callback Id, ignoring.
2016-07-15 13:13:30.699 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2016-07-15 13:13:30.700 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-07-15 13:13:35.787 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-15 13:13:35.787 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-07-15 13:13:40.788 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
2016-07-15 13:13:40.789 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-07-15 13:13:45.790 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
2016-07-15 13:13:45.790 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
2016-07-15 13:13:50.791 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=11, payload=02 03 70 05 08

Is there any way I can debug this better?

Kind regards,
Rene

From the log it looks like the device (node 2) simply isn’t responding. It might not be properly included into the network, or there may be a communication problem (eg distance) or it may be a database problem - it’s hard to tell from this log.

I would suggest enabling debug logging - this will help establish what is being sent, and if other commands are being processed correctly.

To enable debug, use the command log:set debug org.openhab.binding.zwave

Hi Chris

I seemed to manage to get rid of the timing errors, but I still see retries of several messages:

2016-07-19 15:57:17.600 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_111_4 - config
2016-07-19 15:57:17.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_111_4 - index 111
2016-07-19 15:57:17.600 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_112_4 - config
2016-07-19 15:57:17.600 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_112_4 - index 112
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_113_4 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_113_4 - index 113
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_201_2 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_201_2 - index 201
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_202_1 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_202_1 - index 202
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_203_2 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_203_2 - index 203
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_204_1 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_204_1 - index 204
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_252_1 - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_252_1 - index 252
2016-07-19 15:57:17.601 [DEBUG] [class.ZWaveConfigurationCommandClass] - NODE 2: Creating new message for application command CONFIGURATIONCMD_GET
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_100_1_wo - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_100_1_wo - wo
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_110_1_wo - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_110_1_wo - wo
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_255_4_wo - config
2016-07-19 15:57:17.601 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: GET_CONFIGURATION - checking config_255_4_wo - wo
2016-07-19 15:57:17.608 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-07-19 15:57:17.608 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-19 15:57:17.608 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-07-19 15:57:17.608 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-07-19 15:57:17.608 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-07-19 15:57:17.608 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-07-19 15:57:17.628 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 3F 00 00 03 D7
2016-07-19 15:57:17.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-07-19 15:57:17.629 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 3F 00 00 03 00 00 D9
2016-07-19 15:57:17.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 3F 00 00 03 00 00 D9
2016-07-19 15:57:17.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 03
2016-07-19 15:57:17.629 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 63, Status = Transmission complete and ACK received(0)
2016-07-19 15:57:17.629 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=2, callback=63, payload=02 03 70 05 08
2016-07-19 15:57:17.629 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=3F 00 00 03
2016-07-19 15:57:17.629 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=63, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2016-07-19 15:57:22.603 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-19 15:57:22.603 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.

This is with a Z-Stick Gen5 and a Aeon Multisensor ZW100-C

Kind regards,
Rene

It’s a bit hard to say conclusively from a short log, but this looks ok to me…

Retries and timeouts will occur occasionally - it’s part of life with radio communications. If the issue is “occasional” then just live with it, but if it is quite often, then you will need to resolve the network difficulties by adding more devices.

If it’s always the same request that times out, then we can look to see if there’s a bug in the database, but I think the ZW100 is quite common so I suspect it is ok.

Cheers
Chris