Zwave binding not responding to send commands

Hi

I got a weird problem lately with my openhab. Before I’ll start resetting all and setting up from the beginning I was wondering if anybody had a similar issue or have some clue how to trace the source of that issue.

Lately, my zwave binding stopped responding to sent commands - yeah that’s right, it perfectly reads the states from switches and metrics from sensors, but no sending of ON/OFF works.

Got Aotec stick as a controller, and approx 30 zwave things. OH is on RPi 3B+ and int doesn’t seem like I’m out of some resources (RAM/CPU).

And I know I should drop logs here but the thing is … there are no. I mean there are zwave binding logs where I can see that openhab is gathering data and receiving events from zwave nodes but literary after:

“Item ‘Some_Light’ received command ON” (when i switch the light from openhab), there is nothing happening in logs related to that action.

Obviously, reboot od OH helps, but the problem is returning randomly.

And as a side note is that other thing types command sends (like HTTP binding) are working fine.

So maybe someone had simmilar issue or has an idea how to debug that.
P.S. i got technical background so if any ideas will involve some extra coding in bingins sources that is no problem to me. Just if anyone can point me where to search.

I would suspect some issue with zwave binging but then again no trace of “starting” the “command sending” process makes me thing like the issues would be with some OH core features. On the other hand only the zwave binigng has issues with this so i’m kind of confused here.

Appreciate any help.

I’m struggling to understand how there can be no debug logs if you enable debug logging?

Hmmm - then this is what we need to see. The debug logging allows us to see what is happening in the binding - without that, we’re really left a little guessing to understand the problem.

1 Like

Did you follow the clear instructions in the binding documentation for when things do nor go as expected? Looking to the expert written documentation should be an early step when stuck.

Hi @chris thx for quick response.

I’m struggling to understand how there can be no debug logs if you enable debug logging?

Like no DEBUG/TRACE from the zwave binding after Item status change event:

19:24:53.701 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'GF_Office_Light' received command OFF
19:24:53.722 [INFO ] [arthome.event.ItemStatePredictedEvent] - GF_Office_Light predicted to become OFF
19:24:53.744 [INFO ] [smarthome.event.ItemStateChangedEvent] - GF_Office_Light changed from ON to OFF

… and nothing after that (obviously with TRACE log level set on the binding).

I didn’t check on how stuff works but I presume binding is a listener to the item state change event so it like the binding listener is cut of from the event bus? (is that even possible?).

Hmmm - then this is what we need to see. The debug logging allows us to see what is happening in the binding - without that, we’re really left a little guessing to understand the problem.

As said those are DEBUG logs from the binging but from all stuff going in the zwave network like traffic returned to OH (the GF_Office_Light item is linked to NODE 4 which is not present in here):

2020-10-11 19:25:07.322 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 28 0E 32 02 21 44 80 01 CA 78 01 2D 80 01 CA 77 BF
2020-10-11 19:25:07.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 44 80 01 CA 78 01 2D 80 01 CA 77
2020-10-11 19:25:07.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 44 80 01 CA 78 01 2D 80 01 CA 77
2020-10-11 19:25:07.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-10-11 19:25:07.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Application Command Request (ALIVE:DYNAMIC_VALUES)
2020-10-11 19:25:07.361 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-10-11 19:25:07.364 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: SECURITY NOT required on COMMAND_CLASS_METER
2020-10-11 19:25:07.370 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 40: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-10-11 19:25:07.373 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 40: Meter: Type=Electric(1), Scale=kWh(0), Value=-21473662.8
2020-10-11 19:25:07.379 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-10-11 19:25:07.382 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=-21473662.8
2020-10-11 19:25:07.400 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Updating channel state zwave:device:c70df1e6:node40:meter_kwh to -21473662.8 [DecimalType]
2020-10-11 19:25:07.408 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 28 0E 32 02 21 54 00 00 03 D1 01 2D 00 00 01 4A 39
2020-10-11 19:25:07.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Commands processed 1.
2020-10-11 19:25:07.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@b55b0f.
2020-10-11 19:25:07.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-10-11 19:25:07.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-10-11 19:25:07.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-10-11 19:25:07.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-10-11 19:25:07.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 54 00 00 03 D1 01 2D 00 00 01 4A
2020-10-11 19:25:07.497 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 28 0A 32 02 A1 42 5D 53 01 2D 5D 03 66
2020-10-11 19:25:07.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0A 32 02 A1 42 5D 53 01 2D 5D 03
2020-10-11 19:25:07.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 54 00 00 03 D1 01 2D 00 00 01 4A
2020-10-11 19:25:07.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-10-11 19:25:07.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Application Command Request (ALIVE:DYNAMIC_VALUES)
2020-10-11 19:25:07.576 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-10-11 19:25:07.579 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: SECURITY NOT required on COMMAND_CLASS_METER
2020-10-11 19:25:07.582 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 40: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-10-11 19:25:07.585 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 40: Meter: Type=Electric(1), Scale=W(2), Value=9.77
2020-10-11 19:25:07.589 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 28 0A 32 02 A1 4A 00 09 01 2D 00 08 3F

When I turn DEBUG on ROOT i got lot more stuff in logs but obviously lot of that is not interesting to me so this. The best capture i think is those ~40 lines of logs after running smarthome:send GF_Office_Light OFF from OH console:

2020-10-11 20:08:13.373 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Executing command: 'smarthome:send  GF_Office_Light OFF'
2020-10-11 20:08:13.399 [DEBUG] [e.osgi.LoggingCommandSessionListener] - Command: 'smarthome:send  GF_Office_Light OFF' returned 'null'
2020-10-11 20:08:16.703 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job MapDB_SchedulerGroup.Commit_Transaction
2020-10-11 20:08:16.703 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2020-10-11 20:08:16.707 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2020-10-11 20:08:20.003 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
2020-10-11 20:08:20.003 [DEBUG] [org.quartz.core.JobRunShell         ] - Calling execute on job DEFAULT.greeTemp.rules#Green Temp Check Cron Lilys#20 * * * * ?
2020-10-11 20:08:20.229 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2020-10-11 20:08:20.236 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 28 0E 32 02 21 44 00 01 CA 81 01 2D 00 01 CA 80 B1
2020-10-11 20:08:20.240 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 14 00 04 00 28 0E 32 02 21 44 00 01 CA 81 01 2D 00 01 CA 80 B1
2020-10-11 20:08:20.242 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -79
2020-10-11 20:08:20.245 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2020-10-11 20:08:20.249 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 40: Message payload = 00 28 0E 32 02 21 44 00 01 CA 81 01 2D 00 01 CA 80
2020-10-11 20:08:20.251 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2020-10-11 20:08:20.255 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2020-10-11 20:08:20.259 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 44 00 01 CA 81 01 2D 00 01 CA 80
2020-10-11 20:08:20.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 44 00 01 CA 81 01 2D 00 01 CA 80
2020-10-11 20:08:20.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-10-11 20:08:20.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Application Command Request (ALIVE:DYNAMIC_VALUES)
2020-10-11 20:08:20.272 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-10-11 20:08:20.275 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: SECURITY NOT required on COMMAND_CLASS_METER
2020-10-11 20:08:20.287 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 40: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-10-11 20:08:20.290 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 40: Meter: Type=Electric(1), Scale=kWh(0), Value=1173.77
2020-10-11 20:08:20.292 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2020-10-11 20:08:20.295 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-10-11 20:08:20.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=1173.77
2020-10-11 20:08:20.301 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:switch_binary, cmdClass=COMMAND_CLASS_SWITCH_BINARY, endpoint=0
2020-10-11 20:08:20.303 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:meter_voltage, cmdClass=COMMAND_CLASS_METER, endpoint=0
2020-10-11 20:08:20.305 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:meter_current, cmdClass=COMMAND_CLASS_METER, endpoint=0
2020-10-11 20:08:20.309 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:meter_kwh, cmdClass=COMMAND_CLASS_METER, endpoint=0
2020-10-11 20:08:20.312 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Updating channel state zwave:device:c70df1e6:node40:meter_kwh to 1173.77 [DecimalType]
2020-10-11 20:08:20.315 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:meter_watts, cmdClass=COMMAND_CLASS_METER, endpoint=0
2020-10-11 20:08:20.324 [TRACE] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Checking channel=zwave:device:c70df1e6:node40:alarm_power, cmdClass=COMMAND_CLASS_ALARM, endpoint=0
2020-10-11 20:08:20.326 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2020-10-11 20:08:20.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Commands processed 1.
2020-10-11 20:08:20.335 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 28 0E 32 02 21 54 00 00 15 6E 01 2D 00 00 18 E3 20
2020-10-11 20:08:20.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1a233be.
2020-10-11 20:08:20.340 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 14 00 04 00 28 0E 32 02 21 54 00 00 15 6E 01 2D 00 00 18 E3 20
2020-10-11 20:08:20.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-10-11 20:08:20.343 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 32
2020-10-11 20:08:20.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-10-11 20:08:20.347 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2020-10-11 20:08:20.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-10-11 20:08:20.353 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 40: Message payload = 00 28 0E 32 02 21 54 00 00 15 6E 01 2D 00 00 18 E3
2020-10-11 20:08:20.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-10-11 20:08:20.356 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2020-10-11 20:08:20.358 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 50: listening == false, frequentlyListening == false, awake == false
2020-10-11 20:08:20.360 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2020-10-11 20:08:20.361 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 50: Node not awake!
2020-10-11 20:08:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 54 00 00 15 6E 01 2D 00 00 18 E3

Are you looking at the right file? From these logs, it looks like you are looking at the event log - not the debug log? The event log just logs the events, and will not have debug information.

If the binding isn’t receiving the commands, then I expect there is a configuration issue somewhere in your system?

1 Like

this was from log:tail on oh-cli console.

If You look at next log piece which is from the openhab.log file you’ll see that the Item state change event occurred at 19:24:53.744 and the first one from openhab.lo is at 2020-10-11 19:25:07.322 which is:
Receive Message = 01 14 00 04 00 28 0E 32 02 21 44 80 01 CA 78 01 2D 80 01 CA 77 BF
2020-10-11 19:25:07.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0E 32 02 21 44 80 01 CA 78 01 2D 80 01 CA 77

… but as I see this refers to NODE 40 which is not related to the state change event on NODE 4 (which should occur). Also nothing “interesting” is happening before as the fist previous event happens on 2020-10-11 18:51:02.005 and is from different binding (the TRACE was turned smth around 19:20` so not that there is some gap in logs)

Forgot to mention that this is something new. I’ve had OH working without any issues on Zwave for like 1yr and this recently came up.

If the binding isn’t receiving the commands, then I expect there is a configuration issue somewhere in your system?

That would probably be the case if this was a persistent issue but reboot of OH helps and is booting all to normal. And the issue is coming up randomly 2-3 times a day.
Interesting is also that rebooting just the binding for cli console bundle:restart is not helping. This kind of confirms that the issue is somewhere in the OH core, not the binding itself.

Anyway, thx for your time. I didn’t expect a magic answer that would solve the issue :slight_smile: as this is some crazy edge case scenario.
just thought maybe, maybe someone had a similar problem.

seems like I’ll be trying to debug the event bus and/or listener notifications process of the core components.

It doesn’t help unravel the mystery here, but no - the binding/channel is listening for commands. Understanding basic openHAB workflow will stand you in good stead other times.

In this case, we can see the command gets on to the OH events bus okay, because it invokes the autoupdate action (the prediction). That does help narrow it down to channel and not a generally seized events bus.

zwave binding logs often talk about ‘command’ but that’s in the context of a zwave message, not what you’re looking for.
For OH Item command, you should log something like

06:12:00	[DEBUG]	[ding.zwave.handler.ZWaveThingHandler]	NODE 10: Command received zwave:device:4e4692bc:node10:thermostat_setpoint_heating --> 25

might be worth confirming you do see these when things are working, and the channel UID is what you expect

No version updates or new devices added within that time?

No version updates or new devices added within that time?

Unfortunately a lot of “changes” including system updates, internal OH changes things/items changes, rules, etc… so a lot of noise that could have a “side effect” :confused:

Probably it would be more effective to search for some debugging rather than searching for the root cause of this issue but thx for replay.

There haven’t really been any changes in the binding that would affect this.

As far as I can see the binding is not getting the command from the system even.

1 Like
It doesn’t help unravel the mystery here, but no - the binding/channel is listening for  **commands** .
...
For OH Item command, you should log something like

Thx for this hint I’ll try to dig more into the debug logs and correlate this with the binding source to get and the idea of what is going one behind the scene.

Exactly, that’s what i presume from the logic of actions and log correlation.

So @chris as contributor of OH maybe you can point me quickly where is the handleCommand (https://github.com/openhab/org.openhab.binding.zwave/blob/098dd26239144785eef774372b2d5757f171a91f/src/main/java/org/openhab/binding/zwave/handler/ZWaveThingHandler.java#L1133) called in the core? (i think this is what i should follow, but correct me if i’m wrong)

As a user you should not really need to dig around in the depths of the source. There must be something wrong with your configuration or commands sent.

The action here certainly involves Things.

Before tearing into the code, you might scan your events.log looking for unexpected “Thing updated” events.