turbo icon indicating copy to clipboard operation
turbo copied to clipboard
verified publisher icon vercel

Remote cache miss despite --dry-run=json reporting "remote": true

Open mike-hogan opened this issue 3 years ago • 4 comments

What version of Turborepo are you using?

1.5.6

What package manager are you using / does the bug impact?

pnpm

What operating system are you using?

Mac

Describe the Bug

Github actions reports a cache miss like this:

@docsndata/ops-team-backup:build: cache miss, executing d15aaa2304d06baf

Running npx turbo build --dry-run=json locally reports this:

{
      "taskId": "@docsndata/ops-team-backup#build",
      "task": "build",
      "package": "@docsndata/ops-team-backup",
      "hash": "d15aaa2304d06baf",
      "cacheState": {
        "local": false,
        "remote": true
      },
      "command": "tsc -p tsconfig.json \u0026\u0026 tsc -p tsconfig-cjs.json",
      "outputs": [
        ".svelte-kit/**",
        "dist/**",
        "package/**"
      ],
      "excludedOutputs": null,
      "logFile": "ops/team-backup/.turbo/turbo-build.log",
      "directory": "ops/team-backup",
      "dependencies": [
        "@docsndata/data-graphql#build",
        "@docsndata/ops-monitor#build",
        "@docsndata/data-graphql-for-tables#build",
        "@docsndata/model-team#build",
        "@docsndata/model-types#build",
        "@docsndata/data-backend-tables#build",
        "@docsndata/lang-util#build",
        "@docsndata/lang-lodash#build",
        "@docsndata/data-backend-test-schema#build",
        "@docsndata/model-core2#build",
        "@docsndata/testing-stub-graphql#build"
      ],
      "dependents": [
        "@docsndata/ops-cli#build",
        "@docsndata/ops-team-restore#build"
      ]
    }

My github actions yml file is:

name: CI


on:
  push:
    branches: ["master"]
  pull_request:
    types: [opened, synchronize]

jobs:
  build:
    name: Build and Test
    timeout-minutes: 30
    runs-on: ubuntu-latest
#    runs-on: self-hosted
#     To use Remote Caching, uncomment the next lines and follow the steps below.
    env:
     TURBO_TOKEN: ${{ secrets.TURBO_TOKEN }}
     TURBO_TEAM: ${{ secrets.TURBO_TEAM }}

    steps:
      - name: Check out code
        uses: actions/checkout@v3
        with:
          fetch-depth: 2

      - uses: pnpm/[email protected]
        with:
          version: 7
          run_install: false

      - name: Setup Node.js environment
        uses: actions/setup-node@v3
        with:
          node-version: 16
          cache: "pnpm"

      - name: Install dependencies
        run: pnpm install --frozen-lockfile

      - name: Running postinstall script
        run: ./scripts/postinstall.sh

      - name: Build
        run: npx turbo build

      - name: Test
        run: npx turbo test

My monorepo consists of 152 packages. Github actions always gets cache misses, but never the same ones. It made me wonder if maybe the remote cache server was failing http calls under load. But that is conjecture.

Running npx turbo build --remote-only locally reports a full cache hit.

Expected Behavior

I expected a cache hit for given hash

To Reproduce

I don't have a small reproduction of this problem. It varies each time I run the github action.

mike-hogan avatar Oct 16 '22 10:10 mike-hogan

I'm experience a similar issue. After building a monorepo locally and pushing it to Github, only one (count varies) out of the three triggered workflows will get a cache hit. The others will miss.

Example:

These three workflows ran simultaneously.

workflow 1 logs:

@self/utils:build: cache hit, replaying output b1f5b06bf4732195

workflow 2 logs:

@self/utils:build: cache miss, executing b1f5b06bf4732195

workflow 3 logs:

@self/utils:build: cache miss, executing b1f5b06bf4732195

thenbe avatar Oct 17 '22 03:10 thenbe

Out of curiosity what is the full output with log verbosity increased? (-vv)

sppatel avatar Oct 17 '22 17:10 sppatel

We are starting work soon on increasing the amount of information you get on cache misses!

mehulkar avatar Oct 18 '22 00:10 mehulkar

Out of curiosity what is the full output with log verbosity increased? (-vv)

@sppatel Here are the logs for the three workflows I mentioned (with -vvv flag). You want to search for b1f5b06bf4732195 in the logs. These ran at the same time (see timestamps), but only one had a cache hit, the other two missed.

Workflow 1


Run pnpm run build -vvv --filter @self/backend

> [email protected] build /home/runner/work/aqtech/aqtech
> turbo run build "-vvv" "--filter" "@self/backend"

2022-10-17T03:23:54.275Z [INFO]  turbo: skipping turbod since we appear to be in a non-interactive context
2022-10-17T03:23:54.277Z [DEBUG] turbo: global hash env vars: vars=["VERCEL_ANALYTICS_ID"]
2022-10-17T03:23:54.282Z [DEBUG] turbo: global hash: value=6b41293fc987019d
2022-10-17T03:23:54.282Z [DEBUG] turbo: local cache folder: path=""
• Packages in scope: @self/backend
2022-10-17T03:23:54.314Z [DEBUG] turbo.: start
2022-10-17T03:23:54.314Z [DEBUG] turbo: task hash: value=49a96ba4898bacd3
2022-10-17T03:23:54.314Z [DEBUG] turbo.: no task in package, skipping
2022-10-17T03:23:54.314Z [DEBUG] turbo.: done: status=skipped duration="197.002µs"
2022-10-17T03:23:54.314Z [DEBUG] turbo.: start
2022-10-17T03:23:54.314Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:54.314Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195?slug=***
• Running build in 1 packages
• Remote caching enabled
2022-10-17T03:23:54.319Z [DEBUG] turbo.: start
2022-10-17T03:23:54.319Z [DEBUG] turbo: task hash: value=7bde139d5f55f9cf
2022-10-17T03:23:54.319Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/7bde139d5f55f9cf?slug=***
2022-10-17T03:23:54.520Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
2022-10-17T03:23:54.937Z [DEBUG] turbo.: log file: path=/home/runner/work/aqtech/aqtech/packages/seed/.turbo/turbo-build.log
2022-10-17T03:23:54.937Z [DEBUG] turbo.: start replaying logs
2022-10-17T03:23:54.937Z [DEBUG] turbo.: finish replaying logs
@self/seed:build: cache hit, replaying output 7bde139d5f55f9cf
@self/seed:build: 
@self/seed:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/seed
@self/seed:build: > rm -rf dist && preconstruct build
@self/seed:build: 
@self/seed:build: 🎁 info building bundles!
@self/seed:build: 🎁 success built bundles!
2022-10-17T03:23:55.136Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
2022-10-17T03:23:55.187Z [DEBUG] turbo.: log file: path=/home/runner/work/aqtech/aqtech/packages/utils/.turbo/turbo-build.log
@self/utils:build: cache hit, replaying output b1f5b06bf4732195
@self/utils:build: 
@self/utils:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/utils
2022-10-17T03:23:55.187Z [DEBUG] turbo.: start replaying logs
@self/utils:build: > rm -rf dist && preconstruct build
@self/utils:build: 
@self/utils:build: 🎁 info building bundles!
@self/utils:build: 🎁 success built bundles!
2022-10-17T03:23:55.188Z [DEBUG] turbo.: finish replaying logs
2022-10-17T03:23:55.188Z [DEBUG] turbo.: start
2022-10-17T03:23:55.188Z [DEBUG] turbo: task hash: value=a108484fc4283541
2022-10-17T03:23:55.189Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/a108484fc4283541?slug=***
2022-10-17T03:23:55.389Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
2022-10-17T03:23:55.720Z [DEBUG] turbo.: log file: path=/home/runner/work/aqtech/aqtech/packages/backend/.turbo/turbo-build.log
@self/backend:build: cache hit, replaying output a108484fc4283541
2022-10-17T03:23:55.720Z [DEBUG] turbo.: start replaying logs
@self/backend:build: 
@self/backend:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/backend
2022-10-17T03:23:55.720Z [DEBUG] turbo.: finish replaying logs
@self/backend:build: > rimraf dist && nest build
@self/backend:build: 

 Tasks:    3 successful, 3 total
Cached:    3 cached, 3 total
  Time:    1.516s >>> FULL TURBO

2022-10-17T03:23:55.721Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***

Workflow 2


Run pnpm run build -vvv --filter @self/site

> [email protected] build /home/runner/work/aqtech/aqtech
> turbo run build "-vvv" "--filter" "@self/site"

2022-10-17T03:23:34.258Z [INFO]  turbo: skipping turbod since we appear to be in a non-interactive context
2022-10-17T03:23:34.258Z [DEBUG] turbo: global hash env vars: vars=["VERCEL_ANALYTICS_ID"]
2022-10-17T03:23:34.263Z [DEBUG] turbo: global hash: value=6b41293fc987019d
2022-10-17T03:23:34.263Z [DEBUG] turbo: local cache folder: path=""
• Packages in scope: @self/site
2022-10-17T03:23:34.292Z [DEBUG] turbo.: start
• Running build in 1 packages
2022-10-17T03:23:34.292Z [DEBUG] turbo: task hash: value=49a96ba4898bacd3
2022-10-17T03:23:34.292Z [DEBUG] turbo.: no task in package, skipping
2022-10-17T03:23:34.292Z [DEBUG] turbo.: done: status=skipped duration="114.703µs"
2022-10-17T03:23:34.292Z [DEBUG] turbo.: start
2022-10-17T03:23:34.292Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:34.292Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195?slug=***
• Remote caching enabled
2022-10-17T03:23:34.494Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/utils:build: cache miss, executing b1f5b06bf4732195
2022-10-17T03:23:34.927Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/utils:build: 
@self/utils:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/utils
@self/utils:build: > rm -rf dist && preconstruct build
@self/utils:build: 
@self/utils:build: 🎁 info building bundles!
@self/utils:build: 🎁 success built bundles!
2022-10-17T03:23:38.214Z [DEBUG] turbo.: caching output: outputs="{[packages/utils/.turbo/turbo-build.log packages/utils/.svelte-kit/** packages/utils/build/** packages/utils/dist/**] []}"
2022-10-17T03:23:38.214Z [DEBUG] turbo.: done: status=complete duration=3.921852533s
2022-10-17T03:23:38.214Z [DEBUG] turbo.: start
2022-10-17T03:23:38.214Z [DEBUG] turbo: task hash: value=deda93a7bec7666b
2022-10-17T03:23:38.214Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/deda93a7bec7666b?slug=***
2022-10-17T03:23:38.220Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195?slug=***
2022-10-17T03:23:38.416Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/site:build: cache miss, executing deda93a7bec7666b
2022-10-17T03:23:38.798Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/site:build: 
@self/site:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/site
@self/site:build: > rm -rf ./{.svelte-kit,build} && vite build && ./remove-slash.sh ./build
@self/site:build: 
Warning: e:build: ▲ [WARNING] Cannot find base config file "./.svelte-kit/tsconfig.json" [tsconfig.json]
@self/site:build: 
@self/site:build:     tsconfig.json:2:12:
@self/site:build:       2 │   "extends": "./.svelte-kit/tsconfig.json",
@self/site:build:         ╵              ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@self/site:build: 
@self/site:build: Not building for production.
@self/site:build: vite v3.1.8 building for production...
@self/site:build: transforming...

<REMOVED SOME LOGS HERE FOR VERBOSITY BUT INCLUDING THE TAIL END OF THE LOGS BELOW>

@self/site:build:   ✔ done
@self/site:build: Replacing string_decoder/ with string_decoder in the following files:
2022-10-17T03:24:36.134Z [DEBUG] turbo.: caching output: outputs="{[packages/site/.turbo/turbo-build.log packages/site/.svelte-kit/** packages/site/build/** packages/site/dist/**] []}"
2022-10-17T03:24:36.146Z [DEBUG] turbo.: done: status=complete duration=57.919456682s

 Tasks:    2 successful, 2 total
Cached:    0 cached, 2 total
  Time:    1m1.965s 

...writing to cache...
2022-10-17T03:24:38.096Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/deda93a7bec7666b?slug=***

Workflow 3


Run pnpm run build -vvv

> [email protected] build /home/runner/work/aqtech/aqtech
> turbo run build "-vvv"

2022-10-17T03:23:29.944Z [INFO]  turbo: skipping turbod since we appear to be in a non-interactive context
2022-10-17T03:23:29.944Z [DEBUG] turbo: global hash env vars: vars=["VERCEL_ANALYTICS_ID"]
2022-10-17T03:23:29.948Z [DEBUG] turbo: global hash: value=6b41293fc987019d
2022-10-17T03:23:29.948Z [DEBUG] turbo: local cache folder: path=""
• Packages in scope: @self/backend, @self/seed, @self/site, @self/test, @self/utils, eslint-config-custom
2022-10-17T03:23:29.992Z [DEBUG] turbo.: start
2022-10-17T03:23:29.992Z [DEBUG] turbo: task hash: value=49a96ba4898bacd3
2022-10-17T03:23:29.992Z [DEBUG] turbo.: no task in package, skipping
2022-10-17T03:23:29.992Z [DEBUG] turbo.: done: status=skipped duration="103.502µs"
• Running build in 6 packages
• Remote caching enabled
2022-10-17T03:23:29.992Z [DEBUG] turbo.: start
2022-10-17T03:23:29.992Z [DEBUG] turbo: task hash: value=7bde139d5f55f9cf
2022-10-17T03:23:29.992Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/7bde139d5f55f9cf?slug=***
2022-10-17T03:23:29.992Z [DEBUG] turbo.: start
2022-10-17T03:23:29.992Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:29.992Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195?slug=***
2022-10-17T03:23:30.193Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/utils:build: cache miss, executing b1f5b06bf4732195
@self/seed:build: cache miss, executing 7bde139d5f55f9cf
2022-10-17T03:23:30.715Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/utils:build: 
@self/utils:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/utils
@self/utils:build: > rm -rf dist && preconstruct build
@self/utils:build: 
@self/seed:build: 
@self/seed:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/seed
@self/seed:build: > rm -rf dist && preconstruct build
@self/seed:build: 
@self/utils:build: 🎁 info building bundles!
@self/seed:build: 🎁 info building bundles!
@self/utils:build: 🎁 success built bundles!
2022-10-17T03:23:35.665Z [DEBUG] turbo.: caching output: outputs="{[packages/utils/.turbo/turbo-build.log packages/utils/.svelte-kit/** packages/utils/build/** packages/utils/dist/**] []}"
2022-10-17T03:23:35.666Z [DEBUG] turbo.: done: status=complete duration=5.672835937s
2022-10-17T03:23:35.671Z [DEBUG] turbo.: start
2022-10-17T03:23:35.671Z [DEBUG] turbo: task hash: value=deda93a7bec7666b
2022-10-17T03:23:35.671Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/deda93a7bec7666b?slug=***
2022-10-17T03:23:35.675Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195?slug=***
@self/site:build: cache miss, executing deda93a7bec7666b
2022-10-17T03:23:35.981Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/site:build: 
@self/site:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/site
@self/site:build: > rm -rf ./{.svelte-kit,build} && vite build && ./remove-slash.sh ./build
@self/site:build: 
Warning: e:build: ▲ [WARNING] Cannot find base config file "./.svelte-kit/tsconfig.json" [tsconfig.json]
@self/site:build: 
@self/site:build:     tsconfig.json:2:12:
@self/site:build:       2 │   "extends": "./.svelte-kit/tsconfig.json",
@self/site:build:         ╵              ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@self/site:build: 
@self/seed:build: 🎁 success built bundles!
2022-10-17T03:23:37.497Z [DEBUG] turbo.: caching output: outputs="{[packages/seed/.turbo/turbo-build.log packages/seed/.svelte-kit/** packages/seed/build/** packages/seed/dist/**] []}"
2022-10-17T03:23:37.497Z [DEBUG] turbo.: done: status=complete duration=7.505388014s
2022-10-17T03:23:37.498Z [DEBUG] turbo.: start
2022-10-17T03:23:37.498Z [DEBUG] turbo: task hash: value=a108484fc4283541
2022-10-17T03:23:37.498Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/a108484fc4283541?slug=***
2022-10-17T03:23:37.498Z [DEBUG] turbo.: start
2022-10-17T03:23:37.498Z [DEBUG] turbo: task hash: value=f3d4ab8ade76317e
2022-10-17T03:23:37.498Z [DEBUG] turbo.: no task in package, skipping
2022-10-17T03:23:37.498Z [DEBUG] turbo.: done: status=skipped duration="69µs"
2022-10-17T03:23:37.513Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/7bde139d5f55f9cf?slug=***
@self/site:build: Not building for production.
2022-10-17T03:23:37.699Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/backend:build: cache miss, executing a108484fc4283541
@self/site:build: vite v3.1.8 building for production...
@self/site:build: transforming...
2022-10-17T03:23:38.012Z [DEBUG] turbo: performing request: method=POST url=https://vercel.com/api/v8/artifacts/events?slug=***
@self/backend:build: 
@self/backend:build: > @self/[email protected] build /home/runner/work/aqtech/aqtech/packages/backend
@self/backend:build: > rimraf dist && nest build


<REMOVED SOME LOGS HERE FOR VERBOSITY BUT INCLUDING THE TAIL END OF THE LOGS BELOW>


@self/site:build:   ✔ done
@self/site:build: Replacing string_decoder/ with string_decoder in the following files:
2022-10-17T03:24:38.704Z [DEBUG] turbo.: caching output: outputs="{[packages/site/.turbo/turbo-build.log packages/site/.svelte-kit/** packages/site/build/** packages/site/dist/**] []}"
2022-10-17T03:24:38.717Z [DEBUG] turbo.: done: status=complete duration=1m3.033407057s

 Tasks:    4 successful, 4 total
Cached:    0 cached, 4 total
  Time:    1m8.841s 

...writing to cache...
2022-10-17T03:24:40.685Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/deda93a7bec7666b?slug=***

thenbe avatar Oct 18 '22 13:10 thenbe

@ambiguous48 I've sorted your workflows by time which makes it super-clear what happened in your case, and is not indicative of a bug:

2022-10-17T03:23:29.992Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:29.992Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195
@self/utils:build: cache miss, executing b1f5b06bf4732195
2022-10-17T03:23:35.675Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195

2022-10-17T03:23:34.292Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:34.292Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195
@self/utils:build: cache miss, executing b1f5b06bf4732195
2022-10-17T03:23:38.220Z [DEBUG] turbo: performing request: method=PUT url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195

2022-10-17T03:23:54.314Z [DEBUG] turbo: task hash: value=b1f5b06bf4732195
2022-10-17T03:23:54.314Z [DEBUG] turbo: performing request: method=GET url=https://vercel.com/api/v8/artifacts/b1f5b06bf4732195
@self/utils:build: cache hit, replaying output b1f5b06bf4732195

I'm going to collapse your comments as they're unrelated to the initial report from @mike-hogan. Thank you for providing enough information for us to investigate and fully rule out any issues.

nathanhammond avatar Nov 30 '22 09:11 nathanhammond

@mike-hogan Since we dynamically update the state of the cache during the run for this to indicate an error we would need:

  • attestation that you have precisely one workflow running at a time.
  • a --dry=json run in the same GitHub Actions workflow prior to running turbo run build.
  • -vvv on the turbo run build.
  • The command you're running for turbo, and any TURBO_ env vars.
  • the hash in question
  • the dry run showing { cacheState: { remote: true } } and the actual run showing cache miss, executing ....

If you get me this information within 48 hours of encountering something weird we can take a look and identify if the behavior is expected.

For the interim: I'm going to close this issue because in searching our server logs I don't see the GET/HEAD 200 then PUT for any assets.

If anybody other than @mike-hogan encounters this: open a new issue with the same information that I asked @mike-hogan for! Ping me on Discord or Twitter so that I can get to our server logs within 48 hours.

nathanhammond avatar Nov 30 '22 10:11 nathanhammond