Skip to content

Bounded Google Cloud Logging writes, background log emitter, and agent-native stdout format - #23

Closed
anth-volk wants to merge 7 commits into
mainfrom
feat/bounded-async-log-emission
Closed

Bounded Google Cloud Logging writes, background log emitter, and agent-native stdout format#23
anth-volk wants to merge 7 commits into
mainfrom
feat/bounded-async-log-emission

Conversation

@anth-volk

@anth-volk anth-volk commented Jul 7, 2026

Copy link
Copy Markdown
Contributor

Fixes #22

What this adds

The full bounded + asynchronous log emission suite, in four gated commits plus docs. Everything defaults off (OBSERVABILITY_LOG_EMIT_MODE=sync, OBSERVABILITY_STDOUT_FORMAT=plain): the only default behavior change is the bounded write timeout, which is strictly safer.

  1. Bounded Google Cloud Logging writesLogger.log_struct exposes no call options, so writes inherited the transport defaults (60s retry deadline / 60s timeout), letting a degraded Logging API stall a caller 60s per record. Entries are now built directly (the Logger is kept for full_name and platform-detected default_resource) and written through the gapic layer with a configurable per-call budget (OBSERVABILITY_GOOGLE_LOG_TIMEOUT_SECONDS, default 5s) that both bounds the call and caps retries of transient errors, falling back fail-open to the unbounded call on non-gapic transports. Adds emit_batch (N records, one bounded call). The gapic-path test parses the hand-built entries through the real proto machinery, so field parity with log_struct is checked by protobuf itself.
  2. Agent-native stdout format (OBSERVABILITY_STDOUT_FORMAT=google) — JSON lines carry the special keys the Cloud Run/GKE agent promotes to first-class LogEntry fields (severity, logging.googleapis.com/trace|spanId|labels), enabling full-fidelity Cloud Logging ingestion from stdout with zero in-process network emission.
  3. BackgroundEmitDestination — the standard accept/emit split: emit() appends to a bounded buffer (default 1000, drop-oldest with counted, throttled reporting) and returns immediately; a lazy pid-aware daemon worker drains batches (preferring emit_batch). After 3 consecutive failed batches the wrapper trips and subsequent emit() calls raise, flowing through the existing manager circuit breaker and stdout fallback with zero manager changes. flush(deadline) drains from the caller's thread (registered atexit); recovery for forked or snapshot-restored processes goes through manager-level restart_observability().
  4. Config, wiring, lifecycleOBSERVABILITY_LOG_EMIT_MODE=async wraps non-stdout destinations (stdout, as the fallback sink, is never wrapped); queue/batch/latency/flush-deadline knobs; runtime.shutdown() now flushes log destinations before the OTel flush (which previously early-returned past everything when no providers existed); public flush_observability() / restart_observability().

Fail-open invariants preserved

Per-destination BaseException guards at construction and emission, the DESTINATION_FAILURE_LIMIT breaker, and stdout fallback (all from #21) are unchanged and re-verified: an integration test drives a tripped async wrapper through the manager and asserts the disable + stdout-fallback path fires exactly as for a synchronous destination.

Review fixes (commit d7152b8)

A 9-angle review of the branch surfaced 15 findings, all addressed:

  • Recovery actually works now: restart_observability() rebuilds destinations from config — reviving breaker-disabled destinations with fresh clients (the Modal snapshot-restore case that was previously a silent no-op) and clearing the manager's failure ledger. configure() closes replaced destinations (no orphaned workers/clients/atexit hooks on adapter reconfigure); close() unregisters its atexit hook.
  • No more hair-trigger trips: writes retry transient errors inside the bounded budget (default raised to 5s), the worker backs off between failed batches, and batch failures report records_lost. A one-time report fires when only the unbounded non-gapic transport is available.
  • Drop-oldest buffering (reviewed and reversed from drop-newest): an outage keeps the freshest, most diagnostic records instead of pinning stale pre-incident chatter.
  • Concurrency corrections: normalize-at-enqueue (caller mutation can't tear records), flush() waits for the in-flight batch, superseded workers are signaled instead of leaking, one persistent wake event, thread-local internal-error flag (was a cross-thread stderr-misroute), idempotent disable under reentrant failure reporting, except Exception so Ctrl-C propagates from main-thread flushes.
  • Hygiene: knob clamps (queue>=1, latency>=10ms, batch<=500), explicit _drain_once outcomes, single async-wrapping choke point, normalized emit-mode comparison, shared trace/timestamp helpers with event-time stamping from created_at, single-source defaults, honest Protocols, BackgroundEmitDestination exported, docs corrected.

Second-round review fixes (commit 0253238)

A second review at the same depth surfaced 15 fix-the-fix findings, all addressed:

  • Event-time integrity: records are normalized and timestamped at enqueue, carried as (payload, log_type, severity, enqueue_time) tuples, so delayed batches keep their event time; the previous created_at stamping was removed (it backdated entries to context start time). Synchronous writes deliberately carry no timestamp — server receive time is correct there, so stdout's google format drops its time key too.
  • Generation/thread correctness: failure counters mutate under the lock with a stale-generation skip (a superseded worker can no longer trip the fresh one); the emitter trips before its report fires (reports include records_lost and, on trip, the stranded count); drop-oldest accounting was moved before the deque eviction it counts; the worker survives BaseException with a destination_worker_crashed report; fork handling registers instances in a WeakSet wired to os.register_at_fork, signals the superseded generation, and reports records the child inherited and dropped.
  • Lifecycle: flush(0) now attempts one drain (do-while) and flush exits clean when drained and idle; close() is terminal — no worker respawn, no atexit re-register — and reports the count of records it discards; the manager's configure/restart/disable serialize on a reentrant lifecycle lock, failure reports are deferred until the new destination set is live (a report's own emission cannot re-enter configuration), replaced destinations close only after their successors are installed, and disabling is exactly-once and closes the destination.
  • Config/wiring: one absolute deadline shared across per-destination flushes; string knobs normalize in __post_init__ regardless of construction path; config warnings for unknown emit modes and the double-ingestion stdout_format=google + google-destination combination; runtime.shutdown() flushes log destinations inside the timed closure so shutdown_timeout_seconds bounds it; the bounded-write closure is resolved once at construction.
  • Automatic (half-open) breaker recovery is deliberately out of scope; follow-up tracked separately.

Validation

  • 169 tests, coverage 91% (repo gate ≥90, branch coverage), ruff clean. New concurrency code is tested deterministically — the worker loop is factored (_drain_once/_write_batch) so batching, tripping, overflow, flush, restart, and fork-detection are all driven synchronously; one end-to-end test exercises the real thread.
  • Sync mode is byte-identical: all pre-existing destination/manager/runtime tests pass unmodified (except the google-destination fakes, reworked for the new write path).

Merging auto-releases per the push workflow; the .added fragments make this 1.4.0. Downstream consumers (policyengine-household-api) adopt via a separate PR after release.

🤖 Generated with Claude Code

anth-volk and others added 7 commits July 7, 2026 21:51
Logger.log_struct exposes no call options, so writes inherited the
transport defaults: a 60-second retry deadline and 60-second timeout
that let a degraded Logging API stall the calling request far longer
than any observability write is worth. Build the log entries directly
(keeping the Logger for its full_name and platform-detected default
resource) and write through the gapic layer with retry disabled and a
configurable timeout (OBSERVABILITY_GOOGLE_LOG_TIMEOUT_SECONDS, default
2s), falling back to the unbounded write_entries call on non-gapic
transports rather than dropping logs. Adds emit_batch so multiple
records cost one bounded call.

Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
OBSERVABILITY_STDOUT_FORMAT=google emits JSON lines carrying the
special keys the Cloud Run/GKE logging agent promotes to first-class
LogEntry fields (severity, time, logging.googleapis.com/trace, spanId,
labels), so agent-collected stdout gets full-fidelity ingestion with no
in-process network emission. The bounded-labels helper moves to
destinations.base for reuse by both destinations. Default format is
unchanged.

Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
BackgroundEmitDestination installs the standard accept/emit split
around any destination: emit() appends to a bounded buffer and returns
immediately, and a lazy pid-aware daemon worker drains batches to the
wrapped destination (preferring emit_batch, so a batch costs one
bounded API call). Overflow drops the newest record with counted,
throttled reporting; after the failure limit of consecutive failed
batches the wrapper trips and subsequent emit() calls raise, flowing
through the manager's existing circuit breaker and stdout fallback
unchanged. flush(deadline) drains from the caller's thread with an
atexit hook registered on first worker start; restart() clears buffer
and trip state for forked or snapshot-restored processes whose threads
did not survive.

Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
OBSERVABILITY_LOG_EMIT_MODE=async (default sync) wraps non-stdout
destinations in the background emitter with knobs for queue size,
batch size, batch latency, and flush deadline; stdout is never wrapped
because it is the fallback sink. runtime.shutdown() now flushes log
destinations before the OTel provider flush (which previously
early-returned past everything when no providers existed), and the
runtime exposes flush_log_destinations/restart_log_destinations,
surfaced publicly as flush_observability/restart_observability for
consumers whose processes fork or restore from memory snapshots.

Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Recovery: manager.restart() now rebuilds destinations from config,
reviving breaker-disabled destinations with fresh clients (the Modal
snapshot-restore case), clearing the failure ledger; configure() closes
the destinations it replaces so reconfigures cannot orphan workers,
clients, or atexit hooks, and close() unregisters its atexit hook.

Resilience: Google writes retry transient errors inside the bounded
budget (default now 5s) instead of retry=None turning every blip into a
breaker strike; the worker backs off between failed batches and reports
records_lost; a one-time report fires when only the unbounded non-gapic
transport is available; the buffer drops OLDEST on overflow, keeping
the freshest records through an outage.

Concurrency: payloads are normalized at enqueue so caller mutation
cannot tear records; flush() tracks and waits for the in-flight batch
and includes it in the remainder report; superseded workers are
signaled before their generation event is replaced (fixing a leaked
worker the fork test now asserts against); one persistent wake event
removes the lost-wakeup window; the runtime's internal-error flag is
thread-local; manager disable is idempotent under reentrant failure
reporting; _write_batch catches Exception, letting KeyboardInterrupt
propagate from main-thread flushes.

Hygiene: knob clamps (queue >= 1, latency >= 10ms, batch <= 500);
_drain_once returns explicit empty/delivered/failed outcomes; async
wrapping moved to a single choke point; emit-mode comparison
normalized; shared trace/timestamp helpers in destinations.base with
event-time stamping from created_at; defaults defined once in config;
Protocol declares logging_api; BackgroundEmitDestination exported;
duplicate test fakes consolidated; README and fragments corrected.

Refs #22

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Correctness: records are normalized and timestamped at enqueue and
carried as (payload, log_type, severity, enqueue-time) tuples so
delayed batches keep their event time and the removed created_at
backdating cannot recur; drop-oldest accounting moved before the deque
eviction it counts; failure counters mutate under the lock with a
stale-generation skip so a superseded worker cannot trip the fresh one;
the emitter trips before its report fires and includes the stranded
record count; flush attempts one drain before the first deadline check
so flush(0) works against a healthy sink, exits clean when drained and
idle, and waits for in-flight batches; close() is terminal (no worker
respawn, no atexit re-register) and reports the count of records it
discards; the worker survives BaseException with a crash report;
fork/snapshot handling registers instances in a WeakSet wired to
os.register_at_fork, signals the superseded generation, and reports
inherited records dropped in the child.

Manager: configure/restart/disable serialize on a reentrant lifecycle
lock; failure reports are deferred until the new destination set is
live so a report's own emission cannot re-enter configuration; replaced
destinations close only after their successors are installed; disabling
is exactly-once under reentrant reporting and closes the destination;
one absolute deadline is shared across per-destination flushes; config
warnings fire for unknown emit modes and the double-ingestion
stdout_format=google + google-destination combination.

Google destination: transient errors retry inside the bounded budget
via a single closure resolved at construction (worst case ~2x budget,
documented); a one-time report fires when only the unbounded non-gapic
transport is available; close() releases the client transport. Config
knobs normalize in __post_init__ regardless of construction path. The
runtime shutdown flushes log destinations inside the timed closure so
the shutdown timeout bounds it. Stdout google mode no longer emits a
time key: synchronous emission makes server receive time correct.

Docs and changelog updated to match; 169 tests, branch coverage 91%.
@anth-volk

Copy link
Copy Markdown
Contributor Author

Abandoning this branch. A third deep review round kept surfacing new lifecycle defects — including regressions introduced by the previous two fix rounds (shutdown budget inversion, configure/restart rebuild race) — so we're discarding this implementation and starting over rather than continuing to patch it. The commits remain viewable in this PR (final state: 0253238) for reference. Issue #22 stays open for the redesign.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Bounded and asynchronous log emission: cap Google write latency, add a background emitter, and agent-native stdout format

1 participant