node js 5.2.0 segmentation fault after console.log

[jianpingw]

The segementation fault is easy to trigger. I use sailsJS and here are the lines to cause the crash:

foo: function (req, res) {
    console.log(req.body); // This line will trigger crash later on.
    // One ORM call.
    Bar.findOne(...) // ORM call, crashed
}

The "console.log" reliably causes the nodeJS crash later on. The same code works fine on 5.1.1.

Trace from segfault-handler.node(+0x1af4)[0x7f9a58a9aaf4]:

/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f9a5de94340]
/usr/local/bin/node(_ZN4node8debugger5Agent14MessageHandlerERKN2v85Debug7MessageE+0x41)[0xe06371]
/usr/local/bin/node(_ZN2v88internal5Debug20NotifyMessageHandlerENS_10DebugEventENS0_6HandleINS0_8JSObjectEEES5_b+0x9e3)[0xa540d3]
/usr/local/bin/node(_ZN2v88internal5Debug17ProcessDebugEventENS_10DebugEventENS0_6HandleINS0_8JSObjectEEEb+0x9b)[0xa5630b]
/usr/local/bin/node(_ZN2v88internal5Debug14OnAfterCompileENS0_6HandleINS0_6ScriptEEE+0x23e)[0xa5751e]
/usr/local/bin/node(_ZN2v88internal8Compiler19GetFunctionFromEvalENS0_6HandleINS0_6StringEEENS2_INS0_18SharedFunctionInfoEEENS2_INS0_7ContextEEENS0_12LanguageModeENS0_16ParseRestrictionEiiNS2_INS0_6ObjectEEENS_19ScriptOriginOptionsE+0x143)[0xa31ff3]
/usr/local/bin/node(_ZN2v88internal21Runtime_CompileStringEiPPNS0_6ObjectEPNS0_7IsolateE+0x143)[0xca1c43]
[0x27fae210839b]

[mscdex]

Do you get the same backtrace if you run under say gdb instead of using segfault-handler?

[jianpingw]

Here is the the backtrace when running under gdb:

(gdb) backtrace
#0  0x00007ffff6c01fb7 in kill () at ../sysdeps/unix/syscall-template.S:81
#1  0x0000000000fdf939 in uv_kill (pid=<optimized out>, signum=<optimized out>) at ../deps/uv/src/unix/process.c:540
#2  0x0000000000e1852d in node::Kill(v8::FunctionCallbackInfo<v8::Value> const&) ()
#3  0x0000000000913622 in v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&))
    ()
#4  0x000000000093d9d1 in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::(anonymous namespace)::BuiltinArguments<(v8::internal::BuiltinExtraArguments)1>&) ()
#5  0x000000000093dec2 in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) ()
#6  0x00000f4ff0e0839b in ?? ()
#7  0x0000123892ceb481 in ?? ()
#8  0x00000f4ff0e082e1 in ?? ()
#9  0x00007fffffffdb40 in ?? ()
#10 0x00007fffffffdbb0 in ?? ()
#11 0x00000f4ff0f65ee5 in ?? ()
#12 0x0000123892ceb481 in ?? ()
#13 0x0000000b00000000 in ?? ()
#14 0x0000425a00000000 in ?? ()
#15 0x00003b7fe3514401 in ?? ()
#16 0x0000123892ceb481 in ?? ()
#17 0x0000123892c04189 in ?? ()
#18 0x0000123892c04189 in ?? ()
#19 0x000039013e310dd1 in ?? ()
#20 0x00003b7fe35141e1 in ?? ()
#21 0x00007fffffffdbf0 in ?? ()
#22 0x00000f4ff0f65ae0 in ?? ()
#23 0x00000c13d20c9b01 in ?? ()
#24 0x0000425a00000000 in ?? ()
#25 0x00003b7fe3514401 in ?? ()
#26 0x000039013e310dd1 in ?? ()
#27 0x00000c13d20c9d71 in ?? ()
#28 0x00000c13d20c9d31 in ?? ()
#29 0x00007fffffffdc20 in ?? ()
#30 0x00000f4ff0e08297 in ?? ()
#31 0x00003b7fe3514401 in ?? ()
#32 0x0000000100000000 in ?? ()
#33 0x00000c13d20c9d71 in ?? ()
#34 0x0000000a00000000 in ?? ()
#35 0x00007fffffffdc70 in ?? ()
#36 0x00000f4ff0f657ef in ?? ()
#37 0x0000000000000000 in ?? ()

[fixed formatting - ofrobots]

[bnoordhuis]

The gdb backtrace suggests something calls process.kill(process.pid) in your application while the segfault-handler backtrace seems to be a new Function() or eval() call when the debugger is enabled. Hard to say what's going on, an isolated test case would help.

[paskakaska]

I faced very similar issue. NodeJS crashed then I passed object to console.log. The problem seemed to be require('vm').runInDebugContext('Debug') inside util.inspect inside util.format. So I tried debugging this script:

var Debug = require('vm').runInDebugContext('Debug')
console.log('a')

I noticed that every time I stepped over require('vm').runInDebugContext('Debug') or set or triggered a breakpoint after this line had executed NodeJS crashed. If I ran this script without debugger attached or didn't set any breakpoints everything ran as expected.

[jianpingw]

Steps to reproduce (make sure to use node 5.2.0 and npm 3.x):

git clone https://github.com/balderdashy/sails-examples
cd sails-examples
npm update

Open the file "api/controllers/ExampleController.js", add a line in jQuery function:

jQuery: function(req, res) {
    console.log(req.body); // add this line
    res.view();
},

Run the app:
node --debug app.js

The "--debug" flag is very important!

Open a browser, and go to "http://localhost:1339/". App crashes with segmentation fault.

[bnoordhuis]

Thanks, I've been able to reproduce the issue. As a stop-gap measure (which may also end up being the final fix), you can apply this patch:

diff --git a/src/debug-agent.cc b/src/debug-agent.cc
index 3409fb2..53be4f9 100644
--- a/src/debug-agent.cc
+++ b/src/debug-agent.cc
@@ -320,7 +320,11 @@ void Agent::EnqueueMessage(AgentMessage* message) {

 void Agent::MessageHandler(const v8::Debug::Message& message) {
   Isolate* isolate = message.GetIsolate();
+
   Environment* env = Environment::GetCurrent(isolate);
+  if (env == nullptr)
+    return;
+
   Agent* a = env->debugger_agent();
   CHECK_NE(a, nullptr);
   CHECK_EQ(isolate, a->parent_env()->isolate());

[jianpingw]

Yes, the patch fixes the segmentation fault. Thanks @bnoordhuis !

[andreabianco]

I'm not using SailsJS but I have the same problem.

I'm using ExpressJS and after each console.log() the server stops to working. I'm using node v5.2.0

[bnoordhuis]

#4328