diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 9a275a00c..cfc1545a5 100644 --- a/.github/workflows/tests.yml +++ b/.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 diff --git a/ansible_mitogen/connection.py b/ansible_mitogen/connection.py index 5053a5f5b..0c6bd7fc6 100644 --- a/ansible_mitogen/connection.py +++ b/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 diff --git a/ansible_mitogen/logging.py b/ansible_mitogen/logging.py index 4d5647a45..3fb7d5529 100644 --- a/ansible_mitogen/logging.py +++ b/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) diff --git a/ansible_mitogen/mixins.py b/ansible_mitogen/mixins.py index 3953eb52e..33f74fb4a 100644 --- a/ansible_mitogen/mixins.py +++ b/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(), } diff --git a/ansible_mitogen/runner.py b/ansible_mitogen/runner.py index b60e537ce..6da5f4e8d 100644 --- a/ansible_mitogen/runner.py +++ b/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', diff --git a/ansible_mitogen/services.py b/ansible_mitogen/services.py index abc0e3794..c63e82003 100644 --- a/ansible_mitogen/services.py +++ b/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() diff --git a/ansible_mitogen/target.py b/ansible_mitogen/target.py index ee4cb398f..51ec1aaed 100644 --- a/ansible_mitogen/target.py +++ b/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: diff --git a/ansible_mitogen/transport_config.py b/ansible_mitogen/transport_config.py index 937755528..d2296226a 100644 --- a/ansible_mitogen/transport_config.py +++ b/ansible_mitogen/transport_config.py @@ -441,7 +441,7 @@ def _become_option(self, name): if name not in fallback_options: raise - LOG.info( + LOG.warning( 'Used fallback=PlayContext.%s for plugin=%r, option=%r', name, self._connection, name, ) @@ -453,7 +453,7 @@ def _connection_option(self, name, fallback_attr=None): except KeyError: if fallback_attr is None: fallback_attr = name - LOG.info( + LOG.warning( 'Used fallback=PlayContext.%s for plugin=%r, option=%r', fallback_attr, self._connection, name, ) @@ -513,9 +513,18 @@ def ssh_executable(self): return self._connection_option('ssh_executable') def timeout(self): - return self._connection_option('timeout') + #return self._play_context.timeout + timeout = self._connection_option('timeout') + if timeout != 30: + raise ValueError(timeout) + return timeout def ansible_ssh_timeout(self): + return ( + # self._connection.get_task_var('ansible_timeout') or + # self._connection.get_task_var('ansible_ssh_timeout') or + self.timeout() + ) return self.timeout() def ssh_args(self): @@ -733,12 +742,15 @@ def ssh_executable(self): def timeout(self): # TODO: must come from PlayContext too. - return C.DEFAULT_TIMEOUT + timeout = C.DEFAULT_TIMEOUT + if timeout != 30: + raise ValueError(timeout) + return timeout def ansible_ssh_timeout(self): return ( - self._host_vars.get('ansible_timeout') or - self._host_vars.get('ansible_ssh_timeout') or + # self._host_vars.get('ansible_timeout') or + # self._host_vars.get('ansible_ssh_timeout') or self.timeout() ) diff --git a/mitogen/parent.py b/mitogen/parent.py index fa3092c19..22fae8ab1 100644 --- a/mitogen/parent.py +++ b/mitogen/parent.py @@ -1304,7 +1304,11 @@ def __init__(self, max_message_size, name=None, remote_name=None, self.profiling = profiling self.unidirectional = unidirectional self.max_message_size = max_message_size - self.connect_deadline = mitogen.core.now() + self.connect_timeout + try: + self.connect_deadline = mitogen.core.now() + self.connect_timeout + except TypeError: + raise TypeError('self.connect_timeout=%r, type=%s' + % (self.connect_timeout, type(self.connect_timeout))) class Connection(object): diff --git a/tests/ansible/all.yml b/tests/ansible/all.yml index 7a3e70001..44ea7efd7 100644 --- a/tests/ansible/all.yml +++ b/tests/ansible/all.yml @@ -1,6 +1,2 @@ -- import_playbook: setup/all.yml - tags: setup - import_playbook: regression/all.yml tags: regression -- import_playbook: integration/all.yml - tags: integration diff --git a/tests/ansible/regression/all.yml b/tests/ansible/regression/all.yml index a7c8033e4..47dedfcaf 100644 --- a/tests/ansible/regression/all.yml +++ b/tests/ansible/regression/all.yml @@ -1,20 +1 @@ - import_playbook: issue_109__target_has_old_ansible_installed.yml -- import_playbook: issue_113__duplicate_module_imports.yml -- import_playbook: issue_118__script_not_marked_exec.yml -- import_playbook: issue_122__environment_difference.yml -- import_playbook: issue_140__thread_pileup.yml -- import_playbook: issue_152__local_action_wrong_interpreter.yml -- import_playbook: issue_152__virtualenv_python_fails.yml -- import_playbook: issue_154__module_state_leaks.yml -- import_playbook: issue_177__copy_module_failing.yml -- import_playbook: issue_332_ansiblemoduleerror_first_occurrence.yml -- import_playbook: issue_558_unarchive_failed.yml -- import_playbook: issue_590__sys_modules_crap.yml -- import_playbook: issue_591__setuptools_cwd_crash.yml -- import_playbook: issue_615__streaming_transfer.yml -- import_playbook: issue_655__wait_for_connection_error.yml -- import_playbook: issue_776__load_plugins_called_twice.yml -- import_playbook: issue_952__ask_become_pass.yml -- import_playbook: issue_1066__add_host__host_key_checking.yml -- import_playbook: issue_1079__wait_for_connection_timeout.yml -- import_playbook: issue_1087__template_streamerror.yml diff --git a/tests/ansible/regression/issue_109__target_has_old_ansible_installed.yml b/tests/ansible/regression/issue_109__target_has_old_ansible_installed.yml index 064832ece..a7ae0908c 100644 --- a/tests/ansible/regression/issue_109__target_has_old_ansible_installed.yml +++ b/tests/ansible/regression/issue_109__target_has_old_ansible_installed.yml @@ -26,6 +26,7 @@ - env.cwd == ansible_user_dir - (not env.mitogen_loaded) or (env.python_path.count("") == 1) fail_msg: | + ansible_user_dir={{ ansible_user_dir }} env={{ env }} - name: Run some new-style from ansible.module_utils... modules diff --git a/tox.ini b/tox.ini index ea988aa0c..fa73ee45f 100644 --- a/tox.ini +++ b/tox.ini @@ -114,7 +114,7 @@ setenv = # Ansible 10 (ansible-core 2.17) requires Python >= 3.7 on targets ansible10: MITOGEN_TEST_DISTRO_SPECS=debian10-py3 debian11-py3 ubuntu2004-py3 # Ansible 11 (ansible-core 2.18) requires Python >= 3.8 on targets - ansible11: MITOGEN_TEST_DISTRO_SPECS=debian11-py3 ubuntu2004-py3 + ansible11: MITOGEN_TEST_DISTRO_SPECS=ubuntu2004-py3 distros_centos: MITOGEN_TEST_DISTRO_SPECS=centos6 centos7 centos8 distros_centos5: MITOGEN_TEST_DISTRO_SPECS=centos5 distros_centos6: MITOGEN_TEST_DISTRO_SPECS=centos6