Exception handlers bypass middlewares

[winpat]

First Check

• I added a very descriptive title to this issue.
• I used the GitHub search to find a similar issue and didn't find it.
• I searched the FastAPI documentation, with the integrated search.
• I already searched in Google "How to X in FastAPI" and didn't find any information.
• I already read and followed all the tutorial in the docs and didn't find an answer.
• I already checked if it is not related to FastAPI but to Pydantic.
• I already checked if it is not related to FastAPI but to Swagger UI.
• I already checked if it is not related to FastAPI but to ReDoc.

Commit to Help

• I commit to help with one of those options 👆

Example Code

import logging
import sys
import time

import uvicorn
from fastapi import FastAPI, Request
from fastapi.responses import Response

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler(sys.stdout)
handler.setLevel(logging.DEBUG)
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
handler.setFormatter(formatter)
logger.addHandler(handler)

app = FastAPI()


@app.get("/")
def index():
    raise ValueError("Crash.")
    return "Test."


async def log_request(request: Request, call_next):
    try:
        response = await call_next(request)
    except Exception:
        logger.error("Middleware observed exception.")

    logger.info("Returning response.")
    return response


async def log_exception(request: Request, exc: Exception):
    logger.error(f"Encountered exception {exc}.")
    return Response(status_code=503, content="test")


if __name__ == "__main__":
    app.exception_handler(Exception)(log_exception)
    app.middleware("http")(log_request)
    uvicorn.run(app, host="0.0.0.0", port=8000)

Description

I have this use case where I want to log the duration of all requests, this includes requests which crash the route handler function. For this I introduced a request logging middleware. From my observations once a exception handler is triggered, all middlewares are bypassed. So even if the exception handler returns an Response object there is no way to react to it in the middleware.

Is my understanding of this correct? And is this a bug or a feature?

(Based on the answer to do this I will submit an MR which adds this to the Middleware documentation)

Operating System

Linux

Operating System Details

No response

FastAPI Version

0.70.1

Python Version

Python 3.10.0

Additional Context

No response

[jgould22]

When I run your sample code I get the following

ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/home/user/.local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py", line 376, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/home/user/.local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/fastapi/applications.py", line 212, in __call__
    await super().__call__(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/errors.py", line 181, in __call__
    raise exc
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/base.py", line 63, in __call__
    response = await self.dispatch_func(request, call_next)
  File "/home/user/code/test/gh_help/middleware_except/main.py", line 34, in log_request
    return response
UnboundLocalError: local variable 'response' referenced before assignment
2022-04-21 19:58:12,206 - uvicorn.error - ERROR - Exception in ASGI application
Traceback (most recent call last):
  File "/home/user/.local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py", line 376, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/home/user/.local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/fastapi/applications.py", line 212, in __call__
    await super().__call__(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/errors.py", line 181, in __call__
    raise exc
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
  File "/home/user/.local/lib/python3.10/site-packages/starlette/middleware/base.py", line 63, in __call__
    response = await self.dispatch_func(request, call_next)
  File "/home/user/code/test/gh_help/middleware_except/main.py", line 34, in log_request
    return response
UnboundLocalError: local variable 'response' referenced before assignment
2022-04-21 19:58:12,286 - root - INFO - Returning response.

Which you would expect since call_next is throwing the exception response is never set.

If I correct for the error by refactoring your function to

async def log_request(request: Request, call_next):
    response = None
    try:
        response = await call_next(request)
    except Exception:
        logger.error("Middleware observed exception.")
        response =  Response(status_code=200, content="Caught in the middleware")
    logger.info("Returning response.")
    return response

I get the expected 200 with the logged

2022-04-21 20:05:12,086 - uvicorn.error - INFO - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
2022-04-21 20:05:14,417 - root - ERROR - Middleware observed exception.
2022-04-21 20:05:14,418 - root - INFO - Returning response.
INFO:     127.0.0.1:35808 - "GET / HTTP/1.1" 200 OK

This is with FastAPI 0.75.1 so my suggestion to you is to update FastAPI since 0.70.1 uses starlette 16 and there have been a number of fixes related to exception handling between 16 and 17

[winpat]

@jgould22 Thank you very much! After upgrading to FastAPI 0.75.1 it works like I would expect it to.

[glebignatieff]

HI guys! I have a question related to this one: what if I want to log the response body size that is returned from the exception handler? If call_next raises, then there's no way to access response. What should one do in such case?

[angely-dev]

I don't think you can. The exception occurs while building the response object so I doubt there is a way to access its properties. Why do you want to access it anyway? In general, we want to log request parameters (query or body) so that the error, if there is one, can be reproduced.