fix: Say how long a deploy waited and whether logs existed #26

ahmad · 2026-09-03T00:04:54Z

ahmad commented

2026-09-03 00:04:54 +00:00

Issue

Closes #23 · Follows #24

Problem

#23 and #22 are the same defect found twice an hour apart, from opposite ends: the pipeline side saw two red deploys on ahmad/portfolio while production served the version they had just deployed, and the host side had the number that explains it — the container took 169 seconds to bind, and the sixty-second wait gave up 63 seconds before the application had opened its port.

v3.5.2 (#24) fixed the wait itself. What it did not fix is the other half of #23's complaint: the failure said the container "did not become healthy" and then printed fifty lines of an empty log, which is the least informative output this step can produce.

Solution

Every outcome now reports how long it waited, and an empty log tail says so.

Failure messages carry the elapsed seconds alongside the budget. The two differ when the poll interval overshoots, and the elapsed figure is the one that tells a reader whether raising health-timeout would have helped.
The success line reports elapsed too, so a deployment that took four minutes is visible as such rather than looking identical to one that took four seconds.
report_logs prints the tail when there is one and says (the container has produced no log output at all) when there is not — which is precisely the case of a container that died before writing anything.

Review notes

Measured against a stub docker, driving each branch and both log modes:

healthy late                api-1 is healthy after 4s.
never healthy, empty log    api-1 did not become healthy after 9s (budget 8s, last status: starting)
                              (the container has produced no log output at all)
unhealthy, with logs        api-1 reported unhealthy after 0s; its healthcheck retries are exhausted.
                            api listening on port 3000
unknown, empty log          api-1 is not reporting a health status after 6s.
                            Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK.
                              (the container has produced no log output at all)

The second line is worth a second look: after 9s (budget 8s) is the overshoot the elapsed figure exists to expose.

One acceptance criterion is deliberately not met, and I would rather say so than quietly pass it. Criterion 1 asks that a caller setting no new input behaves as it does today; v3.5.2 changed exactly that, taking the default from 60s to 600s. Keeping the old default would have left every repository on the broken behaviour until each one opted out. If you would rather have it back, it is a one-line change.

Risks and trade-offs

report_logs captures the tail into a variable to test whether it is empty, so a very large tail is held in memory briefly. It is bounded by --tail 50.
Nothing here has run against a real host; the deploy key is in OpenBao. The first real deployment is the live proof, as it was for #24.

### Issue Closes #23 · Follows #24 ### Problem #23 and #22 are the same defect found twice an hour apart, from opposite ends: the pipeline side saw two red deploys on `ahmad/portfolio` while production served the version they had just deployed, and the host side had the number that explains it — the container took **169 seconds** to bind, and the sixty-second wait gave up 63 seconds before the application had opened its port. v3.5.2 (#24) fixed the wait itself. What it did not fix is the other half of #23's complaint: the failure said the container "did not become healthy" and then printed fifty lines of an empty log, which is the least informative output this step can produce. ### Solution Every outcome now reports how long it waited, and an empty log tail says so. - Failure messages carry the elapsed seconds alongside the budget. The two differ when the poll interval overshoots, and the elapsed figure is the one that tells a reader whether raising `health-timeout` would have helped. - The success line reports elapsed too, so a deployment that took four minutes is visible as such rather than looking identical to one that took four seconds. - `report_logs` prints the tail when there is one and says `(the container has produced no log output at all)` when there is not — which is precisely the case of a container that died before writing anything. ### Review notes Measured against a stub `docker`, driving each branch and both log modes: ``` healthy late api-1 is healthy after 4s. never healthy, empty log api-1 did not become healthy after 9s (budget 8s, last status: starting) (the container has produced no log output at all) unhealthy, with logs api-1 reported unhealthy after 0s; its healthcheck retries are exhausted. api listening on port 3000 unknown, empty log api-1 is not reporting a health status after 6s. Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK. (the container has produced no log output at all) ``` The second line is worth a second look: `after 9s (budget 8s)` is the overshoot the elapsed figure exists to expose. **One acceptance criterion is deliberately not met, and I would rather say so than quietly pass it.** Criterion 1 asks that a caller setting no new input behaves as it does today; v3.5.2 changed exactly that, taking the default from 60s to 600s. Keeping the old default would have left every repository on the broken behaviour until each one opted out. If you would rather have it back, it is a one-line change. ### Risks and trade-offs - `report_logs` captures the tail into a variable to test whether it is empty, so a very large tail is held in memory briefly. It is bounded by `--tail 50`. - Nothing here has run against a real host; the deploy key is in OpenBao. The first real deployment is the live proof, as it was for #24.

ahmad added 1 commit

2026-09-03 00:04:54 +00:00

fix: Say how long a deploy waited and whether logs existed 0e8ac68a87

The failure named the container and its last status but not how long it had
waited, so a reader could not tell whether a longer budget would have helped.
An empty log tail also printed as nothing at all, which is the least
informative output this step can produce and exactly what a container that
died before opening its port gives you.

Every outcome now reports elapsed seconds, and an empty tail says so.

ahmad changed title from ~~WIP: fix: Say how long a deploy waited and whether logs existed~~ to fix: Say how long a deploy waited and whether logs existed

2026-09-03 00:05:16 +00:00

ahmad_bot reviewed

2026-09-03 00:35:45 +00:00

ahmad_bot left a comment

All five acceptance criteria on #23 assessed, four met and one deliberately not.

Verified by running the block against a stub docker driving each branch and both log modes:

case	output
healthy at 5s	`api-1 is healthy after 5s.` (exit 0)
never healthy, budget 8s, empty log	`did not become healthy after 8s (budget 8s, last status: starting)` then `(the container has produced no log output at all)`
never healthy, with logs	same message, then the tail — container stdout and stderr both survive the `2>&1` capture
unhealthy	`reported unhealthy after 0s` then the tail
name does not resolve	fails at 30s, and the daemon's `No such container` now reaches the log, which is a better answer than an empty tail

AC3 (container, elapsed, last status), AC4 (empty log said rather than shown) and AC5 (health-timeout documented at README.md:107) all hold. AC2 was delivered by #24 and is untouched here. On AC1 — that a caller setting no input behaves as before — your read is right and saying so in the description was the right call: #24 changed the default deliberately, and keeping 60s would have left every repository on the broken behaviour until it opted out. I would not revert it.

printf '%s\n' "${LOGS}" rather than echo is worth keeping; a log line containing a % or a backslash would otherwise be mangled on its way to the reader.

One finding, inline. It is not introduced by this change — it came in with the unknown grace in #24 and is already live on v3 — but this PR rewrites those exact lines, so it is the natural place to raise it. Had this PR introduced it I would have requested changes.

All five acceptance criteria on #23 assessed, four met and one deliberately not. **Verified by running the block** against a stub `docker` driving each branch and both log modes: | case | output | |---|---| | healthy at 5s | `api-1 is healthy after 5s.` (exit 0) | | never healthy, budget 8s, empty log | `did not become healthy after 8s (budget 8s, last status: starting)` then `(the container has produced no log output at all)` | | never healthy, with logs | same message, then the tail — container stdout and stderr both survive the `2>&1` capture | | unhealthy | `reported unhealthy after 0s` then the tail | | name does not resolve | fails at 30s, and the daemon's `No such container` now reaches the log, which is a better answer than an empty tail | AC3 (container, elapsed, last status), AC4 (empty log said rather than shown) and AC5 (`health-timeout` documented at `README.md:107`) all hold. AC2 was delivered by #24 and is untouched here. On AC1 — that a caller setting no input behaves as before — your read is right and saying so in the description was the right call: #24 changed the default deliberately, and keeping 60s would have left every repository on the broken behaviour until it opted out. I would not revert it. `printf '%s\n' "${LOGS}"` rather than `echo` is worth keeping; a log line containing a `%` or a backslash would otherwise be mangled on its way to the reader. **One finding, inline. It is not introduced by this change** — it came in with the `unknown` grace in #24 and is already live on `v3` — but this PR rewrites those exact lines, so it is the natural place to raise it. Had this PR introduced it I would have requested changes.

deploy-vps/action.yml Outdated

					
				@ -366,4 +380,4 @@

				              exit 1

				            fi

				            if [ "${STATUS}" = "unknown" ] && [ "$(date +%s)" -ge "${UNKNOWN_GRACE}" ]; then

A single failed docker inspect after the grace fails the whole deploy, and blames the wrong thing.

UNKNOWN_GRACE is an absolute deadline set once at line 369, not a run of consecutive observations. Past it, the first unknown seen at any point exits 1. And unknown is not only "no such container" — || echo unknown on the docker inspect line turns any non-zero exit into that status, a daemon that is briefly unreachable or too slow to answer included.

Measured, with a stub whose inspect fails for two seconds at t=36 and otherwise reports starting until it goes healthy at 60s, budget 600s:

clean  exit=0 elapsed=61s   api-1 is healthy after 61s.
blip   exit=1 elapsed=37s   api-1 is not reporting a health status after 37s.
                            Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK.
                            api listening on port 3000

The container exists, has a HEALTHCHECK, is reporting starting, and would have been healthy 23 seconds later. It is failed at 37s, told to check a name that is correct, and its own log — printed right underneath — shows it working.

That is the failure class #22 and #23 exist to remove: a red deploy for a deployment that succeeded, now with a misleading diagnosis attached. I cannot tell you how often docker inspect actually fails transiently on apps; what I can say is that the condition it is sensitive to is host load, which is the same condition that motivated the whole change (io_full avg300 65.8, load 6.6 on #23's timeline) — so the new failure mode is most likely exactly where the old one was.

Fix — make the grace consecutive by resetting it whenever a status does arrive:

if [ "${STATUS}" = "unknown" ]; then
  if [ "$(date +%s)" -ge "${UNKNOWN_GRACE}" ]; then
    echo "${container} is not reporting a health status after $(( $(date +%s) - STARTED_AT ))s." >&2
    echo "Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK." >&2
    report_logs "${container}"
    exit 1
  fi
else
  UNKNOWN_GRACE=$(( $(date +%s) + 30 ))
fi

A name that never resolves is unknown from the first poll, so it still fails at 30s — the behaviour #24 was after is unchanged. A blip costs 30 more seconds of waiting instead of the deployment.

Since this is already merged behaviour affecting every consumer of v3, it may deserve its own issue rather than riding along here — your call, given this PR is already editing the block.

**A single failed `docker inspect` after the grace fails the whole deploy, and blames the wrong thing.** `UNKNOWN_GRACE` is an absolute deadline set once at `line 369`, not a run of consecutive observations. Past it, the *first* `unknown` seen at any point exits 1. And `unknown` is not only "no such container" — `|| echo unknown` on the `docker inspect` line turns **any** non-zero exit into that status, a daemon that is briefly unreachable or too slow to answer included. Measured, with a stub whose `inspect` fails for two seconds at t=36 and otherwise reports `starting` until it goes healthy at 60s, budget 600s: ``` clean exit=0 elapsed=61s api-1 is healthy after 61s. blip exit=1 elapsed=37s api-1 is not reporting a health status after 37s. Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK. api listening on port 3000 ``` The container exists, has a `HEALTHCHECK`, is reporting `starting`, and would have been healthy 23 seconds later. It is failed at 37s, told to check a name that is correct, and its own log — printed right underneath — shows it working. That is the failure class #22 and #23 exist to remove: a red deploy for a deployment that succeeded, now with a misleading diagnosis attached. I cannot tell you how often `docker inspect` actually fails transiently on `apps`; what I can say is that the condition it is sensitive to is host load, which is the same condition that motivated the whole change (`io_full` avg300 65.8, load 6.6 on #23's timeline) — so the new failure mode is most likely exactly where the old one was. Fix — make the grace consecutive by resetting it whenever a status does arrive: ```sh if [ "${STATUS}" = "unknown" ]; then if [ "$(date +%s)" -ge "${UNKNOWN_GRACE}" ]; then echo "${container} is not reporting a health status after $(( $(date +%s) - STARTED_AT ))s." >&2 echo "Check the name in healthcheck-containers, and that the image defines a HEALTHCHECK." >&2 report_logs "${container}" exit 1 fi else UNKNOWN_GRACE=$(( $(date +%s) + 30 )) fi ``` A name that never resolves is `unknown` from the first poll, so it still fails at 30s — the behaviour #24 was after is unchanged. A blip costs 30 more seconds of waiting instead of the deployment. Since this is already merged behaviour affecting every consumer of `v3`, it may deserve its own issue rather than riding along here — your call, given this PR is already editing the block.

ahmad changed title from ~~fix: Say how long a deploy waited and whether logs existed~~ to WIP: fix: Say how long a deploy waited and whether logs existed

2026-09-03 01:02:56 +00:00

ahmad added 1 commit

2026-09-03 01:03:58 +00:00

fix: Count consecutive unknowns, not an absolute grace 7c2e8ef1d4

Any non-zero docker inspect becomes the unknown status, a daemon briefly too
loaded to answer included. With an absolute grace, one such blip past it
failed a container that was reporting starting and would have been healthy
seconds later — and told the reader to check a container name that was
correct.

The grace now resets whenever a status arrives, so it measures a run of
consecutive unknowns. A name that never resolves is unknown from the first
poll and still fails at the grace.

ahmad commented

2026-09-03 01:03:58 +00:00

Fixed in 7c2e8ef. You are right, and it is worth being explicit that this is a defect in code I added yesterday, not one inherited: the grace was an absolute deadline, so past it a single unknown — which || echo unknown produces for any non-zero docker inspect, including a daemon briefly too loaded to answer — failed a container that was reporting starting.

The grace now resets whenever a status arrives, so it measures a run of consecutive unknowns rather than a point in time.

I built two loops differing only in that semantics and ran both against the same stub, so the comparison isolates the change:

case	absolute grace	consecutive grace
blip: `starting` ×3, one `unknown`, then healthy	exit 1 at 6s, "not reporting a health status"	exit 0, healthy
container name never resolves	exit 1 at the grace	exit 1 at the grace
healthy, no unknowns at all	exit 0	exit 0

The first row is your finding reproduced; the second is the check that the fix does not weaken the case the grace was written for.

Your point about where this bites is the part I would underline: the condition that makes docker inspect flaky is host load, which is the same condition that motivated the whole change. The new failure mode would have landed exactly where the old one did — and with a diagnosis pointing at a container name that was correct, which is worse than the failure it replaced.

Ready again immediately rather than waiting for your next look, since leaving it WIP: is what stalled #24.

Fixed in `7c2e8ef`. You are right, and it is worth being explicit that this is a defect in code I added yesterday, not one inherited: the grace was an absolute deadline, so past it a single `unknown` — which `|| echo unknown` produces for *any* non-zero `docker inspect`, including a daemon briefly too loaded to answer — failed a container that was reporting `starting`. The grace now resets whenever a status arrives, so it measures a run of consecutive unknowns rather than a point in time. I built two loops differing only in that semantics and ran both against the same stub, so the comparison isolates the change: | case | absolute grace | consecutive grace | | --- | --- | --- | | blip: `starting` ×3, one `unknown`, then healthy | **exit 1** at 6s, "not reporting a health status" | **exit 0**, healthy | | container name never resolves | exit 1 at the grace | exit 1 at the grace | | healthy, no unknowns at all | exit 0 | exit 0 | The first row is your finding reproduced; the second is the check that the fix does not weaken the case the grace was written for. Your point about where this bites is the part I would underline: the condition that makes `docker inspect` flaky is host load, which is the same condition that motivated the whole change. The new failure mode would have landed exactly where the old one did — and with a diagnosis pointing at a container name that was correct, which is worse than the failure it replaced. Ready again immediately rather than waiting for your next look, since leaving it `WIP:` is what stalled #24.

ahmad changed title from ~~WIP: fix: Say how long a deploy waited and whether logs existed~~ to fix: Say how long a deploy waited and whether logs existed

2026-09-03 01:04:00 +00:00

ahmad_bot approved these changes

2026-09-03 01:34:40 +00:00

ahmad_bot left a comment

Approving. Re-reviewed the delta only (0e8ac68 → 7c2e8ef); everything else was verified in review 102.

The grace is now a run of consecutive unknown observations, reset whenever a status does arrive. Measured against a stub docker driving each path:

case	result
inspect fails for 2s at t=36, container healthy at 50s	exit 0 at 50s — the blip that used to fail it
name never resolves (`unknown` from the first poll)	exit 1 at 31s — what #24 was after, unchanged
reports `starting`, then vanishes at t=20 and stays gone	exit 1 at 49s — 30s of consecutive unknowns after the last status, not 30s from container start and not the whole budget
`unhealthy`	exit 1 at 0s
`starting` throughout, budget 12s	exit 1 at 12s, `last status: starting`

The third row is the one that shows the reset is a real consecutive run rather than a single tolerated blip, and it is the case I had not tested when I raised this — a container that genuinely disappears mid-wait still fails, and reasonably promptly.

You are right to call it a defect in code you added rather than an inherited one; I framed it as inherited because I was reading #26's diff against a merged base, and that was the less accurate way to put it.

#23's criteria stand where review 102 left them: elapsed and last status in the failure message, the empty-log line, health-timeout at README.md:107, the input itself unchanged. The unchanged-default criterion remains knowingly unmet and declared in the description, which I still think is the right call.

Same two caveats as #24, neither a defect here: merging moves v3 for expiro, portfolio and trip, and this repository still runs no pull-request pipeline (platform-actions#25), so nothing has executed any of it outside stubs. Approval does not merge.

Approving. Re-reviewed the delta only (`0e8ac68` → `7c2e8ef`); everything else was verified in review 102. The grace is now a run of consecutive `unknown` observations, reset whenever a status does arrive. Measured against a stub `docker` driving each path: | case | result | |---|---| | inspect fails for 2s at t=36, container healthy at 50s | **exit 0 at 50s** — the blip that used to fail it | | name never resolves (`unknown` from the first poll) | exit 1 at 31s — what #24 was after, unchanged | | reports `starting`, then vanishes at t=20 and stays gone | exit 1 at **49s** — 30s of consecutive unknowns after the last status, not 30s from container start and not the whole budget | | `unhealthy` | exit 1 at 0s | | `starting` throughout, budget 12s | exit 1 at 12s, `last status: starting` | The third row is the one that shows the reset is a real consecutive run rather than a single tolerated blip, and it is the case I had not tested when I raised this — a container that genuinely disappears mid-wait still fails, and reasonably promptly. You are right to call it a defect in code you added rather than an inherited one; I framed it as inherited because I was reading #26's diff against a merged base, and that was the less accurate way to put it. `#23`'s criteria stand where review 102 left them: elapsed and last status in the failure message, the empty-log line, `health-timeout` at `README.md:107`, the input itself unchanged. The unchanged-default criterion remains knowingly unmet and declared in the description, which I still think is the right call. Same two caveats as #24, neither a defect here: merging moves `v3` for expiro, portfolio and trip, and this repository still runs no pull-request pipeline (`platform-actions#25`), so nothing has executed any of it outside stubs. Approval does not merge.

ahmad merged commit 710c6689ad into main

2026-09-03 02:02:40 +00:00

ahmad referenced this pull request from a commit

2026-09-03 02:02:41 +00:00

fix: Say how long a deploy waited and whether logs existed (#26)

ahmad deleted branch feature/23-deploy-failure-message

2026-09-03 02:02:43 +00:00

Sign in to join this conversation.

No reviewers