Openhab 2.4 hanging

I’ve had my share of errors with 2.3 but it never full-on hung up like this.

I have 2.4 release running in a docker and at random it just stops working. The web interface is still responsive but no switches actually do anything. If I tail the events or openhab log there’s nothing out of the ordinary. whatever the last item that updated is the last entry in the events log and the openhab log is clean (unless i’ve used the mobile app and then i get those tell-tale errors about the app disconnecting).
Sometimes it takes 2-3 days or this last time took 6 days.

Karaf console is still responsive. I usually have to restart it right away cause I already get an earful from SWMBO. What could I do in karaf to gather more information when this happens?

What other information can I provide?
this is my userdata/config/org/openhab/addons.config

//package="standard"
binding="astro,hue,exec,http,plex,samsungtv,unifi,weather,expire,expire1,plex1,weather1,network,serial1,mqtt,mqtt1,zwave,sonos"
legacy=B"true"
misc="restdocs,openhabcloud,market"
package="minimal"
persistence="rrd4j,influxdb,mapdb"
remote=B"true"
service.pid="org.openhab.addons"
transformation="map,regex,javascript,jsonpath"
ui="basic,rest,paper,habmin,habpanel"

openhab> bundle:list
START LEVEL 100 , List Threshold: 50
 ID │ State    │ Lvl │ Version                │ Name
────┼──────────┼─────┼────────────────────────┼───────────────────────────────────────────────────────────────────────────────────────────────────────────────
 20 │ Active   │  80 │ 5.3.1.201602281253     │ OSGi JAX-RS Connector
 21 │ Active   │  80 │ 2.7.0.v20170129-0911   │ Gson: Google Json Library for Java
 22 │ Active   │  80 │ 18.0.0                 │ Guava: Google Core Libraries for Java
 23 │ Active   │  80 │ 3.0.0.v201312141243    │ Google Guice (No AOP)
 26 │ Active   │  80 │ 3.5.5                  │ JmDNS
 28 │ Active   │  80 │ 1.0.0                  │ Units of Measurement API
 30 │ Active   │  80 │ 1.1.0.Final            │ Bean Validation API
 31 │ Active   │  80 │ 2.0.1                  │ javax.ws.rs-api
 32 │ Active   │  80 │ 3.2.0.v201101311130    │ ANTLR Runtime
 35 │ Active   │  80 │ 3.2.1                  │ Commons Collections
 36 │ Active   │  80 │ 1.1                    │ Commons Exec
 37 │ Active   │  80 │ 2.2.0                  │ Commons IO
 38 │ Active   │  80 │ 2.6                    │ Commons Lang
 47 │ Active   │  80 │ 4.2.1                  │ Apache Karaf :: OSGi Services :: Event
 63 │ Active   │  80 │ 4.6.0                  │ Apache XBean OSGI Bundle Utilities
 64 │ Active   │  80 │ 4.6.0                  │ Apache XBean :: Classpath Resource Finder
 65 │ Active   │  80 │ 2.12.0.v20160420-0247  │ EMF Common
 66 │ Active   │  80 │ 2.12.0.v20160420-0247  │ EMF Ecore
 67 │ Active   │  80 │ 2.11.0.v20160420-0247  │ EMF Change Model
 68 │ Active   │  80 │ 2.12.0.v20160420-0247  │ EMF XML/XMI Persistence
 69 │ Active   │  80 │ 3.8.0.v20160509-1230   │ Common Eclipse Runtime
 70 │ Active   │  80 │ 3.6.100.v20160223-2218 │ Extension Registry Support
 80 │ Active   │  80 │ 9.4.11.v20180605       │ Jetty :: Proxy
 94 │ Active   │  80 │ 0.4.1.v20180515-1321   │ org.eclipse.lsp4j
 95 │ Active   │  80 │ 0.4.1.v20180515-1321   │ org.eclipse.lsp4j.jsonrpc
 96 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome OAuth2Client
 97 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Config Core
 98 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Configuration Discovery
 99 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Configuration mDNS Discovery
100 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Config Dispatcher
101 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome Config XML
102 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core
103 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Audio
104 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Binding XML
105 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core ID
106 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Persistence
107 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Scheduler Service
108 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Semantics
109 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Thing
110 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome Core Thing XML
111 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Transformation Service
112 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core Voice
113 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Console
114 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Console for OSGi runtime Karaf
115 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome HTTP Interface Bundle
116 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome JavaSound I/O, Fragments: 183
117 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Monitor
118 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Net I/O Bundle
119 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome REST Interface Bundle
120 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Core REST API
121 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome REST mDNS Announcer
122 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome REST Interface JAX-RS optimization Bundle
123 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Sitemap REST API
124 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome SSE REST API
125 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Voice REST API
126 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Bonjour/MDS Service Discovery Bundle
127 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Web Audio Support
128 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Model Core
129 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Item Model
130 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Item Model IDE
131 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Item Model Runtime
132 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Language Server
133 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Persistence Model
134 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Persistence Model IDE
135 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Persistence Runtime
136 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Rule Model
137 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Rule Model IDE
138 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Rule Runtime
139 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Script
140 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Script Model IDE
141 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Script Runtime
142 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Sitemap Model
143 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Sitemap Model IDE
144 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Sitemap Runtime
145 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Thing Model
146 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Thing Model IDE
147 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Thing Model Runtime
148 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Json Storage Service
149 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome UI
150 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome UI Icons
151 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Classic IconSet
152 │ Active   │  80 │ 2.14.0.v20180522-1629  │ Xtend Runtime Library
153 │ Active   │  80 │ 2.14.0.v20180522-1629  │ Xtend Macro Interfaces
154 │ Active   │  80 │ 2.14.0.v20180522-1821  │ Xtext
155 │ Active   │  80 │ 2.14.0.v20180522-1833  │ Xtext Common Types
156 │ Active   │  80 │ 2.14.0.v20180522-1821  │ Xtext IDE Core
157 │ Active   │  80 │ 2.14.0.v20180522-1821  │ Xtext Utility
158 │ Active   │  80 │ 2.14.0.v20180522-1833  │ Xbase Model
159 │ Active   │  80 │ 2.14.0.v20180522-1833  │ Xbase Generic IDE Services
160 │ Active   │  80 │ 2.14.0.v20180522-1629  │ Xbase Runtime Library
175 │ Active   │  80 │ 1.9.6                  │ MIME streaming extension
177 │ Active   │  80 │ 6.2.0                  │ org.objectweb.asm
178 │ Active   │  80 │ 6.2.0                  │ org.objectweb.asm.commons
179 │ Active   │  80 │ 6.2.0                  │ org.objectweb.asm.tree
180 │ Active   │  90 │ 2.4.0                  │ openHAB Core
181 │ Active   │  80 │ 2.4.0                  │ openHAB Karaf Integration
183 │ Resolved │  80 │ 2.4.0                  │ openHAB Sound Support, Hosts: 116
184 │ Active   │  80 │ 2.4.0                  │ openHAB Dashboard UI
189 │ Active   │  80 │ 1.0.2                  │ Units of Measurement Common Library
190 │ Active   │  80 │ 1.0.8                  │ Units of Measurement Implementation for Java SE
195 │ Active   │  80 │ 3.3.0                  │ Commons Net
200 │ Active   │  80 │ 1.1.1.201605111122     │ Swagger Provider
201 │ Active   │  80 │ 2.4.5                  │ Jackson-annotations
202 │ Active   │  80 │ 2.4.5                  │ Jackson-core
203 │ Active   │  80 │ 2.4.5                  │ jackson-databind
204 │ Active   │  80 │ 2.4.5                  │ Jackson-dataformat-XML
205 │ Active   │  80 │ 2.4.5                  │ Jackson-dataformat-YAML
206 │ Active   │  80 │ 2.4.5                  │ Jackson-module-JAXB-annotations
207 │ Active   │  80 │ 2.1.0                  │ json-path
208 │ Active   │  80 │ 1.5.8                  │ swagger-annotations
209 │ Active   │  80 │ 1.5.8                  │ swagger-core
210 │ Active   │  80 │ 1.5.8                  │ swagger-jaxrs
211 │ Active   │  80 │ 1.5.8                  │ swagger-models
212 │ Active   │  80 │ 3.19.0.GA              │ Javassist
213 │ Active   │  80 │ 2.2                    │ json-smart
214 │ Active   │  80 │ 3.2.1                  │ Apache Commons Lang
216 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome JavaScript Transformation Service
217 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome JSonPath Transformation Service
218 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome Map Transformation Service
219 │ Active   │  75 │ 0.10.0.oh240           │ Eclipse SmartHome RegEx Transformation Service
223 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Basic UI, Fragments: 227
225 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Paper UI, Fragments: 231
226 │ Active   │  80 │ 2.4.0                  │ openHAB REST Documentation
227 │ Resolved │  75 │ 2.4.0                  │ openHAB Basic UI Fragment, Hosts: 223
229 │ Active   │  80 │ 2.4.0                  │ HABmin User Interface
230 │ Active   │  80 │ 2.4.0                  │ HABPanel User Interface
231 │ Resolved │  75 │ 2.4.0                  │ openHAB Paper UI Theme Fragment, Hosts: 225
232 │ Active   │  80 │ 0.9.10.v20160429-1435  │ reflections (wrap)
233 │ Active   │  80 │ 3.1.4                  │ Stax2 API
234 │ Active   │  80 │ 1.5.8.v20160511-1038   │ swagger-jersey2-jaxrs (wrap)
235 │ Active   │  80 │ 3.14.0                 │ nrjavaserial
236 │ Active   │  80 │ 3.15.0.OH2             │ nrjavaserial
237 │ Active   │  80 │ 1.6.0                  │ Commons Codec
238 │ Active   │  80 │ 4.2.3                  │ Apache HttpClient OSGi bundle
239 │ Active   │  80 │ 4.2.3                  │ Apache HttpCore OSGi bundle
240 │ Active   │  80 │ 3.1.0.7                │ Apache ServiceMix :: Bundles :: commons-httpclient
241 │ Active   │  80 │ 1.2.0                  │ Paho MQTT Client
242 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Automation API
243 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Astro Binding
244 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome hue Binding
245 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome MQTT Binding
246 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome MQTT Thing Binding
248 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Configuration UPnP Discovery
249 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Configuration USB-Serial Discovery
250 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Configuration USB-Serial Discovery Linux sysf Scanning
251 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Config Serial
252 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome IoT Marketplace Extension Service
253 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome MQTT Transport Bundle
254 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Serial Transport
255 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Serial Transport for RXTX
256 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Serial Transport extension for RXTX RFC2217
257 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome UPnP Transport Bundle
258 │ Active   │  80 │ 2.5.1                  │ JUPnP Library
259 │ Active   │  80 │ 2.4.0                  │ Exec Binding
260 │ Active   │  80 │ 1.13.0                 │ openHAB Expire Binding
262 │ Active   │  80 │ 1.13.0                 │ openHAB MQTT Binding
264 │ Active   │  80 │ 2.4.0                  │ Network Binding
265 │ Active   │  80 │ 1.13.0                 │ openHAB Plex Binding
266 │ Active   │  80 │ 2.4.0                  │ Samsung Tv Binding
267 │ Active   │  80 │ 1.13.0                 │ openHAB Serial Binding
268 │ Active   │  80 │ 2.4.0                  │ UniFi Binding
269 │ Active   │  80 │ 1.13.0                 │ openHAB Weather Binding
270 │ Active   │  80 │ 2.4.0                  │ ZWave Binding
271 │ Active   │  80 │ 2.4.0                  │ openHAB 1.x Compatibility Layer
272 │ Active   │  80 │ 2.4.0                  │ openHAB Cloud Connector Bundle
273 │ Active   │  80 │ 1.13.0                 │ openHAB MQTT Transport Bundle
274 │ Active   │  80 │ 1.13.0                 │ openHAB InfluxDB Persistence bundle
275 │ Active   │  80 │ 1.13.0                 │ openHAB MapDB Persistence Bundle
276 │ Active   │  80 │ 1.13.0                 │ openHAB RRD4j Persistence Bundle
277 │ Active   │  80 │ 2.2.0                  │ Nest Binding
278 │ Active   │  80 │ 2.4.0.a32              │ SynologySurveillanceStation Binding
279 │ Active   │  80 │ 1.12.0.201804032255    │ openHAB Pushover Action
280 │ Active   │  80 │ 0.10.0.oh240           │ Eclipse SmartHome Sonos Binding

1 Like

Hi,

Try setting the following in your karaf console and then check the openhab log to see if bindings are being re-initialised all the time, that’s what caused my performance issues recently.

 log:set debug org.openhab.core.karaf

If you see bindings being installed over and over again then you need to try and remove/add them again until the message stops, or you may also have a binding bein installed that you no-longer need.

K

Should I be seeing any installation issues beyond the initial startup?

I would love to clear out old bindings if I knew what wasn’t necessary. Why are there two nrjavaserial bindings for instance? Can I get rid of either? both? Lots of stuff in there…

Anyway, it’s back up and running 45 minutes already and I’m currently seeing this

2019-01-04 20:00:55.199 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-weather, openhab-binding-expire, openhab-ui-rest, openhab-binding-http, openhab-binding-plex'
2019-01-04 20:01:53.905 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-04 20:01:55.092 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-weather, openhab-binding-expire, openhab-ui-rest, openhab-binding-http, openhab-binding-plex'
2019-01-04 20:02:53.906 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-04 20:02:54.902 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-weather, openhab-binding-expire, openhab-ui-rest, openhab-binding-http, openhab-binding-plex'

Hi,
Ok so looking at your debug message the same 5 bindings are being re-installed over and over again which will slow the oh instance down, try removing all 5 and the re-add one at a time watching the debug log in between.

I’ve had to do the same thing a few times since upgrading to 2.4 but my system is now stable and running great.

Another possibility could be java heap, some recent posts on that one, but I’d start with the bindings first.

Need to hit the sack now so good luck!

Update: should have mentioned you should just see the following repeated for debug if the issue is resolved.

Running scheduled sync job
Running scheduled sync job
Etc....

K

1 Like

I’d try debug on org.apache.karaf and one or two of your main bindings (where your devices belong to).
Should give you a lot more output w.r.t. state of bindings, to hopefully give pointers where to investigate further.

Same problem here. Because of the Yahoo weather binding not working anymore I had to move to OpenWeatherMap binding, which only works under 2.4 where I had 2.3 (in docker). So stopped OH, deleted image, started new image with 2.4 (had to do some work on configfiles).
After that everytime in about 10-20 minutes the system dies on me: no log info anymore, no events, no response from the ui. OSGI works but that is about it. Going back to 2.3 solves all the problems. I will be following this thread :thinking:

kr Han

Put it in debug while it’s in its “limbo” state?

Same thing here. It was installing http and db4o over and over again. I removed those two for now.

You saved me. Thanks. I was trying to find the issue the past 48h with no success. No it seems solved. THANKS. System load went down from 100% to 20%.

Will let you keep updated.

Hi,

That’s the same behaviour as mine with system load dropping back to a manageable 20% ish so sounds like a winner, funny enough http binding was one of the three I also had re-loading time and time again.
To be honest the thanks belongs to another post which originally helped me but I’m just trying to help pass the knowledge on but good to know your oh service is stable again.
K

Still have the same behaviour. System stalls quietly. I have put Karaf on debug

log:set debug org.openhab.core.karaf

and now see the following log:

2019-01-06 10:56:53.670 [WARN ] [e.jetty.util.thread.ThreadPoolBudget] - Low configured threads: (max=8 - required=1)=7 < warnAt=8 for QueuedThreadPool[ServletModel-9]@8a29b35{STARTING,8<=0<=8,i=0,q=0}[ReservedThreadExecutor@7c61c4dd{s=0/1,p=0}]
2019-01-06 10:56:54.061 [DEBUG] [org.openhab.core.karaf              ] - BundleEvent STARTING - org.openhab.core.karaf
2019-01-06 10:56:54.100 [DEBUG] [org.openhab.core.karaf              ] - BundleEvent STARTED - org.openhab.core.karaf
2019-01-06 10:56:54.131 [DEBUG] [org.openhab.core.karaf              ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService}={service.id=344, service.bundleid=181, service.scope=singleton} - org.openhab.core.karaf
2019-01-06 10:56:54.104 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /rest/items
javax.servlet.ServletException: javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_2,3,251341278) has been shut down

	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:88) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.Server.handle(Server.java:531) ~[84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [84:org.eclipse.jetty.server:9.4.11.v20180605]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [87:org.eclipse.jetty.util:9.4.11.v20180605]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_2,3,251341278) has been shut down

	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
	... 15 more
Caused by: org.glassfish.hk2.api.MultiException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_2,3,251341278) has been shut down

	at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:106) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
	at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[?:?]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
	... 15 more
Caused by: java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_2,3,251341278) has been shut down
	at org.jvnet.hk2.internal.ServiceLocatorImpl.checkState(ServiceLocatorImpl.java:2288) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandleImpl(ServiceLocatorImpl.java:629) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:622) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:640) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:103) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
	at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[?:?]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[?:?]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[?:?]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[?:?]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[?:?]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) ~[?:?]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[?:?]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) ~[?:?]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[?:?]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) ~[?:?]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) ~[?:?]
	... 15 more
2019-01-06 10:56:54.614 [DEBUG] [org.openhab.core.karaf              ] - ServiceEvent REGISTERED - {org.openhab.core.karaf.internal.FeatureInstaller, org.osgi.service.cm.ConfigurationListener}={action=mqtt, package=expert, service.id=345, service.bundleid=181, service.scope=bundle, binding=astro,weatherunderground,hue,rfxcom,network,http1,mqtt,mqtt1, persistence=mysql, transformation=map,regex,xslt,exec,javascript,scale,xpath,jsonpath, misc=restdocs,openhabcloud, component.name=org.openhab.addons, service.config.label=Add-on Management, component.id=196, ui=classic,basic,paper,habpanel,habmin, remote=true, service.config.category=system, legacy=true, service.config.description.uri=system:addons, service.pid=org.openhab.addons} - org.openhab.core.karaf
2019-01-06 10:56:54.635 [DEBUG] [org.openhab.core.karaf              ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.extension.ExtensionService}={service.id=346, service.bundleid=181, service.scope=bundle, component.name=org.openhab.core.karafextension, component.id=197} - org.openhab.core.karaf
2019-01-06 10:56:54.799 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://172.17.0.1:8080
2019-01-06 10:56:54.801 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://172.17.0.1:8443
2019-01-06 10:57:02.799 [INFO ] [rthome.model.script.Time of Day rule] - Calculating time of day...
2019-01-06 10:57:02.845 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Calculate time of day state': Could not cast NULL to org.eclipse.smarthome.core.library.types.DateTimeType; line 18, column 31, length 34
2019-01-06 10:57:04.506 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '172.30.2.4' with clientid Openhab MQTT binding 2.4 and file store '/openhab/userdata/mqtt/172.30.2.4'
2019-01-06 10:57:04.846 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2019-01-06 10:57:05.108 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:minus60
2019-01-06 10:57:05.260 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2019-01-06 10:57:05.917 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-01-06 10:57:07.066 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2019-01-06 10:57:07.531 [ERROR] [org.jupnp.transport.spi.StreamClient] - Request: HttpRequest[GET /gsctrl_SCPD.xml HTTP/1.1]@3ee6ab46 failed
java.lang.NullPointerException: Missing SslContextFactory
	at java.util.Objects.requireNonNull(Objects.java:228) ~[?:?]
	at org.eclipse.jetty.io.ssl.SslClientConnectionFactory.<init>(SslClientConnectionFactory.java:50) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpClient.newSslClientConnectionFactory(HttpClient.java:1155) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpDestination.newSslClientConnectionFactory(HttpDestination.java:138) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpDestination.<init>(HttpDestination.java:95) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.PoolingHttpDestination.<init>(PoolingHttpDestination.java:25) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.http.HttpDestinationOverHTTP.<init>(HttpDestinationOverHTTP.java:32) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.http.HttpClientTransportOverHTTP.newHttpDestination(HttpClientTransportOverHTTP.java:51) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpClient.destinationFor(HttpClient.java:539) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpClient.send(HttpClient.java:572) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:727) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:680) ~[71:org.eclipse.jetty.client:9.4.11.v20180605]
	at org.jupnp.transport.impl.jetty.JettyStreamClientImpl$1.call(JettyStreamClientImpl.java:155) [244:org.jupnp:2.5.1]
	at org.jupnp.transport.impl.jetty.JettyStreamClientImpl$1.call(JettyStreamClientImpl.java:1) [244:org.jupnp:2.5.1]
	at org.jupnp.transport.spi.AbstractStreamClient$RequestWrapper.call(AbstractStreamClient.java:204) [244:org.jupnp:2.5.1]
	at org.jupnp.transport.spi.AbstractStreamClient$RequestWrapper.call(AbstractStreamClient.java:1) [244:org.jupnp:2.5.1]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	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) [?:?]
2019-01-06 10:57:09.618 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.

Anybody any clue?

kr

Han

Hi @havaak,

I have had a quick look at the log extract and can see only one entry so far where “org.openhab.core.karaf.internal.FeatureInstaller” is mentioned, can you try doing a grep for the string in the log now to see if more entries exist?

2019-01-06 10:56:54.614 [DEBUG] [org.openhab.core.karaf              ] - ServiceEvent REGISTERED - {org.openhab.core.karaf.internal.FeatureInstaller,
grep "core.karaf.internal.FeatureInstaller" openhab.log

See if more lines are now being returned?

K

Hey @KevinI,

the log shows:

2019-01-06 11:11:46.204 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:11:49.046 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:12:46.210 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:12:48.570 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:13:46.219 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:13:48.436 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:14:46.235 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:14:48.372 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:15:46.240 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:15:48.143 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:16:46.244 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:16:48.261 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:17:46.251 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:17:48.788 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:18:46.257 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:18:47.958 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:19:46.264 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:19:48.033 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:20:46.277 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:20:48.042 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'
2019-01-06 11:21:46.280 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-06 11:21:47.991 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt'

I already removed and installed openhab-binding-mqtt a couple of times. Maybe note worthy is that I have MQTT 1.13 and 2.4 installed because I have to migrate from old to new.

kr

Han

Hi Han,

So the issue is it’s continually re-loading the mqtt binding which will be adding load to your system, if your capturing cpu usage via the sysinfo binding the load will be higher while the problem exists and the knock on effect is 500/503 errors in the iOS app for instance.
Do you use the ui or addons.cfg for loading the bindings, I bet if you uninstall the mqtt binding the issue goes away?

It took me a few cycles, via addons.cfg, to get the issue resolved but since then the system has been stable.

K

Kevin,

the thing is I see the same error logging on 2.3 which does not get stuck and I have already removed the addons.cfg file. I will try to build a clean (docker) system because everytime I try I bring down my primary system

kr Han

Doesn’t matter when.

Hi Han,

Ok understood, another solution is mentioned at the end of the below post by @wborn about removing the addons.config file.

Seems a few people have been suffering from the same issue however mine only started after going to 2.4.

K

Kevin,

a thing I noted when deinstalling and installing the MQTT binding:

2019-01-06 12:03:52.662 [DEBUG] [core.karaf.internal.FeatureInstaller] - Installed 'openhab-binding-mqtt, openhab-binding-mqtt1'

Is the system installing 2 bindings, mqtt & mqtt1?

kr

Han

Hi Han,

Yep looks like it’s doing both.

K

Ok, but how do I prevent that?

openhab> bundle:list | grep -i mqtt
245 │ Active   │  80 │ 1.12.0                 │ openHAB Mqtt Action
247 │ Active   │  80 │ 1.12.0                 │ openHAB MQTT Transport Bundle
248 │ Active   │  80 │ 1.12.0                 │ openHAB MQTT Binding

Han

Hi Han,

Do you use ui or addons.cfg?

What’s in the file?

/var/lib/openhab2/config/org/openhab/addons.config

K