From b58603c7a4cd9a5750cd09c2ce667b74f6178885 Mon Sep 17 00:00:00 2001 From: David Wilson Date: Fri, 22 Jun 2018 16:30:51 +0100 Subject: [PATCH 1/4] issue #278: ssh: support ssh_debug_level option and log TTY output. Now debug logs may be captured all the way through the connection. --- docs/api.rst | 3 ++- mitogen/parent.py | 15 +++++++++++++-- mitogen/ssh.py | 46 +++++++++++++++++++++++++++++++++++++++++++--- 3 files changed, 58 insertions(+), 6 deletions(-) diff --git a/docs/api.rst b/docs/api.rst index 114f58d0..3df12c0b 100644 --- a/docs/api.rst +++ b/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. diff --git a/mitogen/parent.py b/mitogen/parent.py index 0ebad519..2b2bcd2c 100644 --- a/mitogen/parent.py +++ b/mitogen/parent.py @@ -620,16 +620,27 @@ class TtyLogStream(mitogen.core.BasicStream): self.receive_side = mitogen.core.Side(stream, 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): diff --git a/mitogen/ssh.py b/mitogen/ssh.py index 94e5323a..5e81ff46 100644 --- a/mitogen/ssh.py +++ b/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(): From 04b65020acd3c7cb47d1197a46aa67841a68f60c Mon Sep 17 00:00:00 2001 From: David Wilson Date: Fri, 22 Jun 2018 16:31:55 +0100 Subject: [PATCH 2/4] issue #278: ansible: support mitogen_ssh_debug_level variable. --- ansible_mitogen/connection.py | 6 ++++++ docs/ansible.rst | 2 ++ 2 files changed, 8 insertions(+) diff --git a/ansible_mitogen/connection.py b/ansible_mitogen/connection.py index 6a6f387e..7c3f59c5 100644 --- a/ansible_mitogen/connection.py +++ b/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) diff --git a/docs/ansible.rst b/docs/ansible.rst index be615375..b7502586 100644 --- a/docs/ansible.rst +++ b/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 From 0e958ea177d691482c0731db79f566850b90e484 Mon Sep 17 00:00:00 2001 From: David Wilson Date: Sat, 23 Jun 2018 16:12:52 +0000 Subject: [PATCH 3/4] issue #278: tty logger Side constructed with incorrect Stream Harmless, but produced the wrong log message prefix. --- mitogen/parent.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mitogen/parent.py b/mitogen/parent.py index 2b2bcd2c..899f8955 100644 --- a/mitogen/parent.py +++ b/mitogen/parent.py @@ -617,7 +617,7 @@ 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 = '' From 6d146520778ba28cdeb99386d4a2afc1af68b385 Mon Sep 17 00:00:00 2001 From: David Wilson Date: Sat, 23 Jun 2018 16:17:24 +0000 Subject: [PATCH 4/4] issue #278: tests: fix fakessh. See source comment. This behaviour always existed, but it now seems to be triggered since we started draining the master side input buffer, which someone was prolonging the life of the PTY. --- tests/data/fakessh.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/tests/data/fakessh.py b/tests/data/fakessh.py index 9bcf9571..08a5da3e 100755 --- a/tests/data/fakessh.py +++ b/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))