Vscode: NodeJS debugger doesn't properly handle launched apps that restart on file change.

Created on 28 Dec 2017  ·  19Comments  ·  Source: microsoft/vscode

I've included additional details here Microsoft/vscode-recipes#52

I assume a property would need to be added to the node launch config to allow this to work correctly, and that this property doesn't already exit.

I did attempt to use restart: true, but that didn't correct anything.

  • VSCode Version: 1.91.1
  • OS Version: 10.12.6

Steps to Reproduce:

  1. Clone the sample project git clone https://github.com/SteelPhase/vscode-meteor-test vscode-meteor-test
  2. CD into the directory cd vscode-meteor-test
  3. install npm dependencies meteor npm install
  4. open vscode without extentions code --disable-extensions .
  5. launch Meteor: Node launch config
  6. wait util meteor launch, and debugger attaches
  7. modify !! Change me !! on line 6 of server/main.js to any value
  8. save file
  9. wait for => Server modified -- restarting...
  10. debugger will disconnect, and in doing so kills the npm, and meteor node processes

Expected end result:
Meteor should restart as usual with the file change, and either the node debugger should detach, or reattach as the debugger becomes available again.


Reproduces without extensions: Yes

*out-of-scope debug feature-request

Most helpful comment

@mattblackdev nice use of the Auto Attach feature!

/cc @auchenberg

All 19 comments

Have you tried setting the restart: true property? See https://code.visualstudio.com/docs/nodejs/nodejs-debugging#_restarting-debug-sessions-automatically-when-source-is-edited

Yes i did, and it's not really ideal for this situation. Ideally a property that would let the debugger detach when the process exits, without killing the process, and then listening for the inspector to be available again would solve this.

In this instance, if i set restart: true before step 5 in my test case, the debugger will disconnect in step 10 but vscode will attempt to restart the debugger while the mongo instance is still running.
This results in this message.

Debugging with inspector protocol because a runtime executable is set.
Verbose logs are written to:
/var/folders/0b/zk7t542s1sj_31mwpwyk3cy81gy8z8/T/vscode-node-debug2.txt
/usr/local/bin/npm run debug 
> testapp@ debug /Users/user/meteor/vscode-meteor-test
> meteor run --inspect
[[[[[ ~/meteor/vscode-meteor-test ]]]]]
=> Started proxy.
=> Started MongoDB.
W20171229-09:04:38.595(-5)? (STDERR) Debugger listening on ws://127.0.0.1:9229/4a9b3122-df9c-4215-b40b-9640327bafb6
W20171229-09:04:38.671(-5)? (STDERR) For help see https://nodejs.org/en/docs/inspector
W20171229-09:04:38.673(-5)? (STDERR) Debugger attached.
I20171229-09:04:39.575(-5)? !! Change me !!
=> Started your app.
=> App running at: http://localhost:3000/
=> Server modified -- restarting...
Verbose logs are written to:
/var/folders/0b/zk7t542s1sj_31mwpwyk3cy81gy8z8/T/vscode-node-debug2.txt
MongoError
future.js:313
Verbose logs are written to:
/var/folders/0b/zk7t542s1sj_31mwpwyk3cy81gy8z8/T/vscode-node-debug2.txt

@weinand @roblourens How does this fit into the existing scenarios for restart? Sounds like we shouldn't try to kill the processes in this case.

The restart option is correct assuming it works the same as nodemon. Trying your project, I see the same thing. The debugger simply tries to reattach after Mongo restarts the server, but it fails and Mongo throws that error. The extension never tries to kill any process.

It seems to work if I run it in the terminal instead of the debug console, using "console": "integratedTerminal". Does that work for you?

It seems like when it doesn't work, it's attaching to the Mongo build process, or something, which shouldn't be in debug mode. This is the full exception with stack trace, someone familiar with Mongo might know what it implies

←
From target: {
    "method": "Runtime.exceptionThrown",
    "params": {
        "timestamp": 283232366.054263,
        "exceptionDetails": {
            "exceptionId": 1,
            "text": "Uncaught",
            "lineNumber": 312,
            "columnNumber": 5,
            "url": "/Users/roblou/.meteor/packages/meteor-tool/.1.6.0_1.1sxfuon++os.osx.x86_64+web.browser+web.cordova/mt-os.osx.x86_64/dev_bundle/server-lib/node_modules/fibers/future.js",
            "stackTrace": {
                "callFrames": [{
                    "functionName": "",
                    "scriptId": "81",
                    "url": "/Users/roblou/.meteor/packages/meteor-tool/.1.6.0_1.1sxfuon++os.osx.x86_64+web.browser+web.cordova/mt-os.osx.x86_64/dev_bundle/server-lib/node_modules/fibers/future.js",
                    "lineNumber": 312,
                    "columnNumber": 6
                }, {
                    "functionName": "_combinedTickCallback",
                    "scriptId": "28",
                    "url": "internal/process/next_tick.js",
                    "lineNumber": 130,
                    "columnNumber": 6
                }, {
                    "functionName": "_tickDomainCallback",
                    "scriptId": "28",
                    "url": "internal/process/next_tick.js",
                    "lineNumber": 217,
                    "columnNumber": 8
                }],
                "parent": {
                    "description": "TickObject",
                    "callFrames": [{
                        "functionName": "init",
                        "scriptId": "34",
                        "url": "internal/inspector_async_hook.js",
                        "lineNumber": 18,
                        "columnNumber": 14
                    }, {
                        "functionName": "emitInitNative",
                        "scriptId": "29",
                        "url": "async_hooks.js",
                        "lineNumber": 471,
                        "columnNumber": 42
                    }, {
                        "functionName": "emitInitScript",
                        "scriptId": "29",
                        "url": "async_hooks.js",
                        "lineNumber": 387,
                        "columnNumber": 2
                    }, {
                        "functionName": "nextTick",
                        "scriptId": "28",
                        "url": "internal/process/next_tick.js",
                        "lineNumber": 269,
                        "columnNumber": 6
                    }, {
                        "functionName": "throw",
                        "scriptId": "81",
                        "url": "/Users/roblou/.meteor/packages/meteor-tool/.1.6.0_1.1sxfuon++os.osx.x86_64+web.browser+web.cordova/mt-os.osx.x86_64/dev_bundle/server-lib/node_modules/fibers/future.js",
                        "lineNumber": 311,
                        "columnNumber": 13
                    }, {
                        "functionName": "",
                        "scriptId": "81",
                        "url": "/Users/roblou/.meteor/packages/meteor-tool/.1.6.0_1.1sxfuon++os.osx.x86_64+web.browser+web.cordova/mt-os.osx.x86_64/dev_bundle/server-lib/node_modules/fibers/future.js",
                        "lineNumber": 346,
                        "columnNumber": 14
                    }, {
                        "functionName": "runWithEnvironment",
                        "scriptId": "103",
                        "url": "packages/meteor.js",
                        "lineNumber": 1244,
                        "columnNumber": 8
                    }],
                    "parent": {
                        "description": "TickObject",
                        "callFrames": [{
                            "functionName": "init",
                            "scriptId": "34",
                            "url": "internal/inspector_async_hook.js",
                            "lineNumber": 18,
                            "columnNumber": 14
                        }, {
                            "functionName": "emitInitNative",
                            "scriptId": "29",
                            "url": "async_hooks.js",
                            "lineNumber": 471,
                            "columnNumber": 42
                        }, {
                            "functionName": "emitInitScript",
                            "scriptId": "29",
                            "url": "async_hooks.js",
                            "lineNumber": 387,
                            "columnNumber": 2
                        }, {
                            "functionName": "nextTick",
                            "scriptId": "28",
                            "url": "internal/process/next_tick.js",
                            "lineNumber": 269,
                            "columnNumber": 6
                        }, {
                            "functionName": "",
                            "scriptId": "248",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb/lib/mongo_client.js",
                            "lineNumber": 415,
                            "columnNumber": 21
                        }, {
                            "functionName": "",
                            "scriptId": "248",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb/lib/mongo_client.js",
                            "lineNumber": 391,
                            "columnNumber": 19
                        }, {
                            "functionName": "",
                            "scriptId": "245",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb/lib/db.js",
                            "lineNumber": 235,
                            "columnNumber": 13
                        }, {
                            "functionName": "",
                            "scriptId": "250",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb/lib/server.js",
                            "lineNumber": 264,
                            "columnNumber": 8
                        }, {
                            "functionName": "onceWrapper",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 314,
                            "columnNumber": 29
                        }, {
                            "functionName": "emitOne",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 115,
                            "columnNumber": 12
                        }, {
                            "functionName": "emit",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 210,
                            "columnNumber": 6
                        }, {
                            "functionName": "",
                            "scriptId": "211",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb-core/lib/topologies/server.js",
                            "lineNumber": 335,
                            "columnNumber": 20
                        }, {
                            "functionName": "emitOne",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 115,
                            "columnNumber": 12
                        }, {
                            "functionName": "emit",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 210,
                            "columnNumber": 6
                        }, {
                            "functionName": "",
                            "scriptId": "213",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb-core/lib/connection/pool.js",
                            "lineNumber": 279,
                            "columnNumber": 11
                        }, {
                            "functionName": "onceWrapper",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 316,
                            "columnNumber": 29
                        }, {
                            "functionName": "emitTwo",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 125,
                            "columnNumber": 12
                        }, {
                            "functionName": "emit",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 213,
                            "columnNumber": 6
                        }, {
                            "functionName": "",
                            "scriptId": "199",
                            "url": "/Users/roblou/.meteor/packages/npm-mongo/.2.2.33.86x98c.cbbwu++os+web.browser+web.cordova/npm/node_modules/mongodb-core/lib/connection/connection.js",
                            "lineNumber": 186,
                            "columnNumber": 48
                        }, {
                            "functionName": "onceWrapper",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 314,
                            "columnNumber": 29
                        }, {
                            "functionName": "emitOne",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 115,
                            "columnNumber": 12
                        }, {
                            "functionName": "emit",
                            "scriptId": "18",
                            "url": "events.js",
                            "lineNumber": 210,
                            "columnNumber": 6
                        }, {
                            "functionName": "emitErrorNT",
                            "scriptId": "43",
                            "url": "internal/streams/destroy.js",
                            "lineNumber": 63,
                            "columnNumber": 7
                        }, {
                            "functionName": "_combinedTickCallback",
                            "scriptId": "28",
                            "url": "internal/process/next_tick.js",
                            "lineNumber": 137,
                            "columnNumber": 10
                        }, {
                            "functionName": "_tickDomainCallback",
                            "scriptId": "28",
                            "url": "internal/process/next_tick.js",
                            "lineNumber": 217,
                            "columnNumber": 8
                        }],
                        "parent": {
                            "description": "TickObject",
                            "callFrames": [{
                                "functionName": "init",
                                "scriptId": "34",
                                "url": "internal/inspector_async_hook.js",
                                "lineNumber": 18,
                                "columnNumber": 14
                            }, {
                                "functionName": "emitInitNative",
                                "scriptId": "29",
                                "url": "async_hooks.js",
                                "lineNumber": 471,
                                "columnNumber": 42
                            }, {
                                "functionName": "emitInitScript",
                                "scriptId": "29",
                                "url": "async_hooks.js",
                                "lineNumber": 387,
                                "columnNumber": 2
                            }, {
                                "functionName": "nextTick",
                                "scriptId": "28",
                                "url": "internal/process/next_tick.js",
                                "lineNumber": 269,
                                "columnNumber": 6
                            }, {
                                "functionName": "_destroy",
                                "scriptId": "43",
                                "url": "internal/streams/destroy.js",
                                "lineNumber": 33,
                                "columnNumber": 14
                            }, {
                                "functionName": "Socket._destroy",
                                "scriptId": "38",
                                "url": "net.js",
                                "lineNumber": 560,
                                "columnNumber": 2
                            }, {
                                "functionName": "destroy",
                                "scriptId": "43",
                                "url": "internal/streams/destroy.js",
                                "lineNumber": 31,
                                "columnNumber": 7
                            }, {
                                "functionName": "afterConnect",
                                "scriptId": "38",
                                "url": "net.js",
                                "lineNumber": 1190,
                                "columnNumber": 9
                            }],
                            "parent": {
                                "description": "TCPCONNECTWRAP",
                                "callFrames": [{
                                    "functionName": "init",
                                    "scriptId": "34",
                                    "url": "internal/inspector_async_hook.js",
                                    "lineNumber": 18,
                                    "columnNumber": 14
                                }, {
                                    "functionName": "emitInitNative",
                                    "scriptId": "29",
                                    "url": "async_hooks.js",
                                    "lineNumber": 471,
                                    "columnNumber": 42
                                }, {
                                    "functionName": "internalConnect",
                                    "scriptId": "38",
                                    "url": "net.js",
                                    "lineNumber": 947,
                                    "columnNumber": 25
                                }, {
                                    "functionName": "",
                                    "scriptId": "38",
                                    "url": "net.js",
                                    "lineNumber": 1064,
                                    "columnNumber": 8
                                }, {
                                    "functionName": "_combinedTickCallback",
                                    "scriptId": "28",
                                    "url": "internal/process/next_tick.js",
                                    "lineNumber": 130,
                                    "columnNumber": 6
                                }, {
                                    "functionName": "_tickDomainCallback",
                                    "scriptId": "28",
                                    "url": "internal/process/next_tick.js",
                                    "lineNumber": 217,
                                    "columnNumber": 8
                                }]
                            }
                        }
                    }
                }
            },
            "exception": {
                "type": "object",
                "className": "MongoError",
                "description": "MongoError",
                "objectId": "{\"injectedScriptId\":1,\"id\":1}",
                "preview": {
                    "type": "object",
                    "description": "MongoError",
                    "overflow": false,
                    "properties": [{
                        "name": "name",
                        "type": "string",
                        "value": "MongoError"
                    }, {
                        "name": "message",
                        "type": "string",
                        "value": "failed to connect to server [127.0.0.1:3001] on fi\u2026[MongoError: connect ECONNREFUSED 127.0.0.1:3001]"
                    }, {
                        "name": "stack",
                        "type": "string",
                        "value": "MongoError: failed to connect to server [127.0.0.1\u2026ents.js:315:30)\n    at emitOne (events.js:116:13)"
                    }, {
                        "name": "futureStack",
                        "type": "string",
                        "value": "MongoError: failed to connect to server [127.0.0.1\u2026ents.js:315:30)\n    at emitOne (events.js:116:13)"
                    }]
                }
            },
            "executionContextId": 1
        }
    }
}

I've previously tried "console": "integratedTerminal". While it does seem to handle auto-restart wonderfully , it runs into an issue where the debugger can't stop meteor correctly. It seems to stop the wrong process, and meteor will output the below. the key message is => Exited from signal: SIGKILL

user@computer:vscode-meteor-test$cd /Users/user/meteor/vscode-meteor-test ; /usr/local/bin/npm run debug

> testapp@ debug /Users/user/meteor/vscode-meteor-test
> meteor run --inspect

[[[[[ ~/Code/meteor/vscode-meteor-test ]]]]]

=> Started proxy.
=> Started MongoDB.
W20180102-13:45:16.151(-5)? (STDERR) Debugger listening on ws://127.0.0.1:9229/c4505f61-f3ff-4fb1-9921-0bd11205ad02
W20180102-13:45:16.214(-5)? (STDERR) For help see https://nodejs.org/en/docs/inspector
W20180102-13:45:16.216(-5)? (STDERR) Debugger attached.
I20180102-13:45:17.445(-5)? !! Change me !!
=> Started your app.

=> App running at: http://localhost:3000/
=> Exited from signal: SIGKILL
W20180102-13:45:20.282(-5)? (STDERR) Debugger listening on ws://127.0.0.1:9229/12930645-4501-471d-9318-61b7885f7754
W20180102-13:45:20.282(-5)? (STDERR) For help see https://nodejs.org/en/docs/inspector
I20180102-13:45:20.801(-5)? !! Change me !!
=> Meteor server restarted

It actually can't kill meteor, because it doesn't know the process ID of the meteor parent process. It only knows the process ID of the process it's attached to.

I could understand that, but it still leads to a very confusing ui for some users that were using this.

@roblourens What's the logic when we try to re-attach? First available process, since we attach to the Mongo one? What difference does the integratedTerminal make to the logic?

Right, it attaches to whatever is listening on the port.

I don't see it doing anything different in the integratedTerminal case, so I don't know why that works. It might be a little slower or something.

so is there anything that can done to solve this problem?

The latest VS Code's Auto Attach feature has simply solved this for me. I think the meteor debug recipe should probably mention this. Now I don't use launch for server debugging. I simply run meteor/meteor test with the --inspect flag and vs code auto attaches to the node process. When I change code the process dies and when meteor restarts vs code attaches again automatically.

@mattblackdev nice use of the Auto Attach feature!

/cc @auchenberg

I tried the auto-attach feature, but it seemed messy when using launch as well. I'm going to attempt to use it with a task instead. Thanks @mattblackdev for the idea.

@SteelPhase

I tried the auto-attach feature, but it seemed messy when using launch as well

Are you referring to the Cannot connect to runtime process, timeout after 10000 ms - (reason: Cannot connect to the target: connect ECONNREFUSED 127.0.0.1:9229). popup alert? I'm starting to hate this thing. It happens when the meteor build process fails. I'm not sure why vs code tries to connect to it unless Meteor is starting the build process with the inspect flag too.

@weinand Not sure where else to route this comment, but when auto-attach is being used I don't ever need to "Open launch.json" as the popup suggests. It forces me to use the mouse to click cancel on this popup and this has happened enough for me to write this comment lol. Please let me know if there's a better place to make this comment.

@mattblackdev yes that is one of the annoying things. I would prefer if that went away.

The message "Cannot connect to runtime process, timeout after 10000 ms - (reason: Cannot connect to the target: connect ECONNREFUSED 127.0.0.1:9229)" no longer appears when using Auto Attach.

To the original problem:
If a debug configuration of type "launch" is used, VS Code launches the debuggee and tries to terminate it at the end (with the stop button) or when the session is restarted. However "terminating the debuggee" requires that VS Code knows the process ID of the debuggee. This is only the case if the debuggee was directly launched by VS Code in the debug console. If the debugge was launched in the integrated terminal, the process ID is unknown and VS Code cannot kill the debuggee. This "problem" is sometimes actually quite helpful if the debuggee is not really the debuggee but just an intermediary process like nodemon or meteor

A better approach in this case is to use a debug configuration of type "attach". Here the user is responsible to launch (and later to terminate) the debuggee and the debug config is only used for to attach the debugger. VS Code will not try to kill the debuggee (which is good in the case of nodemon or meteor).

I will convert this issue into a "feature".

Nice! Thanks!

Thanks,
Matthew
On Sep 18, 2018, 4:46 AM -0400, Andre Weinand notifications@github.com, wrote:

The message "Cannot connect to runtime process, timeout after 10000 ms - (reason: Cannot connect to the target: connect ECONNREFUSED 127.0.0.1:9229)" no longer appears when using Auto Attach.
To the original problem:
If a debug configuration of type "launch" is used, VS Code launches the debuggee and tries to terminate it at the end (with the stop button) or when the session is restarted. However "terminating the debuggee" requires that VS Code knows the process ID of the debuggee. This is only the case if the debuggee was directly launched by VS Code in the debug console. If the debugge was launched in the integrated terminal, the process ID is unknown and VS Code cannot kill the debuggee. This "problem" is sometimes actually quite helpful if the debuggee is not really the debuggee but just an intermediary process like nodemon or meteor
A better approach in this case is to use a debug configuration of type "attach". Here the user is responsible to launch (and later to terminate) the debuggee and the debug config is only used for to attach the debugger. VS Code will not try to kill the debuggee (which is good in the case of nodemon or meteor).

You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

As already said by @mattblackdev above, "auto attach" is the way to go. Since this is supported by the new js-debug in even more and better ways, I'll close this issue because this issue refers to the now obsolete node-debug.

Was this page helpful?
0 / 5 - 0 ratings