Back to blog overview

October 5, 2020

Debug as Code

Nate Clark

&

&

Senior Software Engineer
Norton, OH

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](https://developer.mozilla.org/en-US/docs/Web/API/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](https://developers.google.com/web/tools/chrome-devtools) 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](https://www.html5rocks.com/en/tutorials/developertools/sourcemaps/) 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](https://www.npmjs.com/package/debug) logging package.

## 👼 Debugging with `debug`

A few years back I stumbled upon `debug` by [Sindre Sorhus](https://sindresorhus.com/about) (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](https://dev.to/praneshpsg239/noop-in-javascript-478h) by default. Only when you enable it via an environment variable does it produce anything.

## ⛺ Setup

```js
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.

```js
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.

```js
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](https://www.cliffsnotes.com/) for your component.

```js
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
```bash
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](https://dev.to/n8io/debug-as-code-15mn#wildcard-filtering) 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.

---

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

Let's Chat

Are you ready to build something brilliant? We're ready to help.

Thank you! Your submission has been received!
Oops! Something went wrong while submitting the form.
RedwoodJS Logo
RedwoodJS
Conference

conference
for builders

Grants Pass, Oregon • September 26 - 29, 2023
View All