open-telemetry / open-telemetry/opentelemetry-python-contrib
Changing order of instrumentation changes the span start timestamp
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 1.1k
- Forks
- 1.1k
- Avg merge
- 4d 15h
- Merged PRs (30d)
- 16
Description
Environment
opentelemetry-api/sdk: 1.7.1
opentelemetry-instrumentation-flask/wsgi/requests: 0.26b1
Steps to reproduce
Setup: A flask app with both wsgi and flask instrumentations enabled.
Flask app used (wsgi instrumentor called first)
# flask_example.py
import flask
import requests
from opentelemetry import trace
from opentelemetry.instrumentation.flask import FlaskInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
BatchSpanProcessor,
ConsoleSpanExporter,
)
from opentelemetry.instrumentation.wsgi import OpenTelemetryMiddleware
app = flask.Flask(__name__)
app.wsgi_app = OpenTelemetryMiddleware(app.wsgi_app)
FlaskInstrumentor().instrument_app(app)
RequestsInstrumentor().instrument()
trace.set_tracer_provider(TracerProvider())
trace.get_tracer_provider().add_span_processor(
BatchSpanProcessor(ConsoleSpanExporter())
)
tracer = trace.get_tracer(__name__)
@app.route("/")
def hello():
import time
time.sleep(0.5)
requests.get("http://www.example.com")
return "hello"
app.run(port=5000)
In the app above two traces are sent one for wsgi and other for flask. Start timestamp of spans of wsgi is later than that of flask spans. If the order of instrumentors called is reversed then the timestamps of the wsgi span comes becomes earlier than flask span.
Output of console span exporter for above app (wsgi instrumentor called first):
# flask trace
{
"name": "HTTP GET",
"context": {
"trace_id": "0x07dd0539c8d59f63779384cccba1a397",
"span_id": "0xde437079bb6f1aef",
"trace_state": "[]"
},
"kind": "SpanKind.CLIENT",
"parent_id": "0xafe8b3bf688693dc",
"start_time": "2021-11-17T14:51:50.981281Z",
"end_time": "2021-11-17T14:51:51.655743Z",
"status": {
"status_code": "UNSET"
},
"attributes": {
"http.method": "GET",
"http.url": "http://www.example.com",
"http.status_code": 200
},
"events": [],
"links": [],
"resource": {
"telemetry.sdk.language": "python",
"telemetry.sdk.name": "opentelemetry",
"telemetry.sdk.version": "1.7.1",
"service.name": "unknown_service"
}
}
{
"name": "/",
"context": {
"trace_id": "0x07dd0539c8d59f63779384cccba1a397",
"span_id": "0xafe8b3bf688693dc",
"trace_state": "[]"
},
"kind": "SpanKind.SERVER",
"parent_id": null,
"start_time": "2021-11-17T14:51:50.473056Z",
"end_time": "2021-11-17T14:51:51.656217Z",
"status": {
"status_code": "UNSET"
},
"attributes": {
"http.method": "GET",
"http.server_name": "127.0.0.1",
"http.scheme": "http",
"net.host.port": 5000,
"http.host": "localhost:5000",
"http.target": "/",
"net.peer.ip": "127.0.0.1",
"http.user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36",
"net.peer.port": 56543,
"http.flavor": "1.1",
"http.route": "/",
"http.status_code": 200
},
"events": [],
"links": [],
"resource": {
"telemetry.sdk.language": "python",
"telemetry.sdk.name": "opentelemetry",
"telemetry.sdk.version": "1.7.1",
"service.name": "unknown_service"
}
}
# wsgi trace
{
"name": "HTTP GET",
"context": {
"trace_id": "0xd6abc91fc7cbce1f0353eed0229d2c4a",
"span_id": "0x5715efd5f9b9d634",
"trace_state": "[]"
},
"kind": "SpanKind.SERVER",
"parent_id": null,
"start_time": "2021-11-17T14:51:50.475583Z",
"end_time": "2021-11-17T14:51:51.657066Z",
"status": {
"status_code": "UNSET"
},
"attributes": {
"http.method": "GET",
"http.server_name": "127.0.0.1",
"http.scheme": "http",
"net.host.port": 5000,
"http.host": "localhost:5000",
"http.target": "/",
"net.peer.ip": "127.0.0.1",
"http.user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36",
"net.peer.port": 56543,
"http.flavor": "1.1",
"http.status_code": 200
},
"events": [],
"links": [],
"resource": {
"telemetry.sdk.language": "python",
"telemetry.sdk.name": "opentelemetry",
"telemetry.sdk.version": "1.7.1",
"service.name": "unknown_service"
}
}
What is the expected behavior?
Order of instrumentors called should not affect span start timestamps.
What is the actual behavior?
Order of instrumentors called is affecting span start timestamps.
Additional context
Found this issue while working on [#446]. Upon marking the flask spans as internal in presence of a server span by wsgi, the start timestamp of flask span(child) comes before wsgi span(parent).
Slack conversation for more details: https://cloud-native.slack.com/archives/C01PD4HUVBL/p1637134298083200
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Reproduce the behavior with flask_example.py, comparing the two instrumentor call orders. Inspect the FlaskInstrumentor and OpenTelemetryMiddleware entry points first; done means span start timestamps no longer depend on instrumentation order, including the parent and child spans described in the issue.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- flask, python
- Domain
- observability-sre
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 40/100