yhal003 commented 4 years ago

Which version of Ansible are you running? ansible 2.9.9
Is your version of Ansible patched in any way? no
Are you running with any custom modules, or module_utils loaded? no
Have you tried the latest master version from Git? yes

ansible playbook, when run with mitogen, fails with incorrect sudo password about half the time. There is no apparent pattern in failures, but if I use --become-ask-pass instead of passing the password in ansible_become_pass it always works. ansible without mitogen always works.

fatal: hostname]: FAILED! => {"msg": "error occurred on host hostname: sudo password is incorrect"}

When it fails, I see the following in the logs: [mux 14109] 04:42:19.919785 D mitogen.parent.[ssh.hostname]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkc1OwzAQhO95itxsqyZ1UhA0kiVQD4gDQooQOUCF8uO0htS2nKSmfXq2KaJJOXDztzv2jDwJTbluAiONwMSz1A1IVj5Ape0nJrF3OJediTCjIWPkxAkdkoVteOS i1o3AyRDsENIhOAAwbHZgX2ctuG58zn1UZtZJhfxMlf1SfImia7O8Fv162jV2mks1Nbt2rRWCnOeyCe8nW2EbqdVrPFv2tkJtpQVGd8n9C0NLPr521ADWeLygY5wgvJGtXgkVf3QQQth1l19oI+zt2hTuNGOzAAZVoEQjA21 XgdrH0fwyuiGIeODlrGwFDil6fHh+Yoy9KQQZC11CFcRb8Hd8KKOElxVUgGyOSGBFVuLwml3NCUV7aeClyvCTLqXI5ejQT2V+DBb9+fjnZ2r3n/pvynCc8rfNiHwDNPLAOw==\".encode(),\"base64\"),\"zip\"))" [mux 14109] 04:42:19.924882 D mitogen.parent.[ssh.hostname]: child for Connection(None) started: pid:29457 stdin:18 stdout:18 stderr:16 [mux 14109] 04:42:20.280717 D mitogen.parent.[ssh.hostname]: sudo.root: (partial): [sudo] password for username: [mux 14109] 04:42:20.280924 D mitogen.sudo.[ssh.hostname]: sudo.root: (password prompt): [sudo] password for username: [mux 14109] 04:42:20.281058 D mitogen.parent.[ssh.hostname]: sudo.root: (partial): [sudo] password for username: * [mux 14109] 04:42:20.281206 D mitogen.sudo.[ssh.hostname]: sudo.root: (password prompt): [sudo] password for username: * [mux 14109] 04:42:20.281328 D mitogen.parent.[ssh.hostname]: failing connection sudo.root due to PasswordError(u'sudo password is incorrect',) [mux 14109] 04:42:20.281445 D mitogen.[ssh.hostname]: BootstrapProtocol(sudo.root): disconnecting [mux 14109] 04:42:20.281581 D mitogen.parent.[ssh.hostname]: failing connection sudo.root due to EofError(u'EOF on stream; last 100 lines rece ived:\n',) [mux 14109] 04:42:20.281728 D mitogen.parent.[ssh.hostname]: PopenProcess sudo.root pid 29457 still running after IO disconnect, recheck in 0. 050s [mux 14109] 04:42:20.281839 D mitogen.[ssh.hostname]: SetupProtocol(sudo.root): disconnecting [mux 14109] 04:42:20.281968 D mitogen.[ssh.hostname]: SetupProtocol(sudo.root): disconnecting [mux 14109] 04:42:20.282231 D mitogen.[ssh.hostname]: Dispatcher: Message(1004, 0, 0, 101, 1003, '\x80\x02(NX\x0e\x00\x00\x00mitogen.parentq\x 00NX\x0e\x00\x00\x00_proxy_connectq\x01)cm'..465) -> {u'msg': 'error occurred on host hostname: sudo password is incorrect', u'id': None, u'nam e': None}

When it succeeds I see: [mux 15321] 04:48:10.238979 D mitogen.parent.[ssh.hostname]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkc1OwzAQhO95itzWVk3qtKKISJZAPSAOCClC9FAqlB+nNaS25SQN7dOzTRFNyoGbv92xZ+SJ2UKYKrDKSkI9x9oeqcJHKIz7JDTyjue8sRPCWcg5PXPM+uRwG544K00lSdwH14dFH1oENKz2aF8mNbpufSF8yBPXKg1+ovNuKb9k1tRJWspuPW4qN06VHtt9vTEaMOelbCS6yU66Shm9jKarzlbqnXLIcB8/vHJYieG1kwaxJMMFG+IIyFbVZi119NFgCOk2TXplrHR3G5u15xmfBjgoAi0rFRi3DvQhmvLZZEaBeujVOlVLEjJ4enx55py/acCMmcmxCurNxTs5lpHjyxorAJcCDZxMchLe8OtbyuCgLL5UWHHWLRi0KRz7KeyPwbw7n/78Qt3+p/6bMhym/G1zQr8BLifAMw==\".encode(),\"base64\"),\"zip\"))" [mux 15321] 04:48:10.243668 D mitogen.parent.[ssh.hostname]: child for Connection(None) started: pid:30655 stdin:18 stdout:18 stderr:16 [mux 15321] 04:48:10.506317 D mitogen.parent.[ssh.hostname]: sudo.root: (partial): [sudo] password for username: [mux 15321] 04:48:10.506610 D mitogen.sudo.[ssh.hostname]: sudo.root: (password prompt): [sudo] password for username: [mux 15321] 04:48:10.506774 D mitogen.parent.[ssh.hostname]: sudo.root: (unrecognized): [sudo] password for username: *****************

s1113950 commented 4 years ago

Do you have a minimal playbook that I can use to reproduce the error? Also, which Python and OS are you running for both host and target node?

yhal003 commented 4 years ago

I can reproduce it even by running setup module via ansible command: ansible --become -i test-inventory.yml -u user -e "ansible_ssh_pass=*** ansible_become_pass=***" -m setup group host: python 3.6.8, OS CentOS 7.4 target: python 2.7.5 but I tried setting interpreter to 3.6.8, didn't help. OS CentOS 7.4

s1113950 commented 4 years ago

Does it work with Ansible 2.9.6? Also, does it work with vanilla Ansible 2.9.6?

Aethylred commented 4 years ago

I work in the same environment as @yhal003 but with different playbooks and I see the same with Ansible 2.9.9

ansible-playbook 2.9.9
  config file = /home/hicksaw/hpcf-ansible/ansible-k8s/ansible.cfg
  configured module search path = ['/home/hicksaw/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.6/site-packages/ansible
  executable location = /usr/local/bin/ansible-playbook
  python version = 3.6.8 (default, Aug  7 2019, 17:28:10) [GCC 4.8.5 20150623 (Red Hat 4.8.5-39)]

I enable the mitogen strategies in my ansible.cfg, but specify a non-mitogen default (which works, but is slow):

[defaults]
vault_identity_list = prod@.vault
host_key_checking = False
force_valid_group_names = ignore
# Enable mitogen strategies
strategy_plugins = /usr/local/lib/python3.6/site-packages/ansible_mitogen/plugins/strategy
strategy = linear
[connection]
pipelining = True

And specify strategy and python interpreter in my plays:

- name: Common tasks
  strategy: mitogen_linear
  hosts: k8s-hosts
  vars:
    ansible_user: "{{ vault_ansible_user }}"
    ansible_ssh_pass: "{{ vault_ansible_password }}"
    ansible_become_pass: "{{ vault_become_password }}"
    ansible_become_method: sudo
    # ansible_python_interpreter: "/bin/python3"
  tasks:
    <snip>

So when it tries to run on the client we see (this task is just comparing /etc/resolv.conf to a template):

Friday 17 July 2020  03:26:16 +0000 (0:00:00.169)       0:00:35.102 ***********
[task 21787] 03:26:17.003386 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 21788] 03:26:17.062595 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 21787] 03:26:17.192114 D ansible_mitogen.mixins: _make_tmp_path(remote_user=None)
[task 21787] 03:26:17.214627 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_xc2fg42w.sock) to connect to "host2.example.org"
[task 21787] 03:26:17.214766 D mitogen.unix: client: connecting to /tmp/mitogen_unix_xc2fg42w.sock
[mux  21649] 03:26:17.215444 D mitogen.unix: listener: accepted connection from PID 21787: unix_client.21787
[task 21787] 03:26:17.225438 D mitogen.unix: client: local ID is 1, remote is 0
[mux  21649] 03:26:17.229505 D mitogen.parent: creating connection to context 2 using mitogen.ssh
[task 21788] 03:26:17.233632 D ansible_mitogen.mixins: _make_tmp_path(remote_user=None)
[task 21788] 03:26:17.234922 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_xc2fg42w.sock) to connect to "host1.example.org"
[task 21788] 03:26:17.235062 D mitogen.unix: client: connecting to /tmp/mitogen_unix_xc2fg42w.sock
[mux  21649] 03:26:17.393239 D mitogen.parent: command line for Connection(None): ssh -o "LogLevel ERROR" -l ansible -o "Compression yes" -o "ServerAliveInterval 30" -o "ServerAliveCountMax 10" -o "StrictHostKeyChecking no" -o "UserKnownHostsFile /dev/null" -o "GlobalKnownHostsFile /dev/null" -C -o ControlMaster=auto -o ControlPersist=60s host2.example.org /usr/bin/python -c "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkc1qwzAQhM/xU/gmiQhHdkt/DIKWHEoPpWBKc0hDsS05EXEkITtRk6fvximNnR5624+d3Rl2MzrjpomsshKTwFHfI1WFAJVxa0zSYAS12NoEMxozRs6c0T456MYnLmvTSJz1wfVh1gcPAIbNHuzrvAXXTch5iETuvNIozLXomvJLlts2L2rZtSfbxk0KpSd2366MRpBzdCEb825wJ12jjJ6nV4vOVuqdcsDoMXt6Z2jBh2MnDWCNhw06xDHCG9WapdTpSpXrJvcPK1v6XGyUZkkEdRVp2ajIuGWkD2kS31zfE0QCWO+daiWOKXp5fntljH1oBLFKI+D6JJjyT3y8vzBWarg6cgUikZO5wPEtS+4IRQdlYVNl+Vk3o8gX6PiSyv4YTLv6dOYLtf9P/TdlPEz5+8CEfAMXY7mL\".encode(),\"base64\"),\"zip\"))'"
[mux  21649] 03:26:17.404649 D mitogen.parent: child for Connection(None) started: pid:21793 stdin:79 stdout:79 stderr:77
[mux  21649] 03:26:17.405537 D mitogen.unix: listener: accepted connection from PID 21788: unix_client.21788
[task 21788] 03:26:17.410475 D mitogen.unix: client: local ID is 3, remote is 0
[mux  21649] 03:26:17.412216 D mitogen.parent: creating connection to context 4 using mitogen.ssh
[mux  21649] 03:26:17.414232 D mitogen.parent: command line for Connection(None): ssh -o "LogLevel ERROR" -l ansible -o "Compression yes" -o "ServerAliveInterval 30" -o "ServerAliveCountMax 10" -o "StrictHostKeyChecking no" -o "UserKnownHostsFile /dev/null" -o "GlobalKnownHostsFile /dev/null" -C -o ControlMaster=auto -o ControlPersist=60s host1.example.org /usr/bin/python -c "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkc1qwzAQhM/xU/gmiQhHdkt/DIKWHEoPpWBKc0hDsS05EXEkITtRk6fvximNnR5624+d3Rl2MzrjpomsshKTwFHfI1WFAJVxa0zSYAS12NoEMxozRs6c0T456MYnLmvTSJz1wfVh1gcPAIbNHuzrvAXXTch5iETuvNIozLXomvJLlts2L2rZtSfbxk0KpSd2366MRpBzdCEb825wJ12jjJ6nV4vOVuqdcsDoMXt6Z2jBh2MnDWCNhw06xDHCG9WapdTpSpXrJvcPK1v6XGyUZkkEdRVp2ajIuGWkD2kS31zfE0QCWO+daiWOKXp5fntljH1oBLFKI+D6JJjyT3y8vzBWarg6cgUikZO5wPEtS+4IRQdlYVNl+Vk3o8gX6PiSyv4YTLv6dOYLtf9P/TdlPEz5+8CEfAMXY7mL\".encode(),\"base64\"),\"zip\"))'"
[mux  21649] 03:26:17.421641 D mitogen.parent: child for Connection(None) started: pid:21795 stdin:82 stdout:82 stderr:80
[mux  21649] 03:26:17.981171 D mitogen.parent: ssh.host2.example.org: (partial): Login Password:
[mux  21649] 03:26:17.981612 D mitogen.ssh: ssh.host2.example.org: (password prompt): b'Login Password:'
[mux  21649] 03:26:17.982074 D mitogen.parent: ssh.host2.example.org: (unrecognized): Login Password:
[mux  21649] 03:26:18.128679 D mitogen.parent: ssh.host1.example.org: (partial): Login Password:
[mux  21649] 03:26:18.128840 D mitogen.ssh: ssh.host1.example.org: (password prompt): b'Login Password:'
[mux  21649] 03:26:18.129266 D mitogen.parent: ssh.host1.example.org: (unrecognized): Login Password:
[mux  21649] 03:26:19.473549 D mitogen.parent: BootstrapProtocol(ssh.host1.example.org): first stage started succcessfully
[mux  21649] 03:26:19.478005 D mitogen.parent: BootstrapProtocol(ssh.host1.example.org): first stage received mitogen.core source
[mux  21649] 03:26:19.522594 D mitogen.parent: BootstrapProtocol(ssh.host1.example.org): new child booted successfully
[mux  21649] 03:26:19.523130 D mitogen.[ssh.host1.example.org]: Python version is 2.7.5 (default, Aug  4 2017, 00:39:18)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-16)]
[mux  21649] 03:26:19.523325 D mitogen.[ssh.host1.example.org]: Parent is context 0 (master); my ID is 4
[mux  21649] 03:26:19.523508 D mitogen.[ssh.host1.example.org]: pid:28586 ppid:28585 uid:66400050/66400050, gid:66400050/66400050 host:'host1.example.org'
[mux  21649] 03:26:19.523668 D mitogen.[ssh.host1.example.org]: Recovered sys.executable: '/usr/bin/python'
[mux  21649] 03:26:19.524910 D mitogen.parent: starting function call to ssh.host1.example.org: ansible_mitogen.target.init_child(log_level=10, candidate_temp_dirs=['~/.ansible/tmp', '/var/tmp', '/tmp'])
[mux  21649] 03:26:19.526833 D mitogen.responder: ansible is a package at /usr/local/lib/python3.6/site-packages/ansible/__init__.py with submodules ['cli', 'compat', 'config', 'constants', 'context', 'errors', 'executor', 'galaxy', 'inventory', 'module_utils', 'modules', 'parsing', 'playbook', 'plugins', 'release', 'template', 'utils', 'vars']
[mux  21649] 03:26:19.527359 D mitogen.responder: sending ansible (0.49 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.529838 D mitogen.responder: ansible.module_utils is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/__init__.py with submodules ['_text', 'acme', 'alicloud_ecs', 'ansible_release', 'ansible_tower', 'api', 'aws', 'azure_rm_common', 'azure_rm_common_ext', 'azure_rm_common_rest', 'basic', 'cloud', 'cloudscale', 'cloudstack', 'common', 'compat', 'connection', 'crypto', 'csharp', 'database', 'digital_ocean', 'dimensiondata', 'distro', 'docker', 'ec2', 'ecs', 'exoscale', 'f5_utils', 'facts', 'firewalld', 'gcdns', 'gce', 'gcp', 'gcp_utils', 'gitlab', 'hcloud', 'heroku', 'hetzner', 'hwc_utils', 'ibm_sa_utils', 'identity', 'infinibox', 'influxdb', 'ipa', 'ismount', 'json_utils', 'k8s', 'known_hosts', 'kubevirt', 'ldap', 'linode', 'lxd', 'manageiq', 'memset', 'mysql', 'net_tools', 'netapp', 'netapp_elementsw_module', 'netapp_module', 'network', 'oneandone', 'oneview', 'online', 'opennebula', 'openstack', 'oracle', 'ovirt', 'parsing', 'podman', 'postgres', 'powershell', 'pure', 'pycompat24', 'rabbitmq', 'rax', 'redfish_utils', 'redhat', 'remote_management', 'scaleway', 'service', 'service_now', 'six', 'source_control', 'splitter', 'storage', 'univention_umc', 'urls', 'utm_utils', 'vca', 'vexata', 'vmware', 'vmware_rest_client', 'vmware_spbm', 'vultr', 'xenserver', 'yumdnf']
[mux  21649] 03:26:19.530233 D mitogen.responder: sending ansible.module_utils (1.62 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.584953 D mitogen: PkgutilMethod(): loading 'ansible.module_utils.distro' using <_frozen_importlib_external.SourceFileLoader object at 0x7f520f8d6e80> failed: loader for ansible.module_utils.distro._distro cannot handle ansible.module_utils.distro
[mux  21649] 03:26:19.585107 D mitogen: _get_module_via_sys_modules('ansible.module_utils.distro') -> <module 'ansible.module_utils.distro._distro' from '/usr/local/lib/python3.6/site-packages/ansible/module_utils/distro/_distro.py'>
[mux  21649] 03:26:19.585243 D mitogen: sys.modules['ansible.module_utils.distro'].__name__ is incorrect, assuming this is a hacky module alias and ignoring it. Got 'ansible.module_utils.distro._distro', module object: <module 'ansible.module_utils.distro._distro' from '/usr/local/lib/python3.6/site-packages/ansible/module_utils/distro/_distro.py'>
[mux  21649] 03:26:19.585577 D mitogen: ParentEnumerationMethod(): 'ansible.module_utils.distro' is PKG_DIRECTORY: '/usr/local/lib/python3.6/site-packages/ansible/module_utils/distro/__init__.py'
[mux  21649] 03:26:19.683223 D mitogen: _get_module_via_sys_modules('markupsafe._speedups') -> <module 'markupsafe._speedups' from '/usr/local/lib64/python3.6/site-packages/markupsafe/_speedups.cpython-36m-x86_64-linux-gnu.so'>
[mux  21649] 03:26:19.683691 D mitogen: get_module_source('markupsafe._speedups'): cannot find source
[mux  21649] 03:26:19.684564 D mitogen.responder: ansible.config is a package at /usr/local/lib/python3.6/site-packages/ansible/config/__init__.py with submodules ['data', 'manager']
[mux  21649] 03:26:19.684766 D mitogen.responder: sending ansible.config (0.22 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.685086 D mitogen.responder: sending ansible.config.data (0.90 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.688326 D mitogen.responder: sending ansible.config.manager (10.43 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.689299 D mitogen.responder: sending ansible.constants (5.00 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.689722 D mitogen.responder: sending ansible.context (2.00 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.690560 D mitogen.responder: ansible.errors is a package at /usr/local/lib/python3.6/site-packages/ansible/errors/__init__.py with submodules ['yaml_strings']
[mux  21649] 03:26:19.691381 D mitogen.responder: sending ansible.errors (5.77 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.691871 D mitogen.responder: sending ansible.errors.yaml_strings (2.83 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.692976 D mitogen.responder: sending ansible.module_utils._text (5.50 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.693473 D mitogen.responder: ansible.module_utils.common is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/common/__init__.py with submodules ['_collections_compat', '_json_compat', '_utils', 'collections', 'dict_transformations', 'file', 'json', 'network', 'parameters', 'process', 'removed', 'sys_info', 'text', 'validation']
[mux  21649] 03:26:19.693676 D mitogen.responder: sending ansible.module_utils.common (0.47 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.693957 D mitogen.responder: sending ansible.module_utils.common._collections_compat (1.03 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.694206 D mitogen.responder: sending ansible.module_utils.common._json_compat (0.81 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.694525 D mitogen.responder: sending ansible.module_utils.common._utils (1.32 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.694949 D mitogen.responder: sending ansible.module_utils.common.collections (2.27 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.695567 D mitogen.responder: sending ansible.module_utils.common.file (3.73 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.696409 D mitogen.responder: sending ansible.module_utils.common.parameters (4.39 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.696752 D mitogen.responder: sending ansible.module_utils.common.process (1.41 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.697336 D mitogen.responder: sending ansible.module_utils.common.sys_info (3.10 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.697608 D mitogen.responder: ansible.module_utils.common.text is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/common/text/__init__.py with submodules ['converters', 'formatters']
[mux  21649] 03:26:19.697788 D mitogen.responder: sending ansible.module_utils.common.text (0.33 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.698161 D mitogen.responder: sending ansible.module_utils.common.text.converters (1.77 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.698617 D mitogen.responder: sending ansible.module_utils.common.text.formatters (2.61 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.700648 D mitogen.responder: sending ansible.module_utils.common.validation (6.63 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.700983 D mitogen.responder: ansible.module_utils.distro is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/distro/__init__.py with submodules ['_distro']
[mux  21649] 03:26:19.701251 D mitogen.responder: sending ansible.module_utils.distro (1.58 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.707437 D mitogen.responder: sending ansible.module_utils.distro._distro (15.87 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.707711 D mitogen.responder: ansible.module_utils.parsing is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/parsing/__init__.py with submodules ['convert_bool']
[mux  21649] 03:26:19.707887 D mitogen.responder: sending ansible.module_utils.parsing (0.27 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.708166 D mitogen.responder: sending ansible.module_utils.parsing.convert_bool (1.09 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.708662 D mitogen.responder: sending ansible.module_utils.pycompat24 (2.93 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.709720 D mitogen.responder: ansible.module_utils.six is a package at /usr/local/lib/python3.6/site-packages/ansible/module_utils/six/__init__.py with submodules []
[mux  21649] 03:26:19.712460 D mitogen.responder: sending ansible.module_utils.six (12.14 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.712933 D mitogen.responder: ansible.parsing is a package at /usr/local/lib/python3.6/site-packages/ansible/parsing/__init__.py with submodules ['ajson', 'dataloader', 'metadata', 'mod_args', 'plugin_docs', 'quoting', 'splitter', 'utils', 'vault', 'yaml']
[mux  21649] 03:26:19.713153 D mitogen.responder: sending ansible.parsing (1.07 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.713460 D mitogen.responder: sending ansible.parsing.quoting (1.17 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.713756 D mitogen.responder: ansible.parsing.yaml is a package at /usr/local/lib/python3.6/site-packages/ansible/parsing/yaml/__init__.py with submodules ['constructor', 'dumper', 'loader', 'objects']
[mux  21649] 03:26:19.713973 D mitogen.responder: sending ansible.parsing.yaml (1.02 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.714556 D mitogen.responder: sending ansible.parsing.yaml.objects (2.76 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.715188 D mitogen.responder: ansible.utils is a package at /usr/local/lib/python3.6/site-packages/ansible/utils/__init__.py with submodules ['cmd_functions', 'collection_loader', 'color', 'context_objects', 'display', 'encrypt', 'hashing', 'helpers', 'jsonrpc', 'listify', 'multiprocessing', 'path', 'plugin_docs', 'py3compat', 'sentinel', 'shlex', 'singleton', 'ssh_functions', 'unicode', 'unsafe_proxy', 'vars']
[mux  21649] 03:26:19.715470 D mitogen.responder: sending ansible.utils (1.25 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.716387 D mitogen.responder: sending ansible.utils.color (3.26 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.716866 D mitogen.responder: sending ansible.utils.context_objects (2.21 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.718710 D mitogen.responder: sending ansible.utils.display (7.65 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.719350 D mitogen.responder: sending ansible.utils.path (3.72 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.719770 D mitogen.responder: sending ansible.utils.py3compat (1.78 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.720059 D mitogen.responder: sending ansible.utils.singleton (0.91 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.720599 D mitogen.responder: sending ansible.utils.unsafe_proxy (3.48 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.720917 D mitogen.responder: sending ansible.module_utils.basic (40.70 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.722030 D mitogen.responder: sending ansible.module_utils.json_utils (2.50 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.722550 D mitogen.responder: sending ansible.release (0.99 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.723089 D mitogen.responder: ansible_mitogen is a package at /usr/local/lib/python3.6/site-packages/ansible_mitogen/__init__.py with submodules ['affinity', 'compat', 'connection', 'loaders', 'logging', 'mixins', 'module_finder', 'parsing', 'planner', 'plugins', 'process', 'runner', 'services', 'strategy', 'target', 'transport_config']
[mux  21649] 03:26:19.723283 D mitogen.responder: sending ansible_mitogen (0.42 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.835940 D mitogen.responder: sending ansible_mitogen.target (7.88 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.845896 D mitogen.responder: sending mitogen.fork (2.62 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.956700 D mitogen.responder: sending mitogen.parent (18.79 KiB) to ssh.host1.example.org
[mux  21649] 03:26:19.965827 D mitogen.responder: sending mitogen.select (1.62 KiB) to ssh.host1.example.org
[mux  21649] 03:26:20.016973 D mitogen.responder: sending mitogen.service (8.64 KiB) to ssh.host1.example.org
[mux  21649] 03:26:20.017191 D mitogen.responder: sending ansible_mitogen.runner (8.69 KiB) to ssh.host1.example.org
[mux  21649] 03:26:20.017592 D mitogen.importer.[ssh.host1.example.org]: received ansible
[mux  21649] 03:26:20.017723 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils
[mux  21649] 03:26:20.017830 D mitogen.importer.[ssh.host1.example.org]: received ansible.config
[mux  21649] 03:26:20.017928 D mitogen.importer.[ssh.host1.example.org]: received ansible.config.data
[mux  21649] 03:26:20.018023 D mitogen.importer.[ssh.host1.example.org]: received ansible.config.manager
[mux  21649] 03:26:20.018115 D mitogen.importer.[ssh.host1.example.org]: received ansible.constants
[mux  21649] 03:26:20.018205 D mitogen.importer.[ssh.host1.example.org]: received ansible.context
[mux  21649] 03:26:20.018295 D mitogen.importer.[ssh.host1.example.org]: received ansible.errors
[mux  21649] 03:26:20.018383 D mitogen.importer.[ssh.host1.example.org]: received ansible.errors.yaml_strings
[mux  21649] 03:26:20.018489 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils._text
[mux  21649] 03:26:20.018579 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common
[mux  21649] 03:26:20.018667 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common._collections_compat
[mux  21649] 03:26:20.018755 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common._json_compat
[mux  21649] 03:26:20.018855 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common._utils
[mux  21649] 03:26:20.018945 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.collections
[mux  21649] 03:26:20.019033 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.file
[mux  21649] 03:26:20.019121 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.parameters
[mux  21649] 03:26:20.019210 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.process
[mux  21649] 03:26:20.019297 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.sys_info
[mux  21649] 03:26:20.019385 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.text
[mux  21649] 03:26:20.019489 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.text.converters
[mux  21649] 03:26:20.019578 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.text.formatters
[mux  21649] 03:26:20.019666 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.common.validation
[mux  21649] 03:26:20.019755 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.distro
[mux  21649] 03:26:20.019842 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.distro._distro
[mux  21649] 03:26:20.019929 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.parsing
[mux  21649] 03:26:20.020025 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.parsing.convert_bool
[mux  21649] 03:26:20.020115 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.pycompat24
[mux  21649] 03:26:20.020203 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.six
[mux  21649] 03:26:20.020291 D mitogen.importer.[ssh.host1.example.org]: received ansible.parsing
[mux  21649] 03:26:20.020378 D mitogen.importer.[ssh.host1.example.org]: received ansible.parsing.quoting
[mux  21649] 03:26:20.020482 D mitogen.importer.[ssh.host1.example.org]: received ansible.parsing.yaml
[mux  21649] 03:26:20.020570 D mitogen.importer.[ssh.host1.example.org]: received ansible.parsing.yaml.objects
[mux  21649] 03:26:20.020657 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils
[mux  21649] 03:26:20.020744 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.color
[mux  21649] 03:26:20.020832 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.context_objects
[mux  21649] 03:26:20.020919 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.display
[mux  21649] 03:26:20.021006 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.path
[mux  21649] 03:26:20.021092 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.py3compat
[mux  21649] 03:26:20.021192 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.singleton
[mux  21649] 03:26:20.021302 D mitogen.importer.[ssh.host1.example.org]: received ansible.utils.unsafe_proxy
[mux  21649] 03:26:20.021675 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.basic
[mux  21649] 03:26:20.021790 D mitogen.importer.[ssh.host1.example.org]: received ansible.module_utils.json_utils
[mux  21649] 03:26:20.021887 D mitogen.importer.[ssh.host1.example.org]: received ansible.release
[mux  21649] 03:26:20.021979 D mitogen.importer.[ssh.host1.example.org]: received ansible_mitogen
[mux  21649] 03:26:20.022069 D mitogen.importer.[ssh.host1.example.org]: received ansible_mitogen.target
[mux  21649] 03:26:20.022198 D mitogen.importer.[ssh.host1.example.org]: received mitogen.fork
[mux  21649] 03:26:20.022304 D mitogen.importer.[ssh.host1.example.org]: received mitogen.parent
[mux  21649] 03:26:20.022455 D mitogen.importer.[ssh.host1.example.org]: received mitogen.select
[mux  21649] 03:26:20.022599 D mitogen.importer.[ssh.host1.example.org]: received mitogen.service
[mux  21649] 03:26:20.022695 D mitogen.importer.[ssh.host1.example.org]: received ansible_mitogen.runner
[mux  21649] 03:26:20.029111 D mitogen.[ssh.host1.example.org]: Dispatcher: dispatching (None, u'ansible_mitogen.target', None, u'init_child', (), Kwargs({u'candidate_temp_dirs': [u'~/.ansible/tmp', u'/var/tmp', u'/tmp'], u'log_level': 10}))
[mux  21649] 03:26:20.029264 D mitogen.importer.[ssh.host1.example.org]: requesting ansible_mitogen
[mux  21649] 03:26:20.029363 D mitogen.importer.[ssh.host1.example.org]: requesting ansible_mitogen.target
[mux  21649] 03:26:20.029484 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule errno
[mux  21649] 03:26:20.029576 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule grp
[mux  21649] 03:26:20.029666 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule operator
[mux  21649] 03:26:20.029754 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule os
[mux  21649] 03:26:20.029842 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule pwd
[mux  21649] 03:26:20.029929 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule re
[mux  21649] 03:26:20.030046 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule signal
[mux  21649] 03:26:20.030141 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule stat
[mux  21649] 03:26:20.030230 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule subprocess
[mux  21649] 03:26:20.030637 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule sys
[mux  21649] 03:26:20.030775 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule tempfile
[mux  21649] 03:26:20.033783 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule traceback
[mux  21649] 03:26:20.033934 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule types
[mux  21649] 03:26:20.034060 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule mitogen
[mux  21649] 03:26:20.034157 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.fork
[mux  21649] 03:26:20.036254 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule errno
[mux  21649] 03:26:20.036367 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule logging
[mux  21649] 03:26:20.036489 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule os
[mux  21649] 03:26:20.036582 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule random
[mux  21649] 03:26:20.036672 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule sys
[mux  21649] 03:26:20.036760 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule threading
[mux  21649] 03:26:20.036849 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule traceback
[mux  21649] 03:26:20.036936 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule mitogen
[mux  21649] 03:26:20.037023 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.parent
[mux  21649] 03:26:20.049756 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule codecs
[mux  21649] 03:26:20.050075 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule fcntl
[mux  21649] 03:26:20.050227 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule getpass
[mux  21649] 03:26:20.050322 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule heapq
[mux  21649] 03:26:20.050465 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule inspect
[mux  21649] 03:26:20.063852 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule re
[mux  21649] 03:26:20.063998 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule signal
[mux  21649] 03:26:20.064217 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule socket
[mux  21649] 03:26:20.064334 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule struct
[mux  21649] 03:26:20.065829 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule subprocess
[mux  21649] 03:26:20.065951 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule termios
[mux  21649] 03:26:20.066050 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule textwrap
[mux  21649] 03:26:20.066145 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule zlib
[mux  21649] 03:26:20.066247 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule thread
[mux  21649] 03:26:20.066943 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.service
[mux  21649] 03:26:20.072493 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule grp
[mux  21649] 03:26:20.072636 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule pprint
[mux  21649] 03:26:20.073020 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule pwd
[mux  21649] 03:26:20.073210 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule stat
[mux  21649] 03:26:20.073315 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.select
[mux  21649] 03:26:20.075876 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule json
[mux  21649] 03:26:20.076166 D mitogen.importer.[ssh.host1.example.org]: json.decoder is submodule of a locally loaded package
[mux  21649] 03:26:20.076528 D mitogen.importer.[ssh.host1.example.org]: json.re is submodule of a locally loaded package
[mux  21649] 03:26:20.076704 D mitogen.importer.[ssh.host1.example.org]: json.sys is submodule of a locally loaded package
[mux  21649] 03:26:20.076880 D mitogen.importer.[ssh.host1.example.org]: json.struct is submodule of a locally loaded package
[mux  21649] 03:26:20.077029 D mitogen.importer.[ssh.host1.example.org]: json.json is submodule of a locally loaded package
[mux  21649] 03:26:20.077155 D mitogen.importer.[ssh.host1.example.org]: json.scanner is submodule of a locally loaded package
[mux  21649] 03:26:20.077252 D mitogen.importer.[ssh.host1.example.org]: json._json is submodule of a locally loaded package
[mux  21649] 03:26:20.078120 D mitogen.importer.[ssh.host1.example.org]: encodings.hex_codec is submodule of a locally loaded package
[mux  21649] 03:26:20.078330 D mitogen.importer.[ssh.host1.example.org]: encodings.binascii is submodule of a locally loaded package
[mux  21649] 03:26:20.078795 D mitogen.importer.[ssh.host1.example.org]: json.encoder is submodule of a locally loaded package
[mux  21649] 03:26:20.079679 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule ansible
[mux  21649] 03:26:20.079820 D mitogen.importer.[ssh.host1.example.org]: requesting ansible
[mux  21649] 03:26:20.080123 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils
[mux  21649] 03:26:20.080379 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.json_utils
[mux  21649] 03:26:20.080833 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils has no submodule json
[mux  21649] 03:26:20.081012 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule ansible_mitogen
[mux  21649] 03:26:20.081138 D mitogen.importer.[ssh.host1.example.org]: requesting ansible_mitogen.runner
[mux  21649] 03:26:20.085296 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule atexit
[mux  21649] 03:26:20.085477 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule imp
[mux  21649] 03:26:20.085578 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule shlex
[mux  21649] 03:26:20.085850 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule shutil
[mux  21649] 03:26:20.086600 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule ctypes
[mux  21649] 03:26:20.087000 D mitogen.importer.[ssh.host1.example.org]: ctypes.os is submodule of a locally loaded package
[mux  21649] 03:26:20.087178 D mitogen.importer.[ssh.host1.example.org]: ctypes.sys is submodule of a locally loaded package
[mux  21649] 03:26:20.087303 D mitogen.importer.[ssh.host1.example.org]: ctypes._ctypes is submodule of a locally loaded package
[mux  21649] 03:26:20.087951 D mitogen.importer.[ssh.host1.example.org]: ctypes.struct is submodule of a locally loaded package
[mux  21649] 03:26:20.088790 D mitogen.importer.[ssh.host1.example.org]: ctypes.ctypes is submodule of a locally loaded package
[mux  21649] 03:26:20.089029 D mitogen.importer.[ssh.host1.example.org]: ctypes._endian is submodule of a locally loaded package
[mux  21649] 03:26:20.089308 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule StringIO
[mux  21649] 03:26:20.089626 D mitogen.importer.[ssh.host1.example.org]: ansible_mitogen has no submodule pipes
[mux  21649] 03:26:20.090107 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.basic
[mux  21649] 03:26:20.111408 D mitogen.importer.[ssh.host1.example.org]: requesting systemd
[mux  21649] 03:26:20.112023 D mitogen.importer.[ssh.host1.example.org]: selinux.sys is submodule of a locally loaded package
[mux  21649] 03:26:20.112221 D mitogen.importer.[ssh.host1.example.org]: selinux.os is submodule of a locally loaded package
[mux  21649] 03:26:20.112330 D mitogen.importer.[ssh.host1.example.org]: selinux.imp is submodule of a locally loaded package
[mux  21649] 03:26:20.112906 D mitogen.importer.[ssh.host1.example.org]: requesting swig_runtime_data4
[mux  21649] 03:26:20.113220 D mitogen.importer.[ssh.host1.example.org]: selinux.shutil is submodule of a locally loaded package
[mux  21649] 03:26:20.113371 D mitogen.importer.[ssh.host1.example.org]: selinux.errno is submodule of a locally loaded package
[mux  21649] 03:26:20.113490 D mitogen.importer.[ssh.host1.example.org]: selinux.stat is submodule of a locally loaded package
[mux  21649] 03:26:20.113975 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils._text
[mux  21649] 03:26:20.114871 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils has no submodule codecs
[mux  21649] 03:26:20.115124 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils has no submodule ansible
[mux  21649] 03:26:20.115234 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.six
[mux  21649] 03:26:20.121292 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common
[mux  21649] 03:26:20.121484 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.text
[mux  21649] 03:26:20.121612 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.text.converters
[mux  21649] 03:26:20.122449 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common._collections_compat
[mux  21649] 03:26:20.122865 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.text.formatters
[mux  21649] 03:26:20.124310 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common._json_compat
[mux  21649] 03:26:20.124435 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.process
[mux  21649] 03:26:20.124736 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.file
[mux  21649] 03:26:20.126799 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.sys_info
[mux  21649] 03:26:20.127568 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.distro
[mux  21649] 03:26:20.128096 D mitogen.importer.[ssh.host1.example.org]: requesting distro
[mux  21649] 03:26:20.128250 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.distro._distro
[mux  21649] 03:26:20.131572 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule os
[mux  21649] 03:26:20.131743 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule re
[mux  21649] 03:26:20.131920 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule sys
[mux  21649] 03:26:20.132073 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule json
[mux  21649] 03:26:20.132190 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule shlex
[mux  21649] 03:26:20.132329 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule logging
[mux  21649] 03:26:20.132453 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule optparse
[mux  21649] 03:26:20.133618 D mitogen.importer.[ssh.host1.example.org]: requesting org
[mux  21649] 03:26:20.134414 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.distro has no submodule subprocess
[mux  21649] 03:26:20.135123 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common._utils
[mux  21649] 03:26:20.135543 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.pycompat24
[mux  21649] 03:26:20.136239 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils has no submodule sys
[mux  21649] 03:26:20.136383 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils has no submodule ast
[mux  21649] 03:26:20.136880 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.parameters
[mux  21649] 03:26:20.138309 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.collections
[mux  21649] 03:26:20.139078 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.common.validation
[mux  21649] 03:26:20.141693 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.parsing
[mux  21649] 03:26:20.141800 D mitogen.importer.[ssh.host1.example.org]: requesting ansible.module_utils.parsing.convert_bool
[mux  21649] 03:26:20.142172 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.parsing has no submodule ansible
[mux  21649] 03:26:20.142337 D mitogen.importer.[ssh.host1.example.org]: ansible.module_utils.six has no submodule moves
[mux  21649] 03:26:20.145615 D ansible_mitogen.runner.[ssh.host1.example.org]: EnvironmentFileWatcher('/localhome/ansible/.pam_environment') installed; existing keys: []
[mux  21649] 03:26:20.145733 D ansible_mitogen.runner.[ssh.host1.example.org]: EnvironmentFileWatcher('/etc/environment') installed; existing keys: []
[mux  21649] 03:26:20.145845 D mitogen.parent.[ssh.host1.example.org]: upgraded Poller with EpollPoller (new: 4 readers, 0 writers; old: 4 readers, 0 writers)
[mux  21649] 03:26:20.145939 D mitogen.parent.[ssh.host1.example.org]: upgrading Router(Broker(9690)) with capabilities to start new children
[mux  21649] 03:26:20.146029 D mitogen.[ssh.host1.example.org]: sending message to Context(0, u'master'): Message(0, 4, 4, 105, 1000, ''..0)
[mux  21649] 03:26:20.146130 D mitogen: IdAllocator(Router(Broker(1898))): allocating [5..1005)
[mux  21649] 03:26:20.146244 D mitogen: IdAllocator(Router(Broker(1898))): allocating [5..1005) to Context(4, 'ssh.host1.example.org')
[mux  21649] 03:26:20.147311 D mitogen.parent.[ssh.host1.example.org]: creating connection to context 5 using mitogen.fork
[mux  21649] 03:26:20.149026 D mitogen.parent.[ssh.host1.example.org]: child for Connection(None) started: pid:28613 stdin:14 stdout:14 stderr:None
[mux  21649] 03:26:20.149700 D mitogen.parent.[ssh.host1.example.org]: BootstrapProtocol(fork.28613): new child booted successfully
[mux  21649] 03:26:20.149878 D mitogen.[ssh.host1.example.org]: Router(Broker(9690)): registering Context(5, u'fork.28613') to stream <Stream fork.28613 #30d0>
[mux  21649] 03:26:20.150038 D mitogen.route_monitor: Adding route to 5 via <Stream ssh.host1.example.org #f550>
[mux  21649] 03:26:20.150138 D mitogen.parent: Router(Broker(1898)): adding route to context 5 via <Stream ssh.host1.example.org #f550>
[mux  21649] 03:26:20.151327 D ansible_mitogen.target.[ssh.host1.example.org]: Selected temp directory: u'/localhome/ansible/.ansible/tmp' (from [u'/localhome/ansible/.ansible/tmp', u'/var/tmp', u'/tmp', '/tmp', '/var/tmp', '/usr/tmp', '/localhome/ansible'])
[mux  21649] 03:26:20.152622 D mitogen.[ssh.host1.example.org]: Dispatcher: Message(4, 0, 0, 101, 1000, '\x80\x02(NX\x16\x00\x00\x00ansible_mitogen.targetq\x00NX\n\x00\x00\x00init_childq'..186) -> {u'fork_context': Context(5, u'fork.28613'), u'home_dir': u'/localhome/ansible', u'good_temp_dir': u'/localhome/ansible/.ansible/tmp'}
[mux  21649] 03:26:20.152786 D mitogen.[fork.28613]: Router(Broker(31d0)): registering Context(4, u'parent') to stream <Stream parent #3510>
[mux  21649] 03:26:20.152887 D mitogen.[fork.28613]: Python version is 2.7.5 (default, Aug  4 2017, 00:39:18)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-16)]
[mux  21649] 03:26:20.152980 D mitogen.[fork.28613]: Parent is context 4 (parent); my ID is 5
[mux  21649] 03:26:20.153096 D mitogen.[fork.28613]: pid:28613 ppid:28586 uid:66400050/66400050, gid:66400050/66400050 host:'host1.example.org'
[mux  21649] 03:26:20.153201 D mitogen.[fork.28613]: Recovered sys.executable: '/usr/bin/python'
[mux  21649] 03:26:20.158649 D mitogen.parent: starting function call to ssh.host1.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 20, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  21649] 03:26:20.160738 D mitogen.[ssh.host1.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 20})}))
[mux  21649] 03:26:20.160929 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.sudo
[mux  21649] 03:26:20.161040 D mitogen.importer.[ssh.host1.example.org]: sending new mitogen.sudo request to parent
[mux  21649] 03:26:20.161168 D mitogen.responder: ssh.host1.example.org requested module mitogen.sudo
[mux  21649] 03:26:20.172942 D mitogen.responder: sending mitogen.sudo (3.36 KiB) to ssh.host1.example.org
[mux  21649] 03:26:20.174825 D mitogen.importer.[ssh.host1.example.org]: received mitogen.sudo
[mux  21649] 03:26:20.178296 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule base64
[mux  21649] 03:26:20.178435 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule optparse
[mux  21649] 03:26:20.184774 D mitogen.parent.[ssh.host1.example.org]: creating connection to context 6 using mitogen.sudo
[mux  21649] 03:26:20.196237 D mitogen.importer.[ssh.host1.example.org]: encodings.ascii is submodule of a locally loaded package
[mux  21649] 03:26:20.196736 D mitogen.importer.[ssh.host1.example.org]: encodings.base64_codec is submodule of a locally loaded package
[mux  21649] 03:26:20.196877 D mitogen.importer.[ssh.host1.example.org]: encodings.base64 is submodule of a locally loaded package
[mux  21649] 03:26:20.197698 D mitogen.parent.[ssh.host1.example.org]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkc1OwzAQhO95itxsq1bqFAWqSJZAPSAOCClC9AAVyo/TWqS2sdOa9unZJogm5cBtv52xZ7Wb0SXXLjLSCEwCS/2AZB0C1Np+YJIGp7ramRlmNGaMnDmjQ7Kgxj2XjXYCZ0OwQ1gOwQNAoDtAfJO3kLoNOQ9RlVsvFQpzVXWi+BLlrs2LRnTydOfstJBqag7tRisEc17aJrzr7IV1UqvX9GrVxQq1lxYY3WX3Lwyt+PhZ7wFs8FigY5wgvJWtXguV5spJ6NxuTOnN2n02LImgriMlnIy0XUfqmM7myfyaIBLA997KVuCYoseH5yfG2JtCMFapK9g+CRb8HZ/2X2kjFGwd2QKRyIq8wvENSxJC0VEa+Kk2/OxbUuQLdDpJbX4CFl3dr/nC7f9z/50yHk/5e8AZ+QYTHLq7\".encode(),\"base64\"),\"zip\"))"
[mux  21649] 03:26:20.201133 D mitogen.parent.[ssh.host1.example.org]: child for Connection(None) started: pid:28615 stdin:18 stdout:18 stderr:16
[mux  21649] 03:26:20.361665 D mitogen.parent.[ssh.host1.example.org]: sudo.root: (partial): Sudo Password:
[mux  21649] 03:26:20.361861 D mitogen.sudo.[ssh.host1.example.org]: sudo.root: (password prompt): Sudo Password:
[mux  21649] 03:26:20.362083 D mitogen.parent.[ssh.host1.example.org]: sudo.root: (partial): Sudo Password:******
[mux  21649] 03:26:20.362365 D mitogen.sudo.[ssh.host1.example.org]: sudo.root: (password prompt): Sudo Password:******
[mux  21649] 03:26:20.362575 D mitogen.parent.[ssh.host1.example.org]: failing connection sudo.root due to PasswordError(u'sudo password is incorrect',)
[mux  21649] 03:26:20.362707 D mitogen.[ssh.host1.example.org]: BootstrapProtocol(sudo.root): disconnecting
[mux  21649] 03:26:20.362827 D mitogen.parent.[ssh.host1.example.org]: failing connection sudo.root due to EofError(u'EOF on stream; last 100 lines received:\n',)
[mux  21649] 03:26:20.363025 D mitogen.parent.[ssh.host1.example.org]: PopenProcess sudo.root pid 28615 still running after IO disconnect, recheck in 0.050s
[mux  21649] 03:26:20.363170 D mitogen.[ssh.host1.example.org]: SetupProtocol(sudo.root): disconnecting
[mux  21649] 03:26:20.363291 D mitogen.[ssh.host1.example.org]: SetupProtocol(sudo.root): disconnecting
[mux  21649] 03:26:20.363474 D mitogen.[ssh.host1.example.org]: Dispatcher: Message(4, 0, 0, 101, 1001, '\x80\x02(NX\x0e\x00\x00\x00mitogen.parentq\x00NX\x0e\x00\x00\x00_proxy_connectq\x01)cm'..456) -> {u'msg': 'error occurred on host host1.example.org: sudo password is incorrect', u'id': None, u'name': None}
[task 21788] 03:26:20.364900 D ansible_mitogen.mixins: _remove_tmp_path(None)
[task 21788] 03:26:20.365828 D mitogen: MitogenProtocol(unix_listener.21649): disconnecting
[mux  21649] 03:26:20.366901 D mitogen: <Side of unix_client.21788 fd 78>: empty read, disconnecting
[task 21788] 03:26:20.366957 D mitogen: Waker(fd=12/13): disconnecting
[mux  21649] 03:26:20.367414 D mitogen: MitogenProtocol(unix_client.21788): disconnecting
[task 21788] 03:26:20.368004 D mitogen: Router(Broker(44a8)): stats: 0 module requests in 0 ms, 0 sent (0 ms minify time), 0 negative responses. Sent 0.0 kb total, 0.0 kb avg.
TASK [nameservers : Manage /etc/resolv.conf] *******************************************
task path: /home/aethylred/ansible/ansible-playbook/ignore/roles/nameservers/tasks/main.yml:4
fatal: [host1.example.org]: FAILED! =>
  msg: 'error occurred on host host1.example.org: sudo password is incorrect'

Aethylred commented 4 years ago

The main thing I notice is that mitogen is still using /usr/bin/python and not /bin/python3 as set by the ansible_python_interpreter... which is wrong, and actually setting that successfully breaks yum 😭

 msg: The Python 2 bindings for rpm are needed for this module. If you require Python 3 support use the `dnf` Ansible module instead.. The Python 2 yum module is needed for this module. If you require Python 3 support use the `dnf` Ansible module instead.

I fixed the previous example to represent this 😸

s1113950 commented 4 years ago

@Aethylred which version of Mitogen are you using? If you're using latest master of Mitogen then it should be determining what python version to use 🤔

Aethylred commented 4 years ago

I'm using mitogen==0.2.9, I'm no longer specifying the ansible_python_interpreter

Aethylred commented 4 years ago

I think /usr/local/lib/python3.6/site-packages/ansible_mitogen/plugins/strategy refers to mitogen as installed via pip:

Confirmed from my bash history:

727  pip3 install mitogen
728  pip3 install --upgrade mitogen

s1113950 commented 4 years ago

Can you try master of Mitogen? master auto detects the correct Python interpreter now :) pip install git+https://github.com/dw/mitogen.git@a18be5afefd1c8b7a860a994773737f788405a93 a18be5afefd1c8b7a860a994773737f788405a93 is the current master hash.

Aethylred commented 4 years ago

I've updated to master as requested, and it seems more reliable, however I've also extended timeout to 60s and set retries to 3. We occasionally still see sudo timing out:

Wednesday 22 July 2020  02:01:49 +0000 (0:00:00.738)       0:00:06.857 ********
[task 13944] 02:01:49.733476 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 13945] 02:01:49.795463 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 13946] 02:01:49.927437 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 13944] 02:01:50.108587 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_tidm2_jj.sock) to connect to "host1.example.org"
[task 13944] 02:01:50.108804 D mitogen.unix: client: connecting to /tmp/mitogen_unix_tidm2_jj.sock
[mux  13840] 02:01:50.109296 D mitogen.unix: listener: accepted connection from PID 13944: unix_client.13944
[task 13944] 02:01:50.119446 D mitogen.unix: client: local ID is 5016, remote is 0
[task 13949] 02:01:50.122440 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[mux  13840] 02:01:50.127085 D mitogen.parent: starting function call to ssh.host1.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 60, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  13840] 02:01:50.141538 D mitogen.[ssh.host1.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 60})}))
[mux  13840] 02:01:50.141699 D mitogen.importer.[ssh.host1.example.org]: requesting mitogen.sudo
[mux  13840] 02:01:50.141822 D mitogen.importer.[ssh.host1.example.org]: sending new mitogen.sudo request to parent
[mux  13840] 02:01:50.141945 D mitogen.responder: ssh.host1.example.org requested module mitogen.sudo
[mux  13840] 02:01:50.157196 D mitogen.responder: sending mitogen.sudo (3.57 KiB) to ssh.host1.example.org
[mux  13840] 02:01:50.176537 D mitogen.importer.[ssh.host1.example.org]: received mitogen.sudo
[mux  13840] 02:01:50.176661 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule base64
[mux  13840] 02:01:50.176761 D mitogen.importer.[ssh.host1.example.org]: mitogen has no submodule optparse
[mux  13840] 02:01:50.187499 D mitogen.parent.[ssh.host1.example.org]: creating connection to context 4012 using mitogen.sudo
[mux  13840] 02:01:50.209549 D mitogen.importer.[ssh.host1.example.org]: encodings.base64_codec is submodule of a locally loaded package
[mux  13840] 02:01:50.209667 D mitogen.importer.[ssh.host1.example.org]: encodings.base64 is submodule of a locally loaded package
[task 13945] 02:01:50.209636 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_tidm2_jj.sock) to connect to "host2.example.org"
[mux  13840] 02:01:50.209768 D mitogen.parent.[ssh.host1.example.org]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"XXXXXX".encode(),\"base64\"),\"zip\"))"
[task 13945] 02:01:50.209817 D mitogen.unix: client: connecting to /tmp/mitogen_unix_tidm2_jj.sock
[mux  13840] 02:01:50.210171 D mitogen.unix: listener: accepted connection from PID 13945: unix_client.13945
[task 13945] 02:01:50.220437 D mitogen.unix: client: local ID is 5017, remote is 0
[mux  13840] 02:01:50.221362 D mitogen.parent.[ssh.host1.example.org]: child for Connection(None) started: pid:29692 stdin:23 stdout:23 stderr:21
[mux  13840] 02:01:50.221862 D mitogen.parent: starting function call to ssh.host2.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 60, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  13840] 02:01:50.242540 D mitogen.[ssh.host2.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 60})}))
[mux  13840] 02:01:50.242674 D mitogen.importer.[ssh.host2.example.org]: requesting mitogen.sudo
[mux  13840] 02:01:50.242777 D mitogen.importer.[ssh.host2.example.org]: sending new mitogen.sudo request to parent
[mux  13840] 02:01:50.242879 D mitogen.responder: ssh.host2.example.org requested module mitogen.sudo
[mux  13840] 02:01:50.243040 D mitogen.responder: sending mitogen.sudo (3.57 KiB) to ssh.host2.example.org
[task 13952] 02:01:50.245226 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[mux  13840] 02:01:50.254598 D mitogen.importer.[ssh.host2.example.org]: received mitogen.sudo
[mux  13840] 02:01:50.265524 D mitogen.importer.[ssh.host2.example.org]: mitogen has no submodule base64
[mux  13840] 02:01:50.265641 D mitogen.importer.[ssh.host2.example.org]: mitogen has no submodule optparse
[mux  13840] 02:01:50.265738 D mitogen.parent.[ssh.host2.example.org]: creating connection to context 12 using mitogen.sudo
[mux  13840] 02:01:50.283638 D mitogen.importer.[ssh.host2.example.org]: encodings.base64_codec is submodule of a locally loaded package
[mux  13840] 02:01:50.283759 D mitogen.importer.[ssh.host2.example.org]: encodings.base64 is submodule of a locally loaded package
[mux  13840] 02:01:50.283859 D mitogen.parent.[ssh.host2.example.org]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"XXXX".encode(),\"base64\"),\"zip\"))"
[mux  13840] 02:01:50.283960 D mitogen.parent.[ssh.host2.example.org]: child for Connection(None) started: pid:4598 stdin:23 stdout:23 stderr:21
[task 13946] 02:01:50.316627 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_tidm2_jj.sock) to connect to "host5.example.org"
[task 13946] 02:01:50.316804 D mitogen.unix: client: connecting to /tmp/mitogen_unix_tidm2_jj.sock
[mux  13840] 02:01:50.317182 D mitogen.unix: listener: accepted connection from PID 13946: unix_client.13946
[task 13946] 02:01:50.327442 D mitogen.unix: client: local ID is 5018, remote is 0
[mux  13840] 02:01:50.328804 D mitogen.parent: starting function call to ssh.host5.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 60, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  13840] 02:01:50.350653 D mitogen.[ssh.host5.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 60})}))
[mux  13840] 02:01:50.350791 D mitogen.importer.[ssh.host5.example.org]: requesting mitogen.sudo
[mux  13840] 02:01:50.350897 D mitogen.importer.[ssh.host5.example.org]: sending new mitogen.sudo request to parent
[mux  13840] 02:01:50.351026 D mitogen.responder: ssh.host5.example.org requested module mitogen.sudo
[mux  13840] 02:01:50.351177 D mitogen.responder: sending mitogen.sudo (3.57 KiB) to ssh.host5.example.org
[mux  13840] 02:01:50.372631 D mitogen.importer.[ssh.host5.example.org]: received mitogen.sudo
[mux  13840] 02:01:50.372751 D mitogen.importer.[ssh.host5.example.org]: mitogen has no submodule base64
[mux  13840] 02:01:50.372849 D mitogen.importer.[ssh.host5.example.org]: mitogen has no submodule optparse
[mux  13840] 02:01:50.383032 D mitogen.parent.[ssh.host5.example.org]: creating connection to context 1012 using mitogen.sudo
[mux  13840] 02:01:50.404629 D mitogen.importer.[ssh.host5.example.org]: encodings.base64_codec is submodule of a locally loaded package
[mux  13840] 02:01:50.404743 D mitogen.importer.[ssh.host5.example.org]: encodings.base64 is submodule of a locally loaded package
[task 13949] 02:01:50.404712 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_tidm2_jj.sock) to connect to "host4.example.org"
[mux  13840] 02:01:50.404840 D mitogen.parent.[ssh.host5.example.org]: command line for Connection(None): sudo -u root -H -- /usr/bin/python -c "import codecs,os,sys;_=codecs.decode;exec(_(_(\"XXXX".encode(),\"base64\"),\"zip\"))"
[task 13949] 02:01:50.404885 D mitogen.unix: client: connecting to /tmp/mitogen_unix_tidm2_jj.sock
[mux  13840] 02:01:50.405227 D mitogen.unix: listener: accepted connection from PID 13949: unix_client.13949
[task 13949] 02:01:50.415436 D mitogen.unix: client: local ID is 5019, remote is 0
[mux  13840] 02:01:50.416446 D mitogen.parent.[ssh.host5.example.org]: child for Connection(None) started: pid:31080 stdin:23 stdout:23 stderr:21
[mux  13840] 02:01:50.416900 D mitogen.parent: starting function call to ssh.host4.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 60, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  13840] 02:01:50.431288 D mitogen.[ssh.host4.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 60})}))
[mux  13840] 02:01:50.431446 D mitogen.importer.[ssh.host4.example.org]: requesting mitogen.sudo
[mux  13840] 02:01:50.431552 D mitogen.importer.[ssh.host4.example.org]: sending new mitogen.sudo request to parent
[mux  13840] 02:01:50.431670 D mitogen.responder: ssh.host4.example.org requested module mitogen.sudo
[mux  13840] 02:01:50.431813 D mitogen.responder: sending mitogen.sudo (3.57 KiB) to ssh.host4.example.org
[task 13952] 02:01:50.432000 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_tidm2_jj.sock) to connect to "host3.example.org"
[task 13952] 02:01:50.432208 D mitogen.unix: client: connecting to /tmp/mitogen_unix_tidm2_jj.sock
[mux  13840] 02:01:50.432596 D mitogen.unix: listener: accepted connection from PID 13952: unix_client.13952
[task 13952] 02:01:50.433036 D mitogen.unix: client: local ID is 5020, remote is 0
[mux  13840] 02:01:50.434632 D mitogen.parent: starting function call to ssh.host3.example.org: mitogen.parent._proxy_connect(name=None, method_name='sudo', kwargs=Kwargs({'unidirectional': True, 'username': 'root', 'password': [secret], 'python_path': ['/usr/bin/python'], 'sudo_path': 'sudo', 'connect_timeout': 60, 'sudo_args': ['-H', '-S', '-n'], 'remote_name': None, 'debug': False, 'profiling': False}))
[mux  13840] 02:01:50.435001 D mitogen.importer.[ssh.host4.example.org]: received mitogen.sudo
[mux  13840] 02:01:50.437465 D mitogen.[ssh.host3.example.org]: Dispatcher: dispatching (None, u'mitogen.parent', None, u'_proxy_connect', (), Kwargs({u'method_name': u'sudo', u'name': None, u'kwargs': Kwargs({u'username': u'root', u'password': [secret], u'profiling': False, u'sudo_path': u'sudo', u'python_path': [u'/usr/bin/python'], u'unidirectional': True, u'debug': False, u'remote_name': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 60})}))
[mux  13840] 02:01:50.437852 D mitogen.importer.[ssh.host3.example.org]: requesting mitogen.sudo
[mux  13840] 02:01:50.438504 D mitogen.importer.[ssh.host3.example.org]: sending new mitogen.sudo request to parent
[mux  13840] 02:01:50.438655 D mitogen.responder: ssh.host3.example.org requested module mitogen.sudo
[mux  13840] 02:01:50.438798 D mitogen.responder: sending mitogen.sudo (3.57 KiB) to ssh.host3.example.org
[mux  13840] 02:01:50.438970 D mitogen.importer.[ssh.host4.example.org]: mitogen has no submodule base64
[mux  13840] 02:01:50.440656 D mitogen.importer.[ssh.host4.example.org]: mitogen has no submodule optparse
[mux  13840] 02:01:50.440792 D mitogen.importer.[ssh.host3.example.org]: received mitogen.sudo
[mux  13840] 02:01:50.444950 D mitogen.importer.[ssh.host3.example.org]: mitogen has no submodule base64
[mux  13840] 02:01:50.447255 D mitogen.importer.[ssh.host3.example.org]: mitogen has no submodule optparse
[mux  13840] 02:01:50.449455 D mitogen.parent.[ssh.host4.example.org]: creating connection to context 3012 using mitogen.sudo
[mux  13840] 02:01:50.455407 D mitogen.parent.[ssh.host3.example.org]: creating connection to context 2012 using mitogen.sudo
[mux  13840] 02:01:50.471817 D mitogen.importer.[ssh.host4.example.org]: encodings.base64_codec is submodule of a locally loaded package
[mux  13840] 02:01:50.472418 D mitogen.importer.[ssh.host4.example.org]: encodings.base64 is submodule of a locally loaded package
[mux  13840] 02:01:50.487046 D mitogen.parent.[ssh.host4.example.org]: child for Connection(None) started: pid:20195 stdin:23 stdout:23 stderr:21
[mux  13840] 02:01:50.487957 D mitogen.parent.[ssh.host3.example.org]: child for Connection(None) started: pid:24676 stdin:23 stdout:23 stderr:21
[mux  13840] 02:01:50.777015 D mitogen.parent.[ssh.host1.example.org]: sudo.root: (partial): Sudo Password:
[mux  13840] 02:01:50.777241 D mitogen.sudo.[ssh.host1.example.org]: sudo.root: (password prompt): Sudo Password:
[mux  13840] 02:01:50.777667 D mitogen.parent.[ssh.host1.example.org]: sudo.root: (unrecognized): Sudo Password:
[mux  13840] 02:01:51.461457 D mitogen.parent.[ssh.host2.example.org]: sudo.root: (partial): Sudo Password:
[mux  13840] 02:01:51.461871 D mitogen.sudo.[ssh.host2.example.org]: sudo.root: (password prompt): Sudo Password:
[mux  13840] 02:01:51.462300 D mitogen.parent.[ssh.host2.example.org]: sudo.root: (partial): Sudo Password:********
[mux  13840] 02:01:51.462722 D mitogen.sudo.[ssh.host2.example.org]: sudo.root: (password prompt): Sudo Password:********
[mux  13840] 02:01:51.462985 D mitogen.parent.[ssh.host2.example.org]: failing connection sudo.root due to PasswordError(u'sudo password is incorrect',)
[mux  13840] 02:01:51.463227 D mitogen.[ssh.host2.example.org]: BootstrapProtocol(sudo.root): disconnecting
[mux  13840] 02:01:51.463515 D mitogen.parent.[ssh.host2.example.org]: failing connection sudo.root due to EofError(u'EOF on stream; last 100 lines received:\n',)
[mux  13840] 02:01:51.463763 D mitogen.parent.[ssh.host2.example.org]: PopenProcess sudo.root pid 4598 still running after IO disconnect, recheck in 0.050s
[mux  13840] 02:01:51.463994 D mitogen.[ssh.host2.example.org]: SetupProtocol(sudo.root): disconnecting
[mux  13840] 02:01:51.464216 D mitogen.[ssh.host2.example.org]: SetupProtocol(sudo.root): disconnecting
[mux  13840] 02:01:51.464559 D mitogen.[ssh.host2.example.org]: Dispatcher: Message(4, 0, 0, 101, 1011, '\x80\x02(NX\x0e\x00\x00\x00mitogen.parentq\x00NX\x0e\x00\x00\x00_proxy_connectq\x01)cm'..456) -> {u'msg': 'error occurred on host host2.example.org: sudo password is incorrect', u'id': None, u'name': None}
[task 13945] 02:01:51.466601 D ansible_mitogen.mixins: _remove_tmp_path(None)
[task 13945] 02:01:51.467537 D mitogen: MitogenProtocol(unix_listener.13840): disconnecting
[mux  13840] 02:01:51.468723 D mitogen: <Side of unix_client.13945 fd 78>: empty read, disconnecting
[mux  13840] 02:01:51.469102 D mitogen: MitogenProtocol(unix_client.13945): disconnecting
[task 13945] 02:01:51.468722 D mitogen: Waker(fd=15/16): disconnecting
[task 13945] 02:01:51.469796 D mitogen: Router(Broker(eef0)): stats: 0 module requests in 0 ms, 0 sent (0 ms minify time), 0 negative responses. Sent 0.0 kb total, 0.0 kb avg.

TASK [Who am I now?] ************************************************************************
task path: /home/hicksaw/hpcf-ansible/ansible-k8s/conntest.yaml:30
fatal: [host2.example.org]: FAILED! =>
  msg: 'error occurred on host host2.example.org: sudo password is incorrect'

Aethylred commented 4 years ago

Adding this sudo rule makes it intermittent (sudo rules with wildcards are very bad):

ansible ALL = (ALL) NOPASSWD:/usr/bin/python -c*

So does adding the following sudo rule to our IPA server

> ipa sudorule-show allow-ansible-python
  Rule name: allow-ansible-python
  Enabled: TRUE
  User category: all
  RunAs User category: all
  RunAs Group category: all
  Host Groups: ansible-hosts
  Sudo Allow Commands: /usr/bin/python
  Sudo Option: !authenticate

However, we consider this to be a terrible idea and would rather that mitogen properly uses become passwords.

Aethylred commented 3 years ago

I've done some tests with v0.3.0rc1 and this issue persists.

Aethylred commented 3 years ago

A less risky sudo rule is:

ansible ALL = (ALL) NOPASSWD:/usr/bin/python

Though you probably want to create a command group with all the Python executables you would like Ansible to use.

mickaelperrin commented 11 months ago

I can confirm the issue.

I encountered it with:

ansible 2.12.10
mitogen 0.3.4

Reverting to mitogen 0.3.3 resolved the issue.

azmeuk commented 7 months ago

1007 solved this issue for me. Thank you @moreati :bow:

mitogen-hq / mitogen

sudo fails intermittently #726

1007 solved this issue for me. Thank you @moreati :bow: