X-Trace-ID and structured logging output. by MikeNeilson · Pull Request #1682 · USACE/cwms-data-api

MikeNeilson · 2026-04-08T22:52:07Z

Okay, somewhat got away from me, but it all works now.

The combination of slf4j and logback, while not required, does simplify the creation of structured logs. As well as having the same log output as OpenDCS uses in cloud environment which will simplify log searches (we aren't learning two formats.)

There is a gRPC context mechanism provided by flogger but I'm still reading up. I think I'm likely to create a custom ContextDataProvider (what Flogger needs implemented) to handle mapping to the SLF4j MDC. so still using that system, just cleaner.

Additionally, since we know we have async things, we needed to sort out how the nested contexts work on a thread pool to make sure the Trace ID passing along correctly.

For those that do not like the log formatting, one can always setup your local environment to use something you find more friendly. However, the cda-plain.log was thrown together at the last moment so suggestions welcome.

The structured output uses jsonl as the extension. At least in VS Code this validates and renders correctly as a defined JSON file... e.g. nice element coloring.

MikeNeilson · 2026-04-13T16:57:27Z

NOTE: I'm not hard set on the whole logback thing, it was a rather obnoxious pain to get working; However, I believe there is going to be custom work no matter what as most items that use JUL don't really provide much support for things like the MappedDiagnosticContext concept.

krowvin

Tomecat is def a fix, the rest is up to you!

krowvin · 2026-04-14T18:20:56Z

+        if (UUID_MATCHER.matcher(id).matches()) {
+            return id;
+        } else {
+            throw new IOException("Trace id '" + id + "' is not a valid UUIDish value.");


Throwing here will likely bubble up as a 500. This makes it look like a server issue but really it's for bad client input.

Should we fallback to a generated ID or return a 400 instead?

Fair point, but would have to sort out how to do that. Probably need to hijack the response... which is fine since why process any more if the request is invalid.

krowvin · 2026-04-14T18:22:07Z

+    public static final String CONTEXT_TRACE_ID = "traceID";
+    public static final String HEADER_TRACE_ID = "X-Trace-ID";
+
+    public static final Pattern UUID_MATCHER = Pattern.compile("[a-z0-9]{8}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{12}");


This looks like it will only cover lowercase UUID?

Good catch, spec says should be lower case, but to accept both.

krowvin · 2026-04-14T18:24:19Z

+            // Just reset back the MDC map to whatever it was before we decided to muck with it.
+            return () -> {
+                MDC.clear();
+                MDC.setContextMap(currentMdc);


if currentMdc is null will it throw an unhandled error? Might need a guard clause for null

MDC::setContextMap handles null inputs since several version earlier than we're using.

krowvin · 2026-04-14T18:26:14Z

+            final var meta = this.getMetadata();
+            final var currentMdc = MDC.getCopyOfContextMap();
+
+            atCreationMdc.putAll(atCreationMdc);


Is this putting the current value back into itself?

Is that the same as doing this

myVar = 1

myVar = myVar

print(myVar)

1

... kinda, but not.

It does look super weird, but we have to copy the current context as it is in the thread where install was called, then add all of the values this LoggingContext already has, and then put them onto the current thread.

MDC values are "ThreadLocal" hence all the magic to shift the contexts around.

Bit more, The CdaLoggingContext instance was (possibly) created on a different thread than where install() is called. If they're on the same thread, yeah it's basically a no-op, but it's done this way to cover the case it was made for, separate threads.

this seems a little too clever. I think rewriting to:

final Map<String, String> mergedMdc = new HashMap<>(); if (currentMdc != null) { mergedMdc.putAll(currentMdc); } mergedMdc.putAll(atCreationMdc);

and then populating a mergedMdc in the two loops followed by

MDC.setContextMap(mergedMdc);

would accomplish the same thing, be less confusing to look at, and not muck with atCreationMdc (which by its name, shouldn't be modified).

Thanks, wasn't trying to be clever, just dealing with the which thread has what situtation. I'll look at it again. that said MDC.getCopy... can never be null; according to the SLF4j docs.

krowvin · 2026-04-14T18:29:35Z

This would end up needing merged with #1428 - i'm happy to merge this into 1428 after you get this into main though!

Co-authored-by: Charles Graham <charles.r.graham@usace.army.mil>

MikeNeilson

Thanks, that Dockerfile change was probably why a specific form of override wasn't working.

MikeNeilson · 2026-04-14T18:30:48Z

+    public static final String CONTEXT_TRACE_ID = "traceID";
+    public static final String HEADER_TRACE_ID = "X-Trace-ID";
+
+    public static final Pattern UUID_MATCHER = Pattern.compile("[a-z0-9]{8}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{4}-[a-z0-9]{12}");


Good catch, spec says should be lower case, but to accept both.

MikeNeilson · 2026-04-14T18:31:53Z

+        if (UUID_MATCHER.matcher(id).matches()) {
+            return id;
+        } else {
+            throw new IOException("Trace id '" + id + "' is not a valid UUIDish value.");


Fair point, but would have to sort out how to do that. Probably need to hijack the response... which is fine since why process any more if the request is invalid.

MikeNeilson · 2026-04-14T18:34:13Z

+            final var meta = this.getMetadata();
+            final var currentMdc = MDC.getCopyOfContextMap();
+
+            atCreationMdc.putAll(atCreationMdc);


... kinda, but not.

It does look super weird, but we have to copy the current context as it is in the thread where install was called, then add all of the values this LoggingContext already has, and then put them onto the current thread.

MDC values are "ThreadLocal" hence all the magic to shift the contexts around.

MikeNeilson · 2026-04-14T18:34:42Z

+            // Just reset back the MDC map to whatever it was before we decided to muck with it.
+            return () -> {
+                MDC.clear();
+                MDC.setContextMap(currentMdc);


MDC::setContextMap handles null inputs since several version earlier than we're using.

MikeNeilson · 2026-04-14T20:13:57Z

This would end up needing merged with #1428 - i'm happy to merge this into 1428 after you get this into main though!

That is separate, that's more about the transparent proxy, not something within CDA itself.

adamkorynta · 2026-04-16T23:03:21Z

out of curiosity, why did this get modified for this PR?

There's a post commit hook for the javascript, so it just always gets updated. I usually do a git restore or something to exclude it and just forgot on this one.

adamkorynta · 2026-04-16T23:23:11Z

+            final var tags = this.getTags();
+            if (tags != null) {
+                tags.asMap().forEach((key, entry) ->
+                    MDC.put(key, String.join(",", entry.stream()


Since you're already streaming, use Collectors.joining(",") in the collect instead of joining the end product.

adamkorynta · 2026-04-16T23:28:21Z

+            final var meta = this.getMetadata();
+            final var currentMdc = MDC.getCopyOfContextMap();
+
+            atCreationMdc.putAll(atCreationMdc);


this seems a little too clever. I think rewriting to:

final Map<String, String> mergedMdc = new HashMap<>(); if (currentMdc != null) { mergedMdc.putAll(currentMdc); } mergedMdc.putAll(atCreationMdc);

and then populating a mergedMdc in the two loops followed by

MDC.setContextMap(mergedMdc);

would accomplish the same thing, be less confusing to look at, and not muck with atCreationMdc (which by its name, shouldn't be modified).

adamkorynta · 2026-04-16T23:36:15Z

+public class TraceIdFilter implements Filter
+{
+    public static final String CONTEXT_TRACE_ID = "traceID";
+    public static final String HEADER_TRACE_ID = "X-Trace-ID";


Why "X-Trace-ID" instead of (or maybe in addition to?) traceparent: https://www.w3.org/TR/trace-context/

would be a 16-byte hex value as standard, not a UUID

To be honest, I wasn't aware of that, and from my brief search of what people have done it never came up. Just about everyone just does a UUID with X-Trace-Id or X-Client-Trace-Id.

But I'll go do some more research, all for standards. Especially if used by default in systems like Granafa/etc for searching.

MikeNeilson added 5 commits April 13, 2026 15:37

Initial trace id using a bit of a hack.

86b3c4d

Working Flogger ScopedLoggerContext.

65a4205

WIP, tomcat messages not logged during integration test.

ab407ad

Logback working locally, normal logging in docker compose.

2fff3e1

New logging working in container.

a953cac

MikeNeilson force-pushed the feature/1666-trace-id branch from 558997c to a953cac Compare April 13, 2026 16:37

Cleanup, correct test behavior.

b3d34b5

MikeNeilson marked this pull request as ready for review April 13, 2026 16:53

MikeNeilson requested review from adamkorynta, krowvin, rma-psmorris, rma-rripken and zack-rma April 13, 2026 16:56

krowvin requested changes Apr 14, 2026

View reviewed changes

Apply suggestion from @krowvin

cd0e694

Co-authored-by: Charles Graham <charles.r.graham@usace.army.mil>

MikeNeilson commented Apr 14, 2026

View reviewed changes

MikeNeilson added 2 commits April 14, 2026 11:37

Merge branch 'develop' into feature/1666-trace-id

0f0b852

Improved Trace ID error handling, with tests. Improve log output.

f2c33a8

MikeNeilson changed the title ~~Initial trace id using a bit of a hack.~~ X-Trace-ID and structured logging output. Apr 14, 2026

adamkorynta reviewed Apr 16, 2026

View reviewed changes

Conversation

MikeNeilson commented Apr 8, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MikeNeilson commented Apr 13, 2026

Uh oh!

krowvin left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

MikeNeilson Apr 14, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

krowvin commented Apr 14, 2026

Uh oh!

MikeNeilson left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

MikeNeilson commented Apr 14, 2026

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

MikeNeilson commented Apr 8, 2026 •

edited

Loading

MikeNeilson Apr 14, 2026 •

edited

Loading