neutron

When kill(sometines doesn't restart) the ovs switch or restart it in the compute nodes vm conectivity is lost

Bug #1804842 reported by Candido Campos Rivas on 2018-11-23

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	neutron	Fix Released	Medium	Slawek Kaplonski

Bug Description

OSP 14

3 controllers + 3 computes + dvr

several vms in one compute with fip.

Problem 1 :

root@compute-2 heat-admin]# systemctl restart openvswitch

fip conectivity with undercloud vm is lost and no recover

conectivity with other computes is lost, but it is recovered restarting neutron openvswitch agent container

root@compute-2 heat-admin]# systemctl restart openvswitch.

Problem 2:

After kill -9 "pid ovs switch"

Sometimes the ovs switch in not restarted automatically

Same problems that in the scenario1

[root@compute-2 heat-admin]# root 10558 7292 0 12:09 ? 42435 46886 46871 0 13:17 ? openvsw+ 49054 1 1 13:20 ? root 49217 17666 0 13:21 pts/0 [root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# root 10558 7292 0 12:09 ? 42435 46886 46871 0 13:17 ? openvsw+ 49054 1 0 13:20 ? root 49421 17666 0 13:21 pts/0 [root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# root 10558 7292 0 12:09 ? 42435 46886 46871 0 13:17 ? openvsw+ 49054 1 0 13:20 ? root 49423 17666 0 13:21 pts/0 [root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# [root@compute-2 heat-admin]# root 10558 7292 0 12:09 ? 42435 46886 46871 0 13:17 ? root 49610 17666 0 13:22 pts/0 [root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# root 10558 7292 0 12:09 ? 42435 46886 46871 0 13:17 ? root 49628 17666 0 13:22 pts/0 ps -ef | grep ovs
00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
00:00:00 ovs-vswitchd unix:/var/run/openvswitch/db.sock -vconsole:emer -vsyslog:err -vfile:info --mlockall --user openvswitch:hugetlbfs --no-chdir --log-file=/var/log/openvswitch/ovs-vswitchd.log --pidfile=/var/run/openvswitch/ovs-vswitchd.pid --detach
00:00:00 grep --color=auto ovs
ps -ef | grep ovs
00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
00:00:00 ovs-vswitchd unix:/var/run/openvswitch/db.sock -vconsole:emer -vsyslog:err -vfile:info --mlockall --user openvswitch:hugetlbfs --no-chdir --log-file=/var/log/openvswitch/ovs-vswitchd.log --pidfile=/var/run/openvswitch/ovs-vswitchd.pid --detach
00:00:00 grep --color=auto ovs
ps -ef | grep ovs
00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
00:00:00 ovs-vswitchd unix:/var/run/openvswitch/db.sock -vconsole:emer -vsyslog:err -vfile:info --mlockall --user openvswitch:hugetlbfs --no-chdir --log-file=/var/log/openvswitch/ovs-vswitchd.log --pidfile=/var/run/openvswitch/ovs-vswitchd.pid --detach
00:00:00 grep --color=auto ovs
kill -9 49054
ps -ef | grep ovs
00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
00:00:00 grep --color=auto ovs
ps -ef | grep ovs
00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
00:00:00 grep --color=auto ovs

[root@compute-2 heat-admin]# date
Fri Nov 23 13:22:22 UTC 2018
[root@compute-2 heat-admin]# ps -ef | grep ovs
root 10558 7292 0 12:09 ? 00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
42435 46886 46871 0 13:17 ? 00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
root 49788 17666 0 13:22 pts/0 00:00:00 grep --color=auto ovs
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# ps -ef | grep ovs
root 10558 7292 0 12:09 ? 00:00:01 /usr/bin/python2 /bin/privsep-helper --config-file /usr/share/nova/nova-dist.conf --config-file /etc/nova/nova.conf --privsep_context vif_plug_ovs.privsep.vif_plug --privsep_sock_path /tmp/tmpATdioG/privsep.sock
42435 46886 46871 0 13:17 ? 00:00:00 /bin/bash /neutron_ovs_agent_launcher.sh
root 49790 17666 0 13:22 pts/0 00:00:00 grep --color=auto ovs

Tags:

YAMAMOTO Takashi (yamamoto) on 2018-11-26

tags:

added: ovs

Revision history for this message

YAMAMOTO Takashi (yamamoto) wrote on 2018-11-26:

by undercloud/overcloud, do you mean triple-o?

problem 1 means you rebooted openvswitch (ovs-vswitchd/ovsdb-server) without restarting
neutron-ovs-agent? maybe canary flow check is not working well for some reasons. can you provide the log of ovs agent?

problem 2 means you killed ovs-vswitchd? looks unrelated to neutron.

Changed in neutron:
status:	New → Incomplete

Revision history for this message

Candido Campos Rivas (ccamposr) wrote on 2018-11-26:

bug1804842.tgz Edit (102.7 KiB, application/x-tar)

Download full text (14.1 KiB)

Yes, I refer to tripleo undercloud vm:

Yes, I refer to tripleo undercloud vm:

(overcloud) [stack@undercloud-0 ~]$ ping 10.0.0.234
PING 10.0.0.234 (10.0.0.234) 56(84) bytes of data.
64 bytes from 10.0.0.234: icmp_seq=1 ttl=62 time=0.512 ms
64 bytes from 10.0.0.234: icmp_seq=2 ttl=62 time=0.525 ms
64 bytes from 10.0.0.234: icmp_seq=3 ttl=62 time=0.453 ms
.....

After systemctl restart:

(undercloud) [stack@undercloud-0 ~]$ ping 10.0.0.234
PING 10.0.0.234 (10.0.0.234) 56(84) bytes of data.
From 10.0.0.29 icmp_seq=1 Destination Host Unreachable
From 10.0.0.29 icmp_seq=2 Destination Host Unreachable
From 10.0.0.29 icmp_seq=3 Destination Host Unreachable
From 10.0.0.29 icmp_seq=4 Destination Host Unreachable

-----------------

Actions in compute2:

[root@compute-2 heat-admin]# date;systemctl restart openvswitch
Mon Nov 26 08:52:14 UTC 2018
[root@compute-2 heat-admin]# 
[root@compute-2 heat-admin]# 
[root@compute-2 heat-admin]# date;docker restart neutron_ovs_agent
Mon Nov 26 08:53:19 UTC 2018
neutron_ovs_agent
[root@compute-2 heat-admin]#

I attach ovs agent logs. as you comment, the problem seems that the flows are not correctly reloaded  after the restarts.

with  problem 2:

There are some comunication problem after some kill:

root@compute-2 heat-admin]# tail -f  /var/log/containers/neutron/metadata-agent.log
2018-11-26 08:51:10.883 8224 INFO eventlet.wsgi.server [-] 10.2.0.18,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200  len: 139 time: 0.1934390
2018-11-26 08:51:10.968 8223 INFO eventlet.wsgi.server [-] 10.3.0.25,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200  len: 139 time: 0.1648369
2018-11-26 09:11:20.883 8224 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed
2018-11-26 09:11:34.307 7137 ERROR oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:35.323 7137 INFO oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50096.
2018-11-26 09:11:43.938 8223 ERROR oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] AMQP server controller-1.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:44.955 8223 INFO oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] Reconnected to AMQP server on controller-1.internalapi.localdomain:5672 via [amqp] client with port 37994.
2018-11-26 09:11:45.218 8224 ERROR oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:46.235 8224 INFO oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50116.
2018-11-26 09:11:59.117 8223 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed

2018-11-26 09:12:04.417 7137 ERROR oslo.messaging._drivers.impl_rabbit [-] [8f9c38d5-3ad8-4cab-8446-a2f07e6d370f] AMQP server controller-1.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:12:05.444 7137 INFO oslo.messaging._drivers.impl_rabbit [-] [8f9c38d5-3ad8-4cab-8446-a2f07e6d370f] Reconnected to AMQP server on controller-1.internalapi.localdomain:5672 via [amqp] client with port 38042.
2018-11-26 09:12:15.386 8224 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: error: [Errno 104] Connection reset by peer

....................

vi /var/log/containers/neutron/openvswitch-agent.log

2018-11-26 09:12:55.615 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-6fcf8cf0-e4cb-4142-b6ea-16efb2115491 - - - - -] Switch connection timeout
2018-11-26 09:12:55.616 28480 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): DbGetCommand(column=datapath_id, table=Bridge, record=br-tun) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2018-11-26 09:12:55.616 28480 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server [req-6fcf8cf0-e4cb-4142-b6ea-16efb2115491 - - - - -] Exception during message handling: RuntimeError: Switch connection timeout
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 159, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_log/helpers.py", line 67, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     return method(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/l2pop/rpc_manager/l2population_rpc.py", line 41, in add_fdb_entries
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     self.fdb_add(context, self._unmarshall_fdb_entries(fdb_entries))
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 159, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 541, in fdb_add
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     agent_ports, self._tunnel_port_lookup)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 159, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_log/helpers.py", line 67, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     return method(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/l2pop/rpc_manager/l2population_rpc.py", line 254, in fdb_add_tun
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     self.add_fdb_flow(br, port, remote_ip, lvm, ofport)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 159, in wrapper
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py", line 561, in add_fdb_flow
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     lvm.tun_ofports)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/br_tun.py", line 174, in install_flood_to_tun
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     (_dp, ofp, ofpp) = self._get_dp()
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ovs_bridge.py", line 69, in _get_dp
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     self._cached_dpid = new_dpid
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     self.force_reraise()
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ovs_bridge.py", line 52, in _get_dp
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     dp = self._get_dp_by_dpid(self._cached_dpid)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/openflow/native/ofswitch.py", line 79, in _get_dp_by_dpid
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server     raise RuntimeError(m)
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server RuntimeError: Switch connection timeout
2018-11-26 09:12:55.617 28480 ERROR oslo_messaging.rpc.server
2018-11-26 09:12:56.272 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-6fcf8cf0-e4cb-4142-b6ea-16efb2115491 - - - - -] Switch connection timeout
2018-11-26 09:12:56.273 28480 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): DbGetCommand(column=datapath_id, table=Bridge, record=br-tun) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84

Revision history for this message

Candido Campos Rivas (ccamposr) wrote on 2018-11-26:

Download full text (9.9 KiB)

Reprodcution logs attached:

[heat-admin@compute-2 ~]$ sudo su
[root@compute-2 heat-admin]# date;systemctl restart openvswitch
Mon Nov 26 08:52:14 UTC 2018
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]#
[root@compute-2 heat-admin]# date;docker restart neutron_ovs_agent
Mon Nov 26 08:53:19 UTC 2018
neutron_ovs_agent

Logs for 2 problem when openvswich doesn't restart :

[root@compute-2 heat-admin]# tail -f /var/log/containers/neutron/metadata-agent.log
2018-11-26 08:51:10.883 8224 INFO eventlet.wsgi.server [-] 10.2.0.18,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200 len: 139 time: 0.1934390
2018-11-26 08:51:10.968 8223 INFO eventlet.wsgi.server [-] 10.3.0.25,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200 len: 139 time: 0.1648369
2018-11-26 09:11:20.883 8224 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed
2018-11-26 09:11:34.307 7137 ERROR oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:35.323 7137 INFO oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50096.
2018-11-26 09:11:43.938 8223 ERROR oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] AMQP server controller-1.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:44.955 8223 INFO oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] Reconnected to AMQP server on controller-1.internalapi.localdomain:5672 via [amqp] client with port 37994.
2018-11-26 09:11:45.218 8224 ERROR oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:46.235 8224 INFO oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50116.
2018-11-26 09:11:59.117 8223 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed

vi /var/log/containers/neutron/openvswitch-agent.log

Reprodcution logs attached:

[heat-admin@compute-2 ~]$ sudo su 
[root@compute-2 heat-admin]# date;systemctl restart openvswitch
Mon Nov 26 08:52:14 UTC 2018
[root@compute-2 heat-admin]# 
[root@compute-2 heat-admin]# 
[root@compute-2 heat-admin]# date;docker restart neutron_ovs_agent
Mon Nov 26 08:53:19 UTC 2018
neutron_ovs_agent

Logs for 2 problem when openvswich doesn't restart :

[root@compute-2 heat-admin]# tail -f  /var/log/containers/neutron/metadata-agent.log
2018-11-26 08:51:10.883 8224 INFO eventlet.wsgi.server [-] 10.2.0.18,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200  len: 139 time: 0.1934390
2018-11-26 08:51:10.968 8223 INFO eventlet.wsgi.server [-] 10.3.0.25,<local> "GET /2009-04-04/meta-data/placement/availability-zone HTTP/1.1" status: 200  len: 139 time: 0.1648369
2018-11-26 09:11:20.883 8224 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed
2018-11-26 09:11:34.307 7137 ERROR oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:35.323 7137 INFO oslo.messaging._drivers.impl_rabbit [-] [357cec88-105c-4f2b-b26c-70ae3864ec0f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50096.
2018-11-26 09:11:43.938 8223 ERROR oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] AMQP server controller-1.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:44.955 8223 INFO oslo.messaging._drivers.impl_rabbit [-] [24405812-662e-4c40-b834-37a07d80366f] Reconnected to AMQP server on controller-1.internalapi.localdomain:5672 via [amqp] client with port 37994.
2018-11-26 09:11:45.218 8224 ERROR oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] AMQP server controller-2.internalapi.localdomain:5672 closed the connection. Check login credentials: Socket closed: IOError: Socket closed
2018-11-26 09:11:46.235 8224 INFO oslo.messaging._drivers.impl_rabbit [-] [7bf56d8a-afcf-4b87-b2dd-c865c2faf08f] Reconnected to AMQP server on controller-2.internalapi.localdomain:5672 via [amqp] client with port 50116.
2018-11-26 09:11:59.117 8223 WARNING oslo.messaging._drivers.impl_rabbit [-] Unexpected error during heartbeart thread processing, retrying...: IOError: Socket closed

vi /var/log/containers/neutron/openvswitch-agent.log

2018-11-26 14:23:44.338 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     raise RuntimeError(m)
2018-11-26 14:23:44.338 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: Switch connection timeout
2018-11-26 14:23:44.338 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int
2018-11-26 14:23:44.339 28480 WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] OVS is dead. OVSNeutronAgent will keep running and checking OVS status periodically.
2018-11-26 14:23:44.340 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Agent rpc_loop - iteration:623 completed. Processed ports statistics: {'regular': {'updated': 0, 'added': 0, 'removed': 0}}. Elapsed:30.020 loop_count_and_wait /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1875
2018-11-26 14:23:44.340 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Loop iteration exceeded interval (2 vs. 30.0197079182)! loop_count_and_wait /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1882
2018-11-26 14:23:44.340 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Agent rpc_loop - iteration:624 started rpc_loop /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2086
2018-11-26 14:24:14.353 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.ofswitch [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Switch connection timeout
2018-11-26 14:24:14.354 28480 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): DbGetCommand(column=datapath_id, table=Bridge, record=br-int) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2018-11-26 14:24:14.355 28480 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Failed to communicate with the switch: RuntimeError: Switch connection timeout
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int Traceback (most recent call last):
2018-11-26 14:24:14.355 28480 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-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     flows = self.dump_flows(constants.CANARY_TABLE)
2018-11-26 14:24:14.355 28480 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 156, in dump_flows
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     (dp, ofp, ofpp) = self._get_dp()
2018-11-26 14:24:14.355 28480 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/ovs_bridge.py", line 69, in _get_dp
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     self._cached_dpid = new_dpid
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     self.force_reraise()
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     six.reraise(self.type_, self.value, self.tb)
2018-11-26 14:24:14.355 28480 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/ovs_bridge.py", line 52, in _get_dp
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     dp = self._get_dp_by_dpid(self._cached_dpid)
2018-11-26 14:24:14.355 28480 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 79, in _get_dp_by_dpid
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int     raise RuntimeError(m)
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int RuntimeError: Switch connection timeout
2018-11-26 14:24:14.355 28480 ERROR neutron.plugins.ml2.drivers.openvswitch.agent.openflow.native.br_int
2018-11-26 14:24:14.356 28480 WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] OVS is dead. OVSNeutronAgent will keep running and checking OVS status periodically.
2018-11-26 14:24:14.356 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Agent rpc_loop - iteration:624 completed. Processed ports statistics: {'regular': {'updated': 0, 'added': 0, 'removed': 0}}. Elapsed:30.016 loop_count_and_wait /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1875
2018-11-26 14:24:14.357 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Loop iteration exceeded interval (2 vs. 30.0161988735)! loop_count_and_wait /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1882
2018-11-26 14:24:14.357 28480 DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [req-cb6bf194-1ceb-415b-aecc-3ba950053b37 - - - - -] Agent rpc_loop - iteration:625 started rpc_loop /usr/lib/python2.7/site-packages/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2086

Revision history for this message

Slawek Kaplonski (slaweq) wrote on 2018-11-28:

So I can confirm that this issue happens with l2pop mechanism driver and neutron-ovs-agent - it didn't configure properly open flow rules in br-tun thus private vxlan network didn't work - restart of neutron-ovs-agent fixed this.

I think that there is bug in L2pop mechanism driver: after ovs-vswitchd is restarted, it should reconfigure all fdb flows in the same way as it is done when neutron-ovs-agent is restarted but l2 mech_driver don't send all fdb flows to agent as this agent wasn't just restarted.

Slawek Kaplonski (slaweq) on 2018-11-28

Changed in neutron:
status:	Incomplete → Confirmed
importance:	Undecided → Medium

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-11-28: Related fix proposed to neutron (master)

Related fix proposed to branch: master
Review: https://review.openstack.org/620708

Slawek Kaplonski (slaweq) on 2018-11-28

Changed in neutron:
assignee:	nobody → Slawek Kaplonski (slaweq)
status:	Confirmed → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-07: Fix merged to neutron (master)

Reviewed: https://review.openstack.org/620708
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=ae031d18866a9e3652f4fc122f120915209a7b29
Submitter: Zuul
Branch: master

commit ae031d18866a9e3652f4fc122f120915209a7b29
Author: Slawek Kaplonski <email address hidden>
Date: Wed Nov 28 22:42:18 2018 +0100

Force all fdb entries update after ovs-vswitchd restart

    When ovs-vswitchd process is restarted neutron-ovs-agent will
    handle it and reconfigure all ports and openflows in bridges.
    Unfortunatelly when tunnel networks are used together with
    L2pop mechanism driver, this driver will not notice that agent
    lost all openflow config and will not send all fdb entries which
    should be added on host.

    In such case L2pop mechanism driver should behave in same way like
    when neutron-ovs-agent is restarted and send all fdb_entries to
    agent.

    This patch adds "simulate" of agent start flag when ovs_restart is
    handled thus neutron-server will send all fdb_entries to agent and
    tunnels openflow rules can be reconfigured properly.

Change-Id: I5f1471e20bbad90c4cdcbc6c06d3a4412db55b2a
Closes-bug: #1804842

Changed in neutron:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-07: Fix proposed to neutron (stable/rocky)

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/623499

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-07: Fix proposed to neutron (stable/queens)

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/623502

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-07: Fix proposed to neutron (stable/pike)

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/623503

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-08: Fix merged to neutron (stable/rocky)

#10

Reviewed: https://review.openstack.org/623499
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=ae2ef681403d1f103170ea70df1010f006244752
Submitter: Zuul
Branch: stable/rocky

commit ae2ef681403d1f103170ea70df1010f006244752
Author: Slawek Kaplonski <email address hidden>
Date: Wed Nov 28 22:42:18 2018 +0100

Force all fdb entries update after ovs-vswitchd restart

    In such case L2pop mechanism driver should behave in same way like
    when neutron-ovs-agent is restarted and send all fdb_entries to
    agent.

    This patch adds "simulate" of agent start flag when ovs_restart is
    handled thus neutron-server will send all fdb_entries to agent and
    tunnels openflow rules can be reconfigured properly.

    Change-Id: I5f1471e20bbad90c4cdcbc6c06d3a4412db55b2a
    Closes-bug: #1804842
    (cherry picked from commit ae031d18866a9e3652f4fc122f120915209a7b29)

tags:

added: in-stable-rocky

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-08: Fix merged to neutron (stable/pike)

#11

Reviewed: https://review.openstack.org/623503
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=fccc786fd572e4ce3bfd421ac3b1da7e7f31480b
Submitter: Zuul
Branch: stable/pike

commit fccc786fd572e4ce3bfd421ac3b1da7e7f31480b
Author: Slawek Kaplonski <email address hidden>
Date: Wed Nov 28 22:42:18 2018 +0100

Force all fdb entries update after ovs-vswitchd restart

    In such case L2pop mechanism driver should behave in same way like
    when neutron-ovs-agent is restarted and send all fdb_entries to
    agent.

    This patch adds "simulate" of agent start flag when ovs_restart is
    handled thus neutron-server will send all fdb_entries to agent and
    tunnels openflow rules can be reconfigured properly.

    Change-Id: I5f1471e20bbad90c4cdcbc6c06d3a4412db55b2a
    Closes-bug: #1804842
    (cherry picked from commit ae031d18866a9e3652f4fc122f120915209a7b29)

tags:

added: in-stable-pike

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-09: Fix merged to neutron (stable/queens)

#12

Reviewed: https://review.openstack.org/623502
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=dd6a52529e483829e48e2ed62d10bb98307fd3c9
Submitter: Zuul
Branch: stable/queens

commit dd6a52529e483829e48e2ed62d10bb98307fd3c9
Author: Slawek Kaplonski <email address hidden>
Date: Wed Nov 28 22:42:18 2018 +0100

Force all fdb entries update after ovs-vswitchd restart

    In such case L2pop mechanism driver should behave in same way like
    when neutron-ovs-agent is restarted and send all fdb_entries to
    agent.

    This patch adds "simulate" of agent start flag when ovs_restart is
    handled thus neutron-server will send all fdb_entries to agent and
    tunnels openflow rules can be reconfigured properly.

    Change-Id: I5f1471e20bbad90c4cdcbc6c06d3a4412db55b2a
    Closes-bug: #1804842
    (cherry picked from commit ae031d18866a9e3652f4fc122f120915209a7b29)

tags:

added: in-stable-queens

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-13: Fix proposed to neutron (stable/ocata)

#13

Fix proposed to branch: stable/ocata
Review: https://review.openstack.org/625081

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-21: Fix included in openstack/neutron 14.0.0.0b1

#14

This issue was fixed in the openstack/neutron 14.0.0.0b1 development milestone.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-01-31: Fix merged to neutron (stable/ocata)

#15

Reviewed: https://review.openstack.org/625081
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=de6bca3ed184a50580689374d789302193cff5e0
Submitter: Zuul
Branch: stable/ocata

commit de6bca3ed184a50580689374d789302193cff5e0
Author: Slawek Kaplonski <email address hidden>
Date: Wed Nov 28 22:42:18 2018 +0100

Force all fdb entries update after ovs-vswitchd restart

    In such case L2pop mechanism driver should behave in same way like
    when neutron-ovs-agent is restarted and send all fdb_entries to
    agent.

    This patch adds "simulate" of agent start flag when ovs_restart is
    handled thus neutron-server will send all fdb_entries to agent and
    tunnels openflow rules can be reconfigured properly.

    Change-Id: I5f1471e20bbad90c4cdcbc6c06d3a4412db55b2a
    Closes-bug: #1804842
    (cherry picked from commit ae031d18866a9e3652f4fc122f120915209a7b29)
    (cherry picked from commit dd6a52529e483829e48e2ed62d10bb98307fd3c9)