Node.js Contextual Logging with Logfmt

logfmt-demo.js

// Demo contextual log pattern with the logfmt-node library.

var logger = require('logfmt').namespace({app: "test"});

function task(id, throwError) {
  var taskLogger = logger.namespace({event: "task.run", "task.id": id});
  var taskTimer  = taskLogger.time();

  taskLogger.log({msg: "Starting the task.", at: "start"});
  setTimeout(function() {
    if (throwError) {
      taskTimer.error(new Error("Boom!"));
    } else {
      taskTimer.log({msg: "Completed the task!.", at: "done"});
    }
  }, 1000);
}

function test() {
  logger.log({msg: "Running task that should succeed.", "task.id": 1});
  task1(1);

  logger.log({msg: "Running task that should fail.", "task.id": 2});
  task1(2, true);
}

output.sh

# Output of test() in Node console.
app=test msg="Running task that should succeed." task.id=1
app=test event=task.run task.id=1 msg="Starting the task." at=start
app=test msg="Running task that should fail." task.id=2
app=test event=task.run task.id=2 msg="Starting the task." at=start
undefined
app=test event=task.run task.id=1 msg="Completed the task!." at=done elapsed=1001ms
app=test event=task.run task.id=2 error=true id=6842017734 now=2016-04-20T19:26:53.667Z message=Boom! elapsed=1003ms
app=test event=task.run task.id=2 error=true id=6842017734 now=2016-04-20T19:26:53.667Z line=0 trace="Error: Boom!" elapsed=1003ms
app=test event=task.run task.id=2 error=true id=6842017734 now=2016-04-20T19:26:53.667Z line=1 trace="    at null._onTimeout (repl:8:17)" elapsed=1003ms
app=test event=task.run task.id=2 error=true id=6842017734 now=2016-04-20T19:26:53.667Z line=2 trace="    at Timer.listOnTimeout [as ontimeout] (timers.js:121:15)" elapsed=1003ms