Logging en Express.js: Identificador unico para cada request – Node.js
David Vicente Fuentes Colaboraciones 04/06/2018
Este artículo ha sido escrito por David Vicente y publicado originalmente en el blog de Solid GEAR
Cuando llevamos un sistema a producción, uno de los elementos más importantes a la hora de detectar cualquier problema o anomalía son los logs. En el caso de implementaciones de APIs uno de los mayores problemas es poder rastrear el flujo de una única petición, ya que cuando hay muchas peticiones concurrentes, los logs de todas ellas se mezclan haciendo imposible su seguimiento salvo que tengan un identificador único. Express.js carece de un identificador único por request, ni implementa un modo de obtener del contexto información sobre la petición en cualquier sitio del código, salvo que se pase el objeto request en todas las llamadas afectadas. Esto dificulta mucho el traceado de logs, o ensucia muchísimo el código si decidimos pasar el objeto request en todas las llamadas.
¿Existe alguna solución a este problema?
Sí, además nos va a servir para proyectos que ya estén desarrollados, ya que no va a requerir que pasemos objetos entre múltiples llamadas ni grandes cambios en los diferentes módulos del proyecto.
Introducción
Durante el desarrollo, muchas veces olvidamos introducir logs en el código, y esto hace que muchas partes de nuestro código sean ciegas a la hora de encontrar errores por parte de los administradores del sistema.
En el caso de implementación de un API en NodeJS, lo más habitual es utilizar el framework de Express. Espress.js nos permite implementar APIs de un modo muy sencillo. Algunas de las características más potentes que nos ofrece son:
- Implementación de funciones que se ejecutarán en cada petición que llegue al API
- Establecimiento de un flujo de funciones por cada path del API tratado
- Objetos request y response por cada petición recibida, que permiten obtener la información de la petición así como responder de una manera muy sencilla
Limitaciones de Express.js
Express pasa por ser un framework muy sencillo que nos facilita mucho la vida. Además es muy ligero. Y la manera de conseguir estos objetivos ha sido simplificando al máximo el número de funcionalidades que implementa, dejando las extrictamente necesarias para su funcionamiento.
En otros frameworks para implementación de APIs (no sólo en JavaScript), cada petición suele tener su propio identificador único. Además suele estar disponible en el contexto, de manera que en cualquier punto de la ejecución, el programa puede escribir un log identificando unívocamente la petición para que luego se pueda realizar un seguimiento de las peticiones, así como usar programas que saquen estadísticas de número de peticiones, para detectar problemas o fallos de peticiones.
Como vemos, el poder identificar en cada traza de log a que petición pertenece es importantísimo, por lo que en Expresses necesario solventar este problema si queremos tener un sistema que en producción no nos suponga quebradero de cabeza cada vez que haya un fallo.
Pasar el objeto request a través de todas las llamadas del código no sería una solución aceptable por dos razones principales:
- Estaríamos ensuciando nuestro código pasando parámetros a las funciones que nada tienen que ver con la funcionalidad para la que fueron creadas esas funciones
- El módulo de API quedaría ligado al resto de módulos de modo que sería casi imposible (o excesivamente tedioso) cambiarlo por otra interfaz, añadir otro módulo de interfaz o eliminarlo de nuestro sistema.
Librería para imprimir identificador único en cada petición
Si lo que queremos es que una librería haga todo el trabajo por nosotros, sólo tenemos que instalar esta librería express-logger-unique-req-id
npm install express-logger-unique-req-id --save
La configuración es muy sencilla, ya que usa Winston por debajo. Podríamos dejar la configuración por defecto si es que nos sirve, o podríamos pasarle una configuración válida para Winston y la aplicaría por nosotros. En cada línea de log añadirá el id de la req que habrá generado de manera única al llegar la petición a express. Lo bueno de esta librería es que soluciona los problemas que había con otras librerías que trabajaban con contextos pero que sólo funcionaban con callbacks, pero tenían problemas con promesas.
Con este sencillo ejemplo ya tendríamos un objeto logger que podríamos utilizar en cualquier parte de nuestro código. Podremos obtener el objeto en todos los módulos que queramos y el se encargará de manera transparente de imprimir el id de cada request sin que tengamos que hacer nada más.
Si quieres hacerlo por tu cuenta, continúa leyendo …
Identificador único de petición en Express.js
El primer paso que debemos dar para conseguir nuestro objetivo es asignar un identificador único a cada petición y que se mantenga aunque haya varias de ellas recurrentes.
Para esto vamos a necesitar dos librerías:
- uuid: La librería node-uuid es ampliamente utilizada para generar identificadores únicos en el sistema. Con ella crearemos un uuid que le asignaremos a cada petición de manera única.
- express-http-context: La librería express-http-context es una librería que nos ayuda a almacenar información asociada a cada hilo de ejecución. En Node.js como bien sabéis no existen hilos como tales, sino que se basa en ejecución asíncrona. Funciona con un contexto por “cada hilo de ejecución” en el que podemos almacenar y recuperar valores asociados a una clave. La librería nos ayudará a compartir entre los diferentes módulos de nuestro proyecto y que nos permitirá compartir la información que necesitamos.
Instalamos ambas librerías en nuestro entorno:
npm install uuid
npm install express-http-context
En el módulo donde arrancamos el servidor, típicamente el fichero server.js importamos las librerías y creamos un namespace de la librería express-http-context, el cual utilizaremos para almacenar los identificadores de las peticiones:
Y una vez incializado el framework Express, le asociaremos la librería del contexto y le añadiremos una funcionalidad, con el método use que se ejecutará una vez por cada petición entrante. En ella generaremos el identificador único de la petición y lo guardaremos en el namespace que hemos creado y quedará asociado al hilo de nuestra petición.
En este código hemos inicializado el módulo express, y le hemos añadido una funcionalidad que queremos que se ejecute con cada petición con el método use. Ahí hemos llamado al método set de la librería, que es el modo en que la librería nos permite escribir o leer datos en el contexto del hilo. Le asignamos un identificador único ( uuid.v1() ) a una entrada que hemos llamado reqId y que luego necesitaremos para recuperar este identificador en otros módulos.
El Logger en Express
El logger que utilizamos habitualmente en Node.js es Winston, probablemente el más extendido.
npm install winston
Típicamente esta librería permite escribir trazas de log con diferentes niveles de criticidad llamando a un método diferente por cada nivel y pasándoles el mensaje a imprimir logger.debug(message), logger.info(message), logger.error(message) ... o llamando al método log y pasándole el nivel de criticidad y el mensaje como parametros logger.log(level, message);
Hasta aquí el funcionamiento habitual de la librería. Pero nosotros queremos que en el caso de que estemos en un hilo de ejecución de una petición al API podamos escribir ese mensaje que pasamos a la librería junto con el identificador de la petición, y sin tener que pasarle el objeto request en cada llamada al logger. ¿Es posible? Claro que sí, aunque nos tenemos que poner el mono de trabajo.
Aquí es donde viene la magia. Vamos a hacer un recubrimiento de la librería del logger y ahí vamos a recuperar el identificador único de la petición (si es que es una petición) y a imprimirlo junto con el mensaje. Además vamos a hacerlo de manera que la interfaz de la librería siga siendo la misma, de modo que no habrá que hacer modificaciones en el resto de módulos si ya estábamos utilizando el logger en múltiples sitios. Pero tranquilos que va a ser mucho más sencillo de lo que parece.
El recubrimiento va a ser un nuevo módulo, al que he llamado logger.js en el que ya habitualmente tenía la configuración del módulo logger, pero que para este caso no afecta así que no la usaremos. En este módulo tendremos que importar la librería express-http-context que ya hemos usado antes, y de ella vamos a usar el método get. Con este método podremos recuperar el identificador único de la petición que está intentando escribir en el log.
var httpContext = require('express-http-context');var reqId = httpContext.get('reqId');
Con estas líneas obtendremos cada identificador de petición, aunque para que funcione, el namespace y el identificador tendremos que obtenerlos en cada llamada al logger.
Ahora que ya somos capaces de recuperar el identificador de la petición, el siguiente paso será sobreescribir los métodos de la librería respetando su interfaz actual, de modo que podamos llamar a un método propio que llamaremos formatMessage y que se encargará de añadir el identificador de la petición a cada línea imprimida en el log.
El módulo completo quedaría así:
El objeto logger es el que exportamos, y al que estarán llamando el resto de módulos. Sus métodos los he hecho coincidir con los de la librería para respetar su interfaz, y dentro de cada uno llamamos al método correspondiente de la librería pero pasando el mensaje a imprimir por nuestro método formatMessage que se encarga de hacer la magia. Es decir, en formatMessage recuperamos el namespace y si existe en él la entrada reqId la sacamos y se la añadimos al mensaje, y sino dejamos el mensaje tal cual estaba.
Y con esto ya hemos conseguido imprimir el identificador único de la petición con cada línea de log imprimida. El único cambio que habría que realizar en los módulos donde imprimiendo logs es importar nuestro módulo en vez del módulo de winston.
Este es un proyecto Node muy sencillo que implementa un solo recurso de test en el API y que usa la implementación del logger que hemos explicado en este post. Simula una llamada a la base de datos que tarda 5 segundos, por lo que si hacemos varias peticiones seguidas veremos en los logs como se alternan las diferentes peticiones con sus respectivos ids, lo que nos ayudará a hacer un seguimiento de cada petición por separado
https://github.com/davicente/express_logger
¿Esta solución funcionaría con otras librerías de logs?
Sí, simplemente tendríamos que hacer el recubrimiento de los métodos de la librería, y sólo tendríamos que importar nuestro módulo en vez del módulo de logs que estuviéramos usando en nuestros módulos.
Conclusión
Express.js carece de un método que nos permita acceder al contexto de cada petición sin estar pasando el objeto request en cada llamada. Pero usando una combinación entre una librería para el almacenamiento de información basado en la cadena de callbacks, creación de identificadores únicos y haciendo un pequeño recubrimiento sobre la librería de logs podemos tener esta funcionalidad sin necesidad de que nuestro código se convierta en una maraña de parámetros que circulan por todas las llamadas a funciones.
Artículos relacionados
Refresh token con autenticación JWT. Implementación en Node.js
Lo mejor y peor de Mocha y de los unit tests en JavaScriptEncriptación de password en Node.js y MongoDB: bcrypt
