deer-flow/backend/tests/test_logging_config.py
hataa 26800d1245
fix(channels): stream-cap and validate WeChat/WeCom inbound media downloads, fixes #5223 (#5225)
* fix(channels): stream-cap and validate WeChat/WeCom inbound media downloads, fixes #5223

* fix(channels): address WeCom APPID, decompression, and log-sanitization review findings (#5223)

Round-4 review follow-ups on the inbound-media download cap:

- The COS bucket numeric suffix is the owner's Tencent Cloud APPID and bucket
  names are user-chosen, so any Tencent Cloud account could register a
  matching ww-aibot-img-* bucket and pass the shape gate. The built-in rule
  now admits only the APPID observed in Tencent's published aibot callback
  examples (1258476243), across regions; any other account (including a
  future WeCom rotation) goes through channels.wecom.allowed_media_hosts.
- aiter_bytes() transparently decodes Content-Encoding, and the decoder
  allocates the full decompressed body before the byte cap sees a chunk (an
  ~8 KB gzip wire chunk decoding to 8 MiB reproduces it). Both URL readers
  now send Accept-Encoding: identity, refuse a response with a residual
  Content-Encoding before reading, and iterate aiter_raw().
- httpx.HTTPStatusError formats the signed URL (path + query credentials)
  into its message, so _ingest_inbound_files' reader-failure branch logs a
  sanitized summary (class + status) instead of logger.exception, and the
  WeChat extract paths catch httpx.HTTPError so the polling loop's
  per-message logger.exception can never render a media URL.

Every change ships with a red/green regression: the reviewer's 403
mock-transport repro asserted against caplog.text (fully formatted logs),
the reviewer's different-APPID bucket host, and gzip bombs driven through
real httpx mock transports in both readers. Docs (channels AGENTS.md,
README, config.example.yaml) updated for the APPID pinning and encoding
gate.

* docs(channels): document why the inbound-media cap is 50 MB, not WeCom's 100 MB ceiling

* fix(logging): redact URLs in httpx request logs down to scheme + host, fixes #5223

httpx emits 'HTTP Request: GET <full URL>' at the Gateway's INFO level
before any response handling runs, so even successful signed-media
downloads leaked their credentials. HttpxUrlQueryRedactionFilter
(installed by configure_logging) rewrites those records in place — path
and query become /<redacted>, method/status/duration observability is
preserved — which also keeps Telegram's token-bearing Bot API paths out
of the logs. Reader-level regression tests run at production INFO level
with a real MockTransport, success paths included.

* fix(logging): blank userinfo credentials in httpx request-log redaction

* fix(logging): redact authority-only URLs and cover urllib3 redirect logs

Two follow-ups from the review plus one extrapolation of the same class:

- rest is now optional in _URL_REDACT_RE, so an authority-only URL
  (scheme://user:pass@host, no path) is rewritten too — userinfo had
  nowhere else to hide and previously passed through verbatim. A bare
  credential-free origin still passes through unchanged.
- Renamed to UrlRedactionFilter / install_url_log_redaction and attached
  to the urllib3 logger as well: urllib3 logs 'Redirecting <url> -> <url>'
  at INFO with full URLs on both sides, the same leak class on a different
  library logger. No gateway path today both uses requests and redirects
  a signed URL, but the class stays closed instead of dormant.
- Unit tests now build records with the real httpx 0.28.1 format string
  ('HTTP Request: %s %s "%s %d %s"', 5 args) and httpx.URL args, per
  the nit, instead of a synthetic shape httpx never emits.

* fix(logging): install URL redaction at handler level so propagated records are covered

A logging.Filter on a logger only runs for records emitted through that
exact logger — child loggers neither inherit it nor trigger it on
propagation — so the previous attachment to the bare urllib3 logger was
dead code: urllib3 emits Redirecting via urllib3.poolmanager at INFO and
urllib3.connectionpool at DEBUG. The filter is now attached to every root
handler (mirroring _install_trace_filter, which already iterates root
handlers; handler-level filters see propagated records) in addition to
the httpx logger (httpx emits via the bare name, and emission-point
coverage survives handlers added later). The wiring is pinned by tests
that emit through the real urllib3 child loggers — a mutation removing
the handler-level install turns them red. Comments, docstrings, and
AGENTS.md now state the actual emitter names and levels.

* fix(logging): redact urllib3 DEBUG request lines, whose split shape evaded the URL regex

urllib3's per-request line (connectionpool.py:545 on 2.7.0) renders as
`scheme://host:port "METHOD /path?query HTTP/x.x" status len` — the
authority ends at a space so _URL_REDACT_RE's bare-origin early return
applies, and the quoted origin-form target has no scheme, so neither half
was rewritten. UrlRedactionFilter now runs a dedicated request-line shape
first (collapsing the target to /<redacted>, keeping scheme+host+method+
version), then the absolute-URL pass. Regressions pin the exact format
string both at unit level and through the real urllib3.connectionpool
DEBUG emit path; AGENTS.md wording now names both covered DEBUG shapes.

* fix(logging): redact urllib3 retry lines and linearize scheme scanning

Closes the two open review threads on the inbound-media log hardening:

Retry/redirect targets: urllib3 logs the request target with no scheme in
five shapes the generic absolute-URL pass cannot see - `Retry: <target>`
(connectionpool.py:954 DEBUG), `Incremented Retry for (url='<target>')`
(util/retry.py:545 DEBUG, absolute on the redirect path), `Retrying (...)
after connection broken by '<err>': <target>` (connectionpool.py:869
WARNING, above the INFO root), and origin-form halves of both Redirecting
emitters (poolmanager.py:500 INFO / connectionpool.py:922 DEBUG). Each
gets a rewrite anchored to the exact urllib3 format, collapsing the
target to /<redacted>; the generic pass's rest now stops at quote
characters so a quoted URL keeps its closing punctuation (previously the
absolute-form increment line was mangled), and the request-line method
class accepts any case. The emitter enumeration in channels AGENTS.md is
closed against the installed urllib3 2.7.0 source.

Quadratic scanning: both scheme-bearing patterns start with a character
class, so re.sub retried every suffix of a long token - 64K paths cost
~1.8s and URL-free 64K error bodies ~3.1s per record, synchronously in
every root handler. The two passes are now driven from literal "://"
occurrences: _scheme_starts walks back over the scheme charset to each
run's first letter and the pattern is attempted only there, reproducing
re.sub's leftmost-non-overlapping result in linear time (256K path:
5.6ms; worst adversarial shapes <= 28ms). Long-input regressions pin the
URL-bearing and URL-free cases with mutation-verified bounds, plus
nested-scheme and digit-headed-run equivalence cases.

Validation: tests/test_logging_config.py 12/12; scheme-pass equivalence
against the old re.sub pipeline verified by two independent 30k+ case
fuzz runs; full-suite A/B against HEAD shows zero tests that pass on HEAD
and fail with this diff.

* fix(logging): boundary-aware quote stops and whole-message Redirecting anchor

Two follow-ups on the urllib3 redaction shapes:

Embedded quotes: `rest` treated ANY quote as a closing mark, so a URL
with an apostrophe in the path kept everything after it verbatim
(`https://h/path'quoted'?token=Q` rendered the credential suffix in
full) while the class docstring claimed path/query/fragment are
replaced. A quote now closes `rest` only at a boundary - followed by
whitespace, a closing parenthesis, or end of string - so urllib3's
Incremented Retry (url='...') scaffolding keeps its ') closer while an
embedded quote stays consumed. The increment line's url capture gets
the same rule narrowed to its fixed ')' closer.

Redirecting anchoring: the origin-half pass matched `(?
<=-> )/path` as a substring, and an `-> /path` arrow is not
urllib3-owned shape - the sandbox provider's actionable mount error
(`sandbox.mounts entry <host> -> /mnt/knowledge ignored: ...`) had its
container path rewritten to /<redacted>, failing
test_setup_path_mappings_logs_actionable_error_for_missing_host_path on
CI (backend-unit-tests shard 3). The pass is now anchored to the whole
`Redirecting <t> -> <t>` message, which is exactly urllib3's record;
origin slots collapse, absolute slots stay for the generic pass.
Regression tests pin the embedded-quote shapes and the sandbox error's
byte-for-byte passthrough; both mutations verified red.

Validation: tests/test_logging_config.py 14/14; the CI-failing sandbox
test green locally; every test file asserting redaction/arrow log
content passes (attachments, support bundle, run metadata, skill
secrets, ragflow, skillscan, sandbox provider); full offline backend
suite 14084 passed / 164 failed with the failure set matching this
machine's documented Windows-environment baseline (NTFS chmod/symlink,
docker/lark/langfuse absences) - no failure involves redaction output.

* fix(logging): redact redirects with spaced locations

* fix(logging): grammar-complete Redirecting anchor; neutral WeChat guard labels

Round-13 P3 (Redirecting anchor strictness): the whole-message anchor kept
the ^Redirecting prefix (the urllib3-owned literal that stops the sandbox
false positive) but required BOTH slots whitespace-free, so a Location
header with an interior space voided the pass and leaked the origin-form
request target in the first slot - redirect_location is the raw header
string and interior spaces are legal field syntax. The tail is now loose
(\S.*$) and the first slot gets the same grammar treatment (\S.*?): the
recursive urlopen frame passes the previous raw Location as its url, so
t1 can carry interior spaces too, lazy-split at the first arrow the way
the line is constructed. A space-carrying slot collapses whole when it
starts with /; the sandbox mount error keeps passing through untouched.

Round-14 nit (None conflation): _download_cdn_bytes returns None for two
reasons (in-flight cap abort, Content-Encoding refusal) but both image and
file callers labeled it "exceeds size limit (N bytes)" - contradicting the
accurate encoding line right above it, and reporting the plaintext limit
for a ciphertext-cap decision. Callers now log a neutral
"skipped by download guard" line (the manager reader callers' shape);
the accurate reason stays inside the download function. The same sweep
also logs _stage_downloaded_file's silent None (no state dir configured),
which made an attachment vanish with no log line at all.

Also anchors the emitter-enumeration closure to its urllib3 version: the
closure reopens if an upgrade changes these format strings, so the comment
now says so explicitly.

Validation: logging 15/15 and attachments 60/62 (the two pre-existing
Windows symlink-privilege failures documented in the PR body); three
mutations verified red (old wording, strict t1, silent staging None);
ruff clean. Full offline suite run before push (per round-11 lesson).

---------

Co-authored-by: Willem Jiang <willem.jiang@gmail.com>
2026-09-16 16:33:47 +08:00

734 lines
34 KiB
Python

import io
import logging
from types import SimpleNamespace
import httpx
from deerflow.logging_config import TraceContextFilter, configure_logging
from deerflow.trace_context import request_trace_context
def test_trace_context_filter_injects_current_trace_id() -> None:
record = logging.LogRecord("deerflow.test", logging.INFO, __file__, 1, "hello", (), None)
with request_trace_context("trace-log-1"):
assert TraceContextFilter().filter(record) is True
assert record.trace_id == "trace-log-1"
def test_configure_logging_enhanced_text_includes_trace_id() -> None:
root = logging.getLogger()
old_handlers = root.handlers[:]
old_level = root.level
stream = io.StringIO()
handler = logging.StreamHandler(stream)
try:
root.handlers = [handler]
root.setLevel(logging.INFO)
config = SimpleNamespace(
log_level="info",
logging=SimpleNamespace(enhance=SimpleNamespace(enabled=True, format="text")),
)
configure_logging(config)
with request_trace_context("trace-log-2"):
logging.getLogger("deerflow.test").info("hello")
assert "[trace_id=trace-log-2]" in stream.getvalue()
finally:
root.handlers = old_handlers
root.setLevel(old_level)
# The installed httpx (0.28.1) emits this exact record from _client.py:
# logger.info('HTTP Request: %s %s "%s %d %s"', method, url, version, status, reason)
_HTTPX_REQUEST_FORMAT = 'HTTP Request: %s %s "%s %d %s"'
def _httpx_record(url: str, method: str = "GET", status: int = 200) -> logging.LogRecord:
return logging.LogRecord(
"httpx",
logging.INFO,
__file__,
1,
_HTTPX_REQUEST_FORMAT,
(method, httpx.URL(url), "HTTP/1.1", status, "OK"),
None,
)
def test_url_redaction_filter_rewrites_request_records() -> None:
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
# Records are built with the real httpx format string and httpx.URL args
# (verified against httpx/_client.py on the installed version), so the
# unit test pins the production format. Redaction runs on the formatted
# message and clears args; path AND query disappear — only scheme + host
# may remain (the repo-wide inbound-media log rule).
record = _httpx_record("https://host.example/private/BearerSecret?token=QuerySecret")
assert filt.filter(record) is True
formatted = record.getMessage()
assert "host.example/<redacted>" in formatted
assert "BearerSecret" not in formatted
assert "token=" not in formatted
assert "GET" in formatted and "200" in formatted # observability preserved
# Same class of leak, different secret location: the Telegram Bot API
# carries the bot token in the PATH (api.telegram.org/bot<token>/method),
# and python-telegram-bot's HTTPXRequest rides the same httpx logger —
# redacting down to scheme + host is what keeps telegram.py's promise
# that the token-bearing URL never reaches the logs.
telegram = _httpx_record("https://api.telegram.org/bot123456:AAE-token-secret/sendMessage", method="POST")
assert filt.filter(telegram) is True
telegram_formatted = telegram.getMessage()
assert "api.telegram.org/<redacted>" in telegram_formatted
assert "AAE-token-secret" not in telegram_formatted
assert "bot123456" not in telegram_formatted
# Userinfo credentials in the authority (basic-auth style endpoints that
# httpx accepts, e.g. MCP/extension proxies) must be blanked too — the
# authority is split so only <redacted>@ survives in front of the host.
userinfo = _httpx_record("https://user:token123@internal-proxy.corp:8080/v1/secret-endpoint")
assert filt.filter(userinfo) is True
userinfo_formatted = userinfo.getMessage()
assert "https://<redacted>@internal-proxy.corp:8080/<redacted>" in userinfo_formatted
assert "token123" not in userinfo_formatted
assert "user:" not in userinfo_formatted
# Authority-ONLY URL (no path/query): rest is optional in the regex, so a
# userinfo credential with nowhere else to hide is still blanked.
authority_only = _httpx_record("https://user:tok@internal-proxy.corp")
assert filt.filter(authority_only) is True
authority_formatted = authority_only.getMessage()
assert "https://<redacted>@internal-proxy.corp" in authority_formatted
assert "tok" not in authority_formatted.replace("<redacted>", "")
# A bare credential-free origin without path/query is left as-is.
bare = _httpx_record("https://host.example")
assert filt.filter(bare) is True
assert "https://host.example" in bare.getMessage()
assert "<redacted>" not in bare.getMessage()
# Records without a URL pass through untouched (message + args kept).
plain = logging.LogRecord("httpx", logging.INFO, __file__, 1, "keep %s", ("this",), None)
assert filt.filter(plain) is True
assert plain.getMessage() == "keep this"
def test_url_redaction_filter_covers_urllib3_redirect_records() -> None:
"""Real-emitter wiring: urllib3 logs through CHILD loggers, and a filter on
the bare ``urllib3`` logger never sees propagated records (logger filters
are not inherited). Verified against the installed urllib3 2.7.0:
``urllib3.poolmanager`` logs ``Redirecting %s -> %s`` at INFO
(poolmanager.py:500) and ``urllib3.connectionpool`` logs the same shape at
DEBUG (connectionpool.py:922). Both must come out redacted through the
real emit path with configure_logging's handler-level installation."""
from deerflow.logging_config import configure_logging
root = logging.getLogger()
old_handlers = root.handlers[:]
old_level = root.level
stream = io.StringIO()
handler = logging.StreamHandler(stream)
try:
root.handlers = [handler]
root.setLevel(logging.DEBUG)
configure_logging(SimpleNamespace(log_level="debug", logging=SimpleNamespace(enhance=SimpleNamespace(enabled=False, format="text"))))
logging.getLogger("urllib3.poolmanager").info(
"Redirecting %s -> %s",
"https://cdn.example/private/BearerSecret?token=QuerySecret",
"https://mirror.example/private/BearerSecret?sig=OtherSecret",
)
logging.getLogger("urllib3.connectionpool").debug(
"Redirecting %s -> %s",
"https://cdn.example/private/BearerSecret?token=QuerySecret",
"https://mirror.example/private/BearerSecret?sig=OtherSecret",
)
out = stream.getvalue()
assert "BearerSecret" not in out
assert "QuerySecret" not in out
assert "OtherSecret" not in out
assert out.count("cdn.example/<redacted>") == 2
assert out.count("mirror.example/<redacted>") == 2
finally:
root.handlers = old_handlers
root.setLevel(old_level)
def test_url_redaction_filter_covers_urllib3_request_line_records() -> None:
"""urllib3's per-request DEBUG line splits the URL across its format
string, so the absolute-URL regex alone cannot catch it. The installed
urllib3 (2.7.0) emits this exact record from
HTTPConnectionPool._make_request (connectionpool.py:545):
log.debug('%s://%s:%s "%s %s %s" %s %s', scheme, host, port, method,
url, response.version_string, response.status,
response.length_remaining) — the authority ends at a space (bare-origin
early return) and the quoted origin-form target has no scheme, which is
why the request line needs its own redaction shape."""
from deerflow.logging_config import UrlRedactionFilter
format_string = '%s://%s:%s "%s %s %s" %s %s'
filt = UrlRedactionFilter()
def _record(target: str, version: str = "HTTP/1.1", method: str = "GET") -> logging.LogRecord:
return logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
format_string,
("https", "cdn.example", 443, method, target, version, 200, None),
None,
)
# The reviewer's repro shape: host:port, then a quoted request line whose
# origin-form target carries the signed path+query. The rewrite keeps
# scheme + host + method + version for observability and collapses the
# target to /<redacted>.
record = _record("/private/BearerSecret?token=QuerySecret")
assert filt.filter(record) is True
formatted = record.getMessage()
assert formatted == 'https://cdn.example:443 "GET /<redacted> HTTP/1.1" 200 None'
assert "BearerSecret" not in formatted
assert "token=" not in formatted
# A target with no query still hides the path: the inbound-media rule is
# host-only visibility, not query-only.
path_only = _record("/private/photo.jpg")
assert filt.filter(path_only) is True
assert '"GET /<redacted> HTTP/1.1"' in path_only.getMessage()
assert "photo.jpg" not in path_only.getMessage()
# HTTP/2 responses keep version_string in the quoted line; the shape must
# still match and rewrite.
http2 = _record("/private/BearerSecret?token=QuerySecret", version="HTTP/2")
assert filt.filter(http2) is True
assert '"GET /<redacted> HTTP/2"' in http2.getMessage()
assert "BearerSecret" not in http2.getMessage()
def test_url_redaction_filter_covers_urllib3_request_line_through_real_emit() -> None:
"""Real-emitter wiring for the per-request line: urllib3 logs through the
``urllib3.connectionpool`` child logger at DEBUG, so only the
handler-level filters installed by configure_logging can rewrite the
record. Emits with the connectionpool.py:545 format string at root
DEBUG."""
from deerflow.logging_config import configure_logging
root = logging.getLogger()
old_handlers = root.handlers[:]
old_level = root.level
stream = io.StringIO()
handler = logging.StreamHandler(stream)
try:
root.handlers = [handler]
root.setLevel(logging.DEBUG)
configure_logging(SimpleNamespace(log_level="debug", logging=SimpleNamespace(enhance=SimpleNamespace(enabled=False, format="text"))))
logging.getLogger("urllib3.connectionpool").debug(
'%s://%s:%s "%s %s %s" %s %s',
"https",
"cdn.example",
443,
"GET",
"/private/BearerSecret?token=QuerySecret",
"HTTP/1.1",
200,
None,
)
out = stream.getvalue()
assert "BearerSecret" not in out
assert "QuerySecret" not in out
assert 'https://cdn.example:443 "GET /<redacted> HTTP/1.1"' in out
assert "200" in out # status observability preserved
finally:
root.handlers = old_handlers
root.setLevel(old_level)
def test_url_redaction_filter_covers_urllib3_retry_lines() -> None:
"""urllib3's retry sites log the request target with no scheme and no
quoting, so neither the absolute-URL nor the quoted request-line pattern
can see it. Verified against the installed urllib3 (2.7.0):
``Retry: %s`` (connectionpool.py:954, DEBUG),
``Incremented Retry for (url='%s'): %r`` (util/retry.py:545, DEBUG —
origin-form target on the request path), and
``Retrying (%r) after connection broken by '%r': %s``
(connectionpool.py:869, WARNING — above the Gateway's INFO root). Each
collapses the target to ``/<redacted>`` while keeping the surrounding
format (status counts, error text) for observability."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
def _record(name: str, fmt: str, args: tuple) -> logging.LogRecord:
return logging.LogRecord(name, logging.DEBUG, __file__, 1, fmt, args, None)
# connectionpool.py:954 — bare origin-form target after "Retry: ".
retry_target = _record("urllib3.connectionpool", "Retry: %s", ("/private/BearerSecret?token=QuerySecret",))
assert filt.filter(retry_target) is True
assert retry_target.getMessage() == "Retry: /<redacted>"
# An absolute target on the same line is the generic pass's job.
retry_absolute = _record("urllib3.connectionpool", "Retry: %s", ("https://cdn.example/private/BearerSecret?token=QuerySecret",))
assert filt.filter(retry_absolute) is True
assert retry_absolute.getMessage() == "Retry: https://cdn.example/<redacted>"
# util/retry.py:545 — origin-form target inside the quoted url slot; the
# ``'): `` closer must survive the rewrite byte-for-byte.
increment = _record(
"urllib3.util.retry",
"Incremented Retry for (url='%s'): %r",
("/private/BearerSecret?token=QuerySecret", "Retry(total=1, connect=2, read=None, redirect=None, status=None, other=None, allowed_methods=None)"),
)
assert filt.filter(increment) is True
assert increment.getMessage() == "Incremented Retry for (url='/<redacted>'): 'Retry(total=1, connect=2, read=None, redirect=None, status=None, other=None, allowed_methods=None)'"
# The same line on the redirect path carries an ABSOLUTE target. The
# round-8 review repro: the generic pass's ``rest`` swallowed the
# ``'): `` closer and mangled the line — ``rest`` now stops at quotes, so
# the absolute URL is rewritten in place with the closer intact.
increment_absolute = _record(
"urllib3.util.retry",
"Incremented Retry for (url='%s'): %r",
("https://cdn.example/private/BearerSecret?token=QuerySecret", "Retry(total=1, connect=2)"),
)
assert filt.filter(increment_absolute) is True
assert increment_absolute.getMessage() == "Incremented Retry for (url='https://cdn.example/<redacted>'): 'Retry(total=1, connect=2)'"
# Userinfo in the absolute increment target is blanked like everywhere
# else, with the closing quote intact.
increment_userinfo = _record(
"urllib3.util.retry",
"Incremented Retry for (url='%s'): %r",
("https://user:tok@internal-proxy.corp:8080/private/BearerSecret", "Retry(total=1)"),
)
assert filt.filter(increment_userinfo) is True
assert increment_userinfo.getMessage() == "Incremented Retry for (url='https://<redacted>@internal-proxy.corp:8080/<redacted>'): 'Retry(total=1)'"
# connectionpool.py:869 — WARNING level, so it passes an INFO root. The
# error repr keeps its own quotes; the greedy split still pins the target
# to the final ``': `` and the error text survives for observability.
# Args are real objects, matching how urlopen calls the site.
import urllib3
retries_obj = urllib3.Retry(total=2, redirect=0)
timeout_err = urllib3.exceptions.ReadTimeoutError(None, None, "Read timed out.")
retrying = _record(
"urllib3.connectionpool",
"Retrying (%r) after connection broken by '%r': %s",
(retries_obj, timeout_err, "/private/BearerSecret?token=QuerySecret"),
)
assert filt.filter(retrying) is True
# Exact line equality: only the target changed; retry state and error
# text (observability) survive verbatim.
assert retrying.getMessage() == f"Retrying ({retries_obj!r}) after connection broken by '{timeout_err!r}': /<redacted>"
assert "BearerSecret" not in retrying.getMessage()
assert "Read timed out" in retrying.getMessage()
# Redirecting (poolmanager.py:500 INFO / connectionpool.py:922 DEBUG):
# either slot may be an origin-form target — connectionpool passes the
# origin-form request target, and a relative Location header has no
# scheme. Origin-form slots collapse; absolute slots are the generic
# pass's job.
redirect_origin = logging.LogRecord("urllib3.connectionpool", logging.DEBUG, __file__, 1, "Redirecting %s -> %s", ("/private/BearerSecret?token=QuerySecret", "/other/BearerSecret?sig=OtherSecret"), None)
assert filt.filter(redirect_origin) is True
assert redirect_origin.getMessage() == "Redirecting /<redacted> -> /<redacted>"
redirect_mixed = logging.LogRecord("urllib3.poolmanager", logging.INFO, __file__, 1, "Redirecting %s -> %s", ("/private/BearerSecret?token=QuerySecret", "https://mirror.example/other?sig=OtherSecret"), None)
assert filt.filter(redirect_mixed) is True
assert redirect_mixed.getMessage() == "Redirecting /<redacted> -> https://mirror.example/<redacted>"
# A raw Location field from a misbehaving server can contain interior
# whitespace. It must not disable the source-target redaction.
redirect_spaced_location = logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
"Redirecting %s -> %s",
("/private/BearerSecret?token=QuerySecret", "/bad location"),
None,
)
assert filt.filter(redirect_spaced_location) is True
assert redirect_spaced_location.getMessage() == "Redirecting /<redacted> -> /<redacted>"
# Lowercase custom methods ride the same request-line shape (methods are
# case-sensitive tokens; callers may pass any case).
lowercase = logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
'%s://%s:%s "%s %s %s" %s %s',
("https", "cdn.example", 443, "patch", "/private/BearerSecret?token=QuerySecret", "HTTP/1.1", 200, None),
None,
)
assert filt.filter(lowercase) is True
assert lowercase.getMessage() == 'https://cdn.example:443 "patch /<redacted> HTTP/1.1" 200 None'
# Adjacent non-URL lines must pass through untouched: the shapes are
# anchored to the exact urllib3 formats, not to the word "Retry".
plain_retry = _record("some.other.lib", "Retry: attempt scheduled soon", ())
assert filt.filter(plain_retry) is True
assert plain_retry.getMessage() == "Retry: attempt scheduled soon"
plain_conn = _record("urllib3.connectionpool", "Starting new HTTP connection (%d): %s:%s", (1, "cdn.example", 443))
assert filt.filter(plain_conn) is True
assert plain_conn.getMessage() == "Starting new HTTP connection (1): cdn.example:443"
def test_url_redaction_filter_covers_urllib3_retry_lines_through_real_emit() -> None:
"""Real-emitter wiring for the retry lines: the increment line is produced
by actually calling ``Retry.increment`` (retry.py:545 logs through the
``urllib3.util.retry`` child logger at DEBUG), and the connectionpool
shapes are emitted through the real child logger with the exact installed
format strings. Only the handler-level filters installed by
configure_logging can rewrite propagated records."""
import urllib3
from urllib3.util.retry import Retry
from deerflow.logging_config import configure_logging
root = logging.getLogger()
old_handlers = root.handlers[:]
old_level = root.level
stream = io.StringIO()
handler = logging.StreamHandler(stream)
try:
root.handlers = [handler]
root.setLevel(logging.DEBUG)
configure_logging(SimpleNamespace(log_level="debug", logging=SimpleNamespace(enhance=SimpleNamespace(enabled=False, format="text"))))
# retry.py:545 via the library's own code path (no-args increment
# takes the generic-response branch and logs without raising).
Retry(total=2).increment(method="GET", url="/private/BearerSecret?token=QuerySecret")
logging.getLogger("urllib3.connectionpool").debug("Retry: %s", "/private/BearerSecret?token=QuerySecret")
logging.getLogger("urllib3.connectionpool").warning(
"Retrying (%r) after connection broken by '%r': %s",
Retry(total=2, redirect=0),
urllib3.exceptions.ReadTimeoutError(None, None, "Read timed out."),
"/private/BearerSecret?token=QuerySecret",
)
logging.getLogger("urllib3.connectionpool").debug(
"Redirecting %s -> %s",
"/private/BearerSecret?token=QuerySecret",
"https://mirror.example/other/BearerSecret?sig=OtherSecret",
)
out = stream.getvalue()
assert "BearerSecret" not in out
assert "QuerySecret" not in out
assert "OtherSecret" not in out
# Redacted, not suppressed: every line still renders with its shape
# and the parts that carry no URL (retry state, error text, hosts).
assert "Incremented Retry for (url='/<redacted>')" in out
assert "Retry: /<redacted>" in out
assert "after connection broken by" in out and "Read timed out" in out and "': /<redacted>" in out
assert "Redirecting /<redacted> -> https://mirror.example/<redacted>" in out
finally:
root.handlers = old_handlers
root.setLevel(old_level)
def test_configure_logging_installs_url_redaction_on_httpx_logger_and_root_handlers() -> None:
from deerflow.logging_config import UrlRedactionFilter, _has_url_redaction_filter, configure_logging, install_url_log_redaction
httpx_logger = logging.getLogger("httpx")
root = logging.getLogger()
old_filters = httpx_logger.filters[:]
old_handlers = root.handlers[:]
handler = logging.StreamHandler(io.StringIO())
try:
root.handlers = [handler]
httpx_logger.filters = [f for f in old_filters if not isinstance(f, UrlRedactionFilter)]
install_url_log_redaction()
install_url_log_redaction() # idempotent
assert sum(isinstance(f, UrlRedactionFilter) for f in httpx_logger.filters) == 1
assert all(_has_url_redaction_filter(h) for h in root.handlers)
# Handlers added later are covered by the configure_logging loop, not
# by the one-shot installer.
late = logging.StreamHandler(io.StringIO())
root.handlers.append(late)
configure_logging(SimpleNamespace(log_level="info", logging=SimpleNamespace(enhance=SimpleNamespace(enabled=False, format="text"))))
assert _has_url_redaction_filter(late)
assert _has_url_redaction_filter(root.handlers[0])
finally:
httpx_logger.filters = old_filters
root.handlers = old_handlers
def test_url_redaction_filter_long_input_stays_linear_time() -> None:
"""Long-input regression (round-9 review finding): both scheme-bearing
patterns start with a character class, so re.sub-style scanning retries
every suffix of a long token — the reviewer measured ~1.79 s for a 64K
path and ~3.10 s for a URL-free 64K error body, per filter call, and the
filter runs synchronously in every root handler. The scheme passes are
driven from "://" occurrences instead, so the same inputs cost
milliseconds. The bound is generous (the quadratic path at 256K would
take tens of seconds) to stay robust on slow CI runners, while still
going red against any regression to per-position rescanning."""
import time
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
# Ordinary HTTPX URL whose path is a 256K letter run. httpx.URL rejects
# URLs this long, so the record is built directly with the URL as a
# plain string arg — the rendered message shape is identical.
record = logging.LogRecord(
"httpx",
logging.INFO,
__file__,
1,
_HTTPX_REQUEST_FORMAT,
("GET", "https://cdn.weixin.qq.com/private/" + "A" * 262144, "HTTP/1.1", 200, "OK"),
None,
)
started = time.perf_counter()
assert filt.filter(record) is True
elapsed_url = time.perf_counter() - started
assert elapsed_url < 5.0, f"URL-bearing record took {elapsed_url:.2f}s"
formatted = record.getMessage()
assert "cdn.weixin.qq.com/<redacted>" in formatted # still redacted, and
assert "A" * 64 not in formatted # the long path itself did not survive
# A URL-free 64K letter error body through the real wiring: the filter
# runs in the root handler, and the message must pass through verbatim.
root = logging.getLogger()
old_handlers = root.handlers[:]
old_level = root.level
stream = io.StringIO()
handler = logging.StreamHandler(stream)
try:
root.handlers = [handler]
root.setLevel(logging.INFO)
configure_logging(SimpleNamespace(log_level="info", logging=SimpleNamespace(enhance=SimpleNamespace(enabled=False, format="text"))))
body = "E" * 65536
started = time.perf_counter()
logging.getLogger("some.error.reporter").error("payload too large: %s", body)
elapsed_plain = time.perf_counter() - started
assert elapsed_plain < 5.0, f"URL-free record took {elapsed_plain:.2f}s"
assert stream.getvalue().endswith("payload too large: " + body + "\n")
finally:
root.handlers = old_handlers
root.setLevel(old_level)
def test_url_redaction_filter_nested_scheme_in_path_keeps_both_passes() -> None:
"""The scheme-bearing passes run per "://" start, so a scheme-shaped
target NESTED inside another URL's path still gets its own pass attempt:
the outer absolute URL is rewritten first (its rest swallows the inner
scheme text), and the inner request-line shape — if the path is followed
by urllib3 quoting — is rewritten by the request-line pass that ran
before it. Pins the leftmost-non-overlapping equivalence with the old
two-pass re.sub behavior on overlapping candidates."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
record = logging.LogRecord(
"httpx",
logging.INFO,
__file__,
1,
"fetch failed for %s and %s",
("https://gateway.example/redirect?to=https://evil.example/sink", 'https://evil.example "GET /private/BearerSecret?token=QuerySecret HTTP/1.1" 200 None'),
None,
)
assert filt.filter(record) is True
formatted = record.getMessage()
assert "BearerSecret" not in formatted
assert "token=" not in formatted
assert "gateway.example/<redacted>" in formatted
# The nested request line kept its quoted target redacted too.
assert 'https://evil.example "GET /<redacted> HTTP/1.1"' in formatted
def test_url_redaction_filter_scheme_start_skips_non_letter_run_head() -> None:
"""The linear scan walks back over the full scheme charset (letters,
digits, +, -, .) but a regex match can only start at the run's first
LETTER — digits are valid scheme tail characters, never the head. A
digit glued in front of a URL shifts the match start past it, exactly
like re.sub's leftmost scan; a run with no letter at all ("123://x")
cannot start any match and passes through with nothing rewritten."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
glued = logging.LogRecord("httpx", logging.INFO, __file__, 1, "fetch %s", ("9https://host.example/private/x?token=QuerySecret",), None)
assert filt.filter(glued) is True
assert glued.getMessage() == "fetch 9https://host.example/<redacted>"
digits_only = logging.LogRecord("httpx", logging.INFO, __file__, 1, "fetch %s", ("123://host.example/private/x?token=QuerySecret",), None)
assert filt.filter(digits_only) is True
# "123" is not a scheme head, so no scheme starts at this "://" — the
# text is left as-is by the scheme passes (no URL rewrite, no signal
# loss; the record itself is not a valid URL shape).
assert digits_only.getMessage() == "fetch 123://host.example/private/x?token=QuerySecret"
def test_url_redaction_filter_embedded_quotes_stay_inside_rest() -> None:
"""Boundary rule for the rest quote-stop (round-10 residual): a quote is
a closing mark only when whitespace, ``)``, or end of string follows —
the shapes that actually close a quoted URL (urllib3's
``Incremented Retry for (url='')`` scaffolding, surrounding prose). A
quote EMBEDDED in the URL itself (``/path'quoted'?token=…``) must be
consumed so the whole path+query stays redacted; the earlier
quote-stop-at-any-quote behavior kept the suffix after the quote
verbatim."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
# The review repro, through the real httpx record shape: httpx.URL keeps
# an apostrophe raw, so the embedded quote is present verbatim in the
# rendered message. rest must consume it — the credential-bearing suffix
# does not survive. (The httpx format quotes "version status reason"
# together.)
embedded = _httpx_record("https://host.example/path'quoted'?token=QuerySecret")
assert filt.filter(embedded) is True
assert embedded.getMessage() == 'HTTP Request: GET https://host.example/<redacted> "HTTP/1.1 200 OK"'
assert "quoted" not in embedded.getMessage()
assert "token=" not in embedded.getMessage()
# A raw embedded DOUBLE quote (httpx.URL would percent-encode %22, so
# this rides a plain string arg — MCP/extension riders may log
# pre-rendered URLs).
embedded_double = logging.LogRecord(
"httpx",
logging.INFO,
__file__,
1,
_HTTPX_REQUEST_FORMAT,
("GET", 'https://host.example/pa"th?token=QuerySecret', "HTTP/1.1", 200, "OK"),
None,
)
assert filt.filter(embedded_double) is True
assert embedded_double.getMessage() == 'HTTP Request: GET https://host.example/<redacted> "HTTP/1.1 200 OK"'
assert "token=" not in embedded_double.getMessage()
# Boundary quotes still close rest: prose quoting keeps its punctuation.
prose_double = logging.LogRecord("some.lib", logging.INFO, __file__, 1, "see %s in the docs", ('"https://host.example/private/x?tok=1"',), None)
assert filt.filter(prose_double) is True
assert prose_double.getMessage() == 'see "https://host.example/<redacted>" in the docs'
prose_single = logging.LogRecord("some.lib", logging.INFO, __file__, 1, "see %s please", ("'https://host.example/private/x?tok=1'",), None)
assert filt.filter(prose_single) is True
assert prose_single.getMessage() == "see 'https://host.example/<redacted>' please"
# The increment line's url capture applies the same rule with its fixed
# ``')`` closer: an embedded quote inside the target no longer truncates
# the capture, so the whole origin-form target collapses.
increment = logging.LogRecord(
"urllib3.util.retry",
logging.DEBUG,
__file__,
1,
"Incremented Retry for (url='%s'): %r",
("/a'b?tok=QuerySecret", "Retry(total=1)"),
None,
)
assert filt.filter(increment) is True
assert increment.getMessage() == "Incremented Retry for (url='/<redacted>'): 'Retry(total=1)'"
assert "tok=" not in increment.getMessage()
def test_url_redaction_filter_leaves_arrow_paths_in_other_logs_alone() -> None:
"""The Redirecting origin pass is anchored to the WHOLE ``Redirecting
<t> -> <t>`` message because an ``-> /path`` arrow is not urllib3-owned
shape: the sandbox provider's actionable mount error renders
``sandbox.mounts entry <host_path> -> <container_path>`` and a substring
match rewrote the container path to ``/<redacted>``, breaking the error's
instructions (backend-unit-tests shard 3 on CI, round 11)."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
sandbox_error = (
"sandbox.mounts entry /srv/deer-flow/knowledge -> /mnt/knowledge ignored: host_path "
"/srv/deer-flow/knowledge does not exist from the perspective of the gateway process. "
"In Docker deployments (make up / docker-compose), this path must also be bind-mounted "
"into the gateway container — add a matching volume entry under services.gateway.volumes "
"in docker/docker-compose.yaml (and use the in-container path here), or run in local mode "
"(make dev) where the gateway sees the host filesystem directly."
)
record = logging.LogRecord("deerflow.sandbox.local.local_sandbox_provider", logging.ERROR, "provider.py", 1, "%s", (sandbox_error,), None)
assert filt.filter(record) is True
assert record.getMessage() == sandbox_error # byte-for-byte passthrough
assert "/mnt/knowledge" in record.getMessage()
assert "<redacted>" not in record.getMessage()
def test_url_redaction_filter_redirecting_survives_spacey_location() -> None:
"""Round-13 P3: the Redirecting anchor keeps the ``^Redirecting `` prefix
(the urllib3-owned literal that stops the sandbox false positive) but the
tail must be loose — ``redirect_location`` is the raw Location header
string, and interior spaces are legal field syntax a misbehaving server
can emit. A whitespace-strict tail voided the pass entirely and leaked
the origin-form request target in the first slot; a space-carrying
second slot now collapses whole."""
from deerflow.logging_config import UrlRedactionFilter
filt = UrlRedactionFilter()
# The reviewer's repro: both credentials must go, shape kept.
spacey = logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
"Redirecting %s -> %s",
("/private/BearerSecret?token=QuerySecret", "/bad location"),
None,
)
assert filt.filter(spacey) is True
assert spacey.getMessage() == "Redirecting /<redacted> -> /<redacted>"
assert "BearerSecret" not in spacey.getMessage()
# The FIRST slot gets the same grammar treatment: the recursive urlopen
# frame passes the previous raw Location as its url, so t1 can carry
# interior spaces too.
spacey_t1 = logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
"Redirecting %s -> %s",
("/bad target?token=QuerySecret", "/private/x"),
None,
)
assert filt.filter(spacey_t1) is True
assert spacey_t1.getMessage() == "Redirecting /<redacted> -> /<redacted>"
assert "QuerySecret" not in spacey_t1.getMessage()
# An absolute Location with an interior space stays whole for the
# generic absolute-URL pass (which stops its rest at whitespace).
spacey_absolute = logging.LogRecord(
"urllib3.connectionpool",
logging.DEBUG,
__file__,
1,
"Redirecting %s -> %s",
("/private/BearerSecret?token=QuerySecret", "https://mirror.example/other page?sig=OtherSecret"),
None,
)
assert filt.filter(spacey_absolute) is True
assert spacey_absolute.getMessage() == "Redirecting /<redacted> -> https://mirror.example/<redacted> page?sig=OtherSecret"
assert "BearerSecret" not in spacey_absolute.getMessage()
# The sandbox arrow false positive stays excluded: the prefix anchor,
# not a strict tail, is what keeps non-Redirecting messages untouched.
sandbox = logging.LogRecord("deerflow.sandbox.local.local_sandbox_provider", logging.ERROR, "p.py", 1, "sandbox.mounts entry /srv/knowledge -> /mnt/knowledge ignored: missing", (), None)
assert filt.filter(sandbox) is True
assert sandbox.getMessage() == "sandbox.mounts entry /srv/knowledge -> /mnt/knowledge ignored: missing"