Problem with caching npm modules

[ksmigiel]

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

• Agent - Hosted or Private:

  • If using private agent, provide the OS of the machine running the agent and the agent version: windows-2019

Issue Description

I have noticed the problem with caching npm-cache/.npm folder (similar to unfortunately closed without resolution issue: #12121), either by using default %AppData%\npm-cache or setting npm_config_cache environment variable. After some investigation it seems like Cache@2 task has problem with uploading tarballed archive with .npm folder content. It uploads only ~20% in my case of all npm modules. It must be somehow connected with .npm folder structure (_cacache folder to be precise) which contains hashes as folder and files names. Some deduplication and archive optimization process must treat those files as possible to compress/deduplicate and thus results in stripped archive.

When I zipped .npm folder before upload, then Cache@2 uploaded 100% of chunks of data. Also .cypress cache folder, which we are using in the same pipeline is being cached without any problem.

[Zhaph]

We've seen the same issue.

Further details:

Pipeline .yaml:

variables:
- name: 'npm_config_cache'
  value: $(Pipeline.Workspace)\npm-cache

pool:
  vmImage: 'windows-latest'

stages:
- stage: Build
  jobs:
  - job: MSBuild
    steps:
    - task: Cache@2
      inputs:
        key: 'npm | "$(Agent.OS)" | $(Build.SourcesDirectory)/PatternLibrary/package-lock.json'
        restoreKeys: |
          npm | "$(Agent.OS)"
        path: $(npm_config_cache)
      displayName: Cache npm

    - script: |
        npm ci --config $(npm_config_cache) --loglevel verbose
      workingDirectory: $(Build.SourcesDirectory)/PatternLibrary/
      displayName: 'ACS npm install'
      env:
        CI: true

Cache upload was reporting substantial deduplication when caching npm's cache folder:

Content upload statistics:
Total Content: 113.1 MB
Physical Content Uploaded: 19.8 MB
Logical Content Uploaded: 24.5 MB
Compression Saved: 4.7 MB
Deduplication Saved: 88.6 MB
Number of Chunks Uploaded: 287
Total Number of Chunks: 2,643

When downloading the cache, we see:

Extracting archive: 
Expected size to be downloaded: 56.6 MB
Downloaded 0.0 MB out of 56.6 MB (0%).
Downloaded 56.6 MB out of 56.6 MB (100%).

Download statistics:
Total Content: 56.6 MB
Physical Content Downloaded: 50.3 MB
Compression Saved: 6.3 MB
Local Caching Saved: 0.0 MB
Chunks Downloaded: 714
Nodes Downloaded: 2

--
Path = 
Type = tar
Code Page = UTF-8

Everything is Ok

Folders: 3767
Files: 4087
Size:       51445284
Compressed: 4022272
Process exit code: 0
Cache restored.

However from the verbose logging on npm ci we can see over 1000 requests to registry.npmjs.org to download the packages which can have a significant (and variable) impact on the build times.

We've added the following steps to work around this for now:

    # There appears to be an issue with the way the cache task creates archives and npm's cache format.
    # To work around this we manually archive the cache folder and cache that instead. This means we
    # need to manually unpack and pack the archive. Partial hits should still see some performance gains.
    - task: Cache@2
      inputs:
        key: 'npmzip | "$(Agent.OS)" | $(Build.SourcesDirectory)/PatternLibrary/package-lock.json'
        restoreKeys: |
          npmzip | "$(Agent.OS)"
        path: $(npm_config_cache)-archive
        cacheHitVar: NPMZIP_CACHE_RESTORED
      displayName: Cache npm

    - task: ExtractFiles@1
      condition: ne(variables.NPMZIP_CACHE_RESTORED, 'false')
      inputs:
        archiveFilePatterns: $(npm_config_cache)-archive\cache.zip
        destinationFolder: $(npm_config_cache)
        cleanDestinationFolder: true
      displayName: "Extract npm cache"

    # Force config to a known, local folder that has (hopefully) been pre-filled.
    - script: |
        npm ci --config $(npm_config_cache)
      workingDirectory: $(Build.SourcesDirectory)/PatternLibrary/
      displayName: 'ACS npm install'
      env:
        CI: true

    - task: ArchiveFiles@2
      condition: ne(variables.NPMZIP_CACHE_RESTORED, 'true')
      inputs:
        rootFolderOrFile: "$(npm_config_cache)"
        includeRootFolder: false
        archiveType: "zip"
        archiveFile: $(npm_config_cache)-archive\cache.zip
        cleanDestinationFolder: true
      displayName: "Archive npm cache"

This results in the following output from the archive task:

Found 2 files
Archiving file: node-sass
Archiving file: _cacache
D:\a\_tasks\ArchiveFiles_d8b84976-e99a-4b86-b885-4849694435b0\2.189.0\7zip\7z.exe a -tzip -mx=5 D:\a\1\npm-cache-archive\cache.zip @D:\a\_temp\vdyufvuztw9

7-Zip 19.00 (x64) : Copyright (c) 1999-2018 Igor Pavlov : 2019-02-21

Scanning the drive:
3766 folders, 3061 files, 51263717 bytes (49 MiB)

Creating archive: D:\a\1\npm-cache-archive\cache.zip

Add new data to archive: 3766 folders, 3061 files, 51263717 bytes (49 MiB)

Files read from disk: 3061
Archive size: 50087739 bytes (48 MiB)
Everything is Ok

Which curiously appears very similar to the report from the cache restore, however subsequent runs using that restored cache show that no further calls are needed to registry.npmjs.org.

[Ogglas]

We are also having this issue, cache code from docs.microsoft.com

https://docs.microsoft.com/en-us/azure/devops/pipelines/release/caching?view=azure-devops#nodejsnpm

trigger:
  batch: true
  branches:
    include:
    - master
    - develop

pool:
  vmImage: 'windows-2022'

variables:
  npm_config_cache: $(Pipeline.Workspace)/.npm
  clientApp: 'Repo\Repo.Web\ClientApp'

steps:
- task: Cache@2
  inputs:
    key: 'npm | "$(Agent.OS)" | $(clientApp)\package-lock.json'
    restoreKeys: |
       npm | "$(Agent.OS)"
    path: $(npm_config_cache)
  displayName: Cache npm

- script: npm ci
  displayName: 'npm ci'
  workingDirectory: $(clientApp)

- script: npm run build
  displayName: 'npm run build'
  workingDirectory: $(clientApp)

Both Cache npm and npm ci looks successful but looking at npm ci it is full of Invalid response body while trying to fetch errors.

Example:

npm WARN old lockfile FetchError: Invalid response body while trying to fetch https://registry.npmjs.org/resolve: ENOENT: no such file or directory, lstat 'D:\a\1.npm_cacache\content-v2\sha512\12\57\394f579cc50c27a51fafd47bc9b67bad8f0b3e6c37e5d7af10541cb3c48f62a57e1f58700f1e6a2789e73b52898a12e79b0e1760b8d943b09d2c546c09de' npm WARN old lockfile at C:\Program Files\nodejs\node_modules\npm\node_modules\minipass-fetch\lib\body.js:162:15 npm WARN old lockfile at async Array. (C:\Program Files\nodejs\node_modules\npm\node_modules\@npmcli\arborist\lib\arborist\build-ideal-tree.js:741:9) npm WARN old lockfile Could not fetch metadata for resolve@1.20.0 FetchError: Invalid response body while trying to fetch https://registry.npmjs.org/resolve: ENOENT: no such file or directory, lstat 'D:\a\1.npm_cacache\content-v2\sha512\12\57\394f579cc50c27a51fafd47bc9b67bad8f0b3e6c37e5d7af10541cb3c48f62a57e1f58700f1e6a2789e73b52898a12e79b0e1760b8d943b09d2c546c09de' npm WARN old lockfile at C:\Program Files\nodejs\node_modules\npm\node_modules\minipass-fetch\lib\body.js:162:15 npm WARN old lockfile at async Array. (C:\Program Files\nodejs\node_modules\npm\node_modules\@npmcli\arborist\lib\arborist\build-ideal-tree.js:741:9) { npm WARN old lockfile code: 'ENOENT', npm WARN old lockfile errno: 'ENOENT', npm WARN old lockfile syscall: 'lstat', npm WARN old lockfile path: 'D:\a\1\.npm\_cacache\content-v2\sha512\12\57\394f579cc50c27a51fafd47bc9b67bad8f0b3e6c37e5d7af10541cb3c48f62a57e1f58700f1e6a2789e73b52898a12e79b0e1760b8d943b09d2c546c09de', npm WARN old lockfile type: 'system' npm WARN old lockfile }

If I remove cache everything works normally. The code worked perfectly well up until 2021-11-30 but started to fail 2021-12-02. In the morning 2021-12-02 1/5 builds got through with cache but since then everything failed.

The actual error occurs in npm run build that simply says:

'react-scripts' is not recognized as an internal or external command, operable program or batch file.

[Ogglas]

Still present. Any update on this?

[ranouf]

Same here, any updates?

[Ogglas]

Tried it again and the same thing happens. Is anyone looking into this?

[stevenvolckaert]

We are experiencing this issue as well; it seems that the caching functionality does not work properly.

Is there any update on this issue?

[viktorsteinwand]

We have very similar pipeline setup. However if the files are cached, with the next build the cache hit is present:

Starting: Cache npm packages
==============================================================================
Task         : Cache
Description  : Cache files between runs
Version      : 2.198.0
Author       : Microsoft Corporation
Help         : https://aka.ms/pipeline-caching-docs
==============================================================================
Resolving key:
 - "npm"                                              [string]
 - "Windows_NT"                                       [string]
 - "partnerportal-v1"                                 [string]
 - D:\a\1\s/client-app/package-loc... [file] --> SOMEKEY
Resolved to: "npm"|"Windows_NT"|"app-v1"|somekey=
Using default max parallelism.
Max dedup parallelism: 192
Getting a pipeline cache artifact with one of the following fingerprints:
Fingerprint: `"npm"|"Windows_NT"|"app-v1"|somekey=`
There is a cache hit: `"npm"|"Windows_NT"|"app-v1"|somekey=`
...

7-Zip 21.07 (x64) : Copyright (c) 1999-2021 Igor Pavlov : 2021-12-26

Extracting archive: 
Expected size to be downloaded: 286.5 MB
Downloaded 0.0 MB out of 286.5 MB (0%).
Downloaded 19.2 MB out of 286.5 MB (7%).
Downloaded 21.0 MB out of 286.5 MB (7%).
Downloaded 63.1 MB out of 286.5 MB (22%).
Downloaded 190.6 MB out of 286.5 MB (67%).
Downloaded 286.5 MB out of 286.5 MB (100%).

Download statistics:
Total Content: 286.5 MB
Physical Content Downloaded: 256.2 MB
Compression Saved: 30.3 MB
Local Caching Saved: 0.0 MB
Chunks Downloaded: 3,568
Nodes Downloaded: 7

--
Path = 
Type = tar
Code Page = UTF-8
Characteristics = ASCII

Everything is Ok

Folders: 5430
Files: 6817
Size:       278214736
Compressed: 6271488
Process exit code: 0
Cache restored.
Finishing: Cache npm packages

If running npm ci later the tarballs seems to be corrupted:

Starting: Install packages
==============================================================================
Task         : Command line
Description  : Run a command line script using Bash on Linux and macOS and cmd.exe on Windows
Version      : 2.201.1
Author       : Microsoft Corporation
Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/command-line
==============================================================================
Generating script.
Script contents: shell
npm ci --prefer-offline
========================== Starting Command Output ===========================
"C:\Windows\system32\cmd.exe" /D /E:ON /V:OFF /S /C "CALL "D:\a\_temp\someguid.cmd""
npm WARN tarball tarball data for yup@https://registry.npmjs.org/yup/-/yup-0.32.11.tgz (sha512-Z2Fe1bn+eLstG8DRR6FTavGD+MeAwyfmouhHsIUgaADz8jvFKbO/fXc2trJKZg+5EBjh4gGm3iU/t3onKlXHIg==) seems to be corrupted. Trying again.
...

[peksipatongeis]

Having same issue with cached npm packages and npm ci

[github-actions[bot]]

This issue is stale because it has been open for 180 days with no activity. Remove the stale label or comment on the issue otherwise this will be closed in 5 days

[stevenvolckaert]

Any news on this issue?

[ksmigiel]

@johnterickson do you have some input/news here?

[ollie-airways]

Any updates here?

[github-actions[bot]]

This issue is stale because it has been open for 180 days with no activity. Remove the stale label or comment on the issue otherwise this will be closed in 5 days