perf(boot): wait for readiness on the host and take the container id from docker run

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:

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,35 +74,43 @@ 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
         info "Deploying #{role} on #{host} via dash-proxy (waiting up to #{DASH.config.deploy_timeout}s for it to become healthy)..."
         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}"
       dump_diagnostics
       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.
+    #
+    # 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
+      end
     end
 
     # Every failed boot gets the container log, and the health probe history when the

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

lib/dash/cli/healthcheck/progress_reporter.rb

@@ -0,0 +1,39 @@
+# 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. 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)} (?<elapsed>\d+) (?<left>\d+)(?: |\z)/
+
+  def initialize
+    @buffer = +""
+    @mutex = Mutex.new
+  end
+
+  # SSHKit's interaction-handler contract.
+  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"))
+        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

lib/dash/commands/app.rb

@@ -60,6 +60,31 @@ 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. 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);",
+      "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 0; 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 +145,28 @@ 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. 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 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 $?;",
+          "if [ -z \"$status\" ]; then echo \"could not read the status of #{container_name(version)}\" 1>&2; exit 1; fi;" ]
+      end
+    end
+
     def latest_image_id
       docker :image, :ls, *argumentize("--filter", "reference=#{config.latest_image}"), "--format", "'{{.ID}}'"
     end

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)

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