Opened 4 months ago

Last modified 3 months ago

#29040 new Cleanup/optimization

test database creation log output doesn't use consistent stream

Reported by: Chris Jerdonek Owned by: nobody
Component: Testing framework Version: master
Severity: Normal Keywords: stdout, stderr, database, creation
Cc: Triage Stage: Accepted
Has patch: no Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

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

Change History (5)

comment:1 Changed 4 months ago by Tim Graham

Triage Stage: UnreviewedAccepted

comment:2 Changed 4 months ago by 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.

comment:3 Changed 4 months ago by 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.

comment:4 Changed 4 months ago by 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.

comment:5 Changed 3 months ago by 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.

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