Request-Response Logging

Automatic request logging

The previous lesson assigned request IDs. This lesson logs every request and response automatically — method, path, status code, and duration — without adding code to individual route handlers.

The onRequest + onResponse pattern

export const app = setup({
  onRequest: ({ request }) => {
    const requestId = request.headers.get("x-request-id") ?? generateRequestId();
    const url = new URL(request.url);

    return { requestId, startTime: Date.now(), method: request.method, path: url.pathname };
  },

  onResponse: ({ response, locals }) => {
    const duration = Date.now() - (locals.startTime as number);

    logger.info("request completed", {
      requestId: locals.requestId,
      method: locals.method,
      path: locals.path,
      status: response.status,
      duration,
    });

    response.headers.set("X-Request-Id", locals.requestId as string);
    response.headers.set("X-Response-Time", `${duration}ms`);
  },

  routes: [
    /* ... */
  ],
});

onRequest captures the start time. onResponse calculates the duration and logs the complete request-response pair. Every request — regardless of which route handles it — gets a log entry.

The output:

{"timestamp":"2024-01-15T14:32:05.123Z","level":"info","message":"request completed","requestId":"req_a1b2c3","method":"GET","path":"/v2/books","status":200,"duration":12}
{"timestamp":"2024-01-15T14:32:05.135Z","level":"info","message":"request completed","requestId":"req_d4e5f6","method":"POST","path":"/v2/books","status":201,"duration":45}
{"timestamp":"2024-01-15T14:32:05.180Z","level":"info","message":"request completed","requestId":"req_g7h8i9","method":"GET","path":"/v2/books/nonexistent","status":404,"duration":3}

One line per request. Every field searchable. Duration reveals slow endpoints.

Log level by status code

Not all requests deserve the same log level:

onResponse: ({ response, locals }) => {
  const duration = Date.now() - (locals.startTime as number);
  const status = response.status;

  const level = status >= 500 ? "error" : status >= 400 ? "warn" : "info";

  logger[level]("request completed", {
    requestId: locals.requestId,
    method: locals.method,
    path: locals.path,
    status,
    duration,
  });
},

2xx/3xx → info. Normal operation. 4xx → warn. Client made a mistake (bad input, not found). Not a server problem, but worth tracking. 5xx → error. Server failed. Needs attention.

Slow request warnings

const SLOW_REQUEST_THRESHOLD_MS = 100;

onResponse: ({ response, locals }) => {
  const duration = Date.now() - (locals.startTime as number);

  if (duration > SLOW_REQUEST_THRESHOLD_MS) {
    logger.warn("slow request", {
      requestId: locals.requestId,
      method: locals.method,
      path: locals.path,
      duration,
      threshold: SLOW_REQUEST_THRESHOLD_MS,
    });
  }

  // ... normal request log
},

[!NOTE] The Caching course added X-Response-Time to responses. Now the logging system captures it too — both in the response header (for the client) and in the log entry (for you).

What NOT to log in request logs

Do not include the request body in the default request log. Bodies can contain passwords, tokens, or personal data. Log bodies only in debug mode or for specific endpoints where you need them:

if (process.env.LOG_LEVEL === "debug") {
  logger.debug("request body", { requestId: locals.requestId, body: await request.text() });
}

Exercises

Exercise 1: Implement request-response logging in onRequest and onResponse. Make 5 requests. Verify each produces a log entry.

Exercise 2: Add level-by-status: info for 2xx, warn for 4xx, error for 5xx. Trigger each by making valid, invalid, and error-causing requests.

Exercise 3: Add slow request warnings with a 50ms threshold. Find the slowest endpoint.

Why log requests in onResponse instead of onRequest?