From 951c52d8e82fada4315981566e235fe7aa6d6025 Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 10 Nov 2026 13:48:04 +0000 Subject: [PATCH] test(compile): name each SQL test cache miss when a delta comparison fails The seeded delta-compile series in test_compile_delta.py sometimes fails in CI because one compile of a delta/full pair re-plans SQL tests and the other does not, from the same copied project. It has not reproduced locally, and the failure text only shows the extra "SQL test planning START" line. - A warm compile's cache-miss debug line now also names each missed record by its key's first 12 characters and its reason, for example "identity_changed=1 (records d11ac5013d79:identity_changed)". - A cache file that exists but yields no records (unreadable, cut short, malformed or simply empty) was silent; it now logs "(the cache file held no usable records)". - When a delta/full comparison fails, the series appends what each side's compile logged about the SQL test cache, so the CI log says which side missed, which records and why. These are synthetic test-project metadata only: record keys and reason labels, with no SQL text or environment. The hit/miss decision itself is unchanged: an artifact whose mtime differs from its record is already compared by digest before it counts as a miss. --- .../sqlbuild-cache/src/artifacts/constants.rs | 3 +- .../_helpers/compile_command/target_writer.rs | 41 ++++++++++++++++--- .../delta_compile_series/_helpers/outcomes.py | 34 +++++++++++++++ scripts/delta_compile_series/constants.py | 4 ++ .../main/run_delta_compile_series.py | 14 ++++++- .../cli/commands/main/compile/helpers.py | 8 ++++ .../compile/test_sql_test_cache_misses.py | 6 +++ .../delta_compile_series/main/_test_types.py | 3 ++ .../delta_compile_series/main/helpers.py | 8 ++++ .../main/test_comparison_evidence.py | 3 ++ 10 files changed, 117 insertions(+), 7 deletions(-) diff --git a/crates/sqlbuild-cache/src/artifacts/constants.rs b/crates/sqlbuild-cache/src/artifacts/constants.rs index 93d990ca58..93f0d72737 100644 --- a/crates/sqlbuild-cache/src/artifacts/constants.rs +++ b/crates/sqlbuild-cache/src/artifacts/constants.rs @@ -2,7 +2,8 @@ pub const NEW_FILE_MODE: u32 = 0o666; /// The existing SQL-test cache snapshot format, shared by native readers and writers. pub(crate) const SQL_TEST_CACHE_VERSION: u64 = 5; -pub(crate) const SQL_TEST_CACHE_FILE: &str = "sql-test-artifacts.json"; +/// The SQL-test cache snapshot's file name inside the compile cache directory. +pub const SQL_TEST_CACHE_FILE: &str = "sql-test-artifacts.json"; pub(crate) const MAX_SQL_TEST_CACHE_BYTES: u64 = 10_000_000; pub(crate) const MAX_SQL_TEST_CACHE_RECORDS: usize = 100_000; /// The extension every compiled SQL test artifact carries. diff --git a/crates/sqlbuild-python/src/bindings/_helpers/compile_command/target_writer.rs b/crates/sqlbuild-python/src/bindings/_helpers/compile_command/target_writer.rs index 4bc7b64b92..d75efc66e2 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/compile_command/target_writer.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/compile_command/target_writer.rs @@ -9,6 +9,7 @@ use pyo3::prelude::{ }; use pyo3::types::{PyDict, PyDictMethods, PyTuple, PyTupleMethods}; use pyo3::{IntoPyObjectExt, pyclass, pyfunction, wrap_pyfunction}; +use sqlbuild_cache::artifacts::constants::SQL_TEST_CACHE_FILE; use sqlbuild_cache::artifacts::main::new_sql_test_record::new_sql_test_record; use sqlbuild_cache::artifacts::main::reusable_sql_test_record::reusable_sql_test_record; use sqlbuild_cache::artifacts::models::{SqlTestArtifactRecord, SqlTestRecordMiss}; @@ -66,6 +67,10 @@ const SQL_FILE_SUFFIX: &str = ".sql"; const SQL_TEST_CACHE_LOGGER: &str = "sqlbuild.compile.reuse"; /// The miss reason of a SQL test the cache file holds no record for. const NOT_RECORDED: &str = "not_recorded"; +/// Missed records a cache-miss debug line names before summarising the rest. +const LOGGED_MISSES: usize = 16; +/// Leading characters of a record key that name it in a cache-miss debug line. +const LOGGED_KEY_CHARS: usize = 12; /// `functions/` path components that already lead a function's path. const LANGUAGE_DIR_DEPTH: usize = 2; const PUBLISHED_STAGING_CHANGED: &str = "changed"; @@ -453,20 +458,43 @@ fn test_identities<'py>( Ok(identities) } -/// Log why a warm SQL test artifact cache could not keep some artifacts, by reason. -fn log_cache_misses(py: Python<'_>, misses: &BTreeMap<&'static str, usize>) -> PyResult<()> { +/// Log a warm SQL test cache's misses: counts by reason, then each record's key and reason. +fn log_cache_misses( + py: Python<'_>, + misses: &BTreeMap<&'static str, usize>, + missed: &[String], + unreadable: bool, +) -> PyResult<()> { let reasons: String = misses .iter() .map(|(reason, count)| format!("{reason}={count}")) .collect::>() .join(","); + let detail: String = if unreadable { + "the cache file held no usable records".to_owned() + } else { + let mut shown: Vec = missed.iter().take(LOGGED_MISSES).cloned().collect(); + if missed.len() > LOGGED_MISSES { + shown.push(format!("{} more", missed.len() - LOGGED_MISSES)); + } + format!("records {}", shown.join(",")) + }; host::log_debug_message( py, SQL_TEST_CACHE_LOGGER, - &format!("SQL test artifact cache missed: {reasons}"), + &format!("SQL test artifact cache missed: {reasons} ({detail})"), ) } +/// Whether `cache_dir` holds a SQL test cache file, so an empty read means it was unreadable. +fn cache_file_present(cache_dir: &Bound<'_, PyAny>) -> PyResult { + if cache_dir.is_none() { + return Ok(false); + } + let directory: PathBuf = cache_dir.extract()?; + Ok(directory.join(SQL_TEST_CACHE_FILE).is_file()) +} + /// Plan every SQL test whose cached artifact under `target_dir` cannot be reused. pub(crate) fn plan_tests<'py>( target_dir: &Bound<'py, PyAny>, @@ -503,6 +531,7 @@ pub(crate) fn plan_tests<'py>( let mut cached_paths: Vec = Vec::new(); let mut cached_records: Vec<(String, SqlTestArtifactRecord)> = Vec::new(); let mut misses: BTreeMap<&'static str, usize> = BTreeMap::new(); + let mut missed: Vec = Vec::new(); for (index, (test, identity)) in tests.into_iter().zip(identities).enumerate() { let Some((record_key, identity)) = identity else { pending.push((test.unbind(), None, None)); @@ -517,6 +546,8 @@ pub(crate) fn plan_tests<'py>( }); if let Err(reason) = reusable { *misses.entry(reason).or_default() += 1; + let short: &str = record_key.get(..LOGGED_KEY_CHARS).unwrap_or(&record_key); + missed.push(format!("{short}:{reason}")); } if let Ok(record) = reusable { let path = tests_root_path.join(&record.relative_path); @@ -528,8 +559,8 @@ pub(crate) fn plan_tests<'py>( } yield_interpreter(py, index); } - if !cached.is_empty() && !misses.is_empty() { - log_cache_misses(py, &misses)?; + if !misses.is_empty() && (!cached.is_empty() || cache_file_present(&cache_dir)?) { + log_cache_misses(py, &misses, &missed, cached.is_empty())?; } let pending_tests: Vec> = pending .iter() diff --git a/scripts/delta_compile_series/_helpers/outcomes.py b/scripts/delta_compile_series/_helpers/outcomes.py index d47cb8aed8..76a38537af 100644 --- a/scripts/delta_compile_series/_helpers/outcomes.py +++ b/scripts/delta_compile_series/_helpers/outcomes.py @@ -2,9 +2,11 @@ from __future__ import annotations +import json import re from itertools import zip_longest from pathlib import Path +from typing import Any from scripts.delta_compile_series.constants import ( AFTER_FAILED_RULES, @@ -15,7 +17,11 @@ DELTA_MISMATCH_PATTERN, DELTA_VERIFIED_LINE, DURATION_PATTERN, + LOG_DIAGNOSTICS_FILE, + LOG_RUNS_GLOB, + MAX_CACHE_LOG_LINES, MISMATCH_EXIT_CODE, + SQL_TEST_CACHE_LOG_PREFIX, STALE_PROBLEMS, ) from scripts.delta_compile_series.models import DeltaCompileEdit, DeltaCompileOutcome @@ -96,3 +102,31 @@ def full_compile_difference( ) return f"{stream} differs from a full compile: {first[0]!r} vs {first[1]!r}" return None + + +def log_runs(project: Path) -> frozenset[Path]: + """The per-invocation log directories a project holds.""" + + return frozenset(path for path in project.glob(LOG_RUNS_GLOB) if path.is_dir()) + + +def sql_test_cache_lines(*, project: Path, earlier: frozenset[Path]) -> str: + """Cache-miss reasons and record keys logged since `earlier`, never SQL text or environment.""" + + lines: list[str] = [] + for run in sorted(log_runs(project) - earlier): + try: + text: str = (run / LOG_DIAGNOSTICS_FILE).read_text(encoding="utf-8", errors="replace") + rows: list[str] = text.splitlines() + except OSError: + continue + for row in rows: + try: + record: Any = json.loads(row) + except ValueError: + continue + message: Any = record.get("message") if isinstance(record, dict) else None + if isinstance(message, str) and message.startswith(SQL_TEST_CACHE_LOG_PREFIX): + lines.append(message) + shown: list[str] = lines[:MAX_CACHE_LOG_LINES] + return " | ".join(shown) if shown else "none logged" diff --git a/scripts/delta_compile_series/constants.py b/scripts/delta_compile_series/constants.py index 8e8e24d12c..7c8a33a4fb 100644 --- a/scripts/delta_compile_series/constants.py +++ b/scripts/delta_compile_series/constants.py @@ -22,6 +22,10 @@ PROJECT_CONFIG: str = "sqlbuild_project.toml" RANDOM_VALUE_LIMIT: int = 10**6 FULL_COPY_SUFFIX: str = "_full_copy" +LOG_RUNS_GLOB: str = "logs/*/*" +LOG_DIAGNOSTICS_FILE: str = "diagnostics.jsonl" +SQL_TEST_CACHE_LOG_PREFIX: str = "SQL test artifact cache" +MAX_CACHE_LOG_LINES: int = 4 DURATION_PATTERN: re.Pattern[str] = re.compile(r"\s*\(\d+(?:\.\d+)?s\)") COMPILE_TIMINGS_PATTERN: re.Pattern[str] = re.compile(r'\n "compile_timings": \{[^{}]*\n \}') MAX_FAILURES: int = 4 diff --git a/scripts/delta_compile_series/main/run_delta_compile_series.py b/scripts/delta_compile_series/main/run_delta_compile_series.py index dd8e31d65d..2b181b1db5 100644 --- a/scripts/delta_compile_series/main/run_delta_compile_series.py +++ b/scripts/delta_compile_series/main/run_delta_compile_series.py @@ -10,7 +10,12 @@ from scripts.delta_compile_series._helpers.edits import edited_file from scripts.delta_compile_series._helpers.evidence import cache_state, keep_comparison_failure -from scripts.delta_compile_series._helpers.outcomes import full_compile_difference, judged +from scripts.delta_compile_series._helpers.outcomes import ( + full_compile_difference, + judged, + log_runs, + sql_test_cache_lines, +) from scripts.delta_compile_series.constants import ( DELTA_COMPILE_LINE, DELTA_WEIGHT, @@ -41,6 +46,7 @@ def _compared( copy: Path = project_dir.with_name(project_dir.name + FULL_COPY_SUFFIX) shutil.rmtree(copy, ignore_errors=True) _ = shutil.copytree(project_dir, copy, symlinks=True) + earlier: tuple[frozenset[Path], frozenset[Path]] = (log_runs(project_dir), log_runs(copy)) before: dict[str, Any] = ( {"delta": cache_state(project_dir), "full": cache_state(copy)} if diagnostics_dir else {} ) @@ -68,6 +74,12 @@ def _compared( ) except OSError: pass + if problem is not None: + problem += ( + f"; SQL test cache: delta " + f"{sql_test_cache_lines(project=project_dir, earlier=earlier[0])}" + f"; full {sql_test_cache_lines(project=copy, earlier=earlier[1])}" + ) return outcome, problem diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/compile/helpers.py b/tests/e2e/src/sqlbuild/cli/commands/main/compile/helpers.py index 7b42f1adbd..978b2a6221 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/compile/helpers.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/compile/helpers.py @@ -5573,3 +5573,11 @@ def flip_compiled_sql_test_bytes(project_dir: Path) -> None: for artifact in sorted((project_dir / "target/compiled/tests").rglob("*.sql")): _ = artifact.write_text(artifact.read_text().replace("SELECT", "select", 1)) + + +def truncate_sql_test_cache(project_dir: Path) -> None: + """Cut every SQL test cache file to its first half, as a write cut short would leave it.""" + + for cache in sorted((project_dir / "target/cache").rglob("sql-test-artifacts.json")): + text: str = cache.read_text() + _ = cache.write_text(text[: len(text) // 2]) diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/compile/test_sql_test_cache_misses.py b/tests/e2e/src/sqlbuild/cli/commands/main/compile/test_sql_test_cache_misses.py index 2f9750e3d5..f8899b59d7 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/compile/test_sql_test_cache_misses.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/compile/test_sql_test_cache_misses.py @@ -15,6 +15,7 @@ append_to_compiled_sql_tests, flip_compiled_sql_test_bytes, run_installed_sqb, + truncate_sql_test_cache, ) _MISS_LINE: str = "SQL test artifact cache missed" @@ -34,6 +35,11 @@ change=flip_compiled_sql_test_bytes, expected_debug_line=f"{_MISS_LINE}: content_changed=", ), + SqlTestCacheMissE2ETestCase( + description="a cut-short cache file logs that it held no usable records", + change=truncate_sql_test_cache, + expected_debug_line="(the cache file held no usable records)", + ), ], ids=lambda case: case.description, ) diff --git a/tests/unit/scripts/delta_compile_series/main/_test_types.py b/tests/unit/scripts/delta_compile_series/main/_test_types.py index 30c764273b..44cc778147 100644 --- a/tests/unit/scripts/delta_compile_series/main/_test_types.py +++ b/tests/unit/scripts/delta_compile_series/main/_test_types.py @@ -13,3 +13,6 @@ class ComparisonEvidenceTestCase: steps: int = 1 expected_mismatches: int = 1 cache_relative_path: str = "orders/check.sql" + full_cache_log: str = ( + "SQL test artifact cache missed: not_recorded=1 (the cache file held no usable records)" + ) diff --git a/tests/unit/scripts/delta_compile_series/main/helpers.py b/tests/unit/scripts/delta_compile_series/main/helpers.py index 22d1a9df03..6bc8ea8e40 100644 --- a/tests/unit/scripts/delta_compile_series/main/helpers.py +++ b/tests/unit/scripts/delta_compile_series/main/helpers.py @@ -52,6 +52,14 @@ def compile_project() -> DeltaCompileOutcome: def compile_full(copy: Path) -> DeltaCompileOutcome: _ = (copy / cache.relative_to(project)).write_text("{") + run: Path = copy / "logs/2026-11-10/full-run" + run.mkdir(parents=True) + _ = (run / "diagnostics.jsonl").write_text( + json.dumps({"message": "Delta compile fell back: disabled"}) + + "\n" + + json.dumps({"message": test_case.full_cache_log}) + + "\n" + ) return DeltaCompileOutcome( 0, test_case.stdout, diff --git a/tests/unit/scripts/delta_compile_series/main/test_comparison_evidence.py b/tests/unit/scripts/delta_compile_series/main/test_comparison_evidence.py index 98c2548a32..c4183fcf7d 100644 --- a/tests/unit/scripts/delta_compile_series/main/test_comparison_evidence.py +++ b/tests/unit/scripts/delta_compile_series/main/test_comparison_evidence.py @@ -32,6 +32,9 @@ def test_given_mismatch_when_capturing_then_keeps_private_paired_evidence( "stderr differs from a full compile: '' vs 'SQL test planning START'" in result.unexpected[0] ) + assert result.unexpected[0].endswith( + f"; SQL test cache: delta none logged; full {test_case.full_cache_log}" + ) directory: Path = destination / "failure-00" manifest: dict[str, Any] = json.loads((directory / "manifest.json").read_text()) before: dict[str, Any] = json.loads((directory / "cache-before.json").read_text())