When a DisallowedHost exception is raised, the log message contains an exception trace

[Andrew Selby]

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.