DEV Community

Vladimir Elchinov for Session Replay

Posted on

Your Console Screenshot Shows Values That Never Coexisted

Three lines, from MDN's own documentation for console:

const obj = {};
console.log(obj);
obj.prop = 123;
Enter fullscreen mode Exit fullscreen mode

That logs {}. Expand the object in the console afterwards and you see prop: 123.

MDN states the mechanism plainly: "Information about an object is lazily retrieved. This means that the log message shows the content of an object at the time when it's first viewed, not when it was logged."

Not when it was logged. That is the whole article, and it has a consequence most people have never had to think about.

The common explanation is wrong

The usual account of this is that console.log is asynchronous, and that you are seeing a race. That is not what happens. The call is synchronous and the message is recorded at the moment you make it, in order, with the right timestamp.

What is deferred is reading the object's contents. The console message holds a reference, not a copy, and the contents are serialised when something asks to see them. If nothing ever expands that line, nothing ever reads it. If you expand it four minutes later, you get the object as it is four minutes later, under a line stamped four minutes ago.

Primitives do not behave this way. console.log(count) captures the number. It is objects, arrays, Maps and anything else held by reference where the line and its payload can come from different moments.

Which breaks the single most requested artefact in bug reporting

"Send me the console" is the most common follow-up question in software, and for good reason: a red line in the console is often the whole answer.

Now think about how that screenshot gets made. Something goes wrong. The user, or a colleague, opens developer tools after the fact, finds the interesting line, clicks the arrow to expand the object, and screenshots what appears.

Every expanded object in that image was read at screenshot time. The log line next to it was written earlier. If your code mutates the object it logged, and most code that logs state does, then the screenshot shows a pairing of time and value that never existed.

You then debug against it. You read status: "settled" against a line that fired during pending, and you look for a bug that explains how a settled order got into the pending branch. There is no such bug. There is a viewer that read the object late.

And two reporters can hand you contradictory evidence, both honest

The split that makes this genuinely nasty: whether the value is stale depends on whether somebody clicked the triangle.

A collapsed line often shows a preview rendered at log time. Expanded, it shows the current contents. So one reporter who screenshots without expanding and one who expands first can send you two images of the same console on the same bug, disagreeing about what the object held, and neither of them has done anything wrong or touched anything.

If you have ever had two tickets for the same fault that contradicted each other on a detail and closed one as unreproducible, this is a candidate for why.

The fix in your own logging

If the object is going to be mutated and the moment matters, clone it at the point of logging. MDN's suggestion:

console.log(JSON.parse(JSON.stringify(obj)));
Enter fullscreen mode Exit fullscreen mode

and it notes that structuredClone() is more effective for cloning different types of object, which it is: JSON round-tripping silently drops functions and undefined, turns Date into a string, and throws on anything circular.

console.log("order before dispatch", structuredClone(order));
Enter fullscreen mode Exit fullscreen mode

The cost is real and worth stating. Cloning is work at log time rather than at view time, which is the wrong trade on a hot path, and it loses the things a reference gives you: a live object you can keep expanding, DOM nodes, class instances with their prototypes. So do it where the object is mutable and the timing is the point, and leave the reference where you are logging something you only ever read once.

The rule underneath it

A log line's timestamp tells you when the call happened. It tells you nothing about when its payload was read.

Anything that reads later is reading later, and that includes the viewer in your browser. A collector that serialises at the moment of the call gets a different answer from a viewer that serialises on expand, and the difference is not a bug in either of them. It is the difference between a snapshot and a reference, and only one of the two is evidence about a moment.

Top comments (0)