logging Archives - Piotr's TechBlog https://piotrminkowski.com/tag/logging/ Java, Spring, Kotlin, microservices, Kubernetes, containers Wed, 05 Jul 2023 21:15:29 +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 logging Archives - Piotr's TechBlog https://piotrminkowski.com/tag/logging/ 32 32 181738725 Logging in Spring Boot with Loki https://piotrminkowski.com/2023/07/05/logging-in-spring-boot-with-loki/ https://piotrminkowski.com/2023/07/05/logging-in-spring-boot-with-loki/#comments Wed, 05 Jul 2023 21:15:27 +0000 https://piotrminkowski.com/?p=14316 In this article, you will learn how to collect and send the Spring Boot app logs to Grafana Loki. We will use Loki4j Logback appended for that. Loki is a horizontally scalable, highly available log aggregation system inspired by Prometheus. I’ll show how to configure integration between the app and Loki step by step. However, […]

The post Logging in Spring Boot with Loki appeared first on Piotr's TechBlog.

]]>
In this article, you will learn how to collect and send the Spring Boot app logs to Grafana Loki. We will use Loki4j Logback appended for that. Loki is a horizontally scalable, highly available log aggregation system inspired by Prometheus. I’ll show how to configure integration between the app and Loki step by step. However, you can also use my auto-configured library for logging HTTP requests and responses that will do all those steps for you.

Source Code

If you would like to try it by yourself, you may always take a look at my source code. To do that you need to clone my GitHub repository. For the source code repository with my custom Spring Boot Logging library go here. Then you should just follow my instructions.

Using Loki4j Logback Appender

In order to use Loki4j Logback appended we need to include a single dependency in Maven pom.xml. The current version of that library is 1.4.1:

<dependency>
    <groupId>com.github.loki4j</groupId>
    <artifactId>loki-logback-appender</artifactId>
    <version>1.4.1</version>
</dependency>

Then we need to create the logback-spring.xml file in the src/main/resources directory. Our instance of Loki is available under the http://localhost:3100 address (1). Loki does not index the contents of the logs – but only metadata labels. There are some static labels like the app name, log level, or hostname. We can set them in the format.label field (2). We will also set some dynamic labels and therefore we enable the Logback markers feature (3). Finally, we are setting the log format pattern (4). In order to simplify, potential transformations with LogQL (Loki query language) we will use JSON notation.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

  <springProperty name="name" source="spring.application.name" />

  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>
        %d{HH:mm:ss.SSS} %-5level %logger{36} %X{X-Request-ID} - %msg%n
      </pattern>
    </encoder>
  </appender>

  <appender name="LOKI" class="com.github.loki4j.logback.Loki4jAppender">
    <!-- (1) -->
    <http>
      <url>http://localhost:3100/loki/api/v1/push</url>
    </http>
    <format>
      <!-- (2) -->
      <label>
        <pattern>app=${name},host=${HOSTNAME},level=%level</pattern>
        <!-- (3) -->
        <readMarkers>true</readMarkers>
      </label>
      <message>
        <!-- (4) -->
        <pattern>
{
   "level":"%level",
   "class":"%logger{36}",
   "thread":"%thread",
   "message": "%message",
   "requestId": "%X{X-Request-ID}"
}
        </pattern>
      </message>
    </format>
  </appender>

  <root level="INFO">
    <appender-ref ref="CONSOLE" />
    <appender-ref ref="LOKI" />
  </root>

</configuration>

Besides the static labels, we may send dynamic data, e.g. something specific just for the current request. Assuming we have a service that manages persons, we want to log the id of the target person from the request. As I mentioned before, with Loki4j we can use Logback markers for that. In classic Logback, markers are mostly used to filter log records. With Loki, we just need to define the LabelMarker object containing the key/value Map of dynamic fields (1). Then we pass the object to the current log line (2).

@RestController
@RequestMapping("/persons")
public class PersonController {

    private final Logger LOG = LoggerFactory
       .getLogger(PersonController.class);
    private final List<Person> persons = new ArrayList<>();

    @GetMapping
    public List<Person> findAll() {
        return persons;
    }

    @GetMapping("/{id}")
    public Person findById(@PathVariable("id") Long id) {
        Person p = persons.stream().filter(it -> it.getId().equals(id))
                .findFirst()
                .orElseThrow();
        LabelMarker marker = LabelMarker.of("personId", () -> 
           String.valueOf(p.getId())); // (1)
        LOG.info(marker, "Person successfully found"); // (2)
        return p;
    }

    @GetMapping("/name/{firstName}/{lastName}")
    public List<Person> findByName(
       @PathVariable("firstName") String firstName,
       @PathVariable("lastName") String lastName) {
       
       return persons.stream()
          .filter(it -> it.getFirstName().equals(firstName)
                        && it.getLastName().equals(lastName))
          .toList();
    }

    @PostMapping
    public Person add(@RequestBody Person p) {
        p.setId((long) (persons.size() + 1));
        LabelMarker marker = LabelMarker.of("personId", () -> 
           String.valueOf(p.getId()));
        LOG.info(marker, "New person successfully added");
        persons.add(p);
        return p;
    }

    @DeleteMapping("/{id}")
    public void delete(@PathVariable("id") Long id) {
        Person p = persons.stream()
           .filter(it -> it.getId().equals(id))
           .findFirst()
           .orElseThrow();
        persons.remove(p);
        LabelMarker marker = LabelMarker.of("personId", () -> 
           String.valueOf(id));
        LOG.info(marker, "Person successfully removed");
    }

    @PutMapping
    public void update(@RequestBody Person p) {
        Person person = persons.stream()
                .filter(it -> it.getId().equals(p.getId()))
                .findFirst()
                .orElseThrow();
        persons.set(persons.indexOf(person), p);
        LabelMarker marker = LabelMarker.of("personId", () -> 
            String.valueOf(p.getId()));
        LOG.info(marker, "Person successfully updated");
    }

}

Assuming we have multiple dynamic fields in the single log line, we have to create the LabelMarker object in this way:

LabelMarker marker = LabelMarker.of(() -> Map.of("audit", "true",
                    "X-Request-ID", MDC.get("X-Request-ID"),
                    "X-Correlation-ID", MDC.get("X-Correlation-ID")));

Running Loki with Spring Boot App

The simplest way to run Loki on the local machine is with a Docker container. Besides just the Loki instance, we will also run Grafana to display and search logs. Here’s the docker-compose.yml with all the required services. You can run them with the docker compose up command. However, there is another way – directly with the Spring Boot app.

version: "3"

networks:
  loki:

services:
  loki:
    image: grafana/loki:2.8.2
    ports:
      - "3100:3100"
    command: -config.file=/etc/loki/local-config.yaml
    networks:
      - loki

  grafana:
    environment:
      - GF_PATHS_PROVISIONING=/etc/grafana/provisioning
      - GF_AUTH_ANONYMOUS_ENABLED=true
      - GF_AUTH_ANONYMOUS_ORG_ROLE=Admin
    entrypoint:
      - sh
      - -euc
      - |
        mkdir -p /etc/grafana/provisioning/datasources
        cat <<EOF > /etc/grafana/provisioning/datasources/ds.yaml
        apiVersion: 1
        datasources:
        - name: Loki
          type: loki
          access: proxy
          orgId: 1
          url: http://loki:3100
          basicAuth: false
          isDefault: true
          version: 1
          editable: false
        EOF
        /run.sh
    image: grafana/grafana:latest
    ports:
      - "3000:3000"
    networks:
      - loki

In order to take advantage of the Spring Boot Docker Compose support we need to place the docker-compose.yml in the app root directory. Then, we have to include the spring-boot-docker-compose dependency in the Maven pom.xml:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-docker-compose</artifactId>
  <optional>true</optional>
</dependency>

Once we do all the required things, we can run the app. For example, with the following Maven command:

$ mvn spring-boot:run

Now, before the app, Spring Boot starts containers defined in the docker-compose.yml.

spring-boot-loki-docker-compose

Let’s just display a list of running containers. As you see, everything will work fine since Loki listens on the local port 3100:

$ docker ps            
CONTAINER ID   IMAGE                    COMMAND                  CREATED         STATUS         PORTS                    NAMES
d23390fbee06   grafana/loki:2.8.2       "/usr/bin/loki -conf…"   4 minutes ago   Up 2 minutes   0.0.0.0:3100->3100/tcp   sample-spring-boot-web-loki-1
84a47637a50b   grafana/grafana:latest   "sh -euc 'mkdir -p /…"   2 days ago      Up 2 minutes   0.0.0.0:3000->3000/tcp   sample-spring-boot-web-grafana-1

Testing Logging on the Spring Boot REST App

After running the app, we can make some test calls of our REST API. In the beginning, let’s add some persons:

$ curl 'http://localhost:8080/persons' \
  -H 'Content-Type: application/json' \
  -d '{"firstName": "AAA","lastName": "BBB","age": 20,"gender": "MALE"}'

$ curl 'http://localhost:8080/persons' \
  -H 'Content-Type: application/json' \
  -d '{"firstName": "CCC","lastName": "DDD","age": 30,"gender": "FEMALE"}'

$ curl 'http://localhost:8080/persons' \
  -H 'Content-Type: application/json' \
  -d '{"firstName": "EEE","lastName": "FFF","age": 40,"gender": "MALE"}'

Then, we may call the “find” endpoints several times with different criteria:

$ curl http://localhost:8080/persons/1
$ curl http://localhost:8080/persons/2
$ curl http://localhost:8080/persons/3

Here are the application logs from the console. There are just simple log lines – not formatted in JSON.

Now, let’s switch to Grafana. We already have integration with Loki configured. In the new dashboard, we need to choose Loki.

spring-boot-loki-grafana-datasource

Here’s the history of app logs stored in Loki.

As you see we are logging in the JSON format. Some log lines contain dynamic labels included with the Loki4j Logback appended.

spring-boot-loki-logs

We added the personId label to some logs, so we can easily filter records only with requests for a particular person. Here’s the LogQL query that filters records for the personId=1:

{app="first-service"} |= `` | personId = `1`

Here’s the result visible in the Grafana dashboard:

spring-boot-loki-labels

We can also format logs using LogQL. Thanks to JSON format it is possible to prepare a query that parses the whole log message.

{app="first-service"} |= `` | json

As you see, now Loki treats all the JSON fields as metadata labels:

Using Spring Boot Loki Starter Library

If you don’t want to configure those things by yourself, you can use my Spring Boot library which provides auto-configuration for that. Additionally, it automatically logs all the incoming HTTP requests and outgoing HTTP responses. If default settings are enough you just need to include the single Spring Boot starter as a dependency:

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

The library logs each request and response with several default labels including e.g. requestId or correlationId.

If you need more information about my Spring Boot Logging library you can refer to my previous articles about it. Here’s the article with a detailed explanation with some implementation details. Another one is more focused on the usage guide.

The post Logging in Spring Boot with Loki appeared first on Piotr's TechBlog.

]]>
https://piotrminkowski.com/2023/07/05/logging-in-spring-boot-with-loki/feed/ 3 14316
Guide to Quarkus with Kotlin https://piotrminkowski.com/2020/08/09/guide-to-quarkus-with-kotlin/ https://piotrminkowski.com/2020/08/09/guide-to-quarkus-with-kotlin/#comments Sun, 09 Aug 2020 08:28:56 +0000 http://piotrminkowski.com/?p=8353 Quarkus is a lightweight Java framework developed by RedHat. It is dedicated for cloud-native applications that require a small memory footprint and a fast startup time. Its programming model is built on top of proven standards like Eclipse MicroProfile. Recently it is growing in popularity. It may be considered as an alternative to Spring Boot […]

The post Guide to Quarkus with Kotlin appeared first on Piotr's TechBlog.

]]>
Quarkus is a lightweight Java framework developed by RedHat. It is dedicated for cloud-native applications that require a small memory footprint and a fast startup time. Its programming model is built on top of proven standards like Eclipse MicroProfile. Recently it is growing in popularity. It may be considered as an alternative to Spring Boot framework, especially if you are running your applications on Kubernetes or OpenShift.
In this guide, you will learn how to implement a simple Quarkus Kotlin application, that exposes REST endpoints and connects to a database. We will discuss the following topics:

  • Implementation of REST endpoints
  • Integration with H2 with Hibernate and Panache project
  • Generating and exposing OpenAPI/Swagger documentation
  • Exposing health checks
  • Exposing basic metrics
  • Logging request and response
  • Testing REST endpoints with RestAssured library

github-logo Source code

The source code with the sample Quarkus Kotlin applications is available on GitHub. First, you need to clone the following repository: https://github.com/piomin/sample-quarkus-applications.git. Then, you need to go to the employee-service directory.

1. Enable Quarkus Kotlin support

To enable Kotlin support in Quarkus we need to include quarkus-kotlin module. We also have to add kotlin-stdlib library.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-kotlin</artifactId>
</dependency>
<dependency>
   <groupId>org.jetbrains.kotlin</groupId>
   <artifactId>kotlin-stdlib</artifactId>
</dependency>

In the next step we need to include kotlin-maven-plugin. Besides standard configuration, we have to use all-open Kotlin compiler plugin. The all-open compiler plugin makes classes annotated with a specific annotation and their members open without the explicit open keyword. Since classes annotated with @Path, @ApplicationScoped, or @QuarkusTest should not be final, we need to add all those annotations to the pluginOptions section.

<build>
   <sourceDirectory>src/main/kotlin</sourceDirectory>
   <testSourceDirectory>src/test/kotlin</testSourceDirectory>
   <plugins>
      <plugin>
         <groupId>io.quarkus</groupId>
         <artifactId>quarkus-maven-plugin</artifactId>
         <version>${quarkus-plugin.version}</version>
         <executions>
            <execution>
               <goals>
                  <goal>build</goal>
               </goals>
            </execution>
         </executions>
      </plugin>
      <plugin>
         <groupId>org.jetbrains.kotlin</groupId>
         <artifactId>kotlin-maven-plugin</artifactId>
         <version>${kotlin.version}</version>
         <executions>
            <execution>
               <id>compile</id>
               <goals>
                  <goal>compile</goal>
               </goals>
            </execution>
            <execution>
               <id>test-compile</id>
               <goals>
                  <goal>test-compile</goal>
               </goals>
            </execution>
         </executions>
         <dependencies>
            <dependency>
               <groupId>org.jetbrains.kotlin</groupId>
               <artifactId>kotlin-maven-allopen</artifactId>
               <version>${kotlin.version}</version>
            </dependency>
         </dependencies>
         <configuration>
            <javaParameters>true</javaParameters>
            <jvmTarget>11</jvmTarget>
            <compilerPlugins>
               <plugin>all-open</plugin>
            </compilerPlugins>
            <pluginOptions>
               <option>all-open:annotation=javax.ws.rs.Path</option>
               <option>all-open:annotation=javax.enterprise.context.ApplicationScoped</option>
               <option>all-open:annotation=io.quarkus.test.junit.QuarkusTest</option>
            </pluginOptions>
         </configuration>
      </plugin>
   </plugins>
</build>

2. Implement REST endpoint

In Quarkus support for REST is built on top of Resteasy and JAX-RS libraries. You can choose between two available extentions for JSON serialization/deserialization: JsonB and Jackson. Since I decided to use Jackson I need to include quarkus-resteasy-jackson dependency. It also includes quarkus-resteasy module.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-resteasy-jackson</artifactId>
</dependency>

We mostly use JAX-RS annotations for mapping controller methods and fields into HTTP endpoints. We may also use Resteasy annotations like @PathParam, that does not require to set any fields. In order to interact with database, we are injecting a repository bean.

@Path("/employees")
@Produces(MediaType.APPLICATION_JSON)
@Consumes(MediaType.APPLICATION_JSON)
class EmployeeResource(val repository: EmployeeRepository) {

    @POST
    @Transactional
    fun add(employee: Employee): Response {
        repository.persist(employee)
        return Response.ok(employee).status(201).build()
    }

    @DELETE
    @Path("/{id}")
    @Transactional
    fun delete(@PathParam id: Long) {
        repository.deleteById(id)
    }

    @GET
    fun findAll(): List<Employee> = repository.listAll()

    @GET
    @Path("/{id}")
    fun findById(@PathParam id: Long): Employee? = repository.findById(id)

    @GET
    @Path("/first-name/{firstName}/last-name/{lastName}")
    fun findByFirstNameAndLastName(@PathParam firstName: String, @PathParam lastName: String): List<Employee>
            = repository.findByFirstNameAndLastName(firstName, lastName)

    @GET
    @Path("/salary/{salary}")
    fun findBySalary(@PathParam salary: Int): List<Employee> = repository.findBySalary(salary)

    @GET
    @Path("/salary-greater-than/{salary}")
    fun findBySalaryGreaterThan(@PathParam salary: Int): List<Employee>
            = repository.findBySalaryGreaterThan(salary)

}

3. Integration with database

Quarkus provides Panache JPA extension to simplify work with Hibernate ORM. It also provides driver extensions for the most popular SQL databases like Postgresql, MySQL, or H2. To enable both these features for H2 in-memory database we need to include the following dependencies.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-hibernate-orm-panache-kotlin</artifactId>
</dependency>
<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-jdbc-h2</artifactId>
</dependency>

We should also configure connection settings inside application.properties file.


quarkus.datasource.db-kind=h2
quarkus.datasource.username=sa
quarkus.datasource.password=password
quarkus.datasource.jdbc.url=jdbc:h2:mem:testdb

Panache extension allows to use well-known repository pattern. To use it we should first define entity that extends PanacheEntity class.

@Entity
data class Employee(var firstName: String = "",
                    var lastName: String = "",
                    var position: String = "",
                    var salary: Int = 0,
                    var organizationId: Int? = null,
                    var departmentId: Int? = null): PanacheEntity()

In the next step, we are defining repository bean that implements PanacheRepository interface. It comes with some basic methods like persist, deleteById or listAll. We may also use those basic methods to implement more advanced queries or operations.

@ApplicationScoped
class EmployeeRepository: PanacheRepository<Employee> {
    fun findByFirstNameAndLastName(firstName: String, lastName: String): List<Employee> =
           list("firstName = ?1 and lastName = ?2", firstName, lastName)

    fun findBySalary(salary: Int): List<Employee> = list("salary", salary)

    fun findBySalaryGreaterThan(salary: Int): List<Employee> = list("salary > ?1", salary)
}

4. Enable OpenAPI documentation for Quarkus Kotlin

It is possible to generate OpenAPI v3 specification automatically. To do that we need to include SmallRye OpenAPI extension. The specification is available under path /openapi.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-smallrye-openapi</artifactId>
</dependency>

We may provide some additional informations to the generated OpenAPI specification like description or version number. To do that we need to create application class that extends javax.ws.rs.core.Application, and annotate it with @OpenAPIDefinition, as shown below.

@OpenAPIDefinition(info = Info(title = "Employee API", version = "1.0"))
class EmployeeApplication: Application()

Usually, we want to expose OpenAPI specification using Swagger UI. Such a feature may be enabled using configuration property quarkus.swagger-ui.always-include=true.

quarkus-swagger

5. Health checks

We may expose built-in health checks implementation by including SmallRye Health extension.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-smallrye-health</artifactId>
</dependency>

It exposes three REST endpoints compliant with Kubernetes health checks pattern:

  • /health/live – The application is up and running (Kubernetes liveness probe).
  • /health/ready – The application is ready to serve requests (Kubernetes readiness probe).
  • /health – Accumulating all health check procedures in the application.

The default implementation of readiness health check verifies database connection status, while liveness just determines if the application is running.

quarkus-readiness

6. Expose metrics

We may enable metrics collection by adding SmallRye Metrics extension. By default, it collects only JVM, CPU and processes metrics.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-smallrye-metrics</artifactId>
</dependency>

We may force the library to collect metrics from JAX-RS endpoints. To do that we need to annotate the selected endpoints with @Timed.

@POST
@Transactional
@Timed(name = "add", unit = MetricUnits.MILLISECONDS)
fun add(employee: Employee): Response {
   repository.persist(employee)
   return Response.ok(employee).status(201).build()
}

Now, we may call endpoint POST /employee 100 times in a row. Here’s the list of metrics generated for the single endpoint. If you would like to ensure compatibility with Micrometer metrics format you need to set the following configuration property: quarkus.smallrye-metrics.micrometer.compatibility=true.

quarkus-metrics

7. Logging request and response for Quarkus Kotlin application

There is no built-in mechanism for logging HTTP requests and responses. We may implement custom logging filter that implements interfaces ContainerRequestFilter, and ContainerResponseFilter.

@Provider
class LoggingFilter: ContainerRequestFilter, ContainerResponseFilter {

    private val logger: Logger = LoggerFactory.getLogger(LoggingFilter::class.java)

    @Context
    lateinit var info: UriInfo
    @Context
    lateinit var request: HttpServerRequest

    override fun filter(ctx: ContainerRequestContext) {
        logger.info("Request {} {}", ctx.method, info.path)
    }

    override fun filter(r: ContainerRequestContext, ctx: ContainerResponseContext) {
        logger.info("Response {} {}: {}", r.method, info.path, ctx.status)
    }
    
}

8. Testing

The module quarkus-junit5 is required for testing, as it provides the @QuarkusTest annotation that controls the testing framework. The extension rest-assured is not required, but is a convenient way to test HTTP endpoints.

<dependency>
   <groupId>io.quarkus</groupId>
   <artifactId>quarkus-junit5</artifactId>
   <scope>test</scope>
</dependency>
<dependency>
   <groupId>io.rest-assured</groupId>
   <artifactId>kotlin-extensions</artifactId>
   <scope>test</scope>
</dependency>

We are adding new Employee in the first test. Then the second test verifies if there is a single Employee stored inside in-memory database.

@QuarkusTest
class EmployeeResourceTest {

    @Test
    fun testAddEmployee() {
        val emp = Employee(firstName = "John", lastName = "Smith", position = "Developer", salary = 20000)
        given().body(emp).contentType(ContentType.JSON)
                .post("/employees")
                .then()
                .statusCode(201)
    }

    @Test
    fun testGetAll() {
        given().get("/employees")
                .then()
                .statusCode(200)
                .assertThat().body("size()", `is`(1))
    }

}

Conclusion

In this guide, I showed you how to build a Quarkus Kotlin application that connects to a database and follows some best practices like exposing health checks, metrics, or logging incoming requests and outgoing responses. The last step is to run our sample application. To do that in development mode we just need to execute command mvn compile quarkus:dev. Here’s my start screen. You can see there, for example, the list of included Quarkus modules.

quarkus-run

If you are interested in Quarkus framework the next useful article for you is Guide to Quarkus on Kubernetes.

The post Guide to Quarkus with Kotlin appeared first on Piotr's TechBlog.

]]>
https://piotrminkowski.com/2020/08/09/guide-to-quarkus-with-kotlin/feed/ 5 8353
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