System now becoming unresponsive and requiring multiple reboots a day

joedirt · June 24, 2020, 7:20pm

hey guys my system becomes unresponsive and all of my wave devices do not respond at all until I reboot the rpi. does anyone have any ideas?

an example of my logs

2020-06-25 07:14:28.805 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@1442f9c': Timer already cancelled.
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[?:?]
	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.GeneratedMethodAccessor201.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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.$Proxy10434.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.GeneratedMethodAccessor200.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2020-06-25 07:14:47.924 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@19727c6': Timer already cancelled.
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[?:?]
	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.GeneratedMethodAccessor201.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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.$Proxy10456.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.GeneratedMethodAccessor200.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2020-06-25 07:14:47.960 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@1f27e6b': Timer already cancelled.
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[?:?]
	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.GeneratedMethodAccessor201.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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.$Proxy10465.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.GeneratedMethodAccessor200.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2020-06-25 07:14:52.499 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@19727c6': Timer already cancelled.
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[?:?]
	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.GeneratedMethodAccessor201.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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.$Proxy10523.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.GeneratedMethodAccessor200.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2020-06-25 07:14:52.538 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@1f27e6b': Timer already cancelled.
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[?:?]
	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.GeneratedMethodAccessor201.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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.$Proxy10531.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.GeneratedMethodAccessor200.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	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_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2020-06-25 07:14:55.977 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: Polling aborted due to exception
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397) ~[?:1.8.0_252]
	at java.util.Timer.schedule(Timer.java:208) ~[?:1.8.0_252]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:1005) ~[bundleFile:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:376) ~[bundleFile:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:332) ~[bundleFile:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:505) ~[bundleFile:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendData(ZWaveController.java:889) ~[bundleFile:?]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.sendData(ZWaveControllerHandler.java:472) ~[bundleFile:?]
	at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:427) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

sihui · June 24, 2020, 8:26pm

Apply the fix for the Amazon Echo Control Binding.

Burzin_Sumariwalla · June 24, 2020, 9:02pm

@sihui

Just curious. How did you figure it’s Amazon Echo binding related? I wondering for my own benefit. I was guessing timers in rules not functioning correctly.

rlkoshak · June 24, 2020, 9:36pm

A bit of inside information. Right now there are two bugs (both fixed BTW) that anyone like sihui and myself can’t help but be aware of.

The first has to do with the JavaScript transformation and the other is the Amazon Echo Control Binding was recently released with a really severe memory leak which causes openHAB to crash after a bit. The behavior you describe sounds like it might be caused by the latter bug.

joedirt · June 24, 2020, 11:14pm

Thanks guys, any links to the updated binding?

roy_liao · June 25, 2020, 6:16am

Yup, you can get it here:
https://ci.openhab.org/job/openHAB2.5.x-Addons/ws/bundles/org.openhab.binding.amazonechocontrol/target/

To clarify, the problem seemed to have stemmed from a change on amazon’s side. The updated version addresses these issues.

In case you want the details the discussion thread is here:
https://community.openhab.org/t/web-socket-error-on-amazonechocontrol-binding-every-65-seconds

sihui · June 25, 2020, 6:16am

I had the exact same error messages

Latest Snapshot should have the fix.

joedirt · June 26, 2020, 4:00am

Awesome, that fixed it!!