Installation broken with empty logs after 3.1 upgrade from 3.0.x

Hoehlenbauer · July 4, 2021, 4:20pm

Just upgraded from latest 3.0.x to 3.1 on my production system. OpenHab is down, UI not reachable after reboot, OpenHab logs empty, nothing OpenHab specific ins syslog that I can see. OpenHab service is shown as active. The only thing that looks suspicious is a bunch of FireMotD related parsing errors in syslog, which were gone after updating FireMotD via openhabian-config.

Repeated restarting, rebooting, etc. all proved without effect, logs alway empty, except after one restart, which (non-reproducibly) gave this in openhab.log:

2021-07-03 19:20:23.119 [WARN ] [raf.features.internal.osgi.Activator] - Error starting activator
java.lang.IllegalStateException: BundleContext is no longer valid org.apache.karaf.features.core_4.3.2 [18]
    at 

org.eclipse.osgi.internal.framework.BundleContextImpl.checkValid(BundleContextImpl.java:1027) ~[org.eclipse.osgi-3.16.200.jar:?]
    at 
org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(Bundle
ContextImpl.java:495) ~[org.eclipse.osgi-3.16.200.jar:?]
    at 
org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:515) ~[org.eclipse.osgi-3.16.200.jar:?]
    at 
org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:1043) ~[org.eclipse.osgi-3.16.200.jar:?]
    at 
org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:425) ~[bundleFile:?]
    at 
org.apache.karaf.util.tracker.BaseActivator.register(BaseActivator.java:413) ~[bundleFile:?]
    at 
org.apache.karaf.features.internal.osgi.Activator.doStart(Activator.java:198) ~[bundleFile:?]
    at org.apache.karaf.util.tracker.BaseActivator.run(BaseActivator.java:312) 
[bundleFile:?]
    at 
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    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:829) [?:?]

Any suggestions would be much appreciated. Note: I’m running a 64-bit OpenHabian…

Wolfgang_S · July 4, 2021, 5:08pm

Although I am not sure if it would help does “etc.” include clearing the OH cache ?

Hoehlenbauer · July 4, 2021, 6:21pm

Thanks for the suggestion. Hadn’t tried this (am pretty new to the OpenHab world…).
Results:
openhab-cli stop
would not stop service.
systemctl stop openhab.service
worked.
openhab-cli clean-cache
did not produce any errors.

After reboot, openhab.log actually shows various errors for the first time (I guess this counts as progress ?)
2021-07-04 20:09:41.602 [INFO ] [org.openhab.ui.internal.UIService ] - Started UI on port 8080 2021-07-04 20:09:56.414 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to ‘Europe/Berlin’. 2021-07-04 20:09:56.424 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ‘50.69290478895001,7.0868402966942865’. 2021-07-04 20:09:56.428 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to ‘de_DE’. 2021-07-04 20:09:56.431 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to ‘SI’. 2021-07-04 20:10:00.605 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘jdbc.persist’ 2021-07-04 20:10:03.874 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /rest/ java.lang.NullPointerException: null at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[?:?] at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[?:?] at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[?:?] at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[?:?] at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[?:?] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[?:?] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:222) ~[?:?] at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) ~[bundleFile:3.1.0] at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[?:?] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:791) ~[?:?] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[?:?] at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[?:?] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[?:?] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435) ~[bundleFile:9.4.40.v20210413] at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[?:?] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[?:?] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.40.v20210413] at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[?:?] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) ~[bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.40.v20210413] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.40.v20210413]

Wolfgang_S · July 5, 2021, 5:31am

You still cannot connect to port 8080 ?

Hoehlenbauer · July 5, 2021, 9:36am

Correct. Although the Main UI was on 8443 previously (via SSL). Neither works.

Hoehlenbauer · July 5, 2021, 10:08am

Update: now that logging was back online, it turned out there were a bunch of permission issues which broke the OpenHab startup process. Running the “fix permissions” tool once more (had done this before clearing the cache without effect) in openhabian-config + one more reboot fixed this => OpenHab back online, from what I can see without any apparent damage.

Thanks for all the the help! Let me know if you need further info to help improve the upgrade process.