Azure-storage-azcopy: AzCopy 10.1.2 TLS Handshake Timeout on VM with Low Memory

Created on 22 May 2019  路  31Comments  路  Source: Azure/azure-storage-azcopy

Which version of the AzCopy was used?

Note: The version is visible when running AzCopy without any argument

AzCopy 10.1.2

Which platform are you using? (ex: Windows, Mac, Linux)

Azure VM size DS1_v2: Windows Server 2019 Datacenter version 1809 build 17763.437

What command did you run?

Note: Please remove the SAS to avoid exposing your credentials. If you cannot remember the exact command, please retrieve it from the beginning of the log file.

.\azcopy.exe copy "*.json" "https://REDACTED.blob.core.windows.net/memory?st=2019-05-22T00%3A17%3A13Z&se=2019-05-23T00%3A17%3A13Z&sp=racwl&sv=2018-03-28&sr=c&sig=REDACTED" --overwrite=false --from-to=LocalBlob --blob-type=BlockBlob --put-md5;

What problem was encountered?

On an Azure size DS1_v2 VM running the latest stock Server 2019 image provided by Microsoft the command above does not run. Here's some relevant output from the logs:

2019/05/22 01:08:23 ==> REQUEST/RESPONSE (Try=1/3m59.8699959s[SLOW >3s], OpTime=3m59.8699959s) -- REQUEST ERROR
   PUT https://REDACTED.blob.core.windows.net/memory/memdumptest-20190522-003248.json?se=2019-05-23t00%3A17%3A13z&sig=REDACTED&sp=racwl&sr=c&st=2019-05-22t00%3A17%3A13z&sv=2018-03-28&timeout=901
   Content-Length: [1504]
   User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
   X-Ms-Blob-Cache-Control: []
   X-Ms-Blob-Content-Disposition: []
   X-Ms-Blob-Content-Encoding: []
   X-Ms-Blob-Content-Language: []
   X-Ms-Blob-Content-Md5: []
   X-Ms-Blob-Content-Type: [application/json]
   X-Ms-Blob-Type: [BlockBlob]
   X-Ms-Client-Request-Id: [01297009-16c5-46af-5bdb-fcecc71b69f0]
   X-Ms-Version: [2018-03-28]
   --------------------------------------------------------------------------------
   ERROR:
-> github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.NewError, /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/error.go:154
HTTP request failed

Put https://REDACTED.blob.core.windows.net/memory/memdumptest-20190522-003248.json?se=2019-05-23T00%3A17%3A13Z&sig=REDACTED%3D&sp=racwl&sr=c&st=2019-05-22T00%3A17%3A13Z&sv=2018-03-28&timeout=901: net/http: TLS handshake timeout

How can we reproduce the problem in the simplest way?

Deploy an Azure DS1_v2 VM and run the command on it. It'll fail. I've reproduced this on two DS1_v2 VMs.

Have you found a mitigation/solution?

If I run this same command on a VM with 8GB memory llike the B2ms AzCopy executes successfully. It looks like running the latest version of AzCopy on a system with low memory causes TLS handshakes to fail. It's possible that other operations are failing on a system with low memory, too, I just can't get past the handshake failures to see what else may be broken.

It looks like AzCopy has undocumented minimum system hardware requirements.

picture AtomicGaryBusey
👍1

Most helpful comment

Thanks for letting us know @koder101. It's on our list to be looked at, but we don't have a public ETA yet. By the way, the related issue, where after this failure it mistakenly saves your SAS token into the log file, is being treated at a higher priority than this issue - because the SAS one relates to security. In the meantime, don't send us (or anyone) your AzCopy log files after TLS failure.

picture JohnRusk on 7 Jun 2019
👍2

All 31 comments

I am also facing the same issue. I just resized the same machine with 14GB of RAM and the login worked.

koder101 picture koder101 on 7 Jun 2019
👍1

Thanks for letting us know @koder101. It's on our list to be looked at, but we don't have a public ETA yet. By the way, the related issue, where after this failure it mistakenly saves your SAS token into the log file, is being treated at a higher priority than this issue - because the SAS one relates to security. In the meantime, don't send us (or anyone) your AzCopy log files after TLS failure.

JohnRusk picture JohnRusk on 7 Jun 2019
👍2

@AtomicGaryBusey I've spent a few hours trying to reproduce this, and I have not been able to. I've tried a couple of different test payloads, one with about 10 files each with sizes in the 100's of MB range; and another with 4000 very small files. The only difference I can see is that I'm using the _new_ latest Windows Server 2019 image, which is version 17763.557. But I'd be surprised if that small version change accounted for the difference.

In all my tests, the job ran fine. Total RAM usage was never about 3 GB (the VM has 3.5) and was often much lower (e.g. 1.7 GB).

One question, how long after the start of your AzCopy job did you see the error? Almost immediately, or after a few minutes?

Oh, and has it happened again since you first logged this with us?

JohnRusk picture JohnRusk on 17 Jun 2019

I am getting same error from my Application server which is on Win 2012 R2 but works fine locally with same SAS token . The error is : --------------------------------------------------------------------------------
ERROR:
-> github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.NewError, /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/error.go:154
HTTP request failed. If interested to know more we can do a working session on same.

jiteshkumargouthamchand picture jiteshkumargouthamchand on 26 Jun 2019

@jiteshkumargouthamchand What size is the VM you are using?

JohnRusk picture JohnRusk on 26 Jun 2019

16 GB

jiteshkumargouthamchand picture jiteshkumargouthamchand on 26 Jun 2019

How long after the start of your AzCopy job did you see the error? Almost immediately, or after a few minutes? If the latter, do you see and throughput before the error?

JohnRusk picture JohnRusk on 26 Jun 2019

@JohnRusk I'm having a similar issue. When I run my script manually is runs as expected, but when scheduled to run with crontab I receive the same error.

Isaiah-FLS picture Isaiah-FLS on 26 Jun 2019

@Isaiah-FLS The crontab issue is being tracked here: #408

JohnRusk picture JohnRusk on 26 Jun 2019

Immediately .
2019/06/26 20:17:09 AzcopyVersion 10.1.2
2019/06/26 20:17:09 OS-Environment windows
2019/06/26 20:17:09 OS-Architecture amd64
2019/06/26 20:17:09 Job-Command copy D:\Temp\AzCopy\v10.1.2\azcopy_windows_amd64_10.1.2\azcopy_windows_amd64_10.1.2\ThirdPartyNotice.txt https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp? --log-level=DEBUG --recursive=true
2019/06/26 20:17:09 Number of CPUs: 4
2019/06/26 20:17:09 Max file buffer RAM 2.000 GB
2019/06/26 20:17:09 Max open files when downloading: 2147483114
2019/06/26 20:17:09 Max concurrent transfer initiation routines: 64
2019/06/26 20:17:09 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 0, T: 0
2019/06/26 20:17:09 JobID=68b0979e-a28e-3144-6cf4-20ef55b09cac, credential type: Anonymous
2019/06/26 20:17:09 scheduling JobID=68b0979e-a28e-3144-6cf4-20ef55b09cac, Part#=0, Transfer#=0, priority=0
2019/06/26 20:17:09 INFO: [P#0-T#0] has worker 55 which is processing TRANSFER
2019/06/26 20:17:09 INFO: [P#0-T#0] Starting transfer: Source "d:///Temp/AzCopy/v10.1.2/azcopy_windows_amd64_10.1.2/azcopy_windows_amd64_10.1.2/ThirdPartyNotice.txt" Destination "https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?". Specified chunk size 8388608
2019/06/26 20:17:09 ==> OUTGOING REQUEST (Try=1)
PUT https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?timeout=901
Content-Length: [15910]
User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
X-Ms-Blob-Cache-Control: []
X-Ms-Blob-Content-Disposition: []
X-Ms-Blob-Content-Encoding: []
X-Ms-Blob-Content-Language: []
X-Ms-Blob-Content-Md5: []
X-Ms-Blob-Content-Type: [text/plain; charset=utf-8]
X-Ms-Blob-Type: [BlockBlob]
X-Ms-Client-Request-Id: [6247817d-45d6-4e3a-4ce8-253270cdf930]
X-Ms-Version: [2018-03-28]

2019/06/26 20:17:11 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:13 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:15 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:17 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:19 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:21 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:23 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:25 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:27 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:29 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:30 ==> REQUEST/RESPONSE (Try=1/21.0272036s[SLOW >3s], OpTime=21.0272036s) -- REQUEST ERROR
PUT https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?timeout=901
Content-Length: [15910]
User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
X-Ms-Blob-Cache-Control: []
X-Ms-Blob-Content-Disposition: []
X-Ms-Blob-Content-Encoding: []
X-Ms-Blob-Content-Language: []
X-Ms-Blob-Content-Md5: []
X-Ms-Blob-Content-Type: [text/plain; charset=utf-8]
X-Ms-Blob-Type: [BlockBlob]
X-Ms-Client-Request-Id: [6247817d-45d6-4e3a-4ce8-253270cdf930]
X-Ms-Version: [2018-03-28]

ERROR:
-> github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.NewError, /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/error.go:154
HTTP request failed

Put https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?&timeout=901: dial tcp 52.176.224.96:443: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.

goroutine 16 [running]:
github.com/Azure/azure-storage-azcopy/ste.stack(0xc042294070, 0xc0422deb00, 0x0)
/go/src/github.com/Azure/azure-storage-azcopy/ste/xferLogPolicy.go:135 +0xae
github.com/Azure/azure-storage-azcopy/ste.NewRequestLogPolicyFactory.func1.1(0xc9d620, 0xc04302e4e0, 0xc04302a300, 0xbfcb6f, 0xc, 0xbfaeb3, 0xa)
/go/src/github.com/Azure/azure-storage-azcopy/ste/xferLogPolicy.go:102 +0x66c
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc04302c2d0, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0xa, 0xc04303e120, 0x90, 0x90)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/ste.NewVersionPolicyFactory.func1.1(0xc9d620, 0xc04302e4e0, 0xc04302a300, 0x10dd3e0, 0x0, 0x370000, 0x0)
/go/src/github.com/Azure/azure-storage-azcopy/ste/mgr-JobPartMgr.go:68 +0xef
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc0420f5ee0, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0xc04306af00, 0x10, 0xc043086e01, 0xc04306aeb0)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do(0xc96820, 0xc0420f5ee0, 0xc0422e15e0, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0x10, 0x10, 0xb2fde0, 0x10dd3e0)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zz_generated_responder_policy.go:34 +0x5a
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.anonymousCredentialPolicy.Do(0xc96860, 0xc0420f5f00, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0xd192ea4e01, 0xc04306af20, 0xc04306afe0, 0x4e1eda)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zc_credential_anonymous.go:54 +0x56
github.com/Azure/azure-storage-azcopy/ste.(retryNotificationPolicy).Do(0xc04309f8a0, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0x0, 0x0, 0x0, 0xc04306b030)
/go/src/github.com/Azure/azure-storage-azcopy/ste/xferRetryNotificationPolicy.go:59 +0x65
github.com/Azure/azure-storage-azcopy/ste.(retryNotificationPolicy).Do-fm(0xc9d620, 0xc04302e4e0, 0xc04302a300, 0x10dc4e0, 0xc9d620, 0xc04302e4e0, 0xc04309fa40)
/go/src/github.com/Azure/azure-storage-azcopy/ste/xferRetryNotificationPolicy.go:77 +0x4f
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc04309f8b0, 0xc9d620, 0xc04302e4e0, 0xc04302a300, 0xc04302e4e0, 0xc04309fa40, 0x1, 0x0)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/ste.NewBlobXferRetryPolicyFactory.func1.1(0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0xc042cf, 0x16, 0xc0424fe5a0, 0x24)
/go/src/github.com/Azure/azure-storage-azcopy/ste/xferRetrypolicy.go:365 +0x71d
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc04302c320, 0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0x24, 0x60e8c7, 0xb5fbc0, 0xc043086d80)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.NewUniqueRequestIDPolicyFactory.func1.1(0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0xbfb237, 0xa, 0xc043032380, 0x36)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zc_policy_unique_request_id.go:19 +0xa3
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc0420f5f20, 0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0x36, 0xc042ff2520, 0xc043086de0, 0xc04306b400)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.NewTelemetryPolicyFactory.func1.1(0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0x1, 0x0, 0x1, 0xc042ff2520)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zc_policy_telemetry.go:34 +0xa5
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc043086de0, 0xc9d5a0, 0xc042ff0200, 0xc04302a200, 0xc043086de0, 0x0, 0xc04306b470, 0x410eff)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:42 +0x4b
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.(pipeline).Do(0xc042ff01c0, 0xc9d5a0, 0xc042ff0200, 0xc96880, 0xc0422e15e0, 0xc04302a200, 0x2a, 0xc0421c6442, 0xd, 0x0)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/core.go:128 +0x88
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.Upload(0xc0421c6410, 0x5, 0x0, 0x0, 0x0, 0xc0421c6418, 0x2a, 0xc0421c6442, 0xd, 0x0, ...)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zz_generated_block_blob.go:421 +0x560
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.Upload(0xc0421c6410, 0x5, 0x0, 0x0, 0x0, 0xc0421c6418, 0x2a, 0xc0421c6442, 0xd, 0x0, ...)
/go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/url_block_blob.go:64 +0x252
github.com/Azure/azure-storage-azcopy/ste.(blockBlobUploader).generatePutWholeBlob.func1()
/go/src/github.com/Azure/azure-storage-azcopy/ste/sender-blockBlobFromLocal.go:108 +0x530
github.com/Azure/azure-storage-azcopy/ste.createChunkFunc.func1(0x8)
/go/src/github.com/Azure/azure-storage-azcopy/ste/sender.go:148 +0x137
github.com/Azure/azure-storage-azcopy/ste.(*jobsAdmin).chunkProcessor(0xc04210e1e0, 0x8)
/go/src/github.com/Azure/azure-storage-azcopy/ste/JobsAdmin.go:230 +0x97
created by github.com/Azure/azure-storage-azcopy/ste.initJobsAdmin
/go/src/github.com/Azure/azure-storage-azcopy/ste/JobsAdmin.go:181 +0x6d6

2019/06/26 20:17:31 ==> OUTGOING REQUEST (Try=2)
PUT https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?timeout=901
Content-Length: [15910]
User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
X-Ms-Blob-Cache-Control: []
X-Ms-Blob-Content-Disposition: []
X-Ms-Blob-Content-Encoding: []
X-Ms-Blob-Content-Language: []
X-Ms-Blob-Content-Md5: []
X-Ms-Blob-Content-Type: [text/plain; charset=utf-8]
X-Ms-Blob-Type: [BlockBlob]
X-Ms-Client-Request-Id: [6247817d-45d6-4e3a-4ce8-253270cdf930]
X-Ms-Version: [2018-03-28]

2019/06/26 20:17:31 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:33 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:35 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:37 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:39 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:41 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:43 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:45 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:47 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:49 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:51 PERF: primary performance constraint is Unknown. States: R: 0, D: 0, W: 0, F: 0, B: 1, T: 1
2019/06/26 20:17:52 ==> REQUEST/RESPONSE (Try=2/21.0822068s[SLOW >3s], OpTime=42.9694608s) -- REQUEST ERROR
PUT https://stausc1r6400t10dscdf.blob.core.windows.net/poslink/temp?timeout=901
Content-Length: [15910]
User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
X-Ms-Blob-Cache-Control: []
X-Ms-Blob-Content-Disposition: []
X-Ms-Blob-Content-Encoding: []
X-Ms-Blob-Content-Language: []
X-Ms-Blob-Content-Md5: []
X-Ms-Blob-Content-Type: [text/plain; charset=utf-8]
X-Ms-Blob-Type: [BlockBlob]
X-Ms-Client-Request-Id: [6247817d-45d6-4e3a-4ce8-253270cdf930]
X-Ms-Version: [2018-03-28]

ERROR:
-> github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline.NewError, /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-pipeline-go/pipeline/error.go:154
HTTP request failed

jiteshkumargouthamchand picture jiteshkumargouthamchand on 26 Jun 2019

@jiteshkumargouthamchand That pattern of log events shows that it cannot find the destination i.e. when it looks for stausc1r6400t10dscdf.blob.core.windows.net it cannot connect. The most likely reasons are that either
(a) there is a typo in the name of the storage account, or
(b) there is some kind of firewall blocking you - either on or near the machine where you are running AzCopy, or else a Storage firewall on the Storage account itself.

JohnRusk picture JohnRusk on 27 Jun 2019

Same script works fine from my local machine. So it is firewall then but pls. note that v6.1 works fine from same server. I also added AzCopy.exe.config where the v10 exe folder is:




jiteshkumargouthamchand picture jiteshkumargouthamchand on 27 Jun 2019

defaultProxy enabled="true" useDefaultCredentials="true"

jiteshkumargouthamchand picture jiteshkumargouthamchand on 27 Jun 2019

Ah, your server sits behind a proxy? Is it an authenticating proxy? AzCopy v10 doesn't have good support for _authenticating_ proxies yet (but it's high on our list of things to sort out).

If the proxy does _not_ require authentication, you can set up AzCopy v10 to use it right now using the steps here: https://docs.microsoft.com/en-us/azure/storage/common/storage-use-azcopy-configure?toc=%2fazure%2fstorage%2fblobs%2ftoc.json#configure-proxy-settings . Also, in the next release (coming soon) it will automaticaly detect proxy settings on Windows.

(Creating an exe.config won't work in v10).

JohnRusk picture JohnRusk on 27 Jun 2019

I do not have access to the link. Whats the ETA for next release ?

jiteshkumargouthamchand picture jiteshkumargouthamchand on 27 Jun 2019

Sorry, I posted the wrong link. I have edited my previous post and corrected it. ETA for next release is within the next week.

JohnRusk picture JohnRusk on 27 Jun 2019

I can confirm this issue still happens. I just reproduced it on an 8GB VM. Also, when executed via an Azure Custom Script Extension it dumps the errors to the Windows Application Event log as Event ID 0, which has other implications I'll post in the redaction problem thread.

AtomicGaryBusey picture AtomicGaryBusey on 27 Jun 2019

I believe this issue is resolved with the latest version, 10.2.1
Please download here and try: https://docs.microsoft.com/en-us/azure/storage/common/storage-use-azcopy-v10

ZNPapa picture ZNPapa on 18 Jul 2019
👍1

BTW, there's a lot mentioned in this issue thread. 10.2.1 solves the redaction issues and it auto-detects proxy servers on Windows. We did not specifically do anything about TLS handshake timeouts - although any cases where they were caused by inability to find the proxy (on Windows) should now be fixed.

Thanks for updating this thread with mention of the latest version @ZNPapa

JohnRusk picture JohnRusk on 18 Jul 2019

@AtomicGaryBusey

I can confirm this issue still happens. I just reproduced it on an 8GB VM.

Is that the TLS handshake timeout that you're referring to?

JohnRusk picture JohnRusk on 30 Jul 2019

hello, Im also having the same issue in local V, but it is behind a firewall, in order to unblock this address, do you know wich port is ussing when it tries to do the handshake?? THANK YOU

ERROR:
-> github.com/Azure/azure-pipeline-go/pipeline.NewError, /home/vsts/go/pkg/mod/github.com/!azure/[email protected]/pipeline/error.go:154
HTTP request failed

danramracing picture danramracing on 2 Oct 2019

Assuming you are using HTTPS URLs as source/destination (depending on whether download/upload) then everything will be on the standard HTTPS port, which is 443

JohnRusk picture JohnRusk on 2 Oct 2019

I'm closing this thread now, since all-but-one of the various issues it covers have been resolved some time ago, and the other one - possible impact of low memory - should be addressed by today's release of version 10.3, which allows the use of an environment variable called AZCOPY_BUFFER_GB to limit AzCopy's memory usage. (E.g. set it to 0.75 to use 0.75 GB for AzCopy's internal buffering). If you are running on a low memory machine, you can set that variable, so that AzCopy doesn't eat up too much.

JohnRusk picture JohnRusk on 11 Oct 2019

@abhi-msft Oops, I accidentally deleted your comment here, instead of my obsolete comment on the other thread. Can you repost yours here please?

JohnRusk picture JohnRusk on 15 Jun 2020

Ah ok :)
I am using v10.4.3 and I think I am hitting the same issue. In brief, I am trying to copy several files with in a PowerShell session from local to Azure. It works for all the files except for a .dmp file which is <15GB. I tried zipping it as well but seems failing all the time with below error.

2020/06/15 01:26:56 AzcopyVersion 10.4.3
2020/06/15 01:26:56 OS-Environment windows
2020/06/15 01:26:56 OS-Architecture amd64
2020/06/15 01:26:56 Log times are in UTC. Local time is 14 Jun 2020 18:26:56
2020/06/15 01:26:56 Job-Command copy G:\06-14-2020\06-19\MEMORY_DMP.Zip https://blahblahblah.dfs.core.windows.net/automation/06-14-2020/blahblahblah/06-19/MEMORY_DMP.Zip
2020/06/15 01:26:56 Number of CPUs: 12
2020/06/15 01:26:56 Max file buffer RAM 6.000 GB
2020/06/15 01:26:56 Max concurrent network operations: 192 (Based on number of CPUs. Set AZCOPY_CONCURRENCY_VALUE environment variable to override)
2020/06/15 01:26:56 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)
2020/06/15 01:26:56 Max concurrent transfer initiation routines: 64 (Based on hard-coded default. Set AZCOPY_CONCURRENT_FILES environment variable to override)
2020/06/15 01:26:56 Max enumeration routines: 64 (Based on hard-coded default. Set AZCOPY_CONCURRENT_SCAN environment variable to override)
2020/06/15 01:26:56 Max open files when downloading: 2147482995 (auto-computed)

2020/06/15 01:26:56 Authenticating to destination using Azure AD

2020/06/15 01:27:32 ==> REQUEST/RESPONSE (Try=1/20.9416ms, OpTime=32.832603s) -- REQUEST ERROR
PUT https://blahblahblah.dfs.core.windows.net/automation/06-14-2020/blahblahblah/06-19/MEMORY_DMP.Zip?action=append&position=343932928&timeout=901
Authorization: REDACTED
Content-Length: [8388608]
User-Agent: [AzCopy/10.4.3 Azure-Storage/0.1 (go1.13; Windows_NT)]
X-Http-Method-Override: [PATCH]
X-Ms-Client-Request-Id: [9cedaccb-da4e-449d-68bc-82d57af4680f]
X-Ms-Version: [2018-11-09]

ERROR:
-> github.com/Azure/azure-pipeline-go/pipeline.NewError, /home/vsts/go/pkg/mod/github.com/!azure/[email protected]/pipeline/error.go:154
HTTP request failed

Put https://blahblahblah.dfs.core.windows.net/automation/06-14-2020/blahblahblah/06-19/MEMORY_DMP.Zip?action=append&position=343932928&timeout=901: write tcp IPblahblahblah:443: wsasend: An existing connection was forcibly closed by the remote host.

abhi-msft picture abhi-msft on 15 Jun 2020
👍1

That error is fine, as long as it doesn't repeatedly happen. (AzCopy automatically retries after such failures). Can you search for the point in the log where it says UPLOADFAILED and see what the error is there?

JohnRusk picture JohnRusk on 15 Jun 2020

I never saw it complete. Few times I saw it running for couple of hours and I had to stop forcefully. I kicked a process 30 min back and it's retrying now. Do you want me to wait for it to complete this time? If possible may I know the retry count or time to exit?

abhi-msft picture abhi-msft on 15 Jun 2020

The retry count is 20. I.e. 20th failure - for any one specific block of the file - will trigger failure.
I see it's using quite a high connection count (192 connections). Generally the best thing to try in such cases - when there's a high connection count chosen by default, but you are seeing connection-related errors - is to set the environment variable AZCOPY_CONCURRENCY_VALUE to "AUTO" from your command prompt window, before you launch AzCopy. That often solves problems like this.

JohnRusk picture JohnRusk on 15 Jun 2020

Sure, I can try that. BTW, I am seeing the below error too. Not sure if this helps.
RESPONSE Status: 500 Operation could not be completed within the specified time.
Content-Length: [193]
Content-Type: [application/json;charset=utf-8]
Date: [Mon, 15 Jun 2020 02:09:52 GMT]
Server: [Windows-Azure-HDFS/1.0 Microsoft-HTTPAPI/2.0]
X-Ms-Error-Code: [OperationTimedOut]
X-Ms-Request-Id: [d294fccc-001f-0070-39b9-42c82a000000]
X-Ms-Version: [2018-11-09]
Response Details: {"error":{"code":"OperationTimedOut","message":"Operation could not be completed within the specified time.\nRequestId:d294fccc-001f-0070-39b9-42c82a000000\nTime:2020-06-15T02:09:53.4407531Z"}}

abhi-msft picture abhi-msft on 15 Jun 2020

I think try the AUTO thing, and then let that run to completion, and then let us know what happens.

JohnRusk picture JohnRusk on 15 Jun 2020
👍1

That worked. Thank you John :)

abhi-msft picture abhi-msft on 15 Jun 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

ayeltsov picture ayeltsov  路  3Comments
alvipeo picture alvipeo  路  4Comments
wahalulu picture wahalulu  路  3Comments
DavidLafond picture DavidLafond  路  5Comments
LoofahBu picture LoofahBu  路  3Comments