Improve console output

[hugo-vrijswijk]

The console output could be clearer. I think we should try to improve it:

• ℹ Configurable log levels (right now debug is always on) Fixed Allow overriding the log level from the config file #49
• 👓 Improve readability with a nicer logging template with a logback.xml. Maybe something similar to Stryker. Personally, I think the long package names are quite ugly and don't add much (who has duplicate class names in different packages anyway?). Fixed with Add a more compact logback.xml than the default one #54
• 🌈 Colorize some output! (like mutations, log levels, files, etc). Fansi seems like a good candidate. Ideally, we'd also only output color codes if stdout supports it (so not when outputting to a file, just text terminal etc)
• 📊 Progress bar while running. Also similar to what Stryker has
• ⌚ ETA until mutation run is finished

More ideas are welcome!

[legopiraat]

When calculating the ETA we need to keep in mind that the first run will always be slower by a lot.

The reason for is the first time compilation the Scala compiler has to do. If we want a more accurate ETA we should base it on the second test run.

[cbrunnkvist]

In my experience, the most frustrating thing is not the lack of a somewhat accurate ETA (#267), but rather the absence of any progress report. At the current state and default level, I sometimes end up staring at:`

[info] Creating 4 test-runners
[info] Starting initial test run...

...for about an hour, with no clue whatsoever as to whether something is hanging or there is some error I should know of or where if there is one specific test / mutant that is responsible the majority of the test-time. Just some "$n/$total" would already be quite an improvement, the name of the test classes running, by each runner, would be just bonus...

[cbrunnkvist]

(On a related note: the next logLevel up from Info is obviously Debug, but that one is currently almost too "debuggy" - I think I remember that it is due to SBT's Level-enum deciding for all of us that "Trace" is a superfluous level, so I don't think there is any way to improve on logLevel side...)

[hugo-vrijswijk]

@cbrunnkvist is there any logging in debug that you think is too debuggy? We can maybe remove some statements if they don't add much

[cbrunnkvist]

@hugo-vrijswijk I'm sure we can figure out some pragmatic compromise: like, if we have a flag to leave temporary files / mutation directories around, that flag could also be the one which enables printing "copying XXX into YYY" for example.

But when I look at different project's output at Debug level, what seems to make up a lot of the spamminess seems to actually be DEBUG level output from the app being tested, via the test-runners:

(...thousands of lines...)
[debug] testrunner 13338: 2021-08-17 12:29:05 [ab-product] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient - [exchange: 1574] Connection allocated: CPoolProxy{http-outgoing-29 [ACTIVE]}
(...thousands of lines...)

When we we logLevel in stryker, we seem to be getting everything that the app sends to its (slf4j-) log facility. But maybe not always, only for some projects, maybe it has to do with the logback-test.xml not being applied? I'm not sure what's going on here, but it feels like we should have a clear way to distinguish "I want to stryker4s debug" and "I want to stryker4s debug AND all app debug log".

[hugo-vrijswijk]

@cbrunnkvist All testrunner stdout is now sent to debug. Which is very useful for debugging issues with testrunners, but I agree it can be a bit spammy. I'd be all for some more specific debug log configuration. There could be scope settings for testrunner output, file writing, and maybe other things where debug information might be useful, but is usually too much when you want debug logs to find a more common error.

[hugo-vrijswijk]

Test-runner stdout is now by default no longer in debug and configurable. Colored output is in #1070. For any other improvements, new issues can be made