[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@...
<mailto:thanh.ha@...>> wrote:

Hi Everyone,

I cancelled autorelease-nitrogen build #102 because SFT was hanging
for over 3 hrs. I'm not sure if this is normal or if it's the issue
we were seeing before back in Carbon?

[INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [ 03:02 h]


https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
<https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>

Regards,
Thanh


So this is a serious problem. Build #103 was hanging too on "ODL ::
neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
hanging on the same thing.

Not sure if it's related but appears we are consistently hanging tests
now. How do we troubleshoot this?
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:


On 13/07/17 17:22, Thanh Ha wrote:
On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
<mailto:thanh.ha@...>> wrote:

Hi Everyone,

I cancelled autorelease-nitrogen build #102 because SFT was hanging
for over 3 hrs. I'm not sure if this is normal or if it's the issue
we were seeing before back in Carbon?

[INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [ 03:02 h]


https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
<https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>

Regards,
Thanh


So this is a serious problem. Build #103 was hanging too on "ODL ::
neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
hanging on the same thing.

Not sure if it's related but appears we are consistently hanging tests
now. How do we troubleshoot this?
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.
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:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release



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:
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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release




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:
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:
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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release





Tom Pantelis
 

On Thu, Jul 13, 2017 at 4:32 PM, Tom Pantelis <tompantelis@...> wrote:
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:
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:
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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release






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:

On Thu, Jul 13, 2017 at 4:32 PM, Tom Pantelis <tompantelis@...> wrote:
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:
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:
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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release






_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release



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:
Do we know if this fixed the issue?

--Colin


On Thu, Jul 13, 2017 at 1:57 PM, Tom Pantelis <tompantelis@...> wrote:

On Thu, Jul 13, 2017 at 4:32 PM, Tom Pantelis <tompantelis@...> wrote:
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:
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:
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:
On Thu, Jul 13, 2017 at 11:51 AM, Robert Varga <nite@...> wrote:
On 13/07/17 17:22, Thanh Ha wrote:
> On Wed, Jul 12, 2017 at 4:35 PM, Thanh Ha <thanh.ha@...
> <mailto:thanh.ha@linuxfoundation.org>> wrote:
>
>     Hi Everyone,
>
>     I cancelled autorelease-nitrogen build #102 because SFT was hanging
>     for over 3 hrs. I'm not sure if this is normal or if it's the issue
>     we were seeing before back in Carbon?
>
>     [INFO] OpenDaylight :: Clustered Netconf Topology :: Netconf Connector + Netconf SSH Server FAILURE [  03:02 h]
>
>
>     https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/
>     <https://jenkins.opendaylight.org/releng/view/autorelease/job/autorelease-release-nitrogen/102/>
>
>     Regards,
>     Thanh
>
>
> So this is a serious problem. Build #103 was hanging too on "ODL ::
> neutron :: integration-test 0.9.0-Nitrogen". and build #104 is currently
> hanging on the same thing.
>
> Not sure if it's related but appears we are consistently hanging tests
> now. How do we troubleshoot this?

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.


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


_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release






_______________________________________________
release mailing list
release@...
https://lists.opendaylight.org/mailman/listinfo/release