Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
jdforsythe opened this issue Feb 2, 2017 · 57 comments
Closed
Assignees
Labels
debug Debug viewlet, configurations, breakpoints, adapter issues feature-request Request for new features or functionality verified Verification succeeded

Comments

@jdforsythe
Copy link

jdforsythe commented Feb 2, 2017

  • 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
Copy link
Author

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

@jdforsythe
Copy link
Author

The issue is also present on Mac

@pkeuter
Copy link

pkeuter commented Feb 3, 2017

+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 isidorn assigned roblourens and unassigned isidorn Feb 6, 2017
@isidorn
Copy link
Contributor

isidorn commented Feb 6, 2017

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

@roblourens
Copy link
Member

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
Copy link

pkeuter commented Feb 6, 2017

@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
Copy link
Member

roblourens commented Feb 6, 2017

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
Copy link

pkeuter commented Feb 6, 2017

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
Copy link
Author

jdforsythe commented Feb 6, 2017

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
Copy link

pkeuter commented Feb 6, 2017

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
Copy link
Member

@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
Copy link

pkeuter commented Feb 6, 2017

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:

image
image

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
Copy link

pkeuter commented Feb 6, 2017

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
Copy link
Member

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
Copy link
Member

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

@pkeuter
Copy link

pkeuter commented Feb 6, 2017

@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
Copy link
Member

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

@pkeuter
Copy link

pkeuter commented Feb 6, 2017

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

@jdforsythe
Copy link
Author

@roblourens We are also using winston

@jdforsythe
Copy link
Author

jdforsythe commented Feb 7, 2017

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

winstonjs/winston#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: winstonjs/winston#982

@roblourens
Copy link
Member

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

@roblourens roblourens changed the title Debug output no longer showing in console process.stdout.write calls don't show in the console from node2 debug sessions Feb 7, 2017
@roblourens
Copy link
Member

roblourens commented Sep 11, 2017

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
Copy link

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

screen shot 2017-09-12 at 14 50 04

@roblourens
Copy link
Member

Do those actually get written to stdout?

@atif089
Copy link

atif089 commented Sep 16, 2017

@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
Copy link
Member

roblourens commented Sep 17, 2017

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

@roblourens
Copy link
Member

roblourens commented Sep 21, 2017

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
Copy link
Member

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
Copy link
Contributor

aeschli commented Sep 29, 2017

verified with Node 8.1.1

@aeschli aeschli added verified Verification succeeded and removed verification-needed Verification of issue is requested labels Sep 29, 2017
@rluncasu
Copy link

verified with v8.4.0

@nsgundy
Copy link

nsgundy commented Oct 2, 2017

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
Copy link
Member

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

@felipemullen
Copy link

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
Copy link
Member

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

@DeividasJackus
Copy link

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

@GitFlip
Copy link

GitFlip commented Nov 13, 2017

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
Copy link
Contributor

igelbox commented Nov 13, 2017

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
Copy link
Member

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

@microsoft microsoft locked and limited conversation to collaborators Nov 13, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
debug Debug viewlet, configurations, breakpoints, adapter issues feature-request Request for new features or functionality verified Verification succeeded
Projects
None yet
Development

No branches or pull requests