Debug as Code

Long have the days been using console.log to debug JavaScript code. Local or production, front or back end, it just works. In this post I will try to persuade you to try a different approach to debug logging that your future self will be proud of.

Don't get me wrong, I love me some console.log. There is something elegant about its simplicity and portability. Drop it in the browser console or your Node backend and you've got instant insight into the runtime state of your code.

The Problem

While helpful for debugging, console.log statements are noisy.

Almost every JS project I've worked on in recent years has had some sort of linting rule that disallows console.log statements to be checked into the code base. In general, that is a good practice because displaying any non-critical messages in production will bloat logging and introduce a butt-ton of useless noise 🔊.

For example, here is a small console excerpt from ESPN.com 🤮:

I can almost hear the developer's crying and log service budgets overflowing.

The lesson here being that you should avoid committing console.log statements to your code base.

🔴 What about breakpoints?

At this point you might be thinking..

Couldn't we open up the production code in Dev Tools and drop a breakpoint in there?

Kinda but not really. Production code is almost always mangled and minified. In my experience there is a 50/50 chance that source maps of the original code are available.

Let's say for a moment you're lucky and you have source maps. You place a breakpoint exactly where you think a bug originates. More often than not it's only the tip of the iceberg. So then you dive deeper and place another breakpoint. Rinsing and repeating until you find the source of the bug. All the while you are tripping over your own breakpoints, accidentally stepping into jQuery's internals, and losing context along the way.

Keep in mind, breakpoints can only be used in the browser. Backend code is inaccessible in this way. So even if this completely solved the problem for the client it's only half the equation.

There has to be a better way that works on both client and server.

Enter the debug logging package.

👼 Debugging with debug

A few years back I stumbled upon debug by Sindre Sorhus (a.k.a the Man of a Thousand npm packages).

The debug library is not your typical logging package. It does not display, record, track, or ship any logs. It is a noop by default. Only when you enable it via an environment variable does it produce anything.

⛺ Setup

import debug from 'debug';

const log = debug("apollo"); // an arbitrary namespace

log("✅ We're cleared for launch"); // log something

Maybe to your surprise, the above code will not log anything. As I mentioned before, we have to turn on debug logging first.

This is done differently depending on your environment.

For example:

• On the server: export DEBUG=apollo
• In the browser: localStorage.debug = 'apollo'

For simplicity we can assume logging is enabled for the rest of this post.

👾 Namespacing

Continuing with our code above we add another log instance with a different namespace.

import debug from 'debug';

const log = debug("apollo");
const logLaunch = debug("apollo:launch");

log("✅ We're cleared for launch");
logLaunch(`⏳ T-minus 10 seconds`);
// ...waits 10 seconds
logLaunch("🚀 We have lift-off");

That in turn yields the following log messages:

Right away you'll notice we get some nice information here.

• Namespaces are colored uniquely to make them easier to differentiate
• Each statement is suffixed by the elapsed time between log messages

For what it's worth, you can log objects like console.log too.

log("📨 Form values", { values });

...but wait there's more

🧮 Wildcard Filtering

Remember the environment variable we set to enable logging? The value of that variable can be a wildcard string.

Let me explain with a few examples.

Assuming in the browser we set localStorage.debug to the one of the following:

• apollo - only log the apollo namespace
• apollo:* - log any namespace starting with apollo:
• apollo:*,-*launch* - log any namespace starting with apollo:, excluding any namespaces that contain launch

This proves quite powerful.

💼 A real use case

Imagine you are creating a new React AirScrubber component. Internal to that component you namespace a log instance apollo:air-scrubber. Then as you develop the component you add debug messages throughout. These act as a sort of CliffNotes for your component.

const log = debug("apollo:air-scrubber");
const logInit = debug("apollo:air-scrubber:init");
const logScrub = debug("apollo:air-scrubber:scrub");

const init = (config) => {
  logInit("🗂️ Air scrubber initializing...", { config });
  // Do initialization work...
  logInit("👍 Air scrubber initialized");
};

const isAirQualityLow = () => { ... };

const scrub = () => {
  logScrub("🧽 Scrubbing air...");
  // Do scrub work
  logScrub("🏁 Air scrubbed.");
}

const AirScrubber = () => {
  init();

  if (isAirQualityLow()) {
    log("🚬 Air quality is low. Starting to scrub...");
    scrub();
  }
};

export { AirScrubber };

Fast forward to the future... 💥 a user discovers there's an AirScrubber bug in production.

Don't panic. We have a way to triage that component quickly and precisely.

Here's how:

1. Open your Dev Tools console

2. Run the following
   

   localStorage.debug = 'apollo:air-scrubber*';
   

3. Interact with the component and now you'll see all the detailed debug logs you wrote during local development without having to rely on source maps, breakpoints, or even our old friend console.log

4. Receive high fives from your peers and future self

💻 What about server side?

Much like in Dev Tools, we're going to set the DEBUG environment variable on the server to whatever granularity we choose to enabled debug logging. Once we've done that we have to restart the app to pickup the new value and tail the output.

The debug messages will output the same look and feel we saw on the client.

📘 Summary

Using console.log...

• Produces all the log messages - all the time
• Is noisy and covers up potential issues
• Should not be committed to code base

Using debug...

• Allows developers to bake in logging without having to worry about bloat in production
• Allows for conditional verbosity (log only what you want)
• Provides logging granularity to complex systems via namespacing
• Displays log messaging with higher readability
• Allows us to debug the same way we do in local development
• Should be committed to code base

👷‍♂️ Take Action

Next time you find yourself writing console.log, take a moment to consider the value of the messaging.

• Will this message help me debug in the future?
• Will this help a new hire understand the system in the future?

If the answer is yes to either question, please consider replacing it with a debug log instead.

These debug messages will prove to be invaluable the next time you track down a bug.

Am I wrong? Agree with me? Got questions? Drop me a line in the comments, leave me a big squishy ♥️ and/or a glitter pooping 🦄.

Today's post was brought to you by VSCode's "open focused file in explorer" shortcut: Command + Down Arrow