[Django] #33860: When debug level == DEBUG, loading admin page causes a voluminous exception message to be emitted in logging
Django
message to be emitted in logging
-------------------------------------------+------------------------
Reporter: ultra-andy | Owner: (none)
Type: Bug | Status: new
Component: Error reporting | Version: 4.0
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
-------------------------------------------+------------------------
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
--
Ticket URL: <https://code.djangoproject.com/ticket/33860>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
message to be emitted in logging
Reporter: ultra-andy | Owner: (none)
Type: Bug | Status: new
Component: Error reporting | Version: 4.0
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by ultra-andy):
* Attachment "console_excerpt.txt" added.
Excerpt from console output showing problematic logging messages
Django
message to be emitted in logging
---------------------------------+--------------------------------------
Type: Bug | Status: closed
Component: Error reporting | Version: 4.0
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
---------------------------------+--------------------------------------
* status: new => closed
* resolution: => duplicate
Comment:
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
[https://docs.djangoproject.com/en/stable/topics/logging/ 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/33860#comment:1>
Django
message to be emitted in logging
---------------------------------+--------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Bug | Status: closed
Component: Error reporting | Version: 4.0
Severity: Normal | Resolution: duplicate
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
---------------------------------+--------------------------------------
Comment (by Andrew Selby):
Replying to [comment:1 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!
--
Ticket URL: <https://code.djangoproject.com/ticket/33860#comment:2>
Django
message to be emitted in logging
---------------------------------+--------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Bug | Status: closed
Component: Error reporting | Version: 4.0
Severity: Normal | Resolution: duplicate
Keywords: | Triage Stage: Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
---------------------------------+--------------------------------------
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/33860#comment:3>