Issue 50316: Console.log gives incorrect output in Chrome Developer Tools console

Two problems here:
1) we check whether objects are equal when increasing counter
2) we evaluate array content asynchronously when it has its latest value

Simply fixing (1) does not resolve the issue due to the (2).

 Issue 78325  has been merged into this issue.

I am having a simular problem when i am mutating an object and doing console.log()'s along the way.

the result for the object only reports the most recent version.

this is occurring in chrome 12

Blog entry with more tests and comparison to Firebug: http://techblog.appnexus.com/2011/webkit-chrome-safari-console-log-bug/

 Issue 94887  has been merged into this issue.

 Issue 62652  has been merged into this issue.

 Issue 105559  has been merged into this issue.

related upstream bug: https://bugs.webkit.org/show_bug.cgi?id=35801

 Issue 107828  has been merged into this issue.

 Issue 111020  has been merged into this issue.

 Issue 131124  has been merged into this issue.

I think you should leave the console.log as it is and add a console.deepLog.

Or maybe call it console.logClone.
Or another way to do it would be to get a console.logDepth( maxDepth, [ther other things] );
And it would automatically expand the tree representing the object directly up to the given depth.

@16, @17, why would you do that? Do not complicate a simple and pretty API!

I agree. Don't complicate the console API. Just make it "log". Plain static log.

I agree replace plain log function

I would do that because you'll want to log things at difference depth.

Currently it logs at depth 0: just the object.
Most use cases will need to log at depth 1: the properties of the object.
But then, imagine someone working with a matrix object containing a 2D array. He would already need depth 3: 1 for the property holding the array, 2 for 1D and 3 for 2D. You could argue that he could do he own toString method. But... so can people needing depth 1?

And then, you could consider using an "infinite" depths.
And the problem with that is that *even if you use a hashtable (to know where to point to) or a set to keep track of what has already been seen, it'll fail*.

function _deepLog( o, a ) {
    if ( a.indexOf( o ) != -1 ) {
        return;
    }
    a.push( o );
    console.log( o );
    if ( o == null ) {
        return;
    }
    if ( typeof o == "object" ) {
        Object.getOwnPropertyNames( o ).forEach( function ( i ) {
            _deepLog( o[ i ], a );
        } );
    }
    _deepLog( o.__proto__, a );
}
function deepLog( o ) {
    _deepLog( o, [ ] );
}
deepLog( window );

You can check it, you'll get an infinite recursion between a MimeType object and another object. Of course, that could be fixed. But then, every single time the browser or a plugin gets an error like that, the console.log will stop working for every single object that gets to window at some point.

Plus with Proxies and getters, it's obvious that you'll get such infinite recursion at some point.

Then you could say we could keep console.log and specify the depth in it... but how would you do that? If the first parameter is a number, use it as depth? That would "break" some scripts.

That's why I think another function is needed.

Firebug gets this right, so apparently it is possible.
Perhaphs it has other downsides?

From what I remember, Firebug logs depth 1 if and only if the object has
less than a given number of properties and level 0 otherwise.
But I haven't used it for a while.

Sent from my smartphone.

Sounds like a legit approach.

Well again, if you log a matrix, you're ******...

Whatever it does should be predictable.  The fact that xavier couldn't tell us off the top of his head what the "given number" is would in itself prove that this is broken.

The real problem:
Grabbing the values at display time instead of at log time is deceiving and leads to troubleshooting errors.  "What's wrong?  The value's right there, why didn't this function use it?"  It didn't use it because the value showed up some time between when the function was run and when you looked at it, but this isn't at all obvious.

The best solution:
Add a native function (preferably to the ECMA spec) that deep copies JS objects.  console.log() could then use this along with the rest of us.  Yes it'd be slow.  It's okay for logging to be slow.

A workable solution:
Write a deep-copy function just for console.log().  I have written one in JS and it works, but should be much faster if written in native code, with access to the raw pointers.

@wartthog: Do you mind sharing the deep copy function over here, so that those who face this bug at least have some respite?

Agree on deep copy. Console.log isn't something used for performance, it's for debugging. I manually clone Objects to get the damned thing to work as it is.

@dev.akhawe: I'd love to but our code is really messy at the moment because we're still in the inflationary stage of development if you know what I mean, and I haven't had time to clean it up yet.

Here are a couple of tips for you though to find/write your own solution:
1) Read up on other people's solutions by just Googling "javascript deep copy", especially this: http://oranlooney.com/deep-copy-javascript/
2) Write a recursive function which deep copies the current array/object.
3) Copying primitives is easy.  The only complication is when you're copying an object/array/function.
4) Deep-copying a function is tricky because you want to point to the original implementation but make copies of any additional members that have been added later.  I ignored this case since logging doesn't show a function's members.
5) When you're ready to copy a child object (arrays are similar), do something like this:
  if (src.__SOME_UNIQUE_NAME__ !== undefined) {
    dst = src.__SOME_UNIQUE_NAME__;
  } else {
    dst = {};
    src.__SOME_UNIQUE_NAME__ = dst; // Important to do this after checking above,
                                    // but before recursing.
    deepCopy(src, dst);
  }
  This should handle cycles effectively and efficiently.
6) deepCopy should have a "depth" parameter.  Using it you can see when you're returning from the root instance of deepCopy and can strip out all the __SOME_UNIQUE_NAME__ members from the source tree.
7) This method doesn't handle multi-member cycles which are common in DOM nodes (parent->childNodes->parent->childNodes) so you'll have to use https://developer.mozilla.org/en-US/docs/DOM/Node.cloneNode or something.
8) Doesn't handle properties (getters/setters)

Good luck!

Ok, so I am going to close this as Fixed (http://trac.webkit.org/changeset/125174). The above test case on the ToT Chromium gives me the expected behavior (see screenshot1). Should be live on Canary in a day or two.

What it does is that it generates the instant object preview (5 object properties or 100 array elements) at the moment of logging. This preview is rendered using the italic font. Preview is only generated if the DevTools window is opened.

Now if I add an object (window in my case) to that array, we detect that there are complex objects inside the array. We still create the preview string in italic, but we also allow expanding the log entry (in the form of console.dir). But when expanding the live object, it'll give its properties taken at the time of expansion, not at the log time. See screenshot2 for that.

In other words, the only snapshot value is the preview in italic, rest are the live objects. This matches the Firebug behavior pretty much + I don't think we can do much better here. This change only affects the operation of console.log, interactive work with console will stay the same, it'll produce nice smart arrays with in-place expansion (screenshot3).

One more important note: if the logging is happening with DevTools closed, we don't generate the preview. So one will see the 3 [-1, -1, -1]. I intend to fix it right away via making it output
> Array(3)
> Array(3)
> Array(3)
in order to emphasize the fact that these values are not snapshotted.

Deleted: Screen shot 2012-08-10 at 11.10.14 AM.png 12.7 KB

	Screen shot 2012-08-10 at 11.10.14 AM.png 12.7 KB View Download

Deleted: Screen shot 2012-08-10 at 11.20.02 AM.png 8.8 KB

	Screen shot 2012-08-10 at 11.20.02 AM.png 8.8 KB View Download

Deleted: Screen shot 2012-08-10 at 11.10.42 AM.png 19.3 KB

	Screen shot 2012-08-10 at 11.10.42 AM.png 19.3 KB View Download

 Issue 152115  has been merged into this issue.

Came across this thread after running into this issue and spending hours trying to figure out what was going on. I tried the latest Canary 24.0.1283.0 on Mac 10.8.2 and I still see this issue for my scenario. 

I have a variable set to a tr table row that I create using jQuery, I console.log this variable right after the variable's value is set. I then invoke a function that manipulates this row (adds it to a table then changes the values of some of the td elements). The console.log shows the tr object with the new values instead of the values at log time. I do see the tr in italics but the contents have the new values. So it looks like this issue is not completely resolved?

@baseliners: could you please provide a reduction / code snippet?

Sure, see attached file. Click on the button and you'll see two tr's being logged, both with the same "new data".

Deleted: console_log.html 612 bytes

console_log.html 612 bytes View Download

Oh, ok, we might want to give a better hint on the fact that only italic represents the instant value. When you expand the object, its content is not italic, we are expanding the live object there. Snapshotting the entire heap is not feasible. In your case, we would need to snapshot 2 levels deep.

I could improve tag capture to include attributes and / or textContent, however, there was an explicit request to not have them.

Perhaps adding a tiny "info" icon next to the italic output of objects would be useful?
Hovering on the icon could show an explanation of why it's italic, why the expanded information is not italic, etc.

@pfeldman: what was the rationale behind the request to not include attributes/textContent? (can't seem to find it in this thread) I see a lot of upside to doing this especially since the latest values are easily viewable in the Elements tab if someone only wants to see the latest values... i.e. there is *a* way to get to the latest values but no way to get to the values at log time.

@baseliners people that dump DOM lists appreciate the dense look.