Ruby Bundler Cache not found for input keys

[ahaverty]

Following the recommended setup for ruby bundler, the error "Cache not found for input keys" is always given, despite it saving correctly. I have tested multiple times with back to back runs, ensuring the previous run's keys are matching, and that Gemfile.lock is not changing. Is there anything else I can use to debug?

name: 'Rspec'
on: [pull_request]
jobs:
  test:
    runs-on: ubuntu-latest
    services:
      db:
        image: postgres:11
        ports: ['5432:5432']
        options: >-
          --health-cmd pg_isready
          --health-interval 10s
          --health-timeout 5s
          --health-retries 5
      redis:
        image: redis
        ports: ['6379:6379']
        options: --entrypoint redis-server
    steps:
      - uses: actions/checkout@v1
      - name: Setup Ruby
        uses: actions/setup-ruby@v1
        with:
          ruby-version: 2.5.7
      - uses: actions/cache@v1
        with:
          path: vendor/bundle
          key: ${{ runner.os }}-gem-${{ hashFiles('**/Gemfile.lock') }}
          restore-keys: |
            ${{ runner.os }}-gem-
      - uses: borales/actions-yarn@v2.0.0
        with:
          cmd: install
      - name: Install Bundler
        run: |
          gem install bundler
      - name: Install libpq-dev
        run: |
          sudo apt-get install libpq-dev
      - name: Install Dependencies
        run: |
          bundle config path vendor/bundle
          bundle install --jobs 4 --retry 3
      - name: Prepare DB and run tests
        run: |
          bundle exec rails db:prepare
          bundle exec rspec

[ahaverty]

I've just tested with v1.10 and I'm still getting the exact same output/logs.

[Neyaz]

I have the same problem.

[ahaverty]

@Neyaz well we may be in luck! I think I found the problem. I turned on debug logging, and I can see the hash is different in the post-process step. It looks like it's picking up a load of Gem lock files from the vendor folder, therefore saving it to a different hash. I'm going to remove the ** wildcard and see what happens. I'll report back soon 👍

Here's the output with action debug logs:

##[debug]=> 'Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd'
##[debug]Result: 'Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd'
##[debug]Evaluating: format('{0}-gem-
##[debug]', runner.os)
##[debug]Evaluating format:
##[debug]..Evaluating String:
##[debug]..=> '{0}-gem-
##[debug]'
##[debug]..Evaluating Index:
##[debug]....Evaluating runner:
##[debug]....=> Object
##[debug]....Evaluating String:
##[debug]....=> 'os'
##[debug]..=> 'Linux'
##[debug]=> 'Linux-gem-
##[debug]'
##[debug]Result: 'Linux-gem-
##[debug]'
##[debug]Loading env
Run actions/cache@v1.1.0
##[debug]Cache Path: /home/runner/work/twinlite-web/twinlite-web/vendor/bundle
::save-state name=CACHE_KEY,::Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd
##[debug]Save intra-action state CACHE_KEY = Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd
##[debug]Resolved Keys:
##[debug]["Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd","Linux-gem-"]
##[debug]Cache Url: https://artifactcache.actions.githubusercontent.com/3GL0GY4gZLRCyhtLz6RGJxsahKQk2JaVDvuSIfE0recce15dzP/
Cache not found for input keys: Linux-gem-13dae1767568a2ec2763df7761ad7c9fde2ed4f2d400231ad04eec596a0787bd, Linux-gem-.
##[debug]Finishing: Run actions/cache@v1.1.0

2020-01-22T15:30:25.1645750Z ##[debug]Evaluating condition for step: 'Post actions/cache@v1.1.0'
2020-01-22T15:30:25.1647657Z ##[debug]Parsing expression: <success()>
2020-01-22T15:30:25.1649525Z ##[debug]Evaluating: success()
2020-01-22T15:30:25.1649883Z ##[debug]Evaluating success:
2020-01-22T15:30:25.1651324Z ##[debug]=> true
2020-01-22T15:30:25.1651811Z ##[debug]Result: true
2020-01-22T15:30:25.1652357Z ##[debug]Starting: Post actions/cache@v1.1.0
2020-01-22T15:30:25.1709126Z ##[debug]Loading inputs
2020-01-22T15:30:25.1747097Z ##[debug]Evaluating: format('{0}-gem-{1}', runner.os, hashFiles('**/Gemfile.lock'))
2020-01-22T15:30:25.1747331Z ##[debug]Evaluating format:
2020-01-22T15:30:25.1747491Z ##[debug]..Evaluating String:
2020-01-22T15:30:25.1747655Z ##[debug]..=> '{0}-gem-{1}'
2020-01-22T15:30:25.1748326Z ##[debug]..Evaluating Index:
2020-01-22T15:30:25.1748482Z ##[debug]....Evaluating runner:
2020-01-22T15:30:25.1748655Z ##[debug]....=> Object
2020-01-22T15:30:25.1748901Z ##[debug]....Evaluating String:
2020-01-22T15:30:25.1749039Z ##[debug]....=> 'os'
2020-01-22T15:30:25.1749282Z ##[debug]..=> 'Linux'
2020-01-22T15:30:25.1749459Z ##[debug]..Evaluating hashFiles:
2020-01-22T15:30:25.1749632Z ##[debug]....Evaluating String:
2020-01-22T15:30:25.1749769Z ##[debug]....=> '**/Gemfile.lock'
2020-01-22T15:30:25.1749978Z ##[debug]Search root directory: '/home/runner/work/twinlite-web/twinlite-web'
2020-01-22T15:30:25.1750143Z ##[debug]Search pattern: '/home/runner/work/twinlite-web/twinlite-web/**/Gemfile.lock'
2020-01-22T15:30:25.3771596Z ##[debug]Found 33426 files
2020-01-22T15:30:25.9498568Z ##[debug]7 matches to hash
2020-01-22T15:30:25.9499222Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/Gemfile.lock
2020-01-22T15:30:25.9501871Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/bcrypt-3.1.13/Gemfile.lock
2020-01-22T15:30:25.9509304Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/database_cleaner-1.7.0/Gemfile.lock
2020-01-22T15:30:25.9516673Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/rack-proxy-0.6.5/Gemfile.lock
2020-01-22T15:30:25.9518031Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/sidekiq-6.0.0/Gemfile.lock
2020-01-22T15:30:25.9519232Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/warden-1.2.8/Gemfile.lock
2020-01-22T15:30:25.9520196Z ##[debug]Hash /home/runner/work/twinlite-web/twinlite-web/vendor/bundle/ruby/2.5.0/gems/webpacker-4.2.0/Gemfile.lock
2020-01-22T15:30:25.9522407Z ##[debug]Final hash result: '6232b2bb1e1c325e89f5688a99018b67a5fbef3588d7159079819c92a60ec1b0'
2020-01-22T15:30:25.9522824Z ##[debug]..=> '6232b2bb1e1c325e89f5688a99018b67a5fbef3588d7159079819c92a60ec1b0'
2020-01-22T15:30:25.9523281Z ##[debug]=> 'Linux-gem-6232b2bb1e1c325e89f5688a99018b67a5fbef3588d7159079819c92a60ec1b0'
2020-01-22T15:30:25.9523586Z ##[debug]Result: 'Linux-gem-6232b2bb1e1c325e89f5688a99018b67a5fbef3588d7159079819c92a60ec1b0'
2020-01-22T15:30:25.9526698Z ##[debug]Evaluating: format('{0}-gem-
2020-01-22T15:30:25.9526842Z ##[debug]', runner.os)
2020-01-22T15:30:25.9527497Z ##[debug]Evaluating format:
2020-01-22T15:30:25.9527718Z ##[debug]..Evaluating String:
2020-01-22T15:30:25.9528051Z ##[debug]..=> '{0}-gem-
2020-01-22T15:30:25.9528161Z ##[debug]'
2020-01-22T15:30:25.9528802Z ##[debug]..Evaluating Index:
2020-01-22T15:30:25.9528979Z ##[debug]....Evaluating runner:
2020-01-22T15:30:25.9529573Z ##[debug]....=> Object
2020-01-22T15:30:25.9530172Z ##[debug]....Evaluating String:
2020-01-22T15:30:25.9531222Z ##[debug]....=> 'os'
2020-01-22T15:30:25.9532445Z ##[debug]..=> 'Linux'
2020-01-22T15:30:25.9532846Z ##[debug]=> 'Linux-gem-
2020-01-22T15:30:25.9532952Z ##[debug]'
2020-01-22T15:30:25.9533164Z ##[debug]Result: 'Linux-gem-
2020-01-22T15:30:25.9533274Z ##[debug]'

[dhadka]

This may not be the same cause, but we have seen this behavior before when the cache is created using a different ref (e.g., tag or branch) each time but was never created on the master branch, so it appears as if the cache doesn't exist and is created each time (see for example https://github.com/actions/cache/issues/149).

One thing you can do is enable debug logging and check the scope. If the scope is different each time, then the caches won't be shared. If you send me the org and repo name, I can also check this.

[ahaverty]

Thanks @dhadka , I think I've found an obvious flaw with the way the hashing matches now that I have the debug logs. I've a feeling changing the gemfile.lock match to the following will give the same key for pre and post:

- uses: actions/cache@v1.1.0
        with:
          path: vendor/bundle
          key: ${{ runner.os }}-gem-${{ hashFiles('Gemfile.lock') }}
          restore-keys: |
            ${{ runner.os }}-gem-

It just takes 10 minutes for each of my runs at the moment, and I'll need to do two runs to test if caching works, so I should have an answer in the next 30 mins 👍

[ahaverty]

@dhadka ok, it looks like I've solved the inconsistent pre/post key issue by removing the wildcard asterix from 'Gemfile.lock'. However, I'm also running this on my develop branch, and the cache is still not being found, which matches the conversation in https://github.com/actions/cache/issues/149

I'm confused about how caching should work based on https://github.com/actions/cache/issues/149#issuecomment-573933774 If I continuously branch off of my develop branch, let's say feature/new-blog, and PR back into develop, will my feature/new-blog job use the cache from the last PR into develop? (My rspec jobs only run with: on: [pull_request]) Or is it literally a case of it needing to be created by the default branch, i.e master? If there's any documentation on the logic of how that works, I'd love to read.

Could I also suggest that this action log's out the keys it's saving the cache under by default (so I can turn off these action debug logs), and maybe updating the readme with an example of the Gemfile.lock without the wildcards or a warning about vendor/bundle potentially containing a lot of lock files after a bundle install.

[dhadka]

In the example you gave, for a pull request, it should give read-write permissions to the feature branch (in this case it's the pull ref, such as refs/pull/180/merge), read-only permission to the develop branch, and read-only permission to the default branch (typically master).

I'm only seeing records in the cache for the pull refs (refs/pull/179/merge, refs/pull/180/merge, ...). As such, they aren't shared. Can you please check if you have any actions getting triggered from the develop branch? If I had to guess, you probably need to also trigger the action on the push event.

I don't think we have any detailed public docs on how the scoping works. The overall mechanism is discussed on the cache docs page (search for "scope"). Edit: Also see the restrictions for accessing a cache section.

[ahaverty]

@dhadka thanks for the help. I'm not sure I understand the scopes entirely, but after fixing the Gemfile lock matching issue, and merging a PR with an action with caching, it's now caching for my other PR actions. I'll close this issue, but I have a feeling I won't be the last person with the Gemfile.lock matching issue 😅

[pke]

Thought I ran into the same problem here. bundle install ran every time and the cache was not used. But my problem was not the globbing, which I also changed from **/Gemfile.lock to Gemfile.lock. But the problem was that the action never completed (due to failing tests) and therefore the cache was not saved (in a post step)

Would it be possible to save the cache before post like via trigger after bundle install?

My action file contains:

- name: Set up bundler
    uses: actions/cache@v2
    with:
    path: vendor/bundle
    key: ${{ runner.os }}-gems-${{ hashFiles('Gemfile.lock') }}
    restore-keys: |
        ${{ runner.os }}-gems-

- name: Install Ruby dependencies
    run: |
    sudo apt-get install libpq-dev
    bundle config path vendor/bundle
    bundle install --jobs 4 --retry 3