util: change inspect depth #22846

BridgeAR · 2018-09-13T17:59:55Z

The current default is not ideal in most use cases. Therefore it is
changed to inspect objects to a maximum depth of 20 in case
util.inspect is called with it's defaults. The default is kept at 2
when using console.log() and similar in the repl.

See the commit message for further details.

This should not be an issue for e.g., npm, since the maximum output
size is limited to 128 MB of data.

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

nodejs-github-bot · 2018-09-13T17:59:58Z

@BridgeAR build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/883/pipeline

jdalton · 2018-09-13T19:31:25Z

\cc @iarna since this has impacted npm in the past.

vsemozhetbyt · 2018-09-13T19:44:55Z

doc/api/util.md

@@ -360,6 +364,9 @@ stream.write('With ES6');
 <!-- YAML
 added: v0.3.0
 changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/REPLACEME
+    description: The `depth` default changed to 20.


20 -> `20`?

vsemozhetbyt · 2018-09-13T19:45:27Z

Is this semver-major?

AyushG3112 · 2018-09-14T03:29:31Z

@BridgeAR @vsemozhetbyt https://nodejs.org/api/util.html#util_util_inspect_object_options says

The output of util.inspect may change at any time and should not be depended upon programmatically.

As such, I don't think this needs to be semver-major

BridgeAR · 2018-09-15T09:15:34Z

@AyushG3112 in most cases I'd agree but changing a default option does seem to be a semver-major change for me.

iarna · 2018-09-15T16:40:33Z

Change is always disruptive, what I'm not seeing here (and forgive if I'm just missing it) is any discussion of what the benefit of this change is?

And how does it balance with the potential disruption? Has anyone involved with this change done any investigation into potential impact?

addaleax

CI: https://ci.nodejs.org/job/node-test-pull-request/17212/
CITGM: https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/1546/

@iarna From previous conversation with @BridgeAR, I think the benefit he’s seeing here is that the output is more verbose, and depth: 2 misses too much useful information.

Personally, I agree with that part of the assessment, but would prefer a depth of 4 or so that is much less dramatic and doesn’t lead to overwhelmingly large output.

addaleax · 2018-09-16T07:39:01Z

doc/api/util.md

@@ -183,6 +183,10 @@ property take precedence over `--trace-deprecation` and
 <!-- YAML
 added: v0.5.3
 changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/17907
+    description: The `%o` specifiers `depth` option will now fall back to the


Is this a typo (specifier’s)?

I guess so. @vsemozhetbyt @Trott can you verify this? :-)

I am not a native speaker, but it seems for me that `%o` specifier's `depth` option or `%o` specifier `depth` option would be OK?

Yes, there should be an apostrophe: specifier's

BridgeAR · 2018-09-17T09:39:42Z

@iarna I spoke to multiple people before originally wanting to change this default. The depth was often a thing I heard complains about and it was pretty much the reason that the defaultOptions were introduced (so people were able to change the depth to a different limit in their whole application). Right now the very low limit prevents proper inspection of objects and in pretty much all cases, the depth should be set to a higher limit. Instead, it would be great if the default would be more user friendly. Just recently @mafintosh asked me about this change again because he missed it and knew I planned on changing it.

@addaleax setting the limit to 4 would still be quite conservative. My problem with that limit is, that there is not ideal restricted limit. We might always miss some information, depending on the object's structure and it might not always be clear how the objects that are later inspected will look like. I choose 20 as limit because objects still seem well readable with that limit while almost always containing all information. It is definitely fair to expect users to manually increase the limit if they want inspection of deeper levels as well. I also believe it is fair to let users decrease the limit if they explicitly want to minify the output as that is probably not the common case.

BridgeAR · 2018-09-18T12:01:17Z

CI https://ci.nodejs.org/job/node-test-pull-request/17282/

BridgeAR · 2018-09-18T13:37:30Z

@nodejs/util PTAL

mafintosh · 2018-09-18T13:40:17Z

I personally like this change a lot, 👍

BridgeAR · 2018-09-18T13:42:15Z

@nodejs/tsc PTAL

jdalton · 2018-09-18T13:52:39Z

I think this probably isn't the last time depth will be discussed/changed, and I wouldn't be heartbroken if it needed to be reverted, but I'm cautiously optimistic.

side note: 😲

mcollina

LGTM

jdalton · 2018-09-19T02:38:30Z

Heads up the error helpers use inspect without specifying a depth and truncate to 128 chars. It looks like a depth of 20 would likely always bust that so likely need a specified one (maybe 2?)

node/lib/internal/errors.js

Lines 654 to 660 in a7b59d6

    
           E('ERR_INVALID_ARG_VALUE', (name, value, reason = 'is invalid') => { 
        
             let inspected = util.inspect(value); 
        
             if (inspected.length > 128) { 
        
               inspected = `${inspected.slice(0, 128)}...`; 
        
             } 
        
             return `The argument '${name}' ${reason}. Received ${inspected}`; 
        
           }, TypeError, RangeError);

BridgeAR · 2018-09-19T11:07:38Z

@jdalton it would indeed change this but to me it seems to the better, not to the worse. I would prefer to keep it this way or go ahead and explicitly add option to inspect it further.

BridgeAR · 2018-09-19T11:28:13Z

Rebased due to conflicts.

CI https://ci.nodejs.org/job/node-test-pull-request/17318/

addaleax · 2018-09-27T11:59:23Z

plain http req with depth 4: 768 lines

It might really just be me, but even that seems excessive for inspecting an object to get an overview over it? That’s still 4 full-screen terminal pages on my machine.

Maybe the point is that util.inspect has different use cases, and this effectively disables one of them: Getting an overview of an object rather than a full description of it. Of course sometimes full output is desirable, but I feel like we’re making another type of debugging a lot harder here.

BridgeAR · 2018-09-27T12:10:02Z

@addaleax

even that seems excessive for inspecting an object to get an overview over it?

The reason for the size of these objects is mainly redundant information that I am about to limit with a couple of PRs that I opened yesterday. Especially, super_ is bad since all code that uses that produces a significantly bigger output. The same for any code using domain but that is something we should probably not hide (or should we?).

We also have lots of symbols on our objects that are only meant for Node core and those are visible to all users. Hiding those is also going to reduce the output to a more regular size.

I also want to keep the "overview" functionality in the REPL, that's why I explicitly kept that at a depth of 2 (see above for the different output in the REPL depending on using console or not).

In an server application I personally want to have the full data logged, no matter how big it is. Otherwise I might loose information that is important to me.

So my suggestion is: we clean up all Node core internal properties to be only visible when using showHidden === true and to limit linked list output and stuff like that.
When thinking about random company code, I do not know data structures that are not meant to be logged fully, no matter how small or big they are (if they are logged).

silverwind

Changed my mind, I think this is a better approach than #23062. The http example shows that logged lines do not grow in size considerable with increasing depth, so I guess we should be save, even with a depth of 20.

silverwind · 2018-09-27T18:23:03Z

we clean up all Node core internal properties to be only visible when using showHidden === true

Agree, but please retain plain underscore-prefixed properties, if possible. While discouraged, I often find them useful to look at while debugging.

addaleax · 2018-09-28T00:16:01Z

In an server application I personally want to have the full data logged, no matter how big it is. Otherwise I might loose information that is important to me.

Right, but not all Node.js applications are server applications…

I still think this PR is not a good idea, but I don’t want to be the only one blocking this. If everybody else is okay with it, we can try to go for it in Node 11 and see how things turn out.

not blocking

BridgeAR · 2018-09-28T07:40:10Z

@addaleax I would rather have consensus before landing. What could be changed / done so you would not think it's the wrong thing to do?

BridgeAR · 2018-09-28T07:41:41Z

Resumbed build https://ci.nodejs.org/job/node-test-commit/21855/ ✔️

BridgeAR · 2018-09-28T07:47:09Z

@silverwind

please retain plain underscore-prefixed properties

Those are a different thing when compared to the symbol properties in general. So at least I personally would not touch them in most cases.

BridgeAR · 2018-10-01T09:48:15Z

Ping @addaleax is there anything that I could change so you feel more comfortable with this PR?

addaleax · 2018-10-02T18:52:55Z

@BridgeAR I don’t think so … I still think it’s not a good idea, and I guess we’ll just have to see how this plays out in the real world.

The current default is not ideal in most use cases. Therefore it is changed to inspect objects to a maximum depth of 20 in case util.inspect is called with it's defaults. The default is kept at 2 when using console.log() and similar in the repl. PR-URL: nodejs#17907 Refs: nodejs#12693 PR-URL: nodejs#22846 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Denys Otrishko <[email protected]> Reviewed-By: Roman Reiss <[email protected]>

Since the default for depth is changed to `20` it is logical to change the %o default as well. It will now always use the default depth. PR-URL: nodejs#17907 Refs: nodejs#12693 PR-URL: nodejs#22846 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Denys Otrishko <[email protected]> Reviewed-By: Roman Reiss <[email protected]>

BridgeAR · 2018-10-02T20:50:24Z

Landed in ac7450a, 1a1fe53

@addaleax I strongly hope we'll all be happy about it in the end!

Thanks everyone for the reviews.

refack · 2018-10-03T01:14:39Z

Probably due to some PR/PR interaction this fails on master:
https://travis-ci.com/nodejs/node/builds

Revert PR #23231
(If anyone can make a fix PR instead, that would be great)

devsnek · 2018-10-05T02:45:51Z

@BridgeAR I think this needs to be reverted. It makes the default behaviour pretty much unusable. Logging an object that used to be instant now takes ~66 seconds, and creates 1,793,699 lines of output.

addaleax · 2018-10-05T05:57:54Z

@devsnek Could you share the use case that led to that? One thing @BridgeAR has been asking for – that I could not deliver – was real-world cases of breakage that would be caused by this PR.

BridgeAR · 2018-10-05T07:43:34Z

I am trying to come up with different kinds of objects that might cause such an extreme behavior but I can't.

It would be great to know the shape of the object, the reason why it is so enormous (most data structures are significantly smaller) and what system you used. inspect() became pretty fast and even significantly bigger objects than the one mentioned by you are logged significantly faster on my notebook.

My guess is that logging the object almost hits the maximum heap size and the stop logging heuristic is not triggered. But even that is difficult to tell without further information.

devsnek · 2018-10-05T13:27:48Z

@BridgeAR logging an instance of this https://github.com/devsnek/engine262/blob/1b1631d9f0e8f24fd3b7af16a823acace1c25ca7/src/value.mjs#L218

i'm on macos, and here's the output http://s.gc.gy/2018-10-05-12314.out

BridgeAR · 2018-10-08T16:15:51Z

I had another look into this and the main issue is the actual output size, not the inspection time. Inspection itself is pretty fast but logging more than 128 MB is slow. Piping improves the performance but it's still slow.

So I suggest the following for Node.js 11: I open a PR to change the default depth to 5 instead of 20 and afterwards I work on a PR to change the inspection algorithm from inspecting the most inner depth first to fully inspecting the most outer depth first before moving on to the next level. After each level the current object size is measured and if it exceeds a specific limit, the inner levels will not be fully inspected anymore.

I also open another PR to add a new option to console so we are able to pass through default inspection options.

@addaleax @devsnek @silverwind what do you think?

devsnek · 2018-10-08T16:20:49Z

whatever keeps it fast and reasonable is fine with me. even if the above output happened instantly I obviously wouldn't want it in my console.

addaleax · 2018-10-08T17:11:29Z

@BridgeAR Yes, I think that sounds okay to me.

silverwind · 2018-10-08T19:03:13Z

~66 seconds

I'd wager most of that is terminal rendering time, but good to know that such big objects are not as uncommon as we thought.

After each level the current object size is measured and if it exceeds a specific limit, the inner levels will not be fully inspected anymore.

That sounds pretty complicated and not easy to understand/document. I'd say keep it at a simple number, 4 or 5, I don't really care.

thefourtheye · 2018-10-09T07:05:39Z

@BridgeAR I haven't thought about the traversing algorithm much, but looks like the proposal is to traverse the object breadth wise instead of depth wise, to find the size at the each level. Can we find circular references if we did breadth wise traversal?

BridgeAR · 2018-10-09T07:40:00Z

Circular reference detection will stay the same. It is not completely trivial to do a breath wise inspection because we have to delay object inspection and have to iterate over all properties once more. So the only concern for me is performance and implementation complexity.

BridgeAR requested a review from addaleax September 13, 2018 17:59

nodejs-github-bot added repl Issues and PRs related to the REPL subsystem. util Issues and PRs related to the built-in util module. labels Sep 13, 2018

vsemozhetbyt reviewed Sep 13, 2018

View reviewed changes

BridgeAR added the semver-major PRs that contain breaking changes and should be released in the next major version. label Sep 13, 2018

addaleax reviewed Sep 16, 2018

View reviewed changes

BridgeAR force-pushed the change-inspect-depth branch from 1b3e54d to 6379db9 Compare September 18, 2018 12:00

mafintosh approved these changes Sep 18, 2018

View reviewed changes

BridgeAR added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Sep 18, 2018

addaleax added the tsc-review label Sep 18, 2018

mcollina approved these changes Sep 18, 2018

View reviewed changes

joyeecheung mentioned this pull request Sep 18, 2018

CI failures: 20180918 nodejs/reliability#16

Closed

BridgeAR force-pushed the change-inspect-depth branch from 6379db9 to 702cf21 Compare September 19, 2018 11:26

BridgeAR requested review from targos and apapirovski September 19, 2018 11:29

silverwind approved these changes Sep 27, 2018

View reviewed changes

addaleax added the notable-change PRs with changes that should be highlighted in changelogs. label Oct 2, 2018

BridgeAR closed this Oct 2, 2018

BridgeAR mentioned this pull request Oct 9, 2018

util: reduce inspection depth default to five #23350

Closed

4 tasks

silverwind mentioned this pull request Jun 17, 2019

util: change inspect's default depth to 4 #28269

Closed

3 tasks

BridgeAR deleted the change-inspect-depth branch January 20, 2020 11:41

util: change inspect depth #22846

util: change inspect depth #22846

Conversation

BridgeAR commented Sep 13, 2018

Checklist

nodejs-github-bot commented Sep 13, 2018

jdalton commented Sep 13, 2018

vsemozhetbyt Sep 13, 2018

Choose a reason for hiding this comment

vsemozhetbyt commented Sep 13, 2018

AyushG3112 commented Sep 14, 2018

BridgeAR commented Sep 15, 2018

iarna commented Sep 15, 2018

addaleax left a comment

Choose a reason for hiding this comment

addaleax Sep 16, 2018

Choose a reason for hiding this comment

BridgeAR Sep 17, 2018

Choose a reason for hiding this comment

vsemozhetbyt Sep 17, 2018

Choose a reason for hiding this comment

Trott Sep 18, 2018

Choose a reason for hiding this comment

BridgeAR commented Sep 17, 2018

BridgeAR commented Sep 18, 2018

BridgeAR commented Sep 18, 2018

mafintosh commented Sep 18, 2018

BridgeAR commented Sep 18, 2018

jdalton commented Sep 18, 2018

mcollina left a comment

Choose a reason for hiding this comment

jdalton commented Sep 19, 2018

BridgeAR commented Sep 19, 2018

BridgeAR commented Sep 19, 2018

addaleax commented Sep 27, 2018

BridgeAR commented Sep 27, 2018

silverwind left a comment

Choose a reason for hiding this comment

silverwind commented Sep 27, 2018

addaleax commented Sep 28, 2018

BridgeAR commented Sep 28, 2018

BridgeAR commented Sep 28, 2018 • edited Loading

BridgeAR commented Sep 28, 2018

BridgeAR commented Oct 1, 2018

addaleax commented Oct 2, 2018

BridgeAR commented Oct 2, 2018

refack commented Oct 3, 2018

devsnek commented Oct 5, 2018

addaleax commented Oct 5, 2018

BridgeAR commented Oct 5, 2018

devsnek commented Oct 5, 2018 • edited Loading

BridgeAR commented Oct 8, 2018

devsnek commented Oct 8, 2018

addaleax commented Oct 8, 2018

silverwind commented Oct 8, 2018 • edited Loading

thefourtheye commented Oct 9, 2018

BridgeAR commented Oct 9, 2018 • edited Loading

BridgeAR commented Sep 28, 2018 •

edited

Loading

devsnek commented Oct 5, 2018 •

edited

Loading

silverwind commented Oct 8, 2018 •

edited

Loading

BridgeAR commented Oct 9, 2018 •

edited

Loading