search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

[neeo] Scheduled runnable ended with an exception & NPE after upgrade #15043

Open morph166955 opened 1 year ago

morph166955 commented 1 year ago

When upgrading from snapshot to snapshot I see the following exceptions. From what I can tell, everything starts normally (including Neeo, my things all come ONLINE), and I assume after all of the cache is built OH does some kind of restart... 

2023-05-30 10:28:27.993 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.neeo.internal.handler.NeeoBrainHandler@49018fb3': Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
java.lang.RuntimeException: Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$doUnregisterServlet$2(HttpServiceEnabled.java:703) ~[?:?]
        at org.ops4j.pax.web.service.spi.model.ServerModel.lambda$run$2(ServerModel.java:541) ~[?:?]
        at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
        Suppressed: java.lang.Throwable
                at org.ops4j.pax.web.service.spi.model.ServerModel.run(ServerModel.java:535) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceEnabled.doUnregisterServlet(HttpServiceEnabled.java:585) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceEnabled.unregister(HttpServiceEnabled.java:545) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregister(HttpServiceProxy.java:186) ~[?:?]
                at org.openhab.binding.neeo.internal.handler.NeeoBrainHandler.dispose(NeeoBrainHandler.java:352) ~[?:?]
                at jdk.internal.reflect.GeneratedMethodAccessor167.invoke(Unknown Source) ~[?:?]
                at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
                at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
                at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) ~[?:?]
                at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) ~[?:?]
                at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
                at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.IllegalArgumentException: Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$doUnregisterServlet$2(HttpServiceEnabled.java:612) ~[?:?]
        ... 8 more
2023-05-30 10:28:28.005 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while disposing handler of thing 'neeo:brain:05dbea22': Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
java.lang.RuntimeException: Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$doUnregisterServlet$2(HttpServiceEnabled.java:703) ~[?:?]
        at org.ops4j.pax.web.service.spi.model.ServerModel.lambda$run$2(ServerModel.java:541) ~[?:?]
        at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
        Suppressed: java.lang.Throwable
                at org.ops4j.pax.web.service.spi.model.ServerModel.run(ServerModel.java:535) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceEnabled.doUnregisterServlet(HttpServiceEnabled.java:585) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceEnabled.unregister(HttpServiceEnabled.java:545) ~[?:?]
                at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregister(HttpServiceProxy.java:186) ~[?:?]
                at org.openhab.binding.neeo.internal.handler.NeeoBrainHandler.dispose(NeeoBrainHandler.java:352) ~[?:?]
                at jdk.internal.reflect.GeneratedMethodAccessor167.invoke(Unknown Source) ~[?:?]
                at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
                at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
                at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) ~[?:?]
                at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) ~[?:?]
                at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
                at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.IllegalArgumentException: Alias "/neeo/binding/05dbea22/forwardactions" was never registered by org.openhab.binding.neeo_4.0.0.202305290353 [263]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$doUnregisterServlet$2(HttpServiceEnabled.java:612) ~[?:?]
        ... 8 more

As it restarts I get flooded with the following...

2023-05-30 10:29:37.604 [WARN ] [eclipse.jetty.servlet.ServletHandler] - EXCEPTION
java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.server.handler.ContextHandler$Context.getContextHandler()" because the return value of "org.eclipse.jetty.server.handler.ContextHandler.getCurrentContext()" is null
        at org.eclipse.jetty.servlet.ListenerHolder.doStop(ListenerHolder.java:114) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:94) ~[?:?]
        at org.eclipse.jetty.servlet.ServletHandler.doStop(ServletHandler.java:331) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doStop(PaxWebServletHandler.java:182) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:94) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:180) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.remove(ContainerLifeCycle.java:642) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.removeBean(ContainerLifeCycle.java:618) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.updateBean(ContainerLifeCycle.java:873) ~[?:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.setHandler(HandlerWrapper.java:89) ~[?:?]
        at org.eclipse.jetty.servlet.ServletContextHandler.replaceHandler(ServletContextHandler.java:596) ~[?:?]
        at org.eclipse.jetty.servlet.ServletContextHandler.setSecurityHandler(ServletContextHandler.java:630) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper.ensureServletContextStarted(JettyServerWrapper.java:2222) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper.visitTransactionStateChange(JettyServerWrapper.java:731) ~[?:?]
        at org.ops4j.pax.web.service.spi.task.TransactionStateChange.accept(TransactionStateChange.java:35) ~[?:?]
        at org.ops4j.pax.web.service.spi.task.Batch.accept(Batch.java:430) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerController.sendBatch(JettyServerController.java:168) ~[?:?]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$stop$0(HttpServiceEnabled.java:267) ~[?:?]
        at org.ops4j.pax.web.service.spi.model.ServerModel.lambda$run$2(ServerModel.java:541) ~[?:?]
        at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
2023-05-30 10:29:37.610 [ERROR] [ce.jetty.internal.JettyServerWrapper] - Multiple servlets map to path /neeo/*: default-fcbf65ab-50dd-46fb-a794-9c32384865a3[mapped:EMBEDDED:null],default-e6c65075-6078-40e4-9b2c-96fda20eee6c[mapped:EMBEDDED:null]
java.lang.IllegalStateException: Multiple servlets map to path /neeo/*: default-fcbf65ab-50dd-46fb-a794-9c32384865a3[mapped:EMBEDDED:null],default-e6c65075-6078-40e4-9b2c-96fda20eee6c[mapped:EMBEDDED:null]
        at org.eclipse.jetty.servlet.ServletHandler.updateMappings(ServletHandler.java:1434) ~[?:?]
        at org.eclipse.jetty.servlet.ServletHandler.doStart(ServletHandler.java:166) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doStart(PaxWebServletHandler.java:143) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[?:?]
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[?:?]
        at org.eclipse.jetty.security.SecurityHandler.doStart(SecurityHandler.java:411) ~[?:?]
        at org.eclipse.jetty.security.ConstraintSecurityHandler.doStart(ConstraintSecurityHandler.java:417) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[?:?]
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[?:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.doStart(ScopedHandler.java:120) ~[?:?]
        at org.eclipse.jetty.server.session.SessionHandler.doStart(SessionHandler.java:505) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[?:?]
        at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[?:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.doStart(ScopedHandler.java:120) ~[?:?]
        at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:975) ~[?:?]
        at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:375) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletContextHandler.startContext(PaxWebServletContextHandler.java:279) ~[?:?]
        at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:916) ~[?:?]
        at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:288) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletContextHandler.doStart(PaxWebServletContextHandler.java:307) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper.ensureServletContextStarted(JettyServerWrapper.java:2380) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper.visitTransactionStateChange(JettyServerWrapper.java:731) ~[?:?]
        at org.ops4j.pax.web.service.spi.task.TransactionStateChange.accept(TransactionStateChange.java:35) ~[?:?]
        at org.ops4j.pax.web.service.spi.task.Batch.accept(Batch.java:430) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerController.sendBatch(JettyServerController.java:168) ~[?:?]
        at org.ops4j.pax.web.service.internal.HttpServiceEnabled.lambda$stop$0(HttpServiceEnabled.java:267) ~[?:?]
        at org.ops4j.pax.web.service.spi.model.ServerModel.lambda$run$2(ServerModel.java:541) ~[?:?]
        at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]

The system starts normally otherwise. If I then stop and start OH manually everything comes up and is fine. This seems to only happen on that first start after an update.

morph166955 commented 1 year ago

Could be related to #14545

lsiepel commented 2 months ago

Can you confirm this is still happening with 4.2.1?