Debug Console: wrong order of incoming input

[roojay520]

Runtime environment

• Visual Studio Code v1.15.1 own compiler
• Node.js v8.2.1
• OS: Windows_NT ia32 10.0.15063

Description

I want to add "After sort:" between source arry and sort arry, look like this:

But console occasionally shows:

Why for-of-loop has not finished running, jump out to run console.log ? Source code:

    // Random to generate double digits.
    function getRandom() {
      return Math.round(Math.random() * 100);
    }
    // Writing data to the array.
    var score = [
      ["a", getRandom()],
      ["b", getRandom()],
      ["c", getRandom()],
      ["d", getRandom()],
      ["e", getRandom()]
    ];
    console.log("Before sort:");

    // Print source arry
    for (let m of score) {
      console.log(m);
    }

    // Call sort()
    score.sort((a, b) => {
      return b[1] - a[1];
    });
    console.log("After sort:");

    // Print sort arry.
    for (let n of score) {
      console.log(n);
    }

If i change my code like this:

// Writing data to the array.
var score = [["a", 55], ["b", 33], ["c", 44], ["d", 88], ["e", 22]];
// Print source arry
for (let m of score) {
  console.log(m);
}
console.log("After sort：");

This bug will still appear:

[isidorn]

This is just the order the order in which node is emitting events. Not sure if we can do anything here, though assigning to @roblourens since I see you are using the inspector protocol.

[roblourens]

The output events come back from the adapter in the right order, but they seem to get reordered by the console when it resolves the variables.

If the log statement is console.log(1) instead of logging an object, then this doesn't repro.

[isidorn]

I acknowledge the bug, the issue is that vscode gets an object as output from node2. VSCode has to get the children of that object by sending some request to node2. In the meantime more output comes which gets recieved before the children get resolved thus being appended to the output before.

Code pointer

The fix would be to remember the events in which they came and append them to the repl in that order. This has the downside that if some object takes a long time to resolve all subsequent output will be stuck.
Not a big fan of the fix -> backlog

[roojay520]

Thanks for your answer.

[roblourens]

Can't the object be inserted in the right position, once it's resolved, while still appending other output?

This seems like a really bad bug - having logs in the wrong order could make someone waste a lot of time debugging.

[isidorn]

Yes, we could insert it in the right position by changing the appendToRepl API we have in the debugModel.
I would only look into this if more users complain since the model is quite fragile due to various heuristics on spliting incoming output.

[good-bits]

@isidorn Possibly related to this defect and hopefully helpful: I bumped into an issue where console.log() and console.error() messages consistently appear out of order in the VS Code JavaScript DEBUG CONSOLE. The isolated code below demonstrates the observation. Has NOT been observed outside of the DEBUG CONSOLE (not when running Node.js from the command prompt; not in Chrome web browser). Thanks!

Particulars:

• Visual Studio Code v1.17.2
• Node.js v8.5.0
• Windows 10 v1703, build 15063.674, 64-bit

The VS Code DEBUG CONSOLE:

[isidorn]

@good-bits yeah, this seem to be the same issue. Assigning to November to investigate into a fix.

[good-bits]

@isidorn Thanks!

[weinand]

I agree with Rob that this is really a bad bug that we should fix: logs are for troubleshooting bugs not for making the troubleshooting more difficult...

[isidorn]

@good-bits I have investigated into your issue and it is actually not the same as the one from above. To be more precise the issue is in the debug adapter - it is sending the events in the wrong order. To track this issue I have created #37770

Keeping this open as this is a different issue explained in my comment above and I will investigate in a fix.

[good-bits]

@isidorn @roblourens @weinand Thank you so much!