Relación de Logs y Traces

Cuando instrumentas una aplicación con OpenTelemetry, el contexto del trace (trace context) se propaga automáticamente a través de la aplicación. Esto significa que tienes una "línea de tiempo" de las operaciones que ocurren.

• Cada petición genera un trace que posee un identificador único.
• Cuando se genera un log, pueden correlacionarse automáticamente con el trace a través de ese identificador.

La belleza de este sistema es que cuando necesitas depurar un problema, puedes ver:

• El flujo completo de la petición (trace)
• Todos los logs relacionados con esa ejecución específica
• Las métricas asociadas

Es como tener una "historia completa" de cada petición, donde puedes ver no solo el camino que recorrió, sino también todos los detalles de lo que ocurrió en cada etapa.

En el proyecto, si quieres ver esta modificación, estará en la rama logs.

En todo-service.ts tenemos esto.

app.get('/todos', async (req, res) => {
    requestCounter.add(1);
    const user = await axios.get('http://auth:8080/auth');
    const todoKeys = await redis.keys('todo:*');
    const todos: any[] = [];

    for (const key of todoKeys) {
        const todoItem = await redis.get(key);
        if (todoItem) {
            todos.push(JSON.parse(todoItem));
        }
    }

    if(req.query['slow']){
        await sleep(1000);
    }

    if(req.query['fail']){ // Vamos a hablar de este if
        // Y aquí estamos registrando un error en caso de que pasemos ?fail=1
        console.error('Really Bad error!');
        res.sendStatus(500);
    }

    res.json({ todos, user: user.data });
});

Este log está yendo a la consola, pero sería muy bueno si pudiéramos registrarlo usando el contexto del trace.

Vamos a cambiar ese if por esto:

// Vamos a usar el SDK de OpenTelemetry
import { api } from '@opentelemetry/sdk-node';
// Código...

app.get('/todos', async (req, res) => {
    // Código...

    if(req.query['fail']){
        try{
            // Simulación de un error - lanza una excepción intencionadamente
            throw new Error('Really Bad error!')
        } catch (e: any) {
            // Obtiene el span (intervalo) actual del contexto de trace
            const activeSpan = api.trace.getSpan(api.context.active());
            // Registra la excepción en el span actual, permitiendo que aparezca en el trace
            // Si activeSpan existe, entonces llama al método recordException
            activeSpan?.recordException(e) // Esta es la línea que nos interesa
            // Registra el error junto con información importante del trace en la consola para que podamos verlo
            console.error('Really Bad error!', {
                spanId: activeSpan?.spanContext()?.spanId,     // ID único de este span específico
                traceId: activeSpan?.spanContext()?.traceId,   // ID único de la transacción completa
                traceFlag: activeSpan?.spanContext()?.traceFlags, // Flags del trace (ej: muestreo)
            });
            // Retorna status 500 (error interno del servidor)
            res.sendStatus(500);
            return
        }
        // Código...
    }
});
// Código...

Haciendo la petición y comprobando lo que tenemos.

curl http://localhost:8081/todos?fail=1

En el log del compose tenemos este log en la consola mostrando nuestro spanId, traceId y traceFlag

todo-1        | Todo service is running on port 8080
todo-1        | prometheus scrape endpoint: http://localhost:9464/metrics
todo-1        | Really Bad error! {
todo-1        |   spanId: '7f830392097970ee',
todo-1        |   traceId: '66c8f22097c5adf08452acea0e8cf23a',
todo-1        |   traceFlag: 1
todo-1        | }

Puedes (y muchas veces es recomendable) añadir logs en varios puntos del trace, no solo en excepciones como hicimos anteriormente.

Puedes usar el span para registrar eventos importantes durante toda la ejecución del código. Algunos ejemplos a continuación.

Logs de eventos normales

activeSpan?.addEvent('Iniciando búsqueda en la base de datos');
activeSpan?.addEvent('Datos encontrados', { attributes: { count: 5 } });

Logs de excepciones (como hicimos anteriormente)

activeSpan?.recordException(error);

Logs de estado/progreso

activeSpan?.addEvent('Cache hit');
activeSpan?.addEvent('Procesamiento 50% completo');

Logs con contexto de negocio

activeSpan?.addEvent('Pedido procesado', {
    attributes: {
        orderId: '123',
        status: 'approved'
    }
});

La idea es que puedes usar logs para contar la "historia" completa de la ejecución, no solo cuando algo sale mal. Esto ayuda mucho en la depuración y en la comprensión del comportamiento del sistema en producción.

Es en este momento cuando cambiamos la forma en que usamos los logs en aplicaciones distribuidas.

¿Es necesario hacer esto manualmente? No. Si la biblioteca para registrar logs tiene una instrumentación para OpenTelemetry, esto se hará automáticamente. En el caso de NodeJS, nuestro proyecto de ejemplo, tenemos una llamada Winston que es muy popular, flexible y con transporte de varios formatos. Pero aún tenemos otras como Pino, Bunyan, Morgan, etc., cada una con enfoque y mejor para cosas diferentes.

Si no quieres usar una biblioteca, basta con crear una función de log y simplemente usarla.