DD_TRACE_METHODS does not fully wrap async functions

[chiewwy]

Summary of problem

When using DD_TRACE_METHODS with async functions, only the coroutine creation gets wrapped in a span but not the await call. This results in a very short span for the coroutine and also doesn't allow child spans to nest correctly in the resulting flame graph.

Which version of dd-trace-py are you using?

2.12.2

Which version of pip are you using?

23.3.2

Which libraries and their versions are you using?

`pip freeze`

build==1.2.1 bytecode==0.15.1 CacheControl==0.14.0 certifi==2024.2.2 cffi==1.16.0 charset-normalizer==3.3.2 cleo==2.1.0 crashtest==0.4.1 cryptography==42.0.7 ddtrace==2.12.2 Deprecated==1.2.14 distlib==0.3.8 dulwich==0.21.7 envier==0.5.2 exceptiongroup==1.2.2 fastjsonschema==2.19.1 filelock==3.14.0 idna==3.7 importlib_metadata==8.4.0 iniconfig==2.0.0 installer==0.7.0 jaraco.classes==3.4.0 jeepney==0.8.0 keyring==24.3.1 more-itertools==10.2.0 msgpack==1.0.8 opentelemetry-api==1.27.0 packaging==24.1 pexpect==4.9.0 pkginfo==1.10.0 platformdirs==4.2.2 pluggy==1.5.0 poetry==1.8.1 poetry-core==1.9.0 poetry-plugin-export==1.8.0 protobuf==5.28.2 ptyprocess==0.7.0 pycparser==2.22 pyproject_hooks==1.1.0 pytest==8.3.3 rapidfuzz==3.9.1 requests==2.32.1 requests-toolbelt==1.0.0 SecretStorage==3.3.3 shellingham==1.5.4 tomli==2.0.1 tomlkit==0.12.5 trove-classifiers==2024.5.17 typing_extensions==4.12.2 urllib3==2.2.1 virtualenv==20.26.2 wrapt==1.16.0 xmltodict==0.13.0 zipp==3.20.2

How can we reproduce your problem?

Put this code in src/foo.py and use ddtrace-run with DD_TRACE_METHODS=src.foo:bar, then call both bar() and baz().

import asyncio
import logging
from ddtrace import tracer

logger = logging.getLogger(__name__)


async def bar():
    logger.info("bar() start")
    await asyncio.sleep(2)
    logger.info("bar() end")


@tracer.wrap()
async def baz():
    logger.info("baz() start")
    await asyncio.sleep(2)
    logger.info("baz() end")

More details on docker compose setup

docker-compose.yml:

services:
  app:
    environment:
      - DD_TRACE_ENABLED=true
      - DD_TRACE_DEBUG=true
      - DD_TRACE_METHODS=src.foo:bar
    build:
      context: .

Dockerfile:

FROM python:3.10.9

WORKDIR /app

RUN pip install "poetry==1.8.1"

COPY pyproject.toml poetry.lock ./
RUN poetry config virtualenvs.create false && poetry install

COPY src ./src

CMD ["ddtrace-run", "python", "-m", "src.main"]

src/main.py:

import asyncio
import logging

from src.foo import bar, baz


logger = logging.getLogger(__name__)


async def main() -> None:
    logging.basicConfig(level=logging.INFO)
    logging.getLogger("ddtrace").setLevel(logging.DEBUG)

    logger.info("Running bar...")
    await bar()
    logger.info("Done")

    logger.info("Running baz...")
    await baz()
    logger.info("Done")


if __name__ == "__main__":
    asyncio.run(main())

What is the result that you get?

The output shows that a span is created but finishes before bar() start is logged.

Using docker compose log app | grep -E 'INFO|DEBUG:ddtrace._trace.tracer' to extract relevant lines:

app-1  | INFO:__main__:Running bar...
app-1  | DEBUG:ddtrace._trace.tracer:finishing span name='trace.annotation' id=8885613181476808800 trace_id=136833452400278591126657067328970768192 parent_id=None service=None resource='bar' type=None start=1727080978.1589851 end=1727080978.159019 duration=3.3917e-05 error=0 tags={'_dd.p.dm': '-0', '_dd.p.tid': '66f12a1200000000', 'component': 'trace', 'language': 'python', 'runtime-id': '6d8cd0ba5492470ea5f51817b3c7f91a'} metrics={'_dd.top_level': 1, '_dd.tracer_kr': 0.0, '_sampling_priority_v1': 1, 'process_id': 1} links='' events='' (enabled:True)
app-1  | INFO:src.foo:bar() start
app-1  | INFO:src.foo:bar() end
app-1  | INFO:__main__:Done

This behavior is also observed even if bar is not awaited.

app-1  | INFO:__main__:Calling bar without await...
app-1  | DEBUG:ddtrace._trace.tracer:finishing span name='trace.annotation' id=2746159863322698467 trace_id=136833452717191241185050188834873199747 parent_id=None service=None resource='bar' type=None start=1727080982.1749313 end=1727080982.1749756 duration=4.4416e-05 error=0 tags={'_dd.p.dm': '-0', '_dd.p.tid': '66f12a1600000000', 'component': 'trace', 'language': 'python', 'runtime-id': '6d8cd0ba5492470ea5f51817b3c7f91a'} metrics={'_dd.top_level': 1, '_dd.tracer_kr': 0.0, '_sampling_priority_v1': 1, 'process_id': 1} links='' events='' (enabled:True)
app-1  | INFO:__main__:Done
app-1  | DEBUG:ddtrace._trace.tracer:Waiting 5 seconds for tracer to finish. Hit ctrl-c to quit.

What is the result that you expected?

On the other hand, the span for baz finishes only after it completes, which is what I'd expect.

app-1  | INFO:__main__:Running baz...
app-1  | INFO:src.foo:baz() start
app-1  | INFO:src.foo:baz() end
app-1  | DEBUG:ddtrace._trace.tracer:finishing span name='src.foo.baz' id=20220167502050434 trace_id=136833452558734916152741987134516448483 parent_id=None service=None resource='src.foo.baz' type=None start=1727080980.1653466 end=1727080982.1733022 duration=2.007955626 error=0 tags={'_dd.p.dm': '-0', '_dd.p.tid': '66f12a1400000000', 'language': 'python', 'runtime-id': '6d8cd0ba5492470ea5f51817b3c7f91a'} metrics={'_dd.top_level': 1, '_dd.tracer_kr': 0.0, '_sampling_priority_v1': 1, 'process_id': 1} links='' events='' (enabled:True)
app-1  | INFO:__main__:Done

[doctornkz-intelas]

I think we have the same issue, my K8S python CI/CD runner is giving this traceback(obfuscated). We are using async code with pytests:

[gw1] [100%] PASSED tests/test_sample.py::test_sample[sample_file.xls] Waiting 5 seconds for tracer to finish. Hit ctrl-c to quit.
--- Logging error ---
Waiting 5 seconds for tracer to finish. Hit ctrl-c to quit.
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
Traceback (most recent call last):
ValueError: I/O operation on closed file.
  File "/usr/lib/python3.10/logging/__init__.py", line 1103, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
Call stack:
  File "/path/to/project/virtualenv/lib/python3.10/site-packages/ddtrace/_trace/tracer.py", line 313, in _atexit
    log.debug(
  File "/usr/lib/python3.10/logging/__init__.py", line 1465, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python3.10/logging/__init__.py", line 1624, in _log
    self.handle(record)
  File "/path/to/project/virtualenv/lib/python3.10/site-packages/ddtrace/internal/logger.py", line 148, in handle
    super(DDLogger, self).handle(record)
Message: 'Waiting %d seconds for tracer to finish. Hit %s to quit.'
Arguments: (5, 'ctrl-c')
  File "/path/to/project/virtualenv/lib/python3.10/site-packages/ddtrace/_trace/tracer.py", line 313, in _atexit
    log.debug(
  File "/usr/lib/python3.10/logging/__init__.py", line 1465, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python3.10/logging/__init__.py", line 1624, in _log
    self.handle(record)
  File "/path/to/project/virtualenv/lib/python3.10/site-packages/ddtrace/internal/logger.py", line 148, in handle
    super(DDLogger, self).handle(record)
Message: 'Waiting %d seconds for tracer to finish. Hit %s to quit.'
Arguments: (5, 'ctrl-c')

UPD: Please ignore this: The problem is CI job takes too much time because Waiting 5 seconds.... : I removed ddtrace at all and got almost the same time.

Our variables:

export DD_TRACE_DEBUG="false"
export DD_TRACE_ENABLED="false"
export DD_INSTRUMENTATION_TELEMETRY_ENABLED="false"

ddtrace==2.14.2

[naohide]

DD_CIVISIBILITY_AGENTLESS_ENABLED can reduce traceback. However, it is still not perfect..

[doctornkz-intelas]

Do we have any plans to make it prettier than marking the issue as stale

[rachelyangdog]

Hello! We apologize for the delayed response. The issue should be fixed with this PR. Thank you for your patience.