Ten tips for coding with Node.js #1: develop debugging techniques

By: David Mark Clements

Welcome to this new series of blog posts. The series is based on a list of ten recommended practices or tips to help you in your journey with Node.js.

nearForm staff train and consult with teams all over the world. Our experts also host and speak at various conferences throughout America and Europe on a regular basis. This means that I frequently get to speak with developers on the front line.

When developers begin to share their questions, needs and frustrations with me, it gets my attention. This is partly because one of my roles is to curate our training material, but also because I’ve been there, had the same questions, and shared the same frustrations and needs.

In response to these conversations, I’ve compiled the following list of ten Node.js tips:

  1. Develop debugging techniques
  2. Avail and beware of the ecosystem
  3. Know when (not) to throw
  4. Reproduce core callback signatures
  5. Use streams
  6. Break out blockers
  7. Deprioritize synchronous code optimizations
  8. Use and create small single-purpose modules
  9. Prepare for scale with microservices
  10. Expect to fail, recover quickly

Let’s kick off our series with the first tip on the list.

Tips for Node.js

Develop debugging techniques

Interactive debugging

Let’s begin with the fundamentals.

Node has a built-in debugger. For those of you who have worked with lower-level languages, like C/C++, the built-in Node debugger may feel familiar. It resonates with the likes of GDB or LLDB:

$ node debug myApp.js

Node.js developers tend to have diverse backgrounds. If you’re one of those who is comfortable with debuggers like LLDB, the built-in Node debugger may suit you down to the ground. However, a large number of migrators to Node.js come from the front end or from languages that tend to be accompanied by powerful IDEs. These developers may prefer a more visual debugging experience. Enter node-inspector:

$ npm -g i node-inspector
$ node-debug myApp.js

The node-inspector  module hooks up Node’s remote debug API with a now slightly aging version of Chrome Devtools, connecting to it via web sockets. Essentially, we can debug and control a process the same way as we debug a web app. This is manna from heaven for those already familiar with Devtools.

While it is present in the provided Devtools UI, node-inspector does not provide profiling. However, webkit-devtools-agent covers Devtools-based heap and CPU profiling.

Debug logs

You can enable core API debug information using the NODE_DEBUG environment variable:

$ NODE_DEBUG=http,net node server.js

Debug information is supported for the following internal mechanisms: * fs, * http, * net, * tls, * module and * timers.

Similarly, the non-core debug module can be used to implement the same pattern as core, with a DEBUG environment variable:

$ npm install debug --save
var debug = require('debug');
var log = debug('myThing:log');
var info = debug('myThing:info');
var error = debug('myThing:error');
log('Squadron 40, DIVE!!!');
info('Gordon\'s ALIVE!');
error('Impetuous boy!');

Just like internal debug output, the debug module creates log output on a per-namespace basis. You do this by requiring the module, creating logger functions, and passing them a namespace during initialization. Log functions are essentially no-ops unless the DEBUG environment variable enables a log:

$ DEBUG=myThing:info node app.js

The DEBUG variable can contain wildcards; for instance, DEBUG=* turns on all debug and DEBUG=myThing:* turns on any debug namespaces prefixed with myThing:.

In the example above, we set up log, info and error loggers. However, in larger apps that are subdivided by library modules, we could sub-namespace by the name of each module, affording granular, specific debug output.

Debugging Node.js

Stack traces

The default stack trace limit for Node.js is ten frames. Of course, it requires some internal state management to keep track of stack frames, so the higher the tracing limit, the greater the performance hit.

A good Node app is composed of lots of small modules, which in turn tend to rely on lots of other small modules. This generally means that a full stack trace would consist of more than 10 frames:

$ node -e "function x() { --x.c ? x() : u } x.c=100; x()"

The -e flag here tells Node to evaluate the subsequent string. The code in that string causes x to be called 100 times. 99 times x is calling itself, which creates a stack frame each time. The result is a stack that is much larger than ten frames.

In production, we would probably prefer to keep the stack trace depth low. However, for debugging purposes we can set the stack trace limit to a higher number, using the --stack_trace_limit v8 flag:

$ node --stack_trace_limit=200 -e "function x() { --x.c ? x() : u } x.c=100; x()"

The stack trace limit can also be set in process. We do this by setting the stackTraceLimit property on the native global Error object:

$ node -e "Error.stackTraceLimit=200; function x() { --x.c ? x() : u } x.c=100; x();"

This can be useful in certain cases where the Node binary is executed indirectly—for example, when a Node script is spawned as a child process or when an executable script is called from the command line (executable scripts use the #!/usr/bin/env node hashbang, which is essentially indirect execution of node). In these cases, flags aren’t passed to the Node executable. A quick and easy solution is to set the Error.stackTraceLimit property.

Unlike the --stack_trace_limit flag, Error.stackTraceLimit can be set to Infinity for the longest possible stack traces. This can be useful when we don’t or can’t know how long the stack trace will be:

node -e "Error.stackTraceLimit=Infinity; function x() { --x.c ? x() : u } x.c=Math.floor(Math.random()*1e3); x();"

Of course, we could achieve the same with the --stack-trace-limit by setting it to an arbitrarily super-high number, but setting Error.stackTraceLimit to Infinity is more elegant. However, a flag is much easier to keep out of production. If you’re setting trace limits in code, I recommend running it through a build process that strips Error.stackTraceLimit.

Node.js tips

Asynchronous stack traces

The asynchronous nature of JavaScript is made possible by the event loop. The event loop is an infinite loop that processes event queues. Certain actions in one iteration of the loop can lead to events being processed in a future iteration (an iteration is known as a tick). For instance, while an AJAX request would be part of one event queue, the handling of the response would appear in a later tick and would therefore be part of a different queue.

Stack traces are intrinsically tied to the event queue. By default, we can’t trace a series of operations across separate ticks.

Going back to the AJAX example, if the callback handler for that request causes a throw, the stack trace will only lead back to whatever function ultimately triggered the request callback. It won’t transfer to a tick that occurred in the past.

The longjohn module allows us to trace calls across ticks:

$ npm install longjohn
$ node -e "require('longjohn'); function x() { --x.c ? setImmediate(x) : u } x.c=10; x()"

Our evaluated code is similar here to previous examples, except that subsequent calls to the x function are made via setImmediate. This is an asynchronous operation that means ‘do some work at the beginning of the next tick’.

As with deep stack traces, asynchronous tracing capabilities should be removed before production, as longjohn comes with a significant performance hit.

Cleaner stacks

This is the tiny cute-stack module:

npm install cute-stack --save

cute-stack applies assorted strategies to making stack traces more descriptive and visually clearer. It works for most kinds of trace origins, such as throw, console.trace, and Error().stack, try{}catch(e) {e.stack}. The only traces that cute-stack does not catch are during parse stage, where a syntax error occurs before cute-stack has initialized.

Example of cute-stack output

Example of cute-stack output

 

cute-stack supplies a variety of output formats for improved human-parseable output, such as colored output, tables and JSON.

If a function doesn’t have a name, but exists as a method on an object, cute-stack uses the method name instead. Failing that, cute-stack displays the function signature so that a developer can more easily recognize anonymous functions that they have written.

cute-stack also normalizes paths to the current working directory, resulting in more readable and shorter file locations.

When traces relate to deeply embedded dependencies, they also tend to have long paths. cute-stack has a way of shortening these too (see the [Readme] page for info).

Function deanonymizing

Anonymous functions lead to puzzling stack traces. A function is often used as a lambda; that is, a small item of work, or an iterable function or a continuation (a callback). Functions that are used as lambdas and continuations can be hard to name:

setTimeout(function whatDoICallThis() {}, 1000);

There are many other reasons why a code base may contain anonymous functions: bad habits, ignorance and laziness all contribute. The cute-stack module handles this by supplying function signatures instead. However, what if there are no function parameters? In this case, we’re none the wiser.

The decofun module parses code and names any anonymous functions according to their context. The easiest way to use decofun is as an executable.

Let’s say we have the following code called app.js:

function gravy () {
   return function () {
       return {
         prop: function () {
           setTimeout(function () {
             console.trace('Getting a trace...');  
           }, 10)
           
         }
       }
   }
}

console.log(gravy+'');
gravy()().prop();

We can deanonymize any anonymous functions by running this file with the deco executable instead of the node binary:

npm -g install decofun 
deco app.js
Deco executable

The deco executable named all the functions in app.js for us

Notice that function names appear to contain pipe and space characters, which are illegal JavaScript characters. Yet the code still executes. These are actually characters from Hangul, the Korean alphabet, and they’re legal JavaScript from EcmaScript 5. The space is code point U+FFAO, a “Halfwidth Hangul Filler”(basically half a space in Korean), and the pipe is code point U+3163, the 10th and 21st vowel in North and South Korean Hangul respectively. It’s said by Sejong the Great to represent a mediator between yin and yang. For our purposes, it’s a Javascript-legal character acts a decent visual separator between meta-data.

The decofun module is integrated with cute-stack as follows:

deco app.js --cute
decofun

decofun supports the cute-stack integration

The decofun module can also be required in-process. Check out the github page for details.

Conclusion: comment and subscribe

I hope you found this post useful. Please post your comments and questions below – feedback is very welcome!

Our next Node.js practice is ‘Avail and beware of the ecosystem’. Subscribe to this blog to be notified as soon as that post, and others, are published.

Want to work for nearForm? We’re hiring.


We’re currently seeking applications for a UI developer.

Find out more here.

Email hello@nearform.com

Twitter @nearform

Phone +353-1-514 3545

Check out nearForm at www.nearform.com.


 

By: David Mark Clements

David Mark Clements is a JavaScript and Node.js specialist based in Northern Ireland. He is nearForm's lead trainer and training content curator. From a very early age he was fascinated with programming. He first learned BASIC on one of the many Ataris he had accumulated by the age of nine. David learned JavaScript at age twelve, moving into Linux administration and PHP as a teenager. Node has become a prominent member of his toolkit due to its versatility, vast ecosystem, and the cognitive ease that comes with full-stack JavaScript. David is author of Node Cookbook (Packt), now in its second edition.
  • http://glebbahmutov.com/ Gleb Bahmutov

    Great post, thanks for posting screenshots, love good error stacks. One thing I would add – forward error to realtime error reporting service, like Sentry or anything else. This will give you a great deal of info about your application in production.
    http://bahmutov.calepin.co/know-unknown-unknowns-with-sentry.html

    • David Clements

      Thanks Gleb, let’s add an issue to cute-stack on this

  • http://glebbahmutov.com/ Gleb Bahmutov

    I have written debug-logdown https://github.com/bahmutov/debug-logdown that works similar to debug, but allows each logger to have log / info / error levels, plus markdown formatting