Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

util.format(object) causes node debugger to terminate #4815

Closed
mattoshry opened this issue Jan 22, 2016 · 14 comments
Closed

util.format(object) causes node debugger to terminate #4815

mattoshry opened this issue Jan 22, 2016 · 14 comments
Labels
util Issues and PRs related to the built-in util module.

Comments

@mattoshry
Copy link

$ 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 [email protected]. 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
Copy link
Contributor

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

@MylesBorins
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

I have narrowed it down to this specific line

2d5380e#diff-3deb3f32958bb937ae05c6f3e4abbdf5R322

Seems like inspectPromise is giving a false positive

@targos
Copy link
Member

targos commented Jan 22, 2016

Seems like inspectPromise is giving a false positive

Do you know for what object ?

@MylesBorins
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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.

@mscdex mscdex added util Issues and PRs related to the built-in util module. debugger labels Jan 22, 2016
@MylesBorins
Copy link
Contributor

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

@MylesBorins
Copy link
Contributor

The fix is now in master, you should expect this to see it in a release in the next 2 - 3 weeks on v4 and v5.

@mattoshry
Copy link
Author

Thanks, Myles.

rvagg pushed a commit that referenced this issue Feb 8, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in #4815

Fixes: #4440
Fixes: #4815
Fixes: #4597
Fixes: #4952

PR-URL: #4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
rvagg pushed a commit that referenced this issue Feb 9, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in #4815

Fixes: #4440
Fixes: #4815
Fixes: #4597
Fixes: #4952

PR-URL: #4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
@MylesBorins
Copy link
Contributor

The fix is now released in v5.6.0. Expect LTS next week

MylesBorins pushed a commit that referenced this issue Feb 11, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in #4815

Fixes: #4440
Fixes: #4815
Fixes: #4597
Fixes: #4952

PR-URL: #4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
MylesBorins pushed a commit to MylesBorins/node that referenced this issue Feb 11, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in nodejs#4815

Fixes: nodejs#4440
Fixes: nodejs#4815
Fixes: nodejs#4597
Fixes: nodejs#4952

PR-URL: nodejs#4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
MylesBorins pushed a commit to MylesBorins/node that referenced this issue Feb 13, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in nodejs#4815

Fixes: nodejs#4440
Fixes: nodejs#4815
Fixes: nodejs#4597
Fixes: nodejs#4952

PR-URL: nodejs#4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
MylesBorins pushed a commit to MylesBorins/node that referenced this issue Feb 13, 2016
Notable changes:

* buffer: make byteLength work with Buffer correctly (Jackson Tian)
  - nodejs#4738
* debugger: guard against call from non-node context (Ben Noordhuis)
  - nodejs#4328
* node_contextify: do not incept debug context (Myles Borins)
  - nodejs#4815
MylesBorins pushed a commit to MylesBorins/node that referenced this issue Feb 15, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in nodejs#4815

Fixes: nodejs#4440
Fixes: nodejs#4815
Fixes: nodejs#4597
Fixes: nodejs#4952

PR-URL: nodejs#4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
@MylesBorins
Copy link
Contributor

The fix is now in lts on v4.3.1 !

scovetta pushed a commit to scovetta/node that referenced this issue Apr 2, 2016
Currently a debug context is created for various calls to util.

If the node debugger is being run the main context is the debug
context. In this case node_contextify was freeing the debug context
and causing everything to explode.

This change moves around the logic and no longer frees the context.

There is a concern about the dangling pointer

The regression test was adapted from code submitted by @3y3 in nodejs#4815

Fixes: nodejs#4440
Fixes: nodejs#4815
Fixes: nodejs#4597
Fixes: nodejs#4952

PR-URL: nodejs#4815

Reviewed-By: Fedor Indutny <[email protected]>
Reviewed-By: Ben Noordhuis <[email protected]>
Reviewed-By: Rich Trott <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
util Issues and PRs related to the built-in util module.
Projects
None yet
Development

No branches or pull requests

4 participants