2.5 Logging

Two configurations, one after the other

configure_logging is called with two settings, and what it does depends on both.

LOGGING_CONFIG is the dotted path of a function that takes a configuration dictionary. Its default is "logging.config.dictConfig", the standard library’s logging.config.dictConfig. If the setting is empty, configure_logging does nothing at all: Django’s defaults are not applied either, and logging is left as the process found it.

Otherwise it imports that function, then applies Django’s defaults by calling the standard library’s function with DEFAULT_LOGGING, and then, if LOGGING is not empty, calls the function with LOGGING.

The two dictionaries are not merged. They are two separate calls, and the second is whatever the standard library makes of a second configuration. DEFAULT_LOGGING sets "disable_existing_loggers" to false, so that applying it does not disable loggers the process already has. A project’s dictionary that leaves the key out gets the standard library’s default for it, which is true. A logger the first call configured is then disabled unless the project’s dictionary names it or a parent of it. Neither case keeps what the first call set up. A logger the dictionary names has its handlers replaced by the ones the dictionary gives it, and one that is only the child of a named logger is reset: no level, no handlers, and its records passed up.

Because django.setup begins with this call, logging is configured before Apps.populate imports any application, so a record logged while a project’s models are being imported is handled as the project configured. A second call of django.setup configures logging a second time, and makes every handler anew.

What the default configures

DEFAULT_LOGGING configures two loggers and leaves the root logger alone.

Every logger Django writes to has a name beginning with django., so every record climbs to the "django" logger and meets its two handlers, each guarded by a filter that looks at settings.DEBUG. The effect is a switch: with settings.DEBUG on, records go to the console and no mail is sent; with it off, nothing goes to the console and errors are offered to the mail handler. The filters read the setting each time a record passes, not when logging is configured.

"django.server" is the exception. It is the development server’s log of requests. It has a handler of its own with no filter, and it does not pass its records up, so those lines appear whatever the setting is. Its formatter, ServerFormatter, colours each line by the status code the server attached to the record.

This was recorded by logging a record to each of several loggers, first with settings.DEBUG false and then with it true, and noting which handlers had their emit method called.

Where a log record goes: the handlers whose emit is called
    with settings.DEBUG False
      "django.request" ERROR                  -> mail_admins
      "django.request" WARNING                -> no handler
      "django.security.DisallowedHost" ERROR  -> mail_admins
      "django.db.backends" DEBUG              -> no handler
      "django" INFO                           -> no handler
      "django.server" INFO                    -> django.server
      "library" WARNING                       -> Python's handler of last resort
    with settings.DEBUG True
      "django.request" ERROR                  -> console
      "django.request" WARNING                -> console
      "django.security.DisallowedHost" ERROR  -> console
      "django.db.backends" DEBUG              -> no handler
      "django" INFO                           -> console
      "django.server" INFO                    -> django.server
      "library" WARNING                       -> Python's handler of last resort

Three lines of it deserve a second look.

With settings.DEBUG off, a warning on "django.request", which is what a 404 produces, reaches no handler. It is below the level of the mail handler, and the console is filtered out.

A record of the level logging.DEBUG on "django.db.backends", which is what each SQL query produces, reaches no handler in either mode. The "django" logger’s level is logging.INFO, and a record below a logger’s effective level is dropped before any handler sees it. Giving "django.db.backends" a lower level in LOGGING is not enough to see queries on the console, because the "console" handler has a level of its own, also "INFO": the entry has to bring a handler that admits such records as well.

A record on a logger outside the django namespace, here one named "library", gets nothing from Django’s defaults. Django gives the root logger no handler, so the record falls to the standard library’s handler of last resort, which prints warnings and errors to the standard error stream. A project’s own loggers are configured by the project or not at all.

Put together, the defaults come to this. In development, everything Django logs at "INFO" or above appears on the console, and no mail is sent. In production nothing is written anywhere. An error is passed to the handler that mails the administrators, and that handler sends nothing unless ADMINS names someone, which by default it does not. A project that wants a record of what its production servers did has to configure one.

The loggers Django writes to

A connection records queries, and logs them, when settings.DEBUG is true or its force_debug_cursor is set; otherwise its cursors are of a class that does neither.

log_response: a response is logged once

The request path seldom writes to a logger itself. It calls log_response, which hands the message and the response’s status to log_message, then marks the response as logged; for a response that is already marked it returns at once. The mark is what lets two layers both try. When an exception of any kind but Http404 becomes a response, the code that catches it logs the response there, with the exception attached so that the record carries a traceback. Later the request handler, seeing a response with a status of 400 or more come out of the middleware chain, calls log_response again. The first call wins, and the second finds the mark. A 404, and a response that a view simply returned with such a status, are logged by the second call alone.

Not everything goes through it. The ASGI handler answers a request it could not build before the middleware chain is reached, and it logs one such answer with a call of its own and the other not at all (The two entry points).

log_message, which the development server also uses, does the logging. It chooses the level from the status, error for 500 and above and warning for 400 and above, and attaches the request and the status code to the record, where a handler or a formatter can use them. Before it logs, it escapes every string argument so that control characters, a line break among them, are written as escape sequences. A path taken from a request is text an attacker controls, and without this a crafted path could forge lines in a log.

AdminEmailHandler: error email is a log handler

Django has no separate feature for mailing errors to the administrators. With settings.DEBUG off, an uncaught exception in a view becomes a 500 response, the response is logged as an error on "django.request", the record reaches the "mail_admins" handler, and the handler sends the mail.

AdminEmailHandler.emit does nothing when ADMINS is empty, unless a subclass has replaced the method that sends, which it takes as a sign that the mail has somewhere else to go. Otherwise it writes a subject from the record’s level and message, and a body that ends with a traceback and, where the record carries a request, the details of the request. The message goes out through mail_admins.

The traceback is drawn by an exception reporter, the class that also draws the debug page (The debug pages and ExceptionReporter). The handler imports the class named by DEFAULT_EXCEPTION_REPORTER when it is constructed, which is why the recording of django.setup shows that setting being read inside configure_logging: the default configuration has just made the handler.