Can't get trace or span ID in ASGI style middleware with FastAPI for request log

[mattupstate]

Summary of problem

Which version of dd-trace-py are you using?

1.14.0

Which version of pip are you using?

N/A

Which libraries and their versions are you using?

python = "^3.10"
fastapi = "^0.96.0"
ddtrace = "^1.14.0"
structlog = "^23.1.0"
uvicorn = "^0.22.0"
asgiref = "^3.7.2"

How can we reproduce your problem?

Take a look at this gist: https://gist.github.com/mattupstate/eee68a5ac531b82e0cf18b45816330c5
What's very unusual is that the trace and span ID are non-zero when adding an arbitrary middleware using FastAPI's app.middleware decorator. I wonder if this is at all related to #4397

What is the result that you get?

Trace and span ID values equal to 0 when using ASGI spec style middleware to produce a request log.

What is the result that you expected?

Trace and span ID values to be non-zero.

[emmettbutler]

Thanks for the issue report, @mattupstate. I spent a little while today going deep on FastAPI and I have some information to share. This isn't conclusive, but I think it's a reasonable hypothesis.

When using only ASGI-style middlewares with add_middleware(), the entire middleware stack is executed at the same time, with control passing through each of the middlewares in sequence before moving on to the next one. You can see an example in this traceback:

In your example code, this means that the span you're trying to get the ID of finishes via Datadog's TraceMiddleware before the await in RequestLoggerMiddleware returns.

It appears to me that using the middleware() decorator causes the middleware stack to be split into separate groups under the hood, as illustrated by these two tracebacks:

In your example, this means that the relative ordering of the await-returns in RequestLoggerMiddleware and TraceMiddleware gets switched relative to the first scenario. Thus, the span has not yet finished by the time RequestLoggerMiddleware tries to read its ID.

It's not clear to me why FastAPI behaves this way. It might be possible to adjust the TraceMiddleware's position in the middleware stack such that it always finishes executing after all of the user middlewares, but I'm not certain. I'll look into that next.

[emmettbutler]

@mattupstate

I noticed during my debugging that moving the logger.info("ASGI spec style") call to happen just before the await self.app(), the span IDs are set correctly in both cases. Is that sufficient as a workaround for you in this case?

[mattupstate]

@emmettbutler hmm, this stemmed from wanting a (mostly) accurate request duration/time log containing the trace ID, so I can't say it would be a sufficient workaround at the moment. The workaround we've used is to register a "no-op" middleware to get the trace ID in the log.

Perhaps there isn't much to do here for ddtrace and we have to live with this. But I figured I'd share since it seemed rather unexpected to me.

[emmettbutler]

@mattupstate That makes sense, thanks for sharing. I agree it's unexpected.

The ddtrace library does not alter when the middleware stack is initalized and how middlewares are applied. All it does is ensure that the ddtrace middleware is always first in the stack. It also adds an additional layer of complexity by finishing the fastapi.request span at different points depending on the response, which is why you're seeing this behavior. We can't easily change this behavior because it's a fix for another issue.

So, until we figure out if and how it's possible to make fixes for both issues coexist, your workaround seems to be the best way forward.