#33981: When a DisallowedHost exception is raised, the log message contains an
exception trace
-------------------------------------+-------------------------------------
Reporter: Andrew Selby | Owner: (none)
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
-------------------------------------+-------------------------------------
Description changed by Andrew Selby:
Old description:
> 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.
New description:
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
}}}
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 <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
--
You received this message because you are subscribed to the Google Groups
"Django updates" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to django-updates+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/django-updates/010701830cde7c87-78a202bf-f95f-493b-8e18-88ac50da381d-000000%40eu-central-1.amazonses.com.
