Azure-storage-azcopy: AzCopy 10.1.2 Fails to Redact SAS Sig in Job Logs upon TLS Handshake Failure

[AtomicGaryBusey]

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)

Windows Server 2019 with 3.5GB memory available.

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?

When an AzCopy copy job is executed on a system with low memory (i.e. an Azure DS1_v2 VM with 3.5GB memory), a TLS handshake failure reliably occurs. See AzCopy Issue 402 for more info on this. The error is logged to the job's log file located in C:\Users\username\.azcopy\, but for this specific error the SAS signature is not REDACTED like it is elsewhere in the log.

Here's the a full excerpt from an actual log from my system. The part that says "THISWASNOTACTUALLYREDACTEDINTHEJOBLOG" is where I took out my SAS sig before posting this issue.

2019/05/22 01:46:27 ==> REQUEST/RESPONSE (Try=1/2m26.7379989s[SLOW >3s], OpTime=2m26.7379989s) -- REQUEST ERROR
   HEAD https://forensicspelunking.blob.core.windows.net/memory/memdumptest-20190522-003248.json?se=2019-05-23t01%3A28%3A02z&sig=REDACTED&sp=racwdl&sr=c&st=2019-05-22t01%3A28%3A02z&sv=2018-03-28&timeout=901
   User-Agent: [AzCopy/10.1.2 Azure-Storage/0.6 (go1.10.8; Windows_NT)]
   X-Ms-Client-Request-Id: [23bc1e46-079f-4968-500e-3c15319d21aa]
   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

Head https://forensicspelunking.blob.core.windows.net/memory/memdumptest-20190522-003248.json?se=2019-05-23T01%3A28%3A02Z&sig=THISWASNOTACTUALLYREDACTEDINTHEJOBLOG%3D&sp=racwdl&sr=c&st=2019-05-22T01%3A28%3A02Z&sv=2018-03-28&timeout=901: net/http: TLS handshake timeout

goroutine 46 [running]:
github.com/Azure/azure-storage-azcopy/ste.stack(0xc042136070, 0xc0422cab00, 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, 0xc042250360, 0xc0422cb400, 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(0xc042082550, 0xc9d620, 0xc042250360, 0xc0422cb400, 0xa, 0xc04215a120, 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, 0xc042250360, 0xc0422cb400, 0x10dd3e0, 0x0, 0x412263, 0x1b4ea0)
    /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(0xc04281cba0, 0xc9d620, 0xc042250360, 0xc0422cb400, 0x1b4ea0, 0x7f, 0xc042291e01, 0xc042fc91c0)
    /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, 0xc04281cba0, 0xc042052780, 0xc9d620, 0xc042250360, 0xc0422cb400, 0x10, 0x10, 0xb2fde0, 0x10dd300)
    /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, 0xc04281cbc0, 0xc9d620, 0xc042250360, 0xc0422cb400, 0xd1913f1f01, 0xc042fc9230, 0xc042fc92f0, 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(0xc04219a6d0, 0xc9d620, 0xc042250360, 0xc0422cb400, 0x0, 0x0, 0x0, 0xc042fc9340)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/xferRetryNotificationPolicy.go:59 +0x65
github.com/Azure/azure-storage-azcopy/ste.(*retryNotificationPolicy).Do-fm(0xc9d620, 0xc042250360, 0xc0422cb400, 0x10dc4e0, 0xc9d620, 0xc042250360, 0xc04219a7f0)
    /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(0xc04219a6e0, 0xc9d620, 0xc042250360, 0xc0422cb400, 0xc042250360, 0xc04219a7f0, 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, 0xc042048400, 0xc0422cb300, 0xc042cf, 0x16, 0xc0420190e0, 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(0xc0420825a0, 0xc9d5a0, 0xc042048400, 0xc0422cb300, 0x24, 0x60e8c7, 0xb5fbc0, 0xc042291dd0)
    /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, 0xc042048400, 0xc0422cb300, 0xbfb237, 0xa, 0xc04201c780, 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(0xc04281cbe0, 0xc9d5a0, 0xc042048400, 0xc0422cb300, 0x36, 0xc042004720, 0xc042291e30, 0xc042fc9710)
    /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, 0xc042048400, 0xc0422cb300, 0x1, 0x0, 0x1, 0xc042004720)
    /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(0xc042291e30, 0xc9d5a0, 0xc042048400, 0xc0422cb300, 0xc042291e30, 0xbf6280, 0xc042fc9780, 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(0xc0420483c0, 0xc9d5a0, 0xc042048400, 0xc96880, 0xc042052780, 0xc0422cb300, 0x28, 0xc0420d62d0, 0x28, 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.blobClient.GetProperties(0xc0420d62a0, 0x5, 0x0, 0x0, 0x0, 0xc0420d62a8, 0x28, 0xc0420d62d0, 0x28, 0x0, ...)
    /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/zz_generated_blob.go:657 +0x3c1
github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob.BlobURL.GetProperties(0xc0420d62a0, 0x5, 0x0, 0x0, 0x0, 0xc0420d62a8, 0x28, 0xc0420d62d0, 0x28, 0x0, ...)
    /go/src/github.com/Azure/azure-storage-azcopy/vendor/github.com/Azure/azure-storage-blob-go/azblob/url_blob.go:113 +0x126
github.com/Azure/azure-storage-azcopy/ste.(*blockBlobSenderBase).RemoteFileExists(0xc04204aa00, 0xc000000000, 0x0, 0x0)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/sender-blockBlob.go:110 +0xb5
github.com/Azure/azure-storage-azcopy/ste.anyToRemote(0xcadf80, 0xc0420823c0, 0xc94c60, 0xc0420483c0, 0xc04201a260, 0xc35228, 0xc35238)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/xfer-anyToRemote.go:76 +0xc1b
github.com/Azure/azure-storage-azcopy/ste.parameterizeSend.func1(0xcadf80, 0xc0420823c0, 0xc94c60, 0xc0420483c0, 0xc04201a260)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/xfer.go:67 +0x73
github.com/Azure/azure-storage-azcopy/ste.(*jobPartMgr).StartJobXfer(0xc04281e380, 0xcadf80, 0xc0420823c0)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/mgr-JobPartMgr.go:519 +0x6c
github.com/Azure/azure-storage-azcopy/ste.(*jobPartTransferMgr).StartJobXfer(0xc0420823c0)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/mgr-JobPartTransferMgr.go:142 +0x4e
github.com/Azure/azure-storage-azcopy/ste.(*jobsAdmin).transferProcessor.func1(0xcadf80, 0xc0420823c0)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/JobsAdmin.go:261 +0x1ae
github.com/Azure/azure-storage-azcopy/ste.(*jobsAdmin).transferProcessor(0xc0420ec1e0, 0x0)
    /go/src/github.com/Azure/azure-storage-azcopy/ste/JobsAdmin.go:269 +0x8a
created by github.com/Azure/azure-storage-azcopy/ste.initJobsAdmin
    /go/src/github.com/Azure/azure-storage-azcopy/ste/JobsAdmin.go:188 +0x71e

How can we reproduce the problem in the simplest way?

Deploy an Azure DS1_v2 VM and run the command on it. It'll log the secret in unredacted form. I've reproduced this on two DS1_v2 VMs.

Have you found a mitigation/solution?

No, a user cannot mitigate this as they cannot possibly prevent all TLS handshake failure scenarios.

[JohnRusk]

Thanks for logging this! We'll look into what we can do about it!

[jiteshkumargouthamchand]

I am getting same error from my Application server 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

[JohnRusk]

@jiteshkumargouthamchand This issue is specifically about the fact that SAS tokens are left in the log after such a TLS failure. Your problem sounds like something different. Can you please see if its the same as #402 and if it is please leave a comment there. If it's not the same, please create a new issue.

NOTE: that because SAS tokens are not being properly removed from the log, don't copy the entire HTTP Request failed error into your issue (i.e. not the bit where it has the SAS URL).

[AtomicGaryBusey]

I discovered today if you execute AzCopy via a script run as an Azure Custom Script Extension it logs errors to the Application Event log as Event ID 0 with the SAS unredacted. See this screenshot:

If you have something like the OMS agent lifting your event logs out of the VM into Azure Security Center, Sentinel, or some other system, you're going to be transporting secrets across systems without being aware of it. Seems like a bigger problem than I first realized.

[JohnRusk]

Thanks. Fix is due out very shortly.

[JohnRusk]

Fixed in 10.2.0, released today.