1326182 - console.table data is affected by later alterations

Status: RESOLVED FIXED

(DevTools :: Console, defect, P3)

Description

[dxcqcv]

Attachment: fx-consoleTable-bug.png

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0
Build ID: 20161130210124

Steps to reproduce:

Sort a array like

const inventors =[ 
{ first: 'Albert', last: 'Einstein', year: 1879, passed: 1955 },
{ first: 'Isaac', last: 'Newton', year: 1643, passed: 1727 },
{ first: 'Galileo', last: 'Galilei', year: 1564, passed: 1642 },
{ first: 'Marie', last: 'Curie', year: 1867, passed: 1934 },
{ first: 'Johannes', last: 'Kepler', year: 1571, passed: 1630 },
{ first: 'Nicolaus', last: 'Copernicus', year: 1473, passed: 1543 },
{ first: 'Max', last: 'Planck', year: 1858, passed: 1947 },
{ first: 'Katherine', last: 'Blodgett', year: 1898, passed: 1979 },
{ first: 'Ada', last: 'Lovelace', year: 1815, passed: 1852 },
{ first: 'Sarah E.', last: 'Goode', year: 1855, passed: 1905 },
{ first: 'Lise', last: 'Meitner', year: 1878, passed: 1968 },
{ first: 'Hanna', last: 'Hammarström', year: 1829, passed: 1909 }
                 ];

                 const ordered = inventors.sort((a,b)=>a.year>b.year ? 1: -1);
                 console.table(ordered)


Actual results:

Only display old order


Expected results:

Show new order

Comment 1

[dxcqcv]

Attachment: fx-consoleTable-bug01.png

Comment 2

[Loic]

Attachment: 1326182.html

Comment 3

[Loic]

Attachment: screenshotFF50win7.jpg

WFM with FF50 on Win 7, the table is displayed sorted by "year"

Comment 5

[dxcqcv]

I think it's console.table bug so did not check other first.

Comment 6

[Tom Tromey :tromey]

I don't understand what the bug is here.
When I try the attached test, I get the results I expect: a table sorted by year.
Can you say what is wrong?  Otherwise I think we should simply close this.

Comment 7

[alex.bea]

I'm experiencing this bug as well, but it requires different code. This example is from a JS exercise series, and the original starter file has a second `.sort()` function in the same file that seems to cause the issue.

See below. Even though the `console.table()` function is used on the `firstSort`, in FF it displays the `secondSort`. I'm using v52.0.1.

```
const inventors =[
  { first: 'Albert', last: 'Einstein', year: 1879, passed: 1955 },
  { first: 'Isaac', last: 'Newton', year: 1643, passed: 1727 },
  { first: 'Galileo', last: 'Galilei', year: 1564, passed: 1642 },
  { first: 'Marie', last: 'Curie', year: 1867, passed: 1934 },
  { first: 'Johannes', last: 'Kepler', year: 1571, passed: 1630 },
  { first: 'Nicolaus', last: 'Copernicus', year: 1473, passed: 1543 },
  { first: 'Max', last: 'Planck', year: 1858, passed: 1947 },
  { first: 'Katherine', last: 'Blodgett', year: 1898, passed: 1979 },
  { first: 'Ada', last: 'Lovelace', year: 1815, passed: 1852 },
  { first: 'Sarah E.', last: 'Goode', year: 1855, passed: 1905 },
  { first: 'Lise', last: 'Meitner', year: 1878, passed: 1968 },
  { first: 'Hanna', last: 'Hammarström', year: 1829, passed: 1909 }
];

// Sorts inventors by birth year.
const firstSort = inventors.sort((a, b) => a.year > b.year ? 1 : -1);

console.table(firstSort);

// Sorts the inventors by years lived
const secondSort = inventors.sort(
  (a, b) => {
    return (a.passed - a.year) > (b.passed - b.year) ? -1 : 1;
  }
);
```

Comment 8

[Tom Tromey :tromey]

Ok, thanks.

My theory for what is going on here is that the table is not rendered -- and in particular the
table elements are not gathered -- until after the entire pasted code has completed.
And, because |sort| sorts in-place, firstSort and secondSort are identical, so the
display is unexpected.

I think there's another bug open about this sort of problem with console.log.

Clearing the needinfo because I think I understand the bug now.

Comment 9

[Nicolas Chevobbe [:nchevobbe]]

Steps to reproduce:
1. Open the console
2. Evaluate : 
```
x = [1,2,3];
console.table(x);
x.push(4);
console.table(x);
```


Expected results:

I should see 2 tables, one with 3 elements, one with 4 elements

Actual results:

The 2 tables are the same, and contains 4 elements (first console.table is erroneous)

---

This does not happen with console.log

Comment 11

[Siddharth Maurya [:savvysiddharth]]

This bug is still present, Can I work on this? Which files should I look for to do so?

Comment 12

[Nicolas Chevobbe [:nchevobbe]]

Hello Siddharth,

So, console.table is handled in this component: https://searchfox.org/mozilla-central/source/devtools/client/webconsole/components/ConsoleTable.js

At first, we don't have the data we need to display the table [1], so we fetch them [2][3]

Since this is happening asynchronously, `x` is now modified, so retrieving the properties for the first console.table will still return the "final" properties, not the one that were in the object at the time of logging.

One possible fix for that, would be to return from the server, when we handle the console.table, all the properties of the logged object (instead of a preview like we currently do).

Console API calls are handled here [4], so we could make something in [5] to detect if we are dealing with a console.table and try to return all the properties directly.

This could be risky performance wise if we are trying to log a very large array/object, so we need to be careful here.

---

[1] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/client/webconsole/components/ConsoleTable.js#91,96
[2] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/client/webconsole/components/ConsoleTable.js#47-48
[3] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/client/webconsole/actions/messages.js#88-107
[4] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/server/actors/webconsole.js#1542-1557
[5] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/server/actors/webconsole.js#1722-1744

Comment 13

[Siddharth Maurya [:savvysiddharth]]

Thanks for info 👍!
Will start working on the fix 🙂.

Comment 14

[Siddharth Maurya [:savvysiddharth]]

(In reply to Nicolas Chevobbe from comment #12) 
> One possible fix for that, would be to return from the server, when we
> handle the console.table, all the properties of the logged object (instead
> of a preview like we currently do).
🤔 didn't get the "preview" part, where are we taking preview of object ?

Comment 15

[Nicolas Chevobbe [:nchevobbe]]

(clearing needinfo as we discussed on Slack)

Comment 16

[Siddharth Maurya [:savvysiddharth]]

I'm not sure if preview is culprit or not..

For checking what's happening, I added this if condition to this line...
https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/server/actors/webconsole.js#1736

if(message.level == "table" || message.level == "log") {
  dump("\n\n<---------SERVER DUMP START-------->\n\n");
  
  let seen = [];
  dump(JSON.stringify(message, function(key, val) { //to serialize object
                     if (val != null && typeof val == "object") {
                          if (seen.indexOf(val) >= 0) {
                              return;
                          }
                          seen.push(val);
                      }
                      return val;
                  }));

  dump("\n\n");

  dump(JSON.stringify(result.arguments));
  dump("\n\n<---------SERVER DUMP END---------->\n\n");
}

I did this to simply check state of message and result.arguments ...

And I also modified this... https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/devtools/client/webconsole/actions/messages.js#88-107
to this...

fetchObjectActorData(enumResponse => {
  const {iterator} = enumResponse;
  iterator.slice(0, iterator.count, sliceResponse => {

    let seen = [];
    console.log("<---------CLIENT LOG START-------->");
    console.log("");
    console.log(JSON.stringify(sliceResponse, function(key, val) { //to serialize object
                   if (val != null && typeof val == "object") {
                        if (seen.indexOf(val) >= 0) {
                            return;
                        }
                        seen.push(val);
                    }
                    return val;
                }));
    console.log("");
    console.log("<---------CLIENT LOG END---------->");

    const {ownProperties} = sliceResponse;
    dispatch(messageTableDataReceive(id, ownProperties));
  });
});

to check state of recieved message..

-------------------------

Then I ran following code...

let x = [11,22,33];
console.table(x);
x.push(44);
console.table(x);

Here's what I got on terminal :-

<---------SERVER DUMP START-------->

{"ID":8589934593,"addonId":"","arguments":[[11,22,33]],"columnNumber":1,"consoleID":"","counter":null,"filename":"debugger eval code","functionName":"","groupName":"","innerID":8589934595,"level":"table","lineNumber":2,"prefix":"","private":false,"timeStamp":1541155241134,"timer":null}

[{"type":"object","actor":"server1.conn1.child1/obj29","class":"Array","extensible":true,"frozen":false,"sealed":false,"ownPropertyLength":4,"preview":{"kind":"ArrayLike","length":3,"items":[11,22,33]}}]

<---------SERVER DUMP END---------->



<---------SERVER DUMP START-------->

{"ID":8589934593,"addonId":"","arguments":[[11,22,33,44]],"columnNumber":1,"consoleID":"","counter":null,"filename":"debugger eval code","functionName":"","groupName":"","innerID":8589934595,"level":"table","lineNumber":4,"prefix":"","private":false,"timeStamp":1541155241142,"timer":null}

[{"type":"object","actor":"server1.conn1.child1/obj30","class":"Array","extensible":true,"frozen":false,"sealed":false,"ownPropertyLength":5,"preview":{"kind":"ArrayLike","length":4,"items":[11,22,33,44]}}]

<---------SERVER DUMP END---------->

console.log: "<---------CLIENT LOG START-------->"
console.log: ""
console.log: "{\"ownProperties\":{\"0\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":11},\"1\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":22},\"2\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":33},\"3\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":44}},\"from\":\"server1.conn1.child1/propertyIterator31\"}"
console.log: ""
console.log: "<---------CLIENT LOG END---------->"
console.log: "<---------CLIENT LOG START-------->"
console.log: ""
console.log: "{\"ownProperties\":{\"0\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":11},\"1\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":22},\"2\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":33},\"3\":{\"configurable\":true,\"enumerable\":true,\"writable\":true,\"value\":44}},\"from\":\"server1.conn1.child1/propertyIterator32\"}"
console.log: ""
console.log: "<---------CLIENT LOG END---------->"


----------------------------------------
Here we can see that message sent by server contains property "preview" which seems to hold correct values for array item (that is [11,22,33] for first call, and [11,22,33,44] for second call) for both of "console.table(x)" call,
But for the response at client side we get latest state for both call.

So my question is,

How come preview of object can be issue here, since all properties are being send with it?

And where exactly this message it recieved?
I looked at variable 'enumResponse' in "message.js" file which isn't like the message sent and I coudn't figure out using Browser Content toolbox debugger, as after sending it goes on continuing other server side stuff.

Why does not this happen with console.log() ?

Comment 17

[Nicolas Chevobbe [:nchevobbe]]

> How come preview of object can be issue here, since all properties are being send with it?

Because you chose a simple array, with 3 (then 4) items in it.
Preview will usually contain the first 10 items of the array, so if you console.table on an object with less than 10 items, we'll have everything send right away.
You can try with the following:

```js
let x = Array.from({length: 20}, (_, i) => i);
console.table(x);
x.push("added later")
console.table(x);
```

Comment 18

[Siddharth Maurya [:savvysiddharth]]

> Because you chose a simple array, with 3 (then 4) items in it.
> Preview will usually contain the first 10 items of the array, so if you
> console.table on an object with less than 10 items, we'll have everything
> send right away.

Ok, got it, thanks!

Comment 19

[Siddharth Maurya [:savvysiddharth]]

Attachment: Bug 1326182 - Console table affected by later alteration fixed; r=nchevobbe

all properties of object are send instead of preview to fix this

Comment 20

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1326182 - Send all the console.table items in the console message. r=Honza.

This allows us to not have to reach for the server
again from the client to get all the data we need
to render the table.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e06f2a4de969
Send all the console.table items in the console message. r=Honza.

Comment 22

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/e06f2a4de969