Debug not working

[meelash]

I had been using debugging of individual tests successfully (and gotten addicted to the feature :)) Suddenly, it stopped working. I thought it might be something in my project so to debug debug, I created a new workspace, only installed mocha, reset all settings to defaults, and just have a single test in test/index.js:

it('should debug, for god\'s sake', ()=> {
  console.log('yyooooooooo');
  assert(3 === 3);
  assert(3 === 6);
})

Running the individual test from the explorer or code lens works. Running from the mocha cli works. Running from the VS Code debugger works.

However when I click on Debug in the test explorer or code lens, it opens the debugger panel, shows the little floating menu:

but doesn't apparently do anything. Doesn't stop at breakpoints, doesn't run the test, doesn't log to console.

In the Mocha debug log there are just these lines and no errors:

[2019-11-15 15:17:28.800] [INFO] Debugging test(s) ["/Users/username/tmp/mocha_explorerTest/test/index.js: should debug, for god's sake"] of /Users/username/tmp/mocha_explorerTest
[2019-11-15 15:17:28.800] [INFO] Running test(s) ["/Users/username/tmp/mocha_explorerTest/test/index.js: should debug, for god's sake"] of /Users/username/tmp/mocha_explorerTest
[2019-11-15 15:17:28.801] [INFO] Starting the debug session
[2019-11-15 15:17:28.845] [INFO] Worker finished

Any ideas what this could be? I feel I must have modified some setting somewhere that killed my beloved per-test debugging but can't figure out what it is.

Help!

[hbenl]

Thanks for the detailed description. Unfortunately I couldn't reproduce this. Some suggestions:

• do you have any mochaExplorer or testExplorer configuration in your user settings?
• try with an earlier VS Code release (e.g. this one)

That's all I can think of, after all it used to work and this extension hasn't changed for a while...

[OchirDarmaev]

Hello, @hbenl
I also faced this bug.
It may help to reproduce the bug https://github.com/Cuprumbur/simple-mocha-test-explorer.

[meelash]

So the interesting thing is, I downloaded that version of VS Code that was linked and tried it and it worked. Then I quit and tried my existing one and it also started working. I don't know enough about VS Code to know if there is something that happens on starting up a different version that would fix this...

I thought there might have been some setting that I reset that fixed it but didn't fix until after a restart, but I can't think of any. My settings are completely clear of any custom settings, and all setting in the Settings dialog are reset to defaults.

[meelash]

After the previous comment it again stopped working similarly to the first time. I think the first time it failed it was with this error message:

[2019-11-19 16:50:00.968] [INFO] Configuration changed
[2019-11-19 16:51:31.041] [INFO] Configuration changed
[2019-11-19 16:51:33.957] [INFO] Configuration changed
[2019-11-19 16:51:40.716] [INFO] Configuration changed
[2019-11-19 16:57:32.759] [INFO] Debugging test(s) ["/Users/user/project/test/controllers/EligibilityParsing.test.js: controllers/EligibilityParsing buildTransactionMap(tblElgAnsiFieldsResult) method returns an object"] of /Users/user/project
[2019-11-19 16:57:32.759] [INFO] Running test(s) ["/Users/user/project/test/controllers/EligibilityParsing.test.js: controllers/EligibilityParsing buildTransactionMap(tblElgAnsiFieldsResult) method returns an object"] of /Users/user/project
[2019-11-19 16:57:32.759] [INFO] Starting the debug session
[2019-11-19 16:57:32.928] [INFO] Worker finished
[2019-11-19 16:57:38.622] [ERROR] Failed starting the debug session - aborting [Error: Debug session failed to start within 5 seconds
	at Timeout._onTimeout (/Users/usre/.vscode/extensions/hbenl.vscode-mocha-test-adapter-2.1.2/out/adapter.js:68:32)
	at listOnTimeout (internal/timers.js:531:17)
	at processTimers (internal/timers.js:475:7)]

Then, on subsequent runs it switches to the debug window and then does nothing with these logs:

[2019-11-19 16:58:17.193] [INFO] Debugging test(s) ["/Users/user/project/test/controllers/EligibilityParsing.test.js: controllers/EligibilityParsing buildTransactionMap(tblElgAnsiFieldsResult) method returns an object"] of /Users/user/project
[2019-11-19 16:58:17.194] [INFO] Running test(s) ["/Users/user/project/test/controllers/EligibilityParsing.test.js: controllers/EligibilityParsing buildTransactionMap(tblElgAnsiFieldsResult) method returns an object"] of /Users/user/project
[2019-11-19 16:58:17.194] [INFO] Starting the debug session
[2019-11-19 16:58:17.432] [INFO] Worker finished

Restarting VS Code twice got it working again. I will continue to investigate. @Cuprumbur does the problem go away for you upon restarting VS Code?

[hbenl]

@Cuprumbur thanks a lot for the repo, unfortunately I was not able to reproduce this. I've tried debugging the test dozens of times (on Linux and on Windows version 10.0.18362) and it didn't fail a single time.

@meelash VS Code also has some "hidden" settings, where it stores parts of the editor state (e.g. source files that you have opened, breakpoints you have set, etc.) so that it can restore that state when it is restarted. But I don't think it's related to those either.

I think this is most likely a problem in the latest version of VS Code. When this happens again, please open the VS Code developer tools (Menu item "Help" -> "Toggle Developer Tools" or Ctrl+Shift+I), go to the Console and look for error messages from VS Code appearing while you're trying to debug.

[OchirDarmaev]

Restarting VS Code twice got it working again. I will continue to investigate. @Cuprumbur does the problem go away for you upon restarting VS Code?

@meelash Unfortunately, the problem still exists

[OchirDarmaev]

@hbenl I attached some info.
Would you need more details?

[OchirDarmaev]

@hbenl I have a slow computer.
But when I run debug of test on the fast computer, the bug doesn't reproduce.

[hbenl]

@Cuprumbur Thanks!
So it looks like VS Code takes longer to start a debug session now. I have increased the timeout from 5 to 10 seconds in version 2.1.3, please tell me if that solves the problem for you.

[OchirDarmaev]

@hbenl It still doesn't work properly.
I decided to use just a fast computer.

[hbenl]

@meelash What about you, does version 2.1.3 work better for you?

[meelash]

@hbenl I'm on 2.1.3, but still getting:

[2019-11-23 02:19:03.400] [INFO] Starting the debug session
[2019-11-23 02:19:03.905] [INFO] Worker finished
[2019-11-23 02:19:04.164] [INFO] /Users/user/project/bin/syncElibilityFieldDefinitions was saved - checking if this affects /Users/user/project
[2019-11-23 02:19:04.165] [INFO] Sending autorun event
[2019-11-23 02:19:14.035] [ERROR] Failed starting the debug session - aborting [Error: Debug session failed to start within 5 seconds
	at Timeout._onTimeout (/Users/user/.vscode/extensions/hbenl.vscode-mocha-test-adapter-2.1.3/out/adapter.js:68:32)
	at listOnTimeout (internal/timers.js:531:17)
	at processTimers (internal/timers.js:475:7)]

Of note is that this error only throws in the Mocha Explorer Log the first time. After that, it fails silently which is why I didn't initially know what the error was.

[meelash]

Ah, I see that you did increase the timeout to 10 seconds, just forgot to update the error message. Increasing it to 20 seconds myself to see what happens. Again I have to restart 2 times for some reason for it to reset and start working again...

[hbenl]

VS Code 1.40.2 came out and it fixes this bug, which is probably the cause of this issue: users of other extensions complained about debugging javascript not working and it turns out that sometimes VS Code 1.40 will occupy port 9229, which is the default debugging port for node.js. Quote:

[...] we start the inspect protocol on the extension host process as soon as we detect that the process has become unresponsive.

This would also explain why it happened on a slower computer but not a faster one: only on a slow computer VS Code would think that the extension host process is unresponsive and hence occupy port 9229.

@Cuprumbur @meelash please tell me if it works for you with VS Code 1.40.2.

I will also have a look at why there was no useful error message in the logs and try to fix that.

[hbenl]

In my experiments, the "Mocha Tests" output channel did contain an error message "Starting inspector on [...] failed: address already in use" and I couldn't find an easy way to improve on that.

[meelash]

@hbenl Apologies for the delay, as I wanted to confirm my observations before replying. I can confirm the original issue was fixed by the VS Code update.

I find two scenarios in which the debugger fails- One is if either my test or code did not clean up all in-use handles on a previous test (for example, ftp or database connection is left open) and multiple test processes are open. There is an issue in the mocha project about the test runner not forcibly killing the process when complete; personally, I think that is the correct behavior as it forces you to fix whatever the problem is. However, it might cause some confusion on the part of a new user why the debugger is not starting.

Secondly, if there is an error in before/after/setup/teardown steps, the error is logged in Mocha Explorer Log (Output tab) but not in the Test Explorer log. The "Show Log" code visor also does not display. Maybe this is by design, that actual test failures show in the Test Explorer and failures of the test itself show in the Mocha Explorer Log?

In summary, thanks for your time looking into the original issue, and to whoever fixed it on the VS Code side :)

[hbenl]

@meelash Thanks for the feedback!

There is an issue in the mocha project about the test runner not forcibly killing the process when complete

You could try Mocha's --exit option (put it in a Mocha config file or use the mochaExplorer.exit VS Code setting)

Secondly, if there is an error in before/after/setup/teardown steps, the error is logged in Mocha Explorer Log (Output tab) but not in the Test Explorer log.

Yes, this is by design: the Test Explorer log is used to show the messages from a single test, but the messages from the before/after/setup/teardown steps can't be linked to any test, so they only show up in the "Mocha Tests" output channel (which I introduced specifically to make sure that there is a place where you can find all messages, including those that can't be linked to any test)

[jpangburn]

You could try Mocha's --exit option (put it in a Mocha config file or use the mochaExplorer.exit VS Code setting)

TL;DR This worked for me.

This tool was working great for me (awesome tool btw, thank you) and then it stopped debugging, wouldn't hit breakpoints any more. I noticed that the debug "remote process" kept running after the tests completed, so I tried the disconnect button, but that didn't help. Checked the log and saw stuff about port is already in use, so incremented the port- and it worked for one debug, but not for any debug attempts after that.

For whatever reason (something I changed I assume), something caused the testing process to stop exiting when it finished. Killing the processes from the command line worked, but a hassle. Using the mochaExplorer.exit setting did the job. Debug is working smoothly again!

[Almenon]

Yes, this is by design: the Test Explorer log is used to show the messages from a single test, but the messages from the before/after/setup/teardown steps can't be linked to any test, so they only show up in the "Mocha Tests" output channel (which I introduced specifically to make sure that there is a place where you can find all messages, including those that can't be linked to any test)

I would recommend including before/after/setup/teardown steps in the test explorer log if it's possible, it's confusing to have them in separate places. Having the extension match the behavior of mocha on the terminal makes it more consistent with what the user expects. Thanks for making sure the before/... logs still show up somewhere, though.