win_get_url large download - Exception calling "CopyTo" with "1" argument(s): "The operation has timed out."

[cruscio]

SUMMARY

When downloading a large file, win_get_url sometimes fails with a Stream.CopyTo timeout.

"msg": "Error downloading 'https://[.. URL ..]' to 'C:/[.. file path ..].zip': Exception calling \"CopyTo\" with \"1\" argument(s): \"The operation has timed out.\"",

ISSUE TYPE

• Bug Report

COMPONENT NAME

win_get_url

ANSIBLE VERSION

ansible [core 2.15.2]
  config file = [***]ansible/ansible.cfg
  configured module search path = ['/home/[***]/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /home/[***]/.local/pipx/venvs/ansible/lib/python3.11/site-packages/ansible
  ansible collection location = /home/[***]/.ansible/collections:/usr/share/ansible/collections
  executable location = /home/[***]/.local/bin/ansible
  python version = 3.11.2 (main, Mar 13 2023, 12:18:29) [GCC 12.2.0] (/home/[***]/.local/pipx/venvs/ansible/bin/python)
  jinja version = 3.1.2
  libyaml = True

COLLECTION VERSION

# /home/[***]/.local/pipx/venvs/ansible/lib/python3.11/site-packages/ansible_collections
Collection      Version
--------------- -------
ansible.windows 1.14.0 

CONFIGURATION

CALLBACKS_ENABLED(/home/[***]/ansible/ansible.cfg) = ['profile_tasks']
CONFIG_FILE() = /home/[***]/ansible/ansible.cfg
DEFAULT_BECOME_METHOD(/home/[***]/ansible/ansible.cfg) = runas
DEFAULT_HOST_LIST(/home/[***]/ansible/ansible.cfg) = ['/home/[***]/ansible/i>
DEFAULT_LOG_PATH(/home/[***]/ansible/ansible.cfg) = /home/[***]/ansible/log
DEFAULT_LOOKUP_PLUGIN_PATH(/home/[***]/ansible/ansible.cfg) = ['/usr/share/ansible/plugins/lookup']
DEFAULT_VAULT_PASSWORD_FILE(env: ANSIBLE_VAULT_PASSWORD_FILE) = /home/[***]/.ansible_vault_[...]
EDITOR(env: EDITOR) = nano
PAGER(env: PAGER) = less

OS / ENVIRONMENT

Windows Server 2019 hosted in Azure
Standard B2s (2 vcpus, 4 GiB memory)
Disk: Standard HDD LRS, SIze: 127GB, Max IOPS 500, Max Throughput 60

STEPS TO REPRODUCE

# Note: Variable names have been changed to redact business specific labels.
# File being downloaded is a 5GB zip archive hosted as an Azure Storage blob.
# Both the Storage Account and the target host are in the same location: Central US (all local network traffic)

- name: Download Zip to {{ file_path }}
  ansible.windows.win_get_url:
    url: '{{ url }}'
    headers: '{{ headers }}'
    dest: '{{ dest }}'
    checksum: '{{ sha }}'
    checksum_algorithm: sha256
  register: win_get_url_task_register
  no_log: true #Don't log the URL in case it has a key in the parameters/header
  ignore_errors: true
  async: '{{ 30 * 60 | int }}' # 30 minutes
  poll: 60

- name: Log output and fail the play when the download failed
  ansible.builtin.debug:
    var: win_get_url_task_register
  when: win_get_url_task_register.failed
  failed_when: win_get_url_task_register.failed

EXPECTED RESULTS

Download completes without timeout.
It should not timeout in the middle of reading the response.

.Net Stream objects have ReadTimeout and CanTimeout properties that may be relevant here. (see links below)

With the above configuration, I would expect a timeout under two conditions:

1. At 30 minutes when the async limit is reached
2. At 30 seconds if the request was pending for the default url_timeout value
   Neither of these happened here.

ACTUAL RESULTS

Download fails with a timeout in the middle of reading the response. This happens long after the 30s url_timeout on the request, and well before the task's async timeout.

# Note: Output has been changed to redact business specific labels.

TASK [my_role : Download Zip to C:/[.. file path ..].zip] **********************
Friday 22 September 2023  16:59:11 +0000 (0:00:02.178)       0:00:34.026 ****** 
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC POLL on [.. FQDN ..]: jid=j906110358023.492 started=1 finished=0
ASYNC FAILED on [.. FQDN ..]: jid=None
fatal: [[.. FQDN ..]]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}
...ignoring

TASK [my_role : Log output and fail the play when the download failed] *********
Friday 22 September 2023  17:06:22 +0000 (0:07:10.695)       0:07:44.721 ****** 
fatal: [[.. FQDN ..]]: FAILED! => {
    "win_get_url_task_register": {
        "ansible_async_watchdog_pid": 1264,
        "ansible_job_id": "j906110358023.492",
        "changed": false,
        "dest": "C:/[.. file path ..].zip",
        "elapsed": 388.9810754,
        "failed": true,
        "finished": 1,
        "msg": "Error downloading 'https://[.. URL ..]' to 'C:/[.. file path ..].zip': Exception calling \"CopyTo\" with \"1\" argument(s): \"The operation has timed out.\"",
        "results_file": "C:\\Users\\ansible_user\\.ansible_async\\j906110358023.492",
        "started": 1,
        "status_code": 200,
        "stderr": "",
        "stderr_lines": [],
        "stdout": "",
        "stdout_lines": [],
        "url": "https://[.. URL ..]"
    },
    "failed_when_result": true
}

Additional Information

Error downloading 'https://[...]' to 'C:/[...].zip': Exception calling "CopyTo" with "1" argument(s): "The operation has timed out."

Error message came from an exception being logged here:

ansible.windows/plugins/modules/win_get_url.ps1

Line 213 in 052ef99

$Module.FailJson("Error downloading '$Uri' to '$Dest': $($_.Exception.Message)", $_)

The exception is raised by a CopyTo() in a $download_script that's defined in win_get_url's Invoke-DownloadFile and executed by WebRequest.psm1's Invoke-AnsibleWindowsWebRequest:

ansible.windows/plugins/modules/win_get_url.ps1

Lines 167 to 174 in 052ef99

	$download_script = {
	param($Response, $Stream)
	# Download the file to a temporary directory so we can compare it
	$tmp_dest = Join-Path -Path $Module.Tmpdir -ChildPath ([System.IO.Path]::GetRandomFileName())
	$fs = [System.IO.File]::Create($tmp_dest)
	try {
	$Stream.CopyTo($fs)

The CopyTo() is called on a Stream that's created from a WebResponse, and passed to the $download_script here:

ansible.windows/plugins/module_utils/WebRequest.psm1

Line 440 in 052ef99

$web_response = $Request.GetResponse()

ansible.windows/plugins/module_utils/WebRequest.psm1

Line 471 in 052ef99

$response_stream = $web_response.GetResponseStream()

ansible.windows/plugins/module_utils/WebRequest.psm1

Line 474 in 052ef99

&$Script -Response $web_response -Stream $response_stream

Stream objects have ReadTimeout and CanTimeout properties that may be relevant here.

.Net reference:

• WebRequest.GetResponse Method (System.Net) | Microsoft Learn
• WebResponse Class (System.Net) | Microsoft Learn
• WebResponse.GetResponseStream Method (System.Net) | Microsoft Learn
• Stream Class (System.IO) | Microsoft Learn
• Stream.CanTimeout Property (System.IO) | Microsoft Learn
• Stream.ReadTimeout Property (System.IO) | Microsoft Learn
• Stream.CopyTo Method (System.IO) | Microsoft Learn

[jborean93]

Thanks for the detailed issue, I'll be having a look at this closer sometime in the next 2 weeks sorry.