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

[prateekj201]

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]

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]

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]

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

[dw]

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]

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]

@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]

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]

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]

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]

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