New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 90 users

Issue metadata

Status: Fixed
Owner:
Closed: Aug 2012
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug



Sign in to add a comment
link

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

Reported by chengz...@gmail.com, Jul 27 2010

Issue description

Chrome Version       : 5.0.375.99 (Official Build 51029)
URLs (if applicable) :
Other browsers tested:
Add OK or FAIL after other browsers where you have tested this issue:
     Safari 4: n/a
  Firefox 3.x: (firebug) OK
         IE 7: n/a
         IE 8: n/a

What steps will reproduce the problem?

Execute:

var arr = [0, 1, 2];
for (var i=0; i<arr.length; i++) {
	arr[i] = -1;
	console.log(arr);
}

What is the expected result?
[-1, 1, 2]
[-1, -1, 2]
[-1, -1, -1]

What happens instead?
3 [-1, -1, -1]
 

Comment 1 by loislo@chromium.org, Jul 27 2010

Labels: -Area-Undefined Feature-DevTools

Comment 2 by loislo@chromium.org, Jul 27 2010

Status: Assigned

Comment 3 by pfeldman@chromium.org, Jul 27 2010

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).

Comment 4 by pfeldman@chromium.org, Jan 27 2011

Labels: Mstone-X
Status: Available

Comment 5 by pfeldman@chromium.org, Apr 6 2011

Cc: yu...@chromium.org
 Issue 78325  has been merged into this issue.

Comment 6 by justin.k...@gmail.com, Jun 17 2011

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

Comment 7 by trippleq...@gmail.com, Sep 3 2011

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

Comment 8 by pfeldman@chromium.org, Sep 12 2011

 Issue 94887  has been merged into this issue.

Comment 9 by paulir...@chromium.org, Oct 6 2011

 Issue 62652  has been merged into this issue.

Comment 10 by pfeldman@chromium.org, Dec 1 2011

Cc: jryans@chromium.org
 Issue 105559  has been merged into this issue.

Comment 11 by paulir...@chromium.org, Dec 16 2011

Comment 12 by pfeldman@chromium.org, Dec 18 2011

 Issue 107828  has been merged into this issue.

Comment 13 by pfeldman@chromium.org, Feb 6 2012

 Issue 111020  has been merged into this issue.

Comment 14 by pfeldman@chromium.org, Jun 9 2012

Cc: bmonajj...@gmail.com
 Issue 131124  has been merged into this issue.

Comment 15 by pfeldman@chromium.org, Aug 2 2012

Cc: -pfeldman@chromium.org
Labels: -Mstone-X Mstone-22
Owner: pfeldman@chromium.org
Status: Assigned

Comment 16 by xavierm0...@gmail.com, Aug 2 2012

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

Comment 17 by xavierm0...@gmail.com, Aug 2 2012

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.

Comment 18 by sokolov....@gmail.com, Aug 3 2012

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

Comment 19 by iacob.ca...@gmail.com, Aug 3 2012

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

Comment 20 by Deleted ...@, Aug 3 2012

I agree replace plain log function

Comment 21 by xavierm0...@gmail.com, Aug 4 2012

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.

Comment 22 by sokolov....@gmail.com, Aug 6 2012

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

Comment 23 by xavierm0...@gmail.com, Aug 6 2012

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.

Comment 24 by sokolov....@gmail.com, Aug 6 2012

Sounds like a legit approach.

Comment 25 by xavierm0...@gmail.com, Aug 6 2012

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

Comment 26 by wartt...@gmail.com, Aug 7 2012

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.

Comment 27 by dev.akh...@gmail.com, Aug 7 2012

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

Comment 28 by Deleted ...@, Aug 7 2012

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.

Comment 29 by wartt...@gmail.com, Aug 7 2012

@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!

Comment 30 by pfeldman@chromium.org, Aug 10 2012

Cc: vsevik@chromium.org
Status: Fixed
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.
Screen shot 2012-08-10 at 11.10.14 AM.png
12.7 KB View Download
Screen shot 2012-08-10 at 11.20.02 AM.png
8.8 KB View Download
Screen shot 2012-08-10 at 11.10.42 AM.png
19.3 KB View Download

Comment 31 by pfeldman@chromium.org, Sep 25 2012

 Issue 152115  has been merged into this issue.

Comment 32 by baselin...@gmail.com, Oct 2 2012

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?

Comment 33 by pfeldman@chromium.org, Oct 2 2012

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

Comment 34 by baselin...@gmail.com, Oct 2 2012

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

Comment 35 by pfeldman@chromium.org, Oct 2 2012

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.

Comment 36 by sokolov....@gmail.com, Oct 2 2012

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.

Comment 37 by baselin...@gmail.com, Oct 2 2012

@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.

Comment 38 by pfeldman@chromium.org, Oct 3 2012

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

Comment 39 by bugdroid1@chromium.org, Mar 10 2013

Project Member
Labels: -Feature-DevTools -Mstone-22 Cr-Platform-DevTools M-22

Comment 40 Deleted

Comment 41 Deleted

Sign in to add a comment