Dynamic routing: Error logged during speaker removal

[Dr. Jens Harbott]

During normal operations, when a BGP speaker is deleted and being removed from an agent during that operation, an error like this is being logged:

Feb 19 10:25:05.054654 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: INFO bgpspeaker.peer [-] Connection to peer 192.168.10.129 lost, reason: Connection to peer lost: [Errno 9] Bad file descriptor. Resetting retry connect loop: False
Feb 19 10:25:05.054912 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: DEBUG bgpspeaker.signals.base [-] SIGNAL: ('core', 'adj', 'down') emitted with data: {'peer': <ryu.services.protocols.bgp.peer.Peer object at 0x7fd5af3299d0>} {{(pid=30255) emit_signal /usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/signals/base.py:11}}
Feb 19 10:25:05.055034 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: INFO neutron_dynamic_routing.services.bgp.agent.driver.ryu.driver [-] BGP Peer 192.168.10.129 for remote_as=64522 went DOWN.
Feb 19 10:25:05.055144 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: DEBUG bgpspeaker.peer [-] Peer 192.168.10.129 BGP FSM went from Established to Idle {{(pid=30255) bgp_state /usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/peer.py:237}}
Feb 19 10:25:05.055554 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: ERROR bgpspeaker.base [-] Traceback (most recent call last):
Feb 19 10:25:05.055768 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/base.py", line 256, in start
Feb 19 10:25:05.055929 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: self._run(*args, **kwargs)
Feb 19 10:25:05.056106 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", line 275, in _run
Feb 19 10:25:05.056293 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: self._recv_loop()
Feb 19 10:25:05.056519 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", line 571, in _recv_loop
Feb 19 10:25:05.056719 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: self.connection_lost(conn_lost_reason)
Feb 19 10:25:05.056911 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", line 596, in connection_lost
Feb 19 10:25:05.057096 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: self._peer.connection_lost(reason)
Feb 19 10:25:05.057282 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/peer.py", line 2328, in connection_lost
Feb 19 10:25:05.057463 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: self._protocol.stop()
Feb 19 10:25:05.057659 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/speaker.py", line 405, in stop
Feb 19 10:25:05.057835 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: Activity.stop(self)
Feb 19 10:25:05.058019 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: File "/usr/local/lib/python2.7/dist-packages/ryu/services/protocols/bgp/base.py", line 314, in stop
Feb 19 10:25:05.058186 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: raise ActivityException(desc='Cannot call stop when activity is '
Feb 19 10:25:05.058363 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: ActivityException: 100.1 - Cannot call stop when activity is not started or has been stopped already.
Feb 19 10:25:05.058734 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: : ActivityException: 100.1 - Cannot call stop when activity is not started or has been stopped already.
Feb 19 10:25:31.149666 ubuntu-xenial-ovh-bhs1-0002607943 neutron-bgp-dragent[30255]: DEBUG neutron_dynamic_routing.services.bgp.agent.bgp_dragent [None req-590735a1-3669-43e0-8feb-3afa445663d9 None None] Report state task started {{(pid=30255) _report_state /opt/stack/new/neutron-dynamic-routing/neutron_dynamic_routing/services/bgp/agent/bgp_dragent.py:682}}

This is confusing since the operation is finishing successfully, so the expected result is that no error should be seen in the logs.

[Ihar Hrachyshka (ihar-hrachyshka)]

It sounds this bug doesn't affect operations, just an annoying log message. Setting importance to Low.

[Dr. Jens Harbott (j-harbott)]

Actually I traced this back to an issue in ryu, see https://sourceforge.net/p/ryu/mailman/message/36260483/ . A workaround might be to explicitly remove all peers (in the ryu driver) before shutting down the speaker, but I'd be fine with waiting for this to be fixed in ryu, too.

[Brian Haley (brian-haley)]

Can anyone confirm this is still an issue when using os-ken? It has been so long since it was filed and has had no updates. Thanks.