Logging

When your app runs on a server, you cannot watch it. If a customer in Lucknow says "my order failed at 9:40 last night", the only way to find out what happened is to read what the app wrote down at that moment. Those records are logs. Good logs answer three questions quickly: what happened, when, and for which request or user.

In this lesson you will see what console offers and where its output goes, then move to structured logging with pino, a fast JSON logger: log levels, extra fields, child loggers, request logs with pino-http, readable output during development, and hiding passwords and tokens.

console and the two output streams

Every process has two output streams: stdout (standard output) for normal output and stderr (standard error) for errors and warnings. Both appear in your terminal, but tools can separate them.

console.log("Server starting");              // normal output (stdout)
console.error("Database connection failed"); // errors (stderr)
console.warn("Disk is 90% full");            // also stderr

console.table([
  { city: "Rohtak", orders: 42 },
  { city: "Kochi", orders: 37 },
]);

console.time("report");
let sum = 0;
for (let i = 0; i < 1e6; i++) sum += i;
console.timeEnd("report");

The stdout part:

Server starting
┌─────────┬──────────┬────────┐
│ (index) │ city     │ orders │
├─────────┼──────────┼────────┤
│ 0       │ 'Rohtak' │ 42     │
│ 1       │ 'Kochi'  │ 37     │
└─────────┴──────────┴────────┘
report: 9.473ms

and the stderr part:

Database connection failed
Disk is 90% full

console.table() is handy for checking arrays of objects, and console.time()/timeEnd() measure how long code takes. For learning and small scripts, console is enough.

Why console.log is not enough for servers

On a busy server, thousands of plain lines such as order failed are almost useless. You cannot tell which order, which user, when, or how serious it was, and you cannot easily search or count them. Real apps need:

• Levels, so you can show only warnings and errors in production and everything while debugging.
• Timestamps on every line.
• Context fields such as orderId, userId and requestId.
• A machine-readable format, so log tools (Grafana Loki, Elasticsearch, cloud consoles) can search and filter.
• Speed: logging should not slow down the event loop.

Structured logging writes each entry as one JSON object per line. Libraries such as pino do this for you.

Structured logs with pino

npm install pino

import pino from "pino";

const logger = pino({
  level: process.env.LOG_LEVEL ?? "info",
  redact: ["user.password", "card.number"],
});

logger.info("Server started");
logger.info({ port: 3000, mode: "production" }, "Listening");
logger.debug("This is hidden at level info");
logger.warn({ diskUsedPercent: 91 }, "Disk almost full");

const orderLog = logger.child({ orderId: 1042 });
orderLog.info("Payment received");
orderLog.error({ err: new Error("Courier API timeout") }, "Shipping label failed");

logger.info({ user: { email: "priya@example.in", password: "Jaipur#Pink77" } }, "Login attempt");

The output (the error's stack trace is shortened here):

{"level":30,"time":1793357103412,"pid":19996,"hostname":"Cyber","msg":"Server started"}
{"level":30,"time":1793357103415,"pid":19996,"hostname":"Cyber","port":3000,"mode":"production","msg":"Listening"}
{"level":40,"time":1793357103415,"pid":19996,"hostname":"Cyber","diskUsedPercent":91,"msg":"Disk almost full"}
{"level":30,"time":1793357103416,"pid":19996,"hostname":"Cyber","orderId":1042,"msg":"Payment received"}
{"level":50,"time":1793357103416,"pid":19996,"hostname":"Cyber","orderId":1042,"err":{"type":"Error","message":"Courier API timeout","stack":"Error: Courier API timeout\n    at file:///C:/node-course/logging/pino-basic.js:15:23\n ..."},"msg":"Shipping label failed"}
{"level":30,"time":1793357103417,"pid":19996,"hostname":"Cyber","user":{"email":"priya@example.in","password":"[Redacted]"},"msg":"Login attempt"}

What each part means:

• The first argument can be an object of fields, the second the message. Each line gets level, time (milliseconds since 1970), the process id pid and the hostname automatically.
• The debug message did not appear, because the logger's level is info. Run with LOG_LEVEL=debug to see it, with no code change.
• logger.child({ orderId: 1042 }) creates a logger that adds orderId to every line. Create a child per request or per job, and every line about it can be found by searching for that ID.
• Pass errors as { err }. Pino records the type, message and full stack trace.
• redact replaces sensitive fields with [Redacted], so a password never reaches your log files even if someone logs the whole object by mistake.

Readable logs in development

JSON is perfect for machines but tiring to read. Pipe the output through pino-pretty while developing:

npm install --save-dev pino-pretty
node app.js | npx pino-pretty

[16:15:21.466] INFO (14880): Server started
[16:15:21.468] INFO (14880): Listening
    port: 3000
    mode: "production"
[16:15:21.468] WARN (14880): Disk almost full
    diskUsedPercent: 91
[16:15:21.469] INFO (14880): Payment received
    orderId: 1042

In production keep the raw JSON, so log tools can read it.

Logging every request

pino-http is middleware that logs one line for each finished request, with the method, URL, status and response time, and gives every request its own child logger as req.log:

npm install pino-http

import express from "express";
import pino from "pino";
import { pinoHttp } from "pino-http";

const logger = pino();
const app = express();

app.use(pinoHttp({
  logger,
  redact: ["req.headers.authorization", "req.headers.cookie"],
}));

app.get("/api/menu", (req, res) => {
  req.log.info("Fetching menu from cache");
  res.json(["Masala chai", "Samosa"]);
});

app.listen(3000, () => logger.info("ready"));

A request to /api/menu with an Authorization header logs two lines, both with the same request id. The final line looks like this (some headers removed to fit):

{"level":30,"time":1793357171561,"pid":26552,"hostname":"Cyber","req":{"id":1,"method":"GET","url":"/api/menu","query":{},"params":{},"headers":{"host":"localhost:3000","authorization":"[Redacted]","user-agent":"node"},"remoteAddress":"::1","remotePort":64286},"res":{"statusCode":200,"headers":{"content-type":"application/json; charset=utf-8","content-length":"24"}},"responseTime":22,"msg":"request completed"}

When a customer reports a problem, you can now find the request, see how long it took and read every line logged during it.

Where should logs go?

Write logs to stdout and let the environment collect them. PM2 saves them to files and can rotate them, Docker keeps them per container, and cloud platforms send them to their log viewers. Do not open and manage log files from inside your app; it complicates rotation and fails on platforms with read-only disks.

Common mistakes

• Only console.log in production. No levels, no context, hard to search.
• Logging secrets or personal data. Use redact and log IDs.
• Logging too much at info. Logs become noise and cost money to store. Use debug for detail.
• Logging an error as a string. logger.error("failed: " + err) loses the stack trace; pass { err }.
• Writing log files from the app. Log to stdout and let PM2, Docker or the platform handle files.

Key points

• console.log writes to stdout; console.error and console.warn write to stderr.
• Structured logging writes one JSON object per line with level, time and context fields.
• Pino has levels from trace (10) to fatal (60); set the minimum level with an environment variable.
• Child loggers add fields such as orderId to every line; pass errors as { err }.
• pino-http logs every request with an ID and response time; redact hides secrets.
• Log to stdout and let the process manager or platform collect and rotate logs.

import pino from "pino";

const logger = pino({
  level: process.env.LOG_LEVEL ?? "info",
  redact: ["passenger.phone"],
});

const bookingLog = logger.child({ pnr: "4521098765" });
bookingLog.info({ seats: 2, passenger: { name: "Meera", phone: "9812345678" } }, "Booking confirmed");
bookingLog.debug("Seat map loaded");

{"level":30,"time":1793357234323,"pid":12896,"hostname":"Cyber","pnr":"4521098765","seats":2,"passenger":{"name":"Meera","phone":"[Redacted]"},"msg":"Booking confirmed"}