mirror of
https://github.com/bytedance/deer-flow.git
synced 2026-09-19 19:16:17 +00:00
* 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>
734 lines
34 KiB
Python
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"
|