Skip to content

Commit 33e7990

Browse files
committed
fix(tests): add GIL-proof watchdog and restore logger global state
Two Group 5 release-CI fixes for the py3.13 freeze-at-98% (run 31235996603, both retry attempts): - tests/conftest.py: arm faulthandler.dump_traceback_later(120s, exit=True) around each test. pytest-timeout's thread method (timeout=90) needs the GIL to fire, so a C-level hang that holds the GIL freezes the worker silently until the 50-min step wall; faulthandler's C watchdog needs no GIL, dumps every thread's stack, and hard-exits the worker so xdist replaces it and --reruns retries the test. The stderr fd is dup'd at pytest_configure time because pytest's fd-level capture otherwise swallows the dump (which is why the 3.12 thread dumps never reached CI logs). LANGFLOW_TEST_HARD_TIMEOUT=0 disables it for debugger sessions. - tests/unit/test_logger.py: module-scoped autouse fixture restoring the process-global logging state the module rewires (structlog config, root handlers/level, named-logger levels, lfx file-handler global). In every observed freeze the wedged worker had just finished this module and hung in its next full-app test (test_login.py:: test_session_endpoint_rejects_expired_external_token).
1 parent 279378e commit 33e7990

4 files changed

Lines changed: 117 additions & 3 deletions

File tree

.secrets.baseline

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1088,15 +1088,15 @@
10881088
"filename": "src/backend/tests/conftest.py",
10891089
"hashed_secret": "8bb6118f8fd6935ad0876a3be34a717d32708ffd",
10901090
"is_verified": false,
1091-
"line_number": 559,
1091+
"line_number": 608,
10921092
"is_secret": false
10931093
},
10941094
{
10951095
"type": "Secret Keyword",
10961096
"filename": "src/backend/tests/conftest.py",
10971097
"hashed_secret": "61fbb5a12cd7b1f1fe1624120089efc0cd299e43",
10981098
"is_verified": false,
1099-
"line_number": 769,
1099+
"line_number": 818,
11001100
"is_secret": false
11011101
}
11021102
],
@@ -7242,5 +7242,5 @@
72427242
}
72437243
]
72447244
},
7245-
"generated_at": "2026-08-05T23:30:16Z"
7245+
"generated_at": "2026-08-08T15:38:52Z"
72467246
}

pyproject.toml

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -249,6 +249,9 @@ ignore-regex = '.*(Stati Uniti|Tense=Pres).*'
249249
# 50-min step wall. A 90s cap fires below the ~127s stall, and timeout_method="thread" dumps ALL
250250
# thread stacks (faulthandler) — naming the exact blocking call even when it is a leaked background
251251
# task. Revert to timeout=150 / timeout_method="signal" once the stall is identified and bounded.
252+
# NOTE: the thread method's timer needs the GIL, so a C-level hang that holds the GIL defeats it
253+
# (observed: release-1.11.3 py3.13 Group 5 froze 25+ min with no dump). A second, GIL-proof
254+
# faulthandler watchdog (120s, dump + exit) backstops it in src/backend/tests/conftest.py.
252255
timeout = 90
253256
timeout_method = "thread"
254257
minversion = "6.0"

src/backend/tests/conftest.py

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,9 @@
11
import asyncio
2+
import faulthandler
23
import json
34
import os
45
import shutil
6+
import sys
57

68
# we need to import tmpdir
79
import tempfile
@@ -165,7 +167,54 @@ def blockbuster(request):
165167
yield bb
166168

167169

170+
# Hard, GIL-proof per-test watchdog. pytest-timeout's thread method (pyproject
171+
# `timeout = 90`) arms a *Python* timer thread, which needs the GIL to run its
172+
# callback -- a hang inside a C call that never releases the GIL (observed on
173+
# the release-1.11.3 py3.13 Group 5 job: a worker froze for 25+ minutes in
174+
# test_login.py::test_session_endpoint_rejects_expired_external_token with no
175+
# dump) silently defeats it and the job burns to the CI step wall.
176+
# faulthandler.dump_traceback_later() instead uses a C-level watchdog thread
177+
# that needs no GIL: it dumps every thread's stack to the real stderr fd
178+
# (inherited by xdist workers, so it lands in the CI log) and, with exit=True,
179+
# hard-exits the wedged worker -- xdist then reports "node down", replaces the
180+
# worker, and --reruns retries the test on the fresh one. The 120s default sits
181+
# above pytest-timeout's 90s so the soft watchdog (clean per-test failure)
182+
# always gets first shot; this only fires when that one *couldn't* run.
183+
# Disable locally for debugger sessions with LANGFLOW_TEST_HARD_TIMEOUT=0.
184+
_HARD_TIMEOUT_S = float(os.getenv("LANGFLOW_TEST_HARD_TIMEOUT", "120"))
185+
186+
# Real-stderr fd, dup'd at pytest_configure time. pytest's fd-level capture
187+
# redirects fd 2 into a per-test temp file that is discarded when the process
188+
# hard-exits, so a dump armed against sys.__stderr__ at *test* time vanishes
189+
# (which is also why pytest-timeout's thread dumps never showed in CI logs).
190+
# At configure time fd 2 still points at the process's original stderr -- in an
191+
# xdist worker that fd is inherited from the controller, so dumps written to
192+
# the dup land in the CI step log. Same strategy as pytest's builtin
193+
# faulthandler plugin.
194+
_watchdog_stderr_fd: int | None = None
195+
196+
197+
@pytest.hookimpl(wrapper=True)
198+
def pytest_runtest_protocol(item, nextitem): # noqa: ARG001
199+
if _HARD_TIMEOUT_S <= 0 or _watchdog_stderr_fd is None:
200+
return (yield)
201+
faulthandler.dump_traceback_later(_HARD_TIMEOUT_S, file=_watchdog_stderr_fd, exit=True)
202+
try:
203+
return (yield)
204+
finally:
205+
faulthandler.cancel_dump_traceback_later()
206+
207+
168208
def pytest_configure(config):
209+
global _watchdog_stderr_fd # noqa: PLW0603
210+
if _HARD_TIMEOUT_S > 0 and _watchdog_stderr_fd is None:
211+
with suppress(AttributeError, ValueError, OSError):
212+
try:
213+
fd = sys.stderr.fileno()
214+
except (AttributeError, ValueError, OSError):
215+
fd = sys.__stderr__.fileno()
216+
_watchdog_stderr_fd = os.dup(fd)
217+
169218
config.addinivalue_line("markers", "noclient: don't create a client for this test")
170219
config.addinivalue_line("markers", "load_flows: load the flows for this test")
171220
config.addinivalue_line("markers", "api_key_required: run only if the api key is set in the environment variables")

src/backend/tests/unit/test_logger.py

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
import builtins
1313
import contextlib
14+
import importlib
1415
import json
1516
import logging
1617
import os
@@ -35,6 +36,67 @@
3536
from loguru import logger as loguru_logger
3637

3738

39+
@pytest.fixture(scope="module", autouse=True)
40+
def _restore_process_logging_state():
41+
"""Restore every process-global logging object this module mutates.
42+
43+
The tests here call ``configure()`` dozens of times and edit
44+
``logging.root.handlers`` directly, which rewires *process-wide* state:
45+
the structlog config, stdlib root handlers (InterceptHandler /
46+
RotatingFileHandler pointed at since-deleted temp dirs), named-logger
47+
levels (via LANGFLOW_LOG_LEVELS), and the ``lfx.log.logger`` module
48+
globals. Under xdist that poisoned state leaks into whatever test the
49+
worker picks up next -- observed on the release-1.11.3 CI run, where the
50+
worker that had just finished this module hung indefinitely inside the
51+
next test needing the full-app ``client`` fixture
52+
(test_login.py::test_session_endpoint_rejects_expired_external_token),
53+
freezing the whole Group 5 job to the 50-min step wall on py3.13. This
54+
fixture snapshots the pre-module state and puts it back at module exit.
55+
"""
56+
# ``import lfx.log.logger as ...`` would bind the *logger object* that
57+
# ``lfx.log``'s ``__init__`` re-exports under the same name, not the module.
58+
_lfx_log = importlib.import_module("lfx.log.logger")
59+
60+
orig_structlog_config = dict(structlog.get_config())
61+
orig_root_handlers = logging.root.handlers[:]
62+
orig_root_level = logging.root.level
63+
orig_file_handler = _lfx_log._file_handler
64+
orig_logger_levels = {
65+
name: lg.level for name, lg in logging.Logger.manager.loggerDict.items() if isinstance(lg, logging.Logger)
66+
}
67+
68+
yield
69+
70+
# structlog: reinstall the exact pre-module config (processor chain,
71+
# wrapper_class -- which also carries configure()'s change fingerprint).
72+
structlog.configure(**orig_structlog_config)
73+
74+
# stdlib root: drop handlers the module added (closing file handlers so
75+
# they stop pointing into deleted temp dirs), then restore the original
76+
# handler list and level. If the module's configure() calls replaced the
77+
# lfx-managed file handler, the original one was already closed by
78+
# setup_log_file(), so it must not be reinstalled.
79+
current_file_handler = _lfx_log._file_handler
80+
for handler in logging.root.handlers[:]:
81+
if handler not in orig_root_handlers:
82+
logging.root.removeHandler(handler)
83+
if isinstance(handler, logging.handlers.RotatingFileHandler):
84+
with contextlib.suppress(OSError, ValueError):
85+
handler.close()
86+
restored_handlers = orig_root_handlers
87+
if current_file_handler is not orig_file_handler:
88+
restored_handlers = [h for h in orig_root_handlers if h is not orig_file_handler]
89+
_lfx_log._file_handler = None
90+
logging.root.handlers[:] = restored_handlers
91+
logging.root.setLevel(orig_root_level)
92+
93+
# Named loggers whose levels configure() changed via LANGFLOW_LOG_LEVELS.
94+
for name, level in orig_logger_levels.items():
95+
lg = logging.Logger.manager.loggerDict.get(name)
96+
if isinstance(lg, logging.Logger) and lg.level != level:
97+
lg.setLevel(level)
98+
99+
38100
class TestConfigure:
39101
"""Test suite for the configure() function."""
40102

0 commit comments

Comments
 (0)