Structured logging for WebSocket connections #

A user reports that their live feed “keeps dropping”, and you open the logs to find out why. You find either nothing — because the WebSocket server logs only startup messages — or everything: one line per inbound and outbound frame, 40 million lines an hour, with the user’s session token in half of them and no way to tell which lines belong to the same connection. Neither lets you answer the only question that matters: what happened to this connection? WebSocket logging needs a different shape from HTTP request logging, because the unit of work is a connection that lives for hours, not a request that lasts milliseconds.

Root cause #

HTTP access logs work because one request produces one line containing everything: who, what, status, duration. A WebSocket has no single moment where all of that is known. The identity is known at the upgrade, the duration and close code only at the end, and the interesting events — auth refreshes, subscription changes, backpressure evictions — happen in between. Teams that reuse HTTP logging get one line at the upgrade (with status 101 and a meaningless duration) and nothing else. Teams that add logging in the message handler get a line per frame, which is too much volume to keep and too little structure to query.

The second problem is correlation. Without a connection identifier generated at the upgrade and attached to every subsequent line, events from one socket cannot be grouped, and events from the server cannot be joined with client-side logs or with traces.

Log the lifecycle, count the traffic.

Resolution #

Log a small set of lifecycle events, each as one JSON object carrying the same conn_id. Put per-frame activity into counters on the connection object and emit them as fields on the close event, so the final line summarises the whole connection. Use a logger child bound to the connection so every line automatically includes its context, and redact credentials at the logger level rather than trusting every call site.

import pino from 'pino';
import { randomUUID } from 'node:crypto';
import { WebSocketServer, WebSocket } from 'ws';
import type { IncomingMessage } from 'node:http';

const log = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  // Redaction at the source: these paths never reach the transport.
  redact: { paths: ['url_query.token', 'url_query.ticket', 'headers.cookie', 'headers.authorization'], censor: '[redacted]' },
});

interface ConnStats { msgsIn: number; msgsOut: number; bytesIn: number; bytesOut: number }

export function attachLogging(wss: WebSocketServer) {
  wss.on('connection', (ws: WebSocket, req: IncomingMessage, userId?: string) => {
    const connId = randomUUID();
    const openedAt = Date.now();
    const stats: ConnStats = { msgsIn: 0, msgsOut: 0, bytesIn: 0, bytesOut: 0 };
    // Child logger: every line from here on carries conn_id, user and node.
    const clog = log.child({
      conn_id: connId,
      user_id: userId,
      node: process.env.HOSTNAME,
      remote_ip: req.headers['x-forwarded-for'] ?? req.socket.remoteAddress,
      user_agent: req.headers['user-agent'],
    });
    (ws as any).log = clog;                 // handlers can log subscribe/refresh events
    (ws as any).connId = connId;
    clog.info({ event: 'ws.open', subprotocol: ws.protocol || undefined });

    ws.on('message', (data) => { stats.msgsIn += 1; stats.bytesIn += (data as Buffer).length; });
    const origSend = ws.send.bind(ws);
    ws.send = ((data: any, ...rest: any[]) => {
      stats.msgsOut += 1;
      stats.bytesOut += typeof data === 'string' ? Buffer.byteLength(data) : data.length ?? 0;
      return origSend(data, ...rest);
    }) as typeof ws.send;

    ws.on('close', (code, reason) => {
      const level = code === 1000 || code === 1001 ? 'info' : 'warn';
      clog[level]({
        event: 'ws.close',
        close_code: code,
        close_reason: reason.toString().slice(0, 120),
        duration_ms: Date.now() - openedAt,
        ...stats,
      });
    });
    ws.on('error', (err) => clog.error({ event: 'ws.error', err: { message: err.message, code: (err as any).code } }));
  });
}

Log rejected upgrades too, from the upgrade handler, with the reason (bad_origin, invalid_token, rate_limited) and no credential material. A spike of rejections is often the first sign of a broken client release or an expired signing key — the loop described in avoiding reconnect loops on auth failure.

Send the conn_id to the client in your welcome message and have the client include it in its own error reports. That single field joins a user’s bug report, the client’s console log and the server’s lifecycle lines. If you also run tracing, add the trace id of the upgrade span to the child logger; instrumenting WebSockets with OpenTelemetry shows where that span comes from.

Lines for decisions and state changes; counters for volume.

Verification #

Check that the logs answer a real question. Pick a user ID and reconstruct their day of connections with one query — every open matched with a close, and the close codes explaining each drop:

# Every connection for one user, with duration and close code, from JSON logs.
jq -c 'select(.user_id=="u_8812" and (.event=="ws.open" or .event=="ws.close"))
       | {t: .time, event, conn_id, close_code, duration_ms}' app.log
# Close codes across the fleet in the last hour: the shape of your disconnects.
jq -r 'select(.event=="ws.close") | .close_code' app.log | sort | uniq -c | sort -rn

Then verify redaction: search the log store for your token prefix (eyJ) and for ticket=; both should return nothing. Finally, estimate volume: lines per connection should be single digits. If the average is in the hundreds, something is logging per frame.

Five lines tell the whole story of a 49-minute connection.

Operational checklist #

A conn_id is generated at upgrade and attached to every log line via a child logger.
ws.open, ws.close (with code, reason, duration, counters) and rejected upgrades are logged.
Subscription changes, token refreshes and backpressure events are logged as they happen.
Per-frame activity is counted, not logged.
Credentials in query strings, cookies and headers are redacted at the logger.
The conn_id is sent to the client and included in client error reports.
Abnormal closes log at warn so they can be alerted on by level.

FAQ #

Should I log every WebSocket message in production? #

No. At any real scale it produces enormous volume, costs more than the rest of your logging combined, and risks storing user content you should not keep. Count messages and bytes per connection, and use sampled tracing or a temporary debug flag scoped to one connection when you need frame-level detail.

How do I correlate client and server logs? #

Generate the connection id on the server, send it to the client in the first message, and have the client attach it to its telemetry. Both sides then share a key that survives even when timestamps disagree.

Which log level should an abnormal close use? #

warn for codes other than 1000 and 1001, info for normal closes. Individually, a 1006 is often a user closing a laptop; in aggregate, a rising rate is an incident — which is a job for alerting on WebSocket connection drops, not for paging on log lines.

Where does the remote IP come from behind a proxy? #

From X-Forwarded-For (or Forwarded), set by your load balancer. Only trust it when the request came from your proxy; otherwise clients can spoof it.

Instrumenting WebSockets with OpenTelemetry — traces that share the connection id.
Exporting WebSocket Metrics to Prometheus — the counters that replace per-frame logs.
Alerting on WebSocket Connection Drops — turning close codes into alerts.
WebSocket Close Codes Explained — reading the codes in your close lines.

Back to WebSocket Observability & Monitoring.