MDC log Archives - Piotr's TechBlog https://piotrminkowski.com/tag/mdc-log/ Java, Spring, Kotlin, microservices, Kubernetes, containers Fri, 01 Jan 2021 13:31:38 +0000 en-US hourly 1 https://wordpress.org/?v=6.9.1 https://i0.wp.com/piotrminkowski.com/wp-content/uploads/2020/08/cropped-me-2-tr-x-1.png?fit=32%2C32&ssl=1 MDC log Archives - Piotr's TechBlog https://piotrminkowski.com/tag/mdc-log/ 32 32 181738725 Reactive Logging With Spring WebFlux and Logstash https://piotrminkowski.com/2019/10/15/reactive-logging-with-spring-webflux-and-logstash/ https://piotrminkowski.com/2019/10/15/reactive-logging-with-spring-webflux-and-logstash/#comments Tue, 15 Oct 2019 11:12:57 +0000 https://piotrminkowski.wordpress.com/?p=7346 I have already introduced my Spring Boot library for synchronous HTTP request/response logging in one of my previous articles Logging with Spring Boot and Elastic Stack. This library is dedicated to synchronous REST applications built with Spring MVC and Spring Web. Since version 5.0 Spring Framework also offers support for reactive REST API through the […]

The post Reactive Logging With Spring WebFlux and Logstash appeared first on Piotr's TechBlog.

]]>
I have already introduced my Spring Boot library for synchronous HTTP request/response logging in one of my previous articles Logging with Spring Boot and Elastic Stack. This library is dedicated to synchronous REST applications built with Spring MVC and Spring Web. Since version 5.0 Spring Framework also offers support for reactive REST API through the Spring WebFlux project. I decided to extend support for logging in my library to reactive Spring WebFlux.
The repository with source code is available on GitHub: https://github.com/piomin/spring-boot-logging.git. It consists with two Maven modules: logstash-logging-spring-boot-starter for synchronous logging and reactive-logstash-logging-spring-boot-starter for reactive Spring WebFlux applications. The library is available on Maven Central:

<dependency>
  <groupId>com.github.piomin</groupId>
  <artifactId>reactive-logstash-logging-spring-boot-starter</artifactId>
  <version>1.0.0.RELEASE</version>
</dependency>

Motivations

Although we are working with reactive APIs and streams, a requirement for logging every incoming request and outgoing response is still actual. Today, we are usually running many, small applications communicating with each other, so we are focusing on storing the logs in a single, central place. Here comes Logstash and Elastic Stack. Spring Boot and Spring WebFlux allow you to build reactive microservices fast. My library takes care of gathering HTTP request/response logs, sending them to ELK with proper tags and correlation. Using it in your application does not require any additional source code. You just need to include the library.
However, some things need to be discussed when talking about reactive logging. Because we are logging full requests with payloads we need to buffer them. It somehow goes against the reactive programming, since we’re trying there to be efficient with the available resources. Also, integration with Logstash is realized synchronously. It is worth keeping those two things in mind when using reactive-logstash-logging-spring-boot-starter in your application.

Implementation Details

Spring WebFlux Dependencies

Since the library is used for Spring Boot reactive APIs logging it needs to have Spring WebFlux in the dependencies. In turn, Spring WebFlux is built on top of Project Reactor, so reactor-core artifact also has to be on the dependencies list. We also need some standard Spring libraries, used for example to provide auto-configuration.

<dependency>
   <groupId>org.springframework</groupId>
   <artifactId>spring-context</artifactId>
   <version>${spring.version}</version>
   <scope>provided</scope>
</dependency>
<dependency>
   <groupId>org.springframework</groupId>
   <artifactId>spring-webflux</artifactId>
   <version>${spring.version}</version>
   <scope>provided</scope>
</dependency>
<dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-autoconfigure</artifactId>
   <version>${spring.boot.version}</version>
   <scope>provided</scope>
</dependency>
<dependency>
   <groupId>io.projectreactor</groupId>
   <artifactId>reactor-core</artifactId>
   <version>3.3.0.RELEASE</version>
   <scope>provided</scope>
</dependency>

Spring WebFlux Reactive Interceptor

With Spring WebFlux we don’t have popular Spring MVC components for caching request/response bodies: ContentCachingRequestWrapper and ContentCachingResponseWrapper. However, an approach will be pretty similar to the approach applied when building a library for synchronous logging. We need to access the request and response body by wrapping it and buffering without consuming the stream. To do that we first need to create classes extending ServerHttpRequestDecorator and ServerHttpResponseDecorator. They give us access to the message body while Spring WebFlux is reading the stream and writing to the stream.
When extending ServerHttpRequestDecorator we need to override getBody. Keep in mind that we cannot block a reactive stream, so one of doOn is suitable for accessing it. The body is published as Flux containing DataBuffer objects. Inside the asynchronous doOnNext method we write the buffer to the temporary byte array.

public class RequestLoggingInterceptor extends ServerHttpRequestDecorator {

   private static final Logger LOGGER = LoggerFactory.getLogger(RequestLoggingInterceptor.class);

   public RequestLoggingInterceptor(ServerHttpRequest delegate) {
      super(delegate);
   }

   @Override
   public Flux<DataBuffer> getBody() {
      ByteArrayOutputStream baos = new ByteArrayOutputStream();
      return super.getBody().doOnNext(dataBuffer -> {
         try {
            Channels.newChannel(baos).write(dataBuffer.asByteBuffer().asReadOnlyBuffer());
            String body = IOUtils.toString(baos.toByteArray(), "UTF-8");
            LOGGER.info("Request: method={}, uri={}, payload={}, audit={}", getDelegate().getMethod(),
                  getDelegate().getPath(), body, value("audit", true));
         } catch (IOException e) {
            e.printStackTrace();
         } finally {
            try {
               baos.close();
            } catch (IOException e) {
               e.printStackTrace();
            }
         }
      });
   }

}

When extending ServerHttpResponseDecorator we need to override writeWith method responsible for writing body to output reactive stream. We will listen for body writing events in doOnNext. Then we access DataBuffer and buffer it in ByteArrayOutputStream.

public class ResponseLoggingInterceptor extends ServerHttpResponseDecorator {

   private static final Logger LOGGER = LoggerFactory.getLogger(ResponseLoggingInterceptor.class);

   private long startTime;
   private boolean logHeaders;

   public ResponseLoggingInterceptor(ServerHttpResponse delegate, long startTime, boolean logHeaders) {
      super(delegate);
      this.startTime = startTime;
      this.logHeaders = logHeaders;
   }

   @Override
   public Mono<Void> writeWith(Publisher<? extends DataBuffer> body) {
      Flux<DataBuffer> buffer = Flux.from(body);
      return super.writeWith(buffer.doOnNext(dataBuffer -> {
         ByteArrayOutputStream baos = new ByteArrayOutputStream();
         try {
            Channels.newChannel(baos).write(dataBuffer.asByteBuffer().asReadOnlyBuffer());
            String bodyRes = IOUtils.toString(baos.toByteArray(), "UTF-8");
            if (logHeaders)
               LOGGER.info("Response({} ms): status={}, payload={}, audit={}", value("X-Response-Time", System.currentTimeMillis() - startTime),
                     value("X-Response-Status", getStatusCode().value()), bodyRes, value("audit", true));
            else
               LOGGER.info("Response({} ms): status={}, payload={}, audit={}", value("X-Response-Time", System.currentTimeMillis() - startTime),
                     value("X-Response-Status", getStatusCode().value()), bodyRes, value("audit", true));
         } catch (IOException e) {
            e.printStackTrace();
         } finally {
            try {
               baos.close();
            } catch (IOException e) {
               e.printStackTrace();
            }
         }
      }));
   }
}

Spring WebFlux Logging Filter

To be able to decorate requests and responses we first need to declare filter intercepting an incoming request. To do that we have to declare a bean that implements WebFilter and its method filter(...). The filtering method allows you to access the exchange object, which contains objects representing request and response. So if we would like to decorate request and response objects we first need to decorate ServerWebExchange. We may easily do it by defining an instance of  the ServerWebExchangeDecorator object with overridden methods getRequest and getResponse. Our decorators are responsible just for listening to events related to message body processing. So, the significant information here is that if a message has an empty body, the listening methods won’t be fired. That’s why I decided to add a code for analyzing the length of content to log a request or response message with an empty body. It is based on the HTTP header Content-Length.

public class ReactiveSpringLoggingFilter implements WebFilter {

   private static final Logger LOGGER = LoggerFactory.getLogger(ReactiveSpringLoggingFilter.class);
   private UniqueIDGenerator generator;
   private String ignorePatterns;
   private boolean logHeaders;
   private boolean useContentLength;

   public ReactiveSpringLoggingFilter(UniqueIDGenerator generator, String ignorePatterns, boolean logHeaders, boolean useContentLength) {
      this.generator = generator;
      this.ignorePatterns = ignorePatterns;
      this.logHeaders = logHeaders;
      this.useContentLength = useContentLength;
   }

   @Override
   public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
      if (ignorePatterns != null && exchange.getRequest().getURI().getPath().matches(ignorePatterns)) {
         return chain.filter(exchange);
      } else {
         generator.generateAndSetMDC(exchange.getRequest());
         final long startTime = System.currentTimeMillis();
         List<String> header = exchange.getRequest().getHeaders().get("Content-Length");
         if (useContentLength && (header == null || header.get(0).equals("0"))) {
            if (logHeaders)
               LOGGER.info("Request: method={}, uri={}, headers={}, audit={}", exchange.getRequest().getMethod(),
                     exchange.getRequest().getURI().getPath(), exchange.getRequest().getHeaders(), value("audit", true));
            else
               LOGGER.info("Request: method={}, uri={}, audit={}", exchange.getRequest().getMethod(),
                     exchange.getRequest().getURI().getPath(), value("audit", true));
         }
         ServerWebExchangeDecorator exchangeDecorator = new ServerWebExchangeDecorator(exchange) {
            @Override
            public ServerHttpRequest getRequest() {
               return new RequestLoggingInterceptor(super.getRequest(), logHeaders);
            }

            @Override
            public ServerHttpResponse getResponse() {
               return new ResponseLoggingInterceptor(super.getResponse(), startTime, logHeaders);
            }
         };
         return chain.filter(exchangeDecorator)
            .doOnSuccess(aVoid -> {
               logResponse(startTime, exchangeDecorator.getResponse(), exchangeDecorator.getResponse().getStatusCode().value());
            })
            .doOnError(throwable -> {
               logResponse(startTime, exchangeDecorator.getResponse(), 500);
            });
      }
   }
}

The last step of implementation is auto-configuration. Here’s the class responsible for it.

@Configuration
@ConfigurationProperties(prefix = "logging.logstash")
public class ReactiveSpringLoggingAutoConfiguration {

   private static final String LOGSTASH_APPENDER_NAME = "LOGSTASH";

   private String url = "localhost:8500";
   private String ignorePatterns;
   private boolean logHeaders;
   private boolean useContentLength;
   private String trustStoreLocation;
   private String trustStorePassword;
   @Value("${spring.application.name:-}")
   String name;

   @Bean
   public UniqueIDGenerator generator() {
      return new UniqueIDGenerator();
   }

   @Bean
   public ReactiveSpringLoggingFilter reactiveSpringLoggingFilter() {
      return new ReactiveSpringLoggingFilter(generator(), ignorePatterns, logHeaders, useContentLength);
   }

   @Bean
   @ConditionalOnProperty("logging.logstash.enabled")
   public LogstashTcpSocketAppender logstashAppender() {
      ...
   }
}

Usage of Spring WebFlux Logging

To be able to create reactive APIs with Spring Boot we first need to include Spring WebFlux starter to Maven dependencies.

<parent>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-parent</artifactId>
   <version>2.1.9.RELEASE</version>
   <relativePath/>
</parent>
<groupId>pl.piomin.test</groupId>
<artifactId>sample-webflux-app</artifactId>
<version>1.0-SNAPSHOT</version>
<properties>
   <java.version>11</java.version>
</properties>
<dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-webflux</artifactId>
</dependency>
<dependency>
   <groupId>com.github.piomin</groupId>
   <artifactId>reactive-logstash-logging-spring-boot-starter</artifactId>
   <version>1.0.0.BUILD-SNAPSHOT</version>
</dependency>

I have already described how to build microservices architecture with Spring WebFlux and Spring Cloud in one of my previous articles Reactive Microservices with Spring WebFlux and Spring Cloud. So for more information about advanced use cases, you can refer to this article. Here’s a typical controller implementation with Spring WebFlux Mono and Flux objects.

@RestController
public class AccountController {

   private static final Logger LOGGER = LoggerFactory.getLogger(AccountController.class);
   
   @Autowired
   private AccountRepository repository;

   @GetMapping("/customer/{customer}")
   public Flux<Account> findByCustomer(@PathVariable("customer") String customerId) {
      LOGGER.info("findByCustomer: customerId={}", customerId);
      return repository.findByCustomerId(customerId);
   }

   @GetMapping
   public Flux<Account> findAll() {
      LOGGER.info("findAll");
      return repository.findAll();
   }

   @GetMapping("/{id}")
   public Mono<Account> findById(@PathVariable("id") String id) {
      LOGGER.info("findById: id={}", id);
      return repository.findById(id);
   }

   @PostMapping
   public Mono<Account> create(@RequestBody Account account) {
      LOGGER.info("create: {}", account);
      return repository.save(account);
   }
   
}

Here are the log entries for GET (empty body) and POST requests.

reactive-logging

We can customize the library behaviour by overriding default values of configuration properties with logging.logstash.*. Here’s the typical configuration that enables embedded Logstash appender configuration, changes default Logstash URL, includes list of headers to the log and ignores logging of /favicon.ico requests.


logging.logstash:
  enabled: true
  url: 192.168.99.100:8500
  ignorePatterns: .*(favicon).*
  logHeaders: true

With the settings visible above the logs are sent to Logstash available on address 192.168.99.100:8500.

logstash-1

Summary

Spring Boot Logging library now supports logging for synchronous HTTP API with Spring MVC and reactive HTTP API with Spring WebFlux. The detailed description of the libraries configuration features may be found in my article Using logstash-logging-spring-boot-starter for logging with Spring Boot and Logstash. You can report the bugs or propose new enhancements here: https://github.com/piomin/spring-boot-logging/issues. Any feedback would be very welcome.

The post Reactive Logging With Spring WebFlux and Logstash appeared first on Piotr's TechBlog.

]]>
https://piotrminkowski.com/2019/10/15/reactive-logging-with-spring-webflux-and-logstash/feed/ 12 7346
Using logstash-logging-spring-boot-starter for logging with Spring Boot and Logstash https://piotrminkowski.com/2019/10/02/using-logstash-logging-spring-boot-starter-for-logging-with-spring-boot-and-logstash/ https://piotrminkowski.com/2019/10/02/using-logstash-logging-spring-boot-starter-for-logging-with-spring-boot-and-logstash/#comments Wed, 02 Oct 2019 08:39:50 +0000 https://piotrminkowski.wordpress.com/?p=7270 I have already described some implementation details related to my library Spring Boot Logging Logstash starter for HTTP request/response logging in one of the previous articles Logging with Spring Boot and Elastic Stack. The article has been published some weeks ago, and since that time some important features have been added to this library. Today […]

The post Using logstash-logging-spring-boot-starter for logging with Spring Boot and Logstash appeared first on Piotr's TechBlog.

]]>
I have already described some implementation details related to my library Spring Boot Logging Logstash starter for HTTP request/response logging in one of the previous articles Logging with Spring Boot and Elastic Stack. The article has been published some weeks ago, and since that time some important features have been added to this library. Today I’m going to summarise all those changes and describe all the features provided by the library.

First, let’s begin from a brief review of main features provided by the Spring Boot Logging Logstash starter:

  • it is able to log all incoming HTTP requests and outgoing HTTP responses with full body, and send those logs to Logstash with the proper tags
  • calculate and store an execution time for each request
  • it generates and propagates correlationId for downstream services calling with Spring RestTemplate or OpenFeign
  • it is auto-configurable Spring Boot library – you don’t have to do anything more than including it as a dependency to your application to make it work

1. Dependency

The first major change is that the library has been published on Maven Central and now you may use it in your application by including the following dependency to you pom.xml. The current version of library is 1.2.2.RELEASE.

<dependency>
  <groupId>com.github.piomin</groupId>
  <artifactId>logstash-logging-spring-boot-starter</artifactId>
  <version>1.2.2.RELEASE</version>
</dependency>

2. Enable Spring Boot logging

By default the library is enabled, but tries to locate Logback configuration inside your application to settings for Logstash appender. If such appender won’t be found, the library uses Spring Boot default logging configuration, which does not include Logstash appender. To force it use auto-configured appender definition inside library we have to set property logging.logstash.enabled to true. After setting the property the logs would be send to auto-configured default address of Logstash, which is localhost:5000. To override we have to use property logging.logstash.url. Generally, all the names of properties has been changed from spring.logging.* to logstash.logging.*, to meet the requirements for third-party libraries defined by Spring Boot team.

logging.logstash:
  enabled: true
  url: 192.168.99.100:5000

3. Secure connection with Logstash

We can enable secure connection on the client site by providing trust store location. To do that we should define property logstash.logging.trustStoreLocation, and if required password to the keystore in property logstash.logging.trustStorePassword.

logging.logstash:
  trustStoreLocation: /tmp/location/sample.jks
  trustStorePassword: 123456

4. Filtering the logs

By default all HTTP incoming request are intercepted and log by the library. We can customize this behavior and filter some unnecessary calls by declaring matching pattern. The sample configuration is visible below. The following pattern will filter all the requests starting with actuator (to exclude healthcheck calls), swagger (only documentation – not required to log) or webjars.

logging:
  logstash:
    ignorePatterns: /(actuator|swagger|webjars).*

5. Logging HTTP headers

By default HTTP request and response headers are not logged. To enable it we have to set property logging.logstash.logHeaders to true. After that change log message will include section ‘headers’ with key/value map with all HTTP headers.

6. Fields exported to Logstash

If you decided to set property logging.logstash.enabled to true the library is sending all the MDC fields to Logstash. If you provide your own Logback configuration file you should configure Logstash appender to send all fields in mdc tag or define the list of fields to send. Here’s the list of supported fields logged by the library:

  • X-Correlation-ID: correlates all the requests send to downstream services within a single call of endpoint
  • X-Request-ID: id generated for a single pair request/response
  • X-Response-Time: the time of request processing in milliseconds
  • X-Response-Status: the HTTP status of response
  • X-Operation-Name: the name of operation including controller name and method name
  • audit: used for marking logs generated by the library

You can easily filter all the logs generated by the library using audit field as shown below.

spring-boot-logging-logstash-1

Here’s the screen showing all the fields sent by the library for a single record.

logstash-2

Summary

The source code repository with logstash-logging-spring-boot-starter is available on GitHub. You can check it out here: https://github.com/piomin/spring-boot-logging.git. You can report the bugs or propose new enhancements here: https://github.com/piomin/spring-boot-logging/issues. Any feedback would be very welcome. Enjoy 🙂

The post Using logstash-logging-spring-boot-starter for logging with Spring Boot and Logstash appeared first on Piotr's TechBlog.

]]>
https://piotrminkowski.com/2019/10/02/using-logstash-logging-spring-boot-starter-for-logging-with-spring-boot-and-logstash/feed/ 2 7270
Logging with Spring Boot and Elastic Stack https://piotrminkowski.com/2019/05/07/logging-with-spring-boot-and-elastic-stack/ https://piotrminkowski.com/2019/05/07/logging-with-spring-boot-and-elastic-stack/#comments Tue, 07 May 2019 10:00:19 +0000 https://piotrminkowski.wordpress.com/?p=7128 In this article I’ll introduce my library for Spring Boot request and response logging designed especially for Spring Boot RESTful web application. The main assumptions regarding this library are: Logging all incoming HTTP requests and outgoing HTTP responses with full body Integration with Elastic Stack through Logstash using logstash-logback-encoder library Possibility for enabling logging on […]

The post Logging with Spring Boot and Elastic Stack appeared first on Piotr's TechBlog.

]]>
In this article I’ll introduce my library for Spring Boot request and response logging designed especially for Spring Boot RESTful web application. The main assumptions regarding this library are:

  • Logging all incoming HTTP requests and outgoing HTTP responses with full body
  • Integration with Elastic Stack through Logstash using logstash-logback-encoder library
  • Possibility for enabling logging on a client-side for most commonly used components in Spring Boot application: RestTemplate and OpenFeign
  • Generating and propagating correlationId across all communication within a single API endpoint call
  • Calculating and storing execution time for each request
  • A library should be auto-configurable – you don’t have to do anything more than including it as a dependency to your application to make it work

Motivation for request and response logging

I guess that after reading the preface to that article you may ask why I decided to build such a library, while Spring Boot has such features. But the question is if it really has these features? It may be quite surprisingly, but the answer is no. While you may easily log HTTP requests using some built-in Spring components like CommonsRequestLoggingFilter, you don’t have any out-of-the-box mechanism for logging response body. Of course you may implement your own custom solution based Spring HTTP interceptor (HandlerInterceptorAdapter) or filter (OncePerRequestFilter), but that is no so simple as you might think. The second option is to use Zalando Logbook, which is an extensible Java library to enable complete request and response logging for different client-side and server-side technologies. It is a very interesting library dedicated especially for logging HTTP requests and responses, that provides many customization options and supports different clients. So, for more advanced you may always use this library.
My goal is to create a simple library that not only log requests and responses, but provides auto-configuration for sending these logs to Logstash and correlating them. It will also generate automatically some valuable statistics like time of request processing. All such values should be sent to Logstash. Let’s proceed to the implementation.

Implementation of Spring Boot logging library

Let’s start with dependencies. We need some basic Spring libraries, which are included to spring-web, and spring-context that provides some additional annotations. For integration with Logstash we use logstash-logback-encoder library. Slf4j contains abstraction for logging, while javax.servlet-api for HTTP communication. Commons IO is not required, but it offers some useful methods for manipulating input and output streams.

<properties>
   <java.version>11</java.version>
   <commons-io.version>2.6</commons-io.version>
   <javax-servlet.version>4.0.1</javax-servlet.version>
   <logstash-logback.version>5.3</logstash-logback.version>
   <spring.version>5.1.6.RELEASE</spring.version>
   <slf4j.version>1.7.26</slf4j.version>
</properties>
<dependencies>
   <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-context</artifactId>
      <version>${spring.version}</version>
   </dependency>
   <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-web</artifactId>
      <version>${spring.version}</version>
   </dependency>
   <dependency>
      <groupId>net.logstash.logback</groupId>
      <artifactId>logstash-logback-encoder</artifactId>
      <version>${logstash-logback.version}</version>
   </dependency>
   <dependency>
      <groupId>javax.servlet</groupId>
      <artifactId>javax.servlet-api</artifactId>
      <version>${javax-servlet.version}</version>
      <scope>provided</scope>
   </dependency>
   <dependency>
      <groupId>commons-io</groupId>
      <artifactId>commons-io</artifactId>
      <version>${commons-io.version}</version>
   </dependency>
   <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-api</artifactId>
      <version>${slf4j.version}</version>
   </dependency>
</dependencies>

The first step is to implement HTTP request and response wrappers. We have to do it because it is not possible to read the HTTP stream twice. If you would like to log the request or response body, you first have to read the input stream before processing or the output stream before returning it to the client. Spring provides an implementation of an HTTP request and response wrappers, but for unknown reasons they support only some specific use cases like content type application/x-www-form-urlencoded. Because we usually use application/json content type in the communication between RESTful applications Spring ContentCachingRequestWrapper and ContentCachingResponseWrapper won’t be useful here.
Here’s my implementation of the HTTP request wrapper. This can be done in various ways. This is just one of them:

public class SpringRequestWrapper extends HttpServletRequestWrapper {

    private byte[] body;

    public SpringRequestWrapper(HttpServletRequest request) {
        super(request);
        try {
            body = IOUtils.toByteArray(request.getInputStream());
        } catch (IOException ex) {
            body = new byte[0];
        }
    }

    @Override
    public ServletInputStream getInputStream() throws IOException {
        return new ServletInputStream() {
            public boolean isFinished() {
                return false;
            }

            public boolean isReady() {
                return true;
            }

            public void setReadListener(ReadListener readListener) {

            }

            ByteArrayInputStream byteArray = new ByteArrayInputStream(body);

            @Override
            public int read() throws IOException {
                return byteArray.read();
            }
        };
    }
}

The same thing has to be done for the output stream. This implementation is a little bit more complicated:

public class SpringResponseWrapper extends HttpServletResponseWrapper {

   private ServletOutputStream outputStream;
   private PrintWriter writer;
   private ServletOutputStreamWrapper copier;

   public SpringResponseWrapper(HttpServletResponse response) throws IOException {
      super(response);
   }

   @Override
   public ServletOutputStream getOutputStream() throws IOException {
      if (writer != null) {
         throw new IllegalStateException("getWriter() has already been called on this response.");
      }

      if (outputStream == null) {
         outputStream = getResponse().getOutputStream();
         copier = new ServletOutputStreamWrapper(outputStream);
      }

      return copier;
   }

   @Override
   public PrintWriter getWriter() throws IOException {
      if (outputStream != null) {
         throw new IllegalStateException("getOutputStream() has already been called on this response.");
      }

      if (writer == null) {
         copier = new ServletOutputStreamWrapper(getResponse().getOutputStream());
         writer = new PrintWriter(new OutputStreamWriter(copier, getResponse().getCharacterEncoding()), true);
      }

      return writer;
   }

   @Override
   public void flushBuffer() throws IOException {
      if (writer != null) {
         writer.flush();
      }
      else if (outputStream != null) {
         copier.flush();
      }
   }

   public byte[] getContentAsByteArray() {
      if (copier != null) {
         return copier.getCopy();
      }
      else {
         return new byte[0];
      }
   }

}

I moved the implementation out ServletOutputStream wrapper into the separated class:

public class ServletOutputStreamWrapper extends ServletOutputStream {

   private OutputStream outputStream;
   private ByteArrayOutputStream copy;

   public ServletOutputStreamWrapper(OutputStream outputStream) {
      this.outputStream = outputStream;
      this.copy = new ByteArrayOutputStream();
   }

   @Override
   public void write(int b) throws IOException {
      outputStream.write(b);
      copy.write(b);
   }

   public byte[] getCopy() {
      return copy.toByteArray();
   }

   @Override
   public boolean isReady() {
      return true;
   }

   @Override
   public void setWriteListener(WriteListener writeListener) {

   }
}

Because we need to wrap both HTTP request stream and response stream before processing we should use an HTTP filter for that. Spring provides their own implementation of an HTTP filter. Out filter is extending it and uses custom request and response wrappers to log payloads. Additionally it generates and sets X-Request-ID, X-Correlation-ID headers, and request processing time.

public class SpringLoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(SpringLoggingFilter.class);
    private UniqueIDGenerator generator;

    public SpringLoggingFilter(UniqueIDGenerator generator) {
        this.generator = generator;
    }

    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) throws ServletException, IOException {
        generator.generateAndSetMDC(request);
        final long startTime = System.currentTimeMillis();
        final SpringRequestWrapper wrappedRequest = new SpringRequestWrapper(request);
        LOGGER.info("Request: method={}, uri={}, payload={}", wrappedRequest.getMethod(),
                wrappedRequest.getRequestURI(), IOUtils.toString(wrappedRequest.getInputStream(),
                wrappedRequest.getCharacterEncoding()));
        final SpringResponseWrapper wrappedResponse = new SpringResponseWrapper(response);
        wrappedResponse.setHeader("X-Request-ID", MDC.get("X-Request-ID"));
        wrappedResponse.setHeader("X-Correlation-ID", MDC.get("X-Correlation-ID"));
        chain.doFilter(wrappedRequest, wrappedResponse);
        final long duration = System.currentTimeMillis() - startTime;
        LOGGER.info("Response({} ms): status={}, payload={}", value("X-Response-Time", duration),
                value("X-Response-Status", wrappedResponse.getStatus()),
                IOUtils.toString(wrappedResponse.getContentAsByteArray(), wrappedResponse.getCharacterEncoding()));
    }
}

Auto-configuration

Once we have finished an implementation of wrappers and HTTP filter, we may prepare auto-configuration for our library. The first step is to create @Configuration that contains all the required beans. We have to register our custom HTTP filter SpringLoggingFilter, the logger appender for integration with Logstash and RestTemplate with HTTP client interceptor:

@Configuration
public class SpringLoggingAutoConfiguration {

   private static final String LOGSTASH_APPENDER_NAME = "LOGSTASH";

   @Value("${spring.logstash.url:localhost:8500}")
   String url;
   @Value("${spring.application.name:-}")
   String name;

   @Bean
   public UniqueIDGenerator generator() {
      return new UniqueIDGenerator();
   }

   @Bean
   public SpringLoggingFilter loggingFilter() {
      return new SpringLoggingFilter(generator());
   }

   @Bean
   public RestTemplate restTemplate() {
      RestTemplate restTemplate = new RestTemplate();
      List<ClientHttpRequestInterceptor> interceptorList = new ArrayList<ClientHttpRequestInterceptor>();
      restTemplate.setInterceptors(interceptorList);
      return restTemplate;
   }

   @Bean
   public LogstashTcpSocketAppender logstashAppender() {
      LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
      LogstashTcpSocketAppender logstashTcpSocketAppender = new LogstashTcpSocketAppender();
      logstashTcpSocketAppender.setName(LOGSTASH_APPENDER_NAME);
      logstashTcpSocketAppender.setContext(loggerContext);
      logstashTcpSocketAppender.addDestination(url);
      LogstashEncoder encoder = new LogstashEncoder();
      encoder.setContext(loggerContext);
      encoder.setIncludeContext(true);
      encoder.setCustomFields("{\"appname\":\"" + name + "\"}");
      encoder.start();
      logstashTcpSocketAppender.setEncoder(encoder);
      logstashTcpSocketAppender.start();
      loggerContext.getLogger(Logger.ROOT_LOGGER_NAME).addAppender(logstashTcpSocketAppender);
      return logstashTcpSocketAppender;
   }

}

The configuration set inside the library has to be loaded by Spring Boot. Spring Boot checks for the presence of a META-INF/spring.factories file within your published jar. The file should list your configuration classes under the EnableAutoConfiguration key:


org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
pl.piomin.logging.config.SpringLoggingAutoConfiguration

Integration with Logstash

Integration with Logstash is realized through auto-configured logging appender. We can override Logstash destination URL by setting property spring.logstash.url in application.yml file;

spring:
  application:
    name: sample-app
  logstash:
    url: 192.168.99.100:5000

To enable all the features described in this article in your application you just need to include my library to the dependencies:

<dependency>
   <groupId>pl.piomin</groupId>
   <artifactId>spring-boot-logging</artifactId>
   <version>1.0-SNAPSHOT</version>
</dependency>

Before running your application you should start Elastic Stack tools on your machine. The best way to do that is through Docker containers. But first let’s create a Docker network to enable communication between containers via container name.


$ docker network create es

Now, let’s start a single node instance of Elasticsearch exposed on port 9200. I use version6.7.2 of Elastic Stack tools :


$ docker run -d --name elasticsearch --net es -p 9200:9200 -p 9300:9300 -e "discovery.type=single-node" elasticsearch:6.7.2

When running Logstash we need to provide an additional configuration that contains input and output definitions. We will start TCP input with JSON codec, which is not enabled by default. Elasticsearch URL is set as an output. It will also create an index containing the name of the application.

input {
  tcp {
    port => 5000
    codec => json
  }
}
output {
  elasticsearch {
    hosts => ["http://elasticsearch:9200"]
    index => "micro-%{appname}"
  }
}

Now we can start Docker container with Logstash. It is exposed on port 5000 and reads configuration from logstash.conf file:


docker run -d --name logstash --net es -p 5000:5000 -v ~/logstash.conf:/usr/share/logstash/pipeline/logstash.conf docker.elastic.co/logstash/logstash:6.7.2

Finally, we can run Kibana, which used just for displaying logs:

$ docker run -d --name kibana --net es -e "ELASTICSEARCH_URL=http://elasticsearch:9200" -p 5601:5601 docker.elastic.co/kibana/kibana:6.7.2

After starting my sample application that uses spring-boot-logging library the logs from POST requests are displayed in Kibana as shown below:

logging-1

Each entry with response log contains X-Correlation-ID, X-Request-ID, X-Response-Time and X-Response-Status headers.

spring-boot-logging-example-2

Summary

My Spring logging library is available on GitHub in the repository https://github.com/piomin/spring-boot-logging.git. I’m still working on it, so any feedback or suggestions are very welcome. This library is dedicated for use in microservices-based architecture, where your applications may be launched in many instances inside containers. In this model, storing logs in the files does not have any sense. That’s why integration with Elastic Stack is very important.
But the most important feature of this library is to log HTTP request/response with full body and some additional information to this log like correlation id or request processing time. The library is really simple, small, and everything is done out-of-the-box after including it in your application.

The post Logging with Spring Boot and Elastic Stack appeared first on Piotr's TechBlog.

]]>
https://piotrminkowski.com/2019/05/07/logging-with-spring-boot-and-elastic-stack/feed/ 4 7128