email thread discussing this problem

another example

Since this is NETVIRT Issue, will be fixed as https://jira.opendaylight.org/browse/NETVIRT-1541

Saw a different variation of the issue with bug in genius

While testing NETVIRT-1541 fixes, ran into another variation of this bug in d/s testing, this time in Genius.

tunea6b6a44e1b is not created. This is what sequence of log entries looks like:

2019-01-11T07:46:30,224 | INFO | nioEventLoopGroup-9-9 | opendaylight.openflowplugin.impl.device.initialization.OF13DeviceInitializer | Static node openflow:9444498845632 info: OFPMPPORTDESC collected
2019-01-11T07:46:30,226 | DEBUG | ForkJoinPool-1-worker-5 | org.opendaylight.genius.interfacemanager.listeners.InterfaceTopologyStateListener | Bridge entry not found in config DS for dpn: 154706290356175
2019-01-11T07:46:30,226 | INFO | ForkJoinPool-1-worker-5 | genius.interfacemanager.renderer.ovs.confighelpers.OvsInterfaceConfigAddHelper | adding tunnel configuration for interface tunea6b6a44e1b
2019-01-11T07:46:30,227 | DEBUG | ForkJoinPool-1-worker-5 | genius.interfacemanager.renderer.ovs.confighelpers.OvsInterfaceConfigAddHelper | creating bridge interfaceEntry in ConfigDS 154706290356175

No further references to this tunnel after this.

This is what they look like for a tunnel that gets created:

2019-01-11T07:46:30,208 | INFO | ForkJoinPool-1-worker-2 | genius.interfacemanager.renderer.ovs.confighelpers.OvsInterfaceConfigAddHelper | adding tunnel configuration for interface tun4fab841ac4e
2019-01-11T07:46:30,208 | DEBUG | ForkJoinPool-1-worker-2 | genius.interfacemanager.renderer.ovs.confighelpers.OvsInterfaceConfigAddHelper | creating bridge interfaceEntry in ConfigDS 9444498845632
2019-01-11T07:46:30,209 | DEBUG | ForkJoinPool-1-worker-2 | genius.interfacemanager.renderer.ovs.confighelpers.OvsInterfaceConfigAddHelper | creating bridge interface on dpn 9444498845632
2019-01-11T07:46:30,209 | DEBUG | ForkJoinPool-1-worker-2 | genius.interfacemanager.renderer.ovs.utilities.SouthboundUtils | adding tunnel port tun4fab841ac4e to bridge InstanceIdentifier

The highlighted log entry in second is missing from first.

Looking at the code, following check is failing

LOG.debug("creating bridge interfaceEntry in ConfigDS {}", dpId);
interfaceMetaUtils.createBridgeInterfaceEntryInConfigDS(dpId, interfaceNew.getName());

// create bridge on switch, if switch is connected
BridgeRefEntry bridgeRefEntry = interfaceMetaUtils.getBridgeRefEntryFromOperDS(dpId);
if (bridgeRefEntry != null && bridgeRefEntry.getBridgeReference() != null) {
LOG.debug("creating bridge interface on dpn {}", dpId);

This means bridgeRefEntry is missing, even though it was created couple log entries before the one above:

2019-01-11T07:46:30,216 | DEBUG | ForkJoinPool-1-worker-5 | org.opendaylight.genius.interfacemanager.commons.InterfaceMetaUtils | Creating bridge ref entry for dpn: 154706290356175 bridge:

For reference, this is log entry for bridgeRefEntry for the working case:

2019-01-11T07:46:29,351 | DEBUG | ForkJoinPool-1-worker-4 | org.opendaylight.genius.interfacemanager.commons.InterfaceMetaUtils | Creating bridge ref entry for dpn: 9444498845632 bridge:

In working there is a gap of about 1s between two. In failure case it is less than 10ms.

k.faseela Issue is tunnel missing from OVSDB config. From log entries I shared you can see ITM never pushes the tunnel to OVSDB config and have pointed out what I think is the race condition. Any suggestions on fix?

thapar : Got the issue, let me think about an easy way to fix this.

great what's the TL;DR on the root cause?

jluhrsen Race condition. Genius stores BridgeRefEntry that maps a bridge to its corresponding DPNID. It gets populated when bridge is created or switch first connects, whichever is latter. Tunnels creation trigger is also same but different part of code. Due to extra steps in tunnel creation, we mostly have this entry in place before we get to point where we try creating tunnel port. But in this case by the time we read it is not present yet. It might have something to do with changes done as part of tx runner that we're hitting this race more frequently.

thapar : Here is an overall idea of the fix I want to try out.

                         FYI, not tested yet.

                          https://git.opendaylight.org/gerrit/79553

thapar/jluhrsen : Is it possible to run the patch against netvirt CSIT couple of times to see if the issue is not reproducible now? Have done local testing to make sure the patch is not breaking anything, but couldn't really hit the race condition timings to see if that problem is solved.

this gerrit keyword should trigger the 3node job: "test-genius-cluster-netvirt"
I triggered it once just now.

For ITM also we have added a similar fix.

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

The fix for this issue has been merged here, https://git.opendaylight.org/gerrit/#/c/81980/ for ITM.