yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1750383] [NEW] Dynamic routing: Error logged during speaker removal

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: "Dr. Jens Harbott" <j.harbott@xxxxxxxx>
Date: Mon, 19 Feb 2018 14:22:20 -0000
Reply-to: Bug 1750383 <1750383@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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.

** Affects: neutron
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1750383

Title:
  Dynamic routing: Error logged during speaker removal

Status in neutron:
  New

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1750383/+subscriptions