Log it like you mean it
Gleb Bahmutov
@bahmutov
gleb.dev
Boston Node Meetup
-
Good logging
-
Server logs for API testing
-
Important stuff
-
Crash happens 💥
-
You look at the logs before the crash 📜
-
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 ./serveUSE "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' } } +0mslog 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 usualLogging 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 42Why did this test fail?
-
test fails 💥
-
rerun the test with DEBUG=* ...
-
find the root cause
Why can't you run all tests with full debug logs all the time?
-
test fails 💥
-
rerun the test with DEBUG=* ...
-
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/mochaProxy 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)
})
})
