Vscode: process.stdout.write calls don't show in the console from node2 debug sessions

[jdforsythe]

• VSCode Version: 1.9.0
• OS Version: Windows 10

Steps to Reproduce:

1. Launch debug task
2. Watch debug console

The new update appears to have broken the debug output. Previously we would get the following when launching the debug task:

node --inspect=30770 --debug-brk --nolazy debugall.js 
Debugger listening on port 30770.
Warning: This is an experimental feature and could change at any time.

This would then be followed by the normal debug output from our project. Now when we run the debug task, the above is the only thing showing in the debug console. The application functions normally so it is running, but no output is shown.

launch.json:

{
  "version": "0.1.0",
  "configurations": [
    {
      "name": "Debug All",
      "type": "node2",
      "program": "${workspaceRoot}/debugall.js",
      "stopOnEntry": false,
      "args": [],
      "cwd": "${workspaceRoot}/",
      "runtimeExecutable": null,
      "runtimeArgs": [
        "--nolazy"
      ],
      "env": {
        "NODE_ENV": "development",
        "LOGSQL": "false",
        "USE_COMPRESSION": "false",
      },
      "sourceMaps": false,
      "outDir": null,
      "console": "internalConsole"
    }
  ]
}

[jdforsythe]

Note: if you change to "console": "integratedTerminal" it works fine

[jdforsythe]

The issue is also present on Mac

[pkeuter]

+1, this only happens when using node2. When switching to node, the problem does not appear. Also, breakpoints only get verified when restarting the application (they do work though).

[isidorn]

Assigning to @roblourens to do an initial investigation since it only happens with node2

[roblourens]

Which version of node?

Can you set "diagnosticLogging": true and try again? It will print a path to a log file at the top of the debug console. Can you upload that log file?

[pkeuter]

@roblourens, version 7.5.0
http://pastebin.com/WA9mDVLJ

I have just tested with 6.9.5 (latest LTS), and this has the same issues.

[roblourens]

Thanks, I'm looking for the full log though, "Verbose logs are written to ...", can you upload that? You can just drag the file into github.

Do the messages show up in chrome devtools? If you debug with node --inspect ...?

[pkeuter]

This is what I've just uploaded. I'm not using chrome-debug here.

I'm not sure what you mean with the last question. If you want to know if there is any output when I run the application with node --inspect, yes there is.

[jdforsythe]

I can confirm it's only using node2 and not with node.

$ node -v
v6.9.1

Running the task with "diagnosticLogging": true:

Verbose logs are written to C:\Users\JFORSY~1\AppData\Local\Temp\vscode-node-debug2.txt
4:44:18 PM, 2/6/2017
OS: win32 ia32
Adapter node: v6.5.0 ia32
vscode-chrome-debug-core: 3.11.7
node-debug2: 1.9.12
node --inspect=37775 --debug-brk --nolazy c:\dev\project/debugall.js 
Discovering targets via http://127.0.0.1:37775/json
Debugger listening on port 37775.
Warning: This is an experimental feature and could change at any time.
Paused on entry
Target node version: v6.9.1 x64

The debug file has some potentially sensitive information in it, so I won't post the full thing (I can email if you'd like) but the important bits, I think, are here:

Verbose logs are written to C:\Users\JFORSY~1\AppData\Local\Temp\vscode-node-debug2.txt
4:44:18 PM, 2/6/2017
OS: win32 ia32
Adapter node: v6.5.0 ia32
vscode-chrome-debug-core: 3.11.7
node-debug2: 1.9.12
From client: initialize({"adapterID":"node2","pathFormat":"path","linesStartAt1":true,"columnsStartAt1":true,"supportsVariableType":true,"supportsVariablePaging":true,"supportsRunInTerminalRequest":true})
To client: {"seq":0,"type":"response","request_seq":1,"command":"initialize","success":true,"body":{"exceptionBreakpointFilters":[{"label":"All Exceptions","filter":"all","default":false},{"label":"Uncaught Exceptions","filter":"uncaught","default":true}],"supportsConfigurationDoneRequest":true,"supportsSetVariable":true,"supportsConditionalBreakpoints":true,"supportsCompletionsRequest":true,"supportsHitConditionalBreakpoints":true,"supportsRestartFrame":true}}
From client: launch({"name":"Debug All","type":"node2","diagnosticLogging":true,"request":"launch","stopOnEntry":false,"args":["c:\\dev\\project/debugall.js"],"cwd":"c:\\dev\\project/","preLaunchTask":null,"runtimeExecutable":null,"runtimeArgs":["--nolazy"],"env":{"NODE_ENV":"development","LOGSQL":"false","USE_COMPRESSION":"false","ENABLE_DEV_DOMAIN":"true","LOCALS3":"false","LOCALFS":"false"},"sourceMaps":false,"outDir":null,"console":"internalConsole","skipFiles":["<node_internals>/**","**/node_modules/**"]})
Discovering targets via http://127.0.0.1:37775/json
Attaching to target: {"description":"node.js instance","devtoolsFrontendUrl":"https://chrome-devtools-frontend.appspot.com/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:37775/8f0f49c1-590c-47a3-94f5-0373bc99b8b5","faviconUrl":"https://nodejs.org/static/favicon.ico","id":"8f0f49c1-590c-47a3-94f5-0373bc99b8b5","title":"c:_dev_project/debugall.js","type":"node","url":"file://C:_dev_project_debugall.js","webSocketDebuggerUrl":"ws://127.0.0.1:37775/8f0f49c1-590c-47a3-94f5-0373bc99b8b5"}
WebSocket Url: ws://127.0.0.1:37775/8f0f49c1-590c-47a3-94f5-0373bc99b8b5
To target: "{\"id\":1,\"method\":\"Debugger.setBlackboxPatterns\",\"params\":{\"patterns\":[\"(.*[\\\\/\\\\\\\\])?node_modules[\\\\/\\\\\\\\](.*[\\\\/\\\\\\\\])?\",\"^(?!\\\\/)(?![a-zA-Z]:)(.*[\\\\/\\\\\\\\])?\"]}}"
To target: "{\"id\":2,\"method\":\"Console.enable\"}"
To target: "{\"id\":3,\"method\":\"Debugger.enable\"}"
To target: "{\"id\":4,\"method\":\"Runtime.enable\"}"
To target: "{\"id\":5,\"method\":\"Runtime.runIfWaitingForDebugger\"}"
To target: "{\"id\":6,\"method\":\"Runtime.run\"}"
From target: {"id":1,"result":{}}
From target: {"id":2,"result":{}}
From target: {"id":3,"result":{}}
From target: {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"NodeJS Main Context"}}}
From target: {"id":4,"result":{}}
From target: {"id":5,"result":{}}
From target: {"error":{"code":-32601,"message":"'Runtime.run' wasn't found"},"id":6}
To target: "{\"id\":7,\"method\":\"Runtime.evaluate\",\"params\":{\"expression\":\"[process.pid, process.version, process.arch]\",\"returnByValue\":true,\"contextId\":1}}"
To client: {"seq":0,"type":"response","request_seq":2,"command":"launch","success":true}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"43","url":"bootstrap_node.js","startLine":0,"startColumn":0,"endLine":511,"endColumn":0,"executionContextId":1,"hash":"ACC5FC93EBC03965891A7B76D65D5EC42EB55E82","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"45","url":"","startLine":0,"startColumn":0,"endLine":0,"endColumn":44,"executionContextId":1,"hash":"22960EE2CC885872F71ED2E747A68B200282CC65","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"id":7,"result":{"result":{"type":"object","subtype":"error","className":"ReferenceError","description":"ReferenceError: process is not defined\n    at \u003Canonymous\u003E:1:2\n    at bootstrap_node.js:1:1","objectId":"{\"injectedScriptId\":1,\"id\":1}"},"exceptionDetails":{"exceptionId":1,"text":"Uncaught","lineNumber":0,"columnNumber":1,"scriptId":"45","stackTrace":{"callFrames":[{"functionName":"","scriptId":"45","url":"","lineNumber":0,"columnNumber":1},{"functionName":"","scriptId":"43","url":"bootstrap_node.js","lineNumber":0,"columnNumber":0}]},"exception":{"type":"object","subtype":"error","className":"ReferenceError","description":"ReferenceError: process is not defined\n    at \u003Canonymous\u003E:1:2\n    at bootstrap_node.js:1:1","objectId":"{\"injectedScriptId\":1,\"id\":2}"}}}}
Got expected exception: `process is not defined`. Will try again later.
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"46","url":"events.js","startLine":0,"startColumn":0,"endLine":483,"endColumn":3,"executionContextId":1,"hash":"2079B9E3C9B84A4288F47F5531D9546816946054","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"47","url":"util.js","startLine":0,"startColumn":0,"endLine":1056,"endColumn":3,"executionContextId":1,"hash":"60453D708420B9B69FB9E7D4037748F1141CB272","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"48","url":"buffer.js","startLine":0,"startColumn":0,"endLine":1344,"endColumn":3,"executionContextId":1,"hash":"AAD441B347D9863975EF55B231FCDDD2ACB26B65","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"49","url":"internal/util.js","startLine":0,"startColumn":0,"endLine":168,"endColumn":3,"executionContextId":1,"hash":"6C92DF6384FC749A971ADFB6D252E5CAB1D4F883","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"50","url":"timers.js","startLine":0,"startColumn":0,"endLine":718,"endColumn":3,"executionContextId":1,"hash":"A4226291250E4D4006474285058AF9EB6E1C0520","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"51","url":"internal/linkedlist.js","startLine":0,"startColumn":0,"endLine":72,"endColumn":3,"executionContextId":1,"hash":"C9B003D0A94D6420CFF22A00EAEB23D947FAA760","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"52","url":"assert.js","startLine":0,"startColumn":0,"endLine":372,"endColumn":3,"executionContextId":1,"hash":"CBAC7782F03628433FAF7EB49B2B45A4745166C3","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"53","url":"internal/process.js","startLine":0,"startColumn":0,"endLine":252,"endColumn":3,"executionContextId":1,"hash":"CE9F3E60D93CBBB954B38AD56845AD77CBDC6FE2","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"54","url":"internal/process/warning.js","startLine":0,"startColumn":0,"endLine":50,"endColumn":3,"executionContextId":1,"hash":"539015137923A6348BA33CE0B81DFFF54211A1A0","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"55","url":"internal/process/next_tick.js","startLine":0,"startColumn":0,"endLine":158,"endColumn":3,"executionContextId":1,"hash":"B8CBC4126F5C1951A454D4F64DC68E872ABA0E37","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"56","url":"internal/process/promises.js","startLine":0,"startColumn":0,"endLine":77,"endColumn":3,"executionContextId":1,"hash":"16F634A161C02BF8E72355F5D2B0397CCCB944B4","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"57","url":"internal/process/stdio.js","startLine":0,"startColumn":0,"endLine":176,"endColumn":3,"executionContextId":1,"hash":"D060A290AD916B0296AD4F8351EEA1A5BB6CD143","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"58","url":"path.js","startLine":0,"startColumn":0,"endLine":1598,"endColumn":3,"executionContextId":1,"hash":"D75D8992EB9A8DD54ADF5EC62AF90684DB174F03","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"59","url":"module.js","startLine":0,"startColumn":0,"endLine":668,"endColumn":3,"executionContextId":1,"hash":"BCAB2D7041B142E78572F7025028086A6EEE0165","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"60","url":"internal/module.js","startLine":0,"startColumn":0,"endLine":97,"endColumn":3,"executionContextId":1,"hash":"A799FB00D3EECEA0E36238210812CBD6D68533B6","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"61","url":"vm.js","startLine":0,"startColumn":0,"endLine":105,"endColumn":3,"executionContextId":1,"hash":"B4F6B9D140C54AC0002962F54D66A389D75DBAA0","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"62","url":"fs.js","startLine":0,"startColumn":0,"endLine":2243,"endColumn":3,"executionContextId":1,"hash":"B75B8D128AFCB417EB1101F7686665B357CA0508","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"63","url":"stream.js","startLine":0,"startColumn":0,"endLine":108,"endColumn":3,"executionContextId":1,"hash":"4EA8A5B1EFFACB02F4F714F611015942BFA250B5","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"64","url":"_stream_readable.js","startLine":0,"startColumn":0,"endLine":977,"endColumn":3,"executionContextId":1,"hash":"257A3951AF5BDDC09A213D96006D4CEB93C66587","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"65","url":"internal/streams/BufferList.js","startLine":0,"startColumn":0,"endLine":73,"endColumn":3,"executionContextId":1,"hash":"A7683B52CD6F6299B8D6DF70EF9B54E9CAE2BC96","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"66","url":"_stream_writable.js","startLine":0,"startColumn":0,"endLine":557,"endColumn":3,"executionContextId":1,"hash":"38172B63B6EBD73281233F759E50F47B6D60D754","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"67","url":"_stream_duplex.js","startLine":0,"startColumn":0,"endLine":58,"endColumn":3,"executionContextId":1,"hash":"5E476583F40B11B912420FD1AC4295F8C71738F2","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"68","url":"_stream_transform.js","startLine":0,"startColumn":0,"endLine":193,"endColumn":3,"executionContextId":1,"hash":"D99FBE9083ADCBA4CD40A7815E34A88A3D75CB45","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"69","url":"_stream_passthrough.js","startLine":0,"startColumn":0,"endLine":23,"endColumn":3,"executionContextId":1,"hash":"122E62B378B03CAABE23C6A421ED869B93DBE6E1","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"70","url":"c:\\dev\\project\\debugall.js","startLine":0,"startColumn":0,"endLine":18,"endColumn":3,"executionContextId":1,"hash":"F85EFFB1344347A96F0220C093ACC64AD682D1D4","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"method":"Debugger.paused","params":{"callFrames":[{"callFrameId":"{\"ordinal\":0,\"injectedScriptId\":1}","functionName":"","functionLocation":{"scriptId":"70","lineNumber":0,"columnNumber":10},"location":{"scriptId":"70","lineNumber":0,"columnNumber":62},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":3}"},"startLocation":{"scriptId":"70","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"70","lineNumber":18,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":4}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":5}"}},{"callFrameId":"{\"ordinal\":1,\"injectedScriptId\":1}","functionName":"Module._compile","functionLocation":{"scriptId":"59","lineNumber":509,"columnNumber":36},"location":{"scriptId":"59","lineNumber":569,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":6}"},"name":"Module._compile","startLocation":{"scriptId":"59","lineNumber":509,"columnNumber":36},"endLocation":{"scriptId":"59","lineNumber":572,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":7}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":8}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":9}"}},{"callFrameId":"{\"ordinal\":2,\"injectedScriptId\":1}","functionName":"Module._extensions..js","functionLocation":{"scriptId":"59","lineNumber":576,"columnNumber":36},"location":{"scriptId":"59","lineNumber":578,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":10}"},"name":"Module._extensions..js","startLocation":{"scriptId":"59","lineNumber":576,"columnNumber":36},"endLocation":{"scriptId":"59","lineNumber":579,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":11}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":12}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":13}"}},{"callFrameId":"{\"ordinal\":3,\"injectedScriptId\":1}","functionName":"Module.load","functionLocation":{"scriptId":"59","lineNumber":477,"columnNumber":32},"location":{"scriptId":"59","lineNumber":486,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":14}"},"name":"Module.load","startLocation":{"scriptId":"59","lineNumber":477,"columnNumber":32},"endLocation":{"scriptId":"59","lineNumber":488,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":15}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":16}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":17}"}},{"callFrameId":"{\"ordinal\":4,\"injectedScriptId\":1}","functionName":"tryModuleLoad","functionLocation":{"scriptId":"59","lineNumber":442,"columnNumber":22},"location":{"scriptId":"59","lineNumber":445,"columnNumber":11},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":18}"},"name":"tryModuleLoad","startLocation":{"scriptId":"59","lineNumber":442,"columnNumber":22},"endLocation":{"scriptId":"59","lineNumber":452,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":19}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":20}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":5,\"injectedScriptId\":1}","functionName":"Module._load","functionLocation":{"scriptId":"59","lineNumber":411,"columnNumber":23},"location":{"scriptId":"59","lineNumber":437,"columnNumber":2},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":21}"},"name":"Module._load","startLocation":{"scriptId":"59","lineNumber":411,"columnNumber":23},"endLocation":{"scriptId":"59","lineNumber":440,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":22}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":23}"}}],"this":{"type":"function","className":"Function","description":"function Module(id, parent) {\n  this.id = id;\n  this.exports = {};\n  this.parent = parent;\n  if (parent && parent.children) {\n    parent.children.push(this);\n  }\n\n  this.filename = null;\n  this.loaded = false;\n  this.children = [];\n}","objectId":"{\"injectedScriptId\":1,\"id\":24}"}},{"callFrameId":"{\"ordinal\":6,\"injectedScriptId\":1}","functionName":"Module.runMain","functionLocation":{"scriptId":"59","lineNumber":601,"columnNumber":25},"location":{"scriptId":"59","lineNumber":603,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":25}"},"name":"Module.runMain","startLocation":{"scriptId":"59","lineNumber":601,"columnNumber":25},"endLocation":{"scriptId":"59","lineNumber":606,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":26}"},"startLocation":{"scriptId":"59","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"59","lineNumber":668,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":27}"}}],"this":{"type":"object","className":"Timeout","description":"Timeout","objectId":"{\"injectedScriptId\":1,\"id\":28}"}},{"callFrameId":"{\"ordinal\":7,\"injectedScriptId\":1}","functionName":"ontimeout","functionLocation":{"scriptId":"50","lineNumber":360,"columnNumber":18},"location":{"scriptId":"50","lineNumber":364,"columnNumber":13},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":29}"},"name":"ontimeout","startLocation":{"scriptId":"50","lineNumber":360,"columnNumber":18},"endLocation":{"scriptId":"50","lineNumber":382,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":30}"},"startLocation":{"scriptId":"50","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"50","lineNumber":718,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":31}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":8,\"injectedScriptId\":1}","functionName":"tryOnTimeout","functionLocation":{"scriptId":"50","lineNumber":232,"columnNumber":21},"location":{"scriptId":"50","lineNumber":236,"columnNumber":4},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":32}"},"name":"tryOnTimeout","startLocation":{"scriptId":"50","lineNumber":232,"columnNumber":21},"endLocation":{"scriptId":"50","lineNumber":250,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":33}"},"startLocation":{"scriptId":"50","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"50","lineNumber":718,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":34}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":9,\"injectedScriptId\":1}","functionName":"listOnTimeout","functionLocation":{"scriptId":"50","lineNumber":160,"columnNumber":22},"location":{"scriptId":"50","lineNumber":206,"columnNumber":4},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":35}"},"name":"listOnTimeout","startLocation":{"scriptId":"50","lineNumber":160,"columnNumber":22},"endLocation":{"scriptId":"50","lineNumber":227,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":36}"},"startLocation":{"scriptId":"50","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"50","lineNumber":718,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":37}"}}],"this":{"type":"object","className":"Timer","description":"Timer","objectId":"{\"injectedScriptId\":1,\"id\":38}"}}],"reason":"other","hitBreakpoints":[]}}
Paused on entry
To target: "{\"id\":8,\"method\":\"Runtime.evaluate\",\"params\":{\"expression\":\"[process.pid, process.version, process.arch]\",\"returnByValue\":true,\"contextId\":1}}"
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"72","url":"","startLine":0,"startColumn":0,"endLine":0,"endColumn":44,"executionContextId":1,"hash":"22960EE2CC885872F71ED2E747A68B200282CC65","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
From target: {"id":8,"result":{"result":{"type":"object","value":[8776,"v6.9.1","x64"]}}}
Target node version: v6.9.1 x64
To client: {"seq":0,"type":"event","event":"initialized"}
From client: setExceptionBreakpoints({"filters":["all","uncaught"]})
To target: "{\"id\":9,\"method\":\"Debugger.setPauseOnExceptions\",\"params\":{\"state\":\"all\"}}"
From target: {"id":9,"result":{}}
To client: {"seq":0,"type":"response","request_seq":3,"command":"setExceptionBreakpoints","success":true}
From client: configurationDone(undefined)
To target: "{\"id\":10,\"method\":\"Debugger.resume\"}"
To client: {"seq":0,"type":"response","request_seq":4,"command":"configurationDone","success":true}
From target: {"id":10,"result":{}}
From target: {"method":"Debugger.resumed","params":{}}
From client: threads(undefined)
To client: {"seq":0,"type":"response","request_seq":5,"command":"threads","success":true,"body":{"threads":[{"id":1,"name":"Thread 1"}]}}
From target: {"method":"Debugger.scriptParsed","params":{"scriptId":"73","url":"c:\\dev\\project\\manage\\app.js","startLine":0,"startColumn":0,"endLine":373,"endColumn":3,"executionContextId":1,"hash":"9FB68BC08CCB9FD468489285187B0D11DE2D5497","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}

There are many (6000+) of these last lines (From target:)

A couple more things that may or may not help: using nodemon also doesn't show any debug output (which was expected). Also, if there is an uncaught exception, it WILL show in the debug output.

[pkeuter]

I just found out that the problem is not with console.log, but with process.stdout.write, process.stderr.write seems to work fine.

So you can reproduce this. Make a new .js file with process.stdout.write("test");, launch it. It will work. Change the launch.json to use node2, it will stop outputting "test".

[roblourens]

@pkeuter Sorry you're right, that is the right file. I was looking for the messages from node containing the log messages, but they are missing. I actually had seen this on someone else's computer last week but couldn't repro it under the same conditions.

Are you saying that console.log output shows up, but process.stdout.write doesn't? I wouldn't expect process.stdout.write output to show up, because node2 isn't listening to the process' stdout. It only gets log messages over the debug socket from console.log.

You can check this by running with node --inspect --debug-brk and navigating to that URL in Chrome - then you won't see those messages in chrome devtools either. But if you are running 'console.log` and it doesn't show up, that's a problem, and I'd like to know if there's a difference between what you see in chrome devtools vs vscode.

[pkeuter]

Alright, console.log does (indeed) show up in devtools, process.stdout.write does not. So vscode and devtools do the same thing.

By the way, console output does show the process.stdout line:

So this doesn't seem to be a vscode issue then? But then how can it be that this is a problem since 1.9.0?

[pkeuter]

By the way, Winston is using process.stdout.write, that's why I noticed:
https://github.com/winstonjs/winston/blob/master/lib/winston/transports/console.js#L121

[roblourens]

Yeah, it will show up in the console output you see, because that's just showing stdout.

In 1.9 we switched from showing stdout to showing log messages from the debug protocol. There are a couple advantages to this, mainly that you can now log an object, and see an actual expandable object in the console, instead of just text like before.

We could listen to stdout as well, but then we would have to de-dupe messages between the two channels so that we don't show them twice. And if we do that, you could have an issue with message ordering. They might come over stdout faster than the debug protocol, and I think that showing messages in the wrong order is worse than not showing them at all.

Thanks for pointing out that Winston uses that - searching around a little, this might end up being a common issue.

[roblourens]

@jdforsythe Are you also using process.stdout.write? Or console.log?

[pkeuter]

@roblourens That sounds like a bad solution indeed. You could make it a setting though (showing stdout vs showing debug protocol)? With the way it is now as default. But you probably already thought of this :-)

Or you might do process.stdout.write = console.log, but this is obviously even uglier, haha.

[roblourens]

Yeah, I think we might want a setting for this. I also opened an issue on Winston - https://github.com/winstonjs/winston/issues/981 - so I'm curious what they will say.

[pkeuter]

Yeah, me too! I'll keep following that. Thanks.

[jdforsythe]

@roblourens We are also using winston

[jdforsythe]

@roblourens It looks like they specifically made the change from console.log:

https://github.com/winstonjs/winston/pull/163

I made a PR to winston to add a setting for the console transport to use console.log/console.error. It fixes this issue. I still have no output with nodemon using this, but in a regular launch configuration it works.

Fix PR: https://github.com/winstonjs/winston/pull/982

[roblourens]

Thanks for making the PR, but I hope we can find a solution that works out of the box for everyone.

[adelphes]

Is there any update to this?

In 1.9 we switched from showing stdout to showing log messages from the debug protocol. There are a couple advantages to this, mainly that you can now log an object, and see an actual expandable object in the console, instead of just text like before.

Losing the ability for the internal console to show console.log() messages is really unhelpful. Previously it was simple to run a node app and see what was happening in the same window - it now requires an extra config setting (console: "integratedTerminal" and switching back and forth between the terminal and debug windows.

I would prefer to revert the behaviour back to the original and rethink/redesign the change to only show messages from the debug protocol.

[roblourens]

console.log messages should still show up. Only process.stdout.write calls will not appear. Is that not what you are seeing?

[adelphes]

I haven't seen any console.log()messages in the Debug Console in 1.9 versions.
I've just created a brand new file with a default node2 launch.json and a simple console.log() source:

launch.json

{
// Use IntelliSense to learn about possible Node.js debug attributes.
// Hover to view descriptions of existing attributes.
// For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
"version": "0.2.0",
"configurations": [
{
"type": "node2",
"request": "launch",
"name": "Launch Program",
"program": "${workspaceRoot}/a.js",
"cwd": "${workspaceRoot}",
},
{
"type": "node2",
"request": "attach",
"name": "Attach to Process",
"port": 5858
}
]
}

a.js

console.log('Boom!')
return;

Stepping through it, nothing is outputted is Code - not in the Debug Console nor in the terminal or Output windows. I have to add a "console": "integratedTerminal" entry in order to see any output.
Am I missing something or is there anything I should be looking for?

[roblourens]

Can you try something? Run node --inspect --debug-brk a.js, then open the URL that it prints in Chrome. Then check whether it prints that log statement in the console?

Also, what OS and node version are you using?

[adelphes]

I don't see the log appear in Chrome - I do seem to get a lot of errors (in the Chrome debug tools) though, so perhaps something else is wrong.

I'm using Ubuntu 16 - x64, Code 1.9.1, Node 6.3.0 and Chrome 56.0.2924.87 (64-bit).

[adelphes]

@roblourens turns out my node version is too old!

I've just updated to the node LTS (v6.9.5) and console.log() is now shown in Debug Console. Thanks for the pointers - that was driving me crazy!
And, like the others, output from process.stdout.write() is not shown.

[roblourens]

I see, glad you figured it out!

[tinovyatkin]

Just my two cents for anybody who want to use inspector protocol with Winston now, while waiting for fix from any side, Winston console logger can be easily overridden to use real console:

const winston = require('winston');
const winstonCommon = require('winston/lib/winston/common');

// Override to use real console.log etc for VSCode debugger
  winston.transports.Console.prototype.log = function (level, message, meta, callback) {
    const output = winstonCommon.log(Object.assign({}, this, {
      level,
      message,
      meta,
    }));

    console[level in console ? level : 'log'](output);

    setImmediate(callback, null, true);
  };

and it magically works after that :)

[ilovett]

I had been piping my node process through a runtimeExecutable that looks like:

node $* | bunyan -L

This was working well with node but when switching to node2 (in order to work with node 6.9.5 debugging breakpoints not showing call stack) the bunyan outputted piped data seemed to break, which probably goes through stdout as well I'm guessing. Anything in my application that called console.log did show up in the Debug Console, however.

To get bunyan formatted text in the debug console. I tried the "console": "integratedTerminal" as mentioned above and that works in the Terminal tab, but the Debug Console is still missing text.

The surprising thing I saw though was the color text! Looking forward to that.

[roblourens]

I looked at bunyan's code, and it looks like they try to use console.log in the browser, and process.stdout.write in node. https://github.com/trentm/node-bunyan/blob/master/lib/bunyan.js#L475

I'm not sure why they do that in node, but it might be worth filing an issue on them to use console.log for node as well.

"console": "integratedTerminal" won't make the output show up in the debug console, but you should see all stdout output in the terminal at least.

[pkeuter]

Related to this: vscode prints console.warn and console.error twice. Once as a pretty printed object (debug protocol) and once as error (stderr). I don't think this is wanted behaviour?

[roblourens]

@pkeuter That's https://github.com/Microsoft/vscode/issues/21947, likely a Node bug on Windows.

[mrhein]

FYI
const debug = require('debug');
debug.log = console.log.bind(console);

[Nepoxx]

For the record Pino also suffers from this problem. I don't think filing issues on the logging libraries and convincing them to change to console.log is the way to go here, especially since console.log is slower.

[tonivj5]

It's a serious problem, when will it be resolved?

[yaronyg]

I'm using Winston with Node 8.1.4 and I just spent an hour before I finally got to this bug and realized what was going on. And the comment way above regarding integratedTerminal isn't working for me at all.

[Bnaya]

            "console": "integratedTerminal"

works very well,
Make sure you are on the right tab on the terminal tabs area

[yaronyg]

Thank you @Bnaya that was the problem. I was expecting it to be streamed in Debug Console but it was in the "Node Debug Console" terminal instance under Terminal.

[oliversalzburg]

For bunyan users, I can recommend using https://github.com/ibm-watson-data-lab/bunyan-console-stream while debugging. You can use https://github.com/oliversalzburg/debugger-attached to determine when to load it.

This way we're logging with console while running in VS Code and with process.stdout when running in production.

[roblourens]

The Insider's build now has the "outputCapture": "std" option, which will show stdout and stderr in the debug console, instead of the debug protocol messages, which should make it easier to work with process.stdout.write. Try it out and let me know!

[franklindner]

@roblourens Just tested the latest Insider Build, only debug and error output are showing in the debug console when using Winston.

[roblourens]

Do those actually get written to stdout?

[atif089]

@roblourens any hints on if this will be a part of minor release or patch release? Very excited to see this finally getting sorted out.

[roblourens]

You can use it today in the Insiders build. https://code.visualstudio.com/insiders

[roblourens]

Honestly I don't expect to find a better solution than opting into showing stdout/err directly with the new outputCapture option, (or "console": "integratedTerminal") so I'm closing this.

[roblourens]

Verification steps:

Debug this node script:

console.log('this is from console.log');
process.stdout.write('this is from process.stdout.write\n')

• You should see log from console.log, but not from process.stdout.write
• Set "outputCapture": "std" in your launch config (won't be recognized until the next build but will still work)
• Debug it again. Now you should see both logs.

[aeschli]

verified with Node 8.1.1

[rluncasu]

verified with v8.4.0

[nsgundy]

I tried to use "outputCapture": "std" on a remote node v6.9.1 process, but it seems that this is not compatible with an "request": "attach" type config (the squigglies somewhat in the launch.json somewhat illude to that). I guess this is a "nothing can be done here" situation?

[roblourens]

Yes, we can't capture the stdout when attaching to a running process.

[felipemullen]

Is this going to be a permanent issue? After updating node to the latest version I am seeing winston logging problems on several applications

[roblourens]

Yes but you can set "outputCapture": "std" to work around it.

[DeividasJackus]

"console": "internalConsole", "outputCapture": "std" verified with node 8.6.0 - thank you!

[GitFlip]

More of an FYI since using "outputCapture": "std" got this working for me:

Using VS Code v1.17.2 and node v6.11.4 on my Windows machine I was not able to capture console.log() output in the Debug Console without adding "outputCapture": "std" in my launch.json.

However using VS Code v1.17.0 and node v6.9.4 on my CentOS machine I was able to capture console.log() output in the Debug Console without adding "outputCapture": "std" in my launch.json.

I'm running the same exact code, but getting different results based on OS and slightly different VS Code and Node versions.

[igelbox]

I've tested using VSCode 1.18.0 and suggested node versions.

//launch.json:
{
  "version": "0.2.0",
  "configurations": [{
      "type": "node",
      "request": "launch",
      "runtimeExecutable": "/home/user/.nvm/versions/node/v6.9.4/bin/node",
      "name": "Launch Program",
      "outputCapture": "std",
      "program": "${workspaceRoot}/main.js"
    }]
}

//main.js:
console.log('test');

Logging works well on both: "runtimeExecutable": "/home/user/.nvm/versions/node/v6.9.4/bin/node", and "runtimeExecutable": "/home/user/.nvm/versions/node/v6.11.4/bin/node",

@GitFlip could you please check your code using VSCode 1.18 and provide more details (e.g. simplified source code).

[roblourens]

Using VS Code v1.17.2 and node v6.11.4 on my Windows machine I was not able to capture console.log() output in the Debug Console without adding "outputCapture": "std" in my launch.json.

Please open a new issue with details