mitogen
mitogen copied to clipboard
Published
20 hours ago •
mitogen-hq
mitogen-hq
Exception runnging ansible 2.8 and mitogen 0.2.8
Hi,
I am facing an exception to run any playbook / ad-hoc command in the following environment:
$ ansible --version
ansible 2.8.4
config file = /home/ansible/infra/ansible.cfg
configured module search path = [u'/home/ansible/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
ansible python module location = /usr/lib/python2.7/site-packages/ansible
executable location = /usr/bin/ansible
python version = 2.7.5 (default, Sep 12 2018, 05:31:16) [GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
$ python
Python 2.7.5 (default, Sep 12 2018, 05:31:16)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-36)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import mitogen
>>> print mitogen.__version__
(0, 2, 8)
Both ansible and mitogen are installed from EPEL repositories on a RHEL 7.7 box.
Works well without mitogen.
Here is the full trace:
$ ansible -m ping localhost -vvv
ansible 2.8.4
config file = /home/ansible/infra/ansible.cfg
configured module search path = [u'/home/ansible/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
ansible python module location = /usr/lib/python2.7/site-packages/ansible
executable location = /usr/bin/ansible
python version = 2.7.5 (default, Sep 12 2018, 05:31:16) [GCC 4.8.5 20150623 (Red Hat 4.8.5-36)]
Using /home/ansible/infra/ansible.cfg as config file
host_list declined parsing /home/ansible/infra/inventories/01-wea as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/01-wea as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/01-wea as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/01-wea inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/_vmware.py as it did not pass it's verify_file() method
[DEPRECATION WARNING]: The TRANSFORM_INVALID_GROUP_CHARS settings is set to allow bad characters in group names by default, this will change, but still be user configurable on deprecation. This feature will be removed in version 2.10.
Deprecation warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.
[WARNING]: Invalid characters were found in group names but not replaced, use -vvvv to see details
Parsed /home/ansible/infra/inventories/_vmware.py inventory source with script plugin
host_list declined parsing /home/ansible/infra/inventories/aix as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/aix as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/aix as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/aix inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/destroy as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/destroy as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/destroy as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/destroy inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/empty as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/empty as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/empty as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/empty inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/exzos as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/exzos as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/exzos as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/exzos inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/inventory as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/inventory as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/inventory as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/inventory inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/old_mysql as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/old_mysql as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/old_mysql as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/old_mysql inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/old_php as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/old_php as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/old_php as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/old_php inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/oldschool as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/oldschool as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/oldschool as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/oldschool inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/pointeuses as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/pointeuses as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/pointeuses as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/pointeuses inventory source with ini plugin
host_list declined parsing /home/ansible/infra/inventories/zabbix_tst as it did not pass it's verify_file() method
script declined parsing /home/ansible/infra/inventories/zabbix_tst as it did not pass it's verify_file() method
auto declined parsing /home/ansible/infra/inventories/zabbix_tst as it did not pass it's verify_file() method
Parsed /home/ansible/infra/inventories/zabbix_tst inventory source with ini plugin
[top 39485] 13:58:00.964105 D ansible_mitogen.affinity: CPU mask for Ansible top-level process: 0x000002
[top 39485] 13:58:00.965085 D ansible_mitogen.process: inherited open file limits: soft=16384 hard=16384
[top 39485] 13:58:00.965264 D ansible_mitogen.process: max open files already set to hard limit: 16384
[mux 39502] 13:58:00.969475 D ansible_mitogen.affinity: CPU mask for MuxProcess 0: 0x000001
[mux 39502] 13:58:00.984485 D mitogen.service: Pool(b190, size=32, th='MainThread'): initialized
[mux 39502] 13:58:00.984978 D ansible_mitogen.process: Service pool configured: size=32
META: ran handlers
[task 39536] 13:58:01.059281 D ansible_mitogen.affinity: CPU mask for WorkerProcess: 0x000002
[task 39536] 13:58:01.076850 D ansible_mitogen.process: will use multiplexer 0 (/tmp/mitogen_unix_LpKoEy.sock) to connect to "localhost"
[task 39536] 13:58:01.077113 D mitogen.unix: client: connecting to /tmp/mitogen_unix_LpKoEy.sock
[task 39536] 13:58:01.077642 D mitogen.unix: client: local ID is 1, remote is 0
[mux 39502] 13:58:01.077822 D mitogen.unix: listener: accepted connection from PID 39536: unix_client.39536
[mux 39502] 13:58:01.079719 D mitogen.parent: creating connection to context 2 using mitogen.parent
[mux 39502] 13:58:01.132095 D mitogen.parent: failing connection None due to AssertionError()
ERROR! [mux 39502] 13:58:01.132694 E mitogen.service: Pool(b190, size=32, th='mitogen.Pool.b190.0'): while invoking u'get' of u'ansible_mitogen.services.ContextService' [64/17683]
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 621, in _on_service_call
return invoker.invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 307, in invoke
response = self._invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 293, in _invoke
ret = method(**kwargs)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 467, in get
reraise(*result)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 425, in _wait_or_start
response = self._connect(key, spec, via=via)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 377, in _connect
context = method(via=via, unidirectional=True, **spec['kwargs'])
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2483, in local
return self.connect(u'local', **kwargs)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2443, in connect
return self._connect(klass, **mitogen.core.Kwargs(kwargs))
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2423, in _connect
conn.connect(context=context)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 1705, in connect
raise self.exception
AssertionError
[WARNING]:
[task 39536] 13:58:01.135219 W ansible_mitogen.connection: Connection failed; stack configuration was:
({u'kwargs': {u'python_path': [u'/usr/bin/python2']}, u'method': u'local'},
{u'enable_lru': True,
u'kwargs': {u'connect_timeout': 10,
u'password': None,
u'python_path': [u'/usr/bin/python2'],
u'remote_name': None,
u'sudo_args': [u'-H', u'-S', u'-n'],
u'sudo_path': u'sudo',
u'username': u'root'},
u'method': u'sudo'})
[task 39536] 13:58:01.138016 D mitogen: MitogenProtocol(unix_listener.39502): disconnecting
[task 39536] 13:58:01.138274 D mitogen: Waker(fd=11/12): disconnecting
[mux 39502] 13:58:01.138283 D mitogen: <Side of unix_client.39536 fd 76>: empty read, disconnecting
[mux 39502] 13:58:01.138490 D mitogen: MitogenProtocol(unix_client.39536): disconnecting
[task 39536] 13:58:01.138570 D mitogen: Router(Broker(3710)): stats: 0 module requests in 0 ms, 0 sent (0 ms minify time), 0 negative responses. Sent 0.0 kb total, 0.0 kb avg.
The full traceback is:
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 145, in run
res = self._execute()
File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 664, in _execute
result = self._handler.run(task_vars=variables)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/mixins.py", line 116, in run
return super(ActionModuleMixin, self).run(tmp, task_vars)
File "/usr/lib/python2.7/site-packages/ansible/plugins/action/normal.py", line 46, in run
result = merge_hash(result, self._execute_module(task_vars=task_vars, wrap_async=wrap_async))
File "/usr/lib/python2.7/site-packages/ansible_mitogen/mixins.py", line 346, in _execute_module
self._temp_file_gibberish(module_args, wrap_async)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/mixins.py", line 325, in _temp_file_gibberish
self._connection.get_good_temp_dir()
File "/usr/lib/python2.7/site-packages/ansible_mitogen/connection.py", line 762, in get_good_temp_dir
self._connect()
File "/usr/lib/python2.7/site-packages/ansible_mitogen/connection.py", line 782, in _connect
self._connect_stack(stack)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/connection.py", line 735, in _connect_stack
stack=mitogen.utils.cast(list(stack)),
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 120, in call
return call_context.call_service(service_name, method_name, **kwargs)
File "/usr/lib/python2.7/site-packages/mitogen/core.py", line 2270, in call_service
return recv.get().unpickle()
File "/usr/lib/python2.7/site-packages/mitogen/core.py", line 963, in unpickle
raise obj
CallError: exceptions.AssertionError:
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 621, in _on_service_call
return invoker.invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 307, in invoke
response = self._invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 293, in _invoke
ret = method(**kwargs)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 467, in get
reraise(*result)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 425, in _wait_or_start
response = self._connect(key, spec, via=via)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 377, in _connect
context = method(via=via, unidirectional=True, **spec['kwargs'])
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2483, in local
return self.connect(u'local', **kwargs)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2443, in connect
return self._connect(klass, **mitogen.core.Kwargs(kwargs))
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2423, in _connect
conn.connect(context=context)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 1705, in connect
raise self.exception
localhost | FAILED! => {
"msg": "Unexpected failure during module execution.",
"stdout": ""
}
[mux 39502] 13:58:01.148895 D mitogen: Waker(fd=6/8): disconnecting
[mux 39502] 13:58:01.149370 D mitogen: Router(Broker(5b90)): stats: 0 module requests in 0 ms, 0 sent (0 ms minify time), 0 negative responses. Sent 0.0 kb total, 0.0 kb avg.
[mux 39502] 13:58:01.149601 D mitogen.service: thread mitogen.Pool.b190.1 exiting gracefully
[mux 39502] 13:58:01.149866 D mitogen.service: thread mitogen.Pool.b190.2 exiting gracefully
[mux 39502] 13:58:01.150069 D mitogen.service: thread mitogen.Pool.b190.3 exiting gracefully
[mux 39502] 13:58:01.150264 D mitogen.service: thread mitogen.Pool.b190.4 exiting gracefully
[mux 39502] 13:58:01.150536 D mitogen.service: thread mitogen.Pool.b190.5 exiting gracefully
[mux 39502] 13:58:01.150816 D mitogen.service: thread mitogen.Pool.b190.6 exiting gracefully
[mux 39502] 13:58:01.151079 D mitogen.service: thread mitogen.Pool.b190.7 exiting gracefully
[mux 39502] 13:58:01.151331 D mitogen.service: thread mitogen.Pool.b190.8 exiting gracefully
[mux 39502] 13:58:01.151581 D mitogen.service: thread mitogen.Pool.b190.9 exiting gracefully
[mux 39502] 13:58:01.151796 D mitogen.service: thread mitogen.Pool.b190.10 exiting gracefully
[mux 39502] 13:58:01.152022 D mitogen.service: thread mitogen.Pool.b190.11 exiting gracefully
[mux 39502] 13:58:01.152260 D mitogen.service: thread mitogen.Pool.b190.12 exiting gracefully
[mux 39502] 13:58:01.152530 D mitogen.service: thread mitogen.Pool.b190.13 exiting gracefully
[mux 39502] 13:58:01.152748 D mitogen.service: thread mitogen.Pool.b190.14 exiting gracefully
[mux 39502] 13:58:01.152973 D mitogen.service: thread mitogen.Pool.b190.15 exiting gracefully
[mux 39502] 13:58:01.153218 D mitogen.service: thread mitogen.Pool.b190.16 exiting gracefully
[mux 39502] 13:58:01.153478 D mitogen.service: thread mitogen.Pool.b190.17 exiting gracefully
[mux 39502] 13:58:01.153695 D mitogen.service: thread mitogen.Pool.b190.18 exiting gracefully
[mux 39502] 13:58:01.153900 D mitogen.service: thread mitogen.Pool.b190.19 exiting gracefully
[mux 39502] 13:58:01.154122 D mitogen.service: thread mitogen.Pool.b190.20 exiting gracefully
[mux 39502] 13:58:01.154374 D mitogen.service: thread mitogen.Pool.b190.21 exiting gracefully
[mux 39502] 13:58:01.154605 D mitogen.service: thread mitogen.Pool.b190.22 exiting gracefully
[mux 39502] 13:58:01.154810 D mitogen.service: thread mitogen.Pool.b190.23 exiting gracefully
[mux 39502] 13:58:01.155031 D mitogen.service: thread mitogen.Pool.b190.24 exiting gracefully
[mux 39502] 13:58:01.155240 D mitogen.service: thread mitogen.Pool.b190.25 exiting gracefully
[mux 39502] 13:58:01.155505 D mitogen.service: thread mitogen.Pool.b190.26 exiting gracefully
[mux 39502] 13:58:01.155715 D mitogen.service: thread mitogen.Pool.b190.27 exiting gracefully
[mux 39502] 13:58:01.155921 D mitogen.service: thread mitogen.Pool.b190.28 exiting gracefully
[mux 39502] 13:58:01.156143 D mitogen.service: thread mitogen.Pool.b190.29 exiting gracefully
[mux 39502] 13:58:01.156372 D mitogen.service: thread mitogen.Pool.b190.30 exiting gracefully
[mux 39502] 13:58:01.156698 D mitogen.service: thread mitogen.Pool.b190.31 exiting gracefully
[mux 39502] 13:58:01.156934 D mitogen.service: thread mitogen.Pool.b190.0 exiting gracefully
[mux 39502] 13:58:01.157265 D mitogen.service: FileService().on_shutdown()
[top 39485] 13:58:01.161564 D ansible_mitogen.process: multiplexer 0 PID 39502 exited with return code 0
It looks like this assertion may not be coming from within Mitogen.. possible it is Python struggling to start a subprocess.
If you allow me a few hours, I will check in some extra logging into master so the full stack trace of the exception can be captured. Apologies for this! I didn't realize the code path capturing that exception could capture such a generic error, it needs more logging
Thanks a ton for reporting this!
would you mind grabbing dmw branch from Git and trying your -vvv run again? There should be a new chunk of log in there, starting with 'failed to start child', that will include the original stack trace
You can also simply grab a ZIP file: https://github.com/dw/mitogen/archive/dmw.zip
Hi,
I didn't manage to reproduce my issue. :(
Here is my ansible config, if it can help:
inventory = inventories/
forks = 15
poll_interval = 5
ansible_managed = Managed by Ansible
retry_files_enabled = False
retry_files_save_path = ~/.ansible/retry
fact_caching = memory
vault_password_file=.vault
remote_user = ansible
private_key_file=/home/ansible/.ssh/id_rsa_ansible
host_key_checking = False
bin_ansible_callbacks = True
#stdout_callback = debug
#callback_plugins = /usr/share/ansible/plugins/callback
callback_whitelist = log_plays
#experimental
strategy_plugins =/usr/lib/python2.7/site-packages/ansible_mitogen/plugins/strategy
strategy = mitogen_linear
[privilege_escalation]
become = true
become_method = sudo
become_user = root
become_ask_pass = false
[ssh_connection]
ssh_args = -C -o ControlMaster=auto -o ControlPersist=60s -F /home/ansible/.ssh/config_ansible
[diff]
always = true
And my SSH config:
Host esx-p-*
User root
IdentityFile ~/.ssh/id_rsa_ansible
StrictHostKeyChecking no
UserKnownHostsFile=~/.ssh/kown_hosts
Host *
StrictHostKeyChecking no
UserKnownHostsFile=/dev/null
User ansible
IdentityFile ~/.ssh/id_rsa_ansible
```
I will give it another try tomorrow.
Thanks for your time!
oh that's interesting. I forgot to ask: was the bug 100% repeatable before?
I just assumed it was 100% repeatable because you were able to produce logs :) If this doesn't trigger every time, that's super important information
I spent some time trying to reproduce on both my Ansible host and a host where Ansible has been freshly installed, with no success.
The issue seemed to be 100% repeatable two days ago, for my colleague and myself (at least 6-7 runs in a row).
The only change on the Ansible host between the time I opened this issue and now is a temporary downgrade of Ansible (to 2.7) to run an incompatible playbook in 2.8, and immediately re-update again. Not sure if it could explain this strange behavior...
During the gather-facts stage of running ansible-playbook, I get a similar error stack trace as #645 on ansible 2.7.5 rhel 7.7 using python2-mitogen 0.2.8. Are there any work arounds or suggestions for finding what the cause is?
I am having the exact same issue on a RHEL7.6 box with the stock mitogen :
$ yum list installed | grep mitogen
python2-mitogen.noarch 0.2.8-1.el7 @base-epel
Stock Ansible and Python from RHEL7.6 :
$ ansible --version
ansible 2.8.4
config file = /opt/ansible-playbooks-poc/ansible.cfg
configured module search path = [u'/home/kwyxz/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
ansible python module location = /usr/lib/python2.7/site-packages/ansible
executable location = /usr/bin/ansible
python version = 2.7.5 (default, Jun 11 2019, 14:33:56) [GCC 4.8.5 20150623 (Red Hat 4.8.5-39)]
$ python
Python 2.7.5 (default, Jun 11 2019, 14:33:56)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-39)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import mitogen
>>> print mitogen.__version__
(0, 2, 8)
Any attempt to run Ansible using the mitogen_linear strategy ends with:
TASK [Gathering Facts] **************************************************************************************************************************************************************************************************************[376/1859]
ERROR! [mux 39135] 11:46:37.976392 E mitogen.service: Pool(a090, size=32, th='mitogen.Pool.a090.0'): while invoking u'get' of u'ansible_mitogen.services.ContextService'
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 621, in _on_service_call
return invoker.invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 307, in invoke
response = self._invoke(method_name, kwargs, msg)
File "/usr/lib/python2.7/site-packages/mitogen/service.py", line 293, in _invoke
ret = method(**kwargs)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 467, in get
reraise(*result)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 425, in _wait_or_start
response = self._connect(key, spec, via=via)
File "/usr/lib/python2.7/site-packages/ansible_mitogen/services.py", line 377, in _connect
context = method(via=via, unidirectional=True, **spec['kwargs'])
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2501, in ssh
return self.connect(u'ssh', **kwargs)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2443, in connect
return self._connect(klass, **mitogen.core.Kwargs(kwargs))
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 2423, in _connect
conn.connect(context=context)
File "/usr/lib/python2.7/site-packages/mitogen/parent.py", line 1705, in connect
raise self.exception
AssertionError
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: raise self.exception
fatal: [192.168.0.10]: FAILED! => {"msg": "Unexpected failure during module execution.", "stdout": ""}
However using the mitogen-dmw version from the zip file https://github.com/dw/mitogen/archive/dmw.zip and pointing to it in ansible.cfg seems to work fine, fyi.
I just installed mitogen 0.2.9 on centos7. I am seeing this issue as well and it is unusable at this point. Has there been any progress on the cause or how to fix this?
ansible 2.9.23 python 2.7.5 kernel 3.10.0-1160.31.1.el7.x86_64
