[#OPNFLWPLUG-605] He: Failed to issue flow stats; get-flow-statistics-from-flow-table

[OPNFLWPLUG-605] He: Failed to issue flow stats; get-flow-statistics-from-flow-table Created: 25/Jan/16 Updated: 27/Sep/21 Resolved: 12/Dec/17
Status:	Verified
Project:	OpenFlowPlugin
Component/s:	General
Affects Version/s:	None
Fix Version/s:	None

Type:

Bug

Reporter:

Hideyuki Tai

Assignee:

Unassigned

Resolution:

Won't Do

Votes:

Labels:

None

Remaining Estimate:

Not Specified

Time Spent:

Not Specified

Original Estimate:

Not Specified

Environment:

Operating System: All
Platform: All

Attachments:

karaf.log

karaf.log.1

External issue ID:

5090

Description

What I used
-----------

Source code: stable/beryllium of 01/25/2016
OpenFlow version: OF10
Target OFP: OpenFlow plugin Helium version
Application: VTN Manager ("odl-vtn-manager-rest" feature)
Failed RPC: get-flow-statistics-from-flow-table

What I happened
---------------

Just after the OpenFlow plugin got connected with an OpenFlow 1.0 switch, VTN Manager called the RPC "get-flow-statistics-from-flow-table" to get all flow entries in a flow table of the switch.
However, the RPC failed, because the RPC was not registered yet.

2016-01-25 15:24:00,423 | ERROR | er Task Thread-0 | StatsReaderService | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | get-flow-stats: Caught an exception: canceled=false, input=GetFlowStatisticsFromFlowTableInput [_cookie=FlowCookie [_value=9175521290813964288], _cookieMask=FlowCookie [_value=18446462598732840960], _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:2]]]]}

], _tableId=0, 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:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299)[54:com.google.guava:18.0.0]

2016-01-25 15:24:00,424 | ERROR | er Task Thread-0 | StatsReaderService | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Failed to issue flow stats RPC: get-flow-stats
org.opendaylight.vtn.manager.VTNException: No local or remote implementation available for rpc AbsoluteSchemaPath

{path=[(urn:opendaylight:flow:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

at org.opendaylight.vtn.manager.internal.util.concurrent.AbstractVTNFuture.getException(AbstractVTNFuture.java:75)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]
at org.opendaylight.vtn.manager.internal.util.rpc.RpcInvocation.getResult(RpcInvocation.java:89)[178:org.opendaylight.vtn.manager.implementation:0.4.0.SNAPSHOT]]

The issue happened in the CSIT for VTN project.
https://jenkins.opendaylight.org/releng/view/vtn/job/vtn-csit-1node-manager-only-beryllium/75/artifact/karaf.log

The issue does not happen always.
It occurred in the build 75 of the vtn-csit-1node-manager-only-beryllium, but it didn't occurr in hte build 73, 74, and 76.
https://jenkins.opendaylight.org/releng/view/vtn/job/vtn-csit-1node-manager-only-beryllium/

Comments

Comment by Hideyuki Tai [ 25/Jan/16 ]

After VTN Manager failed to issue flow stats RPC, following operations like installing flow entries on the switch worked well.

Therefore, we are thinking that the OpenFlow plugin sent a notification of the node addition on which VTN Manager called the RPC, before the OpenFlow plugin completed to register the RPC.

Comment by Anil Vishnoi [ 26/Jan/16 ]

Hi Hideyuki,

Can you try with this patch and see if it fixes your issue.

https://git.opendaylight.org/gerrit/#/c/33529/3

Thanks
Anil

Comment by Hideyuki Tai [ 27/Jan/16 ]

(In reply to Anil Vishnoi from comment #2)
> Hi Hideyuki,
>
> Can you try with this patch and see if it fixes your issue.
>
> https://git.opendaylight.org/gerrit/#/c/33529/3
>
> Thanks
> Anil

Hi Anil,

Thank you for checking the issue, and creating the patch.
However, even with your patch, the issues still happens.

When I repeatedly started up and shutdown the Mininet, I can observed the issue.
It occurs rarely though.

2016-01-26 11:54:20,002 | INFO | entLoopGroup-9-2 | ConnectionAdapterImpl | 159 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | Hello received / branch
2016-01-26 11:54:20,005 | INFO | entLoopGroup-9-2 | OfEntityManager | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | requestOpenflowEntityOwnership: Registered controller for the ownership of Uri [_value=openflow:1]
2016-01-26 11:54:20,006 | INFO | ofEntity-0 | RolePushTask | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | OpenFlow 1.0 devices don't support multi controller features, skipping role push.
2016-01-26 11:54:20,006 | INFO | ult-dispatcher-2 | OfEntityManager | 162 - 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:1}

]}
2016-01-26 11:54:20,009 | INFO | lt-dispatcher-21 | VTNInventoryManager | 175 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Node has been created: id=openflow:1, proto=OF10
2016-01-26 11:54:20,009 | INFO | lt-dispatcher-21 | VTNInventoryManager | 175 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Port has been created:

{id=openflow:1:1, name=s1-eth1, enabled=true, cost=1000, links=none}

{id=openflow:1:2, name=s1-eth2, enabled=true, cost=1000, links=none}

2016-01-26 11:54:20,011 | INFO | ult-dispatcher-2 | OfEntityManager | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | registerRoutedRPCForSwitch: Registered routed rpc for ModelDrivenSwitch openflow:1
2016-01-26 11:54:20,011 | INFO | ofEntity-0 | RolePushTask | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | OpenFlow 1.0 devices don't support multi controller features, skipping role push.
2016-01-26 11:54:20,013 | INFO | ofEntity-0 | OfEntityManager | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: Controller is successfully set as a MASTER controller for 1
2016-01-26 11:54:20,013 | INFO | ofEntity-0 | OfEntityManager | 162 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | sendNodeAddedNotification: Node Added notification is sent for ModelDrivenSwitch openflow:1
2016-01-26 11:54:20,010 | ERROR | er Task Thread-0 | StatsReaderService | 175 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | get-flow-stats: Caught an exception: canceled=false, input=GetFlowStatisticsFromFlowTableInput [_cookie=FlowCookie [_value=9175521290813964288], _cookieMask=FlowCookie [_value=18446462598732840960], _node=NodeRef [_value=KeyedInstanceIdentifier

{path=[(urn:opendaylight:flow:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

(snip)

2016-01-26 11:54:20,013 | ERROR | er Task Thread-0 | StatsReaderService | 175 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Failed to issue flow stats RPC: get-flow-stats
org.opendaylight.vtn.manager.VTNException: No local or remote implementation available for rpc AbsoluteSchemaPath

{path=[(urn:opendaylight:flow:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

Please note that VTN Manager calls the RPC for a node, after the VTN Manager gets the notification of the addition the node.

Comment by Hideyuki Tai [ 27/Jan/16 ]

Attachment karaf.log has been added with description: Karaf log file on a failure case

Comment by Hideyuki Tai [ 29/Jan/16 ]

The following patch was merged for the bug.
https://git.opendaylight.org/gerrit/#/c/33534/

I will test the latest artifacts of the stable/beryllium branch to see if the patch fixes the bug or not.

Comment by Hideyuki Tai [ 29/Jan/16 ]

Even after the following patch is applied, the same issue still happens.
https://git.opendaylight.org/gerrit/#/c/33534/

I observed that the issue occurred in the CSIT job for Beryllium on Jan 29.
https://jenkins.opendaylight.org/releng/view/vtn/job/vtn-csit-1node-manager-only-beryllium/97/artifact/karaf.log

Also, when I tested the Beryllium RC1, I faced the same issue.

Comment by Anil Vishnoi [ 29/Jan/16 ]

Hi Hideyuki,

Looks like you are sending your rpc request before openflowplugin publishes the nodeAdded event. Looking at the log, it looks like VTN create the bridge and once it's done with creating the bridge it sends the stats request to get the stats, but it does not really check the in inventory data store to make sure that the node (in this case openflow:2) is added by openflowplugin or not. Before the clustering implementation, openflowplugin was not setting any role for the switch, but with clustering implementation, it first set the role and it role setting is successful, it notifies application about the node addition. So i think if you put check in your code to see if the node is in inventory or not, that will solve the issue.

Comment by Hideyuki Tai [ 01/Feb/16 ]

(In reply to Anil Vishnoi from comment #7)
> Hi Hideyuki,
>
> Looks like you are sending your rpc request before openflowplugin publishes
> the nodeAdded event. Looking at the log, it looks like VTN create the bridge
> and once it's done with creating the bridge it sends the stats request to
> get the stats, but it does not really check the in inventory data store to
> make sure that the node (in this case openflow:2) is added by openflowplugin
> or not. Before the clustering implementation, openflowplugin was not setting
> any role for the switch, but with clustering implementation, it first set
> the role and it role setting is successful, it notifies application about
> the node addition. So i think if you put check in your code to see if the
> node is in inventory or not, that will solve the issue.

Hi Anil,

Could you tell me when the OFP-He write a new node data (OpenFlow switch) into the MD-SAL data store?
Is it before the OFP-He registers its RPC for the node?

[Longer version of this question]

I think I slightly misunderstood the behavior of the VTN features and OpenFlow Plugin Helium design.

Could you check if the current my understanding of the OFP-He is correct?
I think the OFP-He works as follows when it detects a new session with an OpenFlow switch.

Step 1. OFP-He detects a new session with an OpenFlow switch.
Step 2. OFP-He writes the new node information into the MD-SAL data store.
Step 3. OFP-He decides the roll of the controller for the switch.
Step 4. OFP-He registers its RPC for the switch.
Step 5. OFP-He sends notifications for the event of the addition of the switch. (In the sendNodeAddedNotification method of the OfEntityManager class.)

Is the above my understanding correct?
Does the OFP-He write the new node information into the MD-SAL data store (Step 2) before the step 4?

The VTN feature registers its DataChangeListener for the opendaylight-inventory.
So the VTN would receive the notification of the data change of the opendaylight-inventory.
And, when the VTN receive the notification of the node addition in the opendaylight-inventory (which, I think, caused by the step 2), it calls the "get-flow-stat..." RPC for the switch.
If my understanding is correct, it would make sense that the VTN feature would call the RPC before the step 4 occasionally.

Comment by Hideyuki Tai [ 02/Feb/16 ]

I had a conversation about the bug with Anil.

The information what I got from his is as follows:

[This is what happens]

1) openflowplugin get connection request
2) it decides controllers role for the device
3) it register for the rpc
4) it sends role change request to the device
5) If role change is successful, it sends the sendNodeAddedNotification to the application
6) Application receives the nodeAdded notifications (inventory manager) writes node details to the data store
7) and then application gets the data change notification about the new node added

Comment by Hideyuki Tai [ 02/Feb/16 ]

Attachment karaf.log.1 has been added with description: Logs on the issue in which DEBUG logs for the inventory-manager was enabled

Comment by Hideyuki Tai [ 02/Feb/16 ]

Here is one additional observation from my side.

I enabled DEBUG logs of "org.opendaylight.openflowplugin.applications.inventory.manager", and reproduced the problem.

I've found out that the inventory-manager received the "Node connector updated" notification right after the OFP-He registered controller for the ownership for the switch.
That was before the OFP-He registered its RPC for the switch.

Following that "Node connector updated" notification in the inventory-manager, the VTN feature recived the notification of data changes on the opendaylight-inventory, and the VTN feature called the "get-stats-..." RPC for the switch.

Though the inventory-manager received the "Node updated" notification after the OFP-He registered its RPC for the switch.

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.node.NodeConnector, 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:2]]], org.opendaylight.yang.gen.v1.urn.opendaylight.inventory.rev130819.node.NodeConnector[key=NodeConnectorKey [_id=Uri [_value=openflow:2:3]]]]}

.
2016-02-02 08:23:44,175 | INFO | lt-dispatcher-26 | OfEntityManager | 165 - 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:2}

]}
2016-02-02 08:23:44,175 | DEBUG | nventoryProvider | FlowCapableInventoryProvider | 169 - org.opendaylight.openflowplugin.applications.inventory-manager - 0.2.0.SNAPSHOT | Processed 4 operations, submitting transaction DOM-CHAIN-2-1544
2016-02-02 08:23:44,178 | INFO | ult-dispatcher-3 | VTNInventoryManager | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Node has been created: id=openflow:2, proto=OF10
2016-02-02 08:23:44,178 | TRACE | ult-dispatcher-3 | VTNInventoryManager | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Delivering node event: id=openflow:2, type=CREATED
2016-02-02 08:23:44,178 | INFO | ult-dispatcher-3 | VTNInventoryManager | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Port has been created:

{id=openflow:2:3, name=s2-eth2, enabled=true, cost=1000, links=none}

(snip)

2016-02-02 08:23:44,179 | ERROR | er Task Thread-0 | StatsReaderService | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | get-flow-stats: Caught an exception: canceled=false, input=GetFlowStatisticsFromFlowTableInput [_cookie=FlowCookie [_value=9175521290813964288], _cookieMask=FlowCookie [_value=18446462598732840960], _node=NodeRef [_value=KeyedInstanceIdentifier

{path=[(urn:opendaylight:flow:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

(snip)

2016-02-02 08:23:44,180 | ERROR | er Task Thread-0 | StatsReaderService | 178 - org.opendaylight.vtn.manager.implementation - 0.4.0.SNAPSHOT | Failed to issue flow stats RPC: get-flow-stats
org.opendaylight.vtn.manager.VTNException: No local or remote implementation available for rpc AbsoluteSchemaPath

{path=[(urn:opendaylight:flow:statistics?revision=2013-08-19)get-flow-statistics-from-flow-table]}

(snip)

2016-02-02 08:23:44,181 | INFO | lt-dispatcher-26 | OfEntityManager | 165 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | registerRoutedRPCForSwitch: Registered routed rpc for ModelDrivenSwitch openflow:2
2016-02-02 08:23:44,181 | INFO | ofEntity-1 | RolePushTask | 165 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | OpenFlow 1.0 devices don't support multi controller features, skipping role push.
2016-02-02 08:23:44,181 | INFO | ofEntity-1 | OfEntityManager | 165 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | onDeviceOwnershipChanged: Controller is successfully set as a MASTER controller for 2
2016-02-02 08:23:44,181 | INFO | ofEntity-1 | OfEntityManager | 165 - org.opendaylight.openflowplugin - 0.2.0.SNAPSHOT | sendNodeAddedNotification: Node Added notification is sent for ModelDrivenSwitch openflow:2
2016-02-02 08:23:44,182 | INFO | pool-28-thread-1 | StatNodeRegistrationImpl | 170 - org.opendaylight.openflowplugin.applications.statistics-manager - 0.2.0.SNAPSHOT | Received onNodeUpdated for node FlowCapableNodeUpdated [_ipAddress=IpAddress [_ipv4Address=Ipv4Address [_value=192.168.2.60], _value=[1, 9, 2, ., 1, 6, 8, ., 2, ., 6, 0]], _switchFeatures=SwitchFeatures [_capabilities=[class org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowFeatureCapabilityArpMatchIp, class org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowFeatureCapabilityFlowStats, class org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowFeatureCapabilityPortStats, class org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowFeatureCapabilityQueueStats, class org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowFeatureCapabilityTableStats], _maxBuffers=256, _maxTables=254, augmentation=[]]]
2016-02-02 08:23:44,182 | INFO | pool-28-thread-1 | StatNodeRegistrationImpl | 170 - org.opendaylight.openflowplugin.applications.statistics-manager - 0.2.0.SNAPSHOT | onNodeUpdated: Send group/meter feature request to the device KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowCapableNode, 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:2]]], org.opendaylight.yang.gen.v1.urn.opendaylight.flow.inventory.rev130819.FlowCapableNode]}

{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:2]]], 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]]]}

2016-02-02 08:23:44,183 | DEBUG | nventoryProvider | FlowCapableInventoryProvider | 169 - org.opendaylight.openflowplugin.applications.inventory-manager - 0.2.0.SNAPSHOT | Processed 2 operations, submitting transaction DOM-CHAIN-2-1546
2016-02-02 08:23:44,183 | INFO | pool-28-thread-1 | StatNodeRegistrationImpl | 170 - org.opendaylight.openflowplugin.applications.statistics-manager - 0.2.0.SNAPSHOT | Received onNodeUpdated for node FlowCapableNodeUpdated [_description=None, _hardware=Open vSwitch, _manufacturer=Nicira, Inc., _serialNumber=None, _software=2.1.0]
2016-02-02 08:23:44,183 | DEBUG | pool-28-thread-1 | NodeChangeCommiter | 169 - org.opendaylight.openflowplugin.applications.inventory-manager - 0.2.0.SNAPSHOT | Node updated notification received,KeyedInstanceIdentifier

Comment by Hideyuki Tai [ 03/Feb/16 ]

One observation.

It seems to me that the postHandshakeBasic method of ConnectionConductorImpl class is related to this bug.

In the openflowplugin/src/main/java/org/opendaylight/openflowplugin/openflow/md/core/ConnectionConductorImpl.java:

476 protected void postHandshakeBasic(GetFeaturesOutput featureOutput,
477 Short negotiatedVersion) {
478 version = negotiatedVersion;
479 if (version == OFConstants.OFP_VERSION_1_0)

{ 480 // Because the GetFeaturesOutput contains information about the port 481 // in OF1.0 (that we would otherwise get from the PortDesc) we have 482 // to pass 483 // it up for parsing to convert into a NodeConnectorUpdate 484 // 485 // BUG-1988 - this must be the first item in queue in order not to 486 // get behind link-up message 487 enqueueMessage(featureOutput); 488 }

Comment by Anil Vishnoi [ 12/Dec/17 ]

No activity on this bug from last 2 years, also Helium plugin design is deprecated now. Please reopen the bug if you see the issue with carbon/nitrogen/oxygen branches.

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

[OPNFLWPLUG-605] He: Failed to issue flow stats; get-flow-statistics-from-flow-table Created: 25/Jan/16 Updated: 27/Sep/21 Resolved: 12/Dec/17