Convenient Tactics of Logging in NodeJS and JavaScript in the browser

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.

Tracking / Debugging

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:

Performance

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.

Analyzing

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:

• Duplicate requests
• Memory leaks
• Unnecessary variables
• Typos
• Reminding us on revisiting todos
• Trace function calls
• Unexpected behavior

The list goes on.

Important Logging Methods

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()

Tactics

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.

Automation

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:

Loggers in practice

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.

Conclusion

And that concludes the end of this post! I hope you found this to valuable and look out for more in the future!