Skip to content

[Bugfix] Skip request body JSON serialization when its log level is disabled - #62108

Open
dskwe wants to merge 1 commit into
vllm-project:mainfrom
dskwe:fix-request-body-log-guard
Open

dskwe wants to merge 1 commit into
vllm-project:mainfrom
dskwe:fix-request-body-log-guard

Conversation

@dskwe

@dskwe dskwe commented Oct 17, 2026 •

Copy link
Copy Markdown
Contributor

Overview

Avoid serializing request JSON when the configured request-body logging level is disabled. This restores the logger-level guard removed by #60630 while preserving configurable body log levels.

Claims

  • Disabled request-body logging no longer calls model_dump_json.
  • Enabled INFO body logging still works when DEBUG is disabled; existing body truncation remains unchanged.
  • No measured end-to-end speedup is claimed.

Why this is not duplicating an existing PR

Scoped searches (open and all-state) for log_request_body, 60630, isEnabledFor + request logging, and request-body serialization found no PR adding this guard. Nearest work inspected: #60498 (Prometheus counters), #38583 (opt-in INFO prompt summaries), #58712 (LoggingConfig log_color/log_stream fields), RFC issue #57200. None touches the eager serialization in log_request_body.

Validation

Tests were run against ae8f41238cc7316781ef4359890940749735b209 and re-verified unchanged at e7a5bdb4542ca13e70a1ef0a1d9fb628b632c691; vllm/entrypoints/serve/utils/request_logger.py and its test file are unchanged between that SHA and current main (523d74e2ac78867aa35d535835e14f78fb7433af), where the bug is still present. Real CPU Docker environment, Python 3.12.13, torch 2.13.0+cpu, pytest 9.1.1. No GPU, successful generation E2E or model evaluation was performed.

On unchanged production source with the new regression test: 2 failed, 12 passed. Both failures show one serialization instead of zero for disabled DEBUG/INFO and WARNING/ERROR combinations. Enabled INFO passes.

After the three-line guard:

docker exec -w /validation/overnight-frontend-20261017 \
  -e PYTHONPATH=/validation/overnight-frontend-20261017 \
  -e VLLM_TARGET_DEVICE=cpu vllm-tokenizer-validation-20261013 \
  .venv/bin/python -m pytest \
  tests/entrypoints/serve/utils/test_request_logger.py \
  tests/entrypoints/openai/responses/test_responses_utils.py -q --disable-warnings

60 passed, 14 warnings in 17.53s. Adding tests/test_logger.py to the same command: 82 passed, 16 warnings in 50.64s. All applicable patch-scoped pinned pre-commit hooks passed; verbose mypy reported no issues in 2 files targeting Python 3.11. git diff --check passed. Independent read-only patch review found no code blocker.

A real FastAPI completion-route validation reproduced unnecessary serialization on a 404 unknown-model request: baseline DEBUG serialized once, fixed zero; enabled INFO remained once, with unchanged error responses. The harness initializes only early-rejection dependencies, not an engine; this is not successful serving E2E or model evaluation.

Serialization-only microbenchmark in the same CPU container, five repeats of 200 calls, body DEBUG/logger INFO, max_log_len=100: median helper cost for 32-byte/1MiB ASCII prompts was 16.844/1123.862 µs before versus 3.375/3.397 µs after. These are helper costs, not end-to-end performance results.

A normal render-server startup/HTTP A/B probe used the cached OPT-125m config/tokenizer snapshot 27dcfa74d334bc871f3234de431e71c6eeba5dd6: real render.entry CLI, normal app initialization, Uvicorn loopback HTTP. Expanded A/B covered /v1/completions/render, /v1/chat/completions/render and /v1/responses/render: all 12 render requests and 4 health checks returned 200; DEBUG body serialization changed 1→0 for each endpoint; enabled INFO remained 1; all six corresponding complete response bodies matched across variants; prompt token IDs agreed with independent Transformers encoding using each endpoint's special-token defaults (diagnostic chat template; not OPT chat quality validation). This is preprocessing only, not generated-token equivalence, inference E2E or evaluation. Full generation serving validation remains blocked in this environment: importing the native vllm._C terminates with SIGILL in the CPU container; the exact instruction mismatch is undiagnosed.

Independent read-only audits of the saved harness evidence confirmed serializer marker counts, the six parsed-JSON response pairs, HTTP status fields, parent exit codes and imported-module source hashes; the auditors did not rerun HTTP or tests. Equality is parsed-JSON, not wire-byte equality; recorded module hashes are selected-source, not whole-environment provenance.

Details

Python evaluates model_dump_json(...) before logger.log checks its level. BaseServing._check_model calls this helper when request logging is enabled, including completions, chat completions and Responses paths. With the default DEBUG body level and INFO logger threshold, request bodies are needlessly serialized even though no body record is emitted. Request logging is opt-in; deployments without it are not affected. Pooling overrides _check_model, so this report does not claim pooling impact.

The fix checks logger.isEnabledFor(level) after resolving the configured level and before serialization, matching the existing isEnabledFor use elsewhere in this file. It does not try to predict later handler/filter rejection. Tests use a real CompletionRequest and real logger, tracking the serializer through a wrapper instead of substituting a fabricated request.

On configuration mechanism: markmc's post-merge comment on #60630 suggests the body log level belongs in the typed --logging-config (#57200) rather than a new env var. This guard is independent of where the level comes from: whether the level continues to be read from the env var or moves into LoggingConfig, serialization should still be skipped when that level is disabled. This PR intentionally does not restructure the configuration.

AI assistance was used for identifying, reproducing and validating this fix; the full validation record above reflects commands actually run in a local CPU container.


Pull Request Checklist
  • I used vLLM's /pr-checklist skill. (Mandatory for agents, optional for humans).

  • AI assistance was used during the creation of this PR.

  • Design Fit: Minimizes impact on core components, reuses existing functionality, and justifies added complexity.

  • Testing and Validation: Validates the change and ensures any added tests are meaningful and reliable, with CI coverage or documented CI resource constraints and validation performed outside CI.

  • Pull Request Contents: Includes a brief summary and relevant links, supports claims with evidence, explains root causes and implementation trade-offs, and follows the contributing guide.

…isabled

log_request_body() eagerly evaluates model_dump_json() before
logger.log() checks the configured level, so with the default DEBUG
body level and an INFO logger every logged request serializes its
full JSON body even when no body record is emitted. Guard the
serialization with logger.isEnabledFor(level), mirroring the
existing isEnabledFor checks in this module, and add a regression
test covering disabled DEBUG/INFO and WARNING/ERROR combinations
plus the enabled INFO control.

Co-authored-by: Hermes Agent
Signed-off-by: Yuan Li <dskwelmcy@163.com>
@dskwe
dskwe requested a review from njhill as a code owner October 17, 2026 00:10

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Claude Code Review

This pull request is from a fork — automated review is disabled. A repository maintainer can comment @claude review to run a one-time review.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working frontend

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant