Z-wave becomes unresponsive after recent update

[Update] It appears this issue was a result of a problem with another binding.

[Original Post]
I’ve been using openHAB for years with much success but every so often, especially after an upgrade I run into a snag.

Yesterday my Alexa devices said my openHAB devices were not responding so I SSHed in and did an update. It took forever for my Pine64 to restart. I thought I had a bad MicroSD card. After one more try and giving it a lot of time, I finally had a system working but from what I could tell my Z-wave devices were really delayed. After things seemed to be working again I just went to bed for the night.

Tonight my normal sunset rules didn’t seem to trigger so I noticed I seemed to be having a problem. Funny thing is I think I used my Alexa to successfully control some z-wave devices just a few hours earlier. Now when I try to use Alexa or my openHAB android app I get the follwing in my log viewer. I’m not understanding what is the problem but I see the words Java and I seem to recall the point at which I got to Java when I was upgrading the openHAB software yesterday is where is stopped for a long time.

Any suggestions?

2020-06-14 21:25:33.321 [ome.event.ItemCommandEvent] - Item ‘OD_Landscape’ received command ON

2020-06-14 21:25:33.353 [nt.ItemStatePredictedEvent] - OD_Landscape predicted to become ON

2020-06-14 21:25:33.396 [vent.ItemStateChangedEvent] - OD_Landscape changed from OFF to ON

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

2020-06-14 21:25:33.374 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method ‘ThingHandler.handleCommand()’ on ‘org.openhab.binding.zwave.handler.ZWaveThingHandler@f0473b’: Timer already cancelled.

java.lang.IllegalStateException: Timer already cancelled.

at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_222]

at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_222]

at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1010) ~[?:?]

at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:381) ~[?:?]

at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:337) ~[?:?]

at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:505) ~[?:?]

at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendData(ZWaveController.java:889) ~[?:?]

at org.openhab.binding.zwave.handler.ZWaveControllerHandler.sendData(ZWaveControllerHandler.java:472) ~[?:?]

at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleCommand(ZWaveThingHandler.java:1191) ~[?:?]

at sun.reflect.GeneratedMethodAccessor425.invoke(Unknown Source) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]

at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]

at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]

at com.sun.proxy.$Proxy1938.handleCommand(Unknown Source) [?:?]

at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:74) [bundleFile:?]

at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]

at sun.reflect.GeneratedMethodAccessor424.invoke(Unknown Source) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]

at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]

at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

I’m seeing the same thing with the same errors after updating to 2.5.5. This is with the Nortek HUSBZB-1 device acting as my Z-wave controller. I’m running on my home media server which is overpowered for OpenHAB (8cpu, 32GB of memory, 1TB SSD)… I can’t think of anything else that’s changed recently on it, although I have kept up with OpenJDK fixes - but I too am running a 1.8.0-222 JVM.

Thank you for the response. I’m running on a Pine 64 with 1GB and a Aeon z-wave (Gen 5). I have noticed that z-wave is responsive after a restart but after some time it seems to have issues. I can confirm that other bindings are working as my Monoprice amplifier on serial works just fine. I’ll keep investigating but if anyone has tips I’d appreciate them.

If your network is not changing then the daily heal is not needed. Several people here have disabled it for similar reasons.

Probably unrelated to your problem but consider replacing your HW with a RPi4/2GB, get a new SD card, too, and use openHABian to install. Default ZRAM will mitigate SD issues.
(you could try with your old PINE, too, but support for that was dropped so it might work or not. So it’s clearly the right time to change HW).

And right, disable network heal. Use PaperUI or habmin (it’s a property to the controller thing).

1 Like

Removing my replies due to misunderstanding of issue.

Threads threads threads…

openhab> shell:threads | grep '\".*\"' | wc -l
openhab> shell:threads | grep 'TIMED_WAITING' | wc -l

Seems excessive.

Researching and learning.

There’s nothing in your logs indicating your exception or system state are zwave related, so please don’t think or mislead others telling it is.

1 Like

@mstormi I’m not blaming Zwave, I stated that these were just the downstream errors. There were a ton of exceptions, but from what I can tell it was Zwave complaining about the lack of memory. The environment continues to leak threads (>500 now), and in the end I will attempt to control a Zwave device and OH will puke and be non responsive.

Again, that’s no indication your problems are ZWave related or even caused.
Stay on topic. The OP has ZWave issues so don’t hijack his thread please open your own.
(or stop, it’s pretty likely the memleak in Amazonechocontrol has caused that for you).

1 Like

My bad. I incorrectly read the OP. And now do see the AEC thread. Sorry all.

I didn’t realize Pine64 was no longer supported with system images. There are still instructions on the openHAB documentation at https://www.openhab.org/docs/installation/pine.html

I ordered a 2GB RPi4 and I have fresh SD cards. Not looking forward to moving all of my z-wave devices over again. Maybe it’ll be easier this time. I looked into ZRAM and am happy for that option.

This morning I ran the “Upgrade System” in the config tool and it seemed to update my Java. Below is what I’m at now and so far I’m not seeing errors.

openjdk version “1.8.0_252”
OpenJDK Runtime Environment (Zulu (build 1.8.0_252-b225)
OpenJDK Client VM (Zulu (build 25.252-b225, mixed mode, Evaluation)

Thank you,

There should be no hassle with your Z-Wave devices as they are stored in the controller. Just backup your OH configuration (sudo openhab-cli backup), install OH on your new RPi, move the backup file from your Pine64 to the RPi, stop OH and restore the config (sudo openhab-cli restore /path/and/filename/ofyourbackupfile). I did that 2 weeks ago moving from a RPi3 to a RPi4 and it was a very smooth process.

1 Like

So no luck after Java upgrade. My rules didn’t do anything and when I try to trigger a change I get what looks like to me as a positive results but nothing happens with the z-wave devices. Example:

2020-06-16 21:42:40.741 [ome.event.ItemCommandEvent] - Item 'OD_Landscape' received command ON
2020-06-16 21:42:40.761 [nt.ItemStatePredictedEvent] - OD_Landscape predicted to become ON
2020-06-16 21:42:40.807 [vent.ItemStateChangedEvent] - OD_Landscape changed from OFF to ON

Have you followed the binding documentation and gathered debug logs? If so post some unfiltered ones here.

Enable Karaf debug level logging on org.openhab.binding.zwave to see what’s going on.

It seems that this issue was a result of a memory leak in the Amazon Echo Control Binding that would take some time to manifest. I’ll check the logs and keep monitoring but so far my OpenHAB seems to be working. I’m not sure why this issue seemed to only impact Z-Wave and why the Z-Wave basic logs seemed to show no issues. My serial control still worked.

I appreciate your willingness to help. My 2GB RPi 4 will be here today. I’ll get working on moving over to that device.

I JUST started encountering the same error in a similar environment two days ago. Running both zwave and amazonechocontrol.

Oddly, this setup has been running stable for at least a few months with no major changes to either EAC or zwave bindings.

I’m running the 2.5.0.-2019-09-12 beta version of the Amazon Echo Control binding. Which version are you on? I wonder if it might have something to do with amazon API?

EDIT: Nevermind, just read up on the EAC thread. Seems lots of echo users are having memory issues right now

1 Like

Same here. Nothing useful in the logs, but Amazon Echo Control binding not working, Zwave not working, some other bindings also not working, out of memory error.
After installing the fix from the main thread everything is working again …


For what it’s worth, I too have the Amazon Echo Control binding installed as well as Zwave (simply sharing this as another data point to the OP). I’m going to investigate that other thread as well.