open-telemetry / open-telemetry/opentelemetry-python-contrib

FlaskInstrumentor - Span created too late in the request lifecycle - open_session traces have no parent

Open
#1,397 1 comment 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
Python
Stars
1.1k
Forks
1.1k
Avg merge
4d 15h
Merged PRs (30d)
16

Description

Describe your environment
Docker Environment

Python Version: Python 3.10.8

Pip Freeze:

async-timeout==4.0.2
click==8.1.3
Deprecated==1.2.13
Flask==2.2.2
itsdangerous==2.1.2
Jinja2==3.1.2
MarkupSafe==2.1.1
opentelemetry-api==1.13.0
opentelemetry-instrumentation==0.34b0
opentelemetry-instrumentation-flask==0.34b0
opentelemetry-instrumentation-redis==0.34b0
opentelemetry-instrumentation-wsgi==0.34b0
opentelemetry-sdk==1.13.0
opentelemetry-semantic-conventions==0.34b0
opentelemetry-util-http==0.34b0
packaging==21.3
pyparsing==3.0.9
redis==4.3.4
typing_extensions==4.4.0
Werkzeug==2.2.2
wrapt==1.14.1

Steps to reproduce

  1. Create 3 files in an empty directory:

app.py:

from flask import Flask
from flask.sessions import SessionInterface

from redis import StrictRedis

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.instrumentation.flask import FlaskInstrumentor
from opentelemetry.instrumentation.redis import RedisInstrumentor

class TestSessionInterface(SessionInterface):
    def open_session(self, app, request):
        StrictRedis(host='redis').get('test')

app = Flask(__name__)

app.session_interface = TestSessionInterface()

provider = TracerProvider()
processor = BatchSpanProcessor(ConsoleSpanExporter())
provider.add_span_processor(processor)
trace.set_tracer_provider(provider)

FlaskInstrumentor().instrument_app(app)
RedisInstrumentor().instrument()


@app.route('/')
def test():
    return 'test'

if __name__ == "__main__":
    app.run(host='0.0.0.0', port=80)

Dockerfile:

FROM python:3.10 

RUN pip install redis \
    flask \
    opentelemetry-sdk \
    opentelemetry-api \
    opentelemetry-instrumentation-flask \
    opentelemetry-instrumentation-redis

ADD app.py /app.py

EXPOSE 80

CMD ["python", "/app.py"]

docker-compose.yaml:

version: '3.7'

services:
    flask:
        build: .
        ports:
            - "8080:80"
    redis: 
      image: redis

  1. With a running docker daemon run docker compose up and wait for output to stablize

  2. run curl localhost:8080 from another terminal and observe logs, specifically the traces output by the console span exporter

What is the expected behavior?
Redis traces should have a parent_id of the request

What is the actual behavior?
Redis traces do not have a parent_id. Example output:

demo_issue-flask-1  | 172.18.0.1 - - [21/Oct/2022 19:24:11] "GET / HTTP/1.1" 200 -
demo_issue-flask-1  | {
demo_issue-flask-1  |     "name": "GET",
demo_issue-flask-1  |     "context": {
demo_issue-flask-1  |         "trace_id": "0x1f414dbcd0dea89ecabf34cc48a8dc25",
demo_issue-flask-1  |         "span_id": "0xc0142b0f7a3221ba",
demo_issue-flask-1  |         "trace_state": "[]"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "kind": "SpanKind.CLIENT",
demo_issue-flask-1  |     "parent_id": null,
demo_issue-flask-1  |     "start_time": "2022-10-21T19:24:11.592007Z",
demo_issue-flask-1  |     "end_time": "2022-10-21T19:24:11.592800Z",
demo_issue-flask-1  |     "status": {
demo_issue-flask-1  |         "status_code": "UNSET"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "attributes": {
demo_issue-flask-1  |         "db.statement": "GET test",
demo_issue-flask-1  |         "db.system": "redis",
demo_issue-flask-1  |         "db.name": 0,
demo_issue-flask-1  |         "db.redis.database_index": 0,
demo_issue-flask-1  |         "net.peer.name": "redis",
demo_issue-flask-1  |         "net.peer.port": 6379,
demo_issue-flask-1  |         "net.transport": "ip_tcp",
demo_issue-flask-1  |         "db.redis.args_length": 2
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "events": [],
demo_issue-flask-1  |     "links": [],
demo_issue-flask-1  |     "resource": {
demo_issue-flask-1  |         "attributes": {
demo_issue-flask-1  |             "telemetry.sdk.language": "python",
demo_issue-flask-1  |             "telemetry.sdk.name": "opentelemetry",
demo_issue-flask-1  |             "telemetry.sdk.version": "1.13.0",
demo_issue-flask-1  |             "service.name": "unknown_service"
demo_issue-flask-1  |         },
demo_issue-flask-1  |         "schema_url": ""
demo_issue-flask-1  |     }
demo_issue-flask-1  | }
demo_issue-flask-1  | {
demo_issue-flask-1  |     "name": "/",
demo_issue-flask-1  |     "context": {
demo_issue-flask-1  |         "trace_id": "0x6b5a20549e430074b6e2c5a1073dd30e",
demo_issue-flask-1  |         "span_id": "0xfe2e7effef079c63",
demo_issue-flask-1  |         "trace_state": "[]"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "kind": "SpanKind.SERVER",
demo_issue-flask-1  |     "parent_id": null,
demo_issue-flask-1  |     "start_time": "2022-10-21T19:24:11.591681Z",
demo_issue-flask-1  |     "end_time": "2022-10-21T19:24:11.594252Z",
demo_issue-flask-1  |     "status": {
demo_issue-flask-1  |         "status_code": "UNSET"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "attributes": {
demo_issue-flask-1  |         "http.method": "GET",
demo_issue-flask-1  |         "http.server_name": "0.0.0.0",
demo_issue-flask-1  |         "http.scheme": "http",
demo_issue-flask-1  |         "net.host.port": 80,
demo_issue-flask-1  |         "http.host": "localhost:8080",
demo_issue-flask-1  |         "http.target": "/",
demo_issue-flask-1  |         "net.peer.ip": "172.18.0.1",
demo_issue-flask-1  |         "http.user_agent": "curl/7.64.1",
demo_issue-flask-1  |         "net.peer.port": 57460,
demo_issue-flask-1  |         "http.flavor": "1.1",
demo_issue-flask-1  |         "http.route": "/",
demo_issue-flask-1  |         "http.status_code": 200
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "events": [],
demo_issue-flask-1  |     "links": [],
demo_issue-flask-1  |     "resource": {
demo_issue-flask-1  |         "attributes": {
demo_issue-flask-1  |             "telemetry.sdk.language": "python",
demo_issue-flask-1  |             "telemetry.sdk.name": "opentelemetry",
demo_issue-flask-1  |             "telemetry.sdk.version": "1.13.0",
demo_issue-flask-1  |             "service.name": "unknown_service"
demo_issue-flask-1  |         },
demo_issue-flask-1  |         "schema_url": ""
demo_issue-flask-1  |     }
demo_issue-flask-1  | }
demo_issue-flask-1  | 172.18.0.1 - - [21/Oct/2022 19:24:15] "GET / HTTP/1.1" 200 -
demo_issue-flask-1  | {
demo_issue-flask-1  |     "name": "GET",
demo_issue-flask-1  |     "context": {
demo_issue-flask-1  |         "trace_id": "0x10dea420d604470876b28b2ad0b27974",
demo_issue-flask-1  |         "span_id": "0x0cfa22a18b790c37",
demo_issue-flask-1  |         "trace_state": "[]"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "kind": "SpanKind.CLIENT",
demo_issue-flask-1  |     "parent_id": null,
demo_issue-flask-1  |     "start_time": "2022-10-21T19:24:15.257892Z",
demo_issue-flask-1  |     "end_time": "2022-10-21T19:24:15.258978Z",
demo_issue-flask-1  |     "status": {
demo_issue-flask-1  |         "status_code": "UNSET"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "attributes": {
demo_issue-flask-1  |         "db.statement": "GET test",
demo_issue-flask-1  |         "db.system": "redis",
demo_issue-flask-1  |         "db.name": 0,
demo_issue-flask-1  |         "db.redis.database_index": 0,
demo_issue-flask-1  |         "net.peer.name": "redis",
demo_issue-flask-1  |         "net.peer.port": 6379,
demo_issue-flask-1  |         "net.transport": "ip_tcp",
demo_issue-flask-1  |         "db.redis.args_length": 2
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "events": [],
demo_issue-flask-1  |     "links": [],
demo_issue-flask-1  |     "resource": {
demo_issue-flask-1  |         "attributes": {
demo_issue-flask-1  |             "telemetry.sdk.language": "python",
demo_issue-flask-1  |             "telemetry.sdk.name": "opentelemetry",
demo_issue-flask-1  |             "telemetry.sdk.version": "1.13.0",
demo_issue-flask-1  |             "service.name": "unknown_service"
demo_issue-flask-1  |         },
demo_issue-flask-1  |         "schema_url": ""
demo_issue-flask-1  |     }
demo_issue-flask-1  | }
demo_issue-flask-1  | {
demo_issue-flask-1  |     "name": "/",
demo_issue-flask-1  |     "context": {
demo_issue-flask-1  |         "trace_id": "0x89a019e1e6ee9b61c7decd51e121de95",
demo_issue-flask-1  |         "span_id": "0xf66862762c0f7528",
demo_issue-flask-1  |         "trace_state": "[]"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "kind": "SpanKind.SERVER",
demo_issue-flask-1  |     "parent_id": null,
demo_issue-flask-1  |     "start_time": "2022-10-21T19:24:15.257550Z",
demo_issue-flask-1  |     "end_time": "2022-10-21T19:24:15.259765Z",
demo_issue-flask-1  |     "status": {
demo_issue-flask-1  |         "status_code": "UNSET"
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "attributes": {
demo_issue-flask-1  |         "http.method": "GET",
demo_issue-flask-1  |         "http.server_name": "0.0.0.0",
demo_issue-flask-1  |         "http.scheme": "http",
demo_issue-flask-1  |         "net.host.port": 80,
demo_issue-flask-1  |         "http.host": "localhost:8080",
demo_issue-flask-1  |         "http.target": "/",
demo_issue-flask-1  |         "net.peer.ip": "172.18.0.1",
demo_issue-flask-1  |         "http.user_agent": "curl/7.64.1",
demo_issue-flask-1  |         "net.peer.port": 57462,
demo_issue-flask-1  |         "http.flavor": "1.1",
demo_issue-flask-1  |         "http.route": "/",
demo_issue-flask-1  |         "http.status_code": 200
demo_issue-flask-1  |     },
demo_issue-flask-1  |     "events": [],
demo_issue-flask-1  |     "links": [],
demo_issue-flask-1  |     "resource": {
demo_issue-flask-1  |         "attributes": {
demo_issue-flask-1  |             "telemetry.sdk.language": "python",
demo_issue-flask-1  |             "telemetry.sdk.name": "opentelemetry",
demo_issue-flask-1  |             "telemetry.sdk.version": "1.13.0",
demo_issue-flask-1  |             "service.name": "unknown_service"
demo_issue-flask-1  |         },
demo_issue-flask-1  |         "schema_url": ""
demo_issue-flask-1  |     }
demo_issue-flask-1  | }

Additional context
It appears that the tracing is implemented by wrapping flask's before_request function, however it appears that flask calls open_session on the session_interface before it calls before_request causing it to get missed and not have a parent trace. Given how common using redis for distributed sessions is, it seems fairly important that this span would be properly attributed to the request, and that an earlier hook for instrumentation is needed.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Reproduce the issue with app.py, Dockerfile, and docker-compose.yaml by running docker compose up and curling the Flask service. Inspect FlaskInstrumentor's before_request instrumentation alongside Flask's SessionInterface.open_session lifecycle. Done means Redis spans created during open_session have the request span as their parent.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker, docker-compose, flask, python, redis
Domain
backend, observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.