diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 92257578e..eea3e7921 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -56,6 +56,8 @@ jobs: - name: Calculate number of parallel_rspec processes (half of num of lines in runtime log) run: echo "PARALLEL_TEST_PROCESSORS=$(( ($(cat test/var/log/parallel_runtime_rspec.${STACK}.log | wc -l)+2-1)/2 ))" >> "$GITHUB_ENV" - name: Execute tests - run: bundle exec parallel_rspec --group-by runtime --unknown-runtime 1 --allowed-missing 100 --runtime-log "test/var/log/parallel_runtime_rspec.${STACK}.log" --verbose-command --combine-stderr --prefix-output-with-test-env-number test/spec/ + run: bundle exec parallel_rspec --group-by runtime --first-is-1 --unknown-runtime 1 --allowed-missing 100 --runtime-log "test/var/log/parallel_runtime_rspec.${STACK}.log" --verbose-command --combine-stderr --prefix-output-with-test-env-number test/spec/ + - name: Print list of executed examples + run: cat test/var/log/group.*.json | jq -r --slurp '[.[].examples[]] | sort_by(.id) | flatten[] | .full_description' - name: Print parallel_runtime_rspec.log - run: cat parallel_runtime_rspec.log | grep -E '^test/spec/[a-z0-9_/\.-]+\.rb:[0-9]+\.[0-9]+$' | sort + run: cat test/var/log/parallel_runtime_rspec.log | grep -E '^test/spec/[a-z0-9_/\.-]+\.rb:[0-9]+\.[0-9]+$' | sort diff --git a/.rspec_parallel b/.rspec_parallel index 32dcd0b4f..75bd2164e 100644 --- a/.rspec_parallel +++ b/.rspec_parallel @@ -1,2 +1,3 @@ --format progress ---format ParallelTests::RSpec::RuntimeLogger --out parallel_runtime_rspec.log +--format json --out test/var/log/group.<%= "%02d" % ENV["TEST_ENV_NUMBER"] %>.json +--format ParallelTests::RSpec::RuntimeLogger --out test/var/log/parallel_runtime_rspec.log diff --git a/test/fixtures/ci/composertest/composer.json b/test/fixtures/ci/composertest/composer.json deleted file mode 100644 index f0670420c..000000000 --- a/test/fixtures/ci/composertest/composer.json +++ /dev/null @@ -1,5 +0,0 @@ -{ - "scripts": { - "test": "echo 'all tests passed'" - } -} diff --git a/test/fixtures/ci/zendassert/test.php b/test/fixtures/ci/zendassert/test.php index ae0cb2f51..137322433 100644 --- a/test/fixtures/ci/zendassert/test.php +++ b/test/fixtures/ci/zendassert/test.php @@ -1,4 +1,10 @@ "4"}), - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" } ) elsif mode == "without BLACKFIRE_SERVER_TOKEN" # ext-blackfire is listed as a dependency in composer.json, but a BLACKFIRE_SERVER_TOKEN/ID is missing @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', buildpacks: buildpacks, config: { "BLACKFIRE_LOG_LEVEL" => "4" }, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" } ) elsif mode == "with default BLACKFIRE_LOG_LEVEL" # ext-blackfire is listed as a dependency in composer.json, and BLACKFIRE_LOG_LEVEL is the default (1=error) @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', buildpacks: buildpacks, config: credentials, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-blackfire:*'") or raise "Failed to require PHP/ext-blackfire" } ) else # a BLACKFIRE_SERVER_TOKEN/ID triggers the automatic installation of ext-blackfire at the end of the build @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', buildpacks: buildpacks, config: credentials.merge({ "BLACKFIRE_LOG_LEVEL" => "4"}), - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*'") or raise "Failed to require PHP version" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*'") or raise "Failed to require PHP version" } ) end @app.deploy @@ -80,30 +77,57 @@ end end - ['heroku-php-apache2', 'heroku-php-nginx'].each do |script| - # without log level info, we will not see the messages we're using to test any behavior - # but we need to assert that no info is printed at all in this case - it "does not output info messages during startup with #{script}", if: mode == "with default BLACKFIRE_LOG_LEVEL" do + context "during boot" do + cases = ['heroku-php-apache2', 'heroku-php-nginx'] + before(:all) do + delimiter = SecureRandom.uuid + # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + run_cmds = cases + .map { |script| "#{script} -F conf/fpm.include.broken 2>&1"} + .join("; echo -n '#{delimiter}'; ") retry_until retry: 3, sleep: 5 do - out = @app.run("#{script} -F conf/fpm.include.broken") # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call - expect(out).not_to match(/\[Info\]/) # this message should not occur if defaults are applied correctly + @run = @app.run(run_cmds).split(delimiter) end end - it "launches blackfire CLI, but not the extension, during boot preparations, with #{script}", if: mode != "with default BLACKFIRE_LOG_LEVEL" do - retry_until retry: 3, sleep: 5 do - out = @app.run("#{script} -F conf/fpm.include.broken") # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call + + # these we check only once - it's stuff that happens in .profile.d on boot, not on each script run + it "does not log info messages about agent startup", if: mode == "with default BLACKFIRE_LOG_LEVEL" do + # without log level info, we will not see the messages we're using to test any behavior + # but we need to assert that no info is printed at all in this case + expect(@run[0].unansi).not_to match(/Reading agent configuration file/) # this message should not occur if defaults are applied correctly + end + it "logs info messages about agent startup", if: mode != "with default BLACKFIRE_LOG_LEVEL" do + out = @run[0].unansi - out_before_fpm, out_after_fpm = out.unansi.split("Starting php-fpm", 2) + out_before_fpm, out_after_fpm = out.split("Starting php-fpm", 2) - expect(out_before_fpm).to match(/Reading agent configuration file/) # that is the very first thing the agent prints - if mode == "without BLACKFIRE_SERVER_TOKEN" - expect(out_before_fpm).to match(/The server ID parameter is not set/) - else - expect(out.unansi).to match(/Waiting for new connection/) # match on whole output in case it takes a bit longer to start - end + expect(out_before_fpm).to match(/Reading agent configuration file/) # that is the very first thing the agent prints + if mode == "without BLACKFIRE_SERVER_TOKEN" + expect(out_before_fpm).to match(/The server ID parameter is not set/) + else + expect(out).to match(/Waiting for new connection/) # match on whole output in case it takes a bit longer to start + end + end + + # these others we check for each script invocation + cases.each_with_index do |script, idx| + # without log level info, we will not see the messages we're using to test any behavior + # but we need to assert that no info is printed at all in this case + it "does not output info messages with #{script}", if: mode == "with default BLACKFIRE_LOG_LEVEL" do + out = @run[idx] + expect(out).not_to match(/\[Info\]/) # this message should not occur if defaults are applied correctly + end + it "preparations launches blackfire CLI, but not the extension, with #{script}", if: mode != "with default BLACKFIRE_LOG_LEVEL" do + out = @run[idx] + + out_before_fpm, out_after_fpm = out.unansi.split("Starting php-fpm", 2) + expect(out_before_fpm).not_to match(/\[Warning\] APM: Cannot start/) # extension does not attempt to start on `php-fpm -i` during boot expect(out_before_fpm).to match(/\[Debug\] APM: disabled/) # blackfire reports itself disabled (by us) during the various boot prep PHP invocations - + expect(out_after_fpm).not_to match(/\[Debug\] APM: disabled/) expect(out_after_fpm).to match(/\[Info\] APCu extension is not loaded/) end diff --git a/test/spec/ci_frameworks-a_spec.rb b/test/spec/ci_frameworks-a_spec.rb new file mode 100644 index 000000000..1d499fdb1 --- /dev/null +++ b/test/spec/ci_frameworks-a_spec.rb @@ -0,0 +1,20 @@ +require_relative "spec_helper" + +describe "A PHP application on Heroku CI" do + { + "atoum": "atoum", + "Behat": "behat", + "Codeception": "codecept run", + }.each do |name, command| + context "using the #{name} CI framework" do + let(:app) { + new_app_with_stack_and_platrepo("test/fixtures/ci/#{name.downcase}") + } + it "automatically executes '#{command}'" do + app.run_ci do |test_run| + expect(test_run.output).to match("#{name} found, executing '#{command}'...") + end + end + end + end +end diff --git a/test/spec/ci_frameworks_spec.rb b/test/spec/ci_frameworks-k_spec.rb similarity index 85% rename from test/spec/ci_frameworks_spec.rb rename to test/spec/ci_frameworks-k_spec.rb index fc79bb0ee..8568b2d1c 100644 --- a/test/spec/ci_frameworks_spec.rb +++ b/test/spec/ci_frameworks-k_spec.rb @@ -2,11 +2,8 @@ describe "A PHP application on Heroku CI" do { - "Codeception": "codecept run", - "Behat": "behat", - "PHPSpec": "phpspec run", - "atoum": "atoum", "Kahlan": "kahlan", + "PHPSpec": "phpspec run", "PHPUnit": "phpunit", }.each do |name, command| context "using the #{name} CI framework" do diff --git a/test/spec/ci_spec.rb b/test/spec/ci_spec.rb index 69f717b7e..71bf91b91 100644 --- a/test/spec/ci_spec.rb +++ b/test/spec/ci_spec.rb @@ -11,11 +11,11 @@ end end - it "has zend.assertions enabled" do - app = new_app_with_stack_and_platrepo('test/fixtures/ci/zendassert', allow_failure: true) + it "has zend.assertions enabled and auto-runs a composer.json 'test' script entry" do + app = new_app_with_stack_and_platrepo('test/fixtures/ci/zendassert') app.run_ci do |test_run| - expect(test_run.status).to eq :failed - expect(test_run.output).to match("AssertionError") + expect(test_run.output).to match("Script 'composer test' found, executing...") + expect(test_run.output).to match("Caught expected AssertionError") end end @@ -26,15 +26,4 @@ expect(test_run.output).to match("No tests found.") end end - - context "specifying a composer.json 'test' script entry" do - let(:app) { - new_app_with_stack_and_platrepo('test/fixtures/ci/composertest') - } - it "executes 'composer test'" do - app.run_ci do |test_run| - expect(test_run.output).to match("Script 'composer test' found, executing...") - end - end - end end diff --git a/test/spec/composer-1_spec.rb b/test/spec/composer-1_spec.rb new file mode 100644 index 000000000..8a97a3e18 --- /dev/null +++ b/test/spec/composer-1_spec.rb @@ -0,0 +1,38 @@ +require_relative "spec_helper" + +describe "A PHP application intended for Composer 1", :stack => "heroku-20" do + context "with a composer.lock generated by an old version of Composer" do + it "builds using Composer 1.x and prints a notice" do + new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_oldv1').deploy do |app| + expect(app.output).to match(/No Composer plugin-api-version recorded/) + expect(app.output).to match(/- composer \(1/) + expect(app.output).to match(/Composer version 1/) + end + end + end + context "with a composer.lock generated by a late version 1 of Composer" do + before(:all) do + @app = new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v1') + @app.deploy + end + + after(:all) do + @app.teardown! + end + + it "builds using Composer 1.x" do + expect(@app.output).to match(/- composer \(1/) + expect(@app.output).to match(/Composer version 1/) + end + + context "with a malformed COMPOSER_AUTH env var" do + it "still boots" do + # config test is enough, it's past any uses of composer on startup + cmds = ['heroku-php-apache2', 'heroku-php-nginx'].map { |script| "#{script} -t" } + retry_until retry: 3, sleep: 5 do + expect_exit(code: 0) { @app.run("( set -e; #{cmds.join('; ')}; )", :return_obj => true, :heroku => {:env => "COMPOSER_AUTH=malformed"}) } + end + end + end + end +end diff --git a/test/spec/composer-2_spec.rb b/test/spec/composer-2_spec.rb new file mode 100644 index 000000000..65d32f0be --- /dev/null +++ b/test/spec/composer-2_spec.rb @@ -0,0 +1,53 @@ +require_relative "spec_helper" + +describe "A PHP application intended for Composer 2" do + context "with a composer.lock generated by version 2.2 of Composer" do + it "builds using Composer 2.2" do + new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2lts').deploy do |app| + expect(app.output).to match(/- composer \(2\.2\./) + expect(app.output).to match(/Composer version 2\.2\./) + end + end + end + context "with a composer.lock generated by version 2.3 of Composer" do + before(:all) do + @app = new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2') + @app.deploy + end + + after(:all) do + @app.teardown! + end + + it "builds using Composer 2.3 or later" do + expect(@app.output).to match(/- composer \(2\.([3-9]|\d{2,})\./) + expect(@app.output).to match(/Composer version 2\.([3-9]|\d{2,}\.)/) + end + + context "with a malformed COMPOSER_AUTH env var" do + it "still boots" do + # config test is enough, it's past any uses of composer on startup + cmds = ['heroku-php-apache2', 'heroku-php-nginx'].map { |script| "#{script} -t" } + retry_until retry: 3, sleep: 5 do + expect_exit(code: 0) { @app.run("( set -e; #{cmds.join('; ')}; )", :return_obj => true, :heroku => {:env => "COMPOSER_AUTH=malformed"}) } + end + end + end + end + context "with a composer.lock generated by a future version 2 of Composer" do + it "builds using Composer 2.3 or later" do + new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2.999').deploy do |app| + expect(app.output).to match(/- composer \(2\.([3-9]|\d{2,})\./) + expect(app.output).to match(/Composer version 2\.([3-9]|\d{2,}\.)/) + end + end + end + context "with only an index.php" do + it "builds using Composer 2.2" do + new_app_with_stack_and_platrepo('test/fixtures/default').deploy do |app| + expect(app.output).to match(/- composer \(2\.2\./) + expect(app.output).to match(/Composer version 2\.2\./) + end + end + end +end diff --git a/test/spec/composer_spec.rb b/test/spec/composer_spec.rb deleted file mode 100644 index bdc1ad288..000000000 --- a/test/spec/composer_spec.rb +++ /dev/null @@ -1,81 +0,0 @@ -require_relative "spec_helper" - -describe "A PHP application" do - context "that has its stack changed", :stack => "heroku-22" do - it "re-uses cached dependencies from the prior stack build" do - new_app_with_stack_and_platrepo("php-getting-started").deploy do |app| - expect(app.output).to include("Downloading") - app.update_stack("heroku-20") - # we are changing the stack to heroku-20, so we also need to adjust the platform repository accordingly, otherwise, for tests running on branches where HEROKU_PHP_PLATFORM_REPOSITORIES is set to a value, the build would use the wrong repo - app.set_config({"HEROKU_PHP_PLATFORM_REPOSITORIES" => ENV["HEROKU_PHP_PLATFORM_REPOSITORIES"].sub("heroku-22", "heroku-20")}) if ENV["HEROKU_PHP_PLATFORM_REPOSITORIES"] - app.commit! - app.push! - expect(app.output).to_not include("Downloading") - end - end - end - context "with a composer.lock generated by an old version of Composer", :stack => "heroku-20" do - it "builds using Composer 1.x and prints a notice" do - new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_oldv1').deploy do |app| - expect(app.output).to match(/No Composer plugin-api-version recorded/) - expect(app.output).to match(/- composer \(1/) - expect(app.output).to match(/Composer version 1/) - end - end - end - context "with a composer.lock generated by a late version 1 of Composer", :stack => "heroku-20" do - it "builds using Composer 1.x" do - new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v1').deploy do |app| - expect(app.output).to match(/- composer \(1/) - expect(app.output).to match(/Composer version 1/) - end - end - end - context "with a composer.lock generated by version 2.2 of Composer" do - it "builds using Composer 2.2" do - new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2lts').deploy do |app| - expect(app.output).to match(/- composer \(2\.2\./) - expect(app.output).to match(/Composer version 2\.2\./) - end - end - end - context "with a composer.lock generated by version 2.3 of Composer" do - it "builds using Composer 2.3 or later" do - new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2').deploy do |app| - expect(app.output).to match(/- composer \(2\.([3-9]|\d{2,})\./) - expect(app.output).to match(/Composer version 2\.([3-9]|\d{2,}\.)/) - end - end - end - context "with a composer.lock generated by a future version 2 of Composer" do - it "builds using Composer 2.3 or later" do - new_app_with_stack_and_platrepo('test/fixtures/composer/basic_lock_v2.999').deploy do |app| - expect(app.output).to match(/- composer \(2\.([3-9]|\d{2,})\./) - expect(app.output).to match(/Composer version 2\.([3-9]|\d{2,}\.)/) - end - end - end - context "with only an index.php" do - it "builds using Composer 2.2" do - new_app_with_stack_and_platrepo('test/fixtures/default').deploy do |app| - expect(app.output).to match(/- composer \(2\.2\./) - expect(app.output).to match(/Composer version 2\.2\./) - end - end - end - context "with a malformed COMPOSER_AUTH env var" do - ['v1', 'v2'].each do |cv| - next unless cv == "v2" or "heroku-20" == ENV['STACK'] - it "the app still boots" do - new_app_with_stack_and_platrepo("test/fixtures/composer/basic_lock_#{cv}", run_multi: true).deploy do |app| - ['heroku-php-apache2', 'heroku-php-nginx'].each do |script| - retry_until retry: 3, sleep: 5 do - out = app.run("#{script} -F composer.lock", :heroku => {:env => "COMPOSER_AUTH=malformed"}) # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call - expect(out).to match(/FPM initialization failed/) # we got far enough (until FPM spits out an error) - end - end - end - end - end - end -end diff --git a/test/spec/newrelic_spec.rb b/test/spec/newrelic_spec.rb index 6712d587f..aced64987 100644 --- a/test/spec/newrelic_spec.rb +++ b/test/spec/newrelic_spec.rb @@ -1,4 +1,5 @@ require_relative "spec_helper" +require "securerandom" describe "A PHP application using New Relic" do ["explicitly", "without NEW_RELIC_LICENSE_KEY", "with default NEW_RELIC_LOG_LEVEL", "implicitly"].each do |mode| @@ -8,29 +9,25 @@ # ext-newrelic is listed as a dependency in composer.json, and a NEW_RELIC_LICENSE_KEY is provided @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', config: { "NEW_RELIC_LOG_LEVEL" => "info", "NEW_RELIC_LICENSE_KEY" => "somethingfake" }, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" } ) elsif mode == "without NEW_RELIC_LICENSE_KEY" # ext-newrelic is listed as a dependency in composer.json, but a NEW_RELIC_LICENSE_KEY is missing @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', config: { "NEW_RELIC_LOG_LEVEL" => "info" }, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" } ) elsif mode == "with default NEW_RELIC_LOG_LEVEL" # ext-newrelic is listed as a dependency in composer.json, and NEW_RELIC_LOG_LEVEL is the default (warning) @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', config: { "NEW_RELIC_LICENSE_KEY" => "somethingfake" }, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*' 'ext-newrelic:*'") or raise "Failed to require PHP/ext-newrelic" } ) else # a NEW_RELIC_LICENSE_KEY triggers the automatic installation of ext-newrelic at the end of the build @app = new_app_with_stack_and_platrepo('test/fixtures/bootopts', config: { "NEW_RELIC_LOG_LEVEL" => "info", "NEW_RELIC_LICENSE_KEY" => "thiswilltriggernewrelic" }, - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*'") or raise "Failed to require PHP version" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs 'php:*'") or raise "Failed to require PHP version" } ) end @app.deploy @@ -59,32 +56,51 @@ expect(@app.output).not_to match(/daemon='@newrelic-daemon'.*?startup=agent/) # no extension connects during build end - ['heroku-php-apache2', 'heroku-php-nginx'].each do |script| - if mode == "with default NEW_RELIC_LOG_LEVEL" + context "during boot" do + cases = ['heroku-php-apache2', 'heroku-php-nginx'] + before(:all) do + delimiter = SecureRandom.uuid + # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + run_cmds = cases + .map { |script| "#{script} -F conf/fpm.include.broken 2>&1"} + .join("; echo -n '#{delimiter}'; ") + retry_until retry: 3, sleep: 5 do + @run = @app.run(run_cmds).split(delimiter) + end + end + + # these we check only once - it's stuff that happens in .profile.d on boot, not on each script run + it "does not log info messages about daemon startup", if: mode == "with default NEW_RELIC_LOG_LEVEL" do # without log level info, we will not see the messages we're using to test any behavior # but we need to assert that no info is printed at all in this case - it "does not output info messages during startup with #{script}" do - retry_until retry: 3, sleep: 5 do - out = @app.run("#{script} -F conf/fpm.include.broken") # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call - - expect(out).not_to match(/New Relic PHP Agent globally disabled/) # this message should not occur if defaults are applied correctly even at build time - expect(out).not_to match(/New Relic daemon/) # this message should not occur if defaults are applied correctly even at build time - end - end - next # the other tests do not apply to this case since the log level isn't sufficient to assert anything + expect(@run[0]).not_to match(/New Relic daemon/) # this message should not occur if defaults are applied correctly end - it "launches newrelic-daemon, but not the extension, during boot preparations, with #{script}" do - retry_until retry: 3, sleep: 5 do - out = @app.run("#{script} -F conf/fpm.include.broken") # prevent FPM from starting up using an invalid config, that way we don't have to wrap the server start in a `timeout` call - + it "logs info messages about daemon startup", if: mode != "with default NEW_RELIC_LOG_LEVEL" do + out_before_fpm, out_after_fpm = @run[0].split("Starting php-fpm", 2) + expect(out_before_fpm).to match(/listen="@newrelic-daemon"[^\n]+?startup=init/) # NR daemon starts on boot + end + + # these others we check for each script invocation + cases.each_with_index do |script, idx| + # without log level info, we will not see the messages we're using to test any behavior + # but we need to assert that no info is printed at all in this case + it "does not output info messages during startup with #{script}", if: mode == "with default NEW_RELIC_LOG_LEVEL" do + # these messages should not occur if defaults are applied correctly + expect(@run[idx]).not_to match(/New Relic daemon/) + expect(@run[idx]).not_to match(/New Relic PHP Agent globally disabled/) + end + it "launches newrelic-daemon, but not the extension, during boot preparations, with #{script}", if: mode != "with default NEW_RELIC_LOG_LEVEL" do + out = @run[idx] expect(out).not_to match(/spawned daemon child/) # extension does not spawn its own daemon - + out_before_fpm, out_after_fpm = out.split("Starting php-fpm", 2) - - expect(out_before_fpm).to match(/listen="@newrelic-daemon"[^\n]+?startup=init/) # NR daemon starts on boot + expect(out_before_fpm).not_to match(/daemon='@newrelic-daemon'[^\n]+?startup=agent/) # extension does not connect to daemon before FPM starts expect(out_before_fpm).to match(/New Relic PHP Agent globally disabled/) # NR extension reports itself disabled - + expect(out_after_fpm).to match(/daemon='@newrelic-daemon'[^\n]+?startup=agent/m) # extension connects to daemon when FPM starts end end diff --git a/test/spec/php_base_shared.rb b/test/spec/php_base_shared.rb index 55db04c47..f462953ab 100644 --- a/test/spec/php_base_shared.rb +++ b/test/spec/php_base_shared.rb @@ -1,13 +1,31 @@ require_relative "spec_helper" +require "securerandom" shared_examples "A basic PHP application" do |series| context "with a composer.json requiring PHP #{series}" do before(:all) do @app = new_app_with_stack_and_platrepo('test/fixtures/default', - before_deploy: -> { system("composer require --quiet --ignore-platform-reqs php '#{series}.*'") or raise "Failed to require PHP version" }, - run_multi: true + before_deploy: -> { system("composer require --quiet --ignore-platform-reqs php '#{series}.*'") or raise "Failed to require PHP version" } ) @app.deploy + + delimiter = SecureRandom.uuid + run_cmds = [ + "php -v", + "php -i", + "php -i | grep memory_limit", + "ldd .heroku/php/bin/php .heroku/php/lib/php/extensions/no-debug-non-zts-*/{imap,mbstring,pdo_sqlite,sqlite3}.so | grep -E ' => (/usr)?/lib/' | grep -e 'libc-client.so' -e 'libonig.so' -e 'libsqlite3.so' -e 'libzip.so' | wc -l", + ] + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + .map { |cmd| "#{cmd} 2>&1" } + .join("; echo -n '#{delimiter}'; ") + retry_until retry: 3, sleep: 5 do + # must be careful with multiline command strings, as the CLI effectively appends '; echo $?' to the command when using 'heroku run -x' + # we put all commands into a subshell with set -e, so that one failing will abort early, but the following '; echo $?' logic still executes + @run = expect_exit(code: 0) { @app.run("( set -e; #{run_cmds.strip}; )", :return_obj => true) }.output.split(delimiter) + end end after(:all) do @@ -16,30 +34,23 @@ it "picks a version from the desired series" do expect(@app.output).to match(/- php \(#{Regexp.escape(series)}\./) - retry_until retry: 3, sleep: 5 do - expect(@app.run('php -v')).to match(/#{Regexp.escape(series)}\./) - end + expect(@run[0]).to match(/#{Regexp.escape(series)}\./) end it "has Heroku php.ini defaults" do - retry_until retry: 3, sleep: 5 do - ini_output = @app.run('php -i') - expect(ini_output).to match(/date.timezone => UTC/) - .and match(/error_reporting => 30719/) - .and match(/expose_php => Off/) - .and match(/user_ini.cache_ttl => 86400/) - .and match(/variables_order => EGPCS/) - end + expect(@run[1]) + .to match(/date.timezone => UTC/) + .and match(/error_reporting => 30719/) + .and match(/expose_php => Off/) + .and match(/user_ini.cache_ttl => 86400/) + .and match(/variables_order => EGPCS/) end it "uses all available RAM as PHP CLI memory_limit" do - retry_until retry: 3, sleep: 5 do - expect(@app.run("php -i | grep memory_limit")).to match "memory_limit => 536870912 => 536870912" - end + expect(@run[2]).to match("memory_limit => 536870912 => 536870912") end it "is running a PHP build that links against libc-client, libonig, libsqlite3 and libzip from the stack" do - ldd_output = @app.run("ldd .heroku/php/bin/php .heroku/php/lib/php/extensions/no-debug-non-zts-*/{imap,mbstring,pdo_sqlite,sqlite3}.so | grep -E ' => (/usr)?/lib/' | grep -e 'libc-client.so' -e 'libonig.so' -e 'libsqlite3.so' -e 'libzip.so' | wc -l") # 1x libc-client.so for extensions/…/imap.so # 1x libonig for extensions/…/mbstring.so # 1x libsqlite3.so for extensions/…/pdo_sqlite.so @@ -47,9 +58,9 @@ # 1x libsqlite3.so for bin/php (before heroku-22) # 1x libzip.so for bin/php if "heroku-20" == ENV['STACK'] - expect(ldd_output).to match(/^6$/) + expect(@run[3]).to match(/^6$/) else - expect(ldd_output).to match(/^5$/) + expect(@run[3]).to match(/^5$/) end end end diff --git a/test/spec/php_boot_shared.rb b/test/spec/php_boot_shared.rb index a3ddeec95..5c8d88938 100644 --- a/test/spec/php_boot_shared.rb +++ b/test/spec/php_boot_shared.rb @@ -1,4 +1,5 @@ require_relative "spec_helper" +require "securerandom" shared_examples "A PHP application for testing boot options" do |series, server| # the matrix of options and arguments to test @@ -101,39 +102,53 @@ def self.gencmd(args) combinations = interesting.map {|v| genmatrix(matrix, v)}.flatten(1).uniq # # a few more "manual" cases combinations << {0 => "heroku-php-#{server}", "--verbose" => true, "-C" => "conf/#{server}.server.include.conf", "-F" => "conf/fpm.include.conf"} - combinations.each do | combination | + + commands = Array.new + combinations.each do |combination| cmd = gencmd(combination) - context "launching using `#{cmd}'" do - if combination.value?(false) or cmd.match("broken") - it "does not boot" do - retry_until retry: 3, sleep: 5 do - # check if "timeout" exited with a status other than 124, which means the process exited (due to the expected error) before "timeout" stepped in after the given duration (five seconds) and terminated it - expect_exit(expect: :not_to, code: 124) { @app.run("timeout 15 #{cmd}", :return_obj => true) } - end - end - else - it "boots" do - retry_until retry: 3, sleep: 5 do - # check if "waitforit" exited with status 0, which means the process successfully output the expected message - expect_exit(expect: :to, code: 0) { @app.run("./waitforit.sh 15 'ready for connections' #{cmd}", :return_obj => true) } - end - end - end + if combination.value?(false) or cmd.match("broken") + commands << {group: "does not boot", title: "using command #{cmd}", cmd: "timeout 10 #{cmd}", expect: :not_to, operator: :eq, code: 124} + else + commands << {group: "boots", title: "using command #{cmd}", cmd: "./waitforit.sh 10 'ready for connections' #{cmd}", expect: :to, operator: :eq, code: 0} end end - context "launching using too many arguments" do - it "fails to boot" do - retry_until retry: 3, sleep: 5 do - expect_exit(expect: :to, code: 2) { @app.run("timeout 10 heroku-php-#{server} docroot/ anotherarg", :return_obj => true) } - end - end - end + # some more simple arg cases + commands << {group: "does not boot", title: "using too many arguments", cmd: "timeout 10 heroku-php-#{server} docroot/ anotherarg", expect: :to, operator: :eq, code: 2} + commands << {group: "does not boot", title: "using unknown options", cmd: "timeout 10 heroku-php-#{server} --what -u erp", expect: :to, operator: :eq, code: 2} - context "launching using unknown options" do - it "fails to boot" do - retry_until retry: 3, sleep: 5 do - expect_exit(expect: :to, code: 2) { @app.run("timeout 10 heroku-php-#{server} --what -u erp", :return_obj => true) } + commands.group_by { |command| command[:group] }.each do |group, examples| + + context group do + before(:all) do + delimiter = SecureRandom.uuid + # run the command, then print a newline and the exit status (which we also test against) + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + run_cmds = examples + .map { |example| "#{example[:cmd]} 2>&1; echo $'\\n'$?" } + .join("; echo -n '#{delimiter}'; ") + retry_until retry: 3, sleep: 5 do + @run = @app.run(run_cmds).split(delimiter) + end + end + + examples.each_with_index do |example, index| + it example[:title] do + output, _, code = @run[index].rstrip.rpartition("\n") + # in case this one has failed, print what the previous runs have done - maybe something unexpected (but still with correct exit code) happened that can aid debugging + previous = @run.slice(0, index).map.with_index { |run, idx| out, _, status = run.rstrip.rpartition("\n"); "Output for '#{examples[idx][:cmd]}' (exited #{status}):\n#{out}" } + if previous.empty? + previous = "" + else + previous = "\n\nFor reference, here is the output from the previous commands in this run:\n\n#{previous.join("\n\n")}" + end + expect(code).method(example[:expect]).call( + method(example[:operator]).call(example[:code].to_s), + "Expected exit code #{code} #{example[:expect]} be #{example[:operator]} to #{example[:code]}; output for '#{example[:cmd]}':\n#{output}#{previous}" + ) + end end end end diff --git a/test/spec/php_concurrency_shared.rb b/test/spec/php_concurrency_shared.rb index 087757a97..f6aba1660 100644 --- a/test/spec/php_concurrency_shared.rb +++ b/test/spec/php_concurrency_shared.rb @@ -1,4 +1,5 @@ require_relative "spec_helper" +require "securerandom" shared_examples "A PHP application for testing WEB_CONCURRENCY behavior" do |series, server| @@ -15,93 +16,99 @@ @app.teardown! end - context "setting concurrency via .user.ini memory_limit" do - it "calculates concurrency correctly" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt docroot/", :return_obj => true) }.output) + context "setting concurrency via" do + before(:all) do + delimiter = SecureRandom.uuid + run_cmds = [ + "heroku-php-#{server} -tt docroot/", + "heroku-php-#{server} -tt docroot/onegig/", + "heroku-php-#{server} -tt -F conf/fpm.include.conf docroot/", + "heroku-php-#{server} -tt", + "heroku-php-#{server} -tt -F conf/fpm.include.conf", + "heroku-php-#{server} -tt -F conf/fpm.onegig.conf", + "heroku-php-#{server} -tt -F conf/fpm.admin.conf docroot/onegig/", + "heroku-php-#{server} -tt -F conf/fpm.unlimited.conf", + "WEB_CONCURRENCY=22 heroku-php-#{server} -tt", + "WEB_CONCURRENCY=22 heroku-php-#{server} -tt docroot/onegig/", + "WEB_CONCURRENCY=22 heroku-php-#{server} -tt -F conf/fpm.onegig.conf", + "WEB_CONCURRENCY=zomg heroku-php-#{server} -tt", + ] + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + .map { |cmd| "#{cmd} 2>&1" } + .join("; echo -n '#{delimiter}'; ") + retry_until retry: 3, sleep: 5 do + # must be careful with multiline command strings, as the CLI effectively appends '; echo $?' to the command when using 'heroku run -x' + # we put all commands into a subshell with set -e, so that one failing will abort early, but the following '; echo $?' logic still executes + @run = expect_exit(code: 0) { @app.run("( set -e; #{run_cmds}; )", :return_obj => true) }.output.split(delimiter) + end + end + + context ".user.ini memory_limit" do + it "calculates concurrency correctly" do + expect(@run[0]) .to match("PHP memory_limit is 32M Bytes") .and match("pm.max_children = 16") end - end - it "always launches at least one worker" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt docroot/onegig/", :return_obj => true) }.output) + it "always launches at least one worker" do + expect(@run[1]) .to match("PHP memory_limit is 1024M Bytes") .and match("pm.max_children = 1") end - end - it "takes precedence over a PHP-FPM memory_limit" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.include.conf docroot/", :return_obj => true) }.output) + it "takes precedence over a PHP-FPM memory_limit" do + expect(@run[2]) .to match("PHP memory_limit is 32M Bytes") .and match("pm.max_children = 16") end - end - it "is only done for a .user.ini directly in the document root" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt", :return_obj => true) }.output) + it "is only done for a .user.ini directly in the document root" do + expect(@run[3]) .to match("PHP memory_limit is 128M Bytes") .and match("pm.max_children = 4") end end - end - - context "setting concurrency via FPM config memory_limit" do - it "calculates concurrency correctly" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.include.conf", :return_obj => true) }.output) + + context "FPM config memory_limit" do + it "calculates concurrency correctly" do + expect(@run[4]) .to match("PHP memory_limit is 16M Bytes") .and match("pm.max_children = 32") end - end - it "always launches at least one worker" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.onegig.conf", :return_obj => true) }.output) + it "always launches at least one worker" do + expect(@run[5]) .to match("PHP memory_limit is 1024M Bytes") .and match("pm.max_children = 1") end - end - it "takes precedence over a .user.ini memory_limit if it's a php_admin_value" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.admin.conf docroot/onegig/", :return_obj => true) }.output) + it "takes precedence over a .user.ini memory_limit if it's a php_admin_value" do + expect(@run[6]) .to match("PHP memory_limit is 24M Bytes") .and match("pm.max_children = 21") end - end - it "handles a negative (unlimited) memory_limit" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.unlimited.conf", :return_obj => true) }.output) + it "handles a negative (unlimited) memory_limit" do + expect(@run[7]) .to match("PHP memory_limit is unlimited") .and match("pm.max_children = 1") end end - end - - context "setting WEB_CONCURRENCY explicitly" do - it "uses the explicit value" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt", :return_obj => true, :heroku => {:env => "WEB_CONCURRENCY=22"}) }.output) + + context "an explicit WEB_CONCURRENCY var" do + it "uses the explicit value" do + expect(@run[8]) .to match("\\$WEB_CONCURRENCY env var is set, skipping automatic calculation") .and match("pm.max_children = 22") end - end - it "overrides a .user.ini memory_limit" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt docroot/onegig/", :return_obj => true, :heroku => {:env => "WEB_CONCURRENCY=22"}) }.output) + it "overrides a .user.ini memory_limit" do + expect(@run[9]) .to match("\\$WEB_CONCURRENCY env var is set, skipping automatic calculation") .and match("pm.max_children = 22") end - end - it "overrides an FPM config memory_limit" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.onegig.conf", :return_obj => true, :heroku => {:env => "WEB_CONCURRENCY=22"}) }.output) + it "overrides an FPM config memory_limit" do + expect(@run[10]) .to match("\\$WEB_CONCURRENCY env var is set, skipping automatic calculation") .and match("pm.max_children = 22") end - end - it "ignores an illegal value" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("heroku-php-#{server} -tt -F conf/fpm.onegig.conf", :return_obj => true, :heroku => {:env => "WEB_CONCURRENCY=zomg"}) }.output) + it "ignores an illegal value" do + expect(@run[11]) .to match("\\$WEB_CONCURRENCY env var is set, skipping automatic calculation") .and include("Setting WEB_CONCURRENCY=1 (was outside allowed range)") .and match("pm.max_children = 1") @@ -130,38 +137,55 @@ # for these, we fake the CPU core count by "overriding" getconf context "running on a machine with unusual core-to-RAM ratios" do - it "calculates a worker count that does not vastly exceed CPU core capacity" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("getconf() { echo '_NPROCESSORS_ONLN 1'; }; export -f getconf; heroku-php-#{server} -v -tt", :return_obj => true, :heroku => {:size => "Performance-M"}) }.output) - .to match("Available RAM is 2560M Bytes") - .and match("Number of CPU cores is 1") - .and match("Calculated number of workers based on RAM and CPU cores is 10") - .and match("Maximum number of workers that fit available RAM at memory_limit is 20") - .and match("Limiting number of workers to 10") - .and match("pm.max_children = 10") + before(:all) do + delimiter = SecureRandom.uuid + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + run_cmds = [<<~CMD1, <<~CMD2, <<~CMD3].map { |cmd| cmd.strip }.map { |cmd| "#{cmd} 2>&1" }.join("; echo -n '#{delimiter}'; ") + getconf() { echo '_NPROCESSORS_ONLN 1'; } + export -f getconf + heroku-php-#{server} -v -tt 2>&1 + CMD1 + getconf() { echo '_NPROCESSORS_ONLN 16'; } + heroku-php-#{server} -v -tt 2>&1 + CMD2 + getconf() { echo '_NPROCESSORS_ONLN 1'; } + heroku-php-#{server} -v -tt -F conf/fpm.admin.conf 2>&1 + CMD3 + retry_until retry: 3, sleep: 5 do + # must be careful with multiline command strings, as the CLI effectively appends '; echo $?' to the command when using 'heroku run -x' + # we put all commands into a subshell with set -e, so that one failing will abort early, but the following '; echo $?' logic still executes + @run = expect_exit(code: 0) { @app.run("( set -e; #{run_cmds.strip}; )", :return_obj => true, :heroku => {:size => "Performance-M"}) }.output.split(delimiter) end end + + it "calculates a worker count that does not vastly exceed CPU core capacity" do + expect(@run[0]) + .to match(/Available RAM is 2560M Bytes$/) + .and match(/Number of CPU cores is 1$/) + .and match(/Calculated number of workers based on RAM and CPU cores is 10$/) + .and match(/Maximum number of workers that fit available RAM at memory_limit is 20$/) + .and match(/Limiting number of workers to 10$/) + .and match(/pm.max_children = 10$/) + end it "calculates a worker count whose cumulative memory_limit will not exceed available RAM" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("getconf() { echo '_NPROCESSORS_ONLN 16'; }; export -f getconf; heroku-php-#{server} -v -tt", :return_obj => true, :heroku => {:size => "Standard-1X"}) }.output) - .to match("Available RAM is 512M Bytes") - .and match("Number of CPU cores is 16") - .and match("Calculated number of workers based on RAM and CPU cores is 64") - .and match("Maximum number of workers that fit available RAM at memory_limit is 4") - .and match("Limiting number of workers to 4") - .and match("pm.max_children = 4") - end + expect(@run[1]) + .to match(/Available RAM is 2560M Bytes$/) + .and match(/Number of CPU cores is 16$/) + .and match(/Calculated number of workers based on RAM and CPU cores is 160$/) + .and match(/Maximum number of workers that fit available RAM at memory_limit is 20$/) + .and match(/Limiting number of workers to 20$/) + .and match(/pm.max_children = 20$/) end it "calculates a correct worker count for memory_limits that divide available RAM with a remainder" do - retry_until retry: 3, sleep: 5 do - expect(expect_exit(code: 0) { @app.run("getconf() { echo '_NPROCESSORS_ONLN 1'; }; export -f getconf; heroku-php-#{server} -v -tt -F conf/fpm.admin.conf", :return_obj => true, :heroku => {:size => "Performance-M"}) }.output) - .to match("Available RAM is 2560M Bytes") - .and match("Number of CPU cores is 1") - .and match(/Calculated number of workers based on RAM and CPU cores is 53$/) - .and match(/Maximum number of workers that fit available RAM at memory_limit is 106$/) - .and match(/Limiting number of workers to 53$/) - .and match(/pm.max_children = 53$/) - end + expect(@run[2]) + .to match(/Available RAM is 2560M Bytes$/) + .and match(/Number of CPU cores is 1$/) + .and match(/Calculated number of workers based on RAM and CPU cores is 53$/) + .and match(/Maximum number of workers that fit available RAM at memory_limit is 106$/) + .and match(/Limiting number of workers to 53$/) + .and match(/pm.max_children = 53$/) end end end diff --git a/test/spec/php_default_spec.rb b/test/spec/php_default_spec.rb index 69901c593..cfaaacd8a 100644 --- a/test/spec/php_default_spec.rb +++ b/test/spec/php_default_spec.rb @@ -1,45 +1,69 @@ require_relative "spec_helper" +require "securerandom" describe "A PHP application" do context "like the Heroku Getting Started guide example for PHP" do - it "deploys and works" do + it "deploys, works, and re-uses cached dependencies on stack change" do new_app_with_stack_and_platrepo("php-getting-started").deploy do |app| expect(successful_body(app)) + + # we need to test inside this deploy block for the push to work (subsequent deploy or in_directory calls start with a fresh fixture copy and repo) + + next unless "heroku-22" == ENV['STACK'] # testing one stack change is enough + + expect(app.output).to include("Downloading") + app.update_stack("heroku-20") + # we are changing the stack to heroku-20, so we also need to adjust the platform repository accordingly, otherwise, for tests running on branches where HEROKU_PHP_PLATFORM_REPOSITORIES is set to a value, the build would use the wrong repo + app.set_config({"HEROKU_PHP_PLATFORM_REPOSITORIES" => ENV["HEROKU_PHP_PLATFORM_REPOSITORIES"].sub("heroku-22", "heroku-20")}) if ENV["HEROKU_PHP_PLATFORM_REPOSITORIES"] + app.commit! + app.push! + expect(app.output).to_not include("Downloading") end end end context "with just an index.php" do - let(:app) { - new_app_with_stack_and_platrepo('test/fixtures/default') - } - it "picks a default version from the expected series" do - app.deploy do |app| - series = expected_default_php(ENV["STACK"]) - expect(app.output).to match(/- php \(#{Regexp.escape(series)}\./) - retry_until retry: 3, sleep: 5 do - expect(app.run('php -v')).to match(/#{Regexp.escape(series)}\./) - end + before(:all) do + @app = new_app_with_stack_and_platrepo('test/fixtures/default') + @app.deploy + + delimiter = SecureRandom.uuid + run_cmds = [ + "php -v", + "env | grep COMPOSER_", + ] + # there are very rare cases of stderr and stdout getting read (by the dyno runner) slightly out of order + # if that happens, the last stderr line(s) from the program might get picked up after the next thing we echo + # for that reason, we redirect stderr to stdout + .map { |cmd| "#{cmd} 2>&1" } + .join("; echo -n '#{delimiter}'; ") + retry_until retry: 3, sleep: 5 do + # must be careful with multiline command strings, as the CLI effectively appends '; echo $?' to the command when using 'heroku run -x' + # we put all commands into a subshell with set -e, so that one failing will abort early, but the following '; echo $?' logic still executes + @run = expect_exit(code: 0) { @app.run("( set -e; #{run_cmds.strip}; )", :return_obj => true) }.output.split(delimiter) end end - # FIXME re-use deploy + + after(:all) do + @app.teardown! + end + + it "picks a default version from the expected series" do + series = expected_default_php(ENV["STACK"]) + expect(@app.output).to match(/- php \(#{Regexp.escape(series)}\./) + expect(@run[0]).to match(/#{Regexp.escape(series)}\./) + end + it "serves traffic" do - app.deploy do |app| - expect(successful_body(app)) - end + expect(successful_body(@app)) end it "has Composer defaults set" do - app.deploy do |app| - retry_until retry: 3, sleep: 5 do - composer_envs = app.run('env | grep COMPOSER_') - expect(composer_envs) - .to match(/^COMPOSER_MEMORY_LIMIT=536870912$/) - .and match(/^COMPOSER_MIRROR_PATH_REPOS=1$/) - .and match(/^COMPOSER_NO_INTERACTION=1$/) - .and match(/^COMPOSER_PROCESS_TIMEOUT=0$/) - end - end + expect(@run[1]) + .to match(/^COMPOSER_MEMORY_LIMIT=536870912$/) + .and match(/^COMPOSER_MIRROR_PATH_REPOS=1$/) + .and match(/^COMPOSER_NO_INTERACTION=1$/) + .and match(/^COMPOSER_PROCESS_TIMEOUT=0$/) end end end diff --git a/test/spec/platform_spec.rb b/test/spec/platform_spec.rb index de2539f33..bf9635ac2 100644 --- a/test/spec/platform_spec.rb +++ b/test/spec/platform_spec.rb @@ -230,8 +230,10 @@ end context "of a project that uses polyfills providing both bundled-with-PHP and third-party extensions" do + # we set an invalid COMPOSER_AUTH on all of these to stop and fail the build on userland dependency install + # we only need to check what happened during the platform install step, so that speeds things up it "treats polyfills for bundled-with-PHP and third-party extensions the same", :requires_php_on_stack => "7.4" do - new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills').deploy do |app| + new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills', config: { "COMPOSER_AUTH" => "broken" }, allow_failure: true).deploy do |app| expect(app.output).to include("detected userland polyfill packages for PHP extensions") expect(app.output).not_to include("- ext-mbstring") # ext not required by any dependency, so should not be installed or even attempted ("- ext-mbstring...") out_before_polyfills, out_after_polyfills = app.output.split("detected userland polyfill packages for PHP extensions", 2) @@ -244,7 +246,7 @@ end end it "installs native bundled extensions for legacy PHP builds for installer < 1.6 even if they are provided by a polyfill", :requires_php_on_stack => "7.3" do - new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-legacy').deploy do |app| + new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-legacy', config: { "COMPOSER_AUTH" => "broken" }, allow_failure: true).deploy do |app| expect(app.output).to include("detected userland polyfill packages for PHP extensions") expect(app.output).not_to include("- ext-mbstring") # ext not required by any dependency, so should not be installed or even attempted ("- ext-mbstring...") out_before_polyfills, out_after_polyfills = app.output.split("detected userland polyfill packages for PHP extensions", 2) @@ -256,7 +258,7 @@ end end it "solves using the polyfills first and does not downgrade installed packages in the later native install step" do - new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-nodowngrade').deploy do |app| + new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-nodowngrade', config: { "COMPOSER_AUTH" => "broken" }, allow_failure: true).deploy do |app| expect(app.output).to include("detected userland polyfill packages for PHP extensions") expect(app.output).not_to include("- ext-mbstring") # ext not required by any dependency, so should not be installed or even attempted ("- ext-mbstring...") out_before_polyfills, out_after_polyfills = app.output.split("detected userland polyfill packages for PHP extensions", 2) @@ -270,7 +272,7 @@ end end it "ignores a polyfill for an extension that another extension depends upon" do - new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-nointernaldeps').deploy do |app| + new_app_with_stack_and_platrepo('test/fixtures/platform/installer/polyfills-nointernaldeps', config: { "COMPOSER_AUTH" => "broken" }, allow_failure: true).deploy do |app| expect(app.output).to include("detected userland polyfill packages for PHP extensions") # ext-pq got installed... expect(app.output).to include("- ext-pq (") diff --git a/test/utils/waitforit.sh b/test/utils/waitforit.sh index cd1368c39..80f0987f6 100755 --- a/test/utils/waitforit.sh +++ b/test/utils/waitforit.sh @@ -14,7 +14,7 @@ print_help() { ${1:-Execute a given program and terminate after timeout or line match.} Usage: - waitforit [options] + waitforit The given COMMAND will be terminated after the given number of seconds, or the given TEXT_TO_MATCH has matched, whichever comes first. @@ -64,34 +64,57 @@ else grepargs="-q" fi -# First, we spawn a subshell that executes the desired program, wrapped in timeout (as a hard limit to prevent hanging forever if the desired text does not match). -# A trap is set up that fires on SIGPIPE (and SIGUSR1, see note below) and kills the program. -# After the program is launched, we check if it's alive in a loop, and write a dot to the following pipeline -# This writing acts as a check to see whether the following pipeline is still alive - if it is not, that's because it has terminated (see its explanation further below). -# Once the pipeline is gone, our trap fires, and shuts down the program. - -# TODO: have option to suppress output to stderr -( - # we trap SIGPIPE, but also SIGUSR1 - # there are cases where the invoking shell does not allow SIGPIPE traps to be installed - trap 'trap - PIPE USR1; kill -TERM $pid 2> /dev/null || true; wait $pid; exit 0' PIPE USR1 - - # we redirect stderr to stdout so it can be captured as well... - # ... and redirect stdout to a tee that also writes to stderr (so the output is visible) - this is done so that $! is still the pid of the timeout command - timeout $duration "$@" > >(tee >(cat 1>&2)) 2>&1 & pid=$! - - # while the program is alive, write a dot to the following pipeline - # once the following pipeline has finished, the echo will cause a SIGPIPE, which our trap above will catch - # for cases where SIGPIPE handlers are not available, we manually issue a SIGUSR1 to ourselves if the echo fails with an error (due to broken pipe) - while kill -0 $pid 2>/dev/null; do echo "." 2>/dev/null || kill -USR1 $BASHPID; sleep 0.1; done; - - wait $pid || exit $? - - exec 1>&-; -# The following pipeline blocks until grep has matched the desired text. -# Once the match has succeeded, and we're in $pipeout mode, the pipeline that follows us (outside this script), with the user test, will start running (since it is something like `{ read; curl localhost:$PORT/test | grep foo; }`, and the `read` will unblock due to our grep having output something). -# We then keep writing dots to that outer pipeline, which will start failing with SIGPIPE once the outer pipeline has finished executing. -# Once that happens, we break out of the loop, and that will cause the pipeline above (that executed the program) to also hit a SIGPIPE, and shut down the program. -) | { grep --line-buffered $grepargs -E -e "$text" && while test $pipeout; do echo "." 2>/dev/null || break; sleep 0.1; done; exec 1>&-; } - -exit ${PIPESTATUS[0]} +# a temp log file which the program writes to in one 'timeout', and a tail/grep pipeline reads from in another 'timeout' +# this way, the 'tee' that duplicates all output to both the log file and stderr lives until the very end of the program's lifetime and outputs everything +# this is much simpler than chaining the two together using a pipeline, since SIGPIPE propagates through it in a funny manner, and timeout +stdout_log=$(mktemp) +stderr_log=$(mktemp) + +# launch the program wrapped in a timeout, sending stderr to stdout to separate logs while maintaining their respective original "channels" +timeout $duration "$@" > >(tee "$stdout_log") 2> >(tee "$stderr_log" >&2) & pid=$! + +# tail the log file in a timeout, and grep for our expected output +# once the grep returns, we keep writing output to a following pipeline (if there is one), so that a program there can do some stuff - once it's done, our echo attempts will start failing (due to SIGPIPE), and we exit +timeout $duration tail -q -F "$stdout_log" "$stderr_log" > >(grep --line-buffered $grepargs -E -e "$text" && while test $pipeout; do echo "." 2>/dev/null || break; sleep 0.1; done; ) & tid=$! + +# wait for whichever returns first - could be the program "crashing" or timing out, or the tail hitting the grep expression or timing out +wait -n $pid $tid + +# we first check if the tail is still alive, not if the program is still alive +# this allows testing cases where the program exits using a particular message +if kill -0 $tid 2> /dev/null; then + wait $pid + if [[ $? != 124 ]]; then + kill -TERM $tid + fi +fi + +# record the exit status of the first part of the tail pipeline, so that we can differentiate between a timeout (status 124) and a successful match (status 141, SIGPIPE) +wait $tid +pipest=$? + +if [[ "$pipest" == 141 ]]; then + # if we have a match (pipe status 141), then let's shut down the program + # it's likely the program is still alive, as it should be - shut it down, then exit 0, so that the caller can know all was well + kill -TERM $pid 2> /dev/null + # wait and get its real exit status + wait $pid + # exit 0 in all cases + exit 0 +elif [[ "$pipest" != 124 && "$pipest" != 143 ]]; then + # if the tail did not time out, and was not killed by us... that would be weird! + echo "$(basename $0): unexpected status ${pipest} for 'timeout tail'" >&2 +fi + +# the tail/grep pipeline timed out, so we had no match +# we rely on the timeout for the "main" program to kick in +wait $pid + +progst=$? +if [[ "$pipest" != "$progst" ]]; then + # we relay that exit status - it is possible that it did not exit due to timeout, but just early with some error + exit $progst +else + # both timed out, all is well + exit $pipest +fi diff --git a/test/var/log/README.md b/test/var/log/README.md index 76c9982ec..4bee4f9f9 100644 --- a/test/var/log/README.md +++ b/test/var/log/README.md @@ -3,5 +3,3 @@ The `parallel_runtime_rspec.*.log` files in this directory are here on purpose. They're test runtime logs generated by `parallel_tests`, and they are output at the end of a run. They should, for each stack, periodically be copied from the test run logs and updated here in the repository, so that balanced grouping of test runs works well for minimal execution time. - -It's important to include all spec files from the code in the list. You must fake entries if needed for files that are skipped completely (like the PHP series tests, which don't all run on every stack). Otherwise, parallel_tests will not balance things correctly - the --unknown-runtime=1 flag does not work. diff --git a/test/var/log/parallel_runtime_rspec.heroku-20.log b/test/var/log/parallel_runtime_rspec.heroku-20.log index c2b80e8ba..117db5ecd 100644 --- a/test/var/log/parallel_runtime_rspec.heroku-20.log +++ b/test/var/log/parallel_runtime_rspec.heroku-20.log @@ -1,52 +1,54 @@ -test/spec/blackfire-buildpackagent_spec.rb:105 -test/spec/blackfire-herokuagent_spec.rb:130 -test/spec/bugs_spec.rb:30 -test/spec/ci_frameworks_spec.rb:190 -test/spec/ci_spec.rb:130 -test/spec/composer_spec.rb:135 +test/spec/blackfire-buildpackagent_spec.rb:100 +test/spec/blackfire-herokuagent_spec.rb:120 +test/spec/bugs_spec.rb:40 +test/spec/ci_frameworks-a_spec.rb:120 +test/spec/ci_frameworks-k_spec.rb:120 +test/spec/ci_spec.rb:125 +test/spec/composer-1_spec.rb:50 +test/spec/composer-2_spec.rb:90 test/spec/devcenter_spec.rb:5 test/spec/httpd_spec.rb:18 -test/spec/newrelic_spec.rb:110 +test/spec/newrelic_spec.rb:115 test/spec/nginx_spec.rb:49 -test/spec/php-7.3_base_spec.rb:55 -test/spec/php-7.3_boot-apache2_spec.rb:110 -test/spec/php-7.3_boot-nginx_spec.rb:100 -test/spec/php-7.3_concurrency-apache2_spec.rb:130 -test/spec/php-7.3_concurrency-nginx_spec.rb:120 -test/spec/php-7.4_base_spec.rb:55 -test/spec/php-7.4_boot-apache2_spec.rb:110 -test/spec/php-7.4_boot-nginx_spec.rb:100 -test/spec/php-7.4_concurrency-apache2_spec.rb:130 -test/spec/php-7.4_concurrency-nginx_spec.rb:120 -test/spec/php-7.4_sigterm-apache2_spec.rb:55 -test/spec/php-7.4_sigterm-nginx_spec.rb:55 -test/spec/php-8.0_base_spec.rb:55 -test/spec/php-8.0_boot-apache2_spec.rb:110 -test/spec/php-8.0_boot-nginx_spec.rb:100 -test/spec/php-8.0_concurrency-apache2_spec.rb:130 -test/spec/php-8.0_concurrency-nginx_spec.rb:120 -test/spec/php-8.0_sigterm-apache2_spec.rb:55 -test/spec/php-8.0_sigterm-nginx_spec.rb:55 -test/spec/php-8.1_base_spec.rb:55 -test/spec/php-8.1_boot-apache2_spec.rb:110 -test/spec/php-8.1_boot-nginx_spec.rb:100 -test/spec/php-8.1_concurrency-apache2_spec.rb:130 -test/spec/php-8.1_concurrency-nginx_spec.rb:120 -test/spec/php-8.1_sigterm-apache2_spec.rb:55 -test/spec/php-8.1_sigterm-nginx_spec.rb:55 -test/spec/php-8.2_base_spec.rb:55 -test/spec/php-8.2_boot-apache2_spec.rb:110 -test/spec/php-8.2_boot-nginx_spec.rb:100 -test/spec/php-8.2_concurrency-apache2_spec.rb:130 -test/spec/php-8.2_concurrency-nginx_spec.rb:120 -test/spec/php-8.2_sigterm-apache2_spec.rb:55 -test/spec/php-8.2_sigterm-nginx_spec.rb:55 -test/spec/php-8.3_base_spec.rb:55 -test/spec/php-8.3_boot-apache2_spec.rb:110 -test/spec/php-8.3_boot-nginx_spec.rb:100 -test/spec/php-8.3_concurrency-apache2_spec.rb:130 -test/spec/php-8.3_concurrency-nginx_spec.rb:120 -test/spec/php-8.3_sigterm-apache2_spec.rb:55 -test/spec/php-8.3_sigterm-nginx_spec.rb:55 -test/spec/php_default_spec.rb:80 -test/spec/platform_spec.rb:105 +test/spec/php-7.3_base_spec.rb:30 +test/spec/php-7.3_boot-apache2_spec.rb:65 +test/spec/php-7.3_boot-nginx_spec.rb:55 +test/spec/php-7.3_concurrency-apache2_spec.rb:70 +test/spec/php-7.3_concurrency-nginx_spec.rb:65 +test/spec/php-7.4_base_spec.rb:30 +test/spec/php-7.4_boot-apache2_spec.rb:65 +test/spec/php-7.4_boot-nginx_spec.rb:55 +test/spec/php-7.4_concurrency-apache2_spec.rb:70 +test/spec/php-7.4_concurrency-nginx_spec.rb:65 +test/spec/php-7.4_sigterm-apache2_spec.rb:70 +test/spec/php-7.4_sigterm-nginx_spec.rb:70 +test/spec/php-8.0_base_spec.rb:30 +test/spec/php-8.0_boot-apache2_spec.rb:65 +test/spec/php-8.0_boot-nginx_spec.rb:55 +test/spec/php-8.0_concurrency-apache2_spec.rb:70 +test/spec/php-8.0_concurrency-nginx_spec.rb:65 +test/spec/php-8.0_sigterm-apache2_spec.rb:70 +test/spec/php-8.0_sigterm-nginx_spec.rb:70 +test/spec/php-8.1_base_spec.rb:30 +test/spec/php-8.1_boot-apache2_spec.rb:65 +test/spec/php-8.1_boot-nginx_spec.rb:55 +test/spec/php-8.1_concurrency-apache2_spec.rb:70 +test/spec/php-8.1_concurrency-nginx_spec.rb:65 +test/spec/php-8.1_sigterm-apache2_spec.rb:70 +test/spec/php-8.1_sigterm-nginx_spec.rb:70 +test/spec/php-8.2_base_spec.rb:30 +test/spec/php-8.2_boot-apache2_spec.rb:65 +test/spec/php-8.2_boot-nginx_spec.rb:55 +test/spec/php-8.2_concurrency-apache2_spec.rb:70 +test/spec/php-8.2_concurrency-nginx_spec.rb:65 +test/spec/php-8.2_sigterm-apache2_spec.rb:70 +test/spec/php-8.2_sigterm-nginx_spec.rb:70 +test/spec/php-8.3_base_spec.rb:30 +test/spec/php-8.3_boot-apache2_spec.rb:65 +test/spec/php-8.3_boot-nginx_spec.rb:55 +test/spec/php-8.3_concurrency-apache2_spec.rb:70 +test/spec/php-8.3_concurrency-nginx_spec.rb:65 +test/spec/php-8.3_sigterm-apache2_spec.rb:70 +test/spec/php-8.3_sigterm-nginx_spec.rb:70 +test/spec/php_default_spec.rb:50 +test/spec/platform_spec.rb:100 diff --git a/test/var/log/parallel_runtime_rspec.heroku-22.log b/test/var/log/parallel_runtime_rspec.heroku-22.log index ff854a4f1..46f94f5f1 100644 --- a/test/var/log/parallel_runtime_rspec.heroku-22.log +++ b/test/var/log/parallel_runtime_rspec.heroku-22.log @@ -1,33 +1,34 @@ -test/spec/blackfire-buildpackagent_spec.rb:105 -test/spec/blackfire-herokuagent_spec.rb:130 -test/spec/bugs_spec.rb:30 -test/spec/ci_frameworks_spec.rb:190 -test/spec/ci_spec.rb:130 -test/spec/composer_spec.rb:120 +test/spec/blackfire-buildpackagent_spec.rb:100 +test/spec/blackfire-herokuagent_spec.rb:120 +test/spec/bugs_spec.rb:40 +test/spec/ci_frameworks-a_spec.rb:120 +test/spec/ci_frameworks-k_spec.rb:120 +test/spec/ci_spec.rb:125 +test/spec/composer-2_spec.rb:90 test/spec/devcenter_spec.rb:5 test/spec/httpd_spec.rb:18 -test/spec/newrelic_spec.rb:110 +test/spec/newrelic_spec.rb:115 test/spec/nginx_spec.rb:49 -test/spec/php-8.1_base_spec.rb:55 -test/spec/php-8.1_boot-apache2_spec.rb:110 -test/spec/php-8.1_boot-nginx_spec.rb:100 -test/spec/php-8.1_concurrency-apache2_spec.rb:130 -test/spec/php-8.1_concurrency-nginx_spec.rb:120 -test/spec/php-8.1_sigterm-apache2_spec.rb:55 -test/spec/php-8.1_sigterm-nginx_spec.rb:55 -test/spec/php-8.2_base_spec.rb:55 -test/spec/php-8.2_boot-apache2_spec.rb:110 -test/spec/php-8.2_boot-nginx_spec.rb:100 -test/spec/php-8.2_concurrency-apache2_spec.rb:130 -test/spec/php-8.2_concurrency-nginx_spec.rb:120 -test/spec/php-8.2_sigterm-apache2_spec.rb:55 -test/spec/php-8.2_sigterm-nginx_spec.rb:55 -test/spec/php-8.3_base_spec.rb:55 -test/spec/php-8.3_boot-apache2_spec.rb:110 -test/spec/php-8.3_boot-nginx_spec.rb:100 -test/spec/php-8.3_concurrency-apache2_spec.rb:130 -test/spec/php-8.3_concurrency-nginx_spec.rb:120 -test/spec/php-8.3_sigterm-apache2_spec.rb:55 -test/spec/php-8.3_sigterm-nginx_spec.rb:55 -test/spec/php_default_spec.rb:80 -test/spec/platform_spec.rb:65 +test/spec/php-8.1_base_spec.rb:30 +test/spec/php-8.1_boot-apache2_spec.rb:65 +test/spec/php-8.1_boot-nginx_spec.rb:55 +test/spec/php-8.1_concurrency-apache2_spec.rb:70 +test/spec/php-8.1_concurrency-nginx_spec.rb:65 +test/spec/php-8.1_sigterm-apache2_spec.rb:70 +test/spec/php-8.1_sigterm-nginx_spec.rb:70 +test/spec/php-8.2_base_spec.rb:30 +test/spec/php-8.2_boot-apache2_spec.rb:65 +test/spec/php-8.2_boot-nginx_spec.rb:55 +test/spec/php-8.2_concurrency-apache2_spec.rb:70 +test/spec/php-8.2_concurrency-nginx_spec.rb:65 +test/spec/php-8.2_sigterm-apache2_spec.rb:70 +test/spec/php-8.2_sigterm-nginx_spec.rb:70 +test/spec/php-8.3_base_spec.rb:30 +test/spec/php-8.3_boot-apache2_spec.rb:65 +test/spec/php-8.3_boot-nginx_spec.rb:55 +test/spec/php-8.3_concurrency-apache2_spec.rb:70 +test/spec/php-8.3_concurrency-nginx_spec.rb:65 +test/spec/php-8.3_sigterm-apache2_spec.rb:70 +test/spec/php-8.3_sigterm-nginx_spec.rb:70 +test/spec/php_default_spec.rb:60 +test/spec/platform_spec.rb:60