fix(logging): keep info diagnostics actionable
Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
1 parent
4ff948c7e1
commit
bcc0751060
28 files changed
+211
-135
No files matched your search
@@ -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",
|
||||
|
||||
@@ -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__":
|
||||
|
||||
@@ -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()),
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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"
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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),
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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
|
||||
@@ -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)
|
||||
@@ -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"
|
||||
@@ -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()]
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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}]
|
||||
@@ -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);
|
||||
}
|
||||
});
|
||||
|
||||
|
||||
@@ -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",
|
||||
};
|
||||
}
|
||||
|
||||
@@ -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();
|
||||
});
|
||||
@@ -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(" "),
|
||||
|
||||
@@ -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<Record<string, unknown>> = [];
|
||||
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<string, unknown>;
|
||||
expect(typeof exception?.details).toBe("object");
|
||||
const details = exception?.details as Record<string, unknown>;
|
||||
expect(typeof details.stack_origin).toBe("string");
|
||||
expect(details.stack_origin).toContain("recall-broker");
|
||||
});
|
||||
|
||||
@@ -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 (
|
||||
|
||||
Reference in new issue
Block a user