feat(ledger): quiet idle outbox polling

This commit is contained in:
Hermes Agent
2026-09-20 21:57:30 +09:00
parent 62e4f57c2b
commit a2be76b199
14 changed files with 437 additions and 15 deletions
+75
View File
@@ -1,6 +1,7 @@
"""LedgerOutbox + LedgerWriter direct unit tests (REQ-019)."""
from __future__ import annotations
import logging
from dataclasses import replace
from datetime import UTC, datetime, timedelta
@@ -132,6 +133,80 @@ def test_writer_exposes_claim_and_outcome_counters():
assert writer.counters["outcome:completed"] == 1
def test_idle_day_is_silent_and_counted_per_instance(caplog):
writers = [
LedgerWriter(
InMemoryLedgerOutbox(instance_key=instance_key),
InMemoryLedger(),
instance_key=instance_key,
)
for instance_key in ("instance-a", "instance-b")
]
with caplog.at_level(logging.INFO, logger="trex_core.application.ledger_outbox"):
for writer in writers:
for _ in range(86_400):
writer.run_once()
assert [
writer.metrics_snapshot()["claims"]["empty_polls_total"]
for writer in writers
] == [86_400, 86_400]
assert "claim_result=empty" not in caplog.text
assert "correlation_ids" not in caplog.text
def test_nonempty_claim_log_has_ordered_json_correlation_ids(caplog):
outbox = InMemoryLedgerOutbox(instance_key="inst-a")
writer = LedgerWriter(outbox, InMemoryLedger(), instance_key="inst-a")
first = outbox.enqueue(_trade(execution_id="e-1"))
second = outbox.enqueue(_trade(execution_id="e-2"))
with caplog.at_level(logging.INFO, logger="trex_core.application.ledger_outbox"):
writer.run_once(limit=2)
claim_logs = [
record.getMessage()
for record in caplog.records
if "ledger outbox claim:" in record.getMessage()
]
assert claim_logs == [
"ledger outbox claim: instance_key=inst-a claim_result=claimed "
f"count=2 limit=2 correlation_ids=[\"{first.correlation_id}\","
f"\"{second.correlation_id}\"]"
]
def test_metrics_snapshot_is_complete_and_detached():
outbox = InMemoryLedgerOutbox(instance_key="inst-a")
writer = LedgerWriter(outbox, InMemoryLedger(), instance_key="inst-a")
snapshot = writer.metrics_snapshot()
assert snapshot == {
"available": True,
"scope": "process_lifetime",
"instance_key": "inst-a",
"claims": {
"empty_polls_total": 0,
"claimed_batches_total": 0,
"unavailable_total": 0,
"lost_total": 0,
"foreign_instance_total": 0,
},
"outcomes": {
"completed_total": 0,
"duplicate_completed_total": 0,
"retryable_failure_total": 0,
"conflict_blocked_total": 0,
"permanent_failure_total": 0,
"dead_lettered_total": 0,
},
}
snapshot["claims"]["empty_polls_total"] = 999
assert writer.metrics_snapshot()["claims"]["empty_polls_total"] == 0
@pytest.mark.parametrize("instance_key", ["", " "])
def test_writer_rejects_explicit_empty_instance_key(instance_key):
outbox = InMemoryLedgerOutbox(instance_key="inst-a")
+60
View File
@@ -207,6 +207,66 @@ def test_spy_true_no_watchdog_update():
assert watchdog.last_seen(sid) is None # still not updated (spy=True)
def test_spy_response_exposes_ledger_outbox_metrics():
class _MetricsReader:
def metrics_snapshot(self):
return {
"available": True,
"scope": "process_lifetime",
"instance_key": "default",
"claims": {
"empty_polls_total": 7,
"claimed_batches_total": 1,
"unavailable_total": 0,
"lost_total": 0,
"foreign_instance_total": 0,
},
"outcomes": {
"completed_total": 1,
"duplicate_completed_total": 0,
"retryable_failure_total": 0,
"conflict_blocked_total": 0,
"permanent_failure_total": 0,
"dead_lettered_total": 0,
},
}
repo, *_ = _wire()
handler = make_slots_rpc_handler(
repo,
ledger_outbox_metrics_reader=_MetricsReader(),
)
spy_payload = handler(_req(spy=True)).payload
strategy_payload = handler(_req(spy=False)).payload
assert spy_payload["ledger_outbox_metrics"]["claims"]["empty_polls_total"] == 7
assert "ledger_outbox_metrics" not in strategy_payload
def test_spy_response_reports_metrics_unavailable_without_failing_slots():
class _FailingReader:
def metrics_snapshot(self):
raise RuntimeError("SECRET_METRICS_READER_FAILURE")
repo, *_ = _wire()
for reader in (None, _FailingReader()):
handler = make_slots_rpc_handler(
repo,
instance_key="default",
ledger_outbox_metrics_reader=reader,
)
payload = handler(_req(spy=True)).payload
assert len(payload["slots"]) == 2
assert payload["ledger_outbox_metrics"] == {
"available": False,
"scope": "process_lifetime",
"instance_key": "default",
"reason": "ledger_outbox_metrics_unavailable",
}
# REQ-073 AC-4: spy=False (default) → holding watchdog updated
def test_spy_false_updates_watchdog():
repo, svc, _, _, watchdog, handler = _wire()
@@ -0,0 +1,47 @@
"""Ledger writer loop failures remain visible without leaking exception text."""
from __future__ import annotations
import logging
import threading
from typing import Any
from trex_core.runtime.daemon import Daemon
_SENTINEL = "SECRET-LEDGER-DSN-PAYLOAD-DO-NOT-LOG"
def test_ledger_loop_logs_sanitized_error_and_continues(caplog):
call_count = 0
stop_event = threading.Event()
class _Writer:
def run_once(self):
nonlocal call_count
call_count += 1
if call_count == 1:
raise RuntimeError(f"dsn=postgresql://user:{_SENTINEL}@host/db")
stop_event.set()
class _Config:
ledger_interval_sec = 0.001
instance_key = "instance-a"
daemon: Any = object.__new__(Daemon)
daemon.stop = stop_event
daemon.config = _Config()
daemon.ledger_writer = _Writer()
with caplog.at_level(logging.ERROR, logger="trex_core.runtime.daemon"):
thread = threading.Thread(target=daemon._ledger_loop, daemon=True)
thread.start()
thread.join(timeout=2.0)
assert not thread.is_alive()
assert call_count >= 2
assert len(caplog.records) == 1
record = caplog.records[0]
assert "reason=ledger_writer_run_once_failed" in record.getMessage()
assert "instance_key=instance-a" in record.getMessage()
assert "exc_type=RuntimeError" in record.getMessage()
assert _SENTINEL not in caplog.text
assert record.exc_info is None