[OPNFLWPLUG-617] RPC Exceptions observed with openflowplugin He design (tested with VTN) Created: 09/Feb/16  Updated: 27/Sep/21  Resolved: 24/Feb/16

Status: Resolved
Project: OpenFlowPlugin
Component/s: General
Affects Version/s: None
Fix Version/s: None

Type: Bug
Reporter: Venkatrangan Govindarajan Assignee: Anil Vishnoi
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

Attachments: File vtn_karaf_log.tgz    
External issue ID: 5276

 Description   

Tested the VTN Openstack support. the instances were not reachable. When analyzing the log, Found exceptions when VTN Manager tries to invoke rpc's of openflowplgin.

:54:14,874 | ERROR | TN Flow Thread-0 | ClearNodeFlowsTask | 163 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | remove-flow: Caught an exception: canceled=false, input=RemoveFlowInput [_flowTable=FlowTableRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.tables.Table, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:121713027126083]]], org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowCapableNode, org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.tables.Table[key=TableKey [_id=0]]]}

], _node=NodeRef [_value=KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:121713027126083]]]]}

], _tableId=0, _transactionUri=Uri [_value=clean-up:openflow:121713027126083], _barrier=true, _strict=false, augmentation=[]]
java.util.concurrent.ExecutionException: org.opendaylight.controller.md.sal.dom.api.DOMRpcImplementationNotAvailableException: No local or remote implementation available for rpc AbsoluteSchemaPath

{path=[(urn:opendaylight:flow:service?revision=2013-08-19)remove-flow]}

at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299)[39:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:272)[39:com.google.guava:18.0.0]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:96)[39:com.google.guava:18.0.0]
at org.opendaylight.vtn.manager.internal.util.rpc.RpcInvocation.getResult(RpcInvocation.java:82)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.ClearNodeFlowsTask.uninstall(ClearNodeFlowsTask.java:178)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.ClearNodeFlowsTask.run(ClearNodeFlowsTask.java:233)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.concurrent.VTNThreadPool$WorkerThread.run(VTNThreadPool.java:400)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
Caused by: org.opendaylight.controller.md.sal.dom.api.DOMRpcImplementationNotAvailableException: No local or remote implementation available for rpc AbsoluteSchemaPath

{path=[(urn:opendaylight:flow:service?revision=2013-08-19)remove-flow]}

at org.opendaylight.controller.remote.rpc.RemoteRpcImplementation$1.onComplete(RemoteRpcImplementation.java:65)[138:org.opendaylight.controller.sal-remoterpc-connector:1.3.0.SNAPSHOT]
at org.opendaylight.controller.remote.rpc.RemoteRpcImplementation$1.onComplete(RemoteRpcImplementation.java:56)[138:org.opendaylight.controller.sal-remoterpc-connector:1.3.0.SNAPSHOT]
at akka.dispatch.OnComplete.internal(Future.scala:248)[124:com.typesafe.akka.actor:2.3.14]
at akka.dispatch.OnComplete.internal(Future.scala:245)[124:com.typesafe.akka.actor:2.3.14]

at akka.dispatch.japi$CallbackBridge.apply(Future.scala:172)[124:com.typesafe.akka.actor:2.3.14]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]
at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:121)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[121:org.scala-lang.scala-library:2.11.7.v20150622-112736-1fbce4612c]

 Comments   
Comment by Venkatrangan Govindarajan [ 09/Feb/16 ]

As discussed enabled the vtn log in karaf. the following sequence created the issue

ODL + VTN Manager, Stacked one openstack node, Createed Network and instances and there was no issue, Stacked an additional compute node, Created instances , error occured

in - 0.2.0.SNAPSHOT | unregisterEntityOwnershipRequest: Unregister controller entity ownership request for Uri [_value=openflow:68962386306631]
2016-02-08 12:32:35,595 | ERROR | pool-28-thread-1 | StatisticsManagerImpl | 155 - org.opendaylight.openflowplugin.applications.statistics-manager - 0.2.0.SNAPSHOT | Received node removed for KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node, path=[org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.Nodes, org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.nodes.Node[key=NodeKey [_id=Uri [_value=openflow:68962386306631]]]]}

, but unable to find it in nodeCollectorMap
2016-02-08 12:32:35,593 | ERROR | TN Flow Thread-0 | ClearNodeFlowsTask | 163 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | remove-flow: RPC returned error: errors=[RpcError [message=check switch connection, severity=ERROR, errorType=RPC, tag=OPENFLOW, applicationTag=OPENFLOW_LIBRARY, info=flow-mod sending failed, cause=java.util.concurrent.RejectedExecutionException: Channel disconnected]]
java.util.concurrent.RejectedExecutionException: Channel disconnected
at org.opendaylight.openflowjava.protocol.impl.core.connection.ChannelOutboundQueue.channelInactive(ChannelOutboundQueue.java:260)[147:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:218)[99:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:204)[99:io.netty.transport:4.0.33.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)[99:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:625)[99:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:329)[98:io.netty.common:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:350)[99:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[98:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[98:io.netty.common:4.0.33.Final]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
2016-02-08 12:32:35,595 | ERROR | ofEntity-1 | RolePushTask | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | Role push request failed for device [62, -72, -114, -119, -26, 71]
@
org.opendaylight.openflowplugin.openflow.md.core.session.RolePushException: Giving up role change: read generation-id failed Timeout waiting for task.
at org.opendaylight.openflowplugin.openflow.md.core.session.RolePushTask.call(RolePushTask.java:117)[150:org.opendaylight.openflowplugin:0.2.0.SNAPSHOT]
at org.opendaylight.openflowplugin.openflow.md.core.session.RolePushTask.call(RolePushTask.java:38)[150:org.opendaylight.openflowplugin:0.2.0.SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
2016-02-08 12:32:35,595 | ERROR | ofEntity-1 | RolePushTask | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | Generation ID is NULL for device [62, -72, -114, -119, -26, 71]
2016-02-08 12:32:35,595 | ERROR | TN Flow Thread-0 | ClearNodeFlowsTask | 163 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Failed to remove VTN flows in openflow:68962386306631
org.opendaylight.vtn.manager.VTNException: RPC returned error
at org.opendaylight.vtn.manager.internal.util.rpc.RpcUtils.checkResult(RpcUtils.java:189)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.rpc.RpcInvocation.getResult(RpcInvocation.java:92)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.ClearNodeFlowsTask.uninstall(ClearNodeFlowsTask.java:178)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.flow.remove.ClearNodeFlowsTask.run(ClearNodeFlowsTask.java:233)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.concurrent.VTNThreadPool$WorkerThread.run(VTNThreadPool.java:400)[163:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
2016-02-08 12:32:35,596 | WARN | ofEntity-1 | OfEntityManager | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: Controller is not able to set the MASTER role for 68962386306631.
org.opendaylight.openflowplugin.openflow.md.core.session.RolePushException: Giving up role change: current generation-id can not be read
at org.opendaylight.openflowplugin.openflow.md.core.session.RolePushTask.call(RolePushTask.java:129)[150:org.opendaylight.openflowplugin:0.2.0.SNAPSHOT]
at org.opendaylight.openflowplugin.openflow.md.core.session.RolePushTask.call(RolePushTask.java:38)[150:org.opendaylight.openflowplugin:0.2.0.SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
2016-02-08 12:32:35,596 | INFO | ofEntity-1 | OfEntityManager | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: ..and this instance is owner of the device 68962386306631. Closing the registration, so other entity can become owner and attempt to be master controller.
2016-02-08 12:32:35,596 | INFO | ofEntity-1 | OfEntityManager | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: ..and registering it back to participate in ownership and re-try
2016-02-08 12:32:35,596 | INFO | ofEntity-1 | OfEntityManager | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: re-registered candidate for ownership of the 68962386306631
2016-02-08 12:32:35,597 | INFO | lt-dispatcher-19 | OfEntityManager | 150 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: Set controller as a MASTER controller because it's the OWNER of the Entity{type='openflow', id=/(urn:opendaylight:params:xml:ns:yang:controller:md:sal:core:general-entity?revision=2015-08-20)entity/entity[

{(urn:opendaylight:params:xml:ns:yang:controller:md:sal:core:general-entity?revision=2015-08-20)name=openflow:68962386306631}

]}
@

Comment by Venkatrangan Govindarajan [ 09/Feb/16 ]

Attachment vtn_karaf_log.tgz has been added with description: VTN Karaf Log with TRACE enabled

Comment by A H [ 10/Feb/16 ]

Raising the severity of this to blocker because of impact to Beryllium release with respect to VTN project.

Comment by Abhijit Kumbhare [ 10/Feb/16 ]

Can you please look at this Anil?

Comment by Anil Vishnoi [ 10/Feb/16 ]

Looking at it.

Comment by Anil Vishnoi [ 10/Feb/16 ]

Looking at the log, it looks like by the time VTN calls removeFlow() rpc to the bridge (br-int), bridge gets disconnected from the controller. So once bridge disconnected from the controller, openflowplugin will deregister the rpcs. So this is expected behavior from plugin.

Also looks like the second compute node connected to the controller already had br-int bridge and that connects to the controller as a openflow switch and disconnected immediately and never connects back. This is where we see this rpc behavior. I see another bridge pops up and connected to controller in <1 second. So to me it looks like compute node stacking issue.

Discussed this with venkat, he will be re-testing it with some sanity check on the compute node stacking and will update the bug with the current status.

Comment by Venkatrangan Govindarajan [ 10/Feb/16 ]

Tested the scenario again with OpenStack. The exceptions and errors were not observed. I have modified the importance as Normal. The integration has issues but seems to be problem due to https://bugs.opendaylight.org/show_bug.cgi?id=4678, which we are debugging now.

Comment by Venkatrangan Govindarajan [ 24/Feb/16 ]

The issue was initially thought to be a problem with openflowplugin as some exceptions were observed in karaf.log when tested. But, After further investigation, it was identified that VTN Bug#4678 was observed again. The issues have been addressed now.

Although there was an observation for openflowplugin that sometimes a switch that was not found in inventory features in the notifications. We are not able to reproduce the problem now. So closing this bug for now.

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