open-telemetry / opentelemetry-python

OpenTelemetry Python API and SDK
https://opentelemetry.io
Apache License 2.0
1.67k stars 571 forks source link

Spans do not have the parent child relationship when created using the decorator : @tracer.start_as_current_span() #3832

Closed summahto closed 2 months ago

summahto commented 3 months ago
[tool.poetry.dependencies]
aiohttp = "^3.8"
aiofiles = "^23.2"
azure-cosmos = "^4.3"
azure-identity = "^1.13"
azure-monitor-opentelemetry = "^1.2.0"
azure-purview-catalog = "1.0.0b4"
azure-storage-blob = "12.18.2"
fastapi = "^0"  # TODO Pin minor version before releasing to PROD
fastapi-sessions = "^0"
httpx = "^0"  # TODO Pin minor version before releasing to PROD
opentelemetry-instrumentation = "^0.44b0"
opentelemetry-instrumentation-aiohttp-client = "^0.44b0"
opentelemetry-instrumentation-httpx = "^0.44b0"
opentelemetry-instrumentation-asyncio = "^0.44b0"
opentelemetry-instrumentation-logging = "^0.44b0"
opentelemetry-distro = "^0.44b0"
uvicorn = { extras = ["standard"], version = ">=0.21, <0.22" }

Steps to reproduce

  1. Create a sample FastAPI application and create an endpoint.
  2. Call a function test1() within this endpoint.
  3. Within the function test1() call 2 more functions test2() and test3().
  4. Create spans in the 3 functions using the decorator @tracer.start_as_current_span()

Here is the sample code :

CASE 1:

logger = logging.getLogger(__name__)
logger.setLevel(logger.parent.level)
tracer = trace.get_tracer('doc_generator_api')

configure_azure_monitor(
        connection_string= os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING"),
        logger_name=docgen_logger.name
    )

FastAPIInstrumentor.instrument_app(app)

# This generates test2 and test3 span as child spans within test1 span. which is as expected.
@app.get("/healthcheck")
async def healthcheck():
    """Responses with HTTP status code 200 and empty body"""
    await test1()
    return Response()

async def test1():
    with tracer.start_as_current_span("test1"):
        for i in range(10, 20):
            logger.info(i)
        await test2()
        await test3()

@tracer.start_as_current_span("test2")
async def test2():
    for i in range(20, 30):
        logger.info(i)

@tracer.start_as_current_span("test3")
async def test3():
    for i in range(30, 40):
        logger.info(i)

CASE 2:

# This generates 3 separate spans without any parent child relationship between them
@tracer.start_as_current_span("test1")
async def test1():
    for i in range(10, 20):
        logger.info(i)
    await test2()
    await test3()

@tracer.start_as_current_span("test2")
async def test2():
    for i in range(20, 30):
        logger.info(i)

@tracer.start_as_current_span("test3")
async def test3():
    for i in range(30, 40):
        logger.info(i)

Expected behavior Behavior should be the same in both the CASES 1 and 2. The correct one being the spans seen in CASE 1. Attached the screenshots for the spans as visualized in Application Insights in the following section.

According to Opentelemetry's documentation Create-span-using-decorator :

Creating spans with decorators It’s common to have a single span track the execution of an entire function. In that scenario, there is a decorator you can use to reduce code:

@tracer.start_as_current_span("do_work")
def do_work():
    print("doing some work...")

Use of the decorator is equivalent to creating the span inside do_work() and ending it when do_work() is finished. To use the decorator, you must have a tracer instance available global to your function declaration. Based on this definition of how tracer decorator should create spans, the behavior of CASE1 and CASE2 should be the same.

Screenshots Spans seen in Application Insights CASE1 (which is fine and expected) :

image

Spans seen in Application Insights CASE2 (which is wrong and should be the same as CASE 1 ) :

image

aabmass commented 3 months ago

Can you confirm what opentelemetry-api and opentelemetry-sdk version you are using? The sounds related to https://github.com/open-telemetry/opentelemetry-python/issues/3270 which was just fixed in the latest release by https://github.com/open-telemetry/opentelemetry-python/pull/3633. Can you try with the latest v1.24.0 packages?

summahto commented 3 months ago

Can you confirm what opentelemetry-api and opentelemetry-sdk version you are using?

Following is the versions of above packages :

name = "opentelemetry-api" version = "1.23.0"

name = "opentelemetry-sdk" version = "1.23.0"

Let me try the new version(1.24) and confirm

summahto commented 2 months ago

@aabmass ,

I checked it in the latest version that is (v1.24.0) and it works as expected. I can see the parent child relationship between spans when using the decorator as shown in CASE 2 as well. Thanks for the support.