Merge "Extend remote client to allow for better debugging"
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)