BaseCommand should use logging instead of custom output wrappers

[Nical]

Since python offers the powerful logging class, django.core.management.base.BaseCommand should use it to output messages instead of using custom output wrappers (django.core.management.base.OutputWrapper).

Doing so, we could override those loggers in the settings.py file.

Instead of having two wrappers in a command and having to do:

class Command(BaseCommand):
  def handle(self):
    self.stdout.write('this is an info message')
    self.stderr.write('this is an error message')

We could do

class Command(BaseCommand):
  def handle(self):
    self.output.info('this is an info message')
    self.output.error('this is an error message')
    # and even
    self.output.warning('this is a warning message')

The style_func and ending arguments that the django.core.management.base.OutputWrapper.write method takes could be removed and be configured at once in a overriding custom logger.

[Claude Paroz]

I worked on that idea in #15107 (that I just closed).

[Berker Peksag]

​https://github.com/django/django/pull/3467

This PR implements an initial integration of logging module in BaseCommand. I've also updated the documentation a bit. If this approach is okay, I'll update all management commands and tests.

[Claude Paroz]

Do we want to keep the old stdout/stderr way of outputting messages in addition to the new API? This would make self.stdout.write/self.info and self.stderr.write/self.error redundants. Or did you intend to deprecate self.stdout/self.stderr?

[Berker Peksag]

Or did you intend to deprecate self.stdout/self.stderr?

Yes, but I couldn't find a simple way to deprecate them yesterday. Today, here is my approach: ​https://github.com/berkerpeksag/django/commit/b439b472842bfd2d04c36b28d079a80fac5814bb

PR updated to address Simon's comments.

[Stephane Poss]

I saw that the pull request was closed on github. Are there any plans to revive this? It would be very nice to be able to configure logging like everywhere else...

[Tim Graham]

Feel free to resume work on the patch if you like.

[John Kang]

Hi all, going to resume work on this patch.

[John Kang]

Hi,

I was working through this ticket when I noticed that some of the command outputs (migrations for example) output a status on the same line. Example would be:
"migrating-xx.. OK"

Python loggers implicitly add new line characters at the end.
Should I leave these log outputs with newlines or is there a better way to append command statuses on the same line?

[Forest Gregg]

Python loggers implicitly add new line characters at the end.
Should I leave these log outputs with newlines or is there a better way to append command statuses on the same line?

As of Python 3.2, you can set the terminator to ​something other than the newline in the StreamHandler. You could use a special handler for logging migrations to keep the current behavior.

[François Freitag]

It seems this ticket stalled. I am interested in seeing that feature in Django, resuming work on it.

[François Freitag]

An update after about 2 months. There is still a good chunk of work left, to clean-up commits, prepare for the transition, update the documentation, etc. but the work is taking shape: all management commands have been updated to use a logger, tests updated accordingly and the test suite passes.

In my draft, there’s a main logger for all commands, django.command, and a logger dedicated to report progress of commands django.progress that uses \r as a terminator. I’m planning on splitting django.command to have a logger per command, e.g. django.command.migrate, all with django.command as their parent. That will facilitate redirecting the output of a particular command while relying on the parent behavior otherwise.

Notable changes:

• CommandError assumed the message was interpolated. A logger_args keyword argument was introduced to pass variable arguments separately (​https://docs.python.org/3.8/howto/logging.html#logging-variable-data).
• Format placeholders are generated for messages where a variable number of arguments is used, in order to pass the variable data separately from the message. For example, a message listing issues in apps was previously logged as "\n".join(variables). To log variable data separately, the message becomes "\n".join(["%s"] * len(variables)).

Left out of scope:
Some commands directly raise the message from an exception they caught as a CommandError.
Ideally, variable data would be separated from the message, so that the logger handles the variable data separately. However, the exceptions are generated by other modules, which do not know how the exception will be used.. In these cases, I’m using the interpolated error message for the CommandError, not logging variable data separately. This can be improved upon at a later stage.

[Mariusz Felisiak <felisiak.mariusz@…>]

In 7ca7f449:

Refs #21429 -- Added SimpleTestCase.assertNoLogs() on Python < 3.10.