Cache: Very long execution of post action/cache@v1

[Komar0ff]

Problem

The average step time is about 4-6 hours🤕
Unfortunately, the reason why the step is being performed for so long is not clear. Logs do not open

Workflow:

...
steps:
  - uses: actions/checkout@v1
  - uses: actions/setup-node@v1
       with:
         node-version: '12.x'
  - uses: actions/cache@v1
      with:
        path: node_modules
        key: node-${{ hashFiles('**/package-lock.json') }}
  - name: Setup npm
    run: echo "//registry.npmjs.org/:_authToken=${{ secrets.NPM_AUTH_TOKEN }}" > ~/.npmrc
  - name: Bootstrap
    run: npm i
...

Any idea what might have gone wrong?

[joshmgross]

Hey @Komar0ff, sorry you're hitting this. We had some service issues the past couple of days, and it's possible that your run was affected by this.

Do you repeatedly see this issue? If so, could you link me to an example run?

[nklayman]

I only get this issue on Windows, it works fine on Ubuntu. Here is a pr with runs that take many hours: https://github.com/nklayman/vue-cli-plugin-electron-builder/pull/552, and a specific example.

[joshmgross]

@nklayman Could you turn on debug logging and see if you can get another repro?

[IchHabRecht]

It seems, I'm having the same issue for one of my repositories https://github.com/IchHabRecht/content_defender/commit/319e623fab7087e70e13474c120d38bd8c9d8d5e/checks?check_suite_id=362349005

I turned on all debug information. Maybe anyone can help me to find the problem.

[TingluoHuang]

@IchHabRecht I forked your repo and i noticed it's hang during key: ${{ runner.os }}-composer-${{ hashFiles('**/composer.json') }}, everything start working when i remove the hashFiles part. I am continue debug try to figure out what's wrong with hashfiles

[IchHabRecht]

@TingluoHuang thanks for your work and information. Please let me know if I can do anything to find the problem.

[TingluoHuang]

@IchHabRecht looks like your functional tests are creating symlink loop which cause the runner stuck on find all files to hash

/home/runner/work/content_defender/content_defender/.Build/public/typo3conf/ext/content_defender ->/home/runner/work/content_defender/content_defender

/home/runner/work/content_defender/content_defender/.Build/public/typo3temp/var/tests/functional-1d3fcff/typo3conf/ext/content_defender -> /home/runner/work/content_defender/content_defender

/home/runner/work/content_defender/content_defender/.Build/public/typo3temp/var/tests/functional-278ffc0/typo3conf/ext/content_defender -> /home/runner/work/content_defender/content_defender

/home/runner/work/content_defender/content_defender/.Build/public/typo3temp/var/tests/functional-440e983/typo3conf/ext/content_defender -> /home/runner/work/content_defender/content_defender

/home/runner/work/content_defender/content_defender/.Build/public/typo3temp/var/tests/functional-529ffc0/typo3conf/ext/content_defender  -> /home/runner/work/content_defender/content_defender

/home/runner/work/content_defender/content_defender/.Build/public/typo3temp/var/tests/functional-73aca13/typo3conf/ext/content_defender -> /home/runner/work/content_defender/content_defender

I will file issue and fix the runner to handle the loop gracefully, to mitigate, you might want to fix it by stop creating symlink look in your functional test.

[IchHabRecht]

Hi @TingluoHuang,

Thank you for your feedback. Unfortunately creating the symlink is how functional testing for/with TYPO3 works currently. There is no chance to mitigate that. But I'm a bit surprised that the .Build folder is included in any file search as only the composer cache folder should be cached?! Not sure how things work in the runner but shouldn't only the cache target be included in any hash generation? Is there any way to simple exclude the whole .Build folder from the runner handling?

[TingluoHuang]

@IchHabRecht
in your yaml file:

- name: Cache composer dependencies
  uses: actions/cache@v1
  with:
    path: ${{ steps.composer-cache.outputs.dir }}
    key: ${{ runner.os }}-composer-${{ hashFiles('**/composer.json') }}
    restore-keys: ${{ runner.os }}-composer-

You set key to ${{ runner.os }}-composer-${{ hashFiles('**/composer.json') }}, which will make the runner find all files under GitHub.Workspace that match **/composer.json and hash them. the cache target are not included in the hash generation.

We don't support exclusion right now.

If you want the cache key by the composer.json under your repository root, maybe you can do
key: ${{ runner.os }}-composer-${{ hashFiles('composer.json') }} to avoid the file search

[IchHabRecht]

@TingluoHuang thank you so much for your help. I just took this caching script from another action example but didn't realize the composer.json is taken from folders recursively. Changing the path does indeed help to solve my problem.

[JLHwung]

Removing the glob star in the hashFiles argument does not help in my case: https://github.com/JLHwung/babel/commit/a6b48655ca1180dc27eeb6afbd11537428c53aef, where the cache post action time has outweighed CI execution.

[nklayman]

I have the same issue as @JLHwung, removing the **/ does not help: https://github.com/nklayman/vue-cli-plugin-electron-builder/runs/306446668

[TingluoHuang]

This problem are mostly caused by the symlink loop under node_modules, we are working on change the hashFiles() function to handle symlink

https://github.com/actions/runner/issues/234

[nklayman]

My repo does have a symlink to itself in node modules.

[cyangOL]

This problem happens randomly with our testing flows.

[joshmgross]

👋 hashFiles has been fixed on the runner to correctly handle symlink loops (see https://github.com/actions/runner/issues/234).

Can someone confirm that this issue is resolved?

[nklayman]

Yep, looks like it works now: https://github.com/nklayman/vue-cli-plugin-electron-builder/runs/560861885?check_suite_focus=true. Thanks for the fix!

[jagregory]

Looking good so far. 5 hours down to 25 seconds 😍

I'll run a few more builds through it today, but it's looking great right now. Thanks everyone.