Debug console loses ability to differentiate lines of output

[dancrumb]

Does this issue occur when all extensions are disabled?: Yes

• VS Code Version: Version: 1.75.1 (Universal)
• OS Version: macOS 13.0.1 (22A400) (M1 Pro)

Steps to Reproduce:

It's not 100% clear to me what the definitive recreate is. Initially, I thought it was something to do with code that outputs multiline log entries, but while testing with Extensions disabled, I realized that observation was a red herring.

I created a Loom to show the issue:
https://www.loom.com/share/66777e9fdb774a4186db493d02091667

In short, the Debug console starts by identifying individual output lines as I would expect; then it clumps a bunch of lines together as if they are one; then it goes back to single lines.

The impact is that output filtering doesn't work properly, which makes some debugging tasks very difficult.

[roblourens]

I think that using Winston writing directly to stdout here will be the issue, because then there is just a stream of output and no correspondence between calling some log API and one "message". Grabbing some logs might help verify that's the issue.

/jsDebugLogs

[vscodenpa]

Please collect trace logs using the following instructions:

If you're able to, add "trace": true to your launch.json and reproduce the issue. The location of the log file on your disk will be written to the Debug Console. Share that with us.

⚠️ This log file will not contain source code, but will contain file paths. You can drop it into https://microsoft.github.io/vscode-pwa-analyzer/index.html to see what it contains. If you'd rather not share the log publicly, you can email it to connor@xbox.com

[dancrumb]

Thanks Rob.

I've attached the VSCode logs and the debug console output.

Here's the launch configuration:

{
  "version": "0.2.0",
  "configurations": [
    {
      "type": "node",
      "request": "launch",
      "name": "Launch Sutro Server",
      "skipFiles": ["<node_internals>/**"],
      "runtimeArgs": [
        "-r",
        "ts-node/register",
        "-r",
        "tsconfig-paths/register",
        "--expose-gc"
      ],
      "args": "${workspaceFolder}/server.ts",
      "console": "internalConsole",
      "internalConsoleOptions": "openOnSessionStart",
      "outputCapture": "std",
      "env": {
        "NODE_ENV": "DEV",
        "SUTRO_LOG_LEVEL": "debug"
      },
      "trace": true
    }
  ]
}

Note that outputCapture is set to std because, you're right that Winston writes directly to STDOUT (see https://github.com/winstonjs/winston/blob/master/lib/winston/transports/console.js#L77 for confirmation of this).

Each debug console log entry starts with a date, an option service name in parentheses, a level in square brackets and then the data. Some log entries are multiline.

The file lines starting at 702 all the way up to and including 1164 are identified in the Debug Console as being the same line.

vscode-debugadapter-835d37d5.json.gz
debug-console.out.zip

[connor4312]

In the debugger we just do process.stdout.on('data', sendToVSCode), we don't make an effort to split lines, which means multiple lines could be sent in a single output event.

Code pointer: https://github.com/microsoft/vscode-js-debug/blob/cd4fe8e3d271db323323bdb13c881061d39dc657/src/targets/node/subprocessProgramLauncher.ts#L64-L65

[roblourens]

You can have a multiline log output message too, the loom shows this. But maybe splitting single messages by line is better than combining messages randomly?

[dancrumb]

FWIW - I have a few thoughts on what I could work with.

• Since you're just forwarding data chunks from the std* streams, there really isn't any way that I can see that would allow DAP or VSCode to know the difference between a newline in a multiline log entry and a newline at the end of a log entry. I don't see this as a shortcoming in VSCode; it's just the nature of streams.
• For the specific use case of Winston, I have the liberty of creating a specific Transport that could be configured specifically to support VSCode (if that's doable). This could append log entries with a specific character that VSCode would recognize as an "end of log entry" character.
• Alternatively, such a transport could use DAP to make calls to output with individual log entries.

[dancrumb]

A framework-agnostic version could be to support ETX characters when capturing std instead of console.

This would need an opt-in approach.

In this mode, the JS DAP implementation would store incoming data and only call dap.output on receipt of an ETX character.

I'd be happy to have a crack at implementing this if you think it seems sensible.

[connor4312]

The ETX character approach is neat, but I've never seen that used anywhere. It seems like someone would have to (a) run into this problem and (b) research to find out about this workaround if they hit it. Not sure that's worth the trouble.

I think splitting by lines is probably fine. If we wanted to be slightly more creative, we could automatically start splitting by EXT if we encounter one in the stream.

such a transport could use DAP to make calls to output with individual log entries.

The program lives several layers above DAP, this is not very feasible

[dancrumb]

Took a crack at an implementation. Be gentle :)

[roblourens]

For the specific use case of Winston, I have the liberty of creating a specific Transport that could be configured specifically to support VSCode (if that's doable).

Or you could use a transport that calls console.log once per message 🤷

[dancrumb]

For the specific use case of Winston, I have the liberty of creating a specific Transport that could be configured specifically to support VSCode (if that's doable).

Or you could use a transport that calls console.log once per message 🤷

Ahem... Yeah... Or that :)

[connor4312]

Or you could use a transport that calls console.log once per message 🤷

Even that's not guaranteed, we don't know how the OS will chunk output to us

[dancrumb]

Yeah, it looks like console.log is just a wrapper around writes to the stdout and stderr streams: https://github.com/nodejs/node/blob/2d9bf91fe1c545521e5578f6b31d59c79b402b82/lib/internal/console/constructor.js#L268

However, I was (perhaps mistakenly) under the impression from here that VSCode somehow intercepts calls to console.* differently... is this not the case? Looking at the code, I'm guessing the consoleAPICalled event comes into play, which should package things up appropriately.

[connor4312]

Yea, we get them in that event over CDP. It does some magic, such as putting objects in the "console" group so that they can be examined and don't get garabage collected as soon as they fall out of scope, for example. Node.js emits that event, though I'm not sure where internally that happens.

You might be looking at the wrong thing, though, as Node.js also has a console API that does not result in that event getting fired.

[nabeelkhan10]

Hey, @connor4312 I am new to programming and use vs code for my projects. I would love to contribute to this project.
But I don't know much programming currently learning OOP in java.
Please assign me some basic tasks so I can also start my open-source journey.

[connor4312]

Thanks for volunteering, but Dan already put in a PR (which I just merged 🙂 )