Merge pull request #282 from dw/issue278

Issue278

ansible_mitogen/connection.py

@@ -83,6 +83,7 @@ def _connect_ssh(spec):
             'ssh_path': spec['ssh_executable'],
             'connect_timeout': spec['ansible_ssh_timeout'],
             'ssh_args': spec['ssh_args'],
+            'ssh_debug_level': spec['mitogen_ssh_debug_level'],
         }
     }
 
@@ -260,6 +261,7 @@ def config_from_play_context(transport, inventory_name, connection):
         'mitogen_docker_path': connection.mitogen_docker_path,
         'mitogen_lxc_info_path': connection.mitogen_lxc_info_path,
         'mitogen_machinectl_path': connection.mitogen_machinectl_path,
+        'mitogen_ssh_debug_level': connection.mitogen_ssh_debug_level,
     }
 
 
@@ -334,6 +336,9 @@ class Connection(ansible.plugins.connection.ConnectionBase):
     #: Set to 'mitogen_lxc_info_path' by on_action_run().
     mitogen_machinectl_path = None
 
+    #: Set to 'mitogen_ssh_debug_level' by on_action_run().
+    mitogen_ssh_debug_level = None
+
     #: Set to 'inventory_hostname' by on_action_run().
     inventory_hostname = None
 
@@ -374,6 +379,7 @@ class Connection(ansible.plugins.connection.ConnectionBase):
         self.mitogen_docker_path = task_vars.get('mitogen_docker_path')
         self.mitogen_lxc_info_path = task_vars.get('mitogen_lxc_info_path')
         self.mitogen_machinectl_path = task_vars.get('mitogen_machinectl_path')
+        self.mitogen_ssh_debug_level = task_vars.get('mitogen_ssh_debug_level')
         self.inventory_hostname = task_vars['inventory_hostname']
         self.host_vars = task_vars['hostvars']
         self.close(new_task=True)

docs/ansible.rst

@@ -619,6 +619,8 @@ except connection delegation is supported.
 * ``ansible_ssh_private_key_file``
 * ``ansible_ssh_pass``, ``ansible_password`` (default: assume passwordless)
 * ``ssh_args``, ``ssh_common_args``, ``ssh_extra_args``
+* ``mitogen_ssh_debug_level``: integer between `0..3` indicating the SSH client
+  debug level. Ansible must also be run with '-vvv' to view the output.
 
 
 Debugging

docs/api.rst

@@ -707,7 +707,8 @@ Router Class
             are already compressed, however it has a large effect on every
             remaining message in the otherwise uncompressed stream protocol,
             such as function call arguments and return values.
-
+        :parama int ssh_debug_level:
+            Optional integer `0..3` indicating the SSH client debug level.
         :raises mitogen.ssh.PasswordError:
             A password was requested but none was specified, or the specified
             password was incorrect.

mitogen/parent.py

@@ -617,19 +617,30 @@ class TtyLogStream(mitogen.core.BasicStream):
     """
 
     def __init__(self, tty_fd, stream):
-        self.receive_side = mitogen.core.Side(stream, tty_fd)
+        self.receive_side = mitogen.core.Side(self, tty_fd)
         self.transmit_side = self.receive_side
         self.stream = stream
+        self.buf = ''
 
     def __repr__(self):
-        return 'mitogen.parent.TtyLogStream(%r)' % (self.stream,)
+        return 'mitogen.parent.TtyLogStream(%r)' % (self.stream.name,)
 
     def on_receive(self, broker):
+        """
+        This handler is only called after the stream is registered with the IO
+        loop, the descriptor is manually read/written by _connect_bootstrap()
+        prior to that.
+        """
         buf = self.receive_side.read()
         if not buf:
             return self.on_disconnect(broker)
 
-        LOG.debug('%r.on_receive(): %r', self, buf)
+        self.buf += buf
+        while '\n' in self.buf:
+            lines = self.buf.split('\n')
+            self.buf = lines[-1]
+            for line in lines[:-1]:
+                LOG.debug('%r:  %r', self, line.rstrip())
 
 
 class Stream(mitogen.core.Stream):

mitogen/ssh.py

@@ -43,12 +43,43 @@ import mitogen.parent
 
 LOG = logging.getLogger('mitogen')
 
-PASSWORD_PROMPT = 'password:'
+# sshpass uses 'assword' because it doesn't lowercase the input.
+PASSWORD_PROMPT = 'password'
 PERMDENIED_PROMPT = 'permission denied'
 HOSTKEY_REQ_PROMPT = 'are you sure you want to continue connecting (yes/no)?'
 HOSTKEY_FAIL = 'host key verification failed.'
 
 
+DEBUG_PREFIXES = ('debug1:', 'debug2:', 'debug3:')
+
+
+def _filter_debug(stream, it, buf):
+    while True:
+        if not buf.startswith(DEBUG_PREFIXES):
+            return buf
+        while '\n' in buf:
+            line, _, buf = buf.partition('\n')
+            LOG.debug('%r: received %r', stream, line.rstrip())
+        try:
+            buf += next(it)
+        except StopIteration:
+            return buf
+
+
+def filter_debug(stream, it):
+    """
+    Read line chunks from it, either yielding them directly, or building up and
+    logging individual lines if they look like SSH debug output.
+
+    This contains the mess of dealing with both line-oriented input, and partial
+    lines such as the password prompt.
+    """
+    for chunk in it:
+        chunk = _filter_debug(stream, it, chunk)
+        if chunk:
+            yield chunk
+
+
 class PasswordError(mitogen.core.StreamError):
     pass
 
@@ -62,6 +93,9 @@ class Stream(mitogen.parent.Stream):
     child_is_immediate_subprocess = False
     python_path = 'python2.7'
 
+    #: Number of -v invocations to pass on command line.
+    ssh_debug_level = 0
+
     #: Once connected, points to the corresponding TtyLogStream, allowing it to
     #: be disconnected at the same time this stream is being torn down.
     tty_stream = None
@@ -82,7 +116,8 @@ class Stream(mitogen.parent.Stream):
     def construct(self, hostname, username=None, ssh_path=None, port=None,
                   check_host_keys='enforce', password=None, identity_file=None,
                   compression=True, ssh_args=None, keepalive_enabled=True,
-                  keepalive_count=3, keepalive_interval=15, **kwargs):
+                  keepalive_count=3, keepalive_interval=15,
+                  ssh_debug_level=None, **kwargs):
         super(Stream, self).construct(**kwargs)
         if check_host_keys not in ('accept', 'enforce', 'ignore'):
             raise ValueError(self.check_host_keys_msg)
@@ -101,6 +136,8 @@ class Stream(mitogen.parent.Stream):
             self.ssh_path = ssh_path
         if ssh_args:
             self.ssh_args = ssh_args
+        if ssh_debug_level:
+            self.ssh_debug_level = ssh_debug_level
 
     def on_disconnect(self, broker):
         self.tty_stream.on_disconnect(broker)
@@ -108,6 +145,8 @@ class Stream(mitogen.parent.Stream):
 
     def get_boot_command(self):
         bits = [self.ssh_path]
+        if self.ssh_debug_level:
+            bits += ['-' + ('v' * min(3, self.ssh_debug_level))]
         if self.username:
             bits += ['-l', self.username]
         if self.port is not None:
@@ -179,9 +218,10 @@ class Stream(mitogen.parent.Stream):
             deadline=self.connect_deadline
         )
 
-        for buf in it:
+        for buf in filter_debug(self, it):
             LOG.debug('%r: received %r', self, buf)
             if buf.endswith('EC0\n'):
+                self._router.broker.start_receive(self.tty_stream)
                 self._ec0_received()
                 return
             elif HOSTKEY_REQ_PROMPT in buf.lower():

tests/data/fakessh.py

@@ -3,6 +3,7 @@
 import optparse
 import os
 import shlex
+import subprocess
 import sys
 
 parser = optparse.OptionParser()
@@ -12,6 +13,11 @@ parser.disable_interspersed_args()
 
 opts, args = parser.parse_args(sys.argv[1:])
 args.pop(0)  # hostname
+
+# On Linux the TTY layer appears to begin tearing down a PTY after the last FD
+# for it is closed, causing SIGHUP to be sent to its foreground group. Since
+# the bootstrap overwrites the last such fd (stderr), we can't just exec it
+# directly, we must hold it open just like real SSH would. So use
+# subprocess.call() rather than os.execve() here.
 args = [''.join(shlex.split(s)) for s in args]
-print args
-os.execvp(args[0], args)
+sys.exit(subprocess.call(args))