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" ]