trying to debug ansible and win_package

[Divan Santana]

Hi,

I'm trying to debug a ansible windows issue, if someone with powershell
knowledge could help me debug it, it would be great.

I can successfully win_ping win_setup the windows 2019SE server, but not
win_package install or install using chocolatey. No idea why.

I have this piece of ansible code, to install a package via win_package.

- name: Ensure 7-Zip is installed through win_package
win_package:
path: C:\temp\7z.exe
state: present

The above fails with:

The win_package action failed to execute in the expected time frame (5) and was terminated.

I run my playbook with -vvvvv, I see this[1] in the output. I believe
to debug this further I need to run the powershell script on the windows
box directly. I'm not quite sure how to do that. What I've done is
enable powershell script block logging, so that I can decode the
EncodedCommand string (not sure how else to decode it?). Looking at the
Event Viewer, I can see that the powershell script block is this[2].

I'm rather clueless with powershell. I'm now stuck at, how can I
execute this powershell script block[2] in the same manner as ansible is
doing it, to see why it's failing to install? Currently I take the
scriptblock[2] as is and paste it in powershell which simply returns
nothing to the screen.

Any help would be appreciated. Version details in [3].


[1]:
Using module file /home/opc/.ansible/collections/ansible_collections/ansible/windows/plugins/modules/win_package.ps1
Pipelining is enabled.
<10.20.100.184> ESTABLISH WINRM CONNECTION FOR USER: opc on PORT 5986 TO 10.20.100.184
<10.20.100.184> WINRM CONNECT: transport=credssp endpoint=https://10.20.100.184:5986/wsman
<10.20.100.184> WINRM OPEN SHELL: 37E74DAA-A27C-4642-89BB-CDDD11AF95DF
EXEC (via pipeline wrapper)
<10.20.100.184> WINRM EXEC 'PowerShell' ['-NoProfile', '-NonInteractive', '-ExecutionPolicy', 'Unrestricted', '-EncodedCommand', 'UABvAHcAZQByAFMAaABlAGwAbAAgAC0ATgBvAFAAcgBvAGYAaQBsAGUAIAAtAE4AbwBuAEkAbgB0AGUAcgBhAGMAdABpAHYAZQAgAC0ARQB4AGUAYwB1AHQAaQBvAG4AUABvAGwAaQBjAHkAIABVAG4AcgBlAHMAdAByAGkAYwB0AGUAZAAgAC0ARQBuAGMAbwBkAGUAZABDAG8AbQBtAGEAbgBkACAASgBnAEIAagBBAEcAZwBBAFkAdwBCAHcAQQBDADQAQQBZAHcAQgB2AEEARwAwAEEASQBBAEEAMgBBAEQAVQBBAE0AQQBBAHcAQQBEAEUAQQBJAEEAQQArAEEAQwBBAEEASgBBAEIAdQBBAEgAVQBBAGIAQQBCAHMAQQBBAG8AQQBhAFEAQgBtAEEAQwBBAEEASwBBAEEAawBBAEYAQQBBAFUAdwBCAFcAQQBHAFUAQQBjAGcAQgB6AEEARwBrAEEAYgB3AEIAdQBBAEYAUQBBAFkAUQBCAGkAQQBHAHcAQQBaAFEAQQB1AEEARgBBAEEAVQB3AEIAVwBBAEcAVQBBAGMAZwBCAHoAQQBHAGsAQQBiAHcAQgB1AEEAQwBBAEEATABRAEIAcwBBAEgAUQBBAEkAQQBCAGIAQQBGAFkAQQBaAFEAQgB5AEEASABNAEEAYQBRAEIAdgBBAEcANABBAFgAUQBBAGkAQQBEAE0AQQBMAGcAQQB3AEEAQwBJAEEASwBRAEEAZwBBAEgAcwBBAEMAZwBBAG4AQQBIAHMAQQBJAGcAQgBtAEEARwBFAEEAYQBRAEIAcwBBAEcAVQBBAFoAQQBBAGkAQQBEAG8AQQBkAEEAQgB5AEEASABVAEEAWgBRAEEAcwBBAEMASQBBAGIAUQBCAHoAQQBHAGMAQQBJAGcAQQA2AEEAQwBJAEEAUQBRAEIAdQBBAEgATQBBAGEAUQBCAGkAQQBHAHcAQQBaAFEAQQBnAEEASABJAEEAWgBRAEIAeABBAEgAVQBBAGEAUQBCAHkAQQBHAFUAQQBjAHcAQQBnAEEARgBBAEEAYgB3AEIAMwBBAEcAVQBBAGMAZwBCAFQAQQBHAGcAQQBaAFEAQgBzAEEARwB3AEEASQBBAEIAMgBBAEQATQBBAEwAZwBBAHcAQQBDAEEAQQBiAHcAQgB5AEEAQwBBAEEAYgBnAEIAbABBAEgAYwBBAFoAUQBCAHkAQQBDAEkAQQBmAFEAQQBuAEEAQQBvAEEAWgBRAEIANABBAEcAawBBAGQAQQBBAGcAQQBEAEUAQQBDAGcAQgA5AEEAQQBvAEEASgBBAEIAbABBAEgAZwBBAFoAUQBCAGoAQQBGADgAQQBkAHcAQgB5AEEARwBFAEEAYwBBAEIAdwBBAEcAVQBBAGMAZwBCAGYAQQBIAE0AQQBkAEEAQgB5AEEAQwBBAEEAUABRAEEAZwBBAEMAUQBBAGEAUQBCAHUAQQBIAEEAQQBkAFEAQgAwAEEAQwBBAEEAZgBBAEEAZwBBAEUAOABBAGQAUQBCADAAQQBDADAAQQBVAHcAQgAwAEEASABJAEEAYQBRAEIAdQBBAEcAYwBBAEMAZwBBAGsAQQBIAE0AQQBjAEEAQgBzAEEARwBrAEEAZABBAEIAZgBBAEgAQQBBAFkAUQBCAHkAQQBIAFEAQQBjAHcAQQBnAEEARAAwAEEASQBBAEEAawBBAEcAVQBBAGUAQQBCAGwAQQBHAE0AQQBYAHcAQgAzAEEASABJAEEAWQBRAEIAdwBBAEgAQQBBAFoAUQBCAHkAQQBGADgAQQBjAHcAQgAwAEEASABJAEEATABnAEIAVABBAEgAQQBBAGIAQQBCAHAAQQBIAFEAQQBLAEEAQgBBAEEAQwBnAEEASQBnAEIAZwBBAEQAQQBBAFkAQQBBAHcAQQBHAEEAQQBNAEEAQgBnAEEARABBAEEASQBnAEEAcABBAEMAdwBBAEkAQQBBAHkAQQBDAHcAQQBJAEEAQgBiAEEARgBNAEEAZABBAEIAeQBBAEcAawBBAGIAZwBCAG4AQQBGAE0AQQBjAEEAQgBzAEEARwBrAEEAZABBAEIAUABBAEgAQQBBAGQAQQBCAHAAQQBHADgAQQBiAGcAQgB6AEEARgAwAEEATwBnAEEANgBBAEYASQBBAFoAUQBCAHQAQQBHADgAQQBkAGcAQgBsAEEARQBVAEEAYgBRAEIAdwBBAEgAUQBBAGUAUQBCAEYAQQBHADQAQQBkAEEAQgB5AEEARwBrAEEAWgBRAEIAegBBAEMAawBBAEMAZwBCAEoAQQBHAFkAQQBJAEEAQQBvAEEAQwAwAEEAYgBnAEIAdgBBAEgAUQBBAEkAQQBBAGsAQQBIAE0AQQBjAEEAQgBzAEEARwBrAEEAZABBAEIAZgBBAEgAQQBBAFkAUQBCAHkAQQBIAFEAQQBjAHcAQQB1AEEARQB3AEEAWgBRAEIAdQBBAEcAYwBBAGQAQQBCAG8AQQBDAEEAQQBMAFEAQgBsAEEASABFAEEASQBBAEEAeQBBAEMAawBBAEkAQQBCADcAQQBDAEEAQQBkAEEAQgBvAEEASABJAEEAYgB3AEIAMwBBAEMAQQBBAEkAZwBCAHAAQQBHADQAQQBkAGcAQgBoAEEARwB3AEEAYQBRAEIAawBBAEMAQQBBAGMAQQBCAGgAQQBIAGsAQQBiAEEAQgB2AEEARwBFAEEAWgBBAEEAaQBBAEMAQQBBAGYAUQBBAEsAQQBGAE0AQQBaAFEAQgAwAEEAQwAwAEEAVgBnAEIAaABBAEgASQBBAGEAUQBCAGgAQQBHAEkAQQBiAEEAQgBsAEEAQwBBAEEATABRAEIATwBBAEcARQBBAGIAUQBCAGwAQQBDAEEAQQBhAGcAQgB6AEEARwA4AEEAYgBnAEIAZgBBAEgASQBBAFkAUQBCADMAQQBDAEEAQQBMAFEAQgBXAEEARwBFAEEAYgBBAEIAMQBBAEcAVQBBAEkAQQBBAGsAQQBIAE0AQQBjAEEAQgBzAEEARwBrAEEAZABBAEIAZgBBAEgAQQBBAFkAUQBCAHkAQQBIAFEAQQBjAHcAQgBiAEEARABFAEEAWABRAEEASwBBAEMAUQBBAFoAUQBCADQAQQBHAFUAQQBZAHcAQgBmAEEASABjAEEAYwBnAEIAaABBAEgAQQBBAGMAQQBCAGwAQQBIAEkAQQBJAEEAQQA5AEEAQwBBAEEAVwB3AEIAVABBAEcATQBBAGMAZwBCAHAAQQBIAEEAQQBkAEEAQgBDAEEARwB3AEEAYgB3AEIAagBBAEcAcwBBAFgAUQBBADYAQQBEAG8AQQBRAHcAQgB5AEEARwBVAEEAWQBRAEIAMABBAEcAVQBBAEsAQQBBAGsAQQBIAE0AQQBjAEEAQgBzAEEARwBrAEEAZABBAEIAZgBBAEgAQQBBAFkAUQBCAHkAQQBIAFEAQQBjAHcAQgBiAEEARABBAEEAWABRAEEAcABBAEEAbwBBAEoAZwBBAGsAQQBHAFUAQQBlAEEAQgBsAEEARwBNAEEAWAB3AEIAMwBBAEgASQBBAFkAUQBCAHcAQQBIAEEAQQBaAFEAQgB5AEEAQQA9AD0A']
<10.20.100.184> WINRM CLOSE SHELL: 37E74DAA-A27C-4642-89BB-CDDD11AF95DF
fatal: [divan-windows-test-prod]: FAILED! => {
"changed": false,
"msg": "The win_package action failed to execute in the expected time frame (5) and was terminated"
}

[2]:

{
param (
[String]
$Arguments,

[Int32[]]
$ReturnCodes,

[Object]
$Module,

[String]
$Path,

[String]
$State,

[String]
$WorkingDirectory,

[String]
$RegistryPath,

[Switch]
$WaitChildren
)

$invokeParams = @{
Module = $Module
ReturnCodes = $ReturnCodes
WorkingDirectory = $WorkingDirectory
WaitChildren = $WaitChildren
}

if ($Path) {
$invokeParams.CommandLine = ConvertTo-EscapedArgument -InputObject $Path
}
else {
$registryProperties = Get-ItemProperty -LiteralPath $RegistryPath

if ('QuietUninstallString' -in $registryProperties.PSObject.Properties.Name) {
$command = $registryProperties.QuietUninstallString
}
elseif ('UninstallString' -in $registryProperties.PSObject.Properties.Name) {
$command = $registryProperties.UninstallString
}
else {
$module.FailJson("Failed to find registry uninstall string at registry path '$RegistryPath'")
}

# If the uninstall string starts with '%', we need to expand the env vars.
if ($command.StartsWith('%') -or $command.StartsWith('"%')) {
$command = [System.Environment]::ExpandEnvironmentVariables($command)
}

# If the command is not quoted and contains spaces we need to see if it needs to be manually quoted for the executable.
if (-not $command.StartsWith('"') -and $command.Contains(' ')) {
$rawArguments = [System.Collections.Generic.List[String]]@()

$executable = New-Object -TypeName System.Text.StringBuilder
foreach ($cmd in ($command | ConvertFrom-EscapedArgument)) {
if ($rawArguments.Count -eq 0) {
# Still haven't found the path, append the arg to the executable path and see if it exists.
$null = $executable.Append($cmd)
$exe = $executable.ToString()
if (Test-Path -LiteralPath $exe -PathType Leaf) {
$rawArguments.Add($exe)
}
else {
$null = $executable.Append(" ") # The arg had a space and we need to preserve that.
}
}
else {
$rawArguments.Add($cmd)
}
}

# If we still couldn't find a file just use the command literally and hope WIndows can handle it,
# otherwise recombine the args which will also quote whatever is needed.
if ($rawArguments.Count -gt 0) {
$command = @($rawArguments | ConvertTo-EscapedArgument) -join ' '
}
}

$invokeParams.CommandLine = $command
}

if ($Arguments) {
$invokeParams.CommandLine += " $Arguments"
}

Invoke-Executable @invokeParams
}


My version details are[3]:

[3]:
ansible 2.16
python 3.10.13
ansible.windows 2.1.0

pip list:

ansible 9.0.1
ansible-compat 4.1.10
ansible-core 2.16.0
ansible-lint 6.22.0
arrow 1.3.0
attrs 23.1.0
black 23.11.0
bracex 2.4
certifi 2023.11.17
cffi 1.16.0
charset-normalizer 3.3.2
circuitbreaker 1.4.0
click 8.0.4
cryptography 41.0.5
decorator 5.1.1
filelock 3.13.1
gssapi 1.8.3
idna 3.4
Jinja2 3.1.2
jmespath 0.10.0
jsonschema 4.20.0
jsonschema-specifications 2023.11.1
krb5 0.5.1
markdown-it-py 3.0.0
MarkupSafe 2.1.3
mdurl 0.1.2
mypy-extensions 1.0.0
oci 2.116.0
oci-cli 3.36.2
packaging 23.2
pathspec 0.11.2
pip 23.0.1
platformdirs 4.0.0
prompt-toolkit 3.0.29
pycparser 2.21
Pygments 2.17.2
pykerberos 1.2.4
pyOpenSSL 23.3.0
pyspnego 0.10.2
python-dateutil 2.8.2
pytz 2023.3.post1
pywinrm 0.4.3
PyYAML 6.0.1
referencing 0.31.0
requests 2.31.0
requests-credssp 2.0.0
requests-kerberos 0.14.0
requests-ntlm 1.2.0
resolvelib 1.0.1
rich 13.7.0
rpds-py 0.13.1
ruamel.yaml 0.18.5
ruamel.yaml.clib 0.2.8
setuptools 65.5.0
six 1.16.0
subprocess-tee 0.4.1
terminaltables 3.1.0
tomli 2.0.1
types-python-dateutil 2.8.19.14
typing_extensions 4.8.0
urllib3 2.1.0
wcmatch 8.5
wcwidth 0.2.12
xmltodict 0.13.0
yamllint 1.33.0

[jbor...@gmail.com]

The only time this error ever appears is if you have a timeout set on the task [1]. Check to ensure you don't have that config entry set 'ansible-config dump --only-changed' or haven't set it on the task play.

[1] https://docs.ansible.com/ansible/latest/reference_appendices/config.html#task-timeout

[Divan Santana]

>> The win_package action failed to execute in the expected time frame (5)
>> and was terminated.

> The only time this error ever appears is if you have a timeout set on the
> task [1]. Check to ensure you don't have that config entry set
> 'ansible-config dump --only-changed' or haven't set it on the task play.
>
> [1]
> https://docs.ansible.com/ansible/latest/reference_appendices/config.html#task-timeout

No it's not that sadly. It times out before 5 seconds anyway.

Checking ansible-config dump --only-changed it says:

ANSIBLE_NOCOWS(/home/opc/vb-ansible-core/ansible.cfg) = True
CALLBACKS_ENABLED(/home/opc/vb-ansible-core/ansible.cfg) = ['ansible.posix.profile_tasks']
CONFIG_FILE() = /home/opc/vb-ansible-core/ansible.cfg
DEFAULT_BECOME(/home/opc/vb-ansible-core/ansible.cfg) = False
DEFAULT_FORKS(/home/opc/vb-ansible-core/ansible.cfg) = 100
DEFAULT_HOST_LIST(/home/opc/vb-ansible-core/ansible.cfg) = ['/home/opc/vb-ansible-core/inventories/auto_inventory.oci.yml', '/home/opc/vb-ansible-core/invent>
DEFAULT_LOG_PATH(/home/opc/vb-ansible-core/ansible.cfg) = /home/opc/vb-ansible-core/.logs/ansible.log
DEFAULT_ROLES_PATH(/home/opc/vb-ansible-core/ansible.cfg) = ['/home/opc/vb-ansible-core/roles_external', '/home/opc/vb-ansible-core/roles']
DEFAULT_TIMEOUT(/home/opc/vb-ansible-core/ansible.cfg) = 30
HOST_KEY_CHECKING(/home/opc/vb-ansible-core/ansible.cfg) = False
INTERPRETER_PYTHON(/home/opc/vb-ansible-core/ansible.cfg) = auto_silent
RETRY_FILES_ENABLED(/home/opc/vb-ansible-core/ansible.cfg) = True
RETRY_FILES_SAVE_PATH(/home/opc/vb-ansible-core/ansible.cfg) = /home/opc/.ansible-retry

Moreover explicitly setting task_timeout = 60 or 0 in ansible.cfg, results in the
same error.

[Divan Santana]

> I'm rather clueless with powershell. I'm now stuck at, how can I
> execute this powershell script block[2] in the same manner as ansible is
> doing it, to see why it's failing to install? Currently I take the
> scriptblock[2] as is and paste it in powershell which simply returns
> nothing to the screen.

OK, I think I run the powershell script like so via cmd:

powershell -NoProfile -NonInteractive -ExecutionPolicy Unrestricted Invoke-Command -ScriptBlock { param ( [String] $Arguments, [Int32[]] $ReturnCodes, [Object] $Module, [String] $Path, [String] $State, [String] $WorkingDirectory, [String] $RegistryPath, [Switch] $WaitChildren ) $invokeParams = @{ Module = $Module ReturnCodes = $ReturnCodes WorkingDirectory = $WorkingDirectory WaitChildren = $WaitChildren } if ($Path) { $invokeParams.CommandLine = ConvertTo-EscapedArgument -InputObject $Path } else { $registryProperties = Get-ItemProperty -LiteralPath $RegistryPath if ('QuietUninstallString' -in $registryProperties.PSObject.Properties.Name) { $command = $registryProperties.QuietUninstallString } elseif ('UninstallString' -in $registryProperties.PSObject.Properties.Name) { $command = $registryProperties.UninstallString } else { $module.FailJson("Failed to find registry uninstall string at registry path '$RegistryPath'") } # If the uninstall string starts with '%', we need to expand the env vars. if ($command.StartsWith('%') -or $command.StartsWith('"%')) { $command = [System.Environment]::ExpandEnvironmentVariables($command) } # If the command is not quoted and contains spaces we need to see if it needs to be manually quoted for the executable. if (-not $command.StartsWith('"') -and $command.Contains(' ')) { $rawArguments = [System.Collections.Generic.List[String]]@() $executable = New-Object -TypeName System.Text.StringBuilder foreach ($cmd in ($command | ConvertFrom-EscapedArgument)) { if ($rawArguments.Count -eq 0) { # Still haven't found the path, append the arg to the executable path and see if it exists. $null = $executable.Append($cmd) $exe = $executable.ToString() if (Test-Path -LiteralPath $exe -PathType Leaf) { $rawArguments.Add($exe) } else { $null = $executable.Append(" ") # The arg had a space and we need to preserve that. } } else { $rawArguments.Add($cmd) } } # If we still couldn't find a file just use the command literally and hope WIndows can handle it, # otherwise recombine the args which will also quote whatever is needed. if ($rawArguments.Count -gt 0) { $command = @($rawArguments | ConvertTo-EscapedArgument) -join ' ' } } $invokeParams.CommandLine = $command } if ($Arguments) { $invokeParams.CommandLine += " $Arguments" } Invoke-Executable @invokeParams }

That results in this error:

'ConvertFrom-EscapedArgument))' is not recognized as an internal or external command, operable program or batch file.

Anyone have a clue what's wrong?

My Powershell version is:

Name Value
---- -----
PSVersion 5.1.17763.5328
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.17763.5328
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1

.net version is:

Release in one case says =0x00080eb1=
InstallPath =C:\Windows\Microsoft.Net\Framework64\v4.0.30319=
Version =4.8.03761=

[Divan Santana]

> The above fails with:
>
> The win_package action failed to execute in the expected time frame (5) and was terminated.

OK, I was being stupid. There was a timeout: 5 at the top of my play.


win_package now hangs while trying to install. I've disabled UAC, but
still it just hangs.

[Divan Santana]

OK, the win_package install works fine too. Seems one needs to look at
the exe maker and figure out which switch to use for a silent install.