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 <name>
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 <name>
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 �[90;1m==> �[0m�[37;1mSetup PHP�[0m
2023-07-01T19:43:38.5491996Z �[32;1m✓ �[0m�[34;1mPHP �[0m�[90;1mUpdated to PHP 8.1.20�[0m
2023-07-01T19:43:38.5492618Z 
2023-07-01T19:43:38.5493829Z �[90;1m==> �[0m�[37;1mSetup Tools�[0m
2023-07-01T19:43:39.3109045Z �[32;1m✓ �[0m�[34;1mcomposer �[0m�[90;1mAdded composer 2.5.8�[0m
2023-07-01T19:43:40.3926737Z �[32;1m✓ �[0m�[34;1mpsalm �[0m�[90;1mAdded psalm �[0m
2023-07-01T19:43:41.7787342Z �[32;1m✓ �[0m�[34;1mphpstan �[0m�[90;1mAdded phpstan 1.10.22�[0m
2023-07-01T19:43:42.3480156Z �[32;1m✓ �[0m�[34;1mcs2pr �[0m�[90;1mAdded cs2pr 1.8.5�[0m
2023-07-01T19:43:43.0744461Z �[32;1m✓ �[0m�[34;1mphpcs �[0m�[90;1mAdded phpcs 3.7.2�[0m
2023-07-01T19:43:43.4772759Z �[32;1m✓ �[0m�[34;1mphpunit �[0m�[90;1mAdded phpunit 10.2.3�[0m
2023-07-01T19:43:43.4773484Z 
2023-07-01T19:43:43.4815433Z �[90;1m==> �[0m�[37;1mSetup Coverage�[0m
2023-07-01T19:43:43.6794487Z �[32;1m✓ �[0m�[34;1mpcov.enabled=1 �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7340613Z �[32;1m✓ �[0m�[34;1mpcov �[0m�[90;1mPCOV 1.0.11 enabled as coverage driver�[0m
2023-07-01T19:43:43.7340912Z 
2023-07-01T19:43:43.7341128Z �[90;1m==> �[0m�[37;1mAdd php.ini values�[0m
2023-07-01T19:43:43.7428660Z �[32;1m✓ �[0m�[34;1massert.exception=1 �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7429686Z �[32;1m✓ �[0m�[34;1mzend.assertions=1 �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7430417Z �[32;1m✓ �[0m�[34;1merror_reporting=-1 �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7431038Z �[32;1m✓ �[0m�[34;1mlog_errors_max_len=0 �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7431703Z �[32;1m✓ �[0m�[34;1mdisplay_errors=On �[0m�[90;1mAdded to php.ini�[0m
2023-07-01T19:43:43.7448731Z 
2023-07-01T19:43:43.7449420Z �[90;1m==> �[0m�[37;1m#StandWithUkraine�[0m
2023-07-01T19:43:43.7450151Z �[32;1m✓ �[0m�[34;1mread-more �[0m�[90;1mhttps://setup-php.com/support-ukraine�[0m
2023-07-01T19:43:43.7566722Z ##[group]Run echo "::add-matcher::/opt/hostedtoolcache/php.json"
2023-07-01T19:43:43.7567200Z �[36;1mecho "::add-matcher::/opt/hostedtoolcache/php.json"�[0m
2023-07-01T19:43:43.7567635Z �[36;1mecho "::add-matcher::/opt/hostedtoolcache/phpunit.json"�[0m
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 �[36;1m${GITHUB_ACTION_PATH}/bin/php_version.sh�[0m
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 �[36;1m${GITHUB_ACTION_PATH}/bin/should_cache.sh ""�[0m
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 �[36;1m${GITHUB_ACTION_PATH}/bin/composer_paths.sh \�[0m
2023-07-01T19:43:43.9664415Z �[36;1m  "" \�[0m
2023-07-01T19:43:43.9664596Z �[36;1m  "" \�[0m
2023-07-01T19:43:43.9664804Z �[36;1m  "/usr/bin/php"�[0m
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 �[36;1m${GITHUB_ACTION_PATH}/bin/cache_key.sh \�[0m
2023-07-01T19:43:44.6935984Z �[36;1m  "Linux" \�[0m
2023-07-01T19:43:44.6936195Z �[36;1m  "8.1.20" \�[0m
2023-07-01T19:43:44.6936384Z �[36;1m  "" \�[0m
2023-07-01T19:43:44.6936578Z �[36;1m  "" \�[0m
2023-07-01T19:43:44.6936884Z �[36;1m  "b619f299fb03a570a4a0af7f304aa547b70bbfdcd115619c20a806660a0c2e09" \�[0m
2023-07-01T19:43:44.6937197Z �[36;1m  "" \�[0m
2023-07-01T19:43:44.6937378Z �[36;1m  "" \�[0m
2023-07-01T19:43:44.6937564Z �[36;1m  ""�[0m
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.