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&ss=b&srt=sco&sp=rwdlac&se=2019-09-19T09%3A53%3A50Z&st=2019-09-19T01%3A53%3A50Z&spr=https&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&comp=block&se=2019-09-21t14%3A07%3A32z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&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&comp=block&se=2019-09-21t14%3A07%3A32z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&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/[email protected]/pipeline/error.go:154
HTTP request failed
Put https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=YWJmYzQxZDItZDQ4Yi1mZDQxLTY4MTItMTU2MmEwYjExZWRi&comp=block&se=2019-09-21T14%3A07%3A32Z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&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/[email protected]/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/[email protected]/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