Allow DiscoverRunner to use a logger instead of printing to stdout

[Chris Jerdonek]

Currently, the DiscoverRunner class (used when running tests) "logs" by printing directly to stdout. Here is one example:
​https://github.com/django/django/blob/7bdd09d016f418719f2d0297f58bd81c5349101d/django/test/runner.py#L592-L596

It would be much better if DiscoverRunner could instead use a Python logger. The "verbosity" of each print() statement could be converted to a log message at an appropriate level.

Related to this, passing a --verbosity {0,1,2,3} (e.g. when using ​runtests.py) could configure a logger at the appropriate level.

This ticket is related to (but different from) ticket #21429, which is about BaseCommand. While DiscoverRunner can be triggered by the test command, it can also be run separately from a management command, e.g. via runtests.

[Chris Jerdonek]

I'll note that one thing this would help with is when testing DiscoverRunner. Currently, testing some DiscoverRunner methods results in undesired console output. If a logger was used instead of printing, then the test framework could take care of this without any extra work. Using a logger would also make it easier to test that certain messages are being emitted, because the testing framework's logging assertions could be used.

[Daniyal Abbasi]

Is this ticket available? I would like to take up.

I went through the DiscoverRunner class and I found 7 instances where print was used.

I believe a good starting approach would be to classify the print statements on the bases of their logging levels.

105: print("\nOpening PDB: %r" % exc_value) -> DEBUG

142: print("""Subtest failed: ... -> ERROR

172 & 186 : Two print statements in the check_picklable() -> ERROR

594: print('Including test tag(s): %s.' % ', '.join(sorted(self.tags))) -> INFO

596: print('Excluding test tag(s): %s.' % ', '.join(sorted(self.exclude_tags))) -> INFO

681: print('Skipping setup of unused database(s): %s.' % ', '.join(sorted(unused_databases))) -> INFO

Let me know if this is the right way to proceed!

[Chris Jerdonek]

Only the last three are in the DiscoverRunner class. The others have different considerations.

I don't think this ticket is necessarily straightforward. For example, I think the behavior should be opt-in (at least for now) because callers might not have logging enabled. I'm not sure yet what the API should be for opting in though. I'm still thinking about it.

I think a good first step would be to add a log(level, msg) method to the DiscoverRunner class that preserves the existing print() behavior. I.e. the signature of the method would match:
​https://docs.python.org/3/library/logging.html#logging.Logger.log
And then change the class to use that method for its print statements. The method would use the given level and compare to self.verbosity to determine whether the message should be printed.

[Daniyal Abbasi]

Sure. As suggested, we could add a member function, something like this

def log(self, msg, level=2):
  if self.verbosity >= level:
    sys.stderr.write(msg + os.linesep)

Should we stick with print for now or use sys.stderr.write / Logger?

[Chris Jerdonek]

Since this would be a simple refactor with no behavior change, it should be print(). For the level though, I was thinking a logging level since that's where we're headed and that's the API that most people are familiar with. The method can do the conversion from logging level to "verbosity."

[Carlton Gibson]

I think this is a good move, so let's accept the ticket.

I don't think this ticket is necessarily straightforward. For example, I think the behavior should be opt-in (at least for now) because callers might not have logging enabled. I'm not sure yet what the API should be for opting in though. I'm still thinking about it.

Yes... 🤔 And folks have a hard time getting up and running with logging, so we need to be conscious of that. Part of it is good documentation.

Thanks for all the work you're doing in this area Chris, and thanks for wanting to pick this up Daniyal!

[Daniyal Abbasi]

Sure Carlton! Will be sending a PR soon.

[Chris Jerdonek]

By the way, I think the step after Daniyal's PR would be to change DiscoverRunner's constructor to accept an optional Python logger object. Then, DiscoverRunner.log() could use that, if available, and falling back to the current print() behavior if self.logger isn't set.

[Mariusz Felisiak <felisiak.mariusz@…>]

In a0410ffe:

Refs #32552 -- Added DiscoverRunner.log() to allow customization.

Thanks Carlton Gibson, Chris Jerdonek, and David Smith for reviews.

[Chris Jerdonek]

PR: ​https://github.com/django/django/pull/14759

[Mariusz Felisiak <felisiak.mariusz@…>]

In b263f4b6:

Fixed #32552 -- Added logger argument to DiscoverRunner.