[OVSDB-412] OVSDB HWVTEP unable to find logical switch in operational datastore Created: 02/May/17  Updated: 30/Oct/17  Resolved: 06/May/17

Status: Resolved
Project: ovsdb
Component/s: Southbound.hw_vtep
Affects Version/s: unspecified
Fix Version/s: None

Type: Bug
Reporter: Giles Heron Assignee: Vishal Thapar
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: Zip Archive karaf.zip    
External issue ID: 8353

 Description   

I'm able to configure a logical switch on a HWVTEP, but ODL seems unable to correlate the configured and operational topology entries for the HWVTEP. So the logical switch is "created" rather than "updated", and the operational topology is unchanged.

so then when I create the termination point for the port/VLAN mapping to the logical switch ODL sends "named-uuid","LogicalSwitch_ls0" instead of "uuid","c0d53932-dd4b-46b3-8d7f-b3bbceacdf05" as expected by the switch.

I'm seeing this both with Boron-SR3 and with Carbon snapshot (with Carbon I also get an NPE).

 Comments   
Comment by Giles Heron [ 02/May/17 ]

Attachment karaf.zip has been added with description: zipped logs

Comment by Giles Heron [ 02/May/17 ]

example config/operational topologies (from another run trying - unsuccessfully - to make this work with Beryllium)

config:

{
"topology": [
{
"topology-id": "hwvtep:1",
"node": [
{
"node-id": "hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98",
"hwvtep:logical-switches": [

{ "hwvtep-node-name": "ls0", "hwvtep-node-description": "", "tunnel-key": "10000" }

]
},
{
"node-id": "hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98/physicalswitch/SB-DEV-NODE2",
"termination-point": [
{
"tp-id": "eth1/12",
"hwvtep:hwvtep-node-name": "eth1/12",
"hwvtep:hwvtep-node-description": "",
"hwvtep:vlan-bindings": [

{ "vlan-id-key": 100, "logical-switch-ref": "/network-topology:network-topology/network-topology:topology[network-topology:topology-id='hwvtep:1']/network-topology:node[network-topology:node-id='hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98']/hwvtep:logical-switches[hwvtep:hwvtep-node-name='ls0']" }

]
}
]
}
]
}
]
}

operational:

{
"topology": [
{
"topology-id": "hwvtep:1",
"node": [
{
"node-id": "hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98",
"hwvtep:connection-info":

{ "local-ip": "10.195.94.43", "local-port": 6640, "remote-port": 52544, "remote-ip": "10.23.237.112" }

,
"hwvtep:managers": [

{ "target": "tcp:10.195.94.43:6640", "manager-uuid": "bc9a45d0-4dab-4a8a-ac6b-5791d4654c35", "is-connected": true }

],
"hwvtep:switches": [

{ "switch-ref": "/network-topology:network-topology/network-topology:topology[network-topology:topology-id='hwvtep:1']/network-topology:node[network-topology:node-id='hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98/physicalswitch/SB-DEV-NODE2']" }

]
},
{
"node-id": "hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98/physicalswitch/SB-DEV-NODE2",
"hwvtep:hwvtep-node-description": "",
"hwvtep:managed-by": "/network-topology:network-topology/network-topology:topology[network-topology:topology-id='hwvtep:1']/network-topology:node[network-topology:node-id='hwvtep://uuid/b4872522-2fc5-42c9-a9fd-441bb5dfef98']",
"hwvtep:hwvtep-node-name": "SB-DEV-NODE2",
"hwvtep:tunnel-ips": [

{ "tunnel-ips-key": "50.50.50.1" }

],
"hwvtep:physical-switch-uuid": "030f5109-0f32-431f-aed5-778cc108b7e9",
"hwvtep:management-ips": [

{ "management-ips-key": "10.23.237.112" }

],
"termination-point": [

{ "tp-id": "eth1/11", "hwvtep:hwvtep-node-name": "eth1/11", "hwvtep:hwvtep-node-description": "", "hwvtep:physical-port-uuid": "ae4fb25e-19cd-4597-a604-d5708f039d41" }

,

{ "tp-id": "eth1/10", "hwvtep:hwvtep-node-name": "eth1/10", "hwvtep:hwvtep-node-description": "", "hwvtep:physical-port-uuid": "91ca60d3-a6a0-4431-b8b1-ef4fec999820" }

,

{ "tp-id": "eth1/12", "hwvtep:hwvtep-node-name": "eth1/12", "hwvtep:hwvtep-node-description": "", "hwvtep:physical-port-uuid": "31d7390c-c3d2-4f20-8794-3813500e3564" }

]
}
]
}
]
}

Comment by Giles Heron [ 03/May/17 ]

is there any update on this?

or any more info you need from me?

Comment by suneel verma [ 04/May/17 ]

Can you enable TRACE for the following package aswell.
org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md

From the logs it could be seen that logical switch is created in the device.
2017-05-01 11:09:46,448 | TRACE | entLoopGroup-5-1 | HwvtepMonitorCallback | 191 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.3.3.Boron-SR3 | result: TableUpdates [map={Logical_Switch=TableUpdate [{c0d53932-dd4b-46b3-8d7f-b3bbceacdf05=RowUpdate [uuid=c0d53932-dd4b-46b3-8d7f-b3bbceacdf05, oldRow=null, newRow=Row [columns=

{name=[name=ls0], description=[description= ], tunnel_key=[tunnel_key=[10000]]}

]]}]}, error=null, details=null, getError()=null, getDetails()=null, getClass()=class org.opendaylight.ovsdb.lib.message.TableUpdates, hashCode()=877596989, toString()=org.opendaylight.ovsdb.lib.message.TableUpdates@344f113d] dbSchema: hardware_vtep

But it is not updated in operational datastore.

It could be because the previous transaction threw an exception other than
NullPointerException | NoSuchElementException | ClassCastException e
as caught by https://github.com/opendaylight/ovsdb/blob/stable/boron/hwvtepsouthbound/hwvtepsouthbound-impl/src/main/java/org/opendaylight/ovsdb/hwvtepsouthbound/transactions/md/HwvtepOperationalCommandAggregator.java

That exception would have killed the operational datastore update thread in TransactionInvokerImpl and preventing any further updates to operational datastore.

This patch https://git.opendaylight.org/gerrit/#/c/51517/ should address such issues.

Comment by Giles Heron [ 04/May/17 ]

that trace ought to have been there already as I was tracing org.opendaylight.ovsdb?

I've tried building carbon/stable with the patch you noted. Still fails This time I get an NPE just after getting the response to my command to create the logical switch:

2017-05-04 10:13:51,107 | DEBUG | on-dispatcher-74 | LogicalSwitchUpdateCommand | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Creating logical switch named: HwvtepNodeName [_value=ls0]
2017-05-04 10:13:51,108 | TRACE | on-dispatcher-74 | LogicalSwitchUpdateCommand | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | execute: creating LogicalSwitch entry: Logical_Switch : Row [columns=

{name=[name=ls0], description=[description=], tunnel_key=[tunnel_key=[10000]]}

]
2017-05-04 10:13:51,109 | DEBUG | on-dispatcher-74 | HwvtepDeviceInfo | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Marking device data as intransit KeyedInstanceIdentifier

{targetType=interface org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.ovsdb.hwvtep.rev150901.hwvtep.global.attributes.LogicalSwitches, path=[org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.NetworkTopology, org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.network.topology.Topology[key=TopologyKey [_topologyId=Uri [_value=hwvtep:1]]], org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.network.topology.topology.Node[key=NodeKey [_nodeId=Uri [_value=hwvtep://uuid/0b197212-3ce8-4ea2-a2f7-3fc455a02485]]], org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.ovsdb.hwvtep.rev150901.HwvtepGlobalAugmentation, org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.ovsdb.hwvtep.rev150901.hwvtep.global.attributes.LogicalSwitches[key=LogicalSwitchesKey [_hwvtepNodeName=HwvtepNodeName [_value=ls0]]]]}

2017-05-04 10:13:51,119 | TRACE | on-dispatcher-74 | JsonRpcEndpoint | 212 - org.opendaylight.ovsdb.library - 1.4.0.SNAPSHOT | getClient Request : {"id":"33d58219-fbef-4bee-b819-7ace9e8b151e","method":"transact","params":["hardware_vtep",{"op":"insert","row":

{"name":"ls0","description":"","tunnel_key":["set",[10000]]}

,"uuid-name":"LogicalSwitch_ls0","table":"Logical_Switch"},

{"op":"comment","comment":"Logical Switch: Creating ls0"}

]}
2017-05-04 10:13:51,119 | DEBUG | on-dispatcher-74 | TransactInvokerImpl | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | invoke: command: org.opendaylight.ovsdb.hwvtepsouthbound.transact.TransactCommandAggregator@7f792b56, tb: org.opendaylight.ovsdb.lib.operations.TransactionBuilder@6b795c9f
2017-05-04 10:13:51,198 | TRACE | entLoopGroup-5-3 | JsonRpcDecoder | 212 - org.opendaylight.ovsdb.library - 1.4.0.SNAPSHOT | readable bytes 200, records read 6, incomplete record bytes 0
2017-05-04 10:13:51,200 | TRACE | entLoopGroup-5-3 | JsonRpcEndpoint | 212 - org.opendaylight.ovsdb.library - 1.4.0.SNAPSHOT | Request : null "update" ["75384b61-4ea3-4b0c-a75b-38758ceb8c93",{"Logical_Switch":{"03611caf-c9af-4600-965f-4e7efaf3640d":{"new":{"description":" ","name":"ls0","tunnel_key":10000}}}}]
2017-05-04 10:13:51,251 | TRACE | entLoopGroup-5-3 | HwvtepMonitorCallback | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | result: TableUpdates [map={Logical_Switch=TableUpdate [{03611caf-c9af-4600-965f-4e7efaf3640d=RowUpdate [uuid=03611caf-c9af-4600-965f-4e7efaf3640d, oldRow=null, newRow=Row [columns=

{name=[name=ls0], description=[description= ], tunnel_key=[tunnel_key=[10000]]}

]]}]}, error=null, details=null, getError()=null, getDetails()=null, getClass()=class org.opendaylight.ovsdb.lib.message.TableUpdates, hashCode()=1025312520, toString()=org.opendaylight.ovsdb.lib.message.TableUpdates@3d1d0708] dbSchema: hardware_vtep
2017-05-04 10:13:51,251 | TRACE | entLoopGroup-5-3 | HwvtepMonitorCallback | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | update exit
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.GlobalUpdateCommand@63dd3577
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepPhysicalSwitchUpdateCommand@27e1e3d3
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepPhysicalSwitchRemoveCommand@30e8b701
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepManagerUpdateCommand@37182927
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepManagerRemoveCommand@3de4d43e
2017-05-04 10:13:51,251 | TRACE | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Executing command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepLogicalSwitchUpdateCommand@15b3472a
2017-05-04 10:13:51,251 | TRACE | entLoopGroup-5-3 | JsonRpcDecoder | 212 - org.opendaylight.ovsdb.library - 1.4.0.SNAPSHOT | readable bytes 132, records read 7, incomplete record bytes 0
2017-05-04 10:13:51,252 | TRACE | entLoopGroup-5-3 | JsonRpcEndpoint | 212 - org.opendaylight.ovsdb.library - 1.4.0.SNAPSHOT | Response : {"error":null,"id":"33d58219-fbef-4bee-b819-7ace9e8b151e","result":[

{"uuid":["uuid","03611caf-c9af-4600-965f-4e7efaf3640d"]}

,{}]}
2017-05-04 10:13:51,252 | ERROR | n-invoker-impl-0 | vtepOperationalCommandAggregator | 220 - org.opendaylight.ovsdb.hwvtepsouthbound-impl - 1.4.0.SNAPSHOT | Execution of command org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepLogicalSwitchUpdateCommand@15b3472a failed with the following exception. Continuing the execution of remaining commands
java.lang.NullPointerException
at org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepLogicalSwitchUpdateCommand.buildConnectionNode(HwvtepLogicalSwitchUpdateCommand.java:76)[220:org.opendaylight.ovsdb.hwvtepsouthbound-impl:1.4.0.SNAPSHOT]
at org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepLogicalSwitchUpdateCommand.updateLogicalSwitch(HwvtepLogicalSwitchUpdateCommand.java:58)[220:org.opendaylight.ovsdb.hwvtepsouthbound-impl:1.4.0.SNAPSHOT]
at org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepLogicalSwitchUpdateCommand.execute(HwvtepLogicalSwitchUpdateCommand.java:50)[220:org.opendaylight.ovsdb.hwvtepsouthbound-impl:1.4.0.SNAPSHOT]
at org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.HwvtepOperationalCommandAggregator.execute(HwvtepOperationalCommandAggregator.java:57)[220:org.opendaylight.ovsdb.hwvtepsouthbound-impl:1.4.0.SNAPSHOT]
at org.opendaylight.ovsdb.hwvtepsouthbound.transactions.md.TransactionInvokerImpl.run(TransactionInvokerImpl.java:107)[220:org.opendaylight.ovsdb.hwvtepsouthbound-impl:1.4.0.SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_91]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]

Comment by Giles Heron [ 04/May/17 ]

I've also just tested using the latest carbon/stable (but without the patch).

I get the same NPE (only at line 98 rather than line 107 of TransactionInvokerImpl.java).

it's the same line of code (just before/after the patch was applied).

any thoughts?

Comment by suneel verma [ 05/May/17 ]

The npe is coming from this line
lsBuilder.setLogicalSwitchUuid(new Uuid(lSwitch.getUuid().toString()));

which means either lswitch is null or its uuid is null.

controller is not able to parse the logical switch update properly and create the lswitch object.

What is the version of openvswitch you are using ?

Comment by Giles Heron [ 05/May/17 ]

I think 1.3 with a plan to use 1.4 - but can check with the developer later on (she's in SJ so won't be in for a while). Both the UUID and logical switch should be there.

will see if can make progress on my own for now...

Comment by Giles Heron [ 05/May/17 ]

so we've made progress - we fixed a bug in our code where we were sending a notification with a missing UUID. So yeah - maybe in future it might be worth programming a little more defensively in ODL and checking whether a value is null before calling "toString()" on it

so now we've got the logical switch in our operational topology

as a result we've been able to update the ethernet port mapping also and now we see the local-mcast-macs entry for 00:00:00:00:00:00 and also the termination point for the VXLAN tunnel.

our next step is to try and add the remote-mcast-macs entry and the remote termination point for the far end of the tunnel. At that point we should be able to pass traffic (I hope!)

Comment by Giles Heron [ 06/May/17 ]

all seems to work now - even without the patch.

will close the bug

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