Logging

The IAM service uses Pino for all logging. There are two distinct logger instances: an application logger for general-purpose messages (auth decisions, token operations, anomaly events), and an HTTP logger for per-request lifecycle tracking (method, status, latency, IP). Both write to files inside the auth-logs/ directory, both redact sensitive fields before anything reaches disk, and both attach structured metadata so every log entry carries machine-readable context.

The application logger is a singleton. It is created once at startup and shared across the entire process through getLogger(). Every module that needs to log creates a child logger from that singleton, tagging entries with a service and branch field so you can filter by domain (tokens, OAuth, MFA, anomalies) without splitting into separate files.

The HTTP logger is an Express middleware powered by pino-http. It wraps each request in a log entry that records timing, status, client IP, user agent, and the full URL. It assigns a unique request ID to every inbound request and propagates it in the X-Request-Id response header.

Log Directory

All log files live under a single directory. The service resolves the path in this order:

1. If the LOG_DIR environment variable is set, use that value.
2. Otherwise, default to ${PROJECT_ROOT}/auth-logs.

The directory is created automatically at startup if it does not exist. Four files are written:

The first three files are fed by the application logger through Pino's transport pipeline. Each transport targets a different file with a different minimum level, so the same application log entry can appear in info.log, warn.log, and errors.log simultaneously if its level qualifies. The HTTP logger writes exclusively to http.log through its own separate Pino instance.

Application Logger

Singleton Pattern

The application logger is created by getLogger(). On the first call, it reads the logLevel field from the service configuration, builds a Pino instance with three file transports, and caches it. Every subsequent call returns the same instance.

import { getLogger } from '@riavzon/auth'

const log = getLogger()
log.info({ userId: 42 }, 'Token generated')

Configuration

The logLevel field in the service configuration controls the minimum severity for the application logger. It accepts any standard Pino level.

Transports

The logger uses pino.transport() with three pino/file targets:

Each target is a Pino file transport that appends newline-delimited JSON. The targets run in worker threads managed by Pino's transport system, so log writes do not block the main event loop.

Timestamps

Every log entry carries an ISO 8601 timestamp generated by pino.stdTimeFunctions.isoTime. This produces values like "2025-01-15T14:30:00.000Z" rather than Unix epoch milliseconds.

Uptime Mixin

A mixin function injects process.uptime() into every log entry. Both the application logger and the HTTP logger include this field. It records how many seconds the Node.js process has been running at the moment the log line was emitted. It helps correlate events to process lifecycle phases (startup, steady state, post-restart).

{
  "level": 30,
  "time": "2025-01-15T14:30:00.000Z",
  "uptime": 842.331,
  "msg": "Token generated"
}

Redaction

Both loggers aggressively redact sensitive data. Pino replaces the value of any matching path with [SECRET] before the entry reaches the transport layer - the raw value never appears in the log file.

Application Logger Redaction Paths

HTTP Logger Redaction Paths

Child Loggers

Modules and controllers do not use the root logger directly. Instead, each creates a child logger that inherits all transports, redaction, and formatting from the parent but adds contextual fields. This pattern makes it possible to filter logs by service domain, branch, or request type without modifying the log destination.

Creating a Child Logger

const log = getLogger().child({ service: 'auth', branch: 'access token' })

log.info('New access token issued')
// Output includes: { "service": "auth", "branch": "access token", ... }

Naming Conventions

The service field identifies the subsystem. The branch field narrows it to a specific operation. Some branches add extra fields for request-level tracing:

HTTP Logger

The HTTP logger is an Express middleware that wraps every inbound request in a structured log entry. It is the first middleware mounted in the Express chain, so it captures the full lifecycle of every request including those rejected by later middleware.

Middleware Position

httpLogger → helmet → headers → validateIp → hmacAuth? → json → cookieParser → routes

Because httpLogger runs before everything else, every request gets a log entry regardless of whether it passes authentication, HMAC validation, or body parsing.

Request ID

The HTTP logger generates a unique identifier for every request and exposes it in the response:

Log Levels by Status Code

The HTTP logger assigns a severity level to each request based on the response status code:

Asset Filtering

Static asset requests are excluded entirely from HTTP logging. The logger checks the request URL against a regex of file extensions and skips the log entry if any match:

.css, .js, .png, .jpg, .jpeg, .svg, .ico, .woff, .woff2, .ttf, .map, .webp, .json

This prevents CDN or browser cache-miss requests for static files from cluttering http.log with entries that carry no diagnostic value.

Custom Properties

Each HTTP log entry includes these additional fields beyond the standard pino-http output:

Custom Attribute Keys

The HTTP logger renames pino-http's default attribute keys to more descriptive names:

A typical http.log entry looks like this:

{
  "level": 30,
  "time": "2025-01-15T14:30:00.000Z",
  "requestId": "a1b2c3d4-e5f6-7890-abcd-ef1234567890",
  "httpRequest": { "method": "POST", "url": "/auth/user/refresh-session" },
  "httpResponse": { "statusCode": 201 },
  "latency": 23,
  "ip": "192.168.1.1",
  "userAgent": "Mozilla/5.0 ...",
  "FullUrl": "https://auth.example.com/auth/user/refresh-session",
  "msg": "POST /auth/user/refresh-session 201 23ms"
}

Custom Messages

The HTTP logger generates context-aware log messages depending on the response status:

The 404 message includes the Referer header to help trace where broken links originate. Error messages include the full stack trace so you can diagnose server errors directly from http.log without needing to correlate with errors.log.

Serializers

The HTTP logger uses pino-http's built-in req, res, and err serializers. These extract a safe subset of request and response data (method, url, headers for requests; statusCode for responses; message, type, stack for errors) while avoiding circular references and excessively large objects.

Accessing Logs

File System

# Real-time application errors
tail -f auth-logs/errors.log

# Real-time HTTP traffic
tail -f auth-logs/http.log

# Warnings and errors together
tail -f auth-logs/warn.log

# Everything (most verbose)
tail -f auth-logs/info.log

Docker Compose

When the IAM service runs inside Docker, the auth-logs/ directory is typically mounted as a volume. You can tail logs from the host:

docker compose logs -f auth

Or access the log files directly in the mounted volume:

tail -f ./auth-logs/errors.log

Filtering with jq

Since every log file contains newline-delimited JSON, you can use jq to filter entries:

# All MFA-related application logs
cat auth-logs/info.log | jq 'select(.branch == "mfa")'

# All HTTP 500 errors with latency > 100ms
cat auth-logs/http.log | jq 'select(.httpResponse.statusCode >= 500 and .latency > 100)'

# All requests from a specific IP
cat auth-logs/http.log | jq 'select(.ip == "203.0.113.42")'

# Trace a request by ID across both logs
export RID="a1b2c3d4-e5f6-7890-abcd-ef1234567890"
cat auth-logs/http.log | jq "select(.requestId == \"$RID\")"
cat auth-logs/info.log | jq "select(.requestId == \"$RID\")"

Summary