Useful Strategies to Use Console Logging More Efficiently

Without some sort of logging mechanism applied to our applications it becomes extremely difficult to debug various bugs as developers.

Logs can capture any exact point in time in our code and output useful stack traces or information on the current state of our app life cycle which can be used to trace state back in time.

We will be going over several powerful tactics of logging in nodejs as well as browser environments in JavaScript.

Tracking / Debugging

When code grows larger in size, managing logs become increasingly important. With any code base, the difficulty of code management grows in conjunction with code size. When we need to track several parts of our app ideally we want the code to be as small as possible to make it easier to navigate our project easier. This issue is made worse when we add the console logs everywhere.

When unexpected behavior occurs, the best way to track what changes are made over time are writing logs because in this moment the more information we have the valuable it becomes.

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.

The method on the console object to log this information is console.time and console.timeEnd. Using these two methods we can wrap an arbitrary amount of functions and log the performance of each of them to the console:

console.log('')
console.log('')
console.log('')

const rootEl = document.createElement('div')

document.body.appendChild(rootEl)

function start() {
  function appendUsingCallback(callback) {
    for (let i = 0; i < 1000; i++) {
      callback(i)
    }
  }

  function appendDirectly() {
    for (let i = 0; i < 1000; i++) {
      const btn = document.createElement('button')
      btn.id = String(i)
      rootEl.appendChild(btn)
    }
  }

  let counter = 3

  while (counter !== 0) {
    rootEl.textContent = ''

    console.time('add-elements-using-callback')

    appendUsingCallback((index) => {
      const btn = document.createElement('button')
      btn.id = String(index)
      rootEl.appendChild(btn)
    })

    console.timeEnd('add-elements-using-callback')

    console.time('add-elements-directly')

    appendDirectly()

    console.timeEnd('add-elements-directly')

    --counter
  }
}

start()

console.log('')
console.log('')
console.log('')

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.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.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.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.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.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 get too carried away and log too much information. This impacts runtime performance especially with large objects carried in our logs.

Logging is always useful in NodeJS but there are times when they aren't. However there are also opportunities 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 of the familyMembers in the output.

But when it's displayed to the console we are not given anything useful:

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.

Navigation

In my experience when there are times where we do need to be spamming logs to the console, too many logs at once becomes harder to read.

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.

There are also 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!