Tracing from the grequests module doesn't have the correct context information

[kamalhussain]

Describe your environment
The grequests module is a wrapper around the requests module to parallelize requests. While using this module, the trace of the HTTP requests are not getting associated with the parent context. I tried with 4 parallel requests and all of them have different trace ids.

Steps to reproduce
Please see the following code snippet to reproduce the problem.

import grequests

from opentelemetry import trace
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    ConsoleSpanExporter,
    SimpleSpanProcessor,
)
from opentelemetry.sdk.trace import sampling

tracer_provider = TracerProvider()
tracer_provider.sampler = sampling.ParentBased(sampling.ALWAYS_ON)

trace.set_tracer_provider(tracer_provider)
trace.get_tracer_provider().add_span_processor(
    SimpleSpanProcessor(ConsoleSpanExporter())
)

RequestsInstrumentor().instrument()

urls = [
    'http://www.heroku.com',
    'http://www.facebook.com',
    'http://www.instagram.com',
    'http://www.google.com',
]


def hello():
    tracer = trace.get_tracer(__name__)
    with tracer.start_as_current_span("example-request"):
        rs = (grequests.get(u) for u in urls)
        print(grequests.map(rs))

hello()

What is the expected behavior?
Since requests are created within the parent's context, I expect to see all requests to have the same trace id.

What is the actual behavior?

{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x4b1ec3b31c6450c0be8964c551b44c08",
        "span_id": "0x29c0d897f72a984a",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-06-23T19:21:42.221516Z",
    "end_time": "2021-06-23T19:21:42.485323Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.google.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x69ca27f26d5c8b03f8d55be73cb48fc4",
        "span_id": "0x56115bec426ad4af",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-06-23T19:21:42.219740Z",
    "end_time": "2021-06-23T19:21:43.040657Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.facebook.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x2276dda25bd767a001cd3e1c6c978684",
        "span_id": "0xcc7f68b04b3a6533",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-06-23T19:21:42.220744Z",
    "end_time": "2021-06-23T19:21:43.443545Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.instagram.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x990ec0f55354eedd5fc20d44419d45f9",
        "span_id": "0x048729577c83d30b",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-06-23T19:21:42.205409Z",
    "end_time": "2021-06-23T19:21:43.943165Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.heroku.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
[<Response [200]>, <Response [200]>, <Response [200]>, <Response [200]>]
{
    "name": "example-request",
    "context": {
        "trace_id": "0x8c0e7cfeb2f35ef8ac583f5ca4177b44",
        "span_id": "0x3098a0cd8e7eea49",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2021-06-23T19:21:42.196124Z",
    "end_time": "2021-06-23T19:21:43.946074Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {},
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}

Additional context
Add any other context about the problem here.

[srikanthccv]

I suspect it's the gevent; which works well with thread locals but I don't know it's behaviour contextvars.

[codeboten]

So my understanding is that gevent (at least recent versions of it) do support contextvars by leveraging greenlets, but each greenlet is spawned with an empty context according to the docs:

A new greenlet’s context is initially empty, i.e., all ContextVars have their default values. This matches the behavior of a new thread, but differs from that of a new asyncio.Task, which inherits a copy of the context that was active when it was spawned

Some of the examples do show there's ways to get the context copied into the greenlet, but in the few tests that I ran I was unable to make this work. Will need some more investigation.

[kamalhussain]

@codeboten

I tried with ThreadPoolExecutor but see the same problem.

from opentelemetry import trace
from opentelemetry.instrumentation.requests import RequestsInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import (
    ConsoleSpanExporter,
    SimpleSpanProcessor,
)
from opentelemetry.sdk.trace import sampling

tracer_provider = TracerProvider()
tracer_provider.sampler = sampling.ParentBased(sampling.ALWAYS_ON)

trace.set_tracer_provider(tracer_provider)
trace.get_tracer_provider().add_span_processor(
    SimpleSpanProcessor(ConsoleSpanExporter())
)

RequestsInstrumentor().instrument()

urls = [
    'http://www.heroku.com',
    'http://www.facebook.com',
    'http://www.instagram.com',
    'http://www.google.com',
]

import concurrent.futures
import requests

def get_url(url):
	print(requests.get(url))

def hello():
	tracer = trace.get_tracer(__name__)
	with tracer.start_as_current_span("example-request"):
		with concurrent.futures.ThreadPoolExecutor() as pool:
			pool.map(get_url, urls)
		

hello()

Results:

python3 simple-req-grequests.py
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0x0c15959f35307ba822a99b08b29a8155",
        "span_id": "0x2de455fe4b74b721",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-07-06T15:58:18.836940Z",
    "end_time": "2021-07-06T15:58:19.120136Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.google.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
<Response [200]>
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0xad097925f370cade16dbcfc50b1b5456",
        "span_id": "0x3d0eb44182ea468f",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-07-06T15:58:18.836343Z",
    "end_time": "2021-07-06T15:58:19.439740Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.instagram.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
<Response [200]>
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0xadc164e925db3b74e213ce3cad6c3da1",
        "span_id": "0x30deeefdca704b4e",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-07-06T15:58:18.827078Z",
    "end_time": "2021-07-06T15:58:19.611694Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.heroku.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
<Response [200]>
{
    "name": "HTTP GET",
    "context": {
        "trace_id": "0xf5ada71bdad610a62dbf1d5178df9a7c",
        "span_id": "0xef12c6817ce62e72",
        "trace_state": "[]"
    },
    "kind": "SpanKind.CLIENT",
    "parent_id": null,
    "start_time": "2021-07-06T15:58:18.836636Z",
    "end_time": "2021-07-06T15:58:20.324545Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {
        "http.method": "GET",
        "http.url": "http://www.facebook.com",
        "http.status_code": 200,
        "http.status_text": "OK"
    },
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}
<Response [200]>
{
    "name": "example-request",
    "context": {
        "trace_id": "0x2563cc00750a278404f8fc3040094fc9",
        "span_id": "0x578ff34ec1f24f09",
        "trace_state": "[]"
    },
    "kind": "SpanKind.INTERNAL",
    "parent_id": null,
    "start_time": "2021-07-06T15:58:18.824923Z",
    "end_time": "2021-07-06T15:58:20.327602Z",
    "status": {
        "status_code": "UNSET"
    },
    "attributes": {},
    "events": [],
    "links": [],
    "resource": {
        "telemetry.sdk.language": "python",
        "telemetry.sdk.name": "opentelemetry",
        "telemetry.sdk.version": "1.0.0",
        "service.name": "unknown_service"
    }
}

[github-actions]

This issue was marked stale due to lack of activity. It will be closed in 30 days.

[pdavid31]

Is there any progress to this?

Unfortunately, I am seeing the same problem using

opentelemetry-instrumentation-requests 0.33b0
requests 2.26.0