correlation_id.get got empty in fastapi exception_handler

[liyongzhezz]

I want to use correlation_id.get() to get trace_id in my exception_handler but got empty, is there any wrong?

full code:

import uvicorn

from asgi_correlation_id import CorrelationIdMiddleware, correlation_id
from fastapi import FastAPI, Request, status
from fastapi.responses import JSONResponse

app = FastAPI()

@app.exception_handler(Exception)
async def unicorn_exception_handler(request: Request, exception: Exception):
    trace_id = correlation_id.get() or 'ccc'
    return JSONResponse(
        status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
        content={"code": config.errcode.INSIDE_ERROR, "msg": "error.", "data": [], "trace": trace_id}
    )

app.add_middleware(
    CorrelationIdMiddleware,
    header_name="X-Trace"
)

@app.get("/items")
async def read_item(request: Request):
    trace_id = correlation_id.get()
    print(trace_id)
    raise AttributeError
    return {"item_id": "100", "trace": trace_id}

if __name__ == '__main__':
    uvicorn.run(app='main:app', host="0.0.0.0", port=8000, reload=True)

request:

curl   -XGET  http://<server-ip>:8000/items

response:

Http Code: 500
{"code":99999,"msg":"error.","data":[],"trace":"ccc"}

Thanks

[sondrelg]

When I run

# test.py
import uvicorn

from asgi_correlation_id import CorrelationIdMiddleware, correlation_id
from fastapi import FastAPI, Request, status
from fastapi.responses import JSONResponse

app = FastAPI()

@app.exception_handler(Exception)
async def unicorn_exception_handler(request: Request, exception: Exception):
    trace_id = correlation_id.get() or 'ccc'
    return JSONResponse(
        status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
        content={"code": "123", "msg": "error.", "data": [], "trace": trace_id}
    )

app.add_middleware(
    CorrelationIdMiddleware,
    header_name="X-Trace"
)

@app.get("/items")
async def read_item(request: Request):
    trace_id = correlation_id.get()
    print(trace_id)
    raise AttributeError
    return {"item_id": "100", "trace": trace_id}

if __name__ == '__main__':
    uvicorn.run(app='main:app', host="0.0.0.0", port=8000, reload=True)

with

uvicorn test:app --reload

I get

❯ curl http://127.0.0.1:8000/items
{"code":"123","msg":"error.","data":[],"trace":"74cbadfb0fbb4c24aca1011c019f50df"}%  

:thinking:

[sondrelg]

These are the library versions I'm running locally:

❯ pip show uvicorn starlette fastapi
Name: uvicorn
Version: 0.19.0
Summary: The lightning-fast ASGI server.
Home-page: 
Author: 
Author-email: Tom Christie <tom@tomchristie.com>
License: 
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: click, h11
Required-by: 
---
Name: starlette
Version: 0.19.1
Summary: The little ASGI library that shines.
Home-page: https://github.com/encode/starlette
Author: Tom Christie
Author-email: tom@tomchristie.com
License: BSD
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: anyio
Required-by: asgi-correlation-id, fastapi
---
Name: fastapi
Version: 0.81.0
Summary: FastAPI framework, high performance, easy to learn, fast to code, ready for production
Home-page: https://github.com/tiangolo/fastapi
Author: Sebastián Ramírez
Author-email: tiangolo@gmail.com
License: 
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: pydantic, starlette
Required-by: 

[liyongzhezz]

These are the library versions I'm running locally:

❯ pip show uvicorn starlette fastapi
Name: uvicorn
Version: 0.19.0
Summary: The lightning-fast ASGI server.
Home-page: 
Author: 
Author-email: Tom Christie <tom@tomchristie.com>
License: 
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: click, h11
Required-by: 
---
Name: starlette
Version: 0.19.1
Summary: The little ASGI library that shines.
Home-page: https://github.com/encode/starlette
Author: Tom Christie
Author-email: tom@tomchristie.com
License: BSD
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: anyio
Required-by: asgi-correlation-id, fastapi
---
Name: fastapi
Version: 0.81.0
Summary: FastAPI framework, high performance, easy to learn, fast to code, ready for production
Home-page: https://github.com/tiangolo/fastapi
Author: Sebastián Ramírez
Author-email: tiangolo@gmail.com
License: 
Location: /home/sondrelg/.virtualenvs/asgi-correlation-id/lib/python3.12/site-packages
Requires: pydantic, starlette
Required-by: 

thanks, I use your library versions and restart , it works fine

[waza-ari]

I would like to re-open this issue, because I think something broke with newer FastAPI, Unicorn or Starlette versions. I'm not sure what and in which library has changed, but even the code from the Readme doesn't work anymore:

@app.exception_handler(Exception)
async def unhandled_exception_handler(request: Request, exc: Exception) -> JSONResponse:
    """
    Override the default exception handler to log the exception and return a 500
    Also adds the request ID to the response
    """
    logger.error("An unhandled exception occurred: %s" % str(exc))
    return await http_exception_handler(
        request,
        HTTPException(
            500,
            "Internal server error",
            headers={
                "X-Request-ID": correlation_id.get() or "",
                "Access-Control-Expose-Headers": "X-Request-ID",
            },
        ),
    )

Always returns an empty X-Request-ID header. The ID is displayed when using the logging module in the actual route correctly though.

I'm not sure that's related to versions though. Even when running newest versions,

(asgi-test-py3.10) ➜  asgi-test poetry show | grep -E "fastapi|uvicorn|starlette"                         
fastapi             0.88.0    FastAPI framework, high performance, easy to ...
starlette           0.22.0    The little ASGI library that shines.
uvicorn             0.20.0    The lightning-fast ASGI server.

The example above still works, while it doesn't work in my environment using the very same versions:

poetry show | grep -E "fastapi|uvicorn|starlette"                         
fastapi             0.88.0    FastAPI framework, high performance, easy to ...
starlette           0.22.0    The little ASGI library that shines.
uvicorn             0.20.0    The lightning-fast ASGI server.

[JonasKs]

Can you show your fastapi and starlette versions?

[waza-ari]

I just updated my comment. I'm running a test environment using the latest available versions for fastapi, starlette and unicorn and the minimal example above still works. I'm not sure there is an issue with versions, it does seem to be something different

[waza-ari]

There is another middleware in my code:

@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    """
    Add a X-Process-Time header to responses
    """
    start_time = time.time()
    response = await call_next(request)
    process_time = time.time() - start_time
    response.headers["X-Process-Time"] = str(process_time)
    return response

Once I remove this middleware, everything else is working fine, even with the newest versions. Now there is no real need for this header, but I don't understand how that even influences the behaviour

[JonasKs]

Are you sure that your exception handler is run? If you add a log/print in the exception handler, do you see the output?

[waza-ari]

Sorry I think our answers overlapped. It looks like that removing the other http middleware fixed the issue. I'm not sure why, but that's enough for me, as http middlewares are apparently known for other issues, too.

[mkBGD]

Hi guys, I want to reopen the issue, because the problem indicated seems to be related to fastapis documented way to add a simple middleware. When digging deeper in whats happening when you add a middleware in fastapi like that:

# not working if correlationId middleware is used before an "app.middleware("http")" call
app.add_middleware(CorrelationIdMiddleware)   # not ok

@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    """
    Add a X-Process-Time header to responses
    """
    start_time = time.time()
    response = await call_next(request)
    process_time = time.time() - start_time
    response.headers["X-Process-Time"] = str(process_time)
    return response

# Working when correlationId Middleware is the last one added
app.add_middleware(CorrelationIdMiddleware)  #ok

I guess that due to the way fastapi or starlette (in fact) implements this types of middlewares, that the correlation_id context variable get's cleared or so to say a new context is created by the middleware which behaves like clearing the correlation_id. (see Starlette sources here)

Is this problem solveable in this middleware or only in fastapi?

BR Michi

[sondrelg]

I'm not sure I follow. If the addition of add_process_time_header breaks the response headers, then how can we update this middleware to help that? Perhaps you need to change the way you set headers in your custom middleware?

[mkBGD]

@sondrelg thx for your quick response! No, the problem is not my customization more the implementation of starlette's middleware (see Starlette sources here line 74/75). My guess is that here a new context will be opened so that the correlation id context variable is no longer valid. Therefore the question whether the issue can be solved here at all?

[sondrelg]

I'm no expert on this unfortunately, so think doing your own research is best in this case 👍 Sorry I can't be of more help. If you find a way to solve it here, we're open to PRs of course 🙇

[mkBGD]

Unfortunalty I'm also not an expert on this. My (quick) fix is adding the CorrelationIdMiddleware after all other middlewares (like described above).