From bcc0751060bee63e3d5d6309e2410416ff1ca494 Mon Sep 17 00:00:00 2001 From: alvinfei Date: Sat, 17 Oct 2026 23:25:44 +0800 Subject: [PATCH] fix(logging): keep info diagnostics actionable Co-authored-by: Cursor --- memhub/apps/core/src/one_memory/api.py | 2 +- memhub/apps/core/src/one_memory/cli.py | 24 ++++++- .../core/src/one_memory/database_access.py | 2 +- .../core/src/one_memory/diagnostic_log.py | 5 ++ .../core/src/one_memory/hy_memory_bridge.py | 6 +- .../core/src/one_memory/hy_runtime_config.py | 13 ++++ .../core/src/one_memory/hy_step_timing.py | 4 +- .../src/one_memory/imports/async_bridge.py | 2 +- .../core/src/one_memory/imports/live_sync.py | 2 +- .../core/src/one_memory/imports/live_watch.py | 4 +- .../core/src/one_memory/imports/runner.py | 6 +- .../src/one_memory/imports/sources/common.py | 4 +- .../core/src/one_memory/imports/supervisor.py | 4 +- .../core/src/one_memory/memory_processing.py | 20 +++--- .../core/src/one_memory/service_levels.py | 4 +- memhub/apps/core/tests/test_diagnostic_log.py | 28 ++++++++ .../apps/core/tests/test_diagnostic_trace.py | 18 +++-- .../apps/core/tests/test_hy_runtime_config.py | 18 +++++ memhub/apps/core/tests/test_live_sync.py | 6 ++ .../apps/core/tests/test_memory_processing.py | 13 ++++ .../tests/test_policy_production_entry.py | 14 +++- memhub/apps/core/tests/test_reader_app.py | 4 ++ .../apps/desktop/src/diagnostics-ipc.test.ts | 15 ++-- memhub/apps/desktop/src/diagnostics-ipc.ts | 13 +++- .../apps/web/src/renderer-debug-log.test.ts | 17 +++-- memhub/apps/web/src/renderer-debug-log.ts | 11 +-- .../host-bridge/src/recall-broker.test.ts | 15 ++-- .../packages/host-bridge/src/recall-broker.ts | 72 ++++--------------- 28 files changed, 211 insertions(+), 135 deletions(-) diff --git a/memhub/apps/core/src/one_memory/api.py b/memhub/apps/core/src/one_memory/api.py index 5d44ccd..33bc7d5 100644 --- a/memhub/apps/core/src/one_memory/api.py +++ b/memhub/apps/core/src/one_memory/api.py @@ -4652,7 +4652,7 @@ async def _keep_loop_heartbeat(watchdog: LoopWatchdog) -> None: async def _emit_resource_snapshots(interval_seconds: float = 60.0) -> None: while True: diagnostic_event( - level="info", + level="debug", component="core.resources", event="core.resource_snapshot", outcome="observed", diff --git a/memhub/apps/core/src/one_memory/cli.py b/memhub/apps/core/src/one_memory/cli.py index 9f762e2..dd821e2 100644 --- a/memhub/apps/core/src/one_memory/cli.py +++ b/memhub/apps/core/src/one_memory/cli.py @@ -266,7 +266,13 @@ def serve(*, maintenance: bool = False, reader: bool = False) -> None: ) application = create_reader_app(reader_settings) print(f"reader_port:{port}", file=sys.stderr, flush=True) - uvicorn.run(application, host=settings.host, port=port, reload=False) + uvicorn.run( + application, + host=settings.host, + port=port, + reload=False, + access_log=False, + ) return from one_memory.api import create_app @@ -297,9 +303,21 @@ def serve(*, maintenance: bool = False, reader: bool = False) -> None: ) if maintenance: with CoreRuntime(settings, publish_receipt=False): - uvicorn.run(application, host=settings.host, port=settings.port, reload=False) + uvicorn.run( + application, + host=settings.host, + port=settings.port, + reload=False, + access_log=False, + ) else: - uvicorn.run(application, host=settings.host, port=settings.port, reload=False) + uvicorn.run( + application, + host=settings.host, + port=settings.port, + reload=False, + access_log=False, + ) if __name__ == "__main__": diff --git a/memhub/apps/core/src/one_memory/database_access.py b/memhub/apps/core/src/one_memory/database_access.py index 9f408ac..37046e2 100644 --- a/memhub/apps/core/src/one_memory/database_access.py +++ b/memhub/apps/core/src/one_memory/database_access.py @@ -1039,7 +1039,7 @@ def close_main_databases() -> None: def log_main_database_stats(moment: str) -> None: """One line in core.log: how many connections are open and who waited.""" stats = main_database_stats() - logger.info( + logger.debug( "main_database_connections moment=%s %s", moment, " ".join(f"{key}={value}" for key, value in stats.items()), diff --git a/memhub/apps/core/src/one_memory/diagnostic_log.py b/memhub/apps/core/src/one_memory/diagnostic_log.py index 0c33d7b..8d32ba2 100644 --- a/memhub/apps/core/src/one_memory/diagnostic_log.py +++ b/memhub/apps/core/src/one_memory/diagnostic_log.py @@ -19,6 +19,7 @@ from __future__ import annotations import atexit import json +import logging import os import re import sys @@ -649,6 +650,10 @@ def diagnostic_event(**values: object) -> None: active = _active if active is None: return + if values.get("level") == "debug" and not logging.getLogger().isEnabledFor( + logging.DEBUG + ): + return try: active.write(**values) # type: ignore[arg-type] except OSError: diff --git a/memhub/apps/core/src/one_memory/hy_memory_bridge.py b/memhub/apps/core/src/one_memory/hy_memory_bridge.py index 66b9604..ba5f39c 100644 --- a/memhub/apps/core/src/one_memory/hy_memory_bridge.py +++ b/memhub/apps/core/src/one_memory/hy_memory_bridge.py @@ -438,7 +438,7 @@ class HyMemoryBridge: async def _ingest(self, request: HyMemoryIngestRequest) -> HyMemoryIngestResult: started = monotonic() diagnostic_event( - level="info", + level="debug", component="hy.bridge", event="hy.ingest_started", outcome="started", @@ -574,7 +574,7 @@ class HyMemoryBridge: """Import source memory content when no raw conversation is available.""" started = monotonic() diagnostic_event( - level="info", + level="debug", component="hy.bridge", event="hy.ingest_started", outcome="started", @@ -1156,7 +1156,7 @@ class HyMemoryBridge: ) raise HyMemoryBridgeError("hy_memory_init_failed") from error diagnostic_event( - level="info", + level="debug", component="hy.client", event="hy.client_initialization.completed", outcome="succeeded", diff --git a/memhub/apps/core/src/one_memory/hy_runtime_config.py b/memhub/apps/core/src/one_memory/hy_runtime_config.py index 40f9dcc..1e70a4e 100644 --- a/memhub/apps/core/src/one_memory/hy_runtime_config.py +++ b/memhub/apps/core/src/one_memory/hy_runtime_config.py @@ -31,6 +31,7 @@ _COLLECTION_LOGGERS = ( "httpx", "httpcore", ) +_NOISY_LIBRARY_LOGGERS = ("httpx", "httpcore", "watchfiles", "jieba") # One Memory deliberately stays on ultra because its existing, user-visible # profile/graph flow calls digest(), which the pinned public SDK exposes only @@ -139,6 +140,18 @@ def apply_diagnostic_log_level(level: DiagnosticLogLevel) -> None: for name in tuple(logging.Logger.manager.loggerDict): if any(name == root or name.startswith(f"{root}.") for root in _COLLECTION_LOGGERS): logging.getLogger(name).setLevel(selected) + # Successful HTTP exchanges, file-watch notifications and tokenizer + # initialization are useful only while actively debugging. At INFO they + # dominated core.log and the in-app panel without describing product work. + noisy_level = selected if selected == logging.DEBUG else max(selected, logging.WARNING) + for root in _NOISY_LIBRARY_LOGGERS: + logging.getLogger(root).setLevel(noisy_level) + for name in tuple(logging.Logger.manager.loggerDict): + if any( + name == root or name.startswith(f"{root}.") + for root in _NOISY_LIBRARY_LOGGERS + ): + logging.getLogger(name).setLevel(noisy_level) os.environ["MEMORY_LOG_LEVEL"] = logging.getLevelName(selected) os.environ["MEMORY_PIPELINE_TRACE_ENABLED"] = "true" if level == "debug" else "false" diff --git a/memhub/apps/core/src/one_memory/hy_step_timing.py b/memhub/apps/core/src/one_memory/hy_step_timing.py index 387bf9d..1739e5e 100644 --- a/memhub/apps/core/src/one_memory/hy_step_timing.py +++ b/memhub/apps/core/src/one_memory/hy_step_timing.py @@ -152,7 +152,7 @@ class HyStepTimer: if value is None: continue diagnostic_event( - level="info", + level="debug", component=STEP_COMPONENTS[name], event="hy.step.completed", outcome="succeeded", @@ -168,7 +168,7 @@ class HyStepTimer: ) model = measured.get("model") diagnostic_event( - level="info", + level="debug", component="hy.bridge", event="hy.steps.summary", outcome="succeeded", diff --git a/memhub/apps/core/src/one_memory/imports/async_bridge.py b/memhub/apps/core/src/one_memory/imports/async_bridge.py index 7f5205f..82efd89 100644 --- a/memhub/apps/core/src/one_memory/imports/async_bridge.py +++ b/memhub/apps/core/src/one_memory/imports/async_bridge.py @@ -105,7 +105,7 @@ async def iterate_in_worker[T]( # was unwinding with, and a diagnostic is not worth an import. try: diagnostic_event( - level="info", + level="debug", component="import.async_bridge", event="import.source_read_finished", outcome="succeeded", diff --git a/memhub/apps/core/src/one_memory/imports/live_sync.py b/memhub/apps/core/src/one_memory/imports/live_sync.py index 2a1f593..026d0c1 100644 --- a/memhub/apps/core/src/one_memory/imports/live_sync.py +++ b/memhub/apps/core/src/one_memory/imports/live_sync.py @@ -106,7 +106,7 @@ class PollingLiveSyncSupervisor: level=( "warn" if value.state in {LiveSyncState.DEGRADED, LiveSyncState.UNAVAILABLE} - else "info" + else "debug" ), component="import.live_sync", event="live_sync.state_changed", diff --git a/memhub/apps/core/src/one_memory/imports/live_watch.py b/memhub/apps/core/src/one_memory/imports/live_watch.py index d90d497..1a8500b 100644 --- a/memhub/apps/core/src/one_memory/imports/live_watch.py +++ b/memhub/apps/core/src/one_memory/imports/live_watch.py @@ -156,7 +156,7 @@ class FileWatchLiveSync: if source is not None ): diagnostic_event( - level="info", + level="debug", component="import.live_watch", event="live_sync.hook_received", outcome="queued", @@ -190,7 +190,7 @@ class FileWatchLiveSync: try: await self._trigger_past(source_id, observed) diagnostic_event( - level="info", + level="debug", component="import.live_watch", event="live_sync.hook_completed", outcome="written", diff --git a/memhub/apps/core/src/one_memory/imports/runner.py b/memhub/apps/core/src/one_memory/imports/runner.py index fc67760..5e380f4 100644 --- a/memhub/apps/core/src/one_memory/imports/runner.py +++ b/memhub/apps/core/src/one_memory/imports/runner.py @@ -199,7 +199,7 @@ class ImportRunner: raise ValueError("Import job source does not match adapter source") job, runner_token = await in_the_background(self.job_store.claim, job_id) diagnostic_event( - level="info", + level="debug", component="import.parser", event="import.parse.started", outcome="started", @@ -310,7 +310,7 @@ class ImportRunner: if event.kind == "progress" and str(event.phase) != last_phase: phase = str(event.phase) diagnostic_event( - level="info", + level="debug", component="import.parser", event="import.phase_changed", outcome="changed", @@ -516,7 +516,7 @@ class ImportRunner: async def _emit_parse_result(self, job: ImportJob, started: float) -> None: succeeded = job.status is ImportStatus.COMPLETED diagnostic_event( - level="info" if succeeded else "warn", + level="debug" if succeeded else "warn", component="import.parser", event="import.parse.completed", outcome="succeeded" if succeeded else str(job.status), diff --git a/memhub/apps/core/src/one_memory/imports/sources/common.py b/memhub/apps/core/src/one_memory/imports/sources/common.py index 68f67da..6a6f9c1 100644 --- a/memhub/apps/core/src/one_memory/imports/sources/common.py +++ b/memhub/apps/core/src/one_memory/imports/sources/common.py @@ -355,7 +355,7 @@ class JsonlSourceAdapter: source_file, checkpoint, header = await asyncio.to_thread( self._prepare, listed, options ) - _log.info( + _log.debug( "import_file_read source=%s file=%d/%d file_bytes=%d planned_bytes=%d", self.descriptor.source_id, index, @@ -376,7 +376,7 @@ class JsonlSourceAdapter: else DEFAULT_IMPORT_MAX_FILE_BYTES ) if source_file.size > budget: - _log.info( + _log.debug( "import_file_budgeted source=%s file=%d/%d file_bytes=%d budget=%d path=%s", self.descriptor.source_id, index, diff --git a/memhub/apps/core/src/one_memory/imports/supervisor.py b/memhub/apps/core/src/one_memory/imports/supervisor.py index c3cda03..25e85e5 100644 --- a/memhub/apps/core/src/one_memory/imports/supervisor.py +++ b/memhub/apps/core/src/one_memory/imports/supervisor.py @@ -111,7 +111,7 @@ class ImportSupervisor: ) ) diagnostic_event( - level="info", + level="debug", component="import.supervisor", event="import.queued", outcome="queued", @@ -198,7 +198,7 @@ class ImportSupervisor: started = monotonic() failure_type: str | None = None diagnostic_event( - level="info", + level="debug", component="import.supervisor", event="import.started", outcome="started", diff --git a/memhub/apps/core/src/one_memory/memory_processing.py b/memhub/apps/core/src/one_memory/memory_processing.py index b7fe181..fca3391 100644 --- a/memhub/apps/core/src/one_memory/memory_processing.py +++ b/memhub/apps/core/src/one_memory/memory_processing.py @@ -163,7 +163,7 @@ def _report_stale_known_reasons(task_id: str, reasons: Mapping[str, int]) -> Non """Emit one schema-valid scalar diagnostic per stale-memory reason.""" for reason, count in sorted(reasons.items()): diagnostic_event( - level="info", + level="debug", component="memory.context", event="known_memory_stale_omitted", outcome="omitted", @@ -284,7 +284,7 @@ class MemoryTaskRunner: ) -> MemoryTask: started = monotonic() diagnostic_event( - level="info", + level="debug", component="memory.task", event="memory_task.started", outcome="started", @@ -368,7 +368,7 @@ class MemoryTaskRunner: @staticmethod def _log_step(task_id: str, step: int, action: str, started: float) -> None: diagnostic_event( - level="info", + level="debug", component="memory.task", event="memory_task.step_completed", outcome="succeeded", @@ -1289,7 +1289,7 @@ class MemoryProcessingSupervisor: return self._diagnostic_idle_reason = reason diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.idle", outcome="idle", @@ -1719,7 +1719,7 @@ class MemoryProcessingSupervisor: visited = 0 seed_ids = self.evidence.list_conversation_seed_ids() diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.scan_inventory", outcome="observed", @@ -1789,7 +1789,7 @@ class MemoryProcessingSupervisor: started = monotonic() prepared_count = 0 diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.scan_started", outcome="started", @@ -1848,7 +1848,7 @@ class MemoryProcessingSupervisor: on_first_scheduled() if not exhausted and not self._shutting_down: diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.scan_yielded", outcome="yielded", @@ -1885,7 +1885,7 @@ class MemoryProcessingSupervisor: elif prepared_count: self._diagnostic_idle_reason = None diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.scan_completed", outcome=( @@ -2175,7 +2175,7 @@ class MemoryProcessingSupervisor: if work: self._diagnostic_idle_reason = None diagnostic_event( - level="info", + level="debug", component="memory.scheduler", event="memory_scheduler.tasks_queued", outcome="succeeded", @@ -3050,7 +3050,7 @@ class MemoryProcessingSupervisor: self._read_bridges_ready.add(key) self._read_bridge_generations[key] = generation diagnostic_event( - level="info", + level="debug", component="memory.semantic", event="semantic_read_bridge.refreshed", outcome="succeeded", diff --git a/memhub/apps/core/src/one_memory/service_levels.py b/memhub/apps/core/src/one_memory/service_levels.py index eba8611..694ccff 100644 --- a/memhub/apps/core/src/one_memory/service_levels.py +++ b/memhub/apps/core/src/one_memory/service_levels.py @@ -264,7 +264,7 @@ class ServiceLevelScheduler: self._quiet_admission_logged_at[key] = now if last is not None: diagnostic_event( - level="info", + level="debug", component="service_level.scheduler", event="service_level.summary", outcome="succeeded", @@ -276,7 +276,7 @@ class ServiceLevelScheduler: ) return diagnostic_event( - level="info", + level="debug", component="service_level.scheduler", event="service_level.admitted", outcome="succeeded", diff --git a/memhub/apps/core/tests/test_diagnostic_log.py b/memhub/apps/core/tests/test_diagnostic_log.py index 5631d10..55bfe8e 100644 --- a/memhub/apps/core/tests/test_diagnostic_log.py +++ b/memhub/apps/core/tests/test_diagnostic_log.py @@ -1,4 +1,5 @@ import json +import logging import os import sqlite3 from datetime import UTC, datetime, timedelta @@ -13,6 +14,7 @@ from one_memory.diagnostic_log import ( configure_diagnostics, current_trace_id, database_error_code, + diagnostic_event, diagnostic_exception, diagnostics_enabled, diagnostics_requested, @@ -23,6 +25,32 @@ from one_memory.diagnostic_log import ( ) +def test_debug_events_are_collected_only_at_debug_level(tmp_path, monkeypatch) -> None: + monkeypatch.setenv("ONE_MEMORY_DIAGNOSTICS", "1") + root = logging.getLogger() + previous = root.level + root.setLevel(logging.INFO) + receipt = configure_diagnostics(tmp_path) + try: + diagnostic_event( + level="debug", + component="core.poll", + event="poll.completed", + outcome="succeeded", + ) + diagnostic_event( + level="info", + component="memory.task", + event="memory_task.finished", + outcome="completed", + ) + finally: + reset_diagnostics() + root.setLevel(previous) + events = [json.loads(line) for line in receipt.path.read_text().splitlines()] + assert [event["event"] for event in events] == ["memory_task.finished"] + + def test_high_frequency_success_events_are_summarized_but_warnings_are_not( tmp_path, monkeypatch ) -> None: diff --git a/memhub/apps/core/tests/test_diagnostic_trace.py b/memhub/apps/core/tests/test_diagnostic_trace.py index 7882862..07f5f5f 100644 --- a/memhub/apps/core/tests/test_diagnostic_trace.py +++ b/memhub/apps/core/tests/test_diagnostic_trace.py @@ -162,8 +162,6 @@ def test_import_request_trace_reaches_the_background_job_without_original_text(t ] names = [event["event"] for event in events] assert "import.request.started" in names - assert "import.queued" in names - assert "import.started" in names assert "import.finished" in names finished = next(event for event in events if event["event"] == "import.finished") assert { @@ -175,18 +173,17 @@ def test_import_request_trace_reaches_the_background_job_without_original_text(t assert secret not in written -def test_import_run_logs_parse_stages_and_core_resources_without_content(tmp_path): +def test_default_info_omits_parser_and_resource_internals(tmp_path): written, job_id = _run_codex_import(tmp_path) events = list(map(json.loads, written.splitlines())) job_events = [event for event in events if event.get("job_id") == job_id] names = [event["event"] for event in job_events] - assert names.index("import.parse.started") < names.index("import.parse.completed") - assert "import.phase_changed" in names - completed = next(event for event in job_events if event["event"] == "import.parse.completed") - assert completed["outcome"] == "succeeded" - assert {"stored_count", "skipped_count", "error_count"} <= completed["details"].keys() + assert "import.parse.started" not in names + assert "import.parse.completed" not in names + assert "import.phase_changed" not in names + assert "import.finished" in names everything = [event["event"] for event in events] - assert "core.resource_snapshot" in everything + assert "core.resource_snapshot" not in everything assert everything.index("core.ready") < everything.index("core.stopped") assert IMPORT_SECRET not in written @@ -230,4 +227,5 @@ def test_a_failing_import_finished_log_does_not_escape_the_supervisor_task(tmp_p monkeypatch.setattr(supervisor, "diagnostic_event", rejecting) written, _job_id = _run_codex_import(tmp_path) - assert "import.started" in written + assert "core.stopped" in written + assert "import.finished" not in written diff --git a/memhub/apps/core/tests/test_hy_runtime_config.py b/memhub/apps/core/tests/test_hy_runtime_config.py index 33b325d..d9deda2 100644 --- a/memhub/apps/core/tests/test_hy_runtime_config.py +++ b/memhub/apps/core/tests/test_hy_runtime_config.py @@ -5,6 +5,7 @@ Checking that contract automatically prevents a silently flipped rerank flag from going unnoticed. """ +import logging import re from pathlib import Path @@ -16,6 +17,7 @@ from one_memory.hy_runtime_config import ( HY_MEMORY_MODE, HY_MEMORY_READER, HY_MEMORY_VERSION, + apply_diagnostic_log_level, hy_memory_version, ) @@ -69,3 +71,19 @@ def test_the_pin_matches_the_lock_file_and_its_wheel(): ) assert f"hy_memory-{HY_MEMORY_VERSION}-" in lock assert f'specifier = "=={HY_MEMORY_VERSION}"' in lock + + +def test_info_level_suppresses_noisy_third_party_success_logs(): + names = ("", "one_memory", "httpx", "httpcore", "watchfiles", "jieba") + previous = {name: logging.getLogger(name).level for name in names} + try: + apply_diagnostic_log_level("info") + assert logging.getLogger("one_memory").level == logging.INFO + for name in ("httpx", "httpcore", "watchfiles", "jieba"): + assert logging.getLogger(name).level == logging.WARNING + apply_diagnostic_log_level("debug") + for name in ("one_memory", "httpx", "httpcore", "watchfiles", "jieba"): + assert logging.getLogger(name).level == logging.DEBUG + finally: + for name, level in previous.items(): + logging.getLogger(name).setLevel(level) diff --git a/memhub/apps/core/tests/test_live_sync.py b/memhub/apps/core/tests/test_live_sync.py index f05f45c..c38dbe4 100644 --- a/memhub/apps/core/tests/test_live_sync.py +++ b/memhub/apps/core/tests/test_live_sync.py @@ -1,5 +1,6 @@ import asyncio import json +import logging import sqlite3 import threading import time @@ -1255,6 +1256,9 @@ def test_triggering_a_sync_leaves_the_loop_free_to_answer(tmp_path) -> None: def test_live_sync_diagnostics_only_emit_state_changes(tmp_path, monkeypatch): monkeypatch.setenv("ONE_MEMORY_DIAGNOSTICS", "1") + root = logging.getLogger() + previous = root.level + root.setLevel(logging.DEBUG) receipt = configure_diagnostics(tmp_path) try: supervisor = PollingLiveSyncSupervisor( @@ -1267,5 +1271,7 @@ def test_live_sync_diagnostics_only_emit_state_changes(tmp_path, monkeypatch): supervisor._set_health("codex", unavailable.model_copy(update={"source_id": "codex"})) finally: reset_diagnostics() + root.setLevel(previous) events = [json.loads(line) for line in receipt.path.read_text().splitlines()] assert [event["event"] for event in events] == ["live_sync.state_changed"] + assert events[0]["level"] == "warn" diff --git a/memhub/apps/core/tests/test_memory_processing.py b/memhub/apps/core/tests/test_memory_processing.py index 678da5f..6f17364 100644 --- a/memhub/apps/core/tests/test_memory_processing.py +++ b/memhub/apps/core/tests/test_memory_processing.py @@ -1,5 +1,6 @@ import asyncio import json +import logging import sqlite3 import threading import time @@ -87,6 +88,9 @@ def _segment_at_the_legacy_window(monkeypatch): def test_stale_known_reason_diagnostics_never_fail_dispatch(tmp_path, monkeypatch) -> None: monkeypatch.setenv("ONE_MEMORY_DIAGNOSTICS", "1") + root = logging.getLogger() + previous = root.level + root.setLevel(logging.DEBUG) receipt = configure_diagnostics(tmp_path) try: _report_stale_known_reasons( @@ -95,6 +99,7 @@ def test_stale_known_reason_diagnostics_never_fail_dispatch(tmp_path, monkeypatc ) finally: reset_diagnostics() + root.setLevel(previous) records = [json.loads(line) for line in receipt.path.read_text().splitlines()] assert [(row["details"]["reason"], row["details"]["count"]) for row in records] == [ @@ -306,11 +311,15 @@ def test_memory_task_logs_six_step_durations_without_content(tmp_path) -> None: content=marker, ) task = _task(tasks, profile, record) + root = logging.getLogger() + previous = root.level + root.setLevel(logging.DEBUG) receipt = configure_diagnostics(tmp_path) try: asyncio.run(_runner(tmp_path, stores, FakeBridge()).run(task.task_id)) finally: reset_diagnostics() + root.setLevel(previous) written = receipt.path.read_text() events = [json.loads(line) for line in written.splitlines()] steps = [event for event in events if event["event"] == "memory_task.step_completed"] @@ -1390,6 +1399,9 @@ def test_backfill_scan_logs_inventory_and_queue_without_content(tmp_path) -> Non conversation_id=f"conversation-{index}", content_kind=EvidenceContentKind.MEMORY_CONTENT, ) + root = logging.getLogger() + previous = root.level + root.setLevel(logging.DEBUG) receipt = configure_diagnostics(tmp_path / "logs") async def exercise() -> None: @@ -1409,6 +1421,7 @@ def test_backfill_scan_logs_inventory_and_queue_without_content(tmp_path) -> Non asyncio.run(exercise()) finally: reset_diagnostics() + root.setLevel(previous) written = receipt.path.read_text() events = [json.loads(line) for line in written.splitlines()] diff --git a/memhub/apps/core/tests/test_policy_production_entry.py b/memhub/apps/core/tests/test_policy_production_entry.py index 570725d..eed2877 100644 --- a/memhub/apps/core/tests/test_policy_production_entry.py +++ b/memhub/apps/core/tests/test_policy_production_entry.py @@ -19,7 +19,12 @@ def test_production_serve_passes_only_supported_app_options(monkeypatch, tmp_pat def run(application, **kwargs): assert application is marker - assert kwargs == {"host": "127.0.0.1", "port": 12345, "reload": False} + assert kwargs == { + "host": "127.0.0.1", + "port": 12345, + "reload": False, + "access_log": False, + } monkeypatch.setattr(cli, "load_settings", lambda: settings) monkeypatch.setattr(log_file, "start_logging_to_file", lambda _: None) @@ -46,7 +51,12 @@ def test_maintenance_serve_does_not_own_the_runtime(monkeypatch, tmp_path): def run(application, **kwargs): assert application is marker - assert kwargs == {"host": "127.0.0.1", "port": 12346, "reload": False} + assert kwargs == { + "host": "127.0.0.1", + "port": 12346, + "reload": False, + "access_log": False, + } monkeypatch.setattr(cli, "load_settings", lambda: settings) monkeypatch.setattr(log_file, "start_logging_to_file", lambda _: None) diff --git a/memhub/apps/core/tests/test_reader_app.py b/memhub/apps/core/tests/test_reader_app.py index 72886f8..153e6d9 100644 --- a/memhub/apps/core/tests/test_reader_app.py +++ b/memhub/apps/core/tests/test_reader_app.py @@ -191,10 +191,12 @@ from one_memory import cli from one_memory.config import Settings served_on = [] +served_with = [] def fake_run(application, *, host=None, port=None, **_kwargs): served_on.append(port) + served_with.append(_kwargs) uvicorn.run = fake_run @@ -219,6 +221,7 @@ json.dump( { "printed": printed, "served_on": served_on, + "served_with": served_with, "port": int(match.group(1)) if match else None, }, sys.stdout, @@ -249,3 +252,4 @@ json.dump( # Port 0 means "any free port", so the reported value must be a real one. assert payload["port"] > 0 assert payload["served_on"] == [payload["port"]] + assert payload["served_with"] == [{"reload": False, "access_log": False}] diff --git a/memhub/apps/desktop/src/diagnostics-ipc.test.ts b/memhub/apps/desktop/src/diagnostics-ipc.test.ts index 0cca734..10cd249 100644 --- a/memhub/apps/desktop/src/diagnostics-ipc.test.ts +++ b/memhub/apps/desktop/src/diagnostics-ipc.test.ts @@ -161,7 +161,7 @@ it("tracks diagnostic JSONL across rotation without rereading the old prefix", a ]); }); -it("tracks service output from the launch offset across rotation", async () => { +it("keeps only actionable raw service output across rotation", async () => { const dataDir = await mkdtemp(path.join(os.tmpdir(), "om-debug-service-")); roots.push(dataDir); const logs = path.join(dataDir, "logs"); @@ -177,18 +177,16 @@ it("tracks service output from the launch offset across rotation", async () => { const snapshot = await readDebugLogSnapshot(dataDir, startedAt, cursor); expect(snapshot.entries.map((entry) => entry.message)).toEqual([ - "INFO current request", "WARNING after rotation", "ERROR failed request", ]); expect(snapshot.entries.map((entry) => entry.level)).toEqual([ - "info", "warn", "error", ]); }); -it("includes core.log lines from this launch and classifies their level", async () => { +it("filters raw Core INFO and DEBUG while preserving warnings and errors", async () => { const dataDir = await mkdtemp(path.join(os.tmpdir(), "om-debug-core-log-")); roots.push(dataDir); const logs = path.join(dataDir, "logs"); @@ -200,6 +198,7 @@ it("includes core.log lines from this launch and classifies their level", async await appendFile( target, "2026-10-14 10:30:30 DEBUG hy pipeline queued\n" + + '2026-10-14 10:30:45 INFO: 127.0.0.1:54000 - "GET /health HTTP/1.1" 200 OK\n' + "2026-10-14 10:31:00 WARNING database wait\n" + "2026-10-14 10:32:00 ERROR worker failed\n", ); @@ -207,12 +206,10 @@ it("includes core.log lines from this launch and classifies their level", async const snapshot = await readDebugLogSnapshot(dataDir, startedAt, cursor); expect(snapshot.entries.map((entry) => entry.message)).toEqual([ - "2026-10-14 10:30:30 DEBUG hy pipeline queued", "2026-10-14 10:31:00 WARNING database wait", "2026-10-14 10:32:00 ERROR worker failed", ]); expect(snapshot.entries.map((entry) => entry.level)).toEqual([ - "debug", "warn", "error", ]); @@ -221,7 +218,7 @@ it("includes core.log lines from this launch and classifies their level", async ).toBe(true); }); -it("shows HY pipeline stages with the complete original JSON line", async () => { +it("shows HY pipeline metrics without exposing model content", async () => { const dataDir = await mkdtemp( path.join(os.tmpdir(), "om-debug-hy-pipeline-"), ); @@ -265,7 +262,7 @@ it("shows HY pipeline stages with the complete original JSON line", async () => service: "hy-memory", component: "hy.pipeline", event: "hy.pipeline.extract", - message: expect.stringContaining('"prompt":"private prompt"'), + message: "EXTRACT · 42 tokens · 124 ms", duration_ms: 123.5, trace_id: "request-safe-1", details: { phase: "EXTRACT", count: 42 }, @@ -281,7 +278,7 @@ it("shows HY pipeline stages with the complete original JSON line", async () => "private-agent", "private-session", ]) { - expect(serialized).toContain(secret); + expect(serialized).not.toContain(secret); } }); diff --git a/memhub/apps/desktop/src/diagnostics-ipc.ts b/memhub/apps/desktop/src/diagnostics-ipc.ts index 01653c1..8c5af92 100644 --- a/memhub/apps/desktop/src/diagnostics-ipc.ts +++ b/memhub/apps/desktop/src/diagnostics-ipc.ts @@ -441,6 +441,13 @@ async function readServiceLogEntries( const message = line.trimEnd(); if (!message) continue; const level = serviceLogLevel(message, cursor.name); + // Raw stdout is an implementation trace, not a product event. Core's + // structured diagnostics and HY pipeline logs already carry meaningful + // successful work with request/task identity. Showing raw INFO/DEBUG + // here duplicated those events and turned polling access logs, file + // watchers and library initialization into thousands of fake "useful" + // rows. Keep raw output only when it needs attention. + if (level === "info" || level === "debug") continue; entries.push({ id: `${cursor.name}:${file.info.dev}:${file.info.ino}:${offset}:${lineIndex}`, timestamp: logLineTimestamp(message, startedAt, file.info.mtimeMs), @@ -645,7 +652,11 @@ function pipelineLogEntry( phase: step, ...(tokens === undefined ? {} : { count: tokens }), }, - message: line, + message: [ + step, + ...(tokens === undefined ? [] : [`${Math.round(tokens)} tokens`]), + ...(elapsed === undefined ? [] : [`${Math.round(elapsed)} ms`]), + ].join(" · "), source: "pipeline", }; } diff --git a/memhub/apps/web/src/renderer-debug-log.test.ts b/memhub/apps/web/src/renderer-debug-log.test.ts index 602b109..b72da81 100644 --- a/memhub/apps/web/src/renderer-debug-log.test.ts +++ b/memhub/apps/web/src/renderer-debug-log.test.ts @@ -8,18 +8,20 @@ import { afterEach(() => resetRendererDebugLogsForTest()); -it("captures console output and uncaught renderer failures", () => { - const debug = vi.spyOn(console, "debug").mockImplementation(() => undefined); +it("captures only actionable console output and uncaught renderer failures", () => { + const info = vi.spyOn(console, "info").mockImplementation(() => undefined); + const warn = vi.spyOn(console, "warn").mockImplementation(() => undefined); const error = vi.spyOn(console, "error").mockImplementation(() => undefined); const stop = installRendererDebugLogCapture(); - console.debug("debug-value", { count: 2 }); + console.info("routine-value", { count: 1 }); + console.warn("warning-value", { count: 2 }); window.dispatchEvent(new ErrorEvent("error", { message: "render exploded" })); expect(rendererDebugLogs()).toEqual([ expect.objectContaining({ - level: "debug", - event: "console.debug", - message: 'debug-value {"count":2}', + level: "warn", + event: "console.warn", + message: 'warning-value {"count":2}', }), expect.objectContaining({ level: "error", @@ -29,6 +31,7 @@ it("captures console output and uncaught renderer failures", () => { ]); stop(); - debug.mockRestore(); + info.mockRestore(); + warn.mockRestore(); error.mockRestore(); }); diff --git a/memhub/apps/web/src/renderer-debug-log.ts b/memhub/apps/web/src/renderer-debug-log.ts index 06f4a5e..09c5c24 100644 --- a/memhub/apps/web/src/renderer-debug-log.ts +++ b/memhub/apps/web/src/renderer-debug-log.ts @@ -10,18 +10,19 @@ export function installRendererDebugLogCapture(): () => void { if (installed) return () => undefined; installed = true; const originals = { - debug: console.debug, - info: console.info, - log: console.log, warn: console.warn, error: console.error, }; - const methods = ["debug", "info", "log", "warn", "error"] as const; + // Successful renderer chatter is already represented by structured UI + // diagnostics. Mirroring console.log/info/debug duplicated it without trace + // identity and made the panel less useful. Console capture is now only the + // actionable fallback for warnings and failures. + const methods = ["warn", "error"] as const; for (const method of methods) { console[method] = (...values: unknown[]) => { originals[method](...values); recordRendererDebugLog({ - level: method === "log" ? "info" : method, + level: method, event: `console.${method}`, outcome: method === "error" ? "failed" : "observed", message: values.map(debugValue).join(" "), diff --git a/memhub/packages/host-bridge/src/recall-broker.test.ts b/memhub/packages/host-bridge/src/recall-broker.test.ts index 420cbc8..5a320f8 100644 --- a/memhub/packages/host-bridge/src/recall-broker.test.ts +++ b/memhub/packages/host-bridge/src/recall-broker.test.ts @@ -17,7 +17,7 @@ afterEach(async () => { }); describe("RecallBroker", () => { - it("logs connection polling only when its safe state changes", async () => { + it("does not log successful connection polling", async () => { const diagnostics: Array> = []; const root = await mkdtemp(path.join(os.tmpdir(), "om-broker-poll-log-")); let available = true; @@ -55,14 +55,7 @@ describe("RecallBroker", () => { await poll(); available = false; await poll(); - expect(diagnostics.map((event) => event.event)).toEqual([ - "connection_control.completed", - "connection_control.summary", - "connection_control.completed", - ]); - expect(diagnostics[1]).toMatchObject({ - details: { action: "host", count: 101, error_count: 0 }, - }); + expect(diagnostics).toEqual([]); }); it("logs one repeated connection failure plus a five-minute summary", async () => { @@ -163,8 +156,8 @@ describe("RecallBroker", () => { error_type: "Error", }), }); - expect(typeof exception!.details).toBe("object"); - const details = exception!.details as Record; + expect(typeof exception?.details).toBe("object"); + const details = exception?.details as Record; expect(typeof details.stack_origin).toBe("string"); expect(details.stack_origin).toContain("recall-broker"); }); diff --git a/memhub/packages/host-bridge/src/recall-broker.ts b/memhub/packages/host-bridge/src/recall-broker.ts index 4d6e4cf..f3a3e55 100644 --- a/memhub/packages/host-bridge/src/recall-broker.ts +++ b/memhub/packages/host-bridge/src/recall-broker.ts @@ -589,13 +589,7 @@ export class RecallBroker { throw Error("connection_control_response_limit"); if (!response.destroyed) sendJson(response, 200, envelope); this.recordConnectionDiagnostic(value.action, false); - const fingerprint = connectionStateFingerprint(result); - const previous = this.connectionDiagnosticState.get(value.action); - if ( - !["capability", "receipt", "host"].includes(value.action) || - previous !== fingerprint - ) { - this.connectionDiagnosticState.set(value.action, fingerprint); + if (!["capability", "receipt", "host"].includes(value.action)) { this.emit({ level: "info", component: "host.broker", @@ -1261,18 +1255,20 @@ export class RecallBroker { this.connectionDiagnosticSummary.set(action, current); return; } - this.emit({ - level: current.errorCount ? "warn" : "info", - component: "host.broker", - event: "connection_control.summary", - outcome: "observed", - instance_id: this.options.instanceId, - details: { - action, - count: current.count, - error_count: current.errorCount, - }, - }); + if (current.errorCount) { + this.emit({ + level: "warn", + component: "host.broker", + event: "connection_control.summary", + outcome: "observed", + instance_id: this.options.instanceId, + details: { + action, + count: current.count, + error_count: current.errorCount, + }, + }); + } this.connectionDiagnosticSummary.set(action, { startedAt: now, count: 0, @@ -1281,44 +1277,6 @@ export class RecallBroker { } } -function connectionStateFingerprint(value: unknown): string { - const safe: Array<[string, string | number | boolean | null]> = []; - const visit = (item: unknown): void => { - if (Array.isArray(item)) { - for (const child of item) visit(child); - return; - } - if (!item || typeof item !== "object") return; - for (const [key, child] of Object.entries(item)) { - if ( - [ - "status", - "state", - "error", - "code", - "installed", - "approved", - "available", - ].includes(key) && - (child === null || - ["string", "number", "boolean"].includes(typeof child)) - ) { - safe.push([key, child as string | number | boolean | null]); - } else if (child && typeof child === "object") { - visit(child); - } - } - }; - visit(value); - return JSON.stringify( - safe.sort(([leftKey, left], [rightKey, right]) => - `${leftKey}:${String(left)}`.localeCompare( - `${rightKey}:${String(right)}`, - ), - ), - ); -} - function requestTraceId(request: IncomingMessage): string { const value = request.headers["x-one-memory-trace-id"]; if (