[NETCONF-900] mdsal-netconf-ssh fails to shutdown Created: 22/Aug/22  Updated: 31/Oct/22  Resolved: 31/Oct/22

Status: Resolved
Project: netconf
Component/s: netconf
Affects Version/s: None
Fix Version/s: 3.0.7, 4.0.3

Type: Bug Priority: Medium
Reporter: Robert Varga Assignee: Ivan Hrasko
Resolution: Done Votes: 0
Labels: pt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

During shutdown we can observe the following bit:

2022-08-22T13:01:11,816 | INFO  | Framework stop - Equinox Container: b2b91105-3e38-49c8-add9-45cf9fe2a942 | BlueprintExtender                | 27 - org.apache.aries.blueprint.core - 1.10.3 | Destroying container for blueprint bundle org.opendaylight.netconf.mdsal-netconf-tcp/4.0.2.SNAPSHOT
2022-08-22T13:01:11,817 | INFO  | Framework stop - Equinox Container: b2b91105-3e38-49c8-add9-45cf9fe2a942 | BlueprintExtender                | 27 - org.apache.aries.blueprint.core - 1.10.3 | Destroying container for blueprint bundle org.opendaylight.netconf.mdsal-netconf-ssh/4.0.2.SNAPSHOT
2022-08-22T13:01:11,823 | WARN  | Framework stop - Equinox Container: b2b91105-3e38-49c8-add9-45cf9fe2a942 | DefaultCloseFuture               | 283 - org.opendaylight.netconf.shaded-sshd - 4.0.2.SNAPSHOT | notifyListener(DefaultCloseFuture[id=][value=true]) failed (UnsupportedOperationException) to invoke org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@66c732b7: null
2022-08-22T13:02:11,824 | ERROR | Framework stop - Equinox Container: b2b91105-3e38-49c8-add9-45cf9fe2a942 | BeanRecipe                       | 27 - org.apache.aries.blueprint.core - 1.10.3 | The blueprint bean netconfMdsalServer in bundle org.opendaylight.netconf.mdsal-netconf-ssh/4.0.2.SNAPSHOT incorrectly threw an exception from its destroy method.
java.net.SocketTimeoutException: Failed to receive closure confirmation within PT1M millis
        at org.opendaylight.netconf.shaded.sshd.server.SshServer.stop(SshServer.java:370) ~[?:?]
        at org.opendaylight.netconf.ssh.SshProxyServer.close(SshProxyServer.java:118) ~[?:?]
        at org.opendaylight.netconf.ssh.NetconfNorthboundSshServer.close(NetconfNorthboundSshServer.java:82) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:337) ~[?:?]
        at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:835) ~[?:?]
        at org.apache.aries.blueprint.container.BeanRecipe.destroy(BeanRecipe.java:742) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintRepository.destroy(BlueprintRepository.java:434) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroyComponents(BlueprintContainerImpl.java:778) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.tidyupComponents(BlueprintContainerImpl.java:987) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:923) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:360) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:381) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintExtender.stop(BlueprintExtender.java:199) ~[?:?]
        at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:248) ~[?:?]
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500) ~[?:?]
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433) ~[?:?]
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725) ~[?:?]
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463) ~[?:?]
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.lambda$1(EquinoxEventPublisher.java:252) ~[?:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHookPrivileged(ServiceRegistry.java:1349) ~[?:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHooksPrivileged(ServiceRegistry.java:1322) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.notifyEventHooksPrivileged(EquinoxEventPublisher.java:252) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:210) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) ~[?:?]
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) ~[?:?]
        at org.eclipse.osgi.container.Module.doStop(Module.java:658) ~[?:?]
        at org.eclipse.osgi.container.Module.stop(Module.java:521) ~[?:?]
        at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:207) ~[?:?]
        at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:226) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]

I very much suspect the UnsupportedOpeationException is hiding the reason for the delay in shutdown and eventual reported error.

 Comments   
Comment by Oleksandr Zharov [ 19/Sep/22 ]

rovarga can you give a bit more info? I can't reproduce it.

Comment by Robert Varga [ 19/Sep/22 ]

Not quite sure, I think the steps were just 'install odl-netconf-mdsal'  and then stop the container. I am not sure it happened on every invocation, though.

Comment by Oleksandr Zharov [ 06/Oct/22 ]

Here is stack trace of UnsupportedOpeationException:

java.lang.UnsupportedOperationException
        at io.netty.util.concurrent.GlobalEventExecutor.shutdown(GlobalEventExecutor.java:159) 
        at org.opendaylight.controller.config.yang.netty.eventexecutor.OSGiGlobalEventExecutor.shutdown(OSGiGlobalEventExecutor.java:60) 
        at Proxy1ab31ac1_5484_44e9_a462_c6c8126dfa91.shutdown(Unknown Source) 
        at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$3.run(AsynchronousChannelGroupImpl.java:255) 
        at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$3.run(AsynchronousChannelGroupImpl.java:253) 
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:399) 
        at java.base/java.security.AccessController.doPrivileged(AccessController.java:460) 
        at java.base/sun.nio.ch.AsynchronousChannelGroupImpl.shutdownExecutors(AsynchronousChannelGroupImpl.java:252) 
        at java.base/sun.nio.ch.AsynchronousChannelGroupImpl.shutdownNow(AsynchronousChannelGroupImpl.java:294) 
        at org.opendaylight.netconf.ssh.SshProxyServer$NioServiceWithPoolFactory.doCloseImmediately(SshProxyServer.java:171) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) 
        at org.opendaylight.netconf.shaded.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:159) 
        at org.opendaylight.netconf.shaded.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:166) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) 
        at org.opendaylight.netconf.shaded.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:159) 
        at org.opendaylight.netconf.shaded.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:166) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:48) 
        at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95) 
        at org.opendaylight.netconf.shaded.sshd.server.SshServer.stop(SshServer.java:368) 
        at org.opendaylight.netconf.ssh.SshProxyServer.close(SshProxyServer.java:118) 
        at org.opendaylight.netconf.ssh.NetconfNorthboundSshServer.close(NetconfNorthboundSshServer.java:82) 
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) 
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
        at java.base/java.lang.reflect.Method.invoke(Method.java:568) 
        at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:337) 
        at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:835) 
        at org.apache.aries.blueprint.container.BeanRecipe.destroy(BeanRecipe.java:742) 
        at org.apache.aries.blueprint.container.BlueprintRepository.destroy(BlueprintRepository.java:434) 
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroyComponents(BlueprintContainerImpl.java:778) 
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.tidyupComponents(BlueprintContainerImpl.java:987) 
        at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:923) 
        at org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:360) 
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) 
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) 
        at org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:381) 
        at org.apache.aries.blueprint.container.BlueprintExtender.stop(BlueprintExtender.java:199) 
        at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:248) 
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500) 
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433) 
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725) 
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463) 
        at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422) 
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.lambda$1(EquinoxEventPublisher.java:252) 
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHookPrivileged(ServiceRegistry.java:1349) 
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHooksPrivileged(ServiceRegistry.java:1322) 
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.notifyEventHooksPrivileged(EquinoxEventPublisher.java:252) 
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:210) 
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:138) 
        at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:130) 
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:217) 
        at org.eclipse.osgi.container.Module.publishEvent(Module.java:499) 
        at org.eclipse.osgi.container.Module.doStop(Module.java:658) 
        at org.eclipse.osgi.container.Module.stop(Module.java:521) 
        at org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:207) 
        at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:226) 
        at java.base/java.lang.Thread.run(Thread.java:833) 
Comment by Oleksandr Zharov [ 06/Oct/22 ]

So problem is simple in description: During shutdown procedure GlobalEventExecutor calls method shutdown that looks like this:    

@Override
@Deprecated
public void shutdown() { 
    throw new UnsupportedOperationException();
}

 

Comment by Oleksandr Zharov [ 06/Oct/22 ]

rovarga any ideas? It looks like something greater than I can solve by myself.

Comment by Robert Varga [ 06/Oct/22 ]

So SshServer is assuming it owns the event executor and shuts it down. That is unfortunate, but should be quite easy to fix: wrap the GlobalEventExecutor with a forwarding implementation of EventExecutor which ignores calls to shutdown().

Comment by Ivan Hrasko [ 10/Oct/22 ]

We can go one level deeper and made fix in ExecutorService which is passed into AsynchronousChannelGroup thread pool.

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