azure-pipelines-tasks: Cache step error in pipeline: CaptureResult has already been called for action PipelineCache.RestoreCache

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature?
Type: Bug

Enter Task Name: Cache@2

Environment

  • Server - Azure Pipelines

  • Agent - Hosted

Issue Description

Error occurred during node modules caching: CaptureResult has already been called for action PipelineCache.RestoreCache I found the same issue which was closed without resolution. Base on task documentation there is no any limitation related to stage where it can be used. The same task works well on build pipeline and fails only on CD pipeline, as result we can’t use cache task, and should every time download all node modules during each CD pipeline execution

our pipeline definition:

resources:
  pipelines:
  - pipeline: build
    source: build
    trigger:
      branches:
        include:
        - develop
variables:
- group: variable-group-dev
trigger:
  enabled: false
pr:
  enabled: false
pool:
  vmImage: 'ubuntu-latest'
stages:
- stage: Deploy
  displayName: Deploy Dev
  jobs:
  - job: Deploy
    timeoutInMinutes: 0
    steps:
    - checkout: self
    - task: UsePythonVersion@0
      displayName: 'use python 3'
      inputs:
        versionSpec: '3.x'
        addToPath: true
    - task: CmdLine@2
      displayName: 'pip install aws cli'
      inputs:
        script: pip3 install awscli
    - task: Cache@2
      displayName: cache node_modules
      inputs:
        key: 'npm1 | "$(Agent.OS)" | $(Build.SourcesDirectory)/cdk/package-lock.json'
        restoreKeys: |
          npm1 | "$(Agent.OS)"
        path: $(Build.SourcesDirectory)/cdk/node_modules
    - task: CmdLine@2
      displayName: 'npm install'
      inputs:
        script: npm install
        workingDirectory: cdk

... remain part omitted 

Task logs

Starting: cache node_modules
==============================================================================
Task         : Cache
Description  : Cache files between runs
Version      : 2.0.1
Author       : Microsoft Corporation
Help         : https://aka.ms/pipeline-caching-docs
==============================================================================
Resolving key:
 - npm1                                      [string]
 - "Linux"                                   [string]
 - /home/vsts/work/1/s/cdk/package-lock.json [file] --> 766D530EB535318821053734B01BD300A4EBA42257296D3CAB307A3C72639658
Resolved to: npm1|"Linux"|NQ8TuIEXcUX8/HdObojYu1L3twyI0N+FYCfxie4A7+g=
Resolving restore key:
 - npm1    [string]
 - "Linux" [string]
Resolved to: npm1|"Linux"|**
ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 4c6273e8-46a6-4da0-b85a-a49697a8ddea
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `npm1|"Linux"|NQ8TuIEXcUX8/HdObojYu1L3twyI0N+FYCfxie4A7+g=`
Fingerprint: `npm1|"Linux"|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `npm1|"Linux"|NQ8TuIEXcUX8/HdObojYu1L3twyI0N+FYCfxie4A7+g=`
Fingerprint: `npm1|"Linux"|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `npm1|"Linux"|NQ8TuIEXcUX8/HdObojYu1L3twyI0N+FYCfxie4A7+g=`
Fingerprint: `npm1|"Linux"|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `npm1|"Linux"|NQ8TuIEXcUX8/HdObojYu1L3twyI0N+FYCfxie4A7+g=`
Fingerprint: `npm1|"Linux"|**`
ApplicationInsightsTelemetrySender correlated 5 events with X-TFS-Session 4c6273e8-46a6-4da0-b85a-a49697a8ddea
##[error]CaptureResult has already been called for action PipelineCache.RestoreCache
Finishing: cache node_modules

Troubleshooting

Checkout how to troubleshoot failures and collect debug logs: https://docs.microsoft.com/en-us/vsts/build-release/actions/troubleshooting

Error logs

[Insert error from the logs here for a quick overview]

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 46
  • Comments: 44 (7 by maintainers)

Commits related to this issue

Most upvoted comments

+1 I changed the cache key added a salt, but then another item just failed in the same way that had been working. Major issue. Failure like this should be a cache miss, please fix asap

We think there are two problems here:

  1. There was a regression due to adding retries on GetPipelineCacheArtifactAsync that caused any server side problem to wind up generating the error “CaptureResult has already been called for action PipelineCache.RestoreCache” hiding the actual backend error with the cryptic one in this issue. But this has been in the agent for a while now (Sep 22). It confuses things but is not the root cause. This is fixed by https://github.com/microsoft/azure-pipelines-agent/pull/3621.
  2. There has been an uptick of “FormatExceptions” in cache tasks starting last Thursday in one of the Azure DevOps scale units. All of the X-TFS-Sessions in this issue point to this as the underlying root cause of cache instability. We are still investigating why this started last Thursday, why it is only happening in a single scale unit and the root cause.

So to summarize, the PR that went into the agent won’t increase or decrease the occurrence of the issue but it should log the true backend error message. We are still investigating why downloading from cache is sometimes failing with FormatExceptions.

continueOnError: true

is better then disabling as it will still try/steps that succeeded will still benefit from cache.

Adding some additional notes:

We’ve got a pipeline using this task on hosted agents, last run that succeeded was at 1200GMT today (19 November):

Initialize Job Logs:

Starting: Initialize job
Agent name: 'Hosted Agent'
Agent machine name: 'WIN-P13CC4RF62R'
Current agent version: '2.195.0'
Operating System
Virtual Environment
Virtual Environment Provisioner
Current image version: '20211110.1'
Agent running as: 'VssAdministrator'
Prepare build directory.
Set build variables.
Download all required tasks.
Downloading task: PowerShell (2.194.0)
Downloading task: Cache (2.0.1)
Downloading task: NuGetCommand (2.194.0)
Downloading task: VSBuild (1.192.3)
Downloading task: ExtractFiles (1.189.0)
Downloading task: CmdLine (2.182.0)
Downloading task: ArchiveFiles (2.189.0)
Downloading task: VSTest (2.170.1)
Downloading task: CopyFiles (2.190.1)
Downloading task: PublishPipelineArtifact (1.2.3)
Checking job knob settings.
   Knob: AgentToolsDirectory = C:\hostedtoolcache\windows Source: ${AGENT_TOOLSDIRECTORY} 
   Knob: AgentPerflog = C:\agents\perflog Source: ${VSTS_AGENT_PERFLOG} 
Finished checking job knob settings.
Start tracking orphan processes.
Finishing: Initialize job

Cache Task has a single entry for “Getting a pipeline cache artifact”:

Resolved to: nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=
Resolving restore key:
 - nuget        [string]
 - "Windows_NT" [string]
Resolved to: nuget|"Windows_NT"|**
Resolving restore key:
 - nuget [string]
Resolved to: nuget|**
ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session cc66c526-143e-4e10-9827-784bd0fa2392
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
There is a cache hit: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Used scope: 192;f8afffaa-7381-4806-9648-f186aadeab9f;refs/heads/develop;a6669455-64a0-4a5f-9beb-2a7b319d3643
Missed on the following scopes: 192;f8afffaa-7381-4806-9648-f186aadeab9f;refs/heads/feature/automated-eyebrow;a6669455-64a0-4a5f-9beb-2a7b319d3643
Entry found at fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`

The pipeline started failing with a run at 1232GMT

Starting: Initialize job
Agent name: 'Hosted Agent'
Agent machine name: 'WIN-P13CC4RF62R'
Current agent version: '2.195.0'
Operating System
Virtual Environment
Virtual Environment Provisioner
Current image version: '20211110.1'
Agent running as: 'VssAdministrator'
Prepare build directory.
Set build variables.
Download all required tasks.
Downloading task: PowerShell (2.194.0)
Downloading task: Cache (2.0.1)
Downloading task: NuGetCommand (2.194.0)
Downloading task: VSBuild (1.192.3)
Downloading task: ExtractFiles (1.189.0)
Downloading task: CmdLine (2.182.0)
Downloading task: ArchiveFiles (2.189.0)
Downloading task: VSTest (2.170.1)
Downloading task: CopyFiles (2.190.1)
Downloading task: PublishPipelineArtifact (1.2.3)
Checking job knob settings.
   Knob: AgentToolsDirectory = C:\hostedtoolcache\windows Source: ${AGENT_TOOLSDIRECTORY} 
   Knob: AgentPerflog = C:\agents\perflog Source: ${VSTS_AGENT_PERFLOG} 
Finished checking job knob settings.
Start tracking orphan processes.
Finishing: Initialize job

As you can see the versions of the tasks, agent image, etc. are the same. The Cache task then reported:

Resolved to: nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=
Resolving restore key:
 - nuget        [string]
 - "Windows_NT" [string]
Resolved to: nuget|"Windows_NT"|**
Resolving restore key:
 - nuget [string]
Resolved to: nuget|**
ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session f931fffd-3a9c-4998-9125-6f06ac4bd778
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
ApplicationInsightsTelemetrySender correlated 5 events with X-TFS-Session f931fffd-3a9c-4998-9125-6f06ac4bd778
##[error]CaptureResult has already been called for action PipelineCache.RestoreCache
Finishing: Cache Nuget

So, using the same fingerprint, but clearly failing to communicate with the cache store, retrying 4 times, and then erroring out. Running again with diagnostics enabled gives the following detailed logs:

Resolved to: nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=
##[debug]Processed: ##vso[task.settaskvariable variable=RESTORE_STEP_RAN;issecret=False;]true
##[debug]Processed: ##vso[task.settaskvariable variable=RESTORE_STEP_RESOLVED_FINGERPRINT;issecret=False;]nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=
Resolving restore key:
 - nuget        [string]
 - "Windows_NT" [string]
Resolved to: nuget|"Windows_NT"|**
Resolving restore key:
 - nuget [string]
Resolved to: nuget|**
Verbose, ArtifactHttpClientFactory.CreateVssHttpClient: DedupStoreHttpClient with BaseUri: https://vsblobprodeus21.vsblob.visualstudio.com/A675ab3c5-831f-450a-97a4-a862de041b5f/, MaxRetries:5, SendTimeout:00:00:50
Information, ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 570d18f0-38d4-4c60-84fe-af586f84cb8a
Verbose, Started ITelemetrySender BlobStoreApplicationInsightsTelemetrySender.
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
[] Try 1/3, retryable exception caught. Retrying in 00:00:01. Microsoft.VisualStudio.Services.WebApi.VssServiceResponseException: TF400898: An Internal Error Occurred. Activity Id: 304f588d-c071-4f3e-9ae9-cb6f5c5756d9.
 ---> System.FormatException: TF400898: An Internal Error Occurred. Activity Id: 304f588d-c071-4f3e-9ae9-cb6f5c5756d9.
   --- End of inner exception stack trace ---
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.HandleResponseAsync(HttpResponseMessage response, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync(HttpRequestMessage message, HttpCompletionOption completionOption, Object userState, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync[T](HttpRequestMessage message, Object userState, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.SendAsync[T](HttpMethod method, IEnumerable`1 additionalHeaders, Guid locationId, Object routeValues, ApiResourceVersion version, HttpContent content, IEnumerable`1 queryParameters, Object userState, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.<>c__DisplayClass9_0.<<GetPipelineCacheArtifactAsync>b__1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken, PipelineCacheTelemetryRecord cacheRecordOptional)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.<>c__DisplayClass3_1.<<DownloadAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
Details:
No LastRequestResponse on exception VssServiceResponseException: TF400898: An Internal Error Occurred. Activity Id: 304f588d-c071-4f3e-9ae9-cb6f5c5756d9.
Verbose, ApplicationInsightsTelemetrySender sent PipelineCache.RestoreCache telemetry
Verbose, ApplicationInsightsTelemetrySender sent Error telemetry
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
[] Try 2/3, retryable exception caught. Retrying in 00:00:01.9314922. System.InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
   at Microsoft.VisualStudio.Services.Content.Common.Telemetry.ActionTelemetryRecord.CaptureResult(String actionResult, Stopwatch actionTimer, Int64 itemCount)
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken, PipelineCacheTelemetryRecord cacheRecordOptional)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.<>c__DisplayClass3_1.<<DownloadAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
Details:
No LastRequestResponse on exception InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
Verbose, ApplicationInsightsTelemetrySender sent Error telemetry
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
[] Try 3/3, retryable exception caught. Retrying in 00:00:03.4074818. System.InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
   at Microsoft.VisualStudio.Services.Content.Common.Telemetry.ActionTelemetryRecord.CaptureResult(String actionResult, Stopwatch actionTimer, Int64 itemCount)
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken, PipelineCacheTelemetryRecord cacheRecordOptional)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.<>c__DisplayClass3_1.<<DownloadAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
Details:
No LastRequestResponse on exception InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
Verbose, ApplicationInsightsTelemetrySender sent Error telemetry
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `nuget|"Windows_NT"|GEt1f4kgN5SVFRvSnpeRgsa9GdkzmgwBcOu62XnivLQ=`
Fingerprint: `nuget|"Windows_NT"|**`
Fingerprint: `nuget|**`
[] Try 4/3, retryable exception caught, but retries have been exhausted. Throwing. System.InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
   at Microsoft.VisualStudio.Services.Content.Common.Telemetry.ActionTelemetryRecord.CaptureResult(String actionResult, Stopwatch actionTimer, Int64 itemCount)
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken, PipelineCacheTelemetryRecord cacheRecordOptional)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.<>c__DisplayClass3_1.<<DownloadAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
Details:
No LastRequestResponse on exception InvalidOperationException: CaptureResult has already been called for action PipelineCache.RestoreCache
Verbose, ApplicationInsightsTelemetrySender waiting for 0 of 5 TrackEvent operations to complete...
Verbose, ApplicationInsightsTelemetrySender sent Error telemetry
Verbose, ApplicationInsightsTelemetrySender operations completed in 389 ms
Information, ApplicationInsightsTelemetrySender correlated 5 events with X-TFS-Session 570d18f0-38d4-4c60-84fe-af586f84cb8a
Verbose, Stopped ITelemetrySender BlobStoreApplicationInsightsTelemetrySender.
##[error]CaptureResult has already been called for action PipelineCache.RestoreCache
##[debug]Processed: ##vso[task.logissue type=error;]CaptureResult has already been called for action PipelineCache.RestoreCache
##[debug]Processed: ##vso[task.complete result=Failed;]
##[debug]   at Microsoft.VisualStudio.Services.Content.Common.Telemetry.ActionTelemetryRecord.CaptureResult(String actionResult, Stopwatch actionTimer, Int64 itemCount)
   at Microsoft.VisualStudio.Services.BlobStore.Common.Telemetry.BlobStoreClientTelemetry.MeasureActionAsync[TResult](BlobStoreTelemetryRecord record, Func`1 actionAsync)
   at Microsoft.VisualStudio.Services.PipelineCache.WebApi.PipelineCacheClient.GetPipelineCacheArtifactAsync(Fingerprint[] fingerprints, CancellationToken cancellationToken, PipelineCacheTelemetryRecord cacheRecordOptional)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.<>c__DisplayClass3_1.<<DownloadAsync>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
   at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
   at Agent.Plugins.PipelineCache.PipelineCacheServer.DownloadAsync(AgentTaskPluginExecutionContext context, Fingerprint[] fingerprints, String path, String cacheHitVariable, CancellationToken cancellationToken)
   at Agent.Plugins.PipelineCache.RestorePipelineCacheV0.ProcessCommandInternalAsync(AgentTaskPluginExecutionContext context, Fingerprint fingerprint, Func`1 restoreKeysGenerator, String path, CancellationToken token)
   at Agent.Plugins.PipelineCache.PipelineCacheTaskPluginBase.RunAsync(AgentTaskPluginExecutionContext context, CancellationToken token)
   at Agent.PluginHost.Program.Main(String[] args)
Finishing: Cache Nuget

This makes it look like an error connecting to the cache store, and not handling that properly.

As this task is designed to cache a transient, rebuildable blob, it would probably be better for this to be a warning and report back as a cache miss so that the pipeline can continue and handle the miss as it would do normally. At the moment this is completely blocking builds from happening until we remove/skip the cache step temporarily.

Update:

  1. We have at this point swapped out the VMs in the hope that there would be no more duplicate offsets generated.
  2. We have also deployed a mitigation on the server side which will handle this problem for now.

Early read of the telemetry is indicating that relief is in place. Do let us know if you see otherwise. We’ve mitigated the incident for now.

It looks like we hit this bug https://github.com/dotnet/runtime/issues/4774. We found persisted datetimes like this “cr:expirationDate”: “11/26/2021 2:31:39 PM +00:00 +00:00”, which looks exactly like the problem described in the issue. It’s likely a single machine in our application tier hit this bug and persisted “corrupt” data that caused problems for anyone trying to pull those cache item.

We believe we no longer have a “bad” AT in the mix so changing the salt should mitigate it. We are also looking to deploy something that will mitigate this without changing the salt.

We set a variable and have a condition on all our cache/cache miss items. so if it misses, or fails with continueOneError, the next step will run and add missing things.

- task: Cache@2
  inputs:
    key: 'npm | "$(Agent.OS)" | Web/package-lock.json'
    path: 'Web/node_modules'
    cacheHitVar: CR_Web
  displayName: Web|Cache NPM packages
  continueOnError: true
  
- task: Npm@1
  inputs:
    command: 'install'
    workingDir: 'Web'
  displayName: Web|Restore NPM packages
  condition: ne(variables.CR_Web, 'true')

As in any other step it can be disabled. Im already using it as a workround…

steps:
  - task: Cache@2
    inputs:
      key: v1 | $(Build.Repository.Name) | nuget
      path: $(NUGET_PACKAGES)
    displayName: Cache NuGet packages
    enabled: false

Well we’re seeing this problem as well. Disabled all of our cache steps and are taking the build time hit so that we can keep moving forward–albeit very slowly.

Ok, solution(sort of)

Mark all your cache jobs with:

continueOnError: true

This won’t truly fix the issue, but it will make the pipelines continue to process without the cache if one caching rule failes.

@carl-tanner I am still seeing this issue. Anyone else?

2021-12-07T23:18:57.7569941Z ##[section]Starting: Cache maven local repository 2021-12-07T23:18:57.7575391Z ============================================================================== 2021-12-07T23:18:57.7575662Z Task : Cache 2021-12-07T23:18:57.7575861Z Description : Cache files between runs 2021-12-07T23:18:57.7576056Z Version : 2.0.1 2021-12-07T23:18:57.7576248Z Author : Microsoft Corporation 2021-12-07T23:18:57.7576499Z Help : https://aka.ms/pipeline-caching-docs 2021-12-07T23:18:57.7576755Z ============================================================================== 2021-12-07T23:18:58.6638787Z Resolving key: 2021-12-07T23:18:58.6644669Z - maven [string] 2021-12-07T23:18:58.6645283Z - “Linux” [string] 2021-12-07T23:18:58.6645863Z - **/pom.xml [file pattern; matches: 1] 2021-12-07T23:18:58.6646548Z - s/pom.xml --> 92D2D9836979CFB78F67DB635B2161E4B6C535B1EDC0D29A60FB965D64F9E17C 2021-12-07T23:18:58.6647042Z Resolved to: maven|“Linux”|1Wx+63QbitOZ8GPpH2UHDueFvqUhtDu1IUmMMxDVimU= 2021-12-07T23:18:58.6648958Z Resolving restore key: 2021-12-07T23:18:58.6649462Z - maven [string] 2021-12-07T23:18:58.6649956Z - “Linux” [string] 2021-12-07T23:18:58.6650327Z Resolved to: maven|“Linux”|** 2021-12-07T23:18:58.6650688Z Resolving restore key: 2021-12-07T23:18:58.6651166Z - maven [string] 2021-12-07T23:18:58.6651521Z Resolved to: maven|** 2021-12-07T23:18:58.7452605Z ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 68e8f8c0-5e20-42cf-af1d-af4556de1af8 2021-12-07T23:18:59.0158181Z Getting a pipeline cache artifact with one of the following fingerprints: 2021-12-07T23:18:59.0158633Z Fingerprint: maven|"Linux"|1Wx+63QbitOZ8GPpH2UHDueFvqUhtDu1IUmMMxDVimU= 2021-12-07T23:18:59.0158933Z Fingerprint: maven|"Linux"|** 2021-12-07T23:18:59.0159186Z Fingerprint: maven|** 2021-12-07T23:19:00.3001720Z Getting a pipeline cache artifact with one of the following fingerprints: 2021-12-07T23:19:00.3002453Z Fingerprint: maven|"Linux"|1Wx+63QbitOZ8GPpH2UHDueFvqUhtDu1IUmMMxDVimU= 2021-12-07T23:19:00.3002981Z Fingerprint: maven|"Linux"|** 2021-12-07T23:19:00.3003363Z Fingerprint: maven|** 2021-12-07T23:19:02.1829604Z Getting a pipeline cache artifact with one of the following fingerprints: 2021-12-07T23:19:02.1832862Z Fingerprint: maven|"Linux"|1Wx+63QbitOZ8GPpH2UHDueFvqUhtDu1IUmMMxDVimU= 2021-12-07T23:19:02.1838208Z Fingerprint: maven|"Linux"|** 2021-12-07T23:19:02.1838789Z Fingerprint: maven|** 2021-12-07T23:19:06.3375273Z Getting a pipeline cache artifact with one of the following fingerprints: 2021-12-07T23:19:06.3375870Z Fingerprint: maven|"Linux"|1Wx+63QbitOZ8GPpH2UHDueFvqUhtDu1IUmMMxDVimU= 2021-12-07T23:19:06.3376311Z Fingerprint: maven|"Linux"|** 2021-12-07T23:19:06.3376625Z Fingerprint: maven|** 2021-12-07T23:19:06.9725749Z ApplicationInsightsTelemetrySender correlated 5 events with X-TFS-Session 68e8f8c0-5e20-42cf-af1d-af4556de1af8 2021-12-07T23:19:06.9761717Z ##[error]CaptureResult has already been called for action PipelineCache.RestoreCache 2021-12-07T23:19:06.9801223Z ##[section]Finishing: Cache maven local repository

I just create a new pipeline and the error is gone. The previous pipeline still not working

Encountering this as well – last build succeeded, same pipeline.yaml, < 4hr prior

One of the problems with this issue is many different errors were being reported as “CaptureResult has already been called for action”. Your issue is something else. The underlying error for your cache task is “System.ArgumentException: Unable to find pipeline caching scopes.” When the latest version of the pipelines agent is rolled out you’ll start seeing that error. Feel free to open a new issue for this and we can try and figure out what is going on for your pipelines.

Interestingly I just re-enabled our cache tasks with continueOnError: true and they initially all had a cache miss even though the full fingerprints were identical to the run from Friday morning, and subsequent runs are now either working as expected, or failing with as a warning but continuing as required:

Intermittent failures

did we deploy a new version of the cache task yesterday? our build also started to fail yesterday

Doesn’t look like it, the task version listed in the initialisation log (2.0.1) is the same as for older successful builds.

People are also reporting that builds with multiple cache tasks are seeing some tasks succeeding while one fails within a single build.

@pynej We have a nuget restore task that kicks in only when the cache task misses. Wouldn’t continueOnError: true cause the package restore to be skipped which might result in build failures if a package is missing?

You could adjust your condition to skip the nuget restore only if the output variable is true - this will also help if you have a partial hit (inexact), which could restore a potentially out of date cache.

@pynej We have a nuget restore task that kicks in only when the cache task misses. Wouldn’t continueOnError: true cause the package restore to be skipped which might result in build failures if a package is missing?

Everything so far appears to be pointing to an issue with the Cache task talking to the underlying storage - concerning possibly for the telemetry if I’m reading the stack traces correctly.

Only reliable work around at this time @TOuhrouche appears to be either:

  1. Disable the Cache tasks, and take the hit of rebuilding whatever you’re caching.
  2. Set every subsequent task to “continue on failure or success” and cope with other steps failing but not being caught.

Of those, 1 is probably safest.

The issue really is then to understand how we’re going to know the problem has been fixed, and we can re-enable the tasks again.

Same here.

resources:
  - repo: self
    clean: true

pool:
  vmImage: "ubuntu-20.04"

trigger:
  - feature/*
  - develop
  - release/*
  - master
  - hotfix/*

variables:
  BRANCH_NAME: $(Build.SourceBranch)
  CONTINUOUS_DELIVERY: true
  CAKE_SETTINGS_SKIPVERIFICATION: true
  NUGET_PACKAGES: $(Pipeline.Workspace)/.nuget/packages

steps:
  - task: Cache@2
    inputs:
      key: v1 | $(Build.Repository.Name) | nuget
      path: $(NUGET_PACKAGES)
    displayName: Cache NuGet packages

I’ve logged a Sev A ticket w/ Microsoft. I suggest you do the same if you have a support plan for Azure.

Please Disable Caching task and proceed for now. If performance is not an issue.