From 56bd7fca5172849a25d9f70a3e9c8082f09b1504 Mon Sep 17 00:00:00 2001 From: Dave Mihalcik Date: Tue, 23 Jun 2026 12:17:14 -0400 Subject: [PATCH 1/5] debug(xtest): log PQ/T mechanism detection path Instrument PlatformFeatureSet PQ/T mechanism detection (mechanism-xwing, mechanism-secpmlkem, mechanism-mlkem) to diagnose why these features go undetected even when km1's 'kas trust mechanisms initialized' log line lists hpqt:xwing and hpqt:secp256r1-mlkem768. Logs: resolved KAS_KM1_LOG_FILE path + existence, whether the mechanisms line matched (and what it contained), HTTP-probe fallback results, the semver gate decision, and which features were ultimately added. --- xtest/tdfs.py | 74 +++++++++++++++++++++++++++++++++++++++++++++++---- 1 file changed, 69 insertions(+), 5 deletions(-) diff --git a/xtest/tdfs.py b/xtest/tdfs.py index 1d970444..99a78384 100644 --- a/xtest/tdfs.py +++ b/xtest/tdfs.py @@ -26,9 +26,22 @@ def _km1_log_path() -> Path | None: """Return km1's log file path from env or auto-discovery, or None if absent.""" if p := os.getenv("KAS_KM1_LOG_FILE"): - return Path(p) + resolved = Path(p) + logger.debug( + "pqc-detect: KAS_KM1_LOG_FILE=%r -> %s (cwd=%s, exists=%s)", + p, + resolved.resolve(), + Path.cwd(), + resolved.exists(), + ) + return resolved platform_dir = os.getenv("PLATFORM_DIR", "../../platform") candidate = Path(platform_dir) / "logs" / "kas-km1.log" + logger.debug( + "pqc-detect: KAS_KM1_LOG_FILE unset; auto-discovery candidate=%s (exists=%s)", + candidate.resolve(), + candidate.exists(), + ) return candidate if candidate.exists() else None @@ -40,26 +53,50 @@ def _algs_from_km1_log() -> set[str]: """ log = _km1_log_path() if not log or not log.exists(): + logger.debug( + "pqc-detect: km1 log unavailable (path=%s); algs from log = {}", + log, + ) return set() algs: set[str] = set() + lines_read = 0 + json_lines = 0 try: with log.open() as f: for line in f: + lines_read += 1 try: entry = json.loads(line) except json.JSONDecodeError: continue + json_lines += 1 if ( entry.get("msg") == "kas trust mechanisms initialized" and "mechanisms" in entry ): - return set(entry["mechanisms"]) + mechs = set(entry["mechanisms"]) + logger.debug( + "pqc-detect: matched 'kas trust mechanisms initialized' " + "after %d lines (%d json); mechanisms=%s", + lines_read, + json_lines, + sorted(mechs), + ) + return mechs if entry.get("msg") == "kas config loaded" and "config" in entry: for k in entry["config"].get("keyring", []): if alg := k.get("alg"): algs.add(alg) except Exception: - pass + logger.exception("pqc-detect: failed reading km1 log %s", log) + logger.debug( + "pqc-detect: no 'kas trust mechanisms initialized' line found in %s " + "(read %d lines, %d json); falling back to keyring algs=%s", + log, + lines_read, + json_lines, + sorted(algs), + ) return algs @@ -93,8 +130,16 @@ def _kas_supports_algorithm(algorithm: str) -> bool: ) try: with urllib.request.urlopen(req, timeout=5) as resp: - return resp.status == 200 - except Exception: + ok = resp.status == 200 + logger.debug( + "pqc-detect: HTTP probe %s for %s -> status=%s", + url, + algorithm, + resp.status, + ) + return ok + except Exception as e: + logger.debug("pqc-detect: HTTP probe %s for %s failed: %s", url, algorithm, e) return False @@ -230,18 +275,37 @@ def __init__(self, **kwargs: dict[str, Any]): # Only attempt on platforms new enough to plausibly have PQ support. if self.semver is None or self.semver >= (0, 13, 0): algs = _algs_from_km1_log() + source = "km1-log" if not algs: + source = "http-probe" algs = { a for a in ("hpqt:xwing", "hpqt:secp256r1-mlkem768", "mlkem:768") if _kas_supports_algorithm(a) } + added: set[str] = set() if "hpqt:xwing" in algs: self.features.add("mechanism-xwing") + added.add("mechanism-xwing") if any(a.startswith("hpqt:secp") for a in algs): self.features.add("mechanism-secpmlkem") + added.add("mechanism-secpmlkem") if any(a.startswith("mlkem:") for a in algs): self.features.add("mechanism-mlkem") + added.add("mechanism-mlkem") + logger.debug( + "pqc-detect: semver=%s gate=open source=%s algs=%s -> added %s", + self.semver, + source, + sorted(algs), + sorted(added) or "", + ) + else: + logger.debug( + "pqc-detect: semver=%s < (0, 13, 0); skipping PQ/T mechanism " + "detection entirely (mechanism-xwing/secpmlkem/mlkem will be absent)", + self.semver, + ) # DPoP capabilities via well-known. Branch builds report stale semver # so we probe the live endpoint instead of gating by version. From 7c78e0ae84f60e70488965aa4bb7d497a63c84b7 Mon Sep 17 00:00:00 2001 From: Dave Mihalcik Date: Tue, 23 Jun 2026 12:21:27 -0400 Subject: [PATCH 2/5] debug(xtest): print PlatformFeatureSet detection in session header PQ/T mechanism tests skip (not fail) when a mechanism is undetected, and pytest hides captured output for skipped tests, so the pqc-detect DEBUG lines would not appear in CI. A pytest_report_header hook forces detection and echoes the captured xtest logs into the always-visible session header. --- xtest/conftest.py | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/xtest/conftest.py b/xtest/conftest.py index eaa88c34..1d6c50f0 100644 --- a/xtest/conftest.py +++ b/xtest/conftest.py @@ -27,6 +27,41 @@ logging.basicConfig(level=os.environ.get("LOGLEVEL", "DEBUG")) + +def pytest_report_header() -> list[str]: + """Surface PlatformFeatureSet detection in the always-visible session header. + + PQ/T mechanism detection (mechanism-xwing, mechanism-secpmlkem, ...) reads + km1's startup log and falls back to an HTTP probe. When a mechanism is + undetected the corresponding tests *skip*, and pytest does not show captured + log output for skipped tests -- so the per-step `pqc-detect:` DEBUG lines + would otherwise be invisible in CI. Forcing detection here and echoing the + captured `xtest` logs into the report header makes them always visible. + """ + records: list[str] = [] + + class _Collector(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + records.append(self.format(record)) + + handler = _Collector() + handler.setLevel(logging.DEBUG) + handler.setFormatter(logging.Formatter("%(levelname)s %(name)s: %(message)s")) + xlog = logging.getLogger("xtest") + xlog.addHandler(handler) + try: + pfs = tdfs.get_platform_features() + finally: + xlog.removeHandler(handler) + + lines = [ + f"platform version: {pfs.version} (semver={pfs.semver})", + f"detected features: {', '.join(sorted(pfs.features))}", + ] + lines += [f" {r}" for r in records if "pqc-detect:" in r] + return lines + + # Load all fixture modules pytest_plugins = [ "fixtures.kas", From 72d374da0db6ade6e9f8ae930050835cb9e20927 Mon Sep 17 00:00:00 2001 From: Dave Mihalcik Date: Tue, 23 Jun 2026 12:45:55 -0400 Subject: [PATCH 3/5] debug(xtest): surface platform error in PQ key-create skip reason When kas-registry key create rejects an hpqt algorithm, include the underlying otdfctl/platform error in the skip reason. This distinguishes a client-side otdfctl mapping rejection ('invalid algorithm' from sdkHelpers) from a server-side protovalidate rejection ('key_algorithm_defined' CEL), which the generic message hid. --- xtest/fixtures/keys.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/xtest/fixtures/keys.py b/xtest/fixtures/keys.py index 46a6b42f..5645e328 100644 --- a/xtest/fixtures/keys.py +++ b/xtest/fixtures/keys.py @@ -62,9 +62,16 @@ def _get_or_create_key( wrapping_key=root_key, wrapping_key_id="root", ) - except InvalidAlgorithm: + except InvalidAlgorithm as e: if required_features: - pytest.skip(f"Algorithm {algorithm} not supported by platform") + # Surface the underlying platform/otdfctl error so we can tell a + # client-side mapping rejection ("invalid algorithm" from + # otdfctl sdkHelpers) apart from a server-side protovalidate + # rejection ("key_algorithm_defined" CEL on the policy service). + pytest.skip( + f"Algorithm {algorithm} not supported by platform " + f"(features={required_features!r}): {e}" + ) raise return key From 348fb3a7a2fc81cba7dd865e0460993adcd4807f Mon Sep 17 00:00:00 2001 From: Dave Mihalcik Date: Tue, 23 Jun 2026 13:09:07 -0400 Subject: [PATCH 4/5] fix(xtest): plumb OTDFCTL_HEADS so admin otdfctl uses the head build The admin otdfctl fixture (used to register kas-registry keys for ABAC/PQC tests) is loaded by conftest.load_otdfctl(), which picks the head build via the OTDFCTL_HEADS env var, else dist/main/otdfctl.sh, else falls back to 'go run github.com/opentdf/otdfctl@latest'. OTDFCTL_HEADS was never set by the workflow, so for any platform/go ref that is a branch (not 'main') the admin CLI silently fell back to the released otdfctl@latest. That released CLI predates the hpqt:* algorithm mapping, so 'kas-registry key create --algorithm=hpqt:xwing' was rejected client-side and every PQ/T test skipped as 'Algorithm ... not supported by platform' -- even though the platform (KAS keyring + policy CEL) fully supported it. Set OTDFCTL_HEADS from configure-go.outputs.heads on each pytest step so the admin otdfctl uses the head build (sdk/go/dist/{tag}/otdfctl) that matches what's under test. --- .github/workflows/xtest.yml | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.github/workflows/xtest.yml b/.github/workflows/xtest.yml index 50f293e9..0267a22a 100644 --- a/.github/workflows/xtest.yml +++ b/.github/workflows/xtest.yml @@ -524,6 +524,7 @@ jobs: working-directory: otdftests/xtest env: PLATFORM_TAG: ${{ matrix.platform-tag }} + OTDFCTL_HEADS: ${{ steps.configure-go.outputs.heads }} - name: Validate otdf-local integration tests if: ${{ !inputs }} @@ -543,6 +544,7 @@ jobs: env: PLATFORM_DIR: "../../${{ steps.run-platform.outputs.platform-working-dir }}" PLATFORM_TAG: ${{ matrix.platform-tag }} + OTDFCTL_HEADS: ${{ steps.configure-go.outputs.heads }} - name: Run all standard xtests if: ${{ env.FOCUS_SDK == 'all' }} @@ -554,6 +556,7 @@ jobs: PLATFORM_DIR: "../../${{ steps.run-platform.outputs.platform-working-dir }}" SCHEMA_FILE: "manifest.schema.json" PLATFORM_TAG: ${{ matrix.platform-tag }} + OTDFCTL_HEADS: ${{ steps.configure-go.outputs.heads }} - name: Run xtests focusing on a specific SDK if: ${{ env.FOCUS_SDK != 'all' }} @@ -565,6 +568,7 @@ jobs: PLATFORM_DIR: "../../${{ steps.run-platform.outputs.platform-working-dir }}" SCHEMA_FILE: "manifest.schema.json" PLATFORM_TAG: ${{ matrix.platform-tag }} + OTDFCTL_HEADS: ${{ steps.configure-go.outputs.heads }} ######## ATTRIBUTE BASED CONFIGURATION ############# @@ -674,6 +678,7 @@ jobs: env: PLATFORM_DIR: "../../${{ steps.run-platform.outputs.platform-working-dir }}" PLATFORM_TAG: ${{ matrix.platform-tag }} + OTDFCTL_HEADS: ${{ steps.configure-go.outputs.heads }} PLATFORM_LOG_FILE: "../../${{ steps.run-platform.outputs.platform-log-file }}" KAS_ALPHA_LOG_FILE: "../../${{ steps.kas-alpha.outputs.log-file }}" KAS_BETA_LOG_FILE: "../../${{ steps.kas-beta.outputs.log-file }}" From 33f7239fa3c2a313314974c095f00ffa8275037e Mon Sep 17 00:00:00 2001 From: Dave Mihalcik Date: Tue, 23 Jun 2026 13:27:33 -0400 Subject: [PATCH 5/5] refactor(xtest): trim PQ debug logging to header summary Replace the verbose per-call pqc-detect DEBUG logging with a concise always-visible session-header summary of the detected platform version and feature set (feature detection gates skips, and pytest hides captured output for skipped tests). Keep lightweight logger.debug detail on the failure paths in tdfs.py (km1 log missing/unreadable, KAS algorithm probe failure) so there's still a breadcrumb when PQ/T detection comes up empty. --- xtest/conftest.py | 31 ++++---------------- xtest/tdfs.py | 74 ++++------------------------------------------- 2 files changed, 12 insertions(+), 93 deletions(-) diff --git a/xtest/conftest.py b/xtest/conftest.py index 1d6c50f0..4f39176b 100644 --- a/xtest/conftest.py +++ b/xtest/conftest.py @@ -31,35 +31,16 @@ def pytest_report_header() -> list[str]: """Surface PlatformFeatureSet detection in the always-visible session header. - PQ/T mechanism detection (mechanism-xwing, mechanism-secpmlkem, ...) reads - km1's startup log and falls back to an HTTP probe. When a mechanism is - undetected the corresponding tests *skip*, and pytest does not show captured - log output for skipped tests -- so the per-step `pqc-detect:` DEBUG lines - would otherwise be invisible in CI. Forcing detection here and echoing the - captured `xtest` logs into the report header makes them always visible. + Feature detection drives skips (e.g. mechanism-xwing gates the PQ/T tests), + and pytest does not show captured output for skipped tests. Echoing the + detected version and feature set into the report header makes it visible in + CI even when every gated test skips. """ - records: list[str] = [] - - class _Collector(logging.Handler): - def emit(self, record: logging.LogRecord) -> None: - records.append(self.format(record)) - - handler = _Collector() - handler.setLevel(logging.DEBUG) - handler.setFormatter(logging.Formatter("%(levelname)s %(name)s: %(message)s")) - xlog = logging.getLogger("xtest") - xlog.addHandler(handler) - try: - pfs = tdfs.get_platform_features() - finally: - xlog.removeHandler(handler) - - lines = [ + pfs = tdfs.get_platform_features() + return [ f"platform version: {pfs.version} (semver={pfs.semver})", f"detected features: {', '.join(sorted(pfs.features))}", ] - lines += [f" {r}" for r in records if "pqc-detect:" in r] - return lines # Load all fixture modules diff --git a/xtest/tdfs.py b/xtest/tdfs.py index 99a78384..50f6e459 100644 --- a/xtest/tdfs.py +++ b/xtest/tdfs.py @@ -26,22 +26,9 @@ def _km1_log_path() -> Path | None: """Return km1's log file path from env or auto-discovery, or None if absent.""" if p := os.getenv("KAS_KM1_LOG_FILE"): - resolved = Path(p) - logger.debug( - "pqc-detect: KAS_KM1_LOG_FILE=%r -> %s (cwd=%s, exists=%s)", - p, - resolved.resolve(), - Path.cwd(), - resolved.exists(), - ) - return resolved + return Path(p) platform_dir = os.getenv("PLATFORM_DIR", "../../platform") candidate = Path(platform_dir) / "logs" / "kas-km1.log" - logger.debug( - "pqc-detect: KAS_KM1_LOG_FILE unset; auto-discovery candidate=%s (exists=%s)", - candidate.resolve(), - candidate.exists(), - ) return candidate if candidate.exists() else None @@ -53,50 +40,27 @@ def _algs_from_km1_log() -> set[str]: """ log = _km1_log_path() if not log or not log.exists(): - logger.debug( - "pqc-detect: km1 log unavailable (path=%s); algs from log = {}", - log, - ) + logger.debug("km1 log not found (path=%s); no algs from log", log) return set() algs: set[str] = set() - lines_read = 0 - json_lines = 0 try: with log.open() as f: for line in f: - lines_read += 1 try: entry = json.loads(line) except json.JSONDecodeError: continue - json_lines += 1 if ( entry.get("msg") == "kas trust mechanisms initialized" and "mechanisms" in entry ): - mechs = set(entry["mechanisms"]) - logger.debug( - "pqc-detect: matched 'kas trust mechanisms initialized' " - "after %d lines (%d json); mechanisms=%s", - lines_read, - json_lines, - sorted(mechs), - ) - return mechs + return set(entry["mechanisms"]) if entry.get("msg") == "kas config loaded" and "config" in entry: for k in entry["config"].get("keyring", []): if alg := k.get("alg"): algs.add(alg) except Exception: - logger.exception("pqc-detect: failed reading km1 log %s", log) - logger.debug( - "pqc-detect: no 'kas trust mechanisms initialized' line found in %s " - "(read %d lines, %d json); falling back to keyring algs=%s", - log, - lines_read, - json_lines, - sorted(algs), - ) + logger.debug("failed reading km1 log %s", log, exc_info=True) return algs @@ -130,16 +94,9 @@ def _kas_supports_algorithm(algorithm: str) -> bool: ) try: with urllib.request.urlopen(req, timeout=5) as resp: - ok = resp.status == 200 - logger.debug( - "pqc-detect: HTTP probe %s for %s -> status=%s", - url, - algorithm, - resp.status, - ) - return ok + return resp.status == 200 except Exception as e: - logger.debug("pqc-detect: HTTP probe %s for %s failed: %s", url, algorithm, e) + logger.debug("KAS algorithm probe for %s at %s failed: %s", algorithm, url, e) return False @@ -275,37 +232,18 @@ def __init__(self, **kwargs: dict[str, Any]): # Only attempt on platforms new enough to plausibly have PQ support. if self.semver is None or self.semver >= (0, 13, 0): algs = _algs_from_km1_log() - source = "km1-log" if not algs: - source = "http-probe" algs = { a for a in ("hpqt:xwing", "hpqt:secp256r1-mlkem768", "mlkem:768") if _kas_supports_algorithm(a) } - added: set[str] = set() if "hpqt:xwing" in algs: self.features.add("mechanism-xwing") - added.add("mechanism-xwing") if any(a.startswith("hpqt:secp") for a in algs): self.features.add("mechanism-secpmlkem") - added.add("mechanism-secpmlkem") if any(a.startswith("mlkem:") for a in algs): self.features.add("mechanism-mlkem") - added.add("mechanism-mlkem") - logger.debug( - "pqc-detect: semver=%s gate=open source=%s algs=%s -> added %s", - self.semver, - source, - sorted(algs), - sorted(added) or "", - ) - else: - logger.debug( - "pqc-detect: semver=%s < (0, 13, 0); skipping PQ/T mechanism " - "detection entirely (mechanism-xwing/secpmlkem/mlkem will be absent)", - self.semver, - ) # DPoP capabilities via well-known. Branch builds report stale semver # so we probe the live endpoint instead of gating by version.