SSH driver failure logging does not contain actual error

[Clint Byrum]

Seen in a CI failure for TripleO, this doesn't explain what broke:

Oct 28 22:42:51 ubuntu ironic-conductor: 2014-10-28 22:42:51.592 3914 WARNING ironic.conductor.utils [-] Not going to change_node_power_state because current state = requested state = 'power off'.
Oct 28 23:09:09 ubuntu ironic-conductor: 2014-10-28 23:09:09.198 3914 WARNING ironic.conductor.manager [-] Error in deploy of node c3d1daf4-d5f7-4d63-b982-68c0b5ef9224: Failed to execute command via SSH: LC_ALL=C /usr/bin/virsh --connect qemu:///system destroy baremetalbrbm6_1.
Oct 28 23:09:09 ubuntu ironic-conductor: Traceback (most recent call last):
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 455, in fire_timers
Oct 28 23:09:09 ubuntu ironic-conductor: timer()
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/eventlet/hubs/timer.py", line 58, in __call__
Oct 28 23:09:09 ubuntu ironic-conductor: cb(*args, **kw)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/eventlet/greenthread.py", line 212, in main
Oct 28 23:09:09 ubuntu ironic-conductor: result = function(*args, **kwargs)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/manager.py", line 565, in _do_node_deploy
Oct 28 23:09:09 ubuntu ironic-conductor: node.target_provision_state = states.NOSTATE
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/oslo/utils/excutils.py", line 82, in __exit__
Oct 28 23:09:09 ubuntu ironic-conductor: six.reraise(self.type_, self.value, self.tb)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/manager.py", line 554, in _do_node_deploy
Oct 28 23:09:09 ubuntu ironic-conductor: new_state = task.driver.deploy.deploy(task)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/task_manager.py", line 126, in wrapper
Oct 28 23:09:09 ubuntu ironic-conductor: return f(*args, **kwargs)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/drivers/modules/pxe.py", line 349, in deploy
Oct 28 23:09:09 ubuntu ironic-conductor: manager_utils.node_power_action(task, states.REBOOT)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/task_manager.py", line 126, in wrapper
Oct 28 23:09:09 ubuntu ironic-conductor: return f(*args, **kwargs)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/utils.py", line 118, in node_power_action
Oct 28 23:09:09 ubuntu ironic-conductor: "Error: %(error)s") % {'target': target_state, 'error': e}
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/oslo/utils/excutils.py", line 82, in __exit__
Oct 28 23:09:09 ubuntu ironic-conductor: six.reraise(self.type_, self.value, self.tb)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/utils.py", line 113, in node_power_action
Oct 28 23:09:09 ubuntu ironic-conductor: task.driver.power.reboot(task)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/conductor/task_manager.py", line 126, in wrapper
Oct 28 23:09:09 ubuntu ironic-conductor: return f(*args, **kwargs)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/drivers/modules/ssh.py", line 576, in reboot
Oct 28 23:09:09 ubuntu ironic-conductor: _power_off(ssh_obj, driver_info)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/drivers/modules/ssh.py", line 464, in _power_off
Oct 28 23:09:09 ubuntu ironic-conductor: _ssh_execute(ssh_obj, cmd_to_power_off)
Oct 28 23:09:09 ubuntu ironic-conductor: File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/ironic/drivers/modules/ssh.py", line 270, in _ssh_execute
Oct 28 23:09:09 ubuntu ironic-conductor: raise exception.SSHCommandFailed(cmd=cmd_to_exec)
Oct 28 23:09:09 ubuntu ironic-conductor: SSHCommandFailed: Failed to execute command via SSH: LC_ALL=C /usr/bin/virsh --connect qemu:///system destroy baremetalbrbm6_1.
Oct 28 23:10:06 ubuntu ironic-conductor: 2014-10-28 23:10:06.553 3914 WARNING ironic.conductor.manager [-] Error in tear_down of node c3d1daf4-d5f7-4d63-b982-68c0b5ef9224: Failed to execute command via SSH: LC_ALL=C /usr/bin/virsh --connect qemu:///system destroy baremetalbrbm6_1

http://logs.openstack.org/07/92207/4/check-tripleo/check-tripleo-ironic-overcloud-precise-nonha/5e38211/

[Dmitry Tantsur (divius)]

Hi! I've changed the title. I believe what can be fixed right now is to make sure we do log the actual failure with log level ERROR, not DEBUG https://github.com/openstack/ironic/blob/master/ironic/drivers/modules/ssh.py#L268

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/146985

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/146985
Committed: https://git.openstack.org/cgit/openstack/ironic/commit/?id=379727b57ec1a0ba69ef32f9e6cc5aeb4314e301
Submitter: Jenkins
Branch: master

commit 379727b57ec1a0ba69ef32f9e6cc5aeb4314e301
Author: Michael Turek <email address hidden>
Date: Wed Jan 14 16:28:57 2015 +0000

    Raise SSH failure messages to the error level

    Currently SSH failures are only seen at the
    debug level. These messages are important when
    trying to understand failures. This patch brings
    the failure message up to the error level.

    Change-Id: I7566eede4e249c57e8d93b9f1081cc06e3e93c8e
    Closes-bug: 1386978