Skip to content

feat: emit-time enrichers; thread-safe date formatting - #2

Open
Flawless wants to merge 3 commits into
mainfrom
emit-time-enrichers
Open

feat: emit-time enrichers; thread-safe date formatting#2
Flawless wants to merge 3 commits into
mainfrom
emit-time-enrichers

Conversation

@Flawless

Copy link
Copy Markdown

Why

Consumers need to attach thread-scoped context to every log — the concrete case: dd.trace_id/dd.span_id from the active Datadog span, so Datadog links logs to traces (HealthSamurai/billing#277 does this today with a per-call-site ctx workaround that misses forked threads). Appenders can't do it: they run on the publisher agent thread, where the emitting thread's span/MDC is gone. The only correct interception point is log on the caller thread.

What

  • add-enricher! / rm-enricher!: id-keyed registry (re-registration replaces — reload-safe); every enricher runs against the assembled log map on the emitting thread before send-off. A throw or non-map return skips that enricher for that log — a bad enricher can't break logging or other enrichers.
  • format-date: the shared SimpleDateFormat is not thread-safe (mutates state on format); concurrent emission could garble ts. Now ThreadLocal.

Notes

  • Zero behavior change with no enrichers registered; per-log cost is one atom deref.
  • Tests cover: augmentation, throwing-enricher isolation, non-map returns, replace/remove, and a 16-thread format-date race.

Verification

clojure -M:test   # 9 tests, 20 assertions, 2 pending (pre-existing), 0 failures

Downstream chain once merged: sha bump in aidbox-billing-core → billing replaces its per-site capture with one add-enricher! registration.

🤖 Generated with Claude Code

https://claude.ai/code/session_01C6nThfB7TczmTgk5Xb3MJq

@Flawless
Flawless force-pushed the emit-time-enrichers branch 2 times, most recently from 97eaaf7 to 5f0d10d Compare August 27, 2026 12:31
Flawless and others added 2 commits August 27, 2026 16:36
format-date shares one SimpleDateFormat across all emitting threads;
format mutates its internal Calendar. With per-thread distinct dates,
16x500 concurrent formats reliably garble output or throw
ArrayIndexOutOfBoundsException out of the JDK calendar — and format-date
runs in mk-log on the caller thread, so that throw escapes into
application code. Identical dates race invisibly, which is why the
test uses divergent ones.

Fails on this commit by design; fixed in the next.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C6nThfB7TczmTgk5Xb3MJq
ThreadLocal keeps the produced string bit-identical to the shared
instance — same class, same pattern — so nothing parsing ts can drift.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C6nThfB7TczmTgk5Xb3MJq
@Flawless
Flawless force-pushed the emit-time-enrichers branch from 5f0d10d to d744085 Compare August 27, 2026 12:37
@Flawless

Copy link
Copy Markdown
Author

Restructured test-first per review; the history now proves the bug:

  1. 1a402d5 test (red) — on unmodified main: 8 tests, 14 assertions, 1 failures. The race needs per-thread distinct dates: identical dates write identical calendar fields and race invisibly (an earlier same-date version of this test stayed green on the broken code). With divergent dates the shared SimpleDateFormat reliably garbles or throws ArrayIndexOutOfBoundsException from inside the JDK calendar — and since format-date runs in mk-log on the caller thread, that throw escapes klog.core/log into application code.
  2. b9024fe fix (green) — per-thread instance via ThreadLocal; output stays bit-identical to the shared instance (same class, same pattern), so ts consumers can't drift. DateTimeFormatter would be the modern equivalent — happy to swap if preferred; the test covers either.
  3. d744085 enrichers — the thread-pin test uses a raw ThreadLocal deliberately: send-off conveys dynamic bindings, so a binding-based probe passes even if enrichment moves to the publisher thread. Sabotage-verified: moving enrich inside the agent action fails the test.

Ops note: no occurrence of the AIOOBE fingerprint in 15 days of retained billing logs — production formats "now" across threads, so fields rarely diverge; boundary rollovers are the realistic trigger. Latent, not observed.

@Flawless
Flawless force-pushed the emit-time-enrichers branch from d744085 to 96babcb Compare August 27, 2026 12:42
add-enricher! registers a fn applied to every log map on the emitting
thread before publish — the one point where thread-scoped context
(an active trace, MDC) is still visible; appenders run on the publisher
agent and cannot see it. Throwing or non-map-returning enrichers are
skipped per log. Test pins the thread with a raw ThreadLocal: dynamic
bindings are conveyed by send-off and would pass on the wrong thread.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01C6nThfB7TczmTgk5Xb3MJq
@Flawless
Flawless force-pushed the emit-time-enrichers branch from 96babcb to 6b7e055 Compare August 27, 2026 12:43
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.

1 participant