How to test logging

Trigger the failure and read the record it produced. Here /fail logs "err":{}, because an Error serialises to an empty object: message and stack are not enumerable. A logger given an error serialiser writes type, message and stack, while a test that asserts only the message passes either way.

Why check this

Run this on every path that catches an exception, before release, and after any change to the logger. The failure it prevents is found at three in the morning: the alert fires, the record says order failed, and the field meant to hold the exception is {}. The stack is gone from every record the service ever wrote, so there is nothing to go back to.

The defect survives review because the code looks right. logger.error({ err }, 'order failed') names the error and produces a record with the error in it. What it does not produce is any part of the error a person can read. Browser failures have the same shape and a separate check: How to check console errors on a website.

Prerequisites

• Node 22 or later. node --test is built in.
• The pino logger, npm i pino@9, for the serialiser in step 4.
• A free port. netstat -ano | grep 8791 prints nothing when 8791 is free.
• Stop the service when you finish. netstat -ano | grep ":8791 .*LISTENING" gives the PID and powershell -Command "Stop-Process -Id <pid> -Force" stops it.

Save this as logsvc.mjs and start it with LOG_LEVEL=info node logsvc.mjs > app.log 2>&1 &. The /fail route throws, catches, and logs the error the way most handlers do.

// logsvc.mjs  Node 22, ESM.  Start: LOG_LEVEL=info node logsvc.mjs
import { createServer } from 'node:http';
const LEVELS = { trace: 10, debug: 20, info: 30, warn: 40, error: 50 };
const wanted = LEVELS[process.env.LOG_LEVEL] ?? LEVELS.debug;
const name = Object.keys(LEVELS).find((k) => LEVELS[k] === wanted);
const log = (level, msg, fields = {}) => {
  if (LEVELS[level] < wanted) return;
  process.stdout.write(JSON.stringify({ time: new Date().toISOString(), level, msg, ...fields }) + '\n');
};
createServer((req, res) => {
  const t0 = Date.now();
  const id = req.headers['x-request-id'] ?? 'r' + Math.random().toString(16).slice(2, 8);
  log('debug', 'request received', { req_id: id, url: req.url, headers: req.headers });
  if (req.url === '/fail') {
    try {
      throw new Error('order 4471 has no payment method');
    } catch (err) {
      log('error', 'order failed', { req_id: id, err });
      res.writeHead(500, { 'content-type': 'application/json' }).end('{"error":"internal"}');
      log('info', 'request done', { req_id: id, status: 500, duration_ms: Date.now() - t0 });
      return;
    }
  }
  res.writeHead(200, { 'content-type': 'application/json' }).end('{"ok":true}');
  log('info', 'request done', { req_id: id, status: 200, duration_ms: String(Date.now() - t0) });
}).listen(8791, '127.0.0.1', () => log('info', 'service started', { port: 8791, resolved_level: name }));

Save this as broken.test.mjs for step 6. It holds the same logging call and two assertions.

import test from 'node:test';
import assert from 'node:assert';

// the hand-rolled logger from logsvc.mjs, writing to an array
const lines = [];
const log = (level, msg, fields = {}) => lines.push(JSON.stringify({ level, msg, ...fields }));

test('an error line is written', () => {
  try { throw new Error('order 4471 has no payment method'); }
  catch (err) { log('error', 'order failed', { err }); }
  const rec = JSON.parse(lines.at(-1));
  assert.equal(rec.level, 'error');
  assert.equal(rec.msg, 'order failed');
});

test('the error line carries the message', () => {
  const rec = JSON.parse(lines.at(-1));
  assert.match(rec.err.message ?? '', /no payment method/);
});

Steps

1. 1

   Step 1.

   Make the service fail, and read the status it returned.

   curl -s -o /dev/null -w '%{http_code}\n' http://127.0.0.1:8791/fail
   

   500

   Now read the two records that request wrote.

   tail -2 app.log
   

   {"time":"2026-09-12T07:34:22.803Z","level":"error","msg":"order failed","req_id":"r99a467","err":{}}
   {"time":"2026-09-12T07:34:22.804Z","level":"info","msg":"request done","req_id":"r99a467","status":500,"duration_ms":1}

   The level, the message and the request id are all right, and err is {}. Everything a checklist asks for is present. Nothing that names the failure survived.

2. 2

   Step 2.

   Reproduce the cause outside the service, in one command.

   node -e "const e=new Error('order 4471 has no payment method');console.log('stringify:',JSON.stringify(e));console.log('own keys:',JSON.stringify(Object.keys(e)));console.log('message enumerable:',Object.getOwnPropertyDescriptor(e,'message').enumerable);console.log('stack enumerable:',Object.getOwnPropertyDescriptor(e,'stack').enumerable)"
   

   stringify: {}
   own keys: []
   message enumerable: false
   stack enumerable: false

   Error carries message and stack as non-enumerable own properties, and JSON.stringify walks enumerable ones only. Object spread behaves the same, so { ...err } is also {}. Any logger reaching JSON.stringify without help produces the record in step 1.

3. 3

   Step 3.

   Print the same error the way a developer does at a terminal.

   node -e "function loadOrder(id){throw new Error('order '+id+' has no payment method')};try{loadOrder(4471)}catch(err){console.log(err)}"
   

   Error: order 4471 has no payment method
     at loadOrder ([eval]:1:30)
     at [eval]:1:83
     at runScriptInThisContext (node:internal/vm:209:10)
   …

   console.log runs the object through Node's inspector, which reads the non-enumerable properties on purpose. That is why the error looks complete in local development and arrives empty in the log platform. Two views of one object, produced by different code, and only one of them ships.

4. 4

   Step 4.

   Log the error through a logger that can serialise one, then make the near-miss on purpose.

   node -e "const pino=require('pino');const log=pino({base:null,timestamp:false});function loadOrder(id){throw new Error('order '+id+' has no payment method')};try{loadOrder(4471)}catch(err){log.error({err},'order failed');log.error({error:err},'order failed')}" > pino2.log 2>&1
   

   cut -c1-400 pino2.log
   

   {"level":50,"err":{"type":"Error","message":"order 4471 has no payment method","stack":"Error: order 4471 has no payment method\n    at loadOrder ([eval]:1:101)\n    at [eval]:1:154\n    at runScriptInThisContext (node:internal/vm:209:10)\n    at node:internal/process/execution:446:12\n    at [eval]-wrapper:6:24\n    at runScriptInContext (node:internal/process/execution:444:60)\n    at evalFuncti
   {"level":50,"error":{},"msg":"order failed"}

   Two calls, one error. The first names the key err and gets type, message and stack. The second names it error and gets {}, the empty object from step 1. pino binds its serialiser to the key, not to the value, so renaming the field turns it off silently.

5. 5

   Step 5.

   Read the stack back out of the record.

   node -e "const l=require('fs').readFileSync('pino2.log','utf8').split('\n')[0];console.log(JSON.parse(l).err.stack)"
   

   Error: order 4471 has no payment method
     at loadOrder ([eval]:1:101)
     at [eval]:1:154
   …

   The stack is one string with escaped newlines, so reading it needs a JSON parse and a print, not a text search. Message first, then the frame that threw, then its caller.

6. 6

   Step 6.

   Put an assertion on it, so the next change cannot bring the empty record back.

   node --test --test-reporter=spec broken.test.mjs
   

   ✔ an error line is written (0.8211ms)
   ✖ the error line carries the message (0.6795ms)
   ℹ tests 2
   ℹ pass 1
   ℹ fail 1
   …
   ✖ failing tests:
   
   test at broken.test.mjs:16:1
   ✖ the error line carries the message (0.6795ms)
   AssertionError [ERR_ASSERTION]: The input did not match the regular expression /no payment method/. Input:
   
   ''
   …

   The first test passes against the broken logger, because level and message survive the defect. Only the second fails, with '', the empty string the missing message collapsed to. Assert on err.message or err.stack. An assertion on msg is worth nothing here.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | "err":{} in an error record | The error reached JSON.stringify with no serialiser | Add one, or write type, message and stack into the record by hand. | | "err":{"type":…,"message":…,"stack":…} | The serialiser ran | Nothing. Check the stack has frames from your own files, not only from the runtime. | | An error record with a message and no err key at all | Only the string was logged | The stack was never captured. Pass the error object, not err.message. | | The stack is present but every frame is a runtime path | The error crossed an async boundary that dropped the frames | Look for a rethrow that created a new Error instead of passing the original. | | A test suite green and production records empty | The assertions cover level and message only | Assert on err.stack, as in step 6. |

Common mistakes

What to check next

• Json logging format: the stream this record belongs to has a contract of its own.
• How to check log level in production: a record that never appears may have been filtered, not lost.
• How to test API error responses: what the caller received while this record was written.
• How to check correlation id in logs: the field tying this record to its request.
• Sensitive data in logs: a serialised error carries whatever was in scope.

FAQ

How do I read a stack trace?

Top to bottom, newest frame first. Line one is the error class and message. The frame under it is where the throw happened, and each frame below its caller. Skip frames inside the runtime or a dependency. The first naming your own file is where to look.

How do I check a stack trace in a log file?

Parse the record and print the field, as in step 5. grep for a function name finds the line and shows it as one unreadable row.

How do I unit test logging?

Give the logger a destination you control: an array, or an object with a write method. Call the code that logs, parse the last line, assert on the fields. Step 6 does this with node --test and nothing installed.

Why does the error field arrive empty?

Because JSON.stringify(new Error('boom')) returns {}. The properties a person needs are non-enumerable, so they are skipped. Every logger without an error serialiser inherits the behaviour.

Verified