All checks were successful
Deploy to Test Environment / deploy-to-test (push) Successful in 49m39s
266 lines
8.9 KiB
Markdown
266 lines
8.9 KiB
Markdown
# ADR-027: Standardized Application-Wide Structured Logging
|
|
|
|
**Date**: 2026-02-10
|
|
|
|
**Status**: Accepted
|
|
|
|
**Source**: Imported from flyer-crawler project (ADR-004)
|
|
|
|
**Related**: [ADR-017](ADR-017-structured-logging-with-pino.md), [ADR-028](ADR-028-client-side-structured-logging.md), [ADR-029](ADR-029-error-tracking-with-bugsink.md)
|
|
|
|
## Context
|
|
|
|
While ADR-017 established Pino as our logging framework, this ADR extends that foundation with application-wide standards for request tracing, context propagation, and structured log formats.
|
|
|
|
The implementation of logging can vary significantly across different modules. The error handler middleware may produce high-quality, structured JSON logs for errors, but logging within route handlers and service layers can become 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 log management systems (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 error handler, 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.
|
|
|
|
### 1. 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_id` for each incoming request
|
|
- Create a request-scoped logger instance (a "child logger") that automatically includes the `request_id`, `user_id` (if authenticated), and `ip_address` in every log message it generates
|
|
- Attach this child logger to the `req` object (e.g., `req.log`)
|
|
|
|
### 2. 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.
|
|
|
|
### 3. 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`.
|
|
|
|
### 4. Standardized Logging Practices
|
|
|
|
| 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 |
|
|
|
|
## Implementation Details
|
|
|
|
### Logger Configuration
|
|
|
|
Located in `src/services/logger.server.ts`:
|
|
|
|
```typescript
|
|
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`:
|
|
|
|
```typescript
|
|
import { randomUUID } from 'crypto';
|
|
import type { Request, Response, NextFunction } from 'express';
|
|
import { logger } from './services/logger.server';
|
|
|
|
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`:
|
|
|
|
```typescript
|
|
import { Logger } from 'pino';
|
|
|
|
declare global {
|
|
namespace Express {
|
|
export interface Request {
|
|
log: Logger;
|
|
}
|
|
}
|
|
}
|
|
```
|
|
|
|
### Automatic Sensitive Data Redaction
|
|
|
|
The Pino logger automatically redacts sensitive fields:
|
|
|
|
```json
|
|
// Before redaction
|
|
{
|
|
"body": {
|
|
"email": "user@example.com",
|
|
"password": "secret123",
|
|
"newPassword": "newsecret456"
|
|
}
|
|
}
|
|
|
|
// After redaction (in logs)
|
|
{
|
|
"body": {
|
|
"email": "user@example.com",
|
|
"password": "[REDACTED]",
|
|
"newPassword": "[REDACTED]"
|
|
}
|
|
}
|
|
```
|
|
|
|
### Service Layer Logging
|
|
|
|
Services accept the request-scoped logger as an optional parameter:
|
|
|
|
```typescript
|
|
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):
|
|
|
|
```text
|
|
[2026-01-09 12:34:56.789] INFO (request_id=abc123): Request completed successfully
|
|
method: "GET"
|
|
originalUrl: "/api/users"
|
|
statusCode: 200
|
|
duration: "45.23"
|
|
```
|
|
|
|
**Production** (JSON):
|
|
|
|
```json
|
|
{
|
|
"level": 30,
|
|
"time": 1704812096789,
|
|
"request_id": "abc123",
|
|
"user_id": "user_456",
|
|
"ip_address": "192.168.1.1",
|
|
"method": "GET",
|
|
"originalUrl": "/api/users",
|
|
"statusCode": 200,
|
|
"duration": "45.23",
|
|
"msg": "Request completed successfully"
|
|
}
|
|
```
|
|
|
|
## 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
|
|
|
|
## Key Files
|
|
|
|
- `src/services/logger.server.ts` - Pino logger configuration
|
|
- `src/services/logger.client.ts` - Client-side logger (for frontend)
|
|
- `src/types/express.d.ts` - TypeScript declaration for `req.log`
|
|
- `server.ts` - Request logger middleware
|
|
|
|
## References
|
|
|
|
- [ADR-017: Structured Logging with Pino](ADR-017-structured-logging-with-pino.md)
|
|
- [ADR-001: Standardized Error Handling](ADR-001-standardized-error-handling.md) - Error handler uses `req.log` for error logging
|
|
- [ADR-028: Client-Side Structured Logging](ADR-028-client-side-structured-logging.md) - Client-side logging strategy
|
|
- [Pino Documentation](https://getpino.io/#/)
|