azcopy 10.27.0, 4000 PUT request return 500 operation timed out errors in an hour when uploading to a disk a vhd file of 8GB

[AkechiShiro]

Running into this issue however trying just azcopy to a disk in a resource group using the following script :

Logs :

• Start

2024/11/27 21:51:42 Number of CPUs: 16
2024/11/27 21:51:42 Max file buffer RAM 8.000 GB
2024/11/27 21:51:42 Max concurrent network operations: 256 (Based on number of CPUs. Set AZCOPY_CONCURRENCY_VALUE environment variable to override)
2024/11/27 21:51:42 Check CPU usage when dynamically tuning concurrency: true (Based on hard-coded default. Set AZCOPY_TUNE_TO_CPU environment variable to true or false override)
2024/11/27 21:51:42 Max concurrent transfer initiation routines: 64 (Based on hard-coded default. Set AZCOPY_CONCURRENT_FILES environment variable to override)
2024/11/27 21:51:42 Max enumeration routines: 16 (Based on hard-coded default. Set AZCOPY_CONCURRENT_SCAN environment variable to override)
2024/11/27 21:51:42 Parallelize getting file properties (file.Stat): false (Based on AZCOPY_PARALLEL_STAT_FILES environment variable)
2024/11/27 21:51:42 Max open files when downloading: 523618 (auto-computed)

I also see TLS Handshake timeouts with the following go stacktrace.

2024/11/27 21:55:46 18.9 %, 0 Done, 0 Failed, 1 Pending, 0 Skipped, 1 Total, 2-sec Throughput (Mb/s): 19.125
2024/11/27 21:55:46 INFO: [P#0-T#0] Page blob throughput tuner: Target Mbps 4024
2024/11/27 21:55:47 INFO: [P#0-T#0] Page blob throughput tuner: Target Mbps 4030
2024/11/27 21:55:48 ==> REQUEST/RESPONSE (Try=1/10.323541173s[SLOW >3s], OpTime=10.323548347s) -- REQUEST ERROR
   PUT https://redacted.blob.storage.azure.net/kf5rc2rpx2nw/abcd?comp=page&si=7f841dab-c3ad-4131-b81e-370471fbeb0e&sig=-REDACTED-&sr=b&sv=2018-03-28
   Accept: application/xml
   Content-Length: 4194304
   Content-Type: application/octet-stream
   User-Agent: AzCopy/10.27.0 azsdk-go-azblob/v1.4.0 (go1.23.3; linux)
   X-Ms-Client-Request-Id: e454471f-e968-4633-567f-4be749c95303
   x-ms-page-write: update
   x-ms-range: bytes=599785472-603979775
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   ERROR:
Put "https://redacted.blob.storage.azure.net/kf5rc2rpx2nw/abcd?comp=page&si=7f841dab-c3ad-4131-b81e-370471fbeb0e&sig=-REDACTED-&sr=b&sv=2018-03-28": net/http: TLS handshake timeout
goroutine 36 [running]:
github.com/Azure/azure-storage-azcopy/v10/ste.stack()
	github.com/Azure/azure-storage-azcopy/v10/ste/xferLogPolicy.go:100 +0x5e
github.com/Azure/azure-storage-azcopy/v10/ste.logPolicy.Do({{{0xb2d05e00, 0x0}, 0xc00098e090, 0xc00098e0a8}, 0xc000984270, 0xc0009842a0, 0xc0009842d0}, 0xc18602f2c0)
	github.com/Azure/azure-storage-azcopy/v10/ste/xferLogPolicy.go:232 +0xadd
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc18602f280)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-storage-azcopy/v10/ste.(*retryNotificationPolicy).Do(0x0?, 0xc18602f280)
	github.com/Azure/azure-storage-azcopy/v10/ste/xferRetryNotificationPolicy.go:64 +0x2a
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc0122c1178)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-sdk-for-go/sdk/azcore/runtime.(*retryPolicy).Do(0xc0122c14e0?, 0xc000876c80)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/runtime/policy_retry.go:147 +0x665
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876c40)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-storage-azcopy/v10/ste.(*fileUploadRangeFromURLFixPolicy).Do(0xc0005632d0?, 0xc000876c40)
	github.com/Azure/azure-storage-azcopy/v10/ste/sender-azureFileFromURL.go:118 +0x165
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876c00)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-storage-azcopy/v10/ste.(*versionPolicy).Do(0xc0005632b0?, 0xc000876c00)
	github.com/Azure/azure-storage-azcopy/v10/ste/xferVersionPolicy.go:49 +0x127
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876bc0)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-sdk-for-go/sdk/azcore/runtime.(*requestIDPolicy).Do(0xc000563270?, 0xc000876bc0)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/runtime/policy_request_id.go:33 +0x145
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876b80)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-sdk-for-go/sdk/azcore/runtime.telemetryPolicy.Do({{0xc00099a340?, 0x16b62c0?}}, 0xc000876b80)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/runtime/policy_telemetry.go:70 +0x1b4
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876b40)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-sdk-for-go/sdk/azcore/runtime.includeResponsePolicy(0xc000876b40)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/runtime/policy_include_response.go:19 +0x1c
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.PolicyFunc.Do(0xc000999f80?, 0x10?)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:214 +0x19
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.(*Request).Next(0xc000876b00)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/request.go:144 +0xf0
github.com/Azure/azure-sdk-for-go/sdk/azcore/internal/exported.Pipeline.Do({{0xc0009a0500?, 0x0?, 0x0?}}, 0xc0122c18b0?)
	github.com/Azure/azure-sdk-for-go/sdk/[email protected]/internal/exported/pipeline.go:76 +0x45
github.com/Azure/azure-sdk-for-go/sdk/storage/azblob/internal/generated.(*PageBlobClient).UploadPages(0xc00061e4b0, {0x1a85658?, 0xc0008648a0?}, 0x46dcfd?, {0x1a831a0?, 0xc000864870?}, 0x0?, 0x0?, 0x0?, 0x0, ...)
	github.com/Azure/azure-sdk-for-go/sdk/storage/[email protected]/internal/generated/zz_pageblob_client.go:956 +0xcb
github.com/Azure/azure-sdk-for-go/sdk/storage/azblob/pageblob.(*Client).UploadPages(0xc00061e510, {0x1a85658, 0xc0008648a0}, {0x1a831a0, 0xc000864870}, {0x7f52a697ba68?, 0x60?}, 0xc0122c1cb0)
	github.com/Azure/azure-sdk-for-go/sdk/storage/[email protected]/pageblob/client.go:182 +0x2d3
github.com/Azure/azure-storage-azcopy/v10/ste.(*pageBlobUploader).GenerateUploadFunc.func1()
	github.com/Azure/azure-storage-azcopy/v10/ste/sender-pageBlobFromLocal.go:116 +0x6b0
github.com/Azure/azure-storage-azcopy/v10/ste.(*pageBlobUploader).GenerateUploadFunc.createSendToRemoteChunkFunc.createChunkFunc.func2(0x5f5e100?)
	github.com/Azure/azure-storage-azcopy/v10/ste/sender.go:207 +0x294
github.com/Azure/azure-storage-azcopy/v10/ste.(*jobMgr).chunkProcessor(0xc000005508, 0xfb)
	github.com/Azure/azure-storage-azcopy/v10/ste/mgr-JobMgr.go:1064 +0xac
created by github.com/Azure/azure-storage-azcopy/v10/ste.(*jobMgr).poolSizer in goroutine 140
	github.com/Azure/azure-storage-azcopy/v10/ste/mgr-JobMgr.go:966 +0x23b

2024/11/27 21:32:53 ==> REQUEST/RESPONSE (Try=1/27.992µs, OpTime=2m5.501464239s) -- RESPONSE STATUS CODE ERROR
   PUT https://redacted.blob.storage.azure.net/cp1rcp4ml0sn/abcd?comp=page&si=5b8bdb85-19d3-49bb-9ec6-f9c6415fb1b7&sig=-REDACTED-&sr=b&sv=2018-03-28
   Accept: application/xml
   Content-Length: 4194304
   Content-Type: application/octet-stream
   User-Agent: AzCopy/10.27.0 azsdk-go-azblob/v1.4.0 (go1.23.3; linux)
   X-Ms-Client-Request-Id: dc2c7276-b907-4f8e-6d31-6b05c616ebc3
   x-ms-page-write: update
   x-ms-range: bytes=1669332992-1673527295
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   RESPONSE Status: 500 Operation could not be completed within the specified time.
   Content-Length: 246
   Content-Type: application/xml
   Date: Wed, 27 Nov 2024 21:32:51 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   X-Ms-Client-Request-Id: dc2c7276-b907-4f8e-6d31-6b05c616ebc3
   X-Ms-Error-Code: OperationTimedOut
   X-Ms-Request-Id: e0e741e8-901e-0066-1913-414740000000
   X-Ms-Version: 2023-08-03
Response Details: <?xml version="1.0" encoding="utf-8"?> <Error><Code>OperationTimedOut</Code><Message>Operation could not be completed within the specified time. </Message>

I believe I'm stuck here :

  azcopy copy "${img_file}" "${sasurl}" \
    --blob-type PageBlob

Full scripts used (has been confirmed to work in the past, upload a vhd image to a disk on Azure) :

#!/usr/bin/env bash
####################################################
AZ LOGIN CHECK
####################################################
Making  sure  that  one   is  logged  in  (to  avoid
surprises down the line).
if [ $(az account list | jq -r 'length') -eq 0 ]
then
echo
echo ''
echo '* Please log  in to  Azure by  typing "az  login", and '
echo ' repeat the "./upload-image.sh" command.              *'
echo ''
exit 1
fi
####################################################
HELPERS
####################################################
show_id() {
az $1 show 
--resource-group "${resource_group}" 
--name "${img_name}"        
--query "[id]"              
--output tsv
}
usage() {
echo ''
echo 'USAGE: (Every switch requires an argument)'
echo ''
echo '-g --resource-group REQUIRED Created if does  not exist. Will'
echo '                             house a new disk and the created'
echo '                             image.'
echo ''
echo '-n --image-name     REQUIRED The  name of  the image  created'
echo '                             (and also of the new disk).'
echo ''
echo '-l --location       Values from az account list-locations.'
echo '                    Default value: "westus2".'
}
####################################################
SWITCHES
####################################################
https://unix.stackexchange.com/a/204927/85131
while [ $# -gt 0 ]; do
case "$1" in
-l|--location)
location="$2"
;;
-g|--resource-group)
resource_group="$2"
;;
-n|--image-name)
img_name="$2"
;;
-h|--help)
usage
exit 1
;;
)
printf "\n"
printf " Error: Invalid argument \n"
printf "*\n"
usage
exit 1
esac
shift
shift
done
if [ -z "${img_name}" ] || [ -z "${resource_group}" ]
then
printf "\n"
printf " Error: Missing required argument \n"
printf "\n"
usage
exit 1
fi
####################################################
DEFAULTS
####################################################
location_d="${location:-"uksouth"}"
####################################################
PUT IMAGE INTO AZURE CLOUD
####################################################
https://vaneyckt.io/posts/safer_bash_scripts_with_set_euxo_pipefail/
set -euo pipefail
set -x
img_file="$(readlink -f ./result/disk.vhd)"
Make resource group exists
if ! az group show --resource-group "${resource_group}" &>/dev/null
then
az group create     
--name "${resource_group}" 
--location "${location_d}"
fi
note: the disk access token song/dance is tedious
but allows us to upload direct to a disk image
thereby avoid storage accounts (and naming them) entirely!
if ! az disk show -g "${resource_group}" -n "${img_name}" &>/dev/null; then
bytes="$(stat -c %s ${img_file})"
size="30"
az disk create 
--resource-group "${resource_group}" 
--name "${img_name}" 
--hyper-v-generation V2 
--upload-type Upload --upload-size-bytes "${bytes}"
timeout=$(( 60 * 60 )) # disk access token timeout
sasurl="$(
az disk grant-access 
--access-level Write 
--resource-group "${resource_group}" 
--name "${img_name}" 
--duration-in-seconds ${timeout} 
| jq -r '.accessSas'
)"
azcopy copy "${img_file}" "${sasurl}" 
--blob-type PageBlob
az disk revoke-access 
--resource-group "${resource_group}" 
--name "${img_name}"
fi
if ! az image show -g "${resource_group}" -n "${img_name}" &>/dev/null; then
diskid="$(az disk show -g "${resource_group}" -n "${img_name}" -o json | jq -r .id)"
az image create 
--resource-group "${resource_group}" 
--name "${img_name}" 
--source "${diskid}" 
--hyper-v-generation V2 
--os-type "linux" >/dev/null
fi
imageid="$(az image show -g "${resource_group}" -n "${img_name}" -o json | jq -r .id)"
echo "image creation completed:"
echo "image_id: ${imageid}"

The operation has failed, I've tried this about 3 times already.

Logs failure :

Diagnostic stats:
IOPS: 1
End-to-end ms per request: 115727
Network Errors: 3.81%
Server Busy: 0.00%


Job REDACTED summary
Elapsed Time (Minutes): 51.5539
Number of File Transfers: 1
Number of Folder Property Transfers: 0
Number of Symlink Transfers: 0
Total Number of Transfers: 1
Number of File Transfers Completed: 0
Number of Folder Transfers Completed: 0
Number of File Transfers Failed: 1
Number of Folder Transfers Failed: 0
Number of File Transfers Skipped: 0
Number of Folder Transfers Skipped: 0
Total Number of Bytes Transferred: 0
Final Job Status: Failed

2024/11/27 21:33:07 Closing Log

[souravgupta-msft]

Hi @AkechiShiro. Thanks for reaching out. The 500 OperationTimedOut is a server-side error. Can you please create a support ticket for this where the backend team can help investigate the issue.

[AkechiShiro]

I'm going to check if that's possible and we'll report should I give you any information on the support ticket here ? @souravgupta-msft

[souravgupta-msft]

You can share the AzCopy debug logs in the support ticket