Bug 1545266

Some update from OVS team (Kevin T):

Matteo is supporting Fabrizio on the systems now. 
We noticed VM looking for 2GB but only 1 GB available, so the guys are looking into that.

Node 0 HugePages_Total:    59
Node 0 HugePages_Free:      1

size=2147483648,host-nodes=0,policy=bind: os_mem_prealloc: Insufficient
free host memory pages available to allocate guest RAM

For this testing, did you disable l2pop? If so, can you please also share neutron logs?

No, we didn't disable l2pop because, correct me if I'm wrong, it must be disabled on all nodes on all hypervisors.

As it's a quite invasive configuration change, the customer has to do it, and we'll do more tests afterwards.

Thanks Matteo and Flavio. I will check the logs.

Log path
http://collab-shell.usersys.redhat.com/02028278/sosreport-20180312-195753/cpt6-dpdk-totp/var/log/neutron/openvswitch-agent.log

search for "OVS is dead. OVSNeutronAgent will keep running and checking OVS status periodically." in this log.

2018-03-12 19:05:38.298 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-71ef81a2-e38a-409d-bf17-d3ae358cb684 - - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0xcebff983,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int [req-71ef81a2-e38a-409d-bf17-d3ae358cb684 - - - - -] Failed to communicate with the switch
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int Traceback (most recent call last):
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/br_int.py", line 52, in check_canary_table
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     flows = self.dump_flows(constants.CANARY_TABLE)
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py", line 131, in dump_flows
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     reply_multi=True)
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py", line 89, in _send_msg
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     raise RuntimeError(m)
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0xcebff983,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int 
2018-03-12 19:05:38.308 28932 WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-71ef81a2-e38a-409d-bf17-d3ae358cb684 - - - - -] OVS is dead. OVSNeutronAgent will keep running and checking OVS status periodically.

Looking at OVS logs, the connection to the controller is "active" and not "passive", which means OVS tries to connect to the controller, but the controller is not recovering from a previous disconnection event:

2018-03-12T18:31:13.644Z|00313|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.645Z|00314|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.645Z|00315|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.648Z|00316|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:13.648Z|00317|rconn|WARN|br-erogazione<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:13.648Z|00318|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: waiting 2 seconds before reconnect
2018-03-12T18:31:13.648Z|00319|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:13.648Z|00320|rconn|WARN|br-int<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:13.648Z|00321|rconn|INFO|br-int<->tcp:127.0.0.1:6633: waiting 2 seconds before reconnect
2018-03-12T18:31:13.648Z|00322|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:13.649Z|00323|rconn|WARN|br-tun<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:13.649Z|00324|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: waiting 2 seconds before reconnect
2018-03-12T18:31:15.647Z|00325|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:15.647Z|00326|rconn|WARN|br-erogazione<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:15.647Z|00327|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: waiting 4 seconds before reconnect
2018-03-12T18:31:15.647Z|00328|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:15.647Z|00329|rconn|WARN|br-int<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:15.647Z|00330|rconn|INFO|br-int<->tcp:127.0.0.1:6633: waiting 4 seconds before reconnect
2018-03-12T18:31:15.647Z|00331|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:31:15.647Z|00332|rconn|WARN|br-tun<->tcp:127.0.0.1:6633: connection failed (Connection refused)
2018-03-12T18:31:15.647Z|00333|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: waiting 4 seconds before reconnect


Then after some time, it recovers, and it seems to be ok, but then it breaks again due to not responding the probe:

2018-03-12T18:51:52.337Z|00548|rconn|ERR|br-erogazione<->tcp:127.0.0.1:6633: no response to inactivity probe after 537 seconds, disconnecting
2018-03-12T18:51:52.647Z|00549|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connecting...
2018-03-12T18:51:52.649Z|00550|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connected
2018-03-12T18:52:03.733Z|00551|connmgr|INFO|br-int<->tcp:127.0.0.1:6633: 15 flow_mods 10 s ago (15 deletes)
2018-03-12T18:52:04.535Z|00552|connmgr|INFO|br-tun<->tcp:127.0.0.1:6633: 5 flow_mods 10 s ago (5 adds)

Looking at the last recorded error:
status              : {last_error="Connection timed out",

But the above looks red herring.


However, I am curious about this one:
2018-03-12 19:25:13.793 32560 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:15.070 32584 INFO neutron.common.config [-] Logging enabled!

but it is configured in the host:
33: br-erogazione    inet 10.30.0.186/24 brd 10.30.0.255 scope global br-erogazione\       valid_lft forever preferred_lft forever

Does that prevent the VXLAN tunnel to be recreated?
Because it is the interface IP disappearing from OVS bridge, see:
https://bugzilla.redhat.com/show_bug.cgi?id=1545266#c71

fbl

Hi Anil,

there is something weird here. when the bug triggers we can still give vsctl and ofproto commands, and get responses back.
Last time we also attached GDB to ovs-vswitchd and traced it, the process continued to live.

This is the 'ps ax' output after the ovs/neutron comunication breakdown:

http://collab-shell.usersys.redhat.com/02028278/sosreport-20180312-195753/cpt6-dpdk-totp/ps

I'm looking at the same sosreport and when the communication goes down OVS says this:

2018-03-12T18:05:48.946Z|00029|ofproto_dpif_upcall(pmd31)|WARN|Dropped 1 log messages in last 10438 seconds (most recently, 10438 seconds ago) due to excessive rate
2018-03-12T18:05:48.952Z|00030|ofproto_dpif_upcall(pmd31)|WARN|upcall_cb failure: ukey installation fails

then continues working. Beware that Neutron stores logs in local time, whereas OpenvSwitch uses UTC.

Have a look to the other sosreport where neutron and ovs are in debug mode, that one was normal debug level.

Cheers,
Matteo

Created attachment 1408744 [details]
grep -E "dead|Timeout|timed" var/log/neutron/openvswitch-agent.log | grep -v AMQP | tee ovs-agent-timeout-errors

Two notes before we explain our analysis (@anilvenkata and @majopela):
    
The L2pop mechanism is mandatory for DVR (@anilvenkata)  . In some comments we are talking about deletion of ovs flows
related to a vm(with a MAC) in table 20. This is expected behaviour. When a vm is deleted from a host, other hosts which had
ovs flow to reach this deleted vm(in table 20), will delete this flow from their table.
Also a host will delete flows related to a network(and its ports including table 20 ovs flow) when the network's last port is deleted from that host.
Same thing happes for the tunnel endpoints (as we will see in the next analysis)

The timestamps of neutron and nova are skewed +1h compared to ovs-vswitchd logs (this has been explained before)

cd /cases/02028278/sosreport-20180312-195753/cpt6-dpdk-totp

[majopela@collab-shell nova]$ grep ERROR * | grep "Insufficient free host memory pages" | awk '{ print $1, $2, $5 }' | grep 03-12
2018-03-12 19:14:31.263 nova.compute.manager
2018-03-12 19:37:12.486 nova.compute.manager

Those are the two events related to nova attempts to boot an instance


For the first event we couldn't find any correlatable logs on neutron-openvswitch agent , only the artifacts of restarting ovs-agent and network services (see later)


If we look at neutron logs when the instance is being plugged we find that a tunnel port
is being created (L2POP) to allow such instance to communicate to it's peers on other compute hosts.
    
$ grep "2018-03-12 19:3" var/log/neutron/openvswitch-agent.log | grep vxlan-0a1e000d
2018-03-12 19:37:07.047 35724 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=0): AddPortCommand(bridge=br-tun, may_exist=True, port=vxlan-0a1e000d) do_commit /usr/lib/python2.7/site-packages/neutron/agent/ovsdb/impl_idl.py:98
2018-03-12 19:37:07.047 35724 DEBUG neutron.agent.ovsdb.impl_idl [-] Running txn command(idx=1): DbSetCommand(table=Interface, col_values=(('type', u'vxlan'), ('options', OrderedDict([('df_default', 'true'), ('remote_ip', u'10.30.0.13'), ('local_ip', '10.30.0.186'), ('in_key', 'flow'), ('out_key', 'flow')]))), record=vxlan-0a1e000d) do_commit /usr/lib/python2.7/site-packages/neutron/agent/ovsdb/impl_idl.py:98


At this point the event of nova-compute.log "2018-03-12 19:37:12.486 nova.compute.manager" with "Insufficiente free host memory pages happen"


If we look at the neutron openvswitch agent logs afterwards:

[majopela@collab-shell cpt6-dpdk-totp]$ grep "2018-03-12 19:37" var/log/neutron/openvswitch-agent.log | grep ERROR | grep timeout
<ovsdb TIMEOUT:>
2018-03-12 19:37:23.701 35724 ERROR neutron.agent.ovsdb.impl_idl     'timeout': self.timeout})
2018-03-12 19:37:23.701 35724 ERROR neutron.agent.ovsdb.impl_idl TimeoutException: Commands [DelPortCommand(if_exists=True, bridge=br-tun, port=vxlan-0a1e000d)] exceeded timeout 10 seconds post-commit
<openflow TIMEOUT>
2018-03-12 19:37:33.713 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 - - - - -] ofctl request version=0x4,msg_type=0xe,msg_len=0x40,xid=0xcdab270c,OFPFlowMod(buffer_id=4294967295,command=3,cookie=0,cookie_mask=0,flags=0,hard_timeout=0,idle_timeout=0,instructions=[],match=OFPMatch(oxm_fields={'in_port': 2}),out_group=4294967295,out_port=4294967295,priority=0,table_id=255) timed out

Two things are happening, first, ovsdb timesout trying to delete the vxlan tunnel port which is not needed anymore, since the instance failed, we clean it up. (try to)
but ovsdb times ut.

Afterwards, the neutron-openvswitch-agent continually fails to talk to ovs-vswitchd via the open openflow connection (se the attached 
ovs-agent-timeout-errors), but it's not completely relatable to the 2nd nova failure, since, it was already happening before, first here:
    
2018-03-12 19:05:38.299 28932 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0xcebff983,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
  ^ I cannot correlate this one to any nova-compute events.
  
and here  
    
    2018-03-12 19:34:24.502 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 - - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d7fd,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
    
This one seems correlated to the start of an instance ^ ( 50c87a63-dd8a-4ade-9747-1d9dc0fe4404)

The restarts happen between the first failure in nova, and the second one, but not after:

[majopela@collab-shell cpt6-dpdk-totp]$ cat  var/log/neutron/openvswitch-agent.log  | grep "Logging" | grep 03-12
2018-03-12 19:25:08.083 32478 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:10.306 32511 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:12.064 32537 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:13.553 32560 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:15.070 32584 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:16.552 32607 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:18.046 32632 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:19.560 32656 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:25:21.047 32680 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:26:48.956 34635 INFO neutron.common.config [-] Logging enabled!
2018-03-12 19:31:15.586 35724 INFO neutron.common.config [-] Logging enabled!

Some of them (the repeatitive ones 19:25:10...19:26:48 are due to one of the bridges
not being available momentarily on openvswitch (thus the tunneling IP is not available
br-erogazione    inet 10.30.0.186) as we can see here:

[majopela@collab-shell cpt6-dpdk-totp]$ grep 10.30.0.186 var/log/neutron/openvswitch-agent.log  | grep "IP couldn" | grep "03-12"
2018-03-12 19:25:08.839 32478 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:10.603 32511 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:12.306 32537 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:13.793 32560 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:15.311 32584 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:16.787 32607 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:18.282 32632 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:19.794 32656 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.
2018-03-12 19:25:21.280 32680 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [-] Tunneling can't be enabled with invalid local_ip '10.30.0.186'. IP couldn't be found on this host's interfaces.

systemd eventually notices that the agent didn't boot properly and restarts it.

Matching to your above comments in bz:
    
2018-03-12T18:05:48.946Z|00029|ofproto_dpif_upcall(pmd31)|WARN|Dropped 1 log messages in last 10438 seconds (most recently, 10438 seconds ago) due to excessive rate
2018-03-12T18:05:48.952Z|00030|ofproto_dpif_upcall(pmd31)|WARN|upcall_cb failure: ukey installation fails
ors)

If we look at ovs-vswitchd logs, there are several closed by peer events (correlated to neutron-openvswitch-agent _restart_)
[majopela@collab-shell cpt6-dpdk-totp]$ grep 6633 var/log/openvswitch/ovs-vswitchd.log  | grep closed
2018-03-12T18:24:18.651Z|00358|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:24:18.651Z|00359|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.644Z|00313|rconn|INFO|br-erogazione<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.645Z|00314|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connection closed by peer
2018-03-12T18:31:13.645Z|00315|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connection closed by peer


after that, the ovs-vswitch agent has been trying to talk to ovs-vswitchd, and timing out on responses.

Is there any way we can log the received openflow requests on ovs-vswitchd?
 
We also see this event which doesn't seem related to the nova failures:    
[majopela@collab-shell cpt6-dpdk-totp]$ grep 6633 var/log/openvswitch/ovs-vswitchd.log  | grep inactivity
2018-03-12T18:51:52.337Z|00548|rconn|ERR|br-erogazione<->tcp:127.0.0.1:6633: no response to inactivity probe after 537 seconds, disconnecting


Conclusion:
   We're not able to fully correlate the failure in nova to failures in neutron-openvswitch-agent for both
times, after the second boot attempt, yes, openflow requests from the agent to ovs-vswitchd timeout.

   The reconnection/disconnections only seem to happen when the network/openvswich-agent is restarted,
we see that regardless of that restart and the reconnection, the openflow  commands still timeout (It's 
trying to get OFPFlowStatsRequests)


2018-03-12 19:37:11.064 35724 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 -
 - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8ad,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fi
elds={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) result [OFPFlowStatsReply(body=[OFPFlowStats(byte_count=0,cookie=12310247377014158391L,duration_nsec=299000000,duration_sec=350,flags=0,hard_timeout=0,idle_timeout=0,instructions=[],length=56,match=OFPMatch(oxm_fields={}),packet_count=0,priority=0,table_id=23)],flags=0,type=1)] _send_msg /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py:93
2018-03-12 19:37:13.055 35724 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 - - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8af,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) result [OFPFlowStatsReply(body=[OFPFlowStats(byte_count=0,cookie=12310247377014158391L,duration_nsec=289000000,duration_sec=352,flags=0,hard_timeout=0,idle_timeout=0,instructions=[],length=56,match=OFPMatch(oxm_fields={}),packet_count=0,priority=0,table_id=23)],flags=0,type=1)] _send_msg /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py:93



The nova event goes here: 2018-03-12 19:37:12.486 nova.compute.manager



2018-03-12 19:37:43.731 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 - - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8b9,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
2018-03-12 19:37:43.731 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8b9,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
2018-03-12 19:37:53.734 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-4c80a606-5e55-4c94-b705-ebef140b4651 - - - - -] ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8bb,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out
2018-03-12 19:37:53.734 35724 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: ofctl request version=0x4,msg_type=0x12,msg_len=0x38,xid=0x3409d8bb,OFPFlowStatsRequest(cookie=0,cookie_mask=0,flags=0,match=OFPMatch(oxm_fields={}),out_group=4294967295,out_port=4294967295,table_id=23,type=1) timed out

we are increasing the severity of this case to sev2. 

The issue we are facing at network level, can be also trigger by create and delete a VM on a compute host.

We start with the SC1 on cpt8-dpdk and SC2 on cpt9-dpdk that can ping eachother on the tenant network. We can also check that the vxlan tunnel exists:

[root@cpt8-dpdk-totp ~]# ovs-appctl tnl/ports/show
Listening ports:
vxlan_sys_4789 (4)

We focused on reproducing the bug on cpt8-dpdk by creating and then deleting a dummy VM.

VM creation was done at 20:00:17
(after the creation everything was still OK)

VM deletion at 20:02:14

At that point ping between the two SC VMs doesn't work and we can see that the vxlan tunnel is gone.

We also noticed that by recreating the dummy VM everything is restored: vxlan tunnel comes back and ping between the 2 SC VMs works again.

To facilitate the troubleshooting we did put nova and neutron in debug mode before running the test.

sosreport already attached.

Note: that during the entire test the PID of neutron-openvswitch-agent doesn't change

Me and Miguel debugged this along with Fabrizio.
This is our analysis.

In the setup, vm 'SC1' is on cpt8-dpdk(local_ip 10.30.0.188) and vm 'SC2' is on  cpt9-dpdk(local_ip 10.30.0.189). Both these vms are in same network(I think ID starts with c09766a2).
1) I restarted openvswitch-agent on cpt8-dpdk(as a fresh start).
    On cpt8-dpdk,
     a) I can see vxlan tunnel port on br-tun bridge with local_ip=10.30.0.188 and remote_ip=10.30.0.189
     b) Also "ovs-appctl tnl/ports/show -v" is showing some output.
     c) ping from SC2 to SC1 is successful.

2) Now booted a dummy vm on host cpt8-dpdk(local_ip 10.30.0.188), but on different network(not on SC1's hosting network).
    On cpt8-dpdk,
     a) I can still see vxlan tunnel port on br-tun bridge with local_ip=10.30.0.188 and remote_ip=10.30.0.189
     b) Also "ovs-appctl tnl/ports/show -v" is showing some output.
     c) When this dummy vm booted, openvswitch-agent running on cpt8-dpdk, created vxlan tunnel ports to some other hosts(which have 10.30.0.13, 10.30.0.14 as their local_ip). 
         http://paste.openstack.org/show/703283/
         Note: it didn't delete tunnel between cpt8-dpdk and cpt9-dpdk.
     e)  Still ping from SC2 to SC1 is successful.

2) Now deleted above dummy vm on host cpt8-dpdk(local_ip 10.30.0.188).
    On cpt8-dpdk,
     a) I can still see vxlan tunnel port on br-tun bridge with local_ip=10.30.0.188 and remote_ip=10.30.0.189
     b) But this time  "ovs-appctl tnl/ports/show -v" *not* showing any output.
     c) ping from SC2 to SC1 is successful.
     d) When this dummy vm deleted, openvswitch-agent running on cpt8-dpdk, deleted vxlan tunnel ports(which it created earlier) to some other hosts(which have 10.30.0.13, 10.30.0.14 as their local_ip), this is expected.
         But it didn't delete tunnel between cpt8-dpdk and cpt9-dpdk.
     e)  ping from SC2 to SC1 is failed.

Need to identify why "ovs-appctl tnl/ports/show -v" not showing any output, though tunnels between cpt8-dpdk and cpt9-dpdk exists.

Latest from Fabrizio (BZ updating not working):

I have done another test session with this scenario:

1) spawn a dummy VM on cpt9-dpdk with a tenant network

2) with the SC-1 shutdown, spawn a dummy VM on cpt8-dpdk

3) verify that the two dummy VMs are able to ping and the vxlan tunnels are still present

4) spawn a second dummy VM on cpt8-dpdk

5) verify that everything is still working properly 

6) delete the last dummy VM created on cpt8-dpdk

7) verify that everything is still working properly 

In attach the two sosreports coming from both compute hosts, plus the commands list and the outputs (all with timestamp) file: test_170318_193500

Question:
*** Why seems that the bug occur only with the SC VMs? ***

Hello guys,

   We've been able to reproduce this in the customer environment by doing the following:

1) Create a network
2) Create a subnet WITHOUT a gateway defined
3) Create 2 VMs on compute A and 1 VM on compute B
4) Delete one of the VM on compute A
5) Tunnel stops working.

In order to confirm this, we've tried the following:
1) Create a network
2) Create a subnet WITH a gateway defined
3) Create 2 VMs on compute A and 1 VM on compute B
4) Delete one of the VM on compute A
5) Tunnel keeps working.

Thank you very much,

David Hill

An update, we isolated the failure to openvswitch, it can be reproduced without the intervention of neutron.


You can use the steps 1-3 provided in comment 104, and at that point, go to the compute node where you spawned compute A, and remove one of the tunnel endpoints to the network nodes. 

That will make ovs-vswitchd disconnect absolutely all the tunnels (UDP) (even to other compute nodes)

[root@cpt5-dpdk-totp ~]# ovs-vsctl del-port br-tun vxlan-0a1e000d
[root@cpt5-dpdk-totp ~]# ovs-appctl tnl/ports/show -v
Listening ports:

But if we add such port back, the connectivity is recovered.

[root@cpt5-dpdk-totp ~]# ovs-vsctl --may-exist add-port br-tun vxlan-0a1e000d -- set Interface vxlan-0a1e000d type=vxlan options:df_default=true options:remote_ip=10.30.0.13 options:local_ip=10.30.0.185 options:in_key=flow options:out_key=flow

[root@cpt5-dpdk-totp ~]# ovs-appctl tnl/ports/show -v
Listening ports:
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:3f:40),eth_type(0x86dd),ipv6(dst=fe80::3aea:a7ff:fe8c:3f40,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f0),eth_type(0x86dd),ipv6(dst=fe80::3aea:a7ff:fe8c:31f0,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f1),eth_type(0x86dd),ipv6(dst=fe80::3aea:a7ff:fe8c:31f1,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f0),eth_type(0x0800),ipv4(dst=163.162.39.157,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f0),eth_type(0x0800),ipv4(dst=10.20.0.185,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f1),eth_type(0x0800),ipv4(dst=10.30.0.185,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:3f:40),eth_type(0x0800),ipv4(dst=10.70.0.185,proto=17,frag=no),udp(dst=4789)
vxlan_sys_4789 (7) : eth(dst=38:ea:a7:8c:31:f0),eth_type(0x0800),ipv4(dst=163.162.31.205,proto=17,frag=no),udp(dst=4789)

Please note that such vxlan tunnel is not the one connecting to the other compute node, it's a vxlan tunnel that goes to the network node.

It was fixed upstream in this commit:

commit e7c9ff0ed108d73f4aca2d5e54fa1e671e935e20
Author: zhaozhanxu <zhaozhanxu>
Date:   Mon Jun 26 18:29:22 2017 +0800

    tnl-ports: Fix loss of tunneling upon removal of a single tunnel port.

The fix will included in the next package for OSP10

Regards,
Matteo Croce