util.format(object) causes node debugger to terminate

[mattoshry]

$ node -v
v4.2.6

$ node debug format.js 
< Debugger listening on port 5858
debug> . ok
break in format.js:1
> 1 var util = require('util');
  2 var output = util.format({ p1: 'v1' });
  3 console.log(output);
debug> n
break in format.js:2
  1 var util = require('util');
> 2 var output = util.format({ p1: 'v1' });
  3 console.log(output);
  4 
debug> n
program terminated

This is not reproducible in node@4.2.4. I can repro this in 4.2.5 and 4.2.6.
Ran into this because util.format is how log4js formats log data.

[1] https://github.com/nomiddlename/log4js-node/blob/0fc65d38eb0210bbb2d5bf12b40d3588f7c318e2/lib/layouts.js#L40

[MylesBorins]

I can confirm I noticed this problem on my machine as well. Appears to have been introduced by 2d5380e

[MylesBorins]

I can also confirm that the debugger acts as expected on node v4.2.1 but appears to be acting really odd on v5.5.0 and master as well.

If you attempt to go to the next line after console.log everything stops working in a really lovely way.

[MylesBorins]

I can confirm that reverting 2d5380e does indeed fix the problem on v4. The test suite also passes with this change.

I attempted to run the unit test suite of log4js using citgm on the affected versions and we get all green. This is an odd one

[MylesBorins]

I have narrowed it down to this specific line

2d5380e#diff-3deb3f32958bb937ae05c6f3e4abbdf5R322

Seems like inspectPromise is giving a false positive

[targos]

Seems like inspectPromise is giving a false positive

Do you know for what object ?

[MylesBorins]

I'm still digging in here, I was using the provided example

var util = require('util');
var output = util.format({ p1: 'v1' });
console.log(output);

so it would be on { p1: 'v1'}

[MylesBorins]

Ok... I've dug deeper into this one.

so far I've gotten far enough to rule out util.js as actually causing the problem. The change to how we were checking promising (simply calling inspectPromise) is ensuring that calls to util.format are now calling the inspectPromise function which in turn is calling ensureDebugIsInitialized which in turn is calling runInDebugContext which is a part of vm...

and the digging continues 😄

edit: going a layer deeper... seems runInDebugContext is bound to node_contextify.cc

[MylesBorins]

So things get kind of odd. I have set up some logging before the call to binding.runInDebugContext in js land, and a printf at the begining of RunInDebugContext in c++ land.

when you just run the above example node test.js you get the expected ouput

OH HAI I'M IN JS
OH HAI I'M IN C++
{ p1: 'v1' }

When you run it in debug you get

break in test.js:2
  1 var util = require('util');
> 2 var output = util.format({ p1: 'v1' });
  3 console.log(output);
  4
debug> n
< OH HAI I'M IN JS
program terminated

This is leaving me to believe that the program is exiting before it even calls into the binding.

[MylesBorins]

So I have a hunch right now that the issue is that we are creating two different Debug Contexts. The call to ensureDebugIsInitialized is checking to see if the object Debug exists, which is doesn't when util is first run. If util is being run inside a debugger, there is already a debugger context, and we are trying to incept.

[MylesBorins]

So I think I've gotten to the bottom of things

--> https://github.com/nodejs/node/blob/master/src/debug-agent.cc#L122-L128

The debug-agent sets the parent_env to be v8::Debug::GetDebugContext()

Later when RunInDebugContext is called things blow up on line 273

https://github.com/nodejs/node/blob/master/src/node_contextify.cc#L273

I'm not 100% but I think this may have been introduced by #1229

edit: dug a bit deeper... it seems the problem lies specifically at https://github.com/nodejs/node/blob/master/src/node_contextify.cc#L256

I'm still not familiar enough with c++ to get the subtly of what is going on entirely, but my guess is that this line is tearing down a part of the context that shouldn't be touched if we want to remain in a debug context

/cc @bnoordhuis