log tracing

[swalchemist]

This implements log tracing, where log messages will now include a trace ID and span ID that's either sent in from the API client or otherwise auto-generated. This allows for improved debugging, so transactions can be correlated between different web services that use the same trace ID. In the example below, - [ace36bc5bdccffef,ace36bc5bdccffef] is the part that is added:

[2023-08-16T00:56:46.060135Z] uaa - 13 [https-jsse-nio-8443-exec-1] - [ace36bc5bdccffef,ace36bc5bdccffef] .... DEBUG --- UaaMetricsFilter: Successfully matched URI: /oauth/token to a group: /oauth-oidc

In some code paths, like startup and rate limiting where the filter that implements log tracing isn't run, the trace and span IDs may be blank:

[2023-08-17T01:53:42.790149Z] uaa/uaa - 17490 [main] - [,] .... INFO --- SpringSecurityCoreVersion: You are running with Spring Security Core 5.7.10

See also a related change for uaa-release to update the log4j format there.

NOTE: This could be a breaking change for any stakeholder who parses UAA logs, because this add information to the middle of each log line in uaa.log.

[#185000950]

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/185849157

The labels on this github issue will be updated when the story is started.

[hsinn0]

A message that I posted in a private slack thread before:

Regrading the logging format for trace-id & span-id, I wonder if we should do the similar to what spring-cloud-sleuth does instead. spring-cloud-sleuth does logging as follows by default for example:

2023-06-27 17:19:11.024 INFO [,80f198ee56343ba864fe8b2a57d3eff7,e457b5a2e4d86bd1] 66074 --- [nio-8080-exec-1] c.e.hellosleuth.HelloSleuthApplication : Hello world!

The format is having [service-name-value,trace-id-value,span-id-value] at the beginning.

Has this been considered?

[swalchemist]

Regarding the logging format for trace-id & span-id, I wonder if we should do the similar to what spring-cloud-sleuth does instead. spring-cloud-sleuth does logging as follows by default for example:

2023-06-27 17:19:11.024 INFO [,80f198ee56343ba864fe8b2a57d3eff7,e457b5a2e4d86bd1] 66074 --- [nio-8080-exec-1] c.e.hellosleuth.HelloSleuthApplication : Hello world!

There were tradeoffs wherever we put it. It seems that if someone is parsing the logs, they might have a pattern that looks at the time stamp and the fields following it. So putting the new information just before "----" seemed slightly less likely to break any existing patterns. In fact, there was an acceptance test in uaa-release that had a pattern that still worked, while moving the trace ID earlier would have broken it.

But I get what you've said about the scope of the trace ID being broader than the thread ID (and even the uaa app name). It's hard to compare with the spring-cloud-sleuth example because other things are already in a different order, like the log level.

Ultimately, though, I don't feel strongly about where we place the new information, and we just made what thought was the least undesirable choice at the time.

[Tallicia]

@strehle @torsten-sap In reviewing the comments and discussions, I am inclinded to merge this. Do you feel there is a roadblock that needs to be resolved before merging?

[Tallicia]

I'm curious why these changed.

[swalchemist]

The diff is not very helpful. We just inserted one line and changed the position numbers on the rest.

[Tallicia]

LGTM