[OPNFLWPLUG-945] TimeoutException: Timeout waiting for task. Created: 19/Sep/17  Updated: 16/Apr/18  Resolved: 16/Apr/18

Status: Resolved
Project: OpenFlowPlugin
Component/s: General
Affects Version/s: Nitrogen, Oxygen, Carbon
Fix Version/s: Carbon-SR3

Type: Bug
Reporter: Sridhar Gaddam Assignee: Gobinath Suganthan
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

Issue Links:
Duplicate
is duplicated by OPNFLWPLUG-957 TransactionChainManager... Exception ... Resolved
External issue ID: 9184

 Description   

In a clustered ODL setup with 3 Controllers and 3 Computes, when we triggered browbeat/rally tests with concurrencies of 8, 16, 32 and times set to 500, we observed the following exception in karaf.

Note: some related discussion can be found in bug#9038

2017-09-14 03:54:13,184 | ERROR | ntLoopGroup-7-76 | TransactionChainManager | 304 - org.opendaylight.openflowplugin.common - 0.4.2.SNAPSHOT | Exception during INITIAL transaction submitting.
java.util.concurrent.TimeoutException: Timeout waiting for task.
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:269)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:69)[65:com.google.guava:18.0.0]
at org.opendaylight.openflowplugin.common.txchain.TransactionChainManager.submitTransaction(TransactionChainManager.java:180)[304:org.opendaylight.openflowplugin.common:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.common.txchain.TransactionChainManager.initialSubmitWriteTransaction(TransactionChainManager.java:85)[304:org.opendaylight.openflowplugin.common:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.DeviceContextImpl.initialSubmitTransaction(DeviceContextImpl.java:225)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.statistics.StatisticsContextImpl$4.onSuccess(StatisticsContextImpl.java:362)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.statistics.StatisticsContextImpl$4.onSuccess(StatisticsContextImpl.java:354)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at com.google.common.util.concurrent.Futures$6.run(Futures.java:1319)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:185)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.Futures$ChainingListenableFuture$1.run(Futures.java:918)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:185)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.Futures$ChainingListenableFuture$1.run(Futures.java:918)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:185)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.Futures$ChainingListenableFuture$1.run(Futures.java:918)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.Futures$ImmediateFuture.addListener(Futures.java:106)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.Futures$ChainingListenableFuture.run(Futures.java:914)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:185)[65:com.google.guava:18.0.0]
at com.google.common.util.concurrent.SettableFuture.set(SettableFuture.java:53)[65:com.google.guava:18.0.0]
at org.opendaylight.openflowplugin.impl.rpc.AbstractRequestContext.setResult(AbstractRequestContext.java:32)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.listener.MultiMsgCollectorImpl.endCollecting(MultiMsgCollectorImpl.java:70)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.device.listener.MultiMsgCollectorImpl.addMultipartMsg(MultiMsgCollectorImpl.java:58)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.services.AbstractMultipartRequestCallback.onSuccess(AbstractMultipartRequestCallback.java:54)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowplugin.impl.services.AbstractMultipartRequestCallback.onSuccess(AbstractMultipartRequestCallback.java:22)[307:org.opendaylight.openflowplugin.impl:0.4.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.OutboundQueueEntry.complete(OutboundQueueEntry.java:121)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.StackedSegment.completeEntry(StackedSegment.java:113)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.StackedSegment.pairRequest(StackedSegment.java:153)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractStackedOutboundQueue.pairRequest(AbstractStackedOutboundQueue.java:203)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractOutboundQueueManager.onMessage(AbstractOutboundQueueManager.java:208)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consumeDeviceMessage(ConnectionAdapterImpl.java:143)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractConnectionAdapterStatistics.consume(AbstractConnectionAdapterStatistics.java:66)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consume(ConnectionAdapterImpl.java:44)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.DelegatingInboundHandler.channelRead(DelegatingInboundHandler.java:43)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)[146:io.netty.transport:4.1.8.Final]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractOutboundQueueManager.channelRead(AbstractOutboundQueueManager.java:195)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)[148:io.netty.codec:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)[148:io.netty.codec:4.1.8.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)[148:io.netty.codec:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)[148:io.netty.codec:4.1.8.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)[148:io.netty.codec:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:287)[150:io.netty.handler:4.1.8.Final]
at org.opendaylight.openflowjava.protocol.impl.core.IdleHandler.channelRead(IdleHandler.java:39)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)[146:io.netty.transport:4.1.8.Final]
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:1018)[151:io.netty.transport-native-epoll:4.1.8.Final]
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:394)[151:io.netty.transport-native-epoll:4.1.8.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:288)[151:io.netty.transport-native-epoll:4.1.8.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)[145:io.netty.common:4.1.8.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)[145:io.netty.common:4.1.8.Final]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_141]
2017-09-14 03:54:13,185 | WARN | ntLoopGroup-7-76 | ContextChainHolderImpl | 307 - org.opendaylight.openflowplugin.impl - 0.4.2.SNAPSHOT | Not able to set MASTER role on device openflow:848556169412, reason: Initial transaction cannot be submitted.
2

 Comments   
Comment by Gobinath Suganthan [ 04/Jan/18 ]

Hi SridharG,

Does this issue occur only in cluster?

Could you give some pointers on how to reproduce this issue?

Comment by Sridhar Gaddam [ 04/Jan/18 ]

Hello Gobinath,

Basically we were using a Clustered setup and observed this issue. We did not use a non-clustered setup, so I'm not sure if it would be seen with a non-clustered setup.

Our scenario is a cluster of 3 nodes with odl-netvirt-openstack being stress tested by OpenStack's browbeat/rally benchmarking tool with the following configuration.

rally:
enabled: true
sleep_before: 5
sleep_after: 5
venv: /home/stack/rally-venv/bin/activate
plugins:

  • netcreate-boot: rally/rally-plugins/netcreate-boot
    rally/rally-plugins/neutron-securitygroup-port
    benchmarks:
  • name: neutron
    enabled: true
    Concurrency:
  • 8
  • 16
  • 32
    times: 500
    scenarios:
  • name: create-list-network
    enabled: true
    file: rally/neutron/neutron-create-list-network-cc.yml
  • name: create-list-port
    enabled: true
    file: rally/neutron/neutron-create-list-port-cc.yml
  • name: create-list-router
    enabled: true
    file: rally/neutron/neutron-create-list-router-cc.yml
  • name: create-list-security-group
    enabled: true
    file: rally/neutron/neutron-create-list-security-group-cc.yml
  • name: create-list-subnet
    enabled: true
    file: rally/neutron/neutron-create-list-subnet-cc.yml
Comment by Gobinath Suganthan [ 16/Mar/18 ]

Patch which could address this issue has been raised. 

https://git.opendaylight.org/gerrit/#/c/68296/

We have to repeat this test with this patch

Comment by Anil Vishnoi [ 02/Apr/18 ]

SridharG Can you please test your scenario with the above mentioned gerrit?

Comment by Sridhar Gaddam [ 06/Apr/18 ]

Thanks gobinath and Avishnoi for the patch. Avishnoi, unfortunately its not an easy thing for me to test this scenario immediately as we observed this issue during our performance and scale testing. However, I'll add this to our list of things to be verified when we get allocation to the scale lab and will update the thread on the findings.

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