Robustness bug - cache restore finds nothing even though cache was saved successfully (Windows) #465
Description
Hope you can help - I've been tearing my hair out for 3 days trying to get the cache working but there seems to be a robustness bug. I have a workflow that runs in both Windows and Linux and although it works reliably on Linux, on Windows it nearly always fails to find anything in the cache ("Cache not found for input keys: xxxxx"), despite having saved successfully when the job last ran (Cache saved successfully).
I'm using latest (2.1.3) version of the cache action. I have full debug logs here, hopefully that's enough to go on - though I didn't see any smoking gun (to my untrained eye!) in the debug messages so perhaps more debug logging is needed in the action to track it down?
Here's logs for successfully writing the 355MB tar to the cache (https://github.com/ben-spiller/apama-core-gha/runs/1413864855):
Tue, 17 Nov 2020 18:06:17 GMT
##[debug]Result: 'mykey-amd64_win-TODO.08'
...
Tue, 17 Nov 2020 18:06:19 GMT
##[debug]Matched: cached-apama-installation.tar
Tue, 17 Nov 2020 18:06:19 GMT
##[debug]Cache Paths:
Tue, 17 Nov 2020 18:06:19 GMT
##[debug]["cached-apama-installation.tar"]
Tue, 17 Nov 2020 18:06:19 GMT
##[debug]Archive Path: D:\a\_temp\0c7996da-49a7-4e8d-9369-739899f1f365\cache.tzst
Tue, 17 Nov 2020 18:06:19 GMT
"C:\Program Files\Git\usr\bin\tar.exe" --posix --use-compress-program "zstd -T0" -cf cache.tzst -P -C D:/a/apama-core-gha/apama-core-gha --files-from manifest.txt --force-local
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]File Size: 355931096
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Saving Cache (ID: 20)
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Upload cache
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Resource Url: https://artifactcache.actions.githubusercontent.com/GVoY9ihpc259XWwlY2apWZ9ztMibqKRXJBHEGcPEG82GxmbEe2/_apis/artifactcache/caches/20
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Upload concurrency: 4
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Upload chunk size: 33554432
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Awaiting all uploads
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 0 with content range: bytes 0-33554431/*
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 33554432 with content range: bytes 33554432-67108863/*
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 67108864 with content range: bytes 67108864-100663295/*
Tue, 17 Nov 2020 18:06:22 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 100663296 with content range: bytes 100663296-134217727/*
Tue, 17 Nov 2020 18:06:25 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 134217728 with content range: bytes 134217728-167772159/*
Tue, 17 Nov 2020 18:06:25 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 167772160 with content range: bytes 167772160-201326591/*
Tue, 17 Nov 2020 18:06:25 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 201326592 with content range: bytes 201326592-234881023/*
Tue, 17 Nov 2020 18:06:25 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 234881024 with content range: bytes 234881024-268435455/*
Tue, 17 Nov 2020 18:06:28 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 268435456 with content range: bytes 268435456-301989887/*
Tue, 17 Nov 2020 18:06:28 GMT
##[debug]Uploading chunk of size 33554432 bytes at offset 301989888 with content range: bytes 301989888-335544319/*
Tue, 17 Nov 2020 18:06:29 GMT
##[debug]Uploading chunk of size 20386776 bytes at offset 335544320 with content range: bytes 335544320-355931095/*
Tue, 17 Nov 2020 18:06:31 GMT
##[debug]Commiting cache
Tue, 17 Nov 2020 18:06:31 GMT
##[debug]Resource Url: https://artifactcache.actions.githubusercontent.com/GVoY9ihpc259XWwlY2apWZ9ztMibqKRXJBHEGcPEG82GxmbEe2/_apis/artifactcache/caches/20
Tue, 17 Nov 2020 18:06:32 GMT
Cache saved successfully
But when the job runs again, the cache restore finds nothing (https://github.com/ben-spiller/apama-core-gha/runs/1413893214):
Tue, 17 Nov 2020 18:09:18 GMT
Run actions/cache@v2.1.3
Tue, 17 Nov 2020 18:09:18 GMT
::save-state name=CACHE_KEY::mykey-amd64_win-TODO.08
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]Save intra-action state CACHE_KEY = mykey-amd64_win-TODO.08
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]Resolved Keys:
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]["mykey-amd64_win-TODO.08"]
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]Checking tar --version
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]bsdtar 3.3.2 - libarchive 3.3.2 zlib/1.2.5.f-ipp
Tue, 17 Nov 2020 18:09:18 GMT
##[debug]Resource Url: https://artifactcache.actions.githubusercontent.com/GVoY9ihpc259XWwlY2apWZ9ztMibqKRXJBHEGcPEG82GxmbEe2/_apis/artifactcache/cache?keys=mykey-amd64_win-TODO.08&version=27cbd6037aedd294633d9914d502d29c8c765de0aef4baee071670db7c51a2aa
Tue, 17 Nov 2020 18:09:19 GMT
Cache not found for input keys: mykey-amd64_win-TODO.08
Tue, 17 Nov 2020 18:09:19 GMT
##[debug]Node Action run completed with exit code 0
Tue, 17 Nov 2020 18:09:19 GMT
##[debug]Finishing: Apama installation cache
For interest (though not the main focus of this bug report) the reserveCache fails at the end of the new job:
Tue, 17 Nov 2020 18:12:01 GMT
##[debug]Reserving Cache
Tue, 17 Nov 2020 18:12:01 GMT
##[debug]Resource Url: https://artifactcache.actions.githubusercontent.com/GVoY9ihpc259XWwlY2apWZ9ztMibqKRXJBHEGcPEG82GxmbEe2/_apis/artifactcache/caches
Tue, 17 Nov 2020 18:12:01 GMT
Unable to reserve cache with key mykey-amd64_win-TODO.08, another job may be creating this cache.
Since I know you have testing for the action on all platforms I guess there must be something different here - maybe larger file size (355MB) or maybe something about the timing between save and restore.
Hope we can figure this one out! Caching is so important for many workflows. Thanks!