"Jetty request 5905542 failed: null" causes OH2 to freeze. Getting to be a real problem

BGunnarB · December 6, 2018, 8:28am

Platform: Mini-PC Celeron amd-64 architecture, Ubuntu 18 and OH 2.3.0 Stable
4 Gb RAM, 110 GB SSD.
java version “1.8.0_191”
Java™ SE Runtime Environment (build 1.8.0_191-b12)
Java HotSpot™ 64-Bit Server VM (build 25.191-b12, mixed mode)

For the last couple of days, this has turned into a real issue.
In the middle of the night the logg is flooded with messages like these:
2018-12-06 08:11:59.049 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 5905460 failed: null
2018-12-06 08:11:59.231 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 5905461 failed: null
2018-12-06 08:12:21.557 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 5905510 failed: null
2018-12-06 08:12:21.809 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 5905511 failed: null
2018-12-06 08:12:28.856 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 5905529 failed: null

This causes OH2 to be completely absorbed by this error. No rules get activated. Still processor load is not over the top. Java process is about 25%, which is very high. The system responds to SSH login and I can restart OH2 via systemctl.

But de-facto OH2 is dead to the outside world. No data gets logged in influxdb, no rules work. I first experienced this a week ago but now it has happened again.

Dim · December 6, 2018, 8:30am

Is this OpenJDK or Oracle?

I see that you posted already here:
https://github.com/openhab/openhab2-addons/issues/1782

Do you have any webview elements in your sitemaps?

BGunnarB · December 6, 2018, 8:47am

Oracle.

Webview; You mean references to URLs?
Yes, but only internally to Grafana at localhost. No external URLs

Dim · December 6, 2018, 9:03am

Yeah. https://www.openhab.org/docs/configuration/sitemaps.html#element-type-webview

Can you try to remove these webviews from your sitemap to see if this improves the situation?

Do you get this error when you access your BasicUI via https://home.myopenhab.org/basicui/app (or Mobile App) or anytime?

Also: How many Items have you exposed to the Cloud connector?

BGunnarB · December 6, 2018, 9:19am

OK!
I’ll remove them and let you know in a couple of days how it goes.

Last night this started at 06:05 and continued until restart at 08:15. At that time 06:05 I did not access any UI. Previous time was three days ago when it started at 07:55 There are no rules or anything that fire at these times.

Normally I access the Classic UI locally from my iPhone. I also access Basic UI via the Cloud connector and Chrome web browser. I do not get any error messages when doing this but it happens spontaneously.

There are some 50 Items in my configuration. All visible to the cloud connector.

Dim · December 6, 2018, 9:20am

Are all of them exposed?
Note: You don’t need to expose ANY Item in the Cloud connector configuration if you simply want remote access and notifications.
Exposing Items is for integration purposes to 3rd party applications like IFTTT, Alexa, Google Assistant, etc.
Exposing Items increases the load both on your OH2 instance as well as on the myopenhab.org Cloud instance. Try to avoid it if you don’t really need this functionality

BGunnarB · December 6, 2018, 9:24am

Sorry! In that case none.
I misunderstood your question.

Dim · December 6, 2018, 9:40am

so: here nothing should appear:

In my case, I have 37 Items exposed (due to the Google Assistant integration that I use heavily) and I don’t see any similar Jetty warnings.

BGunnarB · December 6, 2018, 10:19am

That’s correct. Nothing there.

BGunnarB · December 6, 2018, 11:45am

Maybe some more light on the subject:
This is the events.log right before the “crash”:

2018-12-06 06:01:25.481 [vent.ItemStateChangedEvent] - SENSORLillaFRrDet_ActualTemperature changed from 8.3 ℃ to 8.4 ℃
2018-12-06 06:05:17.266 [hingStatusInfoChangedEvent] - 'tellstick:telldus-live:d49721f1' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-12-06 06:05:17.267 [hingStatusInfoChangedEvent] - 'tellstick:switch:d49721f1:129866' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2018-12-06 06:05:17.269 [me.event.ThingUpdatedEvent] - Thing 'tellstick:switch:d49721f1:129866' has been updated.
2018-12-06 06:05:17.270 [hingStatusInfoChangedEvent] - 'tellstick:switch:d49721f1:291127' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE

Then things went off the rails.
I am running a Tellstick Net remotely at another location and I have a Thing “Telldus Live gateway” to connect and read the status of some sensors and switches.
This binding has caused similar problems (lockup) before but then the error messages have been:

2018-11-30 07:00:51.730 [WARN ] [nal.live.TelldusLiveDeviceController] - TimeoutException error in get
java.util.concurrent.TimeoutException: null
	at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:169) ~[?:?]
	at org.openhab.binding.tellstick.internal.live.TelldusLiveDeviceController.innerCallRest(TelldusLiveDeviceController.java:308) ~[?:?]
	at org.openhab.binding.tellstick.internal.live.TelldusLiveDeviceController.callRestMethod(TelldusLiveDeviceController.java:282) ~[?:?]
	at org.openhab.binding.tellstick.internal.live.TelldusLiveBridgeHandler.updateDevices(TelldusLiveBridgeHandler.java:127) ~[?:?]
	at org.openhab.binding.tellstick.internal.live.TelldusLiveBridgeHandler.refreshDeviceList(TelldusLiveBridgeHandler.java:114) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

Could there be any connection? If so, I could remove this binding and associated Items

Dim · December 6, 2018, 11:52am

I don’t think so (but you can never be sure)

This flooding (every few seconds):

says to me the following: your local webserver (Jetty) which is embedded in OH2, acting as a http(s) Client, sends out requests to myopenhab.org Cloud Server and these fail due to some reason.

It could be anything: bad internet connection, problems at the Cloud Servers side, side-effect from a local binding.

Note: I haven’t checked any of this… I am just assuming and I may be completely wrong

Dim · December 6, 2018, 12:00pm

let me offer an “improved” assumption:

Or… the internal client in the openhabcloud addon is calling your Jetty Web Server to get info from the REST API about the state of your Items and the calls fail for some reason… (system overload caused by another root-cause or miss-configuration of something?)

BGunnarB · December 6, 2018, 12:00pm

Thanks for the tip!
I am on a fiber connection and the OH2 is connected over cable but it is worth checking. If a bad internet connection is the case, then maybe there should be some timeout settable in the service configuration?

Dim · December 6, 2018, 12:04pm

I think that the problem is local (see my “improved” assumption )

From the warning message, I understand that:
io.openhabcloud.internal.CloudClient sends requests to Jetty and gets null responses
Maybe you can put the io.openhabcloud addon in TRACE log level to see what the heck is the io.openhabcloud.internal.CloudClient asking from Jetty during the failure?

BGunnarB · December 6, 2018, 6:33pm

The trap is set!
I’ll get back to you when (hopefully not) the trap springs shut!

BGunnarB · December 6, 2018, 9:40pm

I think I have found the culprit. It seems to be the iOS app for accessing OH.
I started the app and suddenly got the “Jetty warning” whenever I did something in the app.

After restarting the app it went away and I have not been able to recreate the error.
But I found this thread: IOS App issues - no connectivity, stability issues

So probably this is what causes the problems.
I’ll leave it for now and continue to monitor the thread above.
Thanks for your fantastic and rapid support!

Dim · December 6, 2018, 10:18pm

But… what is the “connection” between the iOS App and the io.openhabcloud.internal.CloudClient that generates the Warning?

Does this Warning appear also when you access OH2 using the local connection or only the remote connection (via the openHAB Cloud service) on your mobile app?

and how can it be explained that this happened in the middle of the night? (with so much flooding that got your OH2 system stuck…)

Olymp · December 7, 2018, 6:22am

Hi!
I have such warnings in the log file:

2018-12-07 14:12:44.023 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 9300492 failed: null
2018-12-07 14:12:44.024 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2018-12-07 14:12:59.746 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 9300546 failed: null
2018-12-07 14:12:59.748 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null
2018-12-07 14:13:06.710 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 9300644 failed: null
2018-12-07 14:13:06.712 [WARN ] [io.openhabcloud.internal.CloudClient] - Response Failure: null

They appear when I launch the android application or update the data in it.
This has been happening for a long time, I do not remember on which assembly I noticed, it was exactly on 1445, now it was updated on 1451, warnings are still present.

BGunnarB · December 7, 2018, 7:50am

This time it happened on the local connection.
One theory about why it happened at night might be connected to how iPhone handles apps, which I know almost nothing about…
When you close an app I wonder if it really is stopped or if it continues to be connected in the background? It might be, that it stayed active in the background until iOS decided to unload it and a pipe was broken. But this is just a theory from my side. In iOS it is easy to go back to an app you have used. You double-click the button and all apps line up until you swipe them off the screen but until you do that, it seems they are somehow at least partly active.
But I might be barking up the wrong tree.

Dim · December 7, 2018, 7:53am

I think that you may be right here (I also don’t know how iOS handles internally the apps)

Personally, I use both Android (heavy use since it’s mine) and iOS (small use from my wife)
I have the openHAB Cloud connector running and I have never seen this in my logs

but… I don’t use myopenhab.org to access remotely my local OH2 instance from the mobile phones.
I have setup a reverse proxy with encryption (https) and authentication and I connect directly from remote.

I was avoiding myopenhab.org for months/years until recently (big fanboy of Intranet of Things concept ) , but then I decided that I want to play with Google Assistant (GA), so it was a “forced” decision I could setup my own openHAB Cloud instance but I consider it too much for my scenario (happy with the reverse proxy and satisfied with the response time of GA over myopenhab.org)

Soon we will have auth embedded in OH2 so the use of myopenhab.org should be reduced and the focus would be integrations (Alexa, IFTTT, Google, etc)