MacOS Azure Storage Explorer using azcopy indicates 100% then continues trying failed PUT’s and never completes the copy

Written by James McDonald

September 19, 2019

Slow Australian NBN can’t handle the expectation azcopy has about your bandwidth

I have been trying to copy a 1.7GB file to Azure blob storage container and it’s been failing. I’ve changed from Azure account login to a SAS URL and have started to investigate what is going on.

The upload to Azure kept failing because of azcopy trying to send too many things down the pipe at once.

Resolution

This is taken from Storage Explorers option to copy the azcopy command line and then edited to taste

export AZCOPY_CONCURRENCY_VALUE=2
export AZCOPY_CRED_TYPE=Anonymous;
azcopy copy "/Users/jmcd/Downloads/ub3a.zip" "https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?sv=2018-03-28&amp;ss=b&amp;srt=sco&amp;sp=rwdlac&amp;se=2019-09-19T09%3A53%3A50Z&amp;st=2019-09-19T01%3A53%3A50Z&amp;spr=https&amp;sig=<REDACTED>" --overwrite=false --follow-symlinks --recursive --from-to=LocalBlob --blob-type=BlockBlob --put-md5;
unset AZCOPY_CRED_TYPE;

The answer is to change the AZCOPY_CONCURRENCY_VALUE I ended up using 4 and it was fine

What the azcopy job log said

The things I noticed in the log “HTTP request failed”, “context deadline exceeded” once you see debug output that mentions user directories it’s all down hill from the. Notice the (Try=8) I think that means azcopy has tried 8x to upload that block which makes sence since I was seeing masses more data being uploaded than was in the file. I saw “Try” up to Try=20 in the log so you can imagine how much extra, but wasted data that entailed.

PUT https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=mtu0zdc3mdutnzq1mc1kmjqxltq0zmmtmmjjogixztvlzdbk&amp;comp=block&amp;se=2019-09-21t14%3A07%3A32z&amp;sig=-REDACTED-&amp;sp=rwl&amp;sr=c&amp;sv=2018-03-28&amp;timeout=901
   Content-Length: [8388608]
   User-Agent: [AzCopy/10.2.1 Azure-Storage/0.7 (go1.12; darwin)]
   X-Ms-Client-Request-Id: [df195ca0-1246-49ec-7209-2607f70460e7]
   X-Ms-Version: [2018-03-28]

2019/09/18 15:41:21 ==> REQUEST/RESPONSE (Try=8/15m0.000575342s[SLOW >3s], OpTime=1h33m48.55610076s) -- REQUEST ERROR
   PUT https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=ywjmyzqxzditzdq4yi1mzdqxlty4mtitmtu2mmewyjexzwri&amp;comp=block&amp;se=2019-09-21t14%3A07%3A32z&amp;sig=-REDACTED-&amp;sp=rwl&amp;sr=c&amp;sv=2018-03-28&amp;timeout=901
   Content-Length: [8388608]
   User-Agent: [AzCopy/10.2.1 Azure-Storage/0.7 (go1.12; darwin)]
   X-Ms-Client-Request-Id: [6180cbd8-1dcd-49b6-73f0-7aee29630bb0]
   X-Ms-Version: [2018-03-28]
   --------------------------------------------------------------------------------
   ERROR:
-> github.com/Azure/azure-pipeline-go/pipeline.NewError, /Users/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.1/pipeline/error.go:154
HTTP request failed

Put https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=YWJmYzQxZDItZDQ4Yi1mZDQxLTY4MTItMTU2MmEwYjExZWRi&amp;comp=block&amp;se=2019-09-21T14%3A07%3A32Z&amp;sig=-REDACTED-&amp;sp=rwl&amp;sr=c&amp;sv=2018-03-28&amp;timeout=901: context deadline exceeded

goroutine 102 [running]:
github.com/Azure/azure-storage-azcopy/ste.stack(0xc000860e40, 0xc003b9c300, 0x0)
        /Users/vsts/agent/2.153.2/work/1/s/ste/xferLogPolicy.go:139 +0x9d
github.com/Azure/azure-storage-azcopy/ste.NewRequestLogPolicyFactory.func1.1(0x487e840, 0xc001365f20, 0xc043978700, 0x10, 0x1, 0x0, 0xc007923ce0)
        /Users/vsts/agent/2.153.2/work/1/s/ste/xferLogPolicy.go:106 +0x662
github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc003cae0f0, 0x487e840, 0xc001365f20, 0xc043978700, 0xc007923d80, 0x0, 0x48706a0, 0x4097d26)
        /Users/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.1/pipeline/core.go:43 +0x44
github.com/Azure/azure-storage-azcopy/ste.NewVersionPolicyFactory.func1.1(0x487e840, 0xc001365f20, 0xc043978700, 0xc000079000, 0x8, 0x203000, 0x203000)
        /Users/vsts/agent/2.153.2/work/1/s/ste/mgr-JobPartMgr.go:69 +0x1b2
github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc00081a0a0, 0x487e840, 0xc001365f20, 0xc043978700, 0x400e1f9, 0xc003e52aa0, 0x50, 0x48)
        /Users/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.1/pipeline/core.go:43 +0x44
github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do(0x4872160, 0xc00081a0a0, 0xc0000c9cc0, 0x487e840, 0xc001365f20, 0xc043

So far I have noted that my network monitor on Mac is saying that azcopy has only copied less than half the data… (Sent Bytes) This seems to be rising and falling so I’m not sure if the activity monitor is telling me pork pies or not.

Anyway seems like a fat pipe on a better network would be much better

Activity Monitor can help you know how much data each azcopy process has sent or received

Symptom of 100% appearing on an on-going Storage Explorer Transfer

However Storage Explorer is reporting 100%

Looking at the ingress on the storage account it’s kind of obvious that I’ve attempted to upload the file a number of times over in the last 24 hours. So Storage Explorer isn’t happy. Now I’m going to try raw azcopy and have tested a 180MB file and it works… So another 1.7GB and I’ll know if it’s just Storage Explorer or azcopy

Ingress Metric in the Azure Storage Account

0 Comments

Submit a Comment

Your email address will not be published. Required fields are marked *

You May Also Like…