Chrome Dev Tools "Live Update" In The JavaScript Console Is Confusing
Yesterday, I was on a screen share with Ryan Jeffords and Alan Quinlan trying to help debug some JavaScript code. And, like so many developers, we made healthy use of "console.log()" as a means to debug when and where code was going wrong. Only, we were using Chrome as our development browser - not Firefox with Firebug. As such, we got burned by a seriously quirky "live update" feature of the Chrome dev tools.
I use Firefox with Firebug as my development environment. I know people rave about the Chrome Dev Tools and all its new hawtness; but, to me, Firebug feels like that old tee-shirt you've had around for years - it might not be the lastest and greatest style, but it feels wonderful. As such, I'm not too familiar with behavioral differences between the two development environments. And, as it turns out, there's one very significant and critical difference.
In Firebug, when you log something to the console (in my experience), it remains in the console as a fixed, static value. In Chrome Dev Tools, on the other hand, it seems that complex values, once logged to the output, continue to be "live updated" as the JavaScript runs. To see this in action, take a look the following code:
<!doctype html>
<html>
<head>
<meta charset="utf-8" />
<title>Chrome Dev Tools Live Console Updates</title>
<script type="text/javascript">
function getSomeData(){
var data = [
"April Ross",
"Jennifer Kessy",
"Misty May-Treanor",
"Kerri Walsh"
];
return( data )
}
function processSomeData( data ){
// Cut out Ross and Kessy - sorry girls!
data.splice( 0, 2 );
// Return processed data.
return( data );
}
// -------------------------------------------------- //
// -------------------------------------------------- //
var data = getSomeData();
// Log data out for debugging.
console.log( data );
// Process the data.
processSomeData( data );
// Log the data out again for debugging.
console.log( data );
</script>
</head>
<body>
<!-- Left intentionally blank. -->
</body>
</html>
As you can see, we're getting some data, then we're processing it. And, to make sure that the data is being processed correctly, I am logged the data both before and after the processing method.
In Firefox with Firebug, we get the following "expected" value in the console:
["April Ross", "Jennifer Kessy", "Misty May-Treanor", "Kerri Walsh"]
["Misty May-Treanor", "Kerri Walsh"]
The data is clearly different in both cases, demonstrating the effects of the processing method.
Now, this same code, when run in Chrome, gives us the following console output:
["Misty May-Treanor", "Kerri Walsh", undefined Ã- 2]
["Misty May-Treanor", "Kerri Walsh"]
Having little experience with Chrome Dev Tools, I saw the above output and immediately thought:
"Our first log() looks really weird! Something must be wrong with the way data is being assembled in the first place!"
Little did I know that the strange, "undefined x 2", notation meant that there used to be data there. It seems that after the initial log, Chrome Dev Tools actually went back and updated the output once the data array had been mutated.
Now, I am sure some of you are looking at this and thinking, "You should be using Breakpoints to debug your JavaScript code anyway." And, Breakpoints are definitely cool. But, that's fixing the wrong problem, in my opinion. As far as I'm concerned, the whole point of a "log" is that the data output to it is fixed. Otherwise, I think the log loses its value.
I, for one, am going to continue using Firebug, where the output feels more expected. But, I wanted to put this out there in case anyone else was unaware of this Chrome Dev Tools behavior.
Want to use code from this post? Check out the license.
Reader Comments
So it's acting like a "watch". Weird. Thanks for pointing out.
@Joel,
Yeah, I guess so - I wonder if can be turned off. I've been trying to Google it and I can't find anything.
As another check, I tried doing this in Firebug:
Here, we are logging a reference to a DOM node. Both logged elements point to the same DOM node. However, Firebug still logs them as different log items (data-foo="bar") is only present in the second log value.
Firebug for the win!
I use chrome debugging tools all the time, so I guess I'm used to it. When I first discovered this, I thought it was weird and tripped over it. But I think of it now as a dump of a pointer. You always get the current value. In fact, you can watch it change in real time. So now, when I need a dump of *this point in time* I use JSON.stringify( varToDump ).
@Rob,
Oh nice, I didn't even think of using the JSON api! We ended up using:
data.join( "," )
... to output it as a static string. But the JSON approach is way cooler (and more flexible). Thanks!
I never even noticed this before thanks for the heads up. I usually just logged specific properties of an object.
I'm seeing this reported at stackoverflow also.
http://stackoverflow.com/questions/7389069/console-log-object-at-current-state
console.log(JSON.parse(JSON.stringify(testObj)));
and
http://stackoverflow.com/questions/11118758/bug-in-console-log
One of the suggestions they have is similar to Robs except they are adding a JSON.parse also.
console.log(JSON.parse(JSON.stringify(testObj)));
This ends up with a nice looking object like I'm used to seeing in Chrome.
In Firebug you have one feature that is similar and that I don't like either.
Say you log an object. Then in Firebug's console you can click on the object to inspect it.
If the object changed before you click on it, then you get the updated version. Too bad :)
That's easy to test in the console :
var a = { test: "test" };
console.log(a);
a.test2 = "test2";
And then click on what got logged before => you see the test2 key.
The problem is Chrome's console is asynchronous.
Instead of waiting for the array to be written to the console, the script goes on to the next line ( calling processSomeData() ). By the time the array is actually output in the console its contents have changed.
The reason things like JSON.stringify() work as that you're creating a new object -- a string -- and passing that to the console instead of the array.
Oh, nevermind. It's not asynchronous. This answer explains what's going on.
http://stackoverflow.com/a/8249333/437
Looks like they landed a fix for this today. If you do console.log with the dev tools open you should no longer see this behavior after today. Bug: https://bugs.webkit.org/show_bug.cgi?id=35801 Change: http://trac.webkit.org/changeset/125174
Firebug is great, but its got its own share of quirks that you have to get used to.
Yeah this bug is a killer. It's the top of our list with stars.. and.. good news in fact!
Today the engineering team landed a patch to help resolve this issue AND give us more attractive console logging at the same time!
http://trac.webkit.org/changeset/125174
So now we'll get a preview of the object at the time of logging and we'll likely be avoiding this pesky one going forward.
:D
Try out the Canary tomorrow!
Details of the new behavior is here: http://code.google.com/p/chromium/issues/detail?id=50316#c30
@Paul, @Aaron,
Ah, very cool! Good to know - I'll pass along to my dev team :)
["Misty May-Treanor", "Kerri Walsh"]
["Misty May-Treanor", "Kerri Walsh"]
My Chrome with newest update show this, how to fix it to show the right?
@Son,
Maybe it's still in the nightly build, not in the main Chrome release? I don't know much about the bleeding edge stuff; I just have the standard Chrome builds.
It's stable build, my browser was auto updated.
BTW, thank you, I'll look around to fix it.
I use chrome debugging tools and I have great experience with it.. thanks for sharing it to know every developers to better understand.
@Ben ...
Not sure if this was fixed or not ... but did you 'really' have an element with the ID 'title' or did you inadvertently use the wrong function to reference the element ?
// Eh? var title = document.getElementById( "title" );
// ? var title = document.getElementsByTagName("title");
I'm having the same problem today, the console log is showing an object closed with the |> arrow next to the object, when you open the object to inspect it, the object contains information that cannot possibly have been in the object when it was logged.
I'm outputting a test string before each step, so I receive the output for the second parameter AFTER the log of the first console.log of the object, yet the first occurrence contains information from the second step.......which is impossible.
So it's STILL lazily evaluating objects that are logged, this seems like an obvious mistake, a log is exactly how you described, it's supposed to contain information from the instant it was logged, it's the entire purpose to create a traceable history.