id	summary	reporter	owner	description	type	status	component	version	severity	resolution	keywords	cc	stage	has_patch	needs_docs	needs_tests	needs_better_patch	easy	ui_ux
33860	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:
{{{
#!python
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

"	Bug	closed	Error reporting	4.0	Normal	duplicate			Unreviewed	0	0	0	0	0	0