New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ansible: (when running an ansible playbook, the process doesn't end itself. I have to press CONTROL C to end it.) #331

Closed
prateekj201 opened this Issue Jul 31, 2018 · 11 comments

Comments

Projects
None yet
2 participants
@prateekj201

prateekj201 commented Jul 31, 2018

ansible version=2.6.1
Python 2.7.12
Virtualenv 15.0.1
Machine: Ubuntu 16.04.3 LTS
Mitogen=mitogen-0.2.2
I am using virtualenv for execution of all playbooks.
ansible.cfg is updated for the path of strategic plugin with mitogen_linear.
When i execute the playbook (ansible-playbook test.yml -i hosts --key ~/.ssh/my-key.pem -u centos -vvvv) the playbook executes and definitely with better speed than usual. And irrespective of failure or success at the end the process doesn't end but simply left unfinished. Asin i have to press CONTROL C to end the process and come back to terminal to type.
Last few lines of output are attached with here, i have replced the host ip address with x.x.x.x and port number is 3257 here for reference.
mitogen-bug.txt

@prateekj201

This comment has been minimized.

prateekj201 commented Jul 31, 2018

Here's my pip list of virtualenv in case it helps

appdirs         1.4.3  
asn1crypto      0.22.0 
boto            2.49.0 
boto3           1.7.56 
botocore        1.10.56
cffi            1.7.0  
cryptography    1.8.1  
docutils        0.12   
ecdsa           0.13   
enum34          1.1.6  
futures         3.0.5  
httplib2        0.9.2  
idna            2.5    
ipaddress       1.0.18 
Jinja2          2.9.5  
jmespath        0.9.0  
MarkupSafe      1.0    
packaging       16.8   
paramiko        2.1.2  
pip             10.0.1 
pkg-resources   0.0.0  
pyasn1          0.2.3  
pycparser       2.17   
pycrypto        2.6.1  
pyparsing       2.2.0  
python-dateutil 2.5.3  
PyYAML          3.12   
requests        2.10.0 
s3transfer      0.1.13 
setuptools      39.2.0 
six             1.10.0 
wheel           0.31.1```
@prateekj201

This comment has been minimized.

prateekj201 commented Jul 31, 2018

Pasting the logs here same as attached file above

[pid 13469] 15:18:00.160048 I mitogen: mitogen.service.Pool(0x7f72ddd07850, size=16, th='mitogen.service.Pool.7f72ddd07850.worker-9'): channel or latch closed, exitting: None
[pid 13469] 15:18:00.160118 I mitogen: mitogen.service.Pool(0x7f72ddd07850, size=16, th='mitogen.service.Pool.7f72ddd07850.worker-4'): channel or latch closed, exitting: None
[pid 13469] 15:18:00.160292 I mitogen: mitogen.service.Pool(0x7f72ddd07850, size=16, th='mitogen.service.Pool.7f72ddd07850.worker-10'): channel or latch closed, exitting: None
[pid 13469] 15:18:00.160358 I mitogen: mitogen.service.Pool(0x7f72ddd07850, size=16, th='mitogen.service.Pool.7f72ddd07850.worker-11'): channel or latch closed, exitting: None
[pid 13469] 15:18:00.159786 I mitogen: mitogen.service.Pool(0x7f72ddd07850, size=16, th='mitogen.service.Pool.7f72ddd07850.worker-5'): channel or latch closed, exitting: None
[pid 13469] 15:18:00.162494 D mitogen: mitogen.ssh.Stream(u'ssh.x.x.x.x:3257'): child process exit status was 33024
[pid 13469] 15:18:00.164519 D mitogen: mitogen.ssh.Stream(u'ssh.x.x.x.x:3257').on_disconnect()
[pid 13469] 15:18:00.165081 D mitogen: mitogen.ssh.Stream(u'ssh.x.x.x.x:3257') is gone; propagating DEL_ROUTE for set([2, 3, 4, 1003])
[pid 13469] 15:18:00.165282 D mitogen: Router(Broker(0x7f72ddcf6fd0)).del_route(2)
[pid 13469] 15:18:00.165464 D mitogen: Router(Broker(0x7f72ddcf6fd0)).del_route(3)
[pid 13469] 15:18:00.165791 D mitogen: Router(Broker(0x7f72ddcf6fd0)).del_route(4)
[pid 13469] 15:18:00.166125 D mitogen: Router(Broker(0x7f72ddcf6fd0)).del_route(1003)
[pid 13469] 15:18:00.166471 I ansible_mitogen.services: Dropping Context(2, u'ssh.x.x.x.x:3257') due to disconnect of mitogen.ssh.Stream(u'ssh.x.x.x.x:3257')
[pid 13469] 15:18:00.166672 I ansible_mitogen.services: Dropping Context(4, u'ssh.x.x.x.x:3257.sudo.root') due to disconnect of mitogen.ssh.Stream(u'ssh.x.x.x.x:3257')
@prateekj201

This comment has been minimized.

prateekj201 commented Aug 1, 2018

Verified, this is happening in ansible version 2.4.0 and 2.5.0 as well with same mitogen 0.2.2

@dw

This comment has been minimized.

Owner

dw commented Aug 1, 2018

Hi @prateekj201, thanks for reporting! Would you mind emailing a full -vvv log if possible to dw@botanicus.net, otherwise, can you please at least scan the log for any "ERROR!" messages or lines like " E mitogen".

Please also include "ansible-config dump --only-changed", this may be related to another plugin

@prateekj201

This comment has been minimized.

prateekj201 commented Aug 1, 2018

mitogen-bug.txt
Here's all the log relevant to this.

Also, ansible-config dump --only-changed gives me:

DEFAULT_REMOTE_PORT(~/ansible-code/ansible.cfg) = 3257
DEFAULT_STRATEGY(~/ansible-code/ansible.cfg) = mitogen_linear
DEFAULT_STRATEGY_PLUGIN_PATH(~/ansible-code/ansible.cfg) = [u'~/ansible-code/mitogen-0.2.2/ansible_mitogen/plugins/str
HOST_KEY_CHECKING(~/ansible-code/ansible.cfg) = False```
@prateekj201

This comment has been minimized.

prateekj201 commented Aug 1, 2018

@dw Hey, i emailed you a file right now with all the logs. The log files attached here are the last few main lines related to this issue.

@prateekj201

This comment has been minimized.

prateekj201 commented Aug 6, 2018

Ok so i verified and this issue is happening when with any ansible playbook execution i am using more than two 'v' for extra verbosity. When i use less than 3 v(verbosity) it is working fine and when using three or more 'v' for extra verbosity the pid remains visible even after the playbook execution is finished

@dw

This comment has been minimized.

Owner

dw commented Aug 6, 2018

Hi @prateekj201! So sorry for the delay in replying, I've been deep in design mode for the next version of the project. I reviewed your log, and it looks like this is just a known issue:

When running with -vvv, log messages will be printed to the console after the Ansible run completes, as connection multiplexer shutdown only begins after Ansible exits. This is due to a lack of suitable shutdown hook in Ansible, and is fairly harmless, albeit cosmetically annoying. A future release may include a solution.

Can you confirm that after pressing ENTER to re-display the shell prompt, that the prompt does indeed actually appear, without needing CTRL+C? If it does appear, then it is just the connection multiplexer spamming debug output during shutdown.

It is because Ansible exposes no hook that would allow the multiplexer process to be shut down gracefully before Ansible exits, so its exit only begins when it notices that Ansible has already quit. It's annoying ,but in the current extension, it seems the best we can do.

I am going to keep this bug open, so other people will see the same explanation.

I am going to try and fix at least debug output as part of the stable series -- by hiding most of it behind the ANSIBLE_DEBUG environment variable. That would more or less 'fix' the issue :)

@dw

This comment has been minimized.

Owner

dw commented Aug 6, 2018

If you look at the log file you sent, notice that on line 5096, your prompt is being printed :) This is definitely the same issue as in the docs. Sorry for the trouble! I'll find a way to tidy this up as part of #316.

@prateekj201

This comment has been minimized.

prateekj201 commented Aug 6, 2018

yea i verified , after pressing enter or Control C , it takes us to the shell prompt

@dw dw added the target:v0.2 label Aug 11, 2018

dw added a commit that referenced this issue Aug 11, 2018

@dw

This comment has been minimized.

Owner

dw commented Aug 11, 2018

This is soon be on the master branch (end of weekend) and will make it into the next release. To be updated when a new release is made, subscribe to https://www.freelists.org/list/mitogen-announce

Thanks for reporting this!

@dw dw closed this Aug 11, 2018

dw added a commit that referenced this issue Aug 18, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment