Request failure logging in middleware cannot be hit

[danpalmer]

From the Django documentation...

https://docs.djangoproject.com/en/2.2/topics/http/middleware/#exception-handling

Exception handling

Django automatically converts exceptions raised by the view or by middleware into an appropriate HTTP response with an error status code. Certain exceptions are converted to 4xx status codes, while an unknown exception is converted to a 500 status code.

This conversion takes place before and after each middleware (you can think of it as the thin film in between each layer of the onion), so that every middleware can always rely on getting some kind of HTTP response back from calling its get_response callable. Middleware don’t need to worry about wrapping their call to get_response in a try/except and handling an exception that might have been raised by a later middleware or the view. Even if the very next middleware in the chain raises an Http404 exception, for example, your middleware won’t see that exception; instead it will get an HttpResponse object with a status_code of 404.

Currently the middleware in this package depends on thrown exceptions to log request failures, but this never happens.

We can reproduce this under runserver and gunicorn. It should be noted that with django-extensions and the runserver_plus command, this doesn't apply and the middleware does work.

The most obvious solution I can think of is to check the status code for an error code and mark request failure from that. This doesn't capture an exception though, and there may be a better way of doing this that will capture the exception.

[jrobichaud]

In case it is not an exception the request will be logged there

django-structlog/django_structlog/middlewares/request.py

Lines 60 to 62 in c91eb00

	logger.info(
	"request_finished", code=response.status_code, request=request
	)

However it is logged as an info which may not be adequate. We may want to log info for 2XX/3XX, warning for 4XX, and error for 5XX, what do you think?

You can create a separate Issue for django-structlog not working when using django commands.

[danpalmer]

@jrobichaud I think there may be a misunderstanding here, I'm not clear exactly what you mean by your response, but currently I don't believe it's possible to hit this condition:

django-structlog/django_structlog/middlewares/request.py

Lines 48 to 58 in c91eb00

	traceback_object = e.__traceback__
	formatted_traceback = traceback.format_tb(traceback_object)
	logger.error(
	"request_failed",
	error_message=str(e),
	error_traceback=formatted_traceback,
	code=500,
	request=request,
	)
	raise

Django catches all exceptions from get_response, so exception handling around that function call will never fire. The correct way to handle exceptions in middleware is to implement a process_exception method on the middleware. Django will then call this if there is an exception.

This is an issue because the request_failed log message contains the exception details, whereas just logging request_finished does not have that context in.

Here's an example of what we've used instead: https://gist.github.com/danpalmer/16cdd5aa2941fa9706a44bb28c54729b

[jrobichaud]

I will investigate this, thank you.

[jrobichaud]

Ok, with DEBUG = True it was actually raising an exception but not with DEBUG = False.

Your implementation works with both cases.

Do you mind if I use the gist you provided to implement it correctly?

[jrobichaud]

@danpalmer can you take a quick look at #20 and tell me if it makes sense to you?

Thank you again for your help, this is really appreciated.