From 5aff70faebce1d3e49a6796c7f2e6ec00a019681 Mon Sep 17 00:00:00 2001 From: Kazuhiro Sera Date: Sun, 26 Jul 2026 08:51:30 +0900 Subject: [PATCH] fix: reuse the verbose stdout logging handler (#3957) --- src/agents/__init__.py | 25 +++++- tests/test_agents_logging.py | 163 ++++++++++++++++++++++++++++++++++- 2 files changed, 182 insertions(+), 6 deletions(-) diff --git a/src/agents/__init__.py b/src/agents/__init__.py index 515916c2..6c2def39 100644 --- a/src/agents/__init__.py +++ b/src/agents/__init__.py @@ -1,5 +1,6 @@ import logging import sys +import threading from typing import TYPE_CHECKING, Any, Literal from openai import AsyncOpenAI @@ -332,11 +333,29 @@ def set_default_openai_harness(harness_id: str | None) -> None: _config.set_default_openai_harness(harness_id) -def enable_verbose_stdout_logging(): +_verbose_stdout_handler: "logging.StreamHandler[Any] | None" = None +_verbose_stdout_handler_lock = threading.Lock() + + +def enable_verbose_stdout_logging() -> None: """Enables verbose logging to stdout. This is useful for debugging.""" + global _verbose_stdout_handler + logger = logging.getLogger("openai.agents") - logger.setLevel(logging.DEBUG) - logger.addHandler(logging.StreamHandler(sys.stdout)) + with _verbose_stdout_handler_lock: + logger.setLevel(logging.DEBUG) + stream = sys.stdout if sys.stdout is not None else sys.stderr + + if _verbose_stdout_handler is None: + _verbose_stdout_handler = logging.StreamHandler(stream) + else: + _verbose_stdout_handler.acquire() + try: + _verbose_stdout_handler.stream = stream + finally: + _verbose_stdout_handler.release() + + logger.addHandler(_verbose_stdout_handler) __all__ = [ diff --git a/tests/test_agents_logging.py b/tests/test_agents_logging.py index c63fe3d0..60792c10 100644 --- a/tests/test_agents_logging.py +++ b/tests/test_agents_logging.py @@ -1,13 +1,170 @@ from __future__ import annotations +import io import logging +import sys +import threading +from collections.abc import Generator +from concurrent.futures import ThreadPoolExecutor +from typing import Any +import pytest + +import agents from agents import enable_verbose_stdout_logging -def test_enable_verbose_stdout_logging_attaches_handler() -> None: +@pytest.fixture +def agents_logger(monkeypatch: pytest.MonkeyPatch) -> Generator[logging.Logger, None, None]: logger = logging.getLogger("openai.agents") + original_handlers = logger.handlers[:] + original_level = logger.level logger.handlers.clear() + monkeypatch.setattr(agents, "_verbose_stdout_handler", None) + + try: + yield logger + finally: + added_handlers = [ + handler for handler in logger.handlers if handler not in original_handlers + ] + logger.handlers[:] = original_handlers + logger.setLevel(original_level) + for handler in added_handlers: + handler.close() + + +def test_enable_verbose_stdout_logging_reuses_its_handler( + agents_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + stdout = io.StringIO() + monkeypatch.setattr(sys, "stdout", stdout) + enable_verbose_stdout_logging() - assert logger.handlers - logger.handlers.clear() + handler = agents_logger.handlers[0] + enable_verbose_stdout_logging() + agents_logger.debug("debug message") + + assert agents_logger.handlers == [handler] + assert stdout.getvalue() == "debug message\n" + + +def test_enable_verbose_stdout_logging_preserves_application_handler( + agents_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + stdout = io.StringIO() + monkeypatch.setattr(sys, "stdout", stdout) + application_handler = logging.StreamHandler(stdout) + application_handler.setLevel(logging.WARNING) + agents_logger.addHandler(application_handler) + + enable_verbose_stdout_logging() + agents_logger.debug("debug message") + + assert agents_logger.handlers[0] is application_handler + assert application_handler.level == logging.WARNING + assert len(agents_logger.handlers) == 2 + assert stdout.getvalue() == "debug message\n" + + +def test_enable_verbose_stdout_logging_follows_replaced_stdout( + agents_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + first_stdout = io.StringIO() + monkeypatch.setattr(sys, "stdout", first_stdout) + enable_verbose_stdout_logging() + handler = agents_logger.handlers[0] + agents_logger.debug("first message") + assert first_stdout.getvalue() == "first message\n" + first_stdout.close() + + second_stdout = io.StringIO() + monkeypatch.setattr(sys, "stdout", second_stdout) + enable_verbose_stdout_logging() + agents_logger.debug("second message") + + assert agents_logger.handlers == [handler] + assert second_stdout.getvalue() == "second message\n" + + +def test_enable_verbose_stdout_logging_serializes_handler_initialization( + agents_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + stdout = io.StringIO() + monkeypatch.setattr(sys, "stdout", stdout) + original_stream_handler = logging.StreamHandler + original_add_handler = logging.Logger.addHandler + constructor_count = 0 + constructor_count_lock = threading.Lock() + second_constructor_started = threading.Event() + first_handler_attached = threading.Event() + start_barrier = threading.Barrier(3) + + def coordinated_stream_handler(stream: Any = None) -> logging.StreamHandler[Any]: + nonlocal constructor_count + with constructor_count_lock: + constructor_count += 1 + current_constructor = constructor_count + + handler = original_stream_handler(stream) + if current_constructor == 1: + second_constructor_started.wait(timeout=0.2) + else: + second_constructor_started.set() + first_handler_attached.wait(timeout=0.2) + return handler + + def tracking_add_handler( + logger: logging.Logger, + handler: logging.Handler, + ) -> None: + original_add_handler(logger, handler) + if logger is agents_logger: + first_handler_attached.set() + + def enable_logging() -> None: + start_barrier.wait(timeout=1) + enable_verbose_stdout_logging() + + monkeypatch.setattr(logging, "StreamHandler", coordinated_stream_handler) + monkeypatch.setattr(logging.Logger, "addHandler", tracking_add_handler) + + with ThreadPoolExecutor(max_workers=2) as executor: + futures = [executor.submit(enable_logging) for _ in range(2)] + start_barrier.wait(timeout=1) + for future in futures: + future.result(timeout=1) + + monkeypatch.setattr(logging, "StreamHandler", original_stream_handler) + monkeypatch.setattr(logging.Logger, "addHandler", original_add_handler) + agents_logger.debug("debug message") + + assert constructor_count == 1 + assert len(agents_logger.handlers) == 1 + assert stdout.getvalue() == "debug message\n" + + +def test_enable_verbose_stdout_logging_falls_back_to_stderr( + agents_logger: logging.Logger, + monkeypatch: pytest.MonkeyPatch, +) -> None: + stdout = io.StringIO() + stderr = io.StringIO() + monkeypatch.setattr(sys, "stdout", stdout) + monkeypatch.setattr(sys, "stderr", stderr) + enable_verbose_stdout_logging() + handler = agents_logger.handlers[0] + assert isinstance(handler, logging.StreamHandler) + + monkeypatch.setattr(sys, "stdout", None) + enable_verbose_stdout_logging() + agents_logger.debug("debug message") + + assert agents_logger.handlers == [handler] + assert handler.stream is stderr + assert stdout.getvalue() == "" + assert stderr.getvalue() == "debug message\n"