Chapter 12: Debugging Node.js
The asynchronous nature of JavaScript and Node.js makes the debugging process non-trivial. However, over the past decade, Node.js has matured as a technology, and the debugging capabilities and facilities have improved accordingly.
In this chapter, we will consider steps we can take to make our applications easier to debug. We'll also learn how to use modern tools to debug our Node.js applications. Later in the chapter, we'll learn about the diagnostic reports feature that is available in the latest versions of Node.js.
This chapter will cover the following:
- Debugging with Chrome DevTools
- Logging with Node.js
- Enhancing stack trace output
- Using diagnostic reports
Technical requirements
For this chapter, you will require Node.js 14 to be installed and available in your Terminal path. You can test which version of Node.js is installed and available in your path with the following command:
$ node --version
v14.3.0
You'll also need access to an editor and browser. For the Debugging with Chrome DevTools recipe, you will need to have Google Chrome installed, which you can download from https://www.google.co.uk/chrome/.
Diagnosing issues with Chrome DevTools
Node.js exposes a debugging utility via the --inspect process flag, which enables us to debug and profile our Node.js processes using the Chrome DevTools interface. The integration is enabled via the Chrome DevTools Protocol. The existence of this protocol means that tools can be written to integrate with Chrome DevTools.
Important Note
node --debug and node --debug-brk are legacy Node.js process flags that have been deprecated since Node.js v6.3.0. node --inspect and node --inspect-brk are the modern equivalents that should be used in place of these legacy flags.
In the recipe, we will learn how to use Chrome DevTools to diagnose issues within a web application.
Getting ready
In this recipe, we will debug a small web server. Let's prepare this before we start the recipe:
- First, let's set up a directory and the files required for this recipe:
$ mkdir debugging-with-chrome
$ cd debugging-with-chrome
$ npm init --yes
$ npm install express
$ touch server.js random.js
- Add the following source code to server.js to create our web server:
const express = require("express");
const app = express();
const random = require("./random");
app.get("/:number", (req, res) => {
const number = req.params.number;
res.send(random(number).toString());
});
app.listen(3000, () => {
console.log("Server listening on port 3000");
});
- Add the following source code to random.js. This will be a module we interact with via our server:
module.exports = (n) => {
const randomNumber = Math.floor(Math.random() * n) + "1";
return randomNumber;
};
Now that we have an application ready to debug, we can move on to the recipe steps.
How to do it
In this recipe, we're going to use Chrome DevTools to debug a route in our application. Our application will respond with a random number between 0 and the number we specify in the route. For example, http://localhost:3000/10 should return a random number between 1 and 10:
Start the program with $ node server.js and navigate to http://localhost:3000/10. Refresh the endpoint a few times and you should notice that the program will often respond with a number greater than 10. That seems broken, so let's debug to try and understand why.
- First, we need to start our program with the debugger enabled. To do this we need to pass the --inspect argument to our Node.js process:
$ node --inspect server.js
Debugger listening on ws://127.0.0.1:9229/35fa7c65-62a5-48b4-8428-9a414ec28afe
For help, see: https://nodejs.org/en/docs/inspector
Server listening on port 3000
- Instead of going directly to the link specified in the output, navigate to chrome://inspect/#devices in Google Chrome. Expect to see the following output:
Fig. 12.1 Screenshot of the Google Chrome inspector device interface
- Observe that our server.js is showing up as a Remote Target. Click the inspect link and the Chrome DevTools window will open, as shown in the following image:
Fig. 12.2 Screenshot of the Chrome DevTools interface
- Click on server.js:11 in the bottom right of the window. This should ensure our server.js file is open:
Fig. 12.3 Screenshot of the Chrome DevTools interface depicting the server.js file
- Now, we can add a breakpoint. Click the number 7 in the Line-of-Code column to the left of our code. A small red circle should appear next to the number. If you click Show Debugger in the top-right corner, you should see the breakpoint listed in the Breakpoints pane. The Chrome DevTools interface should look like the following:
Figure 12.4 – Screenshot of Chrome DevTools showing a breakpoint registered in the server.js file
- Now, let's open a new regular browser window and navigate to http://localhost:3000/10. The request will hang because it has hit the breakpoint we registered on line 7.
- Go back to Chrome DevTools. You should notice that there is a tooltip stating Paused on breakpoint at the top right of the interface. Also, to the right of the interface, you should see a Call Stack panel, which details the call frames:
Figure 12.5 – Screenshot of the Chrome DevTools interface showing as paused on breakpoint
- The debugger is waiting for us to take action. We can choose to step in or out of the next instruction. Let's step in to the function. To do this, click the icon of an arrow pointing down to a circle (these icons are right above the Paused on breakpoint message). When you hover over each icon, a tooltip will appear describing the icon's behavior. Once you have stepped in, you will see that we have moved into our random.js file:
Figure 12.6 – Screenshot of the Chrome DevTools interface showing the random.js file
- While we're in random.js, we can hover over the values to check whether they are what we expect them to be. We can see that n = 10, as expected.
- Step-over the function (by clicking the semi-circular arrow with a dot underneath) and then inspect the value of randomNumber. In the screenshot, the number is 41, which is greater than 10. This helps us determine that the error is in our randomNumber logic of the previous line. Now that we've identified the line the error is on, it is easier to locate the error. We're adding the string "1" rather than the number 1:
Figure 12.7 – Screenshot of the Chrome DevTools interface showing variable values on hover
We've learned how to pause and step through code using Chrome DevTools. We've also learned that we can inspect variable values.
How it works
The ability to debug Node.js applications is provided by the V8 JavaScript engine. When we pass the node process the --inspect argument, the Node.js process starts to listen for a debugging client. Specifically, it is the V8 inspector that opens a port that accepts WebSocket connections. The WebSocket connection allows the client and V8 inspector to interact.
At the top of the Chrome DevTools window, you will see a URI that starts with devtools://. This is a protocol that is recognized by the Google Chrome browser and instructs Google Chrome to open the Chrome DevTools user interface.
In the recipe, we set a breakpoint in the Chrome DevTools window. When the line of code the breakpoint is registered on is encountered, the event loop (JavaScript thread) will be paused. The V8 inspector will then send a message to the client over the WebSocket connection. The message from the V8 inspector details the position and state of the program. The client can update its state based on the information it receives.
Similarly, if the user chooses to step into a function, a command is sent to the V8 inspector to instruct it to temporarily resume the execution of the script, pausing it again afterward. As before, the V8 inspector sends a message back to the client detailing the new position and state.
Pausing a process on start
Node.js also provides a flag that we can use to pause an application on start. This feature enables us to set up breakpoints before anything executes. It can also help when debugging an error that occurs during the setup phase of your application.
This feature can be enabled with the --inspect-brk flag. The following is how we'd start server.js using the --inspect-brk flag: $ node --inspect-brk server.js.
There's more
Node.js provides a command-line inspector, which can be valuable when we do not have access to a graphical user interface.
We can run the application from the recipe using the command-line-based debugger with the following command:
$ node inspect server.js
This command will take us into debug mode and output the first three lines of server.js:
Figure 12.8 – Terminal window depicting the Node.js inspector utility
Debug mode will pause our program at the first line.
Debug mode provides a series of commands and functions that we can use to step through and debug our program. You can output the complete list of these commands by typing help and hitting Enter.
One of the functions is the list() function, which will list a specified number of following lines. For example, we can type list(11) to output all 12 lines of our program:
debug> list(11)
> 1 const express = require("express");
2 const app = express();
3 const random = require("./random");
4
5 app.get("/:number", (req, res) => {
6 const number = req.params.number;
7 res.send(random(number).toString());
8 });
9
10 app.listen(3000, () => {
11 console.log("Server listening on port 3000");
12 });
We can use the setBreakpoint() function to set a break point. We must supply this function the line number we wish to set the breakpoint on. There's also a shorthand for this function: sb().
Let's set a breakpoint on line 7 by typing setBreakpoint(7) or sb(7):
debug> setBreakpoint(7)
2 const app = express();
3 const random = require("./random");
4
5 app.get("/:number", (req, res) => {
6 const number = req.params.number;
> 7 res.send(random(number).toString());
8 });
9
10 app.listen(3000, () => {
11 console.log("Server listening on port 3000");
12 });
The caret (>) indicates that a breakpoint has been set on line 7.
The program is still paused. We can instruct the process to begin running by typing the continue command, cont. This also has a shorthand command, c:
debug> cont
< Server listening on port 3000
After entering the cont command, our program will start to run. Our breakpoint is within our request handler function. Let's send a request using cURL in a new Terminal window:
$ curl http://localhost:3000/10
The command will hang, as it has hit our breakpoint on line 7 of server.js. If we go back to the debug session, we will see the debugger has detected that a breakpoint has been reached:
break in server.js:7
5 app.get("/:number", (req, res) => {
6 const number = req.params.number;
> 7 res.send(random(number).toString());
8 });
9
Now, to step into the function, we type the step command:
debug> step
break in random.js:2
1 module.exports = (n) => {
> 2 const randomNumber = Math.floor(Math.random() * n) + "1";
3 return randomNumber;
4 };
This goes into the random.js file. Note that the command-line debug utility is providing an interface similar to Chrome DevTools, just without a graphical user interface.
We can print out references in the current scope using the exec command. Type exec n to output the value of n:
debug> exec n
'10'
We can now step out using the out command. This will take us back into our server.js file:
debug> out
break in server.js:7
5 app.get("/:number", (req, res) => {
6 const number = req.params.number;
> 7 res.send(random(number).toString());
8 });
9
We've now learned how to step through our code and output reference values using the command-line debugger. To exit the debugger, you can type .exit or enter Ctrl + C twice.
See also
- The Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks
- The Logging with Node.js recipe in this chapter
- The Enabling debug logs recipe in this chapter
Logging with Node.js
Effective logging can help you understand what is going on in an application. Logs can help triage causes of crashes or failures retrospectively by helping you to see what was happening in your application prior to the crash or failure.
Logging can also be used to help collate data. As an example, if you log all accesses to endpoints on your web application, you could collate all the request logs to determine what the most visited endpoints are.
In this recipe, we will look at logging with pino, a JSON-based logger. In the There's more section, we'll look at the alternative Morgan and Winston loggers.
Getting ready
- First, we'll create a new directory named express-pino-app, initialize our project, and then install the express module:
$ mkdir express-pino-app
$ cd express-pino-app
$ npm init --yes
$ npm install express
- Now, we'll create a file for our server named server.js:
$ touch server.js
- Add the following content to server.js:
const express = require("express");
const app = express();
const PORT = 3000;
app.get("/", (req, res) => {
const randomNumber = getRandomNumber();
res.send(`${randomNumber}`);
});
app.listen(PORT, () =>
console.log(`Server listening on port ${PORT}`)
);
function getRandomNumber() {
return Math.floor(Math.random() * 100) + 1;
};
Now that we have a simple server, we will look at how we can add pino logging to it.
How to do it
In this recipe, we will make use of the express-pino-logger module to add logging via an Express.js middleware:
- First, start by installing the pino and express-pino-logger modules:
$ npm install pino express-pino-logger
- Now, we can import pino and express-pino-logger in server.js. Add the following lines, after the PORT variable assignment:
const pino = require("pino")();
const logger = require("express-pino-logger")({
instance: pino,
});
- Now, we can register our pino logger as an Express.js middleware. Add the following line below the logger declaration added in the previous step:
app.use(logger);
- We are ready to add a pino log message to our request. We'll add a log message that informs us that we're generating a random number. Add the following line to your request handler function. This should be the first line of your request handler function:
req.log.info("Generating random number");
- We'll now convert our existing console.log() statement to use the pino logger instead:
app.listen(PORT, () => pino.info(`Server listening on port ${PORT}`));
- We can start our server and observe that our log message is output, in JSON format:
$ node server.js
{"level":30,"time":1591308577332,"pid":48628,"hostname":"Beths-MBP.lan","msg":"Server listening on port 3000"}
- Navigate to http://localhost:3000 in your browser (or send an HTTP GET request using cURL). Expect to see the following log output in your Terminal window:
Figure 12.9 – Screenshot showing the Terminal with Pino log message output
We've now enabled Pino logging on our Express.js web server, making use of the express-pino-logger module.
How it works
express-pino-logger is a middleware that enables Pino logging on our Express.js web server. We import these independently so that we can interact with the pino logger both directly and via our middleware.
The Pino interface is based on Log4j. Log4j is an Apache logger written for Java, but interpretations of its interface have been implemented across many languages.
Pino allows you to group your error messages by level. The levels are trace, debug, info, warn, error, and fatal. The default logging level is set to info.
In the recipe, we added info-level log messages. To add the "Server listening on port 3000" log message, we interacted with pino directly using pino.info(). When we started our server, the log message was output:
{"level":30,"time":1591309005276,"pid":48790,"hostname":"Beths-MBP.lan","msg":"Server listening on port 3000"}
We registered the express-pino-logger middleware using the app.use() function. For more information on using middlewares with Express.js, refer to the Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks.
The express-pino-logger middleware adds a log object to every incoming request. Each log message is accessible via a property named log on the request object (req.log). Each log object is unique per request. The log object contains data about the request and a unique generated identifier. The unique generated identifier enables log messages to be traced to a specific client request.
In the recipe, we added an additional message to the request's log object using the req.log.info() method. The log message for the incoming request looked similar to the following, containing our specified message:
{"level":30,"time":1591310761795,"pid":48997,"hostname":"Beths-MBP.lan","req":{"id":1,"method":"GET","url":"/","headers":{"host":"localhost:3000","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::1","remotePort":60721},"msg":"Generating random number"}
The express-pino-logger middleware also generates a log message for each completed request. A res key is added to the JSON. The res key contains data about the request's response, including the status code and headers. The following is an example of a completed request log message:
{"level":30,"time":1591310761799,"pid":48997,"hostname":"Beths-MBP.lan","req":{"id":1,"method":"GET","url":"/","headers":{"host":"localhost:3000","user-agent":"curl/7.64.1","accept":"*/*"},"remoteAddress":"::1","remotePort":60721},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"2","etag":"W/\"2-wJdjj5LegLqNbGlrJubmAaX2Hrc\""}},"responseTime":4,"msg":"request completed"}
There's more
Now we'll take a look at how Pino can be used with other web frameworks. We'll also consider Morgan and Winston, two alternative popular loggers for Node.js.
Pino and web frameworks
The recipe demonstrated how Pino can be integrated into an Express.js application to provide JSON logging. It is also possible to integrate Pino with other popular web frameworks. The Pino GitHub organization provides middlewares and connectors for many web frameworks, including the following:
The Pino logging capability is built into the Fastify web framework, and just requires logging to be turned on via the following code:
const fastify = require("fastify")({
logger: true,
});
For details on how to integrate middlewares and plugins, refer to the relevant recipes of Chapter 6, Exploring Node.js Web Frameworks.
Logging with Morgan
Morgan is an HTTP request logger middleware for Node.js. Note that Morgan is focused on providing HTTP logging and is not used as a general-purpose extensible logger. Morgan is commonly used with Express.js and is maintained under the Express.js GitHub organization (https://github.com/expressjs/morgan). Let's take a look at what Morgan provides in terms of logging.
The express-generator generates a skeleton Express.js application (refer to the There's more section in the Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks). The generated skeleton application already includes the morgan logger.
Generate an Express.js application in a new directory named express-morgan-app by entering the following in your Terminal:
$ npx express-generator --view=ejs express-morgan-app
$ cd express-morgan-app
$ npm install
Open app.js and observe that on line 5, the morgan logger is imported:
var logger = require('morgan');
Line 16 in app.js is where the morgan HTTP logging middleware is registered:
app.use(logger('dev'));
The parameter dev indicates we want development formatted logging. In Morgan, development-level logging is concise output colored by the response status. Morgan provides the following predefined formats:
- combined: Apache-style combined output
- common: Apache-style output
- dev: Concise color-coded output
- short: Shorter output
- tiny: Minimal output
If we start our server and navigate to http://localhost:3000, we should see morgan logging the HTTP requests in our Terminal window:
$ npm start
> express-morgan-app@0.0.0 start /Users/bethgriggs/Node-Cookbook/Chapter13/express-morgan-app
> node ./bin/www
GET / 200 8.077 ms - 207
GET /stylesheets/style.css 200 2.210 ms - 111
This is the morgan development-level log output. Observe that it provides us with the request method, route, and response time. The final values (207 and 111) represent the content length.
Logging with Winston
Winston is another popular logger for Node.js. Winston exposes an interface that is also similar to the Log4j interface. The main difference between Pino and Winston is that Winston provides a larger number of features and configuration options. The features Winston provides include logging transformations and log rotations.
Let's generate an Express.js application using express-generator and replace the Morgan logger with the express-winston module:
$ npx express-generator --view=ejs express-winston-app
$ cd express-winston-app
$ npm install
Now, we need to uninstall the morgan module and install express-winston:
$ npm uninstall morgan
$ npm install winston express-winston
Now we can replace the morgan import in app.js with the following. We'll continue to use var to be consistent with the output of express-generator:
var winston = require('winston');
var expressWinston = require('express-winston');
Now we can instruct Express.js to use our winston logger middleware. The following configuration instructs Winston to output the log messages to STDOUT in JSON format.
In app.js, replace the app.use(logger('dev')); line with the following:
app.use(expressWinston.logger({
transports: [
new winston.transports.Console({
json: true
})
]
}));
We pass winston.transports.Console the json: true property to instruct Winston to expose the logs in the JSON format. By default, the log message would be in the format ${level}: ${message}.
Now, we can start the server using $ npm start and navigate to http://localhost:3000. Observe the JSON-formatted logs in the Terminal window:
$ npm start
> express-winston-app@0.0.0 start /Users/bethgriggs/Node-Cookbook/Chapter13/express-winston-app
> node ./bin/www
{"meta":{"req":{"url":"/","headers":{"host":"localhost:3000","connection":"keep-alive","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.61 Safari/537.36","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9","sec-fetch-site":"none","sec-fetch-mode":"navigate","sec-fetch-user":"?1","sec-fetch-dest":"document","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en-US;q=0.9,en;q=0.8","if-none-match":"W/\"cf-sMq3uu/Hzh7Qc54TveG8DxiBA2U\""},"method":"GET","httpVersion":"1.1","originalUrl":"/","query":{}},"res":{"statusCode":304},"responseTime":7},"level":"info","message":"HTTP GET /"}
{"meta":{"req":{"url":"/stylesheets/style.css","headers":{"host":"localhost:3000","connection":"keep-alive","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.61 Safari/537.36","accept":"text/css,*/*;q=0.1","sec-fetch-site":"same-origin","sec-fetch-mode":"no-cors","sec-fetch-dest":"style","referer":"http://localhost:3000/","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en-US;q=0.9,en;q=0.8","if-none-match":"W/\"6f-17281bf98c8\"","if-modified-since":"Thu, 04 Jun 2020 23:51:56 GMT"},"method":"GET","httpVersion":"1.1","originalUrl":"/stylesheets/style.css","query":{}},"res":{"statusCode":200},"responseTime":3},"level":"info","message":"HTTP GET /stylesheets/style.css"}
We've now added Winston logging to our Express.js application. We've added it using the express-winston middleware, which means that log messages will be output for each HTTP request.
See also
- The Consuming Node.js modules recipe in Chapter 5, Developing Node.js Modules
- The Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks
- The Enabling debug logs recipe in this chapter
Enabling debug logs
debug is a popular library, used by many notable frameworks, including the Express.js and Koa.js web frameworks and the Mocha test framework. debug is a small JavaScript debugging utility based on the debugging technique used in Node.js core.
In the recipe, we'll discover how to enable debug logs on an Express.js application.
Getting ready
- Let's create an Express.js web application that we can enable debug logs on. We'll first need to create a new directory and initialize our project:
$ mkdir express-debug-app
$ cd express-debug-app
$ npm init --yes
$ npm install express
- Now, we'll create a single file named server.js:
$ touch server.js
- Add the following code to server.js:
const express = require("express");
const app = express();
app.get("/", (req, res) => res.send("Hello World!"));
app.listen(3000, () => {
console.log("Server listening on port 3000");
});
Now that we have an application, we're ready to enable debug logs.
How to do it
In this recipe, we will be enabling debug logs on our application:
- To turn on debug logging, start your server with the following command:
$ DEBUG=* node server.js
- Expect to see the following color-coded output in your Terminal window:
Figure 12.10 – Screenshot of a Terminal window depicting debug logs for the web server
- Navigate to http://localhost:3000 in your browser to send a request to our server. You should see that the log messages describing your request have been output:
express:router dispatching GET / +1s
express:router query : / +1ms
express:router expressInit : / +0ms
- Stop your server using Ctrl + C.
- Now, we can also filter which debug logs are output. We'll filter it to just see the Express.js router actions. To do this, restart your server with the following command:
$ DEBUG=express:router* node server.js
- Expect to see the following output in your Terminal window. Observe that only Express.js router actions are output:
Figure 12.11 – Screenshot of a Terminal window depicting filtered debug logs for the web server
We've now learned how to enable debug logs, via the Terminal, on our application. We've also learned how to filter the logs.
How it works
We first prepend DEBUG=* to our start command. This syntax passes an environment variable named DEBUG to our Node.js process, which can be accessed from within the application via process.env.DEBUG.
We set the value to *, which enables all logs. Later, we filter out logs by setting DEBUG=express:router*. Internally, the debug module is converting the values we set to regular expressions.
Express.js uses the debug module internally to instrument its code. In the There's more section, we'll look at how to instrument code with debug.
Using debug in production
The default debug configuration is not suitable for logging in production. The default debug logs are intended to be human-readable, hence the color-coding. When in production, you should pass your process the DEBUG_COLORS=no value to remove the ANSI codes that implement the color-coding. This will make the output more easily machine-readable.
There's more
It's possible to instrument your code with the debug module. We can add this to the program from the recipe. Start by copying the server.js file used in the recipe to a new file and install the debug module:
$ cp server.js debug-server.js
$ npm install debug
Change debug-server.js to the following. We have imported the debug module on line 3, and added a debug call on line 6:
const express = require("express");
const app = express();
const debug = require("debug")("my-server");
app.get("/", (req, res) => {
debug("HTTP GET request to /");
res.send("Hello World!");
});
app.listen(3000, () => {
console.log("Server listening on port 3000");
});
Start your application with the following command, and then navigate to http://localhost:3000. Expect to see our HTTP GET request to / log message in your Terminal window:
$ DEBUG=my-server node debug-server.js
Server listening on port 3000
my-server HTTP GET request to / +0ms
Note that our log message has my-server prepended to it. This is the namespace for our log messages, which we declared when we created our debug logging function.
See also
- The Consuming Node.js modules recipe in Chapter 5, Developing Node.js Modules
- The Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks
- The Logging with Node.js recipe in this chapter
- The Enabling Node.js core debug logs recipe in this chapter
Enabling Node.js core debug logs
When debugging some problems in your applications, it can be useful to have insight into the internals of Node.js and how it handles the execution of your program. Node.js provides debug logs that we can enable to help us understand what is happening internally in Node.js.
These core debug logs can be enabled via an environment variable named NODE_DEBUG. In the recipe, we're going to set the NODE_DEBUG environment variable to allow us to log internal Node.js behaviors.
Getting ready
We'll need to create an application that we can enable Node.js core debug logs on. We'll create a simple Express.js-based server with one route:
$ mkdir core-debug-logs
$ cd core-debug-logs
$ npm init --yes
$ npm install express
$ touch server.js
Add the following to server.js:
const express = require("express");
const app = express();
app.get("/", (req, res) => {
res.send("Hello World!");
});
app.listen(3000, () => {
console.log("Server listening on port 3000");
setInterval(() => {
console.log("Server listening...");
}, 3000);
});
Now that we have an application ready, we can enable the core debug logs to allow us to see what is happening at the Node.js runtime level.
How to do it
In this recipe, we will be enabling Node.js core debug logs on an application:
- We just need to set the NODE_DEBUG variable to the internal flag we wish to log. The internal flags align with specific subsystems of Node.js, such as timers or HTTP. To enable the timer core debug logs, start your server with the following command:
$ NODE_DEBUG=timer node server.js
- Observe the additional log output from our program. We can see additional information about our setInterval() function, which is executed every 3000 ms:
Figure 12.12 – Screenshot of a Terminal window depicting Node.js core timer debug messages
The preceding TIMER log statements are additional debug information that derives from the internal implementation of timers in Node.js core, which can be found at https://github.com/nodejs/node/blob/master/lib/internal/timers.js.
- We will now enable core debug logs for the http module. Restart your server with the following command:
$ NODE_DEBUG=http node server.js
- Navigate to http://localhost:3000 in a browser. You should expect to see internal logs about your HTTP request output:
Figure 12.13 – Screenshot of a Terminal window depicting Node.js core HTTP debug messages
We've now learned how to use the NODE_DEBUG environment variable to enable the logging of Node.js internals.
How it works
In the recipe, we set the NODE_DEBUG environment variable to both the timer and http subsystems. The NODE_DEBUG environment variable can be set to the following Node.js subsystems:
Figure 12.14– Table detailing subsystems that expose logs via NODE_DEBUG
It is also possible to enable debug logs on multiple subsystems via the NODE_DEBUG environment variable. To enable multiple subsystem logs, you can pass them as a comma-separated list. For example, to enable both the http and timer subsystems, you'd supply the following command:
$ NODE_DEBUG=http,timer node server.js
The output of each log message includes the subsystem/namespace, followed by the process identifier (PID), and then the log message.
In the recipe, we first enabled the timer core debug logs. In our program, we have a setInterval() function that printed the message Server listening... to STDOUT every 3000 ms. The core debug logs provided insight into how our interval timer was created internally.
Similarly, when we enabled the http core module debug logs, we could follow what was happening internally during HTTP requests. The http debug logs are fairly human-readable in terms of how they describe the actions that are happening when our server receives and responds to an HTTP request.
Extending NODE_DEBUG
It is possible to make use of the Node.js core util.debuglog() method to instrument your own debug logs that you can enable via the NODE_DEBUG environment variable. However, this is not generally recommended. It is preferable to use the third-party debug module, which is covered in the Enabling debug logs recipe in this chapter. The debug module provides additional logging features, including timestamps and color-coding, with minimal overhead.
See also
- The Debugging Node.js with Chrome DevTools recipe in this chapter
- The Logging with Node.js recipe in this chapter
- The Enabling debug logs recipe in this chapter
Increasing stack trace size
A stack trace, sometimes referred to as a stack backtrace, is defined as a list of stack frames. When your Node.js process hits an error, a stack trace is shown detailing the function that experienced the error, and the functions that it was called by. By default, Node.js's V8 engine will return 10 stack frames.
When debugging some errors, it can be useful to have more than 10 stack frames. The number of stack frames stored comes with a performance cost. Keeping track of additional stack frames will result in our applications consuming more memory and CPU.
In the recipe, we're going to increase the size of the stack trace.
Getting ready
- First, we should create a directory for our application. We'll be using the express module for our program, so we'll also need to initialize our project directory:
$ mkdir stack-trace-app
$ cd stack-trace-app
$ npm init --yes
$ npm install express
- We'll need a few files for this recipe:
$ touch server.js routes.js
- Add the following to server.js:
const express = require("express");
const routes = require("./routes");
const app = express();
app.use(routes);
app.listen(3000, () => {
console.log("Server listening on port 3000");
});
- And then add the following to routes.js:
const express = require("express");
const router = new express.Router();
router.get("/", (req, res) => {
res.send(recursiveContent());
});
function recursiveContent(content, i = 10) {
--i;
if (i !== 0) {
return recursiveContent(content, i);
} else {
return content.undefined_property;
}
}
module.exports = router;
The purpose of the recursiveContent() function is to force the creation of function calls, but in larger, more complex applications, it's possible to exceed the stack frames limit naturally.
Now that we have an application that will exceed the default call stack limit, we can move on to the recipe steps.
How to do it
In this recipe, we will learn how to enable additional stack frames using the --stack-trace-limit process flag:
- Start by running the server:
$ node server.js
Server listening on port 3000
- Now, in a browser, navigate to http://localhost:3000. Alternatively, you could use cURL to send a request to the endpoint.
- Observe that we see the following stack trace output returned:
TypeError: Cannot read property 'undefined_property' of undefined
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:13:20)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
- We can now restart our application with the --stack-trace-limit flag. We'll set this to 20:
$ node --stack-trace-limit=20 server.js
Server listening on port 3000
- Now, navigate or send a request to http://localhost:3000 again. Observe that we have more frames from the stack trace now:
TypeError: Cannot read property 'undefined_property' of undefined
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:13:20)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at recursiveContent (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:11:12)
at /Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/routes.js:5:12
at Layer.handle [as handle_request] (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/node_modules/express/lib/router/layer.js:95:5)
at next (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/node_modules/express/lib/router/route.js:137:13)
at Route.dispatch (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/node_modules/express/lib/router/route.js:112:3)
at Layer.handle [as handle_request] (/Users/bethgriggs/Node-Cookbook/Chapter13/stack-trace-app/node_modules/express/lib/router/layer.js:95:5)
- By extending how many stack frames are returned, we can see that the recursiveContent() function is called in routes.js on line 5. This helps us realize the reason our program is failing is we did not define content and pass it to our recursiveContent() function.
We've learned how to return additional stack traces, and how these can help us to debug our applications.
How it works
In the recipe, we make use of the --stack-trace-limit flag. This flag instructs the V8 JavaScript engine to retain more stacks. When an error occurs, the stack trace will show the preceding function calls up to the limit set with the flag. In the recipe, we extended this to 20 stack frames.
Note that it is also possible to set this limit from within your application code. The following line would set the stack trace limit to 20:
Error.stackTraceLimit = 20;
It is also possible to set the stack trace limit to Infinity, meaning all preceding function calls will be retained:
Error.stackTraceLimit = Infinity
Storing additional stack traces comes with a performance cost in terms of CPU and memory usage. You should consider the impact this may have on your application.
There's more
Asynchronous stack traces were added to Node.js 12 via the V8 JavaScript engine update, these can help us debug our asynchronous functions.
Asynchronous stack traces help us to debug asynchronous functions in our programs. Let's take a look at an asynchronous stack trace:
- Create a file named async-stack-trace.js:
$ touch async-stack-trace.js
- Add the following to async-stack-trace.js:
foo().then(
() => console.log("success"),
(error) => console.error(error.stack)
);
async function foo() {
await bar();
}
async function bar() {
await Promise.resolve();
throw new Error("Fail");
}
This program contains an asynchronous function, foo(), that awaits a function named bar(). bar() automatically resolves a Promise and then throws an error.
- In versions of Node.js before Node.js 12, the following stack trace would be returned from the program:
Error: Fail
at bar (/Users/bethgriggs/Node.js-14-Cookbook/Chapter13/stack-trace-app/async-stack-trace.js:12:9)
at process._tickCallback (internal/process/next_tick.js:68:7)
at Function.Module.runMain (internal/modules/cjs/loader.js:834:11)
at startup (internal/bootstrap/node.js:283:19)
at bootstrapNodeJSCore (internal/bootstrap/node.js:623:3)
Observe that the trace just tells us the error is in the bar() function, followed by some internal function calls such as process._tickCallback(). Prior to Node.js 12, stack traces were unable to effectively report the asynchronous function calls. Note that the stack frames do not show that the bar() function was called by foo().
- However, thanks to an updated V8 engine, Node.js 12 and greater enable asynchronous stack traces. We will now get the following stack output when we run the same program with Node.js 14 (with $ node async-stack-trace.js):
Error: Fail
at bar (/Users/bethgriggs/Node.js-14-Cookbook/Chapter13/stack-trace-app/async-stack-trace.js:12:9)
at async foo (/Users/bethgriggs/Node.js-14-Cookbook/Chapter13/stack-trace-app/async-stack-trace.js:7:3)
The stack traces in newer versions of Node.js can show us that the bar() function was called by an asynchronous function named foo().
See also
- The Building web applications with Express.js recipe in Chapter 6, Exploring Node.js Web Frameworks
- The Logging with Node.js recipe in this chapter
- The Enabling Node.js core debug logs recipe in this chapter
- The Creating diagnostic reports recipe in this chapter
Creating diagnostic reports
The diagnostic report utility has been available behind a process flag since Node.js v11.8.0. The diagnostic report utility allows you to generate a report containing diagnostic data on demand or when certain events occur. The situations where a report could be generated include when your application crashes, or when your application is experiencing slow performance or high CPU usage.
It fulfills a similar purpose to the Java core file. The diagnostic report contains information that can be useful to help diagnose problems in applications. The information reported includes the Node.js version, the event that triggered the report, stack traces, and more.
Historically, the diagnostic report utility was available as an npm module named node-report. But, to improve adoption and enhance the core diagnostic features, it was merged into Node.js core.
In this recipe, we'll learn how to enable and configure the diagnostic report utility and generate a report when an uncaught exception happens in our application.
Getting ready
- First, let's create a directory named diagnostic-report:
$ mkdir diagnostic-report
$ cd diagnostic-report
- And a now let's create a file to hold our server named server.js:
$ touch server.js
- Let's also create a directory to store the reports:
$ mkdir reports
Now, we are ready to move on to the recipe steps.
How to do it
In this recipe, we're going to use the diagnostic report utility to create a report on unhandled errors. We'll set a custom directory and filename for the report. We'll also inspect the generated report for information about the unhandled errors:
- First, let's import the core Node.js modules we need for the recipe into server.js:
const http = require("http");
const path = require("path");
- Now, let's set the directory and filename for our diagnostic report to be captured in:
process.report.directory = path.join(__dirname, "reports");
process.report.filename = "my-diagnostic-report.json";
- Now, we'll send a request to a web server, but we'll intentionally specify an invalid protocol. Add the following line to server.js:
http.get("hello://localhost:3000", (response) => {});
- Now, if we run the application, we should expect to see the following uncaught ERR_INVALID_PROTOCOL error:
$ node server.js
_http_client.js:155
throw new ERR_INVALID_PROTOCOL(protocol, expectedProtocol);
^
TypeError [ERR_INVALID_PROTOCOL]: Protocol "hello:" not supported. Expected "http:"
at new ClientRequest (_http_client.js:155:11)
at request (http.js:47:10)
at Object.get (http.js:51:15)
at Object.<anonymous> (/Users/bethgriggs/Node-Cookbook/Chapter13/diagnostic-report/server.js:7:6)
at Module._compile (internal/modules/cjs/loader.js:1200:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:1220:10)
at Module.load (internal/modules/cjs/loader.js:1049:32)
at Function.Module._load (internal/modules/cjs/loader.js:937:14)
at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
at internal/main/run_main_module.js:17:47 {
code: 'ERR_INVALID_PROTOCOL'
}
- To enable the diagnostic report feature, we need to start the Node.js process with the --report-uncaught-exception flag. Expect to see the following output, showing that a report has been created:
$ node --report-uncaught-exception server.js
Writing Node.js report to file: my-diagnostic-report.json
Node.js report completed
_http_client.js:155
throw new ERR_INVALID_PROTOCOL(protocol, expectedProtocol);
^
TypeError [ERR_INVALID_PROTOCOL]: Protocol "hello:" not supported. Expected "http:"
at new ClientRequest (_http_client.js:155:11)
at request (http.js:47:10)
at Object.get (http.js:51:15)
at Object.<anonymous> (/Users/bethgriggs/Node-Cookbook/Chapter13/diagnostic-report/server.js:7:6)
at Module._compile (internal/modules/cjs/loader.js:1200:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:1220:10)
at Module.load (internal/modules/cjs/loader.js:1049:32)
at Function.Module._load (internal/modules/cjs/loader.js:937:14)
at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
at internal/main/run_main_module.js:17:47 {
code: 'ERR_INVALID_PROTOCOL'
}
- Now, we can take a look at the report. It should have been created in the reports directory with the name my-diagnostic-report.json. Open the file in your editor.
- Identify the event and trigger properties towards the top of the file and observe that it provides details about the event that triggered the error:
"event": "Protocol \"hello:\" not supported. Expected \"http:\"",
"trigger": "Exception",
- Further down in the file, identify the javascriptStack property. It should provide the stack trace of the error:
"javascriptStack": {
"message": "TypeError [ERR_INVALID_PROTOCOL]: Protocol \"hello:\" not supported. Expected \"http:\"",
"stack": [
"at new ClientRequest (_http_client.js:155:11)",
"at request (http.js:47:10)",
"at Object.get (http.js:51:15)",
"at Object.<anonymous> (/Users/bethgriggs/Node-Cookbook/Chapter13/diagnostic-report/server.js:7:6)",
"at Module._compile (internal/modules/cjs/loader.js:1200:30)",
"at Object.Module._extensions..js (internal/modules/cjs/loader.js:1220:10)",
"at Module.load (internal/modules/cjs/loader.js:1049:32)",
"at Function.Module._load (internal/modules/cjs/loader.js:937:14)",
"at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)"
]
}
Now we've learned how to enable the diagnostic report utility on uncaught exceptions and how to inspect the report for diagnostic information.
How it works
The diagnostic report utility enables a diagnostic summary to be written in a file under certain conditions. The utility is built into Node.js core and is enabled by passing one of the following command-line flags to the Node.js process:
- --report-uncaught-exception: As used in the recipe, it triggers a crash on an uncaught exception.
- --report-on-signal: A report is triggered upon receiving a specified signal.
- --report-on-fatalerror: A report is triggered on a fatal error, such as an out of memory error.
Note that it is also possible to trigger the generation of the report from within your application using the following line:
process.report.writeReport();
In the recipe, we first set up a custom directory by assigning the process.report.directory and process.report.filename variables in the program. These can also be set via the --report-directory and --report-filename command-line arguments. Neither the directory nor filename is required to be set. When the directory is omitted, the report will be generated in the directory from which we start the Node.js process. When omitting a specified filename, the utility will default to creating one with the following naming convention: report.20181126.091102.8480.0.001.json.
See also
- The Enabling Node.js core debug logs recipe in this chapter
- The Increasing stack trace size recipe in this chapter
