Observabilidad: primer pilar los logs

Varias veces he tocado el tema en alguno que otro post la verdad es que es un tema que me interesa bastante, por ello pienso retomarlo desde diferentes perspectivas, diferentes tecnologías y buscar como hacer que todo converja para lograr tener optimización en los tiempos de respuesta de los problemas que ocurren en ls sistemas en producción, creo yo que un buen sistema no debería ser el que no tenga errores si no el que mejor le de tratamiento a ellos y lo logre informar, por ello iniciaré hablando de los orígenes de este concepto, que viene de muchos años atrás con un estándar llamado syslog que tuvo sus origine en 1980 pero se estandarizó por medio de RFC solo después del 2001 usando en los sistemas operativos unix, esta estandarización definió entre varias cosas el protocolo, los tipos de mensaje y los tipos de campos que se deberían tener en un log de mensaje, uno de los más conocidos quizás sea el nivel del error como se aprecia en la Figura 1

Figura 1: Código y mensajes de error

Claramente no debemos conocer el estándar a profundidad ya que el interés inicial en este artículo es poder escribir logs, por ello usare algunas librerías que nos facilitarán esta tarea, en este post en especifico me centraré en trabajar con Javascript por ello pasemos a ver como funciona

Emitiendo Logs

El concepto de logs centralizados podemos encontrar varios artículos interesantes que hablan del tema, algunos hablan de los procesos que se deben seguir, otros van más a la aplicabilidad con diferentes stacks inicialmente yo creo que se pueden aterrizar tres etapas básicas en este proceso como se aprecia en la Figura 2, el emitir logs es el proceso más importante por que es el primer paso para avanzar en la centralización, por ende si la aplicación aún no hace este proceso la implementación puede llevar tiempo y el costo depende del tamaño del producto, para emitir logs con Javascript utilizaremos la librería llamada winston, crearemos un proyecto con npm init y la instalaremos usando el siguiente comando

Figura 2: etapas de la centralización de logs basado en el libro Software Telemetry

npm install winston

ahora creare un módulo logger.js donde escribiré el siguiente código

const { createLogger, transports, format } = require("winston");

const logger = createLogger({
  format: format.json(),
  transports: [new transports.File({ filename: "application.log" })],
});



const error = new Error("division by zero");
logger.error(`${error}`);

ejecuto el código y obtengo lo siguiente, un archivo llamado application.log con el siguiente contenido

{"message":"Error: division by zero","level":"error"}
{"message":"Error: division by zero","level":"error"}

Diferentes entornos

dependiendo del entorno se pueden agregar otros tipos de transportes por ejemplo si se encuentra en entornos dev se podría habilitar una capa que transporte por consola, sin embargo en stage podría habilitar una capa de transporte de un web service como se aprecia a continuación

const { createLogger, transports, format } = require("winston");

const logger = createLogger({
  format: format.json(),
  transports: [
      new transports.File({ filename: "application.log" }),
      new transports.File({
        filename: 'error.log',
        level: 'error',
        format: format.json()
      })
    ],
});


if (process.env.NODE_ENV == "dev") {
  logger.add(
    new transports.Console({
      format: format.simple(),
    })
  );
}
else if (process.env.NODE_ENV == "stage") {
    logger.add(
      new transports.Http({
        format: format.json(),
         host: 'localhost',
         port:3000,
         path:"/",

      })
    );
  }

const error = new Error("division by zero");
logger.error(`${error}`);

ejecuto seteando la variable de entorno NODE_ENV a stage y tenemos el siguiente resultado en nuestro servidor encargado de recibir el web service

app listening at http://localhost:3000
{ message: 'Error: division by zero', level: 'error' }
{ message: 'Error: division by zero', level: 'error' }
{ message: 'Error: division by zero', level: 'error' }

en el archivo application.log y error.log

{"message":"Error: division by zero","level":"error"}
{"message":"Error: division by zero","level":"error"}
{"message":"Error: division by zero","level":"error"}

en el código anterior estoy definiendo dos capas de transporte en la siguiente porcion de codigo se muestra

const logger = createLogger({
  format: format.json(),
  transports: [
      new transports.File({ filename: "application.log" }),
      new transports.File({
        filename: 'error.log',
        level: 'error',
        format: format.json()
      })
    ],
});

pero la segunda capa de transporte solo se usará para escribir en disco si el tipo de log es de nivel error, luego agregó a la lista de capas de transporte dos capas más una de consola si es dev y otra de stage como se aprecia en el siguiente segmento

else if (process.env.NODE_ENV == "stage") {
    logger.add(
      new transports.Http({
        format: format.json(),
         host: 'localhost',
         port:3000,
         path:"/",

      })
    );
  }

de este modo cuando esté en stage los logs no solo se escribirán en disco si no que se guardaran en un web service definido previamente, esto es una gran ventaja ya que la librería tiene varios pilares que se pueden cambiar de manera independiente, por lo tanto si hoy se desea guardar en disco se usa una capa de transporte File pero si mañana se quiere migrar a un web service o a un servicio personalizado como datadog solo cambio el transporte utilizado el resto de código sigue funcionando sin problemas

Diferentes formatos

Como se ha apreciado en los ejemplos se tiene el formato .json() que utiliza la estructura de json para escribir los logs, sin embargo el formato se puede personalizar creando el propio formato dependiendo de la estructura que sea desea mostrar, siguiendo un poco el concepto del RFC referenciando al principio del artículo se podría pensar en un formato como se aprecia a continuación

const { createLogger, transports, format } = require("winston");
const { combine, printf, timestamp, errors, label } = format;

const formatLog = printf(({ level, message, label, timestamp, stack }) => {
  if (stack) {
    message = message + " - " + stack;
  }

  return `${label} - ${timestamp} - ${level.toUpperCase()} - ${message}`;
});

const logger = createLogger({
  format: combine(
    label({ label: "MYSERVICE" }),
    errors({ stack: true }),
    timestamp(),
    formatLog
  ),
  transports: [
    new transports.File({ filename: "application.log" }),
    new transports.File({
      filename: "error.log",
      level: "error",
      format: combine(
        label({ label: "MYSERVICE" }),
        errors({ stack: true }),
        timestamp(),
        formatLog
      ),
    }),
  ],
});

if (process.env.NODE_ENV == "dev") {
  logger.add(
    new transports.Console({
      format: format.simple(),
    })
  );
} else if (process.env.NODE_ENV == "stage") {
  logger.add(
    new transports.Http({
      format: format.json(),
      host: "localhost",
      port: 3000,
      path: "/",
    })
  );
}

const error = new Error("division by zero");
logger.error(`${error}`);

ejecuto y obtengo el siguiente resultado en el archivo error.log

MYSERVICE - 2021-09-18T04:47:08.810Z - ERROR - Error: division by zero

en el archivo application.log

MYSERVICE - 2021-09-18T04:47:08.810Z - ERROR - Error: division by zero

y en el servicio que está escuchando las peticiones que llegan desde el transporte del HTTP

{
  message: 'Error: division by zero',
  level: 'error',
  label: 'MYSERVICE',
  timestamp: '2021-09-18T04:50:26.551Z'
}

en el código anterior se puede destacar la creación del propio formato para escribir los logs como se aprecia en el siguiente segmento

const formatLog = printf(({ level, message, label, timestamp, stack }) => {
  if (stack) {
    message = message + " - " + stack;
  }

  return `${label} - ${timestamp} - ${level.toUpperCase()} - ${message}`;
});

utilizando la función printf() la cual permite llamarse desde winston para recibir los parámetros que se envían en cada llamada al log estos parámetros se definen en el siguiente segmento de código

const logger = createLogger({
  format: combine(
    label({ label: "MYSERVICE" }),
    errors({ stack: true }),
    timestamp(),
    formatLog
  ),
  transports: [
    new transports.File({ filename: "application.log" }),
    new transports.File({
      filename: "error.log",
      level: "error",
      format: combine(
        label({ label: "MYSERVICE" }),
        errors({ stack: true }),
        timestamp(),
        formatLog
      ),
    }),
  ],
});

se utiliza la función combine de winston para agregar más parámetros entre ellos se agrega un label que funcionara como nombre de app, la función errors para cuando se genere un error capture la linea de codigo donde ocurrió el error, la function timestamp() para capturar la fecha exacta del evento y formatLog es la función que le dará tratamiento a cada envío de registro de log la cual he personalizado, en la capa de transporte sigo manteniendo el formato json ya que es más fácil para el webservice recibir la información con esta estructura

Conclusiones

Los logs son solamente una parte y un pilar de un concepto llamado observabilidad que busca lograr tener buenas prácticas a la hora de hacer seguimiento al funcionamiento del software y el hardware, estos mensajes y fechas deben complementarse con correos y tickets de soporte que crea el cliente el cual da más contexto al posible error que está ocurriendo, en próximos post hablaremos de los otros dos pilares de la observabilidad conocidos como las métricas y los traces de los sistemas