ansible-test - add ssh debugging logging (#75374)

changelogs/fragments/ansible-test-add-ssh-debug-logging.yml

@@ -0,0 +1,2 @@
+minor_changes:
+  - ansible-test - display recent ``ssh`` debug logs after connection failures (https://github.com/ansible/ansible/pull/75374)

test/lib/ansible_test/_internal/manage_ci.py

@@ -2,6 +2,7 @@
 from __future__ import (absolute_import, division, print_function)
 __metaclass__ = type
 
+import functools
 import os
 import tempfile
 import time
@@ -15,6 +16,7 @@ from .io import (
 from .util import (
     SubprocessError,
     ApplicationError,
+    Display,
     cmd_quote,
     display,
     ANSIBLE_TEST_DATA_ROOT,
@@ -340,12 +342,45 @@ class ManagePosixCI:
         if not data:
             options.append('-tt')
 
-        return run_command(self.core_ci.args,
-                           ['ssh'] + self.ssh_args +
-                           options +
-                           ['-p', str(self.core_ci.connection.port),
-                            '%s@%s' % (self.core_ci.connection.username, self.core_ci.connection.hostname)] +
-                           self.become + [command], capture=capture, data=data)
+        # Capture SSH debug logs
+        with tempfile.NamedTemporaryFile(prefix='ansible-test-ssh-debug-', suffix='.log') as ssh_logfile:
+            options.extend(['-vvv', '-E', ssh_logfile.name])
+
+            return run_command(self.core_ci.args,
+                               ['ssh'] + self.ssh_args +
+                               options +
+                               ['-p', str(self.core_ci.connection.port),
+                                '%s@%s' % (self.core_ci.connection.username, self.core_ci.connection.hostname)] +
+                               self.become + [command], capture=capture, data=data,
+                               error_callback=functools.partial(self.capture_log_details, ssh_logfile.name))
+
+    def capture_log_details(self, path, ex):  # type: (str, SubprocessError) -> None
+        """Reads ssh log file and returns relevant error."""
+        if ex.status != 255:
+            return
+
+        markers = [
+            'debug1: Connection Established',
+            'debug1: Authentication successful',
+            'debug1: Entering interactive session',
+            'debug1: Sending command',
+            'debug2: PTY allocation request accepted',
+            'debug2: exec request accepted',
+        ]
+
+        file_contents = read_text_file(path)
+        messages = []
+
+        for line in reversed(file_contents.splitlines()):
+            messages.append(line)
+
+            if any(line.startswith(marker) for marker in markers):
+                break
+
+        message = '\n'.join(reversed(messages))
+
+        ex.message += '>>> SSH Debug Output\n'
+        ex.message += '%s%s\n' % (message.strip(), Display.clear)
 
     def scp(self, src, dst):
         """

test/lib/ansible_test/_internal/util.py

@@ -269,7 +269,7 @@ def generate_pip_command(python):
 
 
 def raw_command(cmd, capture=False, env=None, data=None, cwd=None, explain=False, stdin=None, stdout=None,
-                cmd_verbosity=1, str_errors='strict'):
+                cmd_verbosity=1, str_errors='strict', error_callback=None):
     """
     :type cmd: collections.Iterable[str]
     :type capture: bool
@@ -281,6 +281,7 @@ def raw_command(cmd, capture=False, env=None, data=None, cwd=None, explain=False
     :type stdout: file | None
     :type cmd_verbosity: int
     :type str_errors: str
+    :type error_callback: t.Callable[[SubprocessError], None]
     :rtype: str | None, str | None
     """
     if not cwd:
@@ -361,7 +362,7 @@ def raw_command(cmd, capture=False, env=None, data=None, cwd=None, explain=False
     if status == 0:
         return stdout_text, stderr_text
 
-    raise SubprocessError(cmd, status, stdout_text, stderr_text, runtime)
+    raise SubprocessError(cmd, status, stdout_text, stderr_text, runtime, error_callback)
 
 
 def common_environment():
@@ -670,13 +671,14 @@ class ApplicationWarning(Exception):
 
 class SubprocessError(ApplicationError):
     """Error resulting from failed subprocess execution."""
-    def __init__(self, cmd, status=0, stdout=None, stderr=None, runtime=None):
+    def __init__(self, cmd, status=0, stdout=None, stderr=None, runtime=None, error_callback=None):
         """
         :type cmd: list[str]
         :type status: int
         :type stdout: str | None
         :type stderr: str | None
         :type runtime: float | None
+        :type error_callback: t.Optional[t.Callable[[SubprocessError], None]]
         """
         message = 'Command "%s" returned exit status %s.\n' % (' '.join(cmd_quote(c) for c in cmd), status)
 
@@ -688,10 +690,6 @@ class SubprocessError(ApplicationError):
             message += '>>> Standard Output\n'
             message += '%s%s\n' % (stdout.strip(), Display.clear)
 
-        message = message.strip()
-
-        super(SubprocessError, self).__init__(message)
-
         self.cmd = cmd
         self.message = message
         self.status = status
@@ -699,6 +697,13 @@ class SubprocessError(ApplicationError):
         self.stderr = stderr
         self.runtime = runtime
 
+        if error_callback:
+            error_callback(self)
+
+        self.message = self.message.strip()
+
+        super(SubprocessError, self).__init__(self.message)
+
 
 class MissingEnvironmentVariable(ApplicationError):
     """Error caused by missing environment variable."""

test/lib/ansible_test/_internal/util_common.py

@@ -31,6 +31,7 @@ from .util import (
     ANSIBLE_TEST_DATA_ROOT,
     ApplicationError,
     cmd_quote,
+    SubprocessError,
 )
 
 from .io import (
@@ -457,7 +458,7 @@ def resolve_csharp_ps_util(import_name, path):
 
 
 def run_command(args, cmd, capture=False, env=None, data=None, cwd=None, always=False, stdin=None, stdout=None,
-                cmd_verbosity=1, str_errors='strict'):
+                cmd_verbosity=1, str_errors='strict', error_callback=None):
     """
     :type args: CommonConfig
     :type cmd: collections.Iterable[str]
@@ -470,8 +471,9 @@ def run_command(args, cmd, capture=False, env=None, data=None, cwd=None, always=
     :type stdout: file | None
     :type cmd_verbosity: int
     :type str_errors: str
+    :type error_callback: t.Callable[[SubprocessError], None]
     :rtype: str | None, str | None
     """
     explain = args.explain and not always
     return raw_command(cmd, capture=capture, env=env, data=data, cwd=cwd, explain=explain, stdin=stdin, stdout=stdout,
-                       cmd_verbosity=cmd_verbosity, str_errors=str_errors)
+                       cmd_verbosity=cmd_verbosity, str_errors=str_errors, error_callback=error_callback)