mirror of
https://github.com/NousResearch/hermes-agent.git
synced 2026-11-06 05:17:15 +00:00
fix(redact): the log formatter reads no config
RedactingFormatter resolved a routed profile's redaction policy per record from config, under the logging handler's lock. It now reads only in-memory state: the live secret scope, and the policy recorded when that profile's .env or config is loaded, or when log routing is set up for it (resolve_profile_policy). Unknown means redact, the secure default. This removes load_config_readonly_nowait() and the no-boot read scope.
This commit is contained in:
1 parent
b4d8e4c332
commit
e924f75176
8 files changed
+106
-112
No files matched your search
+45
-36
@@ -103,50 +103,59 @@ _SENSITIVE_QUERY_PARAMS = frozenset({
|
||||
_REDACT_ENABLED = os.getenv("HERMES_REDACT_SECRETS", "true").lower() in {"1", "true", "yes", "on"}
|
||||
|
||||
# Routed multiplex profiles: the import-time snapshot above is the LAUNCH profile's policy. A profile
|
||||
# served under a HERMES_HOME override resolves its own ``security.redact_secrets`` (its ``.env``
|
||||
# value first, like the standalone bridge in hermes_cli/main.py), cached per home so the hot path
|
||||
# stays a dict lookup. Still not a live ``os.environ`` read, so a shell ``export`` cannot flip it.
|
||||
_REDACT_ENABLED_BY_HOME: dict = {}
|
||||
_REDACT_ENABLED_LOCK = threading.Lock()
|
||||
# served under a HERMES_HOME override follows its own ``security.redact_secrets`` (its ``.env`` value
|
||||
# first, like the standalone bridge in hermes_cli/main.py). The formatter never reads config or files
|
||||
# for it (it runs under the logging handler's lock, per record): the values are recorded when that
|
||||
# profile's .env / config is loaded (``note_env_policy`` / ``note_config_policy``) or when log routing
|
||||
# is set up for it (``resolve_profile_policy``). Until then the profile redacts (the secure default).
|
||||
_ENV_POLICY_BY_HOME: dict = {} # home key -> raw HERMES_REDACT_SECRETS from its .env, or None
|
||||
_CONFIG_POLICY_BY_HOME: dict = {} # home key -> raw security.redact_secrets from its config, or None
|
||||
|
||||
|
||||
def note_env_policy(home_key: str, raw) -> None:
|
||||
_ENV_POLICY_BY_HOME[home_key] = None if raw is None else str(raw)
|
||||
|
||||
|
||||
def note_config_policy(home_key: str, raw) -> None:
|
||||
_CONFIG_POLICY_BY_HOME[home_key] = None if raw is None else str(raw)
|
||||
|
||||
|
||||
def resolve_profile_policy(home) -> None:
|
||||
"""Record ``home``'s redaction policy now (log-routing setup), so its records never wait for it."""
|
||||
from hermes_constants import hermes_home_key, reset_hermes_home_override, set_hermes_home_override
|
||||
token = set_hermes_home_override(home)
|
||||
try:
|
||||
key = hermes_home_key()
|
||||
from hermes_cli.config import load_config_readonly, load_env
|
||||
note_env_policy(key, load_env().get("HERMES_REDACT_SECRETS"))
|
||||
note_config_policy(key, (load_config_readonly().get("security") or {}).get("redact_secrets"))
|
||||
except (Exception, SystemExit) as exc: # health: allow BLE001 -- unreadable now: stays unknown, which redacts
|
||||
logging.getLogger(__name__).debug("redaction policy for %s not read: %s", home, exc)
|
||||
finally:
|
||||
reset_hermes_home_override(token)
|
||||
|
||||
|
||||
def _redact_enabled() -> bool:
|
||||
"""Effective redaction switch for the active profile (launch snapshot when no override)."""
|
||||
"""Effective redaction switch for the active profile (launch snapshot when no override). Reads
|
||||
only in-memory state: the live secret scope and the recorded per-profile policy."""
|
||||
from hermes_constants import get_hermes_home_override, hermes_home_key
|
||||
if get_hermes_home_override() is None:
|
||||
return _REDACT_ENABLED
|
||||
home_key = hermes_home_key()
|
||||
cached = _REDACT_ENABLED_BY_HOME.get(home_key)
|
||||
if cached is not None:
|
||||
return cached
|
||||
enabled = True
|
||||
try:
|
||||
from agent.secret_scope import current_secret_scope
|
||||
scope = current_secret_scope()
|
||||
raw = scope.get("HERMES_REDACT_SECRETS") if scope else None
|
||||
if raw is None and scope is None:
|
||||
# No live scope (the log listener thread formats routed records): read the profile's own .env, as
|
||||
# its scope would, or a first call there would cache a config-only answer for the whole process.
|
||||
from hermes_cli.config import load_env
|
||||
raw = load_env().get("HERMES_REDACT_SECRETS")
|
||||
if raw is None:
|
||||
# Never wait for config here: this runs under the logging handler's lock, and the
|
||||
# thread holding the config lock (or booting this profile's config) may be logging.
|
||||
from hermes_cli.config import load_config_readonly_nowait
|
||||
cfg = load_config_readonly_nowait()
|
||||
if cfg is None:
|
||||
return True # not readable at once: the secure default, not cached
|
||||
cfg_val = (cfg.get("security") or {}).get("redact_secrets")
|
||||
raw = None if cfg_val is None else str(cfg_val)
|
||||
if raw is not None:
|
||||
enabled = str(raw).strip().lower() in {"1", "true", "yes", "on"}
|
||||
except Exception:
|
||||
enabled = True # unreadable policy: keep the secure default
|
||||
except SystemExit: # ConfigBackendUnavailable: config not loadable now; never cache that
|
||||
from agent.secret_scope import current_secret_scope
|
||||
scope = current_secret_scope()
|
||||
raw = scope.get("HERMES_REDACT_SECRETS") if scope else None
|
||||
if raw is None and scope is None:
|
||||
# No live scope (the log listener thread formats routed records): the profile's own .env, as
|
||||
# its scope would have it. Not recorded yet: redact, since .env may opt the profile back in.
|
||||
if home_key not in _ENV_POLICY_BY_HOME:
|
||||
return True
|
||||
raw = _ENV_POLICY_BY_HOME[home_key]
|
||||
if raw is None:
|
||||
raw = _CONFIG_POLICY_BY_HOME.get(home_key)
|
||||
if raw is None:
|
||||
return True
|
||||
with _REDACT_ENABLED_LOCK:
|
||||
_REDACT_ENABLED_BY_HOME[home_key] = enabled
|
||||
return enabled
|
||||
return str(raw).strip().lower() in {"1", "true", "yes", "on"}
|
||||
|
||||
# Known API key prefixes -- match the prefix + contiguous token chars.
|
||||
# Every pattern MUST start with a literal prefix: _PREFIX_SUBSTRINGS (the cheap
|
||||
|
||||
+12
-17
@@ -1982,22 +1982,6 @@ def load_config() -> dict[str, Any]:
|
||||
return _load_config_impl(want_deepcopy=True)
|
||||
|
||||
|
||||
def load_config_readonly_nowait() -> Optional[dict[str, Any]]:
|
||||
""":func:`load_config_readonly` for code that must never wait (a log formatter, under the
|
||||
handler's lock). None when ``_CONFIG_LOCK`` is held elsewhere or the read would start a remote
|
||||
boot fetch: callers use a secure default and must not cache it."""
|
||||
from hermes_cli.config_backend import ConfigBackendUnavailable, without_boot
|
||||
if not _CONFIG_LOCK.acquire(blocking=False):
|
||||
return None
|
||||
try:
|
||||
with without_boot():
|
||||
return load_config_readonly()
|
||||
except ConfigBackendUnavailable:
|
||||
return None
|
||||
finally:
|
||||
_CONFIG_LOCK.release()
|
||||
|
||||
|
||||
def load_config_readonly() -> dict[str, Any]:
|
||||
"""``load_config()`` without the defensive deepcopy (~half of the 265us cache-hit cost).
|
||||
**Mutating the returned dict (or any nested structure) corrupts the in-process cache for
|
||||
@@ -2298,6 +2282,7 @@ def _load_config_impl(*, want_deepcopy: bool) -> dict[str, Any]:
|
||||
normalized = _canonicalize_config(config)
|
||||
expanded, managed_config = _merge_managed_overlay(_expand_env_vars(normalized))
|
||||
_LAST_EXPANDED_CONFIG_BY_PATH[path_key] = copy.deepcopy(expanded)
|
||||
_note_policy("note_config_policy", (expanded.get("security") or {}).get("redact_secrets"))
|
||||
if cache_sig is not None:
|
||||
# The cache stores its own deepcopy so load_config() callers can mutate freely while
|
||||
# load_config_readonly() callers all see the same stable object. The env snapshot
|
||||
@@ -2436,7 +2421,17 @@ def load_env() -> dict[str, str]:
|
||||
return {}
|
||||
from agent.secret_scope import load_env_file # the one .env tokenizer; also installs profile scopes
|
||||
|
||||
return load_env_file(get_env_path())
|
||||
env = load_env_file(get_env_path())
|
||||
_note_policy("note_env_policy", env.get("HERMES_REDACT_SECRETS"))
|
||||
return env
|
||||
|
||||
|
||||
def _note_policy(setter: str, raw: Any) -> None:
|
||||
"""Record the loaded profile's redaction policy for the log formatter, which never reads config."""
|
||||
note = getattr(sys.modules.get("agent.redact"), setter, None)
|
||||
if note is not None:
|
||||
from hermes_constants import hermes_home_key
|
||||
note(hermes_home_key(), raw)
|
||||
|
||||
|
||||
def _parse_env_value(raw_value: str) -> str:
|
||||
|
||||
@@ -526,25 +526,6 @@ def refused_locked_omission_prefixes() -> tuple[str, ...]:
|
||||
# Dotted keys a document save in this context stores at the user layer even when the value equals
|
||||
# what an upper level already supplies (an explicit `config set`): the file backend always writes
|
||||
# them, and a backend with levels must not drop them as "no change".
|
||||
_NO_BOOT: contextvars.ContextVar[bool] = contextvars.ContextVar("config_no_boot", default=False)
|
||||
|
||||
|
||||
@contextlib.contextmanager
|
||||
def without_boot():
|
||||
"""Reads in this scope never start loading a profile's config (a remote boot fetch, with its
|
||||
network calls and retries): a backend raises :class:`ConfigBackendUnavailable` instead. For
|
||||
code that must never wait, such as a log formatter."""
|
||||
token = _NO_BOOT.set(True)
|
||||
try:
|
||||
yield
|
||||
finally:
|
||||
_NO_BOOT.reset(token)
|
||||
|
||||
|
||||
def boot_allowed() -> bool:
|
||||
return not _NO_BOOT.get()
|
||||
|
||||
|
||||
_PINNED_KEYS: contextvars.ContextVar[tuple[str, ...]] = contextvars.ContextVar("config_pinned_keys", default=())
|
||||
|
||||
|
||||
|
||||
@@ -935,6 +935,10 @@ def enable_profile_log_routing(profile_homes: Sequence[str | Path]) -> bool:
|
||||
homes.append(resolved)
|
||||
if len(homes) < 2:
|
||||
return False
|
||||
# Each routed profile's redaction policy, read now: the formatter never reads config per record.
|
||||
from agent.redact import resolve_profile_policy
|
||||
for home in homes:
|
||||
resolve_profile_policy(home)
|
||||
|
||||
with _queue_state_lock:
|
||||
if not _queued_file_handlers:
|
||||
|
||||
@@ -21,7 +21,6 @@ from dataclasses import dataclass, field
|
||||
from pathlib import Path
|
||||
from typing import Any, Dict, List, Optional, Tuple
|
||||
|
||||
from hermes_cli.config_backend import boot_allowed as config_backend_boot_allowed
|
||||
from hermes_cli.config_backend import (
|
||||
Changes, ConfigBackendUnavailable, ConfigLockedError, ConfigValueError, ConfigWriteError, UserLayer,
|
||||
pinned_keys, refused_locked_omission_prefixes)
|
||||
@@ -207,9 +206,6 @@ class RemoteBackend:
|
||||
if poller is None or self._poller_pid != os.getpid() or not poller.is_alive():
|
||||
self._ensure_poller()
|
||||
return st
|
||||
if not config_backend_boot_allowed():
|
||||
raise ConfigBackendUnavailable(
|
||||
f"Remote Config: the config for {home} is not loaded yet, and this read does not wait for it.")
|
||||
if key in self._booting():
|
||||
# This thread is loading this profile (resolving its credential or fetching): the read
|
||||
# can only be served by the load it is part of. Waiting would wait on itself forever.
|
||||
|
||||
@@ -107,15 +107,11 @@ def test_nothing_is_logged_under_a_backend_lock(plane, monkeypatch):
|
||||
|
||||
|
||||
def test_boot_retry_warning_through_the_real_redacting_formatter(plane, monkeypatch):
|
||||
"""The boot's retry warning is formatted by RedactingFormatter, which reads the routed profile's
|
||||
redaction policy from config: on the booting thread that read must not re-enter the boot (it
|
||||
would abort it), and it must never wait for the config lock another thread holds."""
|
||||
"""The boot's retry warning goes through RedactingFormatter on a routed profile: formatting reads
|
||||
no config, so it neither re-enters the boot nor waits for a lock a config reader holds."""
|
||||
import logging
|
||||
import threading
|
||||
|
||||
from agent import redact
|
||||
from agent.redact import RedactingFormatter
|
||||
from hermes_cli import config as config_mod
|
||||
from hermes_constants import reset_hermes_home_override, set_hermes_home_override
|
||||
|
||||
backend = remote_pkg.get_remote_backend()
|
||||
@@ -133,40 +129,50 @@ def test_boot_retry_warning_through_the_real_redacting_formatter(plane, monkeypa
|
||||
return resp
|
||||
|
||||
monkeypatch.setattr(backend_mod.client, "request", first_get_fails)
|
||||
monkeypatch.setattr(redact, "_REDACT_ENABLED_BY_HOME", {})
|
||||
handler = Handler(level=logging.WARNING)
|
||||
handler.setFormatter(RedactingFormatter("%(message)s"))
|
||||
backend_mod.logger.addHandler(handler)
|
||||
plane.upper = {"display": {"skin": "ares"}}
|
||||
plane.fail_status = 503
|
||||
token = set_hermes_home_override(plane.home) # a routed profile: the formatter reads its config
|
||||
token = set_hermes_home_override(plane.home)
|
||||
try:
|
||||
assert backend.read_user_doc(plane.home)["display"]["skin"] == "ares" # booted after one retry
|
||||
assert any("retrying" in m for m in formatted), formatted
|
||||
assert len(_gets(plane)) == 2
|
||||
assert redact._REDACT_ENABLED_BY_HOME == {} # the boot-time fallback was not cached
|
||||
|
||||
# Another thread holds the config lock: formatting returns at once with the secure default.
|
||||
held, release = threading.Event(), threading.Event()
|
||||
|
||||
def holder():
|
||||
with config_mod._CONFIG_LOCK:
|
||||
held.set()
|
||||
release.wait(10)
|
||||
|
||||
t = threading.Thread(target=holder, daemon=True)
|
||||
t.start()
|
||||
assert held.wait(5)
|
||||
try:
|
||||
done: list = []
|
||||
worker = threading.Thread(target=lambda: done.append(redact._redact_enabled()), daemon=True)
|
||||
worker.start()
|
||||
worker.join(5)
|
||||
assert done == [True], "the formatter waited for the config lock"
|
||||
assert redact._REDACT_ENABLED_BY_HOME == {}
|
||||
finally:
|
||||
release.set()
|
||||
t.join(5)
|
||||
finally:
|
||||
reset_hermes_home_override(token)
|
||||
backend_mod.logger.removeHandler(handler)
|
||||
assert any("retrying" in m for m in formatted), formatted
|
||||
assert len(_gets(plane)) == 2
|
||||
|
||||
|
||||
def test_the_formatter_never_reads_config(tmp_path, monkeypatch):
|
||||
"""Under a backend whose every read raises, a routed profile's records still format, redacted
|
||||
(its policy is not recorded yet: the secure default), and no config read is attempted."""
|
||||
import logging
|
||||
|
||||
import hermes_cli.config_backend as cb
|
||||
from agent import redact
|
||||
from agent.redact import RedactingFormatter
|
||||
from hermes_constants import hermes_home_key, reset_hermes_home_override, set_hermes_home_override
|
||||
|
||||
reads: list = []
|
||||
|
||||
def refuse(*args, **kwargs):
|
||||
reads.append(args)
|
||||
raise ConfigBackendUnavailable("this test's backend refuses every read")
|
||||
|
||||
monkeypatch.setattr(cb, "_route", refuse)
|
||||
monkeypatch.setattr(redact, "_ENV_POLICY_BY_HOME", {})
|
||||
monkeypatch.setattr(redact, "_CONFIG_POLICY_BY_HOME", {})
|
||||
monkeypatch.setattr(redact, "_REDACT_ENABLED", False) # the launch profile opted out
|
||||
secret = "sk-proj-" + "c" * 32
|
||||
record = logging.LogRecord("t", logging.WARNING, __file__, 1, "key %s", (secret,), None)
|
||||
token = set_hermes_home_override(tmp_path)
|
||||
try:
|
||||
out = RedactingFormatter("%(message)s").format(record)
|
||||
redact.note_env_policy(hermes_home_key(), None)
|
||||
redact.note_config_policy(hermes_home_key(), "false") # recorded later: the profile opted out
|
||||
out_after = RedactingFormatter("%(message)s").format(record)
|
||||
finally:
|
||||
reset_hermes_home_override(token)
|
||||
assert secret not in out and secret in out_after
|
||||
assert reads == []
|
||||
@@ -138,7 +138,8 @@ class TestSetupLogging:
|
||||
@pytest.mark.parametrize("launch_redacts, routed_opt_out, routed_redacted", [
|
||||
(False, None, True), # the launch profile opted out, the routed one did not
|
||||
(True, "env", False), # the routed profile opted out in its own .env
|
||||
], ids=["launch-opt-out", "routed-env-opt-out"])
|
||||
(True, "config", False), # the routed profile opted out in its config
|
||||
], ids=["launch-opt-out", "routed-env-opt-out", "routed-config-opt-out"])
|
||||
def test_routed_records_follow_their_own_profiles_redaction_policy(
|
||||
self, hermes_home, tmp_path, monkeypatch, launch_redacts, routed_opt_out, routed_redacted):
|
||||
"""The listener thread formats every record after its profile scope is gone, so a routed profile's own
|
||||
@@ -147,7 +148,8 @@ class TestSetupLogging:
|
||||
from hermes_constants import reset_hermes_home_override, set_hermes_home_override
|
||||
|
||||
monkeypatch.setattr(redact, "_REDACT_ENABLED", launch_redacts)
|
||||
monkeypatch.setattr(redact, "_REDACT_ENABLED_BY_HOME", {})
|
||||
monkeypatch.setattr(redact, "_ENV_POLICY_BY_HOME", {})
|
||||
monkeypatch.setattr(redact, "_CONFIG_POLICY_BY_HOME", {})
|
||||
routed = tmp_path / "profile-b"
|
||||
routed.mkdir()
|
||||
if routed_opt_out == "config":
|
||||
|
||||
@@ -134,7 +134,8 @@ def test_profile_scoped_process_caches_follow_routed_home(two_homes, monkeypatch
|
||||
|
||||
a, b = two_homes
|
||||
monkeypatch.setattr(redact, "_REDACT_ENABLED", False) # launch profile opted out
|
||||
redact._REDACT_ENABLED_BY_HOME.clear()
|
||||
monkeypatch.setattr(redact, "_ENV_POLICY_BY_HOME", {})
|
||||
monkeypatch.setattr(redact, "_CONFIG_POLICY_BY_HOME", {})
|
||||
token = "sk-abcdefghijklmnopqrstuvwxyz0123456789"
|
||||
assert redact.redact_sensitive_text(token) == token
|
||||
assert _under(b, lambda: redact.redact_sensitive_text(token)) != token
|
||||
|
||||
Reference in new issue
Block a user