Json logging format

A structured log is one JSON object per line, so parse it a line at a time: node ndjson.mjs app.log prints 6/6 lines parsed. Parsing the whole file as one document fails at the second record, because the stream is NDJSON and not a JSON array.

Why check this

Run this when a service is first sent to a log platform, and again whenever a new field appears in a record. The failure it prevents is hard to see later: a field that is a number in one record and a string in another. Both are valid JSON, every local assertion passes, and the backend indexes the field with the type it met first. Queries on the other records return nothing, which you discover during an incident, on the field you most wanted to filter by.

The check has three parts: the stream parses line by line, every record carries the keys a reader depends on, and each key keeps one type. Whether a record should contain a given value at all is a different question, covered by How to check logs for pii.

Prerequisites

• Node 22 or later.
• A free port. netstat -ano | grep 8791 prints nothing when 8791 is free.
• jq is optional. The readers below are Node.
• 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 &.

// 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 }));

Send three good requests and one failure, so the file holds more than one record shape.

curl -s -o /dev/null http://127.0.0.1:8791/orders; curl -s -o /dev/null http://127.0.0.1:8791/orders; curl -s -o /dev/null http://127.0.0.1:8791/orders; curl -s -o /dev/null http://127.0.0.1:8791/fail

Save this as ndjson.mjs. It is the parse gate, and it sets an exit code a pipeline can use.

// node ndjson.mjs <file>   exit 1 when any line is not a JSON object
import { readFileSync } from 'node:fs';
const lines = readFileSync(process.argv[2], 'utf8').split('\n').filter((l) => l.trim());
let ok = 0;
for (const [i, line] of lines.entries()) {
  try { JSON.parse(line); ok += 1; }
  catch (e) { console.log(`line ${i + 1} is not JSON: ${e.message}`); }
}
console.log(`${ok}/${lines.length} lines parsed`);
process.exitCode = ok === lines.length ? 0 : 1;

Save this as audit.mjs. It reports missing keys and every key whose type changes between records.

// node audit.mjs <file>
import { readFileSync } from 'node:fs';
const required = ['time', 'level', 'msg'];
const types = new Map();
const rows = readFileSync(process.argv[2], 'utf8').split('\n').filter((l) => l.trim()).map(JSON.parse);
rows.forEach((r, i) => {
  for (const k of required) if (!(k in r)) console.log(`record ${i + 1} has no "${k}"`);
  for (const [k, v] of Object.entries(r)) {
    const t = Array.isArray(v) ? 'array' : v === null ? 'null' : typeof v;
    if (!types.has(k)) types.set(k, new Map());
    types.get(k).set(t, (types.get(k).get(t) ?? 0) + 1);
  }
});
for (const [k, seen] of types) {
  const shape = [...seen].map(([t, n]) => `${t} x${n}`).join(', ');
  console.log(`${seen.size > 1 ? 'DRIFT ' : '      '}${k}: ${shape}`);
}

Steps

1. 1

   Step 1.

   Parse the file the way a reader reaching for JSON.parse would.

   node -e "JSON.parse(require('fs').readFileSync('app.log','utf8'))"
   

   <anonymous_script>:2
   {"time":"2026-09-12T07:34:22.679Z","level":"info","msg":"request done","req_id":"r487107","status":200,"duration_ms":"2"}
   ^
   
   SyntaxError: Unexpected non-whitespace character after JSON at position 111 (line 2 column 1)
     at JSON.parse (<anonymous>)

   Position 111 is the end of the first record. The parser read one complete object, then found another where the document should have ended. Every line here is valid JSON and the file is not. The format is NDJSON, newline-delimited JSON.

2. 2

   Step 2.

   Parse it the way the format asks, one record per line, and read the exit code.

   node ndjson.mjs app.log; echo "exit $?"
   

   6/6 lines parsed
   exit 0

   Six records, six objects, exit 0. This is the gate for a pipeline: it needs no log platform and it fails on the build that broke the format.

3. 3

   Step 3.

   Check the keys and their types across every record.

   node audit.mjs app.log
   

         time: string x6
       level: string x6
       msg: string x6
       port: number x1
       resolved_level: string x1
       req_id: string x5
       status: number x4
   DRIFT duration_ms: string x3, number x1
       err: object x1

   duration_ms is a string in three records and a number in one. The service has two code paths and one wraps the value in String(). Step 2 passes, a schema check on a single record passes, and a backend that indexed duration_ms as text drops the numeric record or stores it unqueryable.

   Read the low counts too. err appears once and req_id in five records of six. A field missing from one record is optional by design or absent by accident, and the count is how you find it to ask.

4. 4

   Step 4.

   Find out what happens when the process writes something that is not a record. Start a second instance while the first still holds the port, with both streams going to one file.

   LOG_LEVEL=info node logsvc.mjs > crash.log 2>&1
   

   node ndjson.mjs crash.log | head -5; node ndjson.mjs crash.log > /dev/null; echo "exit $?"
   

   line 1 is not JSON: Unexpected token 'o', "node:events:497" is not valid JSON
   line 2 is not JSON: Unexpected token 'h', "      throw er; /"... is not valid JSON
   line 3 is not JSON: Unexpected token '^', "      ^" is not valid JSON
   line 4 is not JSON: Unexpected token 'E', "Error: lis"... is not valid JSON
   line 5 is not JSON: Unexpected token 'a', "    at Server."... is not valid JSON
   exit 1

   Eighteen lines, none of them JSON. The runtime wrote a stack trace to stderr and 2>&1 put it inside a stream a parser has to read as records. The logger is not involved and cannot fix it: anything the process or a dependency prints lands in the same file. That is why the check runs over a whole file.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | 6/6 lines parsed, exit 0 | Every line is one JSON object | Keep the command as a pipeline gate on the log a test run produces. | | Unexpected non-whitespace character after JSON | A whole-file parse of an NDJSON stream | Read it line by line. The stream is correct and the reader is wrong. | | A DRIFT line from the audit | One key carries two types across records | Fix the code path that differs. A backend types a field once, from the record it meets first. | | record N has no "time" | A record is missing a key readers depend on | Find the call site. A record with no timestamp cannot be ordered against the others. | | A run of unparseable lines in the middle | stderr was merged into the record stream | Send stderr somewhere else, or accept that a crash trace breaks the parser and say so in the reader. |

Common mistakes

What to check next

• How to check log level in production: the level field this page parses is set somewhere else, often not where the config says.
• How to test logging: the err key the audit counted once is empty, for a reason worth knowing.
• How to check correlation id in logs: the field that joins these records across services.
• Access log format: a second stream, with its own keys.
• Trace id in logs: the same record from the tracing side.

FAQ

What is structured logging?

Logging where each record is a machine-readable object with named fields, rather than a sentence. The gain is filtering: status: 500 is a query, while "request failed with 500" is a substring search that also matches the body of an unrelated message.

What is a JSON log?

One JSON object per line, written to stdout, with the newline as the record separator. The format is NDJSON. A file of them is not a JSON document, as step 1 shows, and reading it as one is the most common mistake made against it.

Should the file be a JSON array instead?

No. An array has to be closed, so a killed process leaves a file no parser accepts, and a reader has to hold the whole array before it sees the first record. One object per line survives a kill and streams.

Which fields does every record need?

A timestamp, a level and a message, which is what audit.mjs requires. Add a request identifier as soon as two requests can be in flight, because without it their records interleave with nothing to separate them.

Verified