Opened 4 years ago

Closed 3 years ago

#32552 closed New feature (fixed)

Allow DiscoverRunner to use a logger instead of printing to stdout

Reported by: Chris Jerdonek Owned by: Chris Jerdonek
Component: Testing framework Version: 4.0
Severity: Normal Keywords: DiscoverRunner, print, logging, stdout, stderr
Cc: Triage Stage: Ready for checkin
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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.

Change History (18)

comment:1 by Chris Jerdonek, 4 years ago

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.

comment:2 by Daniyal Abbasi, 4 years ago

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!

comment:3 by Chris Jerdonek, 4 years ago

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.

comment:4 by Daniyal Abbasi, 4 years ago

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?

comment:5 by Chris Jerdonek, 4 years ago

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."

comment:6 by Carlton Gibson, 4 years ago

Triage Stage: UnreviewedAccepted

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!

comment:7 by Daniyal Abbasi, 4 years ago

Sure Carlton! Will be sending a PR soon.

comment:8 by Carlton Gibson, 4 years ago

Needs documentation: set
Needs tests: set
Patch needs improvement: set

comment:9 by Chris Jerdonek, 3 years ago

Has patch: set
Needs documentation: unset
Needs tests: unset
Patch needs improvement: unset

comment:10 by Chris Jerdonek, 3 years ago

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.

Last edited 3 years ago by Chris Jerdonek (previous) (diff)

comment:11 by Chris Jerdonek, 3 years ago

Summary: Change DiscoverRunner to use a logger instead of printAllow DiscoverRunner to use a logger instead of printing to stdout

comment:12 by Mariusz Felisiak, 3 years ago

Triage Stage: AcceptedReady for checkin

comment:13 by Mariusz Felisiak <felisiak.mariusz@…>, 3 years ago

In a0410ffe:

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

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

comment:14 by Mariusz Felisiak, 3 years ago

Has patch: unset
Triage Stage: Ready for checkinAccepted

comment:15 by Chris Jerdonek, 3 years ago

Owner: changed from nobody to Chris Jerdonek
Status: newassigned

comment:17 by Mariusz Felisiak, 3 years ago

Triage Stage: AcceptedReady for checkin

comment:18 by Mariusz Felisiak <felisiak.mariusz@…>, 3 years ago

Resolution: fixed
Status: assignedclosed

In b263f4b6:

Fixed #32552 -- Added logger argument to DiscoverRunner.

Note: See TracTickets for help on using tickets.
Back to Top