Microservices logging with Spring and Keycloak
In his book, Building Microservices, Sam Newman touches on the idea of monitoring for microservices. One of the pillars for monitoring is logging. In this article I would like to describe an approach for logging when working with Spring and Keycloak.
What we want to achieve is to have a pattern of logging that looks like this:
[correlation-id] [user email] [date] [service name] [log level] [message]
The first part of the pattern, the correlation id, is a technique described in the book, on how to reconstruct a call flow where multiple microservices are involved. Think that for an API call, the response that you get, relies on x number of services. So what do you do when something crashed and you want to understand and visualize how each piece of the microservices puzzle behaved? Think how logs look when there are a lot of clients making API calls. Can you understand quickly what happened when something failed? — especially in a distributed environment. You would most definitely need an aggregation solution to bring the output of your services in to a central place, and you would need something that allows you to quickly focus on what you’re interested in. One approach is the correlationID concept.
So as far as tech stack we have Spring Boot — java world and Keycloak for security. Keycloak is a really great tool, that has helped me in multiple projects — give it a shot if you haven’t already. The two frameworks play very nicely together, via a Keycloak adapter. From the eyes of Keycloak, the spring boot API is a bearer only open id client. What this means is that any client making a rest API call will need a token, in order for its request to be authenticated. There are a lot of articles and Github projects describing this in more detail, so have a look if you like.
On to the specifics of our spring boot service. In order to achieve that pattern of logging three things are needed— the correlation id, second, having access to the user email based on the bearer token and third, to avoid making every developer responsible for adding the user email and correlation id on every log statement. That will just pollute the code. The magic glue used to tie everything is log4j2’s ThreadContext.
Accessing the email
Out of Sam Newman’s book:
….each service knows to pass on the correlation ID. This is where you need to standardize and be stronger in enforcing this across your system
We can do this by adding a servlet filter:
| public class CorrelationIdFilter implements Filter { | |
| @Override | |
| public void init(FilterConfig filterConfig) throws ServletException { | |
| } | |
| @Override | |
| public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { | |
| String correlationId = ((HttpServletRequest) request).getHeader("x-correlation-id"); | |
| ThreadContext.put("correlationId", correlationId); | |
| try { | |
| chain.doFilter(request, response); | |
| } finally { | |
| ThreadContext.clearAll(); | |
| } | |
| } | |
| @Override | |
| public void destroy() { | |
| } | |
| } |
Correlation ID
In order to get the user’s email we need two things - the ability to access Keycloak’s AccessToken representation and a spring interceptor for injecting the email in the ThreadContext construct.
First, let’s see how to get the AccessToken:
| @Component | |
| public class KeycloakUtils { | |
| @Bean | |
| @Scope(scopeName = WebApplicationContext.SCOPE_REQUEST, | |
| proxyMode = ScopedProxyMode.TARGET_CLASS) | |
| public AccessToken accessToken() { | |
| HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder | |
| .currentRequestAttributes()) | |
| .getRequest(); | |
| AccessToken accessToken = ((KeycloakPrincipal) ((KeycloakAuthenticationToken) request.getUserPrincipal()).getPrincipal()) | |
| .getKeycloakSecurityContext().getToken(); | |
| return accessToken; | |
| } | |
| } |
Next, we need a spring interceptor. In this case a servlet filter wasn’t enough, as the spring context is needed in order to inject the AccessToken.
| @Component | |
| public class EmailThreadContextInterceptor implements HandlerInterceptor { | |
| private final Logger logger = LoggerFactory.getLogger(this.getClass()); | |
| @Autowired | |
| AccessToken accessToken; | |
| @Override | |
| public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o) throws Exception { | |
| if (httpServletRequest.getMethod().equals(HttpMethod.OPTIONS.name())) { | |
| return true; | |
| } | |
| Enumeration<String> reqHeaders = httpServletRequest.getHeaderNames(); | |
| Set<String> headers = new HashSet<>(); | |
| while(reqHeaders.hasMoreElements()){ | |
| headers.add(reqHeaders.nextElement().toLowerCase()); | |
| } | |
| if(headers.contains(HttpHeaders.AUTHORIZATION.toLowerCase())) { | |
| MDC.put("userEmail", String.format("%s", accessToken.getEmail())); | |
| } | |
| return true; | |
| } | |
| @Override | |
| public void postHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o, ModelAndView modelAndView) throws Exception { | |
| logger.debug("post handle hook"); | |
| } | |
| @Override | |
| public void afterCompletion(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o, Exception e) throws Exception { | |
| logger.debug("Clearing ThreadContext data"); | |
| MDC.clearAll(); | |
| } | |
| } |
would yield the email and correlation id from the ThreadContext.
[3e232425-3432-4ace-bd60-3ea9ccab650a] [someone@email.com] 2017-08-29 12:20:04 [ServiceName] [INFO] Method Call
As you can see the ServiceName is something that can be added in the log4j config.
Caveat
One could opt for an async approach in handling a particular request. How would this look like in a useless spring controller?
| @RequestMapping(path = "/test", method = GET, produces = TEXT_PLAIN_VALUE) | |
| public CompletableFuture<ResponseEntity> doAsync() { | |
| logger.info("log1"); | |
| return CompletableFuture.supplyAsync(() -> { | |
| logger.info("log2"); | |
| return ResponseEntity.ok("hello"); | |
| }); | |
| } |
In this case the output of the log statements would look something like this:
[6566ca20..] [email] 2017-08-29 16:13:16 [ServiceName] [INFO] log12017-08-29 16:13:16 [ServiceName] [INFO] log2
What happened? Well ThreadContext is the context of one thread (:
As soon as we go into another thread, then bye bye all the precious information we stored. There is a way out of it — set the system property isThreadContextMapInheritable to true. We do this and now our log output looks like this:
[6566ca20..] [email] 2017-08-29 16:13:16 [ServiceName] [INFO] log1 [6566ca20..] [email] 2017-08-29 16:13:16 [ServiceName] [INFO] log2
Cheers