From e3f6ea6b48308e26a2bf36c37cd86638a4bc0608 Mon Sep 17 00:00:00 2001 From: mhenrixon Date: Sat, 12 Sep 2026 14:39:03 +0200 Subject: [PATCH 1/3] perf(boot): wait for readiness on the host and take the container id from docker run MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Two round trips come out of every boot, and one of them scaled with how long a container takes to come up. `Dash::Commands::App#wait_for_ready` builds a shell loop that evaluates the same status the poller used to read one round trip at a time — docker's health status, or the `healthcheck: exec:` probe's exit code — returns the moment that status is one the poller accepts, and otherwise keeps looking until deploy_timeout. Boot runs it as a single capture with an interaction handler attached, so the "Container not ready yet" beacons still print once a second while it waits. Progress goes to stderr and the final status to stdout, which keeps the captured value the status and nothing else. `docker run --detach` already prints the id of the container it started, so the proxy target is read out of the run rather than asked for again on the next round trip. Per host: a proxy role pays 6 instead of 7, a healthchecked role without a proxy pays 5 instead of 4 + one per poll attempt, an unchecked role 6. Every readiness decision stays in Dash::Cli::Healthcheck::Poller, word for word — drift, the missing-gate warning, the readiness-delay confirm, the timeout error. The host loop only decides when to return, never what it means, and Dash::Commands::Base::READY_STATUSES is the one thing both sides read. `unhealthy` deliberately does NOT return early, against the issue's proposal: dash's default healthcheck probes every second with no start period and docker's default is three retries, so an app slower than ~3s to serve /up reports `unhealthy` long before it is up. Waiting through it is what the client-side poll did, and what keeps a normal Rails boot passing. ## Test Coverage - exact command strings for both branches of the wait, including the deadline and that timeout: 0 makes exactly one observation - the streaming handler against chunks split mid-line, and against lines that are not its own - the poller's new call pattern: one wait for a healthchecked role, wait plus confirm for an unchecked one, and no second wait after an unacceptable result - at the boot level: the proxy target read from the run, one readiness round trip for a healthchecked role, two for an unchecked one, the interaction handler and raise_on_non_zero_exit wiring, and a deadline that fails once ## Verification - [x] bundle exec rubocop --parallel passes - [x] unit tests pass (1899 runs) - [x] bin/test passes (1918 runs, integration included) - [x] the generated loop run under a real POSIX sh against a fake docker Refs #163 --- docs/app/views/docs/pages/worker_roles.rb | 16 +- lib/dash/cli/app/boot.rb | 39 ++-- lib/dash/cli/healthcheck/poller.rb | 18 +- lib/dash/cli/healthcheck/progress_reporter.rb | 35 ++++ lib/dash/commands/app.rb | 32 ++++ lib/dash/commands/base.rb | 16 ++ lib/dash/configuration/docs/role.yml | 14 +- test/cli/app_test.rb | 173 +++++++++++++----- test/cli/cli_test_case.rb | 56 ++++++ test/cli/healthcheck/poller_test.rb | 51 ++++++ .../cli/healthcheck/progress_reporter_test.rb | 43 +++++ test/cli/main_test.rb | 16 +- test/cli/proxy_test.rb | 12 +- test/commands/app_test.rb | 28 +++ 14 files changed, 458 insertions(+), 91 deletions(-) create mode 100644 lib/dash/cli/healthcheck/progress_reporter.rb create mode 100644 test/cli/healthcheck/progress_reporter_test.rb diff --git a/docs/app/views/docs/pages/worker_roles.rb b/docs/app/views/docs/pages/worker_roles.rb index 9a51e100..a25c467f 100644 --- a/docs/app/views/docs/pages/worker_roles.rb +++ b/docs/app/views/docs/pages/worker_roles.rb @@ -122,8 +122,8 @@ def supervisor_readyz md <<~'MD' Read it against the boot sequence: docker starts probing five seconds in, ignores failures for the first sixty (`start_period`), and marks the - container `healthy` on the first `200`. dash polls docker's verdict with - backoff until `deploy_timeout`, then stops the old container — which is + container `healthy` on the first `200`. dash waits on docker's verdict + until `deploy_timeout`, then stops the old container — which is told to stop and given `stop_timeout` seconds to finish. Three straight failures after the start period mark it `unhealthy`, and a boot that never reaches `healthy` fails with the container log and the probe @@ -299,15 +299,15 @@ def exec_probes `healthcheck: exec:` is the escape hatch for an image whose `HEALTHCHECK` you cannot change, or for an emergency override with no rebuild. Instead of configuring docker's healthcheck, dash `docker - exec`s the probe from the deploy host on every poll and gates the boot - on its exit code. It may use `${...}` (quoted through to the container), + exec`s the probe on the deploy host once a second and gates the boot on + its exit code. It may use `${...}` (quoted through to the container), which `cmd` may not. It is strictly worse than `cmd` in the general case: deploy-time only - (docker never runs it, `docker ps` never shows `(healthy)`), an SSH round - trip plus a process spawn per poll, and it cannot be combined with - `cmd`, `port`, `path`, or any duration key. The trade-offs are spelled - out under `healthcheck` in the [Roles reference](/docs/role). + (docker never runs it, `docker ps` never shows `(healthy)`), a process + spawn on the host per attempt, and it cannot be combined with `cmd`, + `port`, `path`, or any duration key. The trade-offs are spelled out + under `healthcheck` in the [Roles reference](/docs/role). MD DocsUI::Code(<<~YAML, filename: "config/deploy.yml", lexer: :yaml) healthcheck: diff --git a/lib/dash/cli/app/boot.rb b/lib/dash/cli/app/boot.rb index 2d863a6c..c4eac452 100644 --- a/lib/dash/cli/app/boot.rb +++ b/lib/dash/cli/app/boot.rb @@ -1,4 +1,9 @@ class Dash::Cli::App::Boot + # What `docker container ls --quiet` prints, and so what dash-proxy has always been + # handed as a target. `docker run --detach` prints the full 64-character id, so the + # target is its first twelve characters rather than a round trip of its own. + SHORT_CONTAINER_ID_LENGTH = 12 + attr_reader :host, :role, :version, :barrier, :sshkit, :cli delegate :execute, :capture_with_info, :capture_with_pretty_json, :info, :error, :upload!, to: :sshkit delegate :run_hook, to: :cli @@ -69,9 +74,13 @@ def start_new_version execute *auditor.record_then("Booted app version #{version}", app.ensure_env_directory) upload! role.secrets_io(host), role.secrets_path, mode: "0600" - execute *app.run(hostname: hostname) + # `docker run --detach` prints the id of the container it just started, so the + # proxy target comes out of the run itself — asking docker for it again was a round + # trip spent re-reading something the host had already said. + container_id = capture_with_info(*app.run(hostname: hostname)).strip + if running_proxy? - endpoint = capture_with_info(*app.container_id_for_version(version)).strip + endpoint = container_id[0, SHORT_CONTAINER_ID_LENGTH] raise Dash::Cli::BootError, "Failed to get endpoint for #{role} on #{host}, did the container boot?" if endpoint.empty? run_hook "pre-proxy-deploy", hosts: host.to_s, role: role.name @@ -79,7 +88,7 @@ def start_new_version timing_healthy { execute *app.deploy(target: endpoint) } run_hook "post-proxy-deploy", hosts: host.to_s, role: role.name else - timing_healthy { Dash::Cli::Healthcheck::Poller.wait_for_healthy(role: role) { health_status } } + timing_healthy { Dash::Cli::Healthcheck::Poller.wait_for_healthy(role: role, &method(:readiness_status)) } end rescue => e error "Failed to boot #{role} on #{host}" @@ -87,17 +96,19 @@ def start_new_version raise e end - # An exec probe is docker-invisible — the container declares no healthcheck, so - # `docker inspect` would only ever report its state. Poll the probe instead. - def health_status - role.healthcheck&.exec? ? exec_probe_status : capture_with_info(*app.status(version: version)) - end - - def exec_probe_status - execute *app.health_probe(version: version) - "healthy" - rescue SSHKit::Command::Failed - "exec probe exited non-zero" + # A role behind the proxy lets `dash-proxy deploy` block on the host until the + # container is healthy; a role without one now does the same, waiting in a shell loop + # on the host that streams its progress back rather than being polled from here once + # per attempt. The poller asks for the wait, and — only for an unchecked container it + # has just let through its readiness delay — for a plain confirming read. + def readiness_status(mode, seconds_left = nil) + if mode == :confirm + capture_with_info(*app.status(version: version)) + else + capture_with_info *app.wait_for_ready(version: version, timeout: seconds_left), + interaction_handler: Dash::Cli::Healthcheck::ProgressReporter.new, + raise_on_non_zero_exit: false + end end # Every failed boot gets the container log, and the health probe history when the diff --git a/lib/dash/cli/healthcheck/poller.rb b/lib/dash/cli/healthcheck/poller.rb index 939b6039..60bb3db3 100644 --- a/lib/dash/cli/healthcheck/poller.rb +++ b/lib/dash/cli/healthcheck/poller.rb @@ -3,13 +3,19 @@ module Dash::Cli::Healthcheck::Poller NO_HEALTHCHECK = Dash::Commands::Base::NO_HEALTHCHECK + # The wait itself happens on the host now (Dash::Commands::App#wait_for_ready), which + # returns the moment the status is one this poller accepts and otherwise waits out the + # deadline it is given. So the block is called once for the wait - and once more only to + # confirm an unchecked container is still running after its readiness delay. Every + # decision below is the one the client-side poll made, in the same words; what shrank is + # the number of round trips it took to reach them. def wait_for_healthy(role:, &block) attempt = 1 timeout_at = Time.now + DASH.config.deploy_timeout readiness_delay = role.readiness_delay begin - status = block.call + status = block.call(:wait, seconds_left(timeout_at)) if unchecked?(status) ensure_no_healthcheck_drift(role, status) @@ -20,7 +26,7 @@ def wait_for_healthy(role:, &block) # Wait for the readiness delay and confirm it is still running if readiness_delay > 0 sleep readiness_delay - status = block.call + status = block.call(:confirm) ensure_no_healthcheck_drift(role, status) end end @@ -55,8 +61,14 @@ def docker_state(status) status.to_s.delete_prefix("#{NO_HEALTHCHECK}:") end + # Shared with the host-side wait, which stops looking on exactly these - see + # Dash::Commands::Base::READY_STATUSES for why the two have to agree. def acceptable?(status) - status == "healthy" || (unchecked?(status) && docker_state(status) == "running") + Dash::Commands::Base::READY_STATUSES.include?(status) + end + + def seconds_left(timeout_at) + [ (timeout_at - Time.now).ceil, 0 ].max end # The config asked docker to probe this container and docker is not probing it — the flags diff --git a/lib/dash/cli/healthcheck/progress_reporter.rb b/lib/dash/cli/healthcheck/progress_reporter.rb new file mode 100644 index 00000000..5d2a2b24 --- /dev/null +++ b/lib/dash/cli/healthcheck/progress_reporter.rb @@ -0,0 +1,35 @@ +# Turns the server-side readiness wait's progress lines back into the beacon the +# client-side poll used to print. It is an SSHKit interaction handler, so it sees the +# wait's stderr as it streams — the operator gets the same once-a-second feedback they +# got when the laptop was the thing doing the polling, for one round trip instead of one +# per attempt. The cadence is fixed at a second because the host loop's is. +# +# The stream is line-oriented but arrives in chunks (the SSH backend splits on packet +# boundaries, not newlines), so data is buffered and only whole lines are reported. The +# line format is the only filter: the wait's stdout carries the final status, and the +# host's own noise is none of this class's business. +class Dash::Cli::Healthcheck::ProgressReporter + LINE = /\A#{Regexp.escape(Dash::Commands::Base::READINESS_PROGRESS_PREFIX)} (?\d+) (?\d+)(?: |\z)/ + + def initialize + @buffer = +"" + @mutex = Mutex.new + end + + # SSHKit's interaction-handler contract. + def on_data(_command, _stream_name, data, _channel = nil) + @mutex.synchronize do + @buffer << data.to_s + while (newline = @buffer.index("\n")) + report @buffer.slice!(0..newline).chomp + end + end + end + + private + def report(line) + match = LINE.match(line) or return + + SSHKit.config.output.info "Container not ready yet, retrying in 1s (#{match[:elapsed]}s elapsed, #{match[:left]}s left)" + end +end diff --git a/lib/dash/commands/app.rb b/lib/dash/commands/app.rb index 037d4de4..ae2bbf72 100644 --- a/lib/dash/commands/app.rb +++ b/lib/dash/commands/app.rb @@ -60,6 +60,27 @@ def health_probe(version:) docker :exec, container_name(version), *shell([ role.healthcheck.exec ]) end + # Waits on the host for the container to reach a status the poller accepts, so a boot + # pays one round trip for the wait however long the container takes to come up - the + # client-side poll paid one per attempt. Exits 0 with that status on stdout the moment + # it sees one of READY_STATUSES; otherwise it reports progress on stderr once a second + # and, at the deadline, prints the last status it saw and exits non-zero. Waiting through + # every other status is deliberate: docker reports a container `unhealthy` after three + # failed probes, which for an app slower than that is a state it recovers from. + def wait_for_ready(version:, timeout:) + shell [ + "started=$(date +%s);", + "while true; do", + *readiness_probe(version: version), + "case \"$status\" in #{READY_STATUSES.join("|")}) echo \"$status\"; exit 0;; esac;", + "elapsed=$(( $(date +%s) - started ));", + "if [ \"$elapsed\" -ge #{timeout.to_i} ]; then echo \"$status\"; exit 1; fi;", + "echo \"#{READINESS_PROGRESS_PREFIX} $elapsed $(( #{timeout.to_i} - elapsed )) $status\" 1>&2;", + "sleep 1;", + "done" + ] + end + def stop(version: nil) pipe \ version ? container_id_for_version(version) : current_running_container_id, @@ -120,6 +141,17 @@ def ensure_env_directory end private + # The same two readiness sources #status and #health_probe cover, read into `$status` + # so the loop around them is the same either way. Both swallow their own stderr: the + # wait's stderr is the progress channel, and nothing else may appear on it. + def readiness_probe(version:) + if role.healthcheck&.exec? + [ "if", *health_probe(version: version), ">/dev/null 2>&1;", "then status=healthy;", "else status=\"#{EXEC_PROBE_FAILED}\";", "fi;" ] + else + [ "status=$({", *status(version: version), ";} 2>/dev/null);" ] + end + end + def latest_image_id docker :image, :ls, *argumentize("--filter", "reference=#{config.latest_image}"), "--format", "'{{.ID}}'" end diff --git a/lib/dash/commands/base.rb b/lib/dash/commands/base.rb index 2c5b67a6..dab1de77 100644 --- a/lib/dash/commands/base.rb +++ b/lib/dash/commands/base.rb @@ -10,6 +10,22 @@ class Base DOCKER_HEALTH_STATUS_FORMAT = "'{{if .State.Health}}{{.State.Health.Status}}{{else}}#{NO_HEALTHCHECK}:{{.State.Status}}{{end}}'" + # The statuses a boot accepts as ready. Dash::Cli::Healthcheck::Poller decides what a + # status means; Dash::Commands::App#wait_for_ready only decides when to stop looking, + # and it stops on exactly these. The two must agree: a status the host loop returned + # early for that the poller would not accept fails a boot the old client-side poll + # would have waited out. + READY_STATUSES = [ "healthy", "#{NO_HEALTHCHECK}:running" ].freeze + + # What a `healthcheck: exec:` probe reports when it exits non-zero. Produced by the + # host-side wait, read back by the poller, so it is a wire format, not a message. + EXEC_PROBE_FAILED = "exec probe exited non-zero" + + # The line #wait_for_ready prints to stderr on every attempt, read back by + # Dash::Cli::Healthcheck::ProgressReporter. stderr, because a capture returns stdout + # alone - which keeps the captured value the final status and nothing else. + READINESS_PROGRESS_PREFIX = "dash-readiness" + attr_accessor :config def initialize(config) diff --git a/lib/dash/configuration/docs/role.yml b/lib/dash/configuration/docs/role.yml index a34d0dba..06e26828 100644 --- a/lib/dash/configuration/docs/role.yml +++ b/lib/dash/configuration/docs/role.yml @@ -107,22 +107,22 @@ servers: # A `healthcheck` cannot be combined with `health-*` keys under `options`. # # `exec` is the escape hatch for an image whose HEALTHCHECK you cannot change, - # or for an emergency override without a rebuild. Kamal `docker exec`s it from - # the deploy host on every poll and gates the deploy on the exit code — no HTTP + # or for an emergency override without a rebuild. Dash `docker exec`s it on the + # deploy host once a second and gates the deploy on the exit code — no HTTP # server and no published port needed, and unlike `cmd` it may use `${...}`, # which is quoted through to the container. It is strictly worse than `cmd` in # the general case, so reach for it only when `cmd` is not available: # # - deploy-time only. Docker never runs it, so `docker ps` never shows # `(healthy)` and `docker inspect` keeps no probe history. - # - each poll costs an SSH round trip plus a process spawn (~100-300ms), which - # rules out sub-second polling. + # - each attempt costs a process spawn on the host (the whole wait is one SSH + # round trip, so the cost does not grow with how long the boot takes). # - nothing outside a deploy ever runs it. # # `exec` replaces docker's healthcheck rather than configuring it, so it cannot - # be combined with `cmd`, `port`, `path`, or any of the duration keys. Polling - # follows the deploy's own backoff and gives up at `deploy_timeout`; a probe that - # never exits zero fails the boot and leaves the old container running. + # be combined with `cmd`, `port`, `path`, or any of the duration keys. The wait + # gives up at `deploy_timeout`; a probe that never exits zero fails the boot and + # leaves the old container running. # # A non-proxied role with neither a `healthcheck` nor a `health-cmd` option # warns on every deploy, because the readiness delay is the only thing standing diff --git a/test/cli/app_test.rb b/test/cli/app_test.rb index fa0f4857..c1b60ec6 100644 --- a/test/cli/app_test.rb +++ b/test/cli/app_test.rb @@ -21,9 +21,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123" - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-web-latest$'", "--quiet") - .returns("12345678") # running version + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("boot").tap do |output| assert_match /Renaming container .* to .* as already deployed on 1.1.1.1/, output # Rename @@ -45,9 +43,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "latest" - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-web-latest$'", "--quiet") - .returns("12345678") + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("boot").tap do |output| renamed = output[/docker rename app-web-latest (app-web-latest_replaced_[0-9a-f]{16})/, 1] @@ -92,6 +88,93 @@ class CliAppTest < CliTestCase end end + # `docker run --detach` prints the id of the container it started, so the proxy target is + # read out of the run itself. The 12 characters are what `docker container ls --quiet` + # used to print, which is the target dash-proxy has always been handed. + test "boot takes the proxy target from the run rather than asking docker for the id again" do + stub_running + stub_run_capture id: "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef" + + captures = recorded_captures do + run_command("boot").tap do |output| + assert_match 'dash-proxy deploy app-web --target="0123456789ab:80"', output + end + end + + assert_equal 0, captures.count { |capture| capture.end_with?("'name=^app-web-latest$' --quiet") }, + "the container id read should be gone: #{captures.inspect}" + end + + # The readiness wait blocks on the host until the container is ready or the deadline + # passes, so a healthchecked role pays one round trip for it however long the container + # takes - the client-side poll paid one per attempt, and the slower the boot the more. + test "a healthchecked role without a proxy pays one round trip for the whole wait" do + stub_running + stub_readiness_wait "healthy", expect: true + + captures = recorded_captures do + run_command("boot", config: :with_readiness_sources, host: "1.1.1.5").tap do |output| + assert_match /Container is healthy!/, output + end + end + + assert_equal 1, captures.count { |capture| readiness_wait_command?(capture) }, captures.inspect + assert_equal 0, captures.count { |capture| status_read?(capture) }, captures.inspect + end + + # An unchecked container is accepted on its readiness delay alone, and the delay is spent + # on the laptop - so it still costs one fresh read afterwards. That is the one readiness + # round trip the host-side wait cannot fold away. + test "an unchecked role waits on the host, then confirms once after the readiness delay" do + stub_running + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running", expect: true + + captures = recorded_captures do + run_command("boot", config: :with_readiness_sources, host: "1.1.1.3").tap do |output| + assert_match /workers has no healthcheck/, output + assert_match /Container is healthy!/, output + end + end + + assert_equal 1, captures.count { |capture| readiness_wait_command?(capture) }, captures.inspect + assert_equal 1, captures.count { |capture| status_read?(capture) }, captures.inspect + end + + # The wait runs for as long as it may take, so the progress an operator sees has to come + # back over that same command while it is still running - and the deadline has to reach + # the poller as a status rather than as a failed command, or the poller never gets to + # phrase the error. + test "the readiness wait streams its progress back and lets the poller judge the result" do + stub_running + options = nil + stub_capture { |args| readiness_wait?(args).tap { |matched| options = args.grep(Hash).last if matched } }.returns("healthy") + + run_command("boot", config: :with_readiness_sources, host: "1.1.1.5") + + assert_instance_of Dash::Cli::Healthcheck::ProgressReporter, options[:interaction_handler] + assert_equal false, options[:raise_on_non_zero_exit] + end + + # The host loop only returns early for a status the poller accepts, so anything else it + # returns means the deadline passed - and the poller must not spend another wait on it. + test "a readiness wait that hits its deadline fails once, with the status it last saw" do + Thread.report_on_exception = false + stub_running + Dash::Configuration.any_instance.stubs(:deploy_timeout).returns(0) + stub_readiness_wait "starting" + + error = nil + captures = recorded_captures do + error = assert_raises(SSHKit::Runner::ExecuteError) { run_command("boot", config: :with_readiness_sources, host: "1.1.1.5") } + end + + assert_match "container not ready after 0 seconds (starting)", error.message + assert_equal 1, captures.count { |capture| readiness_wait_command?(capture) }, captures.inspect + ensure + Thread.report_on_exception = true + end + test "boot uses group strategy when specified" do Dash::Cli::App.any_instance.stubs(:on).with("1.1.1.1").twice Dash::Cli::App.any_instance.stubs(:on).with([ "1.1.1.1", "1.1.1.2", "1.1.1.3", "1.1.1.4" ]).times(3) @@ -215,9 +298,8 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" run_command("boot", config: :with_boot_canary, host: nil).tap do |output| assert_match "First web container is healthy on 1.1.1.1, booting any other roles", output @@ -276,9 +358,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123" - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-web-latest$'", "--quiet") - .returns("12345678") # running version + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("boot", config: :with_assets).tap do |output| assert_match "docker tag dhh/app:latest dhh/app:latest", output @@ -295,9 +375,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123" - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-web-latest$'", "--quiet") - .returns("12345678") # running version + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("boot", config: :with_env_tags).tap do |output| assert_match "docker tag dhh/app:latest dhh/app:latest", output @@ -312,9 +390,8 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" run_command("boot", config: :with_roles, host: nil).tap do |output| assert_match "Waiting for the first healthy web container before booting workers on 1.1.1.3...", output @@ -332,9 +409,8 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" run_command("boot", config: :with_role_boot, host: nil).tap do |output| assert_match "Waiting for the first healthy web container before booting workers on 1.1.1.3...", output @@ -388,9 +464,7 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("unhealthy").at_least_once # workers health check + stub_readiness_wait "unhealthy", expect: true run_command("boot", config: :with_roles, host: nil, allow_execute_error: true).tap do |output| assert_match "Waiting for the first healthy web container before booting workers on 1.1.1.3...", output @@ -412,9 +486,8 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running", "no-healthcheck:stopped").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:stopped", expect: true run_command("boot", config: :with_roles, host: "1.1.1.3", allow_execute_error: true).tap do |output| assert_match "ERROR Failed to boot workers on 1.1.1.3", output @@ -431,9 +504,7 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("unhealthy") # workers health check + stub_readiness_wait "unhealthy" SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", "xargs docker logs --timestamps 2>&1") @@ -462,9 +533,7 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:stopped") # workers has no healthcheck, container just died + stub_readiness_wait "no-healthcheck:stopped" SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info) .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", "xargs docker logs --timestamps 2>&1") @@ -489,9 +558,8 @@ class CliAppTest < CliTestCase SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" run_command("boot", config: :with_only_workers, host: nil).tap do |output| assert_match /First workers container is healthy on 1.1.1.\d, booting any other roles/, output @@ -859,6 +927,7 @@ class CliAppTest < CliTestCase test "boot proxy" do SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false + stub_run_capture run_command("boot", config: :with_proxy).tap do |output| assert_match /Renaming container .* to .* as already deployed on 1.1.1.1/, output # Rename @@ -1018,11 +1087,15 @@ class CliAppTest < CliTestCase assert @executions.any? { |args| args.first == ".dash/hooks/post-app-stop" } end + # The probe runs inside the host-side wait now, once a second there rather than once per + # round trip from here — but it is still the same `docker exec`, and its exit code is + # still the whole gate. test "boot gates a role with an exec healthcheck on the probe's exit code" do stub_running + stub_readiness_wait "healthy", expect: true run_command("boot", config: :with_readiness_sources, host: "1.1.1.8").tap do |output| - assert_match "docker exec app-prober-latest sh -c 'bin/ready-check'", output + assert_match %r{if docker exec app-prober-latest sh -c '\\''bin/ready-check'\\'' >/dev/null 2>&1}, output assert_match /Container is healthy!/, output assert_no_match %r{--health-cmd}, output end @@ -1032,18 +1105,18 @@ class CliAppTest < CliTestCase Dash::Configuration.any_instance.stubs(:deploy_timeout).returns(0) SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: "12345678", running: "123", expect: false + stub_run_capture + stub_readiness_wait Dash::Commands::Base::EXEC_PROBE_FAILED @executions = [] - SSHKit::Backend::Abstract.any_instance.stubs(:execute) - .with { |*args| @executions << args; !args.join(" ").include?("bin/ready-check") } - SSHKit::Backend::Abstract.any_instance.stubs(:execute) - .with { |*args| args.join(" ").include?("bin/ready-check") } - .raises(SSHKit::Command::Failed.new("probe failed")) + SSHKit::Backend::Abstract.any_instance.stubs(:execute).with { |*args| @executions << args; true } - stderred { run_command("boot", config: :with_readiness_sources, host: "1.1.1.8", allow_execute_error: true) } + captures = recorded_captures do + stderred { run_command("boot", config: :with_readiness_sources, host: "1.1.1.8", allow_execute_error: true) } + end - assert @executions.any? { |args| args.join(" ").include?("sh -c 'bin/ready-check'") }, "expected the probe to have run" - assert @executions.any? { |args| args.join(" ").include?("docker run") }, "expected the new container to have booted" + assert captures.any? { |capture| capture.include?("bin/ready-check") }, "expected the probe to have run" + assert captures.any? { |capture| capture.include?("docker run") }, "expected the new container to have booted" assert @executions.none? { |args| args.join(" ").include?("app-prober-123") }, "expected the old container to be left alone" end @@ -1148,6 +1221,15 @@ def stub_rollout_target_not_deployed .returns("12345678") end + def readiness_wait_command?(capture) + capture.include?(Dash::Commands::Base::READINESS_PROGRESS_PREFIX) + end + + # The plain status read, which the wait command also embeds - hence the exclusion. + def status_read?(capture) + capture.include?(Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) && !readiness_wait_command?(capture) + end + def run_command(*command, config: :with_accessories, host: "1.1.1.1", allow_execute_error: false) stdouted do Dash::Cli::App.start([ *command, "-c", "test/fixtures/deploy_#{config}.yml", *([ "--hosts", host ] if host) ]) @@ -1169,6 +1251,7 @@ def stub_running SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).returns("123") # container id stub_boot_state clash: nil, running: "123", expect: false + stub_run_capture end # The one capture Dash::Cli::App::Boot makes before it starts anything: the id of a diff --git a/test/cli/cli_test_case.rb b/test/cli/cli_test_case.rb index 748a25dc..acdd55f0 100644 --- a/test/cli/cli_test_case.rb +++ b/test/cli/cli_test_case.rb @@ -47,6 +47,62 @@ def recorded_commands commands end + # Every command captured during the block, in order. Recorded by a matcher that never + # matches, so whichever stub was going to answer the capture still answers it — mocha + # tries expectations newest first, which is why this has to be set up last. + def recorded_captures + captures = [] + SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info).with { |*args| captures << args.join(" "); false } + + yield + + captures + end + + # The id `docker run --detach` prints, which a boot reads instead of asking docker for + # the container id in a round trip of its own. + def stub_run_capture(id: "123") + stub_capture { |args| docker_run?(args) }.returns(id) + end + + # The readiness wait a boot runs on the host for a role without a proxy: one round trip + # that blocks there until the container is ready or the deadline passes. Each status is + # what one wait returned; the last repeats. + def stub_readiness_wait(*statuses, expect: false) + stub_capture(expect: expect) { |args| readiness_wait?(args) }.returns(*statuses) + end + + # The plain status read the poller makes to confirm an unchecked container is still + # running after its readiness delay — the only readiness round trip left beside the wait. + def stub_readiness_confirm(*statuses, expect: false) + stub_capture(expect: expect) { |args| readiness_confirm?(args) }.returns(*statuses) + end + + # Answers one kind of capture, and echoes the command it answered into the stream + # `stdouted` reads. The echo is the point: a stubbed capture is intercepted above the + # Printer and never printed, so without it every assertion about what a boot ran would + # go blind the moment that command moved from `execute` to `capture`. + def stub_capture(expect: false, &matcher) + backend = SSHKit::Backend::Abstract.any_instance + expectation = expect ? backend.expects(:capture_with_info) : backend.stubs(:capture_with_info) + + expectation + .with { |*args| matcher.call(args).tap { |matched| SSHKit.config.output.info(args.join(" ")) if matched } } + .tap { |it| it.at_least_once if expect } + end + + def docker_run?(args) + args.first == :docker && args[1] == :run + end + + def readiness_wait?(args) + args.first == :sh && args.join(" ").include?(Dash::Commands::Base::READINESS_PROGRESS_PREFIX) + end + + def readiness_confirm?(args) + args.first == :docker && args.include?(Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) + end + # A real `docker buildx build --progress=plain` stream, parsed by the same handler a # build attaches. Cheaper than a Docker daemon and it proves the wiring end to end. def build_report_from_fixture(name = "progress_plain_success") diff --git a/test/cli/healthcheck/poller_test.rb b/test/cli/healthcheck/poller_test.rb index 3b9e48fa..719dc5ab 100644 --- a/test/cli/healthcheck/poller_test.rb +++ b/test/cli/healthcheck/poller_test.rb @@ -112,6 +112,57 @@ class CliHealthcheckPollerTest < CliTestCase assert_match /container not ready after 0 seconds \(no-healthcheck:exited\)/, error.message end + # The wait happens on the host now, so the block is asked for it once - and only an + # unchecked container, which is accepted on its readiness delay alone, costs the one + # further read that confirms it is still running when the delay is up. + test "a healthchecked container is waited for once, with the time left to wait" do + modes = [] + + output = stdouted do + Dash::Cli::Healthcheck::Poller.wait_for_healthy(role: DASH.config.role(:listener)) do |mode, seconds_left| + modes << [ mode, seconds_left ] + "healthy" + end + end + + assert_equal [ [ :wait, 30 ] ], modes + assert_match /Container is healthy!/, output + end + + test "an unchecked container is waited for, then confirmed after the readiness delay" do + Dash::Cli::Healthcheck::Poller.expects(:sleep).with(7) + modes = [] + + stdouted do + Dash::Cli::Healthcheck::Poller.wait_for_healthy(role: DASH.config.role(:workers)) do |mode, _seconds_left| + modes << mode + "no-healthcheck:running" + end + end + + assert_equal [ :wait, :confirm ], modes + end + + # The host loop only returns early for a status this poller accepts, so a status that is + # not acceptable means the deadline has already passed. Spending a second wait on it + # would double what an operator waits for a boot that was never going to come up. + test "a wait that came back unacceptable is not waited for a second time" do + Dash::Cli::Healthcheck::Poller.expects(:sleep).never + DASH.config.stubs(:deploy_timeout).returns(0) # the wait spent it all + calls = 0 + + assert_raises Dash::Cli::Healthcheck::Error do + stdouted do + Dash::Cli::Healthcheck::Poller.wait_for_healthy(role: DASH.config.role(:listener)) do + calls += 1 + "starting" + end + end + end + + assert_equal 1, calls + end + private # Yields each status in turn, then repeats the last one for every further poll. def wait_for_healthy(role_name, *statuses) diff --git a/test/cli/healthcheck/progress_reporter_test.rb b/test/cli/healthcheck/progress_reporter_test.rb new file mode 100644 index 00000000..8bbc7892 --- /dev/null +++ b/test/cli/healthcheck/progress_reporter_test.rb @@ -0,0 +1,43 @@ +require_relative "../cli_test_case" + +class CliHealthcheckProgressReporterTest < CliTestCase + setup do + DASH.configure config_file: Pathname.new(File.expand_path("test/fixtures/deploy_with_readiness_sources.yml")), destination: nil, version: "999" + end + + test "a progress line becomes the beacon the client-side poll used to print" do + output = stdouted { report "dash-readiness 4 26 starting\n" } + + assert_match "Container not ready yet, retrying in 1s (4s elapsed, 26s left)", output + end + + # The SSH backend splits on packet boundaries, not newlines, so a line can arrive in + # pieces - and a beacon printed for half a line would be wrong in both numbers. + test "a line split across chunks is reported once, when it is whole" do + reporter = Dash::Cli::Healthcheck::ProgressReporter.new + + partial = stdouted { reporter.on_data(nil, :stderr, "dash-readiness 4 2") } + assert_equal "", partial + + completed = stdouted { reporter.on_data(nil, :stderr, "6 starting\ndash-readiness 5 25 starting\n") } + assert_match "(4s elapsed, 26s left)", completed + assert_match "(5s elapsed, 25s left)", completed + end + + # The wait's stdout carries the final status and the host may say anything else on its + # way past. Only the wait's own beacon is ours to reprint. + test "anything that is not a progress line is ignored" do + output = stdouted do + report "healthy\n" + report "Error response from daemon: No such container\n" + report "dash-readiness not-a-number 26 starting\n" + end + + assert_equal "", output + end + + private + def report(data) + Dash::Cli::Healthcheck::ProgressReporter.new.on_data(nil, :stderr, data, nil) + end +end diff --git a/test/cli/main_test.rb b/test/cli/main_test.rb index de929f74..f1c6880d 100644 --- a/test/cli/main_test.rb +++ b/test/cli/main_test.rb @@ -451,14 +451,16 @@ class CliMainTest < CliTestCase SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) .with { |*args| args.join(" ").include?("'name=^app-#{role}-123$'") && args.join(" ").include?(Dash::Commands::App::BOOT_STATE_SEPARATOR) } .returns("\n#{Dash::Commands::App::BOOT_STATE_SEPARATOR}\nversion-to-rollback\n").at_least_once - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) + # Read by #container_available? before the rollback starts; the boot's own endpoint + # read is gone - it comes out of the run now. + SSHKit::Backend::Abstract.any_instance.stubs(:capture_with_info) .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-#{role}-123$'", "--quiet") - .returns("version-to-rollback\n").at_least_once + .returns("version-to-rollback\n") end - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-123$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # health check + stub_run_capture # the proxy target, printed by the run itself + stub_readiness_wait "no-healthcheck:running", expect: true # workers + stub_readiness_confirm "no-healthcheck:running" Dash::Commands::Hook.any_instance.stubs(:hook_exists?).returns(true) @@ -477,9 +479,7 @@ class CliMainTest < CliTestCase SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) .with { |*args| args.join(" ").include?(Dash::Commands::App::BOOT_STATE_SEPARATOR) } .returns("\n#{Dash::Commands::App::BOOT_STATE_SEPARATOR}\n").at_least_once # no clash, nothing running - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-web-123$'", "--quiet") - .returns("123").at_least_once + stub_run_capture # the proxy target, printed by the run itself run_command("rollback", "123").tap do |output| assert_match "docker run --detach --restart unless-stopped --name app-web-123", output diff --git a/test/cli/proxy_test.rb b/test/cli/proxy_test.rb index 0d2a0ce5..0f68f893 100644 --- a/test/cli/proxy_test.rb +++ b/test/cli/proxy_test.rb @@ -512,9 +512,9 @@ class CliProxyTest < CliTestCase .with(:docker, :inspect, "dash-proxy", "--format '{{.Config.Image}}'", "|", :awk, "-F:", "'{print $NF}'") .returns(Dash::Configuration::Proxy::Run::MINIMUM_VERSION) - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("upgrade", "-y").tap do |output| assert_match "Upgrading proxy on 1.1.1.1,1.1.1.2,1.1.1.3,1.1.1.4...", output @@ -552,9 +552,9 @@ class CliProxyTest < CliTestCase .with(:docker, :inspect, "dash-proxy", "--format '{{.Config.Image}}'", "|", :awk, "-F:", "'{print $NF}'") .returns(Dash::Configuration::Proxy::Run::MINIMUM_VERSION) - SSHKit::Backend::Abstract.any_instance.expects(:capture_with_info) - .with(:docker, :container, :ls, "--all", "--filter", "'name=^app-workers-latest$'", "--quiet", "|", :xargs, :docker, :inspect, "--format", Dash::Commands::Base::DOCKER_HEALTH_STATUS_FORMAT) - .returns("no-healthcheck:running").at_least_once # workers health check + stub_readiness_wait "no-healthcheck:running", expect: true + stub_readiness_confirm "no-healthcheck:running" + stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("upgrade", "--rolling", "-y",).tap do |output| %w[1.1.1.1 1.1.1.2 1.1.1.3 1.1.1.4].each do |host| diff --git a/test/commands/app_test.rb b/test/commands/app_test.rb index 1aa6f69c..bfa8e34f 100644 --- a/test/commands/app_test.rb +++ b/test/commands/app_test.rb @@ -72,6 +72,34 @@ class CommandsAppTest < ActiveSupport::TestCase new_command.status(version: "999").join(" ") end + # The readiness wait runs on the host so a boot pays one round trip for it however long + # the container takes. It returns the moment the status is one Healthcheck::Poller would + # accept, and otherwise keeps looking until the deadline - the same decision the + # client-side poll made, one round trip at a time. + test "wait for ready polls the container status until it is one the poller accepts" do + assert_equal \ + "sh -c 'started=$(date +%s); while true; do status=$({ docker container ls --all --filter '\\''name=^app-web-999$'\\'' --quiet | xargs docker inspect --format '\\''{{if .State.Health}}{{.State.Health.Status}}{{else}}no-healthcheck:{{.State.Status}}{{end}}'\\'' ;} 2>/dev/null); case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 1; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", + new_command.wait_for_ready(version: "999", timeout: 30).join(" ") + end + + # An exec probe is docker-invisible - the container declares no healthcheck, so there is + # no status to inspect. The loop runs the probe instead and reports the same two strings + # the deploy host used to produce for it. + test "wait for ready runs the exec probe on the host when the role declares one" do + @config[:servers] = { "web" => [ "1.1.1.1" ], "jobs" => { "hosts" => [ "1.1.1.2" ], "cmd" => "bin/jobs", "healthcheck" => { "exec" => "bin/ready-check" } } } + + assert_equal \ + "sh -c 'started=$(date +%s); while true; do if docker exec app-jobs-999 sh -c '\\''bin/ready-check'\\'' >/dev/null 2>&1; then status=healthy; else status=\"exec probe exited non-zero\"; fi; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 1; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", + new_command(role: "jobs", host: "1.1.1.2").wait_for_ready(version: "999", timeout: 30).join(" ") + end + + # A zero deploy timeout must still make exactly one observation, not spin forever. + test "wait for ready with no time left reports the first status it sees" do + command = new_command.wait_for_ready(version: "999", timeout: 0).join(" ") + + assert_match "if [ \"$elapsed\" -ge 0 ]; then echo \"$status\"; exit 1; fi", command + end + test "run with volumes" do @config[:volumes] = [ "/local/path:/container/path" ] From 94be4cb1611c1cedc2a4d5c0283e16ead94add5b Mon Sep 17 00:00:00 2001 From: mhenrixon Date: Sat, 12 Sep 2026 17:34:11 +0200 Subject: [PATCH 2/3] fix(boot): fail the boot when the readiness status cannot be read at all MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three findings from review, two of them real behaviour regressions this PR introduced. The wait swallowed the status read's stderr and ignored its exit status, so a docker daemon that had gone away — or a container that had vanished — turned into an empty status the loop then waited out for the whole deploy timeout, before blaming the container for not being ready. Before this PR that read was a capture of its own with raise_on_non_zero_exit on, and it failed the boot on the spot with docker's own error. Restore that: the inspect read no longer redirects its stderr and takes the command down with `|| exit $?`, and the CLI no longer passes raise_on_non_zero_exit: false. That needs the deadline to stop signalling itself with a non-zero exit, which is the better shape anyway: reaching the deadline is an ANSWER, and the poller is what phrases it, so the loop exits 0 with the last status on stdout. A non-zero exit now means only one thing — the command broke — which is the contract SSHKit already has. An exec probe's non-zero exit is untouched: there it IS the answer "not ready", so it stays swallowed and the loop goes on. The progress reporter buffered both streams into one buffer. stdout and stderr are separate SSH streams whose chunks can interleave, so the final status could land in the middle of a half-arrived progress line and corrupt both. Only stderr is buffered now — the stream is part of the contract, not something the line regex should be left to infer. Lastly, two `stub_readiness_confirm` calls were asserting nothing because they were never invoked at all: deploy_with_accessories.yml and deploy_with_proxy.yml both set readiness_delay: 0, so those roles never make the confirming read. Dead stubs removed rather than asserted; the four call sites where the confirm does happen now assert it with expect: true. ## Test Coverage - the wait fails the command when the status cannot be read, and no longer redirects it to /dev/null - a boot whose readiness read fails reports the failure instead of printing "Container not ready yet" until the deadline - the final status on stdout never lands inside a half-arrived progress line ## Verification - [x] bundle exec rubocop --parallel passes - [x] unit tests pass (1902 runs) - [x] the generated loop run under a real POSIX sh: the deadline exits 0 with the last status, an unreadable status exits 123 with docker's error on stderr (verified under GNU xargs semantics, which is what Linux deploy hosts run) Refs #163 --- lib/dash/cli/app/boot.rb | 6 ++-- lib/dash/cli/healthcheck/progress_reporter.rb | 12 ++++--- lib/dash/commands/app.rb | 25 +++++++++------ test/cli/app_test.rb | 32 +++++++++++++------ .../cli/healthcheck/progress_reporter_test.rb | 15 ++++++++- test/cli/main_test.rb | 1 - test/cli/proxy_test.rb | 2 -- test/commands/app_test.rb | 16 ++++++++-- 8 files changed, 78 insertions(+), 31 deletions(-) diff --git a/lib/dash/cli/app/boot.rb b/lib/dash/cli/app/boot.rb index c4eac452..9da626bf 100644 --- a/lib/dash/cli/app/boot.rb +++ b/lib/dash/cli/app/boot.rb @@ -101,13 +101,15 @@ def start_new_version # on the host that streams its progress back rather than being polled from here once # per attempt. The poller asks for the wait, and — only for an unchecked container it # has just let through its readiness delay — for a plain confirming read. + # + # Neither capture suppresses a non-zero exit: a status that cannot be read is a broken + # command, and it has always failed the boot on the spot rather than being waited out. def readiness_status(mode, seconds_left = nil) if mode == :confirm capture_with_info(*app.status(version: version)) else capture_with_info *app.wait_for_ready(version: version, timeout: seconds_left), - interaction_handler: Dash::Cli::Healthcheck::ProgressReporter.new, - raise_on_non_zero_exit: false + interaction_handler: Dash::Cli::Healthcheck::ProgressReporter.new end end diff --git a/lib/dash/cli/healthcheck/progress_reporter.rb b/lib/dash/cli/healthcheck/progress_reporter.rb index 5d2a2b24..8d11fb8f 100644 --- a/lib/dash/cli/healthcheck/progress_reporter.rb +++ b/lib/dash/cli/healthcheck/progress_reporter.rb @@ -5,9 +5,11 @@ # per attempt. The cadence is fixed at a second because the host loop's is. # # The stream is line-oriented but arrives in chunks (the SSH backend splits on packet -# boundaries, not newlines), so data is buffered and only whole lines are reported. The -# line format is the only filter: the wait's stdout carries the final status, and the -# host's own noise is none of this class's business. +# boundaries, not newlines), so data is buffered and only whole lines are reported. Only +# stderr is buffered: the wait's stdout carries the final status, and stdout and stderr are +# separate SSH streams whose chunks can interleave — folding both into one buffer would let +# the status land in the middle of a half-arrived progress line and corrupt them both. +# Anything on stderr that is not a progress line (docker's own complaints) is ignored. class Dash::Cli::Healthcheck::ProgressReporter LINE = /\A#{Regexp.escape(Dash::Commands::Base::READINESS_PROGRESS_PREFIX)} (?\d+) (?\d+)(?: |\z)/ @@ -17,7 +19,9 @@ def initialize end # SSHKit's interaction-handler contract. - def on_data(_command, _stream_name, data, _channel = nil) + def on_data(_command, stream_name, data, _channel = nil) + return unless stream_name == :stderr + @mutex.synchronize do @buffer << data.to_s while (newline = @buffer.index("\n")) diff --git a/lib/dash/commands/app.rb b/lib/dash/commands/app.rb index ae2bbf72..45aed9dd 100644 --- a/lib/dash/commands/app.rb +++ b/lib/dash/commands/app.rb @@ -62,11 +62,15 @@ def health_probe(version:) # Waits on the host for the container to reach a status the poller accepts, so a boot # pays one round trip for the wait however long the container takes to come up - the - # client-side poll paid one per attempt. Exits 0 with that status on stdout the moment - # it sees one of READY_STATUSES; otherwise it reports progress on stderr once a second - # and, at the deadline, prints the last status it saw and exits non-zero. Waiting through - # every other status is deliberate: docker reports a container `unhealthy` after three - # failed probes, which for an app slower than that is a state it recovers from. + # client-side poll paid one per attempt. Prints the status it stopped on to stdout: the + # moment it sees one of READY_STATUSES, or the last one it saw when the deadline passes. + # Progress goes to stderr once a second in between. Waiting through every other status is + # deliberate: docker reports a container `unhealthy` after three failed probes, which for + # an app slower than that is a state it recovers from. + # + # Reaching the deadline exits 0, because it is an answer - the poller phrases it. Only a + # status that could not be read at all exits non-zero, which is a broken command and + # SSHKit's to raise, exactly as it was when the read was a round trip of its own. def wait_for_ready(version:, timeout:) shell [ "started=$(date +%s);", @@ -74,7 +78,7 @@ def wait_for_ready(version:, timeout:) *readiness_probe(version: version), "case \"$status\" in #{READY_STATUSES.join("|")}) echo \"$status\"; exit 0;; esac;", "elapsed=$(( $(date +%s) - started ));", - "if [ \"$elapsed\" -ge #{timeout.to_i} ]; then echo \"$status\"; exit 1; fi;", + "if [ \"$elapsed\" -ge #{timeout.to_i} ]; then echo \"$status\"; exit 0; fi;", "echo \"#{READINESS_PROGRESS_PREFIX} $elapsed $(( #{timeout.to_i} - elapsed )) $status\" 1>&2;", "sleep 1;", "done" @@ -142,13 +146,16 @@ def ensure_env_directory private # The same two readiness sources #status and #health_probe cover, read into `$status` - # so the loop around them is the same either way. Both swallow their own stderr: the - # wait's stderr is the progress channel, and nothing else may appear on it. + # so the loop around them is the same either way. They differ in what a non-zero exit + # means. A probe that exits non-zero IS the answer "not ready", so its output is + # discarded and the loop goes on; an inspect that exits non-zero is no answer at all - + # docker is unreachable or the container is gone - so it takes the whole command down + # with it, with docker's complaint on stderr for SSHKit to put in the exception. def readiness_probe(version:) if role.healthcheck&.exec? [ "if", *health_probe(version: version), ">/dev/null 2>&1;", "then status=healthy;", "else status=\"#{EXEC_PROBE_FAILED}\";", "fi;" ] else - [ "status=$({", *status(version: version), ";} 2>/dev/null);" ] + [ "status=#{substitute(*status(version: version))} || exit $?;" ] end end diff --git a/test/cli/app_test.rb b/test/cli/app_test.rb index c1b60ec6..a247684a 100644 --- a/test/cli/app_test.rb +++ b/test/cli/app_test.rb @@ -142,10 +142,8 @@ class CliAppTest < CliTestCase end # The wait runs for as long as it may take, so the progress an operator sees has to come - # back over that same command while it is still running - and the deadline has to reach - # the poller as a status rather than as a failed command, or the poller never gets to - # phrase the error. - test "the readiness wait streams its progress back and lets the poller judge the result" do + # back over that same command while it is still running. + test "the readiness wait streams its progress back while it runs" do stub_running options = nil stub_capture { |args| readiness_wait?(args).tap { |matched| options = args.grep(Hash).last if matched } }.returns("healthy") @@ -153,7 +151,23 @@ class CliAppTest < CliTestCase run_command("boot", config: :with_readiness_sources, host: "1.1.1.5") assert_instance_of Dash::Cli::Healthcheck::ProgressReporter, options[:interaction_handler] - assert_equal false, options[:raise_on_non_zero_exit] + end + + # Reaching the deadline is an answer the poller phrases; a status that could not be read + # at all is a broken command, and it failed the boot on the spot before the wait moved to + # the host. It still must - waiting out the deploy timeout for an answer that is never + # coming, and then blaming the container, is the failure mode to avoid. + test "a readiness wait whose status cannot be read fails the boot instead of waiting" do + Thread.report_on_exception = false + stub_running + stub_capture { |args| readiness_wait?(args) }.raises(SSHKit::Command::Failed.new("Cannot connect to the Docker daemon")) + + output = run_command("boot", config: :with_readiness_sources, host: "1.1.1.5", allow_execute_error: true) + + assert_match "Failed to boot listener on 1.1.1.5", output + assert_no_match /Container not ready yet/, output + ensure + Thread.report_on_exception = true end # The host loop only returns early for a status the poller accepts, so anything else it @@ -299,7 +313,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123", expect: false stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" + stub_readiness_confirm "no-healthcheck:running", expect: true run_command("boot", config: :with_boot_canary, host: nil).tap do |output| assert_match "First web container is healthy on 1.1.1.1, booting any other roles", output @@ -391,7 +405,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123", expect: false stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" + stub_readiness_confirm "no-healthcheck:running", expect: true run_command("boot", config: :with_roles, host: nil).tap do |output| assert_match "Waiting for the first healthy web container before booting workers on 1.1.1.3...", output @@ -410,7 +424,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123", expect: false stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" + stub_readiness_confirm "no-healthcheck:running", expect: true run_command("boot", config: :with_role_boot, host: nil).tap do |output| assert_match "Waiting for the first healthy web container before booting workers on 1.1.1.3...", output @@ -559,7 +573,7 @@ class CliAppTest < CliTestCase stub_boot_state clash: "12345678", running: "123", expect: false stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" + stub_readiness_confirm "no-healthcheck:running", expect: true run_command("boot", config: :with_only_workers, host: nil).tap do |output| assert_match /First workers container is healthy on 1.1.1.\d, booting any other roles/, output diff --git a/test/cli/healthcheck/progress_reporter_test.rb b/test/cli/healthcheck/progress_reporter_test.rb index 8bbc7892..7c3220a9 100644 --- a/test/cli/healthcheck/progress_reporter_test.rb +++ b/test/cli/healthcheck/progress_reporter_test.rb @@ -28,7 +28,6 @@ class CliHealthcheckProgressReporterTest < CliTestCase # way past. Only the wait's own beacon is ours to reprint. test "anything that is not a progress line is ignored" do output = stdouted do - report "healthy\n" report "Error response from daemon: No such container\n" report "dash-readiness not-a-number 26 starting\n" end @@ -36,6 +35,20 @@ class CliHealthcheckProgressReporterTest < CliTestCase assert_equal "", output end + # stdout and stderr are separate SSH streams and their chunks can interleave, so the + # final status must never reach the buffer a half-arrived progress line is sitting in. + test "the final status on stdout never lands in the middle of a progress line" do + reporter = Dash::Cli::Healthcheck::ProgressReporter.new + + output = stdouted do + reporter.on_data(nil, :stderr, "dash-readiness 4 2") + reporter.on_data(nil, :stdout, "healthy\n") + reporter.on_data(nil, :stderr, "6 starting\n") + end + + assert_match "(4s elapsed, 26s left)", output + end + private def report(data) Dash::Cli::Healthcheck::ProgressReporter.new.on_data(nil, :stderr, data, nil) diff --git a/test/cli/main_test.rb b/test/cli/main_test.rb index f1c6880d..f62c79a0 100644 --- a/test/cli/main_test.rb +++ b/test/cli/main_test.rb @@ -460,7 +460,6 @@ class CliMainTest < CliTestCase stub_run_capture # the proxy target, printed by the run itself stub_readiness_wait "no-healthcheck:running", expect: true # workers - stub_readiness_confirm "no-healthcheck:running" Dash::Commands::Hook.any_instance.stubs(:hook_exists?).returns(true) diff --git a/test/cli/proxy_test.rb b/test/cli/proxy_test.rb index 0f68f893..f23cb15d 100644 --- a/test/cli/proxy_test.rb +++ b/test/cli/proxy_test.rb @@ -513,7 +513,6 @@ class CliProxyTest < CliTestCase .returns(Dash::Configuration::Proxy::Run::MINIMUM_VERSION) stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("upgrade", "-y").tap do |output| @@ -553,7 +552,6 @@ class CliProxyTest < CliTestCase .returns(Dash::Configuration::Proxy::Run::MINIMUM_VERSION) stub_readiness_wait "no-healthcheck:running", expect: true - stub_readiness_confirm "no-healthcheck:running" stub_run_capture id: "12345678" # the proxy target, printed by the run itself run_command("upgrade", "--rolling", "-y",).tap do |output| diff --git a/test/commands/app_test.rb b/test/commands/app_test.rb index bfa8e34f..8257e9df 100644 --- a/test/commands/app_test.rb +++ b/test/commands/app_test.rb @@ -78,7 +78,7 @@ class CommandsAppTest < ActiveSupport::TestCase # client-side poll made, one round trip at a time. test "wait for ready polls the container status until it is one the poller accepts" do assert_equal \ - "sh -c 'started=$(date +%s); while true; do status=$({ docker container ls --all --filter '\\''name=^app-web-999$'\\'' --quiet | xargs docker inspect --format '\\''{{if .State.Health}}{{.State.Health.Status}}{{else}}no-healthcheck:{{.State.Status}}{{end}}'\\'' ;} 2>/dev/null); case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 1; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", + "sh -c 'started=$(date +%s); while true; do status=$(docker container ls --all --filter '\\''name=^app-web-999$'\\'' --quiet | xargs docker inspect --format '\\''{{if .State.Health}}{{.State.Health.Status}}{{else}}no-healthcheck:{{.State.Status}}{{end}}'\\'') || exit $?; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 0; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", new_command.wait_for_ready(version: "999", timeout: 30).join(" ") end @@ -89,7 +89,7 @@ class CommandsAppTest < ActiveSupport::TestCase @config[:servers] = { "web" => [ "1.1.1.1" ], "jobs" => { "hosts" => [ "1.1.1.2" ], "cmd" => "bin/jobs", "healthcheck" => { "exec" => "bin/ready-check" } } } assert_equal \ - "sh -c 'started=$(date +%s); while true; do if docker exec app-jobs-999 sh -c '\\''bin/ready-check'\\'' >/dev/null 2>&1; then status=healthy; else status=\"exec probe exited non-zero\"; fi; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 1; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", + "sh -c 'started=$(date +%s); while true; do if docker exec app-jobs-999 sh -c '\\''bin/ready-check'\\'' >/dev/null 2>&1; then status=healthy; else status=\"exec probe exited non-zero\"; fi; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 0; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", new_command(role: "jobs", host: "1.1.1.2").wait_for_ready(version: "999", timeout: 30).join(" ") end @@ -97,7 +97,17 @@ class CommandsAppTest < ActiveSupport::TestCase test "wait for ready with no time left reports the first status it sees" do command = new_command.wait_for_ready(version: "999", timeout: 0).join(" ") - assert_match "if [ \"$elapsed\" -ge 0 ]; then echo \"$status\"; exit 1; fi", command + assert_match "if [ \"$elapsed\" -ge 0 ]; then echo \"$status\"; exit 0; fi", command + end + + # A status that cannot be read at all is not a readiness answer - docker is broken or the + # container is gone. Swallowing it would spend the whole deploy timeout waiting for an + # answer that is never coming, and then blame the container for not being ready. + test "wait for ready fails the command when the status cannot be read" do + command = new_command.wait_for_ready(version: "999", timeout: 30).join(" ") + + assert_match "|| exit $?;", command + assert_no_match %r{2>/dev/null}, command end test "run with volumes" do From 1774d57d62d76cca304c1bbd79b23b520c2ab7b8 Mon Sep 17 00:00:00 2001 From: mhenrixon Date: Sat, 12 Sep 2026 18:08:29 +0200 Subject: [PATCH 3/3] fix(boot): do not let the readiness read's failure depend on which xargs the host ships MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The status read is a pipeline, so its exit code is xargs'. When `docker container ls` is the half that fails it pipes nothing, and the two xargs families disagree about what happens next: GNU (no -r) runs `docker inspect` with no container anyway, which exits 1 and makes xargs exit 123; BSD and BusyBox skip the utility and exit 0. So `|| exit $?` catches an unreachable daemon on a Debian host and misses it elsewhere. Both leave $status empty, and empty is not something a working `docker inspect --format` can print — so check that too. The failure path no longer depends on the host's findutils. Verified with the generated command run under both: Debian stable-slim (GNU findutils 4.10.0, /bin/sh -> dash) exits 123 with docker's error on stderr, macOS (BSD xargs) exits 1 with it; `starting` -> deadline exits 0 with the last status and `healthy` exits 0 at once on both. ## Verification - [x] bundle exec rubocop --parallel passes - [x] unit tests pass (1902 runs) - [x] bin/test passes (1921 runs, integration included) Refs #163 --- lib/dash/commands/app.rb | 16 ++++++++++++---- test/commands/app_test.rb | 6 +++++- 2 files changed, 17 insertions(+), 5 deletions(-) diff --git a/lib/dash/commands/app.rb b/lib/dash/commands/app.rb index 45aed9dd..ac87090a 100644 --- a/lib/dash/commands/app.rb +++ b/lib/dash/commands/app.rb @@ -148,14 +148,22 @@ def ensure_env_directory # The same two readiness sources #status and #health_probe cover, read into `$status` # so the loop around them is the same either way. They differ in what a non-zero exit # means. A probe that exits non-zero IS the answer "not ready", so its output is - # discarded and the loop goes on; an inspect that exits non-zero is no answer at all - - # docker is unreachable or the container is gone - so it takes the whole command down - # with it, with docker's complaint on stderr for SSHKit to put in the exception. + # discarded and the loop goes on; an inspect that produced no answer at all - docker is + # unreachable, or the container is gone - takes the whole command down with it, with + # docker's complaint on stderr for SSHKit to put in the exception. + # + # An empty status is checked as well as the exit code, because the exit code alone is + # not portable: the read is a pipeline, so its status is xargs', and a `docker container + # ls` that failed pipes nothing. GNU xargs then runs `docker inspect` with no container + # and exits 123, but BSD and BusyBox xargs skip the utility entirely and exit 0. Both + # leave `$status` empty, and empty is not something a working `docker inspect --format` + # can print. def readiness_probe(version:) if role.healthcheck&.exec? [ "if", *health_probe(version: version), ">/dev/null 2>&1;", "then status=healthy;", "else status=\"#{EXEC_PROBE_FAILED}\";", "fi;" ] else - [ "status=#{substitute(*status(version: version))} || exit $?;" ] + [ "status=#{substitute(*status(version: version))} || exit $?;", + "if [ -z \"$status\" ]; then echo \"could not read the status of #{container_name(version)}\" 1>&2; exit 1; fi;" ] end end diff --git a/test/commands/app_test.rb b/test/commands/app_test.rb index 8257e9df..bac3b173 100644 --- a/test/commands/app_test.rb +++ b/test/commands/app_test.rb @@ -78,7 +78,7 @@ class CommandsAppTest < ActiveSupport::TestCase # client-side poll made, one round trip at a time. test "wait for ready polls the container status until it is one the poller accepts" do assert_equal \ - "sh -c 'started=$(date +%s); while true; do status=$(docker container ls --all --filter '\\''name=^app-web-999$'\\'' --quiet | xargs docker inspect --format '\\''{{if .State.Health}}{{.State.Health.Status}}{{else}}no-healthcheck:{{.State.Status}}{{end}}'\\'') || exit $?; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 0; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", + "sh -c 'started=$(date +%s); while true; do status=$(docker container ls --all --filter '\\''name=^app-web-999$'\\'' --quiet | xargs docker inspect --format '\\''{{if .State.Health}}{{.State.Health.Status}}{{else}}no-healthcheck:{{.State.Status}}{{end}}'\\'') || exit $?; if [ -z \"$status\" ]; then echo \"could not read the status of app-web-999\" 1>&2; exit 1; fi; case \"$status\" in healthy|no-healthcheck:running) echo \"$status\"; exit 0;; esac; elapsed=$(( $(date +%s) - started )); if [ \"$elapsed\" -ge 30 ]; then echo \"$status\"; exit 0; fi; echo \"dash-readiness $elapsed $(( 30 - elapsed )) $status\" 1>&2; sleep 1; done'", new_command.wait_for_ready(version: "999", timeout: 30).join(" ") end @@ -103,10 +103,14 @@ class CommandsAppTest < ActiveSupport::TestCase # A status that cannot be read at all is not a readiness answer - docker is broken or the # container is gone. Swallowing it would spend the whole deploy timeout waiting for an # answer that is never coming, and then blame the container for not being ready. + # The read is a pipeline, so its exit code is xargs' — and whether xargs runs anything at + # all on empty input differs between GNU and BSD/BusyBox. An empty status is the one + # signal both agree on, and one a working `docker inspect --format` cannot produce. test "wait for ready fails the command when the status cannot be read" do command = new_command.wait_for_ready(version: "999", timeout: 30).join(" ") assert_match "|| exit $?;", command + assert_match %(if [ -z "$status" ]; then echo "could not read the status of app-web-999" 1>&2; exit 1; fi;), command assert_no_match %r{2>/dev/null}, command end