neutron

neutron-openvswitch-agent RuntimeError: Switch connection timeout

Bug #1774257 reported by Gaëtan Trellu
40
This bug affects 9 people
Affects Status Importance Assigned to Milestone
neutron
Invalid
Undecided
Unassigned

Bug Description

In neutron-openvswitch-agent.log I see lot of timeout message.

  RuntimeError: Switch connection timeout

This timeout prevents sometime neutron-openvswitch-agent to be UP.
We are running Pike and we have ~1000 ports in Open vSwitch.

I'm able to run ovs-vsctl, ovs-ofctl, etc... commands which mean that Open vSwitch (vswitchd+db) is working fine.

This is the full TRACE of neutron-openvswitch-agent log:

2018-05-30 19:22:42.353 7 WARNING ovsdbapp.backend.ovs_idl.vlog [-] tcp:127.0.0.1:6640: receive error: Connection reset by peer
2018-05-30 19:22:42.358 7 WARNING ovsdbapp.backend.ovs_idl.vlog [-] tcp:127.0.0.1:6640: connection dropped (Connection reset by peer)
2018-05-30 19:24:17.626 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-3c335d47-9b3e-4f18-994b-afca7d7d70be - - - - -] Switch connection timeout: RuntimeError: Switch connection timeout
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-3c335d47-9b3e-4f18-994b-afca7d7d70be - - - - -] Error while processing VIF ports: RuntimeError: Switch connection timeout
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent Traceback (most recent call last):
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 2066, in rpc_loop
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent ofport_changed_ports = self.update_stale_ofport_rules()
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 153, in wrapper
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent return f(*args, **kwargs)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 1210, in update_stale_ofport_rules
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent self.int_br.delete_arp_spoofing_protection(port=ofport)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/br_int.py", line 255, in delete_arp_spoofing_protection
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent match=match)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py", line 111, in uninstall_flows
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent (dp, ofp, ofpp) = self._get_dp()
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ovs_bridge.py", line 67, in _get_dp
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent self._cached_dpid = new_dpid
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent self.force_reraise()
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent six.reraise(self.type_, self.value, self.tb)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ovs_bridge.py", line 50, in _get_dp
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent dp = self._get_dp_by_dpid(self._cached_dpid)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py", line 69, in _get_dp_by_dpid
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent raise RuntimeError(m)
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent RuntimeError: Switch connection timeout
2018-05-30 19:24:17.628 7 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent

Open vSwitch logs.

==> /var/log/kolla/openvswitch/ovs-vswitchd.log <==
2018-05-30T19:25:47.008Z|294667|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: waiting 4 seconds before reconnect
2018-05-30T19:25:50.008Z|294668|rconn|INFO|br-ex<->tcp:127.0.0.1:6633: connecting...
2018-05-30T19:25:50.008Z|294669|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connecting...
2018-05-30T19:25:51.008Z|294670|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connecting...
2018-05-30T19:25:54.008Z|294671|rconn|INFO|br-ex<->tcp:127.0.0.1:6633: connection timed out
2018-05-30T19:25:54.008Z|294672|rconn|INFO|br-ex<->tcp:127.0.0.1:6633: continuing to retry connections in the background but suppressing further logging
2018-05-30T19:25:54.008Z|294673|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connection timed out
2018-05-30T19:25:54.008Z|294674|rconn|INFO|br-int<->tcp:127.0.0.1:6633: continuing to retry connections in the background but suppressing further logging
2018-05-30T19:25:55.008Z|294675|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connection timed out
2018-05-30T19:25:55.008Z|294676|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: continuing to retry connections in the background but suppressing further logging

==> /var/log/kolla/openvswitch/ovsdb-server.log <==
2018-05-30T19:23:29.188Z|28929|reconnect|ERR|tcp:127.0.0.1:45468: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:23:57.341Z|28930|reconnect|ERR|tcp:127.0.0.1:54766: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:23:58.157Z|28931|reconnect|ERR|tcp:127.0.0.1:55294: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:24:27.132Z|28932|reconnect|ERR|tcp:127.0.0.1:37484: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:24:27.655Z|28933|reconnect|ERR|tcp:127.0.0.1:37614: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:24:56.926Z|28934|reconnect|ERR|tcp:127.0.0.1:47597: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:25:11.972Z|28935|reconnect|ERR|tcp:127.0.0.1:47582: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:25:19.962Z|28936|reconnect|ERR|tcp:127.0.0.1:54950: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:25:41.338Z|28937|reconnect|ERR|tcp:127.0.0.1:36394: no response to inactivity probe after 5 seconds, disconnecting
2018-05-30T19:25:49.850Z|28938|reconnect|ERR|tcp:127.0.0.1:39808: no response to inactivity probe after 5 seconds, disconnecting

See original description
Tags: ovs
Gaëtan Trellu (goldyfruit)
description: updated
Revision history for this message
Gaëtan Trellu (goldyfruit) wrote :
Download full text (5.5 KiB)

2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 160, in _process_incoming
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 213, in dispatch
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 183, in _do_dispatch
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 153, in wrapper
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_log/helpers.py", line 67, in wrapper
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return method(*args, **kwargs)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/l2pop/rpc_manager/l2population_rpc.py", line 41, in add_fdb_entries
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server self.fdb_add(context, self._unmarshall_fdb_entries(fdb_entries))
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 153, in wrapper
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 524, in fdb_add
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server agent_ports, self._tunnel_port_lookup)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/osprofiler/profiler.py", line 153, in wrapper
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return f(*args, **kwargs)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/oslo_log/helpers.py", line 67, in wrapper
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server return method(*args, **kwargs)
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/l2pop/rpc_manager/l2population_rpc.py", line 254, in fdb_add_tun
2018-05-30 20:05:32.387 7 ERROR oslo_messaging.rpc.server self.add_fdb_flow(br, port, remote_ip, lvm, ofport)
2...

Read more...

Revision history for this message
Gaëtan Trellu (goldyfruit) wrote :

2018-05-30 21:11:09.347 7 WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-5696c85c-046a-4cfe-8ce8-f16100944081 - - - - -] OVS is dead. OVSNeutronAgent will keep running and checking OVS status periodically.: TimeoutException: Commands [<ovsdbapp.schema.open_vswitch.commands.ListPortsCommand object at 0x7fbb77c94e10>] exceeded timeout 10 seconds

Gaëtan Trellu (goldyfruit)
description: updated
Boden R (boden)
tags: added: ovs
Illuri Hemalatha Reddy (hemalatha-illuri)
Changed in neutron:
assignee: nobody → Illuri Hemalatha Reddy (hemalatha-illuri)
Revision history for this message
IWAMOTO Toshihiro (iwamoto) wrote :

increasing timeout would be an obvious workaround.

Revision history for this message
Swaminathan Vasudevan (swaminathan-vasudevan) wrote :

What timeout you are talking about here to increase.

Illuri Hemalatha Reddy (hemalatha-illuri)
Changed in neutron:
assignee: Illuri Hemalatha Reddy (hemalatha-illuri) → nobody
Revision history for this message
Brian Haley (brian-haley) wrote :

There have been a number of changes to the agent code since this bug was opened, and since we have not seen this reported elsewhere I'm going to close it. Please re-open if you have more data and see it again.

Changed in neutron:
status: New → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.