console.group() emits duplicate CDP messages

[connor4312]

• Version: v12.11.1
• Platform: Darwin 10.14

What steps will reproduce the bug?

With a debugger attached, invoke:

console.group('group name', { foo: true });

How often does it reproduce? Is there a required condition?

Every time

What is the expected behavior?

There should be a single CDP message for the console group. Running that line of code in the Chrome devtools, that is the case and I get a single message:

What do you see instead?

Running that line of code in Node.js, I get two messages--the correct startGroup type, and then an additional log message whose stack says it comes from the group method in internal/console/constructor.js

{"method":"Runtime.consoleAPICalled","params":{"type":"startGroup","args":[{"type":"string","value":"group name"},{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":1}","preview":{"type":"object","description":"Object","overflow":false,"properties":[{"name":"foo","type":"boolean","value":"true"}]}}],"executionContextId":1,"timestamp":1582746620974.181,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"97","url":"file:///Users/copeet/Github/vscode-pwa/demos/node/main.js","lineNumber":1,"columnNumber":8},{"functionName":"Module._compile","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":944,"columnNumber":29},{"functionName":"Module._extensions..js","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":961,"columnNumber":9},{"functionName":"Module.load","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":797,"columnNumber":31},{"functionName":"Module._load","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":710,"columnNumber":11},{"functionName":"Module.runMain","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":1013,"columnNumber":9},{"functionName":"","scriptId":"39","url":"internal/main/run_main_module.js","lineNumber":16,"columnNumber":10}]}}}
{"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"group name"},{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":2}","preview":{"type":"object","description":"Object","overflow":false,"properties":[{"name":"foo","type":"boolean","value":"true"}]}}],"executionContextId":1,"timestamp":1582746620974.757,"stackTrace":{"callFrames":[{"functionName":"group","scriptId":"25","url":"internal/console/constructor.js","lineNumber":385,"columnNumber":11},{"functionName":"","scriptId":"97","url":"file:///Users/copeet/Github/vscode-pwa/demos/node/main.js","lineNumber":1,"columnNumber":8},{"functionName":"Module._compile","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":944,"columnNumber":29},{"functionName":"Module._extensions..js","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":961,"columnNumber":9},{"functionName":"Module.load","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":797,"columnNumber":31},{"functionName":"Module._load","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":710,"columnNumber":11},{"functionName":"Module.runMain","scriptId":"43","url":"internal/modules/cjs/loader.js","lineNumber":1013,"columnNumber":9},{"functionName":"","scriptId":"39","url":"internal/main/run_main_module.js","lineNumber":16,"columnNumber":10}]}}}

Additional information

For now I can look for this behavior inside our debugger and ignore logs that come from the 'group' function in that file, though this is rather delicate. It'd be nice to have it resolved 🙂

Ref: https://github.com/microsoft/vscode/issues/91095

[Pratik-ahirrao]

Can i work on this issue?

[addaleax]

@Pratik-ahirrao There’s nobody actively working on this, as far as I know.

[Pratik-ahirrao]

This is my contribution. Can you help me to get start with this issue?

[addaleax]

@Pratik-ahirrao I don’t really know where to start here, tbh. It’s probably not hard to fix but I don’t know what the actual underlying cause is here, otherwise I would have looked into this when it was opened.

[connor4312]

Following up since I'm refactoring and improving this area in the debugger: this seems to happen for several methods, including group, assert, and count. E.g. and output event for count is given normally as

{
  type: "log",
  args: [
    {
      type: "string",
      value: "asdf: 1",
    },
  ],
  executionContextId: 1,
  timestamp: 1597354790760.242,
  stackTrace: {
    callFrames: [
      {
        functionName: "count",
        scriptId: "25",
        url: "internal/console/constructor.js",
        lineNumber: 369,
        columnNumber: 9,
      },

then shortly followed up

{
  type: "log",
  args: [
    {
      type: "string",
      value: "asdf: 1",
    },
  ],
  executionContextId: 1,
  timestamp: 1597354790760.242,
  stackTrace: {
    callFrames: [
      {
        functionName: "count",
        scriptId: "25",
        url: "internal/console/constructor.js",
        lineNumber: 369,
        columnNumber: 9,
      },
      {
        functionName: "",
        scriptId: "119",
        url: "file:///c:/Users/Connor/Documents/Github/vscode-js-debug/demos/node/main.js",
        lineNumber: 1,
        columnNumber: 10,
      },

In the debugger I have create a denylist of methods in internal/console/constructor.js from which we ignore events.