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())