Gathering facts for windows hosts runs forever/never completes

Gustaf_Ankarloo · March 14, 2019, 10:10am

From time to time I find that some windows hosts never completes the setup task.
I never quite figured out why it happens. Usually restarting the window server solves the issue but looking at the windows server I see nothing wrong.
The applications on the windows server is working fine.

This what shows in the log:

2019-03-14 10:20:38,305 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 847
2019-03-14 10:20:38,697 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 753
2019-03-14 10:20:58,705 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:21:18,712 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:21:38,720 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320

…

And here is an exerpt of a full log with ANSIBLE_DEBUG=1 and -vvvvvvv

2019-03-14 10:20:37,642 p=8409 u=XXX| 8409 1552555237.64232: Loaded config def from plugin (callback/yaml)
2019-03-14 10:20:37,642 p=8409 u=XXX | 8409 1552555237.64252: in VariableManager get_vars()
2019-03-14 10:20:37,651 p=8409 u=XXX | 8409 1552555237.65143: Loading TestModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/core.py
2019-03-14 10:20:37,654 p=8409 u=XXX | 8409 1552555237.65443: Loading TestModule ‘files’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/files.py
2019-03-14 10:20:37,657 p=8409 u=XXX | 8409 1552555237.65740: Loading TestModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/mathstuff.py
2019-03-14 10:20:37,693 p=8409 u=XXX | 8409 1552555237.69369: Loading FilterModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/core.py
2019-03-14 10:20:37,701 p=8409 u=XXX | 8409 1552555237.70172: Loading FilterModule ‘ipaddr’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/ipaddr.py
2019-03-14 10:20:37,741 p=8409 u=XXX | 8409 1552555237.74095: Loading FilterModule ‘json_query’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/json_query.py
2019-03-14 10:20:37,746 p=8409 u=XXX | 8409 1552555237.74609: Loading FilterModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/mathstuff.py
2019-03-14 10:20:37,762 p=8409 u=XXX | 8409 1552555237.76242: Loading FilterModule ‘network’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/network.py
2019-03-14 10:20:37,765 p=8409 u=XXX | 8409 1552555237.76552: Loading FilterModule ‘urlsplit’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/urlsplit.py
2019-03-14 10:20:37,769 p=8409 u=XXX | 8409 1552555237.76903: done with get_vars()
2019-03-14 10:20:37,777 p=8409 u=XXX | 8409 1552555237.77765: Loading StrategyModule ‘linear’ from /usr/lib/python2.7/dist-packages/ansible/plugins/strategy/linear.py
2019-03-14 10:20:37,780 p=8409 u=XXX | 8409 1552555237.77918: getting the remaining hosts for this loop
2019-03-14 10:20:37,780 p=8409 u=XXX | 8409 1552555237.78031: done getting the remaining hosts for this loop
2019-03-14 10:20:37,780 p=8409 u=XXX | 8409 1552555237.78054: building list of next tasks for hosts
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78100: getting the next task for host REDACTED
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78126: done getting next task for host REDACTED
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78145: ^ task is: TASK: meta (flush_handlers)
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78161: ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78177: done building task lists
2019-03-14 10:20:37,781 p=8409 u=XXX | 8409 1552555237.78191: counting tasks in each state of execution
2019-03-14 10:20:37,782 p=8409 u=XXX | 8409 1552555237.78207: done counting tasks in each state of execution:
num_setups: 0
num_tasks: 1
num_rescue: 0
num_always: 0
2019-03-14 10:20:37,782 p=8409 u=XXX | 8409 1552555237.78223: advancing hosts in ITERATING_TASKS
2019-03-14 10:20:37,782 p=8409 u=XXX | 8409 1552555237.78237: starting to advance hosts
2019-03-14 10:20:37,782 p=8409 u=XXX | 8409 1552555237.78274: getting the next task for host REDACTED
2019-03-14 10:20:37,782 p=8409 u=XXX | 8409 1552555237.78291: done getting next task for host REDACTED
2019-03-14 10:20:37,783 p=8409 u=XXX | 8409 1552555237.78308: ^ task is: TASK: meta (flush_handlers)
2019-03-14 10:20:37,783 p=8409 u=XXX | 8409 1552555237.78324: ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-03-14 10:20:37,783 p=8409 u=XXX | 8409 1552555237.78338: done advancing hosts to next task
2019-03-14 10:20:37,783 p=8409 u=XXX | META: ran handlers
2019-03-14 10:20:37,784 p=8409 u=XXX | 8409 1552555237.78394: done queuing things up, now waiting for results queue to drain
2019-03-14 10:20:37,784 p=8409 u=XXX | 8409 1552555237.78435: results queue empty
2019-03-14 10:20:37,784 p=8409 u=XXX | 8409 1552555237.78450: checking for any_errors_fatal
2019-03-14 10:20:37,784 p=8409 u=XXX | 8409 1552555237.78468: done checking for any_errors_fatal
2019-03-14 10:20:37,784 p=8409 u=XXX | 8409 1552555237.78483: checking for max_fail_percentage
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78497: done checking for max_fail_percentage
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78512: checking to see if all hosts have failed and the running result is not ok
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78526: done checking to see if all hosts have failed
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78540: getting the remaining hosts for this loop
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78555: done getting the remaining hosts for this loop
2019-03-14 10:20:37,785 p=8409 u=XXX | 8409 1552555237.78572: building list of next tasks for hosts
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78614: getting the next task for host REDACTED
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78631: done getting next task for host REDACTED
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78648: ^ task is: TASK: setup
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78663: ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78678: done building task lists
2019-03-14 10:20:37,786 p=8409 u=XXX | 8409 1552555237.78692: counting tasks in each state of execution
2019-03-14 10:20:37,787 p=8409 u=XXX | 8409 1552555237.78707: done counting tasks in each state of execution:
num_setups: 0
num_tasks: 1
num_rescue: 0
num_always: 0
2019-03-14 10:20:37,787 p=8409 u=XXX | 8409 1552555237.78744: advancing hosts in ITERATING_TASKS
2019-03-14 10:20:37,787 p=8409 u=XXX | 8409 1552555237.78759: starting to advance hosts
2019-03-14 10:20:37,787 p=8409 u=XXX | 8409 1552555237.78773: getting the next task for host REDACTED
2019-03-14 10:20:37,787 p=8409 u=XXX | 8409 1552555237.78790: done getting next task for host REDACTED
2019-03-14 10:20:37,788 p=8409 u=XXX | 8409 1552555237.78807: ^ task is: TASK: setup
2019-03-14 10:20:37,788 p=8409 u=XXX | 8409 1552555237.78828: ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2019-03-14 10:20:37,788 p=8409 u=XXX | 8409 1552555237.78843: done advancing hosts to next task
2019-03-14 10:20:37,788 p=8409 u=XXX | 8409 1552555237.78883: getting variables
2019-03-14 10:20:37,789 p=8409 u=XXX | 8409 1552555237.78898: in VariableManager get_vars()
2019-03-14 10:20:37,789 p=8409 u=XXX | 8409 1552555237.78943: Loading TestModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,789 p=8409 u=XXX | 8409 1552555237.78961: Loading TestModule ‘files’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,790 p=8409 u=XXX | 8409 1552555237.78993: Loading TestModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,790 p=8409 u=XXX | 8409 1552555237.79048: Loading FilterModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,790 p=8409 u=XXX | 8409 1552555237.79065: Loading FilterModule ‘ipaddr’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/ipaddr.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,790 p=8409 u=XXX | 8409 1552555237.79081: Loading FilterModule ‘json_query’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/json_query.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,791 p=8409 u=XXX | 8409 1552555237.79098: Loading FilterModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/mathstuff.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,791 p=8409 u=XXX | 8409 1552555237.79135: Loading FilterModule ‘network’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/network.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,791 p=8409 u=XXX | 8409 1552555237.79151: Loading FilterModule ‘urlsplit’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/urlsplit.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,792 p=8409 u=XXX | 8409 1552555237.79237: Calling all_inventory to load vars for REDACTED
2019-03-14 10:20:37,792 p=8409 u=XXX | 8409 1552555237.79275: Calling groups_inventory to load vars for REDACTED
2019-03-14 10:20:37,793 p=8409 u=XXX | 8409 1552555237.79297: Calling all_plugins_inventory to load vars for REDACTED
2019-03-14 10:20:37,801 p=8409 u=XXX | 8409 1552555237.80124: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py
2019-03-14 10:20:37,801 p=8409 u=XXX | 8409 1552555237.80157: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,802 p=8409 u=XXX | 8409 1552555237.80208: Loading data from /home/XXX/ansible/inventory/group_vars/all/main.yml
2019-03-14 10:20:37,804 p=8409 u=XXX | 8409 1552555237.80438: Loading data from /home/XXX/ansible/inventory/group_vars/all/vault.yml
2019-03-14 10:20:37,807 p=8409 u=XXX | Found a vault_id (default) in the vaulttext
2019-03-14 10:20:37,807 p=8409 u=XXX | We have a secret associated with vault id (default), will try to use to decrypt /home/XXX/ansible/inventory/group_vars/all/vault.yml
2019-03-14 10:20:37,807 p=8409 u=XXX | Trying to use vault secret=(FileVaultSecret(filename=‘/home/XXX/.vault-apmt’)) id=default to decrypt /home/XXX/ansible/inventory/group_vars/all/vault.yml
2019-03-14 10:20:37,807 p=8409 u=XXX | Trying secret FileVaultSecret(filename=‘/home/XXX/.vault-apmt’) for vault_id=default
2019-03-14 10:20:37,842 p=8409 u=XXX | Decrypt of “/home/XXX/ansible/inventory/group_vars/all/vault.yml” successful with secret=FileVaultSecret(filename=‘/home/XXX/.vault-apmt’) and vault_id=default
2019-03-14 10:20:37,843 p=8409 u=XXX | 8409 1552555237.84305: Calling all_plugins_play to load vars for REDACTED
2019-03-14 10:20:37,843 p=8409 u=XXX | 8409 1552555237.84341: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,843 p=8409 u=XXX | 8409 1552555237.84360: Calling groups_plugins_inventory to load vars for REDACTED
2019-03-14 10:20:37,844 p=8409 u=XXX | 8409 1552555237.84397: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,844 p=8409 u=XXX | 8409 1552555237.84426: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,844 p=8409 u=XXX | 8409 1552555237.84463: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,845 p=8409 u=XXX | 8409 1552555237.84500: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,845 p=8409 u=XXX | 8409 1552555237.84538: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,845 p=8409 u=XXX | 8409 1552555237.84574: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,846 p=8409 u=XXX | 8409 1552555237.84611: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,846 p=8409 u=XXX | 8409 1552555237.84646: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,846 p=8409 u=XXX | 8409 1552555237.84682: processing dir /home/XXX/ansible/inventory/group_vars
2019-03-14 10:20:37,847 p=8409 u=XXX | 8409 1552555237.84732: Loading data from /home/XXX/ansible/inventory/group_vars/windowsGuest/main.yml
2019-03-14 10:20:37,849 p=8409 u=XXX | 8409 1552555237.84973: Loading data from /home/XXX/ansible/inventory/group_vars/windowsGuest/vault.yml
2019-03-14 10:20:37,852 p=8409 u=XXX | Found a vault_id (default) in the vaulttext
2019-03-14 10:20:37,852 p=8409 u=XXX | We have a secret associated with vault id (default), will try to use to decrypt /home/XXX/ansible/inventory/group_vars/windowsGuest/vault.yml
2019-03-14 10:20:37,852 p=8409 u=XXX | Trying to use vault secret=(FileVaultSecret(filename=‘/home/XXX/.vault-apmt’)) id=default to decrypt /home/XXX/ansible/inventory/group_vars/windowsGuest/vault.yml
2019-03-14 10:20:37,852 p=8409 u=XXX | Trying secret FileVaultSecret(filename=‘/home/XXX/.vault-apmt’) for vault_id=default
2019-03-14 10:20:37,885 p=8409 u=XXX | Decrypt of “/home/XXX/ansible/inventory/group_vars/windowsGuest/vault.yml” successful with secret=FileVaultSecret(filename=‘/home/XXX/.vault-apmt’) and vault_id=default
2019-03-14 10:20:37,886 p=8409 u=XXX | 8409 1552555237.88607: Calling groups_plugins_play to load vars for REDACTED
2019-03-14 10:20:37,886 p=8409 u=XXX | 8409 1552555237.88640: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,886 p=8409 u=XXX | 8409 1552555237.88679: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,887 p=8409 u=XXX | 8409 1552555237.88706: processing dir /home/XXX/ansible/inventory/host_vars
2019-03-14 10:20:37,887 p=8409 u=XXX | 8409 1552555237.88755: Loading VarsModule ‘host_group_vars’ from /usr/lib/python2.7/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,897 p=8409 u=XXX | 8409 1552555237.89733: done with get_vars()
2019-03-14 10:20:37,897 p=8409 u=XXX | 8409 1552555237.89765: done getting variables
2019-03-14 10:20:37,897 p=8409 u=XXX | 8409 1552555237.89785: sending task start callback, copying the task so we can template it temporarily
2019-03-14 10:20:37,898 p=8409 u=XXX | 8409 1552555237.89802: done copying, going to template now
2019-03-14 10:20:37,898 p=8409 u=XXX | 8409 1552555237.89820: done templating
2019-03-14 10:20:37,898 p=8409 u=XXX | 8409 1552555237.89835: here goes the callback…
2019-03-14 10:20:37,898 p=8409 u=XXX | 8409 1552555237.89853: sending task start callback
2019-03-14 10:20:37,898 p=8409 u=XXX | 8409 1552555237.89869: entering _queue_task() for REDACTED/setup
2019-03-14 10:20:37,901 p=8409 u=XXX | 8409 1552555237.90094: worker is 1 (out of 1 available)
2019-03-14 10:20:37,901 p=8409 u=XXX | 8409 1552555237.90177: exiting _queue_task() for REDACTED/setup
2019-03-14 10:20:37,902 p=8409 u=XXX | 8409 1552555237.90206: done queuing things up, now waiting for results queue to drain
2019-03-14 10:20:37,902 p=8409 u=XXX | 8409 1552555237.90224: waiting for pending results…
2019-03-14 10:20:37,906 p=8409 u=XXX | 8419 1552555237.90663: running TaskExecutor() for REDACTED/TASK: setup
2019-03-14 10:20:37,907 p=8409 u=XXX | 8419 1552555237.90734: in run() - task 005056a5-1e50-8181-16cb-00000000006e
2019-03-14 10:20:37,920 p=8409 u=XXX | 8419 1552555237.92072: calling self._execute()
2019-03-14 10:20:37,922 p=8409 u=XXX | 8419 1552555237.92231: Loading TestModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,922 p=8409 u=XXX | 8419 1552555237.92280: Loading TestModule ‘files’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,923 p=8409 u=XXX | 8419 1552555237.92300: Loading TestModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,923 p=8409 u=XXX | 8419 1552555237.92376: Loading FilterModule ‘core’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,924 p=8409 u=XXX | 8419 1552555237.92398: Loading FilterModule ‘ipaddr’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/ipaddr.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,924 p=8409 u=XXX | 8419 1552555237.92421: Loading FilterModule ‘json_query’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/json_query.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,924 p=8409 u=XXX | 8419 1552555237.92447: Loading FilterModule ‘mathstuff’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/mathstuff.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,924 p=8409 u=XXX | 8419 1552555237.92466: Loading FilterModule ‘network’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/network.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:37,924 p=8409 u=XXX | 8419 1552555237.92485: Loading FilterModule ‘urlsplit’ from /usr/lib/python2.7/dist-packages/ansible/plugins/filter/urlsplit.py (found_in_cache=True, class_only=False)
2019-03-14 10:20:38,085 p=8409 u=XXX | 8419 1552555238.08356: Loading Connection ‘winrm’ from /usr/lib/python2.7/dist-packages/ansible/plugins/connection/winrm.py
2019-03-14 10:20:38,087 p=8409 u=XXX | 8419 1552555238.08633: Loading ShellModule ‘powershell’ from /usr/lib/python2.7/dist-packages/ansible/plugins/shell/powershell.py
2019-03-14 10:20:38,096 p=8409 u=XXX | 8419 1552555238.09428: assigned :doc
2019-03-14 10:20:38,098 p=8409 u=XXX | 8419 1552555238.09661: Loaded config def from plugin (shell/powershell)
2019-03-14 10:20:38,106 p=8409 u=XXX | 8419 1552555238.10537: assigned :doc
2019-03-14 10:20:38,108 p=8409 u=XXX | 8419 1552555238.10747: Loaded config def from plugin (connection/winrm)
2019-03-14 10:20:38,114 p=8409 u=XXX | 8419 1552555238.11334: Loading ActionModule ‘normal’ from /usr/lib/python2.7/dist-packages/ansible/plugins/action/normal.py
2019-03-14 10:20:38,116 p=8409 u=XXX | 8419 1552555238.11504: starting attempt loop
2019-03-14 10:20:38,116 p=8409 u=XXX | 8419 1552555238.11662: running the handler
2019-03-14 10:20:38,142 p=8409 u=XXX | Using module file /usr/lib/python2.7/dist-packages/ansible/modules/windows/setup.ps1
2019-03-14 10:20:38,142 p=8409 u=XXX | 8419 1552555238.14275: _low_level_execute_command(): starting
2019-03-14 10:20:38,143 p=8409 u=XXX | 8419 1552555238.14293: _low_level_execute_command(): executing: -
2019-03-14 10:20:38,143 p=8409 u=XXX | checking if winrm_host xx.xx.xx.xx is an IPv6 address
2019-03-14 10:20:38,151 urllib3.connectionpool Starting new HTTPS connection (1): xx.xx.xx.xx:5986
2019-03-14 10:20:38,279 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 1627
2019-03-14 10:20:38,281 p=8409 u=XXX | EXEC (via pipeline wrapper)
2019-03-14 10:20:38,305 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 847
2019-03-14 10:20:38,697 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 753
2019-03-14 10:20:58,705 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:21:18,712 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:21:38,720 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:21:58,728 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:22:18,737 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:22:38,745 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:22:58,753 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:23:18,761 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:23:38,773 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:23:58,785 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:24:18,793 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:24:38,800 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:24:58,809 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:25:18,817 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:25:38,826 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:25:58,834 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:26:18,844 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:26:38,851 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:26:58,860 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:27:18,871 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:27:38,879 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:27:58,887 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:28:18,895 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:28:38,902 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:28:58,910 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:29:18,918 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 500 1320
2019-03-14 10:29:21,530 urllib3.connectionpool Starting new HTTPS connection (2): xx.xx.xx.xx:5986
2019-03-14 10:29:21,532 p=8409 u=XXX | 8409 1552555761.53071: RUNNING CLEANUP
2019-03-14 10:29:21,536 p=8409 u=XXX | [ERROR]: User interrupted execution

2019-03-14 10:29:21,565 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 757
2019-03-14 10:29:21,577 urllib3.connectionpool https://xx.xx.xx.xx:5986 “POST /wsman HTTP/1.1” 200 602

jborean · March 18, 2019, 7:30pm

What version of ansible are you on? IIRC there was a bug fixed in an older release that caused it to be really slow in a domain environment. It was fixed in 2.4, 2.5 https://github.com/ansible/ansible/pull/38646.

If that isn’t it you can use gather subset to try and track down what subset is hanging like;

`

hosts: windows
gather_facts: no
tasks:
setup:
gather_subset: # uncomment it one by one until it starts hanging
min
#- hardware
#- network
#- external
``
`

You can get a full list of groups here https://github.com/ansible/ansible/blob/devel/lib/ansible/modules/windows/setup.ps1#L68.

Thanks

Jordan

Gustaf_Ankarloo · March 21, 2019, 9:51am

Thank you for your suggestions.

I’m in version 2.7.0
and apparently it’s the ‘platform’ subset that hangs.

Topic		Replies	Views
Ansible Playbook running for longtime/indefinitely for windows 2012 R2 Ansible Playbook Ansible Project rhel , windows	6	2	April 17, 2018
Ansible for Windows: strange behavior Ansible Project windows	3	0	March 20, 2017
Config for Windows host Ansible Project windows	2	2	August 2, 2017
Ansible host inventory issues Ansible Project windows	0	1	May 30, 2017
unable to ping windows machine Ansible Project windows	3	3	September 24, 2020

Gathering facts for windows hosts runs forever/never completes

Related topics