This post continues on from the first blog in the series and describes how to integrate spt-development-cid into a Spring Boot web project with spt-development-cid-web-spring-boot and how this can be used in conjunction with spt-development-logging-spring to quickly add useful logging to all layers of your web application.
The demo project for this post was created using spring initializr and is available in github.
The project consist of a simple HelloController class along with a simple HelloService class and a slightly contrived UserRepository class which can be run using the spring boot maven plugin by issuing the following command from the top-level project directory: ./mvnw -DskipTests clean install spring-boot:run. Once running, the application can be tested with curl as shown below:
$ curl http://localhost:8080/api/v1.0/hello # Hello, world
$ curl http://localhost:8080/api/v1.0/hello/1 # Hello, Arthur Dent
$ curl http://localhost:8080/api/v1.0/hello/2 # 404
To start including a correlation ID in our log statements we need to add the spt-development-cid-web-spring-boot starter to our pom which will pull in spt-development-cid and spt-development-cid-web as dependencies and automatically configure a FilterRegistrationBean to intialise the correlation ID for each request.
We then need to add some log statements and include the correlation ID in those log statements, for example:
It is worth hilighting the design decision taken which requires the developer to explicitly include the correlation ID in each log statement. An alternative solution would have been to use the Mapped Diagnostic Context (MDC) and automatically include the correlation ID through configuration, without having to include the correlation ID each time. The downside with the MDC solution is that it becomes problematic when going multi-threaded. There are solutions to this problem however these solutions don’t tend to work with libraries that make use of multiple threads - a perfect example of this is Hystrix which I’ve used extensively for implementing the circuit breaker pattern. In my experience, rather than have to solve the multi-threading issue in such scenarios, it is much easier to explicitly include the correlation ID in your log statements, and once in the habit it isn’t particularly onerous.
Now when we restart the application and run our curl tests, we get the following logging output:
As touched upon in my first post correlation IDs are most useful/important in an application consisting of multiple services in order to track requests through each of the services involved in servicing an initial request. spt-development-cid-web facilitates this by including the ability to set the correlation ID to a value read from an incoming request header, by default X-Correlation-ID. This feature is off by default but can be switched on via the config file (there are also options for changing the header name, and controlling the FilterRegistration bean config, see the javadoc for more info).
This time, if we specify the correlation ID header when issuing our curl commands:
$ curl -H "X-Correlation-ID: my-cid-set-via-header" http://localhost:8080/api/v1.0/hello
$ curl -H "X-Correlation-ID: my-cid-set-via-header-2" http://localhost:8080/api/v1.0/hello/1
we see the correlation ID from the header appear in our log statements.
The log statements I have added to the project so far are useful and similar to ones that I like to add to all controller methods, so that I get logging for all requests handled. I also like to add log statements at the end of controller methods, log any exceptions thrown by controller methods and add logging at the beginning and end of service methods and repository methods. I have found this approach invaluable when debugging production issues especially in conjunction with setting the log level with actuator at runtime. Adding these log statements to every method, soon becomes tedious and makes your code hard to read however. This is where spt-development-logging-spring comes in, easily integrated into a Spring Boot project by adding the spt-development-logging-spring-boot starter to your pom.
Now when we run the curl tests, we get the following logging, without making any further code changes that would otherwise clutter up the code.
For demonstration purposes the repository will throw a runtime exception if the user ID is 99, which results in the logging below. Note how this exception is logged at ERROR, whereas the UnknownUserException exception was logged at INFO and the stacktrace at DEBUG. Only ‘unexpected’ or 5XX exceptions are logged as errors; any exception that is not an instance of HttpStatusCodeException or is not annotated with ResponseStatus is an unexpected exception; any exception annotated with ResponseStatus and a 5XX status or HttpStatusCodeException exception with a 5XX status code is treated as a 5XX exception.
