Production Practices

MDB and Node.js

MDB is the illumos modular debugger. MDB is widely used on illumos systems (including SmartOS) to debug the live kernel, kernel crash dumps, processes, and process core dumps. This document describes MDB’s support for debugging Node.js programs.

MDB’s focus is on inspecting program state — and letting application developers build custom tools to inspect their programs — rather than on source code analysis and control flow. While MDB supports breakpoints and single-stepping through assembly, it doesn’t support JavaScript (or even C) source-level debugging. What it can do is show you all of the state in your program: JavaScript objects.

Why MDB?

While console.log debugging is effective for reproducible problems in controlled environments, it doesn’t work very well in production for a bunch of good reasons:

  • Each lap is expensive. Even with a nimble deployment process, it takes time to get new code deployed to production. If you’re skipping deployment and editing live code, you risk taking down your service with a typo, leaving code running in production that’s not checked into the repo, or forgetting to update other instances of the service.
  • Each lap is disruptive. You usually have to restart a service to pick up code changes, and that’s usually visible as downtime, however brief, to users of your service. (If you use dynamic monkey patching to avoid this, you risk other, more difficult-to-debug issues related to having run an untested combination of components in the same process.)
  • Production problems are often hard to reproduce. Problems in distributed systems are especially hard to reproduce on the instance that you’re debugging.
  • Worse, restarts often make the original problem go away. Many problems result from bad in-memory state that’s recreated on restart, so if you restart the service, you lose all hope of debugging it.

So it’s very useful to be able to debug a running program while it’s broken. Besides using MDB, other popular techniques include building a REPL into your program or some other way to pull out program state. These are extremely useful, but have their own limitations:

  • They don’t work to debug crashes, since the program’s gone at that point.
  • They usually don’t work to debug infinite loops, since the program’s stuck.
  • They can’t show you all of the state in your program, like the files it has open, JavaScript objects that aren’t referenced by these tools, or the C-level state used by native add-ons.

Getting started

Prerequisites

All of the following works out-of-the-box on recent SmartOS builds, as well as SmartOS instances provisioned on the Triton Public Cloud.

You can also run the Node example on a GNU/Linux system, but you’ll have to save a core file and run the MDB parts on SmartOS (e.g., using mlogin on Manta).

Working through an example

/* * This script demonstrates a simple stack trace involving an anonymous * function, then goes into an infinite loop so you can catch it with the

* debugger.  One caveat: we grab a stack trace at the start to force V8 to

* compute line number information for this script.  If we didn't have this, the

* debugger would only print out position-in-file information. */

new Error().stack;

function main(arg) { func1(); }

function func1() { func2(); }

function func2()

{

      (function () {

           or (;;);

         })();

}

main({ 'hello': 'world' });

Run this program in the background with node v0.10.24:

$ node -v

v0.10.24

$ node loop.js &

[2] 17334

$

and attach MDB to that process (pid 17334):

$ mdb -p 17334

Loading modules: [ ld.so.1 libumem.so.1 libc.so.1 ]

>

When you attach MDB to a process like this, it stops the process and gives you a prompt. ::status is a good place to start (most MDB commands start with ::):

> ::status

debugging PID 17334 (32-bit)

file: /home/dap/node-v0.10.24-sunos-x86/bin/node

threading model: native threads

status: stopped by debugger

Don’t worry if you don’t know what all that means. MDB is telling you that it’s attached to pid 17334, which is a 32-bit process, and it’s currently stopped.

In order to get any of the Node-specific debugger commands, you have to run ::load v8:1

> ::load v8

V8 version: 3.14.5.9

Autoconfigured V8 support from target

C++ symbol demangling enabled

Now you can get a combined JavaScript/C stack trace with ::jsstack:

> ::jsstack

8047620 0xafa59dee <anonymous> (as <anon>) (a0784dc5)

file: /home/dap/demo/loop.js    

posn: line 15

804763c 0xafa59951 func2 (a0781379)

8047654 0xafa597eb func1 (a0781355)

804766c 0xafa5974b main (a0781331)

804768c 0xafa53c9c <anonymous> (as <anon>) (a0781285)

80476c0 0xafa141a5 <InternalFrame>

80476f8 0xafa53697 <anonymous> (as Module._compile) (8e22e04d)

8047718 0xafa4f799 <anonymous> (as Module._extensions..js) (8e22e08d)

804773c 0xafa4c73f <anonymous> (as Module.load) (8e22e005)

804777c 0xafa3fa37 <anonymous> (as Module._load) (8e22dfbd)

804779c 0xafa3f593 <anonymous> (as Module.runMain) (8e22e0d5)

80477d0 0xafa298f6 startup (a072461d)80477ec 0xafa2910b <anonymous> (as <anon>) (a0723f95)

804780c 0xafa0fe19 <InternalFrame>

8047848 0xafa0a0aa <EntryFrame>

80478c8

_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x

101

8047908 v8::internal::Execution::Call+0xc9

8047968 v8::Function::Call+0x10b

80479d8 node::Load+0x14e

8047a38 node::Start+0x158

8047a58 main+0x1b

8047a70 _start+0x83

You can ignore the first column, as well as the pointers that sta

8047620 0xafa59dee <anonymous> (as <anon>) (a0784dc5)rt with 0x.2 The top frame is what you’d expect: it’s our anonymous function, created at line 15. That was called by func2, which was called by func1, which was called by main. After that you see the JavaScript and C frames that are part of Node itself.

You can get more information about the whole stack using ::jsstack -v:

> ::jsstack -v

8047620 0xafa59dee <anonymous> (as <anon>) (a0784dc5)

       file: /home/dap/demo/loop.js

      posn: line 15

804763c 0xafa59951 func2 (a0781379)

      file: /home/dap/demo/loop.js    

      posn: line 13

8047654 0xafa597eb func1 (a0781355)    

     file: /home/dap/demo/loop.js    

     posn: line 11

804766c 0xafa5974b main (a0781331)  

      file: /home/dap/demo/loop.js    

      posn: line 10  

     arg1: a0784db5 (JSObject)

804768c 0xafa53c9c <anonymous> (as <anon>) (a0781285)    

file: /home/dap/demo/loop.js    

     posn: line 1    

      arg1: a077f6cd (JSObject)    

      arg2: a0780ae1 (JSFunction)    

      arg3: a077f651 (JSObject)  

      arg4: a077e091 (ConsString)    

     arg5: a0780f95 (ConsString)80476c0 0xafa141a5 <InternalFrame>

80476f8 0xafa53697 <anonymous> (as Module._compile) (8e22e04d)  

   file: module.js  

   posn: line 374    

    arg1: a07807f9 (SeqAsciiString)    

    arg2: a077e091 (ConsString)

8047718 0xafa4f799 <anonymous> (as Module._extensions..js) (8e22e08d)    

     file: module.js    

     posn: line 472    

     arg1: a077f651 (JSObject)    

    arg2: a077e091 (ConsString)

804773c 0xafa4c73f <anonymous> (as Module.load) (8e22e005)    

     file: module.js    

    posn: line 346    a

    rg1: a077e091 (ConsString)

804777c 0xafa3fa37 <anonymous> (as Module._load) (8e22dfbd)    

file: module.js    

posn: line 275    

arg1: a0746315 (ConsString)  

arg2: 8e208081 (Oddball: "null")    

arg3: 8e2080a1 (Oddball: "true")

804779c 0xafa3f593 <anonymous> (as Module.runMain) (8e22e0d5)  

file: module.js    

posn: line 49580477d0 0xafa298f6 startup (a072461d)    

file: node.js    

posn: line 3080477ec 0xafa2910b <anonymous> (as <anon>) (a0723f95)    

file: node.js    

posn: line 27    

arg1: a071e9a9 (JSObject)

804780c 0xafa0fe19 <InternalFrame>

8047848 0xafa0a0aa <EntryFrame>

80478c8_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101

8047908 v8::internal::Execution::Call+0xc9

8047968 v8::Function::Call+0x10b

80479d8 node::Load+0x14e

8047a38 node::Start+0x158

8047a58 main+0x1b8047a70 _start+0x83

Now with each of the JavaScript stack frames, you have the filename and line number where the function was defined, along with the arguments it was passed. You can print these arguments by taking the pointer value (the hex number) and using ::jsprint. Here’s how you’d print arg1 to our main() function (the fourth frame down):

> a0784db5::jsprint

{    hello: "world",

}

which is exactly what we passed.

Finding JavaScript objects

MDB can find any JavaScript object in your program.

8e21a321        1        0 <anonymous> (as d)It does this by scanning the entire JavaScript heap and classifying objects by their properties. You do this with ::findjsobjects. This may take a minute, then it prints out a summary of what it found:

> ::findjsobjects

OBJECT #OBJECTS   #PROPS CONSTRUCTOR: PROPS

8e2254c9        1        0 Buffer

a071f289        1        0 <anonymous> (as <anon>)

8e21a321        1        0 <anonymous> (as d)

8e2154a9        1        0 MathConstructor

8e209b31        1        0 JSON

8e22d401        1        0 Module

a0708081       26        0

a0715901       35        0 Array

8e2093cd      329        0 Object

a074a61d        1        1 Object: ...

a074a579        1        1 Object: /home/dap/demo/loop.js

a0711295        1        1 Arguments: length

...

9c912f19        2        5 Object: evals, natives, buffer, fs, constants

9c9109d5        2        5 Object: cflags, default_configuration, defines, ...

a074aea5        1       11 Array

9c90ab55        1       11 process: version, moduleLoadList, versions, ...

9c90aae9        2        6 Object: debug, uv, ipv6, tls_npn, tls_sni, tls

9c90dadd        1       13 Object: _debugger, _linklist, assert, buffer, ...

9c910bcd        1       13 Object: clang, gcc_version, host_arch, ...

9c912ef5        1       13 Object: O_RDONLY, O_WRONLY, O_RDWR, S_IFMT, ...

9c9148f9        2        7 Module: id, exports, parent, filename, loaded, ...

a0718911        1       16 Array

9c90a885        2        8 Object: http_parser, node, v8, ares, uv, zlib, ...

9c9148b1        2       19 process: version, moduleLoadList, versions, ...

...

Each row describes a group of objects that have the same set of properties, so ::findjsobjects groups them together. The first column in each row is a pointer to a representative object for that group. You can print those out with ::jsprint. For example, this one appears to be used internally by Node:

> a074a579::jsprint{

  /home/dap/demo/loop.js: {    

  id: ".",      

 exports: [...],      

parent: null,      

 filename: "/home/dap/demo/loop.js",        

loaded: false,        

children: [...],      

 paths: [...],  

 },}

Once you’ve run “::findjsobjects” once, it keeps track of what it found before so that you can quickly look for more specific kinds of objects. You usually search by a property name. For example, if I wanted to find my “hello world” object (and I didn’t know it was on the stack), I could find it with:

> ::findjsobjects -p hello

a0784d79

> a0784d79::jsprint{

  hello: "world",

}

This is a good time to point out that MDB supports pipelines, similar to most shells. So you can combine these two commands:

> ::findjsobjects -p hello | ::jsprint{  

 hello: "world",

}

Dealing with garbage

The mechanism that “::findjsobjects” uses means that it also tends to pick up “garbage” objects that used to exist in your program, but which are no longer valid. In my process, I can see some of these when I try to look for Node’s global “process” object, which I know has a versions property

> ::findjsobjects -p versions | ::jsprint

mdb: 8e21f06d: unknown JavaScript object type "AccessorInfo"

{

      version: 11,    

     moduleLoadList: 0,

   versions: "title",

   arch: 1572995,

   platform: ,

   argv: "version",

   execArgv: 2621697,

   env: 0,

   pid: "moduleLoadList",

   features: 1835393,

}

...

You can recognize garbage objects because you may see warnings when MDB prints them out (e.g., “unknown JavaScript object type”) and the properties look very wrong. In this case, we know the “versions” property is supposed to be an object, not the string “title”.

These garbage objects are annoying, but they’re generally easily distinguished from valid objects.

Representative objects

Note that “::findjsobjects” only prints out the representative object from each group of objects. Since you might have tens of thousands of instances of the same thing, it doesn’t print all those by default. You have to pipe to ::findjsobjects again to get that. If you wanted to actually find the global “process” object, the reliable way to do that is:

> ::findjsobjects -p versions | ::findjsobjects | ::jsprint

...

{

         version: "v0.10.24",

   moduleLoadList: [

       "Binding evals",

       "Binding natives",

      "NativeModule events",...

   ],

        versions: {

        http_parser: "1.0",

       node: "0.10.24",

       v8: "3.14.5.9",

      ares: "1.9.0-DEV",

       uv: "0.10.21",

       zlib: "1.2.3",  

     modules: "11",

       openssl: "1.0.1e",

   },