Gleb Bahmutov PRO
JavaScript ninja, image processing expert, software quality fanatic
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)
})
})
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.
