mikehardy/buildcache-action

Error in post job cleanup

casconed opened this issue · 10 comments

Using this action with

- name: Use build cache
  uses: mikehardy/buildcache-action@v1

I get the following error in the post-job cleanup:

Post job cleanup.
(node:1069) UnhandledPromiseRejectionWarning: Error: Unable to locate executable file: buildcache. Please verify either the file path exists or the file can be found within a directory specified by the PATH environment variable. Also check the file mode to verify the file is executable.
    at Object.<anonymous> (/Users/runner/work/_actions/mikehardy/buildcache-action/v1/dist/webpack:/buildcache-action/node_modules/@actions/io/lib/io.js:187:1)
    at Generator.next (<anonymous>)
    at fulfilled (/Users/runner/work/_actions/mikehardy/buildcache-action/v1/dist/webpack:/buildcache-action/node_modules/@actions/io/lib/io.js:5:1)
(node:1069) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:1069) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Subsequent runs have a cache status with zeros across the board:

Cache status:
  Entries in cache:  0
  Cache size:        0 bytes (0.0%)
  Direct hits:       0
  Direct misses:     0
  Local hits:        0
  Local misses:      0
  Remote hits:       0
  Remote misses:     0
  Misses:            0
  Direct hit ratio:  0.0%
  Local hit ratio:   0.0%
  Remote hit ratio:  0.0%
  Hit ratio:         0.0%

Here are the full logs from the first step:

Run mikehardy/buildcache-action@v1
  with:
    access_token: ***
    install_dir: /Users/runner/work/***/***
    upload_buildcache_log: false
    zero_buildcache_stats: true
  env:
    CI: true
    FIREBASE_TOKEN: ***
    MY_KEYCHAIN: tmp-keychain
buildcache: release file based on runner os is buildcache-macos.zip
buildcache: installing from https://github.com/mbitsnbites/buildcache/releases/download/v0.27.1/buildcache-macos.zip
buildcache: download path /Users/runner/work/_temp/9b149fea-5053-46ef-abe1-a5b18d373e01
/usr/bin/unzip -q /Users/runner/work/_temp/9b149fea-5053-46ef-abe1-a5b18d373e01
buildcache: unpacked folder /Users/runner/work/***/***
/bin/ln -s /Users/runner/work/***/***/buildcache/bin/buildcache /Users/runner/work/***/***/buildcache/bin/clang
/bin/ln -s /Users/runner/work/***/***/buildcache/bin/buildcache /Users/runner/work/***/***/buildcache/bin/clang++
buildcache: no cache for key buildcache-2021-10-02T05:29:57.900Z or buildcache - cold cache or invalid key
/Users/runner/work/***/***/buildcache/bin/buildcache -c
Configuration file: /Users/runner/work/***/***/.buildcache/config.json

  BUILDCACHE_ACCURACY:               DEFAULT
  BUILDCACHE_CACHE_LINK_COMMANDS:    false
  BUILDCACHE_COMPRESS:               true
  BUILDCACHE_COMPRESS_FORMAT:        DEFAULT
  BUILDCACHE_COMPRESS_LEVEL:         -1
  BUILDCACHE_DEBUG:                  2
  BUILDCACHE_DIR:                    /Users/runner/work/***/***/.buildcache
  BUILDCACHE_DIRECT_MODE:            false
  BUILDCACHE_DISABLE:                false
  BUILDCACHE_HARD_LINKS:             false
  BUILDCACHE_HASH_EXTRA_FILES:       
  BUILDCACHE_IMPERSONATE:            
  BUILDCACHE_LOG_FILE:               /Users/runner/work/***/***/.buildcache/buildcache.log
  BUILDCACHE_LUA_PATH:               /Users/runner/work/***/***/.buildcache/lua
  BUILDCACHE_MAX_CACHE_SIZE:         500000000 (476.8 MiB)
  BUILDCACHE_MAX_LOCAL_ENTRY_SIZE:   134217728 (128.0 MiB)
  BUILDCACHE_MAX_REMOTE_ENTRY_SIZE:  134217728 (128.0 MiB)
  BUILDCACHE_PERF:                   false
  BUILDCACHE_PREFIX:                 
  BUILDCACHE_READ_ONLY:              false
  BUILDCACHE_READ_ONLY_REMOTE:       false
  BUILDCACHE_REMOTE:                 
  BUILDCACHE_REMOTE_LOCKS:           false
  BUILDCACHE_S3_ACCESS:              
  BUILDCACHE_S3_SECRET:              
  BUILDCACHE_TERMINATE_ON_MISS:      false
/Users/runner/work/***/***/buildcache/bin/buildcache -s
Cache status:
  Entries in cache:  0
  Cache size:        0 bytes (0.0%)
  Direct hits:       0
  Direct misses:     0
  Local hits:        0
  Local misses:      0
  Remote hits:       0
  Remote misses:     0
  Misses:            0
  Direct hit ratio:  0.0%
  Local hit ratio:   0.0%
  Remote hit ratio:  0.0%
  Hit ratio:         0.0%
buildcache: zeroing stats - stats display in cleanup task will be for this run only.
/Users/runner/work/***/***/buildcache/bin/buildcache -z

Strange - the only time the buildcache program itself is called in save.ts (the cleanup file), it is inside printStats, where there is an exec call:

async function execBuildCacheWithoutImpersonation(arg: string): Promise<void> {
const env = { ...process.env } as exec.ExecOptions['env']
delete env?.BUILDCACHE_IMPERSONATE
await exec.exec('buildcache', [arg], { env })
}
export async function printConfig(): Promise<void> {
await execBuildCacheWithoutImpersonation('-c')
}
export async function printStats(): Promise<void> {
await execBuildCacheWithoutImpersonation('-s')
}

...but every buildcache call in the whole action funnels through that exec call, and if it works at the start, why wouldn't it work at the end? 🤔

Perhaps there is something wiping out part of the repo's filespace in your build?

You could try setting "install_dir" and putting buildcache someplace else maybe?

export async function getInstallDir(): Promise<string> {
let installDir = core.getInput('install_dir')
if (!installDir || installDir === '') {
installDir = getEnvVar('GITHUB_WORKSPACE', '')
}
if (!installDir || installDir === '') {
throw new Error('install_dir not specified or empty')
}
await io.mkdirP(installDir)
return installDir
}

then when it is installed in this function (which adds the installed location to the whole workflow's path) it will still be there

export async function install(sourcePath: string): Promise<void> {

Very odd. I'm doing another run with the debugging cranked up to 3 and upload_builcache_log set to true to see if that sheds any light on things.

I'm noticing that I have this setup to run before I checkout my repo, so the post-job buildcache step happens AFTER the Post Checkout repository step - I wonder if something in that step is removing files? It doesn't look like it:

Post job cleanup.
/usr/local/bin/git version
git version 2.33.0
/usr/local/bin/git config --local --name-only --get-regexp core\.sshCommand
/usr/local/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :
/usr/local/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
http.https://github.com/.extraheader
/usr/local/bin/git config --local --unset-all http.https://github.com/.extraheader
/usr/local/bin/git submodule foreach --recursive git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :

Pre-job log:

2021-10-02T15:11:18.3819260Z ##[group]Run mikehardy/buildcache-action@v1
2021-10-02T15:11:18.3820050Z with:
2021-10-02T15:11:18.3821010Z   access_token: ***
2021-10-02T15:11:18.3821980Z   install_dir: /Users/runner/work/***/***
2021-10-02T15:11:18.3822630Z   upload_buildcache_log: false
2021-10-02T15:11:18.3823230Z   zero_buildcache_stats: true
2021-10-02T15:11:18.3823920Z env:
2021-10-02T15:11:18.3824340Z   CI: true
2021-10-02T15:11:18.3826810Z   FIREBASE_TOKEN: ***
2021-10-02T15:11:18.3827410Z   MY_KEYCHAIN: tmp-keychain
2021-10-02T15:11:18.3827960Z ##[endgroup]
2021-10-02T15:11:19.5010650Z buildcache: release file based on runner os is buildcache-macos.zip
2021-10-02T15:11:19.7997700Z buildcache: installing from https://github.com/mbitsnbites/buildcache/releases/download/v0.27.1/buildcache-macos.zip
2021-10-02T15:11:20.1694570Z buildcache: download path /Users/runner/work/_temp/c503a513-cdfc-4eb8-b888-3f8e81b85dce
2021-10-02T15:11:20.1764980Z [command]/usr/bin/unzip -q /Users/runner/work/_temp/c503a513-cdfc-4eb8-b888-3f8e81b85dce
2021-10-02T15:11:20.6761410Z buildcache: unpacked folder /Users/runner/work/***/***
2021-10-02T15:11:20.7607890Z [command]/bin/ln -s /Users/runner/work/***/***/buildcache/bin/buildcache /Users/runner/work/***/***/buildcache/bin/clang
2021-10-02T15:11:20.7728170Z [command]/bin/ln -s /Users/runner/work/***/***/buildcache/bin/buildcache /Users/runner/work/***/***/buildcache/bin/clang++
2021-10-02T15:11:21.9761470Z buildcache: no cache for key buildcache-2021-10-02T15:11:21.133Z or buildcache - cold cache or invalid key
2021-10-02T15:11:21.9796920Z [command]/Users/runner/work/***/***/buildcache/bin/buildcache -c
2021-10-02T15:11:22.1214000Z Configuration file: /Users/runner/work/***/***/.buildcache/config.json
2021-10-02T15:11:22.1214780Z 
2021-10-02T15:11:22.1215370Z   BUILDCACHE_ACCURACY:               DEFAULT
2021-10-02T15:11:22.1216100Z   BUILDCACHE_CACHE_LINK_COMMANDS:    false
2021-10-02T15:11:22.1216850Z   BUILDCACHE_COMPRESS:               true
2021-10-02T15:11:22.1217550Z   BUILDCACHE_COMPRESS_FORMAT:        DEFAULT
2021-10-02T15:11:22.1218980Z   BUILDCACHE_COMPRESS_LEVEL:         -1
2021-10-02T15:11:22.1219630Z   BUILDCACHE_DEBUG:                  2
2021-10-02T15:11:22.1220670Z   BUILDCACHE_DIR:                    /Users/runner/work/***/***/.buildcache
2021-10-02T15:11:22.1221410Z   BUILDCACHE_DIRECT_MODE:            false
2021-10-02T15:11:22.1222050Z   BUILDCACHE_DISABLE:                false
2021-10-02T15:11:22.1222650Z   BUILDCACHE_HARD_LINKS:             false
2021-10-02T15:11:22.1223810Z   BUILDCACHE_HASH_EXTRA_FILES:       
2021-10-02T15:11:22.1224430Z   BUILDCACHE_IMPERSONATE:            
2021-10-02T15:11:22.1225530Z   BUILDCACHE_LOG_FILE:               /Users/runner/work/***/***/.buildcache/buildcache.log
2021-10-02T15:11:22.1226710Z   BUILDCACHE_LUA_PATH:               /Users/runner/work/***/***/.buildcache/lua
2021-10-02T15:11:22.1227480Z   BUILDCACHE_MAX_CACHE_SIZE:         500000000 (476.8 MiB)
2021-10-02T15:11:22.1228170Z   BUILDCACHE_MAX_LOCAL_ENTRY_SIZE:   134217728 (128.0 MiB)
2021-10-02T15:11:22.1228860Z   BUILDCACHE_MAX_REMOTE_ENTRY_SIZE:  134217728 (128.0 MiB)
2021-10-02T15:11:22.1229510Z   BUILDCACHE_PERF:                   false
2021-10-02T15:11:22.1230080Z   BUILDCACHE_PREFIX:                 
2021-10-02T15:11:22.1230920Z   BUILDCACHE_READ_ONLY:              false
2021-10-02T15:11:22.1231550Z   BUILDCACHE_READ_ONLY_REMOTE:       false
2021-10-02T15:11:22.1232180Z   BUILDCACHE_REMOTE:                 
2021-10-02T15:11:22.1232760Z   BUILDCACHE_REMOTE_LOCKS:           false
2021-10-02T15:11:22.1233390Z   BUILDCACHE_S3_ACCESS:              
2021-10-02T15:11:22.1233950Z   BUILDCACHE_S3_SECRET:              
2021-10-02T15:11:22.1234590Z   BUILDCACHE_TERMINATE_ON_MISS:      false
2021-10-02T15:11:22.1261100Z [command]/Users/runner/work/***/***/buildcache/bin/buildcache -s
2021-10-02T15:11:22.1318320Z Cache status:
2021-10-02T15:11:22.1319120Z   Entries in cache:  0
2021-10-02T15:11:22.1320780Z   Cache size:        0 bytes (0.0%)
2021-10-02T15:11:22.1321450Z   Direct hits:       0
2021-10-02T15:11:22.1322810Z   Direct misses:     0
2021-10-02T15:11:22.1323370Z   Local hits:        0
2021-10-02T15:11:22.1324070Z   Local misses:      0
2021-10-02T15:11:22.1324620Z   Remote hits:       0
2021-10-02T15:11:22.1325110Z   Remote misses:     0
2021-10-02T15:11:22.1325620Z   Misses:            0
2021-10-02T15:11:22.1326090Z   Direct hit ratio:  0.0%
2021-10-02T15:11:22.1326620Z   Local hit ratio:   0.0%
2021-10-02T15:11:22.1327110Z   Remote hit ratio:  0.0%
2021-10-02T15:11:22.1327660Z   Hit ratio:         0.0%
2021-10-02T15:11:22.1329960Z buildcache: zeroing stats - stats display in cleanup task will be for this run only.
2021-10-02T15:11:22.1357830Z [command]/Users/runner/work/***/***/buildcache/bin/buildcache -z

Post-job log:

2021-10-02T16:03:01.8614690Z Post job cleanup.
2021-10-02T16:03:02.2375480Z (node:17522) UnhandledPromiseRejectionWarning: Error: Unable to locate executable file: buildcache. Please verify either the file path exists or the file can be found within a directory specified by the PATH environment variable. Also check the file mode to verify the file is executable.
2021-10-02T16:03:02.2486790Z     at Object.<anonymous> (/Users/runner/work/_actions/mikehardy/buildcache-action/v1/dist/webpack:/buildcache-action/node_modules/@actions/io/lib/io.js:187:1)
2021-10-02T16:03:02.2489140Z     at Generator.next (<anonymous>)
2021-10-02T16:03:02.2592010Z     at fulfilled (/Users/runner/work/_actions/mikehardy/buildcache-action/v1/dist/webpack:/buildcache-action/node_modules/@actions/io/lib/io.js:5:1)
2021-10-02T16:03:02.2694720Z (node:17522) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
2021-10-02T16:03:02.2796840Z (node:17522) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Ah yeah, I think that is it - problem resolved moving the install step after the repository checkout step. Seems obvious now but might be work having a mention in the README.

Very interesting - If you want to hit the edit button on the README and post a PR with the details of that, you might help some future people, github web PR flow for text edits is really quick and you'll know the exact details best

Will do. New problem though - nothing seems to be saved to to the cache. The post-job cleanup reports a cache size of 0 bytes. Any ideas?

That's where turning up the debug on the build log and examining it will be (hopefully) interesting. Although if it's truly zero that usually implies the buildcache binary is not even in play, not just that it's cache-miss all the time (which is what the buildlog normally helps with)

I'd examine the PATH environment variable before whatever build step you've got, and then compare your build commands vs expectations to make sure that it's referencing your compiler in whatever way buildcache says it should so that buildcache is used

Please note that without some https://duckduckgo.com/?t=canonical&q=minimum+reproducible+example I'm just offering general guidance, all of which may be deduced from source here or on buildcache main docs site

Awesome thanks - I'll do some digging. It definitely seems like the buildcache binaries aren't in play, in the upload step the log is not found.

Got this working, but only after I added the extra variables to xcodebuild as you outline in the docs. For whatever reason, simply having the path set did not seem to work 🤷 .

Also - thanks for making this! I've been banging my head on this problem (speeding up React Native builds in CI) for a couple of years and this is by far the cleanest solution I've found.

Glad it works for you! Honestly (as a mainly react-native build consumer myself...) I've been bouncing between my own action and ccache-action personally (and the both of those locally as well). I have found that ccache can be faster, but only the newest versions (where multiple source files is handled better). So if you haven't tried the ccache-action that this is patterned from you might give it a benchmark for your case too, the difference can be substantial. At any rate, I'm happy to have wrappers for both underlying compiler caches as I've always had success with at least one of them. And it is a big help! Cheers