ansible: prevent logs spamming user console on exit.

Closes #331.

ansible_mitogen/process.py

@@ -27,6 +27,7 @@
 # POSSIBILITY OF SUCH DAMAGE.
 
 from __future__ import absolute_import
+import atexit
 import errno
 import logging
 import os
@@ -53,6 +54,23 @@ from mitogen.core import b
 LOG = logging.getLogger(__name__)
 
 
+def clean_shutdown(sock):
+    """
+    Shut the write end of `sock`, causing `recv` in the worker process to wake
+    up with a 0-byte read and initiate mux process exit, then wait for a 0-byte
+    read from the read end, which will occur after the the child closes the
+    descriptor on exit.
+
+    This is done using :mod:`atexit` since Ansible lacks any more sensible hook
+    to run code during exit, and unless some synchronization exists with
+    MuxProcess, debug logs may appear on the user's terminal *after* the prompt
+    has been printed.
+    """
+    sock.shutdown(socket.SHUT_WR)
+    while sock.recv(1):
+        pass
+
+
 class MuxProcess(object):
     """
     Implement a subprocess forked from the Ansible top-level, as a safe place
@@ -112,6 +130,7 @@ class MuxProcess(object):
 
         cls.unix_listener_path = mitogen.unix.make_socket_path()
         cls.worker_sock, cls.child_sock = socket.socketpair()
+        atexit.register(lambda: clean_shutdown(cls.worker_sock))
         mitogen.core.set_cloexec(cls.worker_sock.fileno())
         mitogen.core.set_cloexec(cls.child_sock.fileno())
 

docs/changelog.rst

@@ -27,6 +27,18 @@ Release Notes
     * Compatible with development versions of Ansible post https://github.com/ansible/ansible/pull/41749
 
 
+v0.2.3 (2018-08-??)
+-------------------
+
+Mitogen for Ansible
+~~~~~~~~~~~~~~~~~~~
+
+* `#331 <https://github.com/dw/mitogen/issues/331>`_: fixed known issue: the
+  connection multiplexer subprocess always exits before the main Ansible
+  process exits, ensuring logs generated by it do not overwrite the user's
+  prompt when ``-vvv`` is enabled.
+
+
 v0.2.2 (2018-07-26)
 -------------------
 
@@ -204,11 +216,11 @@ Mitogen for Ansible
   for Message(..., 102, ...), my ID is ...* may be visible. These are due to a
   minor race while initializing logging and can be ignored.
 
-* When running with ``-vvv``, log messages will be printed to the console
-  *after* the Ansible run completes, as connection multiplexer shutdown only
-  begins after Ansible exits. This is due to a lack of suitable shutdown hook
-  in Ansible, and is fairly harmless, albeit cosmetically annoying. A future
-  release may include a solution.
+.. * When running with ``-vvv``, log messages will be printed to the console
+     *after* the Ansible run completes, as connection multiplexer shutdown only
+     begins after Ansible exits. This is due to a lack of suitable shutdown hook
+     in Ansible, and is fairly harmless, albeit cosmetically annoying. A future
+     release may include a solution.
 
 * Performance does not scale linearly with target count. This requires
   significant additional work, as major bottlenecks exist in the surrounding