Jetty update, Karaf 4.1.3 upgrade and full LSP support

sihui · December 5, 2017, 7:05am

This is what I got with the update script this morning:

pi@raspberrypi3:/opt/openhab2 $ sudo runtime/bin/update 2.2.0-SNAPSHOT

#########################################
       openHAB 2.x.x update script
#########################################

Making Temporary Directory
Downloading openHAB 2.2.0-SNAPSHOT...
######################################################                    75,9%
curl: (23) Failed writing body (2129 != 16384)
Download failed, version 2.2.0-SNAPSHOT does not exist.
If you believe this to be an error, please check the openHAB website. (www.openhab.org)

Instead the previous used script worked right out of the box.

sihui · December 5, 2017, 8:33am

It took a little while but #1112 is up and running.

Only error still left:

2017-12-05 09:09:39.331 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@56033'. Thread 'safeCall-36' (1504) is in state 'RUNNABLE'

but as far as I understand this was not part of the latest fixes.

Benjy · December 5, 2017, 9:03am

I’m not sure if there’s much I can do about another process cancelling the download half-way through. Did this happen every time?

0

Hi @Olymp, did you have any addons installed in /usr/share/openhab2 or had the openhab2-addons package installed? ? I’m trying to get to the bottom of this.

sihui · December 5, 2017, 9:13am

I tried twice with the same result (stopped at 75,9%).

One minute later I tried the mentioned script which pulls the zip via

wget -N https://openhab.ci.cloudbees.com/job/openHAB-Distribution/lastSuccessfulBuild/artifact/distributions/openhab/target/openhab-$vHAB-SNAPSHOT.zip || (echo "failure downloading OH2";exit 1)

and it worked without any issues …

Kai · December 5, 2017, 9:47am

This is actually a very interesting one that might give us a clue of what’s happening in @Dries setup: The EventLogger is the simplest code, which should normally never ever take more than 5 seconds (but which seems to be the case according to your log entry).
So my assumption is that the logger itself blocks. Interestingly, @Dries’ log shows a gap of 8 seconds shortly before the blacklisting. The only good explanation for me is that during that time the log rollover is happening, which is done synchronously by log4j2 and thus zipping 16MB blocks the whole logging framework for more than 5 seconds, which pauses all our activity and thus leads to blacklisting even our event handling.

@Dries Does this sound plausible? Could you check if any log rollover has happened at that time?

Kai · December 5, 2017, 9:54am

Same question to @sihui here - was there any log rollover near the moment when you saw that timeout message?

sihui · December 5, 2017, 10:47am

Nope, I always clean the logs after an upgrade to get a better overview what is going on. So at the time of the timout it was only a couple of kBytes in size.

But I’m using a custom log entry for the zwave logging. Just to make sure I will revert that and use the standard logging configuration for testing … but no time left today, will report tomorrow the results.

Olymp · December 6, 2017, 2:18am

Hello! No! Just this:

package = standard
ui = basic,paper,habpanel
remote = true
action = telegram
binding = astro,expire1,mihome,mqtt1,network,plex1
persistence = influxdb,mapdb
voice = voicerss
transformation = javascript,jsonpath,map,scale
misc =

I deleted the value voicerss in the org.openhab.addons.cfg file and rebooted, OpenHAB booted. I installed in paperUI “voiseRSS” and again rebooted, the download was not stable, errors in the rules, etc., I stopped the openHAB service, cleared the cache and the temp, rebooted and again the openHAB did not boot until the end.
In file org.openhab.addons.cfg was this line: voice = ,voicerss (at the beginning of a comma). I deleted the comma, openHAB is loaded again. I did not experiment any more; this is the working environment.
But these warnings remain. What do they mean? How to get rid of them? Over time, they fill the log and read it to become very difficult. Somebody help me

Olymp · December 6, 2017, 5:32am

Created a new virtual machine (Hyper-V)
installed Ubuntu 16.04.3 Server
apt update && apt dist-upgrade -y && apt autoremove -y
installed mosquitto
installed java:

 java version "1.8.0_151"
Java(TM) SE Runtime Environment (build 1.8.0_151-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.151-b12, mixed mode)

installed openHAB 2.2.0 Build #1114. First start after installation:

openhab.log:

2017-12-06 12:21:33.092 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.215.195:8080
2017-12-06 12:21:33.104 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.215.195:8443
2017-12-06 12:21:33.776 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:21:33<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:21:33.780 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@3c577535(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:21:33.971 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:21:33<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:21:33.971 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@24b9bf7f(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:21:34.458 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:21:34<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>me>NewInternalPor...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:21:34.460 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@4085cb93(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:21:34.957 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:21:34<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:21:34.958 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@178813ef(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:21:35.460 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:21:35<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:21:35.461 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@3cdb185d(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:21:36.505 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-06 12:26:19.397 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:26:19<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:26:19.400 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@13fc279e(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:26:19.496 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:26:19<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:26:19.498 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@141a18d4(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:41:14.400 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:41:14<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:41:14.409 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@4daf5f5f(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:56:09.413 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:56:09<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:56:09.418 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@2ae98ed3(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 12:56:09.426 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:56:09<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 12:56:09.427 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@52da42d(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-06 13:11:04.406 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@7955e47b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 05:11:04<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-06 13:11:04.408 [WARN ] [org.eclipse.jetty.http.HttpParser   ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@6aa559fe(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]

Really, am I the only one who is so sham?

Kai · December 6, 2017, 8:22am

It seems so. These warnings seem to come from external HTTP requests to your openHAB instance. The xml snippets look like some UPnP device sending crappy stuff. Do you maybe have some cheap chinese IP cams or anything similar in your network?
The warnings seem to be added in Jetty 9.3 and weren’t there in 9.2 (and we just did that switch in openHAB).
There seem to be some RFC2616 compliance mode in Jetty to avoid such messages. We would only have to figure out how to activate it…

Olymp · December 6, 2017, 8:36am

I do not have cameras, there is a xiaomi gateway and devices working with it, as well as Sonoff devices with tasmota firmware, milight bulbs. Directly with openHAB communicates only gateway xiaomi.The rest of the device is through a mosquitto. I’ll go there now, it’s far from me and I’ll try to disconnect all devices. Thank you for giving me direction. I will tell you the result of the tests, as I will check.

sihui · December 6, 2017, 8:52am

No change with standard logging (#1112): excerpt openhab.log, full log here:

2017-12-06 08:47:49.553 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@236d62'. Thread 'safeCall-21' (450) is in state 'WAITING'
2017-12-06 08:47:49.556 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@1b45121'. Thread 'safeCall-20' (449) is in state 'WAITING'
2017-12-06 08:47:49.553 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@ff626f'. Thread 'safeCall-7' (173) is in state 'WAITING'
2017-12-06 08:47:49.571 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@127562e'. Thread 'safeCall-9' (233) is in state 'WAITING'
2017-12-06 08:47:49.578 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@7aec67'. Thread 'safeCall-18' (444) is in state 'WAITING'
2017-12-06 08:50:03.906 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-18' (444) is in state 'RUNNABLE'
2017-12-06 08:50:42.036 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-26' (536) is in state 'RUNNABLE'
2017-12-06 08:54:46.800 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-16' (406) is in state 'RUNNABLE'
2017-12-06 08:57:19.297 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-16' (406) is in state 'RUNNABLE'
2017-12-06 09:30:44.968 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-53' (2384) is in state 'RUNNABLE'
2017-12-06 09:43:00.420 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1b389ce'. Thread 'safeCall-51' (2074) is in state 'RUNNABLE'

Corresponding events.log can be found here.

Kai · December 6, 2017, 12:37pm

@sihui If I see it correctly, you do not get into the blacklisting, you only see those warnings, right?
From the logs it seems as if your system isn’t able to write the log file quickly enough.

Could you please try the following? Edit the file etc/org.ops4j.pax.logging.cfg and set the value in this and that line to false? I’d be interested in whether this makes a difference on your system. Thanks!

Kai · December 6, 2017, 1:22pm

@Olymp Could you please check whether this change makes your warnings disappear?

Olymp · December 6, 2017, 2:34pm

I’ll tell you honestly, I did not understand what I should do: (it’s already late, tomorrow I’ll try to understand and tell you in the morning.) I disabled everything that is possible, I think I found the reason for these warnings, this is a miniDLNA server. Thank you for helping!

sihui · December 6, 2017, 3:51pm

Correct.

There are no log files written at all (did both changes at the same time), openHAB is still working fine, though.

Kai · December 6, 2017, 4:14pm

That’s why I didn’t configure it that way as a default. It will eventually write the log, but possibly only after a few MB of data have piled up - until then, everything is only held in memory (which should make it much faster than if every single line is directly written to disk).

snoekieboe · December 6, 2017, 4:15pm

Just my 2 cents after updating and running into similar problems.

Snapshot 1061 started to show strange behaviour after running successfully for weeks.
Harddisk activity would increase to severe levels for no reason, so i decided to reboot.

After the reboot ( still on snapshot 1061) my openhab would not start anymore… UI would show " waiting for UI’s to install". Cleared cache, cleared temp … no succes.

After reading this thread i decided to update to snapshot 1102…used apt-get (running on Ubuntu) to update… hooray… Openhab starts again.

After that i decided to update to the latest snapshot (1114) only to run into the same problems again. No matter what i tried… it would remain stuck at " installing UI’s".

After some investigation i went ahead and cleared my addons folder that still contained JAR files for the Yeelight and Unify binding…Succes!! Openhab starts… i’ve tried several restarts… no errors… all is working fine…

hope this information helps to clear the situation

Kai · December 6, 2017, 4:40pm

Thanks for your observations, @snoekieboe!
As you identified the jars in the addons folder as an issue: May I ask you to try this reconfiguration and see whether it solves the issue?

Vini · December 7, 2017, 6:39am

Do you have a link to this issue?