From c70c1c1c9797fb52618742609cfe4898d539c708 Mon Sep 17 00:00:00 2001 From: Shaun Smith <51304449+smith-xyz@users.noreply.github.com> Date: Fri, 30 Oct 2026 15:39:40 -0400 Subject: [PATCH 1/2] chore: start Ledger diagnostics through Core logging (XWING-2440) From 95509be5cc76e1a1a6683ec83bbbece0710bfa56 Mon Sep 17 00:00:00 2001 From: Shaun Smith <51304449+smith-xyz@users.noreply.github.com> Date: Fri, 30 Oct 2026 22:11:43 -0400 Subject: [PATCH 2/2] feat(logging): integrate ledger diagnostics --- pyproject.toml | 2 +- src/traust_core/v1/context/context.py | 2 +- src/traust_core/v1/context/logging.py | 6 ++ src/traust_core/v1/services/ledger.py | 4 +- tests/v1/services/test_ledger.py | 119 ++++++++++++++++++++++++++ uv.lock | 4 +- 6 files changed, 132 insertions(+), 5 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 4ef6ddef..e2c6e3f9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -24,7 +24,7 @@ dependencies = [ "tree-sitter-rust==0.24.2", "tree-sitter-ruby==0.23.1", "traust-contracts @ git+https://github.com/traust-security/traust-contracts.git@726d2736009a18184cea4eddeabaab185a117918", - "traust-ledger @ git+https://github.com/traust-security/traust-ledger.git@461f00d1a935f50c0f504e0694b258873d12ccfe", + "traust-ledger @ git+https://github.com/traust-security/traust-ledger.git@deb46664c0f95ec32f46b42056da42f83ef2da69", ] [project.scripts] diff --git a/src/traust_core/v1/context/context.py b/src/traust_core/v1/context/context.py index e387d414..51e6df42 100644 --- a/src/traust_core/v1/context/context.py +++ b/src/traust_core/v1/context/context.py @@ -344,7 +344,7 @@ def from_file(cls, path: Path) -> Context: return cls(Config.from_file(path)) def configure_logging(self, *logger_roots: str) -> None: - install_logging(self.config.logging, self.config.home, logger_roots) + install_logging(self.config.logging, self.config.home, ("traust_ledger", *logger_roots)) @cached_property def object_store(self) -> ObjectStore: diff --git a/src/traust_core/v1/context/logging.py b/src/traust_core/v1/context/logging.py index 98e3ea2e..718d4dc7 100644 --- a/src/traust_core/v1/context/logging.py +++ b/src/traust_core/v1/context/logging.py @@ -102,6 +102,9 @@ def format(self, record: logging.LogRecord) -> str: "error_type": getattr(record, "error_type", None), "error_source": getattr(record, "error_source", None), "operation": getattr(record, "operation", None), + "provider": getattr(record, "provider", None), + "method": getattr(record, "method", None), + "reason": getattr(record, "reason", None), "target_hash": getattr(record, "target_hash", None), "outcome": getattr(record, "outcome", None), "attempts": getattr(record, "attempts", None), @@ -133,6 +136,9 @@ def format(self, record: logging.LogRecord) -> str: "error_type", "error_source", "operation", + "provider", + "method", + "reason", "target_hash", "outcome", "attempts", diff --git a/src/traust_core/v1/services/ledger.py b/src/traust_core/v1/services/ledger.py index 644fc707..8faba1b1 100644 --- a/src/traust_core/v1/services/ledger.py +++ b/src/traust_core/v1/services/ledger.py @@ -152,11 +152,13 @@ def append_decision( checkpoint = self._sign(grown, stale) if sign else self._unsigned(grown, stale) self._uow.commit() duration_ms = (perf_counter() - started) * 1000 + degraded = checkpoint.signing is Signing.FAILED self._uow.after_commit( lambda: _log_outcome( "append", - "committed", + "degraded" if degraded else "committed", duration_ms, + level=logging.WARNING if degraded else logging.INFO, repository_id=str(repository_id), decision_id=str(decision.id), layer_id=str(checkpoint.layer.id), diff --git a/tests/v1/services/test_ledger.py b/tests/v1/services/test_ledger.py index 5e5cc23b..8845c70b 100644 --- a/tests/v1/services/test_ledger.py +++ b/tests/v1/services/test_ledger.py @@ -10,11 +10,13 @@ from collections.abc import Callable, Iterator from pathlib import Path from typing import Any +from unittest import mock from uuid import UUID, uuid4 import pytest import sqlalchemy as sa from sqlalchemy.engine import Engine +from traust_ledger.integrity import signing as ledger_signing from tests.v1.conftest import SQL_BACKENDS, contract_db from tests.v1.repositories.tables.conftest import Seed, saved_id @@ -36,6 +38,8 @@ from traust_core.v1.repositories.contract import SqlTraustUnitOfWork from traust_core.v1.services.ledger import LedgerConfig, LedgerService +SECRET = "synthetic-secret-never-log" + @pytest.fixture(params=SQL_BACKENDS) def engine(request: pytest.FixtureRequest, tmp_path: Path) -> Iterator[Engine]: @@ -181,6 +185,121 @@ def test_deferred_ledger_event_keeps_its_request_scope(engine: Engine, tmp_path: assert len(events) == 1 and events[0]["request_id"] == "job-123" +@pytest.mark.parametrize( + "outputs", + [None, ("file",), ("stderr",)], + ids=["default", "file-only", "stderr-only"], +) +def test_core_logging_carries_correlated_provider_and_service_outcomes_once( + engine: Engine, + keys: tuple[str, str], + tmp_path: Path, + capsys: pytest.CaptureFixture[str], + outputs: tuple[str, ...] | None, +) -> None: + file = tmp_path / "ledger-integration.log" + logging_config = {"level": "INFO", "file": file} + if outputs is not None: + logging_config["outputs"] = outputs + Context( + Config(home=tmp_path, logging=LoggingConfig.model_validate(logging_config)) + ).configure_logging() + repo_id, (decision,) = decisions(engine, 1) + assert decision.id is not None + decision = decision.model_copy(update={"actor": SECRET, "rationale": SECRET}) + uow = SqlTraustUnitOfWork(engine) + with correlation_scope("ledger-job-123", order_id=decision.id), uow: + receipt = ledger(uow, key_path=keys[0]).append_decision(decision, repo_id) + uow.commit() + + stderr = capsys.readouterr().err + selected = outputs or ("stderr", "file") + destinations: list[str] = [] + if "stderr" in selected: + destinations.append(stderr) + else: + assert stderr == "" + if "file" in selected: + destinations.append(file.read_text()) + else: + assert not file.exists() + + for output in destinations: + rows = [json.loads(line) for line in output.splitlines()] + events = [row for row in rows if row["operation"] in {"ledger.sign", "ledger.append"}] + assert [(row["operation"], row["outcome"]) for row in events] == [ + ("ledger.sign", "signed"), + ("ledger.append", "committed"), + ] + assert all(row["request_id"] == "ledger-job-123" for row in events) + assert all(row["order_id"] == str(decision.id) for row in events) + assert (events[0]["provider"], events[0]["method"], events[0]["reason"]) == ( + "cosign", + "keypair", + "completed", + ) + assert all( + value not in output + for value in (SECRET, keys[0], receipt.checkpoint.layer.merkle_root_signature) + ) + + +def test_optional_signing_failure_is_correlated_without_raw_provider_error( + engine: Engine, + tmp_path: Path, + monkeypatch: pytest.MonkeyPatch, +) -> None: + file = tmp_path / "ledger-degraded.log" + Context( + Config( + home=tmp_path, + logging=LoggingConfig(level="INFO", file=file, outputs=("file",)), + ) + ).configure_logging() + repo_id, (decision,) = decisions(engine, 1) + assert decision.id is not None + monkeypatch.setattr( + ledger_signing.subprocess, + "run", + mock.Mock( + return_value=mock.Mock(returncode=9, stdout=SECRET.encode(), stderr=SECRET.encode()) + ), + ) + uow = SqlTraustUnitOfWork(engine) + with correlation_scope("ledger-degraded-123", order_id=decision.id), uow: + receipt = ledger(uow, key_path=f"/private/{SECRET}.key").append_decision(decision, repo_id) + uow.commit() + + rows = [json.loads(line) for line in file.read_text().splitlines()] + events = [row for row in rows if row["operation"] in {"ledger.sign", "ledger.append"}] + assert [(row["operation"], row["outcome"], row["status"]) for row in events] == [ + ("ledger.sign", "failed", None), + ("ledger.append", "degraded", "failed"), + ] + assert receipt.checkpoint.signing is Signing.FAILED + assert all(row["request_id"] == "ledger-degraded-123" for row in events) + assert SECRET not in file.read_text() + + +def test_rolled_back_signed_append_has_no_committed_service_outcome( + engine: Engine, keys: tuple[str, str], tmp_path: Path +) -> None: + file = tmp_path / "ledger-rollback.log" + Context( + Config( + home=tmp_path, + logging=LoggingConfig(level="INFO", file=file, outputs=("file",)), + ) + ).configure_logging() + repo_id, (decision,) = decisions(engine, 1) + uow = SqlTraustUnitOfWork(engine) + with correlation_scope("ledger-rollback-123"), uow: + ledger(uow, key_path=keys[0]).append_decision(decision, repo_id) + + rows = [json.loads(line) for line in file.read_text().splitlines()] + assert [row["operation"] for row in rows if row["operation"]] == ["ledger.sign"] + + def test_an_unsaved_decision_is_rejected(engine: Engine) -> None: repo_id, (decision,) = decisions(engine, 1) with pytest.raises(ValidationError, match="saved decision"): diff --git a/uv.lock b/uv.lock index 382d1528..64c8fc7a 100644 --- a/uv.lock +++ b/uv.lock @@ -1331,7 +1331,7 @@ requires-dist = [ { name = "referencing", specifier = ">=0.30" }, { name = "sqlalchemy", specifier = ">=2.0" }, { name = "traust-contracts", git = "https://github.com/traust-security/traust-contracts.git?rev=726d2736009a18184cea4eddeabaab185a117918" }, - { name = "traust-ledger", git = "https://github.com/traust-security/traust-ledger.git?rev=461f00d1a935f50c0f504e0694b258873d12ccfe" }, + { name = "traust-ledger", git = "https://github.com/traust-security/traust-ledger.git?rev=deb46664c0f95ec32f46b42056da42f83ef2da69" }, { name = "tree-sitter", specifier = "==0.26.0" }, { name = "tree-sitter-java", specifier = "==0.23.5" }, { name = "tree-sitter-javascript", specifier = "==0.25.0" }, @@ -1356,7 +1356,7 @@ dev = [ [[package]] name = "traust-ledger" version = "0.0.0" -source = { git = "https://github.com/traust-security/traust-ledger.git?rev=461f00d1a935f50c0f504e0694b258873d12ccfe#461f00d1a935f50c0f504e0694b258873d12ccfe" } +source = { git = "https://github.com/traust-security/traust-ledger.git?rev=deb46664c0f95ec32f46b42056da42f83ef2da69#deb46664c0f95ec32f46b42056da42f83ef2da69" } [[package]] name = "tree-sitter"