Node.js Development & Consulting

Talk with an expert

Try our Node.js monitoring tool

node.js debugging

How to Debug Node.js with the Best Tools Available

How to Debug Node.js with the Best Tools Available

Debugging - the process of finding and fixing defects in software - can be a challenging task to do in all languages. Node.js is no exception.

Luckily, the tooling for finding these issues improved a lot in the past period. Let's take a look at what options you have to find and fix bugs in your Node.js applications!

We will dive into two different aspects of debugging Node.js applications - the first one will be logging, so you can keep an eye on production systems, and have events from there. After logging, we will take a look at how you can debug your applications in development environments.

Logging in Node.js

Logging takes place in the execution of your application to provide an audit trail that can be used to understand the activity of the system and to diagnose problems to find and fix bugs.

For logging purposes, you have lots of options when building Node.js applications. Some npm modules are shipped with built in logging that can be turned on when needed using the debug module. For your own applications, you have to pick a logger too! We will take a look at pino.

Before jumping into logging libraries, let's take a look what requirements they have to fulfil:

  • timestamps - it is crucial to know which event happened when,
  • formatting - log lines must be easily understandable by humans, and straightforward to parse for applications,
  • log destination - it should be always the standard output/error, applications should not concern themselves with log routing,
  • log levels - log events have different severity levels, in most cases, you won't be interested in debug or info level events.

The debug module of Node.js

Recommendation: use for modules published on npm

Let's see how it makes your life easier! Imagine that you have a Node.js module that sends serves requests, as well as send out some.

// index.js
const debugHttpIncoming = require('debug')('http:incoming')  
const debugHttpOutgoing = require('debug')('http:outgoing')

let outgoingRequest = {  
  url: 'https://risingstack.com'
}

// sending some request
debugHttpOutgoing('sending request to %s', outgoingRequest.url)

let incomingRequest = {  
  body: '{"status": "ok"}'
}

// serving some request
debugHttpOutgoing('got JSON body %s', incomingRequest.body)  

Once you have it, start your application this way:

DEBUG=http:incoming,http:outgoing node index.js  

The output will be something like this:

Output of Node.js Debugging

Also, the debug module supports wildcards with the * character. To get the same result we got previously, we simply could start our application with DEBUG=http:* node index.js.

What's really nice about the debug module is that a lot of modules (like Express or Koa) on npm are shipped with it - as of the time of writing this article more than 14.000 modules.

The pino logger module

Recommendation: use for your applications when performance is key

Pino is an extremely fast Node.js logger, inspired by bunyan. In many cases, pino is over 6x faster than alternatives like bunyan or winston:

benchWinston*10000:     2226.117ms  
benchBunyan*10000:      1355.229ms  
benchDebug*10000:       445.291ms  
benchLogLevel*10000:    322.181ms  
benchBole*10000:        291.727ms  
benchPino*10000:        269.109ms  
benchPinoExtreme*10000: 102.239ms  

Getting started with pino is straightforward:

const pino = require('pino')()

pino.info('hello pino')  
pino.info('the answer is %d', 42)  
pino.error(new Error('an error'))  

The above snippet produces the following log lines:

{"pid":28325,"hostname":"Gergelys-MacBook-Pro.local","level":30,"time":1492858757722,"msg":"hello pino","v":1}
{"pid":28325,"hostname":"Gergelys-MacBook-Pro.local","level":30,"time":1492858757724,"msg":"the answer is 42","v":1}
{"pid":28325,"hostname":"Gergelys-MacBook-Pro.local","level":50,"time":1492858757725,"msg":"an error","type":"Error","stack":"Error: an error\n    at Object.<anonymous> (/Users/gergelyke/Development/risingstack/node-js-at-scale-debugging/pino.js:5:12)\n    at Module._compile (module.js:570:32)\n    at Object.Module._extensions..js (module.js:579:10)\n    at Module.load (module.js:487:32)\n    at tryModuleLoad (module.js:446:12)\n    at Function.Module._load (module.js:438:3)\n    at Module.runMain (module.js:604:10)\n    at run (bootstrap_node.js:394:7)\n    at startup (bootstrap_node.js:149:9)\n    at bootstrap_node.js:509:3","v":1}

The Built-in Node.js Debugger module

Node.js ships with an out-of-process debugging utility, accessible via a TCP-based protocol and built-in debugging client. You can start it using the following command:

$ node debug index.js

This debugging agent is a not a fully featured debugging agent - you won't have a fancy user interface, however, simple inspections are possible.

You can add breakpoints to your code by adding the debugger statement into your codebase:

const express = require('express')  
const app = express()

app.get('/', (req, res) => {  
  debugger
  res.send('ok')
})

This way the execution of your script will be paused at that line, then you can start using the commands exposed by the debugging agent:

  • cont or c - continue execution,
  • next or n - step next,
  • step or s - step in,
  • out or o - step out,
  • repl - to evaluate script's context.

V8 Inspector Integration for Node.js

The V8 inspector integration allows attaching Chrome DevTools to Node.js instances for debugging by using the Chrome Debugging Protocol.

V8 Inspector can be enabled by passing the --inspect flag when starting a Node.js application:

$ node --inspect index.js

In most cases, it makes sense to stop the execution of the application at the very first line of your codebase and continue the execution from that. This way you won't miss any command execution.

$ node --inspect-brk index.js


I recommend watching this video in full-screen mode to get every detail!

How to Debug Node.js with Visual Studio Code

Most modern IDEs have some support for debugging applications - so does VS Code. It has built-in debugging support for Node.js.

What you can see below, is the debugging interface of VS Code - with the context variables, watched expressions, call stack and breakpoints.

VS Code Debugging Layout Image credit: Visual Studio Code

One of the most valuable features of the integrated Visual Studio Code debugger is the ability to add conditional breakpoints. With conditional breakpoints, the breakpoint will be hit whenever the expression evaluates to true.

If you need more advanced settings for VS Code, it comes with a configuration file, .vscode/launch.json which describes how the debugger should be launched. The default launch.json looks something like this:

{
    "version": "0.2.0",
    "configurations": [
        {
            "type": "node",
            "request": "launch",
            "name": "Launch Program",
            "program": "${workspaceRoot}/index.js"
        },
        {
            "type": "node",
            "request": "attach",
            "name": "Attach to Port",
            "address": "localhost",
            "port": 5858
        }
    ]
}

For advanced configuration settings of launch.json go to https://code.visualstudio.com/docs/editor/debugging#_launchjson-attributes.

For more information on debugging with Visual Studio Code, visit the official site: https://code.visualstudio.com/docs/editor/debugging.

Next Up

If you have any questions about debugging, please let me know in the comments section.

In the next episode of the Node.js at Scale series, we are going to talk about Node.js Post-Mortem Diagnostics & Debugging.

Announcing Free Node.js Monitoring & Debugging with Trace

Announcing Free Node.js Monitoring & Debugging with Trace

Today, we’re excited to announce that Trace, our Node.js monitoring & debugging tool is now free for open-source projects.

What is Trace?

We launched Trace a year ago with the intention of helping developers looking for a Node.js specific APM which is easy to use and helps with the most difficult aspects of building Node projects, like..

  • finding memory leaks in a production environment
  • profiling CPU usage to find bottlenecks
  • tracing distributed call-chains
  • avoiding security leaks & bad npm packages

.. and so on.

Node.js Monitoring with Trace by RisingStack - Performance Metrics chart

Why are we giving it away for free?

We use a ton of open-source technology every day, and we are also the maintainers of some.

We know from experience that developing an open-source project is hard work, which requires a lot of knowledge and persistence.

Trace will save a lot of time for those who use Node for their open-source projects.

How to get started with Trace?

  1. Visit trace.risingstack.com and sign up - it's free.
  2. Connect your app with Trace.
  3. Head over to this form and tell us a little bit about your project.

Done. Your open-source project will be monitored for free as a result.

If you need help with Node.js Monitoring & Debugging..

Just drop us a tweet at @RisingStack if you have any additional questions about the tool or the process.

If you'd like to read a little bit more about the topic, I recommend to read our previous article The Definitive Guide for Monitoring Node.js Applications.

One more thing

At the same time of making Trace available for open-source projects, we're announcing our new line of business at RisingStack:

Commercial Node.js support, aimed at enterprises with Node.js applications running in a production environment.

RisingStack now helps to bootstrap and operate Node.js apps - no matter what life cycle they are in.


Disclaimer: We retain the exclusive right to accept or deny your application to use Trace by RisingStack for free.

Node.js War Stories: Debugging Issues in Production

Node.js War Stories: Debugging Issues in Production

In this article, you can read stories from Netflix, RisingStack & nearForm about Node.js issues in production - so you can learn from our mistakes and avoid repeating them. You'll also learn what methods we used to debug these Node.js issues.

Special shoutout to Yunong Xiao of Netflix, Matteo Collina of nearForm & Shubhra Kar from Strongloop for helping us with their insights for this post!


At RisingStack, we have accumulated a tremendous experience of running Node apps in production in the past 4 years - thanks to our Node.js consulting, training and development business.

As well as the Node teams at Netflix & nearForm we picked up the habit of always writing thorough postmortems, so the whole team (and now the whole world) could learn from the mistakes we made.

Netflix & Debugging Node: Know your Dependencies

Let's start with a slowdown story from Yunong Xiao, which happened with our friends at Netflix.

The trouble started with the Netflix team noticing that their applications response time increased progressively - some of their endpoints' latency increased with 10ms every hour.

This was also reflected in the growing CPU usage.

Netflix debugging Nodejs in production with the Request latency graph Request latencies for each region over time - photo credit: Netflix

At first, they started to investigate whether the request handler is responsible for slowing things down.

After testing it in isolation, it turned out that the request handler had a constant response time around 1ms.

So the problem was not that, and they started to suspect that probably it's deeper in the stack.

The next thing Yunong & the Netflix team tried are CPU flame graphs and Linux Perf Events.

Flame graph of Netflix Nodejs slowdown Flame graph or the Netflix slowdown - photo credit: Netflix

What you can see in the flame graph above is that

  • it has high stacks (which means lot of function calls)
  • and the boxes are wide (meaning we are spending quite some time in those functions).

After further inspection, the team found that Express's router.handle and router.handle.next has lots of references.

The Express.js source code reveals a couple of interesting tidbits:

  • Route handlers for all endpoints are stored in one global array.
  • Express.js recursively iterates through and invokes all handlers until it finds the right route handler.

Before revealing the solution of this mystery, we have to get one more detail:

Netflix's codebase contained a periodical code that ran every 6 minutes and grabbed new route configs from an external resource and updated the application's route handlers to reflect the changes.

This was done by deleting old handlers and adding new ones. Accidentally, it also added the same static handler all over again - even before the API route handlers. As it turned out, this caused the extra 10ms response time hourly.

Takeaways from Netflix's Issue

  • Always know your dependencies - first, you have to fully understand them before going into production with them.
  • Observability is key - flame graphs helped the Netflix engineering team to get to the bottom of the issue.

Read the full story here: Node.js in Flames.


Expert help when you need it the most

Commercial Node.js Support by RisingStack
Learn more


RisingStack CTO: "Crypto takes time"

You may have already heard to story of how we broke down the monolithic infrastructure of Trace (our Node.js monitoring solution) into microservices from our CTO, Peter Marton.

The issue we'll talk about now is a slowdown which affected Trace in production:

As the very first versions of Trace ran on a PaaS, it used the public cloud to communicate with other services of ours.

To ensure the integrity of our requests, we decided to sign all of them. To do so, we went with Joyent's HTTP signing library. What's really great about it, is that the request module supports HTTP signature out of the box.

This solution was not only expensive, but it also had a bad impact on our response times.

network delay in nodejs request visualized by trace The network delay built up our response times - photo: Trace

As you can see on the graph above, the given endpoint had a response time of 180ms, however from that amount, 100ms was just the network delay between the two services alone.

As the first step, we migrated from the PaaS provider to use Kubernetes. We expected that our response times would be a lot better, as we can leverage internal networking.

We were right - our latency improved.

However, we expected better results - and a lot bigger drop in our CPU usage. The next step was to do CPU profiling, just like the guys at Netflix:

crypto sign function taking up cpu time

As you can see on the screenshot, the crypto.sign function takes up most of the CPU time, by consuming 10ms on each request. To solve this, you have two options:

  • if you are running in a trusted environment, you can drop request signing,
  • if you are in an untrusted environment, you can scale up your machines to have stronger CPUs.

Takeaways from Peter Marton

  • Latency in-between your services has a huge impact on user experience - whenever you can, leverage internal networking.
  • Crypto can take a LOT of time.

nearForm: Don't block the Node.js Event Loop

React is more popular than ever. Developers use it for both the frontend and the backend, or they even take a step further and use it to build isomorphic JavaScript applications.

However, rendering React pages can put some heavy load on the CPU, as rendering complex React components is CPU bound.

When your Node.js process is rendering, it blocks the event loop because of its synchronous nature.

As a result, the server can become entirely unresponsive - requests accumulate, which all puts load on the CPU.

What can be even worse is that even those requests will be served which no longer have a client - still putting load on the Node.js application, as Matteo Collina of nearForm explains.

It is not just React, but string operations in general. If you are building JSON REST APIs, you should always pay attention to JSON.parse and JSON.stringify.

As Shubhra Kar from Strongloop (now Joyent) explained, parsing and stringifying huge payloads can take a lot of time as well (and blocking the event loop in the meantime).

function requestHandler(req, res) {  
  const body = req.rawBody
  let parsedBody
  try {
    parsedBody = JSON.parse(body)
  }
  catch(e) {
     res.end(new Error('Error parsing the body'))
  }
  res.end('Record successfully received')
}

Simple request handler

The example above shows a simple request handler, which just parses the body. For small payloads, it works like a charm - however, if the JSON's size can be measured in megabytes, the execution time can be seconds instead of milliseconds. The same applies for JSON.stringify.

To mitigate these issues, first, you have to know about them. For that, you can use Matteo's loopbench module, or Trace's event loop metrics feature.

With loopbench, you can return a status code of 503 to the load balancer, if the request cannot be fulfilled. To enable this feature, you have to use the instance.overLimit option. This way ELB or NGINX can retry it on a different backend, and the request may be served.

Once you know about the issue and understand it, you can start working on fixing it - you can do it either by leveraging Node.js streams or by tweaking the architecture you are using.

Takeaways from nearForm

  • Always pay attention to CPU bound operations - the more you have, to more pressure you put on your event loop.
  • String operations are CPU-heavy operations

Debugging Node.js Issues in Production

I hope these examples from Netflix, RisingStack & nearForm will help you to debug your Node.js apps in Production.

If you'd like to learn more, I recommend checking out these recent posts which will help you to deepen your Node knowledge:

If you have any questions, please let us know in the comments!

Hunting a Ghost - Finding a Memory Leak in Node.js

Hunting a Ghost - Finding a Memory Leak in Node.js

Finding a Node.js memory leak can be quite challenging - recently we had our fair share of it.

One of our client's microservices started to produce the following memory usage:


Node.js memory leak in Trace

Memory usage grabbed with Trace by RisingStack - our Node.js Performance monitoring and debugging tool

You may spend quite a few days on things like this: profiling the application and looking for the root cause. In this post, I would like to summarize what tools you can use and how, so you can learn from it.

The TL;DR version

In our particular case the service was running on a small instance, with only 512MB of memory. As it turned out, the application didn't leak any memory, simply the GC didn't start collecting unreferenced objects.

Why was it happening? As a default, Node.js will try to use about 1.5GBs of memory, which has to be capped when running on systems with less memory. This is the expected behaviour as garbage collection is a very costly operation.

The solution for it was adding an extra parameter to the Node.js process:

node --max_old_space_size=400 server.js --production  

Still, if it is not this obvious, what are your options to find memory leaks?



Monitor your memory usage and find leaks with ease. - check out Trace by RisingStack!


Understanding V8's Memory Handling

Before diving into the technics that you can employ to find and fix memory leaks in Node.js applications, let's take a look at how memory is handled in V8.

Definitions
  • resident set size: is the portion of memory occupied by a process that is held in the RAM, this contains:
    • the code itself
    • the stack
    • the heap
  • stack: contains primitive types and references to objects
  • heap: stores reference types, like objects, strings or closures
  • shallow size of an object: the size of memory that is held by the object itself
  • retained size of an object: the size of the memory that is freed up once the object is deleted along with its' dependent objects
How The Garbage Collector Works

Garbage collection is the process of reclaiming the memory occupied by objects that are no longer in use by the application. Usually, memory allocation is cheap while it's expensive to collect when the memory pool is exhausted.

An object is a candidate for garbage collection when it is unreachable from the root node, so not referenced by the root object or any other active objects. Root objects can be global objects, DOM elements or local variables.

The heap has two main segments, the New Space and the Old Space. The New Space is where new allocations are happening; it is fast to collect garbage here and has a size of ~1-8MBs. Objects living in the New Space are called Young Generation. The Old Space where the objects that survived the collector in the New Space are promoted into - they are called the Old Generation. Allocation in the Old Space is fast, however collection is expensive so it is infrequently performed .

Why is garbage collection expensive? The V8 JavaScript engine employs a stop-the-world garbage collector mechanism. In practice, it means that the program stops execution while garbage collection is in progress.

Usually, ~20% of the Young Generation survives into the Old Generation. Collection in the Old Space will only commence once it is getting exhausted. To do so the V8 engine uses two different collection algorithms:

  • Scavenge collection, which is fast and runs on the Young Generation,
  • Mark-Sweep collection, which is slower and runs on the Old Generation.

For more information on how this works check out the A tour of V8: Garbage Collection article. For more information on general memory management, visit the Memory Management Reference.

Tools / Technics You Can Use to Find a Memory Leak in Node.js

The heapdump module

With the heapdump module, you can create a heap snapshot for later inspection. Adding it to your project is as easy as:

npm install heapdump --save  

Then in your entry point just add:

var heapdump = require('heapdump');  

Once you are done with it, you can start collecting heapdump with either using the $ kill -USR2 <pid> command or by calling:

heapdump.writeSnapshot(function(err, filename) {  
  console.log('dump written to', filename);
});

Once you have your snapshots, it's time to make sense of them. Make sure you capture multiple of them with some time difference so you can compare them.

Google Chrome DevTools

First you have to load your memory snapshots into the Chrome profiler. To do so, open up Chrome DevTools, go to profiles and Load your heap snapshots.

find a node.js memory leak with chrome load profiles

Once you loaded them it should be something like this:

chrome heap snapshot for finding a node.js memory leak

So far so good, but what can be seen exactly in this screenshot?

One of the most important things here to notice is the selected view: Comparison. This mode enables you to compare two (or more) heap snapshots taken at different times, so you can pinpoint exactly what objects were allocated and not freed up in the meantime.

The other important tab is the Retainers. It shows exactly why an object cannot be garbage collected, what is holding a reference to it. In this case the global variable called log is holding a reference to the object itself, preventing the garbage collector to free up space.

Low-Level Tools

mdb

The mdb utility is an extensible utility for low-level debugging and editing of the live operating system, operating system crash dumps, user processes, user process core dumps, and object files.

gcore

Generate a core dump of a running program with process ID pid.

Putting it together

To investigate dumps, first we have to create one. You can easily do so with:

gcore `pgrep node`  

After you have it, you can search for the all the JS Objects on the heap using:

> ::findjsobjects

Of course, you have to take successive core dumps so that you can compare different dumps.

Once you identified objects that look suspicious, you can analyze them using:

object_id::jsprint  

Now all you have to do is find the retainer of the object (the root).

object_id::findjsobjects -r  

This command will return with id of the retainer. Then you can use ::jsprint again to analyze the retainer.

For a detailed version check out Yunong Xiao's talk from Netflix on how to use it:

Recommended Reading

UPDATE: Read the story of how we found a memory leak in our blogging platform by comparing heapshots with Trace and Chrome's DevTools.

You have additional thoughts or insights on Node.js memory leaks? Share it in the comments.