Stryker: Improve debugging support

[Garethp]

Is your feature request related to a problem? Please describe.
When trying to figure out what's happening in a mutant, I'd like to try and debug the test run

Describe the solution you'd like
I'd like to have the child process that the TestRunners run in have an --inspect or --inspect-brk flag when specified. Here's a few things to consider:

• [ ] Concurrency would be an issue, so we'd need to implement a inspectTestRunner flag that would set concurrency to 1 by default
• [ ] Should we pass in any gc flags that were passed in to the main Stryker process?
• [ ] We'd probably need the instrumentor to emit sourceMaps, so that whatever hooks into the debug mode can place break points at the lines that they expect to see, not knowing what the instrumented code will look like
• [ ] Would it be a good user experience to break for every test for every mutant that hits a specific line of code, if you're only interested in targetting certain mutants?

[nicojs]

Thanks for opening this feature request.

Concurrency would be an issue, so we'd need to implement a inspectTestRunner flag that would set concurrency to 1 by default

Yeah, either force --concurrency 1 or use --inspect-port value of x+offset so that each test runner process has its own unique debug port. I think we should not use the default inspect port of nodejs (9229) because you might want to use that to debug the main process itself. Let's start ports at 9230 instead.

Should we pass in any gc flags that were passed in to the main Stryker process?

What flags are you talking about exactly? I can't find gc in the official documentation.

We'd probably need the instrumentor to emit sourceMaps, so that whatever hooks into the debug mode can place break points at the lines that they expect to see, not knowing what the instrumented code will look like

This is interesting. A couple of hurdles I see:

1. This might make it harder to debug the instrumenter itself.
2. It would also be strange. Take this piece of code for example:
   const foo = 'bar'; debugger;
   When you're debugging on line 2, foo might actually have the value '', because the string mutation on line 1 is active. This would be totally invisible and might be very confusing.
3. It would force code to be "remapped" because most of the time you would use webpack, tsc, or others to build the code after mutating (either with --buildCommand or with your test runner).

If we still want to implement this, I think we should make it its own issue.

Would it be a good user experience to break for every test for every mutant that hits a specific line of code, if you're only interested in targetting certain mutants?

Yeah, targetting specific mutants makes a lot of sense in my opinion. We could also improve our documentation so people know how to debug a specific mutant with their test runner. For example, running __STRYKER_ACTIVE_MUTANT__=42 node --inspect-brk ../../node_modules/mocha/bin/mocha in the sandbox directory allows you to debug mutant 42 with your mocha test runner. I'm pretty sure nobody will figure this out on their own :)

One other thing we might want to consider is to force a no-timeout option of some sort. Otherwise, you're debugging and the worker process is killed. 🤷‍♂️

Putting this all together:

1. Improve our documentation so people know how to debug a specific mutant with their test runner.
2. Support --debug (name pending).
   
   
   
   • Starts each test runner process with --inspect-brk and --inspect-port n+offset where n is 9230 and offset is the test runner count (0, 1, 2 for the first, second, third test runner, etc)
   
   
   • Force timeouts to be disabled.
   
   
3. Don't support source maps at first, let's see how this first.
4. Support --mutant-id-filter (name pending) so you can filter which mutants you want to activate. Let's make this a JSON array of numbers (config file) or a comma-separated list (command line).

I'm also interested in @gramster's opinion, as he is also searching for a better way to debug the test runner process.

[Garethp]

What flags are you talking about exactly? I can't find gc in the official documentation.

I was thinking about --expose-gc specifically, but I'm not sure what other flags there are

For example, running __STRYKER_ACTIVE_MUTANT__=42 node --inspect-brk ../../node_modules/mocha/bin/mocha in the sandbox directory allows you to debug mutant 42 with your mocha test runner. I'm pretty sure nobody will figure this out on their own :)

Would this be reliable in a debug/try something else feedback scenario? If you hit a debug point, change something and try again you can't be sure your mutant id will be the same, can you? Maybe it needs a different ticket, but I think there should be an option to specify the mutant not by the ID, but by what the mutant itself is (Something like index.ts:38:const foo = ''. Or maybe by passing in line and column numbers. That was my first thought for how I was going to implement my plugin)

[nicojs]

If you hit a debug point, change something, and try again you can't be sure your mutant id will be the same

Well, it will be the same as long as you didn't change anything. Maybe you can start with explaining the use case you're trying to support. I was thinking of @gramster's use case where he wants to debug runtime errors when Stryker runs his code.

It is worth noting that running __STRYKER_ACTIVE_MUTANT__=42 node --inspect-brk ../../node_modules/mocha/bin/mocha in your sandbox will not instrument the code again, so mutant id's will stay the same "forever" in that scenario.

[nicojs]

I've been rethinking this approach a little bit. Instead of a new --debug flag with some logic to set --gc, --inspect, etc, why not add a --testRunnerNodeArgs array. The idea is that users can specify whichever node args they want. They will be passed as execArgv option to the test runner worker process.

This would allow you to debug a worker process, as well as add whichever arguments you want.

@Lakitna this would also allow you to add cpu profiling (see #2536).

A user would also be responsible to choose its own --concurrency. I.e. if you use --testRunnerNodeArgs "--inspect-brk"then you should also use --concurrency 1. I personally don't see a use case where you would want to profile the cpu of multiple worker processes at once. What do you think @Lakitna ?

We could add a docs/debugging.md file to explain how debugging works, we can even add some examples for different ideas and code editors.

[Lakitna]

I like the approach of being able to send args to the child processes. When combined with documentation it's a powerful approach. The flexibility this provides might also help in troubleshooting, workarounds, etc. With that in mind, such a thing should probably be both a --cli-arg and a {"configFile": "arg"}.

We should be careful with the naming though. I'm not sure but, I believe that the instrumentation uses the same child process spawner as the test runners? So naming it --testRunnerNodeArgs might be unintentionally misleading unless we make sure that all child processes with these args are all test runner processes. --childProcessNodeArgs might be more correct.

I personally don't see a use case where you would want to profile the CPU of multiple worker processes at once.

I can think of two reasons:

• Debugging interaction between processes, like race conditions. Though I doubt it would be very useful to do it like this.
• Testing performance of a full run.

But that is no problem if you have separate control over the concurrency. This will get pretty complex though, so I agree that we should add some examples and documentation. docs/debugging.md sounds good to me!

Edit: For clarity sake, this might look something like:

Full performance anaylisis of child processes:

stryker run --childProcessNodeArgs="--cpu-prof"

Full performance anaylisis including main process:

node --cpu-prof my/path/to/stryker/@stryker-mutator/core/bin/stryker run --childProcessNodeArgs="--cpu-prof"

Debug a single mutation:

set __STRYKER_ACTIVE_MUTANT__=42 && stryker run --concurrency=1 --testRunnerNodeArgs="--inspect-brk"

Debug the main process:

node --inspect-brk my/path/to/stryker/@stryker-mutator/core/bin/stryker run

[nicojs]

Thanks for your response!

With that in mind, such a thing should probably be both a --cli-arg and a {"configFile": "arg"}.

Agreed.

We should be careful with the naming though. I'm not sure but, I believe that the instrumentation uses the same child process spawner as the test runners?

No, it doesn't. Instrumentation happens in the main process. There are 2 types of worker processes Stryker spawns, namely checkers and test runners. That's why I want to be explicit about it being the --testRunnerNodeArgs. Later we might want to introduce --checkerNodeArgs.

Edit: For clarity sake, [...]

Question about: node --cpu-prof my/path/to/stryker/@stryker-mutator/core/bin/stryker run --childProcessNodeArgs="--cpu-prof", would that work without competing for ports on the host?

[Lakitna]

That's why I want to be explicit about it being the --testRunnerNodeArgs. Later we might want to introduce --checkerNodeArgs.

Makes sense! :)

Question about: node --cpu-prof my/path/to/stryker/@stryker-mutator/core/bin/stryker run --childProcessNodeArgs="--cpu-prof", would that work without competing for ports on the host?

--cpu-prof does not connect to a port like --inspect does. It reports in a file instead. For --inspect I found that only one process will actually show up to connect to, the others will just continue without inspect doing anything. There is no error thrown if --inspect can't connect to the port.

For --cpu-prof there is also --cpu-prof-name={fileName}.cpuprofile. As far as I know, this argument does not support variables. This might make it hard to identify which .cpuprofile file corresponds to which process. A similar issue comes up with --inspect={host}:{port}. Do you think we should add some sort of variable system into this? With variables like {timestamp}, {nthProcess}, etc.

[Garethp]

Would it be worthwhile logging the full set of arguments for the process in a info or something similarly visible by default log inside the child process if --childProcessNodeArgs are defined? Doing so might serve two purposes:

• If it's done inside the child process, the user will see the thread ID, that might be useful for identifying it?
• If I were using something like this where I have to manually type in the args, when I eventually run into trouble the first thing I'd want to double check is that the args are going over properly

[Lakitna]

If it's done inside the child process, the user will see the thread ID, that might be useful for identifying it?

If there is a thread ID logged, I would also expect the output file (--cpu-prof) or port (--inspect) to include that id. This comes back to the variable system thing I mentioned. Though {threadId}/{processId} is a lot better naming compared to my {nthProcess} :)

A quick note that we would have to define our own thread id. Using PID is not possible since it's set after the process is spawned. For the variable thing, we need access to the id before spawn.

On the other hand, we're talking 100ths of log lines here. It's probably better to log the --childProcessNodeArgs once on INFO and per-process on DEBUG.