# Logging and Debugging

Course: [Express.js](https://www.devtutorials.ai/learn/expressjs) · Section: Operations
Source: https://www.devtutorials.ai/learn/expressjs/operations/logging-and-debugging

> What to log, a custom logger with the finish event, request IDs, Morgan formats and custom tokens, error logging, the DEBUG environment variable, debugging routes, middleware order and async handlers, and health checks.

## Logging and Debugging Introduction

A running server is a black box unless it tells you what it does.

- **Log** = a line your server writes about something that happened.
- **Request log** = one line per request: method, URL, status and time.
- **Debugging** = finding out why the server does something you did not expect.
- Logs answer "what happened?". Debugging answers "why?".
- Good logs never contain passwords, tokens or other secrets.

**Simple lesson:** Log every request, and log errors with enough detail to fix them.

### A Real-World Example

The canteen keeps an order register.

1. Each order gets a line: time, token number, item, and "served" or "cancelled".
2. A parent complains: "My child waited 30 minutes."
3. The manager finds token 41 in the register: ordered 12:01, served 12:31.
4. The register never lists the child's lunch card PIN.

The register is your request log. The token number is a request ID.

In this lesson, you will learn:

1. What to put in a request log.
2. How to write logger, timing and request-ID middleware.
3. How to use Morgan, the popular logging package.
4. How to log errors safely.
5. How to use Express's `DEBUG` output.
6. How to debug routes, middleware order and async handlers.

## What to Log

- **Method and URL:** `GET /api/menu?veg=true`.
- **Status code:** `200`, `404`, `500`.
- **Response time:** how many milliseconds the request took.
- **Request ID:** a unique ID to connect log lines for one request.
- **Never:** passwords, tokens, cookies, `Authorization` headers or full card numbers.
- Logs often end up in shared tools, so treat them as semi-public.

**Simple lesson:** Method, URL, status, time and ID. Never secrets.

## A Custom Logger

The status is only known at the **end** of a request. So the logger must wait.

- Record the start time when the request arrives.
- Listen for the response's **finish** event.
- When it fires, the status and time are known. Write the line.
- Call `next()` straight away, so the request carries on.
- `performance.now()` gives a precise time in milliseconds.

- `/slow` shows about 300 ms. `/missing` shows 404.
- If you logged before `next()`, you would not know the status yet.

Easy way to remember: **arrive, start the clock. Finish, write the line.**

**Simple lesson:** Start the clock on arrival, write the line on `finish`.

## Request IDs

**Request ID** = a unique label for one request.

- Create it with `crypto.randomUUID()`.
- If a proxy already sent `X-Request-Id`, reuse it, so both logs match.
- Store it on `req.id`, and send it back in the `X-Request-Id` header.
- Put it in every log line and every error answer.
- A user can then say "my request ID was 3f2a..." and you find it instantly.

- The second request keeps the ID the proxy sent.
- The login log shows the user, but the password is left out.

Never log `req.body` or `req.headers` whole. They often hold passwords, tokens and cookies.

**Simple lesson:** One ID per request, in the header, in the logs and in error answers.

## Logging with Morgan

**Morgan** = a ready-made request logger. Install it with `npm install morgan`.

- **morgan("dev")** = short, coloured lines for development.
- **morgan("tiny")** = the smallest useful line.
- **morgan("combined")** = the standard Apache format, common in production.
- **Custom format strings:** `":method :url :status :response-time ms"`.
- **Custom tokens:** `morgan.token("id", (req) => req.id)`, then use `:id`.
- **skip** = a function that hides some requests, such as health checks.

- `/health` is not logged, because of `skip`.
- Change the format to `"combined"` and run again to see a production-style line.

Big apps often log JSON lines with a package such as **pino**. Tools can then search by status, ID or URL. The ideas are the same as here.

**Simple lesson:** Morgan writes request lines for you. Add tokens for your own fields.

## Logging Errors

- Log every 500 with the **request ID**, the **message** and the **stack**.
- Log 4xx errors more briefly, or not at all. They are the client's mistake.
- Send the request ID to the client in the error answer.
- Keep stacks in the log, out of the answer. See **Error Handling**.

**Simple lesson:** The same request ID in the answer and the log connects the two.

## Express DEBUG Output

Express can print its own internal steps.

- Set the **DEBUG** environment variable before starting.
- `DEBUG=express:*` shows every Express namespace.
- `DEBUG=express:router` shows only routing. `DEBUG=*` shows every package.
- **Namespace** = the label before each debug line, such as `express:application`.
- On Windows PowerShell: `$env:DEBUG="express:*"; node server.js`.

- The terminal shows each setting and each request being dispatched.
- The real output has more lines. In this lab, you see a shortened version.

**Simple lesson:** `DEBUG=express:*` shows what Express itself is doing.

## Debugging Common Problems

When something does not work, check in this order:

1. **Is the request arriving?** A global logger at the top answers this.
2. **Does a route match?** Check the method, the path and `req.path`. Print `req.route?.path` in the handler.
3. **Is middleware in the right order?** Add a `console.log` in each one and watch the order.
4. **Does every path end?** Every branch must call `next()` or send a response.
5. **Is an async call awaited?** A missing `await` sends answers too early.
6. Use `console.log` for quick checks, and `node --inspect` with Chrome DevTools for breakpoints.

- `/api/menu` gives 404. The log shows the request arrived, so the path is wrong.
- `/api/price/2` logs `price is Promise...` and answers `{"price":{}}`. Add `await`.
- `/api/menu/2` works, so the server itself is fine.
- Fix both bugs and run again.

**Simple lesson:** Log the request, check the match, check the order, check the `await`.

## Health Checks

**Health check** = a tiny route that says "the server is alive".

- Load balancers and hosting platforms call it every few seconds.
- It usually answers `200` with `{ "status": "ok" }`.
- It can also check the database and answer `503` when something is down.
- Skip it in request logs, or it floods them.

**Simple lesson:** `/health` lets machines check your server. Keep it fast and quiet.

## Common mistakes

<div className="tscroll">

| Mistake | Wrong idea | Correct idea | What goes wrong |
|---|---|---|---|
| Logging before `next()` | The status is known at once | Wait for `finish` | Every line shows 200 |
| Logging `req.body` on login | It helps debugging | It contains the password | Passwords stored in logs |
| No request ID | The time is enough | Many requests share a time | You cannot match a complaint to a log |
| Logger registered after routes | Order does not matter | Register it first | Some requests are never logged |
| Logging health checks | More logs are better | Skip them | Real problems get buried |
| Stack traces in answers | It helps users | Stacks belong in logs | Internals leak |
| Missing `await` | Async values arrive by themselves | `await` the promise | `{}` or `undefined` answers |

</div>

## Check Yourself

## Exercises

## What to Remember

- Log method, URL, status, time and a request ID. Never secrets.
- Write the log line on `finish`, when the status is known.
- Request IDs connect the client's answer to your logs.
- Morgan handles request logs. Custom tokens add your own fields.
- `DEBUG=express:*` shows Express's own steps.
- Debug in order: arrival, route match, middleware order, ending, `await`.

Next: **Express Security**. You will protect your server with headers, CORS, rate limits and safe secrets.