← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #62799

[Bug 1677742] [NEW] Missing Binary Commands don't log in a sane way

  Thread Previous • Date Previous • • Thread Next 
Public bug reported:

When running neutron in an environment with a missing binary command run
by a linux agent the failure mode is far from clear. For example:

http://paste.openstack.org/show/604877/


Is what was logged on my system when I didn't have ipset installed. It's not clear at all from this error message or stack trace that was the cause of failure. The only way I was able to figure this out was to switch the default rootwrap-daemon config file to DEBUG level and use syslog to actually see the missing executable error message.

You shouldn't need to modify the default log levels to see the cause of
a fatal error like a missing binary command.

** Affects: neutron
     Importance: Undecided
         Status: New

** Description changed:

  When running neutron in an environment with a missing binary command run
  by a linux agent the failure mode is far from clear. For example:
  
  http://paste.openstack.org/show/604877/
  
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent [req-8c98874d-5436-4912-9db5-f675bfe4df5e - - - - -] Error in agent loop. Devices info: {'current': set(['tap0ab3c3ba-09']), 'timestamps': {'tap0ab3c3ba-09': 9}, 'removed': set([]), 'added': set(['tap0ab3c3ba-09']), 'updated': set([])}
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent Traceback (most recent call last):
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/plugins/ml2/drivers/agent/_common_agent.py", line 453, in daemon_loop
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     sync = self.process_network_devices(device_info)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 153, in wrapper
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     return f(*args, **kwargs)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/plugins/ml2/drivers/agent/_common_agent.py", line 203, in process_network_devices
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     device_info.get('updated'))
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 277, in setup_port_filters
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self.prepare_devices_filter(new_devices)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 131, in decorated_function
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     *args, **kwargs)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 139, in prepare_devices_filter
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._apply_port_filter(device_ids)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 157, in _apply_port_filter
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     security_groups, security_group_member_ips)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 173, in _update_security_group_info
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     remote_sg_id, member_ips)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/iptables_firewall.py", line 163, in update_security_group_members
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._update_ipset_members(sg_id, sg_members)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/iptables_firewall.py", line 169, in _update_ipset_members
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     sg_id, ip_version, current_ips)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/ipset_manager.py", line 83, in set_members
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self.set_members_mutate(set_name, ethertype, member_ips)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     return f(*args, **kwargs)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/ipset_manager.py", line 93, in set_members_mutate
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._create_set(set_name, ethertype)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/ipset_manager.py", line 139, in _create_set
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._apply(cmd)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/ipset_manager.py", line 149, in _apply
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     check_exit_code=fail_on_errors)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/utils.py", line 128, in execute
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     execute_rootwrap_daemon(cmd, process_input, addl_env))
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/neutron/agent/linux/utils.py", line 115, in execute_rootwrap_daemon
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     return client.execute(cmd, process_input)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/local/lib/python2.7/dist-packages/oslo_rootwrap/client.py", line 129, in execute
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     res = proxy.run_one_command(cmd, stdin)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "<string>", line 2, in run_one_command
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/multiprocessing/managers.py", line 774, in _callmethod
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent     raise convert_to_error(kind, result)
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent RemoteError:
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent ---------------------------------------------------------------------------
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent Unserializable message: ('#ERROR', ValueError('I/O operation on closed file',))
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent ---------------------------------------------------------------------------
- neutron-linuxbridge-agent[4158]: 2017-03-30 11:57:05.182 4158 ERROR neutron.plugins.ml2.drivers.agent._common_agent
  
- Is what was logged on my system when I didn't have ipset installed. It's
- not clear at all from this error message or stack trace that was the
- cause of failure. The only way I was able to figure this out was to
- switch the default rootwrap-daemon config file to DEBUG level and use
- syslog to actually see the missing executable error message.
+ Is what was logged on my system when I didn't have ipset installed. It's not clear at all from this error message or stack trace that was the cause of failure. The only way I was able to figure this out was to switch the default rootwrap-daemon config file to DEBUG level and use syslog to actually see the missing executable error message.
  
  You shouldn't need to modify the default log levels to see the cause of
  a fatal error like a missing binary command.

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

Title:
  Missing Binary Commands don't log in a sane way

Status in neutron:
  New

Bug description:
  When running neutron in an environment with a missing binary command
  run by a linux agent the failure mode is far from clear. For example:

  http://paste.openstack.org/show/604877/

  
  Is what was logged on my system when I didn't have ipset installed. It's not clear at all from this error message or stack trace that was the cause of failure. The only way I was able to figure this out was to switch the default rootwrap-daemon config file to DEBUG level and use syslog to actually see the missing executable error message.

  You shouldn't need to modify the default log levels to see the cause
  of a fatal error like a missing binary command.

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

Follow ups

  Thread Previous • Date Previous • • Thread Next