perf(boot): wait for readiness on the host and take the container id from docker run - #166
perf(boot): wait for readiness on the host and take the container id from docker run#166mhenrixon wants to merge 1 commit into
Conversation
…from docker run ## 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
There was a problem hiding this comment.
3 issues found across 14 files
Confidence score: 3/5
lib/dash/commands/app.rbconverts Docker or inspected-container failures into an empty readiness status, which can silently wait untildeploy_timeoutinstead of reporting the underlying command failure — preserve probe and inspect failures separately.lib/dash/cli/healthcheck/progress_reporter.rbcan concatenate stdout status data with a stderr progress line across chunks, dropping the progress beacon — ignore non-:stderrcallbacks before appending.test/cli/main_test.rbonly partially asserts the new readiness machinery, leaving the readiness polling behavior insufficiently covered and allowing regressions to pass unnoticed — restore an explicit assertion for the readiness read.
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="test/cli/main_test.rb">
<violation number="1" location="test/cli/main_test.rb:463">
P3: The previous test asserted the poller's health-status read with `expects(...).at_least_once`, but the new readiness machinery is only half-asserted: `stub_readiness_wait` is asserted (`expect: true`) while `stub_readiness_confirm` is registered as a plain `stubs`. Because `stub_capture` with `expect: false` does not require the capture to happen, this test now passes even if the confirm read (the `docker inspect --format` status read for the unchecked container) is removed or broken. Assert both captures, or assert the confirm with `expect: true`, so a regression in the confirm path fails the test.</violation>
</file>
<file name="lib/dash/cli/healthcheck/progress_reporter.rb">
<violation number="1" location="lib/dash/cli/healthcheck/progress_reporter.rb:20">
P2: When stdout’s final status arrives between chunks of a stderr progress line, this shared buffer concatenates the separate streams and drops that progress beacon. Ignore non-`:stderr` callbacks before appending, or maintain one buffer per stream.</violation>
</file>
<file name="lib/dash/commands/app.rb">
<violation number="1" location="lib/dash/commands/app.rb:151">
P2: When Docker or the inspected container is unavailable, this redirection turns a command failure into an empty readiness status and silently waits until `deploy_timeout`. Preserve probe/inspect failures separately from normal `starting` or `unhealthy` statuses so the boot can fail and report the actual Docker error instead of masking it as a readiness timeout.</violation>
</file>
Reply with feedback, questions, or to request a fix.
Fix all with cubic | Re-trigger cubic
| def on_data(_command, _stream_name, data, _channel = nil) | ||
| @mutex.synchronize do |
There was a problem hiding this comment.
P2: When stdout’s final status arrives between chunks of a stderr progress line, this shared buffer concatenates the separate streams and drops that progress beacon. Ignore non-:stderr callbacks before appending, or maintain one buffer per stream.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At lib/dash/cli/healthcheck/progress_reporter.rb, line 20:
<comment>When stdout’s final status arrives between chunks of a stderr progress line, this shared buffer concatenates the separate streams and drops that progress beacon. Ignore non-`:stderr` callbacks before appending, or maintain one buffer per stream.</comment>
<file context>
@@ -0,0 +1,35 @@
+ end
+
+ # SSHKit's interaction-handler contract.
+ def on_data(_command, _stream_name, data, _channel = nil)
+ @mutex.synchronize do
+ @buffer << data.to_s
</file context>
| def on_data(_command, _stream_name, data, _channel = nil) | |
| @mutex.synchronize do | |
| def on_data(_command, stream_name, data, _channel = nil) | |
| return unless stream_name == :stderr |
| 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);" ] |
There was a problem hiding this comment.
P2: When Docker or the inspected container is unavailable, this redirection turns a command failure into an empty readiness status and silently waits until deploy_timeout. Preserve probe/inspect failures separately from normal starting or unhealthy statuses so the boot can fail and report the actual Docker error instead of masking it as a readiness timeout.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At lib/dash/commands/app.rb, line 151:
<comment>When Docker or the inspected container is unavailable, this redirection turns a command failure into an empty readiness status and silently waits until `deploy_timeout`. Preserve probe/inspect failures separately from normal `starting` or `unhealthy` statuses so the boot can fail and report the actual Docker error instead of masking it as a readiness timeout.</comment>
<file context>
@@ -120,6 +141,17 @@ def ensure_env_directory
+ 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
</file context>
| .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" |
There was a problem hiding this comment.
P3: The previous test asserted the poller's health-status read with expects(...).at_least_once, but the new readiness machinery is only half-asserted: stub_readiness_wait is asserted (expect: true) while stub_readiness_confirm is registered as a plain stubs. Because stub_capture with expect: false does not require the capture to happen, this test now passes even if the confirm read (the docker inspect --format status read for the unchecked container) is removed or broken. Assert both captures, or assert the confirm with expect: true, so a regression in the confirm path fails the test.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At test/cli/main_test.rb, line 463:
<comment>The previous test asserted the poller's health-status read with `expects(...).at_least_once`, but the new readiness machinery is only half-asserted: `stub_readiness_wait` is asserted (`expect: true`) while `stub_readiness_confirm` is registered as a plain `stubs`. Because `stub_capture` with `expect: false` does not require the capture to happen, this test now passes even if the confirm read (the `docker inspect --format` status read for the unchecked container) is removed or broken. Assert both captures, or assert the confirm with `expect: true`, so a regression in the confirm path fails the test.</comment>
<file context>
@@ -451,14 +451,16 @@ class CliMainTest < CliTestCase
- .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)
</file context>
Summary
Two round trips come out of every boot, and one of them is the row that scaled with how long a container takes to come up.
The readiness wait moves onto the host.
Dash::Commands::App#wait_for_readybuilds a shell loop that evaluates the same statusDash::Cli::Healthcheck::Pollerused to read one round trip at a time —docker inspect's health status, or thehealthcheck: exec:probe's exit code — returns the moment that status is one the poller accepts, and otherwise keeps looking untildeploy_timeout.Dash::Cli::App::Bootruns it as a single capture with an interaction handler attached, so theContainer not ready yet, retrying in 1s (Xs elapsed, Ys left)beacons still print once a second while it waits. Progress goes to stderr and the final status to stdout, which is what keeps the captured value the status and nothing else.The proxy target comes out of
docker run.docker run --detachprints the id of the container it just started; boot captures it and takes the first twelve characters — the same short iddocker container ls --quietprinted — instead of asking docker for it again on the next round trip.Every readiness decision still lives in the poller, word for word: drift,
announce_missing_gate, the readiness-delay confirm, the timeout error. The host loop only decides when to return, never what it means —Dash::Commands::Base::READY_STATUSESis the one thing both sides read, so they cannot drift apart.Closes #163
Round trips per host, per role shape
Counted from the boot path and pinned by tests (
test/cli/app_test.rb), not from a live deploy — see Deviations.boot_stateensure_env_directory(upload!is SFTP)docker run --detachcontainer_id_for_version10dash-proxy deployN1N2stopold versionclean_up_assetsOn the 4-host deploy in the issue (N ≈ 5 on the job host) that is
web7 → 6 andjob9 → 5.container_id_for_versionsaving is a skip — the answer was already on the host's stdout.unhealthystill waits — the issue's one reversed decisionThe issue proposed returning from the wait the moment docker reports
unhealthy, and invited the executor to keep the retry if there was a reason. There is one, and it is decisive: dash's default healthcheck emits--health-interval 1swith no--health-start-period, and docker's default--health-retriesis 3. A container whose app needs longer than ~3s to serve/upis therefore reportedunhealthyat t≈3s andhealthywhen it finishes booting. Today's poller waits through that and accepts the boot; returning early onunhealthywould fail essentially every normal Rails boot at three seconds.So the host loop returns early for exactly the statuses
Poller#acceptable?accepts and waits out the deadline for everything else — which is precisely what the client-side poll did, attempt by attempt. The only behaviour that changes is the beacon cadence: a fixed second instead of 1s, 2s, 3s … , which is strictly more responsive.Test plan
bundle exec ruby -Itest -e 'Dir["test/**/*_test.rb"].grep_v(/integration/).each { |f| require File.expand_path(f) }'— 1899 runs, 0 failuresbundle exec rubocop --parallel— no offensesbin/test— full suite, 1918 runs, Docker +ghcr.io/zoolutions/dash-proxy:v1.1.0.1(MINIMUM_VERSIONunchanged). The integration deploys run the wait loop on real Docker-in-Docker hosts, includingapp_with_roles' uncheckedworkersroledocs/—bundle exec rspec spec/config_docs_spec.rbgreen after the doc-wording updatesshagainst a fakedocker:starting→healthyexits 0 with the status on stdout and beacons on stderr; never-ready exits 1 at the deadline with the last status;no-healthcheck:runningreturns immediately;timeout: 0makes exactly one observation without spinning; the exec branch loops on the probe's exit codetest/commands/app_test.rb), the streaming handler against chunks split mid-line (test/cli/healthcheck/progress_reporter_test.rb), the poller's new call pattern (test/cli/healthcheck/poller_test.rb), and at the boot level — the proxy target read from the run, one wait round trip for a healthchecked role, wait-plus-confirm for an unchecked one, the handler andraise_on_non_zero_exit: falsewiring, and a deadline that fails once rather than waiting twiceDeviations & judgment calls
Deviation —
unhealthydoes not return early from the host loop. Reasoned above; it is the one decision in the issue's Decision section I reversed, and the tests pin the behaviour either way.Judgment — the block protocol is
|mode, seconds_left|. The poller needs two different reads from the CLI: the blocking wait, and the plain status confirm after a readiness delay. Splittingwait_for_healthyinto two callables would have churned every poller test, so the block is called with:wait/:confirminstead; procs ignore extra args, so the existing tests' blocks were untouched.seconds_leftis passed so a retried wait cannot overshootdeploy_timeout.Judgment — the run capture is unconditional, not proxy-only. One code path reads better than branching
execute/captureonrunning_proxy?, and the id is what the failure message is about for every role.Judgment —
stub_captureechoes the captured command into SSHKit's output. A stubbedcapture_with_infois intercepted above the Printer and never printed, so movingdocker runfromexecutetocapturemade it invisible to roughly a dozen assertions across three test files. Rather than rewrite them all to read a recorded array, the shared stub helper echoes what it answered into the same streamstdoutedreads. Side effects in a mocha matcher are not lovely;recorded_commandsandstub_boot_statealready use the idiom.Discovery — the docs described the old cost model.
lib/dash/configuration/docs/role.ymlanddocs/app/views/docs/pages/worker_roles.rbboth claimed an exec probe costs "an SSH round trip plus a process spawn per poll" and that dash "polls docker's verdict with backoff". Neither survives this change; both updated.Discovery — a latent bug next door, left alone.
Dash::Cli::Main#container_available?rescuesSSHKit::Runner::MultipleExecuteError, which sshkit 1.25 does not define, so a rollback to a version whose container is missing raisesNameErrorinstead of the intended message. Surfaced when a test stub moved; out of this issue's path and not touched here. Worth its own issue.Summary by cubic
Moves the readiness wait onto the host and reads the proxy target out of the
docker runoutput, cutting two round trips from every boot.The container readiness wait used to poll from the laptop, one SSH round trip per attempt — a container that takes 60 seconds to boot cost ten trips. It's now a single blocking shell loop on the host; it returns the moment the status is one the poller accepts and otherwise runs until
deploy_timeout. Progress beacons still print once a second, streamed back through an SSHKit interaction handler. The proxy target no longer costs adocker container lsread; boot takes the first twelve characters of the ID thatdocker run --detachalready prints.Round trips per host
Every readiness decision — drift detection, missing-gate warning, readiness-delay confirm, timeout error — still lives in the poller; the host loop only decides when to return. The one deliberate deviation from the issue proposal is that
unhealthystill waits out the deadline: dash's default healthcheck probes every second with no start period and docker defaults to 3 retries, so an app slower than ~3 seconds to serve/upreportsunhealthybefore it's actually ready.Written for commit e3f6ea6. Summary will update on new commits.