yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1780453] [NEW] openvswitch-agent doesn't try to rebind "binding_failed" ports on startup anymore

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Ralf Haferkamp <1780453@xxxxxxxxxxxxxxxxxx>
Date: Fri, 06 Jul 2018 14:59:22 -0000
Reply-to: Bug 1780453 <1780453@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When ports are created while the openvswitch agent is they're ending up
with "binding:vif_type=binding_failed". In the past upon the next start
of the agent it picked up those ports and would retry to bind them at
least once.

However, currently that is not happening anymore. The agent just logs a
message about the port not being bound. This is from the ovs-agent's log
directly after startup (9cdbb5cb-6e93-4043-bca9-b063cd43626d being the
port id of the "binding_failed" port):


Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Agent rpc_loop - iteration:0 - port information retrieved. Elapsed:0.045 {{(pid=24189) rpc_loop /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2086}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Starting to process devices in:{'current': set([u'9cdbb5cb-6e93-4043-bca9-b063cd43626d']), 'removed': set([]), 'added': set([u'9cdbb5cb-6e93-4043-bca9-b063cd43626d'])} {{(pid=24189) rpc_loop /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2093}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.api.rpc.handlers.resources_rpc [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] neutron.api.rpc.handlers.resources_rpc.ResourcesPullRpcApi method bulk_pull called with arguments (<neutron_lib.context.Context object at 0x7f8143f801d0>, 'Port') {'filter_kwargs': {'id': (u'9cdbb5cb-6e93-4043-bca9-b063cd43626d',)}} {{(pid=24189) wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.agent.resource_cache [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Received new resource Port: Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],created_at=2018-07-06T14:54:09Z,data_plane_status=<?>,description='',device_id='dhcp04771cbe-437e-5f2c-860d-465c2ee070fb-90f6f6f9-8fe5-4865-9550-39189780de7f',device_owner='network:dhcp',dhcp_options=[],distributed_bindings=[],dns=None,fixed_ips=[IPAllocation,IPAllocation],id=9cdbb5cb-6e93-4043-bca9-b063cd43626d,mac_address=fa:16:3e:b4:65:ba,name='',network_id=90f6f6f9-8fe5-4865-9550-39189780de7f,project_id='b5f8567fc10d4bebaf633e24afb353af',qos_policy_id=None,revision_number=2,security=PortSecurity(9cdbb5cb-6e93-4043-bca9-b063cd43626d),security_group_ids=set([]),status='DOWN',updated_at=2018-07-06T14:54:11Z) {{(pid=24189) record_resource_update /opt/stack/neutron/neutron/agent/resource_cache.py:187}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron_lib.callbacks.manager [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Notify callbacks ['neutron.api.rpc.handlers.securitygroups_rpc.SecurityGroupServerAPIShim._handle_sg_member_update-8322652', 'neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent.OVSPluginApi._legacy_notifier-8205701'] for Port, after_update {{(pid=24189) _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.agent.resource_cache [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] 1 resources returned for queries set([('Port', ('id', (u'9cdbb5cb-6e93-4043-bca9-b063cd43626d',)))]) {{(pid=24189) _flood_cache_for_query /opt/stack/neutron/neutron/agent/resource_cache.py:85}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: WARNING neutron.agent.rpc [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Device Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],created_at=2018-07-06T14:54:09Z,data_plane_status=<?>,description='',device_id='dhcp04771cbe-437e-5f2c-860d-465c2ee070fb-90f6f6f9-8fe5-4865-9550-39189780de7f',device_owner='network:dhcp',dhcp_options=[],distributed_bindings=[],dns=None,fixed_ips=[IPAllocation,IPAllocation],id=9cdbb5cb-6e93-4043-bca9-b063cd43626d,mac_address=fa:16:3e:b4:65:ba,name='',network_id=90f6f6f9-8fe5-4865-9550-39189780de7f,project_id='b5f8567fc10d4bebaf633e24afb353af',qos_policy_id=None,revision_number=2,security=PortSecurity(9cdbb5cb-6e93-4043-bca9-b063cd43626d),security_group_ids=set([]),status='DOWN',updated_at=2018-07-06T14:54:11Z) is not bound.
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): ListPortsCommand(bridge=br-int) {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): DbListCommand(if_exists=True, records=[u'tap9cdbb5cb-6e', u'patch-tun', u'int-br-ex'], table=Interface, columns=['name', 'external_ids', 'ofport'], row=False) {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Processing port: 9cdbb5cb-6e93-4043-bca9-b063cd43626d {{(pid=24189) treat_devices_added_or_updated /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1527}}
Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Device 9cdbb5cb-6e93-4043-bca9-b063cd43626d not defined on plugin or binding failed

** 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/1780453

Title:
  openvswitch-agent doesn't try to rebind "binding_failed" ports on
  startup anymore

Status in neutron:
  New

Bug description:
  When ports are created while the openvswitch agent is they're ending
  up with "binding:vif_type=binding_failed". In the past upon the next
  start of the agent it picked up those ports and would retry to bind
  them at least once.

  However, currently that is not happening anymore. The agent just logs
  a message about the port not being bound. This is from the ovs-agent's
  log directly after startup (9cdbb5cb-6e93-4043-bca9-b063cd43626d being
  the port id of the "binding_failed" port):

  
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Agent rpc_loop - iteration:0 - port information retrieved. Elapsed:0.045 {{(pid=24189) rpc_loop /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2086}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Starting to process devices in:{'current': set([u'9cdbb5cb-6e93-4043-bca9-b063cd43626d']), 'removed': set([]), 'added': set([u'9cdbb5cb-6e93-4043-bca9-b063cd43626d'])} {{(pid=24189) rpc_loop /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:2093}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.api.rpc.handlers.resources_rpc [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] neutron.api.rpc.handlers.resources_rpc.ResourcesPullRpcApi method bulk_pull called with arguments (<neutron_lib.context.Context object at 0x7f8143f801d0>, 'Port') {'filter_kwargs': {'id': (u'9cdbb5cb-6e93-4043-bca9-b063cd43626d',)}} {{(pid=24189) wrapper /usr/lib/python2.7/site-packages/oslo_log/helpers.py:66}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.agent.resource_cache [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Received new resource Port: Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],created_at=2018-07-06T14:54:09Z,data_plane_status=<?>,description='',device_id='dhcp04771cbe-437e-5f2c-860d-465c2ee070fb-90f6f6f9-8fe5-4865-9550-39189780de7f',device_owner='network:dhcp',dhcp_options=[],distributed_bindings=[],dns=None,fixed_ips=[IPAllocation,IPAllocation],id=9cdbb5cb-6e93-4043-bca9-b063cd43626d,mac_address=fa:16:3e:b4:65:ba,name='',network_id=90f6f6f9-8fe5-4865-9550-39189780de7f,project_id='b5f8567fc10d4bebaf633e24afb353af',qos_policy_id=None,revision_number=2,security=PortSecurity(9cdbb5cb-6e93-4043-bca9-b063cd43626d),security_group_ids=set([]),status='DOWN',updated_at=2018-07-06T14:54:11Z) {{(pid=24189) record_resource_update /opt/stack/neutron/neutron/agent/resource_cache.py:187}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron_lib.callbacks.manager [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Notify callbacks ['neutron.api.rpc.handlers.securitygroups_rpc.SecurityGroupServerAPIShim._handle_sg_member_update-8322652', 'neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent.OVSPluginApi._legacy_notifier-8205701'] for Port, after_update {{(pid=24189) _notify_loop /usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py:193}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.agent.resource_cache [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] 1 resources returned for queries set([('Port', ('id', (u'9cdbb5cb-6e93-4043-bca9-b063cd43626d',)))]) {{(pid=24189) _flood_cache_for_query /opt/stack/neutron/neutron/agent/resource_cache.py:85}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: WARNING neutron.agent.rpc [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Device Port(admin_state_up=True,allowed_address_pairs=[],binding=PortBinding,binding_levels=[],created_at=2018-07-06T14:54:09Z,data_plane_status=<?>,description='',device_id='dhcp04771cbe-437e-5f2c-860d-465c2ee070fb-90f6f6f9-8fe5-4865-9550-39189780de7f',device_owner='network:dhcp',dhcp_options=[],distributed_bindings=[],dns=None,fixed_ips=[IPAllocation,IPAllocation],id=9cdbb5cb-6e93-4043-bca9-b063cd43626d,mac_address=fa:16:3e:b4:65:ba,name='',network_id=90f6f6f9-8fe5-4865-9550-39189780de7f,project_id='b5f8567fc10d4bebaf633e24afb353af',qos_policy_id=None,revision_number=2,security=PortSecurity(9cdbb5cb-6e93-4043-bca9-b063cd43626d),security_group_ids=set([]),status='DOWN',updated_at=2018-07-06T14:54:11Z) is not bound.
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): ListPortsCommand(bridge=br-int) {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): DbListCommand(if_exists=True, records=[u'tap9cdbb5cb-6e', u'patch-tun', u'int-br-ex'], table=Interface, columns=['name', 'external_ids', 'ofport'], row=False) {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=24189) do_commit /usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:121}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Processing port: 9cdbb5cb-6e93-4043-bca9-b063cd43626d {{(pid=24189) treat_devices_added_or_updated /opt/stack/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1527}}
  Jul 06 14:54:50 net1 neutron-openvswitch-agent[24189]: WARNING neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-21d4d33a-43f9-4100-a452-3ca6aa62b9e3 None None] Device 9cdbb5cb-6e93-4043-bca9-b063cd43626d not defined on plugin or binding failed

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

[Bug 1780453] Re: openvswitch-agent doesn't try to rebind "binding_failed" ports on startup anymore
From: Slawek Kaplonski, 2020-07-03