Logging optional key values

Question

I have this webapplication that logs quite heavily. We have implemented a call to MDC for each requesting thread to be able to trace a user in our logs.

A logmessage could look as follows:

INFO  [2017-10-09 10:10:55,841] user_uuid=123-123-123 com.myapp.SomeClass: Some log message...

Now the problem is that most of the time, no current user exist, and we don't have use for the user_uuid field in the log example above. So instead, it will look like this:

INFO  [2017-10-09 10:10:55,841] user_uuid= com.myapp.SomeClass: Some log message...

Is there any way of not writing the MDC key & value in log if there is no MDC value? Some log format I haven't found yet?

I want it to look like this, if no MDC value is found:

INFO  [2017-10-09 10:10:55,841] com.myapp.SomeClass: Some log message...

The above (MDC) examples are configured like so:

%-5p [%d{ISO8601,UTC}] user_uuid=%mdc{user_uuid:-} %c: %m%n%rEx

Answer 1

You can use %replace to replace user_uuid= with an empty string if the value is missing (note the trailing $ in the regex, meaning "end of input"):

%-5p [%d{ISO8601,UTC}]%replace( user_uuid=%mdc{user_uuid}){' user_uuid=$', ''} %c: %m%n%rEx

As a bonus, the above will also remove the leading space if the value is missing, so you don't get two successive spaces in your log message if the value is missing.

Answer 2

This entry in your pattern ...

user_uuid=%mdc{user_uuid:-}

... consists of two parts:

1. A static 'root' (i.e. the left hand side of the assignment) this is always present in the output. The decision to include this is made when Logback initialises itself.

2. A value (i.e. the right hand side of the assignment), this is only present in the output if the MDC attribute user_uuid is populated. The decision to include this is made at runtime for each log event.

Probably not telling you anything new there but the key point is that the inclusion of the left hand side cannot be undone by any conditional logic which kicks in when evaluating each log event emitted by your application. Logback's PatternLayoutBase walks through its given pattern and each time it comes to something conditional or derivable it evaluates it and appends the evaluated value to the pattern it is walking through. So, for your pattern; Logback has already assigned "user_uuid=" to the current StringBuilder before it even starts evaluating the MDC condition.

However, you could achieve the desired end goal by populating the user_uuid MDC attribute with: user_uuid=<the user id> and then change you logging pattern to simply log the MDC value without the assignment. For example:

%-5p [%d{ISO8601,UTC}] %mdc{user_uuid:-}%c: %m%n%rEx

With that pattern in place the following log invocations ...

logger.info("Does this include the user_uuid?");
MDC.put("user_uuid", "user_uuid=me ");
logger.info("Or does this include the user_uuid?");

... will emit:

INFO  [2017-10-09 11:15:22,420] com.stackoverflow.SomeClassTest: Does this include the user_uuid?
INFO  [2017-10-09 11:15:22,435] user_uuid=me com.stackoverflow.SomeClassTest: Or does this include the user_uuid?

Though that's a bit awkward because you have to remember to include a space at the end of the MDC value and this user_uuid MDC value is only useful for logging within this specific pattern (whereas simply including the user_uuid - without the left hand side and the equals operator - would be more generally useful).

If these drawbacks render this approach unuseable for you then I think you'll have to get stuck into Logback's PatternLayoutBase or FormattingConverter to implement some form of look-ahead or some way of amending the in-progress StringBuilder if the right hand side of an assignment returns an empty String.