Custom API Request & Response Logging in spring boot. Custom API Request & Response Logging in spring boot.

When we create RESTFul APIs in spring boot application in microservices environment. It becomes essential to log incoming API request and response and push it to centralized logging system such as Splunk or ELK for debugging. Also all the logs related to one request should have some common id to relate them. In this post we are going to solve these problems.

1. Create RESTFul API

Let’s create a RestController to expose RESTFul API

@RestController
@RequestMapping("/posts")
public class PostController {

	@GetMapping
	public List<Post> getAllPosts() {
		return Arrays.asList(new Post[] {
		     new Post[] { new Post("spring", "Spring Boot", "All about Spring boot microservice"),
				 new Post("java", "Java", "Learn Streams in Java"),
				 new Post("javascript", "JavaScript", "Whats new in ES6")	     
		});
	}
}


2. Create API Logger

At this point we have exposed API but we haven’t logged it yet. Let’s create an API logger which is having following configurable properties:-

  • app.api.logging.enable If true then api logger will be enabled and log all api request and response
  • app.api.logging.url-patterns If provided in a comma separated url patterns, only those api request and response will be logged. default value is '*' means all api request and response will be printed
  • app.api.logging.requestIdParamName If provided request parameter in incoming api request will be logged across all logs to serve that request. default value is requestId. If not provided, new request id (uuid) will be generated to log across all logs.
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression;
import org.springframework.boot.web.servlet.FilterRegistrationBean;
import org.springframework.context.annotation.Bean;
import org.springframework.stereotype.Component;

@Component
@ConditionalOnExpression("${app.api.logging.enable:true}")
public class ApiLoggingFilterConfig {

	@Value("${app.api.logging.url-patterns:*}")
	private String[] urlPatterns;
	
	@Value("${app.api.logging.requestIdParamName:requestId}")
	private String requestIdParamName;
	
	@Bean
	public FilterRegistrationBean<ApiLoggingFilter> loggingFilter() {
	   FilterRegistrationBean<ApiLoggingFilter> registrationBean = new FilterRegistrationBean<>();
	   registrationBean.setFilter(new ApiLoggingFilter(requestIdParamName));
	   registrationBean.addUrlPatterns(urlPatterns);
	   return registrationBean;
	}
}

Now we will create ApiLoggingFilter which is nothing but a Servlet Filter. This filter intercepts all api request and response and log them. It also make use of slf4j MDC to print requestId across all the logs serve that request. ApiLoggingFilter class is long. you can expand below to see code.

Click to expand ApiLoggingFilter
import java.io.BufferedReader;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.io.OutputStream;
import java.io.PrintWriter;
import java.util.Collection;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Locale;
import java.util.Map;
import java.util.UUID;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.ReadListener;
import javax.servlet.ServletException;
import javax.servlet.ServletInputStream;
import javax.servlet.ServletOutputStream;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.WriteListener;
import javax.servlet.http.Cookie;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletRequestWrapper;
import javax.servlet.http.HttpServletResponse;

import org.apache.commons.io.output.TeeOutputStream;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class ApiLoggingFilter implements Filter {

	private static final Logger LOGGER = LoggerFactory.getLogger(ApiLoggingFilter.class);
	private String requestIdParamName;

	ApiLoggingFilter(String requestIdParamName) {
		this.requestIdParamName = requestIdParamName;
	}

	@Override
	public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
			throws IOException, ServletException {
		try {
			HttpServletRequest httpServletRequest = (HttpServletRequest) request;
			HttpServletResponse httpServletResponse = (HttpServletResponse) response;

			Map<String, String> requestMap = this.getTypesafeRequestMap(httpServletRequest);
			BufferedRequestWrapper bufferedRequest = new BufferedRequestWrapper(httpServletRequest);
			BufferedResponseWrapper bufferedResponse = new BufferedResponseWrapper(httpServletResponse);
			String requestId = requestMap.containsKey(requestIdParamName) ? requestMap.get(requestIdParamName)
					: UUID.randomUUID().toString();
			MDC.put("REQUEST_ID", requestId);
			final StringBuilder logRequest = new StringBuilder("HTTP ").append(httpServletRequest.getMethod())
					.append(" \"").append(httpServletRequest.getServletPath()).append("\" ").append(", parameters=")
					.append(requestMap).append(", body=").append(bufferedRequest.getRequestBody())
					.append(", remote_address=").append(httpServletRequest.getRemoteAddr());
			LOGGER.info(logRequest.toString());
			try {
				chain.doFilter(bufferedRequest, bufferedResponse);
			} finally {
				final StringBuilder logResponse = new StringBuilder("HTTP RESPONSE ")
						.append(bufferedResponse.getContent());
				LOGGER.info(logResponse.toString());
				MDC.clear();
			}
		} catch (Throwable a) {
			LOGGER.error(a.getMessage());
		}
	}

	private Map<String, String> getTypesafeRequestMap(HttpServletRequest request) {
		Map<String, String> typesafeRequestMap = new HashMap<String, String>();
		Enumeration<?> requestParamNames = request.getParameterNames();
		while (requestParamNames.hasMoreElements()) {
			String requestParamName = (String) requestParamNames.nextElement();
			String requestParamValue;
			if (requestParamName.equalsIgnoreCase("password")) {
				requestParamValue = "********";
			} else {
				requestParamValue = request.getParameter(requestParamName);
			}
			typesafeRequestMap.put(requestParamName, requestParamValue);
		}
		return typesafeRequestMap;
	}

	private static final class BufferedRequestWrapper extends HttpServletRequestWrapper {
		private ByteArrayInputStream bais = null;
		private ByteArrayOutputStream baos = null;
		private BufferedServletInputStream bsis = null;
		private byte[] buffer = null;
		public BufferedRequestWrapper(HttpServletRequest req) throws IOException {
			super(req);
			// Read InputStream and store its content in a buffer.
			InputStream is = req.getInputStream();
			this.baos = new ByteArrayOutputStream();
			byte buf[] = new byte[1024];
			int read;
			while ((read = is.read(buf)) > 0) {
				this.baos.write(buf, 0, read);
			}
			this.buffer = this.baos.toByteArray();
		}

		@Override
		public ServletInputStream getInputStream() {
			this.bais = new ByteArrayInputStream(this.buffer);
			this.bsis = new BufferedServletInputStream(this.bais);
			return this.bsis;
		}

		String getRequestBody() throws IOException {
			BufferedReader reader = new BufferedReader(new InputStreamReader(this.getInputStream()));
			String line = null;
			StringBuilder inputBuffer = new StringBuilder();
			do {
				line = reader.readLine();
				if (null != line) {
					inputBuffer.append(line.trim());
				}
			} while (line != null);
			reader.close();
			return inputBuffer.toString().trim();
		}
	}

	private static final class BufferedServletInputStream extends ServletInputStream {
		private ByteArrayInputStream bais;
		public BufferedServletInputStream(ByteArrayInputStream bais) {
			this.bais = bais;
		}
		@Override
		public int available() {
			return this.bais.available();
		}
		@Override
		public int read() {
			return this.bais.read();
		}
		@Override
		public int read(byte[] buf, int off, int len) {
			return this.bais.read(buf, off, len);
		}
		@Override
		public boolean isFinished() {
			return false;
		}
		@Override
		public boolean isReady() {
			return true;
		}
		@Override
		public void setReadListener(ReadListener readListener) {

		}
	}

	public class TeeServletOutputStream extends ServletOutputStream {
		private final TeeOutputStream targetStream;
		public TeeServletOutputStream(OutputStream one, OutputStream two) {
			targetStream = new TeeOutputStream(one, two);
		}
		@Override
		public void write(int arg0) throws IOException {
			this.targetStream.write(arg0);
		}
		public void flush() throws IOException {
			super.flush();
			this.targetStream.flush();
		}
		public void close() throws IOException {
			super.close();
			this.targetStream.close();
		}
		@Override
		public boolean isReady() {
			return false;
		}
		@Override
		public void setWriteListener(WriteListener writeListener) {

		}
	}

	public class BufferedResponseWrapper implements HttpServletResponse {
		HttpServletResponse original;
		TeeServletOutputStream tee;
		ByteArrayOutputStream bos;
		public BufferedResponseWrapper(HttpServletResponse response) {
			original = response;
		}
		public String getContent() {
			return bos.toString();
		}
		public PrintWriter getWriter() throws IOException {
			return original.getWriter();
		}
		public ServletOutputStream getOutputStream() throws IOException {
			if (tee == null) {
				bos = new ByteArrayOutputStream();
				tee = new TeeServletOutputStream(original.getOutputStream(), bos);
			}
			return tee;

		}
		@Override
		public String getCharacterEncoding() {
			return original.getCharacterEncoding();
		}
		@Override
		public String getContentType() {
			return original.getContentType();
		}
		@Override
		public void setCharacterEncoding(String charset) {
			original.setCharacterEncoding(charset);
		}
		@Override
		public void setContentLength(int len) {
			original.setContentLength(len);
		}
		@Override
		public void setContentLengthLong(long l) {
			original.setContentLengthLong(l);
		}
		@Override
		public void setContentType(String type) {
			original.setContentType(type);
		}
		@Override
		public void setBufferSize(int size) {
			original.setBufferSize(size);
		}
		@Override
		public int getBufferSize() {
			return original.getBufferSize();
		}
		@Override
		public void flushBuffer() throws IOException {
			tee.flush();
		}
		@Override
		public void resetBuffer() {
			original.resetBuffer();
		}
		@Override
		public boolean isCommitted() {
			return original.isCommitted();
		}
		@Override
		public void reset() {
			original.reset();
		}
		@Override
		public void setLocale(Locale loc) {
			original.setLocale(loc);
		}
		@Override
		public Locale getLocale() {
			return original.getLocale();
		}
		@Override
		public void addCookie(Cookie cookie) {
			original.addCookie(cookie);
		}
		@Override
		public boolean containsHeader(String name) {
			return original.containsHeader(name);
		}
		@Override
		public String encodeURL(String url) {
			return original.encodeURL(url);
		}
		@Override
		public String encodeRedirectURL(String url) {
			return original.encodeRedirectURL(url);
		}
		@SuppressWarnings("deprecation")
		@Override
		public String encodeUrl(String url) {
			return original.encodeUrl(url);
		}
		@SuppressWarnings("deprecation")
		@Override
		public String encodeRedirectUrl(String url) {
			return original.encodeRedirectUrl(url);
		}
		@Override
		public void sendError(int sc, String msg) throws IOException {
			original.sendError(sc, msg);
		}
		@Override
		public void sendError(int sc) throws IOException {
			original.sendError(sc);
		}
		@Override
		public void sendRedirect(String location) throws IOException {
			original.sendRedirect(location);
		}
		@Override
		public void setDateHeader(String name, long date) {
			original.setDateHeader(name, date);
		}
		@Override
		public void addDateHeader(String name, long date) {
			original.addDateHeader(name, date);
		}
		@Override
		public void setHeader(String name, String value) {
			original.setHeader(name, value);
		}
		@Override
		public void addHeader(String name, String value) {
			original.addHeader(name, value);
		}
		@Override
		public void setIntHeader(String name, int value) {
			original.setIntHeader(name, value);
		}
		@Override
		public void addIntHeader(String name, int value) {
			original.addIntHeader(name, value);
		}
		@Override
		public void setStatus(int sc) {
			original.setStatus(sc);
		}
		@SuppressWarnings("deprecation")
		@Override
		public void setStatus(int sc, String sm) {
			original.setStatus(sc, sm);
		}
		@Override
		public String getHeader(String arg0) {
			return original.getHeader(arg0);
		}
		@Override
		public Collection<String> getHeaderNames() {
			return original.getHeaderNames();
		}
		@Override
		public Collection<String> getHeaders(String arg0) {
			return original.getHeaders(arg0);
		}
		@Override
		public int getStatus() {
			return original.getStatus();
		}
	}
}


3. application.yml

Let’s setup properties related to ApiLoggingFilterConfig file in .properties or .yml file

  • We have enabled api logger app.api.logging.enabled=true
  • We have given comma separated url-patterns for which we want to print all api request and response app.api.logging.url-patterns=/posts/*,/users/*
  • We have given requestIdParamName whose value will be printed in api request and response. If parameter is not there then uuid will be generated and printed.
  • Last but not least, we have changed default logging pattern of spring boot to print REQUEST_ID
    Default Spring Boot Logging Pattern is as follows:-
    "%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"
    
app:
  api:
    logging:
      enable: true
      url-patterns: "/users/*,/posts/*"
      requestIdParamName: reqId
logging:
  level:
    root: INFO
    com.abc.demo: DEBUG
  pattern:
    console: "%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%8.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %X{REQUEST_ID} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"


4. Logs

That’s it. Let’s execute some RESTFul API and look at the logs:-

http://localhost:8080/posts?reqId=1234
2020-04-23 21:09:44.107 - INFO 3240 --- ApiLoggingFilter: 1234 HTTP GET "/posts" , parameters={requestId=1234}, body=, remote_address=0:0:0:0:0:0:0:1
2020-04-23 21:09:44.110 - INFO 3240 --- ApiLoggingFilter: 1234 HTTP RESPONSE [{"id":1,"title":"Spring Boot","body":"All about Spring boot microservice"},{"id":2,"title":"Java","body":"Learn Streams in Java"},{"id":3,"title":"JavaScript","body":"Whats new in ES6"}]
http://localhost:8080/posts

When reqId is not passed as parameter, default uuid will be printed across all logs

2020-04-23 21:09:44.107 - INFO 3240 --- ApiLoggingFilter: 754be6a6-b00a-4c98-b681-2d0041b4f72c HTTP GET "/posts" , parameters={requestId=1234}, body=, remote_address=0:0:0:0:0:0:0:1
2020-04-23 21:09:44.110 - INFO 3240 --- ApiLoggingFilter: 754be6a6-b00a-4c98-b681-2d0041b4f72c HTTP RESPONSE [{"id":1,"title":"Spring Boot","body":"All about Spring boot microservice"},{"id":2,"title":"Java","body":"Learn Streams in Java"},{"id":3,"title":"JavaScript","body":"Whats new in ES6"}]


5. Summary

We saw in this post that how we can create custom logger to print API request and response. Also incoming request can have requestId parameter which can be printed across all the logs which serves that request. This parameter can be further passed down in downstream microservices to further print it in the logs. This way a request can be tracked end to end from the logs.

Please find the complete source code of custom logging API on github springboot-microservice