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