3 times lost all but 2 commands in openhab when bindings failiing since 2.5.0 update

I’ve seen this myself in the is week and it has nothing to do with the network.

What appears to be happening is OH runs out of memory right when it does one of its periodic writes to the JSONDB. When it runs out of memory it can’t do anything so it fails to write and oh crashes.

I have no idea why OH is suddenly running out of memory but this is new since OH 2.5.2. Since core didn’t change it has to be one of the bindings or add-ons. I’ve not had time to instate which it might be.

Please don’t post screenshots of logs. That’s all but useless to us. Please post the text and use code fences.

To be fair, a network disaster (or recovery from) could result in lots of activity, contributing to OOM

Observation from reports; there is something new in 2.5 involving unexpected Thing updates. Not status updates, property updates - which should trigger JSONDB writes of course.

1 Like

I think it runs out of memory because the tcp binding goes crazy.

As I wrote already above i have >23000 lines of this log entry “The channel for /192.168.10.43:4998 is connected” (see yellow line number in front of the logfile and it starts with this message right away on line 1) and this happens within few minutes until it finally crashes. So probably it’s even more messages (as they start on line 1) but log got rotated.

So there seems to be a bad loop when network goes down and then recovers that seems to send tcp binding into infinite loop which eats up the memory slowly until OH is out of memory finally after so many loops. I don’t if loosing the network triggers the loop or recovering but I can also upload the log file which I have backed up in case anyone is interested in it or if it helps fixing stuff.

Or the TCP problems are just the first symptom of some other problem. I don’t use the TCP binding yet I’m having an out of memory error and occasionally lose my Things as a result.

As I said above. Screen shots of logs are useless. I’m on my phone, I can read them. And even if I weren’t, i’m not going to go through the effort to try and read them.

So, um, what is that? What have you got configured with the TCP binding?

I will join this thread, after upgrade to 2.5.2 I lost OH 2x already within a week, in both cases with the same behaviour in the log files:

2020-03-19 16:26:01.596 [ERROR] [io.socket.thread.EventThread        ] - Task threw exception
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1378) ~[?:1.8.0_201]
        at okhttp3.Dispatcher.enqueue(Dispatcher.java:130) ~[bundleFile:?]
        at okhttp3.RealCall.enqueue(RealCall.java:88) ~[bundleFile:?]
        at io.socket.engineio.client.transports.PollingXHR$Request.create(PollingXHR.java:219) ~[bundleFile:?]
        at io.socket.engineio.client.transports.PollingXHR.doPoll(PollingXHR.java:145) ~[bundleFile:?]
        at io.socket.engineio.client.transports.Polling.poll(Polling.java:96) ~[bundleFile:?]
        at io.socket.engineio.client.transports.Polling.doOpen(Polling.java:36) ~[bundleFile:?]
        at io.socket.engineio.client.Transport$1.run(Transport.java:74) ~[bundleFile:?]
        at io.socket.thread.EventThread.exec(EventThread.java:55) ~[bundleFile:?]
        at io.socket.engineio.client.Transport.open(Transport.java:69) ~[bundleFile:?]
        at io.socket.engineio.client.Socket$2.run(Socket.java:263) ~[bundleFile:?]
        at io.socket.thread.EventThread.exec(EventThread.java:55) ~[bundleFile:?]
        at io.socket.engineio.client.Socket.open(Socket.java:241) ~[bundleFile:?]
        at io.socket.client.Manager$1.run(Manager.java:350) ~[?:?]
        at io.socket.thread.EventThread.exec(EventThread.java:55) ~[bundleFile:?]
        at io.socket.client.Manager.open(Manager.java:266) ~[?:?]
        at io.socket.client.Manager$11$1.run(Manager.java:592) ~[?:?]
        at io.socket.thread.EventThread$2.run(EventThread.java:80) [bundleFile:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-03-19 16:26:57.604 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1367) ~[?:1.8.0_201]
        at org.openhab.binding.network.internal.PresenceDetection.performPresenceDetection(PresenceDetection.java:352) ~[?:?]
        at org.openhab.binding.network.internal.PresenceDetection.lambda$10(PresenceDetection.java:606) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_201]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-03-19 16:26:59.076 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1603) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor.reExecutePeriodic(ScheduledThreadPoolExecutor.java:350) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:296) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-03-19 16:35:26.389 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1603) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor.reExecutePeriodic(ScheduledThreadPoolExecutor.java:350) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:296) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-03-19 16:38:08.111 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@910e48' takes more than 5000ms.
2020-03-19 16:38:26.394 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1603) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor.reExecutePeriodic(ScheduledThreadPoolExecutor.java:350) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:296) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2020-03-19 16:40:19.178 [ERROR] [de.csdev.ebus.core.EBusQueue        ] - Send queue is full! The eBUS service will reset the queue to ensure proper operation.
2020-03-19 16:40:26.399 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: unable to create new native thread
        at java.lang.Thread.start0(Native Method) ~[?:1.8.0_201]
        at java.lang.Thread.start(Thread.java:717) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:957) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1603) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor.reExecutePeriodic(ScheduledThreadPoolExecutor.java:350) ~[?:1.8.0_201]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:296) ~[?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]

It is definitely related to upgrade as before it was rock stable. I’m not sure however whether it is caused by core OH or maybe by bindings (I see eBus complaining

Send queue is full! The eBUS service will reset the queue to ensure proper operation.

but I think it is result of the crash, not the reason)