[NETCONF-583] Karaf takes 6 minutes to shutdown when odl-netconf-mdsal is installed Created: 23/Nov/18  Updated: 26/Nov/18  Resolved: 26/Nov/18

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: Fluorine SR1
Fix Version/s: None

Type: Bug Priority: High
Reporter: Richard Kosegi Assignee: Jakub Morvay
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Fedora 29 / openjdk version "1.8.0_191"

Fluorine-SR1


Attachments: Text File threaddump.txt    
Issue Links:
Duplicate
duplicates NETCONF-577 sshd-2.0.0 seems to be stuck on shutdown Resolved

 Description   

When odl-netconf-mdsal is installed, there is unnecessary delay in shutdown (5+1 minutes).

Steps to reproduce:

Download and extract https://nexus.opendaylight.org/content/repositories/opendaylight.release/org/opendaylight/integration/karaf/0.9.1/karaf-0.9.1.tar.gz

Start using

./bin/karaf

Install odl-netconf-mdsal

feature:install odl-netconf-mdsal

Request shutdown from second terminal

./bin/stop

Observe delay.

Here are relevant log entries:

2018-11-23T06:49:11,158 | INFO  | Karaf Shutdown Socket Thread | ShutdownSocketThread             |  -  -  | Karaf shutdown socket: received shutdown command. Stopping framework...

2018-11-23T06:49:11,422 | INFO  | Framework stop   | BlueprintExtender                | 18 - org.apache.aries.blueprint.core - 1.8.3 | Destroying BlueprintContainer for bundle mdsal-netconf-ssh/1.5.1
2018-11-23T06:54:11,424 | INFO  | Framework stop   | ReferenceRecipe                  | 18 - org.apache.aries.blueprint.core - 1.8.3 | Timeout expired when waiting for mandatory OSGi service reference (&(type=global-event-executor)(objectClass=io.netty.util.concurrent.EventExecutor))

Above is first part of delay (5 minutes), followed by another 1 minutes:

2018-11-23T06:54:11,425 | WARN  | Framework stop   | DefaultCloseFuture               | 54 - org.apache.sshd.core - 1.6.0 | notifyListener(DefaultCloseFuture[id=SshServer[178c9d64]][value=true]) failed (ServiceUnavailableException) to invoke org.apache.sshd.common.util.closeable.SequentialCloseable$1@2ca9e995: Timeout expired when waiting for mandatory OSGi service reference: (&(type=global-event-executor)(objectClass=io.netty.util.concurrent.EventExecutor))
2018-11-23T06:55:11,426 | ERROR | Framework stop   | BeanRecipe                       | 18 - org.apache.aries.blueprint.core - 1.8.3 | The blueprint bean netconfMdsalServer in bundle mdsal-netconf-ssh/1.5.1 incorrectly threw an exception from its destroy method.
java.net.SocketTimeoutException: Failed to receive closure confirmation within 60000 millis

I'm attaching full threaddump, but this seems to be most relevant to me:

 

"Framework stop" #263 daemon prio=5 os_prio=0 tid=0x00007f643c0c7000 nid=0x5620 in Object.wait() [0x00007f64311fd000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.apache.aries.blueprint.container.ReferenceRecipe.getService(ReferenceRecipe.java:211)
    - locked <0x00000000ecf538d0> (a java.lang.Object)
    at org.apache.aries.blueprint.container.ReferenceRecipe.access$000(ReferenceRecipe.java:56)
    at org.apache.aries.blueprint.container.ReferenceRecipe$ServiceDispatcher.call(ReferenceRecipe.java:306)
    at Proxyb6cc05cb_233a_49c6_985b_8f8122bb8cce.execute(Unknown Source)
    at sun.nio.ch.AsynchronousChannelGroupImpl.executeOnPooledThread(AsynchronousChannelGroupImpl.java:188)
    at sun.nio.ch.Invoker.invokeIndirectly(Invoker.java:212)
    at sun.nio.ch.UnixAsynchronousServerSocketChannelImpl.implClose(UnixAsynchronousServerSocketChannelImpl.java:118)
    at sun.nio.ch.AsynchronousServerSocketChannelImpl.close(AsynchronousServerSocketChannelImpl.java:111)
    at org.apache.sshd.common.io.nio2.Nio2Acceptor.unbind(Nio2Acceptor.java:113)
    at org.apache.sshd.common.io.nio2.Nio2Acceptor.unbind(Nio2Acceptor.java:99)
    at org.apache.sshd.common.io.nio2.Nio2Acceptor.close(Nio2Acceptor.java:141)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
    at org.apache.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:159)
    at org.apache.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:167)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
    at org.apache.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69)
    at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
    at org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:46)
    at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:83)
    at org.apache.sshd.server.SshServer.stop(SshServer.java:339)
    at org.opendaylight.netconf.ssh.SshProxyServer.close(SshProxyServer.java:106)
    at org.opendaylight.netconf.ssh.NetconfNorthboundSshServer.close(NetconfNorthboundSshServer.java:82)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:299)
    at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:980)
    at org.apache.aries.blueprint.container.BeanRecipe.destroy(BeanRecipe.java:887)
    at org.apache.aries.blueprint.container.BlueprintRepository.destroy(BlueprintRepository.java:329)
    at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroyComponents(BlueprintContainerImpl.java:745)
    at org.apache.aries.blueprint.container.BlueprintContainerImpl.tidyupComponents(BlueprintContainerImpl.java:956)
    at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:890)
    at org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:325)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:346)
    at org.apache.aries.blueprint.container.BlueprintExtender.access$400(BlueprintExtender.java:68)
    at org.apache.aries.blueprint.container.BlueprintExtender$BlueprintContainerServiceImpl.destroyContainer(BlueprintExtender.java:633)
    at org.opendaylight.controller.blueprint.BlueprintBundleTracker.shutdownAllContainers(BlueprintBundleTracker.java:286)
    at org.opendaylight.controller.blueprint.BlueprintBundleTracker.bundleChanged(BlueprintBundleTracker.java:191)
    at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908)
    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:213)
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120)
    at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112)
    at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168)
    at org.eclipse.osgi.container.Module.publishEvent(Module.java:476)
    at org.eclipse.osgi.container.Module.doStop(Module.java:634)
    at org.eclipse.osgi.container.Module.stop(Module.java:498)
    at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:202)
    at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:165)
    at java.lang.Thread.run(Thread.java:748)

 

 

 

 



 Comments   
Comment by Jakub Morvay [ 26/Nov/18 ]

This looks like duplicate of NETCONF-577

Generated at Wed Feb 07 20:15:23 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.