[BUG]: ddtrace throws logging exception during unit test runs with pytest

[ejungcl]

Tracer Version(s)

2.19.1

Python Version(s)

Pyton 3.13.0

Pip Version(s)

uv-pip 0.4.23 (83f835b0d 2024-10-17)

Bug Report

ddtrace tries to log to a closed stream when running unit tests with pytest, and causes an exception to be thrown in the logger. The expected behavior is that ddtrace will not cause any logging exceptions.

I am not using any ddtrace imports or functions. The only thing I have done is install ddtrace using pyproject.toml.

If I change our logging configuration, so that disable_existing_loggers=True instead of False, then the exception goes away.

This seems to be a bug in ddtrace, because setting disable_existing_loggers=True will disable ddtrace logging.

Reproduction Code

conftest.py

@pytest.fixture
def dummy():
    cfg = """
    version: 1
    disable_existing_loggers: False

    formatters:
        simple:
            format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
            datefmt: '%Y-%m-%d %H:%M:%S'

    handlers:
        stdout:
            class: logging.StreamHandler
            level: DEBUG
            formatter: simple
            stream: ext://sys.stdout
    loggers:
        root:
            level: DEBUG
            handlers: [stdout]
    """

    logconfig = yaml.safe_load(cfg)
    dictConfig(logconfig)

test_hello.py

"""Model unit tests."""
import pytest

def test_delete(dummy):
    assert 1 == 2

Error Logs

uv run pytest tests/models/test_hello.py
=============================================================== test session starts ================================================================
platform darwin -- Python 3.13.0, pytest-8.3.4, pluggy-1.5.0
rootdir: /Users/xtaje/clrepo/yoma
configfile: pyproject.toml
plugins: cov-6.0.0, time-machine-2.16.0, ddtrace-2.19.1, timer-1.0.0, Faker-33.3.1
collected 1 item

tests/models/test_hello.py F                                                                                                                 [100%]

===================================================================== FAILURES =====================================================================
___________________________________________________________________ test_delete ____________________________________________________________________

dummy = None

    def test_delete(dummy):
>       assert 1 == 2
E       assert 1 == 2

tests/models/test_hello.py:6: AssertionError
=================================================================== pytest-timer ===================================================================
[fail] 100.00% tests/models/test_hello.py::test_delete: 0.0001s
============================================================= short test summary info ==============================================================
FAILED tests/models/test_hello.py::test_delete - assert 1 == 2
================================================================ 1 failed in 0.05s =================================================================
Waiting 5 seconds for tracer to finish. Hit ctrl-c to quit.
--- Logging error ---
Traceback (most recent call last):
  File "/Users/xtaje/.local/share/uv/python/cpython-3.13.0-macos-aarch64-none/lib/python3.13/logging/__init__.py", line 1153, in emit
    stream.write(msg + self.terminator)
    ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
ValueError: I/O operation on closed file.
Call stack:
  File "/Users/xtaje/clrepo/yoma/.venv/lib/python3.13/site-packages/ddtrace/_trace/tracer.py", line 311, in _atexit
    log.debug(
  File "/Users/xtaje/.local/share/uv/python/cpython-3.13.0-macos-aarch64-none/lib/python3.13/logging/__init__.py", line 1507, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/Users/xtaje/.local/share/uv/python/cpython-3.13.0-macos-aarch64-none/lib/python3.13/logging/__init__.py", line 1664, in _log
    self.handle(record)
  File "/Users/xtaje/clrepo/yoma/.venv/lib/python3.13/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')

Libraries in Use

alembic==1.14.1
amqp==5.3.1
aniso8601==10.0.0
annotated-types==0.7.0
astroid==3.3.8
bandit==1.8.2
beautifulsoup4==4.12.3
billiard==4.2.1
black==24.10.0
blinker==1.9.0
cachelib==0.9.0
celery==5.4.0
certifi==2024.12.14
charset-normalizer==3.4.1
click==8.1.8
click-didyoumean==0.3.1
click-plugins==1.1.1
click-repl==0.3.0
coverage==7.6.10
dill==0.3.9
environs==14.1.0
factory-boy==3.3.1
faker==33.3.1
flask==3.1.0
flask-caching==2.3.0
flask-jwt-extended==4.7.1
flask-migrate==4.1.0
flask-restful==0.3.10
flask-sqlalchemy==3.1.1
gevent==24.11.1
greenlet==3.1.1
gunicorn==23.0.0
httmock==1.4.0
idna==3.10
iniconfig==2.0.0
isort==5.13.2
itsdangerous==2.2.0
jinja2==3.1.5
kombu==5.4.2
legacy-cgi==2.6.2
mako==1.3.8
markdown-it-py==3.0.0
markupsafe==3.0.2
marshmallow==3.25.1
mccabe==0.7.0
mdurl==0.1.2
mypy-extensions==1.0.0
packaging==24.2
pathspec==0.12.1
pbr==6.1.0
pendulum==3.0.0
platformdirs==4.3.6
pluggy==1.5.0
prompt-toolkit==3.0.50
pydantic==2.10.5
pydantic-core==2.27.2
pydantic-extra-types==2.10.2
pygments==2.19.1
pyjwt==2.10.1
pylint==3.3.3
pymysql==1.1.1
pytest==8.3.4
pytest-cov==6.0.0
pytest-timer==1.0.0
python-dateutil==2.9.0.post0
python-dotenv==1.0.1
pytz==2024.2
pyyaml==6.0.2
redis==5.2.1
requests==2.32.3
rich==13.9.4
ruff==0.9.2
setuptools==75.8.0
six==1.17.0
soupsieve==2.6
sqlalchemy==2.0.37
sqlalchemy-utils==0.41.2
stevedore==5.4.0
time-machine==2.16.0
tomlkit==0.13.2
typing-extensions==4.12.2
tzdata==2025.1
urllib3==2.3.0
vine==5.1.0
waitress==3.0.2
wcwidth==0.2.13
webob==1.8.9
webtest==3.0.3
werkzeug==3.1.3
-e file:///Users/xtaje/clrepo/yoma
zope-event==5.0
zope-interface==7.2

Operating System

Darwin CL1076.local 24.0.0 Darwin Kernel Version 24.0.0: Tue Sep 24 23:37:25 PDT 2024; root:xnu-11215.1.12~1/RELEASE_ARM64_T6030 arm64

[doctornkz-intelas]

I think it's very close to this ticket #10754 and I also realised that ddtracer is patching loggers even without imports.

[diranged]

This is definitely a problem... :/ Adding this to my conftest.py as a hack works for now:

logging.config.dictConfig({
    "version": 1,
    "disable_existing_loggers": True,
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "level": "INFO",
        }
    },
    "root": {
        "handlers": ["console"],
        "level": "INFO",
    },
  }
)

[andrewFirstResonance]

We are also running into this problem only for people with new mac m3 machines for some reason though ... Very confusing. We will be trying the temporary conftest hack. It worked. Will subscribe to this issue to see updates

[zoola969]

Same problem

[tj-smith47]

This is not unique to M3 machines, I'm experiencing it on an M1 using 3.9.1.

$ PYTEST=true PYTHON_ENV=test poetry run pytest src/test/tasks/helpers_test.py \
    -p no:ddtrace -p no:ddtrace.pytest_bdd -p no:ddtrace.pytest_benchmark
=======================
platform darwin -- Python 3.12.7, pytest-8.4.0, pluggy-1.6.0
rootdir: ${HOME}/src/repos/python/my-repo
configfile: pyproject.toml
plugins: cov-5.0.0, anyio-4.9.0, flask-1.3.0
collected 2 items

src/test/tasks/helpers_test.py ..
========================
Waiting 5 seconds for tracer to finish. Hit ctrl-c to quit.
--- Logging error ---
Traceback (most recent call last):
  File "${HOME}/.asdf/installs/python/3.12.7/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/wouldnt/you/like/to/know.py", line 251, in _atexit
    log.debug(
Message: 'Waiting %d seconds for tracer to finish. Hit %s to quit.'
Arguments: (5, 'ctrl-c')

EDIT: The cause (at least for me) appeared to be due to when / how patch is imported. We already had a DogStatsd() global instance in the project's root __init__.py without issue. We first started experiencing this error after adding ddtrace and calling patch(celery=True) in our celery dir tasks/__init__.py. Simply wrapping that under a condition checking PYTHON_ENV was insufficient - we had to move the import as well:

if config["env"] == "production":
    from ddtrace import patch

    patch(celery=True)

I would imagine this is not necessarily specific to patch, but rather any file where from ddtrace import [thing] is called unconditionally - at least, so long as [thing]'s dependency chain imports / references Tracer.

[tj-smith47]

Saying this in a separate comment so it's more difficult to miss - the workaround above should not be necessary.

Disabling ddtrace during pytest should either a) be a default behavior, b) be configurable via a single ENV or config setting (e.g., in a pyproject.toml), or at least c) be documented - in the documentation, not just the repo's issues. When I search 'disable' in the Python documentation, these flags never even come up. Instead I get a TON of environment variables with DISABLE in them, none of which just completely disable everything ddtrace when running pytest. I do see this section here, which only references addopts = -p no:ddtrace.pytest_bdd, but this alone doesn't solve all logging errors.

This issue seems to have come up more than once over time. This PR seems it indicate it resolved the issue a while back, but I experienced 0 difference in the nasty logging after tests with any/all of:

• DD_TRACE_ENABLED=False
• DD_INSTRUMENTATION_TELEMETRY_ENABLED=False
• Setting the following in pyproject.toml:

[tool.pytest]
ddtrace = 0
ddtrace-patch-all = 0

I can't seem to find it now, but I could have sworn I saw an Issue / PR from 2020 where running ddtrace at all during pytest was an opt-in behavior. Did I misunderstand, or was that decision overturned?

[goodspark]

Happens in v3.10.1 as well.

[vitor-de-araujo]

The logging issue should be fixed by PR #14121, which will come out as part of dd-trace-py 3.11.0.

[vitor-de-araujo]

I can't seem to find it now, but I could have sworn I saw an Issue / PR from 2020 where running ddtrace at all during pytest was an opt-in behavior. Did I misunderstand, or was that decision overturned?

@tj-smith47 ddtrace is meant to be opt-in in tests, in the sense that if you don't pass --ddtrace to pytest or set it in configuration files, it should not affect test execution. The problem is that by the time we parse command line options, pytest has already imported ddtrace to load the plugin, which starts the tracer. The only way to avoid this at the moment is to pass -p no:ddtrace to pytest, which is described here. But even that is not enough, you would need to pass all of -p no:ddtrace -p no:ddtrace.pytest_bdd -p no:ddtrace.pytest_benchmark to fully prevent ddtrace from being loaded. I agree that this is a problem, and I plan to address this in a future PR. But at least the logging issue should be solved in the next ddtrace release, even if ddtrace is loaded.

[vitor-de-araujo]

The fix for this issue was released in dd-trace-py 3.11.0. Closing the issue, but feel free to reopen if you find any problems.