search

mitogen-hq / mitogen

Distributed self-replicating programs in Python
https://mitogen.networkgenomics.com/
BSD 3-Clause "New" or "Revised" License
2.34k stars 199 forks source link

yum module hangs #195

Closed rouge8 closed 6 years ago

rouge8 commented 6 years ago

The yum module seems to hang, even when running this playbook against a single host:

---

- hosts: all
  tasks:
    - yum: name=yum-cron state=installed

Here's the -vvv output for that task:

[pid 44923] 14:36:19.893254 E mitogen: Router(Broker(0x10e1a7810)): no route for Message(1, 2, 2, 1004, 0, '\x80\x02N.'..4), my ID is 0
task path: /Users/andy/gr/myproject/ansible/playbooks/foo.yml:5
[pid 44926] 14:36:19.919092 D ansible_mitogen.mixins: _remote_expand_user(u'~/.ansible/tmp', sudoable=True)
[pid 44926] 14:36:19.920971 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_Gpgeop')
[pid 44926] 14:36:19.922445 D mitogen: unix.connect(): local ID is 1003, remote is 0
[pid 44923] 14:36:19.925884 D ansible_mitogen.services: ansible_mitogen.services.JobResultService().listen(job_id='78ae9303f7840115', sender=Sender(Context(1003, None), 1001))
[pid 44926] 14:36:19.926011 D mitogen: Context(2, u'ssh.env1-stage-bastion').call_async(<function run_module at 0x10e1928c0>, *({'should_fork': False, 'job_id': '78ae9303f7840115', 'remote_tmp': u'/home/ec2-user/.ansible/tmp', 'args': {'_ansible_version': '2.4.4.0', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], u'name': u'yum-cron', '_ansible_module_name': u'yum', '_ansible_syslog_facility': u'LOG_USER', '_ansible_verbosity': 3, '_ansible_socket': None, u'state': u'installed', '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False, '_ansible_no_log': False}, 'module': u'yum', 'service_context': Context(0, None), 'env': {}, 'interpreter': u'/usr/bin/python', 'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py', 'interpreter_arg': '-tt', 'runner_name': 'NewStyleRunner'},), **{})
[pid 44923] 14:36:19.927039 D ansible_mitogen.services: ansible_mitogen.services.FileService(): registering '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 44923] 14:36:19.965752 D ansible_mitogen.services: Serving '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'

Same setup as https://github.com/dw/mitogen/issues/150 -- OS X master, Amazon Linux target.

dw commented 6 years ago

Hi Andy!

Did this just start happening on you recently? Will setup a local repro

rouge8 commented 6 years ago

I haven't been testing mitogen for a couple weeks, the log in the issue is from 6394226722703e8cdb0784570a610ea5ef86e5a4 (I forgot to pull... 😳), but it also happens with 79fb65c5d69cebc515a316be912194a4e9003c60. Updated logs:

[pid 45516] 14:44:36.511390 E mitogen: Router(Broker(0x10294be90)): no route for Message(1, 2, 2, 1004, 0, '\x80\x02N.'..4), my ID is 0
[pid 45520] 14:44:36.529518 D ansible_mitogen.mixins: _remote_expand_user(u'~/.ansible/tmp', sudoable=True)
[pid 45520] 14:44:36.531205 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_sTNlOh')
[pid 45520] 14:44:36.532497 D mitogen: unix.connect(): local ID is 1003, remote is 0
[pid 45520] 14:44:36.536554 D ansible_mitogen.planner: <ansible_mitogen.planner.BinaryPlanner object at 0x10288d110> rejected u'yum'
[pid 45516] 14:44:36.536590 D ansible_mitogen.services: ansible_mitogen.services.JobResultService().listen(job_id='83e7ea4e77264f4f', sender=Sender(Context(1003, None), 1001))
[pid 45520] 14:44:36.536989 D ansible_mitogen.planner: <ansible_mitogen.planner.NewStylePlanner object at 0x1028d0ad0> accepted u'yum' (filename '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py')
[pid 45516] 14:44:36.537756 D ansible_mitogen.services: ansible_mitogen.services.FileService(): registering '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 45520] 14:44:36.540112 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function run_module at 0x10295c2a8>, *({'should_fork': False, 'job_id': '83e7ea4e77264f4f', 'remote_tmp': u'/home/ec2-user/.ansible/tmp', 'args': {'_ansible_version': '2.4.4.0', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], u'name': u'yum-cron', '_ansible_module_name': u'yum', '_ansible_syslog_facility': u'LOG_USER', '_ansible_verbosity': 3, '_ansible_socket': None, u'state': u'installed', '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False, '_ansible_no_log': False}, 'module': u'yum', 'service_context': Context(0, None), 'env': {}, 'interpreter': u'/usr/bin/python', 'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py', 'interpreter_arg': '-tt', 'runner_name': 'NewStyleRunner'},), **{})
[pid 45516] 14:44:36.580638 D ansible_mitogen.services: Serving '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'

Sorry for the less informative than usual issue, my brain went totally blank 😂

dw commented 6 years ago

Can't reproduce locally :/ Just double-checking brain mush mode.. does running it with vanilla ansible succeed? :)

rouge8 commented 6 years ago

Yeah, works with stock Ansible 2.4.4.0.

On Wed, Apr 18, 2018 at 2:54 PM, dw notifications@github.com wrote:

Can't reproduce locally :/ Just double-checking brain mush mode.. does running it with vanilla ansible succeed? :)

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/dw/mitogen/issues/195#issuecomment-382541628, or mute the thread https://github.com/notifications/unsubscribe-auth/AAOdzcmPRgeZJrCYiChpM3dmAMZkRVNHks5tp7YZgaJpZM4Ta0OU .

dw commented 6 years ago

Can you paste the last log entry further back originating from the context? They look like

[pid 39035] 23:13:52.886071 D mitogen.ctx.ssh.54.246.255.137: I am a log entry

Where 'mitogen.ctx.ssh.*' is the giveaway :)

I just pushed some extra logging to 'dmw' branch (master doesn't get direct commits any more!), might be lucky and those new entries catch something.

rouge8 commented 6 years ago

I updated the playbook to have gather_facts: false, still hangs, but I'm much more comfortable sending all the logs. :)

So logs from f06ae05734808a93ceac8e5397dc362f1b204f19 -- you can see where I ctrl-C and I included the logs from after that too:

$ .tox/deploy/bin/ansible-playbook ansible/playbooks/foo.yml -l env1-stage-web -vvv
ansible-playbook 2.4.4.0
  config file = /Users/andy/gr/myproject/ansible.cfg
  configured module search path = [u'/Users/andy/gr/myproject/ansible/library', u'/Users/andy/gr/myproject/ansible/library/vendor']
  ansible python module location = /Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible
  executable location = .tox/deploy/bin/ansible-playbook
  python version = 2.7.14 (default, Mar 10 2018, 00:01:11) [GCC 4.2.1 Compatible Apple LLVM 8.0.0 (clang-800.0.42.1)]
Using /Users/andy/gr/myproject/ansible.cfg as config file
Parsed /Users/andy/gr/myproject/ansible/inventory_from_ssh_config.py inventory source with script plugin

PLAYBOOK: foo.yml ******************************************************************************************************************************
1 plays in ansible/playbooks/foo.yml

PLAY [all] *************************************************************************************************************************************
[pid 46244] 15:19:18.987067 D ansible_mitogen.process: Service pool configured: size=16
META: ran handlers

TASK [yum] *************************************************************************************************************************************
task path: /Users/andy/gr/myproject/ansible/playbooks/foo.yml:6
[pid 46245] 15:19:19.042765 D ansible_mitogen.mixins: _remote_expand_user(u'~/.ansible/tmp', sudoable=True)
[pid 46245] 15:19:19.044587 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_FrniPA')
[pid 46245] 15:19:19.046217 D mitogen: unix.connect(): local ID is 1, remote is 0
[pid 46245] 15:19:19.047711 D mitogen: service.call_async(Context(0, None), 500, 'get', {'username': u'ec2-user', 'check_host_keys': False, 'hostname': u'env1-stage-web', 'identity_file': None, 'connect_timeout': 10, 'method_name': 'ssh', 'python_path': u'/usr/bin/python', 'ssh_path': u'ssh', 'password': None, 'port': None, 'ssh_args': ['-F', 'ansible/ssh_config', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=60s']})
[pid 46244] 15:19:19.053564 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 46244] 15:19:19.166770 D mitogen: hybrid_tty_create_child() pid=46246 stdio=81, tty=78, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "ServerAliveInterval 15" "-o" "ServerAliveCountMax 3" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-o" "GlobalKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env1-stage-web" "/usr/bin/python2.7" "-c" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdkMFqwzAMhs/LU+wmm7rBbk2hgUBHGLuHsRy2MZLYLaaJbZx0bvf0c0hhzi5Cn35JP1JJqtwMqVVWIpw44iNSx8cAR+POCGfJQ8jFxW4QJYxS/MclickFlc3cdmaQqIzBxVDF4GeQ+ls5o9/hqXx5o/CZD7dQvMr2MtZNJ+eegB1aCmSJK0C9Gs1J6qzW4naYwvpkjHDX9HXdm0Z1Mm1Nn/HdhnMMOAl7vVOjRIzAc0E/dKgV+ReaPiCMlTrcDa4BnDpZC8Qo31FM4EfZefjeVBHwEB5yX1bEml9qsN3z7T4YrYr/9myy/wXlOX4p\".encode(),\"base64\"),\"zip\"))'"
[pid 46244] 15:19:19.170582 D mitogen: mitogen.ssh.Stream('local.46246').connect(): child process stdin/stdout=81
[pid 46244] 15:19:19.818344 D mitogen: mitogen.ssh.Stream('local.46246'): received "Warning: Permanently added 'env1-stage-web' (ECDSA) to the list of known hosts.\r\n"
[pid 46244] 15:19:20.140448 D mitogen: mitogen.ssh.Stream('local.46246'): received 'EC0\n'
[pid 46244] 15:19:20.140908 D mitogen: mitogen.ssh.Stream('local.46246')._ec0_received()
[pid 46244] 15:19:20.263727 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function expanduser at 0x103f2a938>, *('~',), **{})
[pid 46244] 15:19:20.304589 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function start_fork_parent at 0x105f50f50>, *(), **{})
[pid 46245] 15:19:20.306781 D mitogen: service.call_async(Context(0, None), 502, 'listen', {'job_id': 'c33720cf300026a4', 'sender': Sender(Context(1, None), 1001)})
[pid 46245] 15:19:20.308004 D ansible_mitogen.planner: <ansible_mitogen.planner.BinaryPlanner object at 0x105f76c90> rejected u'yum'
[pid 46244] 15:19:20.308151 D ansible_mitogen.services: ansible_mitogen.services.JobResultService().listen(job_id='c33720cf300026a4', sender=Sender(Context(1, None), 1001))
[pid 46245] 15:19:20.308393 D ansible_mitogen.planner: <ansible_mitogen.planner.NewStylePlanner object at 0x105f76fd0> accepted u'yum' (filename '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py')
[pid 46245] 15:19:20.308911 D mitogen: service.call_async(Context(0, None), 501, 'register', {'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'})
[pid 46244] 15:19:20.309522 D ansible_mitogen.services: ansible_mitogen.services.FileService(): registering '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 46245] 15:19:20.312086 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function run_module at 0x105f51320>, *({'should_fork': False, 'job_id': 'c33720cf300026a4', 'remote_tmp': u'/home/ec2-user/.ansible/tmp', 'args': {'_ansible_version': '2.4.4.0', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], u'name': u'yum-cron', '_ansible_module_name': u'yum', '_ansible_syslog_facility': u'LOG_USER', '_ansible_verbosity': 3, '_ansible_socket': None, u'state': u'installed', '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False, '_ansible_no_log': False}, 'module': u'yum', 'service_context': Context(0, None), 'env': {}, 'interpreter': u'/usr/bin/python', 'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py', 'interpreter_arg': '-tt', 'runner_name': 'NewStyleRunner'},), **{})
[pid 46244] 15:19:20.344317 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible_mitogen')
[pid 46244] 15:19:20.345590 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen') -> <pkgutil.ImpLoader instance at 0x1060d3d88>
[pid 46244] 15:19:20.346978 D mitogen: _build_tuple('/Users/andy/forks/mitogen/ansible_mitogen/__init__.py', 'ansible_mitogen') -> ['connection', 'helpers', 'logging', 'mixins', 'planner', 'process', 'runner', 'services', 'strategy', 'target']
[pid 46244] 15:19:20.347461 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen')
[pid 46244] 15:19:20.388050 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible_mitogen.target')
[pid 46244] 15:19:20.388687 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.target') -> <pkgutil.ImpLoader instance at 0x1060d3d40>
[pid 46244] 15:19:20.391949 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.target')
[pid 46244] 15:19:20.439399 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible_mitogen.runner')
[pid 46244] 15:19:20.440016 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.runner') -> <pkgutil.ImpLoader instance at 0x1060d3cf8>
[pid 46244] 15:19:20.443833 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.runner')
[pid 46244] 15:19:20.487267 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('mitogen.service')
[pid 46244] 15:19:20.487905 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.service') -> <pkgutil.ImpLoader instance at 0x105e9aea8>
[pid 46244] 15:19:20.491085 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.core') -> <pkgutil.ImpLoader instance at 0x105e9ac20>
[pid 46244] 15:19:20.505930 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.master') -> <pkgutil.ImpLoader instance at 0x105f86440>
[pid 46244] 15:19:20.511704 D mitogen: pkgutil._get_module_via_pkgutil('mitogen') -> <pkgutil.ImpLoader instance at 0x105f86878>
[pid 46244] 15:19:20.513589 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.parent') -> <pkgutil.ImpLoader instance at 0x105f86e18>
[pid 46244] 15:19:20.524519 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat') -> <pkgutil.ImpLoader instance at 0x105f8e950>
[pid 46244] 15:19:20.526866 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat.functools') -> <pkgutil.ImpLoader instance at 0x105f8eab8>
[pid 46244] 15:19:20.529409 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat.collections') -> <pkgutil.ImpLoader instance at 0x105f8e440>
[pid 46244] 15:19:20.531233 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat')
[pid 46244] 15:19:20.533882 D mitogen: _build_tuple('/Users/andy/forks/mitogen/mitogen/compat/__init__.py', 'mitogen.compat') -> ['collections', 'functools', 'pkgutil', 'tokenize']
[pid 46244] 15:19:20.534817 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat.collections')
[pid 46244] 15:19:20.536502 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat.functools')
[pid 46244] 15:19:20.539244 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.master')
[pid 46244] 15:19:20.541710 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.parent')
[pid 46244] 15:19:20.545322 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.service')
[pid 46244] 15:19:20.772694 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible')
[pid 46244] 15:19:20.774641 D mitogen: pkgutil._get_module_via_pkgutil('ansible') -> <pkgutil.ImpLoader instance at 0x105f8e9e0>
[pid 46244] 15:19:20.777583 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/__init__.py', 'ansible') -> ['cli', 'compat', 'config', 'constants', 'errors', 'executor', 'galaxy', 'inventory', 'module_utils', 'modules', 'parsing', 'playbook', 'plugins', 'release', 'template', 'utils', 'vars']
[pid 46244] 15:19:20.778377 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible')
[pid 46244] 15:19:20.819213 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible.release')
[pid 46244] 15:19:20.822005 D mitogen: pkgutil._get_module_via_pkgutil('ansible.release') -> <pkgutil.ImpLoader instance at 0x105f8e440>
[pid 46244] 15:19:20.824322 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.release')
[pid 46244] 15:19:20.864477 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible.module_utils')
[pid 46244] 15:19:20.865520 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils') -> <pkgutil.ImpLoader instance at 0x105f88710>
[pid 46244] 15:19:20.870122 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/__init__.py', 'ansible.module_utils') -> ['_text', 'a10', 'aci', 'aireos', 'ansible_tower', 'aos', 'api', 'aruba', 'asa', 'avi', 'aws', 'azure_rm_common', 'basic', 'bigswitch_utils', 'ce', 'cloud', 'cloudstack', 'cnos', 'cnos_devicerules', 'cnos_errorcodes', 'connection', 'crypto', 'database', 'dellos10', 'dellos6', 'dellos9', 'digital_ocean', 'dimensiondata', 'docker_common', 'ec2', 'eos', 'exoscale', 'f5_utils', 'facts', 'fortios', 'gcdns', 'gce', 'gcp', 'infinibox', 'ios', 'iosxr', 'ipa', 'ismount', 'json_utils', 'junos', 'k8s_common', 'known_hosts', 'lxd', 'manageiq', 'mysql', 'netapp', 'netcfg', 'netcli', 'netconf', 'netscaler', 'network', 'network_common', 'nxos', 'oneview', 'openshift_common', 'openstack', 'ordnance', 'ovirt', 'parsing', 'postgres', 'powershell', 'pure', 'pycompat24', 'rax', 'redhat', 'service', 'six', 'splitter', 'sros', 'univention_umc', 'urls', 'vca', 'vmware', 'vyos']
[pid 46244] 15:19:20.871785 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils')
[pid 46244] 15:19:20.911859 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible.module_utils.basic')
[pid 46244] 15:19:20.912578 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.basic') -> <pkgutil.ImpLoader instance at 0x105f887e8>
[pid 46244] 15:19:20.950514 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing.convert_bool') -> <pkgutil.ImpLoader instance at 0x105f96cf8>
[pid 46244] 15:19:20.951946 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils._text') -> <pkgutil.ImpLoader instance at 0x105f96f80>
[pid 46244] 15:19:20.953429 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.pycompat24') -> <pkgutil.ImpLoader instance at 0x105f9c950>
[pid 46244] 15:19:20.955285 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.six') -> <pkgutil.ImpLoader instance at 0x105f95dd0>
[pid 46244] 15:19:20.964300 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing') -> <pkgutil.ImpLoader instance at 0x105f88908>
[pid 46244] 15:19:20.965063 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils._text')
[pid 46244] 15:19:20.965981 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.parsing')
[pid 46244] 15:19:20.967096 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/parsing/__init__.py', 'ansible.module_utils.parsing') -> ['convert_bool']
[pid 46244] 15:19:20.967697 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.parsing.convert_bool')
[pid 46244] 15:19:20.968206 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.pycompat24')
[pid 46244] 15:19:20.969079 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.six')
[pid 46244] 15:19:20.970025 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/six/__init__.py', 'ansible.module_utils.six') -> []
[pid 46244] 15:19:20.973972 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.basic')
[pid 46244] 15:19:21.285908 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('ansible_mitogen.services')
[pid 46244] 15:19:21.286800 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.services') -> <pkgutil.ImpLoader instance at 0x105f886c8>
[pid 46244] 15:19:21.289947 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.services')
[pid 46244] 15:19:21.368688 D mitogen: ModuleResponder(Router(Broker(0x105f59e50)))._on_get_module('mitogen.fork')
[pid 46244] 15:19:21.369221 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.fork') -> <pkgutil.ImpLoader instance at 0x105f96d88>
[pid 46244] 15:19:21.370575 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.fork')
[pid 46244] 15:19:21.417182 D mitogen.ctx.ssh.env1-stage-web: mitogen: Router(Broker(0x7f93fd329c50)).upgrade()
[pid 46244] 15:19:21.417507 D mitogen: IdAllocator(Router(Broker(0x105f59e50))): allocating (3..1003]
[pid 46244] 15:19:21.417823 D mitogen: IdAllocator(Router(Broker(0x105f59e50))): allocating [Context(3, None)..Context(2, u'ssh.env1-stage-web')) to 2
[pid 46244] 15:19:21.459683 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('default').connect()
[pid 46244] 15:19:21.497307 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('fork.26401').connect(): child process stdin/stdout=15
[pid 46244] 15:19:21.497691 D mitogen: Adding route to 3 via mitogen.ssh.Stream(u'ssh.env1-stage-web')
[pid 46244] 15:19:21.497918 D mitogen: Router(Broker(0x105f59e50)).add_route(3, mitogen.ssh.Stream(u'ssh.env1-stage-web'))
[pid 46244] 15:19:21.498183 D mitogen.ctx.ssh.env1-stage-web: ansible_mitogen.target: target.get_file(): fetching '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py' from Context(0, None)
[pid 46244] 15:19:21.498447 D mitogen.ctx.ssh.env1-stage-web: mitogen: service.call_async(Context(0, None), 501, 'fetch', {'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'})
[pid 46244] 15:19:21.498856 D mitogen.ctx.fork.26401: mitogen: register(Context(2, 'parent'), mitogen.core.Stream('parent'))
[pid 46244] 15:19:21.499222 D mitogen.ctx.fork.26401: mitogen: Connected to Context(2, 'parent'); my ID is 3, PID is 26401
[pid 46244] 15:19:21.500459 D mitogen.ctx.fork.26401: mitogen: Recovered sys.executable: '/usr/bin/python2.7'
[pid 46244] 15:19:21.501942 D ansible_mitogen.services: Serving '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 46244] 15:19:21.587052 D mitogen.ctx.ssh.env1-stage-web: ansible_mitogen.target: target.get_file(): fetched '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py' from Context(0, None)

^C [ERROR]: User interrupted execution

 [ERROR]: User interrupted execution

[pid 46244] 15:20:08.972654 D mitogen: mitogen.core.Stream('unix_client.46245').on_disconnect()
[pid 46244] 15:20:08.974398 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-4'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.974807 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-6'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.975181 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-5'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.975641 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-7'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.976081 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-9'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.976435 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-8'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.976790 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-11'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.977153 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-10'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.977507 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-12'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.977870 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-13'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.978235 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-14'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.978618 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-0'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.979122 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-2'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.978878 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-1'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.979864 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-3'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.979013 E mitogen: mitogen.service.Pool(0x105f675d0, size=16, th='mitogen.service.Pool.105f675d0.worker-15'): channel or latch closed, exitting: None
[pid 46244] 15:20:08.981020 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web') closing CALL_FUNCTION channel
[pid 46244] 15:20:08.981410 D mitogen: Waker(Broker(0x105f59e50) rfd=16, wfd=43).on_disconnect()
[pid 46244] 15:20:08.981839 D mitogen: <mitogen.unix.Listener object at 0x105f67310>.on_disconnect()
[pid 46244] 15:20:09.021885 D mitogen.ctx.ssh.env1-stage-web: mitogen: Waker(Broker(0x7f93fd329c50) rfd=3, wfd=4).on_disconnect()
[pid 46244] 15:20:09.022265 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('fork.26401') closing CALL_FUNCTION channel
[pid 46244] 15:20:09.022520 D mitogen.ctx.ssh.env1-stage-web: mitogen: <IoLogger stdout>.on_disconnect()
[pid 46244] 15:20:09.022767 D mitogen.ctx.ssh.env1-stage-web: mitogen: <IoLogger stderr>.on_disconnect()
[pid 46244] 15:20:09.059154 D mitogen.ctx.fork.26401: mitogen: _on_shutdown_msg(Message(3, 2, 2, 106, 0, ''..0))
[pid 46244] 15:20:09.060861 D mitogen: mitogen.parent.TtyLogStream(mitogen.ssh.Stream(u'ssh.env1-stage-web')).on_disconnect()
[pid 46244] 15:20:09.061520 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web'): child process exit status was 65280
[pid 46244] 15:20:09.061882 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web').on_disconnect()
[pid 46244] 15:20:09.062592 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web') is gone; propagating DEL_ROUTE for set([2, 3])
[pid 46244] 15:20:09.063056 D mitogen: Router(Broker(0x105f59e50)).del_route(2)
[pid 46244] 15:20:09.063380 D mitogen: Router(Broker(0x105f59e50)).del_route(3)
dw commented 6 years ago

Hi Andy,

It's really strange that the runner successfully fetches the file then 'nothing happens', meanwhile the broker thread is still healthy enough to gracefully tear the process down. So something about the yum module is broken.

I've just checked into 'dmw' branch a new debug mode. Can you please pull and run like:

MITOGEN_DUMP_THREAD_STACKS=1 ansible-playbook my.yml -vvv

Every 5 seconds, every context will log a stack trace from every thread. That's a lot of noise! But the MainThread from the hung context should have some very useful information visible

rouge8 commented 6 years ago

Re-ran on 65fb6ff9feec28f49b0f7276b66702bf7553bd24:

$ MITOGEN_DUMP_THREAD_STACKS=1 .tox/deploy/bin/ansible-playbook ansible/playbooks/foo.yml -l env1-stage-web -vvv
ansible-playbook 2.4.4.0
  config file = /Users/andy/gr/myproject/ansible.cfg
  configured module search path = [u'/Users/andy/gr/myproject/ansible/library', u'/Users/andy/gr/myproject/ansible/library/vendor']
  ansible python module location = /Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible
  executable location = .tox/deploy/bin/ansible-playbook
  python version = 2.7.14 (default, Mar 10 2018, 00:01:11) [GCC 4.2.1 Compatible Apple LLVM 8.0.0 (clang-800.0.42.1)]
Using /Users/andy/gr/myproject/ansible.cfg as config file
Parsed /Users/andy/gr/myproject/ansible/inventory_from_ssh_config.py inventory source with script plugin

PLAYBOOK: foo.yml ******************************************************************************************************************************
1 plays in ansible/playbooks/foo.yml

PLAY [all] *************************************************************************************************************************************
[pid 46808] 16:09:46.645280 D ansible_mitogen.process: Service pool configured: size=16
META: ran handlers

TASK [yum] *************************************************************************************************************************************
task path: /Users/andy/gr/myproject/ansible/playbooks/foo.yml:6
[pid 46809] 16:09:46.696587 D ansible_mitogen.mixins: _remote_expand_user(u'~/.ansible/tmp', sudoable=True)
[pid 46809] 16:09:46.700660 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_039Q0C')
[pid 46809] 16:09:46.702627 D mitogen: unix.connect(): local ID is 1, remote is 0
[pid 46809] 16:09:46.704530 D mitogen: service.call_async(Context(0, None), 500, 'get', {'username': u'ec2-user', 'check_host_keys': False, 'hostname': u'env1-stage-web', 'identity_file': None, 'connect_timeout': 10, 'method_name': 'ssh', 'python_path': u'/usr/bin/python', 'ssh_path': u'ssh', 'password': None, 'port': None, 'ssh_args': ['-F', 'ansible/ssh_config', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=60s']})
[pid 46808] 16:09:46.710012 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 46808] 16:09:46.838615 D mitogen: hybrid_tty_create_child() pid=46810 stdio=81, tty=78, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "ServerAliveInterval 15" "-o" "ServerAliveCountMax 3" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-o" "GlobalKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env1-stage-web" "/usr/bin/python2.7" "-c" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdkMFqwzAMhs/LU+wmm7rB3tLSBQIbYewexnJYx0hit5gllnHSpd3TzyGFObsIffol/UgFKzPsY6utIjRybAxIH249HNB9EZpGNz6XJ3tHOBOc0z8uWEjOq2LmpsVekSIEF0IZwjiDMt/aoXmHp+LljcNH1l988aya01DVrZp7PLZkKbAlroB0esCjMmll5OVxCusjonTn+HXdYa1bFTfYpcl2x3cUaOT3jk4PiggGzznfG1/Ls08yfUCiVcbfDa4GGjtVSSJ4st1QBj/azsPXppLBCP4h12V5qI1LDe4fkk3ijVb5f3sx2f8C6ld+MQ==\".encode(),\"base64\"),\"zip\"))'"
[pid 46808] 16:09:46.840574 D mitogen: mitogen.ssh.Stream('local.46810').connect(): child process stdin/stdout=81
[pid 46808] 16:09:47.486284 D mitogen: mitogen.ssh.Stream('local.46810'): received "Warning: Permanently added 'env1-stage-web' (ECDSA) to the list of known hosts.\r\n"
[pid 46808] 16:09:47.812475 D mitogen: mitogen.ssh.Stream('local.46810'): received 'EC0\n'
[pid 46808] 16:09:47.812845 D mitogen: mitogen.ssh.Stream('local.46810')._ec0_received()
[pid 46808] 16:09:47.936780 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function expanduser at 0x109031938>, *('~',), **{})
[pid 46808] 16:09:47.976869 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function start_fork_parent at 0x10b054ed8>, *(), **{})
[pid 46808] 16:09:47.982040 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function dump_to_logger at 0x10b1e51b8>, *(), **{})
[pid 46808] 16:09:48.022011 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible_mitogen')
[pid 46808] 16:09:48.022756 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen') -> <pkgutil.ImpLoader instance at 0x10b1d9f80>
[pid 46808] 16:09:48.023765 D mitogen: _build_tuple('/Users/andy/forks/mitogen/ansible_mitogen/__init__.py', 'ansible_mitogen') -> ['connection', 'helpers', 'logging', 'mixins', 'planner', 'process', 'runner', 'services', 'strategy', 'target']
[pid 46808] 16:09:48.024747 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen')
[pid 46808] 16:09:48.066840 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible_mitogen.target')
[pid 46808] 16:09:48.068603 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.target') -> <pkgutil.ImpLoader instance at 0x10b1d9ef0>
[pid 46808] 16:09:48.071611 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.target')
[pid 46808] 16:09:48.120193 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible_mitogen.runner')
[pid 46808] 16:09:48.120871 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.runner') -> <pkgutil.ImpLoader instance at 0x10b1e98c0>
[pid 46808] 16:09:48.124709 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.runner')
[pid 46808] 16:09:48.168299 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('mitogen.service')
[pid 46808] 16:09:48.168903 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.service') -> <pkgutil.ImpLoader instance at 0x10b1c1290>
[pid 46808] 16:09:48.172073 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.core') -> <pkgutil.ImpLoader instance at 0x10b0d4170>
[pid 46808] 16:09:48.190096 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.master') -> <pkgutil.ImpLoader instance at 0x10b0907a0>
[pid 46808] 16:09:48.197268 D mitogen: pkgutil._get_module_via_pkgutil('mitogen') -> <pkgutil.ImpLoader instance at 0x10b090bd8>
[pid 46808] 16:09:48.199331 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.parent') -> <pkgutil.ImpLoader instance at 0x10b090d40>
[pid 46808] 16:09:48.207365 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat') -> <pkgutil.ImpLoader instance at 0x10b1d9ef0>
[pid 46808] 16:09:48.208457 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat.functools') -> <pkgutil.ImpLoader instance at 0x10b1d9e18>
[pid 46808] 16:09:48.214363 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.compat.collections') -> <pkgutil.ImpLoader instance at 0x10b09c560>
[pid 46808] 16:09:48.217092 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat')
[pid 46808] 16:09:48.217973 D mitogen: _build_tuple('/Users/andy/forks/mitogen/mitogen/compat/__init__.py', 'mitogen.compat') -> ['collections', 'functools', 'pkgutil', 'tokenize']
[pid 46808] 16:09:48.218469 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat.collections')
[pid 46808] 16:09:48.219133 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.compat.functools')
[pid 46808] 16:09:48.220103 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.master')
[pid 46808] 16:09:48.222828 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.parent')
[pid 46808] 16:09:48.226647 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.service')
[pid 46808] 16:09:48.449509 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible')
[pid 46808] 16:09:48.451510 D mitogen: pkgutil._get_module_via_pkgutil('ansible') -> <pkgutil.ImpLoader instance at 0x10b0d4170>
[pid 46808] 16:09:48.455033 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/__init__.py', 'ansible') -> ['cli', 'compat', 'config', 'constants', 'errors', 'executor', 'galaxy', 'inventory', 'module_utils', 'modules', 'parsing', 'playbook', 'plugins', 'release', 'template', 'utils', 'vars']
[pid 46808] 16:09:48.455711 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible')
[pid 46808] 16:09:48.499553 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible.release')
[pid 46808] 16:09:48.500246 D mitogen: pkgutil._get_module_via_pkgutil('ansible.release') -> <pkgutil.ImpLoader instance at 0x10b0d4248>
[pid 46808] 16:09:48.502007 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.release')
[pid 46808] 16:09:48.548160 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible.module_utils')
[pid 46808] 16:09:48.548832 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils') -> <pkgutil.ImpLoader instance at 0x10b09ccb0>
[pid 46808] 16:09:48.551510 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/__init__.py', 'ansible.module_utils') -> ['_text', 'a10', 'aci', 'aireos', 'ansible_tower', 'aos', 'api', 'aruba', 'asa', 'avi', 'aws', 'azure_rm_common', 'basic', 'bigswitch_utils', 'ce', 'cloud', 'cloudstack', 'cnos', 'cnos_devicerules', 'cnos_errorcodes', 'connection', 'crypto', 'database', 'dellos10', 'dellos6', 'dellos9', 'digital_ocean', 'dimensiondata', 'docker_common', 'ec2', 'eos', 'exoscale', 'f5_utils', 'facts', 'fortios', 'gcdns', 'gce', 'gcp', 'infinibox', 'ios', 'iosxr', 'ipa', 'ismount', 'json_utils', 'junos', 'k8s_common', 'known_hosts', 'lxd', 'manageiq', 'mysql', 'netapp', 'netcfg', 'netcli', 'netconf', 'netscaler', 'network', 'network_common', 'nxos', 'oneview', 'openshift_common', 'openstack', 'ordnance', 'ovirt', 'parsing', 'postgres', 'powershell', 'pure', 'pycompat24', 'rax', 'redhat', 'service', 'six', 'splitter', 'sros', 'univention_umc', 'urls', 'vca', 'vmware', 'vyos']
[pid 46808] 16:09:48.552052 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils')
[pid 46808] 16:09:48.592324 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible.module_utils.basic')
[pid 46808] 16:09:48.593126 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.basic') -> <pkgutil.ImpLoader instance at 0x10b09c7e8>
[pid 46808] 16:09:48.634103 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing.convert_bool') -> <pkgutil.ImpLoader instance at 0x10b0a0758>
[pid 46808] 16:09:48.635911 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils._text') -> <pkgutil.ImpLoader instance at 0x10b0a0878>
[pid 46808] 16:09:48.638001 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.pycompat24') -> <pkgutil.ImpLoader instance at 0x10b0a0830>
[pid 46808] 16:09:48.639436 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.six') -> <pkgutil.ImpLoader instance at 0x10b0a06c8>
[pid 46808] 16:09:48.647449 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing') -> <pkgutil.ImpLoader instance at 0x10b094cb0>
[pid 46808] 16:09:48.648183 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils._text')
[pid 46808] 16:09:48.648982 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.parsing')
[pid 46808] 16:09:48.649341 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/parsing/__init__.py', 'ansible.module_utils.parsing') -> ['convert_bool']
[pid 46808] 16:09:48.649585 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.parsing.convert_bool')
[pid 46808] 16:09:48.649869 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.pycompat24')
[pid 46808] 16:09:48.650212 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.six')
[pid 46808] 16:09:48.650604 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/module_utils/six/__init__.py', 'ansible.module_utils.six') -> []
[pid 46808] 16:09:48.661093 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible.module_utils.basic')
[pid 46808] 16:09:48.980197 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('ansible_mitogen.services')
[pid 46808] 16:09:48.980798 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.services') -> <pkgutil.ImpLoader instance at 0x10b093128>
[pid 46808] 16:09:48.983818 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'ansible_mitogen.services')
[pid 46808] 16:09:49.063694 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('mitogen.fork')
[pid 46808] 16:09:49.064625 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.fork') -> <pkgutil.ImpLoader instance at 0x10b1c1878>
[pid 46808] 16:09:49.066980 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.fork')
[pid 46808] 16:09:49.113662 D mitogen.ctx.ssh.env1-stage-web: mitogen: Router(Broker(0x7f34d3285c50)).upgrade()
[pid 46808] 16:09:49.114217 D mitogen: IdAllocator(Router(Broker(0x10b05fed0))): allocating (3..1003]
[pid 46808] 16:09:49.114611 D mitogen: IdAllocator(Router(Broker(0x10b05fed0))): allocating [Context(3, None)..Context(2, u'ssh.env1-stage-web')) to 2
[pid 46808] 16:09:49.156949 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('default').connect()
[pid 46808] 16:09:49.196754 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('fork.498').connect(): child process stdin/stdout=15
[pid 46808] 16:09:49.197309 D mitogen: Adding route to 3 via mitogen.ssh.Stream(u'ssh.env1-stage-web')
[pid 46808] 16:09:49.197579 D mitogen: Router(Broker(0x10b05fed0)).add_route(3, mitogen.ssh.Stream(u'ssh.env1-stage-web'))
[pid 46808] 16:09:49.197943 D mitogen: ModuleResponder(Router(Broker(0x10b05fed0)))._on_get_module('mitogen.debug')
[pid 46808] 16:09:49.198364 D mitogen: pkgutil._get_module_via_pkgutil('mitogen.debug') -> <pkgutil.ImpLoader instance at 0x10b0a0830>
[pid 46808] 16:09:49.199647 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env1-stage-web'), 'mitogen.debug')
[pid 46808] 16:09:49.200098 D mitogen.ctx.fork.498: mitogen: register(Context(2, 'parent'), mitogen.core.Stream('parent'))
[pid 46808] 16:09:49.200420 D mitogen.ctx.fork.498: mitogen: Connected to Context(2, 'parent'); my ID is 3, PID is 498
[pid 46808] 16:09:49.200692 D mitogen.ctx.fork.498: mitogen: Recovered sys.executable: '/usr/bin/python2.7'
[pid 46809] 16:09:49.246723 D mitogen: service.call_async(Context(0, None), 502, 'listen', {'job_id': '42394a2ccc1096ce', 'sender': Sender(Context(1, None), 1001)})
[pid 46809] 16:09:49.247787 D ansible_mitogen.planner: <ansible_mitogen.planner.BinaryPlanner object at 0x10b0ed250> rejected u'yum'
[pid 46809] 16:09:49.248266 D ansible_mitogen.planner: <ansible_mitogen.planner.NewStylePlanner object at 0x10b07ea50> accepted u'yum' (filename '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py')
[pid 46809] 16:09:49.248701 D mitogen: service.call_async(Context(0, None), 501, 'register', {'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'})
[pid 46808] 16:09:49.250187 D ansible_mitogen.services: ansible_mitogen.services.JobResultService().listen(job_id='42394a2ccc1096ce', sender=Sender(Context(1, None), 1001))
[pid 46808] 16:09:49.250828 D ansible_mitogen.services: ansible_mitogen.services.FileService(): registering '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 46809] 16:09:49.253548 D mitogen: Context(2, u'ssh.env1-stage-web').call_async(<function run_module at 0x10b0562a8>, *({'should_fork': False, 'job_id': '42394a2ccc1096ce', 'remote_tmp': u'/home/ec2-user/.ansible/tmp', 'args': {'_ansible_version': '2.4.4.0', '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], u'name': u'yum-cron', '_ansible_module_name': u'yum', '_ansible_syslog_facility': u'LOG_USER', '_ansible_verbosity': 3, '_ansible_socket': None, u'state': u'installed', '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False, '_ansible_no_log': False}, 'module': u'yum', 'service_context': Context(0, None), 'env': {}, 'interpreter': u'/usr/bin/python', 'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py', 'interpreter_arg': '-tt', 'runner_name': 'NewStyleRunner'},), **{})
[pid 46808] 16:09:49.295219 D mitogen.ctx.ssh.env1-stage-web: ansible_mitogen.target: target.get_file(): fetching '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py' from Context(0, None)
[pid 46808] 16:09:49.332411 D mitogen.ctx.ssh.env1-stage-web: mitogen: service.call_async(Context(0, None), 501, 'fetch', {'path': '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'})
[pid 46808] 16:09:49.333037 D ansible_mitogen.services: Serving '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py'
[pid 46808] 16:09:49.417827 D mitogen.ctx.ssh.env1-stage-web: ansible_mitogen.target: target.get_file(): fetched '/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/packaging/os/yum.py' from Context(0, None)
[pid 46808] 16:09:54.269232 I mitogen.ctx.ssh.env1-stage-web: mitogen.debug: PERIODIC THREAD DUMP

# PID 482 ThreadID: (Thread-1) 139864632157952; <frame object at 0x7f34b8000d60>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 114, in _logging_main
    LOG.info('PERIODIC THREAD DUMP\n\n%s', get_snapshot())
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 82, in get_snapshot
    s = format_stacks()
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
    for filename, lineno, name, line in traceback.extract_stack(stack):

# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34c6a419d8>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1465, in _broker_main
File: "<stdin>", line 1448, in _loop_once
File: "<stdin>", line 230, in io_op

# PID 482 ThreadID: (MainThread) 139864859559744; <frame object at 0x7f34d32937f0>
File: "<stdin>", line 1693, in <module>
File: "<stdin>", line 1684, in main
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1652, in _dispatch_calls
File: "<stdin>", line 480, in __iter__
File: "<stdin>", line 470, in get
File: "<stdin>", line 1051, in get
File: "<stdin>", line 1058, in _get_sleep
File: "<stdin>", line 230, in io_op

[pid 46808] 16:09:59.272783 I mitogen.ctx.ssh.env1-stage-web: mitogen.debug: PERIODIC THREAD DUMP

# PID 482 ThreadID: (Thread-1) 139864632157952; <frame object at 0x7f34b8000d60>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 114, in _logging_main
    LOG.info('PERIODIC THREAD DUMP\n\n%s', get_snapshot())
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 82, in get_snapshot
    s = format_stacks()
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
    for filename, lineno, name, line in traceback.extract_stack(stack):

# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34cb900a00>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1465, in _broker_main
File: "<stdin>", line 1448, in _loop_once
File: "<stdin>", line 230, in io_op

# PID 482 ThreadID: (MainThread) 139864859559744; <frame object at 0x7f34d32937f0>
File: "<stdin>", line 1693, in <module>
File: "<stdin>", line 1684, in main
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1652, in _dispatch_calls
File: "<stdin>", line 480, in __iter__
File: "<stdin>", line 470, in get
File: "<stdin>", line 1051, in get
File: "<stdin>", line 1058, in _get_sleep
File: "<stdin>", line 230, in io_op

--- then

+++ now

@@ -14,7 +14,7 @@

 File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
     for filename, lineno, name, line in traceback.extract_stack(stack):

-# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34c6a419d8>
+# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34cb900a00>
 File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
     self.__bootstrap_inner()
 File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner

[pid 46808] 16:10:04.277609 I mitogen.ctx.ssh.env1-stage-web: mitogen.debug: PERIODIC THREAD DUMP

# PID 482 ThreadID: (Thread-1) 139864632157952; <frame object at 0x7f34b8000d60>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 114, in _logging_main
    LOG.info('PERIODIC THREAD DUMP\n\n%s', get_snapshot())
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 82, in get_snapshot
    s = format_stacks()
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
    for filename, lineno, name, line in traceback.extract_stack(stack):

# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34c6725238>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1465, in _broker_main
File: "<stdin>", line 1448, in _loop_once
File: "<stdin>", line 230, in io_op

# PID 482 ThreadID: (MainThread) 139864859559744; <frame object at 0x7f34d32937f0>
File: "<stdin>", line 1693, in <module>
File: "<stdin>", line 1684, in main
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1652, in _dispatch_calls
File: "<stdin>", line 480, in __iter__
File: "<stdin>", line 470, in get
File: "<stdin>", line 1051, in get
File: "<stdin>", line 1058, in _get_sleep
File: "<stdin>", line 230, in io_op

--- then

+++ now

@@ -14,7 +14,7 @@

 File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
     for filename, lineno, name, line in traceback.extract_stack(stack):

-# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34cb900a00>
+# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34c6725238>
 File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
     self.__bootstrap_inner()
 File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner

[pid 46808] 16:10:09.281889 I mitogen.ctx.ssh.env1-stage-web: mitogen.debug: PERIODIC THREAD DUMP

# PID 482 ThreadID: (Thread-1) 139864632157952; <frame object at 0x7f34b8000d60>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 114, in _logging_main
    LOG.info('PERIODIC THREAD DUMP\n\n%s', get_snapshot())
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 82, in get_snapshot
    s = format_stacks()
File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
    for filename, lineno, name, line in traceback.extract_stack(stack):

# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34cb900a00>
File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
File: "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1465, in _broker_main
File: "<stdin>", line 1448, in _loop_once
File: "<stdin>", line 230, in io_op

# PID 482 ThreadID: (MainThread) 139864859559744; <frame object at 0x7f34d32937f0>
File: "<stdin>", line 1693, in <module>
File: "<stdin>", line 1684, in main
File: "<stdin>", line 280, in <lambda>
File: "<stdin>", line 1652, in _dispatch_calls
File: "<stdin>", line 480, in __iter__
File: "<stdin>", line 470, in get
File: "<stdin>", line 1051, in get
File: "<stdin>", line 1058, in _get_sleep
File: "<stdin>", line 230, in io_op

--- then

+++ now

@@ -14,7 +14,7 @@

 File: "master:/Users/andy/forks/mitogen/mitogen/debug.py", line 63, in format_stacks
     for filename, lineno, name, line in traceback.extract_stack(stack):

-# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34c6725238>
+# PID 482 ThreadID: (mitogen-broker) 139864671676160; <frame object at 0x7f34cb900a00>
 File: "/usr/lib64/python2.7/threading.py", line 777, in __bootstrap
     self.__bootstrap_inner()
 File: "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner

^C [ERROR]: User interrupted execution

 [ERROR]: User interrupted execution

[pid 46808] 16:10:10.099376 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-4'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.100177 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-8'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.100299 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-12'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.100701 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-14'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.100937 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-1'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.101304 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-3'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.101452 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-7'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.102087 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-10'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.102534 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-15'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.103972 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-11'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.102663 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-5'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.103283 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-6'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.103490 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-13'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.102946 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-2'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.105017 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-0'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.105496 E mitogen: mitogen.service.Pool(0x10b06b650, size=16, th='mitogen.service.Pool.10b06b650.worker-9'): channel or latch closed, exitting: None
[pid 46808] 16:10:10.106860 D mitogen: <mitogen.unix.Listener object at 0x10b06b390>.on_disconnect()
[pid 46808] 16:10:10.107464 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web') closing CALL_FUNCTION channel
[pid 46808] 16:10:10.107740 D mitogen: Waker(Broker(0x10b05fed0) rfd=16, wfd=43).on_disconnect()
[pid 46808] 16:10:10.108106 D mitogen: mitogen.core.Stream('unix_client.46809').on_disconnect()
[pid 46808] 16:10:10.150216 D mitogen.ctx.ssh.env1-stage-web: mitogen: Waker(Broker(0x7f34d3285c50) rfd=3, wfd=4).on_disconnect()
[pid 46808] 16:10:10.151444 D mitogen.ctx.ssh.env1-stage-web: mitogen: mitogen.fork.Stream('fork.498') closing CALL_FUNCTION channel
[pid 46808] 16:10:10.151908 D mitogen.ctx.ssh.env1-stage-web: mitogen: <IoLogger stdout>.on_disconnect()
[pid 46808] 16:10:10.152278 D mitogen.ctx.ssh.env1-stage-web: mitogen: <IoLogger stderr>.on_disconnect()
[pid 46808] 16:10:10.187974 D mitogen.ctx.fork.498: mitogen: _on_shutdown_msg(Message(3, 2, 2, 106, 0, ''..0))
[pid 46808] 16:10:10.188575 D mitogen: mitogen.parent.TtyLogStream(mitogen.ssh.Stream(u'ssh.env1-stage-web')).on_disconnect()
[pid 46808] 16:10:10.189394 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web'): child process exit status was 65280
[pid 46808] 16:10:10.189865 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web').on_disconnect()
[pid 46808] 16:10:10.190693 D mitogen: mitogen.ssh.Stream(u'ssh.env1-stage-web') is gone; propagating DEL_ROUTE for set([2, 3])
[pid 46808] 16:10:10.191162 D mitogen: Router(Broker(0x10b05fed0)).del_route(2)
[pid 46808] 16:10:10.191477 D mitogen: Router(Broker(0x10b05fed0)).del_route(3)
dw commented 6 years ago

Amazing, thanks so much for your help once again, I think I've spotted it.

It's to do with the new async/"every style of Ansible module" support. There is a code path that is discarding exceptions.

Please wait for this one overnight, there are a few ways to fix it and I'm not sure which one I like the most yet. :)

edit: sorry, to be clear, this is two bugs. Bug one will take overnight, then we can really find out why your yum invocation is crashing :P~

dw commented 6 years ago

Hi Andy :)

Error reporting should be fixed on master now, and you also shouldn't need -vvv any more to discover what the error is, it should (hopefully) pop out coloured red during a normal run

rouge8 commented 6 years ago 
The full traceback is:
Traceback (most recent call last):
  File "/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 148, in run
    res = self._execute()
  File "/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 551, in _execute
    result = self._handler.run(task_vars=variables)
  File "/Users/andy/forks/mitogen/ansible_mitogen/mixins.py", line 114, in run
    return super(ActionModuleMixin, self).run(tmp, task_vars)
  File "/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/plugins/action/normal.py", line 45, in run
    results = merge_hash(results, self._execute_module(tmp=tmp, task_vars=task_vars, wrap_async=wrap_async))
  File "/Users/andy/forks/mitogen/ansible_mitogen/mixins.py", line 326, in _execute_module
    wrap_async=wrap_async,
  File "/Users/andy/forks/mitogen/ansible_mitogen/planner.py", line 362, in invoke
    planner.plan(invocation),
  File "/Users/andy/forks/mitogen/ansible_mitogen/connection.py", line 339, in call
    return self.call_async(func, *args, **kwargs).get().unpickle()
  File "/Users/andy/forks/mitogen/mitogen/core.py", line 380, in unpickle
    raise obj
CallError: exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 3262: ordinal not in range(128)
  File "<stdin>", line 1654, in _dispatch_calls
  File "<stdin>", line 1649, in _dispatch_one
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/target.py", line 154, in run_module
    return impl.run()
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 148, in run
    self.setup()
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 354, in setup
    super(NewStyleRunner, self).setup()
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 206, in setup
    self._setup_program()
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 217, in _setup_program
    self.program_fp.write(self._get_program())
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 320, in _get_program
    super(ScriptRunner, self)._get_program()
  File "master:/Users/andy/forks/mitogen/ansible_mitogen/runner.py", line 342, in _rewrite_source
    return '\n'.join(new)
dw commented 6 years ago

99.9% this is because of a (I think) custom ansible_foo_interpreter :) Should be easy fix, but will test first. Thanks so much for your perseverance!

dw commented 6 years ago

This is fixed on 'dmw' branch, and on master in about 15 minutes. Thanks again for reporting!