Logging: On The Level

A discussion of logging best practices, specifically on the correct purpose of each logging level.

When Logging Goes Bad

Admit it, you’ve definitely seen this monstrosity of a logging statement at some point during your career:

 12026-06-29T14:03:56.438+01:00 ERROR [nio-5002-exec-1] u.c.s.myproject.controllers.SearchController   
 2    : Request validation error: Parse error on request JSON.
 3java.lang.IllegalArgumentException: Parse error on request JSON
 4        at uk.co.skipoles.myproject.controllers.SearchController.search(SearchController.kt:56) ~[main/:na]
 5        at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
 6        at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
 7        at kotlin.reflect.jvm.internal.calls.CallerImpl$Method.callMethod(CallerImpl.kt:97) ~[kotlin-reflect-2.2.20.jar:2.2.20-release-333]
 8        at kotlin.reflect.jvm.internal.calls.CallerImpl$Method$Instance.call(CallerImpl.kt:113) ~[kotlin-reflect-2.2.20.jar:2.2.20-release-333]
 9        at kotlin.reflect.jvm.internal.KCallableImpl.callDefaultMethod$kotlin_reflection(KCallableImpl.kt:250) ~[kotlin-reflect-2.2.20.jar:2.2.20-release-333]
10        at kotlin.reflect.jvm.internal.KCallableImpl.callBy(KCallableImpl.kt:155) ~[kotlin-reflect-2.2.20.jar:2.2.20-release-333]
11        at org.springframework.web.reactive.result.method.InvocableHandlerMethod$KotlinDelegate.invokeFunction(InvocableHandlerMethod.java:374) ~[spring-webflux-6.2.10.jar:6.2.10]
12        at org.springframework.web.reactive.result.method.InvocableHandlerMethod.lambda$invoke$0(InvocableHandlerMethod.java:205) ~[spring-webflux-6.2.10.jar:6.2.10]
13        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:132) ~[reactor-core-3.7.9.jar:3.7.9]
14        at reactor.core.publisher.MonoZip$ZipCoordinator.signal(MonoZip.java:297) ~[reactor-core-3.7.9.jar:3.7.9]
15        at reactor.core.publisher.MonoZip$ZipInner.onNext(MonoZip.java:478) ~[reactor-core-3.7.9.jar:3.7.9]
16        at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180) ~[reactor-core-3.7.9.jar:3.7.9]
17        at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:122) ~[reactor-core-3.7.9.jar:3.7.9]
18        at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74) ~[reactor-core-3.7.9.jar:3.7.9]
19        at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79) ~[reactor-core-3.7.9.jar:3.7.9]
20        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:158) ~[reactor-core-3.7.9.jar:3.7.9]
21        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107) ~[reactor-core-3.7.9.jar:3.7.9]
22        at reactor.core.publisher.FluxMapFuseable$MapFuseableConditionalSubscriber.onNext(FluxMapFuseable.java:299) ~[reactor-core-3.7.9.jar:3.7.9]
23        at reactor.core.publisher.FluxFilterFuseable$FilterFuseableConditionalSubscriber.onNext(FluxFilterFuseable.java:337) ~[reactor-core-3.7.9.jar:3.7.9]
24        at reactor.core.publisher.Operators$BaseFluxToMonoOperator.completePossiblyEmpty(Operators.java:2096) ~[reactor-core-3.7.9.jar:3.7.9]
25        at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:145) ~[reactor-core-3.7.9.jar:3.7.9]
26        at reactor.core.publisher.FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onComplete(FluxContextWriteRestoringThreadLocals.java:149) ~[reactor-core-3.7.9.jar:3.7.9]
27        at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State.onAllDataRead(AbstractListenerReadPublisher.java:501) ~[spring-web-6.2.10.jar:6.2.10]
28        at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onAllDataRead(AbstractListenerReadPublisher.java:137) ~[spring-web-6.2.10.jar:6.2.10]
29        at org.springframework.http.server.reactive.ServletServerHttpRequest$RequestBodyPublisher$RequestBodyPublisherReadListener.onAllDataRead(ServletServerHttpRequest.java:382) ~[spring-web-6.2.10.jar:6.2.10]
30        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:207) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
31        at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
32        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:50) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
33        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
34        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1769) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
35        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
36        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1189) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
37        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:658) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
38        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63) ~[tomcat-embed-core-10.1.44.jar:10.1.44]
39        at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]

Imagine trying to support a system that’s logging like this. Makes me want to claw my eyes out, but why? Let’s look at the elements that make this a terrible logging statement:

The logging entry is recorded at the ERROR level, but this is just some user-supplied data that is invalid. Your support team/engineer are going to be pissed to get notified each time a user supplies invalid data.
The error message is meaningless. Yes, the request failed to parse correctly, but we have no idea why. How do we know what the user did wrong? How do we offer them support when they contact us to report this error they keep getting?
Oh, that stack trace, why? Apart from perhaps the first two lines, there’s just nothing useful in it at all. Do I really care about the internals of Tomcat or Spring Boot? I do not! The actual log line itself gives more than enough info to locate the place that generated the error.

The Key Logging Distinction

When thinking about logging, there’s an important distinction to make for each logging statement: is this something we will be looking for, or is it something we need to be told about? (thanks to my colleague Fionn for coming up with this excellent phrasing).

Things that we need to be told about are the triggers for investigations. Some of these may be so critical that they should notify a support engineer as soon as they happen. Others may be more advisory and may only trigger an investigation when a certain threshold is reached. The other trigger for an investigation, of course, is a user raising a support ticket.

Things that we will be looking for are the information that supports the investigation. These are all the contextual information that helps us to understand what went on and how the system got into a state that caused a particular error or issue. Sometimes there might not even be a particular issue, and we just need to understand why the system did what it did to explain a valid outcome.

The Correct Level

Typical logging libraries tend to support five common logging levels: TRACE, DEBUG, INFO, WARN, and ERROR. Some might not have TRACE, while others might also add a FATAL/CRITICAL level. For this exploration let’s just stick with the core five.

First off, we need to associate each level with one of the distinctions outlined above. How you do this might be company-specific, based on the requirements of your support team. However, the way I like to work is that ERROR and WARN are the things I want to be told about, while INFO, DEBUG, and TRACE are the things I need to be looking for.

ERROR

I personally tend to avoid the most common conventions and reserve the use of the ERROR level for only the most serious issues. If a system that I built logs an entry at ERROR level, then at minimum I would want this to be surfaced in a Slack channel.

A monitoring system may then sit on top of the logs and inspect these error occurrences. Depending on the nature and frequency of error log entries, it may decide to email a support engineer or immediately trigger a pager call.

The things that I consider for this level of error are:

Scenarios where my application is unable to function successfully (when I don’t have a FATAL level)
Things that are currently not working correctly but that could automatically recover at some point in the future
Unexpected non-recoverable failures to individual request flows (such as an unhandled exception)

A more specific list would include things like:

The underlying database is temporarily down
Storage is full or memory has run out
Authentication with a third-party system is failing
A core system service has become unavailable
A specific security violation has been detected
An unexpected and unhandled exception was thrown while processing a request

WARN

The WARN level I reserve mostly for things that are serious enough to require investigation, but which are usually recoverable and specific to a single user workflow. Warning level items are probably serious enough to raise in a Slack channel, but not for priority investigation. Often they might just be monitored for certain thresholds of occurrences; or they may be used to generate daily reports on certain types of expected and non-critical failures.

I also use the WARN level to flag failures of specific business workflows that need to trigger investigations. These could be items that people/systems want to be aware of so they can monitor and trigger based on frequency or cluster patterns. Alternatively, they might trigger a follow-up call to a customer or supplier to check everything is okay. A secondary advantage is that sometimes important events can get lost in the general logging noise, so putting them at WARN level also makes these more important items stand out clearly.

Some things I would consider at a WARN level are:

A transient authentication error that went away after a retry within the same request scope
A non-critical service that wasn’t available, but which didn’t prevent the workflow from completing
A third-party system that occasionally suffers a timeout or returns an error, but is otherwise working fine
A declined payment, where a cluster of frequent payment failures would trigger closer monitoring by the support team

INFO

This is the main level of logging that I use within my code. We should bear in mind that this is likely to be the lowest level of logging within a production environment. The INFO level log entries should therefore be able to answer the questions “What happened?” and “Why did it happen?”

Things recorded at the INFO level include:

Key workflow steps and the data decisions that dictated those steps
Important data state values and changes
Interaction and results of communicating with third-party systems
Data validation failures

DEBUG

This level is primarily reserved for development level logging. However, it can also be enabled in production for investigation of specific issues when needed. DEBUG logging content should include more details and be more focused on the ‘what’ rather than the ‘why’. This logging should be more numerous in areas that have complex data-driven flow logic, complex calculations, or areas where performance is critical or likely to be an issue.

TRACE

The TRACE level of logging is less used these days due to the quality of modern debugging and performance profiling tools. However, there are some cases where it is still useful, such as embedded systems or critical systems where other tooling might not be available or easily used.

Trace logging is usually used to log entry and exit for every method call, all parameter and return values, each path through conditional logic and so forth. In a modern codebase I tend to find that too much trace logging pollutes the code and makes it less readable. Quality and well-crafted DEBUG logging should be sufficient for most purposes.

Contextual Log Messages

As well as logging at the correct level, the contents of the log message are also incredibly important. Consider the difference between Parse error on request JSON and Error during JSON parsing - field: "startDate" value: "1st January 2030" was not in the expected ISO 8601 format. The first message just tells us generally that something went wrong. The second message tells us exactly which item was the problem, the value that caused the error, and why this value was invalid.

Contextual log messages should always contain the following information:

Some indication of what processing action was taking place
The specific state that was being used by the processing
The result of the processing action
If an error occurred:
- The specific data item that caused the error
- The value of that item
- The expected condition that was not met

However, it is important to note that secrets, credentials, PII, payment data, and the like should not generally have their values logged. If logging the value is useful, then consider masking it in some way. One approach is to use a logger that doesn’t mask during development but is swapped to one that masks values given specific patterns in production environments.

Ideally, the underlying logging platform will provide automated correlation through concepts like trace and span id values. If not then some form of correlation id should also be part of the log message.

The critical thing to avoid is context-free logging messages like: Building the request; Received response from remote system; or Unable to process the search results. None of these contain enough information to understand what actually happened and are therefore meaningless bytes in your logging system storage!

When To Include Stack Traces

Mostly we want to avoid logging stack traces unless they provide real value. I generally avoid throwing exceptions within my own code, preferring monadic result types that are more conducive to normal logging. Even when we do throw our own exceptions, good logging means those stack traces add limited value over the log content itself.

In places where we know exceptions will occasionally be raised as part of normal execution (e.g. communicating with an external system, parsing user-supplied input, marshalling, etc.), it’s usually better to trap the exception, extract the contextual information, turn it into a meaningful log message, and log just that.

The main time it’s worth logging a stack trace is when we receive an exception we were never expecting. These will mostly be runtime exceptions, such as a NullPointerException, where there is real value in knowing the exact place that the exception occurred. This can sometimes be deep inside some standard library or third-party system, so the stack trace is also useful for identifying the specific point in our code that the call originated.

Conclusion

Great logging, consistently applied, can make a huge difference in the ability to support your system and investigate issues. Bad logging can be a major source of frustration for support engineers. Messy logging with limited context, at the wrong level, and full of meaningless stack traces is a recipe for disaster.

Logging levels should be used consistently. They should clearly delineate between the things that we need to be told about and the things that we need to be looking for. The log message itself should be clear, informative, and rich in the relevant context. Stack traces should generally be avoided except for unexpected exceptions where they contain important additional information.