Rainbow Gum 0.15.0: ScopedValue key values, logging into JFR, and OpenTelemetry without the SDK

[u/agentoutlier]

Rainbow Gum 0.15.0: ScopedValue key values, logging into JFR, and OpenTelemetry without the SDK

I try not to spam every release, but 0.15.0 has some stuff I'm genuinely excited about, and 1.0.0 is coming before the holidays hence need some feedback.

First up, Scoped Key Values. MDC on ThreadLocal has been leaking requestIds into the wrong requests since the dawn of time because somebody forgot a finally block or threadpool cleanup. JDK 25 gave us ScopedValue (JEP 506) and holy shit it just fixes it:

ScopedKeyValues.builder()
    .add("requestId", requestId)
    .add("userId", userId)
    .run(() -> {
        logger.info("handling request"); // has requestId and userId
        service.handle(request);
    });

StructuredTaskScope forks get a frozen snapshot, so sibling tasks can't stomp on each other. I barely had to do anything; the JDK devs did the hard part, and this is what MDC should be going forward. This should hopefully get added to SLF4J 3.0. Bless the JDK team.

Next, logging straight into JDK Flight Recorder. Each log event becomes a JFR event, so your logs sit on the same timeline as GC pauses and lock contention in JMC:

logging.appenders=jfr
logging.appender.jfr.output.uri=jfr:///var/log/myapp.jfr

No -XX:StartFlightRecording flags to screw up in your Dockerfile. And here's the kicker: in our benchmark, logging to JFR was about 40% faster than plain text to a file, and the output was about 8x smaller on disk. The JFR folks built something seriously fast and most of us only ever open it when production is on fire.

Last, OpenTelemetry. rainbowgum-otlp ships logs over OTLP using nothing but the JDK's own HttpClient. No OpenTelemetry SDK, no OkHttp. It's roughly 7x smaller than the Logback or Log4j2 OpenTelemetry setups with their default dependencies: https://github.com/jstachio/rainbowgum/blob/main/doc/why/opentelemetry_export_size.md

Oh and here is something shocking. The Logback and Log4j2 OpenTelemetry appenders hand events to the SDK, whose batch processor has a 2048 event queue by default. When it fills up, it throws your logs away and doesn't tell you. When we blasted a burst of logs at a collector with stock settings, only about 7% (Logback) and 10% (Log4j2) of them made it. Rainbow Gum applies backpressure by default, and if a batch does fail you get an alert and a metric, not silence. Losing logs exactly when your app is getting hammered is the worst possible time to lose logs. On a related note after bugging them I think Spring Boot might had some more observation hooks to logging frameworks.

There's a lot more (colorful logs with no pattern strings, error messages that tell you exactly which property is wrong and where it came from). You can even cosplay as a Go process with logfmt support. The longer pitch is here: https://github.com/jstachio/rainbowgum/blob/main/why_rainbowgum_is_better.md

GitHub: https://github.com/jstachio/rainbowgum

Docs: https://jstach.io/doc/rainbowgum/current/apidocs/

Before 1.0 I can still break things without feeling bad about it, so if the API or the property names bug you, now's the time to tell me. Brutal honesty welcome.

Finally I'm not a paid professional OSS developer so this library like my others is sort of a love letter to the Java community and language.

[u/nuharaf]

Wohoo. Coming from spring boot user, this will make my avaje service more on-par with the original spring boot version

[u/Kango_V]

Very nice. I'm using RG on a TUI project with Tamboui and it's working well :)

[u/egahlin]

I'm curious about the JFR implementation, why do you store the stack trace as text instead of using the event’s stack trace? We’re considering adding more stack-trace capabilities to the JDK (filtering, per event stack depths etc), so it would be interesting to know if something is missing.

You create the events in a factory method. This may work, but it’s probably easier for the JIT to eliminate the allocation if the object doesn’t escape the method. Something like:

switch (event.level()) {
case TRACE -> emitTrace(event.loggerName, s);
...
}

[u/agentoutlier → u/egahlin]

There was an issue doing this and we found a memory leak. I original had it like that and then I had a bunch of agents stress test it.

Then I found on my own and not via LLM it was not really that and yeah I forgot to revisit it.

It was somewhat related to this: https://github.com/jstachio/rainbowgum/blob/main/doc/jdk-jfr-bugs.md

I guess I forgot to have the agent check in its findings. The LLM btw wrote that text but I found the issue so I guess I still have use :)

Let me check it again later today.

[u/agentoutlier → u/egahlin]

Erik the string exception was entirely my fault as I implemented it that way and apparently I indeed did have a conversation with both Claude and Codex on it a while back and forgot that there was some issues with the async publisher as well as the bug on the previous comment (I don't vibe code but I do use the best tools I can to help).

Now for your EA claim

You were right: the factory merges the five event types into one allocation so escape analysis can't remove it. With no recording running, write() went from 40 bytes and ~15 ns per call to zero allocation and ~1.7 ns after switching to one emit method per level. That's fixed for the next release. I retried it and your claim is correct and did measure it is a worthwhile saving.

Again w/ transparency I used Claude and Codex to setup this benchmark.

On stack traces, it's two separate things:

1. The text field is the logged Throwable: the exception's own stack plus causes and suppressed. The event's stack trace is where commit() happened, which is a different stack, and there's no field type that can hold a stack trace or Throwable. So we format it, and every repeat of the same exception stores the whole text again. A stack trace (or Throwable) field type that goes into the deduplicated stack pool would be great for logging.

2. For the caller, commit() happens deep inside the logging framework, so the top frames are ours. If the filtering you mentioned could skip frames up to and including a logging package, @StackTrace(true) would become useful and probably cheaper than our StackWalker based caller info (this last part Claude figured out).

So I'm glad you brought it up because it might be a feature for JFR: an async publisher, commit() runs on the publisher thread, so Event Thread, stack and start time are all the publisher's. Being able to capture thread/stack/time at begin() on one thread and commit later on another would fix that for every async logger. It might be possible but I'm not aware it is.

[u/egahlin → u/agentoutlier]

We are aware of both issues.

We could optionally capture the stack trace in the begin() method, but the problem is that a file rotation could happen before commit() is called, so we would need to track those stack trace IDs separately in native so they survive the rotation.

To complicate things further, a user may decide never to call commit(), which would effectively cause a native memory leak. We would likely need to inject a field into the event class and populate it with all the data when we rotate.

It's more expensive, but doable.

[u/AndrewHaley13]

Re ScopedValue: thank you. It was my pleasure, and I'm glad you like it.