Json-log NPM | npm.io

json-log

Lightweight, robust, fast, and opinionated json logger.

Works great with systemd, heroku, or lambda.

Philosophy

Write to stdout/err

Let your process manager (systemd, heroku, lambda etc.) handle writing logs. Persisting logs can get complicated fast; log rotation, file limits, compression, and backups just to name a few.

Your nodejs process should not be burdened with all that complexity. Simply write to stdout/err and let the manager take care of the rest.

I often use systemd with journald+syslog. It works amazing. You can always set up other tools that monitor syslog and pipe them to another service i.e. AWS Cloudwatch.

NOTE: You can customize the write method.

pid? hostname?

The process manager's logger should add info such as the process name, pid and hostname.

NOTE: If needed, you can add them like other context data:

log.child({
  hostname: require("os").hostname(),
  pid: process.pid
});

Logs should be meaningful

Logs should help you monitor the system, alert you of errors, and help you diagnose issues in a post-mortem. They should not be riddled with "normal" error messages that drown out the errors that require your attention.

Having only 3 levels helps you focus and create meaningful, actionable logs.

NOTE: You can customize the levels.

1 - `error`

The system is unstable and staff should be alerted to take action. A stable system will not emit error logs. This way you take error seriously and fix the problem so that condition is gracefully handled in the future. Don't be shy, you should use log.error statements generously. But they should only be called when there is an actual error that requires your attention.

Examples:

A remote service you depend on changed it's api and now responds with unexpected data. Your code now throws an exception trying to parse it.
A bad db query was made. You'll want to fix that query so it will work in the future.
The db connection was lost and the retries failed.

These log entries are sent to stderr. You can setup your process manager to do something special with the stderr stream i.e. email them to you, or trigger a monitoring alarm.

2 - `warn`

A recoverable error that is somewhat unexpected. You'll want to monitor these to give you clues when things may become unstable, or detect malicious users.

Examples:

A user tried uploading a file that exceeded the size limit. Keep an eye on that user id, they may be malicious. (Be sure to include the userId in the log entries so you can correlate their activity)
A rpc call had to retry before getting a successful response. May indicate the service or network connection is having trouble.
A sub-process was restarted. May be an issue if it's repeatedly restarted.

3 - `info`

Any useful information about the operation of the system. Information that helps you in a post-mortem, or in analysing the usage and performance of the system.

Examples:

This request was made
This task was started
This query returned X

Why no debug/trace?

During development use console.log to debug your system. Remove those console.logs before deploying to production. Anything that would be helpful in production should use log.info.

Context is crucial

High concurrency is easy to achieve in nodejs. Therefore it's important that each entry contains information about its context. What request it is a part of, what parameters its working with etc. Include request ids, urls, user ids, db record ids, anything that helps give context to the log message. json-log will robustly serialize them, including error objects.

Create context specific loggers using log.child(data)

Robust json stringification

This json encoder gracefully handles the following:

Circular references
Error objects
Buffers and Typed Arrays (using util.inspect to truncate them)
http req/res objects

See test.js for more details

API

import log from "json-log";
// or
var log = require("json-log").log;

log.info(message, data)

Simply write a message string along with some optional data to stdout at level 3.

log.info("hello world");
// OUT-> {"level":3,"time":...,"msg":"hello world"}

log.info("hello world", { extra: "data", arr: [1, 2] });
// OUT-> {"level":3,"time":...,"extra":"data","arr":[1,2],"msg":"hello world"}

log.info("hello world", [1, 2]); // shorthand for {data: [1,2]}
// OUT-> {"level":3,"time":...,"data":[1,2],"msg":"hello world"}

// Accidentally included a buffer or typed array in your data? No problem.
log.info("oops!!", Buffer.alloc(10000000));
// OUT-> {"level":3,"time":...,"data":"<Buffer 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ... >","msg":"oops!!"}

log.warn(message, data)

Same as log.info but level is 2

log.warn("wat da?", { more: "info" });
// OUT-> {"level":2,"time":...,"more":"info","msg":"wat da?"}

log.error(message, data)

Same as log.info but writes to stderr and level is 1

log.error("grrr", { err: new Error("fail") });
log.error("grrr", new Error("fail")); // shorthand for {err: ...}
// ERR-> {"level":1,"time":...,"err":{"name":"Error","message":"fail","stack":"Error..."},"msg":"some error"}

log2 = log.child(data)

Create a new log that has the context data included on every entry.

var log2 = log.child({ reqId: 1, foo: "bar" });

log2.info("hello again");
// OUT-> {"level":3,"time":...,"reqId":1,"foo":"bar","msg":"hello again"}

log2.info("hello again", { aaa: 1 });
// OUT-> {"level":3,"time":...,"reqId":1,"foo":"bar","aaa":1,"msg":"hello again"}

var log3 = log2.child({ baz: "333" });
log3.info("yet again");
// OUT-> {"level":3,"time":...,"reqId":1,"foo":"bar","baz":"333","msg":"yet again"}

You can override a parent data context key, but it will write both keys to the log so no data is lost.

var log2 = log.child({ aaa: "base" });
var log3 = log2.child({ aaa: "over1" });
log3.info("try to overwrite", { aaa: "inline" });
// OUT-> {"level":3,"time":...,"aaa":"base","aaa":"over1","aaa":"inline","msg":"try to overwrite"}

Customize

This library exports the tools you need to build your own custom logger settings.

import { toJson, stringifyPairs, timeFns, mkLevel } from "json-log";

str = toJson(data)

Json stringify anything in a safe way that makes sense for logging.

str = stringifyPairs(data)

Same as toJson except ment to be a fragment worked into a larger json line.

'"foo":"bar",' === stringifyPairs({ foo: "bar" });

timeFns

export const timeFns = {
  iso: () => `"time":"${new Date().toISOString()}",`,
  now: () => `"time":${Date.now()},`,
  none: () => ""
};

fn = mkLevel(level, time, ctx, write)

This returns the logger function for a given level. See below for how it's used.

class MyAwesomeLogger {
  constructor(ctx) {
    this.ctx = ctx;

    // MyAwesomeLogger is soo much better than the default "json-log"
    // Why may you ask? Because 3 log levels are never enough!

    this.emergency = mkLevel(0, timeFns.iso, ctx, writeStdErr);
    this.panic = mkLevel(10, timeFns.iso, ctx, writeStdErr);
    this.alert = mkLevel(20, timeFns.iso, ctx, writeStdErr);
    this.critical = mkLevel(30, timeFns.iso, ctx, writeStdErr);
    this.error = mkLevel(100, timeFns.iso, ctx, writeStdErr);
    this.danger = mkLevel(110, timeFns.iso, ctx, writeStdErr);
    this.warn = mkLevel(200, timeFns.iso, ctx, writeStdOut);
    this.info = mkLevel(300, timeFns.iso, ctx, writeStdOut);
    this.debug = mkLevel(310, timeFns.now, ctx, writeStdOut);
    this.trace = mkLevel(400, () => `"t":${Date.now},`, ctx, writeStdOut);
    this.blackhole = mkLevel(666, timeFns.none, ctx, function(line) {});
  }
  child(moreCtx) {
    return new MyAwesomeLogger(this.ctx + stringifyPairs(moreCtx));
  }
}