[Django] #33981: When a DisallowedHost exception is raised, the log message contains an exception trace
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew | Owner: (none)
Selby |
Type: | Status: new
Uncategorized |
Component: Error | Version: 4.1
reporting | Keywords: DisallowedHost
Severity: Normal | HTTP_HOST exception trace
Triage Stage: | Has patch: 0
Unreviewed |
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
-------------------------------------+-------------------------------------
The problem is in django/core/handlers/exception.py, in the following code
inside response_for_exception(...):
{{{
security_logger.error(
str(exc),
exc_info=exc,
extra={"status_code": 400, "request": request},
)
}}}
The line: **exc_info=exc,** is causing an exception trace to be added to
the log, like below:
{{{
2022-09-01 03:35:09,722 INFO [uvicorn.access:437] httptools_impl 11
140632030787392 172.31.11.68:50412 - "GET / HTTP/1.0" 200
web 2022-09-01 03:59:27,719 ERROR [django.security.DisallowedHost:124]
exception 11 140631569585920 Invalid HTTP_HOST header: '54.252.244.208'.
You may need to add '54.252.244.208' to ALLOWED_HOSTS.
Traceback (most recent call last):
File "/opt/venv/lib/python3.8/site-packages/asgiref/sync.py", line 472,
in thread_handler
raise exc_info[1]
File "/opt/venv/lib/python3.8/site-
packages/django/core/handlers/exception.py", line 42, in inner
response = await get_response(request)
File "/opt/venv/lib/python3.8/site-
packages/django/utils/deprecation.py", line 148, in __acall__
response = await sync_to_async(
File "/opt/venv/lib/python3.8/site-packages/asgiref/sync.py", line 435,
in __call__
ret = await asyncio.wait_for(future, timeout=None)
File "/usr/lib/python3.8/asyncio/tasks.py", line 455, in wait_for
return await fut
File "/opt/venv/lib/python3.8/site-
packages/asgiref/current_thread_executor.py", line 22, in run
result = self.fn(*self.args, **self.kwargs)
File "/opt/venv/lib/python3.8/site-packages/asgiref/sync.py", line 476,
in thread_handler
return func(*args, **kwargs)
File "/opt/venv/lib/python3.8/site-
packages/django/middleware/common.py", line 48, in process_request
host = request.get_host()
File "/opt/venv/lib/python3.8/site-packages/django/http/request.py",
line 148, in get_host
raise DisallowedHost(msg)
django.core.exceptions.DisallowedHost: Invalid HTTP_HOST header:
'54.252.244.208'. You may need to add '54.252.244.208' to ALLOWED_HOSTS.
web 2022-09-01 03:59:27,723 WARNING [django.request:241] log 11
140631569585920 Bad Request: /
2022-09-01 03:59:27,723 INFO [uvicorn.access:437] httptools_impl 11
140632030787392 172.31.11.68:59180 - "GET / HTTP/1.0" 400
}}}
The exception traceback bit should not be there in a log message about a
handled exception - it pollutes the logs.
The problem is that removing the line of code in question and then running
the Django unit tests then causes three tests to fail:
* test_suspicious_operation_creates_log_message
* test_suspicious_operation_uses_sublogger
* test_suspicious_email_admins
The first two appear to be failing because of the absence of exc_info in
the exception (refer LoggingAssertionMixin), and the last one appears to
fail because it parses (?) the exception name from the exception
traceback, which is no longer there. So, it looks like the last test fails
because the email reporting of SuspiciousOperation errors has been written
so that they *require* an exception trace to be attached to the log, in
order for the exception name to be parsed out. The exception name can be
parsed by: e.__class__.__name__, but it looks like the tests have been
designed to expect an exception trace, even though this is not
fundamentally required for functionality, and has the side effect of
polluting the logs.
I've had a go at trying to knock this bug out, but got stymied by the need
to refactor a number of existing tests.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
exception trace
-------------------------------------+-------------------------------------
Type: Uncategorized | Status: new
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution:
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Old description:
New description:
It looks like it was introduced in commit
#84e98ba19456a03f355c3f01ba6c70d5f45ee260, as
https://github.com/django/django/pull/13910.
The exception traceback bit should not be there in a log message about a
handled exception, though - it pollutes the logs.
The problem is that removing the line of code in question and then running
the Django unit tests then causes three tests to fail:
* test_suspicious_operation_creates_log_message
* test_suspicious_operation_uses_sublogger
* test_suspicious_email_admins
The first two appear to be failing because of the absence of exc_info in
the exception (refer LoggingAssertionMixin), and the last one appears to
fail because it parses (?) the exception name from the exception
traceback, which is no longer there. So, it looks like the last test fails
because the email reporting of SuspiciousOperation errors has been written
so that they *require* an exception trace to be attached to the log, in
order for the exception name to be parsed out. The exception name can be
parsed by: e.__class__.__name__, but it looks like the tests have been
designed to expect an exception trace, even though this is not
fundamentally required for functionality, and has the side effect of
polluting the logs.
I've had a go at trying to knock this bug out, but got stymied by the need
to refactor a number of existing tests.
--
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:1>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Component: Error reporting | Version: 4.1
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
* status: new => closed
* resolution: => wontfix
Comment:
Hi Andrew, thanks. There was a pretty clear consensus on the PR to accept
this change.
> The other logging calls from response_for_exception() include the
exception, it seems to only have been missed here. This allows better
debugging and filtering of errors.
... as such I'm going to close as `wontfix`.
If the traceback bothers you a custom formatter overriding
[https://docs.python.org/3/library/logging.html#logging.Formatter.formatException
formatException] would likely be the way to go.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:2>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by Andrew Selby):
Hello Carlton,
Well...! I'd already spent today looking at the tests and working out how
to tweak things so that the existing test functionality was maintained,
specifically the exception testing you mention as the motivation for PR
13910, while also removing that exception trace dump from the logs. I
think you'll find that my changes protect the intent of the original PR,
so I've taken the liberty of creating a PR for this ticket. Would you
please review my PR & consider reopening the ticket?
Specific commentary on the motivations for my PR follow:
Putting an exception trace into the logs in order to enable a test to
verify the exception type was a problematic case of the tail wagging the
dog - user functionality was being affected in order to enable a test to
be run. That's a mistake.
There is a strange requirement in LoggingAssertionMixin that exc_info must
be non-zero - this has nothing to do with verifying the exception type,
and is likely only there to ensure that exc_info is there so that the
exception type can be extracted from it.
There is also a limitation in AdminEmailHandler in that it **requires**
exc_info in the exception (done by adding an exception trace to the logs)
in order to provide the exception in the notification message. My fix also
gets around this issue, so that now means that if we **don't** want to
provide an exception trace in the notification email, we have the ability
to not do so. It is still possible to include it by adding an exception
trace to the log - but it's no longer necessary, as we now have another
mechanism available to include the exception type in the notification
email.
I've identified a minimal set of changes that protect the logic of
existing tests, eliminates unnecessary existing requirements and
limitations, and removes the unnecessary exception trace from the logs, so
that should keep everybody happy.
Replying to [comment:2 Carlton Gibson]:
> Hi Andrew, thanks. There was a pretty clear consensus on the PR to
accept this change.
>
> > The other logging calls from response_for_exception() include the
exception, it seems to only have been missed here. This allows better
debugging and filtering of errors.
>
> ... as such I'm going to close as `wontfix`.
>
> If the traceback bothers you a custom formatter overriding
[https://docs.python.org/3/library/logging.html#logging.Formatter.formatException
formatException] would likely be the way to go.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:3>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
* has_patch: 0 => 1
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:4>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by Carlton Gibson):
Given the pre-existing discussion, I see no reason to change. Agreement on
the DevelopersMailingList would be the way forward, but a custom formatter
is the correct solution.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:5>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by Andrew Selby):
Ok, so now I know comments on this ticket are still being read post
closure - this is my first time creating a Django PR, so I'm still
familiarizing myself with the nuances of how the system works. I'll put
all future correspondence on this ticket.
I'm not sure that you understand my proposed change. I've made a change
that **removes** the unnecessary exception trace from the logs, while
**maintaining** the additional exception type testing, so I don't see a
rationale to close the ticket.
Requiring a user to write a custom formatter in order to eliminate an
exception trace dump from the logs is, in my view, a useability mistake.
My PR would be a better solution, since it maintains test functionality
and avoids unnecessary exceptions in the logs.
Would you please reopen the ticket.
Replying to [comment:5 Carlton Gibson]:
> Given the pre-existing discussion, I see no reason to change. Agreement
on the DevelopersMailingList would be the way forward, but a custom
formatter is the correct solution.
>
>
> > I think you'll find that my changes protect the intent of the original
PR, …
>
> I take it that the previous intent was exactly to add the exception
details, so I don't really see this is correct.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:6>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by Carlton Gibson):
Hi Andy.
I think removing the traceback would be a net-negative. I want to see a
traceback when an exception is logged.
I also think that the previous PR was implemented as intended by the
author, and the three reviewers.
Hence triaging as wontfix.
The appropriate route forward if you want the ticket reopened is to post
the DevelopersMailingList as per
[https://docs.djangoproject.com/en/dev/internals/contributing/triaging-
tickets/#closing-tickets the ticket triage guidelines for closed tickets].
If there is a consensus for re-opening there then we can reopen.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:7>
Django
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
Type: Uncategorized | Status: closed
Component: Error reporting | Version: 4.1
Severity: Normal | Resolution: wontfix
Keywords: DisallowedHost | Triage Stage:
HTTP_HOST exception trace | Unreviewed
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Comment (by Andrew Selby):
Thanks Carlton,
Now posting on this ticket again in desperate hopes that we finally end up
with the discussion in one place... sigh!
There are places in the framework where there are exception handlers that
serve as a catch-all for exceptions that haven't been able to be handled
at lower level - tracebacks are needed when logs are written from these
locations as they are so general and it's too late to find a clean way to
handle them all. So then, yes, in those cases a traceback in the logs is
very appropriate.
But for SuspiciousOperation, this is a handled exception, handled cleanly
and specifically. When an exception is handled cleanly and specifically,
the probability that you want a traceback is low. So why would you
generate a traceback for this well handled exception? That just has the
effect of potentially distracting from any other more urgent tracebacks.
So, I'm still arguing for removing this specific traceback as a net-
positive :)
Thanks for advice on appropriate routes forward, much appreciated.
--
Ticket URL: <https://code.djangoproject.com/ticket/33981#comment:8>