DIAGNOSTIC: route VCR diagnostics through per-PID files (bypass xdist capture)

Re-push of the diagnostic logging from the previous commit, this
time wired so the output actually survives to the CI log. xdist
captures stdout/stderr from every passing test in the worker
process; the body-matcher and normalizer-skip diagnostics fire from
inside vcrpy machinery during the test, so for any test that
ultimately passes (which is all of them once the cassettes are
recorded), the diagnostic lines are silently swallowed.

Fix: write each diagnostic line to a per-PID file under
``test-results/vcr-diagnostics/<pid>.log`` instead of writing to
stderr. The controller's ``pytest_terminal_summary`` aggregates
those files and writes them through ``terminalreporter.write_line``,
which is not subject to per-test capture. As a bonus,
``test-results/`` is already collected by the ``store_test_results``
step in CircleCI, so the raw per-worker logs survive as build
artifacts even after the test session ends.

Three call sites updated:

1. ``_emit_body_mismatch_diagnostic`` (matcher) -- writes the
   structured type/length/sha/window block via ``vcr_diag_write_line``.
2. ``_normalize_multipart_boundary`` -- logs the silent-skip path
   (body not bytes/bytearray/str) the same way.
3. ``_maybe_log_episode_body_hashes`` (persister) -- replaces the
   ``_log.warning`` calls (which the root-logger config also
   swallows in CI) with ``vcr_diag_write_line``.

Image-gen conftest is the only suite wired to dump the aggregated
log at session end. Other suites can opt in by adding
``emit_vcr_diagnostic_log(terminalreporter)`` to their own
``pytest_terminal_summary``. The diagnostic dir is cleared at the
start of each session (controller-only) so a local rerun does not
mix output from prior runs.

Same revert plan as the previous diagnostic commit: keep the
matcher + normalizer skip diagnostics permanently (they only fire
on signal events), revert the persister body-hash dump once the
async variance is identified.
This commit is contained in:
Mateo Wang 2026-05-17 07:08:39 +00:00
parent ba3915d9c6
commit 85430bc01f
No known key found for this signature in database
3 changed files with 104 additions and 20 deletions

View file

@ -36,6 +36,78 @@ SAFE_BODY_MATCHER_NAME = "safe_body"
KEY_FINGERPRINT_MATCHER_NAME = "key_fingerprint"
KEY_FINGERPRINT_HEADER = "x-litellm-key-fp"
# Directory for per-process VCR diagnostic logs that bypass pytest's
# stdout/stderr capture. ``sys.stderr.write`` from inside vcrpy
# machinery is swallowed by xdist for any test that ultimately passes,
# so a diagnostic that fires on a body-matcher miss but the test still
# records and passes will never reach the CI log. Each xdist worker
# (or the main process) writes line-buffered to a per-PID file under
# this directory, and the controller's ``pytest_terminal_summary``
# concatenates them into the terminal at session end. ``test-results/``
# is already collected by ``store_test_results`` in CI, so the raw
# files survive as build artifacts too.
VCR_DIAG_DIR_ENV = "LITELLM_VCR_DIAG_DIR"
VCR_DIAG_DIR_DEFAULT = "test-results/vcr-diagnostics"
def _vcr_diag_dir() -> str:
return os.environ.get(VCR_DIAG_DIR_ENV) or VCR_DIAG_DIR_DEFAULT
def vcr_diag_write_line(msg: str) -> None:
"""Append a single diagnostic line to the current process's
per-PID file. Atomic against other workers in the same xdist
session because each PID owns its own file.
Errors are swallowed -- diagnostic logging must never fail a test.
"""
try:
directory = _vcr_diag_dir()
os.makedirs(directory, exist_ok=True)
path = os.path.join(directory, f"{os.getpid()}.log")
with open(path, "a", encoding="utf-8") as fh:
fh.write(msg.rstrip("\n") + "\n")
except OSError:
pass
def emit_vcr_diagnostic_log(terminalreporter) -> None:
"""Concatenate every per-PID diagnostic file into the controller's
terminal at session end. Each file is dumped under a header that
names the originating worker PID so cross-process events can still
be ordered if needed.
"""
directory = _vcr_diag_dir()
if not os.path.isdir(directory):
return
try:
files = sorted(f for f in os.listdir(directory) if f.endswith(".log"))
except OSError:
return
if not files:
return
terminalreporter.write_sep("=", "VCR DIAGNOSTIC LOG", bold=True)
terminalreporter.write_line(
f" source dir: {directory} (also archived as a CI artifact)"
)
for name in files:
path = os.path.join(directory, name)
try:
with open(path, "r", encoding="utf-8") as fh:
content = fh.read()
except OSError as exc:
terminalreporter.write_line(
f" [failed to read {name}: {type(exc).__name__}: {exc}]"
)
continue
if not content.strip():
continue
terminalreporter.write_sep("-", name, bold=False)
for line in content.splitlines():
terminalreporter.write_line(line)
terminalreporter.write_sep("=", bold=True)
# Intentionally narrower than ``FILTERED_REQUEST_HEADERS``: AWS SigV4 headers
# carry secrets but their values rotate on every call, so fingerprinting them
# would defeat caching.
@ -324,7 +396,7 @@ def _emit_body_mismatch_diagnostic(r1, r2, body1, body2, n1, n2) -> None:
lines.append(f" first divergent byte offset: {offset}")
lines.append(f" window[a] @ {start}..{end_a}: {n1[start:end_a]!r}")
lines.append(f" window[b] @ {start}..{end_b}: {n2[start:end_b]!r}")
sys.stderr.write("\n".join(lines) + "\n")
vcr_diag_write_line("\n".join(lines))
def _iter_header_values(headers, name: str):
@ -478,12 +550,12 @@ def _normalize_multipart_boundary(request) -> None:
# because body type was X". The header was still rewritten
# above, so the recorded Content-Type stays stable; only the
# body bytes carry the random boundary verbatim.
sys.stderr.write(
vcr_diag_write_line(
f"[vcr-multipart-normalize] body normalization SKIPPED: "
f"body type {type(body).__name__!r} is not bytes/bytearray/str. "
f"content-type={content_type_value!r}. "
f"Recorded body will retain the random boundary substring "
f"and the safe_body matcher will miss on the next run.\n"
f"and the safe_body matcher will miss on the next run."
)
return

View file

@ -223,6 +223,9 @@ def make_redis_persister(
def _maybe_log_episode_body_hashes(key: str, cassette_dict) -> None:
import hashlib
# Imported lazily to avoid a circular import at module load.
from tests._vcr_conftest_common import vcr_diag_write_line
requests = cassette_dict.get("requests", []) or []
if not requests:
return
@ -235,27 +238,19 @@ def _maybe_log_episode_body_hashes(key: str, cassette_dict) -> None:
elif isinstance(body, str):
body_bytes = body.encode("utf-8")
else:
_log.warning(
"[vcr-episode-body-hash] %s episode[%d]: body type=%r is "
"not bytes/bytearray/str -- cannot hash. This is the "
"smoking gun for matcher-side bugs on async multipart.",
key,
i,
type(body).__name__,
vcr_diag_write_line(
f"[vcr-episode-body-hash] {key} episode[{i}]: body type="
f"{type(body).__name__!r} is not bytes/bytearray/str -- "
"cannot hash. This is the smoking gun for matcher-side "
"bugs on async multipart."
)
continue
method = getattr(req, "method", "?")
uri = getattr(req, "uri", getattr(req, "url", "?"))
_log.warning(
"[vcr-episode-body-hash] %s episode[%d] %s %s body sha256=%s "
"len=%d preview=%r",
key,
i,
method,
uri,
hashlib.sha256(body_bytes).hexdigest(),
len(body_bytes),
body_bytes[:120],
vcr_diag_write_line(
f"[vcr-episode-body-hash] {key} episode[{i}] {method} {uri} "
f"body sha256={hashlib.sha256(body_bytes).hexdigest()} "
f"len={len(body_bytes)} preview={body_bytes[:120]!r}"
)

View file

@ -11,9 +11,11 @@ import litellm # noqa: E402,F401
from tests._vcr_conftest_common import ( # noqa: E402
VerboseReporterState,
_vcr_diag_dir,
apply_vcr_auto_marker_to_items,
emit_cassette_cache_session_banner,
emit_vcr_classification_summary,
emit_vcr_diagnostic_log,
install_live_call_probe,
pin_httpx_multipart_boundary,
record_vcr_outcome,
@ -76,6 +78,20 @@ def _vcr_outcome_gate(request, vcr):
def pytest_configure(config):
_verbose_state.remember_pluginmanager(config)
# Clear any leftover per-PID diagnostic logs from a previous local
# run so the controller's terminal summary at session end only
# surfaces this session's data. Worker processes inherit the same
# directory and append by PID, so the controller doing the cleanup
# once is sufficient.
if not os.environ.get("PYTEST_XDIST_WORKER"):
directory = _vcr_diag_dir()
if os.path.isdir(directory):
for name in os.listdir(directory):
if name.endswith(".log"):
try:
os.remove(os.path.join(directory, name))
except OSError:
pass
def pytest_runtest_logreport(report):
@ -89,3 +105,4 @@ def pytest_collection_modifyitems(config, items):
def pytest_terminal_summary(terminalreporter, exitstatus, config):
emit_cassette_cache_session_banner(terminalreporter)
emit_vcr_classification_summary(terminalreporter)
emit_vcr_diagnostic_log(terminalreporter)