Varying-Vagrant-Vagrants / VVV

An open source Vagrant configuration for developing with WordPress
https://varyingvagrantvagrants.org
MIT License
4.54k stars 848 forks source link

Bug: Composer provisioner seems to be partially failing #2573

Closed ssnepenthe closed 2 years ago

ssnepenthe commented 2 years ago

What was The Command Used To Provision

vagrant up

What Kind of VVV Provision Was This

This was a fresh install

Logs/What Broke

Not really sure what to do with this - It has happened twice in a row.

Composer is successfully installed to /home/vagrant and given execute permission.

It seems like the provisioner is failing while trying to change ownership of files in /usr/local/bin. Nothing after this line in the provisioner function is running.

Steps to Reproduce (for bugs)

  1. New windows machine
  2. Install virtualbox, vagrant and git
  3. Open git bash as admin
  4. Clone vvv, install plugins and run vagrant up
  5. ???

Provisioning output: https://gist.github.com/ssnepenthe/5efa946668b900ba4808e7cbe98dbf21

Your Environment

Operating System: Windows 11 Vagrant Version: 2.2.19 Virtualbox Version: 6.1.32

tomjn commented 2 years ago

@ssnepenthe can you be more specific? I've tried looking through the logs but the only clue i have is composer and I could not find the problem output or the issue you described. When you say it's failing, how is it failing and where is it failing? Which provisioner function are you referring to?

ssnepenthe commented 2 years ago

Yeah sorry about that... I was referring to this: https://github.com/Varying-Vagrant-Vagrants/VVV/blob/dc28ec9fa53a4cab46d3857ce58cb2eeaec52f00/provision/core/composer/provision.sh

I did not see any errors or warnings, or really any indication that anything is wrong or failing.

However, once provisioning has finished if I run vagrant ssh and try to use composer I get -bash: composer: command not found.

When I look through that provisioner file it seems to be succeeding up through line 21. Composer is installed at /home/vagrant/composer.phar and has been given execute permissions. Nothing after that seems to have run.

For example I would assume that we should see more about composer in the ouput log such as "Composer installer steps completed" and "Making sure the Composer cache is not owned by root" but these entries are missing.

tomjn commented 2 years ago

So /usr/local/bin/composer does not exist? Or it exists but isn't in path? I'm not sure you've stated the actual problem, but you've tried to debug it and described the theories and speculated at causes

tomjn commented 2 years ago

Does this PR result in more information? https://github.com/Varying-Vagrant-Vagrants/VVV/pull/2574

ssnepenthe commented 2 years ago

/usr/local/bin/composer does not exist.

I'm not sure you've stated the actual problem

That's fair... Sorry if I haven't been very clear or helpful I'm just not really sure I know how else to approach this issue beyond "it doesn't seem to be working as expected..."

I am re-provisioning now with that PR and will get back to you.

ssnepenthe commented 2 years ago
   default:  ▷ Running the 'tools' provisioner...
    default:  * Running tools_install
    default:  ▷ Running tools_setup hook
    default:    - Starting subhook composer_setup with priority 10
    default:    - Starting subhook grunt_setup with priority 10
    default:  * Turning off XDebug to avoid Composer performance issues
    default:    - Starting subhook wp_cli_setup with priority 10
    default:  * Installing/updating WP-CLI
    default:  * Updating wp-cli...
    default: Error: /usr/local/bin is not writable by current user.
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Checking if Composer is installed
    default:  * Running Composer Installer...
    default:  * Updating Grunt CLI
    default: /srv/provision/core/composer/provision.sh: line 21: -f: command not found
    default:  ! Expected to find a composer.phar after running composer installer, but none was found
    default:  * Updating grunt-sass
    default:  * starting gyphack loop
    default:  * grunt-sass Updated
    default:  * Updating grun-cssjanus and grunt-rtlcss
    default:  * Stopped gyphack loop
    default:  * Completed Grunt CLI update
    default:    - Subhooks completed for tools_setup with priority 10
    default:  ✔ Finished tools_setup hook in 10s
    default:  ▷ Running tools_setup_synchronous hook
    default:  * Finalizing Tools
    default:  ✔ The 'tools' provisioner completed in 10 seconds.
ssnepenthe commented 2 years ago

The contents of the actual log file at log/provisioners/{time}/provisioner-tools.log appear to include some additional output from the composer installer script indicating that composer was successfully installed...

 ▷ Running the 'tools' provisioner...
 * Running tools_install
 ▷ Running tools_setup hook
   - Starting subhook composer_setup with priority 10
 * Turning off XDebug to avoid Composer performance issues
   - Starting subhook grunt_setup with priority 10
   - Starting subhook wp_cli_setup with priority 10
 * Installing/updating WP-CLI
 * Updating wp-cli...
 * Restarting PHP FPM services so that the change takes effect
Error: /usr/local/bin is not writable by current user.
 ✔ All PHP Debug mods are now turned off.
 * Checking if Composer is installed
 * Running Composer Installer...
All settings correct for using Composer
Downloading...
 * Updating Grunt CLI

Composer (version 2.2.5) successfully installed to: /home/vagrant/composer.phar
Use it: php composer.phar

/srv/provision/core/composer/provision.sh: line 21: -f: command not found
 ! Expected to find a composer.phar after running composer installer, but none was found
 * Updating grunt-sass
 * starting gyphack loop
 * grunt-sass Updated
 * Updating grun-cssjanus and grunt-rtlcss
 * Stopped gyphack loop
 * Completed Grunt CLI update
   - Subhooks completed for tools_setup with priority 10
 ✔ Finished tools_setup hook in 8s
 ▷ Running tools_setup_synchronous hook
 * Finalizing Tools
 ✔ The 'tools' provisioner completed in 9 seconds.
tomjn commented 2 years ago

looks like I forgot to wrap it in square brackets. I notice WP CLI updating has issues though. I've committed a fix for the [] to that branch

tomjn commented 2 years ago

As for the composer installer, it's just figuring out downloading composer.phar, it's the provisioner that then moves it into place

tomjn commented 2 years ago

I've also changed the move command to report if that failed or not

ssnepenthe commented 2 years ago

Interesting... I've now re-provisioned three times with the latest from #2574 with slightly different results each time. Relevant output from the three runs is below.

The first time the issue was still occurring.

The second time composer was installed correctly. It also seems to be correctly checking for github tokens and composer updates.

The third time composer was installed correctly again but there is nothing about github tokens or composer updates.

FIRST:

    default:  ▷ Running the 'tools' provisioner...
    default:  * Running tools_install
    default:  ▷ Running tools_setup hook
    default:    - Starting subhook composer_setup with priority 10
    default:  * Turning off XDebug to avoid Composer performance issues
    default:    - Starting subhook grunt_setup with priority 10
    default:    - Starting subhook wp_cli_setup with priority 10
    default:  * Installing/updating WP-CLI
    default:  * Updating wp-cli...
    default:  * Updating Grunt CLI
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Checking if Composer is installed
    default:  * Running Composer Installer...
    default:  * starting gyphack loop
    default:  * Updating grunt-sass
    default:  * WP CLI Nightly updated
    default:  * Disabling debug mods if present before running wp package installs
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Updating WP packages
    default:  * WP package updates completed
    default:    - Subhooks completed for tools_setup with priority 10
    default:  ✔ Finished tools_setup hook in 4s
    default:  ▷ Running tools_setup_synchronous hook
    default:  * Finalizing Tools
    default:  ✔ The 'tools' provisioner completed in 4 seconds.

SECOND:

    default:  ▷ Running the 'tools' provisioner...
    default:  * Running tools_install
    default:  ▷ Running tools_setup hook
    default:    - Starting subhook composer_setup with priority 10
    default:  * Turning off XDebug to avoid Composer performance issues
    default:    - Starting subhook grunt_setup with priority 10
    default:    - Starting subhook wp_cli_setup with priority 10
    default:  * Installing/updating WP-CLI
    default:  * Updating wp-cli...
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Checking if Composer is installed
    default:  * Running Composer Installer...
    default:  * Updating Grunt CLI
    default:  * Setting ownership and executable bit of composer...
    default:  * Moving composer into place...
    default:  * Composer installed to /usr/local/bin
    default:  * Making sure the Composer cache is not owned by root
    default:  * Checking for GitHub tokens
    default:  * Checking for Composer updates
    default:  ▷ Running after_composer hook
    default:  * Provisioning PHP_CodeSniffer (phpcs), see https://github.com/squizlabs/PHP_CodeSniffer
    default: Loading composer repositories with package information
    default: Updating dependencies
    default: Lock file operations: 6 installs, 0 updates, 0 removals
    default:   - Locking automattic/vipwpcs (2.3.3)
    default:   - Locking dealerdirect/phpcodesniffer-composer-installer (v0.7.1)
    default:   - Locking phpcompatibility/php-compatibility (9.3.5)
    default:   - Locking sirbrillig/phpcs-variable-analysis (v2.11.2)
    default:   - Locking squizlabs/php_codesniffer (3.6.2)
    default:   - Locking wp-coding-standards/wpcs (2.3.0)
    default: Writing lock file
    default: Installing dependencies from lock file (including require-dev)
    default: Package operations: 6 installs, 0 updates, 0 removals
    default:   - Downloading squizlabs/php_codesniffer (3.6.2)
    default:   - Downloading dealerdirect/phpcodesniffer-composer-installer (v0.7.1)
    default:   - Downloading wp-coding-standards/wpcs (2.3.0)
    default:  * starting gyphack loop
    default:  * Updating grunt-sass
    default:   - Downloading sirbrillig/phpcs-variable-analysis (v2.11.2)
    default:   - Downloading automattic/vipwpcs (2.3.3)
    default:   - Downloading phpcompatibility/php-compatibility (9.3.5)
    default:  * grunt-sass Updated
    default:  * Updating grun-cssjanus and grunt-rtlcss
    default:  * Stopped gyphack loop
    default:   - Installing squizlabs/php_codesniffer (3.6.2): Extracting archive
    default:  * WP CLI Nightly updated
    default:  * Disabling debug mods if present before running wp package installs
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Updating WP packages
    default:  * Completed Grunt CLI update
    default:    - Subhooks completed for tools_setup with priority 10
    default:  ✔ Finished tools_setup hook in 21s
    default:  ▷ Running tools_setup_synchronous hook
    default:  * Finalizing Tools
    default:  ✔ The 'tools' provisioner completed in 21 seconds.

THIRD:

    default:  ▷ Running the 'tools' provisioner...
    default:  * Running tools_install
    default:  ▷ Running tools_setup hook
    default:    - Starting subhook composer_setup with priority 10
    default:  * Turning off XDebug to avoid Composer performance issues
    default:    - Starting subhook grunt_setup with priority 10
    default:    - Starting subhook wp_cli_setup with priority 10
    default:  * Installing/updating WP-CLI
    default:  * Updating wp-cli...
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Checking if Composer is installed
    default:  * Running Composer Installer...
    default:  * Updating Grunt CLI
    default:  * WP CLI Nightly updated
    default:  * Disabling debug mods if present before running wp package installs
    default:  * Restarting PHP FPM services so that the change takes effect
    default:  ✔ All PHP Debug mods are now turned off.
    default:  * Updating WP packages
    default:  * Setting ownership and executable bit of composer...
    default:  * Moving composer into place...
    default:  * Composer installed to /usr/local/bin
    default:  * WP package updates completed
    default:  * Making sure the Composer cache is not owned by root
    default:    - Subhooks completed for tools_setup with priority 10
    default:  ✔ Finished tools_setup hook in 3s
    default:  ▷ Running tools_setup_synchronous hook
    default:  * Finalizing Tools
    default:  ✔ The 'tools' provisioner completed in 3 seconds.
tomjn commented 2 years ago

what do the log files say? Not everything gets printed to the terminal

ssnepenthe commented 2 years ago

FIRST:

 ▷ Running the 'tools' provisioner...
 * Running tools_install
 ▷ Running tools_setup hook
   - Starting subhook composer_setup with priority 10
 * Turning off XDebug to avoid Composer performance issues
   - Starting subhook grunt_setup with priority 10
   - Starting subhook wp_cli_setup with priority 10
 * Installing/updating WP-CLI
 * Updating wp-cli...
 * Updating Grunt CLI
Downloading from https://raw.githubusercontent.com/wp-cli/builds/gh-pages/phar/wp-cli-nightly.phar...
 * Restarting PHP FPM services so that the change takes effect
 ✔ All PHP Debug mods are now turned off.
 * Checking if Composer is installed
 * Running Composer Installer...
All settings correct for using Composer
Downloading...
md5 hash verified: 95d62a48bf4ce749290078b62ebb4242
 * starting gyphack loop
 * Updating grunt-sass
New version works. Proceeding to replace.
Success: Updated WP-CLI to the latest nightly release.
 * WP CLI Nightly updated
 * Disabling debug mods if present before running wp package installs
 * Restarting PHP FPM services so that the change takes effect
 ✔ All PHP Debug mods are now turned off.
 * Updating WP packages
Using Composer to update packages...
---
Loading composer repositories with package information
Updating dependencies
Generating rules
Resolving dependencies through SAT
Looking at all rules.

Dependency resolution completed in 0.000 seconds
Analyzed 90 packages to resolve dependencies
Analyzed 90 rules to resolve dependencies
Nothing to modify in lock file
Installing dependencies from lock file
Nothing to install, update or remove
Generating autoload files
---
Success: Packages updated.
 * WP package updates completed
   - Subhooks completed for tools_setup with priority 10
 ✔ Finished tools_setup hook in 4s
 ▷ Running tools_setup_synchronous hook
 * Finalizing Tools
 ✔ The 'tools' provisioner completed in 4 seconds.

Composer (version 2.2.5) successfully installed to: /home/vagrant/composer.phar
Use it: php composer.phar

SECOND:

 ▷ Running the 'tools' provisioner...
 * Running tools_install
 ▷ Running tools_setup hook
   - Starting subhook composer_setup with priority 10
 * Turning off XDebug to avoid Composer performance issues
   - Starting subhook grunt_setup with priority 10
   - Starting subhook wp_cli_setup with priority 10
 * Installing/updating WP-CLI
 * Updating wp-cli...
 * Restarting PHP FPM services so that the change takes effect
Downloading from https://raw.githubusercontent.com/wp-cli/builds/gh-pages/phar/wp-cli-nightly.phar...
 ✔ All PHP Debug mods are now turned off.
 * Checking if Composer is installed
 * Running Composer Installer...
All settings correct for using Composer
Downloading...
 * Updating Grunt CLI

Composer (version 2.2.5) successfully installed to: /home/vagrant/composer.phar
Use it: php composer.phar

 * Setting ownership and executable bit of composer...
 * Moving composer into place...
 * Composer installed to /usr/local/bin
 * Making sure the Composer cache is not owned by root
 * Checking for GitHub tokens
 * Checking for Composer updates
Composer version 2.2.5 2022-01-21 17:25:52
 ▷ Running after_composer hook
 * Provisioning PHP_CodeSniffer (phpcs), see https://github.com/squizlabs/PHP_CodeSniffer
Loading composer repositories with package information
Updating dependencies
Lock file operations: 6 installs, 0 updates, 0 removals
  - Locking automattic/vipwpcs (2.3.3)
  - Locking dealerdirect/phpcodesniffer-composer-installer (v0.7.1)
  - Locking phpcompatibility/php-compatibility (9.3.5)
  - Locking sirbrillig/phpcs-variable-analysis (v2.11.2)
  - Locking squizlabs/php_codesniffer (3.6.2)
  - Locking wp-coding-standards/wpcs (2.3.0)
Writing lock file
Installing dependencies from lock file (including require-dev)
Package operations: 6 installs, 0 updates, 0 removals
  - Downloading squizlabs/php_codesniffer (3.6.2)
  - Downloading dealerdirect/phpcodesniffer-composer-installer (v0.7.1)
  - Downloading wp-coding-standards/wpcs (2.3.0)
 * starting gyphack loop
 * Updating grunt-sass
  - Downloading sirbrillig/phpcs-variable-analysis (v2.11.2)
  - Downloading automattic/vipwpcs (2.3.3)
  - Downloading phpcompatibility/php-compatibility (9.3.5)
 * grunt-sass Updated
 * Updating grun-cssjanus and grunt-rtlcss
 * Stopped gyphack loop
md5 hash verified: 95d62a48bf4ce749290078b62ebb4242
  - Installing squizlabs/php_codesniffer (3.6.2): Extracting archive
New version works. Proceeding to replace.
Success: Updated WP-CLI to the latest nightly release.
 * WP CLI Nightly updated
 * Disabling debug mods if present before running wp package installs
 * Restarting PHP FPM services so that the change takes effect
 ✔ All PHP Debug mods are now turned off.
 * Updating WP packages
Using Composer to update packages...
---
Loading composer repositories with package information
 * Completed Grunt CLI update
   - Subhooks completed for tools_setup with priority 10
 ✔ Finished tools_setup hook in 21s
 ▷ Running tools_setup_synchronous hook
 * Finalizing Tools
 ✔ The 'tools' provisioner completed in 21 seconds.
Updating dependencies
Generating rules
Resolving dependencies through SAT
Looking at all rules.

Dependency resolution completed in 0.000 seconds
Analyzed 90 packages to resolve dependencies
Analyzed 90 rules to resolve dependencies
Nothing to modify in lock file
Installing dependencies from lock file
Nothing to install, update or remove
Generating autoload files
---
Success: Packages updated.

Fatal error: Uncaught Symfony\Component\Console\Exception\RuntimeException: Unable to write output. in phar:///usr/local/bin/composer/vendor/symfony/console/Output/StreamOutput.php:79
Stack trace:
#0 phar:///usr/local/bin/composer/vendor/symfony/console/Output/Output.php(164): Symfony\Component\Console\Output\StreamOutput->doWrite()
#1 phar:///usr/local/bin/composer/vendor/symfony/console/Output/Output.php(132): Symfony\Component\Console\Output\Output->write()
#2 phar:///usr/local/bin/composer/vendor/symfony/console/Application.php(641): Symfony\Component\Console\Output\Output->writeln()
#3 phar:///usr/local/bin/composer/vendor/symfony/console/Application.php(127): Symfony\Component\Console\Application->renderException()
#4 phar:///usr/local/bin/composer/src/Composer/Console/Application.php(131): Symfony\Component\Console\Application->run()
#5 phar:///usr/local/bin/composer/bin/composer(83): Composer\Console\Application->run()
#6 /usr/local/bin/composer(29): require('phar:///usr/loc...')
#7 {main}
  thrown in phar:///usr/local/bin/composer/vendor/symfony/console/Output/StreamOutput.php on line 79

THIRD:

 ▷ Running the 'tools' provisioner...
 * Running tools_install
 ▷ Running tools_setup hook
   - Starting subhook composer_setup with priority 10
 * Turning off XDebug to avoid Composer performance issues
   - Starting subhook grunt_setup with priority 10
   - Starting subhook wp_cli_setup with priority 10
 * Installing/updating WP-CLI
 * Updating wp-cli...
 * Restarting PHP FPM services so that the change takes effect
Downloading from https://raw.githubusercontent.com/wp-cli/builds/gh-pages/phar/wp-cli-nightly.phar...
 ✔ All PHP Debug mods are now turned off.
 * Checking if Composer is installed
 * Running Composer Installer...
All settings correct for using Composer
Downloading...
 * Updating Grunt CLI
md5 hash verified: 95d62a48bf4ce749290078b62ebb4242
New version works. Proceeding to replace.
Success: Updated WP-CLI to the latest nightly release.
 * WP CLI Nightly updated
 * Disabling debug mods if present before running wp package installs
 * Restarting PHP FPM services so that the change takes effect
 ✔ All PHP Debug mods are now turned off.
 * Updating WP packages
Using Composer to update packages...
---
Loading composer repositories with package information

Composer (version 2.2.5) successfully installed to: /home/vagrant/composer.phar
Use it: php composer.phar

 * Setting ownership and executable bit of composer...
Updating dependencies
Generating rules
Resolving dependencies through SAT
Looking at all rules.

Dependency resolution completed in 0.001 seconds
Analyzed 90 packages to resolve dependencies
Analyzed 90 rules to resolve dependencies
Nothing to modify in lock file
Installing dependencies from lock file
Nothing to install, update or remove
Generating autoload files
 * Moving composer into place...
---
Success: Packages updated.
 * Composer installed to /usr/local/bin
 * WP package updates completed
 * Making sure the Composer cache is not owned by root
   - Subhooks completed for tools_setup with priority 10
 ✔ Finished tools_setup hook in 3s
 ▷ Running tools_setup_synchronous hook
 * Finalizing Tools
 ✔ The 'tools' provisioner completed in 3 seconds.
tomjn commented 2 years ago

@ssnepenthe I've made a number of improvements to logging etc, including better network checks. I've also moved the Grunt gyp loop hack out into a non-parallelised provisioner.

Can you check if things are improved on that PR?

ssnepenthe commented 2 years ago

Just tested the PR with a fresh provision and then a reprovision and everything seems to be working, thanks!

tomjn commented 2 years ago

@ssnepenthe now that it's been merged are we good to close this? I've created #2580 to handle the npm issue that was surfaced while looking into it as well as #2579 which will let us re-enable parallel hooks