mirror of
https://github.com/bytedance/deer-flow.git
synced 2026-09-25 14:06:18 +00:00
4bc4241531
A Redirecting slot stayed verbatim unless it started with "/", but the
Location field-value grammar (RFC 3986 relative-part) also admits
slash-less relative references: 'Redirecting /private/x?token=Q ->
download?sign=LeakedSig' rendered the signed query verbatim, and neither
the slot rule nor the generic absolute-URL pass (which needs a scheme)
could see it. A slot is now kept only when a scheme matches at position
0 (left for the generic pass to rewrite); everything else collapses -
slash-less relative paths, query-only and fragment-only forms,
network-path references (collapsing any userinfo they carry), and
non-hierarchical schemes such as data: URIs. The ^Redirecting prefix
anchor is unchanged, so non-URL '-> /path' arrows (sandbox mount
mappings) keep passing through untouched.
Regression table covers all relative-reference forms plus the absolute
regression anchor; mutation-verified (reverting to startswith('/') goes
red). Aligned with the fix sketched in the #5225 round-15 review thread.
390 lines
20 KiB
Python
390 lines
20 KiB
Python
"""Logging setup helpers for DeerFlow."""
|
|
|
|
from __future__ import annotations
|
|
|
|
import json
|
|
import logging
|
|
import re
|
|
from collections.abc import Iterator
|
|
from datetime import UTC, datetime
|
|
from typing import Any
|
|
|
|
from deerflow.config.app_config import apply_logging_level
|
|
from deerflow.trace_context import get_current_trace_id
|
|
|
|
DEFAULT_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
|
|
DEFAULT_LOG_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
|
|
TRACE_TEXT_LOG_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - [trace_id=%(trace_id)s] - %(message)s"
|
|
_TRACE_FILTER_NAME = "deerflow_trace_context_filter"
|
|
|
|
# httpx logs ``HTTP Request: GET <full URL> HTTP/x.x <status> <duration>`` at
|
|
# INFO before any response handling runs, and urllib3 logs
|
|
# ``Redirecting <url> -> <url>`` at INFO when a redirect is followed. Inbound
|
|
# media URLs are signed — the credentials live in the query string, and the
|
|
# repo-wide inbound-media rule is that no part of a media URL beyond its host
|
|
# may reach the logs — so even successful downloads would leak unless the
|
|
# record itself is rewritten. The authority is split so userinfo (basic-auth
|
|
# ``user:pass@`` credentials, accepted by httpx for MCP/extension/community-
|
|
# tool endpoints) is blanked too, not just the path and query. ``rest`` is
|
|
# optional so an authority-only URL (``scheme://user:pass@host`` — no path)
|
|
# is still rewritten; a bare credential-free origin passes through as-is.
|
|
# ``rest`` treats a quote as a closing mark only at a boundary — followed by
|
|
# whitespace, a closing parenthesis, or end of string — so URLs wrapped in
|
|
# surrounding prose or a format's own quoting (urllib3's
|
|
# ``Incremented Retry for (url='…')``) keep their closing punctuation, while
|
|
# a quote EMBEDDED in the URL (``/path'quoted'?token=…``) is consumed and
|
|
# everything after it stays redacted.
|
|
_URL_REDACT_RE = re.compile(r"(?P<scheme>[a-zA-Z][a-zA-Z0-9+.-]*://)(?P<userinfo>[^/?#\s@]*@)?(?P<host>[^/?#\s]+)(?P<rest>[/?#](?:[^\s'\"]|['\"](?!$|\s|\)))*)?")
|
|
|
|
# urllib3's per-request DEBUG line (connectionpool.py:545 on urllib3 2.7.0)
|
|
# splits the URL across the format string:
|
|
# ``'%s://%s:%s "%s %s %s" %s %s'`` renders as
|
|
# ``scheme://host:port "GET /private/x?token=y HTTP/1.1" 200 None`` — the
|
|
# authority and the signed origin-form target are two separate args. The
|
|
# absolute-URL regex above cannot see either half: the authority is followed
|
|
# by a space (so ``rest`` never matches and the bare-origin early return
|
|
# applies) and the quoted target has no scheme. The request line therefore
|
|
# gets its own shape — authority immediately followed by a quoted
|
|
# ``METHOD target HTTP/x.x`` line — rewritten to scheme + host with the
|
|
# target collapsed to ``/<redacted>``. The method class is case-tolerant:
|
|
# HTTP methods are case-sensitive tokens, and callers may pass lowercase
|
|
# custom methods through to urllib3.
|
|
_URLLIB3_REQUEST_LINE_RE = re.compile(r'(?P<scheme>[a-zA-Z][a-zA-Z0-9+.-]*://)(?P<userinfo>[^/?#\s"@]*@)?(?P<host>[^/?#\s"]+) "(?P<method>[A-Za-z]+) (?P<target>/[^"\s]*) (?P<version>HTTP/[0-9.]+)"')
|
|
|
|
# urllib3's retry sites log the request target with NO scheme and NO request-
|
|
# line scaffolding, so neither pattern above can see it (installed 2.7.0):
|
|
# - ``Retry: %s`` — connectionpool.py:954, DEBUG, origin-form target.
|
|
# - ``Incremented Retry for (url='%s'): %r`` — util/retry.py:545, DEBUG via
|
|
# the ``urllib3.util.retry`` logger; the target is origin-form on the
|
|
# request path and absolute on the redirect path (poolmanager resolves the
|
|
# Location before retrying). The url capture applies the same boundary
|
|
# idea as ``rest``, narrowed to this format's fixed ``')`` closer: an
|
|
# embedded quote is consumed, the closing quote is the one directly
|
|
# followed by ``)``. Absolute targets are left for the generic absolute-
|
|
# URL pass — its ``rest`` stops at the closing quote — while origin-form
|
|
# targets collapse to ``/<redacted>``.
|
|
# - ``Retrying (%r) after connection broken by '%r': %s`` —
|
|
# connectionpool.py:869, **WARNING**, so it passes the Gateway's INFO root
|
|
# without DEBUG being enabled; the greedy prefix groups pin the split to
|
|
# the final ``': `` so an error repr containing quotes cannot shift it.
|
|
_URLLIB3_RETRY_TARGET_RE = re.compile(r"^Retry: (?P<target>/\S+)$")
|
|
_URLLIB3_INCREMENT_RETRY_RE = re.compile(r"Incremented Retry for \(url='(?P<url>(?:[^']|'(?!\)))*)'\)")
|
|
_URLLIB3_RETRYING_RE = re.compile(r"^(?P<head>Retrying \(.*\) after connection broken by .*'): (?P<target>/\S+)$")
|
|
|
|
# urllib3's ``Redirecting %s -> %s`` (poolmanager.py:500 at INFO,
|
|
# connectionpool.py:922 at DEBUG) can carry an origin-form target in either
|
|
# slot: connectionpool passes the origin-form request target, and the Location
|
|
# header may itself be a relative reference (RFC 9110 allows it). The generic
|
|
# absolute-URL pass only sees scheme-bearing halves, so origin-form slots
|
|
# collapse to ``/<redacted>`` here; absolute slots are left for that pass.
|
|
# The pattern keeps the ``^Redirecting `` prefix anchor — the urllib3-owned
|
|
# literal — because an ``-> /path`` arrow is not urllib3-owned shape:
|
|
# non-URL logs render it too (sandbox mount mappings log
|
|
# ``sandbox.mounts entry <host_path> -> <container_path>``), and a substring
|
|
# match rewrote the container path in that actionable error (CI round 11).
|
|
# The tail is deliberately 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 would void the pass entirely
|
|
# and leak the origin-form request target in the first slot (round 13). A
|
|
# space-carrying second slot collapses whole when it starts with ``/``. 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 — it is lazy, splitting at the FIRST `` -> `` the way the
|
|
# line was constructed left to right.
|
|
_URLLIB3_REDIRECTING_ORIGIN_RE = re.compile(r"^Redirecting (?P<t1>\S.*?) -> (?P<t2>\S.*)$")
|
|
|
|
# A Redirecting slot is kept only when it starts with an absolute
|
|
# hierarchical URL; everything else (every RFC 3986 relative-reference
|
|
# form, and non-hierarchical schemes) collapses — see _redact_redirecting_origin.
|
|
_SLOT_ABSOLUTE_URL_RE = re.compile(r"[a-zA-Z][a-zA-Z0-9+.-]*://")
|
|
|
|
# The two scheme-bearing patterns start with a character class, so re.sub
|
|
# retries the match at every position of a long token — a letter run with no
|
|
# ``://`` makes each attempt walk to the end of the run, which is quadratic
|
|
# overall (a 64K-character path or error body costs seconds per record, and
|
|
# this filter runs synchronously in every root handler). Both are instead
|
|
# driven from the literal ``://`` occurrences: each one walks back over the
|
|
# scheme charset to the first letter of its maximal run, and the pattern is
|
|
# attempted only there. A regex match can only start at such a position, and
|
|
# if it fails at the run's first letter it fails identically at every other
|
|
# letter of the run (the scheme group is the only part that differs), so this
|
|
# reproduces re.sub's leftmost-non-overlapping result in linear time. The
|
|
# span-skip below is safe for the same reason: a match of either pattern
|
|
# always ends at a character outside the scheme charset (whitespace, quote,
|
|
# ``/``, ``?``, ``#``, or end of string — never a letter/digit/``+``/``-``/
|
|
# ``.``), so a scheme run — and with it a candidate start — can never
|
|
# straddle a previous match's end; re.sub likewise never re-enters a
|
|
# consumed span.
|
|
_SCHEME_TAIL_CHARS = frozenset("ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789+.-")
|
|
_SCHEME_HEAD_CHARS = frozenset("ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz")
|
|
|
|
|
|
def _scheme_starts(message: str) -> Iterator[int]:
|
|
pos = message.find("://")
|
|
while pos != -1:
|
|
start = pos
|
|
while start > 0 and message[start - 1] in _SCHEME_TAIL_CHARS:
|
|
start -= 1
|
|
# Leading non-letters (digits, +, -, .) are valid scheme TAIL
|
|
# characters but cannot start the scheme, so the match starts at the
|
|
# run's first letter; a run with none cannot start a match at all.
|
|
while start < pos and message[start] not in _SCHEME_HEAD_CHARS:
|
|
start += 1
|
|
if start < pos:
|
|
yield start
|
|
pos = message.find("://", pos + 1)
|
|
|
|
|
|
def _redact_scheme_bearing(pattern: re.Pattern[str], rewrite, message: str) -> str:
|
|
parts: list[str] = []
|
|
last = 0
|
|
for start in _scheme_starts(message):
|
|
if start < last: # inside the span of the previous match
|
|
continue
|
|
match = pattern.match(message, start)
|
|
if match is None:
|
|
continue
|
|
parts.append(message[last:start])
|
|
parts.append(rewrite(match))
|
|
last = match.end()
|
|
if not parts:
|
|
return message
|
|
parts.append(message[last:])
|
|
return "".join(parts)
|
|
|
|
|
|
class UrlRedactionFilter(logging.Filter):
|
|
"""Redact URLs in httpx/urllib3 request log records down to scheme + host.
|
|
|
|
Path, query, fragment, and any userinfo credentials in the authority are
|
|
replaced; the host (and port) stay for operator debuggability. urllib3
|
|
splits or disassembles the URL across several of its own log formats, and
|
|
the generic absolute-URL pattern only sees a scheme-bearing URL in one
|
|
piece, so each remaining shape gets its own rewrite anchored to the
|
|
exact urllib3 format — ``^``-anchored for whole-message lines, literal-
|
|
prefix-anchored otherwise: the
|
|
per-request ``scheme://host:port "METHOD target HTTP/x.x"`` line, the
|
|
retry lines that log a bare origin-form target (``Retry: <target>``,
|
|
``Incremented Retry for (url='<target>')``, ``Retrying (…) after
|
|
connection broken by '…': <target>``), and every non-absolute slot of
|
|
``Redirecting <target> -> <target>`` (kept whole only when a scheme
|
|
starts the slot, for the generic pass to rewrite). The record is rewritten in place
|
|
(``msg`` set to the redacted formatted message, ``args`` cleared) so
|
|
every downstream handler and formatter — text or JSON — sees the same
|
|
redacted line, while the method/status/error observability is preserved.
|
|
The scheme-bearing patterns are attempted only at ``://``-anchored
|
|
scheme starts, so filtering a record costs linear time in its message
|
|
length. A URL is rewritten only when it carries something to hide
|
|
(userinfo, path, query, or fragment); a bare credential-free origin and
|
|
records without any URL pass through untouched.
|
|
"""
|
|
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
message = record.getMessage()
|
|
|
|
def _redact(match: re.Match[str]) -> str:
|
|
if not (match.group("userinfo") or match.group("rest")):
|
|
return match.group(0) # bare origin: nothing to redact
|
|
userinfo = "<redacted>@" if match.group("userinfo") else ""
|
|
return match.group("scheme") + userinfo + match.group("host") + "/<redacted>"
|
|
|
|
def _redact_request_line(match: re.Match[str]) -> str:
|
|
userinfo = "<redacted>@" if match.group("userinfo") else ""
|
|
return match.group("scheme") + userinfo + match.group("host") + ' "' + match.group("method") + " /<redacted> " + match.group("version") + '"'
|
|
|
|
def _redact_increment(match: re.Match[str]) -> str:
|
|
url = match.group("url")
|
|
if _URL_REDACT_RE.fullmatch(url):
|
|
# Absolute target (redirect path): the generic absolute-URL
|
|
# pass rewrites it, and its rest stops at the closing quote.
|
|
return match.group(0)
|
|
return "Incremented Retry for (url='/<redacted>')"
|
|
|
|
def _redact_retry_target(match: re.Match[str]) -> str:
|
|
return "Retry: /<redacted>"
|
|
|
|
def _redact_retrying(match: re.Match[str]) -> str:
|
|
return match.group("head") + ": /<redacted>"
|
|
|
|
def _redact_redirecting_origin(match: re.Match[str]) -> str:
|
|
# A slot stays verbatim ONLY when it is an absolute URL (a
|
|
# scheme at position 0), so the generic absolute-URL pass —
|
|
# which runs after this one — rewrites it. Everything else
|
|
# collapses: the Location field-value grammar (RFC 3986
|
|
# relative-part) also admits slash-less relative references
|
|
# (``download?sign=…``, ``?sign=…``, ``#frag``), network-path
|
|
# references (``//host/x``, whose userinfo collapses with it),
|
|
# and non-hierarchical schemes (``data:…``) — none of which
|
|
# either pass could otherwise see, and the slash-less forms
|
|
# kept their signed queries verbatim (round 15).
|
|
def _slot(target: str) -> str:
|
|
return target if _SLOT_ABSOLUTE_URL_RE.match(target) else "/<redacted>"
|
|
|
|
return "Redirecting " + _slot(match.group("t1")) + " -> " + _slot(match.group("t2"))
|
|
|
|
# The urllib3 shape passes run before the absolute-URL pass: their
|
|
# rewrites either leave scheme-bearing text for that pass to handle
|
|
# or collapse the target before it could interact with surrounding
|
|
# punctuation, while the reverse order would already have rewritten
|
|
# an authority into shapes the urllib3 patterns no longer match. The
|
|
# two scheme-bearing passes scan from ``://`` occurrences (see
|
|
# _scheme_starts) instead of re.sub, so long letter runs in any
|
|
# record — URL paths or URL-free error bodies — stay linear-time.
|
|
redacted = _redact_scheme_bearing(_URLLIB3_REQUEST_LINE_RE, _redact_request_line, message)
|
|
redacted = _URLLIB3_INCREMENT_RETRY_RE.sub(_redact_increment, redacted)
|
|
redacted = _URLLIB3_RETRY_TARGET_RE.sub(_redact_retry_target, redacted)
|
|
redacted = _URLLIB3_RETRYING_RE.sub(_redact_retrying, redacted)
|
|
redacted = _URLLIB3_REDIRECTING_ORIGIN_RE.sub(_redact_redirecting_origin, redacted)
|
|
redacted = _redact_scheme_bearing(_URL_REDACT_RE, _redact, redacted)
|
|
if redacted != message:
|
|
record.msg = redacted
|
|
record.args = None
|
|
return True
|
|
|
|
|
|
# The filter class is generic over the formatted message, so it serves any
|
|
# HTTP client library whose records embed full URLs. Where it must be
|
|
# ATTACHED differs per library, because a logging.Filter on a logger only
|
|
# runs for records emitted through that exact logger — it is not inherited
|
|
# by child loggers and never sees propagated records:
|
|
# - httpx emits via the bare ``httpx`` logger, so a logger filter works.
|
|
# - urllib3 emits via children (``urllib3.poolmanager`` logs
|
|
# ``Redirecting <url> -> <url>`` at INFO, ``urllib3.connectionpool`` logs
|
|
# redirect lines, the per-request authority/quoted-target line, and the
|
|
# ``Retry:``/``Retrying`` lines at DEBUG/WARNING, and ``urllib3.util.retry``
|
|
# logs ``Incremented Retry for (url=…)`` at DEBUG), so a filter on bare
|
|
# ``urllib3`` is dead code. Handler-level filters DO see propagated
|
|
# records, so the filter is also attached to every root handler — covering
|
|
# urllib3 and any future library without knowing its logger names.
|
|
# The enumeration of urllib3's URL-bearing lines is closed against the
|
|
# installed source (2.7.0): every other emitter logs host:port only
|
|
# (connection establishment/reset) or an absolute URL in one piece
|
|
# (``connection.py``'s header-parse warning), which the generic absolute-URL
|
|
# pass rewrites without a dedicated shape. The closure is version-anchored:
|
|
# a urllib3 upgrade can change these format strings and silently reopen it —
|
|
# re-run the emitter enumeration when bumping the dependency.
|
|
_REDACTED_LOGGER_NAMES = ("httpx",)
|
|
|
|
|
|
def _has_url_redaction_filter(handler: logging.Handler) -> bool:
|
|
return any(isinstance(item, UrlRedactionFilter) for item in handler.filters)
|
|
|
|
|
|
def _install_url_redaction_filter(handler: logging.Handler) -> None:
|
|
if not _has_url_redaction_filter(handler):
|
|
handler.addFilter(UrlRedactionFilter())
|
|
|
|
|
|
def install_url_log_redaction() -> None:
|
|
"""Attach URL redaction to the ``httpx`` logger and to every root handler.
|
|
|
|
The httpx logger filter covers records at their emission point (httpx
|
|
logs via the bare ``httpx`` name); the root-handler filters cover
|
|
propagated records from libraries that emit through child loggers, such
|
|
as urllib3's ``urllib3.poolmanager`` / ``urllib3.connectionpool``.
|
|
"""
|
|
for logger_name in _REDACTED_LOGGER_NAMES:
|
|
target = logging.getLogger(logger_name)
|
|
if not any(isinstance(item, UrlRedactionFilter) for item in target.filters):
|
|
target.addFilter(UrlRedactionFilter())
|
|
for handler in logging.root.handlers:
|
|
_install_url_redaction_filter(handler)
|
|
|
|
|
|
class TraceContextFilter(logging.Filter):
|
|
"""Inject the current request trace id into every log record."""
|
|
|
|
name = _TRACE_FILTER_NAME
|
|
|
|
def filter(self, record: logging.LogRecord) -> bool:
|
|
record.trace_id = get_current_trace_id() or "-"
|
|
return True
|
|
|
|
|
|
class JsonTraceFormatter(logging.Formatter):
|
|
"""Small JSON formatter used when ``logging.enhance.format=json``."""
|
|
|
|
_deerflow_trace_formatter = True
|
|
|
|
def format(self, record: logging.LogRecord) -> str:
|
|
if not hasattr(record, "trace_id"):
|
|
record.trace_id = get_current_trace_id() or "-"
|
|
payload: dict[str, Any] = {
|
|
"timestamp": datetime.fromtimestamp(record.created, UTC).isoformat(),
|
|
"logger": record.name,
|
|
"level": record.levelname,
|
|
"trace_id": record.trace_id,
|
|
"message": record.getMessage(),
|
|
}
|
|
if record.exc_info:
|
|
payload["exc_info"] = self.formatException(record.exc_info)
|
|
if record.stack_info:
|
|
payload["stack_info"] = self.formatStack(record.stack_info)
|
|
return json.dumps(payload, ensure_ascii=False)
|
|
|
|
|
|
class TraceTextFormatter(logging.Formatter):
|
|
"""Marker subclass so trace formatting can be reverted cleanly in tests."""
|
|
|
|
_deerflow_trace_formatter = True
|
|
|
|
|
|
def _ensure_root_handler() -> None:
|
|
if logging.root.handlers:
|
|
return
|
|
logging.basicConfig(level=logging.INFO, format=DEFAULT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
|
|
|
|
|
|
def _has_trace_filter(handler: logging.Handler) -> bool:
|
|
return any(getattr(f, "name", None) == _TRACE_FILTER_NAME or isinstance(f, TraceContextFilter) for f in handler.filters)
|
|
|
|
|
|
def _install_trace_filter(handler: logging.Handler) -> None:
|
|
if not _has_trace_filter(handler):
|
|
handler.addFilter(TraceContextFilter())
|
|
|
|
|
|
def _remove_trace_filter(handler: logging.Handler) -> None:
|
|
handler.filters = [f for f in handler.filters if not (getattr(f, "name", None) == _TRACE_FILTER_NAME or isinstance(f, TraceContextFilter))]
|
|
|
|
|
|
def _default_formatter() -> logging.Formatter:
|
|
return logging.Formatter(DEFAULT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
|
|
|
|
|
|
def _trace_formatter(format_name: str | None) -> logging.Formatter:
|
|
if (format_name or "text").strip().lower() == "json":
|
|
return JsonTraceFormatter()
|
|
return TraceTextFormatter(TRACE_TEXT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
|
|
|
|
|
|
def configure_logging(config: object) -> None:
|
|
"""Configure DeerFlow logging from an AppConfig-like object.
|
|
|
|
With logging enhancement disabled this preserves the previous
|
|
``basicConfig + apply_logging_level`` behavior. With enhancement enabled,
|
|
root handlers gain a trace-context filter and a formatter that includes
|
|
only the additional ``trace_id`` field.
|
|
"""
|
|
_ensure_root_handler()
|
|
install_url_log_redaction()
|
|
|
|
logging_config = getattr(config, "logging", None)
|
|
enhance = getattr(logging_config, "enhance", None)
|
|
enhanced = bool(getattr(enhance, "enabled", False))
|
|
|
|
for handler in logging.root.handlers:
|
|
_install_url_redaction_filter(handler)
|
|
# URL redaction is level-agnostic and applies whether or not the
|
|
# trace enhancement is on; handler filters see propagated records
|
|
# from child loggers (urllib3 et al.), which logger filters cannot.
|
|
if enhanced:
|
|
_install_trace_filter(handler)
|
|
handler.setFormatter(_trace_formatter(getattr(enhance, "format", "text")))
|
|
else:
|
|
_remove_trace_filter(handler)
|
|
if getattr(handler.formatter, "_deerflow_trace_formatter", False):
|
|
handler.setFormatter(_default_formatter())
|
|
|
|
apply_logging_level(getattr(config, "log_level", None))
|