Operating System: All
Platform: All

Attachment odl-dhcp-issue.zip has been added with description: tables

Hi Nikolas,

Could you please let us know how many VMs are being spawned. Is it failing for all the VMs initially and works fine when ifup eth0 is done after 2 minutes.

>>One more interesting thing is either the dhcp request goes through directly (less than 10 seconds) or it needs this long time. <<

Do you mean to say that DHCP request is actually being send within 10 secs and not within 120 secs as we expect?

Hey Kency,

thanks for looking into this.

So I spawn 2 VMs both have the same issue is a probability from around 70%. Any additional VM has the same issue.

If in the rare cases that the flows are pushed directly the DHCP request gets answered directly then I see that the VM is botted up in about 10 seconds.

So 2 in short cases:
1. [broken YANGTOOLS-14% of the times] No connectivity at all for the first ~2 minutest
2. [working CONTROLLER-24% of the times] Direct connectivity and through that the DHCP request is answered directly.

You see in the attachment that I added 2 times all the flow tables. That is both times from 1. The not working one is directly after the VM is spawned. The working on is after ~2 mins.

Thanks! Nikolas

I have a new finding!

in ovs logs I can see a lot of this messages:
2017-04-05T10:32:59.834Z|00621|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:32:59.834Z|00622|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:32:59.924Z|00623|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.002Z|00624|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.013Z|00625|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.013Z|00626|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.014Z|00627|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.014Z|00628|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.026Z|00629|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.026Z|00630|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.045Z|00631|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.045Z|00632|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:00.045Z|00633|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_GROUP_MOD message
2017-04-05T10:33:10.045Z|00634|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: 316 flow_mods in the 9 s starting 10 s ago (316 adds)
2017-04-05T10:33:10.187Z|00635|connmgr|INFO|Dropped 8 log messages in last 11 seconds (most recently, 7 seconds ago) due to excessive rate
2017-04-05T10:33:10.187Z|00636|connmgr|INFO|br-int<->tcp:192.0.2.7:6653: sending OFPBAC_BAD_OUT_GROUP error reply to OFPT_FLOW_MOD message

This is related to this bug:
https://bugs.opendaylight.org/show_bug.cgi?id=8132

After a vm is delete groups and flows are not cleanup.

On a fresh deployed system with a clean odl and a clean ovs everything seems to be working. When creating and removeing vms and networks after a while we get a group entry in ovs which is bad:
group_id=210001,type=all
in ODL:
"buckets": {
"bucket": [
{
"action": [
{
"openflowplugin-extension-nicira-action:nx-resubmit":

,
"order": 1
},
{
"order": 0,
"set-field": {
"tunnel":

}
}
],
"bucket-id": 0,
"watch_group": 4294967295,
"watch_port": 4294967295,
"weight": 0
}
]
},
"group-id": 210001,
"group-name": "3c94c809-663c-4ae0-9313-706d1aaf8310",
"group-type": "group-all"

So the group is not correctly synced!

So I think we have still 2 issues here:
1. no cleanup when VMs, networks and bgpvpns are delete
2. a group cannot be modified.

Just to state that one more time:
in ovs the group is really empty!

OFPST_GROUP_DESC reply (OF1.3) (xid=0x2):
group_id=210002,type=all,bucket=actions=group:210001,bucket=actions=load:0x200->NXM_NX_REG6[],resubmit(,220)
group_id=150004,type=all,bucket=actions=set_field:fa:16:3e:12:a0:e5->eth_src,set_field:fa:16:3e:0a:c4:e1->eth_dst,load:0x100->NXM_NX_REG6[],resubmit(,220)
group_id=5000,type=all,bucket=actions=CONTROLLER:65535,bucket=actions=resubmit(,17),bucket=actions=resubmit(,81)
group_id=200002,type=all,bucket=actions=output:48
group_id=210001,type=all
48(tun69773c7a1b0): addr:7a:48:85:85:fe:f9
49(tun441d8835c6b): addr:42:d9:3b:ca:c8:98
50(tape83f7b84-88): addr:fe:16:3e:0a:c4:e1
LOCAL(br-int): addr:e2:4a:ad:35:bc:47

check here the group_id=210001 it does not say anything behind. In odl it says:
"openflowplugin-extension-nicira-action:nx-resubmit": {
"table": 55
},
which means resubmit it to table 55 from where it is then matching on dhcp port and then send to the controller (Neutron dhcp).

In tables_not_working log, I don't see any flows/groups for neutron VMs present in both compute nodes and seeing flows/groups only for transparent port created on the DPN for the flat provider network. Looks like there is no VMs spawned. At this stage, group_id=210001 is empty because of no VMs.

What do you see in odl for group id 210001 ? Does it exist in inventory config ds or not ?

when you add new VM back into this network, Are you seeing only ELAN Local BC group (210001) not updated with bucket? what do you see in wireshark trace ? is it group_mod or group-add ? what about other flows for the VM ?

This is what I see in odl as already written in the comment above:
in ODL:
"buckets": {
"bucket": [
{
"action": [
{
"openflowplugin-extension-nicira-action:nx-resubmit":

,
"order": 1
},
{
"order": 0,
"set-field": {
"tunnel":

}
}
],
"bucket-id": 0,
"watch_group": 4294967295,
"watch_port": 4294967295,
"weight": 0
}
]
},
"group-id": 210001,
"group-name": "3c94c809-663c-4ae0-9313-706d1aaf8310",
"group-type": "group-all"

Have in mind that I reproduced the error few times and what you do see here is not the original issue when the bug was found.

So very short before the vm is stated I see the following in ovs:

3 computes:
OFPST_GROUP_DESC reply (OF1.3) (xid=0x2):
group_id=200000,type=all,bucket=actions=set_field:00:72:2b:16:87:6c->eth_dst,load:0x300->NXM_NX_REG6[],resubmit(,220)
group_id=5000,type=all,bucket=actions=CONTROLLER:65535,bucket=actions=resubmit(,17),bucket=actions=resubmit(,81)
group_id=210002,type=all,bucket=actions=group:210001,bucket=actions=load:0x300->NXM_NX_REG6[],resubmit(,220)
group_id=210001,type=all
group_id=150010,type=all,bucket=actions=set_field:fa:16:3e:33:a2:cc->eth_src,set_field:fa:16:3e:51:eb:2d->eth_dst,load:0x1000->NXM_NX_REG6[],resubmit(,220)
group_id=150003,type=all,bucket=actions=set_field:fe:16:3e:0c:92:f0->eth_src,set_field:fa:16:3e:0c:92:f0->eth_dst,load:0x500->NXM_NX_REG6[],resubmit(,220)

in odl:
{
"buckets": {
"bucket": [
{
"action": [
{
"openflowplugin-extension-nicira-action:nx-resubmit":

,
"order": 2
},
{
"openflowplugin-extension-nicira-action:nx-reg-load": {
"dst":

,
"value": 768
},
"order": 1
},
{
"order": 0,
"set-field": {
"ethernet-match": {
"ethernet-destination":

}
}
}
],
"bucket-id": 0,
"watch_group": 4294967295,
"watch_port": 4294967295,
"weight": 0
}
]
},
"group-id": 200000,
"group-name": "7e763a79-bf3f-409a-80c7-6ea478b783eb",
"group-type": "group-all"
},
{
"buckets": {},
"group-id": 210001,
"group-name": "271c0841-0427-409f-b37c-94aea5175748",
"group-type": "group-all"
},

see full inventory in logs.

Attachment full-inventory.zip has been added with description: full-inventory before vm is booted

group_id=210002,type=all,bucket=actions=group:210001,bucket=actions=load:0x300->NXM_NX_REG6[],resubmit(,220)
group_id=210001,type=all

It looks like the above groups are created for ELAN instance for flat provider network type and doesn't have any VMs in it.
But when add VM, group_mod is sent for 210001 with a bucket to OVS, but not sure why OVS throws OFPGMFC_GROUP_EXISTS error. This should be thrown only for group add OFPGC_ADD request and not for OFPGC_MODIFY.

Can we look at tcpdump to know what kind of group request is sent ?

Reproduced again this time fetching logs and thread dump while and after hanging odl:

https://drive.google.com/open?id=0B_Rr7XjF0yoHc2EwT1psVGQwRVE

I see there are 6 threads which blocked in BgpConfigurationManager while advertising route to bgp. Looks like there is an issue with establishing neighbour with bgp peer. This causes a thread which invokes BgpConfigurationManager#replay holds bgpconfigmgr's instrinsic lock for longer time, eventually other threads trying to advertise routes, etc. are blocked on this lock.
This makes around 7 threads to be unused by ODL (DjC, DCN notification etc.) and it leads to 2 mins hang and flows are not programmed in switches (in the attached log, table 17 flow rules are not programmed for some of the VMs)

We need to address the following.

1. Need to resolve establishing BGP neighbor issue. in karaf.log, i see lot of errors like:
2017-04-06 14:54:52,403 | ERROR | pool-46-thread-1 | BgpConfigurationManager | 318 - org.opendaylight.netvirt.bgpmanager-impl - 0.3.3.SNAPSHOT | Replay:startBgp() received exception: "org.apache.thrift.transport.TTransportException"

Is there any issue with setting up 6wind quagga with ODL ? can you look into it ?
If you resolve this, we may not see the thread blocking issue.

2. Holding lock bgpconfigmgr's intrinsic lock for all method invocations is incorrect. This will make system to be unusable at this situation. It has to be addressed. Suneelu/Siva, Can you have a look ?

Hey,

godd finding! yes quagga bgp is not working yet on this machine. This was a bug raised internally for OPNFV. I will put more effort on this bug then now. You are right we need to remove this sync in addVRF. Can we still pull that in SR-3?

Br Nikolas

just for more information!

1. cat overcloud-controller-0.odl.thread.dump |grep BL
   OCKED -B 1 -A 6
   "ForkJoinPool-1-worker-0" #1072 daemon prio=5 os_prio=0 tid=0x00007f3fb4853000 nid=0x46521 waiting for monitor entry
   [0x00007f3f34568000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   at org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager.addPrefix(BgpConfigurationManager.java:1918)

• waiting to lock <0x000000008e1fe548> (a org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager)
  at org.opendaylight.netvirt.bgpmanager.BgpManager.advertisePrefix(BgpManager.java:122)
  at Proxyf51ee27f_be1b_4724_a075_2d313a52fe71.advertisePrefix(Unknown Source)
  at Proxy4be9080d_62c9_4555_b8c8_5c3f04181a72.advertisePrefix(Unknown Source)
  at org.opendaylight.netvirt.vpnmanager.VpnInterfaceManager.addPrefixToBGP(VpnInterfaceManager.java:965)
  –
  "ForkJoinPool-1-worker-2" #1070 daemon prio=5 os_prio=0 tid=0x00007f3fb4856800 nid=0x46520 waiting for monitor entry
  [0x00007f3f0c347000]
  java.lang.Thread.State: BLOCKED (on object monitor)
  at org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager.addPrefix(BgpConfigurationManager.java:1918)
• waiting to lock <0x000000008e1fe548> (a org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager)
  at org.opendaylight.netvirt.bgpmanager.BgpManager.advertisePrefix(BgpManager.java:122)
  at Proxyf51ee27f_be1b_4724_a075_2d313a52fe71.advertisePrefix(Unknown Source)
  at Proxy4be9080d_62c9_4555_b8c8_5c3f04181a72.advertisePrefix(Unknown Source)
  at org.opendaylight.netvirt.vpnmanager.VpnInterfaceManager.addPrefixToBGP(VpnInterfaceManager.java:965)
  –
  "ForkJoinPool-1-worker-3" #1071 daemon prio=5 os_prio=0 tid=0x00007f3f78206000 nid=0x4651f waiting for monitor entry
  [0x00007f3f1bdfe000]
  java.lang.Thread.State: BLOCKED (on object monitor)
  at org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager.addPrefix(BgpConfigurationManager.java:1918)
• waiting to lock <0x000000008e1fe548> (a org.opendaylight.netvirt.bgpmanager.BgpConfigurationManager)
  at org.opendaylight.netvirt.bgpmanager.BgpManager.advertisePrefix(BgpManager.java:122)
  at Proxyf51ee27f_be1b_4724_a075_2d313a52fe71.advertisePrefix(Unknown Source)
  at Proxy4be9080d_62c9_4555_b8c8_5c3f04181a72.advertisePrefix(Unknown Source)
  at org.opendaylight.netvirt.vpnmanager.VpnInterfaceManager.addPrefixToBGP(VpnInterfaceManager.java:965)

I checked. if effects master branch as well in the same amount.

Vyshakh, Can you get https://git.opendaylight.org/gerrit/#/c/54578/ merged ? Also it has to be cherry picked into stable/boron.