OH3 RC: zwave stops working

It seems like i`m experiencing “java heap space” errors after some time of running (about 2days) which crash my OH3 instance.

I have a debian VM inside a proxmox host and installed OH3 RC1-2.

It may have to do something with the zwave binding because the first abnormalities i can find in the log seem like a zwave controller reset.

Logs:

2020-12-18 23:53:39.292 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:326) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:447) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1078) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:437) ~[bundleFile:?]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:427) [bundleFile:?]
2020-12-18 23:54:03.982 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-12-18 23:54:03.983 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-12-18 23:54:14.422 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 8: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:14.423 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 8: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:15.351 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 8: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:29.554 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 9: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:31.396 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 9: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:32.303 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 9: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:35.994 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 9: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:35.994 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 9: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:52.029 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:52.029 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:52.029 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:52.029 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:54:52.032 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:21.480 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:21.481 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:21.481 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:21.481 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 7: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:47.794 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 6: Not initialized (ie node unknown), ignoring message.
2020-12-18 23:55:49.742 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 6: Not initialized (ie node unknown), ignoring message.
2020-12-19 00:03:46.960 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:46.962 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:47.893 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalMonitorStateException: null
        at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:149) ~[?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1302) ~[?:?]
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:439) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1458) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.waitForPresenceDetection(PresenceDetection.java:442) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.performPresenceDetection(PresenceDetection.java:374) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.lambda$10(PresenceDetection.java:605) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2020-12-19 00:03:47.892 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalMonitorStateException: null
        at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:149) ~[?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1302) ~[?:?]
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:439) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1458) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.waitForPresenceDetection(PresenceDetection.java:442) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.performPresenceDetection(PresenceDetection.java:374) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.lambda$10(PresenceDetection.java:605) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2020-12-19 00:03:58.168 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:58.168 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:58.169 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:58.169 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:03:58.169 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:13.316 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:13.317 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:13.317 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:13.317 [WARN ] [.util.thread.strategy.EatWhatYouKill] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:33.169 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:04:49.903 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:05:02.215 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@2b2e3e91[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@2f11bfab] rejected from java.util.concurrent.ThreadPoolExecutor@6e2cb590[Shutting down, pool size = 6, active threads = 6, queued tasks = 0, completed tasks = 8]
    at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
    at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
    at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:378) ~[bundleFile:?]
    at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]

and later on something like:

2020-12-19 00:14:27.338 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.IllegalArgumentException: Self-suppression not permitted
        at java.lang.Throwable.addSuppressed(Throwable.java:1054) ~[?:?]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:284) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:358) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:14:23.570 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:14:26.394 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.IllegalArgumentException: Self-suppression not permitted
        at java.lang.Throwable.addSuppressed(Throwable.java:1054) ~[?:?]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:284) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:358) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.lang.OutOfMemoryError: Java heap space
2020-12-19 00:14:24.506 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space

Then the logs stop.

My Java version looks like:

root@openhab3:/home/stef# java --version
    openjdk 11.0.9.1 2020-11-04 LTS
    OpenJDK Runtime Environment Zulu11.43+55-CA (build 11.0.9.1+1-LTS)
    OpenJDK 64-Bit Server VM Zulu11.43+55-CA (build 11.0.9.1+1-LTS, mixed mode)

Any idea how to look into this deeper?

Last time my system crashed a had to copy my /var/lib/openhab/jsondb/org.openhab.core.thing.Thing.json from backups because it was completely empty, Looks like a have to do it this time as well. Hope there is no other damage as well.

I could test if the instance runs without the zwave binding, but zwave is my main usecase (danfoss thermostats).

Thanks for any help! Regards, Stefan

The initial problem (java heap space errors) seems to be fixed since i’ve set up the refresh rate of some network items, rules and removed the chromecast binding… i’m not pretty sure if this makes sense, but okay… I will have a look at the java processes until i get enough uptime to eventually run into that error again.

Now (i am additionally on RC2) i have some other problems with zwave, which stopps working without any log entries after some runtime. I now set the zwave loglevel to DEBUG, maybe i can find a hint why it stops working.

I would guess a full queue like mentioned in this thread could be caused by zombie nodes in the Z-Wave network messing up routing or from devices at the very edge of Z-Wave coverage.

Thank you for following what the binding documentation instructs. Too many people skip that.

Thanks for your reply.

@chris: There has been a log analyzer on your website in the past, does it exist anymore?

Thanks & regards,
Stefan

The site moved. The log viewer is now here.

Same viewer, new location.

2 Likes

As always… Since i set the log level to DEBUG everything works fine… I will have to look into it for a while now, but at the moment i will set the log level back to INFO and see if problems come back. Maybe just a second after i set the log level back.

Thanks anyway for all the help, i’ll keep ypu all updated if the errors come back.

One last question in this context, is the network map explained anywhere? I see one of my sensors (Node 13) with an unidirectional connection and am not pretty sure if this is alright or not.

image

Where did you find that diagram in OH3?

You go to your Z-Wave-Stick-Thing, scroll down and click “View network map”

1 Like

LOL I never scrolled that far in my testing. Thanks

1 Like