Traza de logs entre microservicios distribuidos. ¿Misión Imposible?
En Despegar utilizamos una arquitectura de microservicios. Todos sabemos los beneficios que trae este tipo de arquitectura: Tolerancia a fallas, redundancia, independencia entre servicios, mantenibilidad, escalabilidad, etc. Sin embargo, no todo es tan fácil, porque una arquitectura de este estilo trae una mayor complejidad; y uno de los elementos que se vuelven más complicados son los logs.
En general, siempre que surge un problema en producción y necesitamos saber qué pasó, vamos a los logs, donde probablemente podamos encontrar la causa del problema.
Sin embargo, esto que en una arquitectura monolítica es bastante sencillo, en microservicios se convierte rápidamente en un problema complejo.
¿Cuál es el problema?
La mayor parte del stack de aplicaciones que tenemos en Despegar corren sobre la JVM. Debido a esto, en general el sistema de logueo suele ser Slf4j, Logback o algo similar. En todo el ecosistema Java, el logueo está bastante estandarizado con estas librerías.
Al ser una arquitectura basada en microservicios, tenemos múltiples clusters de aplicaciones, cada uno con numerosas instancias. Entonces, el primer problema que se nos presenta es:
¿Dónde guardamos los logs?
Esto ya representa un problema en sí. La forma más básica de loguear con persistencia implica guardar en un archivo dentro de la máquina donde corre el programa todo el log que genera la aplicación, aumentando el tiempo de procesamiento, porque escribir a un archivo en disco suele ser un proceso costoso.
Esta es una solución un poco rústica porque digamos que tenemos un problema en el servicio X y queremos leer los logs para entender qué es lo que sucedió y encontrar la solución. Tenemos N instancias dentro del cluster de la aplicación X, por lo que deberíamos entrar a cada archivo de log de estas N instancias y buscar en CADA UNO por separado la información que queremos.
Leer logs de una sola aplicación ya es un proceso costoso, pero si el problema requiere revisar los logs de varias aplicaciones, sería notablemente más costoso. Claramente esta solución no escala y demanda muchísimo tiempo.
Además, tenemos otro inconveniente: si tenemos un problema en alguna instancia y, por ejemplo, el host tiene un problema de hardware, todo el log que se encontraba en esa instancia se perdería para siempre, junto con, quizás, otra valiosa información. Recuerden, tenemos un cluster para poder escalar horizontalmente, pero también para tener tolerancia a fallos. Y estas cosas parece que no suceden pero sí, ocurren, y bastante más seguido de lo que pensamos.
Entonces podemos concluir que tener los logs dentro de cada instancia es algo que no nos sirve.
¿Qué hacemos entonces?
Los guardamos de forma centralizada.
¿Cómo hacemos eso?
Afortunadamente, los frameworks de logging ya son bastante sofisticados y muy extensibles. En nuestro caso, lo que hicimos fue agregar un appender para logback que envíe cada línea de log a través de UDP. De esta forma, cambiando la configuración en vez de loguear en un archivo local, enviamos toda la información a través de la red.
Lo bueno de UDP es que es un protocolo orientado al datagrama y no a la conexión (como por ejemplo TCP), por lo que podemos enviar los paquetes y olvidarnos del problema. UDP simplemente se encarga de enviar, no le interesa ni comprueba si los paquetes llegan a destino o si llegan en orden. Por lo tanto, es muchísimo más liviano para la aplicación y no nos va a afectar prácticamente en nada, ni a la performance ni a la capacidad de respuesta de nuestros servicios.
Lo interesante de utilizar un protocolo como UDP para enviar las líneas de log es que no estamos acoplados al sistema de logueo. Por ejemplo, aplicaciones escritas en NodeJS (no corren sobre la JVM ni tienen logback) pueden fácilmente escribir un módulo para enviar por UDP, y la solución funciona de igual manera.
¿Y cómo funciona el sistema centralizado?
Es muy sencillo, es un programa que escucha la información que las instancias de las aplicaciones envían por UDP y la guarda en diferentes archivos. De esta forma, podemos leer el log de una aplicación sin la necesidad de entrar a CADA instancia por separado y repetir la búsqueda N veces. Ahora se busca en un solo lugar.
Ahora que tenemos todo centralizado, ¿cómo hace el sistema centralizado de logueo para diferenciar qué viene de cada aplicación?
Para resolver este problema, lo que se hizo es que cada aplicación loguee en un puerto particular. De esta forma, los logs de las diferentes aplicaciones no se mezclan y podemos discriminar la información.
¿Y si quiero ver la información de una instancia en particular?
Para solucionar eso, necesitamos agregar información extra a cada línea de log. Tenemos que agregar la información de qué instancia logueó esa línea y luego, con el archivo completo, filtrar esas líneas, y podríamos “rearmar” el log de cada instancia.
Para evitar que los archivos resulten muy grandes, se hace un rolling por día, por lo que además tendríamos los archivos de log separados por fecha y, al momento de pasar de día, se comprimen con gzip para ahorrar almacenamiento.
Al momento de leer los logs con este sistema, debemos entrar por SSH a la máquina centralizada y luego ir al archivo y greppear (filtrar con el comando “grep” de linux) lo que nos interesa buscar.
Bueno, parece que se solucionaron varios problemas, entonces ¿esta es la solución definitiva?
NO, tiene tres problemas muy importantes:
- La usabilidad: La forma de leer los logs es únicamente a través de una terminal, lo que puede que no sea lo más cómodo del mundo, además de que para buscar, debemos utilizar grep. Hay que saber usar muy bien este comando, porque cuando tenemos que hacer una búsqueda por algo más que un ID, las expresiones que tenemos que escribir se vuelven rápidamente muy, muy complicadas.
- La performance: Grep va escaneando secuencialmente el archivo y va escribiendo en STDOUT aquellas líneas que cumplen con la condición. El problema con esto es que al final del día, las búsquedas van a demorar mucho, y si bien estamos haciendo rolling por día para evitar que crezca demasiado el tamaño de los archivos, algunas aplicaciones que reciben mucho tráfico pueden escribir una gran cantidad de log (muchos GB) por día. En estos casos, se puede volver bastante lento si es necesario hacer varias búsquedas.
- La centralización: Tenemos todo centralizado por aplicación, pero si queremos buscar logs de varias aplicaciones, este problema aún no lo estamos pudiendo resolver, ya que debemos hacer las búsquedas por separado en logs de varias aplicaciones. Otra forma sería una búsqueda recursiva a un nivel superior que incluya las dos aplicaciones, pero esto sería aún más lento y costoso. Lo mismo sucede cuando tenemos búsquedas con líneas de log que se encuentran cerca de las 00hs. Tendremos que aplicar la búsqueda en el archivo de hoy y el de ayer. Teniendo centralizada la posibilidad de búsqueda entre diferentes aplicaciones, se puede ver el camino de cómo una solicitud se va resolviendo en todo el stack de aplicaciones por el que pase.
¿Cómo resolvemos estos últimos problemas mencionados?
Elasticsearch to the rescue!!
Básicamente, Elasticsearch es una base de datos documental distribuida que es muy buena realizando búsquedas. Pero no es una base documental cualquiera como Mongo. Esta está muy preparada y tiene muchísimas herramientas para procesar logs, todo lo que necesitamos nosotros.
Muy lindo todo, pero ¿cómo hago para guardar la data de los logs en Elasticsearch?
La gente que desarrolló Elasticsearch también se encargó de desarrollar logstash. Logstash es un procesador de logs.
En términos generales, logstash hace 3 cosas:
- Recibe un input de una fuente de datos. Por ej: un archivo, HTTP, una conexión TCP, UDP, etc.
- Realiza transformaciones sobre esos datos.
- Los escribe hacia un output que puede ser STDOUT o un archivo, entre otras opciones. Y lo más importante, ¡puede escribirlo sobre índices de Elasticsearch!
Lo interesante de esto es que podemos utilizar toda nuestra arquitectura preexistente de logs a través de UDP para que, en vez de escribirlos en nuestro sistema custom, lo haga sobre Elasticsearch.
Para hacer esto, necesitamos modificar un archivo de configuración de Logstash, en el cual especificamos el pipeline de estas 3 acciones: input, filter y output.
Como ejemplo, podemos usar este archivo pipelines para explicar cómo funciona:
En la primera sección input, estamos diciendo que queremos escuchar por el puerto 9109, y todo lo que llegue por aquí va a ser procesado por Logstash paquete por paquete.
En la segunda sección filter, tenemos 3 pasos. Dos son Grok y uno es date.
Estos son plugins de la etapa filter. La lista completa de plugins está aquí: https://www.elastic.co/guide/en/logstash/current/filter-plugins.html
Grok es un parseador que utiliza expresiones regulares.
Lo que estamos haciendo en el primer Grok es especificar el formato que tienen nuestras líneas de log. Lo interesante es que con todos estos datos que estamos extrayendo de cada línea, podemos realizar búsquedas. Búsquedas que funcionan muy rápido.
El segundo Grok lo que hace es parsear el campo “instance” que obtuvimos del anterior y extraer el nombre de la aplicación. Los nombres de las instancias decidimos que por convención sean “nombre-aplicación”-”número-instancia”.
Por último, se convierte la fecha que estaba en formato String a formato Date. Esto es importante porque queremos que la línea de log tenga el timestamp de cuando se logueó en nuestra aplicación, no de cuando se procesó en logstash.
De esta forma, luego del filter, un mensaje con un formato:
2021–04–28 20:13:17,878Z INFO [app-06] [YEKhsbmiIE] [jetty-128] JavaClass: Una línea de log
Pasa a ser un json como este:
En el output decimos que queremos agregar esta línea de log al cluster de elasticsearch a un índice con el nombre de la aplicación.
Por ejemplo, si nuestra app se llama “appcita” y el log es del día 28 de abril de 2021, el nombre del índice será: “logs-appcita-2021.04.28”.
Esto es muy importante porque a partir de campos extraídos de las líneas de log, podemos determinar a qué índice pertenece cada documento, y nos permite además administrar los logs de las aplicaciones separados por día y por aplicación, haciendo muchísimo más fácil la gestión.
Algo que podemos hacer es eliminar los logs pasados los 7 días de la fecha en que se crearon, con la finalidad de evitar consumir demasiado espacio en disco, o borrar todos los logs de una aplicación de un día en particular sin tocar la información del resto.
Como pueden ver, es un sistema muy poderoso que permite hacer muchísimas cosas con cada línea de log.
Ahora tenemos la información en elasticsearch, separada por índices por aplicación y por día. Genial, pero ¿cómo hago para ver la información???
Hay otra herramienta que nos proveen, “Kibana”, un frontend para poder consultar los datos fácilmente. Se pueden hacer consultas complejas, agregaciones, gráficos, etc.
Desde Kibana nos quedan pendientes todavía algunas configuraciones. Estas cosas se pueden hacer por API directamente a Elasticsearch, pero en la interfaz gráfica de Kibana es muchísimo más fácil.
Lo primero que debemos hacer es crear un lifecycle:
En nuestro caso, la configuración que aplicamos es que los índices se mantengan en fase HOT (pueden recibir lecturas y escrituras) durante 1 día. Luego pasan a fase WARM (solo pueden recibir lecturas) y después de 7 días a fase DELETE, en donde finalmente se eliminan.
Luego de esto, hay que configurar un Index Template para poder aplicar este lifecycle que acabamos de crear a todos nuestros índices de logs. Aquí podemos ver la ventaja de que nuestros índices tengan un prefijo en común. Simplemente indicamos un pattern “logs-*” y se aplica a todos nuestros índices al momento de la creación.
Por último, hay que definir un index-pattern. Básicamente es una forma de decirle a Kibana: “todos estos índices tienen data en común y los quiero buscar en conjunto”. De esta forma, podemos obtener todos los índices de logs a la vez, sin importar que estén separados por fecha y aplicación, logrando así solucionar una de las desventajas que teníamos anteriormente.
Al momento de consultar los datos, la pantalla que más se utiliza es el “discover”, donde se pueden filtrar los logs por todos los campos que parseamos con grok anteriormente, por fecha (algo muy importante), y no solo eso, sino que al igual que con grep, podemos hacer una búsqueda por cualquier texto dentro del cuerpo del mensaje o de cualquier campo parseado.
Kibana tiene un lenguaje de consultas muy sencillo KQL (Kibana Query Language), o sino se puede utilizar también el lenguaje de Lucene (lo que utiliza elasticsearch internamente para guardar los datos). De todas formas, para el tipo de query que queremos realizar, KQL cumple todas las expectativas.
Imaginemos que queremos ver qué líneas de log hay de la aplicación “appcita” donde aparezca el texto “FLIGHT”. En KQL eso se escribe así:
application: “appcita” AND “FLIGHT”
La documentación más completa de cómo funciona KQL se encuentra acá: https://www.elastic.co/guide/en/kibana/current/kuery-query.html
Otro beneficio que nos otorga toda esta configuración son los dashboards que se pueden crear. Por ejemplo, con la información parseada, se pueden sacar métricas como el RPM de la aplicación, qué aplicaciones reciben más tráfico, la tasa de errores, la distribución de log levels (INFO, ERROR, DEBUG, etc), entre otras cosas:
Datos como estos también son obtenibles a través de un APM. La gente de elastic tiene su propio APM, que es fácilmente integrable a nuestra arquitectura:
Lo interesante de los dashboards también es que se pueden filtrar, por lo que el mismo dashboard sirve para mostrar más información dependiendo de qué filtros apliquemos:
Eso no es todo, amigos
Nuestro stack todavía tiene un problema. Logstash funciona por separado y no en clúster, por lo que sólo tendremos una instancia disponible para procesar todos los logs, pudiendo quedarse corto en poder de procesamiento cuando se encuentre bajo mucha carga y siendo un único punto de falla.
Una posible solución es activar varias instancias de logstash y, a través de la combinación ip-puerto, decidir desde cada aplicación a qué instancia de Logstash enviar la información.
De esta forma, si un nodo de Logstash se cae, solo se ven afectadas aquellas aplicaciones que usan ese nodo, y el resto sigue logueando. Sin embargo, podemos llegar a tener downtimes significativos.
Una mejor solución que implementamos fue aplicar un balanceador de carga de capa 4 (transporte).
Probamos usando nginx y funcionaba OK, pero en su versión open source no contaba con health-checks, teniendo un problema similar al que queremos resolver.
Luego de considerar algunas opciones, elegimos gobetween, un balancer escrito en go http://gobetween.io/ open source.
Para poder monitorear los health checks contra logstash, agregamos un nuevo input http al pipeline, y estas líneas no procesarlas en las otras dos etapas “filter” y “output”. Si el mensaje se pudo procesar OK, nos devuelve 200; si hubo algún problema, 500 u otro status code. Con esto pudimos implementar health-checks de forma satisfactoria.
En el pipeline se escribe así usando condicionales:
Y así es como queda la arquitectura final de nuestro stack de logging:
Conclusión
De esta forma logramos implementar un stack de logging basado en ELK, que resuelve los siguientes problemas:
- Centralización de logs de múltiples servicios.
- Búsquedas complejas (y rápidas) sobre los logs de múltiples servicios sin limitaciones de fecha y hora.
- La posibilidad de compartir una búsqueda con el envío de un simple link.
- Eliminación de logs después de cierto tiempo para conservar storage.
- Obtención de métricas a partir de logs.
- Alta disponibilidad de todos los componentes del stack.
Todas estas ventajas hacen que leer logs, en busca de encontrar la causa de un problema productivo, sea más simple, evitando overhead y dando la posibilidad también a las personas de menor seniority del equipo de participar en la “caza” del bug.
