logging output is hard to read in multiprocessing test cases.

[Symmetric]

When running tests using the mutiprocessing module, and printing to stdout/stderr, the output from different subprocesses is interleaved, making it hard to determine what's going on.

For nose2 internal logs, you get something like [DEBUG/Process-N] to disambiguate. But for logs made inside the test, this does not occur.

It looks like the most straightforward fix would be to override the nose2 logger to use the DEFAULT_LOGGING_FORMAT that's specified in multiprocessing/util.py when setting up mp.

[thedrow]

Can you please provide an example output and how the output should really look like in your opinion?

[Symmetric]

Sure. Here's some log output from Nose's startup, helpfully formatted with processName:

[DEBUG/Process-2] Plugins loaded: [<nose2.plugins.loader.testclasses.TestClassLoader object at 0x951e24c>, <nose2.plugins.buffer.OutputBufferPlugin object at 0x951e84c>, <nose2.plugins.loader.parameters.Parameters object at 0x951e20c>, <nose2.plugins.loader.generators.Generators object at 0x9523d4c>, <nose2.plugins.loader.functions.Functions object at 0x9523d0c>, <nose2.plugins.loader.loadtests.LoadTestsLoader object at 0x9523ecc>, <nose2.plugins.loader.discovery.DiscoveryLoader object at 0x9523c8c>, <nose2.plugins.loader.testcases.TestCaseLoader object at 0x952330c>]
[DEBUG/Process-3] Plugins loaded: [<nose2.plugins.loader.testclasses.TestClassLoader object at 0x951e84c>, <nose2.plugins.buffer.OutputBufferPlugin object at 0x951e20c>, <nose2.plugins.loader.parameters.Parameters object at 0x951ee8c>, <nose2.plugins.loader.generators.Generators object at 0x952314c>, <nose2.plugins.loader.functions.Functions object at 0x95234ec>, <nose2.plugins.loader.loadtests.LoadTestsLoader object at 0x9523c8c>, <nose2.plugins.loader.discovery.DiscoveryLoader object at 0x9523f0c>, <nose2.plugins.loader.testcases.TestCaseLoader object at 0x9523e6c>]

And logs in the test use the default nose2 formatter, which is process-agnostic:

INFO:root:Some output from process 1
INFO:root:Some output from process 2

The latter looks like it is using the logger that's hardcoded in PluggableTestProgram.handleCfgArgs. IMO the default logger should at least should be updated to look like the first set of logs when the MP plugin is being used.

Even better, it would be superb if I could configure the log formatter as is possible in nose1; that would actually be a more general and robust solution to this issue, since I could include processName in the formatter that I pass in.