Log it like you mean it

Gleb Bahmutov

@bahmutov

gleb.dev

Boston Node Meetup

  • Good logging

  • Server logs for API testing

  • Important stuff

  1. Crash happens 💥

  2. You look at the logs before the crash 📜

  3. Profit 💵

Every day

IF you can diagnose the problem from the logs

Format your data

const x = {foo: 'bar'}
// logs x as JSON object
console.log('x is %j', x)
// x is {"foo":"bar"}

Format your data

%s - String.
%d - Number.
%i - Integer.
%f - Floating point value.
%j - JSON.
%o - Object.

Single log per message

console.log('user is %o account info is %o', 
  user, account)

Makes it extremely searchable from good logging service (LogDNA)

Single log per message

console.log('user %o', user) // 👎
// make text unique
console.log('logged in user is %o', user) // 👍

Makes it extremely searchable from good logging service (LogDNA)

Single log per message

// if you have to
console.log('%o', { user, account })

Log as object for key names

Do not use "console.log"

Nested object will generate "[Object object]"

Long messages will be split across lines

USE "debug" module

// npm i -S debug
const debug = require('debug')('foo')
const x = 42
debug('x = %i', x)

USE "debug" module

// server/account.js
const debug = require('debug')('server:account')

// server/role.js
const debug = require('debug')('server:role')
DEBUG=server:account,server:role node ./server
DEBUG=server:* node ./server
DEBUG=server:*,-server:role node ./serve

USE "debug" module

$ DEBUG=foo DEBUG_DEPTH=10 node .
  foo x = { foo: { bar: { q: { x: { y: 'baz' } } } } } +0ms

✅ Never splits a single message across lines

✅ Print deeply nested objects

replace console.log with debug log

const debug = require('debug')('foo')
const alwaysLog = require('debug')('*')
const x = {foo: {bar: 'baz'}}
debug('x = %o', x)
alwaysLog('value x = %o', x)
$ node .
  * value x = { foo: { bar: 'baz' } } +0ms

log resolved value or error

Promise = require('bluebird')
const debug = require('debug')('api')
const debugOneLine = (x) => debug('%o', x)
foo() // returns a Bluebird promise instance
  // logs the resolved value
  .tap(debugOneLine) 
  // logs the error
  .tapCatch(debugOneLine)
  // continue with the promise as usual

Logging is expensive ⏱

⚠️ this is your production code

check out http://getpino.io

there is pino-debug

Up to 10x faster than using debug (20x in extreme mode!)

log from tests

const debug = require('debug')('test')
it('works', () => {
  const result = foo()
  debug(result)
  assert(...)
})
const verbose = require('util').debuglog('verbose')
verbose('my message %d', 42)
$ node ./using-util.js 

$ NODE_DEBUG=verbose node ./using-util.js 
VERBOSE 74312: my message 42

Why did this test fail?

  1. test fails 💥

  2. rerun the test with DEBUG=* ...

  3. find the root cause

Why can't you run all tests with full debug logs all the time?

  1. test fails 💥

  2. rerun the test with DEBUG=* ...

  3. find the root cause

Terminal becomes a noisy mess

capture console logs

const util = require('util')
const methodNames = ['log', 'warn', 'error']
const messages = []

methodNames.forEach(methodName => {
  const originalMethod = (global.cnsl[methodName] = console[methodName])

  console[methodName] = function () {
    const params = Array.prototype.slice.call(arguments, 1)
    const message = params.length
      ? util.format(arguments[0], ...params)
      : arguments[0]
    messages.push({
      type: methodName, // "log", "warn", "error"
      message
    })

    // call the original method like "console.log"
    originalMethod.apply(console, arguments)
  }
})
const restore = () => ...

process.on('beforeExit', () => {
  restore()
  console.log('*** printing saved messages ***')
  messages.forEach(m => {
    console.log('%s: %s', m.type, m.message)
  })
})

proxy console.log, console.warn, console.error

print saved logs

capture console logs

const x = {foo: 'bar'}
console.log('x is %j', x)
$ node -r ./log .
x is {"foo":"bar"}
*** printing saved messages ***
log: x is {"foo":"bar"}

require log before program

$ node -r ./log .
$ node --require ./log .
$ ./node_modules/.bin/mocha ...

#!/usr/bin/env node

$ node -r ./log ./node_modules/.bin/mocha

Proxy console.{log, warn, error}

Proxy debug instances

(tricky but works)

Proxy util.debuglog instances

(works)

@bahmutov/all-logs

Utility method to capture all Node logs:

console, debug, util.debuglog

npm install --save @bahmutov/all-logs
{
  "scripts": {
    "start": "node -r @bahmutov/all-logs ./lib/server.js"
  }
}

The logs are just sitting there

@bahmutov/all-logs

Utility method to capture all Node logs:

console, debug, util.debuglog

if (global.messages) {
  require('@bahmutov/all-logs/middleware/express')(app)
}

Adds /__messages__ endpoint

server example

const verbose = require('debug')('verbose')
const debug = require('util').debuglog('hello')
const express = require('express')
const app = express()
const port = 3003

if (global.messages) {
  require('@bahmutov/all-logs/middleware/express')(app)
}

const answer = 'Hello World!'

app.get('/', (req, res) => {
  // 3 different types of logging
  console.log('processing %s %s', req.method, req.path)
  verbose('processing /')
  debug('server responding with %s', answer)

  res.send(answer)
})

app.listen(port, () => console.log(`Example app listening on port ${port}!`))

end-to-end API testing

it('calls API method', () => {
  cy.api(
    {
      url: '/'
    },
    'hello world'
  )
})

Cypress + cy-api plugin for API testing

npm i -D cypress @bahmutov/cy-api

request

response

server logs

@bahmutov/all-logs + @bahmutov/cy-api combo

you have logs in the test

it('yields result that has log messages', () => {
  cy.api(
    {
      url: '/'
    },
    'hello world'
  ).then(({ messages }) => {
    console.table(messages)
  })
})

Logging is important

use debug or any other dedicated logging module

you can capture all logs and use them during api tests

Log it like you mean it

By Gleb Bahmutov

Log it like you mean it

There is a world beyond simple "console.log" statements. In this talk, I will show the best practices for logging from Node programs. Good logs are essential when trying to understand the real-world behavior of your program, debugging a failure and even during API testing.

  • 146
Loading comments...

More from Gleb Bahmutov