2019-Jun Ansible devel branch and random hangs using winrm?

I am posting over at the Ansible Project  Google Group.

Upgraded ansible to 

$ ansible --version
ansible 2.9.0.dev0
  config file = /Users/tanner/projects/ansible.git/playbooks.git/celadonsystems.com/ansible.cfg
  configured module search path = [u'/Users/tanner/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /Users/tanner/projects/ansible.git/ansible/lib/ansible
  executable location = /Users/tanner/projects/ansible.git/ansible/bin/ansible
  python version = 2.7.10 (default, Feb 22 2019, 21:55:15) [GCC 4.2.1 Compatible Apple LLVM 10.0.1 (clang-1001.0.37.14)]

And now random playbooks and tasks just hang in unusual places. 

Before the upgrade of ansible this task worked as expected.

- name: Install programs (choco)
  win_chocolatey:
    name: "{{ item }}"
    state: "present"
  when:
    - chocolatey_packages is defined
  loop: "{{ chocolatey_packages|flatten(levels=1) }}"

The above task that randomly hangs.

<win2016.LAB.testing.com> ESTABLISH WINRM CONNECTION FOR USER: Admini...@LAB.testing.com on PORT 5986 TO win2016.LAB.testing.com
Using module file /Users/tanner/projects/ansible.git/ansible/lib/ansible/modules/windows/win_chocolatey.ps1
Pipelining is enabled.

I've let this sit for 12 hours.

No timeouts. No errors. 

$ python -V
Python 2.7.10

Management host: macOS Mojave 10.14.5

Managed host: Windows Server 2016

$ kinit --version
kinit (Heimdal 1.5.1apple1)

This feels like a personal problem or a python-2.7 problem (still in progress of upgrading to python3)

<update>

Doing a dtruss on the python process on the controller I just get screens of the following.

$ sudo dtruss -p 64569
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0
select(0x0, 0x0, 0x0, 0x0, 0x7FFEE3C1D610) = 0 0

<update>

I am doing the kinit myself.

I did install pexpect but didn’t seem to make a difference, Ansible still hung. This time on removal of the chocolatey packages hung, task below:

- name: remove old/deprecated packages (choco)
  win_chocolatey:
    name: "{{ chocolatey_remove_packages|list }}"
    state: "absent"
  when:
    - chocolatey_remove_packages is defined

Doing a “cup all” there are packages that need to be updated and the update process finishes as expected with an exit code  0

Chocolatey upgraded 9/40 packages.
 See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).

Upgraded:
 - googlechrome v75.0.3770.80
 - winscp v5.15.2
 - flashplayeractivex v32.0.0.207
 - git v2.22.0
 - winscp.install v5.15.2
 - cleanup v4.5.2.20190522
 - vscode v1.35.0
 - flashplayerplugin v32.0.0.207
 - git.install v2.22.0


PS C:\Users\Administrator.CORP> $LASTEXITCODE
0

<update>

Ansible did finally throw an error

TASK [win_chocolatey : update installed chocolatey packages] *******************
An exception occurred during task execution. To see the full traceback, use -vvv. The error was: ConnectionError: HTTPSConnectionPool(host='win7.LAB.testing.com', port=5986): Max retries exceeded with url: /wsman (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x111607d90>: Failed to establish a new connection: [Errno 8] nodename nor servname provided, or not known',))
fatal: [win7.LAB.testing.com]: FAILED! => {"msg": "Unexpected failure during module execution.", "stdout": ""}

Some time stats

real 65m28.845s
user 3m14.159s
sys 0m47.496s

<update>

Doing some debugging and I think the hang is on upgrading a package called CleanUp! (which I do maintain) <https://chocolatey.org/packages/cleanup> and the chocolateyintall.ps1 uses AutoIt

$ErrorActionPreference = 'Stop';

$packageName = 'CleanUp'
$version = '452'
$fullPackage = $packageName + $version + '.exe'
$url = 'http://stevengould.org/downloads/cleanup/' + $fullPackage
$checkSum = '6ac7576c0b48ddee292f85724c7917e11360927ff8e5c5a8d795577a4241c131'
$workSpace = Join-Path $env:TEMP "$packageName-$env:chocolateyPackageVersion"

# silent install requires AutoIT
#
$autoitExe = 'AutoIt3.exe'
$toolsDir = $(Split-Path -parent $MyInvocation.MyCommand.Definition)
$autoitFile = Join-Path $toolsDir 'cleanup.au3'
$fileFullPath = Join-Path $workSpace $fullPackage

$autoitProcess = Start-Process -FilePath $autoitExe -ArgumentList "$autoitFile $fileFullPath" -PassThru

$installArgs = @{
softwareName = 'CleanUp*'
packageName = $packageName
file = Join-Path $workSpace $fullPackage
url = $url
checksum = $checkSum
checksumType = 'sha256'
fileType = 'exe'
silentArgs = "/qn /norestart /l*v `"$($env:TEMP)\$($packageName)-$($env:chocolateyPackageVersion).MsiInstall.log`" ALLUSERS=1"
validExitCodes = @(0, 3010, 1641)
}

Install-ChocolateyPackage @installArgs

Installing the package at the console or upgrading the package at the console all works as expected.

But trying to install or upgrade the package via Ansible and win_chocolatey I see both "CleanUp452.exe *32" and "AutoIt3.exe *32” in Task Manager as well as powershell.exe and choice.exe.

IF remove cancel out (control-c) the Ansible process on the management host and I do a “choco list -lo” on the managed host I get a warning:

“[Pending] Removing incomplete install for ‘cleanup’”

That would seem to hint that the chocolatey was processing the CleanUp! package?

<update>

Took CleanUp! out of the package installation and upgrade tasks and now all win_chocolatey tasks complete.

Another chocolatey package I maintain EasyLog USB <https://chocolatey.org/packages/easylogusb>, it also uses AutoIt for installation/updates <https://github.com/basictheprogram/chocolatey-EasyLogUSB/blob/master/tools/chocolateyinstall.ps1> and the win_chocolatey update task hangs on this package too.

So it looks like win_chocolatey modules has problem interacting with AutoIt?

<update>

Tested against Windows7, Windows10, Windows Server 2008 R2, Windows Server 2016 and all releases hang on the upgrade of CleanUp!

Looking like the problem with win_chocolatey and AutoIt.