Loading...

XML

Word

Printable

Type: Bug
Resolution: Done
Priority: Highest
Fix Version/s: Aluminium, Sodium SR3, Magnesium SR2
Affects Version/s: Aluminium, Sodium SR3, Magnesium SR2
Component/s: None
Labels:
- CSIT

The following patch stack came in when this started happening:

Re-integrate ssh client
Upgrade mina-sshd to 2.4.0
Shade mina-sshd
Eliminate CallHomeSessionContext.nettyChannel

The failure seems to come from the final patch "Re-integrate ssh client" as I ran the
job in the sandbox with the distribution created with that and saw the failures, vs
the distribution created with the "Upgrade mina-sshd to 2.4.0" patch which passed.

Looks like some issue with the rest-perf-client tool, as the log for that tool
shows requests timing out, like this:

06:31:11.317 [pool-4-thread-1] WARN  o.o.n.t.t.c.h.p.SyncExecutionStrategy - Failed to execute request
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Read timeout to /10.30.170.99:8181 of 60000 ms
	at com.ning.http.client.providers.netty.future.NettyResponseFuture.abort(NettyResponseFuture.java:231)
	at com.ning.http.client.providers.netty.request.NettyRequestSender.abort(NettyRequestSender.java:422)
	at com.ning.http.client.providers.netty.request.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:47)
	at com.ning.http.client.providers.netty.request.timeout.ReadTimeoutTimerTask.run(ReadTimeoutTimerTask.java:57)
	at org.jboss.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:556)
	at org.jboss.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:632)
	at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:369)
	at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.util.concurrent.TimeoutException: Read timeout to /10.30.170.99:8181 of 60000 ms
	... 7 common frames omitted

Here is the karaf.log snippet right when the test tool is started:

2020-05-13T06:28:39,371 | INFO  | qtp1894809136-96 | StreamWriterFacade               | 324 - org.opendaylight.yangtools.yang-data-codec-xml - 3.0.10 | Namespace urn:ietf:params:xml:ns:netconf:base:1.0 was not bound, please fix the caller
java.lang.Throwable: null
	at org.opendaylight.yangtools.yang.data.codec.xml.StreamWriterFacade.getPrefix(StreamWriterFacade.java:130) [324:org.opendaylight.yangtools.yang-data-codec-xml:3.0.10]
	at org.opendaylight.yangtools.yang.data.codec.xml.XMLStreamNormalizedNodeStreamWriter.metadata(XMLStreamNormalizedNodeStreamWriter.java:258) [324:org.opendaylight.yangtools.yang-data-codec-xml:3.0.10]
	at org.opendaylight.yangtools.rfc7952.data.util.NormalizedNodeStreamWriterMetadataDecorator.enterChild(NormalizedNodeStreamWriterMetadataDecorator.java:171) [311:org.opendaylight.yangtools.rfc7952-data-util:3.0.10]
	at org.opendaylight.yangtools.rfc7952.data.util.NormalizedNodeStreamWriterMetadataDecorator.enterMetadataNode(NormalizedNodeStreamWriterMetadataDecorator.java:164) [311:org.opendaylight.yangtools.rfc7952-data-util:3.0.10]
	at org.opendaylight.yangtools.rfc7952.data.util.NormalizedNodeStreamWriterMetadataDecorator.startContainerNode(NormalizedNodeStreamWriterMetadataDecorator.java:79) [311:org.opendaylight.yangtools.rfc7952-data-util:3.0.10]
	at org.opendaylight.yangtools.yang.data.api.schema.stream.NormalizedNodeWriter.wasProcessedAsCompositeNode(NormalizedNodeWriter.java:198) [322:org.opendaylight.yangtools.yang-data-api:3.0.10]
	at org.opendaylight.yangtools.yang.data.api.schema.stream.NormalizedNodeWriter.write(NormalizedNodeWriter.java:101) [322:org.opendaylight.yangtools.yang-data-api:3.0.10]
	at org.opendaylight.yangtools.rfc7952.data.util.NormalizedMetadataWriter.write(NormalizedMetadataWriter.java:114) [311:org.opendaylight.yangtools.rfc7952-data-util:3.0.10]
	at org.opendaylight.netconf.util.NetconfUtil.writeNormalizedNode(NetconfUtil.java:116) [299:org.opendaylight.netconf.util:1.7.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.connect.netconf.util.NetconfMessageTransformUtil.createEditConfigAnyxml(NetconfMessageTransformUtil.java:368) [295:org.opendaylight.netconf.sal-netconf-connector:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.connect.netconf.util.NetconfRpcStructureTransformer.createEditConfigStructure(NetconfRpcStructureTransformer.java:61) [295:org.opendaylight.netconf.sal-netconf-connector:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.connect.netconf.util.NetconfBaseOps.createEditConfigStrcture(NetconfBaseOps.java:292) [295:org.opendaylight.netconf.sal-netconf-connector:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.connect.netconf.sal.tx.AbstractWriteTx.put(AbstractWriteTx.java:110) [295:org.opendaylight.netconf.sal-netconf-connector:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.connect.netconf.sal.tx.ReadWriteTx.put(ReadWriteTx.java:41) [295:org.opendaylight.netconf.sal-netconf-connector:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.simplePostPut(BrokerFacade.java:925) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.makeNormalPost(BrokerFacade.java:874) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.postData(BrokerFacade.java:693) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.postDataViaTransaction(BrokerFacade.java:675) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.BrokerFacade.commitConfigurationDataPost(BrokerFacade.java:472) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.RestconfImpl.createConfigurationData(RestconfImpl.java:985) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.RestconfImpl.createConfigurationData(RestconfImpl.java:933) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.restconf.impl.StatisticsRestconfServiceWrapper.createConfigurationData(StatisticsRestconfServiceWrapper.java:161) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	at org.opendaylight.netconf.sal.rest.impl.RestconfCompositeWrapper.createConfigurationData(RestconfCompositeWrapper.java:86) [293:org.opendaylight.netconf.restconf-nb-bierman02:1.10.3.SNAPSHOT]
	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.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [168:org.glassfish.jersey.core.jersey-common:2.25.1]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [169:org.glassfish.jersey.core.jersey-server:2.25.1]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [166:org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.1]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [166:org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.1]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [166:org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.1]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [166:org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.1]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [166:org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.1]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:311) [146:org.eclipse.jetty.servlets:9.4.18.v20190429]
	at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:265) [146:org.eclipse.jetty.servlets:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) [126:org.apache.shiro.core:1.3.2]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) [126:org.apache.shiro.core:1.3.2]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) [126:org.apache.shiro.core:1.3.2]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) [127:org.apache.shiro.web:1.3.2]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [127:org.apache.shiro.web:1.3.2]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:51) [146:org.eclipse.jetty.servlets:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:214) [155:org.eclipse.jetty.websocket.server:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.opendaylight.aaa.filterchain.filters.CustomFilterAdapter.doFilter(CustomFilterAdapter.java:78) [188:org.opendaylight.aaa.filterchain:0.10.3.SNAPSHOT]
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [344:org.ops4j.pax.web.pax-web-jetty:7.2.10]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [142:org.eclipse.jetty.security:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [344:org.ops4j.pax.web.pax-web-jetty:7.2.10]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) [145:org.eclipse.jetty.servlet:9.4.18.v20190429]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [344:org.ops4j.pax.web.pax-web-jetty:7.2.10]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.Server.handle(Server.java:505) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) [144:org.eclipse.jetty.server:9.4.18.v20190429]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [136:org.eclipse.jetty.io:9.4.18.v20190429]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [136:org.eclipse.jetty.io:9.4.18.v20190429]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [136:org.eclipse.jetty.io:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804) [147:org.eclipse.jetty.util:9.4.18.v20190429]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2020-05-13T06:28:39,657 | INFO  | pipe-log:log "ROBOT MESSAGE: Starting suite /w/workspace/netconf-csit-1node-scale-only-sodium/test/csit/suites/netconf/restperfclient/performance.robot" | core                             | 112 - org.apache.karaf.log.core - 4.2.6 | ROBOT MESSAGE: Starting test netconf-scale.txt.Performance.Run_Restperfclient
2020-05-13T06:38:39,949 | WARN  | sshd-SshServer[78e0a333]-nio2-thread-1 | ServerSessionImpl                | 128 - org.apache.sshd.core - 1.7.0 | exceptionCaught(ServerSessionImpl[karaf@/10.30.170.40:33210])[state=Opened] InterruptedByTimeoutException: null

I'm unsure if the test tool needs an update with the new sshd changes coming
in or there is something broken with the sshd changes.

relates to

NETCONF-674 Eliminate use of AsyncSshHandlerReader

Resolved

Assignee:: Robert Varga

Reporter:: Jamo Luhrsen

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Created:: 13/May/20 6:24 PM

Updated:: 20/May/20 6:24 PM

Resolved:: 15/May/20 10:39 AM

Details

Description

Attachments

Issue Links

Activity

People

Dates