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

ansible: deadlock due to forking with logging.Handler lock held #150

Closed rouge8 closed 6 years ago

rouge8 commented 6 years ago

Using mitogen with Ansible and 19 hosts consistently hangs, though not on the same host, or the same task when I rerun. I can reproduce with my own playbooks (as early as the first task) as well as https://github.com/dw/mitogen/blob/44fc8452b686fb742447cf2716f243e9d036aa72/examples/playbook/issue_131.yml. I've reproduced the hang with as few as 10 hosts. Logs at the very bottom.

When it hangs, the output is something like below, where 18/19 hosts complete the task (output from one of my playbooks, but similar on issue_131.yml):

PLAY [all] ********************************************************************

TASK [Gathering Facts] ********************************************************
ok: [env8-prod-bastion]
ok: [env2-prod-bastion]
ok: [env3-prod-bastion]
ok: [env1-prod-bastion]
ok: [env5-prod-bastion]
ok: [env6-prod-bastion]
ok: [env4-prod-bastion]
ok: [env7-prod-bastion]
ok: [env5-stage-bastion]
ok: [env6-stage-bastion]
ok: [env7-demo-bastion]
ok: [env7-stage-bastion]
ok: [env9-demo-bastion]
ok: [env3-stage-bastion]
ok: [env1-stage-bastion]
ok: [env1-demo-bastion]
ok: [env4-demo-bastion]
ok: [env4-stage-bastion]
ok: [env2-demo-bastion]
ok: [env2-stage-bastion]

TASK [common : Configure passwordless sudo for the Ansible user] **************
ok: [env8-prod-bastion]
ok: [env2-prod-bastion]
ok: [env3-prod-bastion]
ok: [env1-prod-bastion]
ok: [env5-prod-bastion]
ok: [env6-prod-bastion]
ok: [env4-prod-bastion]
ok: [env7-prod-bastion]
ok: [env6-stage-bastion]
ok: [env7-stage-bastion]
ok: [env5-stage-bastion]
ok: [env9-demo-bastion]
ok: [env3-stage-bastion]
ok: [env1-stage-bastion]
ok: [env1-demo-bastion]
ok: [env4-stage-bastion]
ok: [env4-demo-bastion]
ok: [env2-demo-bastion]
ok: [env2-stage-bastion]

Versions

Controller: OS X 10.11.6, Python from Homebrew. Targets: Amazon Linux (RHEL-ish + backports + random Amazon things) Mitogen: 44fc8452b686fb742447cf2716f243e9d036aa72

ansible 2.4.3.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
  python version = 2.7.14 (default, Mar  1 2018, 19:23:40) [GCC 4.2.1 Compatible Apple LLVM 8.0.0 (clang-800.0.42.1)]

Ansible config

ANSIBLE_FORCE_COLOR(/Users/andy/gr/myproject/ansible.cfg) = True
ANSIBLE_PIPELINING(/Users/andy/gr/myproject/ansible.cfg) = True
ANSIBLE_SSH_ARGS(/Users/andy/gr/myproject/ansible.cfg) = -F ansible/ssh_config -o ControlMaster=auto -o ControlPersist=60s
DEFAULT_CALLBACK_WHITELIST(/Users/andy/gr/myproject/ansible.cfg) = ['timer']
DEFAULT_FORKS(/Users/andy/gr/myproject/ansible.cfg) = 50
DEFAULT_GATHERING(/Users/andy/gr/myproject/ansible.cfg) = smart
DEFAULT_GATHER_SUBSET(/Users/andy/gr/myproject/ansible.cfg) = all,!ohai,!facter
DEFAULT_HOST_LIST(/Users/andy/gr/myproject/ansible.cfg) = [u'/Users/andy/gr/myproject/ansible/inventory_from_ssh_config.py']
DEFAULT_MODULE_PATH(/Users/andy/gr/myproject/ansible.cfg) = [u'/Users/andy/gr/myproject/ansible/library', u'/Users/andy/gr/myproject/ansible/library/vendor']
DEFAULT_ROLES_PATH(/Users/andy/gr/myproject/ansible.cfg) = [u'/Users/andy/gr/myproject/ansible/roles', u'/Users/andy/gr/myproject/ansible/shared_roles']
DEFAULT_STRATEGY(/Users/andy/gr/myproject/ansible.cfg) = mitogen
DEFAULT_STRATEGY_PLUGIN_PATH(/Users/andy/gr/myproject/ansible.cfg) = [u'/Users/andy/forks/mitogen/ansible_mitogen/plugins/strategy']

Logs

10 hosts, issue_131.yml 

ansible-playbook 2.4.3.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  1 2018, 19:23:40) [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: issue_131.yml *************************************************************************************************************************************************************************
1 plays in /Users/andy/forks/mitogen/examples/playbook/issue_131.yml

PLAY [all] **************************************************************************************************************************************************************************************
META: ran handlers

TASK [command] **********************************************************************************************************************************************************************************
task path: /Users/andy/forks/mitogen/examples/playbook/issue_131.yml:11
[pid 23261] 16:58:55 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23261] 16:58:55 D mitogen: unix.connect(): local ID is 1, remote is 0
[pid 23253] 16:58:55 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23262] 16:58:55 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23262] 16:58:55 D mitogen: unix.connect(): local ID is 3, remote is 0
[pid 23253] 16:58:55 D mitogen: tty_create_child() child 23264 fd 101, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env9-demo-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrwzAMhc/Lr9hNNnOD7TDIAoGOMHYPYzlsYySxW0wT2zjp3O7XzyGFub0IfXqSHq8mTWmm1CorEU4c8RGp3X2AnXEHhIvkLvTiaDmihFGK/7kmMbmgspX7wUwS1TG4GJoY/ApS/yhn9Ac816/vFL7K6RyGJ9kf57Yb5LoTcEDXAoFRzWYvddFqcd4uZbM3RrhT+rYZTacGmfZmLHjGHzPASXjjnZolYgReKvqpw6wqv9ESWBgrdYgJrgOcOtkK9MRzhgn8KrveXnYaAh5C/MuvKtb8tQZZluc8+DxUt+5scf8Db9F3zg==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:55 D mitogen: mitogen.ssh.Stream('local.23264').connect(): child process stdin/stdout=101
[pid 23263] 16:58:55 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23263] 16:58:56 D mitogen: unix.connect(): local ID is 4, remote is 0
[pid 23265] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23265] 16:58:56 D mitogen: unix.connect(): local ID is 5, remote is 0
[pid 23266] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23266] 16:58:56 D mitogen: unix.connect(): local ID is 6, remote is 0
[pid 23267] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23267] 16:58:56 D mitogen: unix.connect(): local ID is 7, remote is 0
[pid 23268] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23268] 16:58:56 D mitogen: unix.connect(): local ID is 8, remote is 0
[pid 23269] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23269] 16:58:56 D mitogen: unix.connect(): local ID is 9, remote is 0
[pid 23270] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23270] 16:58:56 D mitogen: unix.connect(): local ID is 10, remote is 0
[pid 23271] 16:58:56 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23271] 16:58:56 D mitogen: unix.connect(): local ID is 11, remote is 0
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('local.23264'): received "Warning: Permanently added '34.210.11.231' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('local.23264'): received 'EC0\n'
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('local.23264')._ec0_received()
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23261] 16:58:56 D mitogen: Context(2, u'ssh.env9-demo-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:58:56 D mitogen: tty_create_child() child 23272 fd 121, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env7-demo-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrwzAMhc/Lr9hNNnODHTPIAoGOMHYPYzlsYySxW0wT2zjp3O7XzyGFub0IfXqSHq8mTWmm1CorEU4c8RGp3X2AnXEHhIvkLvTiaDNECaMU/3NNYnJBZSv3g5kkqmNwMTQx+BWk/lHO6A94rl/fKXyV0zkMT7I/zm03yHUn4ICuBQKjms1e6qLV4rxdymZvjHCn9G0zmk4NMu3NWGQ8e+SAk/DGOzVLxAi8VPRTh1lVfqMlsDBW6hATXAc4dbIV6CnLGSbwq+x6e9lpCHgI8S+/qljz1xpwnuc8+DxUt+5scf8Db+x3zw==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('local.23272').connect(): child process stdin/stdout=121
[pid 23253] 16:58:56 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen') -> 
[pid 23253] 16:58:56 D mitogen: _build_tuple('/Users/andy/forks/mitogen/ansible_mitogen/__init__.py', 'ansible_mitogen') -> ['connection', 'helpers', 'logging', 'mixins', 'process', 'services', 'strategy']
[pid 23253] 16:58:56 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible_mitogen')
[pid 23253] 16:58:56 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible_mitogen.helpers') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.basic') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing.convert_bool') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils._text') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.pycompat24') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.six') -> 
[pid 23253] 16:58:56 D mitogen: pkgutil._get_module_via_pkgutil('ansible.module_utils.parsing') -> 
[pid 23253] 16:58:56 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:58:56 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:58:56 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 23253] 16:58:56 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible')
[pid 23253] 16:58:56 D mitogen: mitogen.ssh.Stream('local.23272'): received "Warning: Permanently added '35.166.51.42' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:58:57 D mitogen: pkgutil._get_module_via_pkgutil('ansible.release') -> 
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.release')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:58:57 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 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:58:57 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 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:58:57 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 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:58:57 D mitogen: mitogen.ssh.Stream('local.23272'): received 'EC0\n'
[pid 23253] 16:58:57 D mitogen: mitogen.ssh.Stream('local.23272')._ec0_received()
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:58:57 D mitogen: pkgutil._get_module_via_pkgutil('ansible.modules') -> 
[pid 23253] 16:58:57 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/__init__.py', 'ansible.modules') -> ['cloud', 'clustering', 'commands', 'crypto', 'database', 'files', 'identity', 'inventory', 'messaging', 'monitoring', 'net_tools', 'network', 'notification', 'packaging', 'remote_management', 'source_control', 'storage', 'system', 'utilities', 'web_infrastructure', 'windows']
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.modules')
[pid 23253] 16:58:57 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23262] 16:58:57 D mitogen: Context(12, u'ssh.env7-demo-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:58:57 D mitogen: tty_create_child() child 23273 fd 127, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env8-prod-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FLxDAQhc/2V3ibBLMlbRRqobBSxHsRe1CRtskuYdukpF2z6693ShfMehnmmzczj1exurBTPOpRERo55gPSu1uEnXUHQvPoBnt5HFPCWcI5/eOKheRQTVbuejspUoXgQqhD8Cso862dNe/wVL28cfgspjMOT6o7zk3bq3UHsSfXAoNBz3avTN4Yed4uZbO3VrpT/LoZbKt7FXd2yFORPgigEb7xTs+KJAyeS/5hcFYWX2QJLO2oDMYE1wKNnWokeUyze8rgR4/r7WWnZuAB419+laHmrzUQIssE+tyV/92Txf0XcQl30g==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:57 D mitogen: mitogen.ssh.Stream('local.23273').connect(): child process stdin/stdout=127
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:58:57 D mitogen: pkgutil._get_module_via_pkgutil('ansible.modules.commands') -> 
[pid 23253] 16:58:57 D mitogen: _build_tuple('/Users/andy/gr/myproject/.tox/deploy/lib/python2.7/site-packages/ansible/modules/commands/__init__.py', 'ansible.modules.commands') -> ['command', 'expect', 'raw', 'script', 'shell', 'telnet']
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.modules.commands')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible_mitogen')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:58:57 D mitogen: pkgutil._get_module_via_pkgutil('ansible.modules.commands.command') -> 
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env9-demo-bastion'), 'ansible.modules.commands.command')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible_mitogen.helpers')
[pid 23261] 16:58:57 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 1712 ms
[pid 23261] 16:58:57 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23261] 16:58:57 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:58:57 D mitogen: mitogen.core.Stream('unix_client.23261').on_disconnect()
changed: [env9-demo-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003669",
    "end": "2018-03-15 23:58:57.627215",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:58:57.623546",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.release')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils')
[pid 23253] 16:58:57 D mitogen: mitogen.ssh.Stream('local.23273'): received "Warning: Permanently added '52.34.221.103' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.modules')
[pid 23253] 16:58:57 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:58:57 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.modules.commands')
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-demo-bastion'), 'ansible.modules.commands.command')
[pid 23262] 16:58:58 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 2120 ms
[pid 23262] 16:58:58 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:58:58 D mitogen: mitogen.core.Stream('unix_client.23262').on_disconnect()
[pid 23262] 16:58:58 D mitogen: Waker(Broker()).on_disconnect()
changed: [env7-demo-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003860",
    "end": "2018-03-15 23:58:58.045387",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:58:58.041527",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:58:58 D mitogen: mitogen.ssh.Stream('local.23273'): received 'EC0\n'
[pid 23253] 16:58:58 D mitogen: mitogen.ssh.Stream('local.23273')._ec0_received()
[pid 23253] 16:58:58 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23263] 16:58:58 D mitogen: Context(13, u'ssh.env8-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:58:58 D mitogen: tty_create_child() child 23274 fd 97, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env5-prod-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FLxDAQhc/2V3ibBLMlbRRqobBSxHsRe1CRtskuYdukpF2z6693ShfMehnmmzczj1exurBTPOpRERo55gPSu1uEnXUHQvPoBnt5HFPCWcI5/eOKheRQTVbuejspUoXgQqhD8Cso862dNe/wVL28cfgspjMOT6o7zk3bq3UHsSfXAoNBz3avTN4Yed4uZbO3VrpT/LoZbKt7FXd2yFORPgigEb7xTs+KJAyeS/5hcFYWX2QJLO2oDMYE1wKNnWokeUyze8rgR4/r7WWnZuAB419+laHmrzUQIssE+tyV/92Txf0XcQl30g==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:58 D mitogen: mitogen.ssh.Stream('local.23274').connect(): child process stdin/stdout=97
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible_mitogen')
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible')
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.release')
[pid 23253] 16:58:58 D mitogen: mitogen.ssh.Stream('local.23274'): received "Warning: Permanently added '34.210.65.64' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils')
[pid 23253] 16:58:58 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:58:58 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23274'): received 'EC0\n'
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23274')._ec0_received()
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.modules')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.modules.commands')
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23265] 16:58:59 D mitogen: Context(14, u'ssh.env5-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:58:59 D mitogen: tty_create_child() child 23275 fd 99, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env6-prod-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrwzAMhc/Lr9hNNnODHTPIAoGOMHYPYzlsYySxW0wT2zjp3O7XzyGFub0IfXqSHq8mTWmm1CorEU4c8RGp3X2AnXEHhIvkLvTiaDNECaMU/3NNYnJBZSv3g5kkqmNwMTQx+BWk/lHO6A94rl/fKXyV0zkMT7I/zm03yHUn4ICuBQKjms1e6qLV4rxdymZvjHCn9G0zmk4NMu3NWGQ8e+SAk/DGOzVLxAi8VPRTh1lVfqMlsDBW6hATXAc4dbIV6CnLGSbwq+x6e9lpCHgI8S+/qljz1xpwnuc8+DxUt+5scf8Db+x3zw==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23275').connect(): child process stdin/stdout=99
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env8-prod-bastion'), 'ansible.modules.commands.command')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible_mitogen')
[pid 23263] 16:58:59 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 3170 ms
[pid 23263] 16:58:59 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:58:59 D mitogen: mitogen.core.Stream('unix_client.23263').on_disconnect()
[pid 23263] 16:58:59 D mitogen: Waker(Broker()).on_disconnect()
changed: [env8-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004126",
    "end": "2018-03-15 23:58:59.133791",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:58:59.129665",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.release')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils')
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23275'): received "Warning: Permanently added '52.32.214.44' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.modules')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.modules.commands')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-prod-bastion'), 'ansible.modules.commands.command')
[pid 23265] 16:58:59 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 3613 ms
[pid 23265] 16:58:59 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:58:59 D mitogen: mitogen.core.Stream('unix_client.23265').on_disconnect()
[pid 23265] 16:58:59 D mitogen: Waker(Broker()).on_disconnect()
changed: [env5-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003999",
    "end": "2018-03-15 23:58:59.609997",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:58:59.605998",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23275'): received 'EC0\n'
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23275')._ec0_received()
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23266] 16:58:59 D mitogen: Context(15, u'ssh.env6-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:58:59 D mitogen: tty_create_child() child 23276 fd 104, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env7-prod-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FLxDAQhc/2V3ibBLMlbRRqobBSxHsRe1CRtskuYdukpF2z6693ShfMehnmmzczj1exurBTPOpRERo55gPSu1uEnXUHQvPoBnt5HFPCWcI5/eOKheRQTVbuejspUoXgQqhD8Cso862dNe/wVL28cfgspjMOT6o7zk3bq3UHsSfXAoNBz3avTN4Yed4uZbO3VrpT/LoZbKt7FXd2yFORPgigEb7xTs+KJAyeS/5hcFYWX2QJLO2oDMYE1wKNnWokeUyze8rgR4/r7WWnZuAB419+laHmrzUQIssE+tyV/92Txf0XcQl30g==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:58:59 D mitogen: mitogen.ssh.Stream('local.23276').connect(): child process stdin/stdout=104
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible_mitogen')
[pid 23253] 16:58:59 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:58:59 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.release')
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('local.23276'): received "Warning: Permanently added '34.209.231.159' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('local.23276'): received 'EC0\n'
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('local.23276')._ec0_received()
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.modules')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23267] 16:59:00 D mitogen: Context(16, u'ssh.env7-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-prod-bastion'), 'ansible.modules.commands.command')
[pid 23253] 16:59:00 D mitogen: tty_create_child() child 23277 fd 109, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env5-stage-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrwzAMhc/Lr9hNNnODHTPIAoGOMHYPYzlsYySxW0wT2zjp3O7XzyGFub0IfXqSHq8mTWmm1CorEU4c8RGp3X2AnXEHhIvkLvTiaDNECaMU/3NNYnJBZSv3g5kkqmNwMTQx+BWk/lHO6A94rl/fKXyV0zkMT7I/zm03yHUn4ICuBQKjms1e6qLV4rxdymZvjHCn9G0zmk4NMu3NWGQ8e+SAk/DGOzVLxAi8VPRTh1lVfqMlsDBW6hATXAc4dbIV6CnLGSbwq+x6e9lpCHgI8S+/qljz1xpwnuc8+DxUt+5scf8Db+x3zw==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('local.23277').connect(): child process stdin/stdout=109
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible_mitogen')
[pid 23266] 16:59:00 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 4644 ms
[pid 23266] 16:59:00 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23266] 16:59:00 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:00 D mitogen: mitogen.core.Stream('unix_client.23266').on_disconnect()
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible_mitogen.helpers')
changed: [env6-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003834",
    "end": "2018-03-15 23:59:00.651320",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:00.647486",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.release')
[pid 23253] 16:59:00 D mitogen: mitogen.ssh.Stream('local.23277'): received "Warning: Permanently added '34.209.162.80' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:00 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:00 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.modules')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-prod-bastion'), 'ansible.modules.commands.command')
[pid 23267] 16:59:01 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 5143 ms
[pid 23267] 16:59:01 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:01 D mitogen: mitogen.core.Stream('unix_client.23267').on_disconnect()
[pid 23267] 16:59:01 D mitogen: Waker(Broker()).on_disconnect()
changed: [env7-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004086",
    "end": "2018-03-15 23:59:01.170790",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:01.166704",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23277'): received 'EC0\n'
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23277')._ec0_received()
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23268] 16:59:01 D mitogen: Context(17, u'ssh.env5-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:59:01 D mitogen: tty_create_child() child 23278 fd 107, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env6-stage-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FLxDAQhc/2V3ibBLMlbRRqobBSxHsRe1CRtskuYdukpF2z6693ShfMehnmmzczj1exurBTPOpRERo55gPSu1uEnXUHQvPoBnt5HFPCWcI5/eOKheRQTVbuejspUoXgQqhD8Cso862dNe/wVL28cfgspjMOT6o7zk3bq3UHsSfXAoNBz3avTN4Yed4uZbO3VrpT/LoZbKt7FXd2yFORPgigEb7xTs+KJAyeS/5hcFYWX2QJLO2oDMYE1wKNnWokeUyze8rgR4/r7WWnZuAB419+laHmrzUQIssE+tyV/92Txf0XcQl30g==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23278').connect(): child process stdin/stdout=107
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible_mitogen')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.release')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23278'): received "Warning: Permanently added '35.165.138.68' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.modules')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:01 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:01 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env5-stage-bastion'), 'ansible.modules.commands.command')
[pid 23268] 16:59:01 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 5819 ms
[pid 23268] 16:59:01 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:01 D mitogen: mitogen.core.Stream('unix_client.23268').on_disconnect()
[pid 23268] 16:59:01 D mitogen: Waker(Broker()).on_disconnect()
changed: [env5-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003869",
    "end": "2018-03-15 23:59:01.865680",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:01.861811",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23278'): received 'EC0\n'
[pid 23253] 16:59:01 D mitogen: mitogen.ssh.Stream('local.23278')._ec0_received()
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23269] 16:59:02 D mitogen: Context(18, u'ssh.env6-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:59:02 D mitogen: tty_create_child() child 23280 fd 113, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env7-stage-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrwzAMhc/Lr9hNNnODHTPIAoGOMHYPYzlsYySxW0wT2zjp3O7XzyGFub0IfXqSHq8mTWmm1CorEU4c8RGp3X2AnXEHhIvkLvTiaDNECaMU/3NNYnJBZSv3g5kkqmNwMTQx+BWk/lHO6A94rl/fKXyV0zkMT7I/zm03yHUn4ICuBQKjms1e6qLV4rxdymZvjHCn9G0zmk4NMu3NWGQ8e+SAk/DGOzVLxAi8VPRTh1lVfqMlsDBW6hATXAc4dbIV6CnLGSbwq+x6e9lpCHgI8S+/qljz1xpwnuc8+DxUt+5scf8Db+x3zw==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('local.23280').connect(): child process stdin/stdout=113
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible_mitogen')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.release')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('local.23280'): received "Warning: Permanently added '34.212.19.92' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.modules')
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('local.23280'): received 'EC0\n'
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('local.23280')._ec0_received()
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env6-stage-bastion'), 'ansible.modules.commands.command')
[pid 23269] 16:59:02 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 6795 ms
[pid 23269] 16:59:02 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:02 D mitogen: mitogen.core.Stream('unix_client.23269').on_disconnect()
[pid 23269] 16:59:02 D mitogen: Waker(Broker()).on_disconnect()
changed: [env6-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003826",
    "end": "2018-03-15 23:59:02.862670",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:02.858844",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('default').connect()
[pid 23270] 16:59:02 D mitogen: Context(19, u'ssh.env7-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:59:02 D mitogen: tty_create_child() child 23281 fd 116, parent 23253, cmd: "ssh" "-l" "ec2-user" "-o" "Compression yes" "-o" "StrictHostKeyChecking no" "-o" "UserKnownHostsFile /dev/null" "-F" "ansible/ssh_config" "-o" "ControlMaster=auto" "-o" "ControlPersist=60s" "env3-stage-bastion" "'/usr/bin/python2.7'" "'-c'" "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNpdj0FrhDAQhc/1V/Q2Cc1KNBSsIGyR0ruUemhLUZNdwmomRLfu9tc34kKzexnmmzczj1exusAxttoqQiPH5oD07t7DDt2B0Dy687082pRwlnBO/7liITmvJit3PY6KVCG4EOoQ5hWU+dEOzQc8V6/vHL6K8eyHJ9Udp6bt1brjsSfXAoNBT7hXJm+MPG+XstkjSneK3zYDtrpXcYdDnor0UQCN/JvZ6UmRhMFLyT+Nn5XFN1kCS7TK+JjgWqCxU40kT2nGKYNfbdfby07NYAYf//KrDLX5WgMhskx4n4fy1j1Z3P8Ab413zg==\".encode(),\"base64\"),\"zip\"))'"
[pid 23253] 16:59:02 D mitogen: mitogen.ssh.Stream('local.23281').connect(): child process stdin/stdout=116
[pid 23253] 16:59:02 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:59:02 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible_mitogen')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.release')
[pid 23253] 16:59:03 D mitogen: mitogen.ssh.Stream('local.23281'): received "Warning: Permanently added '52.39.77.124' (ECDSA) to the list of known hosts.\r\n"
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.modules')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env7-stage-bastion'), 'ansible.modules.commands.command')
[pid 23270] 16:59:03 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 7383 ms
[pid 23270] 16:59:03 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:03 D mitogen: mitogen.core.Stream('unix_client.23270').on_disconnect()
[pid 23270] 16:59:03 D mitogen: Waker(Broker()).on_disconnect()
changed: [env7-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.008890",
    "end": "2018-03-15 23:59:03.467706",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:03.458816",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:03 D mitogen: mitogen.ssh.Stream('local.23281'): received 'EC0\n'
[pid 23253] 16:59:03 D mitogen: mitogen.ssh.Stream('local.23281')._ec0_received()
[pid 23271] 16:59:03 D mitogen: Context(20, u'ssh.env3-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible_mitogen')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible_mitogen.helpers')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible_mitogen.helpers')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.release')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.release')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils')
[pid 23253] 16:59:03 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.module_utils.basic')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils._text')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils.parsing')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils.parsing.convert_bool')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils.pycompat24')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils.six')
[pid 23253] 16:59:03 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.module_utils.basic')
[pid 23253] 16:59:04 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules')
[pid 23253] 16:59:04 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.modules')
[pid 23253] 16:59:04 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands')
[pid 23253] 16:59:04 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.modules.commands')
[pid 23253] 16:59:04 D mitogen: ModuleResponder(Router(Broker()))._on_get_module('ansible.modules.commands.command')
[pid 23253] 16:59:04 D mitogen: _send_load_module(mitogen.ssh.Stream(u'ssh.env3-stage-bastion'), 'ansible.modules.commands.command')
[pid 23271] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 8062 ms
[pid 23271] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23271').on_disconnect()
[pid 23271] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
changed: [env3-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004009",
    "end": "2018-03-15 23:59:04.172154",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.168145",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}

TASK [command] **********************************************************************************************************************************************************************************
task path: /Users/andy/forks/mitogen/examples/playbook/issue_131.yml:12
[pid 23282] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23282] 16:59:04 D mitogen: unix.connect(): local ID is 21, remote is 0
[pid 23282] 16:59:04 D mitogen: Context(2, u'ssh.env9-demo-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23283] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23283] 16:59:04 D mitogen: unix.connect(): local ID is 22, remote is 0
[pid 23283] 16:59:04 D mitogen: Context(12, u'ssh.env7-demo-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23284] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23284] 16:59:04 D mitogen: unix.connect(): local ID is 23, remote is 0
[pid 23284] 16:59:04 D mitogen: Context(13, u'ssh.env8-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23285] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23285] 16:59:04 D mitogen: unix.connect(): local ID is 24, remote is 0
[pid 23285] 16:59:04 D mitogen: Context(14, u'ssh.env5-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23286] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23286] 16:59:04 D mitogen: unix.connect(): local ID is 25, remote is 0
[pid 23282] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 67 ms
[pid 23282] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23282] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23282').on_disconnect()
[pid 23283] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 66 ms
[pid 23283] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23283] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23287] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23287] 16:59:04 D mitogen: unix.connect(): local ID is 26, remote is 0
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23283').on_disconnect()
[pid 23286] 16:59:04 D mitogen: Context(15, u'ssh.env6-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23284] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 62 ms
[pid 23284] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23284').on_disconnect()
[pid 23284] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23287] 16:59:04 D mitogen: Context(16, u'ssh.env7-prod-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
changed: [env9-demo-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003773",
    "end": "2018-03-15 23:59:04.261797",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.258024",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23285] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 61 ms
[pid 23285] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23285] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23285').on_disconnect()
[pid 23289] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
changed: [env7-demo-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003897",
    "end": "2018-03-15 23:59:04.278335",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.274438",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23289] 16:59:04 D mitogen: unix.connect(): local ID is 27, remote is 0
changed: [env8-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004241",
    "end": "2018-03-15 23:59:04.287483",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.283242",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23286] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 80 ms
[pid 23290] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
changed: [env5-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004149",
    "end": "2018-03-15 23:59:04.302774",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.298625",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23286] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23290] 16:59:04 D mitogen: unix.connect(): local ID is 28, remote is 0
[pid 23286] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23286').on_disconnect()
[pid 23289] 16:59:04 D mitogen: Context(18, u'ssh.env6-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23287] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 68 ms
[pid 23290] 16:59:04 D mitogen: Context(19, u'ssh.env7-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23287] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
changed: [env6-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003517",
[pid 23287] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
;33m    "end": "2018-03-15 23:59:04.336287",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.332770",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23287').on_disconnect()
changed: [env7-prod-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004112",
    "end": "2018-03-15 23:59:04.352272",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.348160",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23291] 16:59:04 D mitogen: unix.connect(path='/var/folders/bw/ghklm2fs6bx_x9x_f0wg5kph0000gn/T/mitogen_unix_zXlNKF')
[pid 23291] 16:59:04 D mitogen: unix.connect(): local ID is 29, remote is 0
[pid 23291] 16:59:04 D mitogen: Context(20, u'ssh.env3-stage-bastion').call_async(, *('ansible.modules.commands.command',), **{'args': {'_ansible_version': '2.4.3.0', '_uses_shell': True, '_ansible_no_log': False, '_ansible_module_name': u'command', u'_raw_params': u'true', '_ansible_verbosity': 3, '_ansible_syslog_facility': u'LOG_USER', '_ansible_socket': None, '_ansible_selinux_special_fs': ['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], '_ansible_diff': False, '_ansible_debug': False, '_ansible_shell_executable': u'/bin/sh', '_ansible_check_mode': False}, 'env': {}})
[pid 23290] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 63 ms
[pid 23290] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23290').on_disconnect()
[pid 23290] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
[pid 23289] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 91 ms
[pid 23289] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23289] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
changed: [env7-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004417",
    "end": "2018-03-15 23:59:04.404302",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.399885",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23289').on_disconnect()
[pid 23291] 16:59:04 D ansible_mitogen.connection: Call run_module('ansible.modules.commands.command',) took 54 ms
[pid 23291] 16:59:04 D mitogen: mitogen.core.Stream('unix_listener.23253').on_disconnect()
[pid 23291] 16:59:04 D mitogen: Waker(Broker()).on_disconnect()
changed: [env6-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.004220",
    "end": "2018-03-15 23:59:04.405513",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.401293",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}
[pid 23253] 16:59:04 D mitogen: mitogen.core.Stream('unix_client.23291').on_disconnect()
changed: [env3-stage-bastion] => {
    "changed": true,
    "cmd": "true",
    "delta": "0:00:00.003855",
    "end": "2018-03-15 23:59:04.416654",
    "invocation": {
        "module_args": {
            "_raw_params": "true",
            "_uses_shell": true,
            "chdir": null,
            "creates": null,
            "executable": null,
            "removes": null,
            "stdin": null,
            "warn": true
        }
    },
    "rc": 0,
    "start": "2018-03-15 23:59:04.412799",
    "stderr": "",
    "stderr_lines": [],
    "stdout": "",
    "stdout_lines": []
}

^C [ERROR]: User interrupted execution

[pid 23253] 16:59:25 D mitogen: : channel closed: Channel closed by local end.
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env5-stage-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env8-prod-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: .on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env3-stage-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env9-demo-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-demo-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env6-stage-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env6-prod-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env5-prod-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-prod-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-stage-bastion') closing CALL_FUNCTION channel
[pid 23253] 16:59:25 D mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env9-demo-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env8-prod-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env5-stage-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env3-stage-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env9-demo-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env7-demo-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env8-prod-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env5-prod-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env6-prod-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env7-prod-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env5-stage-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env6-stage-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen.ctx.ssh.env7-stage-bastion: mitogen: Waker(Broker()).on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-demo-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env5-prod-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env6-prod-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-prod-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env6-stage-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env7-stage-bastion').on_disconnect()
[pid 23253] 16:59:25 D mitogen: mitogen.ssh.Stream(u'ssh.env3-stage-bastion').on_disconnect()
dw commented 6 years ago

Probably something super simple, I haven't been testing against >1 target at all (at least not the Ansible bits). Will setup a reproduction tomorrow. Thanks for the report!

dw commented 6 years ago

First attempt to replicate this against 23 shared vCPU Google Cloud targets failed, but I can see some weird performance characteristics (sometimes it runs through quickly, other times much more slowly).

Thanks for report, may need to defer this one until I get back to UK, because the only place I have good gcloud quota is eu-west-1, and latency to there from here is basically unuseable

rouge8 commented 6 years ago

👍 Let me know if there's any more debug logging I can provide, otherwise I'll be ready to re-test when you think you have a fix. 😃

dw commented 6 years ago

I'm using this as a quick (and therapeutic) excuse to expose the existing Docker connection support.. process model won't change, but means I can have 100 targets on my laptop ;)

kariedo commented 6 years ago

+1 Facing with the same behavior when running with more than 5-10 hosts at once - hangs forever on the random place.

dw commented 6 years ago

Ah @rouge8 one last question: the controller machine, how many cores and how many (hardware) threads, and otherwise how loaded is it?

rouge8 commented 6 years ago

OS X 10.11.6 controller, MBP 2 cores / 4 threads. Screenshots from activity monitor attached. Wasn't doing too much when running Ansible other than the ~300 Chrome tabs open 🙈

CPU Memory

dw commented 6 years ago

Sounds like we have the same laptop :) Thanks

dw commented 6 years ago

Just to confirm I have reproduced it. Workers all sitting there like dummies, top-level process burning 20% CPU doing.. mysterious things.

dw commented 6 years ago

The 20% CPU in the parent process is Ansible polling at 1ms intervals on results.

Haven't found it, but interestingly there are 3 post-fork WorkerProcesses for which no corresponding /tmp/mitogen.*.log file exists. The waiting done by Ansible may be related to results these processes clearly aren't likely to ever generate.

pstree

[02:18:51 Eldil!5 ~] pstree -s python
-+= 00001 root /sbin/launchd
 |--- 42843 dmw (python.exe)
 \-+= 89248 dmw /Applications/iTerm.app/Contents/MacOS/iTerm2
   \-+= 01987 dmw bash --login
     \-+= 12208 dmw /Users/dmw/src/mitogen/.venv/bin/python2.7 /Users/dmw/src/mitogen/.venv/bin/ansible-playbook -i hosts.docker -l mydeb9-1* issue_131.yml -vvvv
       |--- 12219 dmw /Users/dmw/src/mitogen/.venv/bin/python2.7 /Users/dmw/src/mitogen/.venv/bin/ansible-playbook -i hosts.docker -l mydeb9-1* issue_131.yml -vvvv
       |--- 12220 dmw docker exec -i mydeb9-1 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGckxoDIYEE3L3oT60JTiWUkQUSchO1fbru8GBKr3t
       |--- 12224 dmw /Users/dmw/src/mitogen/.venv/bin/python2.7 /Users/dmw/src/mitogen/.venv/bin/ansible-playbook -i hosts.docker -l mydeb9-1* issue_131.yml -vvvv
       |--- 12225 dmw docker exec -i mydeb9-10 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGckxoDIYEE3L3oT60JTiWUkQUSchO1fbru8GBKr3
       |--- 12226 dmw /Users/dmw/src/mitogen/.venv/bin/python2.7 /Users/dmw/src/mitogen/.venv/bin/ansible-playbook -i hosts.docker -l mydeb9-1* issue_131.yml -vvvv
       |--- 12229 dmw docker exec -i mydeb9-11 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       |--- 12230 dmw docker exec -i mydeb9-12 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       |--- 12231 dmw docker exec -i mydeb9-14 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       |--- 12232 dmw docker exec -i mydeb9-15 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       |--- 12233 dmw docker exec -i mydeb9-16 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       |--- 12234 dmw docker exec -i mydeb9-19 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr3
       \--- 12235 dmw docker exec -i mydeb9-100 /usr/bin/python2.7 -c import codecs,os,sys;_=codecs.decode;exec(_(_("eNpdj8FqwzAQRM/1V/S2EhVGcgxNDYYGE3L3IT60pTjWpogqkpCdqunXV8aBKr

Ansible main thread polling

# PID 12208 ThreadID: (MainThread) 140735838786496; <frame object at 0x7fc74282aab0>
File: "/Users/dmw/src/mitogen/.venv/bin/ansible-playbook", line 106, in <module>
    exit_code = cli.run()
File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/cli/playbook.py", line 130, in run
    results = pbex.run()
File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/executor/playbook_executor.py", line 154, in run
    result = self._tqm.run(play=play)
File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/executor/task_queue_manager.py", line 290, in run
    play_return = strategy.run(iterator, play_context)
File: "/Users/dmw/src/mitogen/ansible_mitogen/strategy.py", line 188, in run
    return super(StrategyModule, self).run(iterator, play_context)
File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/plugins/strategy/linear.py", line 292, in run
    results += self._wait_on_pending_results(iterator)
File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/plugins/strategy/__init__.py", line 589, in _wait_on_pending_results
    time.sleep(C.DEFAULT_INTERNAL_POLL_INTERVAL)

# PID 12208 ThreadID: (mitogen.master.join_thread_async) 123145427001344; <frame object at 0x7fc74281ba40>
File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
File: "/Users/dmw/src/mitogen/mitogen/master.py", line 144, in _watch
    target_thread.join()

--- then

+++ now

@@ -47,14 +47,8 @@

     return super(StrategyModule, self).run(iterator, play_context)
 File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/plugins/strategy/linear.py", line 292, in run
     results += self._wait_on_pending_results(iterator)
-File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/plugins/strategy/__init__.py", line 583, in _wait_on_pending_results
-    if self._tqm.has_dead_workers():
-File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/executor/task_queue_manager.py", line 341, in has_dead_workers
-    if hasattr(x[0], 'exitcode'):
-File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/multiprocessing/process.py", line 203, in exitcode
-    return self._popen.poll()
-File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/multiprocessing/forking.py", line 135, in poll
-    pid, sts = os.waitpid(self.pid, flag)
+File: "/Users/dmw/src/mitogen/.venv/lib/python2.7/site-packages/ansible/plugins/strategy/__init__.py", line 589, in _wait_on_pending_results
+    time.sleep(C.DEFAULT_INTERNAL_POLL_INTERVAL)

 # PID 12208 ThreadID: (mitogen.master.join_thread_async) 123145427001344; <frame object at 0x7fc74281ba40>
 File: "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 774, in __bootstrap
dw commented 6 years ago

And what a surprise, the first worker I look at is trying to take a lock. Yay for mixing threading/forking. This one is likely to be fun

dw commented 6 years ago

The lock in question is in the logging package, and quite possibly it's a lock for Mitogen's own log handler. Funsies.

So basically what happens is you have 2 threads, one of which is active logging a message (such as the Mitogen IO multiplexer thread enjoys), and another (such as the Ansible main thread) calls fork. In the child process (which is a worker process actually implementing an Ansible playbook step), a new Mitogen IO multiplexer is created, and of course it'll start logging again, but in the duplicate copy of the parent's process image the child received, the logging code discovers a lock it wants to take already marked as held -- by a thread in the parent that no longer exists in the child. Tada, deadlock.

So the obvious solution to this is to bring forward multithreaded connect work ( https://github.com/dw/mitogen/issues/144 ) since it already entails pre-forking one connection multiplexer process per CPU long before Ansible starts forking off its WorkerProcesses.

The forking done inside those connection multiplexer processes is generally fine: the only forks occur inside create_child() and tty_create_child(), and they do not log, take or release locks, or do anything other than replace the forked Python image with the ssh/sudo/docker command to be executed.

Perhaps I won't go full-hog on implementing that feature, but I will at least move the Mitogen bits out of the Ansible top-level process, because that's the one that's super fork happy.

Relevant long-lived upstream bug (that still only amounts to a partial solution - threading/forking cannot be safely mixed in the general case): https://bugs.python.org/issue6721

dw commented 6 years ago

Hi there,

Can you please try out the wip-issue-150 branch on GitHub, or if following the usual docs installation method, grab https://github.com/dw/mitogen/archive/wip-issue-150.zip and report back :)

This code still needs a lot of cleanup work, and note connection establishment is still single-threaded, I found some minimum-work inbetween approach

rouge8 commented 6 years ago

It works 🎉! It made it through my 45 task play on 19 hosts multiple times. Took 1.5-2 minutes with Mitogen vs. ~2.5 minutes without.

dw commented 6 years ago

@rouge8 can you post /usr/bin/time output before/after and give me a short description of those playbook steps (I'm guessing not much with_items use?). Does it feel like "naturally it should take this long"? i.e. lots of big apt-gets, talking to far-away web services, etc.

There's one known gotcha right now in that use of the copy module with large files is terribly slow, but there may easily be more

Finally I saw some bizarre slowdowns on some local runs, so I figure there are plenty more perf bugs hiding in the multi-target support (not least, single threaded connection establishment)

dw commented 6 years ago

The WIP branch is merged to master, and I'm considering this a solved problem. As for multi-target related performance issues, they definitely still exist, but they're outside the scope of this bug :)

Still interested in related timings or weird behaviour from all participants! This is brand new code, so there is a large chance of some weird new emergent behaviour

rouge8 commented 6 years ago

you post /usr/bin/time output before/after

Of course today's timing is totally different than yesterdays 😂. In all cases 0 tasks were changed.

The playbook is runs 45 tasks, ~30 are custom, and the remaining are https://github.com/threatstack/threatstack-ansible and https://github.com/DataDog/ansible-datadog. No with_items.

My tasks:

Here's the output from the Datadog/Threatstack tasks:

TASK [threatstack : install threatstack] ****************************************************************
[DEPRECATION WARNING]: The use of 'include' for tasks has been deprecated. Use 'import_tasks' for static
 inclusions or 'include_tasks' for dynamic inclusions. This feature will be removed in a future release.
 Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.
[DEPRECATION WARNING]: include is kept for backwards compatibility but usage is discouraged. The module
documentation details page may explain more about this rationale.. This feature will be removed in a
future release. Deprecation warnings can be disabled by setting deprecation_warnings=False in
ansible.cfg.

TASK [threatstack.threatstack-ansible : python-apt dependency.] *****************************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : apt-transport-https dependency.] ********************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository key.] ***************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository.] *******************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Threat Stack is installed.] ******************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure ThreatStack repo is installed.] **************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add ThreatStack repo GPG key.] **********************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Agent is installed.] *************************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create Threat Stack Config Directory] ***************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create ThreatStack Config File] *********************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Cloudsight - setup default] *************************************
ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create file to track extra Cloudsight config] *******************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Configure extra cloudsight parameters] **************************
skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Test cloudsight state] ******************************************
ok: [env1-stage-bastion]

PLAY [all] **********************************************************************************************

TASK [datadog : install datadog] ************************************************************************

TASK [Datadog.datadog : Install apt-transport-https] ****************************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install ubuntu apt-key server] **************************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install Datadog apt-key] ********************************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date] ****************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date (agent5)] *******************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure pinned version of Datadog agent is installed] ****************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog agent is installed] **********************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Download new RPM key] ***********************************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Import new RPM key] *************************************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo] *******************************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo (agent5)] **********************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install pinned datadog-agent package] *******************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install latest datadog-agent package] *******************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agent configuration file] ***********************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] ************************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] ********************************************
skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****************************

TASK [Datadog.datadog : Create /etc/datadog-agent] ******************************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agant yaml configuration file (beta)] ***********************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****************************

TASK [Datadog.datadog : Create trace agent configuration file] ******************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create process agent configuration file] ****************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] ************************************************
ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] ********************************************
skipping: [env1-stage-bastion]

TASK [datadog : Remove legacy dd-agent 5.x config] ******************************************************
ok: [env1-stage-bastion]
dw commented 6 years ago

These timings are all over the place, especially CPU usage, it's not even showing the >.5x typical with a Mirogen run. Thanks, this is immensely useful!

On 17 Mar 2018 23:25, "Andy Freeland" notifications@github.com wrote:

you post /usr/bin/time output before/after

Of course today's timing is totally different than yesterdays 😂. In all cases 0 tasks were changed.

-

Without mitogen, 19 hosts:

Playbook run took 0 days, 0 hours, 3 minutes, 12 seconds

real 3m14.335s user 5m4.604s sys 1m40.063s

-

Without mitogen, 1 host:

Playbook run took 0 days, 0 hours, 0 minutes, 55 seconds

real 0m57.332s user 0m15.213s sys 0m4.223s

-

With mitogen 3e9f01b https://github.com/dw/mitogen/commit/3e9f01bb7af78059fb85b53b4f7a0059f860a5f5, 19 hosts:

Playbook run took 0 days, 0 hours, 2 minutes, 15 seconds

real 2m16.877s user 4m6.684s sys 1m6.321s

-

With mitogen 3e9f01b https://github.com/dw/mitogen/commit/3e9f01bb7af78059fb85b53b4f7a0059f860a5f5, 1 host:

Playbook run took 0 days, 0 hours, 0 minutes, 28 seconds

real 0m29.581s user 0m10.117s sys 0m2.537s

The playbook is runs 45 tasks, ~30 are custom, and the remaining are https://github.com/threatstack/threatstack-ansible and https://github.com/DataDog/ansible-datadog. No with_items.

My tasks:

  • template module, 1 line
  • hostname module
  • lineinfile, 1 line
  • lineinfile, 1 line
  • lineinfile, 1 line
  • lineinfile, 1 line
  • copy, 7 lines
  • file, state=absent
  • lineinfile, 1 line
  • lineinfile, 1 line
  • yum, one package
  • file, state=absent
  • copy, 82 lines
  • service, enabled=false
  • cron
  • service
  • lineinfile, 1 line
  • command: runs rpm --qf to check installed version of a package
  • template, 10 lines
  • set_fact
  • template, 30 lines source, 88 lines once templated
  • service
  • get_url, ~10 lines
  • template, 9 lines
  • yum, install latest
  • service

Here's the output from the Datadog/Threatstack tasks:

TASK [threatstack : install threatstack] **** [DEPRECATION WARNING]: The use of 'include' for tasks has been deprecated. Use 'import_tasks' for static inclusions or 'include_tasks' for dynamic inclusions. This feature will be removed in a future release. Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg. [DEPRECATION WARNING]: include is kept for backwards compatibility but usage is discouraged. The module documentation details page may explain more about this rationale.. This feature will be removed in a future release. Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.

TASK [threatstack.threatstack-ansible : python-apt dependency.] ***** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : apt-transport-https dependency.] **** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository key.] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository.] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Threat Stack is installed.] ** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure ThreatStack repo is installed.] ** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add ThreatStack repo GPG key.] ** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Agent is installed.] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create Threat Stack Config Directory] *** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create ThreatStack Config File] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Cloudsight - setup default] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create file to track extra Cloudsight config] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Configure extra cloudsight parameters] ** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Test cloudsight state] ** ok: [env1-stage-bastion]

PLAY [all] **

TASK [datadog : install datadog] ****

TASK [Datadog.datadog : Install apt-transport-https] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install ubuntu apt-key server] ** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install Datadog apt-key] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date (agent5)] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure pinned version of Datadog agent is installed] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog agent is installed] ** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Download new RPM key] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Import new RPM key] ***** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo (agent5)] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install pinned datadog-agent package] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install latest datadog-agent package] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agent configuration file] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****

TASK [Datadog.datadog : Create /etc/datadog-agent] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agant yaml configuration file (beta)] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****

TASK [Datadog.datadog : Create trace agent configuration file] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create process agent configuration file] **** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] **** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] **** skipping: [env1-stage-bastion]

TASK [datadog : Remove legacy dd-agent 5.x config] ** ok: [env1-stage-bastion]

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/dw/mitogen/issues/150#issuecomment-373938710, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAJC-PFfc4bTiQuAfRBz7WZAd2sug6-ks5tfUqdgaJpZM4StD4S .

dw commented 6 years ago

CPU use doesnt even grow linearly for this many hosts, its 26x vs a 19x increase in actual load. Something is super broken

On 18 Mar 2018 00:17, "David Wilson" dw@botanicus.net wrote:

These timings are all over the place, especially CPU usage, it's not even showing the >.5x typical with a Mirogen run. Thanks, this is immensely useful!

On 17 Mar 2018 23:25, "Andy Freeland" notifications@github.com wrote:

you post /usr/bin/time output before/after

Of course today's timing is totally different than yesterdays 😂. In all cases 0 tasks were changed.

-

Without mitogen, 19 hosts:

Playbook run took 0 days, 0 hours, 3 minutes, 12 seconds

real 3m14.335s user 5m4.604s sys 1m40.063s

-

Without mitogen, 1 host:

Playbook run took 0 days, 0 hours, 0 minutes, 55 seconds

real 0m57.332s user 0m15.213s sys 0m4.223s

-

With mitogen 3e9f01b https://github.com/dw/mitogen/commit/3e9f01bb7af78059fb85b53b4f7a0059f860a5f5, 19 hosts:

Playbook run took 0 days, 0 hours, 2 minutes, 15 seconds

real 2m16.877s user 4m6.684s sys 1m6.321s

-

With mitogen 3e9f01b https://github.com/dw/mitogen/commit/3e9f01bb7af78059fb85b53b4f7a0059f860a5f5, 1 host:

Playbook run took 0 days, 0 hours, 0 minutes, 28 seconds

real 0m29.581s user 0m10.117s sys 0m2.537s

The playbook is runs 45 tasks, ~30 are custom, and the remaining are https://github.com/threatstack/threatstack-ansible and https://github.com/DataDog/ansible-datadog. No with_items.

My tasks:

  • template module, 1 line
  • hostname module
  • lineinfile, 1 line
  • lineinfile, 1 line
  • lineinfile, 1 line
  • lineinfile, 1 line
  • copy, 7 lines
  • file, state=absent
  • lineinfile, 1 line
  • lineinfile, 1 line
  • yum, one package
  • file, state=absent
  • copy, 82 lines
  • service, enabled=false
  • cron
  • service
  • lineinfile, 1 line
  • command: runs rpm --qf to check installed version of a package
  • template, 10 lines
  • set_fact
  • template, 30 lines source, 88 lines once templated
  • service
  • get_url, ~10 lines
  • template, 9 lines
  • yum, install latest
  • service

Here's the output from the Datadog/Threatstack tasks:

TASK [threatstack : install threatstack] **** [DEPRECATION WARNING]: The use of 'include' for tasks has been deprecated. Use 'import_tasks' for static inclusions or 'include_tasks' for dynamic inclusions. This feature will be removed in a future release. Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg. [DEPRECATION WARNING]: include is kept for backwards compatibility but usage is discouraged. The module documentation details page may explain more about this rationale.. This feature will be removed in a future release. Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.

TASK [threatstack.threatstack-ansible : python-apt dependency.] ***** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : apt-transport-https dependency.] **** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository key.] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add Threat Stack apt repository.] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Threat Stack is installed.] ** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure ThreatStack repo is installed.] ** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Add ThreatStack repo GPG key.] ** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Ensure Agent is installed.] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create Threat Stack Config Directory] *** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create ThreatStack Config File] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Cloudsight - setup default] ***** ok: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Create file to track extra Cloudsight config] *** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Configure extra cloudsight parameters] ** skipping: [env1-stage-bastion]

TASK [threatstack.threatstack-ansible : Test cloudsight state] ** ok: [env1-stage-bastion]

PLAY [all] **

TASK [datadog : install datadog] ****

TASK [Datadog.datadog : Install apt-transport-https] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install ubuntu apt-key server] ** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Install Datadog apt-key] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog repository is up-to-date (agent5)] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure pinned version of Datadog agent is installed] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure Datadog agent is installed] ** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Download new RPM key] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Import new RPM key] ***** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install DataDog yum repo (agent5)] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install pinned datadog-agent package] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Install latest datadog-agent package] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agent configuration file] *** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] **** skipping: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****

TASK [Datadog.datadog : Create /etc/datadog-agent] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create main Datadog agant yaml configuration file (beta)] *** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create a configuration file for each Datadog check] *****

TASK [Datadog.datadog : Create trace agent configuration file] ** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Create process agent configuration file] **** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is running] **** ok: [env1-stage-bastion]

TASK [Datadog.datadog : Ensure datadog-agent is not running] **** skipping: [env1-stage-bastion]

TASK [datadog : Remove legacy dd-agent 5.x config] ** ok: [env1-stage-bastion]

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/dw/mitogen/issues/150#issuecomment-373938710, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAJC-PFfc4bTiQuAfRBz7WZAd2sug6-ks5tfUqdgaJpZM4StD4S .

dw commented 6 years ago

If you do another pull, I've landed the first chunk of the multithreaded connect work. Connections are now established up to 16 at a time, and this can be increased with MITOGEN_POOL_SIZE environment variable (although >16 isn't likely to have a tremendous effect)

This might help performance for you, but (as usual) I have no good target to test with in this location.

rouge8 commented 6 years ago

Running the same play as yesterday with 3e9f01bb7af78059fb85b53b4f7a0059f860a5f5:

Playbook run took 0 days, 0 hours, 2 minutes, 9 seconds

real    2m11.507s
user    4m5.808s
sys 1m4.400s

Running with bcf5e3b9028a48f3bbaeb55676d1ff5dbb243d3f:

Playbook run took 0 days, 0 hours, 1 minutes, 58 seconds

real    2m0.281s
user    4m5.931s
sys 1m7.796s

No big differences yet, but moving in the right direction