Microservices with Spring Boot, Netflix OSS and Maven - Log Configuration

This is a follow up post to the microservice overview post. In this post I will explain the log configuration.

The basis of the configuration is the default Spring Boot configuration. I just adapted as I needed. The two important changes are:

• Added [%mdc] to the CONSOLE_LOG_PATTERN and the FILE_LOG_PATTERN
• The log file is only written if the LOG_FILE variable (system variable or environment variable) is set. With the system variable it's possible to have several microservices running on the same machine, which will write the output into the specified log file.

The Mapped Diagnostic Context (MDC) is filled in the RequestContextInterceptor#preHandle method with the uuid and the caller. It's possible to put even more data into the MDC. The MDC data will be printed as key1=value1, key2=value2, ... in the %mdc part. So it's great to fill the MDC at the beginning of the request and clear the data at the end of the request. Thereby you always have the meta data logged within your log output.

For example if you call http://localhost:9090/shopping-cart/3 following output will be generated distributed over 3 processes:

# frontend-service
2015-08-09 21:46:03.337  INFO 10868 --- [nio-9090-exec-2] a.r.c.m.f.c.ShoppingCartController       : [caller=/shopping-cart/3 <- 127.0.0.1, uuid=23badb29-6cb3-4f02-a786-2c15cbcaf302] getShoppingCart(3)

# shopping-cart-service
2015-08-09 21:46:03.340  INFO 17732 --- [o-auto-1-exec-1] a.r.c.m.user.rest.ShoppingCartService    : [caller=frontend-service <- /shopping-cart/3 <- 127.0.0.1, uuid=23badb29-6cb3-4f02-a786-2c15cbcaf302] getShoppingCart(3)

# product-service
2015-08-09 21:46:03.360  INFO 20148 --- [o-auto-1-exec-4] a.r.c.m.product.rest.ProductService      : [caller=frontend-service <- /shopping-cart/3 <- 127.0.0.1, uuid=23badb29-6cb3-4f02-a786-2c15cbcaf302] getproduct(3)

This output makes two things very easy:

• Find all log output which belongs together. Just find all log entries with the same uuid.
• See the flow of the initial request through the microservices.

To make this possible it's necessary to pass the data (uuid, caller) from one microservice to the next microservice. This is quite easy to accomplish with HTTP headers. The implementation of it is quite simple, too. It's handled in the RequestContextInterceptor and the ServiceNameInterceptor. Given that a ThreadLocal is used in the implementation and that Hystrix uses it's own threads it's necessary to configure Hystrix correctly. See this three files.

Last but not least it's nice that you don't have to copy the logback.xml file into each service. With Maven it's possible to pack the logback.xml file into an artifact and then unpack it into the microservices. If you change the log configuration you just need to change the file once. Depending on your setup it might be required to change the version of the artifact so that the new version is unpacked.