Request Logging with Morgan and Audit Trails

Logging is not an afterthought — it is infrastructure. Without good request logs, debugging a production issue means flying blind. Without an audit trail, a security incident is impossible to investigate. Morgan is the standard HTTP request logger for Express, providing instant visibility into every request your API receives. Winston is the general-purpose structured logger for application-level events — errors, warnings, authentication events, and business-critical operations. Together they give you complete observability: Morgan for the HTTP layer, Winston for the application layer. This lesson builds a complete, production-ready logging system for the MEAN Stack API.

Morgan Log Tokens #

Morgan Built-in Formats #

Winston Log Levels #

Complete Logging Setup #

// npm install morgan winston

const morgan  = require('morgan');
const winston = require('winston');
const { combine, timestamp, json, colorize, printf } = winston.format;

// ── Winston logger ────────────────────────────────────────────────────────
const logger = winston.createLogger({
    level: process.env.LOG_LEVEL || (process.env.NODE_ENV === 'production' ? 'info' : 'debug'),
    format: combine(
        timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
        json()   // structured JSON output
    ),
    transports: [
        // Console — always enabled
        new winston.transports.Console({
            format: process.env.NODE_ENV === 'production'
                ? combine(timestamp(), json())
                : combine(
                    colorize(),
                    printf(({ level, message, timestamp, ...meta }) => {
                        const metaStr = Object.keys(meta).length ? ' ' + JSON.stringify(meta) : '';
                        return `${timestamp} [${level}]: ${message}${metaStr}`;
                    })
                  ),
        }),
        // Error log file — production
        ...(process.env.NODE_ENV === 'production' ? [
            new winston.transports.File({ filename: 'logs/error.log',   level: 'error' }),
            new winston.transports.File({ filename: 'logs/combined.log' }),
        ] : []),
    ],
    exitOnError: false,
});

module.exports = logger;

// ── Morgan — HTTP request logging ─────────────────────────────────────────
function createMorganMiddleware() {
    // Custom token: log authenticated user ID
    morgan.token('user-id', req => req.user?.id || 'anonymous');

    // Custom token: request ID (set by requestId middleware)
    morgan.token('request-id', req => req.id || '-');

    // Custom JSON format — feeds into Winston
    const format = JSON.stringify({
        requestId:    ':request-id',
        method:       ':method',
        url:          ':url',
        status:       ':status',
        responseTime: ':response-time ms',
        contentLength:':res[content-length]',
        userId:       ':user-id',
        ip:           ':remote-addr',
        userAgent:    ':user-agent',
    });

    return morgan(format, {
        stream: {
            write: (message) => {
                const log = JSON.parse(message.trim());
                const level = parseInt(log.status, 10) >= 400 ? 'warn' : 'http';
                logger.log(level, 'HTTP Request', log);
            },
        },
        skip: (req) => req.path === '/api/health',  // skip health check spam
    });
}

// ── Request ID middleware ─────────────────────────────────────────────────
const { v4: uuidv4 } = require('uuid');

function requestIdMiddleware(req, res, next) {
    req.id = req.headers['x-request-id'] || uuidv4();
    res.set('X-Request-ID', req.id);   // echo back to client for debugging
    next();
}

// ── app.js integration ────────────────────────────────────────────────────
app.use(requestIdMiddleware);            // 1. assign request ID
app.use(createMorganMiddleware());       // 2. log all HTTP requests
// ... other middleware and routes

Audit Trail Logger #

// utils/audit.js — structured audit logging for security-relevant events
const logger = require('./logger');

const AuditEvent = {
    USER_REGISTER:       'USER_REGISTER',
    USER_LOGIN:          'USER_LOGIN',
    USER_LOGIN_FAILED:   'USER_LOGIN_FAILED',
    USER_LOGOUT:         'USER_LOGOUT',
    PASSWORD_CHANGE:     'PASSWORD_CHANGE',
    PASSWORD_RESET_REQ:  'PASSWORD_RESET_REQUEST',
    TASK_CREATE:         'TASK_CREATE',
    TASK_DELETE:         'TASK_DELETE',
    ADMIN_ACCESS:        'ADMIN_ACCESS',
    RATE_LIMIT_HIT:      'RATE_LIMIT_HIT',
};

function audit(event, details, req) {
    logger.info('AUDIT', {
        event,
        userId:    req?.user?.id || null,
        ip:        req?.ip,
        requestId: req?.id,
        userAgent: req?.get('User-Agent'),
        timestamp: new Date().toISOString(),
        ...details,
    });
}

module.exports = { audit, AuditEvent };

// ── Usage in controllers ───────────────────────────────────────────────────
const { audit, AuditEvent } = require('../utils/audit');

exports.login = asyncHandler(async (req, res) => {
    const { email, password } = req.body;

    try {
        const user = await AuthService.validateCredentials(email, password);

        audit(AuditEvent.USER_LOGIN, { userId: user._id, email }, req);

        const tokens = AuthService.generateTokens(user);
        setRefreshTokenCookie(res, tokens.refreshToken);
        res.json({ success: true, data: { accessToken: tokens.accessToken } });

    } catch (err) {
        audit(AuditEvent.USER_LOGIN_FAILED, { email, reason: err.message }, req);
        throw err;
    }
});

exports.deleteTask = asyncHandler(async (req, res) => {
    const task = await Task.findOneAndDelete({ _id: req.params.id, userId: req.user.id });
    if (!task) throw new NotFoundError('Task not found');

    audit(AuditEvent.TASK_DELETE, { taskId: task._id, taskTitle: task.title }, req);
    res.status(204).end();
});

How It Works #

Step 1 — Morgan Logs Every HTTP Request After the Response Is Sent #

Morgan attaches a listener to the response’s finish event. This means the log entry is written after the response is sent to the client, and therefore includes the actual response status code, response time, and content length — data that is not available before the handler runs. This makes Morgan logs complete and accurate, capturing both request and response information in a single line.

Step 2 — Piping Morgan into Winston Creates a Unified Log Stream #

Morgan’s stream option accepts any object with a write(message) method. By passing a custom stream that calls logger.http(), every Morgan log line flows into Winston. Winston then routes it to all configured transports — console, files, external services. This means your HTTP logs and application logs appear together, in timestamp order, in the same place.

Step 3 — Request IDs Enable Distributed Tracing #

Assigning a UUID to each incoming request and attaching it to req.id creates a correlation ID for the entire request lifecycle. Every log statement — from Morgan’s HTTP log, to the authentication middleware log, to the database query log, to the error handler — includes requestId. When debugging a reported issue, filtering logs by request ID shows the complete story of a single request in chronological order.

Step 4 — Audit Logs Record Security-Relevant Events #

HTTP request logs tell you “a POST to /auth/login happened.” Audit logs tell you “user alice@example.com logged in successfully from IP 1.2.3.4 at 14:30 UTC.” Audit logs capture the business meaning of operations — who did what, when, from where. They are essential for security incident investigations, compliance requirements (GDPR, SOC 2), and detecting anomalous behaviour like one account logging in from 50 different countries.

Step 5 — Structured JSON Enables Log Query and Alerting #

A log management system (Datadog, CloudWatch, Grafana Loki) ingests structured JSON logs and indexes every field. You can query event="USER_LOGIN_FAILED" AND ip="1.2.3.4" to see failed logins from a suspicious IP, or level="error" AND status=500 to find server errors, or responseTime > 2000 to find slow requests. Setting up alerts on these queries gives you automatic notification when something goes wrong in production.

Real-World Example: Log Output in Production #

// Structured log output — easy to parse and query

// HTTP request log (from Morgan via Winston)
{"level":"http","message":"HTTP Request","requestId":"a1b2c3d4-...","method":"POST","url":"/api/v1/auth/login","status":"200","responseTime":"143 ms","userId":"64a1f...","ip":"203.0.113.42","timestamp":"2025-07-15T14:30:22.451Z"}

// Audit event log
{"level":"info","message":"AUDIT","event":"USER_LOGIN","userId":"64a1f...","ip":"203.0.113.42","requestId":"a1b2c3d4-...","email":"alice@example.com","timestamp":"2025-07-15T14:30:22.448Z"}

// Error log
{"level":"error","message":"Task not found","requestId":"b5c6d7e8-...","path":"/api/v1/tasks/invalid-id","userId":"64a1f...","stack":"NotFoundError: Task not found\n    at ...","timestamp":"2025-07-15T14:31:05.123Z"}

// Failed login audit
{"level":"info","message":"AUDIT","event":"USER_LOGIN_FAILED","ip":"192.168.1.1","requestId":"c9d0e1f2-...","email":"admin@example.com","reason":"Invalid password","timestamp":"2025-07-15T14:32:00.000Z"}

Common Mistakes #

Mistake 1 — Logging passwords or tokens in error messages #

❌ Wrong — password appears in logs:

logger.debug('Login attempt', { email, password });  // password in plain text in logs!
logger.error('Auth failed', { body: req.body });       // req.body contains password

✅ Correct — explicitly exclude sensitive fields:

logger.debug('Login attempt', { email });              // log email only
logger.error('Auth failed', { email, ip: req.ip });    // never log passwords

Mistake 2 — Using console.log() instead of structured logger in production #

❌ Wrong — unstructured strings are hard to query:

console.log(`User ${userId} logged in from ${ip}`);  // free-form string — unqueryable
console.error('Database error:', err);               // no context, no level, no timestamp

✅ Correct — use structured logger for all application events:

logger.info('User login', { userId, ip, requestId: req.id });
logger.error('Database error', { message: err.message, stack: err.stack, requestId: req.id });

Mistake 3 — Logging health check endpoints — polluting logs with noise #

❌ Wrong — /health logged every 30 seconds by monitoring systems:

app.use(morgan('dev'));  // logs EVERYTHING including health checks every 30s
// Logs: GET /api/health 200 1ms — repeated 2880 times per day!

✅ Correct — skip health checks and other high-frequency noise:

app.use(morgan('dev', {
    skip: (req) => req.path.startsWith('/api/health') || req.path.startsWith('/api/metrics'),
}));

Quick Reference #