Azure-pipelines-tasks: Pipeline Caching: intermittent internal errors

[ncw]

Required Information

Type: Bug
Task Name: CacheBeta@0

Environment

• Server - Azure Pipelines

Example build: https://dev.azure.com/rclone/rclone/_build/results?buildId=139

Issue Description

The CacheBeta@ task gives intermittent errors

  - task: CacheBeta@0
    inputs:
      key: go-build-cache | "$(Agent.JobName)"
      path: $(GOCACHE)
    continueOnError: true
    displayName: Cache go build
    condition: ne( variables['GOCACHE'], '' )

Full azure-pipelines.yml

Error logs

##[section]Starting: Cache go build
==============================================================================
Task         : Cache (Beta)
Description  : Cache files between runs
Version      : 0.1.0
Author       : Microsoft Corporation
Help         : https://aka.ms/pipeline-caching-docs
==============================================================================
Resolving key `go-build-cache | "Job go1.10"`...
Resolved to `go-build-cache|"Job go1.10"`.
Information, Getting a pipeline cache artifact with one of the following fingerprints:
Information, Fingerprint: `go-build-cache|"Job go1.10"`
##[error]TF400898: An Internal Error Occurred. Activity Id: 8d9509a5-d387-4702-bce6-46fa96be112b.
##[section]Finishing: Cache go build

[alanwales]

I have observed the same thing with downloading pipeline artifacts (below) with the retries, I assume it's based on the same infrastructure the pipeline caching task is.

As a general observation this cache feature doesn't make much of an impact on the overall build time when restoring a NuGet cache: it still takes about 50s to restore the cache from the storage account (600MB downloaded) and there is 10-20s for NuGet to do its own restore logic, whereas it takes 75s to get these dependencies directly from NuGet. Sometimes there is no performance improvement and even times when the restore is even slower than simply calling restore without the cache. It's a bit disappointing because I had high hopes for this feature as the NuGet cache is a huge build performance issue especially across jobs in a pipeline, but hopefully this can be optimized (are the storage accounts in the same data center? are they premium tier storage accounts? are the IOPs being throttled? etc)

Warning, [https://pv3vsblobprodsu6weus8.blob.core.windows.net//B?sv=2017-04-17&sr=b&sig=&spr=https&se=2019-08-20T12%3A42%3A35Z&sp=r&rscl=x-e2eid-1249fd1a-c5e541f7-bde52bc3-4c2eb139-session-208599f6-291143d8-934b36c4-deefd46f] Try 2/5, non-retryable exception caught. Throwing. Details: |  -- | --
  | Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled. |  
  | at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts) |     | at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task1 task, CancellationToken cancellationToken, Func1 makeMessage, String file, String member, Int32 line) |     | at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass56_0.<<GetRedirectResponseAsync>b__0>d.MoveNext() |     | --- End of stack trace from previous location where exception was thrown --- |     | at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper1.InvokeAsync(CancellationToken cancellationToken) |  
  | Warning, [https://pv3vsblobprodsu6weus8.blob.core.windows.net//?sv=2017-04-17&sr=b&sig=&spr=https&se=2019-08-20T12%3A42%3A35Z&sp=r&rscl=x-e2eid-1249fd1a-c5e541f7-bde52bc3-4c2eb139-session-208599f6-291143d8-934b36c4-deefd46f] Try 1/5, retryable exception caught. Retrying in 00:00:01. Details: |  
  | No LastRequestResponse on exception TaskCanceledException: A task was canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled. |  
  | at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts) |     | at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task1 task, CancellationToken cancellationToken, Func1 makeMessage, String file, String member, Int32 line) |     | at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass56_0.<<GetRedirectResponseAsync>b__0>d.MoveNext() |     | --- End of stack trace from previous location where exception was thrown --- |     | at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper1.InvokeAsync(CancellationToken cancellationToken) |  
  | at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass59_0.<b__0>d.MoveNext() |  
  | --- End of stack trace from previous location where exception was thrown --- |  
  | at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken) |  
  | Information, Downloaded 302.0 MB out of 553.1 MB (55%). |  
  | Information, Downloaded 302.0 MB out of 553.1 MB (55%).

[fadnavistanmay]

Hi @ncw - Ack. We are looking into the issue. @alanwales - We have new perf improvements which will be released soon :) Thanks.

[fadnavistanmay]

@ncw - We have found the root cause. We are deploying a fix for this and you guys shouldn't be hitting this again.

Thanks,

[fadnavistanmay]

Hi @ncw - We have deployed the fix. Any new pipelines shouldn't be hitting this error. Feel free to reopen is you still see this. Thanks.

[ncw]

Thank you very much for fixing this and for running a great service.

[whitleykeith]

I'm seeing these errors still with gradle caching. Is there something specific we have to do to avoid this issue?

Note: Our task is Cache@2. I'm assuming that's because this task is out of beta?
Note2: Switching the task to CacheBeta@1 seems to have stopped this issue for us