Structured logging para servicios Node.js en producción
Implementa structured logging en Node.js: entradas analizables y buscables, con IDs de correlación, severidades coherentes y propagación de contexto.
¿Por qué structured logging?
Los logs no estructurados —console.log("User logged in:", userId)— son legibles para humanos, pero hostiles para las máquinas. Cuando manejas miles de solicitudes por segundo en decenas de servicios, necesitas filtrar, agregar y generar alertas sobre los datos de log de forma programática. El structured logging genera objetos JSON con campos consistentes, lo que hace que cada entrada de log sea buscable y analizable.
La base del logger
Usa una biblioteca de logging que genere JSON con campos consistentes. Pino es el estándar para Node.js: rápido, estructurado y diseñado para producción.
import pino from "pino";
const logger = pino({
level: process.env.LOG_LEVEL ?? "info",
formatters: {
level(label) {
return { level: label };
},
},
timestamp: pino.stdTimeFunctions.isoTime,
base: {
service: process.env.SERVICE_NAME ?? "api-server",
environment: process.env.NODE_ENV ?? "development",
version: process.env.APP_VERSION ?? "unknown",
},
});
export { logger };// ❌ Unstructured — impossible to search or filter
console.log("Payment processed for user " + userId + " amount: $" + amount);
console.log("ERROR: Payment failed", error.message);
// ✅ Structured — every field is searchable
logger.info(
{ userId, amount, currency: "USD", paymentId },
"Payment processed successfully"
);
logger.error(
{ userId, amount, paymentId, errorCode: error.code, err: error },
"Payment processing failed"
);IDs de correlación entre solicitudes
Cada solicitud entrante recibe un ID de correlación único que se propaga a todas las llamadas posteriores. Al depurar un problema, filtras los logs por ese ID para ver el recorrido completo de la solicitud a través de los servicios.
import { randomUUID } from "node:crypto";
import { AsyncLocalStorage } from "node:async_hooks";
interface RequestContext {
correlationId: string;
userId?: string;
requestPath: string;
requestMethod: string;
}
const contextStorage = new AsyncLocalStorage<RequestContext>();
// Middleware: set correlation ID for every request
function correlationMiddleware(
req: Request,
res: Response,
next: NextFunction
): void {
const correlationId =
(req.headers["x-correlation-id"] as string) ?? randomUUID();
res.setHeader("x-correlation-id", correlationId);
const context: RequestContext = {
correlationId,
requestPath: req.path,
requestMethod: req.method,
};
contextStorage.run(context, () => next());
}
// Context-aware logger that automatically includes correlation ID
function getLogger(): pino.Logger {
const context = contextStorage.getStore();
if (context) {
return logger.child({
correlationId: context.correlationId,
userId: context.userId,
path: context.requestPath,
});
}
return logger;
}
// Usage anywhere in the request lifecycle
function processOrder(order: Order): void {
const log = getLogger();
log.info({ orderId: order.id, items: order.items.length }, "Processing order");
// Log automatically includes correlationId, userId, path
}Niveles de log y cuándo usarlos
Mantener niveles de severidad consistentes en todo el equipo evita tanto el ruido en los logs como la pérdida de información crítica.
interface LogLevelGuidance {
level: string;
when: string;
example: string;
}
const guidelines: LogLevelGuidance[] = [
{
level: "fatal",
when: "Application cannot continue — process will exit",
example: "Database connection failed after all retries on startup",
},
{
level: "error",
when: "Operation failed — requires investigation but process continues",
example: "Payment processing failed for a specific transaction",
},
{
level: "warn",
when: "Unexpected condition that may indicate a problem",
example: "Cache miss rate exceeding threshold, falling back to database",
},
{
level: "info",
when: "Significant business events and operational milestones",
example: "Order completed, user registered, deployment started",
},
{
level: "debug",
when: "Detailed technical information for troubleshooting",
example: "SQL query executed, cache key checked, retry attempt 2 of 5",
},
{
level: "trace",
when: "Very verbose — function entry/exit, data payloads",
example: "Request body parsed, response serialized, middleware chain",
},
];Enmascaramiento de datos sensibles
Los logs de producción nunca deben contener contraseñas, tokens, números de tarjetas de crédito ni PII. Enmascara estos datos a nivel del logger para que los desarrolladores no tengan que acordarse de hacerlo.
const sensitiveKeys = new Set([
"password",
"token",
"authorization",
"cookie",
"creditCard",
"ssn",
"secret",
"apiKey",
]);
const redactedLogger = pino({
level: "info",
redact: {
paths: [
"password",
"*.password",
"token",
"*.token",
"headers.authorization",
"headers.cookie",
"body.creditCard",
"body.ssn",
],
censor: "[REDACTED]",
},
});
// Automatic redaction — developers don't need to remember
redactedLogger.info(
{
userId: "u_123",
headers: { authorization: "Bearer eyJ..." }, // → [REDACTED]
body: { email: "user@example.com", password: "secret123" }, // password → [REDACTED]
},
"Request received"
);Logging de solicitudes y respuestas
Registra cada solicitud y respuesta junto con su tiempo de ejecución. Este es, con diferencia, el log más útil para depurar problemas en producción.
function requestLogMiddleware(
req: Request,
res: Response,
next: NextFunction
): void {
const start = performance.now();
const log = getLogger();
// Log request
log.info(
{
event: "request_received",
method: req.method,
path: req.path,
query: req.query,
userAgent: req.headers["user-agent"],
contentLength: req.headers["content-length"],
},
"Incoming request"
);
// Capture response
const originalEnd = res.end.bind(res);
res.end = function (...args: Parameters<typeof res.end>) {
const duration = Math.round(performance.now() - start);
log.info(
{
event: "request_completed",
method: req.method,
path: req.path,
statusCode: res.statusCode,
durationMs: duration,
contentLength: res.getHeader("content-length"),
},
"Request completed"
);
// Warn on slow requests
if (duration > 1000) {
log.warn(
{ durationMs: duration, path: req.path },
"Slow request detected"
);
}
return originalEnd(...args);
};
next();
}Logging de errores con contexto
Registra los errores con contexto completo: stack traces, datos de entrada y la operación que falló. Esto elimina el ir y venir de "¿qué estaba haciendo el usuario cuando ocurrió esto?".
function logError(
error: Error,
context: Record<string, unknown>
): void {
const log = getLogger();
log.error(
{
err: {
message: error.message,
name: error.name,
stack: error.stack,
...(error instanceof AppError && {
code: error.code,
statusCode: error.statusCode,
}),
},
...context,
},
`Operation failed: ${error.message}`
);
}
// Usage
try {
await processPayment(order);
} catch (error) {
logError(error as Error, {
operation: "processPayment",
orderId: order.id,
userId: order.userId,
amount: order.total,
});
throw error;
}Puntos clave
El structured logging genera objetos JSON con campos consistentes, lo que hace que cada entrada de log sea buscable y filtrable. Usa una biblioteca como Pino, que gestiona de forma eficiente el formato JSON, los niveles de log y los child loggers. Propaga los IDs de correlación en cada solicitud usando AsyncLocalStorage para poder rastrear una sola solicitud a través de todos los servicios.
Enmascara los datos sensibles a nivel de configuración del logger; nunca dependas de que los desarrolladores recuerden omitir contraseñas o tokens. Registra cada solicitud y respuesta junto con su tiempo de ejecución, ya que son los datos de depuración más valiosos. Usa los niveles de log de forma consistente en todo el equipo: error para fallos que requieren investigación, warn para anomalías, info para eventos de negocio. La inversión en structured logging se recupera la primera vez que depuras un incidente de producción en minutos en lugar de horas.
