Django: Prepend OpenTelemetry middleware instead of append

[ebrake]

Description

Prepends Django Instrumentation in the middleware (instead of append) so that middleware methods get instrumented, included as spans of the original request and improving overall latency.

Fixes #659
Fixes #1160

Type of change

• Bug fix (non-breaking change which fixes an issue)

How Has This Been Tested?

Tested on production, mysql queries in the middleware are now included as spans of the trace, instead of new/separate traces, latency is more accurate.

[linux-foundation-easycla]

The committers are authorized under a signed CLA.

• ✅ E Brake (a1086e9)

[ebrake]

Since we have varying opinions about this, should it be made configurable?

[owais]

@ebrake could you link to the discussion with arguments against doing this please or list them here if that's not too much trouble?

I think this should be the default behavior. Unless there are very good reasons to append in some cases, people who really want it to be appended for whatever reason can may be add the middleware manually instead of using the intrumentor, change the order right after instrumenting or sub-class the instrumentor and change the behavior there.

[lzchen]

Can you explain why the bug in #1160 occurs and how this change solves that?

[owais]

@lzchen I think it's because this django tracing middleware is the one responsible for extracting span context from incoming request and start the "local root span" and setting active context. If there is a middleware that executes before this middleware and internally uses another traced library (e.g, mysql) then the spans generated will not be the children of the "local root span" for the incoming HTTP request as the span would not even exist yet. So making the django tracing middleware execute before all other middlewares making the local root span the parent for any spans generated by any other middlewares and eventually by the views.

[lzchen]

@owais
The fix makes sense to me. However, conceptually the other "middleware" that is generating traces via the mysql-instrumentor (in the example) is technically another instrumented application. It's not like the current application (the one that is a django application) is making calls to the "middleware", in which is then doing some mysql calls. The code in the middleware is simply executing. Doesn't this seem like a separate control flow, and in turn, should be a separate trace?

[ebrake]

@owais I read some discussion/arguments here: open-telemetry/opentelemetry-specification#591 - But, django middleware is part of the request/response cycle (invoked on each request, and run through before business logic and the response generated).

This change would align with the specifications of spans mentioned here:

https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/api.md
"For example, if a span represents a request-response cycle (e.g. HTTP or an RPC), the span should have a start time that corresponds to the start time of the first sub-operation, and an end time of when the final sub-operation is complete.
This includes:
receiving the data from the request
parsing of the data (e.g. from a binary or json format)
any middleware or additional processing logic
business logic
construction of the response
sending of the response"

In my case, middleware is a part of the same application, making service calls based on the user's session data, location, etc, to provide additional context to business logic, not instrumenting it gives an incomplete picture of how long the request/response has taken. It's executed as a part of the http operation.

[owais]

The fix makes sense to me. However, conceptually the other "middleware" that is generating traces via the mysql-instrumentor (in the example) is technically another instrumented application. It's not like the current application (the one that is a django application) is making calls to the "middleware", in which is then doing some mysql calls. The code in the middleware is simply executing. Doesn't this seem like a separate control flow, and in turn, should be a separate trace?

I don't it should be a separate trace. We usually want to trace requests end to end and middlewares are on the critical path for all requests. For example, we may have an authentication middleware which makes some calls to redis, mysql or an external authentication service. Those operations should definitely be part of the trace representing the HTTP request handled by Django. If we don't create the local root span as soon as the request is received then all such operations will not be part of the trace.

A django project may contains a number of "applications" but they are just python modules to help organize the codebase and usually a number of different django applications combine and call each other to serve a request. It's no different from micro-services architecture for example, in the sense we may have a number of services but for a single HTTP request, all spans from every single service that did any work to serve a single request should be part of a single trace.

[owais]

In my case, middleware is a part of the same application, making service calls based on the user's session data, location, etc, to provide additional context to business logic, not instrumenting it gives an incomplete picture of how long the request/response has taken. It's executed as a part of the http operation.

@ebrake I agree and I'd argue that would be the case for every single django project. Can you think of a use case where this wouldn't hold true wrt Django?

[owais]

However, conceptually the other "middleware" that is generating traces via the mysql-instrumentor (in the example) is technically another instrumented application. It's not like the current application (the one that is a django application) is making calls to the "middleware", in which is then doing some mysql calls.

I don't think this is true. Probably the term application is causing the confusion here since Django calls it's building blocks applications but conceptually, one Django project is a single application and all middlewares are definitely part of the same django application.

[ebrake]

In my case, middleware is a part of the same application, making service calls based on the user's session data, location, etc, to provide additional context to business logic, not instrumenting it gives an incomplete picture of how long the request/response has taken. It's executed as a part of the http operation.

@ebrake I agree and I'd argue that would be the case for every single django project. Can you think of a use case where this wouldn't hold true wrt Django?

Django middleware is a series of hooks into request/response processing, and a part of the same application. I can't think of anywhere that hasn't held true, in my experience with django development. I have always seen separate "apps" used for models, views, etc. to be more organizable within the same project, or providing additional modules to the application. Agreed, I think the terminology may be confusing!

[lzchen]

We usually want to trace requests end to end and middlewares are on the critical path for all requests.

Oh maybe I misunderstood the behaviour of middlewares. Are they always only executed based off a request made to the django app? If that's the case then I can see how this makes sense to be all in one trace. However, if the middleware simply executes some logic (ex. initialization) and calls a traced service (mysql) without it being related to any request I don't think that should be part of the same trace correct?

[ebrake]

We usually want to trace requests end to end and middlewares are on the critical path for all requests.

Oh maybe I misunderstood the behaviour of middlewares. Are they always only executed based off a request made to the django app? If that's the case then I can see how this makes sense to be all in one trace. However, if the middleware simply executes some logic (ex. initialization) and calls a traced service (mysql) without it being related to any request I don't think that should be part of the same trace correct?

Yep! It executes based on each request. During the request phase, before calling the view, Django applies middleware in the order it’s defined in MIDDLEWARE, top-down.