Failure to restore cache causes the GitHub Action step to run indefinitely

[ghostwriter]

Hey @ramsey,

Thank you for creating this tool, it has been very helpful.

I wanted to report finding this GitHub Action running for 3+ hours and had to manually cancel it.

Description

It had the following warning:

Warning

Failed to restore cache: The operation cannot be completed in timeout. Cache not found for input keys: Linux-php-8.1.20-composer-locked-b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09, Linux-php-8.1.20-composer-locked-

Then it continued to run for 3+ hours (not sure doing what) until manually canceled.

Steps to reproduce

I have a reusable workflow defined in ghostwriter/compliance

https://github.com/ghostwriter/compliance/#/.github/workflows/automation.yml#L60-L63

That workflow is used in ghostwriter/psalm-plugin-tester https://github.com/ghostwriter/psalm-plugin-tester/actions/runs/5432766284/workflow

It generated these jobs

https://github.com/ghostwriter/psalm-plugin-tester/actions/runs/5432766284/jobs/9880024230

Expected behavior

Continue to the next step or fail gracefully when it fails to restore the cache.

Screenshots or output

https://github.com/ghostwriter/psalm-plugin-tester/actions/runs/5432766284/jobs/9880024230

Click to view Raw Logs

``` 2023-07-01T19:43:18.1919234Z Requested labels: ubuntu-latest 2023-07-01T19:43:18.1919467Z Job defined at: ghostwriter/compliance/.github/workflows/automation.yml@refs/heads/v1 2023-07-01T19:43:18.1919645Z Reusable workflow chain: 2023-07-01T19:43:18.1919746Z ghostwriter/psalm-plugin-tester/.github/workflows/compliance.yml@refs/heads/main (a608ac19d07733d8ef207a8bd34bb45adc7cd93e) 2023-07-01T19:43:18.1919840Z -> ghostwriter/compliance/.github/workflows/automation.yml@refs/heads/v1 (3bf14b28b941722c423f8171861d927f41466e4b) 2023-07-01T19:43:18.1919920Z Waiting for a runner to pick up this job... 2023-07-01T19:43:19.2499773Z Job is waiting for a hosted runner to come online. 2023-07-01T19:43:21.0940986Z Job is about to start running on the hosted runner: GitHub Actions 5 (hosted) 2023-07-01T19:43:23.7566335Z Current runner version: '2.305.0' 2023-07-01T19:43:23.7595345Z ##[group]Operating System 2023-07-01T19:43:23.7595848Z Ubuntu 2023-07-01T19:43:23.7596147Z 22.04.2 2023-07-01T19:43:23.7596495Z LTS 2023-07-01T19:43:23.7596754Z ##[endgroup] 2023-07-01T19:43:23.7597102Z ##[group]Runner Image 2023-07-01T19:43:23.7597482Z Image: ubuntu-22.04 2023-07-01T19:43:23.7597778Z Version: 20230625.1.0 2023-07-01T19:43:23.7598346Z Included Software: https://github.com/actions/runner-images/blob/ubuntu22/20230625.1.0/images/linux/Ubuntu2204-Readme.md 2023-07-01T19:43:23.7599046Z Image Release: https://github.com/actions/runner-images/releases/tag/ubuntu22%2F20230625.1.0 2023-07-01T19:43:23.7599464Z ##[endgroup] 2023-07-01T19:43:23.7599819Z ##[group]Runner Image Provisioner 2023-07-01T19:43:23.7600164Z 2.0.238.1 2023-07-01T19:43:23.7600444Z ##[endgroup] 2023-07-01T19:43:23.7601154Z ##[group]GITHUB_TOKEN Permissions 2023-07-01T19:43:23.7601691Z Contents: read 2023-07-01T19:43:23.7602203Z Metadata: read 2023-07-01T19:43:23.7602642Z Packages: read 2023-07-01T19:43:23.7602970Z ##[endgroup] 2023-07-01T19:43:23.7606591Z Secret source: Actions 2023-07-01T19:43:23.7607216Z Prepare workflow directory 2023-07-01T19:43:23.8343540Z Prepare all required actions 2023-07-01T19:43:23.8534827Z Getting action download info 2023-07-01T19:43:24.0881944Z Download action repository 'actions/checkout@v3' (SHA:c85c95e3d7251135ab7dc9ce3241c5835cc595a9) 2023-07-01T19:43:24.9608826Z Download action repository 'shivammathur/setup-php@v2' (SHA:4bd44f22a98a19e0950cbad5f31095157cc9621b) 2023-07-01T19:43:25.6319014Z Download action repository 'ramsey/composer-install@v2' (SHA:12e7194f379a3773679641adfdfdade1eea3c086) 2023-07-01T19:43:26.1771532Z Getting action download info 2023-07-01T19:43:26.3265492Z Download action repository 'actions/cache@v3' (SHA:88522ab9f39a2ea568f7027eddc7d8d8bc9d59c8) 2023-07-01T19:43:27.2760425Z Uses: ghostwriter/compliance/.github/workflows/automation.yml@refs/heads/v1 (3bf14b28b941722c423f8171861d927f41466e4b) 2023-07-01T19:43:27.2762221Z Complete job name: automation / ECS on PHP 8.1 with highest dependencies 2023-07-01T19:43:27.3560121Z ##[group]Run actions/checkout@v3 2023-07-01T19:43:27.3560414Z with: 2023-07-01T19:43:27.3560722Z repository: ghostwriter/psalm-plugin-tester 2023-07-01T19:43:27.3561249Z token: *** 2023-07-01T19:43:27.3561451Z ssh-strict: true 2023-07-01T19:43:27.3561706Z persist-credentials: true 2023-07-01T19:43:27.3561951Z clean: true 2023-07-01T19:43:27.3562194Z sparse-checkout-cone-mode: true 2023-07-01T19:43:27.3562452Z fetch-depth: 1 2023-07-01T19:43:27.3562681Z lfs: false 2023-07-01T19:43:27.3562883Z submodules: false 2023-07-01T19:43:27.3563149Z set-safe-directory: true 2023-07-01T19:43:27.3563452Z ##[endgroup] 2023-07-01T19:43:27.6367598Z Syncing repository: ghostwriter/psalm-plugin-tester 2023-07-01T19:43:27.6369345Z ##[group]Getting Git version info 2023-07-01T19:43:27.6369917Z Working directory is '/home/runner/work/psalm-plugin-tester/psalm-plugin-tester' 2023-07-01T19:43:27.6371358Z [command]/usr/bin/git version 2023-07-01T19:43:27.6430417Z git version 2.41.0 2023-07-01T19:43:27.6457359Z ##[endgroup] 2023-07-01T19:43:27.6475212Z Temporarily overriding HOME='/home/runner/work/_temp/e1260041-712a-4c82-b995-fa68573df6ad' before making global git config changes 2023-07-01T19:43:27.6476858Z Adding repository directory to the temporary git global config as a safe directory 2023-07-01T19:43:27.6501252Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/psalm-plugin-tester/psalm-plugin-tester 2023-07-01T19:43:27.6537129Z Deleting the contents of '/home/runner/work/psalm-plugin-tester/psalm-plugin-tester' 2023-07-01T19:43:27.6542788Z ##[group]Initializing the repository 2023-07-01T19:43:27.6546702Z [command]/usr/bin/git init /home/runner/work/psalm-plugin-tester/psalm-plugin-tester 2023-07-01T19:43:27.6633273Z hint: Using 'master' as the name for the initial branch. This default branch name 2023-07-01T19:43:27.6634176Z hint: is subject to change. To configure the initial branch name to use in all 2023-07-01T19:43:27.6634993Z hint: of your new repositories, which will suppress this warning, call: 2023-07-01T19:43:27.6635285Z hint: 2023-07-01T19:43:27.6635745Z hint: git config --global init.defaultBranch 2023-07-01T19:43:27.6635993Z hint: 2023-07-01T19:43:27.6636357Z hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and 2023-07-01T19:43:27.6636834Z hint: 'development'. The just-created branch can be renamed via this command: 2023-07-01T19:43:27.6637113Z hint: 2023-07-01T19:43:27.6637378Z hint: git branch -m 2023-07-01T19:43:27.6646644Z Initialized empty Git repository in /home/runner/work/psalm-plugin-tester/psalm-plugin-tester/.git/ 2023-07-01T19:43:27.6661247Z [command]/usr/bin/git remote add origin https://github.com/ghostwriter/psalm-plugin-tester 2023-07-01T19:43:27.6705688Z ##[endgroup] 2023-07-01T19:43:27.6706477Z ##[group]Disabling automatic garbage collection 2023-07-01T19:43:27.6709493Z [command]/usr/bin/git config --local gc.auto 0 2023-07-01T19:43:27.6742925Z ##[endgroup] 2023-07-01T19:43:27.6743549Z ##[group]Setting up auth 2023-07-01T19:43:27.6749535Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand 2023-07-01T19:43:27.6783114Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :" 2023-07-01T19:43:27.7180237Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader 2023-07-01T19:43:27.7213268Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :" 2023-07-01T19:43:27.7438903Z [command]/usr/bin/git config --local http.https://github.com/.extraheader AUTHORIZATION: basic *** 2023-07-01T19:43:27.7478572Z ##[endgroup] 2023-07-01T19:43:27.7479291Z ##[group]Fetching the repository 2023-07-01T19:43:27.7488579Z [command]/usr/bin/git -c protocol.version=2 fetch --no-tags --prune --progress --no-recurse-submodules --depth=1 origin +a608ac19d07733d8ef207a8bd34bb45adc7cd93e:refs/remotes/origin/main 2023-07-01T19:43:28.1389507Z remote: Enumerating objects: 39, done. 2023-07-01T19:43:28.1404326Z remote: Counting objects: 2% (1/39) 2023-07-01T19:43:28.1405233Z remote: Counting objects: 5% (2/39) 2023-07-01T19:43:28.1405688Z remote: Counting objects: 7% (3/39) 2023-07-01T19:43:28.1406349Z remote: Counting objects: 10% (4/39) 2023-07-01T19:43:28.1406801Z remote: Counting objects: 12% (5/39) 2023-07-01T19:43:28.1407449Z remote: Counting objects: 15% (6/39) 2023-07-01T19:43:28.1408004Z remote: Counting objects: 17% (7/39) 2023-07-01T19:43:28.1408669Z remote: Counting objects: 20% (8/39) 2023-07-01T19:43:28.1409113Z remote: Counting objects: 23% (9/39) 2023-07-01T19:43:28.1409763Z remote: Counting objects: 25% (10/39) 2023-07-01T19:43:28.1410238Z remote: Counting objects: 28% (11/39) 2023-07-01T19:43:28.1410897Z remote: Counting objects: 30% (12/39) 2023-07-01T19:43:28.1411350Z remote: Counting objects: 33% (13/39) 2023-07-01T19:43:28.1411989Z remote: Counting objects: 35% (14/39) 2023-07-01T19:43:28.1412435Z remote: Counting objects: 38% (15/39) 2023-07-01T19:43:28.1413073Z remote: Counting objects: 41% (16/39) 2023-07-01T19:43:28.1413795Z remote: Counting objects: 43% (17/39) 2023-07-01T19:43:28.1414435Z remote: Counting objects: 46% (18/39) 2023-07-01T19:43:28.1414877Z remote: Counting objects: 48% (19/39) 2023-07-01T19:43:28.1415532Z remote: Counting objects: 51% (20/39) 2023-07-01T19:43:28.1415980Z remote: Counting objects: 53% (21/39) 2023-07-01T19:43:28.1416603Z remote: Counting objects: 56% (22/39) 2023-07-01T19:43:28.1417041Z remote: Counting objects: 58% (23/39) 2023-07-01T19:43:28.1417991Z remote: Counting objects: 61% (24/39) 2023-07-01T19:43:28.1418457Z remote: Counting objects: 64% (25/39) 2023-07-01T19:43:28.1419119Z remote: Counting objects: 66% (26/39) 2023-07-01T19:43:28.1419782Z remote: Counting objects: 69% (27/39) 2023-07-01T19:43:28.1420773Z remote: Counting objects: 71% (28/39) 2023-07-01T19:43:28.1421112Z remote: Counting objects: 74% (29/39) 2023-07-01T19:43:28.1421650Z remote: Counting objects: 76% (30/39) 2023-07-01T19:43:28.1422769Z remote: Counting objects: 79% (31/39) 2023-07-01T19:43:28.1423221Z remote: Counting objects: 82% (32/39) 2023-07-01T19:43:28.1424014Z remote: Counting objects: 84% (33/39) 2023-07-01T19:43:28.1424708Z remote: Counting objects: 87% (34/39) 2023-07-01T19:43:28.1425300Z remote: Counting objects: 89% (35/39) 2023-07-01T19:43:28.1425994Z remote: Counting objects: 92% (36/39) 2023-07-01T19:43:28.1426653Z remote: Counting objects: 94% (37/39) 2023-07-01T19:43:28.1427184Z remote: Counting objects: 97% (38/39) 2023-07-01T19:43:28.1427763Z remote: Counting objects: 100% (39/39) 2023-07-01T19:43:28.1428363Z remote: Counting objects: 100% (39/39), done. 2023-07-01T19:43:28.1674659Z remote: Compressing objects: 3% (1/29) 2023-07-01T19:43:28.1676454Z remote: Compressing objects: 6% (2/29) 2023-07-01T19:43:28.1677817Z remote: Compressing objects: 10% (3/29) 2023-07-01T19:43:28.1678151Z remote: Compressing objects: 13% (4/29) 2023-07-01T19:43:28.1678857Z remote: Compressing objects: 17% (5/29) 2023-07-01T19:43:28.1679559Z remote: Compressing objects: 20% (6/29) 2023-07-01T19:43:28.1679891Z remote: Compressing objects: 24% (7/29) 2023-07-01T19:43:28.1680939Z remote: Compressing objects: 27% (8/29) 2023-07-01T19:43:28.1681276Z remote: Compressing objects: 31% (9/29) 2023-07-01T19:43:28.1681604Z remote: Compressing objects: 34% (10/29) 2023-07-01T19:43:28.1683010Z remote: Compressing objects: 37% (11/29) 2023-07-01T19:43:28.1683761Z remote: Compressing objects: 41% (12/29) 2023-07-01T19:43:28.1684474Z remote: Compressing objects: 44% (13/29) 2023-07-01T19:43:28.1684811Z remote: Compressing objects: 48% (14/29) 2023-07-01T19:43:28.1685524Z remote: Compressing objects: 51% (15/29) 2023-07-01T19:43:28.1686226Z remote: Compressing objects: 55% (16/29) 2023-07-01T19:43:28.1686556Z remote: Compressing objects: 58% (17/29) 2023-07-01T19:43:28.1686872Z remote: Compressing objects: 62% (18/29) 2023-07-01T19:43:28.1687960Z remote: Compressing objects: 65% (19/29) 2023-07-01T19:43:28.1688296Z remote: Compressing objects: 68% (20/29) 2023-07-01T19:43:28.1688626Z remote: Compressing objects: 72% (21/29) 2023-07-01T19:43:28.1688943Z remote: Compressing objects: 75% (22/29) 2023-07-01T19:43:28.1689653Z remote: Compressing objects: 79% (23/29) 2023-07-01T19:43:28.1690371Z remote: Compressing objects: 82% (24/29) 2023-07-01T19:43:28.1690684Z remote: Compressing objects: 86% (25/29) 2023-07-01T19:43:28.1691173Z remote: Compressing objects: 89% (26/29) 2023-07-01T19:43:28.1691496Z remote: Compressing objects: 93% (27/29) 2023-07-01T19:43:28.1691948Z remote: Compressing objects: 96% (28/29) 2023-07-01T19:43:28.1693500Z remote: Compressing objects: 100% (29/29) 2023-07-01T19:43:28.1694015Z remote: Compressing objects: 100% (29/29), done. 2023-07-01T19:43:28.1965563Z remote: Total 39 (delta 0), reused 19 (delta 0), pack-reused 0 2023-07-01T19:43:28.2054515Z From https://github.com/ghostwriter/psalm-plugin-tester 2023-07-01T19:43:28.2055309Z * [new ref] a608ac19d07733d8ef207a8bd34bb45adc7cd93e -> origin/main 2023-07-01T19:43:28.2083406Z ##[endgroup] 2023-07-01T19:43:28.2084042Z ##[group]Determining the checkout info 2023-07-01T19:43:28.2085472Z ##[endgroup] 2023-07-01T19:43:28.2086405Z ##[group]Checking out the ref 2023-07-01T19:43:28.2091677Z [command]/usr/bin/git checkout --progress --force -B main refs/remotes/origin/main 2023-07-01T19:43:28.2173265Z Switched to a new branch 'main' 2023-07-01T19:43:28.2177860Z branch 'main' set up to track 'origin/main'. 2023-07-01T19:43:28.2183258Z ##[endgroup] 2023-07-01T19:43:28.2226553Z [command]/usr/bin/git log -1 --format='%H' 2023-07-01T19:43:28.2256077Z 'a608ac19d07733d8ef207a8bd34bb45adc7cd93e' 2023-07-01T19:43:28.2582570Z ##[group]Run shivammathur/setup-php@v2 2023-07-01T19:43:28.2582854Z with: 2023-07-01T19:43:28.2583046Z coverage: pcov 2023-07-01T19:43:28.2583407Z ini-values: assert.exception=1, zend.assertions=1, error_reporting=-1, log_errors_max_len=0, display_errors=On 2023-07-01T19:43:28.2583766Z php-version: 8.1 2023-07-01T19:43:28.2584023Z tools: psalm, phpstan, cs2pr, phpcs, phpunit 2023-07-01T19:43:28.2584295Z ini-file: production 2023-07-01T19:43:28.2584508Z ##[endgroup] 2023-07-01T19:43:28.9662006Z [command]/usr/bin/bash /home/runner/work/_actions/shivammathur/setup-php/v2/src/scripts/run.sh 2023-07-01T19:43:28.9782708Z 2023-07-01T19:43:28.9783256Z ==> Setup PHP 2023-07-01T19:43:38.5491996Z ✓ PHP Updated to PHP 8.1.20 2023-07-01T19:43:38.5492618Z 2023-07-01T19:43:38.5493829Z ==> Setup Tools 2023-07-01T19:43:39.3109045Z ✓ composer Added composer 2.5.8 2023-07-01T19:43:40.3926737Z ✓ psalm Added psalm  2023-07-01T19:43:41.7787342Z ✓ phpstan Added phpstan 1.10.22 2023-07-01T19:43:42.3480156Z ✓ cs2pr Added cs2pr 1.8.5 2023-07-01T19:43:43.0744461Z ✓ phpcs Added phpcs 3.7.2 2023-07-01T19:43:43.4772759Z ✓ phpunit Added phpunit 10.2.3 2023-07-01T19:43:43.4773484Z 2023-07-01T19:43:43.4815433Z ==> Setup Coverage 2023-07-01T19:43:43.6794487Z ✓ pcov.enabled=1 Added to php.ini 2023-07-01T19:43:43.7340613Z ✓ pcov PCOV 1.0.11 enabled as coverage driver 2023-07-01T19:43:43.7340912Z 2023-07-01T19:43:43.7341128Z ==> Add php.ini values 2023-07-01T19:43:43.7428660Z ✓ assert.exception=1 Added to php.ini 2023-07-01T19:43:43.7429686Z ✓ zend.assertions=1 Added to php.ini 2023-07-01T19:43:43.7430417Z ✓ error_reporting=-1 Added to php.ini 2023-07-01T19:43:43.7431038Z ✓ log_errors_max_len=0 Added to php.ini 2023-07-01T19:43:43.7431703Z ✓ display_errors=On Added to php.ini 2023-07-01T19:43:43.7448731Z 2023-07-01T19:43:43.7449420Z ==> #StandWithUkraine 2023-07-01T19:43:43.7450151Z ✓ read-more https://setup-php.com/support-ukraine 2023-07-01T19:43:43.7566722Z ##[group]Run echo "::add-matcher::/opt/hostedtoolcache/php.json" 2023-07-01T19:43:43.7567200Z echo "::add-matcher::/opt/hostedtoolcache/php.json" 2023-07-01T19:43:43.7567635Z echo "::add-matcher::/opt/hostedtoolcache/phpunit.json" 2023-07-01T19:43:43.7627581Z shell: /usr/bin/bash -e {0} 2023-07-01T19:43:43.7627854Z env: 2023-07-01T19:43:43.7628157Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:43.7628567Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:43.7628832Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:43.7629142Z ##[endgroup] 2023-07-01T19:43:43.7896649Z ##[group]Run ramsey/composer-install@v2 2023-07-01T19:43:43.7896990Z with: 2023-07-01T19:43:43.7897274Z env: 2023-07-01T19:43:43.7897516Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:43.7897907Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:43.7898217Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:43.7898466Z ##[endgroup] 2023-07-01T19:43:43.8119851Z ##[group]Run ${GITHUB_ACTION_PATH}/bin/php_version.sh 2023-07-01T19:43:43.8120501Z ${GITHUB_ACTION_PATH}/bin/php_version.sh 2023-07-01T19:43:43.8176531Z shell: /usr/bin/bash --noprofile --norc -e -o pipefail {0} 2023-07-01T19:43:43.8177057Z env: 2023-07-01T19:43:43.8177300Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:43.8177635Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:43.8177943Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:43.8178182Z ##[endgroup] 2023-07-01T19:43:43.9457587Z ##[group]Run ${GITHUB_ACTION_PATH}/bin/should_cache.sh "" 2023-07-01T19:43:43.9457939Z ${GITHUB_ACTION_PATH}/bin/should_cache.sh "" 2023-07-01T19:43:43.9513526Z shell: /usr/bin/bash --noprofile --norc -e -o pipefail {0} 2023-07-01T19:43:43.9513794Z env: 2023-07-01T19:43:43.9514020Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:43.9514271Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:43.9514496Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:43.9514718Z ##[endgroup] 2023-07-01T19:43:43.9663763Z ##[group]Run ${GITHUB_ACTION_PATH}/bin/composer_paths.sh \ 2023-07-01T19:43:43.9664152Z ${GITHUB_ACTION_PATH}/bin/composer_paths.sh \ 2023-07-01T19:43:43.9664415Z  "" \ 2023-07-01T19:43:43.9664596Z  "" \ 2023-07-01T19:43:43.9664804Z  "/usr/bin/php" 2023-07-01T19:43:43.9714089Z shell: /usr/bin/bash --noprofile --norc -e -o pipefail {0} 2023-07-01T19:43:43.9714365Z env: 2023-07-01T19:43:43.9714586Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:43.9714826Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:43.9715066Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:43.9715284Z ##[endgroup] 2023-07-01T19:43:44.6935389Z ##[group]Run ${GITHUB_ACTION_PATH}/bin/cache_key.sh \ 2023-07-01T19:43:44.6935724Z ${GITHUB_ACTION_PATH}/bin/cache_key.sh \ 2023-07-01T19:43:44.6935984Z  "Linux" \ 2023-07-01T19:43:44.6936195Z  "8.1.20" \ 2023-07-01T19:43:44.6936384Z  "" \ 2023-07-01T19:43:44.6936578Z  "" \ 2023-07-01T19:43:44.6936884Z  "b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09" \ 2023-07-01T19:43:44.6937197Z  "" \ 2023-07-01T19:43:44.6937378Z  "" \ 2023-07-01T19:43:44.6937564Z  "" 2023-07-01T19:43:44.6992428Z shell: /usr/bin/bash --noprofile --norc -e -o pipefail {0} 2023-07-01T19:43:44.6992706Z env: 2023-07-01T19:43:44.6992934Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:44.6993175Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:44.6993413Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:44.6993634Z ##[endgroup] 2023-07-01T19:43:44.7223085Z ##[group]Run actions/cache@v3 2023-07-01T19:43:44.7223304Z with: 2023-07-01T19:43:44.7223545Z path: /home/runner/.cache/composer 2023-07-01T19:43:44.7224036Z key: Linux-php-8.1.20-composer-locked-b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09 2023-07-01T19:43:44.7224549Z restore-keys: Linux-php-8.1.20-composer-locked- 2023-07-01T19:43:44.7224860Z enableCrossOsArchive: false 2023-07-01T19:43:44.7225117Z fail-on-cache-miss: false 2023-07-01T19:43:44.7225342Z lookup-only: false 2023-07-01T19:43:44.7225559Z env: 2023-07-01T19:43:44.7225768Z COMPOSER_PROCESS_TIMEOUT: 0 2023-07-01T19:43:44.7225999Z COMPOSER_NO_INTERACTION: 1 2023-07-01T19:43:44.7226229Z COMPOSER_NO_AUDIT: 1 2023-07-01T19:43:44.7226517Z CACHE_RESTORE_KEY: Linux-php-8.1.20-composer-locked- 2023-07-01T19:43:44.7226782Z ##[endgroup] 2023-07-01T19:43:46.3611239Z Received 5203550 of 21980766 (23.7%), 5.0 MBs/sec 2023-07-01T19:43:47.3623789Z Received 17786462 of 21980766 (80.9%), 8.5 MBs/sec 2023-07-01T19:43:48.3637866Z Received 17786462 of 21980766 (80.9%), 5.6 MBs/sec 2023-07-01T19:43:49.3653243Z Received 17786462 of 21980766 (80.9%), 4.2 MBs/sec 2023-07-01T19:43:50.3666937Z Received 17786462 of 21980766 (80.9%), 3.4 MBs/sec 2023-07-01T19:43:51.3682461Z Received 17786462 of 21980766 (80.9%), 2.8 MBs/sec 2023-07-01T19:43:52.3695805Z Received 17786462 of 21980766 (80.9%), 2.4 MBs/sec 2023-07-01T19:43:53.3700982Z Received 17786462 of 21980766 (80.9%), 2.1 MBs/sec 2023-07-01T19:43:54.3719802Z Received 17786462 of 21980766 (80.9%), 1.9 MBs/sec 2023-07-01T19:43:55.3738421Z Received 17786462 of 21980766 (80.9%), 1.7 MBs/sec 2023-07-01T19:43:56.3751826Z Received 17786462 of 21980766 (80.9%), 1.5 MBs/sec 2023-07-01T19:43:57.3766642Z Received 17786462 of 21980766 (80.9%), 1.4 MBs/sec 2023-07-01T19:43:58.3782191Z Received 17786462 of 21980766 (80.9%), 1.3 MBs/sec 2023-07-01T19:43:59.3795517Z Received 17786462 of 21980766 (80.9%), 1.2 MBs/sec 2023-07-01T19:44:00.3810859Z Received 17786462 of 21980766 (80.9%), 1.1 MBs/sec 2023-07-01T19:44:01.3808333Z Received 17786462 of 21980766 (80.9%), 1.1 MBs/sec 2023-07-01T19:44:02.3825077Z Received 17786462 of 21980766 (80.9%), 1.0 MBs/sec 2023-07-01T19:44:03.3837340Z Received 17786462 of 21980766 (80.9%), 0.9 MBs/sec 2023-07-01T19:44:04.3850344Z Received 17786462 of 21980766 (80.9%), 0.9 MBs/sec 2023-07-01T19:44:05.3862805Z Received 17786462 of 21980766 (80.9%), 0.8 MBs/sec 2023-07-01T19:44:06.3876766Z Received 17786462 of 21980766 (80.9%), 0.8 MBs/sec 2023-07-01T19:44:07.3890939Z Received 17786462 of 21980766 (80.9%), 0.8 MBs/sec 2023-07-01T19:44:08.3902530Z Received 17786462 of 21980766 (80.9%), 0.7 MBs/sec 2023-07-01T19:44:09.3915201Z Received 17786462 of 21980766 (80.9%), 0.7 MBs/sec 2023-07-01T19:44:10.3931700Z Received 17786462 of 21980766 (80.9%), 0.7 MBs/sec 2023-07-01T19:44:11.3935577Z Received 17786462 of 21980766 (80.9%), 0.7 MBs/sec 2023-07-01T19:44:12.3947934Z Received 17786462 of 21980766 (80.9%), 0.6 MBs/sec 2023-07-01T19:44:13.3962466Z Received 17786462 of 21980766 (80.9%), 0.6 MBs/sec 2023-07-01T19:44:14.3975790Z Received 17786462 of 21980766 (80.9%), 0.6 MBs/sec 2023-07-01T19:44:15.3984269Z Received 17786462 of 21980766 (80.9%), 0.6 MBs/sec 2023-07-01T19:44:16.3998556Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:17.4010650Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:18.4025645Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:19.4037361Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:20.4052468Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:21.4064887Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:22.4078243Z Received 17786462 of 21980766 (80.9%), 0.5 MBs/sec 2023-07-01T19:44:23.4093323Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:24.4106536Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:25.4120160Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:26.4135005Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:27.4144398Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:28.4157275Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:29.4170420Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:30.4183498Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:31.4195821Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:32.4208575Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:33.4222651Z Received 17786462 of 21980766 (80.9%), 0.4 MBs/sec 2023-07-01T19:44:34.4235618Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:35.4249356Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:36.4264488Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:37.4277056Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:38.4292195Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:39.4304753Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:40.4318487Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:41.4330741Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:42.4344771Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:43.4360037Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:44.4371208Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:45.4386468Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:46.4399652Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:47.4412885Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:48.4425984Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:49.4438701Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:50.4451609Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:51.4466314Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:52.4480991Z Received 17786462 of 21980766 (80.9%), 0.3 MBs/sec 2023-07-01T19:44:53.4494284Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:54.4509664Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:55.4522026Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:56.4535056Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:57.4550302Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:58.4564343Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:44:59.4575372Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:00.4589346Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:01.4603106Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:02.4618534Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:03.4631784Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:04.4644618Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:05.4657933Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:06.4671387Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:07.4686078Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:08.4698318Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:09.4712306Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:10.4724761Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:11.4738374Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:12.4744326Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:13.4758496Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:14.4772092Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:15.4784144Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:16.4798344Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:17.4810709Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:18.4813063Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:19.4827574Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:20.4828798Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:21.4841840Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:22.4855045Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:23.4868007Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:24.4876346Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:25.4881901Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:25.6171200Z Received 17786462 of 21980766 (80.9%), 0.2 MBs/sec 2023-07-01T19:45:25.6211265Z ##[warning]Failed to restore: The operation cannot be completed in timeout. 2023-07-01T19:45:25.6212921Z Cache not found for input keys: Linux-php-8.1.20-composer-locked-b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09, Linux-php-8.1.20-composer-locked- 2023-07-01T22:49:50.0546834Z ##[error]The operation was canceled. 2023-07-01T22:49:50.0632850Z Post job cleanup. 2023-07-01T22:49:50.0675800Z Post job cleanup. 2023-07-01T22:49:50.1718367Z [command]/usr/bin/git version 2023-07-01T22:49:50.1804803Z git version 2.41.0 2023-07-01T22:49:50.1857097Z Temporarily overriding HOME='/home/runner/work/_temp/afa29411-aa38-4fae-84e7-21e96aaade43' before making global git config changes 2023-07-01T22:49:50.1858137Z Adding repository directory to the temporary git global config as a safe directory 2023-07-01T22:49:50.1864555Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/psalm-plugin-tester/psalm-plugin-tester 2023-07-01T22:49:50.1921643Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand 2023-07-01T22:49:50.2025300Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :" 2023-07-01T22:49:50.2280292Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader 2023-07-01T22:49:50.2313279Z http.https://github.com/.extraheader 2023-07-01T22:49:50.2325619Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader 2023-07-01T22:49:50.2380948Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :" 2023-07-01T22:49:50.2889918Z Cleaning up orphan processes ```

Environment details

• version of this package: v2
• PHP version:8.1.20
• OS: Linux

Additional context

2023-07-01T19:45:25.6211265Z ##[warning]Failed to restore: The operation cannot be completed in timeout.
2023-07-01T19:45:25.6212921Z Cache not found for input keys: Linux-php-8.1.20-composer-locked-b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09, Linux-php-8.1.20-composer-locked-
2023-07-01T22:49:50.0546834Z ##[error]The operation was canceled. (manually canceled)
2023-07-01T22:49:50.0632850Z Post job cleanup.

[cvergne]

That's really strange as actions/cache@v3 has 2 timeout (since at least 4 months now) :

1. 1 hour for the entire download
2. 10 minutes for each download segment of 128MB

So your step should have been stopped after max 1 hour (even 10 minutes if it was a segment stuck).

Anyway, the segment timeout can be configured on actions/cache with env var SEGMENT_DOWNLOAD_TIMEOUT_MINS (default to 10 min), but I'm not sure if it is handled without any change into composer-install action.

Edit: that comment is because I had the same problem, except the cache action had a timeout after 10 minutes.

[ghostwriter]

It happened again, timed out after 6 hours.

[ramsey]

What does “closed as not planned” mean?

[ghostwriter]

"Closed as not planned" is just GitHub UI string.

In this case, the issue was closed because there was no response from you (the author), at all, and it was deemed by us as stale and unreproducible now based on the information available in the GitHub logs.

I assure you that I have no alternative motives or hidden intentions.

The alternative would mark this issue as resolved.

Additionally, I no longer have this issue and do not want to keep it open.

[ramsey]

Oh, interesting. I didn't realize they had added that to the "close" button.

I had not been able to reproduce this, so I was waiting to see if others found this issue and reported they were experiencing similar things.

So, to confirm, you're no longer able to reproduce this?

[ghostwriter]

That is correct.

Something is still causing this to run for up to 6 hours, but I personally am no longer able to reproduce this.

https://docs.github.com/en/actions/learn-github-actions/usage-limits-billing-and-administration#usage-limits

Job execution time - Each job in a workflow can run for up to 6 hours of execution time. If a job reaches this limit, the job is terminated and fails to complete.

[ramsey]

Do you think the problem that causes it to run that long is in this project or somewhere else?

[ghostwriter]

The problem that causes it to run that long is not in this project, it's in actions/cache.

However, this project runs actions/cache internally and the issue here is not properly handling actions/cache issues.

As stated above,

https://github.com/actions/cache/blob/f7ebb81a3f195b4fb88dab7c14e2f7aff52045aa/README.md#L26-L28

• Fixed the download stuck problem by introducing a timeout of 1 hour for cache downloads.
• Allowed users to provide a custom timeout as input for aborting download of a cache segment using an environment variable SEGMENT_DOWNLOAD_TIMEOUT_MINS. Default is 10 minutes.

eg. There is currently no way to use SEGMENT_DOWNLOAD_TIMEOUT_MINS using this project.