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.