Skip to content
Open
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 45 additions & 0 deletions src/tests/test_log.py
Original file line number Diff line number Diff line change
Expand Up @@ -333,3 +333,48 @@ def test_init_logger_respects_json_format(self):
logger = log.init_logger("test.init_json")
for handler in logger.handlers:
assert isinstance(handler.formatter, log.JsonFormatter)


class TestErrorStreamRedaction:
"""The stderr handler carries its own filter chain."""

def test_error_stream_handler_carries_the_redaction_filter(self):
logger = log.init_logger("test-error-stream-redaction")

error_handlers = [
h
for h in logger.handlers
if isinstance(h, logging.StreamHandler) and h.level == logging.WARNING
]
assert error_handlers, "expected a WARNING-level stream handler"

for handler in error_handlers:
assert any(
isinstance(f, log.TokenRedactionFilter) for f in handler.filters
), "the WARNING handler must redact, since the stdout chain never runs for it"

def test_error_stream_handler_redacts_a_warning_record(self):
logger = log.init_logger("test-error-stream-redaction-applied")
handler = next(
h
for h in logger.handlers
if isinstance(h, logging.StreamHandler) and h.level == logging.WARNING
)
redaction = next(
f for f in handler.filters if isinstance(f, log.TokenRedactionFilter)
)

record = logging.LogRecord(
name="test",
level=logging.WARNING,
pathname="test.py",
lineno=1,
msg="Upstream rejected the request, headers: %s",
args=(Headers({"authorization": "Bearer super-secret-token"}),),
exc_info=None,
)

redaction.filter(record)

assert "super-secret-token" not in record.getMessage()
assert "Bearer ****" in record.getMessage()
61 changes: 61 additions & 0 deletions src/tests/test_request_header_redaction.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,61 @@
"""The session-extraction debug line must not defeat TokenRedactionFilter.

TokenRedactionFilter only inspects ``record.args`` for a Starlette ``Headers``
object, so a call site that formats the headers into the message string leaves
nothing for it to redact.
"""

import logging

from starlette.datastructures import Headers

from vllm_router import log


def test_formatted_headers_are_not_redacted_but_a_lazy_arg_is():
redaction = log.TokenRedactionFilter()
headers = Headers(
{"authorization": "Bearer super-secret-token", "host": "example.invalid"}
)

formatted = logging.LogRecord(
name="test",
level=logging.DEBUG,
pathname="test.py",
lineno=1,
msg=f"Debug session extraction - Request headers: {dict(headers)}",
args=None,
exc_info=None,
)
redaction.filter(formatted)
assert "super-secret-token" in formatted.getMessage(), (
"a pre-formatted dict carries nothing in record.args, so the filter "
"has nothing to act on; this is what the call site must avoid"
)

lazy = logging.LogRecord(
name="test",
level=logging.DEBUG,
pathname="test.py",
lineno=1,
msg="Debug session extraction - Request headers: %s",
args=(headers,),
exc_info=None,
)
redaction.filter(lazy)
assert "super-secret-token" not in lazy.getMessage()
assert "Bearer ****" in lazy.getMessage()


def test_session_extraction_logs_headers_as_a_lazy_arg():
"""The call site itself, read from source, must pass the Headers object."""
import inspect

from vllm_router.services.request_service import request as request_module

source = inspect.getsource(request_module.route_general_request)
assert 'logger.debug("Debug session extraction - Request headers: %s"' in source, (
"the headers must reach the logger as a lazy argument, not formatted "
"into the message, or TokenRedactionFilter cannot redact them"
)
assert "Request headers: {dict(request.headers)}" not in source

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

medium

Using inspect.getsource and string matching to assert on the implementation details of route_general_request is highly fragile. This test will fail if:\n1. The log message is formatted with single quotes instead of double quotes.\n2. A code formatter (like black or ruff) wraps the line differently.\n3. The source code is not available (e.g., when running from compiled .pyc files or in certain CI/CD environments).\n\nInstead of inspecting the source code, a more robust approach is to mock the logger or use pytest's caplog fixture to verify that the logged message is actually redacted when route_general_request is executed. If invoking route_general_request is too complex due to dependencies, we can at least make the string matching more flexible (e.g., using regular expressions or AST parsing via the ast module) to avoid failing on simple formatting changes.

4 changes: 4 additions & 0 deletions src/vllm_router/log.py
Original file line number Diff line number Diff line change
Expand Up @@ -210,6 +210,10 @@ def init_logger(name: str, log_level=None) -> Logger:
error_stream = logging.StreamHandler()
error_stream.setLevel(logging.WARNING)
error_stream.setFormatter(formatter)
# Each handler owns its filter chain, so the stdout handler's
# TokenRedactionFilter never runs for a WARNING or above. Without this,
# a warning that logs headers would print them in cleartext.
error_stream.addFilter(TokenRedactionFilter())
logger.addHandler(error_stream)
logger.propagate = False

Expand Down
5 changes: 4 additions & 1 deletion src/vllm_router/services/request_service/request.py
Original file line number Diff line number Diff line change
Expand Up @@ -607,7 +607,10 @@ async def route_general_request(
f"Debug session extraction - Router type: {type(request.app.state.router).__name__}"
)
logger.debug(f"Debug session extraction - Session key config: {session_key}")
logger.debug(f"Debug session extraction - Request headers: {dict(request.headers)}")
# Pass the Headers object as a lazy argument rather than a formatted dict,
# so TokenRedactionFilter can find it in record.args and redact
# Authorization and Cookie before this line is emitted.
logger.debug("Debug session extraction - Request headers: %s", request.headers)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

medium

Passing request.headers directly as a lazy argument introduces an inconsistency in the log format depending on whether sensitive headers are present.\n\nThis happens because TokenRedactionFilter (in src/vllm_router/log.py) only converts the Headers object to a dict when a sensitive header is found and modified:\n- With sensitive headers: The filter redacts them and replaces the argument with a standard Python dict. The log output formats as a dictionary: {'authorization': 'Bearer ****', 'host': '...'}.\n- Without sensitive headers: The filter does not modify the argument, leaving it as a Starlette Headers object. The log output formats using the Headers __repr__: Headers(headers=[('host', '...')]).\n\nTo ensure consistent log formatting, TokenRedactionFilter should be updated to always convert Headers and MutableHeaders to a dict (or always reconstruct them as Headers / MutableHeaders if type preservation is desired) regardless of whether any sensitive headers were modified.

logger.debug(f"Debug session extraction - Extracted session ID: {session_id}")

logger.info(
Expand Down