A summary diagnostic report for Node.js was introduced in Future directions for diagnostics in Node.js production environments as one of the contributions that the IBM Runtimes development team are focusing on in 2016. This article describes the diagnostic report in more detail, and shows how it can be used as a primary diagnostic for Node.js applications.

First failure data capture (FFDC) covers a range of techniques used in software systems to allow rapid diagnosis of problems with minimal impact to application availability and performance. Techniques used in FFDC include logging of warning and error messages, production of dumps and always-on tracing/flight recorder. The aim is to capture sufficient data on the first incidence of a failure to diagnose and fix a problem without having to re-produce it. Requirements of any solution are that the overhead of error detection and data collection must be low, so that it can be used in production, and that code running after the point of failure needs to be fail-safe itself.

The node-report module produces a summary dump, written as a text file, containing key information about the JavaScript application and the Node.js runtime. Content includes JavaScript and C++ stacks, V8 heap statistics, per-process and per-thread CPU usage, environment variables and resource limits. It can be triggered on unhandled exceptions, fatal errors, signals and by calling a JavaScript API. The runtime overhead of enabling the report is very low. Existing call-backs in Node.js are used to intercept exceptions and fatal errors. There is an additional thread for handling signals, which remains idle unless a report is triggered. The example report shown below is 12Kbytes in size and was written to disk in less than 10 msecs. The implementation is in C++ and can run when the JavaScript environment is no longer available, for example in JavaScript heap out-of-memory conditions.

Installing and using the node-report npm module

The node-report npm module is available for Node.js v4, v6 and v7 on Linux, MacOS, Windows and AIX. It can be installed as follows:

npm install node-report

Using a require() call for node-report in your JavaScript application will configure a report to be triggered automatically on unhandled exceptions, fatal error events (for example out of memory errors), and signals (Unix and Mac OS platforms). A report can also be triggered via an API call from your application:

var nodereport = require('node-report');
nodereport.triggerReport();

Content of the report consists of a header section containing the event type, date, time, PID and Node version, sections containing JavaScript and native stack traces, a section containing V8 heap information, a section containing libuv handle information and an OS platform information section showing CPU and memory usage and system limits. An example report can be triggered using the Node.js REPL:

C:\test>node
> require('node-report').triggerReport()

Writing Node.js report to file: node-report.20161020.091102.8480.001.txt
Node.js report completed
>

When a report is triggered, start and end messages are issued to stderr and the filename of the report is returned to the caller. The default filename includes the date, time, PID and a sequence number. Alternatively, a filename can be specified as a parameter on the triggerReport() call.

nodereport.triggerReport('myReportName');

To see examples of reports generated from these events you can run the demonstration applications provided in the node-report github repo. These are Node.js applications which will prompt you to access via a browser to trigger the required event.

node api_call.js
node fatalerror.js
node api_call.js
node loop.js

Configuration options for the node-report npm module

Configuration is available via JavaScript API calls as follows:

nodereport.setEvents("exception+fatalerror+signal+apicall");
nodereport.setSignal("SIGUSR2|SIGQUIT");
nodereport.setFileName("stdout|stderr|filename");
nodereport.setDirectory("full directory path");
nodereport.setVerbose("yes|no");

Configuration on module initialisation is also available via environment variables. Configuration via the environment variables is actioned when the module is initialized, i.e. when the ‘require(‘node-report’) statement is processed. The configuration can be altered subsequently via the JavaScript API calls above.

export NODEREPORT_EVENTS=exception+fatalerror+signal+apicall
export NODEREPORT_SIGNAL=SIGUSR2|SIGQUIT
export NODEREPORT_FILENAME=stdout|stderr|
export NODEREPORT_DIRECTORY=
export NODEREPORT_VERBOSE=yes|no

Implementation internals

The node-report module has two internal components, both written in C++, including some platform-specific code for Linux, MacOS and Windows:

  1. A module control component processes configuration options and sets up the interception of exception and error events and signals. It also provides the JavaScript NAN APIs for configuring and triggering reports. The V8 SetFatalErrorHandler() API is used to intercept fatal error events. The V8 –abort-on-uncaught-exception option and the SetAbortOnUncaughtExceptionCallback() API are used to intercept uncaught exceptions.
    Signal handling is implemented using a semaphore to hand-off to a watchdog thread, which then schedules the report on the main Node.js event loop. A combination of the V8 RequestInterrupt() and uv_async_send() APIs are used to schedule the report when there is JavaScript code running or when the event loop is idle.

  2. A report writing component constructs the filename, then writes the various sections in the report. V8 Message::PrintCurrentStackTrace(), GetStackSample() and StackTrace::CurrentStackTrace() APIs are used to obtain and print JavaScript stack traces. V8 GetHeapStatistics() and GetHeapSpaceStatistics() APIs are used to obtain V8 heap information. Platform-specific APIs are used to obtain process information, native stack traces, environment variables and resource limits.

Example report for Out of Memory error in a JavaScript Express application

In this example the Node.js instance has terminated because of a memory allocation failure. The report has identified the problem as a failure to allocate space in the JavaScript heap, and shows the JavaScript and C++ stack traces of the code that was running when the failure occurred. It also shows that approximately 51Mb of memory has been allocated to the V8 heap old space region, with less than 1Mb of available space. The environment variables listed in the system information section of the report show that the –max-old-space-size option was set to 64 Mb.

================================================================================
==== Node Report ===============================================================

Event: Allocation failed - JavaScript heap out of memory, location: "CALL_AND_RETRY_LAST"
Filename: node-report.20160815.125548.97.001.txt
Dump event time:  2016/08/15 12:55:48
Module load time: 2016/08/15 12:46:43

Node.js version: v6.3.0
(v8: 5.0.71.52, libuv: 1.9.1, zlib: 1.2.8, ares: 1.10.1-DEV)

OS version: Linux 3.19.0-33-generic #38~14.04.1-Ubuntu SMP Fri Nov 6 18:17:28 UTC 2015
Machine: 19p5p798i5v x86_64

Process ID: 97

================================================================================
==== JavaScript Stack Trace ====================================================

/home/vcap/app/app.js:57:15
Layer.handle [as handle_request] (/home/vcap/app/node_modules/express/lib/router/layer.js:95:5)
next (/home/vcap/app/node_modules/express/lib/router/route.js:131:13)
Route.dispatch (/home/vcap/app/node_modules/express/lib/router/route.js:112:3)
Layer.handle [as handle_request] (/home/vcap/app/node_modules/express/lib/router/layer.js:95:5)
/home/vcap/app/node_modules/express/lib/router/index.js:277:22
Function.process_params (/home/vcap/app/node_modules/express/lib/router/index.js:330:12)
next (/home/vcap/app/node_modules/express/lib/router/index.js:271:10)
SendStream.error (/home/vcap/app/node_modules/serve-static/index.js:120:7)
emitOne (events.js:96:13)
SendStream.emit (events.js:188:7)
SendStream.error (/home/vcap/app/node_modules/serve-static/node_modules/send/index.js:245:17)
SendStream.onStatError (/home/vcap/app/node_modules/serve-static/node_modules/send/index.js:356:12)
next (/home/vcap/app/node_modules/serve-static/node_modules/send/index.js:630:16)
onstat (/home/vcap/app/node_modules/serve-static/node_modules/send/index.js:619:14)
FSReqWrap.oncomplete (fs.js:123:15)

================================================================================
==== Native Stack Trace ========================================================

 0: [pc=0x951ea5] v8::Utils::ReportApiFailure(char const*, char const*) [node]
 1: [pc=0x9520a2] v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [node]
 2: [pc=0xc19e88] v8::internal::Factory::NewUninitializedFixedArray(int) [node]
 3: [pc=0xc0bd7f]  [node]
 4: [pc=0xe102f3] v8::internal::Runtime_GrowArrayElements(int, v8::internal::Object**, v8::internal::Isolate*) [node]
 5: [pc=0x2751e3706338] 

================================================================================
==== JavaScript Heap and Garbage Collector =====================================

Heap space name: new_space
    Memory size: 1,048,576 bytes, committed memory: 52,416 bytes
    Capacity: 1,031,936 bytes, used: 35,776 bytes, available: 996,160 bytes
Heap space name: old_space
    Memory size: 51,298,304 bytes, committed memory: 50,673,800 bytes
    Capacity: 50,117,880 bytes, used: 49,317,408 bytes, available: 800,472 bytes
Heap space name: code_space
    Memory size: 2,097,152 bytes, committed memory: 732,128 bytes
    Capacity: 1,283,968 bytes, used: 669,152 bytes, available: 614,816 bytes
Heap space name: map_space
    Memory size: 1,126,400 bytes, committed memory: 587,240 bytes
    Capacity: 318,648 bytes, used: 318,648 bytes, available: 0 bytes
Heap space name: large_object_space
    Memory size: 6,971,392 bytes, committed memory: 16,640 bytes
    Capacity: 41,913,832 bytes, used: 6,954,728 bytes, available: 34,959,104 bytes

Total heap memory size: 62,541,824 bytes
Total heap committed memory: 52,062,224 bytes
Total used heap memory: 57,295,712 bytes
Total available heap memory: 37,370,552 bytes

Heap memory limit: 134,217,728

================================================================================
==== Resource Usage ============================================================

Process total resource usage:
  User mode CPU: 0.740000 secs
  Kernel mode CPU: 0.256000 secs
  Maximum resident set size: 128,688,128 bytes
  Page faults: 0 (I/O required) 37881 (no I/O required)
  Filesystem activity: 0 reads 16 writes

Event loop thread resource usage:
  User mode CPU: 0.676000 secs
  Kernel mode CPU: 0.244000 secs
  Filesystem activity: 0 reads 16 writes

================================================================================
==== Node.js libuv Handle Summary ==============================================

(Flags: R=Ref, A=Active, I=Internal)

Flags Type     Address
[--I] signal   0x1cd2408
[-AI] async    0x1cd2250
[-A-] async    0x1cd04a0
[---] check    0x251f050
[R--] idle     0x251f0c8
[---] prepare  0x251f140
[---] check    0x251f1b8
[-A-] async    0x7f27f5270de0
[-A-] signal   0x7f27f50642e0
[R--] timer    0x251f250
[R--] pipe     0x25463b0
[RA-] tcp      0x2593280
[R--] pipe     0x2593890
[RA-] tcp      0x2593a40
[-A-] timer    0x2552098

================================================================================
==== System Information ========================================================

Environment variables
. . . . . (lines omitted)
  npm_package_scripts_start=node --max-old-space-size=64 app.js
  npm_config_global_style=
  npm_config_ignore_scripts=
  npm_config_searchsort=name
  npm_config_version=
  CF_INSTANCE_PORT=62920
  npm_config_local_address=
  npm_config_viewer=man
  PATH=/home/vcap/app/vendor/node/lib/node_modules/npm/bin/node-gyp-bin:/home/vcap/app/node_modules/.bin:/home/vcap/app/vendor/node/bin:/home/vcap/app/vendor/node/bin:/bin:/usr/bin:/home/vcap/app/bin:/home/vcap/app/node_modules/.bin
  npm_package_name=NodejsDiagnosticsDemo
  NODE=/home/vcap/app/vendor/node/bin/node
. . . . . (lines omitted)

Resource limits                        soft limit      hard limit
  core file size (blocks)               unlimited       unlimited
  data seg size (kbytes)                unlimited       unlimited
  file size (blocks)                    unlimited       unlimited
  max locked memory (bytes)                 65536           65536
  max memory size (kbytes)              unlimited       unlimited
  open files                                16384           16384
  stack size (bytes)                      8388608         8388608
  cpu time (seconds)                    unlimited       unlimited
  max user processes                          512             512
  virtual memory (kbytes)               unlimited       unlimited

================================================================================

3 comments on"node-report – first failure data capture for Node.js"

  1. […] Chamberlain (IBM) provided a blog “NodeReport – first failure data capture for Node.js” describing how to implement first failure data capture (FFDC) using the NodeReport npm module.  […]

  2. […] summary diagnostic report for Node.js was introduced in NodeReport – first failure data capture for Node.js. The report can be triggered on unhandled exceptions, fatal errors, signals and by calling […]

  3. […] latest releases of 4.x and 6.x. These contain various updated, and 6.10.0.0 now also ships with the node-report module to assist with First Failure Data Capture to assist with problem […]

Join The Discussion

Your email address will not be published. Required fields are marked *