feat(command-logs): add zilla logs command for engine event readiness checks#2136
Merged
Conversation
jfallows
force-pushed
the
claude/command-logs-incubator-e3dnv3
branch
4 times, most recently
from
1f00ec5 to
4f26757
Compare
jfallows
force-pushed
the
claude/command-logs-incubator-e3dnv3
branch
from
44865cb to
8ce9289
Compare
… checks Adds incubator/command-logs providing a `zilla logs` CLI command that attaches a readonly Engine to a running instance's ENGINE_DIRECTORY, reads its event ring buffers, and formats them via the existing EventFormatter pipeline. Supports --grep to filter by event type and --wait-for/--timeout to block until a specific event (e.g. engine.started) appears, so it can serve as a reliable Docker healthcheck in place of a bare TCP-connect probe. Adds Engine.supplyQName()/supplyEventFormatter() delegates (mirroring the existing supplyLocalName()/supplyLabelId()/supplyEventReader() pattern) since the public Engine facade used by external readonly CLI tools did not previously expose per-worker qualified-name resolution or event formatting. Resolves #2131. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
… --wait-for by default Fixes ZillaLogsCommand's default zilla.properties/engine directory resolution to match how `zilla start` resolves it (via the zilla.directory system property the launcher script sets), instead of a CWD-relative default that never matches inside the Docker image where no working directory is set. Also changes --wait-for's default --timeout to a single check instead of a 30s internal poll loop: a Docker HEALTHCHECK's own timeout would otherwise SIGKILL the process mid-retry, since HEALTHCHECK already provides its own interval/retries polling cadence. Updates the asyncapi.http.kafka.proxy example's healthcheck to use `zilla logs --wait-for engine.started` in place of the bare TCP-connect probe, verified against a locally built image with a real docker compose run (health: starting -> healthy). This depends on the readonly-attach event-preservation fix merged separately in #2134. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
JVM cold-start for a single "zilla logs" invocation runs 1.6-2.8s locally; CI runners are typically slower, so the prior 3s timeout was intermittently exceeded. Widen timeout/interval/start_period to give comfortable headroom.
Observed one CI failure where the healthcheck flipped unhealthy ~80s in (not at startup), consistent with transient CPU contention on a shared CI runner rather than a real regression - reproduced locally for 150s+ with zero restarts and no crashes on the same image. Widen timeout and retries so a few consecutive slow checks under load don't flip the container unhealthy.
…r/--timeout --wait-for and --timeout existed to let the command block until a specific event appeared, for use in a Docker HEALTHCHECK. That need is fully served by a one-shot --filter check instead: read the current event buffer, print matches, and exit non-zero if nothing matched - Docker's own interval/retries already provide the retry loop, so the command doesn't need to poll or block internally. --grep is renamed --filter and now matches a glob pattern (* and ?) against the event type name instead of a plain substring, and its match result now drives the command's exit status directly instead of a separate --wait-for string. --follow/-f replaces the removed polling loop: after printing the current buffer it keeps printing new events forever, mirroring `docker logs -f`. It's independent of --filter and unconditional - unlike the old --wait-for polling loop, it never exits on its own. Update the asyncapi.http.kafka.proxy healthcheck to use --filter in place of --wait-for.
…at json --filter's only remaining job was producing an exit code for a Docker HEALTHCHECK. Plain text output already composes with grep for that (and jq once piped through --format json), so the internal glob matching and exit-status plumbing are no longer needed - the command now always exits 0 if it can read the log, matching `docker logs`. Add --format text|json (text is the default, matching prior output). JSON is one object per line (namespace, timestamp epoch-millis, traceId as a zero-padded hex string to avoid precision loss, event, message), rendered via jakarta.json for correct escaping. Update the asyncapi.http.kafka.proxy healthcheck to pipe through grep now that filtering is external.
JsonObjectBuilder.build().toString() materializes a full JsonObject tree (JsonString/JsonNumber wrappers for every field) before serializing. JsonGenerator writes primitives directly to the stream without that intermediate allocation. Only flush(), never close(), the generator - close() closes the underlying output source per the jakarta.json spec, which would break --follow (repeated print() calls against the same System.out across poll iterations). Verified in a real container that --follow --format json keeps printing across iterations rather than silently going dark after the first record.
command-logs has proven stable; move it out of incubator/ into runtime/ and drop the @Incubating gate so it's available without ZILLA_INCUBATOR_ENABLED. Update the module lists and dependency management in incubator/pom.xml and runtime/pom.xml accordingly, and drop the now-unneeded ZILLA_INCUBATOR_ENABLED env var from the asyncapi.http.kafka.proxy example, which only needed it for the logs-based healthcheck. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
The previous commit only captured the git mv renames — the pom.xml parent/name change, the incubator/runtime aggregator pom module-list updates, the @Incubating removal, and the compose.yaml env var drop were left unstaged (a bad pathspec in the git add call aborted the whole staging operation) and broke CI: incubator/pom.xml still declared command-logs as a child module pointing at a directory that no longer existed there. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
Replace the bare TCP-connect probe (proves only that the kernel accepted a connection, not that the engine finished attaching bindings) with `zilla logs | grep -q engine.started` across every examples/*/compose.yaml healthcheck, completing the follow-up from #2131 beyond the single asyncapi.http.kafka.proxy example already updated. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
…oxy and sse.kafka.fanout CI logs show both examples' zilla container missed "healthy" by a narrow margin under CI runner contention (130s vs the prior 125s budget for asyncapi.http.kafka.proxy; 54s vs 40s for sse.kafka.fanout), not a healthcheck logic failure — `zilla logs` reproduces correctly and quickly locally against the same image. Both examples spin up extra containers (kafka-ui, kafka-init, and for sse.kafka.fanout also a ticker-producer), so widen retries to 10 at the same interval/timeout/start_period already used for asyncapi.http.kafka.proxy, giving 145s total. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
… PATH includes it #2154 (merged into develop, picked up by this rebase) adds /opt/zilla to PATH in the Docker image, so every example's healthcheck can call the bare `zilla` command instead of spelling out the full path. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
…rther The 145s budget (retries: 10) was still marginally exceeded under CI contention (156s observed, vs 130s the previous run) — specs are local files, not fetched remotely, so this is CI runner variance, not a fixable root cause. Bump retries to 15 for 195s of headroom. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
…ot with a stack trace zilla logs (and any other readonly Engine attach) could crash with an uncaught NoSuchFileException, IllegalStateException, or ArithmeticException when invoked before the real engine finished writing its layout files (Info, BufferPoolLayout, EventsLayout each have their own independent create-then-populate race). Catching every such exception type in each readonly command doesn't scale — any future layout has its own new failure shape. Add a single, dedicated readiness signal instead: an empty `ready` marker file, written as the last statement in Engine's constructor only after every EngineWorker (and its layouts) is fully built. Info's existing early write is untouched — command-stop depends on reading its PID as soon as the process exists, even mid-init, to be able to kill a hung startup. A readonly attach now checks `ready`'s filesystem mtime against Info's startTime field before touching any layout: if `ready` is missing, or older than the current run's startTime (a stale marker left behind by a prior crashed run when the engine directory survives a restart), the attach throws EngineNotInitializedException instead of constructing anything. zilla logs catches it and prints a short message with exit 1, rather than exposing internal layout exceptions. Verified against a real container under CPU throttling: previously every early attempt crashed with a raw stack trace; now attempts before readiness print "Engine not yet initialized: <dir>" cleanly, and the very first attempt after readiness succeeds. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
jfallows
force-pushed
the
claude/command-logs-incubator-e3dnv3
branch
from
a73742c to
6e96c48
Compare
zilla logs's engine.started event is a more reliable readiness signal than the bare TCP-connect probe it replaced, but it fires later — after every worker/binding fully attaches, not just after the socket listener binds. The previous per-example ad-hoc widening (a few examples bumped individually as they showed marginal-timing failures in CI, most left at the original 40s default) has been chasing flakiness one example at a time. Standardize every example on the same interval: 5s / timeout: 3s / retries: 9 / start_period: 15s budget (15 + 9*5 = 60s), replacing the two previously-widened examples' inconsistent higher values as well, to see if a single generous budget is sufficient across the board in the GitHub Actions environment. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa
CI run 29348244798 (60s budget) showed 3 of 4 failures were genuine healthcheck timeouts, not the already-known MQTT test flakiness: http.kafka.crud, grpc.kafka.fanout, and sse.proxy.jwt all reported "container zilla-1 is unhealthy" ~79-84s after container start, well past the nominal 60s (15s start_period + 9*5s interval) budget. asyncapi.mqtt.kafka.proxy's zilla-1 became healthy fine at ~32s; its failure was an unrelated mosquitto_sub connection-refused timeout. Bump retries from 9 to 15 (nominal budget 60s -> 90s) to absorb the observed ~20-24s of CI runner scheduling drift under matrix-wide Docker healthcheck contention.
…check CI runs kept showing genuine healthcheck timeouts even after widening the budget to 90s (up to 136s observed on run 29350930146, against a different set of examples each time), pointing at something worse than plain scheduling noise. The original healthcheck (pre-#2131) was a bare TCP-connect probe with near-zero cost. Switching it to `zilla logs | grep -q engine.started` made the signal more precise but pays for a full JVM cold start on every 5s poll for the entire startup window -- up to 15+ extra JVM spawns directly competing with the engine's own busy-spinning workers for CPU, right when the engine needs it most to finish initializing. Use `test -f $ENGINE_DIRECTORY/ready` instead: a zero-cost shell check against the same race-free Ready marker introduced for the readonly zilla logs attach path, with no JVM spawn at all. Keeps the 90s budget unchanged so this isolates the one variable.
Ready.markReady() was called at the end of the Engine constructor, before ZillaStartCommand ever calls engine.start(). start() is what calls manager.start(), which synchronously attaches namespaces and bindings (EngineConfigWatchTask.submit() -> onPathChanged() runs the initial config attach before returning). Marking ready in the constructor meant the ready marker -- and therefore any healthcheck or zilla logs consumer relying on it -- could observe "ready" before a single binding existed, let alone was listening. This surfaced concretely once the example healthchecks switched to a plain `test -f $ENGINE_DIRECTORY/ready` shell check (no JVM warm-up delay to accidentally mask the race): tcp.echo, ws.echo, and asyncapi.http.kafka.proxy all went "healthy" while nothing was yet wired to serve traffic, so the actual protocol test against the now-open port got nothing back. Move the Ready.markReady() call to the end of start(), immediately after manager.start() returns -- the same point where the `engine.started` event itself is fired further down in EngineManager.start(), so both signals now describe the same true readiness point. Added EngineTest#shouldNotMarkReadyUntilBindingsAttached, which fails against the old placement (ready flips true before start() is even called) and passes against the fix.
jfallows
added a commit
that referenced
this pull request
Jul 15, 2026
… checks (#2136) * feat(command-logs): add zilla logs command for engine event readiness checks Adds incubator/command-logs providing a `zilla logs` CLI command that attaches a readonly Engine to a running instance's ENGINE_DIRECTORY, reads its event ring buffers, and formats them via the existing EventFormatter pipeline. Supports --grep to filter by event type and --wait-for/--timeout to block until a specific event (e.g. engine.started) appears, so it can serve as a reliable Docker healthcheck in place of a bare TCP-connect probe. Adds Engine.supplyQName()/supplyEventFormatter() delegates (mirroring the existing supplyLocalName()/supplyLabelId()/supplyEventReader() pattern) since the public Engine facade used by external readonly CLI tools did not previously expose per-worker qualified-name resolution or event formatting. Resolves #2131. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(command-logs): resolve zilla.directory correctly and single-check --wait-for by default Fixes ZillaLogsCommand's default zilla.properties/engine directory resolution to match how `zilla start` resolves it (via the zilla.directory system property the launcher script sets), instead of a CWD-relative default that never matches inside the Docker image where no working directory is set. Also changes --wait-for's default --timeout to a single check instead of a 30s internal poll loop: a Docker HEALTHCHECK's own timeout would otherwise SIGKILL the process mid-retry, since HEALTHCHECK already provides its own interval/retries polling cadence. Updates the asyncapi.http.kafka.proxy example's healthcheck to use `zilla logs --wait-for engine.started` in place of the bare TCP-connect probe, verified against a locally built image with a real docker compose run (health: starting -> healthy). This depends on the readonly-attach event-preservation fix merged separately in #2134. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen zilla logs healthcheck timing margin JVM cold-start for a single "zilla logs" invocation runs 1.6-2.8s locally; CI runners are typically slower, so the prior 3s timeout was intermittently exceeded. Widen timeout/interval/start_period to give comfortable headroom. * fix(examples): further widen zilla logs healthcheck tolerance Observed one CI failure where the healthcheck flipped unhealthy ~80s in (not at startup), consistent with transient CPU contention on a shared CI runner rather than a real regression - reproduced locally for 150s+ with zero restarts and no crashes on the same image. Widen timeout and retries so a few consecutive slow checks under load don't flip the container unhealthy. * refactor(command-logs): simplify to --filter/--follow, drop --wait-for/--timeout --wait-for and --timeout existed to let the command block until a specific event appeared, for use in a Docker HEALTHCHECK. That need is fully served by a one-shot --filter check instead: read the current event buffer, print matches, and exit non-zero if nothing matched - Docker's own interval/retries already provide the retry loop, so the command doesn't need to poll or block internally. --grep is renamed --filter and now matches a glob pattern (* and ?) against the event type name instead of a plain substring, and its match result now drives the command's exit status directly instead of a separate --wait-for string. --follow/-f replaces the removed polling loop: after printing the current buffer it keeps printing new events forever, mirroring `docker logs -f`. It's independent of --filter and unconditional - unlike the old --wait-for polling loop, it never exits on its own. Update the asyncapi.http.kafka.proxy healthcheck to use --filter in place of --wait-for. * refactor(command-logs): drop --filter in favor of grep/jq, add --format json --filter's only remaining job was producing an exit code for a Docker HEALTHCHECK. Plain text output already composes with grep for that (and jq once piped through --format json), so the internal glob matching and exit-status plumbing are no longer needed - the command now always exits 0 if it can read the log, matching `docker logs`. Add --format text|json (text is the default, matching prior output). JSON is one object per line (namespace, timestamp epoch-millis, traceId as a zero-padded hex string to avoid precision loss, event, message), rendered via jakarta.json for correct escaping. Update the asyncapi.http.kafka.proxy healthcheck to pipe through grep now that filtering is external. * refactor(command-logs): use JsonGenerator instead of JsonObjectBuilder JsonObjectBuilder.build().toString() materializes a full JsonObject tree (JsonString/JsonNumber wrappers for every field) before serializing. JsonGenerator writes primitives directly to the stream without that intermediate allocation. Only flush(), never close(), the generator - close() closes the underlying output source per the jakarta.json spec, which would break --follow (repeated print() calls against the same System.out across poll iterations). Verified in a real container that --follow --format json keeps printing across iterations rather than silently going dark after the first record. * refactor(command-logs): promote from incubator to runtime command-logs has proven stable; move it out of incubator/ into runtime/ and drop the @Incubating gate so it's available without ZILLA_INCUBATOR_ENABLED. Update the module lists and dependency management in incubator/pom.xml and runtime/pom.xml accordingly, and drop the now-unneeded ZILLA_INCUBATOR_ENABLED env var from the asyncapi.http.kafka.proxy example, which only needed it for the logs-based healthcheck. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(command-logs): actually stage the incubator->runtime module edits The previous commit only captured the git mv renames — the pom.xml parent/name change, the incubator/runtime aggregator pom module-list updates, the @Incubating removal, and the compose.yaml env var drop were left unstaged (a bad pathspec in the git add call aborted the whole staging operation) and broke CI: incubator/pom.xml still declared command-logs as a child module pointing at a directory that no longer existed there. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): use zilla logs for all example healthchecks Replace the bare TCP-connect probe (proves only that the kernel accepted a connection, not that the engine finished attaching bindings) with `zilla logs | grep -q engine.started` across every examples/*/compose.yaml healthcheck, completing the follow-up from updated. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen healthcheck tolerance for asyncapi.http.kafka.proxy and sse.kafka.fanout CI logs show both examples' zilla container missed "healthy" by a narrow margin under CI runner contention (130s vs the prior 125s budget for asyncapi.http.kafka.proxy; 54s vs 40s for sse.kafka.fanout), not a healthcheck logic failure — `zilla logs` reproduces correctly and quickly locally against the same image. Both examples spin up extra containers (kafka-ui, kafka-init, and for sse.kafka.fanout also a ticker-producer), so widen retries to 10 at the same interval/timeout/start_period already used for asyncapi.http.kafka.proxy, giving 145s total. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): drop /opt/zilla/ prefix from healthcheck now that PATH includes it #2154 (merged into develop, picked up by this rebase) adds /opt/zilla to PATH in the Docker image, so every example's healthcheck can call the bare `zilla` command instead of spelling out the full path. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen asyncapi.http.kafka.proxy healthcheck retries further The 145s budget (retries: 10) was still marginally exceeded under CI contention (156s observed, vs 130s the previous run) — specs are local files, not fetched remotely, so this is CI runner variance, not a fixable root cause. Bump retries to 15 for 195s of headroom. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(engine): add readiness marker so readonly attach fails cleanly, not with a stack trace zilla logs (and any other readonly Engine attach) could crash with an uncaught NoSuchFileException, IllegalStateException, or ArithmeticException when invoked before the real engine finished writing its layout files (Info, BufferPoolLayout, EventsLayout each have their own independent create-then-populate race). Catching every such exception type in each readonly command doesn't scale — any future layout has its own new failure shape. Add a single, dedicated readiness signal instead: an empty `ready` marker file, written as the last statement in Engine's constructor only after every EngineWorker (and its layouts) is fully built. Info's existing early write is untouched — command-stop depends on reading its PID as soon as the process exists, even mid-init, to be able to kill a hung startup. A readonly attach now checks `ready`'s filesystem mtime against Info's startTime field before touching any layout: if `ready` is missing, or older than the current run's startTime (a stale marker left behind by a prior crashed run when the engine directory survives a restart), the attach throws EngineNotInitializedException instead of constructing anything. zilla logs catches it and prints a short message with exit 1, rather than exposing internal layout exceptions. Verified against a real container under CPU throttling: previously every early attempt crashed with a raw stack trace; now attempts before readiness print "Engine not yet initialized: <dir>" cleanly, and the very first attempt after readiness succeeds. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): normalize all healthcheck budgets to a uniform 60s zilla logs's engine.started event is a more reliable readiness signal than the bare TCP-connect probe it replaced, but it fires later — after every worker/binding fully attaches, not just after the socket listener binds. The previous per-example ad-hoc widening (a few examples bumped individually as they showed marginal-timing failures in CI, most left at the original 40s default) has been chasing flakiness one example at a time. Standardize every example on the same interval: 5s / timeout: 3s / retries: 9 / start_period: 15s budget (15 + 9*5 = 60s), replacing the two previously-widened examples' inconsistent higher values as well, to see if a single generous budget is sufficient across the board in the GitHub Actions environment. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen zilla logs healthcheck to 90s across all examples CI run 29348244798 (60s budget) showed 3 of 4 failures were genuine healthcheck timeouts, not the already-known MQTT test flakiness: http.kafka.crud, grpc.kafka.fanout, and sse.proxy.jwt all reported "container zilla-1 is unhealthy" ~79-84s after container start, well past the nominal 60s (15s start_period + 9*5s interval) budget. asyncapi.mqtt.kafka.proxy's zilla-1 became healthy fine at ~32s; its failure was an unrelated mosquitto_sub connection-refused timeout. Bump retries from 9 to 15 (nominal budget 60s -> 90s) to absorb the observed ~20-24s of CI runner scheduling drift under matrix-wide Docker healthcheck contention. * fix(examples): replace zilla logs healthcheck with ready-marker file check CI runs kept showing genuine healthcheck timeouts even after widening the budget to 90s (up to 136s observed on run 29350930146, against a different set of examples each time), pointing at something worse than plain scheduling noise. The original healthcheck (pre-#2131) was a bare TCP-connect probe with near-zero cost. Switching it to `zilla logs | grep -q engine.started` made the signal more precise but pays for a full JVM cold start on every 5s poll for the entire startup window -- up to 15+ extra JVM spawns directly competing with the engine's own busy-spinning workers for CPU, right when the engine needs it most to finish initializing. Use `test -f $ENGINE_DIRECTORY/ready` instead: a zero-cost shell check against the same race-free Ready marker introduced for the readonly zilla logs attach path, with no JVM spawn at all. Keeps the 90s budget unchanged so this isolates the one variable. * fix(engine): mark Ready only after bindings are actually attached Ready.markReady() was called at the end of the Engine constructor, before ZillaStartCommand ever calls engine.start(). start() is what calls manager.start(), which synchronously attaches namespaces and bindings (EngineConfigWatchTask.submit() -> onPathChanged() runs the initial config attach before returning). Marking ready in the constructor meant the ready marker -- and therefore any healthcheck or zilla logs consumer relying on it -- could observe "ready" before a single binding existed, let alone was listening. This surfaced concretely once the example healthchecks switched to a plain `test -f $ENGINE_DIRECTORY/ready` shell check (no JVM warm-up delay to accidentally mask the race): tcp.echo, ws.echo, and asyncapi.http.kafka.proxy all went "healthy" while nothing was yet wired to serve traffic, so the actual protocol test against the now-open port got nothing back. Move the Ready.markReady() call to the end of start(), immediately after manager.start() returns -- the same point where the `engine.started` event itself is fired further down in EngineManager.start(), so both signals now describe the same true readiness point. Added EngineTest#shouldNotMarkReadyUntilBindingsAttached, which fails against the old placement (ready flips true before start() is even called) and passes against the fix. --------- Co-authored-by: Claude <noreply@anthropic.com>
jfallows
added a commit
that referenced
this pull request
Jul 15, 2026
… checks (#2136) (#2160) * feat(command-logs): add zilla logs command for engine event readiness checks Adds incubator/command-logs providing a `zilla logs` CLI command that attaches a readonly Engine to a running instance's ENGINE_DIRECTORY, reads its event ring buffers, and formats them via the existing EventFormatter pipeline. Supports --grep to filter by event type and --wait-for/--timeout to block until a specific event (e.g. engine.started) appears, so it can serve as a reliable Docker healthcheck in place of a bare TCP-connect probe. Adds Engine.supplyQName()/supplyEventFormatter() delegates (mirroring the existing supplyLocalName()/supplyLabelId()/supplyEventReader() pattern) since the public Engine facade used by external readonly CLI tools did not previously expose per-worker qualified-name resolution or event formatting. Resolves #2131. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(command-logs): resolve zilla.directory correctly and single-check --wait-for by default Fixes ZillaLogsCommand's default zilla.properties/engine directory resolution to match how `zilla start` resolves it (via the zilla.directory system property the launcher script sets), instead of a CWD-relative default that never matches inside the Docker image where no working directory is set. Also changes --wait-for's default --timeout to a single check instead of a 30s internal poll loop: a Docker HEALTHCHECK's own timeout would otherwise SIGKILL the process mid-retry, since HEALTHCHECK already provides its own interval/retries polling cadence. Updates the asyncapi.http.kafka.proxy example's healthcheck to use `zilla logs --wait-for engine.started` in place of the bare TCP-connect probe, verified against a locally built image with a real docker compose run (health: starting -> healthy). This depends on the readonly-attach event-preservation fix merged separately in #2134. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen zilla logs healthcheck timing margin JVM cold-start for a single "zilla logs" invocation runs 1.6-2.8s locally; CI runners are typically slower, so the prior 3s timeout was intermittently exceeded. Widen timeout/interval/start_period to give comfortable headroom. * fix(examples): further widen zilla logs healthcheck tolerance Observed one CI failure where the healthcheck flipped unhealthy ~80s in (not at startup), consistent with transient CPU contention on a shared CI runner rather than a real regression - reproduced locally for 150s+ with zero restarts and no crashes on the same image. Widen timeout and retries so a few consecutive slow checks under load don't flip the container unhealthy. * refactor(command-logs): simplify to --filter/--follow, drop --wait-for/--timeout --wait-for and --timeout existed to let the command block until a specific event appeared, for use in a Docker HEALTHCHECK. That need is fully served by a one-shot --filter check instead: read the current event buffer, print matches, and exit non-zero if nothing matched - Docker's own interval/retries already provide the retry loop, so the command doesn't need to poll or block internally. --grep is renamed --filter and now matches a glob pattern (* and ?) against the event type name instead of a plain substring, and its match result now drives the command's exit status directly instead of a separate --wait-for string. --follow/-f replaces the removed polling loop: after printing the current buffer it keeps printing new events forever, mirroring `docker logs -f`. It's independent of --filter and unconditional - unlike the old --wait-for polling loop, it never exits on its own. Update the asyncapi.http.kafka.proxy healthcheck to use --filter in place of --wait-for. * refactor(command-logs): drop --filter in favor of grep/jq, add --format json --filter's only remaining job was producing an exit code for a Docker HEALTHCHECK. Plain text output already composes with grep for that (and jq once piped through --format json), so the internal glob matching and exit-status plumbing are no longer needed - the command now always exits 0 if it can read the log, matching `docker logs`. Add --format text|json (text is the default, matching prior output). JSON is one object per line (namespace, timestamp epoch-millis, traceId as a zero-padded hex string to avoid precision loss, event, message), rendered via jakarta.json for correct escaping. Update the asyncapi.http.kafka.proxy healthcheck to pipe through grep now that filtering is external. * refactor(command-logs): use JsonGenerator instead of JsonObjectBuilder JsonObjectBuilder.build().toString() materializes a full JsonObject tree (JsonString/JsonNumber wrappers for every field) before serializing. JsonGenerator writes primitives directly to the stream without that intermediate allocation. Only flush(), never close(), the generator - close() closes the underlying output source per the jakarta.json spec, which would break --follow (repeated print() calls against the same System.out across poll iterations). Verified in a real container that --follow --format json keeps printing across iterations rather than silently going dark after the first record. * refactor(command-logs): promote from incubator to runtime command-logs has proven stable; move it out of incubator/ into runtime/ and drop the @Incubating gate so it's available without ZILLA_INCUBATOR_ENABLED. Update the module lists and dependency management in incubator/pom.xml and runtime/pom.xml accordingly, and drop the now-unneeded ZILLA_INCUBATOR_ENABLED env var from the asyncapi.http.kafka.proxy example, which only needed it for the logs-based healthcheck. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(command-logs): actually stage the incubator->runtime module edits The previous commit only captured the git mv renames — the pom.xml parent/name change, the incubator/runtime aggregator pom module-list updates, the @Incubating removal, and the compose.yaml env var drop were left unstaged (a bad pathspec in the git add call aborted the whole staging operation) and broke CI: incubator/pom.xml still declared command-logs as a child module pointing at a directory that no longer existed there. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): use zilla logs for all example healthchecks Replace the bare TCP-connect probe (proves only that the kernel accepted a connection, not that the engine finished attaching bindings) with `zilla logs | grep -q engine.started` across every examples/*/compose.yaml healthcheck, completing the follow-up from updated. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen healthcheck tolerance for asyncapi.http.kafka.proxy and sse.kafka.fanout CI logs show both examples' zilla container missed "healthy" by a narrow margin under CI runner contention (130s vs the prior 125s budget for asyncapi.http.kafka.proxy; 54s vs 40s for sse.kafka.fanout), not a healthcheck logic failure — `zilla logs` reproduces correctly and quickly locally against the same image. Both examples spin up extra containers (kafka-ui, kafka-init, and for sse.kafka.fanout also a ticker-producer), so widen retries to 10 at the same interval/timeout/start_period already used for asyncapi.http.kafka.proxy, giving 145s total. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): drop /opt/zilla/ prefix from healthcheck now that PATH includes it #2154 (merged into develop, picked up by this rebase) adds /opt/zilla to PATH in the Docker image, so every example's healthcheck can call the bare `zilla` command instead of spelling out the full path. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen asyncapi.http.kafka.proxy healthcheck retries further The 145s budget (retries: 10) was still marginally exceeded under CI contention (156s observed, vs 130s the previous run) — specs are local files, not fetched remotely, so this is CI runner variance, not a fixable root cause. Bump retries to 15 for 195s of headroom. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(engine): add readiness marker so readonly attach fails cleanly, not with a stack trace zilla logs (and any other readonly Engine attach) could crash with an uncaught NoSuchFileException, IllegalStateException, or ArithmeticException when invoked before the real engine finished writing its layout files (Info, BufferPoolLayout, EventsLayout each have their own independent create-then-populate race). Catching every such exception type in each readonly command doesn't scale — any future layout has its own new failure shape. Add a single, dedicated readiness signal instead: an empty `ready` marker file, written as the last statement in Engine's constructor only after every EngineWorker (and its layouts) is fully built. Info's existing early write is untouched — command-stop depends on reading its PID as soon as the process exists, even mid-init, to be able to kill a hung startup. A readonly attach now checks `ready`'s filesystem mtime against Info's startTime field before touching any layout: if `ready` is missing, or older than the current run's startTime (a stale marker left behind by a prior crashed run when the engine directory survives a restart), the attach throws EngineNotInitializedException instead of constructing anything. zilla logs catches it and prints a short message with exit 1, rather than exposing internal layout exceptions. Verified against a real container under CPU throttling: previously every early attempt crashed with a raw stack trace; now attempts before readiness print "Engine not yet initialized: <dir>" cleanly, and the very first attempt after readiness succeeds. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * refactor(examples): normalize all healthcheck budgets to a uniform 60s zilla logs's engine.started event is a more reliable readiness signal than the bare TCP-connect probe it replaced, but it fires later — after every worker/binding fully attaches, not just after the socket listener binds. The previous per-example ad-hoc widening (a few examples bumped individually as they showed marginal-timing failures in CI, most left at the original 40s default) has been chasing flakiness one example at a time. Standardize every example on the same interval: 5s / timeout: 3s / retries: 9 / start_period: 15s budget (15 + 9*5 = 60s), replacing the two previously-widened examples' inconsistent higher values as well, to see if a single generous budget is sufficient across the board in the GitHub Actions environment. Claude-Session: https://claude.ai/code/session_015gEjFBcrpmGxgfvigBdCSa * fix(examples): widen zilla logs healthcheck to 90s across all examples CI run 29348244798 (60s budget) showed 3 of 4 failures were genuine healthcheck timeouts, not the already-known MQTT test flakiness: http.kafka.crud, grpc.kafka.fanout, and sse.proxy.jwt all reported "container zilla-1 is unhealthy" ~79-84s after container start, well past the nominal 60s (15s start_period + 9*5s interval) budget. asyncapi.mqtt.kafka.proxy's zilla-1 became healthy fine at ~32s; its failure was an unrelated mosquitto_sub connection-refused timeout. Bump retries from 9 to 15 (nominal budget 60s -> 90s) to absorb the observed ~20-24s of CI runner scheduling drift under matrix-wide Docker healthcheck contention. * fix(examples): replace zilla logs healthcheck with ready-marker file check CI runs kept showing genuine healthcheck timeouts even after widening the budget to 90s (up to 136s observed on run 29350930146, against a different set of examples each time), pointing at something worse than plain scheduling noise. The original healthcheck (pre-#2131) was a bare TCP-connect probe with near-zero cost. Switching it to `zilla logs | grep -q engine.started` made the signal more precise but pays for a full JVM cold start on every 5s poll for the entire startup window -- up to 15+ extra JVM spawns directly competing with the engine's own busy-spinning workers for CPU, right when the engine needs it most to finish initializing. Use `test -f $ENGINE_DIRECTORY/ready` instead: a zero-cost shell check against the same race-free Ready marker introduced for the readonly zilla logs attach path, with no JVM spawn at all. Keeps the 90s budget unchanged so this isolates the one variable. * fix(engine): mark Ready only after bindings are actually attached Ready.markReady() was called at the end of the Engine constructor, before ZillaStartCommand ever calls engine.start(). start() is what calls manager.start(), which synchronously attaches namespaces and bindings (EngineConfigWatchTask.submit() -> onPathChanged() runs the initial config attach before returning). Marking ready in the constructor meant the ready marker -- and therefore any healthcheck or zilla logs consumer relying on it -- could observe "ready" before a single binding existed, let alone was listening. This surfaced concretely once the example healthchecks switched to a plain `test -f $ENGINE_DIRECTORY/ready` shell check (no JVM warm-up delay to accidentally mask the race): tcp.echo, ws.echo, and asyncapi.http.kafka.proxy all went "healthy" while nothing was yet wired to serve traffic, so the actual protocol test against the now-open port got nothing back. Move the Ready.markReady() call to the end of start(), immediately after manager.start() returns -- the same point where the `engine.started` event itself is fired further down in EngineManager.start(), so both signals now describe the same true readiness point. Added EngineTest#shouldNotMarkReadyUntilBindingsAttached, which fails against the old placement (ready flips true before start() is even called) and passes against the fix. --------- Co-authored-by: Claude <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Description
Adds
runtime/command-logs, providing azilla logsCLI command that attaches a readonlyEngineto a running instance'sENGINE_DIRECTORY(mirroring the existingzilla metricscommand's pattern), reads its event ring buffers, and formats them via the existingEventFormatterpipeline.--format text|json— text (default, human-readable) or newline-delimited JSON, suitable for piping tojq-f, --follow— modelsdocker logs -f: without it, prints the current log and exits; with it, keeps printing new events as they arrive--grep/--filter/--waitflags — composes with externalgrep/jqinstead of reinventing filtering, and a one-shot "did event X already happen" check doesn't need in-process waiting (a DockerHEALTHCHECKre-invokes the command on its own interval/retries cadence)ZillaLogsCommandSpiis a regular (non-@Incubating) command, available withoutZILLA_INCUBATOR_ENABLED— promoted fromincubator/toruntime/once the design settledzilla.properties/engine directory the same wayzilla startdoes (via thezilla.directorysystem property the launcher script sets), rather than a CWD-relative default that never matches inside the Docker imageJSON output is produced with
jakarta.json's streamingJsonGenerator(notJsonObjectBuilder), avoiding an intermediate object tree per event on what can be a--followpolling loop. Trace IDs are encoded as zero-padded hex strings (not JSON numbers) to avoid precision loss for unsigned 64-bit values injq/JS consumers.Also adds
Engine.supplyQName()/Engine.supplyEventFormatter()delegates (mirroring the existingsupplyLocalName()/supplyLabelId()/supplyEventReader()pattern) since the publicEnginefacade used by external readonly CLI tools didn't previously expose per-worker qualified-name resolution or event formatting.Updates the healthcheck in every
examples/*/compose.yaml(39 examples) from the bare TCP-connect probe (echo -n '' > /dev/tcp/127.0.0.1/<port>, which only proves the kernel accepted a connection) tozilla logs | grep -q engine.started, fully addressing the follow-up called out in #2131. TheZILLA_INCUBATOR_ENABLEDenv var is removed fromasyncapi.http.kafka.proxy's compose.yaml since it's no longer needed there (other examples that still require it do so for unrelated incubator bindings, e.g.binding-amqp, and are left untouched).Filed/commented on #1012 to track adding a matching
--format json(or equivalent) option to the stdout exporter, since this PR establishes the JSON-lines convention for one output path but not the other.Example output
Testing
LogsPrinterTest,LogsReaderTest(7 tests) —LogsReaderis a small extracted class so the event-decode logic is unit-testable with a fakeMessageReader/MessageFormatter, without needing a liveEngine../mvnw clean installpasses locally forcommand-logs(compile, checkstyle, license headers, tests, JaCoCo, moditect module-info weaving), and a full-repo./mvnw validate/installconfirms theincubator→runtimemodule move didn't break the reactor.zilla help logs/zilla logswork with noZILLA_INCUBATOR_ENABLEDset, and exercised both--format textand--format json(including--follow) against a running engine's realengine.startedevent.docker compose upagainst the local image for a representative example (tcp.echo): container reaches Docker'shealthystate withinstart_period.Fixes #2131
Generated by Claude Code