Now that we\u2019ve got an almost fully functional webservice we\u2019re going to make sure that we can debug it properly before moving forward to deployment. In this article we\u2019re going to describe how to setup logging.<\/p>\n\n\n\n
We need to start by actually logging something. Spring boot comes packaged with aop and aspectj and we\u2019ll be using these libraries to setup automatic logging around the inputs and outputs of every method.<\/p>\n\n\n\n
In the source code base create a java class called This code is leveraging aspectj and spring to intercept every method call and execute some code that we\u2019ve defined. Since spring is creating interface proxies for you behind the scenes this interception is very easy. Here we\u2019re logging the method call, the method parameters, the returned result as well as an execution time for profiling. We\u2019ve currently got it turned on for every method in our project that we\u2019ve created. However, we could easily create an annotation and use that in a filter as well.<\/p><\/blockquote>\n\n\n\n If we start this up in the IDE and hit the endpoint again with postman, we should see logging that looks like this:<\/p>\n\n\n\n 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:<\/p>\n\n\n\n We also want to emit the access log from tomcat. This is a configuration setting in application.yaml<\/p>\n\n\n\n we\u2019re going to write out the zipkin trace and span ids into the logs as well, so we\u2019ll need to do some configuration into the tomcat access log writer to write the zipkin data into the headers.<\/p>\n\n\n\n in First and then AccessLogSleuthConfiguration<\/p>\n\n\n\n Additionally, we can retry the request with the same parameters to throw an error:<\/p>\n\n\n\n You can see that the span and trace id are different.<\/p>\n\n\n\n You should also see the request in the access logs (and the trace\/spans line up):<\/p>\n\n\n\n However, our response in postman is fairly ugly. Lets see if we can clean that up now.<\/p>\n\n\n\n For now we\u2019re just going to throw out some standard errors, but we could expand this simple implementation in the future.<\/p>\n\n\n\n In We also need to make the exception and update our service class to catch the database exception and throw a system exception instead:<\/p>\n\n\n\n Finally we need to exclude the advice class from the logging aspect<\/p>\n\n\n\nLoggingApect <\/code>in com.brianrook.medium.customer.config<\/code>. Add this content:<\/p>\n\n\n\npackage com.brianrook.medium.customer.config;\n\nimport com.fasterxml.jackson.core.JsonProcessingException;\nimport com.fasterxml.jackson.databind.ObjectMapper;\nimport com.fasterxml.jackson.databind.ObjectWriter;\nimport lombok.extern.slf4j.Slf4j;\nimport org.aspectj.lang.ProceedingJoinPoint;\nimport org.aspectj.lang.annotation.Around;\nimport org.aspectj.lang.annotation.Aspect;\nimport org.aspectj.lang.reflect.MethodSignature;\nimport org.springframework.stereotype.Component;\nimport org.springframework.util.StopWatch;\n\nimport java.io.Writer;\nimport java.util.HashMap;\nimport java.util.Map;\n\n@Aspect\n@Component\n@Slf4j\npublic class LoggingAspect {\n\n ObjectMapper om = new ObjectMapper();\n\n @Around(\"execution(* com.brianrook.medium.customer..*(..)))\")\n public Object profileAllMethods(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {\n logMethodInvocationAndParameters(proceedingJoinPoint);\n\n final StopWatch stopWatch = new StopWatch();\n\n \/\/Measure method execution time\n stopWatch.start();\n Object result = proceedingJoinPoint.proceed();\n stopWatch.stop();\n\n \/\/Log method execution time\n logMethodResultAndParameters(proceedingJoinPoint, result, stopWatch.getTotalTimeMillis());\n\n return result;\n }\n\n private void logMethodResultAndParameters(ProceedingJoinPoint proceedingJoinPoint,\n Object result, long totalTimeMillis) {\n try {\n MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();\n String className = methodSignature.getDeclaringType().getSimpleName();\n String methodName = methodSignature.getName();\n ObjectWriter writer = om.writer();\nlog<\/em>.info(\"<- {}.{} returns:{}. Execution time: {}ms\",\n className,\n methodName,\n writer.writeValueAsString(result),\n totalTimeMillis);\n } catch (JsonProcessingException e) {\nlog<\/em>.error(\"unable to write log value: {}\", e.getMessage(), e);\n }\n }\n\n\n private void logMethodInvocationAndParameters(ProceedingJoinPoint jp) {\n try {\n String[] argNames = ((MethodSignature) jp.getSignature()).getParameterNames();\n Object[] values = jp.getArgs();\n Map<String, Object> params = new HashMap<>();\n if (argNames!=null && argNames.length != 0) {\n for (int i = 0; i < argNames.length; i++) {\n params.put(argNames[i], values[i]);\n }\n }\n ObjectWriter writer = om.writer();\n String className = jp.getSignature().getDeclaringType().getSimpleName();\n String methodName = jp.getSignature().getName();\nlog<\/em>.info(\"-> {}.{} invocation. params: {}\",\n className,\n methodName,\n writer.writeValueAsString(params));\n } catch (JsonProcessingException e) {\nlog<\/em>.error(\"unable to write log value: {}\", e.getMessage(), e);\n }\n\n }\n}<\/code><\/pre>\n\n\n\n2020-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\":\"testuser@gmail.com<\/a>\"}}\n2020-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\":\"testuser@gmail.com<\/a>\"}}\n2020-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: {}\n2020-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\":\"testuser@gmail.com<\/a>\"}. Execution time: 51ms\n2020-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\":\"testuser@gmail.com<\/a>\"}. Execution time: 61ms\n2020-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\":\"testuser@gmail.com<\/a>\"},\"statusCode\":\"CREATED\",\"statusCodeValue\":201}. Execution time: 72ms<\/code><\/pre>\n\n\n\n[customer,76d8b46086af4970,76d8b46086af4970,false]<\/pre>\n\n\n\n
Access Logs<\/h4>\n\n\n\n
server:\n port: 10000\n tomcat:\n accesslog:\n enabled: true\n pattern: '%h %l %u %t \\\"%r\\\" %s %b zipkin:[%{X-B3-TraceId}i, %{X-B3-SpanId}i, %{X-B3-ParentSpanId}i]'\n directory: c:\\workspace\\logs\\customer\n prefix: access_log\n suffix: .log\n buffered: false<\/code><\/pre>\n\n\n\ncom.brianrook.medium.customer.config<\/code> create 2 files.<\/p>\n\n\n\nSleuthValve<\/code><\/p>\n\n\n\npackage com.brianrook.medium.customer.config;\n\nimport brave.Span;\nimport brave.Tracer;\nimport org.apache.catalina.Valve;\nimport org.apache.catalina.connector.Request;\nimport org.apache.catalina.connector.Response;\nimport org.apache.catalina.valves.ValveBase;\nimport org.apache.tomcat.util.buf.MessageBytes;\nimport org.apache.tomcat.util.http.MimeHeaders;\nimport org.springframework.stereotype.Component;\n\nimport javax.servlet.ServletException;\nimport java.io.IOException;\n\n@Component\nclass SleuthValve extends ValveBase {\n private final Tracer tracer;\n\n public SleuthValve(Tracer tracer){\n this.tracer = tracer;\n }\n\n @Override\n public void invoke(Request request, Response response) throws IOException, ServletException {\n\nenrichWithSleuthHeaderWhenMissing<\/em>(tracer, request);\n\n Valve next = getNext();\n if (null == next) {\n return;\n }\n next.invoke(request, response);\n }\n\n private static void enrichWithSleuthHeaderWhenMissing(final Tracer tracer, final Request request) {\n String header = request.getHeader(\"X-B3-TraceId\");\n if (null == header) {\n\n org.apache.coyote.Request coyoteRequest = request.getCoyoteRequest();\n MimeHeaders mimeHeaders = coyoteRequest.getMimeHeaders();\n\n Span span = tracer.newTrace();\n\naddHeader<\/em>(mimeHeaders, \"X-B3-TraceId\", span.context().traceIdString());\naddHeader<\/em>(mimeHeaders, \"X-B3-SpanId\", span.context().traceIdString());\n }\n }\n\n private static void addHeader(MimeHeaders mimeHeaders, String traceIdName, String value) {\n MessageBytes messageBytes = mimeHeaders.addValue(traceIdName);\n messageBytes.setString(value);\n }\n}<\/code><\/pre>\n\n\n\npackage com.brianrook.medium.customer.config;\n\nimport org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory;\nimport org.springframework.boot.web.server.WebServerFactoryCustomizer;\nimport org.springframework.context.annotation.Configuration;\n\n@Configuration\npublic class AccessLogSleuthConfiguration implements WebServerFactoryCustomizer<TomcatServletWebServerFactory> {\n\n private SleuthValve sleuthValve;\n public AccessLogSleuthConfiguration(SleuthValve sleuthValve) {\n this.sleuthValve = sleuthValve;\n }\n @Override\n public void customize(TomcatServletWebServerFactory factory) {\n factory.addContextCustomizers(context -> context.getPipeline().addValve(sleuthValve));\n }\n\n}<\/code><\/pre>\n\n\n\n2020-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\":\"testuser@test.com<\/a>\"}}\n2020-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\":\"testuser@test.com<\/a>\"}}\n2020-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: {}\n2020-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\n2020-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:\ninsert into customer (email, first_name, last_name, phone_number, customer_id) values (?, ?, ?, ?, ?) [23505-200]\n2020-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<\/code><\/pre>\n\n\n\n0:0:0:0:0:0:0:1 - - [29\/Mar\/2020:18:02:54 -0600] \\\"POST \/customer\/ HTTP\/1.1\\\" 500 21342 zipkin:[2f492a51cbdc93dd, 2f492a51cbdc93dd, -]<\/code><\/pre>\n\n\n\nError Handling<\/h3>\n\n\n\n
com.brianrook.medium.customer.controller<\/code> create this CustomerControllerAdvice <\/code>java class:<\/p>\n\n\n\npackage com.brianrook.medium.customer.controller;\n\nimport com.brianrook.medium.customer.exception.CustomerSystemException;\nimport org.springframework.http.HttpHeaders;\nimport org.springframework.http.HttpStatus;\nimport org.springframework.http.ResponseEntity;\nimport org.springframework.web.bind.annotation.ControllerAdvice;\nimport org.springframework.web.bind.annotation.ExceptionHandler;\nimport org.springframework.web.context.request.WebRequest;\nimport org.springframework.web.servlet.mvc.method.annotation.ResponseEntityExceptionHandler;\n\n@ControllerAdvice\npublic class CustomerControllerAdvice extends ResponseEntityExceptionHandler {\n\n @ExceptionHandler(value\n = {IllegalArgumentException.class})\n protected ResponseEntity<Object> handleConflict(\n RuntimeException ex, WebRequest request) {\n String bodyOfResponse = \"Unable to process request because of invalid input data\";\n return handleExceptionInternal(ex, bodyOfResponse,\n new HttpHeaders(), HttpStatus.BAD_REQUEST<\/em>, request);\n }\n\n @ExceptionHandler(value\n = {CustomerSystemException.class})\n protected ResponseEntity<Object> handleSystemException(\n RuntimeException ex, WebRequest request) {\n String bodyOfResponse = String.format<\/em>(\"Unable to process request because of system exception.\");\n return handleExceptionInternal(ex, bodyOfResponse,\n new HttpHeaders(), HttpStatus.INTERNAL_SERVER_ERROR<\/em>, request);\n }\n\n}<\/code><\/pre>\n\n\n\ncom.brianrook.medium.customer.exception.CustomerSystemException<\/code><\/p>\n\n\n\npackage com.brianrook.medium.customer.exception;\n\npublic class CustomerSystemException extends RuntimeException{\n public CustomerSystemException(String message){\n super(message);\n }\n public CustomerSystemException(String message, Exception e){\n super(message,e);\n }\n}<\/code><\/pre>\n\n\n\npublic Customer persistCustomer(Customer customer) {\n try {\n CustomerEntity customerEntity = CustomerEntityMapper.INSTANCE<\/em>.customerToCustomerEntity(customer);\n CustomerEntity storedEntity = customerDAO.save(customerEntity);\n Customer returnCustomer = CustomerEntityMapper.INSTANCE<\/em>.customerEntityToCustomer(storedEntity);\n return returnCustomer;\n }catch (Exception e){\n throw new CustomerSystemException(\"unable to persist customer data: \"+e.getMessage(), e);\n }\n}<\/code><\/pre>\n\n\n\n@Around(\"execution(* com.brianrook.medium.customer..*(..)) \" +\n \"&& !within(com.brianrook.medium.customer.config. .*)\" +\n \"&& !within(com.brianrook.medium.customer.controller.CustomerControllerAdvice)) \")<\/code><\/pre>\n\n\n\nBuild and Commit<\/h3>\n\n\n\n
git checkout -b logging\nmvn clean install\ngit add .\ngit commit -m \"logging and error handling\"\ngit push\ngit checkout master\ngit merge logging<\/code><\/pre>\n","protected":false},"excerpt":{"rendered":"