10 KiB
ADR-004: Standardized Application-Wide Structured Logging
Date: 2025-12-12
Status: Accepted
Implemented: 2026-01-07
Context
Our application currently uses a logger service, but the implementation of logging varies significantly across different modules. The errorHandler middleware produces high-quality, structured JSON logs for errors, but logging within route handlers and service layers is often ad-hoc, using plain strings or inconsistent object structures.
This inconsistency leads to several problems:
Difficult Debugging: It is hard to trace a single user request through the system or correlate events related to a specific operation.
Ineffective Log Analysis: Inconsistent log formats make it difficult to effectively query, filter, and create dashboards in a log management system (like Datadog, Splunk, or the ELK stack).
Security Risks: There is no enforced standard for redacting sensitive information (like passwords or tokens) in logs outside of the errorHandler, increasing the risk of accidental data exposure.
Missing Context: Logs often lack crucial context, such as a unique request ID, the authenticated user's ID, or the source IP address, making them less useful for diagnosing issues.
Decision
We will adopt a standardized, application-wide structured logging policy. All log entries MUST be in JSON format and adhere to a consistent schema.
Request-Scoped Logger with Context: We will create a middleware that runs at the beginning of the request lifecycle. This middleware will:
- Generate a unique
request_idfor each incoming request. - Create a request-scoped logger instance (a "child logger") that automatically includes the
request_id,user_id(if authenticated), andip_addressin every log message it generates. - Attach this child logger to the
reqobject (e.g.,req.log).
Mandatory Use of Request-Scoped Logger: All route handlers and any service functions called by them MUST use the request-scoped logger (req.log) instead of the global logger instance. This ensures all logs for a given request are automatically correlated.
Standardized Log Schema: All log messages should follow a base schema. The logger configuration will be updated to enforce this.
Base Fields: level, timestamp, message, request_id, user_id, ip_address.
Error Fields: When logging an error, the log entry MUST include an error object with name, message, and stack.
Standardized Logging Practices:
INFO: Log key business events, such as User logged in or Flyer processed.
WARN: Log recoverable errors or unusual situations that do not break the request, such as Client Error: 404 on GET /api/non-existent-route or Retrying failed database connection.
ERROR: Log only unhandled or server-side errors that cause a request to fail (typically handled by the errorHandler). Avoid logging expected client errors (like 4xx) at this level.
DEBUG: Log detailed diagnostic information useful during development, such as function entry/exit points or variable states.
Example Usage
// In a new middleware file: logger.middleware.ts
import { logger } from '../services/logger.server';
import { randomUUID } from 'crypto';
export const requestLogger = (req, res, next) => {
const requestId = randomUUID();
// Create a child logger with context for this request
req.log = logger.child({
request_id: requestId,
user_id: req.user?.user_id, // Assumes user is attached by auth middleware
ip_address: req.ip,
});
next();
};
// In server/app setup:
// app.use(requestLogger); // Add this early in the middleware chain
// In a route handler:
router.get('/:id', async (req, res, next) => {
// Use the request-scoped logger
req.log.info({ flyerId: req.params.id }, 'Fetching flyer by ID');
try {
// ... business logic ...
res.json(flyer);
} catch (error) {
// The error itself will be logged with full context by the errorHandler
next(error);
}
});
Consequences
Positive
Enhanced Observability: Every log line from a single request can be instantly grouped and analyzed, dramatically speeding up debugging.
Improved Security: Centralizing the addition of context (like user_id) reduces the chance of developers manually logging sensitive data.
Scalable Log Management: Consistent JSON logs are easily ingested and indexed by any modern log aggregation tool.
Clearer Code: Removes the need to manually pass contextual information (like user ID) down to service functions just for logging purposes.
Negative
Refactoring Effort: Requires adding the requestLogger middleware and refactoring all routes and services to use req.log instead of the global logger.
Slight Performance Overhead: Creating a child logger for every request adds a minor performance cost, though this is negligible for most modern logging libraries.
Implementation Details
Logger Configuration
Located in src/services/logger.server.ts:
import pino from 'pino';
const isProduction = process.env.NODE_ENV === 'production';
const isTest = process.env.NODE_ENV === 'test';
export const logger = pino({
level: isProduction ? 'info' : 'debug',
transport:
isProduction || isTest
? undefined
: {
target: 'pino-pretty',
options: {
colorize: true,
translateTime: 'SYS:standard',
ignore: 'pid,hostname',
},
},
redact: {
paths: [
'req.headers.authorization',
'req.headers.cookie',
'*.body.password',
'*.body.newPassword',
'*.body.currentPassword',
'*.body.confirmPassword',
'*.body.refreshToken',
'*.body.token',
],
censor: '[REDACTED]',
},
});
Request Logger Middleware
Located in server.ts:
const requestLogger = (req: Request, res: Response, next: NextFunction) => {
const requestId = randomUUID();
const user = req.user as UserProfile | undefined;
const start = process.hrtime();
// Create request-scoped logger
req.log = logger.child({
request_id: requestId,
user_id: user?.user.user_id,
ip_address: req.ip,
});
req.log.debug({ method: req.method, originalUrl: req.originalUrl }, 'INCOMING');
res.on('finish', () => {
const duration = getDurationInMilliseconds(start);
const { statusCode, statusMessage } = res;
const logDetails = {
user_id: (req.user as UserProfile | undefined)?.user.user_id,
method: req.method,
originalUrl: req.originalUrl,
statusCode,
statusMessage,
duration: duration.toFixed(2),
};
// Include request details for failed requests (for debugging)
if (statusCode >= 400) {
logDetails.req = { headers: req.headers, body: req.body };
}
if (statusCode >= 500) req.log.error(logDetails, 'Request completed with server error');
else if (statusCode >= 400) req.log.warn(logDetails, 'Request completed with client error');
else req.log.info(logDetails, 'Request completed successfully');
});
next();
};
app.use(requestLogger);
TypeScript Support
The req.log property is typed via declaration merging in src/types/express.d.ts:
import { Logger } from 'pino';
declare global {
namespace Express {
export interface Request {
log: Logger;
}
}
}
Automatic Sensitive Data Redaction
The Pino logger automatically redacts sensitive fields:
// Before redaction
{
"body": {
"email": "user@example.com",
"password": "secret123",
"newPassword": "newsecret456"
}
}
// After redaction (in logs)
{
"body": {
"email": "user@example.com",
"password": "[REDACTED]",
"newPassword": "[REDACTED]"
}
}
Log Levels by Scenario
| Level | HTTP Status | Scenario |
|---|---|---|
| DEBUG | Any | Request incoming, internal state, development info |
| INFO | 2xx | Successful requests, business events |
| WARN | 4xx | Client errors, validation failures, not found |
| ERROR | 5xx | Server errors, unhandled exceptions |
Service Layer Logging
Services accept the request-scoped logger as an optional parameter:
export async function registerUser(email: string, password: string, reqLog?: Logger) {
const log = reqLog || logger; // Fall back to global logger
log.info({ email }, 'Registering new user');
// ... implementation
log.debug({ userId: user.user_id }, 'User created successfully');
return user;
}
// In route handler
router.post('/register', async (req, res, next) => {
await authService.registerUser(req.body.email, req.body.password, req.log);
});
Log Output Format
Development (pino-pretty):
[2026-01-09 12:34:56.789] INFO (request_id=abc123): Request completed successfully
method: "GET"
originalUrl: "/api/flyers"
statusCode: 200
duration: "45.23"
Production (JSON):
{
"level": 30,
"time": 1704812096789,
"request_id": "abc123",
"user_id": "user_456",
"ip_address": "192.168.1.1",
"method": "GET",
"originalUrl": "/api/flyers",
"statusCode": 200,
"duration": "45.23",
"msg": "Request completed successfully"
}
Routes Using req.log
All route files have been migrated to use the request-scoped logger:
src/routes/auth.routes.tssrc/routes/user.routes.tssrc/routes/flyer.routes.tssrc/routes/ai.routes.tssrc/routes/admin.routes.tssrc/routes/budget.routes.tssrc/routes/recipe.routes.tssrc/routes/gamification.routes.tssrc/routes/personalization.routes.tssrc/routes/stats.routes.tssrc/routes/health.routes.tssrc/routes/system.routes.ts
Key Files
src/services/logger.server.ts- Pino logger configurationsrc/services/logger.client.ts- Client-side logger (for frontend)src/types/express.d.ts- TypeScript declaration forreq.logserver.ts- Request logger middleware