feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
"""Tests for hermes_logging — centralized logging setup."""
|
|
|
|
|
|
|
|
|
|
import logging
|
|
|
|
|
import os
|
feat(nix): shared-state permission model for interactive CLI users (#6796)
* feat(nix): shared-state permission model for interactive CLI users
Enable interactive CLI users in the hermes group to share full
read-write state (sessions, memories, logs, cron) with the gateway
service via a setgid + group-writable permission model.
Changes:
nix/nixosModules.nix:
- Directories use setgid 2770 (was 0750) so new files inherit the
hermes group. home/ stays 0750 (no interactive write needed).
- Activation script creates HERMES_HOME subdirs (cron, sessions, logs,
memories) — previously Python created them but managed mode now skips
mkdir.
- Activation migrates existing runtime files to group-writable (chmod
g+rw). Nix-managed files (config.yaml, .env, .managed) stay 0640/0644.
- Gateway systemd unit gets UMask=0007 so files it creates are 0660.
hermes_cli/config.py:
- ensure_hermes_home() splits into managed/unmanaged paths. Managed mode
verifies dirs exist (raises RuntimeError if not) instead of creating
them. Scoped umask(0o007) ensures SOUL.md is created as 0660.
hermes_logging.py:
- _ManagedRotatingFileHandler subclass applies chmod 0660 after log
rotation in managed mode. RotatingFileHandler.doRollover() creates new
files via open() which uses the process umask (0022 → 0644), not the
scoped umask from ensure_hermes_home().
Verified with a 13-subtest NixOS VM integration test covering setgid,
interactive writes, file ownership, migration, and gateway coexistence.
Refs: #6044
* Fix managed log file mode on initial open
Co-authored-by: Siddharth Balyan <alt-glitch@users.noreply.github.com>
* refactor: simplify managed file handler and merge activation loops
- Cache is_managed() result in handler __init__ instead of lazy-importing
on every _open()/_chmod_if_managed() call. Avoids repeated stat+env
checks on log rotation.
- Merge two for-loops over the same subdir list in activation script
into a single loop (mkdir + chown + chmod + find in one pass).
---------
Co-authored-by: Cursor Agent <cursoragent@cursor.com>
Co-authored-by: Siddharth Balyan <alt-glitch@users.noreply.github.com>
2026-04-09 15:18:42 -07:00
|
|
|
import stat
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
import threading
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
from logging.handlers import RotatingFileHandler
|
|
|
|
|
from pathlib import Path
|
|
|
|
|
from unittest.mock import patch
|
|
|
|
|
|
|
|
|
|
import pytest
|
|
|
|
|
|
|
|
|
|
import hermes_logging
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
@pytest.fixture(autouse=True)
|
|
|
|
|
def _reset_logging_state():
|
|
|
|
|
"""Reset the module-level sentinel and clean up root logger handlers
|
fix: repair 57 failing CI tests across 14 files (#5823)
* fix: repair 57 failing CI tests across 14 files
Categories of fixes:
**Test isolation under xdist (-n auto):**
- test_hermes_logging: Strip ALL RotatingFileHandlers before each test
to prevent handlers leaked from other xdist workers from polluting counts
- test_code_execution: Force TERMINAL_ENV=local in setUp — prevents Modal
AuthError when another test leaks TERMINAL_ENV=modal
- test_timezone: Same TERMINAL_ENV fix for execute_code timezone tests
- test_codex_execution_paths: Mock _resolve_turn_agent_config to ensure
model resolution works regardless of xdist worker state
**Matrix adapter tests (nio not installed in CI):**
- Add _make_fake_nio() helper with real response classes for isinstance()
checks in production code
- Replace MagicMock(spec=nio.XxxResponse) with fake_nio instances
- Wrap production method calls with patch.dict('sys.modules', {'nio': ...})
so import nio succeeds in method bodies
- Use try/except instead of pytest.importorskip for nio.crypto imports
(importorskip can be fooled by MagicMock in sys.modules)
- test_matrix_voice: Skip entire file if nio is a mock, not just missing
**Stale test expectations:**
- test_cli_provider_resolution: _prompt_provider_choice now takes **kwargs
(default param added); mock getpass.getpass alongside input
- test_anthropic_oauth_flow: Mock getpass.getpass (code switched from input)
- test_gemini_provider: Mock models.dev + OpenRouter API lookups to test
hardcoded defaults without external API variance
- test_code_execution: Add notify_on_complete to blocked terminal params
- test_setup_openclaw_migration: Mock prompt_choice to select 'Full setup'
(new quick-setup path leads to _require_tty → sys.exit in CI)
- test_skill_manager_tool: Patch get_all_skills_dirs alongside SKILLS_DIR
so _find_skill searches tmp_path, not real ~/.hermes/skills/
**Missing attributes in object.__new__ test runners:**
- test_platform_reconnect: Add session_store to _make_runner()
- test_session_race_guard: Add hooks, _running_agents_ts, session_store,
delivery_router to _make_runner()
**Production bug fix (gateway/run.py):**
- Fix sentinel eviction race: _AGENT_PENDING_SENTINEL was immediately
evicted by the stale-detection logic because sentinels have no
get_activity_summary() method, causing _stale_idle=inf >= timeout.
Guard _should_evict with 'is not _AGENT_PENDING_SENTINEL'.
* fix: address remaining CI failures
- test_setup_openclaw_migration: Also mock _offer_launch_chat (called at
end of both quick and full setup paths)
- test_code_execution: Move TERMINAL_ENV=local to module level to protect
ALL test classes (TestEnvVarFiltering, TestExecuteCodeEdgeCases,
TestInterruptHandling, TestHeadTailTruncation) from xdist env leaks
- test_matrix: Use try/except for nio.crypto imports (importorskip can be
fooled by MagicMock in sys.modules under xdist)
2026-04-07 09:58:45 -07:00
|
|
|
added by setup_logging() so tests don't leak state.
|
|
|
|
|
|
|
|
|
|
Under xdist (-n auto) other test modules may have called setup_logging()
|
|
|
|
|
in the same worker process, leaving RotatingFileHandlers on the root
|
|
|
|
|
logger. We strip ALL RotatingFileHandlers before each test so the count
|
|
|
|
|
assertions are stable regardless of test ordering.
|
|
|
|
|
"""
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
hermes_logging._logging_initialized = False
|
|
|
|
|
root = logging.getLogger()
|
fix: repair 57 failing CI tests across 14 files (#5823)
* fix: repair 57 failing CI tests across 14 files
Categories of fixes:
**Test isolation under xdist (-n auto):**
- test_hermes_logging: Strip ALL RotatingFileHandlers before each test
to prevent handlers leaked from other xdist workers from polluting counts
- test_code_execution: Force TERMINAL_ENV=local in setUp — prevents Modal
AuthError when another test leaks TERMINAL_ENV=modal
- test_timezone: Same TERMINAL_ENV fix for execute_code timezone tests
- test_codex_execution_paths: Mock _resolve_turn_agent_config to ensure
model resolution works regardless of xdist worker state
**Matrix adapter tests (nio not installed in CI):**
- Add _make_fake_nio() helper with real response classes for isinstance()
checks in production code
- Replace MagicMock(spec=nio.XxxResponse) with fake_nio instances
- Wrap production method calls with patch.dict('sys.modules', {'nio': ...})
so import nio succeeds in method bodies
- Use try/except instead of pytest.importorskip for nio.crypto imports
(importorskip can be fooled by MagicMock in sys.modules)
- test_matrix_voice: Skip entire file if nio is a mock, not just missing
**Stale test expectations:**
- test_cli_provider_resolution: _prompt_provider_choice now takes **kwargs
(default param added); mock getpass.getpass alongside input
- test_anthropic_oauth_flow: Mock getpass.getpass (code switched from input)
- test_gemini_provider: Mock models.dev + OpenRouter API lookups to test
hardcoded defaults without external API variance
- test_code_execution: Add notify_on_complete to blocked terminal params
- test_setup_openclaw_migration: Mock prompt_choice to select 'Full setup'
(new quick-setup path leads to _require_tty → sys.exit in CI)
- test_skill_manager_tool: Patch get_all_skills_dirs alongside SKILLS_DIR
so _find_skill searches tmp_path, not real ~/.hermes/skills/
**Missing attributes in object.__new__ test runners:**
- test_platform_reconnect: Add session_store to _make_runner()
- test_session_race_guard: Add hooks, _running_agents_ts, session_store,
delivery_router to _make_runner()
**Production bug fix (gateway/run.py):**
- Fix sentinel eviction race: _AGENT_PENDING_SENTINEL was immediately
evicted by the stale-detection logic because sentinels have no
get_activity_summary() method, causing _stale_idle=inf >= timeout.
Guard _should_evict with 'is not _AGENT_PENDING_SENTINEL'.
* fix: address remaining CI failures
- test_setup_openclaw_migration: Also mock _offer_launch_chat (called at
end of both quick and full setup paths)
- test_code_execution: Move TERMINAL_ENV=local to module level to protect
ALL test classes (TestEnvVarFiltering, TestExecuteCodeEdgeCases,
TestInterruptHandling, TestHeadTailTruncation) from xdist env leaks
- test_matrix: Use try/except for nio.crypto imports (importorskip can be
fooled by MagicMock in sys.modules under xdist)
2026-04-07 09:58:45 -07:00
|
|
|
# Strip ALL RotatingFileHandlers — not just the ones we added — so that
|
|
|
|
|
# handlers leaked from other test modules in the same xdist worker don't
|
|
|
|
|
# pollute our counts.
|
|
|
|
|
pre_existing = []
|
|
|
|
|
for h in list(root.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
|
|
|
|
root.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
else:
|
|
|
|
|
pre_existing.append(h)
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
# Ensure the record factory is installed (it's idempotent).
|
|
|
|
|
hermes_logging._install_session_record_factory()
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
yield
|
|
|
|
|
# Restore — remove any handlers added during the test.
|
|
|
|
|
for h in list(root.handlers):
|
fix: repair 57 failing CI tests across 14 files (#5823)
* fix: repair 57 failing CI tests across 14 files
Categories of fixes:
**Test isolation under xdist (-n auto):**
- test_hermes_logging: Strip ALL RotatingFileHandlers before each test
to prevent handlers leaked from other xdist workers from polluting counts
- test_code_execution: Force TERMINAL_ENV=local in setUp — prevents Modal
AuthError when another test leaks TERMINAL_ENV=modal
- test_timezone: Same TERMINAL_ENV fix for execute_code timezone tests
- test_codex_execution_paths: Mock _resolve_turn_agent_config to ensure
model resolution works regardless of xdist worker state
**Matrix adapter tests (nio not installed in CI):**
- Add _make_fake_nio() helper with real response classes for isinstance()
checks in production code
- Replace MagicMock(spec=nio.XxxResponse) with fake_nio instances
- Wrap production method calls with patch.dict('sys.modules', {'nio': ...})
so import nio succeeds in method bodies
- Use try/except instead of pytest.importorskip for nio.crypto imports
(importorskip can be fooled by MagicMock in sys.modules)
- test_matrix_voice: Skip entire file if nio is a mock, not just missing
**Stale test expectations:**
- test_cli_provider_resolution: _prompt_provider_choice now takes **kwargs
(default param added); mock getpass.getpass alongside input
- test_anthropic_oauth_flow: Mock getpass.getpass (code switched from input)
- test_gemini_provider: Mock models.dev + OpenRouter API lookups to test
hardcoded defaults without external API variance
- test_code_execution: Add notify_on_complete to blocked terminal params
- test_setup_openclaw_migration: Mock prompt_choice to select 'Full setup'
(new quick-setup path leads to _require_tty → sys.exit in CI)
- test_skill_manager_tool: Patch get_all_skills_dirs alongside SKILLS_DIR
so _find_skill searches tmp_path, not real ~/.hermes/skills/
**Missing attributes in object.__new__ test runners:**
- test_platform_reconnect: Add session_store to _make_runner()
- test_session_race_guard: Add hooks, _running_agents_ts, session_store,
delivery_router to _make_runner()
**Production bug fix (gateway/run.py):**
- Fix sentinel eviction race: _AGENT_PENDING_SENTINEL was immediately
evicted by the stale-detection logic because sentinels have no
get_activity_summary() method, causing _stale_idle=inf >= timeout.
Guard _should_evict with 'is not _AGENT_PENDING_SENTINEL'.
* fix: address remaining CI failures
- test_setup_openclaw_migration: Also mock _offer_launch_chat (called at
end of both quick and full setup paths)
- test_code_execution: Move TERMINAL_ENV=local to module level to protect
ALL test classes (TestEnvVarFiltering, TestExecuteCodeEdgeCases,
TestInterruptHandling, TestHeadTailTruncation) from xdist env leaks
- test_matrix: Use try/except for nio.crypto imports (importorskip can be
fooled by MagicMock in sys.modules under xdist)
2026-04-07 09:58:45 -07:00
|
|
|
if h not in pre_existing:
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
root.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
hermes_logging._logging_initialized = False
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
hermes_logging.clear_session_context()
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
|
|
|
|
|
|
|
|
|
|
@pytest.fixture
|
|
|
|
|
def hermes_home(tmp_path, monkeypatch):
|
|
|
|
|
"""Provide an isolated HERMES_HOME for logging tests.
|
|
|
|
|
|
|
|
|
|
Uses the same tmp_path as the autouse _isolate_hermes_home from conftest,
|
|
|
|
|
reading it back from the env var to avoid double-mkdir conflicts.
|
|
|
|
|
"""
|
|
|
|
|
home = Path(os.environ["HERMES_HOME"])
|
|
|
|
|
return home
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestSetupLogging:
|
|
|
|
|
"""setup_logging() creates agent.log + errors.log with RotatingFileHandler."""
|
|
|
|
|
|
|
|
|
|
def test_creates_log_directory(self, hermes_home):
|
|
|
|
|
log_dir = hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
assert log_dir == hermes_home / "logs"
|
|
|
|
|
assert log_dir.is_dir()
|
|
|
|
|
|
|
|
|
|
def test_creates_agent_log_handler(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(agent_handlers) == 1
|
|
|
|
|
assert agent_handlers[0].level == logging.INFO
|
|
|
|
|
|
|
|
|
|
def test_creates_errors_log_handler(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
|
|
|
|
|
error_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "errors.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(error_handlers) == 1
|
|
|
|
|
assert error_handlers[0].level == logging.WARNING
|
|
|
|
|
|
|
|
|
|
def test_idempotent_no_duplicate_handlers(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home) # second call — should be no-op
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(agent_handlers) == 1
|
|
|
|
|
|
|
|
|
|
def test_force_reinitializes(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
# Force still won't add duplicate handlers because _add_rotating_handler
|
|
|
|
|
# checks by resolved path.
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, force=True)
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(agent_handlers) == 1
|
|
|
|
|
|
|
|
|
|
def test_custom_log_level(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, log_level="DEBUG")
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert agent_handlers[0].level == logging.DEBUG
|
|
|
|
|
|
|
|
|
|
def test_custom_max_size_and_backup(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(
|
|
|
|
|
hermes_home=hermes_home, max_size_mb=10, backup_count=5
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert agent_handlers[0].maxBytes == 10 * 1024 * 1024
|
|
|
|
|
assert agent_handlers[0].backupCount == 5
|
|
|
|
|
|
|
|
|
|
def test_suppresses_noisy_loggers(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
assert logging.getLogger("openai").level >= logging.WARNING
|
|
|
|
|
assert logging.getLogger("httpx").level >= logging.WARNING
|
|
|
|
|
assert logging.getLogger("httpcore").level >= logging.WARNING
|
|
|
|
|
|
|
|
|
|
def test_writes_to_agent_log(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test_hermes_logging.write_test")
|
|
|
|
|
test_logger.info("test message for agent.log")
|
|
|
|
|
|
|
|
|
|
# Flush handlers
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
assert agent_log.exists()
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
assert "test message for agent.log" in content
|
|
|
|
|
|
|
|
|
|
def test_warnings_appear_in_both_logs(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test_hermes_logging.warning_test")
|
|
|
|
|
test_logger.warning("this is a warning")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
errors_log = hermes_home / "logs" / "errors.log"
|
|
|
|
|
assert "this is a warning" in agent_log.read_text()
|
|
|
|
|
assert "this is a warning" in errors_log.read_text()
|
|
|
|
|
|
|
|
|
|
def test_info_not_in_errors_log(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test_hermes_logging.info_test")
|
|
|
|
|
test_logger.info("info only message")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
errors_log = hermes_home / "logs" / "errors.log"
|
|
|
|
|
if errors_log.exists():
|
|
|
|
|
assert "info only message" not in errors_log.read_text()
|
|
|
|
|
|
|
|
|
|
def test_reads_config_yaml(self, hermes_home):
|
|
|
|
|
"""setup_logging reads logging.level from config.yaml."""
|
|
|
|
|
import yaml
|
|
|
|
|
config = {"logging": {"level": "DEBUG", "max_size_mb": 2, "backup_count": 1}}
|
|
|
|
|
(hermes_home / "config.yaml").write_text(yaml.dump(config))
|
|
|
|
|
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert agent_handlers[0].level == logging.DEBUG
|
|
|
|
|
assert agent_handlers[0].maxBytes == 2 * 1024 * 1024
|
|
|
|
|
assert agent_handlers[0].backupCount == 1
|
|
|
|
|
|
|
|
|
|
def test_explicit_params_override_config(self, hermes_home):
|
|
|
|
|
"""Explicit function params take precedence over config.yaml."""
|
|
|
|
|
import yaml
|
|
|
|
|
config = {"logging": {"level": "DEBUG"}}
|
|
|
|
|
(hermes_home / "config.yaml").write_text(yaml.dump(config))
|
|
|
|
|
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, log_level="WARNING")
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
agent_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "agent.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert agent_handlers[0].level == logging.WARNING
|
|
|
|
|
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
def test_record_factory_installed(self, hermes_home):
|
|
|
|
|
"""The custom record factory injects session_tag on all records."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
factory = logging.getLogRecordFactory()
|
|
|
|
|
assert getattr(factory, "_hermes_session_injector", False), (
|
|
|
|
|
"Record factory should have _hermes_session_injector marker"
|
|
|
|
|
)
|
|
|
|
|
# Verify session_tag exists on a fresh record
|
|
|
|
|
record = factory("test", logging.INFO, "", 0, "msg", (), None)
|
|
|
|
|
assert hasattr(record, "session_tag")
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestGatewayMode:
|
|
|
|
|
"""setup_logging(mode='gateway') creates a filtered gateway.log."""
|
|
|
|
|
|
|
|
|
|
def test_gateway_log_created(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
|
|
|
|
|
gw_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "gateway.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(gw_handlers) == 1
|
|
|
|
|
|
|
|
|
|
def test_gateway_log_not_created_in_cli_mode(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="cli")
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
|
|
|
|
|
gw_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "gateway.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(gw_handlers) == 0
|
|
|
|
|
|
2026-04-26 15:17:06 -06:00
|
|
|
def test_gateway_log_created_after_cli_init(self, hermes_home):
|
|
|
|
|
"""Gateway mode attaches gateway.log even after earlier CLI init."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="cli")
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
gw_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "gateway.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(gw_handlers) == 1
|
|
|
|
|
|
|
|
|
|
logging.getLogger("gateway.run").info("gateway connected after cli init")
|
|
|
|
|
|
|
|
|
|
for h in root.handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
gw_log = hermes_home / "logs" / "gateway.log"
|
|
|
|
|
assert gw_log.exists()
|
|
|
|
|
assert "gateway connected after cli init" in gw_log.read_text()
|
|
|
|
|
|
|
|
|
|
def test_gateway_log_created_after_cli_init_without_duplicate_handlers(self, hermes_home):
|
|
|
|
|
"""Repeated gateway setup calls do not attach duplicate gateway handlers."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="cli")
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
gw_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
and "gateway.log" in getattr(h, "baseFilename", "")
|
|
|
|
|
]
|
|
|
|
|
assert len(gw_handlers) == 1
|
|
|
|
|
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
def test_gateway_log_receives_gateway_records(self, hermes_home):
|
|
|
|
|
"""gateway.log captures records from gateway.* loggers."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
|
|
|
|
|
gw_logger = logging.getLogger("gateway.platforms.telegram")
|
|
|
|
|
gw_logger.info("telegram connected")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
gw_log = hermes_home / "logs" / "gateway.log"
|
|
|
|
|
assert gw_log.exists()
|
|
|
|
|
assert "telegram connected" in gw_log.read_text()
|
|
|
|
|
|
|
|
|
|
def test_gateway_log_rejects_non_gateway_records(self, hermes_home):
|
|
|
|
|
"""gateway.log does NOT capture records from tools.*, agent.*, etc."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
|
|
|
|
|
tool_logger = logging.getLogger("tools.terminal_tool")
|
|
|
|
|
tool_logger.info("running command")
|
|
|
|
|
|
|
|
|
|
agent_logger = logging.getLogger("agent.context_compressor")
|
|
|
|
|
agent_logger.info("compressing context")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
gw_log = hermes_home / "logs" / "gateway.log"
|
|
|
|
|
if gw_log.exists():
|
|
|
|
|
content = gw_log.read_text()
|
|
|
|
|
assert "running command" not in content
|
|
|
|
|
assert "compressing context" not in content
|
|
|
|
|
|
|
|
|
|
def test_agent_log_still_receives_all(self, hermes_home):
|
|
|
|
|
"""agent.log (catch-all) still receives gateway AND tool records."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home, mode="gateway")
|
|
|
|
|
|
2026-04-13 10:50:24 -07:00
|
|
|
gw_logger = logging.getLogger("gateway.run")
|
|
|
|
|
file_logger = logging.getLogger("tools.file_tools")
|
|
|
|
|
# Ensure propagation and levels are clean (cross-test pollution defense)
|
|
|
|
|
gw_logger.propagate = True
|
|
|
|
|
file_logger.propagate = True
|
|
|
|
|
logging.getLogger("tools").propagate = True
|
|
|
|
|
file_logger.setLevel(logging.NOTSET)
|
|
|
|
|
logging.getLogger("tools").setLevel(logging.NOTSET)
|
|
|
|
|
|
|
|
|
|
gw_logger.info("gateway msg")
|
|
|
|
|
file_logger.info("file msg")
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
assert "gateway msg" in content
|
|
|
|
|
assert "file msg" in content
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestSessionContext:
|
|
|
|
|
"""set_session_context / clear_session_context + _SessionFilter."""
|
|
|
|
|
|
|
|
|
|
def test_session_tag_in_log_output(self, hermes_home):
|
|
|
|
|
"""When session context is set, log lines include [session_id]."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.set_session_context("abc123")
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test.session_tag")
|
|
|
|
|
test_logger.info("tagged message")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
assert "[abc123]" in content
|
|
|
|
|
assert "tagged message" in content
|
|
|
|
|
|
|
|
|
|
def test_no_session_tag_without_context(self, hermes_home):
|
|
|
|
|
"""Without session context, log lines have no session tag."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.clear_session_context()
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test.no_session")
|
|
|
|
|
test_logger.info("untagged message")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
assert "untagged message" in content
|
|
|
|
|
# Should not have any [xxx] session tag
|
|
|
|
|
import re
|
|
|
|
|
for line in content.splitlines():
|
|
|
|
|
if "untagged message" in line:
|
|
|
|
|
assert not re.search(r"\[.+?\]", line.split("INFO")[1].split("test.no_session")[0])
|
|
|
|
|
|
|
|
|
|
def test_clear_session_context(self, hermes_home):
|
|
|
|
|
"""After clearing, session tag disappears."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.set_session_context("xyz789")
|
|
|
|
|
hermes_logging.clear_session_context()
|
|
|
|
|
|
|
|
|
|
test_logger = logging.getLogger("test.cleared")
|
|
|
|
|
test_logger.info("after clear")
|
|
|
|
|
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
assert "[xyz789]" not in content
|
|
|
|
|
|
|
|
|
|
def test_session_context_thread_isolated(self, hermes_home):
|
|
|
|
|
"""Session context is per-thread — one thread's context doesn't leak."""
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
|
|
|
|
|
results = {}
|
|
|
|
|
|
|
|
|
|
def thread_a():
|
|
|
|
|
hermes_logging.set_session_context("thread_a_session")
|
|
|
|
|
logging.getLogger("test.thread_a").info("from thread A")
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
def thread_b():
|
|
|
|
|
hermes_logging.set_session_context("thread_b_session")
|
|
|
|
|
logging.getLogger("test.thread_b").info("from thread B")
|
|
|
|
|
for h in logging.getLogger().handlers:
|
|
|
|
|
h.flush()
|
|
|
|
|
|
|
|
|
|
ta = threading.Thread(target=thread_a)
|
|
|
|
|
tb = threading.Thread(target=thread_b)
|
|
|
|
|
ta.start()
|
|
|
|
|
ta.join()
|
|
|
|
|
tb.start()
|
|
|
|
|
tb.join()
|
|
|
|
|
|
|
|
|
|
agent_log = hermes_home / "logs" / "agent.log"
|
|
|
|
|
content = agent_log.read_text()
|
|
|
|
|
|
|
|
|
|
# Each thread's message should have its own session tag
|
|
|
|
|
for line in content.splitlines():
|
|
|
|
|
if "from thread A" in line:
|
|
|
|
|
assert "[thread_a_session]" in line
|
|
|
|
|
assert "[thread_b_session]" not in line
|
|
|
|
|
if "from thread B" in line:
|
|
|
|
|
assert "[thread_b_session]" in line
|
|
|
|
|
assert "[thread_a_session]" not in line
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestRecordFactory:
|
|
|
|
|
"""Unit tests for the custom LogRecord factory."""
|
|
|
|
|
|
|
|
|
|
def test_record_has_session_tag(self):
|
|
|
|
|
"""Every record gets a session_tag attribute."""
|
|
|
|
|
factory = logging.getLogRecordFactory()
|
|
|
|
|
record = factory("test", logging.INFO, "", 0, "msg", (), None)
|
|
|
|
|
assert hasattr(record, "session_tag")
|
|
|
|
|
|
|
|
|
|
def test_empty_tag_without_context(self):
|
|
|
|
|
hermes_logging.clear_session_context()
|
|
|
|
|
factory = logging.getLogRecordFactory()
|
|
|
|
|
record = factory("test", logging.INFO, "", 0, "msg", (), None)
|
|
|
|
|
assert record.session_tag == ""
|
|
|
|
|
|
|
|
|
|
def test_tag_with_context(self):
|
|
|
|
|
hermes_logging.set_session_context("sess_42")
|
|
|
|
|
factory = logging.getLogRecordFactory()
|
|
|
|
|
record = factory("test", logging.INFO, "", 0, "msg", (), None)
|
|
|
|
|
assert record.session_tag == " [sess_42]"
|
|
|
|
|
|
|
|
|
|
def test_idempotent_install(self):
|
|
|
|
|
"""Calling _install_session_record_factory() twice doesn't double-wrap."""
|
|
|
|
|
hermes_logging._install_session_record_factory()
|
|
|
|
|
factory_a = logging.getLogRecordFactory()
|
|
|
|
|
hermes_logging._install_session_record_factory()
|
|
|
|
|
factory_b = logging.getLogRecordFactory()
|
|
|
|
|
assert factory_a is factory_b
|
|
|
|
|
|
|
|
|
|
def test_works_with_any_handler(self):
|
|
|
|
|
"""A handler using %(session_tag)s works even without _SessionFilter."""
|
|
|
|
|
hermes_logging.set_session_context("any_handler_test")
|
|
|
|
|
handler = logging.StreamHandler()
|
|
|
|
|
handler.setFormatter(logging.Formatter("%(session_tag)s %(message)s"))
|
|
|
|
|
|
|
|
|
|
logger = logging.getLogger("_test_any_handler")
|
|
|
|
|
logger.addHandler(handler)
|
|
|
|
|
logger.setLevel(logging.DEBUG)
|
|
|
|
|
try:
|
|
|
|
|
# Should not raise KeyError
|
|
|
|
|
logger.info("hello")
|
|
|
|
|
finally:
|
|
|
|
|
logger.removeHandler(handler)
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestComponentFilter:
|
|
|
|
|
"""Unit tests for _ComponentFilter."""
|
|
|
|
|
|
|
|
|
|
def test_passes_matching_prefix(self):
|
|
|
|
|
f = hermes_logging._ComponentFilter(("gateway",))
|
|
|
|
|
record = logging.LogRecord(
|
|
|
|
|
"gateway.run", logging.INFO, "", 0, "msg", (), None
|
|
|
|
|
)
|
|
|
|
|
assert f.filter(record) is True
|
|
|
|
|
|
|
|
|
|
def test_passes_nested_matching_prefix(self):
|
|
|
|
|
f = hermes_logging._ComponentFilter(("gateway",))
|
|
|
|
|
record = logging.LogRecord(
|
|
|
|
|
"gateway.platforms.telegram", logging.INFO, "", 0, "msg", (), None
|
|
|
|
|
)
|
|
|
|
|
assert f.filter(record) is True
|
|
|
|
|
|
|
|
|
|
def test_blocks_non_matching(self):
|
|
|
|
|
f = hermes_logging._ComponentFilter(("gateway",))
|
|
|
|
|
record = logging.LogRecord(
|
|
|
|
|
"tools.terminal_tool", logging.INFO, "", 0, "msg", (), None
|
|
|
|
|
)
|
|
|
|
|
assert f.filter(record) is False
|
|
|
|
|
|
|
|
|
|
def test_multiple_prefixes(self):
|
|
|
|
|
f = hermes_logging._ComponentFilter(("agent", "run_agent", "model_tools"))
|
|
|
|
|
assert f.filter(logging.LogRecord(
|
|
|
|
|
"agent.compressor", logging.INFO, "", 0, "", (), None
|
|
|
|
|
))
|
|
|
|
|
assert f.filter(logging.LogRecord(
|
|
|
|
|
"run_agent", logging.INFO, "", 0, "", (), None
|
|
|
|
|
))
|
|
|
|
|
assert f.filter(logging.LogRecord(
|
|
|
|
|
"model_tools", logging.INFO, "", 0, "", (), None
|
|
|
|
|
))
|
|
|
|
|
assert not f.filter(logging.LogRecord(
|
|
|
|
|
"tools.browser", logging.INFO, "", 0, "", (), None
|
|
|
|
|
))
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestComponentPrefixes:
|
|
|
|
|
"""COMPONENT_PREFIXES covers the expected components."""
|
|
|
|
|
|
|
|
|
|
def test_gateway_prefix(self):
|
|
|
|
|
assert "gateway" in hermes_logging.COMPONENT_PREFIXES
|
|
|
|
|
assert ("gateway",) == hermes_logging.COMPONENT_PREFIXES["gateway"]
|
|
|
|
|
|
|
|
|
|
def test_agent_prefix(self):
|
|
|
|
|
prefixes = hermes_logging.COMPONENT_PREFIXES["agent"]
|
|
|
|
|
assert "agent" in prefixes
|
|
|
|
|
assert "run_agent" in prefixes
|
|
|
|
|
assert "model_tools" in prefixes
|
|
|
|
|
|
|
|
|
|
def test_tools_prefix(self):
|
|
|
|
|
assert ("tools",) == hermes_logging.COMPONENT_PREFIXES["tools"]
|
|
|
|
|
|
|
|
|
|
def test_cli_prefix(self):
|
|
|
|
|
prefixes = hermes_logging.COMPONENT_PREFIXES["cli"]
|
|
|
|
|
assert "hermes_cli" in prefixes
|
|
|
|
|
assert "cli" in prefixes
|
|
|
|
|
|
|
|
|
|
def test_cron_prefix(self):
|
|
|
|
|
assert ("cron",) == hermes_logging.COMPONENT_PREFIXES["cron"]
|
|
|
|
|
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
|
|
|
|
|
class TestSetupVerboseLogging:
|
|
|
|
|
"""setup_verbose_logging() adds a DEBUG-level console handler."""
|
|
|
|
|
|
|
|
|
|
def test_adds_stream_handler(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.setup_verbose_logging()
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
verbose_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, logging.StreamHandler)
|
|
|
|
|
and not isinstance(h, RotatingFileHandler)
|
|
|
|
|
and getattr(h, "_hermes_verbose", False)
|
|
|
|
|
]
|
|
|
|
|
assert len(verbose_handlers) == 1
|
|
|
|
|
assert verbose_handlers[0].level == logging.DEBUG
|
|
|
|
|
|
|
|
|
|
def test_idempotent(self, hermes_home):
|
|
|
|
|
hermes_logging.setup_logging(hermes_home=hermes_home)
|
|
|
|
|
hermes_logging.setup_verbose_logging()
|
|
|
|
|
hermes_logging.setup_verbose_logging() # second call
|
|
|
|
|
|
|
|
|
|
root = logging.getLogger()
|
|
|
|
|
verbose_handlers = [
|
|
|
|
|
h for h in root.handlers
|
|
|
|
|
if isinstance(h, logging.StreamHandler)
|
|
|
|
|
and not isinstance(h, RotatingFileHandler)
|
|
|
|
|
and getattr(h, "_hermes_verbose", False)
|
|
|
|
|
]
|
|
|
|
|
assert len(verbose_handlers) == 1
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestAddRotatingHandler:
|
|
|
|
|
"""_add_rotating_handler() is idempotent and creates the directory."""
|
|
|
|
|
|
|
|
|
|
def test_creates_directory(self, tmp_path):
|
|
|
|
|
log_path = tmp_path / "subdir" / "test.log"
|
|
|
|
|
logger = logging.getLogger("_test_rotating")
|
|
|
|
|
formatter = logging.Formatter("%(message)s")
|
|
|
|
|
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
assert log_path.parent.is_dir()
|
|
|
|
|
# Clean up
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
|
|
|
|
logger.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
def test_no_duplicate_for_same_path(self, tmp_path):
|
|
|
|
|
log_path = tmp_path / "test.log"
|
|
|
|
|
logger = logging.getLogger("_test_rotating_dup")
|
|
|
|
|
formatter = logging.Formatter("%(message)s")
|
|
|
|
|
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
rotating_handlers = [
|
|
|
|
|
h for h in logger.handlers
|
|
|
|
|
if isinstance(h, RotatingFileHandler)
|
|
|
|
|
]
|
|
|
|
|
assert len(rotating_handlers) == 1
|
|
|
|
|
# Clean up
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
feat: component-separated logging with session context and filtering (#7991)
* feat: component-separated logging with session context and filtering
Phase 1 — Gateway log isolation:
- gateway.log now only receives records from gateway.* loggers
(platform adapters, session management, slash commands, delivery)
- agent.log remains the catch-all (all components)
- errors.log remains WARNING+ catch-all
- Moved gateway.log handler creation from gateway/run.py into
hermes_logging.setup_logging(mode='gateway') with _ComponentFilter
Phase 2 — Session ID injection:
- Added set_session_context(session_id) / clear_session_context() API
using threading.local() for per-thread session tracking
- _SessionFilter enriches every log record with session_tag attribute
- Log format: '2026-04-11 10:23:45 INFO [session_id] logger.name: msg'
- Session context set at start of run_conversation() in run_agent.py
- Thread-isolated: gateway conversations on different threads don't leak
Phase 3 — Component filtering in hermes logs:
- Added --component flag: hermes logs --component gateway|agent|tools|cli|cron
- COMPONENT_PREFIXES maps component names to logger name prefixes
- Works with all existing filters (--level, --session, --since, -f)
- Logger name extraction handles both old and new log formats
Files changed:
- hermes_logging.py: _SessionFilter, _ComponentFilter, COMPONENT_PREFIXES,
set/clear_session_context(), gateway.log creation in setup_logging()
- gateway/run.py: removed redundant gateway.log handler (now in hermes_logging)
- run_agent.py: set_session_context() at start of run_conversation()
- hermes_cli/logs.py: --component filter, logger name extraction
- hermes_cli/main.py: --component argument on logs subparser
Addresses community request for component-separated, filterable logging.
Zero changes to existing logger names — __name__ already provides hierarchy.
* fix: use LogRecord factory instead of per-handler _SessionFilter
The _SessionFilter approach required attaching a filter to every handler
we create. Any handler created outside our _add_rotating_handler (like
the gateway stderr handler, or third-party handlers) would crash with
KeyError: 'session_tag' if it used our format string.
Replace with logging.setLogRecordFactory() which injects session_tag
into every LogRecord at creation time — process-global, zero per-handler
wiring needed. The factory is installed at import time (before
setup_logging) so session_tag is available from the moment hermes_logging
is imported.
- Idempotent: marker attribute prevents double-wrapping on module reload
- Chains with existing factory: won't break third-party record factories
- Removes _SessionFilter from _add_rotating_handler and setup_verbose_logging
- Adds tests: record factory injection, idempotency, arbitrary handler compat
2026-04-11 17:23:36 -07:00
|
|
|
logger.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
def test_log_filter_attached(self, tmp_path):
|
|
|
|
|
"""Optional log_filter is attached to the handler."""
|
|
|
|
|
log_path = tmp_path / "filtered.log"
|
|
|
|
|
logger = logging.getLogger("_test_rotating_filter")
|
|
|
|
|
formatter = logging.Formatter("%(message)s")
|
|
|
|
|
component_filter = hermes_logging._ComponentFilter(("test",))
|
|
|
|
|
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
log_filter=component_filter,
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
handlers = [h for h in logger.handlers if isinstance(h, RotatingFileHandler)]
|
|
|
|
|
assert len(handlers) == 1
|
|
|
|
|
assert component_filter in handlers[0].filters
|
|
|
|
|
# Clean up
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
|
|
|
|
logger.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
def test_no_session_filter_on_handler(self, tmp_path):
|
|
|
|
|
"""Handlers rely on record factory, not per-handler _SessionFilter."""
|
|
|
|
|
log_path = tmp_path / "no_session_filter.log"
|
|
|
|
|
logger = logging.getLogger("_test_no_session_filter")
|
|
|
|
|
formatter = logging.Formatter("%(session_tag)s%(message)s")
|
|
|
|
|
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
handlers = [h for h in logger.handlers if isinstance(h, RotatingFileHandler)]
|
|
|
|
|
assert len(handlers) == 1
|
|
|
|
|
# No _SessionFilter on the handler — record factory handles it
|
|
|
|
|
assert len(handlers[0].filters) == 0
|
|
|
|
|
|
|
|
|
|
# But session_tag still works (via record factory)
|
|
|
|
|
hermes_logging.set_session_context("factory_test")
|
|
|
|
|
logger.info("test msg")
|
|
|
|
|
handlers[0].flush()
|
|
|
|
|
content = log_path.read_text()
|
|
|
|
|
assert "[factory_test]" in content
|
|
|
|
|
|
|
|
|
|
# Clean up
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
logger.removeHandler(h)
|
feat(nix): shared-state permission model for interactive CLI users (#6796)
* feat(nix): shared-state permission model for interactive CLI users
Enable interactive CLI users in the hermes group to share full
read-write state (sessions, memories, logs, cron) with the gateway
service via a setgid + group-writable permission model.
Changes:
nix/nixosModules.nix:
- Directories use setgid 2770 (was 0750) so new files inherit the
hermes group. home/ stays 0750 (no interactive write needed).
- Activation script creates HERMES_HOME subdirs (cron, sessions, logs,
memories) — previously Python created them but managed mode now skips
mkdir.
- Activation migrates existing runtime files to group-writable (chmod
g+rw). Nix-managed files (config.yaml, .env, .managed) stay 0640/0644.
- Gateway systemd unit gets UMask=0007 so files it creates are 0660.
hermes_cli/config.py:
- ensure_hermes_home() splits into managed/unmanaged paths. Managed mode
verifies dirs exist (raises RuntimeError if not) instead of creating
them. Scoped umask(0o007) ensures SOUL.md is created as 0660.
hermes_logging.py:
- _ManagedRotatingFileHandler subclass applies chmod 0660 after log
rotation in managed mode. RotatingFileHandler.doRollover() creates new
files via open() which uses the process umask (0022 → 0644), not the
scoped umask from ensure_hermes_home().
Verified with a 13-subtest NixOS VM integration test covering setgid,
interactive writes, file ownership, migration, and gateway coexistence.
Refs: #6044
* Fix managed log file mode on initial open
Co-authored-by: Siddharth Balyan <alt-glitch@users.noreply.github.com>
* refactor: simplify managed file handler and merge activation loops
- Cache is_managed() result in handler __init__ instead of lazy-importing
on every _open()/_chmod_if_managed() call. Avoids repeated stat+env
checks on log rotation.
- Merge two for-loops over the same subdir list in activation script
into a single loop (mkdir + chown + chmod + find in one pass).
---------
Co-authored-by: Cursor Agent <cursoragent@cursor.com>
Co-authored-by: Siddharth Balyan <alt-glitch@users.noreply.github.com>
2026-04-09 15:18:42 -07:00
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
def test_managed_mode_initial_open_sets_group_writable(self, tmp_path):
|
|
|
|
|
log_path = tmp_path / "managed-open.log"
|
|
|
|
|
logger = logging.getLogger("_test_rotating_managed_open")
|
|
|
|
|
formatter = logging.Formatter("%(message)s")
|
|
|
|
|
|
|
|
|
|
old_umask = os.umask(0o022)
|
|
|
|
|
try:
|
|
|
|
|
with patch("hermes_cli.config.is_managed", return_value=True):
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1024, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
finally:
|
|
|
|
|
os.umask(old_umask)
|
|
|
|
|
|
|
|
|
|
assert log_path.exists()
|
|
|
|
|
assert stat.S_IMODE(log_path.stat().st_mode) == 0o660
|
|
|
|
|
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
|
|
|
|
logger.removeHandler(h)
|
|
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
def test_managed_mode_rollover_sets_group_writable(self, tmp_path):
|
|
|
|
|
log_path = tmp_path / "managed-rollover.log"
|
|
|
|
|
logger = logging.getLogger("_test_rotating_managed_rollover")
|
|
|
|
|
formatter = logging.Formatter("%(message)s")
|
|
|
|
|
|
|
|
|
|
old_umask = os.umask(0o022)
|
|
|
|
|
try:
|
|
|
|
|
with patch("hermes_cli.config.is_managed", return_value=True):
|
|
|
|
|
hermes_logging._add_rotating_handler(
|
|
|
|
|
logger, log_path,
|
|
|
|
|
level=logging.INFO, max_bytes=1, backup_count=1,
|
|
|
|
|
formatter=formatter,
|
|
|
|
|
)
|
|
|
|
|
handler = next(
|
|
|
|
|
h for h in logger.handlers if isinstance(h, RotatingFileHandler)
|
|
|
|
|
)
|
|
|
|
|
logger.info("a" * 256)
|
|
|
|
|
handler.flush()
|
|
|
|
|
finally:
|
|
|
|
|
os.umask(old_umask)
|
|
|
|
|
|
|
|
|
|
assert log_path.exists()
|
|
|
|
|
assert stat.S_IMODE(log_path.stat().st_mode) == 0o660
|
|
|
|
|
|
|
|
|
|
for h in list(logger.handlers):
|
|
|
|
|
if isinstance(h, RotatingFileHandler):
|
|
|
|
|
logger.removeHandler(h)
|
feat: centralized logging, instrumentation, hermes logs CLI, gateway noise fix (#5430)
Adds comprehensive logging infrastructure to Hermes Agent across 4 phases:
**Phase 1 — Centralized logging**
- New hermes_logging.py with idempotent setup_logging() used by CLI, gateway, and cron
- agent.log (INFO+) and errors.log (WARNING+) with RotatingFileHandler + RedactingFormatter
- config.yaml logging: section (level, max_size_mb, backup_count)
- All entry points wired (cli.py, main.py, gateway/run.py, run_agent.py)
- Fixed debug_helpers.py writing to ./logs/ instead of ~/.hermes/logs/
**Phase 2 — Event instrumentation**
- API calls: model, provider, tokens, latency, cache hit %
- Tool execution: name, duration, result size (both sequential + concurrent)
- Session lifecycle: turn start (session/model/provider/platform), compression (before/after)
- Credential pool: rotation events, exhaustion tracking
**Phase 3 — hermes logs CLI command**
- hermes logs / hermes logs -f / hermes logs errors / hermes logs gateway
- --level, --session, --since filters
- hermes logs list (file sizes + ages)
**Phase 4 — Gateway bug fix + noise reduction**
- fix: _async_flush_memories() called with wrong arg count — sessions never flushed
- Batched session expiry logs: 6 lines/cycle → 2 summary lines
- Added inbound message + response time logging
75 new tests, zero regressions on the full suite.
2026-04-06 00:08:20 -07:00
|
|
|
h.close()
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
class TestReadLoggingConfig:
|
|
|
|
|
"""_read_logging_config() reads from config.yaml."""
|
|
|
|
|
|
|
|
|
|
def test_returns_none_when_no_config(self, hermes_home):
|
|
|
|
|
level, max_size, backup = hermes_logging._read_logging_config()
|
|
|
|
|
assert level is None
|
|
|
|
|
assert max_size is None
|
|
|
|
|
assert backup is None
|
|
|
|
|
|
|
|
|
|
def test_reads_logging_section(self, hermes_home):
|
|
|
|
|
import yaml
|
|
|
|
|
config = {"logging": {"level": "DEBUG", "max_size_mb": 10, "backup_count": 5}}
|
|
|
|
|
(hermes_home / "config.yaml").write_text(yaml.dump(config))
|
|
|
|
|
|
|
|
|
|
level, max_size, backup = hermes_logging._read_logging_config()
|
|
|
|
|
assert level == "DEBUG"
|
|
|
|
|
assert max_size == 10
|
|
|
|
|
assert backup == 5
|
|
|
|
|
|
|
|
|
|
def test_handles_missing_logging_section(self, hermes_home):
|
|
|
|
|
import yaml
|
|
|
|
|
config = {"model": "test"}
|
|
|
|
|
(hermes_home / "config.yaml").write_text(yaml.dump(config))
|
|
|
|
|
|
|
|
|
|
level, max_size, backup = hermes_logging._read_logging_config()
|
|
|
|
|
assert level is None
|