WIP

.github/workflows/tests.yml

@@ -9,7 +9,7 @@ on:
       - docs-master
 
 env:
-  #ANSIBLE_VERBOSITY: 3
+  ANSIBLE_VERBOSITY: 3
   #MITOGEN_LOG_LEVEL: DEBUG
   MITOGEN_TEST_IMAGE_TEMPLATE: "ghcr.io/mitogen-hq/%(distro)s-test"
 
@@ -24,62 +24,10 @@ jobs:
       fail-fast: false
       matrix:
         include:
-          - name: Ans_27_210
-            tox_env: py27-mode_ansible-ansible2.10
-          - name: Ans_27_4
-            tox_env: py27-mode_ansible-ansible4
-
-          - name: Ans_36_210
-            python_version: '3.6'
-            tox_env: py36-mode_ansible-ansible2.10
-          - name: Ans_36_4
-            python_version: '3.6'
-            tox_env: py36-mode_ansible-ansible4
-
-          - name: Ans_311_210
-            python_version: '3.11'
-            tox_env: py311-mode_ansible-ansible2.10
-          - name: Ans_311_3
-            python_version: '3.11'
-            tox_env: py311-mode_ansible-ansible3
-          - name: Ans_311_4
-            python_version: '3.11'
-            tox_env: py311-mode_ansible-ansible4
-          - name: Ans_311_5
-            python_version: '3.11'
-            tox_env: py311-mode_ansible-ansible5
-          - name: Ans_313_6
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible6
-          - name: Ans_313_7
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible7
-          - name: Ans_313_8
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible8
-          - name: Ans_313_9
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible9
-          - name: Ans_313_10
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible10
           - name: Ans_313_11
             python_version: '3.13'
             tox_env: py313-mode_ansible-ansible11
 
-          - name: Van_313_11
-            python_version: '3.13'
-            tox_env: py313-mode_ansible-ansible11-strategy_linear
-
-          - name: Mito_27
-            tox_env: py27-mode_mitogen
-          - name: Mito_36
-            python_version: '3.6'
-            tox_env: py36-mode_mitogen
-          - name: Mito_313
-            python_version: '3.13'
-            tox_env: py313-mode_mitogen
-
     steps:
       - uses: actions/checkout@v4
       - uses: actions/setup-python@v5
@@ -171,12 +119,6 @@ jobs:
           - name: Mito_313
             tox_env: py313-mode_mitogen
 
-          - name: Loc_313_11
-            tox_env: py313-mode_localhost-ansible11
-
-          - name: Van_313_11
-            tox_env: py313-mode_localhost-ansible11-strategy_linear
-
     steps:
       - uses: actions/checkout@v4
       - uses: actions/setup-python@v5

ansible_mitogen/connection.py

@@ -145,7 +145,7 @@ def _connect_ssh(spec):
             'identity_file': private_key_file,
             'identities_only': False,
             'ssh_path': spec.ssh_executable(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout(),  # WIP
             'ssh_args': spec.ssh_args(),
             'ssh_debug_level': spec.mitogen_ssh_debug_level(),
             'remote_name': get_remote_name(spec),
@@ -169,7 +169,7 @@ def _connect_buildah(spec):
             'username': spec.remote_user(),
             'container': spec.remote_addr(),
             'python_path': spec.python_path(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -185,7 +185,7 @@ def _connect_docker(spec):
             'username': spec.remote_user(),
             'container': spec.remote_addr(),
             'python_path': spec.python_path(rediscover_python=True),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -200,7 +200,7 @@ def _connect_kubectl(spec):
         'kwargs': {
             'pod': spec.remote_addr(),
             'python_path': spec.python_path(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'kubectl_path': spec.mitogen_kubectl_path(),
             'kubectl_args': spec.extra_args(),
             'remote_name': get_remote_name(spec),
@@ -218,7 +218,7 @@ def _connect_jail(spec):
             'username': spec.remote_user(),
             'container': spec.remote_addr(),
             'python_path': spec.python_path(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -234,7 +234,7 @@ def _connect_lxc(spec):
             'container': spec.remote_addr(),
             'python_path': spec.python_path(),
             'lxc_attach_path': spec.mitogen_lxc_attach_path(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -250,7 +250,7 @@ def _connect_lxd(spec):
             'container': spec.remote_addr(),
             'python_path': spec.python_path(),
             'lxc_path': spec.mitogen_lxc_path(),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -273,7 +273,7 @@ def _connect_podman(spec):
             'username': spec.remote_user(),
             'container': spec.remote_addr(),
             'python_path': spec.python_path(rediscover_python=True),
-            'connect_timeout': spec.timeout(),
+            'connect_timeout': spec.ansible_ssh_timeout() or spec.timeout(),  # WIP
             'remote_name': get_remote_name(spec),
         }
     }
@@ -762,10 +762,20 @@ def _stack_from_spec(self, spec, stack=(), seen_names=()):
                 seen_names=seen_names + (spec.inventory_name(),),
             )
 
-        stack += (CONNECTION_METHOD[spec.transport()](spec),)
+        spec_to_param_dict = CONNECTION_METHOD[spec.transport()]
+        param_dict = spec_to_param_dict(spec)
+        if 'connect_timeout' in param_dict:
+            assert isinstance(param_dict['connect_timeout'], int), param_dict
+            assert not isinstance(param_dict['connect_timeout'], bool), param_dict
+        stack += (param_dict,)
         if spec.become() and ((spec.become_user() != spec.remote_user()) or
                               C.BECOME_ALLOW_SAME_USER):
-            stack += (CONNECTION_METHOD[spec.become_method()](spec),)
+            spec_to_param_dict = CONNECTION_METHOD[spec.become_method()]
+            param_dict = spec_to_param_dict(spec)
+            if 'connect_timeout' in param_dict:
+                assert isinstance(param_dict['connect_timeout'], int), param_dict
+                assert not isinstance(param_dict['connect_timeout'], bool), param_dict
+            stack += (param_dict,)
 
         return stack
 

ansible_mitogen/logging.py

@@ -59,11 +59,35 @@ def set_process_name(name):
     _process_pid = os.getpid()
 
 
+def logging_level_to_verbosity(logging_level):
+    mapping = {
+        logging.CRITICAL: 0,
+        logging.ERROR: 0,
+        logging.WARNING: 0,
+        logging.INFO: 1,
+        logging.DEBUG: 3,
+    }
+    return mapping[logging_level]
+
+
+def verbosity_to_logging_level(verbosity):
+    mapping = {
+        0: logging.WARNING,
+        1: logging.INFO,
+        2: logging.INFO,
+        3: logging.DEBUG,
+        4: logging.DEBUG,
+        5: logging.DEBUG,
+        6: logging.DEBUG,
+    }
+    return mapping.get(verbosity, logging.DEBUG)
+
+
 class Handler(logging.Handler):
     """
     Use Mitogen's log format, but send the result to a Display method.
     """
-    def __init__(self, normal_method):
+    def __init__(self, normal_method=None):
         logging.Handler.__init__(self)
         self.formatter = mitogen.utils.log_get_formatter()
         self.normal_method = normal_method
@@ -94,8 +118,12 @@ def emit(self, record):
             display.error(s, wrap_text=False)
         elif record.levelno >= logging.WARNING:
             display.warning(s, formatted=True)
-        else:
+        elif self.normal_method:
             self.normal_method(s)
+        else:
+            verbosity = logging_level_to_verbosity(record.levelno)
+            caplevel = verbosity - 1
+            display.verbose(s, caplevel=caplevel)
 
 
 def setup():
@@ -104,25 +132,31 @@ def setup():
     display framework. Ansible installs its own logging framework handlers when
     C.DEFAULT_LOG_PATH is set, therefore disable propagation for our handlers.
     """
+    l_root = logging.getLogger('')
     l_mitogen = logging.getLogger('mitogen')
     l_mitogen_io = logging.getLogger('mitogen.io')
     l_ansible_mitogen = logging.getLogger('ansible_mitogen')
     l_operon = logging.getLogger('operon')
 
     for logger in l_mitogen, l_mitogen_io, l_ansible_mitogen, l_operon:
-        logger.handlers = [Handler(display.vvv)]
+        logger.handlers = [Handler()]
         logger.propagate = False
 
-    if display.verbosity > 2:
-        l_ansible_mitogen.setLevel(logging.DEBUG)
-        l_mitogen.setLevel(logging.DEBUG)
-    else:
-        # Mitogen copies the active log level into new children, allowing them
-        # to filter tiny messages before they hit the network, and therefore
-        # before they wake the IO loop. Explicitly setting INFO saves ~4%
-        # running against just the local machine.
-        l_mitogen.setLevel(logging.ERROR)
-        l_ansible_mitogen.setLevel(logging.ERROR)
+    ansible_display_level = verbosity_to_logging_level(display.verbosity)
+    l_ansible_mitogen.setLevel(ansible_display_level)
+    l_mitogen.setLevel(ansible_display_level)
 
     if display.verbosity > 3:
         l_mitogen_io.setLevel(logging.DEBUG)
+
+    # display.warning('display.verbosity=%s logging_level_to_verbosity(logging.INFO)=%s'
+    #                 % (display.verbosity, logging_level_to_verbosity(logging.INFO)))
+    # display.warning('root=%r level=%s effectiveLevel=%s'
+    #                 % (l_root, l_root.level, l_root.getEffectiveLevel()))
+    # display.warning('ansible_mitogen=%r level=%s effectiveLevel=%s'
+    #                 % (l_ansible_mitogen, l_ansible_mitogen.level, l_ansible_mitogen.getEffectiveLevel()))
+    # display.warning('mitogen=%r level=%s effectiveLevel=%s'
+    #                 % (l_mitogen, l_mitogen.level, l_mitogen.getEffectiveLevel()))
+    # l_ansible_mitogen.info('Hello from %r', l_ansible_mitogen)
+    # l_this_mod = logging.getLogger(__name__)
+    # l_this_mod.info('Hello from %r', l_this_mod)

ansible_mitogen/mixins.py

@@ -489,10 +489,13 @@ def _run_cmd():
 
         for possible_python in possible_pythons:
             try:
+                LOG.debug('_low_level_execute_command(): trying %s', possible_python)
                 self._possible_python_interpreter = possible_python
                 rc, stdout, stderr = _run_cmd()
+                LOG.debug('_low_level_execute_command(): got rc=%d, stdout=%r, stderr=%r', rc, stdout, stderr)
             # TODO: what exception is thrown?
-            except:
+            except BaseException as exc:
+                LOG.warning('%r._low_level_execute_command for possible_python=%r: %s, %r', self, possible_python, type(exc), exc)
                 # we've reached the last python attempted and failed
                 # TODO: could use enumerate(), need to check which version of python first had it though
                 if possible_python == 'python':
@@ -501,10 +504,12 @@ def _run_cmd():
                     continue
 
         stdout_text = to_text(stdout, errors=encoding_errors)
+        stderr_text = to_text(stderr, errors=encoding_errors)
 
         return {
             'rc': rc,
             'stdout': stdout_text,
             'stdout_lines': stdout_text.splitlines(),
-            'stderr': stderr,
+            'stderr': stderr_text,
+            'stderr_lines': stderr_text.splitlines(),
         }

ansible_mitogen/runner.py

@@ -370,6 +370,7 @@ def _setup_cwd(self):
         impossible to restore the old directory, so don't even try.
         """
         if self.cwd:
+            LOG.warning('%s._setup_cwd(): self.cwd=%r', self, self.cwd)
             os.chdir(self.cwd)
 
     def _setup_environ(self):
@@ -389,6 +390,7 @@ def _revert_cwd(self):
         #591: make a best-effort attempt to return to :attr:`good_temp_dir`.
         """
         try:
+            LOG.warning('%s._revert_cwd(): self, self.good_temp_dir=%r', self, self.good_temp_dir)
             os.chdir(self.good_temp_dir)
         except OSError:
             LOG.debug('%r: could not restore CWD to %r',

ansible_mitogen/services.py

@@ -171,8 +171,10 @@ def reset(self, stack):
                 key = key_from_dict(via=context, **spec)
                 response = self._response_by_key.get(key)
                 if response is None:
-                    LOG.debug('%r: could not find connection to shut down; '
-                              'failed at hop %d', self, i)
+                    LOG.warning('%r: could not find connection to shut down; '
+                                'failed at hop %d, key %r', self, i, key)
+                    LOG.warning('%r', stack)
+                    LOG.warning('%r', self._response_by_key)
                     return False
 
                 context = response['context']
@@ -325,7 +327,7 @@ def _on_context_disconnect(self, context):
         """
         self._lock.acquire()
         try:
-            LOG.info('%r: Forgetting %r due to stream disconnect', self, context)
+            #LOG.info('%r: Forgetting %r due to stream disconnect', self, context)
             self._forget_context_unlocked(context)
         finally:
             self._lock.release()

ansible_mitogen/target.py

@@ -584,7 +584,8 @@ def exec_args(args, in_data='', chdir=None, shell=None, emulate_tty=False):
     :return:
         (return code, stdout bytes, stderr bytes)
     """
-    LOG.debug('exec_args(%r, ..., chdir=%r)', args, chdir)
+    LOG.warning('exec_args(%r, ..., chdir=%r) LOG.level=%s LOG.effectiveLevel=%s',
+                args, chdir, LOG.level, LOG.getEffectiveLevel())
     assert isinstance(args, list)
 
     if emulate_tty: