Envío de logs en Spring Boot 2 a ELK sobre TCP

En un sistema basado en microservicios es vital poder centralizar los logs generados por todas las instancias de microservicios. En este post se asume el conocimiento de las diversas soluciones de centralización de logs como puede ser la conocida ELK.

Uno de los principales puntos de pérdida de rendimiento en sistemas productivos con una carga elevada de peticiones es el tiempo invertido por los microservicios en escribir logs en disco, así como su posterior procesado, envío a ELK e incluso el parseo y tratamiento de logs en Logstash.

Este tipo de problemáticas ha llevado a plantear soluciones de envío de logs sobre TCP y directamente generados como JSON para poder ser indexados directamente sobre Elastic Search.

A continuación, mostraremos un ejemplo de un microservicio en Spring Boot 2.1.2.RELEASE que genera logs directamente en JSON y los manda a Logstash para que este los redireccione sobre un Elastic Search.

En dicho ejemplo se ha usado la versión de ELK 6.6.x.

El código fuente de este ejemplo junto con la configuración de Logstash se puede encontrar en:

https://bitbucket.org/jrovirablog/logback_elk_over_tcp/src/master/

El primer paso de todos, es añadir la siguiente dependencia en nuestro pom.xml


 <dependency>
  <groupId>net.logstash.logback</groupId>
  <artifactId>logstash-logback-encoder</artifactId>
  <version>5.3</version>
 </dependency>

Esta dependencia nos da acceso a un Appender de Logback que permite mandar los logs a Logstash sobre TCP. Para más información sobre dicho Appender podéis consultar su documentación en:

https://github.com/logstash/logstash-logback-encoder

También configuraremos el fichero logback-spring.xml (importante añadir el "-spring" en el nombre para que Spring permita a Logback tener acceso a las propiedades que hay en el Spring Context) de la siguiente manera.


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

 <include resource="org/springframework/boot/logging/logback/defaults.xml" />

 <springProperty scope="context" name="microName" source="spring.application.name" defaultValue="not specified"/>
 
 <appender name="LOGSTASH"
  class="net.logstash.logback.appender.LogstashTcpSocketAppender">
  <destination>localhost:5044</destination>
  <reconnectionDelay>5 second</reconnectionDelay>
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
   <includeCallerData>false</includeCallerData>
   <includeContext>false</includeContext>
   <shortenedLoggerNameLength>36</shortenedLoggerNameLength>
   <customFields>
    {
    "custom_field": "xxxx",
    "spring_property": "${microName}",
    "jvm_system_variable": "${java.runtime.name} ${java.runtime.version}",
    "env_variable": "${ENV_VARIABLE}"
    }
   </customFields>
  </encoder>

 </appender>

 <appender name="LOGSTASH_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>500</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>false</neverBlock>
     <appender-ref ref="LOGSTASH" />
   </appender>

 <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  <!-- 
  <encoder>
   <pattern>%d %-5level %logger{35} - %msg%n</pattern>
  </encoder>
   -->
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
   <includeCallerData>false</includeCallerData>
   <includeContext>false</includeContext>
   <shortenedLoggerNameLength>36</shortenedLoggerNameLength>
   <customFields>
    {
    "custom_field": "xxxx",
    "spring_property": "${microName}",
    "jvm_system_variable": "${java.runtime.name} ${java.runtime.version}",
    "env_variable": "${ENV_VARIABLE}"
    }
   </customFields>
  </encoder>
 </appender>

 <appender name="STDOUT_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>500</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>false</neverBlock>
     <appender-ref ref="STDOUT" />
   </appender>

 <logger name="org.jrovira" level="INFO" additivity="false">
   <appender-ref ref="STDOUT_ASYNC" />
  <appender-ref ref="LOGSTASH_ASYNC" />
 </logger>

 <root level="WARN">
  <appender-ref ref="STDOUT_ASYNC" />
  <appender-ref ref="LOGSTASH_ASYNC" />
 </root>
</configuration>

En este fichero hay varias cosas interesantes a analizar, por lo que vamos por partes.

Para configurar el envío de logs a Logstash, lo hemos realizado con el Appender "net.logstash.logback.appender.LogstashTcpSocketAppender" en el cual indicamos que nuestro Logstash se encuentra esperando logs en "localhost:5044"

 <appender name="LOGSTASH"
  class="net.logstash.logback.appender.LogstashTcpSocketAppender">
  <destination>localhost:5044</destination>
  <reconnectionDelay>5 second</reconnectionDelay>
  ...
 </appender>

Si queremos introducir en cada uno de nuestros registros de logs valores de propiedades que tengamos cargadas en el Spring Context, lo haremos a través del tag "springProperty", el cual con el atributo "source" indicamos cual es la propiedad que nos interesa y el atributo "name" indica un nombre para poder hacer referencia posteriormente.

En el encoder de la clase "net.logstash.logback.encoder.LogstashEncoder" indicaremos en el tag "customFields" el campo "springProperty" haciendo referencia al valor de la propiedad que hemos guardado como "microName" en el tag "springProperty" explicado en el párrafo anterior. Con esta configuración, en cada log aparecerá dicho valor.

 ...
<springProperty scope="context" name="microName" source="spring.application.name" defaultValue="not specified"/>
 
 <appender name="LOGSTASH"
  class="net.logstash.logback.appender.LogstashTcpSocketAppender">
  ...
  <encoder class="net.logstash.logback.encoder.LogstashEncoder">
   ...
   <customFields>
    {
    ...
    "spring_property": "${microName}",
    ...
    }
   </customFields>
  </encoder>

 </appender>
 ...

También podemos observar como en "CustomFields", además del campo springProperty, añadimos los siguientes campos:

"custom_field" es un valor fijo que aparecerá en cada registro de logs.
"jvm_system_variable" es un valor que se cargará a partir de System Properties de la JVM.
"env_variable" es un valor que se cargará a partir de una variable de entorno de nuestro sistema operativo llamada "$ENV_VARIABLE".

Además de la configuración de Logback, hemos creado un microservicio que expone un endpoint /hello el cual implementa lo siguiente.


 @GetMapping("/hello")
 public String hello() {
  MDC.put("mdc_field", UUID.randomUUID().toString());
  
  LOGGER.info("Log simple");

  Marker marker = new BasicMarkerFactory().getMarker("test_marker");
  marker.add(new BasicMarkerFactory().getMarker("test_marker2"));
  marker.add(new BasicMarkerFactory().getMarker("test_marker3"));
  LOGGER.info(marker, "Log con markers");
  
  LOGGER.info("Log con un argumento", StructuredArguments.value("arg1", "arg1value"));
  
  Map<Object, Object> map = new HashMap<Object, Object>();
  map.put("arg1", "arg1 with map");
  map.put("arg2", "arg2 with map");
  map.put("arg3", "arg3 with map");
  LOGGER.info("Log con múltiples argumentos", StructuredArguments.entries(map));
  
  return "hello";
 }

Podemos ver que este código introduce para cada request recibida en el microservicio:

UUID en el MDC para que todas las trazas pueden tener acceso a dicho valor.
Escritura de un log con un mensaje "Log Simple".
Escritura de un log con Markers con el mensaje "Log con markers".
Escritura de un log con un argumento con el mensaje "Log con un argumento".
Escritura de un log con varios argumentos con el mensaje "Log con múltiples argumentos".

Si ahora arrancamos nuestro microservicio, podremos ver como por Consola se están generando trazas en formato JSON como las siguientes:


  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.2.RELEASE)

{"@timestamp":"2019-02-16T08:51:06.922+01:00","@version":"1","message":"Started TcploggingApplication in 4.766 seconds (JVM running for 5.271)","logger_name":"o.j.b.l.t.TcploggingApplication","thread_name":"main","level":"INFO","level_value":20000,"custom_field":"xxxx","spring_property":"tcplogging","jvm_system_variable":"Java(TM) SE Runtime Environment 1.8.0_171-b11","env_variable":"Value for ENV_VARIABLE"}

Vamos a formatear la línea de log generada para verla con más comodidad.

{
   "@timestamp": "2019-02-16T08:51:06.922+01:00",
   "@version": "1",
   "message": "Started TcploggingApplication in 4.766 seconds (JVM running for 5.271)",
   "logger_name": "o.j.b.l.t.TcploggingApplication",
   "thread_name": "main",
   "level": "INFO",
   "level_value": 20000,
   "custom_field": "xxxx",
   "spring_property": "tcplogging",
   "jvm_system_variable": "Java(TM) SE Runtime Environment 1.8.0_171-b11",
   "env_variable": "Value for ENV_VARIABLE"
}

Podemos observar como los últimos 4 campos del log corresponden con los indicados en el fichero de Logback. Estos 4 campos se generarán para cualquier log que escribamos en nuestro código.

Ahora vamos a realizar una invocación a nuestro endpoint "/hello" y veremos los 4 logs generados.

El primer log de todos podemos observar como se han generado los 4 campos mencionados anteriormente y también se ha cogido los valores introducidos en el MDC (como también se añadirán en el resto de logs de la invocación realizada).


{
   "@timestamp": "2019-02-16T08:53:25.600+01:00",
   "@version": "1",
   "message": "Log simple",
   "logger_name": "o.j.b.l.t.c.HelloController",
   "thread_name": "http-nio-7070-exec-1",
   "level": "INFO",
   "level_value": 20000,
   "mdc_field": "9754b229-b76d-483c-a3ca-911c27b1f6b1",
   "custom_field": "xxxx",
   "spring_property": "tcplogging",
   "jvm_system_variable": "Java(TM) SE Runtime Environment 1.8.0_171-b11",
   "env_variable": "Value for ENV_VARIABLE"
}

En el log con markers podemos observar como se ha creado un campo "tags" con todos los markers que hemos creado.


{
   "@timestamp": "2019-02-16T08:53:25.602+01:00",
   "@version": "1",
   "message": "Log con markers",
   "logger_name": "o.j.b.l.t.c.HelloController",
   "thread_name": "http-nio-7070-exec-1",
   "level": "INFO",
   "level_value": 20000,
   "mdc_field": "9754b229-b76d-483c-a3ca-911c27b1f6b1",
   "tags": [
      "test_marker",
      "test_marker2",
      "test_marker3"
   ],
   "custom_field": "xxxx",
   "spring_property": "tcplogging",
   "jvm_system_variable": "Java(TM) SE Runtime Environment 1.8.0_171-b11",
   "env_variable": "Value for ENV_VARIABLE"
}

En el log con un argumento veremos como dicho argumento se ha creado como un nuevo campo del JSON pero que solo aplica a este log y no al resto.


{
   "@timestamp": "2019-02-16T08:53:25.604+01:00",
   "@version": "1",
   "message": "Log con un argumento",
   "logger_name": "o.j.b.l.t.c.HelloController",
   "thread_name": "http-nio-7070-exec-1",
   "level": "INFO",
   "level_value": 20000,
   "mdc_field": "9754b229-b76d-483c-a3ca-911c27b1f6b1",
   "arg1": "arg1value",
   "custom_field": "xxxx",
   "spring_property": "tcplogging",
   "jvm_system_variable": "Java(TM) SE Runtime Environment 1.8.0_171-b11",
   "env_variable": "Value for ENV_VARIABLE"
}

Y por último en el log con varios argumentos veremos se crean tantos campos nuevos en el JSON como argumentos se hayan indicado.


{
   "@timestamp": "2019-02-16T08:53:25.606+01:00",
   "@version": "1",
   "message": "Log con múltiples argumentos",
   "logger_name": "o.j.b.l.t.c.HelloController",
   "thread_name": "http-nio-7070-exec-1",
   "level": "INFO",
   "level_value": 20000,
   "mdc_field": "9754b229-b76d-483c-a3ca-911c27b1f6b1",
   "arg3": "arg3 with map",
   "arg2": "arg2 with map",
   "arg1": "arg1 with map",
   "custom_field": "xxxx",
   "spring_property": "tcplogging",
   "jvm_system_variable": "Java(TM) SE Runtime Environment 1.8.0_171-b11",
   "env_variable": "Value for ENV_VARIABLE"
}

Para que Logstash puedo procesar estos logs, lo configuraremos de la siguiente manera.


input {
  tcp {
    port => 5044
 codec => json
  }
}
output {
  elasticsearch {
    hosts => ["http://localhost:9200"]
    index => "logs-%{+YYYY.MM.dd}"
  }
}

Por último mostramos una captura de pantalla de como se pueden visualizar dichos logs en Kibana y poderse hacer una idea de la potencia de esta solución.

{ jrovira }

Envío de logs en Spring Boot 2 a ELK sobre TCP

1 comentario

Tags

Populares

Archivo