Extend remote client to allow for better debugging
Extend the ssh remote client so that server details can be passed
in, to enrich debug messages with server details and console log
when available. Add unit test coverage for the exception handling
and logging as well.
Change-Id: I3127e58a9d333df0f55adb2960dc7f26d66c4609
diff --git a/tempest/common/utils/linux/remote_client.py b/tempest/common/utils/linux/remote_client.py
index 3a215a0..3f573b7 100644
--- a/tempest/common/utils/linux/remote_client.py
+++ b/tempest/common/utils/linux/remote_client.py
@@ -12,6 +12,8 @@
import netaddr
import re
+import six
+import sys
import time
from oslo_log import log as logging
@@ -19,6 +21,7 @@
from tempest import config
from tempest import exceptions
from tempest.lib.common import ssh
+from tempest.lib.common.utils import misc as misc_utils
import tempest.lib.exceptions
CONF = config.CONF
@@ -26,16 +29,61 @@
LOG = logging.getLogger(__name__)
+def debug_ssh(function):
+ """Decorator to generate extra debug info in case off SSH failure"""
+ def wrapper(self, *args, **kwargs):
+ try:
+ return function(self, *args, **kwargs)
+ except tempest.lib.exceptions.SSHTimeout:
+ try:
+ original_exception = sys.exc_info()
+ caller = misc_utils.find_test_caller() or "not found"
+ if self.server:
+ msg = 'Caller: %s. Timeout trying to ssh to server %s'
+ LOG.debug(msg, caller, self.server)
+ if self.log_console and self.servers_client:
+ try:
+ msg = 'Console log for server %s: %s'
+ console_log = (
+ self.servers_client.get_console_output(
+ self.server['id'])['output'])
+ LOG.debug(msg, self.server['id'], console_log)
+ except Exception:
+ msg = 'Could not get console_log for server %s'
+ LOG.debug(msg, self.server['id'])
+ # re-raise the original ssh timeout exception
+ six.reraise(*original_exception)
+ finally:
+ # Delete the traceback to avoid circular references
+ _, _, trace = original_exception
+ del trace
+ return wrapper
+
+
class RemoteClient(object):
- def __init__(self, ip_address, username, password=None, pkey=None):
+ def __init__(self, ip_address, username, password=None, pkey=None,
+ server=None, servers_client=None):
+ """Executes commands in a VM over ssh
+
+ :param ip_address: IP address to ssh to
+ :param username: ssh username
+ :param password: ssh password (optional)
+ :param pkey: ssh public key (optional)
+ :param server: server dict, used for debugging purposes
+ :param servers_client: servers client, used for debugging purposes
+ """
+ self.server = server
+ self.servers_client = servers_client
ssh_timeout = CONF.validation.ssh_timeout
connect_timeout = CONF.validation.connect_timeout
+ self.log_console = CONF.compute_feature_enabled.console_output
self.ssh_client = ssh.Client(ip_address, username, password,
ssh_timeout, pkey=pkey,
channel_timeout=connect_timeout)
+ @debug_ssh
def exec_command(self, cmd):
# Shell options below add more clearness on failures,
# path is extended for some non-cirros guest oses (centos7)
@@ -43,6 +91,7 @@
LOG.debug("Remote command: %s" % cmd)
return self.ssh_client.exec_command(cmd)
+ @debug_ssh
def validate_authentication(self):
"""Validate ssh connection and authentication
diff --git a/tempest/tests/common/utils/linux/test_remote_client.py b/tempest/tests/common/utils/linux/test_remote_client.py
index e9146bc..7d625cf 100644
--- a/tempest/tests/common/utils/linux/test_remote_client.py
+++ b/tempest/tests/common/utils/linux/test_remote_client.py
@@ -12,6 +12,7 @@
# License for the specific language governing permissions and limitations
# under the License.
+import fixtures
import time
from oslo_config import cfg
@@ -19,10 +20,39 @@
from tempest.common.utils.linux import remote_client
from tempest import config
+from tempest.lib import exceptions as lib_exc
from tempest.tests import base
from tempest.tests import fake_config
+SERVER = {
+ 'id': 'server_uuid',
+ 'name': 'fake_server',
+ 'status': 'ACTIVE'
+}
+
+BROKEN_SERVER = {
+ 'id': 'broken_server_uuid',
+ 'name': 'broken_server',
+ 'status': 'ERROR'
+}
+
+
+class FakeServersClient(object):
+
+ CONSOLE_OUTPUT = "Console output for %s"
+
+ def get_console_output(self, server_id):
+ status = 'ERROR'
+ for s in SERVER, BROKEN_SERVER:
+ if s['id'] == server_id:
+ status = s['status']
+ if status == 'ERROR':
+ raise lib_exc.BadRequest('Server in ERROR state')
+ else:
+ return dict(output=self.CONSOLE_OUTPUT % server_id)
+
+
class TestRemoteClient(base.TestCase):
def setUp(self):
super(TestRemoteClient, self).setUp()
@@ -155,3 +185,78 @@
self.conn.set_nic_state(nic, "down")
self._assert_exec_called_with(
'sudo ip link set %s down' % nic)
+
+
+class TestRemoteClientWithServer(base.TestCase):
+
+ server = SERVER
+
+ def setUp(self):
+ super(TestRemoteClientWithServer, self).setUp()
+ self.useFixture(fake_config.ConfigFixture())
+ self.patchobject(config, 'TempestConfigPrivate',
+ fake_config.FakePrivate)
+ cfg.CONF.set_default('ip_version_for_ssh', 4, group='validation')
+ cfg.CONF.set_default('network_for_ssh', 'public',
+ group='validation')
+ cfg.CONF.set_default('connect_timeout', 1, group='validation')
+ cfg.CONF.set_default('console_output', True,
+ group='compute-feature-enabled')
+
+ self.conn = remote_client.RemoteClient(
+ '127.0.0.1', 'user', 'pass',
+ server=self.server, servers_client=FakeServersClient())
+ self.useFixture(fixtures.MockPatch(
+ 'tempest.lib.common.ssh.Client._get_ssh_connection',
+ side_effect=lib_exc.SSHTimeout(host='127.0.0.1',
+ user='user',
+ password='pass')))
+ self.log = self.useFixture(fixtures.FakeLogger(
+ name='tempest.common.utils.linux.remote_client',
+ level='DEBUG'))
+
+ def test_validate_debug_ssh_console(self):
+ self.assertRaises(lib_exc.SSHTimeout,
+ self.conn.validate_authentication)
+ msg = 'Caller: %s. Timeout trying to ssh to server %s' % (
+ 'TestRemoteClientWithServer:test_validate_debug_ssh_console',
+ self.server)
+ self.assertIn(msg, self.log.output)
+ self.assertIn('Console output for', self.log.output)
+
+ def test_exec_command_debug_ssh_console(self):
+ self.assertRaises(lib_exc.SSHTimeout,
+ self.conn.exec_command, 'fake command')
+ self.assertIn('fake command', self.log.output)
+ msg = 'Caller: %s. Timeout trying to ssh to server %s' % (
+ 'TestRemoteClientWithServer:test_exec_command_debug_ssh_console',
+ self.server)
+ self.assertIn(msg, self.log.output)
+ self.assertIn('Console output for', self.log.output)
+
+
+class TestRemoteClientWithBrokenServer(TestRemoteClientWithServer):
+
+ server = BROKEN_SERVER
+
+ def test_validate_debug_ssh_console(self):
+ self.assertRaises(lib_exc.SSHTimeout,
+ self.conn.validate_authentication)
+ msg = 'Caller: %s. Timeout trying to ssh to server %s' % (
+ 'TestRemoteClientWithBrokenServer:test_validate_debug_ssh_console',
+ self.server)
+ self.assertIn(msg, self.log.output)
+ msg = 'Could not get console_log for server %s' % self.server['id']
+ self.assertIn(msg, self.log.output)
+
+ def test_exec_command_debug_ssh_console(self):
+ self.assertRaises(lib_exc.SSHTimeout,
+ self.conn.exec_command, 'fake command')
+ self.assertIn('fake command', self.log.output)
+ caller = ":".join(['TestRemoteClientWithBrokenServer',
+ 'test_exec_command_debug_ssh_console'])
+ msg = 'Caller: %s. Timeout trying to ssh to server %s' % (
+ caller, self.server)
+ self.assertIn(msg, self.log.output)
+ msg = 'Could not get console_log for server %s' % self.server['id']
+ self.assertIn(msg, self.log.output)