When debug level == DEBUG, loading admin page causes a voluminous exception message to be emitted in logging

[Andrew Selby]

1. Follow the standard tutorials to create a basic Django app:

​https://docs.djangoproject.com/en/4.0/intro/tutorial01/
​https://docs.djangoproject.com/en/4.0/intro/tutorial02/

2. Paste in the following logging to settings.py:

   import os
   
   LOGGING = {
       'version': 1,
       'disable_existing_loggers': False,
       'handlers': {
           'console': {
               'class': 'logging.StreamHandler',
           },
       },
       'root': {
           'handlers': ['console'],
           'level': 'DEBUG',
       },
       'loggers': {
           'django': {
               'handlers': ['console'],
               'level': os.getenv('DJANGO_LOG_LEVEL', 'DEBUG'),
               'propagate': False,
           },
       },
   }
   

3. Run the server: python manage.py runserver

4. Visit the admin page in your browser (​http://127.0.0.1:8000/admin/login/)

5. View the console output - two apparent exception traces will be prominent. These are NOT unhandled exceptions, despite appearances!

The problematic logging message is generated in django/template/base.py, at line 930 [class Variable, method _resolve_lookup()].

This logging message is generated when an exception is thrown in parsing html templates, given the app context - if the app context does not contain a 'subtitle' key (which is the case for a plain vanilla Django test app as documented above), an exception gets thrown and then handled internally, but a voluminous logger message is generated, which occupies acres of terminal real estate and appears to contain two separate exception stack traces. The debug level needs to be set to DEBUG for this to occur.

For a stable framework like Django, logging messages from within Django should be kept minimal and relevant to the framework user. This is so that the framework user can add their own logging in creating their service, and only encounter logging messages by Django itself which are likely to be relevant to them as a user of the framework, given the logging level they have specified.

This logging message breaks this principle. I'm developing my own service using Django, and when this message cropped up in my logs it then caused me to look for a bug in my own code, then I created a ticket on my own project to investigate it, and I've now spent two days of professional time investigating this voluminous log message before working out that it's a Django bug. This isn't consistent with Django being 'a framework for professionals with deadlines'!

The problematic commit that added this problematic logging was made in 2015, so this bug affects all current Django releases.

​https://github.com/Selby-Dynamics/django/commit/dc5b01ad05e50ccde688c73c2ed3334a956076b0

The logging code was modified (but not fundamentally changed) in this commit:

​https://github.com/Selby-Dynamics/django/commit/85c52743f7b99ac6575d87080a9ffb7540acbf18

I propose that the fix is to remove all the code corresponding to the 2015 commit.

---

Further work for someone with more experience of Django could be to do the following:

1. Review all logging (do a "grep -rn 'logging.' .") and check that all logging messages are relevant to framework users
2. Check use of 'subtitle' to see if subtitle is still used/required in the framework

[Andrew Selby]

Excerpt from console output showing problematic logging messages

[Mariusz Felisiak]

Logging for template variable resolving is a feature not a bug, you can always change your logging configuration if you want to ignore them, see ​docs.

This specific issue with missing subtitle was partly fixed in 4e5bbb6ef2287126badd32842b239f4a8a7394ca (Django 3.2.9) and completely in 0a4a5e5bacc354df3132d0fcf706839c21afb89d (Django 4.1+).

Duplicate of #32681.

[Andrew Selby]

Replying to Mariusz Felisiak:

Thanks for the quick reply.

I'm perfectly aware that log levels can be used to adjust what log messages I see, the point is that I want to be able to use all levels of logging to develop, debug and test my own code which uses the Django framework. When I'm debugging, I lower the debug level, when it's running smoothly I raise it. This kind of pollution from Django internals impedes my ability to fully use the debug levels when developing my own code.

The logger message that was raised was not something I could take any meaningful action on, or that was likely to be of any use to an informed user. Should logging be used to debug the code using the framework, or to debug the framework itself? Your answer implies that the logging should be used to debug Django itself (ie, for the benefit of the developers), which makes logging a less clean and therefore useful feature for code using the framework. This is a major philosophical mistake. Who is Django intended for - the Django developers, or for the Django users?

An additional problem is, why is an exception trace from an internally handled exception being dumped into the logs? This should just not happen.

It looks like the Django 4.1+ fix ensures that the exception does not get thrown, so I'm hopeful that will avoid the specific problem I had - I see it's due out in a few weeks!

[Mariusz Felisiak]

The logger message that was raised was not something I could take any meaningful action on, or that was likely to be of any use to an informed user.

That's why it was fixed.

Should logging be used to debug the code using the framework, or to debug the framework itself? Your answer implies that the logging should be used to debug Django itself (ie, for the benefit of the developers), which makes logging a less clean and therefore useful feature for code using the framework. This is a major philosophical mistake. Who is Django intended for - the Django developers, or for the Django users?

Removing logging for template variable resolving would be exactly the opposite to what you say. Django users write templates as well as overwrite and customize the templates used by admin.

Your answer implies that the logging should be used to debug Django itself ...

I've never said anything like that.