This chapter covers the following recipes:

• Debugging Node with Chrome Devtools
• Enhancing stack trace output
• Enabling debug logs
• Enabling core debug logs

Debugging JavaScript has traditionally been non-trivial. This is partly to do with evented asynchronous paradigms inherent in the programming model and partly to do with tooling (and the difficulties in creating tooling that is well matched with JavaScript's programming model).

In recent years, however, as JavaScript usage has exponentially increased in both browser and server-side development, tooling has improved and continues to improve.

In this chapter, we talk about how to use fundamental debugging tools, introduce some additional useful introspection resources, and delve deeper into advanced production debugging tools and techniques such as async tracing and postmortems.

Node 6.3.0 onwards provides us with the --inspect flag, which we can use to debug the Node runtime with Google Chrome's Devtools.

In this recipe, we're going to diagnose and solve a problem in a simple Express application.

We're going to debug a small web server, so let's create that real quick.

On the command line, we execute the following commands:

$ mkdir app
$ cd app
$ npm init -y
$ npm install --save express
$ touch index.js future.js past.js
  

Our index.js file should contain the following:

const express = require('express') 
const app = express() 
const past = require('./past') 
const future = require('./future') 
 
app.get('/:age', (req, res) => { 
  res.send(past(req.params.age, 10) + future(req.params.future, 10)) 
}) 
 
app.listen(3000) 

Our past.js file should look like this:

module.exports = (age, gap) => { 
  return `${gap} years ago you were ${Number(age) - gap}<br>` 
} 

And our future.js file should be as follows:

module.exports = (age, gap) => {
   return `In ${gap} years you will be ${Number(age) + gap}<br>`
 }

When we run our server (which we created in the Getting ready section), and navigate our browser to http://localhost:3000/31 , the output is as follows:

10 years ago you were 21 
In 10 years you will be NaN 

It looks like we have a Not a Number problem.

Let's start our server in inspection mode:

$ node --inspect index.js

This will output a message that the debugger is listening.

We can connect to the debugger using the Chrome browser. Let's open Chrome and navigate to chrome://inspect.

Ensuring that we're in the Devices tab, we should be able to see our Node process underneath the Remote Target section, as in the following screenshot:

We should then see something like the following:

Now let's set a breakpoint inside our route handler, on line 7.

If we click the number 7 in the LOC column to the left of the code, an arrow shape will appear over and around the number (which will turn white). Over in the right-hand column, in the Breakpoints pane we should also see a checkbox with index.js:7 next to it, while beneath that is the code from the line we've set a breakpoint on.

In short, the Devtools GUI should now look something like the following:

Now let's open a new tab and navigate to http://localhost:3000/31:

This will cause the breakpoint to trigger, and Devtools will immediately grab focus.

The next thing we see should look like the following:

We can see line 7 is now highlighted, and there's a sort of tooltip showing us the values of the req and res objects on the line above.

Over in the right column, the Call Stack panel is full of call frames (the functions in the stack), and there's now a blue play button in the control icons at the top of the right column. If we were to scroll the right column, we'd also see the Scope pane is populated with references.

The debugger is waiting for us to allow execution to proceed, and we can chose whether to step over, in, or out of the next instruction.

Let's try stepping in. This is the down arrow pointing to a dot, the third icon from the left in the controls section:

When we press this, we step into the past function, which is in the past.js file, so Devtools will open a new tab in the center code panel and highlight the line that is about to execute (in our case, line 2):

So let's step out of the past function by pressing the arrow pointing up and away from a dot, next to the step-in icon:

The second line of the output seems to have the issue, which is our future function.

Now that we've stepped out, we can see that the call to future is highlighted in a darker shade of blue:

Now let's press the step-in icon again, which will take us into the future function in the future.js file:

Okay, this is the function that generates that particular sentence with the NaN in it. A NaN can be generated for all sort of reasons, such as dividing zero by itself, subtracting Infinity from Infinity, trying to coerce a string to a number when the string does not hold a valid number, to name a few. At any rate, it's probably something to do with the values in our future function.

Let's hover over the gap variable. We should see the following:

Seems fine. Now let's hover over the age variable:

Wait... why does that say undefined ? We vicariously passed 31 by navigating to http://localhost:3000/31.

To be sure our eyes aren't deceiving us, we can double-check by collapsing the Call Stack section (by clicking the small downwards arrow next to the C of Call Stack). This will make room for us to easily see the Scope section, which reports that the age variable is indeed undefined, as in the following screenshot:

Well, Number(undefined) is NaN, and NaN + 10 is also NaN.

Why is age set to undefined?

Let's open up the Call Stack bar again and click the second row from the top (which says app.get).

We should be back in the index.js file again (but still frozen on line 2 of future.js), like so:

Now let's hover over the value we're passing in to future:

That's undefined too. Why is it undefined?

Oh. That should be req.params.age, not req.params.future. Oops.

To be absolutely sure, let's fix it while the server is running. If we hit the blue play button once we should see something like this:

Now let's click line 7 again to remove the breakpoint. We should be seeing:

Now if we click immediately after the e in req.params.future we should get a blink cursor. We backspace out the word future and type the word age, making our code look like this:

Finally, we can live save those changes in our running server by pressing Cmd + S on macOS, or Ctrl + S on Windows and Linux.

Finally, let's check our route again:

OK, we've definitely found the problem, and verified a solution.

We don't really need to know how debugging Node with devtools is made possible in order to avail ourselves of the tool, however, for the curious here's a high-level overview.

Debugging ability is ultimately provided by V8, the JavaScript engine used by Node. When we run node with the --inspect flag, the V8 inspector opens a port that accepts WebSocket connections. Once a connection is established, commands in the form of JSON packets are sent back and forth between the inspector and a client.

The chrome-devtools:// URI is a special protocol recognized by the Chrome browser that loads the Devtools UI (which is written in HTML, CSS, and JavaScript, so can be loaded directly into a normal browser tab). The Devtools UI is loaded in a special mode (remote mode), where a WebSocket endpoint is supplied via the URL.

The WebSocket connection allows for bi-directional communication between the inspector and the client. The tiny Inspector WebSocket server is written entirely in C and runs on a separate thread so that when the process is paused, the inspector can continue to receive and send commands.

In order to achieve the level of control we're afforded in debug mode (ability to pause, step, inspect state, view callstack, live edit) V8 operations are instrumented throughout with Inspector C++ functions that can control the flow, and change state in place.

For instance, if we've set a breakpoint, once that line is encountered, a condition will match in the C++ level that triggers a function that pauses the event loop (the JavaScript thread). The Inspector then sends a message to the client over the WebSocket connection telling it that the process is paused on a particular line and the client updates its state. Likewise, if the user chooses to step into a function, this command is sent to the Inspector, which can briefly unpause and repause execution in the appropriate place, then sends a message back with the new position and state.

Let's find out how to debug older versions of Node, make a process start with a paused runtime and learn to use the built-in command-line debugging interface.

The --inspect flag and protocol were introduced in Node 6.3.0, primarily because the V8 engine had changed the debugging protocol. In Node 6.2.0 and down, there's a legacy debugging protocol enabled with the --debug flag, but this isn't compatible with the native Chrome Devtools UI.

Instead, we can use the node-inspector tool, as a client for the legacy protocol.

The node-inspector tool essentially wraps an older version of Devtools that interfaces with the legacy debug API, and then hosts it locally.

Let's install node-inspector:

$ npm i -g node-inspector

This will add a global executable called node-debug, which we can use as shorthand to start our process in debug mode.

If we could run our process like so:

$ node-debug index.js

We should see output that's something like the following:

Node Inspector v0.12.10
Visit http://127.0.0.1:8080/?port=5858 to start debugging.
Debugging `index.js`
    
Debugger listening on [::]:5858

When we load the URL http://127.0.0.1:8080/?port=5858 in our browser we'll again see the familiar Devtools interface.

By default, the node-debug command start our process in a paused state. After pressing run (the blue play button), we should now be able to follow the main recipe in it's entirely using a legacy version of Node.

In many cases, we want to debug a process from initialization, or we may want to set up breakpoints before anything can happen.

From Node 8 onwards, we use the following to start Node in an immediately paused state:

$ node --inspect-brk index.js

In Node 6 (at time of writing, 6.10.0), --inspect is supported but --inspect-brk isn't. Instead, we can use the legacy --debug-brk flag in conjunction with --inspect like so:

$ node --debug-brk --inspect index.js

In Node v4 and lower, we'd simply use --debug-brk instead of --debug (in conjunction with another client, see Using Node Inspector with older Node versions)

There may be rare occasions when we don't have easy access to a GUI. In these scenarios, command-line abilities become paramount.

Let's take a look at Nodes, built in command-line debugging interface.

Let's run our app from the main recipe like so:

$ node debug index.js

When we enter debug mode, we see the first three lines of our entry point (index.js).

Upon entering debug mode, the process is paused on the first line of the entry point. By default, when a breakpoint occurs the debugger shows two lines before and after the current line of code, since this is the first line we only see two lines after.

The debug mode provides several commands in the form of functions, or sometimes as magic getter/setters (we can view these commands by typing help and hitting Enter).

Let's get a little context using the list function:

debug> list(10) 

This provides 10 lines after our current line (again it would also include 10 lines before, but we're on the first line so there's no prior lines to show).

We're interested in the seventh line, because this is the code that's executed when the server receives a request.

We can use the sb function (which stands for Set Breakpoint) to set a break point on line 7, like so:

debug> sb(7)  

Now if we use list(10) again, we should see an asterisk (*) adjacent to line 7:

debug> list(10)  

Since our app began in paused mode, we need to tell the process to begin running as normal so we can send a request to it.

We use the c command to tell the process to continue, like so:

debug> c 

Now let's make a request to our server, we could use a browser to do this, or if we have curl on our system, in another terminal we could run the following:

$ curl http://localhost:3000/31 

This will cause the process to hit our breakpoint and the debugger console should print out break in index.js:7 along with the line our code is currently paused on, with two lines of context before and after. We can see a right caret (>) indicating the current line:

Now let's step in to the first function. To step in, we use the step command:

debug> step

This enters our past.js file, with the current break on line 2.

We can print out references in the current debug scope using the exec command, let's print out the values of the gap and age arguments:

debug> exec gap
debug> exec age

Everything seems to be in order here.

Now let's step back out of the past function. We use the out command to do this, like so:

debug> out 

We should now see that the future function is a different color, indicating that this is the next function to be called. Let's step into the future function:

debug> step

Now we're in our future.js file, again we can print out the gap and age arguments using exec:

debug> exec gap
debug> exec age

Aha, we can see that age is undefined. Let's step back up into the router function using the out command:

debug> out 

Let's inspect req.params.future and req.params:

debug> req.params.future
debug> req.params  

It's now (again) obvious where the mistake lies. There is no req.params.future; that input should be req.params.age.

• Creating an Express web app, in Chapter 7, Working with Web Frameworks
• Writing module code, in Chapter 2, Writing Modules
• Profiling memory, in Chapter 9, Optimizing Performance
• CPU profiling with Chrome Devtools, in the There's more... section of Finding Bottlenecks with Flamegraphs, in Chapter 9, Optimizing Performance

When a Node process experiences an error, the function where the error occurred, and the function that called that function (and so on) is written to STDERR as the final output of the application.

This is called a stack trace. By default, Node's JavaScript engine (V8) retains a total of 10 frames (references to functions in a stack).

However, in many cases we need far more than 10 frames to understand the context from a stack trace when performing root-cause analysis on a faulty process. On the other hand, the larger the stack trace, the more memory and CPU a process has to use to keep track of the stack.

In this recipe, we're going to increase the size of the stack trace, but only in a development environment.

Let's prepare for the recipe by making a small application that causes an error creating a long stack trace.

We'll create a folder called app, initialize it as a package, install express, and create three files, index.js, routes.js, and content.js:

$ mkdir app
$ cd app
$ npm init -y
$ npm install express
$ touch index.js routes.js content.js

Our index.js file should look like this:

    const express = require('express')
    const routes = require('./routes')
    const app = express()
    
    app.use(routes)
    
    app.listen(3000)

The routes.js file like the following:

    const content = require('./content')
    const {Router} = require('express')
    const router = new Router()
    
    router.get('/', (req, res) => {
      res.send(content())
    })
    
    module.exports = router

And the content.js file like so:

function content (opts, c = 20) { 
  return --c ? content(opts, c) : opts.ohoh 
} 
 
module.exports = content 

Let's begin by starting our server:

$ node index.js

All good so far. Okay let's send a request to the server, we can navigate a browser to http://localhost:8080 or we can use curl (if installed) like so:

$ curl http://localhost:3000/

That should spit out some error HTML output containing a stack trace.

Even though an error has been thrown, the process hasn't crashed because express catches errors in routes to keep the server alive.

The terminal window that's running our server will also have a stack trace:

We can see (in this case) that the content function is calling itself recursively (but not too many times, otherwise there would be a Maximum call stack size exceeded error).

The content function looks like this:

function content (opts, c = 20) { 
  return --c ? content(opts, c) : opts.ohoh 
} 

The error message is Cannot read property 'ohoh' of undefined.

It should be fairly clear, that for whatever reason the opts argument is being input as undefined by a function calling the content function.

But because our stack is limited to 10 frames, we can't see what originally called the first iteration of the content function.

One way to address this is to use the --stack-trace-limit flag.

We can see that c defaults to 20, so if we set the limit to 21, maybe we'll see what originally called the c function:

$ node --stack-trace-limit=21 index.js 

This should result in something like the following screenshot:

Now we can see that the original call is made from router.get in the routes.js file, line 6, column 12.

Line 6 is as follows:

res.send(content()) 

Ah... it looks like we're calling content without any inputs; of course, that means the arguments default to undefined.

The --stack-trace-limit flag instructs the V8 JavaScript engine to retain more stacks on each tick (each time round) of the event loop.

When an error occurs, a stack trace is generated that traces back through the preceding function calls as far as the defined limit allows.

Can we set the stack limit in process? What if we want a different stack trace limit in production versus development environments? We can track and trace asynchronous function calls? Is it possible to have nicer looking stack traces?

A lot of the time in development we want as much context as we can get, but we don't want to have to type out a long flag every time we run a process.

But in production, we want to save precious resources.

Let's copy the app folder to infinite-stack-in-dev-app:

$ cp -fr app infinite-stack-in-dev-app

Now at very the top of index.js, we simply write the following:

if (process.env.NODE_ENV !== 'production') { 
  Error.stackTraceLimit = Infinity 
} 

Now if we run our server:

$ node index.js

Then, make a request with curl (or, optionally, some other method, such as a browser):

$ curl http://localhost:3000/

Our stack trace will be limitless.

The default stack trace could definitely stand to be more human friendly.

Enter cute-stack, a tool for creating prettified stack traces.

Let's copy our app folder to pretty-stack-app and install cute-stack:

$ cp -fr app pretty-stack-app
$ cd app 
$ npm install --save cute-stack

Now let's place the following at the very top of the index.js file:

require('cute-stack')() 

Now let's run our process with a larger stack trace limit (as in the main recipe),

$ node --stack-trace-limit=21 index.js

Make a request, either with a browser, or if installed, curl:

$ curl http://localhost:3000/

As a result, we should see a beautified stack trace, similar to the following screenshot:

The cute-stack tool takes advantage of a proprietary V8 API, Error.prepareStackTrace, which can be assigned a function that receives error and stack inputs. This function can then process the stack and return a string that becomes the stack trace output.

The asynchronous nature of JavaScript affects the way a stack trace works. In JavaScript, each tick (each time the JavaScript event-loop iterates) has a new stack.

Let's copy our app folder to async-stack-app:

$ cp -fr app async-stack-app

Now let's alter content.js like so:

function content (opts, c = 20) { 
  function produce (cb) { 
    if (--c) setTimeout(produce, 10, cb) 
    cb(null, opts.ohoh) 
  } 
  return produce 
} 
 
module.exports = content 

Then let's alter routes.js in the following way:

const content = require('./content') 
const {Router} = require('express') 
const router = new Router() 
 
router.get('/', (req, res) => { 
  content()((err, html) => {  
    if (err) { 
      res.send(500) 
      return 
    }  
    res.send(html) 
  }) 
}) 
 
module.exports = router 

Now we start our server:

$ node index.js

And make a request:

$ curl http://localhost:3000/

We'll see only a small stack trace descending from timeout specific internal code, as in the following screenshot:

We can obtain asynchronous stack traces with the longjohn module. Let's install it as a development dependency:

$ npm install --save-dev longjohn

Now we can add the following the very top of the index.js file:

if (process.env.NODE_ENV !== 'production') { 
  require('longjohn') 
} 

Let's run our server again:

$ node index.js
  

And make a request:

$ curl http://localhost:3000/

Now we should see the original stack, followed by a line of dashes, followed by the call stack of the previous tick.

• Creating an Express web app, in Chapter 7, Working with Web Frameworks
• Interfacing with standard I/O, in Chapter 3, Coordinating I/O

More than 13,450 modules directly depend on the third-party debug module (at the time of writing). Many other modules indirectly use the debug module by the use of those 13,450. Some highly notable libraries, such as Express, Koa, and Socket.io, also use the debug module.

In many code bases, there's a wealth of often untapped tracing and debugging logs that we can use to infer and understand how our application is behaving.

In this recipe, we'll discover how to enable and effectively analyze these log messages.

Let's create a small Express app which we'll be debugging.

On the command line, we execute the following commands:

$ mkdir app
$ cd app
$ npm init -y
$ npm install --save express
$ touch index.js

Our index.js file should contain the following:

const express = require('express') 
const app = express() 
const stylus = require('stylus') 
 
app.get('/some.css', (req, res) => { 
  const css = stylus(` 
    body 
      color:black 
  `).render() 
  res.send(css) 
}) 
 
app.listen(3000)

Let's turn on all debug logging:

DEBUG=* node index.js

As soon as we start the server, we see some debug output that should be something like the following screenshot:

The first message is as follows:

express:application set "x-powered-by" to true +0ms

Let's make a mental note to add app.disable('x-powered-by') since it's much better for security to not publicly announce the software a server is using.

This debug log line has helped us to understand how our chosen framework actually behaves, and allows us to mitigate any undesired behaviour in an informed manner.

Now let's make a request to the server. If we have curl installed we can do the following:

$ curl http://localhost:3000/some.css

(Or otherwise, we can simply use a browser to access the same route).

This results in more debug output, mostly a very large amount of stylus debug logs:

While it's interesting to see the Stylus parser at work, it's a little overwhelming. Let's try just looking only at express log output:

$ DEBUG=express:* node index.js

And we'll make a request again (we can use curl or a browser as appropriate):

$ curl http://localhost:3000/some.css

This time our log filtering enabled us to easily see the debug messages for an incoming request.

In our recipe, we initially set DEBUG to *, which means enable all logs. Then we wanted to zoom in explicitly on express related log messages. So we set DEBUG to express:*, which means enable all logs that begin with express:. By convention, modules and frameworks delimit sub-namespaces with a : (colon).

At an internal level, the debug module reads from the process.env.DEBUG, splits the string by whitespace or commas, and then converts each item into a regular expression.

When a module uses the debug module, it will require debug and call it with a namespace representing that module to create a logging function that it then uses to output messages when debug logs are enabled for that namespace.

Each time a module registers itself with the debug module the list of regular expressions (as generated from the DEBUG environment variable) are tested against the namespace provided by the registering module.

If there's no match the resulting logger function is a no-op (that is, an empty function). So the cost of the debug logs in production is minimal.

If there is a match, the returned logging function will accept input, decorate it with ANSI codes (for terminal coloring), and create a time stamp on each call to the logger.

Let's find out how to use debug in our own code, and some best practices around enabling debug logs in production scenarios.

We can use the debug module in our own code to create logs that relate to the context of our application or module.

Let's copy our app folder from the main recipe, call it instrumented-app, and install the debug module:

$ cp -fr app instrumented-app
$ cd instrumented-app
$ npm install --save debug

Next, we'll make index.js look like so:

const express = require('express') 
const app = express() 
const stylus = require('stylus') 
const debug = require('debug')('my-app') 
 
app.get('/some.css', (req, res) => { 
  debug('css requested') 
  const css = stylus(` 
    body 
      color:black 
  `).render() 
  res.send(css) 
}) 
 
app.listen(3000) 

We've required debug, created a logging function (called debug) with the my-app namespace and then used it in our route handler.

Now let's start our app and just turn on logs for the my-app namespace:

$ DEBUG=my-app node index.js

Now let's make a request to http://localhost:3000/some.css, either in the browser, or with curl we could do the following:

$ curl http://localhost:3000/some.css

This should create the following log message:

my-app css requested +0ms

The default debug logs are not suited to production logging. The logging output is human-readable rather than machine-readable output; it uses colors that are enabled with terminal ANSI codes (which will essentially pollute the output when saved to file or database).

In production, if we want to turn on debug logs we can produce more standard logging output with the following:

$ DEBUG_COLORS=no DEBUG=* node index.js

The pino-debug module passes debug messages through pino so that log output is in newline-delimited JSON (a common logging format which offers a good compromise between machine and human readability).

Due to the performant techniques used by pino, using pino-debug leads to a performance increase in log writing (and therefore leaves more room for other in-process activities such as serving requests) even though there's more output per log message!

Let's copy our app folder to logging-app and install pino-debug:

$ cp -fr app logging-app
$ npm install --save pino-debug

We'll add two npm scripts, one for development and one for production. Let's edit package.json like so:

{ 
  "name": "app", 
  "version": "1.0.0", 
  "description": "", 
  "main": "index.js", 
  "scripts": { 
    "test": "echo \"Error: no test specified\" && exit 1", 
    "dev": "node index.js", 
    "prod": "node -r pino-debug index.js" 
  }, 
  "keywords": [], 
  "author": "", 
  "license": "ISC", 
  "dependencies": { 
    "express": "^4.15.0", 
    "pino-debug": "^1.0.3", 
    "stylus": "^0.54.5" 
  } 
} 

Now we run the following:

$ DEBUG=* npm run --silent prod

We should see the express logs in JSON form, where the msg field contains the log contents and the ns field contains the relevant debug message. Additionally, pino adds a few other useful fields, such as time, pid, hostname, level (the log level defaults to 20, which is debug level), and v (the log format version):

• Creating an Express web app, in Chapter 3, Coordinating I/O
• Interfacing with standard I/O, in Chapter 3, Coordinating I/O
• Adding logging, in Chapter 7, Working with Web Frameworks

It can be highly useful to understand what's going on in Node's core. There's a very easy way to get this information.

In this recipe, we're going to use a special environment variable to enable various debugging flags that cause Node core debug logging mechanisms to print to STDOUT.

We're going to debug a small web server, so let's create that real quick.

On the command line, we execute the following commands:

$ mkdir app
$ cd app
$ npm init -y
$ npm install --save express
$ touch index.js

Our index.js file should contain the following:

const express = require('express') 
const app = express() 
 
app.get('/', (req, res) => res.send('hey')) 
 
setTimeout(function myTimeout() {  
   console.log('I waited for you.') 
}, 100) 
 
app.listen(3000)

We simply have to set the NODE_DEBUG environment variable to one or more of the supported flags.

Let's start with the timer flag by running our app like so:

$ NODE_DEBUG=timer node index.js

This should show something like the following screenshot:

Let's try running the process again with both timer and http flags enabled:

$ NODE_DEBUG=timer,http node index.js

Now we need to trigger some HTTP operations to get any meaningful output, so let's send a request to the HTTP server using curl (or an alternative method, such as navigating to http://localhost:3000 in the browser):

$ curl http://localhost:3000

This should give output similar to the following screenshot:

The NODE_DEBUG environment variable can be set to any combination of the following flags:

• http
• net
• tls
• stream
• module
• timer
• cluster
• child_process
• fs

In our recipe, we were able to enable core timer and HTTP debug logs, by setting the NODE_DEBUG environment variable to timers in the first instance and then timers,http in the second.

We used a comma to delimit the debug flags; however, the delimiter can be any character.

Each line of output consists of the namespace, the process ID (PID), and the log message.

When we set NODE_DEBUG to timer, the first log message indicates that it's creating a list for 100. Our code passes 100 as the second argument passed to setTimeout, internally the first argument (the timeout callback) is added to a queue of callbacks that should run after 100 ms. Next, we see a message, timeout callback 100, which means every 100 ms timeout callback will now be called. The following message (the now message) indicates the current time as the internal timers module sees it. This is milliseconds since the timers module was initialized. The now message can be useful to see the time drift between timeouts and intervals, because a timeout of 10 ms will rarely (if ever) be exactly 10 ms. It will be more like 14 ms, because of 4 ms of execution time for other code in a given tick (time around the event loop). While 4 ms drift is acceptable, a 20 ms drift would indicate potential performance problems-a simple NODE_DEBUG=timer prefix could be used for a quick check. The final debug message shows that the 100 list is now empty, meaning all callback functions set for that particular interval have now been called.

Most of the HTTP output is self-explanatory, we can see when a new connection has been made to the server, when a message has ended and when a socket has closed. The remaining two cryptic messages are write ret = true and SERVER socketOnParserExecute 78. The write ret = true relates to when the server attempted to write to a socket. If the value was false, it would mean the socket had closed and (again internally) the server would begin to handle that scenario. As for the socketOnParserExecute message, this has to do with Node's internal HTTP parser (written in C++). The number (78) is the string length of the headers sent from the client to the server.

Combining multiple flags can be useful. We set NODE_DEBUG to timer,http and we were able to see how the http module interacts with the internal timer module. We can see after the SERVER new http connection message; that two timers are set (based on the timeout lists being created), one for 12,0000 ms (two minutes, the default socket timeout) and one (in the example case) for 819 ms.

This second interval (819) is to do with an internal caching mechanism for the HTTP Date header. Since the smallest unit in the Date header is seconds, a timeout is set for the amount of milliseconds remaining before the next second, and the Date header is provided the same string for the remainder of that second.

Let's look at the way Node Core triggers the debug log messages, and see if we can use this knowledge to gain a greater understanding of Node's internal workings.

Core modules tend to use the util module's debuglog method to generate a logging function that defaults to a no-op (an empty function) but writes log messages to STDOUT when the relevant flag appears in the NODE_DEBUG environment variable.

We can use util.debuglog to create our own core like log messages.

Let's take the app folder we created in the main recipe and copy it to instrumented-app:

$ cp -fr app instrumented-app

Now let's make index.js look like this:

const util = require('util') 
const express = require('express') 
const debug = util.debuglog('my-app') 
const app = express() 
 
app.get('/', (req, res) => { 
  debug('incoming request on /', req.route) 
  res.send('hey') 
}) 
 
setTimeout(function myTimeout() {  
   debug('timeout complete') 
   console.log('I waited for you.') 
}, 100) 
 
app.listen(3000) 

Now we can turn on our custom debug logs like so:

$  NODE_DEBUG=my-app node index.js

If we make a request to http://localhost:3000, the output of our process should look something like this:

MY-APP 30843: timeout complete 
I waited for you. 
MY-APP 30843: incoming request on / Route { 
  path: '/', 
  stack: 
   [ Layer { 
       handle: [Function], 
       name: '<anonymous>', 
       params: undefined, 
       path: undefined, 
       keys: [], 
       regexp: /^\/?$/i, 
       method: 'get' } ], 
  methods: { get: true } } 

The core libraries that come bundled with the Node binary are written in JavaScript, which means we can debug them the same way we debug our own code. This level of introspection means we can understand internal mechanics to a fine level of detail.

Let's use Devtools to pick apart how util.debuglog works.

We'll run our code we prepared in the Getting ready section like so (Node 8+):

$ NODE_DEBUG=timer node --inspect-brk index.js

Or if we're using Node 6.3.0+, use the following:

$ NODE_DEBUG=timer node --debug-brk --inspect index.js

Now if we navigate to chrome://inspect, click the inspect link this will open Devtools for our Node process. We should then see something like the following:

Now in left hand pane (the Navigation pane), we should see two drop-down trees (no domain) and file://. The (no domain) files are files that came compiled into Node.

Let's click the small right-facing triangle next to (no domain) to expand the list. Then locate the util.js file and double-click to open. At this point, we should see something like the following:

Next, we want to find the debuglog function. An easy way to do this is to press Cmd + F on macOS or Ctrl + F on Linux and Windows, to bring up the small find dialog, then type debuglog. This should highlight the exported debuglog method:

If we read the exported function, we should be able to ascertain that given the right conditions (for example, if the flag is set on NODE_DEBUG), a function is created and associated to a namespace. Different Node versions could have differences in their util.js. In our case, the first line of this generated function is line 157, so we set a breakpoint on line 157 (or wherever the first line of the generated function may be):

Now if we press run, our breakpoint should be triggered almost immediately. Let's hover over the arguments object referenced in the generated function:

We should see that the second argument passed to the generated debug function is 100 this relates to the millisecond parameter we pass to setTimeout in our index.js and is part of the first debug message (no 100 list was found...).

Now let's hit the blue play button four more times until it changes to a pause button and the top-right corner shows an error count of 4 as shown in the following screenshot:

Devtools perceives each log message as an error because the debug messages are written to STDERR. This is why the error count in the top-right corner is 4.

Now let's open a new browser tab and navigate to http://localhost:3000.

Devtools should have paused again at our breakpoint. If we hover over the arguments object in the generated function we should see that the second argument is 12000. This relates to the default 2 minute timeout on sockets (as discussed in the main recipe):

If we hit the play button again and inspect the arguments object, we should see the second argument is a number that's less than 1000:

Over on the right-hand side, in the Call Stack panel there's a frame called utcDate. Let's select that frame to view the function:

This function is in a library that's only for internal core use called _http_outgoing.js.

We can see that it's currently within an if block that checks whether dateCache is falsey. If dateCache is falsey, it creates a new Date object and assigns the output of toUTCString to dateCache. Then it uses timers.enroll. This is a way of creating a setTimeout where the provided object represents the timeout reference. It sets the time to 1000 minus the millisecond unit in the date object that effectively measures how long there is left of the current second. Then it calls timers._unrefActive, which activates the timer without allowing the timer to keep the event loop open (which means the fact the queued timer operation won't keep the process alive). The utcDate._onTimeout method sets dateCache to undefined, so at the end of the timeout, dateCache is cleared.

If we look down the Call Stack panel, we should be able to infer that the utcDate function is called when a request is made, and is to do with HTTP header generation (specifically the Date HTTP header).

The net effect is that a process may receive, say, 10,000 requests a second, and only the first of those 10,000 has to perform the relatively expensive Date generation, while the following 9,999 requests all use the cached date.

And that's the sort of thing we can discover by debugging core.

• Creating an Express web app, in Chapter 7, Working with Web Frameworks
• Working with files, in Chapter 3, Coordinating I/O
• Communicating over sockets, in Chapter 3, Coordinating I/O