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

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.

[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 ​formatException would likely be the way to go.

[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.

[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.

[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.

[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 ​the ticket triage guidelines for closed tickets. If there is a consensus for re-opening there then we can reopen.

[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.