February 7th, 2022
As developers it is extremely difficult to debug bugs in our applications without some sort of logging mechanism.
This is because logs can capture any point of time in our code and capture stack traces or useful information on the current state of our app life cycle which can be used to trace state back in time.
In this post we will go over several convenient tactics of logging in both nodejs and browser environments in JavaScript.
As our projects become larger over time, establishing logs to track our code becomes increasingly important as our code becomes more complex. Increase in code complexity results to increased difficulty in maintenance and readability to our code.
When unexpected behavior occurs, there's no better way to track changes than logging.
Lets take a look at an example below:
// For the sake of this post I am using these two lines to simulate a browser environment
require('jsdom-global')()
const fetch = require('node-fetch').default
function fetchCats() {
return new Promise((resolve, reject) => {
fetch('https://api.thecatapi.com/v1/images/search?limit=10')
.then((resp) => resp.json())
.then((results) => resolve(results))
.catch(reject)
})
}
class GalleryPages {
constructor(items) {
this.items = items
}
build() {
const wrapper = document.createElement('div')
for (const item of this.items) {
const img = document.createElement('img')
img.width = item.width
img.height = item.height
img.src = item.src
wrapper.appendChild(img)
}
return wrapper
}
}
fetchCats()
.then((cats) => {
return cats.map((cat) => ({
src: cat.url,
width: cat.width,
height: cat.height,
}))
})
.then((cats) => {
const createPage = (child) => {
const container = document.createElement('div')
container.style.width = '250px'
container.style.maxHeight = '250px'
container.style.border = '1px solid magenta'
container.style.margin = '15px 0px'
container.style.position = 'relative'
container.style.overflowX = 'hidden'
container.style.display = 'inline-block'
container.appendChild(child)
document.body.appendChild(container)
return container
}
let elements = []
let cat = cats[cats.length - 1]
while (cats.length) {
const page = new GalleryPages([cat])
elements.push(createPage(page.build()))
cat = cats.pop()
}
return elements
})
.catch((error) => console.error(error))
The behavior we expect is that for every cat image fetched we create a new element containing a single img
element which will eventually be grouped into a "gallery-like" view. Every image should be displayed visually the same size when displaying in the client and every image should be different:
However the first two images are duplicates. By placing simple loggers in our code it provides a shortcut to pinpointing where the bug starts:
{
src: "https://cdn2.thecatapi.com/images/XT3M3LXmE.jpg",
width: 259,
height: 194
}
{
src: "https://cdn2.thecatapi.com/images/XT3M3LXmE.jpg",
width: 259,
height: 194
}
{
src: "https://cdn2.thecatapi.com/images/yeauSxGXb.jpg",
width: 1500,
height: 1124
}
{
src: "https://cdn2.thecatapi.com/images/dfn.jpg",
width: 450,
height: 569
}
{
src: "https://cdn2.thecatapi.com/images/bl9.jpg",
width: 468,
height: 498
}
{
src: "https://cdn2.thecatapi.com/images/bba.jpg",
width: 500,
height: 333
}
{
src: "https://cdn2.thecatapi.com/images/a88.jpg",
width: 1200,
height: 930
}
{
src: "https://cdn2.thecatapi.com/images/a6s.jpg",
width: 450,
height: 300
}
{
src: "https://cdn2.thecatapi.com/images/9tb.jpg",
width: 612,
height: 612
}
{
src: "https://cdn2.thecatapi.com/images/2lv.png",
width: 500,
height: 333
}
The first two objects are the same so we can immediately look into how our for loop starts:
The issue now becomes obvious. Each loop expects to begin with an object that was pulled
from the array. Each loop expects the array to have been mutated, so we need to mutate the array instead:
In modern applications performance is a top concern if we want our apps to stay competitive. As developers it is our responsibility to keep our users happy and it all starts with code. By utilizing the console
we can log the performance in different parts of our code.
Logs are a lot more useful than we expect. Even placing random logs throughout our code gives us information we can use to improve our app.
We can use our logging information to find out things like:
The list goes on.
console.assert
is useful to write error messages to the console (commonly used to validate inputs or output in our functions) if an assertion fails or is false
. Otherwise nothing will happen. This provides sort of a "lazy loading" feel in comparison to the generic console.log
which makes it easier to avoid more memory usage.
console.clear
can be used to clear the console. This is useful when you come across situations where you realize you have too much logs and want to place it right before a function you're debugging to ensure that the first message you see in the console is straight from the function. This helps to avoid unnecessarily scrolling up and down to find that needle in the haystack.
console.error
can also help log messages to the console but in the browser console it actually displays messages that look like errors due to them being in red backgrounds. In most cases this is sufficient. But there are some cases where we'll still choose a fancier way like console.log('%c"obj" is not an object', 'color:red;font-weight:400', obj)
to display error messages.
console.debug
outputs messages to the console in the "verbose" level. Libraries utilize this method to log more technical information for developers who want to dig deeper into the technical details beneath the hood in the library they're using.
console.dir
can be used to display anything to the console in addition to being able to display all properties of objects to the console (configurable with the depth
option). If used in the browser, the objects we use in console.dir
can be interactive where we can click through properties/methods while having the ability to expand/collapse them:
console.group
and console.groupEnd
can be used to wrap multiple logs inside a wrapped "container" where each line can be indented, simulating the "grouping" effect in the console:
const obj = {
myProfile: {
firstName: 'Kelly',
lastName: 'Vaughn',
age: 31,
},
myFavoriteFood: {
fruits: ['strawberry', 'raspberry'],
meat: ['steak'],
},
}
console.group('hello')
console.log(obj.myProfile.firstName)
console.log(obj.myProfile.lastName)
console.log(obj.myFavoriteFood)
console.log(obj.myProfile.age)
console.groupEnd()
What I find interesting about console.group
is that we can use it multiple times to nest/indent underlying messages if needed:
console.group('')
console.group('hello')
console.log(obj.myProfile.firstName)
console.log(obj.myProfile.lastName)
console.group('')
console.group('hello')
console.group('')
console.log(obj.myFavoriteFood)
console.log(obj.myProfile.age)
console.group('')
console.group('')
console.groupEnd()
Sometimes we can get too carried away and log too much information. This impacts runtime performance especially when we include large objects in our logs.
Logging is very useful in NodeJS. But there are times when they aren't useful. However there are also opportunities for us to make some of these logs that aren't useful to become useful.
Lets look at this example below:
class Profile {
#firstName
#lastName
#familyMembers
constructor(firstName, lastName) {
this.#firstName = firstName
this.#lastName = lastName
this.#familyMembers = []
}
get firstName() {
return this.#firstName
}
get lastName() {
return this.#lastName
}
get fullName() {
return `${this.firstName} ${this.lastName}`
}
addFamilyMember(profile) {
this.#familyMembers.push(profile)
}
}
When we create instances of Profile
and log each instance to the console, we want to see useful information like firstName
, lastName
, fullName
, and all the familyMembers
in the output.
But what happens is that when they're showing in the console this is the kind of information we are given:
const myProfile = new Profile('Kelly', 'Gonzalez')
console.log(myProfile)
So how can we make this output useful information? Well, thankfully NodeJS provides a helpful way for us to customize the output of objects.
Inspect
(Recommended: Create a global User Snippet)To customize output of objects in the console, we can attach a Symbol
with the value "nodejs.util.inspect.custom"
like so:
class Profile {
#firstName
#lastName
#familyMembers;
[Symbol.for('nodejs.util.inspect.custom')]() {
return this.toJSON()
}
constructor(firstName, lastName) {
this.#firstName = firstName
this.#lastName = lastName
this.#familyMembers = []
}
get firstName() {
return this.#firstName
}
get lastName() {
return this.#lastName
}
get fullName() {
return `${this.firstName} ${this.lastName}`
}
get familyMembers() {
return this.#familyMembers
}
addFamilyMember(profile) {
this.#familyMembers.push(profile)
}
toJSON() {
return {
firstName: this.firstName,
lastName: this.lastName,
fullName: this.fullName,
familyMembers: this.familyMembers.map((profile) => profile.toJSON()),
totalFamilyMembers: this.familyMembers.length,
}
}
}
const myProfile = new Profile('Kelly', 'Gonzalez')
const lisa = new Profile('Lisa', 'Gonzalez')
const melon = new Profile('Melon', 'Gonzalez')
const george = new Profile('George', 'Gonzalez')
myProfile.addFamilyMember(lisa)
myProfile.addFamilyMember(melon)
myProfile.addFamilyMember(george)
george.addFamilyMember(new Profile('Terrence', 'Gonzalez'))
console.log(myProfile)
Logging our Profile
instance to the console can display information the way we want:
{
"firstName": "Kelly",
"lastName": "Gonzalez",
"fullName": "Kelly Gonzalez",
"familyMembers": [
{
"firstName": "Lisa",
"lastName": "Gonzalez",
"fullName": "Lisa Gonzalez",
"familyMembers": [],
"totalFamilyMembers": 0
},
{
"firstName": "Melon",
"lastName": "Gonzalez",
"fullName": "Melon Gonzalez",
"familyMembers": [],
"totalFamilyMembers": 0
},
{
"firstName": "George",
"lastName": "Gonzalez",
"fullName": "George Gonzalez",
"familyMembers": "[Array]",
"totalFamilyMembers": 1
}
],
"totalFamilyMembers": 3
}
I recommend to bind this to a custom User Snippet because if you're like me you will be using this every time for a more productive development experience.
It's worth mentioning that [Symbol.for('nodejs.util.inspect.custom')]() {}
also comes with 3 arguments:
[Symbol.for('nodejs.util.inspect.custom')](depth, inspectOptions, inspect) {}
You can find out more about these arguments here.
Our previous examples are nice because we can analyze logging in real time while we develop our apps.
However there are times we want to see logs in our automated scripts (such as having a script fetch data every 15 minutes) which we aren't analyzing in runtime anymore.
By default, the Console
constructor in NodeJS logs to the terminal by piping its output to stdout
and stderr
. We can actually configure these two to pipe its output somewhere else, like a file:
const logOutput = fs.createWriteStream(path.join(__dirname, 'logs.json'))
const log = new Console({ stdout: logOutput })
const output = []
output.push(myProfile.familyMembers[0].toJSON())
output.push({ timestamp: new Date().toISOString() })
log.info(JSON.stringify(output, null, 2))
Result:
pino-http [pino] provides a library to tap into the expressjs request pipeline as a middleware to log anything we want from http requests.
file-stream-rotator can be used in conjunction with logging middleware in server apps that keeps their logs inside a file. It aims to provide an automated rotation of Express logs on a regular basis that needs to be rotated based on date, a size limit or combination and remove old log files based on count or elapsed days.
log-update allows developers to simulate a progress bar or customized animations in the terminal by taking advantage of node's stdout
and stderr
(the same I/O Console
uses)
roarr logs information as JSON which supports both nodejs and browser environments
logdown.js provides a logging mechanism for both node and browser environments in addition to supporting markdown syntax.
And that concludes the end of this post! I hope you found this to valuable and look out for more in the future!
Tags
© jsmanifest 2023