yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1284311] Re: lb-agent: delete_vlan_bridge() logs too many errors

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thierry Carrez <thierry.carrez+lp@xxxxxxxxx>
Date: Thu, 04 Sep 2014 14:04:08 -0000
Reply-to: Bug 1284311 <1284311@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: neutron
       Status: Fix Committed => Fix Released

** Changed in: neutron
    Milestone: None => juno-3

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

Title:
  lb-agent: delete_vlan_bridge() logs too many errors

Status in OpenStack Neutron (virtual network service):
  Fix Released

Bug description:
  https://github.com/openstack/neutron/blob/14cb886809e5cccbf799a0dc2e5b99f31b1ab3be/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py#L419

  There are a few problems with delete_vlan_bridge():
  1. It does not allow for get_interfaces_on_bridge returning None.
  2. It does not wrap a couple of ip link calls in try/except.
  3. It logs at level ERROR, but WARN would be more appropriate.
     The last line in the function logs an error every time a network
     is deleted, as delete_vlan_bridge() always gets called twice: 
     once by daemon_loop() and once by the network_delete() rpc.

  These causes errors and exceptions to be logged which are overstated
  becuase the problems are of no consequence.

  Here is a stacktrace of a race between the rpc and daemon_loop
  threads. In the network_delete() rpc thread, delete_vlan_bridge()
  calls device_exists() which returns True. Then it calls
  get_interfaces_on_bridge() which also calls device_exists() but now it
  returned False because the main green thread running daemon_loop has
  deleted the bridge in the time in between.

  
  2014-02-24 13:14:22.885 6475 DEBUG neutron.agent.linux.utils [-] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:23.165 6475 DEBUG neutron.agent.linux.utils [-] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27']
  Exit code: 0
  Stdout: '156: brqa0fdcdd0-27: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN \n    link/ether 00:00:00:00:00:00 brd ff:ff:ff:ff:ff:ff\n'
  Stderr: '' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:23.167 6475 DEBUG neutron.agent.linux.utils [-] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:23.373 6475 DEBUG neutron.agent.linux.utils [-] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27']
  Exit code: 0
  Stdout: '156: brqa0fdcdd0-27: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN \n    link/ether 00:00:00:00:00:00 brd ff:ff:ff:ff:ff:ff\n'
  Stderr: '' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:23.374 6475 DEBUG neutron.plugins.linuxbridge.agent.linuxbridge_neutron_agent [-] Deleting bridge brqa0fdcdd0-27 delete_vlan_bridge /opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py:440
  2014-02-24 13:14:23.375 6475 DEBUG neutron.agent.linux.utils [-] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'set', 'brqa0fdcdd0-27', 'down'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:23.418 6475 DEBUG neutron.openstack.common.rpc.amqp [-] Making asynchronous cast on q-plugin... cast /opt/stack/neutron/neutron/openstack/common/rpc/amqp.py:583
  2014-02-24 13:14:23.420 6475 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 479398d47cc24de9b03195654ac262b5. _add_unique_id /opt/stack/neutron/neutron/openstack/common/rpc/amqp.py:342
  2014-02-24 13:14:23.548 6475 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'_member_', u'admin'], u'_context_request_id': u'req-143cf938-461f-4c2c-b72b-84f67df9a78e', u'_context_read_deleted': u'no', u'_context_user_name': u'admin', u'_context_project_name': u'admin', u'namespace': None, u'_context_tenant_id': u'e4ead7e65ee94a11b86bd404cb03848d', u'args': {u'network_id': u'a0fdcdd0-27f5-4ef5-bc5c-19537de1fd46'}, u'_context_tenant': u'e4ead7e65ee94a11b86bd404cb03848d', u'_unique_id': u'ad76c8f0bb52408894657236f98ac564', u'_context_is_admin': True, u'version': u'1.1', u'_context_timestamp': u'2014-02-24 13:14:23.460752', u'_context_tenant_name': u'admin', u'_context_user': u'7d0f5cc1d41949188da11301926e3a6a', u'_context_user_id': u'7d0f5cc1d41949188da11301926e3a6a', u'method': u'network_delete', u'_context_project_id': u'e4ead7e65ee94a11b86bd404cb03848d'} _safe_log /opt/stack/neutron/neutron/openstack/common/rpc/common.py:276
  2014-02-24 13:14:23.549 6475 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'admin', 'user_id': u'7d0f5cc1d41949188da11301926e3a6a', 'roles': [u'_member_', u'admin'], 'tenant_id': u'e4ead7e65ee94a11b86bd404cb03848d', 'timestamp': u'2014-02-24 13:14:23.460752', 'is_admin': True, 'read_deleted': u'no', 'request_id': u'req-143cf938-461f-4c2c-b72b-84f67df9a78e', 'tenant_name': u'admin', 'project_id': u'e4ead7e65ee94a11b86bd404cb03848d', 'user_name': u'admin', 'tenant': u'e4ead7e65ee94a11b86bd404cb03848d', 'user': u'7d0f5cc1d41949188da11301926e3a6a'} _safe_log /opt/stack/neutron/neutron/openstack/common/rpc/common.py:276
  2014-02-24 13:14:23.556 6475 DEBUG neutron.plugins.linuxbridge.agent.linuxbridge_neutron_agent [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] network_delete received network_delete /opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py:625
  2014-02-24 13:14:23.561 6475 DEBUG neutron.plugins.linuxbridge.agent.linuxbridge_neutron_agent [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Delete brqa0fdcdd0-27 network_delete /opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py:628
  2014-02-24 13:14:23.563 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:23.725 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'set', 'brqa0fdcdd0-27', 'down']
  Exit code: 0
  Stdout: ''
  Stderr: '' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:23.726 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'brctl', 'delbr', 'brqa0fdcdd0-27'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:24.081 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27']
  Exit code: 0
  Stdout: '156: brqa0fdcdd0-27: <BROADCAST,MULTICAST> mtu 1500 qdisc noqueue state DOWN \n    link/ether 00:00:00:00:00:00 brd ff:ff:ff:ff:ff:ff\n'
  Stderr: '' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:24.082 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Running command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27'] create_process /opt/stack/neutron/neutron/agent/linux/utils.py:48
  2014-02-24 13:14:24.126 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'brctl', 'delbr', 'brqa0fdcdd0-27']
  Exit code: 0
  Stdout: ''
  Stderr: '' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:24.127 6475 DEBUG neutron.plugins.linuxbridge.agent.linuxbridge_neutron_agent [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Done deleting bridge brqa0fdcdd0-27 delete_vlan_bridge /opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py:447
  2014-02-24 13:14:24.128 6475 DEBUG neutron.plugins.linuxbridge.agent.linuxbridge_neutron_agent [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Loop iteration exceeded interval (2 vs. 2.8396191597)! daemon_loop /opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py:976
  2014-02-24 13:14:24.350 6475 DEBUG neutron.agent.linux.utils [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] 
  Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'link', 'show', 'dev', 'brqa0fdcdd0-27']
  Exit code: 1
  Stdout: ''
  Stderr: 'Device "brqa0fdcdd0-27" does not exist.\n' execute /opt/stack/neutron/neutron/agent/linux/utils.py:74
  2014-02-24 13:14:24.351 6475 ERROR neutron.openstack.common.rpc.amqp [req-143cf938-461f-4c2c-b72b-84f67df9a78e None] Exception during message handling
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp Traceback (most recent call last):
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp   File "/opt/stack/neutron/neutron/openstack/common/rpc/amqp.py", line 462, in _process_data
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp     **args)
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp   File "/opt/stack/neutron/neutron/openstack/common/rpc/dispatcher.py", line 172, in dispatch
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp     result = getattr(proxyobj, method)(ctxt, **kwargs)
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp   File "/opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py", line 629, in network_delete
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp     self.agent.br_mgr.delete_vlan_bridge(bridge_name)
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp   File "/opt/stack/neutron/neutron/plugins/linuxbridge/agent/linuxbridge_neutron_agent.py", line 422, in delete_vlan_bridge
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp     for interface in interfaces_on_bridge:
  2014-02-24 13:14:24.351 6475 TRACE neutron.openstack.common.rpc.amqp TypeError: 'NoneType' object is not iterable

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

[Bug 1284311] [NEW] lb-agent: delete_vlan_bridge() logs too many errors
From: Darragh O'Reilly, 2014-02-24