ZWave binding updates

Hi Chris,

Here’s a log (from openhab 2.3 - let me know if you need it from 2.4, but I will be a few days before I get to retry) with the door opening, and the door closing: https://pastebin.com/aaphgiRv. The door is opened at 13:42:32 and closed at 13:42:42. The node is NODE 24. The alarm_access and sensor_door channels are both updated.

Interestingly, it’s also captured the problem I have with these sensors: Around 13:42:36 the battery report is delivered, but it also sends the door status at 13:42:35 to CLOSED just prior. The door was not closed then, it was still open. There is no alarm_access update though (which is how I determine if the door really was opened/closed)

Here is another log with me removing the sensor from the wall and replacing it, which should trigger the tamper sensor I guess? There is a tab inside that is pushed in when attached to the wall. https://pastebin.com/3dHDVXdr

This seems to trigger alarm_burglar

Thanks - that’s fine and it confirms what I was expecting to see. However I’m not sure that this is going to help with this bug in the device. The way that notifications are processed is now quite different and I see that the device reports consistently for both the SENSOR_BINARY and the NOTIFICATIONS -:

ie the sensor report with FF gives event 22, and sensor value 00 gives event 23 - this is consistent with the standard (22 means door open, and 23 means door closed) and if it’s wrong, I’m not quite sure how to work around that at the moment.

Hi Chris, thanks for looking into it. Yes, it looks a bug in the sensor hardware/firmware.

My workaround in 2.3 is to react to alarm_access and then check the sensor_door (which is correct at that point) - it’s when it delivers the sensor_door report as a result of SENSOR_BINARY_GET that it’s wrong. I ignore those as I react to alarm_access only.

However, 2.4 doesn’t send the alarm_access so I can’t use this in my workaround. I’m happy to keep using the workaround and don’t expect the zwave extension to do anything clever if the hardware is reporting incorrect values. If it’s possible to get alarm_access updated again that would be great :slight_smile:

Hi Chris,

thanks for your fast response.

i dont know which informations are really important for you, so i post the complete log for one vibration alarm:

2019-01-02 20:35:44.544 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: resetResendCount initComplete=true isDead=false

2019-01-02 20:35:44.545 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-01-02 20:35:44.545 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: SECURITY NOT required on COMMAND_CLASS_BASIC
2019-01-02 20:35:44.545 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 32: Received COMMAND_CLASS_BASIC V0 BASIC_SET
2019-01-02 20:35:44.545 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 32: Basic report, value = 0
2019-01-02 20:35:44.546 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-01-02 20:35:44.546 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BASIC, value = 0
2019-01-02 20:35:44.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Commands processed 1.
2019-01-02 20:35:44.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@83edd37.
2019-01-02 20:35:44.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 20:35:44.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 20:35:44.605 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 20 0A 71 05 02 00 00 FF 07 00 01 02 4C
2019-01-02 20:35:44.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 0A 71 05 02 00 00 FF 07 00 01 02
2019-01-02 20:35:44.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 0A 71 05 02 00 00 FF 07 00 01 02
2019-01-02 20:35:44.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-02 20:35:44.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Application Command Request (ALIVE:DONE)
2019-01-02 20:35:44.607 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: resetResendCount initComplete=true isDead=false
2019-01-02 20:35:44.607 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2019-01-02 20:35:44.608 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: SECURITY NOT required on COMMAND_CLASS_ALARM
2019-01-02 20:35:44.608 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 32: Received COMMAND_CLASS_ALARM V4 NOTIFICATION_REPORT
2019-01-02 20:35:44.608 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 32: NOTIFICATION report - 2 = 0, event=0, status=255, plen=1
2019-01-02 20:35:44.608 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 32: Alarm Type = BURGLAR (2)
2019-01-02 20:35:44.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2019-01-02 20:35:44.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 255
2019-01-02 20:35:44.609 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter processing NOTIFICATION
2019-01-02 20:35:44.610 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 0, type OnOffType
2019-01-02 20:35:44.610 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 0, channel alarm_access is not implemented.
2019-01-02 20:35:44.610 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter processing NOTIFICATION
2019-01-02 20:35:44.610 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 0, type OnOffType
2019-01-02 20:35:44.611 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Updating channel state zwave:device:ControllerUSB:node32:alarm_tamper to OFF [OnOffType]
2019-01-02 20:35:44.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Commands processed 1.
2019-01-02 20:35:44.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1fe2b54.
2019-01-02 20:35:44.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 20:35:44.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 20:35:44.677 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 20 03 20 01 FF 0F
2019-01-02 20:35:44.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 03 20 01 FF
2019-01-02 20:35:44.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 03 20 01 FF
2019-01-02 20:35:44.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-02 20:35:44.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Application Command Request (ALIVE:DONE)
2019-01-02 20:35:44.679 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: resetResendCount initComplete=true isDead=false
2019-01-02 20:35:44.680 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2019-01-02 20:35:44.680 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: SECURITY NOT required on COMMAND_CLASS_BASIC
2019-01-02 20:35:44.680 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 32: Received COMMAND_CLASS_BASIC V0 BASIC_SET
2019-01-02 20:35:44.680 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 32: Basic report, value = 255
2019-01-02 20:35:44.681 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-01-02 20:35:44.681 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BASIC, value = 255
2019-01-02 20:35:44.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Commands processed 1.
2019-01-02 20:35:44.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3350d23a.
2019-01-02 20:35:44.682 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 20:35:44.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 20:35:44.761 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 20 09 71 05 02 FF 00 FF 07 02 00 AE
2019-01-02 20:35:44.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 09 71 05 02 FF 00 FF 07 02 00
2019-01-02 20:35:44.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=32, callback=0, payload=00 20 09 71 05 02 FF 00 FF 07 02 00
2019-01-02 20:35:44.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-02 20:35:44.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Application Command Request (ALIVE:DONE)
2019-01-02 20:35:44.763 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: resetResendCount initComplete=true isDead=false
2019-01-02 20:35:44.764 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2019-01-02 20:35:44.764 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: SECURITY NOT required on COMMAND_CLASS_ALARM
2019-01-02 20:35:44.764 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 32: Received COMMAND_CLASS_ALARM V4 NOTIFICATION_REPORT
2019-01-02 20:35:44.765 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 32: NOTIFICATION report - 2 = 255, event=2, status=255, plen=0
2019-01-02 20:35:44.765 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 32: Alarm Type = BURGLAR (2)
2019-01-02 20:35:44.766 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2019-01-02 20:35:44.766 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ALARM, value = 255
2019-01-02 20:35:44.767 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter processing NOTIFICATION
2019-01-02 20:35:44.767 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 2, type OnOffType
2019-01-02 20:35:44.767 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 2, channel alarm_access is not implemented.
2019-01-02 20:35:44.768 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter processing NOTIFICATION
2019-01-02 20:35:44.768 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 32: Alarm converter NOTIFICATION event is 2, type OnOffType
2019-01-02 20:35:44.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Commands processed 1.
2019-01-02 20:35:44.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3cd0dec3.
2019-01-02 20:35:44.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 20:35:44.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 20:35:44.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 20:35:50.162 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 16 0E 32 02 21 34 00 00 00 33 00 01 00 00 00 35 D5
2019-01-02 20:35:50.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=22, callback=0, payload=00 16 0E 32 02 21 34 00 00 00 33 00 01 00 00 00 35
2019-01-02 20:35:50.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=22, callback=0, payload=00 16 0E 32 02 21 34 00 00 00 33 00 01 00 00 00 35
2019-01-02 20:35:50.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

Hi Chris,

I checked the associations first thing this morning by going into habmin and looking at the group associations that I set last night on each of my zwave Things. They’ve disappeared again. I’ve grabbed the whole DEBUG log from last night, 10 hours worth, which includes healing, but not that much else going on as everyone in the house is asleep, to this morning, however, it’s 1.1M, and I’m not experienced enough yet to know what is relevant data for you and what I can remove.
Log - Part 1: 190103.1.Part1.ZWave.log (700.4 KB)
Log - Part 2: 190103.1.Part2.ZWave.log (375.8 KB)

I will re-associate the devices again and try to monitor every hour or so through the day and capture a smaller log if the associations drop again. But just to confirm the associations are being set correctly, here is a capture of the log from just now for one device:

First, a log from a device fresh before setting association: 190103.2.ZWave.log (41.1 KB)
Here’s the association update: 190103.3.ZWave.log (9.9 KB)
And finally, results of a refresh after the association has been set: 190103.4.ZWave.log (38.1 KB)

Please let me know if there is any further tests you want me to try or logs you want me to capture.

Thanks, Dave.

Hi Chris,
further update, I had a power outage at my home this afternoon, and after the server back online I check the associations, and they’d been dropped. I’m not sure if your interested, however here is the openhab and event logs from the restart. zwave logs had DEBUG enabled.

190103.restart.events.log (35.3 KB)
190103.restart.openhab.part1.log (857.9 KB)
190103.restart.openhab.part2.log (431.1 KB)

Hej,

i have been using the 2.4 SNAPSHOT build for a while and yesterday updated to the stable. Uninstall the SNAPSHOT and install the stable one.

228 x Active x 80 x 2.4.0 x ZWave Binding

But the razberry controller keeps being offline…

I have read numerous post and check permissions and all the procedure of the razbery board integration… but no matter what i keep getting:

2019-01-03 12:34:49.876 [hingStatusInfoChangedEvent] - ‘zwave:serial_zstick:167a22ce452’ changed from UNINITIALIZED to INITIALIZING

2019-01-03 12:34:49.940 [me.event.ThingUpdatedEvent] - Thing ‘zwave:serial_zstick:167a22ce452’ has been updated.

==> /var/log/openhab2/openhab.log <==

2019-01-03 12:34:49.939 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port ‘/dev/ttyAMA0’

==> /var/log/openhab2/events.log <==

2019-01-03 12:34:49.951 [hingStatusInfoChangedEvent] - ‘zwave:serial_zstick:167a22ce452’ changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

==> /var/log/openhab2/openhab.log <==

2019-01-03 12:34:49.954 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2019-01-03 12:34:49.982 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller

2019-01-03 12:34:49.985 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

anything else that i should try?

Ignoring the UI for a second, is there anything actually wrong? Ie are devices reporting ok or not?

I can’t see any sign of the associations being modified in these logs. My guess is that they haven’t actually been changed and that the problem is “just” a display issue in the UI.

I can also see messages coming in from devices that are not polled, so again this indicates that associations are still set ok…

So this looks fine - as above, there are messages being received that confirm that associations are set ok - at least for nodes 2, 6, 7, 8 as below -:

I’m trying to understand if there really is any issue here with the binding? I don’t think so based on what I see in the logs, but if I’m missing something, please can you tell me when things weren’t working and with what node.

Thanks a lot Chris!
I’ll test it with the next Milestone release.

Hi there,

I updated from 2.3 stable to 2.4 stable, following the instructions and everything looks fine. But it figures out, that my Fibaro Dimmer 2 are not reporting state changes anymore. If a command is send by openhab, the dimmers are working as expected and I can see events in the log. Also the status is correctly shown on the sitemaps.
But if a dimmer is operated manually with the attached switch this is not “seen” by openhab. I have 3 of them, all worked fine with the 2.3 binding, but are failing with 2.4

My Fibaro Switch 2 are not affected, they are working like before.

Any ideas how to get closer to the problem?

Thanks Jan

Just tested it, still works fine.
Make sure you are using the switch_dimmer1 channel and have set the correct associations to your controller.

I’m using switch_dimmer1 but never had set an association for the lifeline to the controller in the past. But setting this solved the issue.

Thanks Jan

hi Chris,
I don’t think there’s an issue with the zwave binding now as DEBUG logs show updates on manual event.
However, The UI is not updating properly following a manual event and the events are not being persisted through to the DB, I’ll start debugging that next.
Thanks for your assistance.

Hi All

I’m having a reoccuring issue where my devices are all online and the commands are being sent but nothing happens sigh

I switch the light on and the log shows:

16:55:53.292 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'LivingRoomSw1' received command ON
16:55:53.293 [INFO ] [arthome.event.ItemStatePredictedEvent] - LivingRoomSw1 predicted to become ON
16:55:53.295 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingRoomSw1 changed from OFF to ON
16:55:53.296 [INFO ] [home.event.GroupItemStateChangedEvent] - gAllLights changed from OFF to ON through LivingRoomSw1
16:55:53.298 [INFO ] [home.event.GroupItemStateChangedEvent] - gInsideLights changed from OFF to ON through LivingRoomSw1

But the light didn’t turn on. I checked the associations, again some were missing as usual. So i updated them to controller but the issue persists.

I dont understand why this cant work reliably for me, is there something I’m doing incorrectly? Is this related to having the Controller on a remote linux machine and using socat? which im forced to do because OH2/Binding doesnt allow remote Serial controllers.

@chris does this log help?

zwave.txt (288.8 KB)

Thanks!

It looks to me like something is either wrong with the serial port, or the controller, as there is very little being received from the controller. Sometimes, there might be a message or two, but mostly there is no response at all.

I would suggest to reset the controller to see if that helps.

Hi Chris

Thanks, it was indeed Socat and the remote serial being an issue :frowning:

Do you know when approx you will update the binding to allow it to function with the changes to OH2 that allow the controller to be remotely connected to OH?

If there is any kind of issue on my KODI box which is serving the controller, the zwave network goes down :frowning:

Hi Chris,

i uploaded the log in a separate file, i thinks its better readalbe this way:
zwave-vibration.log (39.7 KB)

The device has the id 32. First i triggered a vibration alarm (not realised from openHAB), after that tamper alarm (works fine!) and last but not least a vibration alarm again - same result, the switch wasn’t triggerd.

If you need any additional informations, please let me know. Thanks.

Greetings
Dino

Please give the latest snapshot a try - there were some updates to the database for this device in the last day or so, so the latest definition may solve the issue (he says hopefully :wink: ).

Hi,

I’ve got a weird problem with my two Aoetec Wallmote and security with both the 2.4 stable and the last snapshot of the zwave binding :

  • each wallmote works correcly, in secure mode (discovery is completed, it is online, wake-up ends correctly, I can process correctly some reports as the battery level for instance, even healing ends up correctly)
  • BUT pressing a button shows “NO VALID NONCE” in the security logs (and the scene is not reported).

Do you know what possibly happens ?

Regards,

Romain

Hi Chris

Ive had this device just drop off the network for some reason, using the mechnical switch is just fine but no zwave control. I tried to reinitialise the device and let it heal over night, it shows online in the UI’s but its definitely not working. its an Aeotec Nano dimmer, ugh these Aeotec things are so problematic!

Ive also deleted the thing, reset the dimmer and excluded/included the device. It shows as a new node ID, number 21 now, but the issue persists:

kris@openhab2:/var/log/openhab2$ tail -f zwave.log | grep "NODE 21:"
08-Jan-2019 09:55:24.709 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update received
08-Jan-2019 09:55:24.719 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set action_heal to true (Boolean)
08-Jan-2019 09:55:24.720 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Starting heal on node!
08-Jan-2019 09:55:24.720 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: Starting network mesh heal.
08-Jan-2019 09:55:24.720 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from HEAL_START
08-Jan-2019 09:55:24.721 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set binding_cmdrepollperiod to 1500 (BigDecimal)
08-Jan-2019 09:55:24.721 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer - advancing to HEAL_START
08-Jan-2019 09:55:24.722 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set action_reinit to false (Boolean)
08-Jan-2019 09:55:24.722 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set action_failed to false (Boolean)
08-Jan-2019 09:55:24.722 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveInitializationStateEvent
08-Jan-2019 09:55:24.722 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set action_remove to false (Boolean)
08-Jan-2019 09:55:24.722 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update set binding_pollperiod to 86400 (BigDecimal)
08-Jan-2019 09:55:24.723 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Polling intialised at 86400 seconds - start in 46828800 milliseconds.
08-Jan-2019 09:55:24.723 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Configuration update ignored node_id to 21 (BigDecimal)
08-Jan-2019 09:55:24.725 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer - advancing to UPDATE_NEIGHBORS
08-Jan-2019 09:55:24.725 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveInitializationStateEvent
08-Jan-2019 09:55:24.726 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer: UPDATE_NEIGHBORS - updating neighbor list
08-Jan-2019 09:55:24.726 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 21: Request neighbor update
08-Jan-2019 09:55:24.727 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1d583b7
08-Jan-2019 09:55:24.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:24.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 256 to queue - size 3
08-Jan-2019 09:55:24.739 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:24.851 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 21: Got NodeNeighborUpdate request.
08-Jan-2019 09:55:24.851 [DEBUG] [erialmessage.RequestNodeNeighborUpdateMessageClass] - NODE 21: NodeNeighborUpdate STARTED
08-Jan-2019 09:55:24.853 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Response processed after 113ms
08-Jan-2019 09:55:24.853 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 256: Transaction completed
08-Jan-2019 09:55:24.854 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:256 DONE
08-Jan-2019 09:55:24.855 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:24.855 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@5e7e3e82
08-Jan-2019 09:55:24.856 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init transaction completed with response COMPLETE
08-Jan-2019 09:55:24.856 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer - advancing to GET_NEIGHBORS
08-Jan-2019 09:55:24.857 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveInitializationStateEvent
08-Jan-2019 09:55:24.857 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer: GET_NEIGHBORS - get RoutingInfo
08-Jan-2019 09:55:24.858 [DEBUG] [.protocol.serialmessage.GetRoutingInfoMessageClass] - NODE 21: Request routing info
08-Jan-2019 09:55:24.899 [DEBUG] [.protocol.serialmessage.GetRoutingInfoMessageClass] - NODE 21: Got NodeRoutingInfo request.
08-Jan-2019 09:55:24.900 [DEBUG] [.protocol.serialmessage.GetRoutingInfoMessageClass] - NODE 21: Neighbor nodes: 1 5 6 20
08-Jan-2019 09:55:24.903 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:24.931 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7e308561
08-Jan-2019 09:55:24.931 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init transaction completed with response COMPLETE
08-Jan-2019 09:55:24.931 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer - advancing to DELETE_SUC_ROUTES
08-Jan-2019 09:55:24.932 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveInitializationStateEvent
08-Jan-2019 09:55:24.932 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node advancer is deleting SUC return route.
08-Jan-2019 09:55:24.933 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Deleting SUC return routes
08-Jan-2019 09:55:24.933 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2c18c9a6
08-Jan-2019 09:55:24.933 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:24.933 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 258 to queue - size 3
08-Jan-2019 09:55:24.934 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:24.955 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:24.956 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command in progress.
08-Jan-2019 09:55:24.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 258: Transaction not completed
08-Jan-2019 09:55:29.957 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 21: TID 258: Timeout at state WAIT_REQUEST. 3 retries remaining.
08-Jan-2019 09:55:29.958 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:29.958 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:258 CANCELLED
08-Jan-2019 09:55:29.960 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@33d7889
08-Jan-2019 09:55:31.017 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2c18c9a6
08-Jan-2019 09:55:31.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:31.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 259 to queue - size 3
08-Jan-2019 09:55:31.019 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:31.035 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:31.036 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:31.036 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:31.094 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:31.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: CANCEL while sending message. Requeueing - 2 attempts left!
08-Jan-2019 09:55:31.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:31.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 259 to queue - size 3
08-Jan-2019 09:55:31.096 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 259: Transaction not completed
08-Jan-2019 09:55:31.345 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:31.716 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:31.717 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:31.717 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:31.719 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:31.719 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: CANCEL while sending message. Requeueing - 1 attempts left!
08-Jan-2019 09:55:31.719 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:31.720 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 259 to queue - size 3
08-Jan-2019 09:55:31.720 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 259: Transaction not completed
08-Jan-2019 09:55:31.970 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:31.985 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:31.985 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:31.986 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:31.987 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:31.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Retry count exceeded. Discarding message: TID 259: [CANCELLED] priority=Controller, requiresResponse=true, callback: 1
08-Jan-2019 09:55:31.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 259: Transaction completed
08-Jan-2019 09:55:31.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:259 CANCELLED
08-Jan-2019 09:55:31.988 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:31.989 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7bf41dad
08-Jan-2019 09:55:34.488 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2c18c9a6
08-Jan-2019 09:55:34.489 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:34.489 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 260 to queue - size 3
08-Jan-2019 09:55:34.490 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:35.466 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:35.466 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:35.466 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:35.467 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:35.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: CANCEL while sending message. Requeueing - 2 attempts left!
08-Jan-2019 09:55:35.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:35.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 260 to queue - size 3
08-Jan-2019 09:55:35.469 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 260: Transaction not completed
08-Jan-2019 09:55:35.719 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:35.735 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:35.735 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:35.736 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:35.737 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:35.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: CANCEL while sending message. Requeueing - 1 attempts left!
08-Jan-2019 09:55:35.738 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Adding to device queue
08-Jan-2019 09:55:35.738 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Added 260 to queue - size 3
08-Jan-2019 09:55:35.739 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 260: Transaction not completed
08-Jan-2019 09:55:35.989 [TRACE] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == true, frequentlyListening == false, awake == false
08-Jan-2019 09:55:36.006 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: Got DeleteSUCReturnRoute response.
08-Jan-2019 09:55:36.006 [DEBUG] [col.serialmessage.DeleteSucReturnRouteMessageClass] - NODE 21: DeleteSUCReturnRoute command failed.
08-Jan-2019 09:55:36.006 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveNetworkEvent
08-Jan-2019 09:55:36.008 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:36.008 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: Retry count exceeded. Discarding message: TID 260: [CANCELLED] priority=Controller, requiresResponse=true, callback: 4
08-Jan-2019 09:55:36.008 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: TID 260: Transaction completed
08-Jan-2019 09:55:36.008 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 21: notifyTransactionResponse TID:260 CANCELLED
08-Jan-2019 09:55:36.009 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
08-Jan-2019 09:55:36.010 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 21: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@195843f