In a previous post, I explained the debug module and how to use it for basic debugging.  I recently used it to help me understand complex interactions between events in Leaflet and Leaflet.Editable. Before going over that, however, I’m going to lay the groundwork with a couple organizational tips that makes debug easier to use. This post assumes you have either used debug or read the previous post….

Namespacing debug functions

The debug module has a great namespace feature that allows you to enable or disable debug functions in groups. It is very simple–you separate namespaces by colons, like this:

debug('app:meta')('config loaded')
debug('app:database')('querying db...');
debug('app:database')('got results!', results);

Enable debug functions in Node by passing the process name via the DEBUG environment variable. The following would enable the database debug function but not meta:

$ DEBUG='app:database' node app.js

To enable both, list both names, separated by commas:

$ DEBUG='app:database,app:meta' node app.js

Alternately, use the asterisk wildcard character (*) to enable any debugger in that namespace. For example, the following enables any debug function whose name starts with “app:":

$ DEBUG='app:*' node app.js

You can get as granular as you want with debug namespaces…

debug('myapp:thirdparty:identica:auth')('success!');
debug('myapp:thirdparty:twitter:auth')('success!');

…but don’t overdo it. Personally, I try not to go deeper than two or sometimes three levels.

More namespace tricks

The asterisk wildcard “*"matches a namespace at any level when enabling a debug function. Given the two debug functions above above, you can enable both by running your program with this command:

$ DEBUG='myapp:thirdparty:*:auth' node app.js

The “*" here matches identica, twitter, or any other string.

It’s often useful to enable all debug functions in a namespace with the exception of one or two. Let’s assume there are separate debug functions for each HTTP status code the app uses (a weird use of debug, but why not!):

const OK = debug('HTTP:200');
const MOVED = debug('HTTP:301');
const FOUND = debug('HTTP:302');
const UNAUTHORIZED = debug('HTTP:403');
const NOTFOUND = debug('HTTP:404');
// etc.

You can turn them all on with HTTP:*, but it turns out that 200 comes up way too frequently so you want to turn it off. Use the “-” (dash or minus sign character) prefix operator to explicitly disable a single debugger. For example, this command enables all debuggers in the “HTTP” namespace then disables just HTTP:200:

$ DEBUG='HTTP:*,-HTTP:200' node app.js

Externalizing debug functions

debug() is factory function, and thus it returns another function, that you can call to write to the console (more specifically, STDERR in Node.js):

debug('abc');        // creates function, doesn't write anything 
debug('foo')('bar'); // writes `foo: bar` (assuming that debugger is enabled)

To use this debugger, assign the function to a variable:

var fooLogger = debug('foo');

fooLogger('bar');                    // writes `foo: bar`
fooLogger('opening pod bay door...') // writes `foo: opening pod bay door...`

While it’s easy to create one-off debug functions as needed as in the first example, it’s important to remember that the debug module does not write anything unless that particular debugger is enabled. If your fellow developer does not know you created a debugger with the name foo, she cannot know to turn it on! Furthermore, she may create a debugger with the name foo as well, not knowing you’re already using that name. For this reason (read: discoverability), I recommend grouping all such debug logging functions in one file and exporting them from there:

// lib/debuggers.js
const debug = require('debug');

const init = debug('app:init');
const menu = debug('app:menu');
const db = debug('app:database');
const http = debug('app:http')

module.exports = {
  init, menu, db, http
};

Note: The code above uses ES2015 object property shorthand.

This way you can discover all available debuggers and reuse debuggers across files. For example, if you access the database in customer.js and want to log the query, simply import that debugger and use it there:

// models/customer.js
const debugDB = require('../lib/debuggers').db;
// ...

debugDB(`looking up user by ID: ${userid}`);
db.Customer.findById(userid)
  .tap(result => debugDB('customer lookup result', result))
  .then(processCustomer)
//.then(...)

Note: The code above uses the Bluebird promises library‘s tap function.

You can then use the same debugger in another file, perhaps with other debuggers as well:

// config.js
debugDB = require('../lib/debuggers').db;
debugInit = require('../lib/debuggers').init;
// ...

debugInit('configuring application...');

if(process.env !== 'DEV'){
  debugInit('env not DEV, loading configs from DB');
  debugDB('reading site config from database');
  db.Config.find()
    .tap(debugDB)
    .then(config){
      configureApp(config);
    }
}else{
  debugInit('local environment: reading config from file');
  // ...
}

Then when you’re confused why the app fails on startup on our local machine, you can enableapp:init (or app:*) and see the following in the console…

app:init env not DEV, loading configs from DB +1ms

…and quickly discover that a missing environment variable is causing the issue.

Debugging All (known) Events on an Event Emitter

Background

My goal was to run my newFeatureAdded function whenever a user created a new “feature” on the map. This example is browser-based, but the approach works just as well with Node.js EventEmiters.

When I started, I attached my newFeatureAdded function to editable:created:

map.on('editable:created', function(e){
  newFeatureAdded(e.layer);
});

But it wasn’t firing when I expected, so I added a debug function call to see what was going on:

map.on('editable:created', function(e){
  eventDebug('editable:created', e.layer);
  newFeatureAdded(e.layer);
});

This revealed that the event was fired when the user clicked “create new feature”, not when they placed the feature on the map. I fixed the issue, but I found myself adding debug function calls all over the place, with almost every event handler function:

map.on('editable:drawing:commit', function(e){
  eventDebug('FIRED: editable:drawing:commit');
  handleDrawingCommit(e);
});

map.on('click', function(e){
  eventDebug('FIRED: click');
  disableAllEdits();
});

map.on('editable:vertex:clicked', function(e){
  eventDebug('FIRED: editable:vertex:clicked');
  handleVertexClick(e);
});

This is starting to look redundant, and doubly bad as it’s forcing me to wrap the handler calls in extra anonymous functions rather than delegate to them directly, for example map.on('click', disableEdits). Furthermore, not knowing the event system well, I want to discover other events that fire at times that might be useful.

Another Approach…

To build my UI, I needed to understand the interactions between Leaflet’s 35 events and Leaflet.Editable’s 18 events, that overlap, trigger one another, and have somewhat ambiguous names (layeradd, dragend, editable:drawing:dragend, editable:drawing:endeditable:drawing:commit, editable:created, and so on.)

I could pore over the docs and source code to find the exact event for each eventuality… or I could attach debug loggers to all events and see what happens!

The approach is:

  1. Create an array of all known events.
  2. Create a debug function for each event.
  3. Attach that function to the target event emitter using .on.
// 1. Create list of events
const leafletEditableEvents = [
  'editable:created',
  'editable:enable',
  'editable:drawing:start',
  'editable:drawing:end',
  'editable:vertex:contextmenu',
// ...
];

const leafletEvents = [
  'click',
  'dblclick',
  'mousedown',
  'dragend',
  'layeradd',
  'layerremove',
// ...
];

To use the event debugging tool on any event emitter, I’ll make a function that takes the target object and events array as arguments:

function debugEvents(target, events){
  events
    // 2. Create debug function for each
    // (but keep the function name as well! we'll need it below)
    // return both as { name, debugger }
    .map(eventName => { return { name: eventName, debugger: debug(eventName) }; })
    // 3. Attach that function to the target
    .map(event => target.on(event.name, event.debugger));
}

debugEvents(mapObject, leafletEditableEvents);
debugEvents(mapObject, leafletEvents);

Assuming I set localStorage.debug='*' in the browser console, I will now see a debug statement in the console when any of the Leaflet.Editable events fire on the map object!

debugger output in console

Note that the data that .on() passes to an event handler target is also passed to the debug functions.

In this case it’s the event object created by Leaflet, shown above in the console as ▶ Object.

mousemove etc. are not in any namespace above, and it’s best to always namespace debug functions so they don’t collide, to add context, and to allow enabling/disabling by namespace. Let’s improve our debugEvents function to use a namespace:

function debugEvents(target, events, namespace){
  events
    .map(eventName => { return {
      name: eventName,
      debugger: debug(`${namespace}:${eventName}`)
    } } )
    .map(event => target.on(event.name, event.debugger));
}

//editable events already prefixed with "editable", so "events:editable:..."
debugEvents(mapObject, leafletEditableEvents, 'event');
//map events not prefixed so we'll add `map`, so they're "events:map:..."
debugEvents(mapObject, leafletEvents, 'event:map');

You can enable all event debuggers in the console, or just editable events, or just core map events, thus:

> localStorage.debug = 'event:*'
> localStorage.debug = 'event:editable:*'
> localStorage.debug = 'event:map:*

Conveniently, the Leaflet.Editable events are all already “namespaced” and colon-separated, just like our debug namespaces!

> localStorage.debug = 'event:editable:*' //enable all editable
> localStorage.debug = 'event:editable:drawing:*'  //just editable:drawing events

Fine-tuning the output

Let’s enable all event debuggers and see what some interactions look like…

gif of debugger output with rapidly flowing debug statments during user interaction with map. Lots and lots of "event:map:mousemove" events.

Looks nice, but the mousemove events are coming so fast they push everything else out of the console–they are basically noise. Some trial and error taught me it that drag events are equally noisy and I don’t need to know the core map events most of the time, just the editable events.

So I can reduce logging to just what I need, enabling only editable:events and ignoring all “drag” and “mousemove” events:

> localStorage.debug = 'event:editable:*,-event:*:drag,-event:*:mousemove

gif of debugger output with a smaller number of events. Console screen does not overflow

Looks good!

Conclusion

While debug is a very small module and easy to get started with, you can tune it in very granular ways and this makes it a powerful development tool. By attaching debug statements to all events, outside of our application code, you can trace the path of an event system and better understand how events interact, without adding any debug statements into your application code. If you’ve found another novel use of this library or have any questions about my post, let me know. Happy logging!

Note: I use the term “debugger function” and “debug logging” rather than “debugger” and “debugging” in this post advisedly. A “debugger” typically refers to a tool that can be used to pause execution and alter the code at runtime, for example the VSCode debugger. What we’re doing here is “logging.”