test database creation log output doesn't use consistent stream

[Chris Jerdonek]

While troubleshooting a test issue, I ran into confusing output that I tracked down to ​`base/creation.py` (code shown below) logging its log output to two different streams. This caused messages to display different from their actual order.

Specifically, I was seeing the following message:

Got an error creating the test database: ...

after this message:

Destroying old test database for alias 'default'

when the actual order is the reverse:

sys.stderr.write(
    "Got an error creating the test database: %s\n" % e)
if not autoclobber:
    confirm = input(
        "Type 'yes' if you would like to try deleting the test "
        "database '%s', or 'no' to cancel: " % test_database_name)
if autoclobber or confirm == 'yes':
    try:
        if verbosity >= 1:
            print("Destroying old test database for alias %s..." % (
                self._get_database_display_str(verbosity, test_database_name),
            ))
        cursor.execute('DROP DATABASE %(dbname)s' % test_db_params)
        self._execute_create_test_db(cursor, test_db_params, keepdb)
    except Exception as e:
        sys.stderr.write(
            "Got an error recreating the test database: %s\n" % e)
        sys.exit(2)

I think the correct solution is for this module to be logging all output to stderr (e.g. like Python's default logging behavior) -- reserving stdout for structured / API output. But even just outputting all messages to the same stream would be a big improvement.

I also think it would be a good idea to define a function like log() instead of having print() and sys.stderr.write() occur throughout. That would allow logging code to be controlled more centrally (aka DRY).

[Chris Jerdonek]

Is there any reason not to be using Python's logging module for this (e.g. inheriting Django's logging configuration)? That would also make the messages go to stderr, which is what we want in my opinion.

[Tim Graham]

I guess that would have the similar ​backwards compatibility issues as when we changed runserver to use logging, yes? I don't know, I've always thought of print/stdout/stderr.write as simpler and "more reliable" than logging.

[Chris Jerdonek]

Hmm, I'm never thought of logging as "unreliable." But your point is a good one. Using logging brings lots of advantages though: custom formatting, central configuration, etc. I wonder if there is a way to make Django logging more reliable. Is there one root cause?

Alternatively, I wonder if a helper function or logging tweak could be used to allow toggling sending messages between Python's logging module and straight stderr. Defaulting to the latter would address the backwards compatibility point you cited (and "reliability") and support an easier migration path.

[Tim Graham]

The problem with logging is that we ​document how to disable it (c633667da3605208ea5fc137f5322c599f48da69) so we can't generally rely on it, at least without it being a backwards-incompatible change for users who have done that.

[Claude Paroz]

​PR

[Tim Graham <timograham@…>]

In 65503ca:

Fixed #29040 -- Made test database creation messages use a consistent output stream.