Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
cruscio opened this issue Sep 22, 2023 · 1 comment

Comments

@cruscio
Copy link
Contributor

cruscio commented Sep 22, 2023

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:

$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:

$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:

$web_response = $Request.GetResponse()

$response_stream = $web_response.GetResponseStream()

&$Script -Response $web_response -Stream $response_stream

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

.Net reference:

@jborean93
Copy link
Collaborator

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants