Logging, Tracing and Error Handling

Now that we’ve got an almost fully functional webservice we’re going to make sure that we can debug it properly before moving forward to deployment. In this article we’re going to describe how to setup logging.

Logging

We need to start by actually logging something. Spring boot comes packaged with aop and aspectj and we’ll be using these libraries to setup automatic logging around the inputs and outputs of every method.

Create the AspectJ Configuration

In the source code base create a java class called LoggingApect in com.brianrook.medium.customer.config. Add this content:

package com.brianrook.medium.customer.config;

import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.ObjectWriter;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

import java.io.Writer;
import java.util.HashMap;
import java.util.Map;

@Aspect
@Component
@Slf4j
public class LoggingAspect {

    ObjectMapper om = new ObjectMapper();

    @Around("execution(* com.brianrook.medium.customer..*(..)))")
    public Object profileAllMethods(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        logMethodInvocationAndParameters(proceedingJoinPoint);

        final StopWatch stopWatch = new StopWatch();

        //Measure method execution time
        stopWatch.start();
        Object result = proceedingJoinPoint.proceed();
        stopWatch.stop();

        //Log method execution time
        logMethodResultAndParameters(proceedingJoinPoint, result, stopWatch.getTotalTimeMillis());

        return result;
    }

    private void logMethodResultAndParameters(ProceedingJoinPoint proceedingJoinPoint,
                                              Object result, long totalTimeMillis) {
        try {
            MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
            String className = methodSignature.getDeclaringType().getSimpleName();
            String methodName = methodSignature.getName();
            ObjectWriter writer = om.writer();
log.info("<- {}.{} returns:{}.  Execution time: {}ms",
                    className,
                    methodName,
                    writer.writeValueAsString(result),
                    totalTimeMillis);
        } catch (JsonProcessingException e) {
log.error("unable to write log value: {}", e.getMessage(), e);
        }
    }


    private void logMethodInvocationAndParameters(ProceedingJoinPoint jp) {
        try {
            String[] argNames = ((MethodSignature) jp.getSignature()).getParameterNames();
            Object[] values = jp.getArgs();
            Map<String, Object> params = new HashMap<>();
            if (argNames!=null && argNames.length != 0) {
                for (int i = 0; i < argNames.length; i++) {
                    params.put(argNames[i], values[i]);
                }
            }
            ObjectWriter writer = om.writer();
            String className = jp.getSignature().getDeclaringType().getSimpleName();
            String methodName = jp.getSignature().getName();
log.info("-> {}.{} invocation.  params: {}",
                    className,
                    methodName,
                    writer.writeValueAsString(params));
        } catch (JsonProcessingException e) {
log.error("unable to write log value: {}", e.getMessage(), e);
        }

    }
}

This code is leveraging aspectj and spring to intercept every method call and execute some code that we’ve defined. Since spring is creating interface proxies for you behind the scenes this interception is very easy. Here we’re logging the method call, the method parameters, the returned result as well as an execution time for profiling. We’ve currently got it turned on for every method in our project that we’ve created. However, we could easily create an annotation and use that in a filter as well.

If we start this up in the IDE and hit the endpoint again with postman, we should see logging that looks like this:

2020-03-29 12:10:18.871  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : -> CustomerController.saveCustomer invocation.  params: {"customerDTO":{"customerId":null,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1212","email":"[email protected]"}}
2020-03-29 12:10:18.881  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : -> CustomerService.saveCustomer invocation.  params: {"customer":{"customerId":null,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1212","email":"[email protected]"}}
2020-03-29 12:10:18.888  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : -> CrudRepository.save invocation.  params: {}
2020-03-29 12:10:18.943  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : <- CrudRepository.save returns:{"customerId":1,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1212","email":"[email protected]"}.  Execution time: 51ms
2020-03-29 12:10:18.943  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : <- CustomerService.saveCustomer returns:{"customerId":1,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1212","email":"[email protected]"}.  Execution time: 61ms
2020-03-29 12:10:18.951  INFO [customer,76d8b46086af4970,76d8b46086af4970,false] 7004 --- [io-10000-exec-2] c.b.m.customer.config.LoggingAspect      : <- CustomerController.saveCustomer returns:{"headers":{},"body":{"customerId":1,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1212","email":"[email protected]"},"statusCode":"CREATED","statusCodeValue":201}.  Execution time: 72ms

Now we can search and filter the logs when we get into production. You can see that sleuth and zipkin are turned on because the zipkin trace and span ids are present in the logs:

[customer,76d8b46086af4970,76d8b46086af4970,false]

Access Logs

We also want to emit the access log from tomcat. This is a configuration setting in application.yaml

server:
  port: 10000
  tomcat:
  accesslog:
    enabled: true
    pattern: '%h %l %u %t \"%r\" %s %b zipkin:[%{X-B3-TraceId}i, %{X-B3-SpanId}i, %{X-B3-ParentSpanId}i]'
    directory: c:\workspace\logs\customer
    prefix: access_log
    suffix: .log
    buffered: false

we’re going to write out the zipkin trace and span ids into the logs as well, so we’ll need to do some configuration into the tomcat access log writer to write the zipkin data into the headers.

in com.brianrook.medium.customer.config create 2 files.

First SleuthValve

package com.brianrook.medium.customer.config;

import brave.Span;
import brave.Tracer;
import org.apache.catalina.Valve;
import org.apache.catalina.connector.Request;
import org.apache.catalina.connector.Response;
import org.apache.catalina.valves.ValveBase;
import org.apache.tomcat.util.buf.MessageBytes;
import org.apache.tomcat.util.http.MimeHeaders;
import org.springframework.stereotype.Component;

import javax.servlet.ServletException;
import java.io.IOException;

@Component
class SleuthValve extends ValveBase {
    private final Tracer tracer;

    public SleuthValve(Tracer tracer){
        this.tracer = tracer;
    }

    @Override
    public void invoke(Request request, Response response) throws IOException, ServletException {

enrichWithSleuthHeaderWhenMissing(tracer, request);

        Valve next = getNext();
        if (null == next) {
            return;
        }
        next.invoke(request, response);
    }

    private static void enrichWithSleuthHeaderWhenMissing(final Tracer tracer, final Request request) {
        String header = request.getHeader("X-B3-TraceId");
        if (null == header) {

            org.apache.coyote.Request coyoteRequest = request.getCoyoteRequest();
            MimeHeaders mimeHeaders = coyoteRequest.getMimeHeaders();

            Span span = tracer.newTrace();

addHeader(mimeHeaders, "X-B3-TraceId", span.context().traceIdString());
addHeader(mimeHeaders, "X-B3-SpanId", span.context().traceIdString());
        }
    }

    private static void addHeader(MimeHeaders mimeHeaders, String traceIdName, String value) {
        MessageBytes messageBytes = mimeHeaders.addValue(traceIdName);
        messageBytes.setString(value);
    }
}

and then AccessLogSleuthConfiguration

package com.brianrook.medium.customer.config;

import org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory;
import org.springframework.boot.web.server.WebServerFactoryCustomizer;
import org.springframework.context.annotation.Configuration;

@Configuration
public class AccessLogSleuthConfiguration implements WebServerFactoryCustomizer<TomcatServletWebServerFactory> {

    private SleuthValve sleuthValve;
    public AccessLogSleuthConfiguration(SleuthValve sleuthValve) {
        this.sleuthValve = sleuthValve;
    }
    @Override
    public void customize(TomcatServletWebServerFactory factory) {
        factory.addContextCustomizers(context -> context.getPipeline().addValve(sleuthValve));
    }

}

Additionally, we can retry the request with the same parameters to throw an error:

2020-03-29 18:02:54.124  INFO [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] c.b.m.customer.config.LoggingAspect      : -> CustomerController.saveCustomer invocation.  params: {"customerDTO":{"customerId":null,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1234","email":"[email protected]"}}
2020-03-29 18:02:54.124  INFO [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] c.b.m.customer.config.LoggingAspect      : -> CustomerService.saveCustomer invocation.  params: {"customer":{"customerId":null,"firstName":"Brian","lastName":"Rook","phoneNumber":"(303)555-1234","email":"[email protected]"}}
2020-03-29 18:02:54.124  INFO [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] c.b.m.customer.config.LoggingAspect      : -> CrudRepository.save invocation.  params: {}
2020-03-29 18:02:54.128  WARN [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 23505, SQLState: 23505
2020-03-29 18:02:54.129 ERROR [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : Unique index or primary key violation: "PUBLIC.UK_DWK6CX0AFU8BS9O4T536V1J5V_INDEX_5 ON PUBLIC.CUSTOMER(EMAIL) VALUES 1"; SQL statement:
insert into customer (email, first_name, last_name, phone_number, customer_id) values (?, ?, ?, ?, ?) [23505-200]
2020-03-29 18:02:54.146 ERROR [customer,2f492a51cbdc93dd,2f492a51cbdc93dd,false] 21388 --- [io-10000-exec-5] o.s.c.s.i.web.ExceptionLoggingFilter     : Uncaught exception thrown

You can see that the span and trace id are different.

You should also see the request in the access logs (and the trace/spans line up):

0:0:0:0:0:0:0:1 - - [29/Mar/2020:18:02:54 -0600] \"POST /customer/ HTTP/1.1\" 500 21342 zipkin:[2f492a51cbdc93dd, 2f492a51cbdc93dd, -]

However, our response in postman is fairly ugly. Lets see if we can clean that up now.

Error Handling

For now we’re just going to throw out some standard errors, but we could expand this simple implementation in the future.

In com.brianrook.medium.customer.controller create this CustomerControllerAdvice java class:

package com.brianrook.medium.customer.controller;

import com.brianrook.medium.customer.exception.CustomerSystemException;
import org.springframework.http.HttpHeaders;
import org.springframework.http.HttpStatus;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.ControllerAdvice;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.context.request.WebRequest;
import org.springframework.web.servlet.mvc.method.annotation.ResponseEntityExceptionHandler;

@ControllerAdvice
public class CustomerControllerAdvice extends ResponseEntityExceptionHandler {

    @ExceptionHandler(value
            = {IllegalArgumentException.class})
    protected ResponseEntity<Object> handleConflict(
            RuntimeException ex, WebRequest request) {
        String bodyOfResponse = "Unable to process request because of invalid input data";
        return handleExceptionInternal(ex, bodyOfResponse,
                new HttpHeaders(), HttpStatus.BAD_REQUEST, request);
    }

    @ExceptionHandler(value
            = {CustomerSystemException.class})
    protected ResponseEntity<Object> handleSystemException(
            RuntimeException ex, WebRequest request) {
        String bodyOfResponse = String.format("Unable to process request because of system exception.");
        return handleExceptionInternal(ex, bodyOfResponse,
                new HttpHeaders(), HttpStatus.INTERNAL_SERVER_ERROR, request);
    }

}

We also need to make the exception com.brianrook.medium.customer.exception.CustomerSystemException

package com.brianrook.medium.customer.exception;

public class CustomerSystemException extends RuntimeException{
    public CustomerSystemException(String message){
        super(message);
    }
    public CustomerSystemException(String message, Exception e){
        super(message,e);
    }
}

and update our service class to catch the database exception and throw a system exception instead:

public Customer persistCustomer(Customer customer) {
    try {
        CustomerEntity customerEntity = CustomerEntityMapper.INSTANCE.customerToCustomerEntity(customer);
        CustomerEntity storedEntity = customerDAO.save(customerEntity);
        Customer returnCustomer = CustomerEntityMapper.INSTANCE.customerEntityToCustomer(storedEntity);
        return returnCustomer;
    }catch (Exception e){
        throw new CustomerSystemException("unable to persist customer data: "+e.getMessage(), e);
    }
}

Finally we need to exclude the advice class from the logging aspect

@Around("execution(* com.brianrook.medium.customer..*(..)) " +
        "&& !within(com.brianrook.medium.customer.config. .*)" +
        "&& !within(com.brianrook.medium.customer.controller.CustomerControllerAdvice)) ")

Build and Commit

git checkout -b logging
mvn clean install
git add .
git commit -m "logging and error handling"
git push
git checkout master
git merge logging