This group is locked. No changes can be made to the group while it is locked.
Date
1 - 9 of 9
[release] netconf SFT hanging for over 3 hrs
|
Robert Varga
On 13/07/17 17:22, Thanh Ha wrote:
On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...Logs have these two last items: 2017-07-12 17:40:12,572 | INFO | Framework stop | ContextHandler | 275 - org.eclipse.jetty.util - 9.2.19.v20160908 | Stopped HttpServiceContext{httpContext=WebAppHttpContext{org.opendaylight.aaa.shiro - 294}} 2017-07-12 17:40:12,574 | INFO | Framework stop | Activator | 326 - org.ops4j.pax.web.pax-web-extender-war - 4.3.0 | Destroying extension for bundle org.opendaylight.aaa.idmlight So the framework is actually stopping, but halted on something related to either idmlight... As Michael noted, a thread dump would shed more light on this. Bye, Robert
|
|
|
|
Robert Varga
On 13/07/17 17:51, Robert Varga wrote:
https://logs.opendaylight.org/releng/jenkins092/autorelease-release-nitrogen/102/netconf/features/netconf-connector/odl-netconf-clustered-topology/target/surefire-reports/org.opendaylight.odlparent.featuretest.SingleFeatureTest-output.txt.gz are the logs. The primary failure cause is this: 2017-07-12 17:35:29,388 | ERROR | rint Extender: 3 | BlueprintContainerImpl | 12 - org.apache.aries.blueprint.core - 1.7.1 | Unable to start blueprint container for bundle org.opendaylight.netconf.topology-singleton/1.3.0.Nitrogen due to unresolved dependencies [(objectClass=org.opendaylight.controller.config.threadpool.ScheduledThreadPool), (objectClass=org.opendaylight.controller.config.threadpool.ThreadPool)] java.util.concurrent.TimeoutException at org.apache.aries.blueprint.container.BlueprintContainerImpl$1.run(BlueprintContainerImpl.java:371)[12:org.apache.aries.blueprint.core:1.7.1] at org.apache.aries.blueprint.utils.threading.impl.DiscardableRunnable.run(DiscardableRunnable.java:48)[12:org.apache.aries.blueprint.core:1.7.1] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_131] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131] at java.lang.Thread.run(Thread.java:748)[:1.8.0_131] But we are failing to shut down cleanly, I suspect it is AAA again, there is this during framework stop: 2017-07-12 17:40:12,554 | INFO | Framework stop | shiro - 294} | 275 - org.eclipse.jetty.util - 9.2.19.v20160908 | Cleaning up Shiro Environment 2017-07-12 17:40:12,555 | ERROR | Framework stop | AbstractFilter | 257 - org.apache.shiro.web - 1.3.2 | Unable to start Filter: [No WebEnvironment found: no EnvironmentLoaderListener registered?]. java.lang.IllegalStateException: No WebEnvironment found: no EnvironmentLoaderListener registered? at org.apache.shiro.web.util.WebUtils.getRequiredWebEnvironment(WebUtils.java:277)[257:org.apache.shiro.web:1.3.2] at org.apache.shiro.web.servlet.ShiroFilter.init(ShiroFilter.java:73)[257:org.apache.shiro.web:1.3.2] at org.opendaylight.aaa.shiro.filters.AAAShiroFilter.init(AAAShiroFilter.java:48)[294:org.opendaylight.aaa.shiro:0.6.0.Nitrogen] at org.apache.shiro.web.servlet.AbstractShiroFilter.onFilterConfigSet(AbstractShiroFilter.java:152)[257:org.apache.shiro.web:1.3.2] at org.apache.shiro.web.servlet.AbstractFilter.init(AbstractFilter.java:97)[257:org.apache.shiro.web:1.3.2] at org.eclipse.jetty.servlet.FilterHolder.initialize(FilterHolder.java:138)[273:org.eclipse.jetty.servlet:9.2.19.v20160908] at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:852)[273:org.eclipse.jetty.servlet:9.2.19.v20160908] at org.eclipse.jetty.servlet.ServletHandler.updateMappings(ServletHandler.java:1526)[273:org.eclipse.jetty.servlet:9.2.19.v20160908] at org.eclipse.jetty.servlet.ServletHandler.setFilterMappings(ServletHandler.java:1560)[273:org.eclipse.jetty.servlet:9.2.19.v20160908] at org.ops4j.pax.web.service.jetty.internal.JettyServerImpl$5.call(JettyServerImpl.java:597)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.web.service.jetty.internal.JettyServerImpl$5.call(JettyServerImpl.java:593)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.swissbox.core.ContextClassLoaderUtils.doWithClassLoader(ContextClassLoaderUtils.java:60)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.web.service.jetty.internal.JettyServerImpl.removeFilter(JettyServerImpl.java:592)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.web.service.jetty.internal.ServerControllerImpl$Started.removeFilter(ServerControllerImpl.java:320)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.web.service.jetty.internal.ServerControllerImpl.removeFilter(ServerControllerImpl.java:150)[328:org.ops4j.pax.web.pax-web-jetty:4.3.0] at org.ops4j.pax.web.service.internal.HttpServiceStarted.unregisterFilter(HttpServiceStarted.java:604)[330:org.ops4j.pax.web.pax-web-runtime:4.3.0] at org.ops4j.pax.web.service.internal.HttpServiceProxy.unregisterFilter(HttpServiceProxy.java:232)[330:org.ops4j.pax.web.pax-web-runtime:4.3.0] at org.ops4j.pax.web.extender.war.internal.UnregisterWebAppVisitorWC.visit(UnregisterWebAppVisitorWC.java:171)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.model.WebApp.accept(WebApp.java:666)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.unregister(WebAppPublisher.java:266)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.removedService(WebAppPublisher.java:224)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.removedService(WebAppPublisher.java:135)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:967)[org.osgi.core-6.0.0.jar:] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:] at org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:341)[org.osgi.core-6.0.0.jar:] at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:909)[org.osgi.core-6.0.0.jar:] at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.ops4j.pax.web.extender.war.internal.DefaultWebAppDependencyManager.removeWebApp(DefaultWebAppDependencyManager.java:101)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.WebObserver$1.doDestroy(WebObserver.java:189)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.extender.SimpleExtension.destroy(SimpleExtension.java:71)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender$2.run(AbstractExtender.java:307)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131] at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender.destroyExtension(AbstractExtender.java:333)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender.bundleChanged(AbstractExtender.java:191)[326:org.ops4j.pax.web.pax-web-extender-war:4.3.0] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.doStop(Module.java:626)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:159)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at java.lang.Thread.run(Thread.java:748)[:1.8.0_131] e.g. we are initializing a filter while shutting down ... why?! Regards, Robert
|
|
|
|
Thanh Ha <thanh.ha@...>
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote: On 13/07/17 17:22, Thanh Ha wrote: The attached zip contains the jstacks for all the java processes I could find. I wasn't sure which process was the correct one but I printed their `ps` statement at the top of each log which I hope helps pinpoint the correct one for those who know what to look for. Regards, Thanh
|
|
|
|
Tom Pantelis
The shutdown thread is waiting on lock 0x00000006cac049f0: "Framework stop" #290 daemon prio=5 os_prio=0 tid=0x00007ff33832d000 nid=0x1b36 waiting for monitor entry [0x00007ff3768b6000] java.lang.Thread.State: BLOCKED (on object monitor) at org.ops4j.pax.web.extender.war.internal.extender.SimpleExtension.destroy(SimpleExtension.java:67) - waiting to lock <0x00000006cac049f0> (a org.ops4j.pax.web.extender.war.internal.WebObserver$1) at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender$2.run(AbstractExtender.java:307) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender.destroyExtension(AbstractExtender.java:333) at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender.bundleChanged(AbstractExtender.java:191) at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165) at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75) at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67) at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102) at org.eclipse.osgi.container.Module.publishEvent(Module.java:466) at org.eclipse.osgi.container.Module.doStop(Module.java:624) at org.eclipse.osgi.container.Module.stop(Module.java:488) at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:1623) at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1542) - locked <0x00000006c7fbe450> (a java.lang.Object) at org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:248) at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:144) at org.eclipse.osgi.container.Module.doStop(Module.java:626) at org.eclipse.osgi.container.Module.stop(Module.java:488) at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:186) Which is held by this thread: "paxweb-extender-2-thread-3" #206 prio=5 os_prio=0 tid=0x00007ff34cf9d000 nid=0x1af2 runnable [0x00007ff32fda6000] java.lang.Thread.State: RUNNABLE at org.opendaylight.aaa.shiro.web.env.KarafIniWebEnvironment.init(KarafIniWebEnvironment.java:72) at org.apache.shiro.util.LifecycleUtils.init(LifecycleUtils.java:45) at org.apache.shiro.util.LifecycleUtils.init(LifecycleUtils.java:40) at org.apache.shiro.web.env.EnvironmentLoader.createEnvironment(EnvironmentLoader.java:221) at org.apache.shiro.web.env.EnvironmentLoader.initEnvironment(EnvironmentLoader.java:133) at org.apache.shiro.web.env.EnvironmentLoaderListener.contextInitialized(EnvironmentLoaderListener.java:58) at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext$3.call(HttpServiceContext.java:354) at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext$3.call(HttpServiceContext.java:350) at org.ops4j.pax.swissbox.core.ContextClassLoaderUtils.doWithClassLoader(ContextClassLoaderUtils.java:60) at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.callContextInitialized(HttpServiceContext.java:349) at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:791) at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:294) at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.startContext(HttpServiceContext.java:601) at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:741) at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doStart(HttpServiceContext.java:260) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) - locked <0x00000006ca9e43d8> (a java.lang.Object) at org.ops4j.pax.web.service.jetty.internal.JettyServerImpl$1.start(JettyServerImpl.java:279) at org.ops4j.pax.web.service.internal.HttpServiceStarted.end(HttpServiceStarted.java:1096) at org.ops4j.pax.web.service.internal.HttpServiceProxy.end(HttpServiceProxy.java:417) at org.ops4j.pax.web.extender.war.internal.RegisterWebAppVisitorWC.end(RegisterWebAppVisitorWC.java:380) at org.ops4j.pax.web.extender.war.internal.model.WebApp.accept(WebApp.java:692) at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.register(WebAppPublisher.java:237) at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.addingService(WebAppPublisher.java:182) at org.ops4j.pax.web.extender.war.internal.WebAppPublisher$WebAppDependencyListener.addingService(WebAppPublisher.java:135) at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318) at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) at org.ops4j.pax.web.extender.war.internal.WebAppPublisher.publish(WebAppPublisher.java:101) at org.ops4j.pax.web.extender.war.internal.WebObserver.deploy(WebObserver.java:219) at org.ops4j.pax.web.extender.war.internal.WebObserver$1.doStart(WebObserver.java:179) at org.ops4j.pax.web.extender.war.internal.extender.SimpleExtension.start(SimpleExtension.java:59) - locked <0x00000006cac049f0> (a org.ops4j.pax.web.extender.war.internal.WebObserver$1) at org.ops4j.pax.web.extender.war.internal.extender.AbstractExtender$1.run(AbstractExtender.java:281) So it looks like org.opendaylight.aaa.shiro.web.env.KarafIniWebEnvironment.init is stuck/hung.
On Thu, Jul 13, 2017 at 3:52 PM, Thanh Ha <thanh.ha@...> wrote:
|
|
|
|
Tom Pantelis
It looks like this is in an endless loop: while (shiroConfiguration == null) { shiroConfiguration = AAAShiroProvider.getInstance().getShiroConfiguration(); }
On Thu, Jul 13, 2017 at 4:09 PM, Tom Pantelis <tompantelis@...> wrote:
|
|
|
|
Tom Pantelis
So if getInstance is called when INSTANCE is yet set, then it will create INSTANCE with all nulls and thus the shiroConfiguration will forever be null. public static AAAShiroProvider getInstance() { if (INSTANCE == null) { newInstance(null, null, null, null, null,null); } return INSTANCE; } So to get a valid INSTANCE, it must be created via the aaa-shiro-impl BP which injects a non-null ShiroConfiguration. So it seems KarafIniWebEnvironment is racing with the BP container. This is a bit fragile - I think getInstance should just return the INSTANCE and not create it and KarafIniWebEnvironment should busy wait on that (with a sleep). Also INSTANCE should be volatile.
On Thu, Jul 13, 2017 at 4:13 PM, Tom Pantelis <tompantelis@...> wrote:
|
|
|
|
Tom Pantelis
toggle quoted messageShow quoted text
On Thu, Jul 13, 2017 at 4:32 PM, Tom Pantelis <tompantelis@...> wrote:
|
|
|
|
Colin Dixon <colin@...>
Do we know if this fixed the issue? --Colin
On Thu, Jul 13, 2017 at 1:57 PM, Tom Pantelis <tompantelis@...> wrote:
|
|
|
|
Thanh Ha <thanh.ha@...>
At least in autorelease we haven't seen it for a few days. Regards, Thanh
On Thu, Jul 20, 2017 at 12:24 AM, Colin Dixon <colin@...> wrote:
|
|
|