Goal of this document

Logging is something subjective. What is for one person too much, is too little for someone else.

The goal of this document is to a common agreement between all teams on when, what and how to log.

What to log

Depending on the logging purpose we should choose a set of properties which we want to store for each log message. It can be divided in following groups and all 4 information group should be included:

when the situations occurs,
where in code,
who caused this situation,
what happened.

Log levels and when they need to be used

*Fatal*	Highest level: important stuff down. Mostly used by frameworks rather than business logic code.
*Error*	Application crashes / exceptions.
*Warn*	Suboptimal behavior, but the application can continue
*Info*	Indication of where we are in the flow, in case of normal behavior
*Debug*	Executed queries, flow decisions, timers
*Trace*	Begin method X, end method X etc.

Examples

*Fatal*	Cannot access database, JMS queue
*Error*	NullPointerException
*Warn*	Data not provided, using default “X”
*Info*	Message with id X received in FLUX Plugin. Message with id X validated. Sending it to Exchange.
*Debug*	SELECT FROM BLA;* Determined that this message is a Sales Response. Method A took 20 ms.
*Trace*	Begin method X, end method X etc.

ToString()

Be careful when logging objects. A toString() method should be implemented. Otherwise, the log of the object is useless.

Be careful when implementing toString() of JPA entities. Make sure that you don’t start to lazy load all your relations. Not only causes this unnecessary strain on the database, in worst case you get a stackoverflow because of 2-directional relationships.

Log levels in different environments

Logs with a log level lower than INFO are not printed.

A developer can manually activate DEBUG and TRACE levels if necessary.

MDC

SLF4J provides us with a very useful tool: an MDC tracer.

In this tracer, you can put thread-related information, like a technical guid, functional ids, the name of the logged in user, …

We use this to have a sense of context in our logs.

An example:

A message is received in the plugin. A technical guid is generated. If we log something in the plugin, that guid will be appended to our log line.
The message is passed to Exchange. The technical guid is passed as a JMS header. Exchange reads this JMS header, and uses the puts that same technical guid on int MDC context. Every log line will be appended with that technical guid.
…

The result: if something goes wrong with a certain message, we determine the technical guid that was put on the MDC context for that message. Now, we can filter on all logs that are caused by this message, in every module.

This is one use of the MDC tracer. We can go further and also use functional keys, a username, …

For more information, check out the following documentation:

Log format

The structure of a log line is defined by a configuration file called logback.xml.

One structure for all logs

At the moment of writing, several modules have their own definition of the structure of a log line. It would make debugging in production easier if we could agree on one format for every module. That would make it possible to consume logs with tools like Logstash.

A proposed pattern:

%d{yyyy-MM-dd HH:mm:ss} [%thread] %X{requestId} %-5level %logger{40} %X{userId}- %msg%n

Exceptions could be made for module-specific information that could be put on the MDC tracer, like functional keys.

Logback is responsible for the log format, not the developer

Because Logback will append the log level to the log line, there is no need to repeat the level in the message.

log.info("[INFO] Received following request method in MDR [{}]", requestMethod);

Another example below. The developer wanted to make this log stand out. Instead of doing this, log level fatal can be used, which makes it stand out in a cleaner way.

log.error("[ERROR] [ERROR] [ERROR] Request method is null! Request type : {}", request.getClass().getSimpleName());

Distinction between logging to console and logging to file

At the moment of writing, some modules append colors to their logs. This look great in the console, making them easier to process.

We would propose to use these colors only when logging to console, and not to do this when logging to a file. In a file, the colors are not processed correctly, leaving us with weird characters.

2018-04-23 00:01:50 [34mINFO [0;39m [36mPingTask.run(30)[0;39m - Ping time arrived!

Logging exceptions

When an exception occurs, the stacktrace is often a very important source of information. The general rule is to log the exception message + the (complete) stacktrace.

Corner case: sometimes exceptions are to be expected as part of normal behavior. This is a code smell. However, if we want to accept this suboptimal situation, it’s no use to print the stacktrace with the exception.

Resources

http://www.diwebsity.com/2016/04/05/logging-guideliness/

https://developer.atlassian.com/server/confluence/logging-guidelines/

https://www.javacodegeeks.com/2011/01/10-tips-proper-application-logging.html

Union VMS

Logging guidelines