Operating System: All
Platform: All

I'm also seeing some this in the same log, at the end, when things have gone haywire:

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.impl.device.TransactionChainManager.submitWriteTransaction(TransactionChainManager.java:175)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.device.TransactionChainManager.initialSubmitWriteTransaction(TransactionChainManager.java:89)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.device.DeviceContextImpl.initialSubmitTransaction(DeviceContextImpl.java:224)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.statistics.StatisticsContextImpl$4.onSuccess(StatisticsContextImpl.java:362)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.statistics.StatisticsContextImpl$4.onSuccess(StatisticsContextImpl.java:354)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
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.Carbon]
at org.opendaylight.openflowplugin.impl.device.listener.MultiMsgCollectorImpl.endCollecting(MultiMsgCollectorImpl.java:70)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.device.listener.MultiMsgCollectorImpl.addMultipartMsg(MultiMsgCollectorImpl.java:58)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.services.AbstractMultipartRequestCallback.onSuccess(AbstractMultipartRequestCallback.java:54)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowplugin.impl.services.AbstractMultipartRequestCallback.onSuccess(AbstractMultipartRequestCallback.java:22)[307:org.opendaylight.openflowplugin.impl:0.4.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.OutboundQueueEntry.complete(OutboundQueueEntry.java:121)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.StackedSegment.completeEntry(StackedSegment.java:113)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.StackedSegment.pairRequest(StackedSegment.java:153)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractStackedOutboundQueue.pairRequest(AbstractStackedOutboundQueue.java:203)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractOutboundQueueManager.onMessage(AbstractOutboundQueueManager.java:208)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consumeDeviceMessage(ConnectionAdapterImpl.java:143)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.AbstractConnectionAdapterStatistics.consume(AbstractConnectionAdapterStatistics.java:66)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.connection.ConnectionAdapterImpl.consume(ConnectionAdapterImpl.java:44)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
at org.opendaylight.openflowjava.protocol.impl.core.DelegatingInboundHandler.channelRead(DelegatingInboundHandler.java:43)[296:org.opendaylight.openflowjava.openflow-protocol-impl:0.9.2.Carbon]
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.Carbon]
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.Carbon]
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]

To better assess the impact of this bug and fix, could someone from your team please help us identify the following:
Regression: Is this bug a regression of functionality/performance/feature compared to Carbon?
Severity: Could you elaborate on the severity of this bug? Is this a BLOCKER such that we cannot release Carbon SR2 without it?
Workaround: Is there a workaround such that we can write a release note instead?
Testing: Could you also elaborate on the testing of this patch? How extensively has this patch been tested? Is it covered by any unit tests or system tests?
Impact: Does this fix impact any dependent projects?

> Regression: Is this bug a regression of functionality/performance/feature compared to Carbon?

Dunno.

> Severity: Could you elaborate on the severity of this bug? Is this a BLOCKER such that we cannot release Carbon SR2 without it?

If the current working assumption that this is the root cause of CONTROLLER-1756 is correct, then yes this is a Blocker, as without this fixed, ODL is not usable at scale.

Currently waiting on feedback to https://lists.opendaylight.org/pipermail/mdsal-dev/2017-August/001317.html to determine if this indeed is the root cause of CONTROLLER-1756.

> Workaround: Is there a workaround such that we can write a release note instead?

Nope, not that I know of.

> Testing: Could you also elaborate on the testing of this patch? How extensively has this patch been tested? Is it covered by any unit tests or system tests?

AFAIK, only reproducible during real scale testing using e.g. OpenStack's rally benchmarking tool.

Will be re-tested internally after a fix is available and merged to stable branch.

> Impact: Does this fix impact any dependent projects?

There is no fix yet, and I'm not sure that this means.

Stable/carbon: https://git.opendaylight.org/gerrit/#/c/62358/

We have prepared the patch https://git.opendaylight.org/gerrit/#/c/62358/ that should fix the IllegalStateException.
If it is possible, please test if it helps.

But it is possible, that it is not the root cause of the issue. We have discussed it in community meeting. Maybe there can be some synchronization issue. We will try to find out, if there is the problem.

Thank you,
Miro

> the patch https://git.opendaylight.org/gerrit/#/c/62358/ that should
> fix the IllegalStateException. If it is possible, please test if it helps.

It would be slightly easier for us, just internal process wise, to test if this fixes both the ERROR log message seen above as well as the original CONTROLLER-1756 if c/62358 were merged into stable/carbon branch - would this be possible? It seems harmless enough, so I doubt that change could cause new issues - at best it fixes this problem, at worst it closes a Tx which should any be canceled also, but may not be the root cause of this problem...

PS, FYI: Over in CONTROLLER-1760 (and on ongoing https://git.opendaylight.org/gerrit/#/q/topic:bug/9060) I'm working on something which in the future will let us see EXACTLY where such transaction were not closed - that will be handy.

Michael, as patch by Miroslav was merged on Carbon some time ago, did you had any chance to test it?

> did you had any chance to test it?

+ Sai & Sridhar - I believe you're planning to redo a QA round with a new RPM including this in the coming days?

(In reply to Michael Vorburger from comment #8)
> > did you had any chance to test it?
>
> + Sai & Sridhar - I believe you're planning to redo a QA round with a new
> RPM including this in the coming days?

Yes @Michael, its on the plan. We shall update the BZ once we have some results. Thanks for looking into the issue.

Jozef, Tomas - perhaps new OPNFLWPLUG-940 is of interest in the context of this one?

https://git.opendaylight.org/gerrit/#/c/62674/ is supposed to fix this - TBC.

Raising Importance from Critical to Blocker to align with CONTROLLER-1756.

Dupe'd OPNFLWPLUG-935 and OPNFLWPLUG-940 to this one, to avoid general confusion.

https://git.opendaylight.org/gerrit/#/c/62674/ does not seem to fix this.

What is the next step on this problem? More investigation for a proper fix? Thanks!

> What is the next step on this problem? More investigation for a proper fix? Thanks!

Jozef Bacigál on https://lists.opendaylight.org/pipermail/openflowplugin-dev/2017-September/007628.html dixit "I do investigations further for the Illegal state bug.". Judging solely based on the discussion ongoing on https://git.opendaylight.org/gerrit/#/c/62674/ that appears to be ongoing (thanks a lot Jozef).

Michael can you please retest it with the latest's changes and if it is still an issue send me the logs ?

Thanks

Jozef

> Michael can you please retest it with the latest's changes

It's unfortunately a little more complicated, not actually just me doing a quick test but internal procedure together with colleagues.. I've just sent direct private email asking for a re-test, and Cc'd you on it.

Ok, with the custom rpm [#] that @Daniel provided us that includes patchset#6 of [*], we deployed a clustered ODL setup with 3 Controllers and 3 Computes.
In this setup, we triggered browbeat/rally with concurrencies of 8, 16, 32 and times set to 500.

After the tests completed, following are the observations.

The current bug (i.e., 9038) talks about three exceptions. The first one out of it (i.e., "ExecutionList | 65 - com.google.guava - 18.0.0 | RuntimeException while executing runnable"), is NO LONGER SEEN in the logs.

However, the other two exceptions are still seen
https://gist.github.com/sridhargaddam/e0aa8c968a31d1bc0b1118c278f53b12
https://gist.github.com/sridhargaddam/85e407c33f8cfc9fbe44b2fceb10f463

[#] opendaylight-6.2.0-0.1.20170913snap58.el7.noarch
[*] https://git.opendaylight.org/gerrit/#/c/62674/

Michael & Team, What are the next steps here? Thanks!

(In reply to Kit Lou from comment #20)
> Michael & Team, What are the next steps here? Thanks!

The patch [*] fixes the main exception that is mentioned in this Bug, so we can go ahead and merge the patch and close this bug as fixed.

For the other two exceptions [#] mentioned in this bug report, if required I can open two separate bugs - but sadly we no longer have the necessary setup to reproduce the issue to share any further logs (if requested).

[*] https://git.opendaylight.org/gerrit/#/c/62674/
[#] https://gist.github.com/sridhargaddam/e0aa8c968a31d1bc0b1118c278f53b12
https://gist.github.com/sridhargaddam/85e407c33f8cfc9fbe44b2fceb10f463

The patch https://git.opendaylight.org/gerrit/#/c/62674/ is for the stable/carbon branch. Has the patch been cherry picked into the stable/nitrogen branch? Please provide the patch number for nitrogen (if needed). Thanks!

Nitrogen patch: https://git.opendaylight.org/gerrit/#/c/63236

Re-opening as we obviously need this on master as well...

... or is there the equivalent already? It's not visible easily in Gerrit at least.

I did try to just cherry-pick via Gerrit UI 1 click but it's non trivial - probably best if someone familiar with the code could do this?

(In reply to Sridhar Gaddam from comment #21)
> (In reply to Kit Lou from comment #20)
> > Michael & Team, What are the next steps here? Thanks!
>
> The patch [*] fixes the main exception that is mentioned in this Bug, so we
> can go ahead and merge the patch and close this bug as fixed.
>
> For the other two exceptions [#] mentioned in this bug report, if required I
> can open two separate bugs - but sadly we no longer have the necessary setup
> to reproduce the issue to share any further logs (if requested).
>
>
> [*] https://git.opendaylight.org/gerrit/#/c/62674/
> [#] https://gist.github.com/sridhargaddam/e0aa8c968a31d1bc0b1118c278f53b12
> https://gist.github.com/sridhargaddam/85e407c33f8cfc9fbe44b2fceb10f463

Just for record, opened the following bugs for the two exceptions.
https://bugs.opendaylight.org/show_bug.cgi?id=9184
https://bugs.opendaylight.org/show_bug.cgi?id=9185

I created cherry-pick for master here: https://git.opendaylight.org/gerrit/#/c/63402/

Cherry-pick on master was merged, closing this issue.