** 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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp