Una de las primeras cosas que aprendí cuando empecé a dedicarme profesionalmente a programar era que iba a necesitar una forma de diagnosticar errores, porque como tuviera que basarme en lo que me decían los usuarios (o en lo que yo intuía), lo llevaba claro.
Ello me llevó a poner siempre mucho cuidado en generar un buen log como primera herramienta de diagnóstico, y es algo que está entre las cosas que considero imprescindibles si desarrollas una aplicación.
Reconozco que siento predilección por los sistemas de logging simples, especialmente los ficheros de texto. La facilidad de acceder a ellos, de gestionarlos, de consultarlos y de compartirlos me resulta muy atractiva, pero sé que no escalan bien cuando tienes un volumen de información muy grande, por lo que no siempre pueden ser la única opción.
Además, no toda la información interesante de una aplicación es del mismo tipo. Por una parte, está bien saber qué está pasando (o qué ha pasado) para diagnosticar errores, pero también es útil poder auditar las operaciones individuales, obtener estadísticas de uso, de rendimiento, etc.
Entre todo este tipo de información, aparece lo que se conoce como semantic logging, a medio camino entre el log convencional puramente textual y una herramienta con más capacidades analíticas.
Un log estructurado
El logging semántico consiste en dotar de una mayor estructura a los eventos registrados en nuestro log. Ni más, ni menos. No es algo especialmente novedoso y hay muchos sistemas que ya hacían cosas similares, pero ya sabéis lo mucho que nos gusta ponerles nombres molones a las cosas para que parezcan más importantes.
En realidad, cualquier evento de un log ya tiene una cierta estructura. Como mínimo, suelen tener una fecha y hora de generación, un nivel de severidad y un mensaje, aunque es frecuente, especialmente si se utilizan sistemas como log4net o NLog, que podamos acceder a más información como el nombre de log o la hebra en la que se generó el evento.
El problema es que la parte realmente importante del evento, lo que ha pasado, no es más que una cadena de texto, por lo que poder tratarla de forma automatizada para explotar la información que contiene no es una tarea fácil. Al utilizar logging semántico intentamos resolver este problema haciendo que los eventos contengan, de forma estructurada, la información relevante para cada evento.
Por ejemplo, si tenemos un evento que representa el usuario ‘Paco’ ha aplicado el cupón de descuento ‘OFER25’, en un log semántico el evento llevaría asociada información parecida a ésta:
{
severity: "INFO",
timestamp: "2016-05-15T10:01:41",
message: "El usuario 'Paco' aplicó el descuento 'OFER25'",
action: "APPLY_DISCOUNT_CODE",
user: "Paco",
offerCode: "OFER25"
}
En lugar de limitarnos a almacenar un mensaje, añadimos información suficiente sobre el evento para tratarlo posteriormente. Así, podríamos obtener todos los descuentos aplicados por un usuario, o comparar las horas en que se aplican descuentos, etc.
Va un paso más allá del log tradicional cuyo objetivo principal es el diagnóstico, y aporta características propias de herramientas analíticas.
Aunque el evento del ejemplo esté representado en JSON, el concepto de log semántico es independiente de la representación elegida para los eventos y de la forma en que los almacenemos. Igual que pasa con sistemas de log tradicionales, que permiten almacenar el log en un fichero de texto, en un syslog o en una base de datos, cuando usamos un sistema de log semántico podemos optar por el sistema de almacenamiento que mejor se ajuste al uso que vayamos a darle después a la información.
Lo malo, claro, es que generar un log de estas características requiere más trabajo que ir escupiendo líneas de texto a un fichero.
Para empezar, si queremos que la información almacenada sea útil, deberíamos dedicar algo de tiempo a pensar qué queremos hacer con ella y qué datos debería incluir cada evento de log. Necesitamos algo de planificación a priori.
Además, generar cada evento de log implica un esfuerzo mayor y, dependiendo del lenguaje de programación que estemos utilizando, puede ser más o menos incómodo. En lenguajes con tipado estático y mal soporte para estructuras de datos dinámicas (como Java), podemos necesitar mucho código para generar los eventos. Podemos crear clases concretas para representar cada evento (al estilo de lo que haríamos con eventos de dominio), pero el coste de desarrollo es aún mayor, y habría que ver si realmente compensa.
Simplificando el proceso con Serilog
Serilog es una librería para .NET que permite generar eventos con información estructurada de una forma muy simple y cómoda. La idea es sencilla: aprovechar el mensaje que escribiríamos en cualquier log de texto para extraer la información relevante en base al formato. Algo así:
log.Information(
"El usuario {user} ha aplicado el cupón de descuento {offerCode}",
user.Name,
offer.Code);
Serilog utiliza una pequeña DSL similar a las cadenas interpoladas de C# 6 para obtener la información estructurada que se guardará junto al mensaje. En este caso, incluirá en el evento una propiedad user ligada al primer parámetro, user.Name, y otra propiedad offerCode asociada al segundo parámetro, offer.Code.
El enlace entre parámetros y propiedades no se basa en el nombre, sino en la posición de los argumentos, y existen varias maneras de elegir cómo se formateará la información. Dependiendo del tipo de valor podemos utilizar su método ToString(), serializarlo, etc.
Una vez generados los eventos serán enviados a los loggers que hayamos creado que, por supuesto, pueden ser jerarquizados, pueden añadir nuevas propiedades a los eventos que reciben, pueden filtrarlas… en fin, todo lo que esperarías de un sistema de logging.
Al igual que ocurre con los sistemas de logs más «tradicionales», la forma de persistir la información es completamente ortogonal al sistema de logging, por lo que podemos asociar distintos destinos (sinks, en terminología de Serilog) a cada logger en función de nuestras necesidades.
No voy a entrar en detalles sobre cómo se utiliza Serilog porque su documentación es muy completa, y si estás familiarizado con cualquier libería de logging, todos los conceptos te resultarán muy familiares.
Lo que me ha parecido muy interesante de esta librería es lo fácil que resulta añadir información estructurada a los eventos del log sin tener que hacer un esfuerzo adicional muy grande.
Puede que no sea la opción más potente, pero es un buen paso intermedio hasta que estés seguro de que realmente puedes explotar esa información adicional y sacarle un rendimiento que compense el esfuerzo de generarla y almacenarla.
Conclusiones
Me ha pasado varias veces y es extremadamente frustrante. Falla un aplicación, hablas con el desarrollador y te dice que no tiene ni idea de lo que puede ser. Te ofreces a enviarle el log y te mira asombrado, él no usa de eso. Le preguntas que cómo puede diagnosticar el problema y pone cara de «a mi qué me cuentas, sólo tengo el mensaje de error y no es muy aclarativo».
Como experiencia de cliente es nefasta, pero es que para el desarrollador tampoco es una situación agradable. Cuando hay un problema, lo mejor es tener herramientas para solucionarlo, y poder contar con un histórico de lo que ha pasado en la aplicación es fundamental (por no decir indispensable).
Si además utilizas un sistema de logging estructurado, puedes aprovecharlo para comprender mejor el uso real de tu aplicación, lo que te ayudará a decidir en qué partes debes hacer más o menos esfuerzo a la hora de desarrollar nuevas funcionalidades, corregir problemas, o incluso enfocar las acciones comerciales y de marketing.
Dar el salto de guardar el stacktrace de las excepciones a tener un sistema de análisis no siempre es fácil, y menos si quieres realmente sacarle partido a ese sistema de análisis (almacenar datos es mucho más sencillo que convertir esos datos en información accionable), pero en ocasiones merece la pena.
Librerías como Serilog son una manera de mejorar la información que obtenemos de nuestras aplicaciones sin que nos cueste demasiado. Si prefieres dormir tranquilo cuando haya problemas y además disfrutas con el porno de estadísticas, tal vez merezca la pena que te plantees su uso.
Hola, muy interesante el post, aunque la última línea…. ¿Seguro que querías decir eso sobre las estadísticas? Muchas gracias por la info y un saludo
Gracias, JJ. Si te refieres al «porno de estadísticas», es intencionado. Lo decía porque a algunos (sé que no soy el único) nos encanta entretenernos con gráficas, porcentajes y cosas así de una forma puramente recreativa.
Hola Juanma,
Gracias por el artículo.
Venía a comentar mi actual experiencia con los logs. Nosotros para el análisis de los logs utilizamos Logstash, de Elastic Search, para parsear el contenido de los logs a lo largo del tiempo y mostrar la información con Kibana en forma de gráficas.
Por un lado nos sirve, como bien dices, para desfogar con el porno estadístico, y por otro lado también muchas vece para hacernos una idea del estado de salud del sistema a lo largo de días o incluso casi en tiempo real. Incluso se puede monitorizar eventos directamente desde otros sistemas como por ejemplo RabbitMQ.
No conocía esta forma de gestionar y tratar la información de los archivos de log y la verdad me pareció útil y curiosa :)
Un saludo
Luis,
Logstash+kibana tienen buena pinta para la parte de análisis, ¿qué usáis para generar la información que mandáis a logstash?
Hola,
Si no tengo mal entendido el funcionamiento (seguro que no porque con 6 meses que llevo ya podria ser consultor de Elastic Search), Logstash lee directamente los archivos de log de las aplicaciones, y es del propio contenido de donde saca la información.
Por un lado se pueden configurar filtros para Logstash sobre el texto de los mensajes, y luego por otro sitio en Kibana se pueden configurar de manera «gráfica» una especie de queries tipo «buscame la palabra EntityNotFound y pintame las coincidencias de rojo».
Pero vamos, en definitiva tratamos directamente los archivos de log y esa información va a parar a Elastic Search (previamente filtrada) y de ahí tira Kibana.
Para generar los ficheros de log, ¿usáis log4net? ¿NLog? ¿Cómo hacéis para luego el contenido sea medianamente indexable por ES?
Sí, efectivamente de momento usamos Log4Net para los logs.
Entiendo que para que los datos sean más o menos coherentes para ES es importante configurar bien los «filter» y quizás los «codec».
Para la parte de codecs utilizamos «multilines»:
https://www.elastic.co/guide/en/logstash/current/plugins-codecs-multiline.html
Para la parte de filtros utilizamos «grok»:
https://www.elastic.co/guide/en/logstash/current/plugins-filters-grok.html
Aquí info sobre la estructura del archivo de configuración:
https://www.elastic.co/guide/en/logstash/current/configuration-file-structure.html
No se si con esta info contesto a la duda :P
Me encanta la sencillez de uso de Serilog. Buen post Juanma, como siempre ;)
Muy buen post y seguro escribirás algo sobre Elmah. ;)
Hola Juanma,
En tu opinión ¿Cuál sería la forma más adecuada de desactivar o cambiar el nivel de logging de Serilog en un sistema en producción? Está claro que se hace con LoggingLevelSwitch, el «cómo» no es problema, el problema es recuperar dinámicamente el nivel sin incurrir en un coste excesivo.
Con log4net es tan sencillo como cargar la configuración con log4net.Config.XmlConfigurator.ConfigureAndWatch y entonces cualquier cambio en el fichero .config de turno será automáticamente tenido en cuenta (yo personalmente muevo el .config a un log4net.xml y así cuando quiero cambiar algo del logging no implica un cambio en el Web.config y su correspondiente reinicio de la aplicación). Sin embargo, ¿Qué debería hacer con Serilog? ¿Guardar este valor en un fichero o bd y en cada petición preguntar por él? Esto no lo veo, sería un super-coste, aquí algo me he perdido…
Otra pregunta que me asalta es ¿Realmente es una buena práctica desactivar/activar el logging en producción? Quizás el logging no es sólo para cuando las cosas van mal (entonces voy y lo activo), sino que simplemente «siempre» está registrando eventos (vayan bien o mal las cosas). Quizás el problema es ese ¿Por que querría desactivar el logging? Aunque cambiar el nivel sí lo veo una práctica razonable.
Otra duda (y con esta termino) es que, ya sé que log4net es viejuno, pero me gusta mucho la idea de la jerarquía de loggers, la herencia entre ellos y el poder desactivar y configurar su nivel por separado. Entiendo que Serilog no tiene nada de esto y lo que te vende es que te crees varios loggers en vez de usar el estático ¿cierto?
Para acabar, no pretendo que mi comentario sea un «log4net vs Serilog», es simplemente que en el proceso de evaluación me surgen estas dudas y las comparto amablemente contigo y por ello te doy las gracias por adelantado :)
Un saludo y muchas gracias.
Hola Sergio,
Lo primero, decirte que yo uso también log4net, no serilog. Descubrí Serilog hace poco y no voy a sacarle rendimiento suficiente como para entretenerme en cambiar los cerca de 1000 usos de log4net que tengo en las aplicaciones más grandes que mantengo.
Con esto quiero decirte que no puedo ayudarte con el API concreta de Serilog y no estoy seguro de la forma recomendada de activar/desactivar el logging o cambiar el nivel de logging.
Lo que sí puedo es darte de una idea global sobre cómo podrías hacerlo y sobre lo que considero razonable o no.
La parte de activar o desactivar el log no la acabo de ver. Es normal poder cambiar el nivel de detalle, incluso de forma independiente para cada logger, pero nunca suelo desactivarlo del todo. Siempre hay cosas que quiero tener, aunque sea errores fatales con su StackTrace.
Lo de cambiar el nivel de logging «per request» ¿qué sentido tiene? Si usas el LoggingLevelSwitch, podrías hacer algo parecido a lo que hace log4net: puedes tener un fichero de configuración con el nivel de log, hacer un Watch sobre el fichero y, cuando cambie, volver a parsearlo y cambiar el nivel. No veo la necesidad de hacerlo para cada petición.
Un saludo,
Juanma.
Gracias Juanma
Para el watch entiendo que te refieres a FileSystemWatcher, no? La verdad es que lo tenía tan asociado a Windows Forms (desktop, en general) que no lo había ni sopesado en ASP.NET, efectivamente por request no tiene ningún sentido.
Sí, me refería al FileSystemWatcher de toda la vida. Sólo un aviso: no es muy fiable y a veces no se entera de los cambios.
Yo lo que suelo hacer es mezclarlo con un Timer (de System.Timers o de System.Threading). Reviso cada X tiempo el fichero, donde X es un valor asumible (por ejemplo, me da igual perder 3ms cada 30 segundos en eso), y uso el FileSystemWatcher como forma de activar el proceso sin esperar a que salte el timer.
Así, en el caso peor si hay algún problema tardaré 30 segundos (por ejemplo) en tener los cambios aplicados, aunque el FileSystemWatcher no se enterase.
Por cierto, sería recomendable que lo primero que haga tu código al cambiar el nivel de detalle del log sea logearlo para que sepas que ha funcionado el cambio ;-)
Gracias Juanma, probaré con eso para verlo funcionar, aunque de momento me quedaré con log4net. Siguientes proyectos, claro está, usaré Serilog, acabáramos!! :)
Hay una versión mejorada del FileSystemWatcher para evitar esos problemas:
https://petermeinl.wordpress.com/2015/05/18/tamed-filesystemwatcher/
Muy buenos los comentarios.
Luis, entiendo que también se podría instalar Logstash, Kibana and ElasticSearch en Windows Server 2012 + IIS ? Otra cosa sea la configuración de Logstash + ElastisSearch.
Logstash + ElastisSearch se basan en Java según creo.
Supongo que con log4net generas los logs en ficheros, que de alguna forma hay que comunicar o pasar los logs a Logstash, no sé ahora si vía comando o con algún API.
Muchas gracias
Yo creo que Luis va orientado a esto: ELK stack + Serilog
http://thomasvestergaard.com/blog/elasticsearch/measure-performance-with-serilog-elasticsearch-and-kibana/