From 6709d52c07ea58de08fbf98640690f5292c6b2db Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 13:35:35 +0100 Subject: [PATCH 1/7] fix: stop clone spinners, compile clone environments structurally and keep library logs off the console --- .../main/console_summary_line.rs | 7 + .../src/diagnostic_routing/main/mod.rs | 2 + .../main/third_party_console_form.rs | 16 + .../src/diagnostic_routing/models.rs | 11 + .../diagnostic_routing/tests/test_routing.rs | 67 ++- .../diagnostic_routing/tests/test_types.rs | 14 +- .../sqlbuild-core/src/progress/constants.rs | 3 +- .../src/progress/tests/test_progress_text.rs | 10 + .../bindings/_helpers/clone/clone_command.rs | 9 +- .../bindings/_helpers/clone/clone_pipeline.rs | 65 ++- .../_helpers/diagnostics/log_records.rs | 57 ++- .../_helpers/planner_entries/clone_plans.rs | 23 +- src/sqlbuild/_native.pyi | 1 + .../classes/dynamic_stderr_handler.py | 16 +- .../classes/invocation_diagnostic_routing.py | 1 + .../classes/log_record_route_filter.py | 3 + .../cli/commands/main/clone/_test_types.py | 15 + .../main/clone/test_clone_preparation.py | 474 ++++++++++++++++++ .../src/sqlbuild/cli/recall/_test_types.py | 8 + .../cli/recall/test_third_party_logs.py | 79 +++ .../src/sqlbuild/diagnostics/_test_types.py | 15 + .../src/sqlbuild/diagnostics/test_main.py | 95 ++++ .../test_scoped_compute_log_capture.py | 2 +- 23 files changed, 934 insertions(+), 59 deletions(-) create mode 100644 crates/sqlbuild-core/src/diagnostic_routing/main/console_summary_line.rs create mode 100644 crates/sqlbuild-core/src/diagnostic_routing/main/third_party_console_form.rs create mode 100644 tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py create mode 100644 tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py diff --git a/crates/sqlbuild-core/src/diagnostic_routing/main/console_summary_line.rs b/crates/sqlbuild-core/src/diagnostic_routing/main/console_summary_line.rs new file mode 100644 index 0000000000..1b84d257bf --- /dev/null +++ b/crates/sqlbuild-core/src/diagnostic_routing/main/console_summary_line.rs @@ -0,0 +1,7 @@ +//! `console_summary_line`: the one line a summarized console record shows. + +/// The first line of `message`, without trailing whitespace. +#[must_use] +pub fn console_summary_line(message: &str) -> &str { + message.lines().next().unwrap_or_default().trim_end() +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs b/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs index cb6240ba1c..6d96165983 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs @@ -1,5 +1,7 @@ pub mod compute_log_admits; +pub mod console_summary_line; pub mod diagnostic_severity; pub mod internal_logger; pub mod route_admits; pub mod sql_digest; +pub mod third_party_console_form; diff --git a/crates/sqlbuild-core/src/diagnostic_routing/main/third_party_console_form.rs b/crates/sqlbuild-core/src/diagnostic_routing/main/third_party_console_form.rs new file mode 100644 index 0000000000..18a95d1e24 --- /dev/null +++ b/crates/sqlbuild-core/src/diagnostic_routing/main/third_party_console_form.rs @@ -0,0 +1,16 @@ +//! `third_party_console_form`: how a non-debug console shows a third-party record. + +use crate::diagnostic_routing::constants::{LEVEL_ERROR, LEVEL_WARNING}; +use crate::diagnostic_routing::models::ThirdPartyConsoleForm; + +/// Errors in full, warnings as one line, and nothing below warning. +#[must_use] +pub fn third_party_console_form(level: i64) -> ThirdPartyConsoleForm { + if level >= LEVEL_ERROR { + ThirdPartyConsoleForm::Full + } else if level >= LEVEL_WARNING { + ThirdPartyConsoleForm::Summary + } else { + ThirdPartyConsoleForm::Hidden + } +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/models.rs b/crates/sqlbuild-core/src/diagnostic_routing/models.rs index fcd0a626ce..15182fa3e6 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/models.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/models.rs @@ -22,3 +22,14 @@ pub struct RouteOptions { /// This destination receives SQL text, so it only accepts records that carry it. pub include_sql_text: bool, } + +/// How a console that is not in debug mode shows one third-party record. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum ThirdPartyConsoleForm { + /// The record stays off the console. + Hidden, + /// The first line of the message, without a traceback. + Summary, + /// The whole message and traceback. + Full, +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs index 59b840ef14..f2622c7304 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs @@ -1,13 +1,16 @@ //! Diagnostic routing decisions match the Python logging filter and compute log handler. use crate::diagnostic_routing::main::compute_log_admits::compute_log_admits; +use crate::diagnostic_routing::main::console_summary_line::console_summary_line; use crate::diagnostic_routing::main::diagnostic_severity::diagnostic_severity; use crate::diagnostic_routing::main::internal_logger::internal_logger; use crate::diagnostic_routing::main::route_admits::route_admits; use crate::diagnostic_routing::main::sql_digest::sql_digest; -use crate::diagnostic_routing::models::{RecordFacts, RouteOptions}; +use crate::diagnostic_routing::main::third_party_console_form::third_party_console_form; +use crate::diagnostic_routing::models::{RecordFacts, RouteOptions, ThirdPartyConsoleForm}; use crate::diagnostic_routing::tests::test_types::{ - ComputeLogTestCase, DigestTestCase, InternalLoggerTestCase, RouteTestCase, SeverityTestCase, + ComputeLogTestCase, ConsoleFormTestCase, DigestTestCase, InternalLoggerTestCase, RouteTestCase, + SeverityTestCase, SummaryLineTestCase, }; const EXTERNAL_DEBUG: RecordFacts = RecordFacts { @@ -198,3 +201,63 @@ fn given_sql_when_digesting_then_prefixed_sha256_hex() { ); } } + +#[test] +fn given_third_party_levels_when_choosing_console_form_then_only_warnings_and_errors_show() { + let test_cases = [ + ConsoleFormTestCase { + description: "INFO stays off the console", + level: 20, + expected_form: ThirdPartyConsoleForm::Hidden, + }, + ConsoleFormTestCase { + description: "WARNING shows one line", + level: 30, + expected_form: ThirdPartyConsoleForm::Summary, + }, + ConsoleFormTestCase { + description: "ERROR shows in full", + level: 40, + expected_form: ThirdPartyConsoleForm::Full, + }, + ConsoleFormTestCase { + description: "CRITICAL shows in full", + level: 50, + expected_form: ThirdPartyConsoleForm::Full, + }, + ]; + + for test_case in test_cases { + assert_eq!( + third_party_console_form(test_case.level), + test_case.expected_form, + "{}", + test_case.description + ); + } +} + +#[test] +fn given_messages_when_summarizing_then_first_line_remains() { + let test_cases = [ + SummaryLineTestCase { + description: "multi-line message keeps its first line", + message: "token refresh failed \nTraceback (most recent call last):\n boom", + expected_line: "token refresh failed", + }, + SummaryLineTestCase { + description: "empty message stays empty", + message: "", + expected_line: "", + }, + ]; + + for test_case in test_cases { + assert_eq!( + console_summary_line(test_case.message), + test_case.expected_line, + "{}", + test_case.description + ); + } +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs index 275aa0b285..efd5109ad7 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs @@ -1,4 +1,4 @@ -use crate::diagnostic_routing::models::{RecordFacts, RouteOptions}; +use crate::diagnostic_routing::models::{RecordFacts, RouteOptions, ThirdPartyConsoleForm}; pub(super) struct InternalLoggerTestCase { pub(super) description: &'static str, @@ -31,3 +31,15 @@ pub(super) struct DigestTestCase { pub(super) sql: &'static str, pub(super) expected_digest: &'static str, } + +pub(super) struct ConsoleFormTestCase { + pub(super) description: &'static str, + pub(super) level: i64, + pub(super) expected_form: ThirdPartyConsoleForm, +} + +pub(super) struct SummaryLineTestCase { + pub(super) description: &'static str, + pub(super) message: &'static str, + pub(super) expected_line: &'static str, +} diff --git a/crates/sqlbuild-core/src/progress/constants.rs b/crates/sqlbuild-core/src/progress/constants.rs index 6118676af0..8c40e39d2a 100644 --- a/crates/sqlbuild-core/src/progress/constants.rs +++ b/crates/sqlbuild-core/src/progress/constants.rs @@ -80,7 +80,7 @@ pub(crate) const KIND_WIDTH: usize = 10; pub(crate) const NESTED_PREFIX: &str = " "; pub(crate) const UNKNOWN_RESOURCE_NAME: &str = "warehouse"; /// Messages that complete a planning phase rather than update it. -pub(crate) const PLANNING_COMPLETION_PREFIXES: [&str; 14] = [ +pub(crate) const PLANNING_COMPLETION_PREFIXES: [&str; 15] = [ "Built ", "Checked ", "Compiled ", @@ -91,6 +91,7 @@ pub(crate) const PLANNING_COMPLETION_PREFIXES: [&str; 14] = [ "Inspected ", "Loaded ", "Planned ", + "Prepared ", "Recorded ", "Refreshed ", "Resolved ", diff --git a/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs b/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs index 4ef6de339e..b90e70a460 100644 --- a/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs +++ b/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs @@ -24,6 +24,16 @@ fn given_planning_message_when_classifying_then_completions_are_recognized() { message: "Applied clone plan. (0.10s)", expected_is_completion: true, }, + CompletionMessageTestCase { + description: "a prepared clone plan completes", + message: "Prepared clone plan. (0.10s)", + expected_is_completion: true, + }, + CompletionMessageTestCase { + description: "an ongoing clone preparation does not complete", + message: "Preparing clone plan...", + expected_is_completion: false, + }, CompletionMessageTestCase { description: "a finalized dbt run completes", message: "Finalized dbt run.", diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs index 06194488c5..c7286b3c63 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs @@ -242,7 +242,7 @@ fn prepare<'py>( let py: Python<'py> = request.py(); let progress: Bound<'py, PyAny> = progress_reporter(&invocation.stream, invocation.style)?; let started: Instant = Instant::now(); - let pipeline: Bound<'py, PyAny> = + let prepared: PyResult> = within(&lifecycle(py, ("project", "project_compile"))?, |_| { progress.call_method1("on_progress", ("Preparing clone plan...",))?; let resolver: Bound<'py, PyAny> = resolve_external_sql_reference_resolver( @@ -288,7 +288,12 @@ fn prepare<'py>( ),), )?; Ok(pipeline) - })?; + }); + if prepared.is_err() { + // Stop the spinner before the error is reported; the preparation error takes precedence. + let _ = progress.call_method0("finish"); + } + let pipeline: Bound<'py, PyAny> = prepared?; if destination_entry_count(&pipeline)? == 0 { return Err(user_error(py, NOTHING_TO_CLONE)); } diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs index 34e409d3c7..f89182c08b 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs @@ -1,7 +1,7 @@ //! Compile the origin and destination environments of a clone and plan it. use pyo3::prelude::{Bound, PyAny, PyAnyMethods, PyModule, PyModuleMethods, PyResult, Python}; -use pyo3::types::{PyDict, PyTuple}; +use pyo3::types::{PyBool, PyDict, PyTuple}; use pyo3::{pyfunction, wrap_pyfunction}; use crate::bindings::_helpers::boundary::keyword_request::Request; @@ -34,7 +34,37 @@ pub(crate) struct ClonePipeline<'py> { pub(crate) resolver: Bound<'py, PyAny>, } -/// The compiled project of one target environment. +/// The structural compiled project of each target environment a clone reads, compiled once each. +/// +/// Clone reads relation names, the dependency graph, configuration and rendered view and +/// function SQL, which compile produces without SQL analysis, so column inference is skipped. +struct Environments<'a, 'py> { + pipeline: &'a ClonePipeline<'py>, + compiled: Vec<(Bound<'py, PyAny>, Bound<'py, PyAny>)>, +} + +impl<'py> Environments<'_, 'py> { + /// The compiled project of `target_name`, compiling it on first use. + fn project(&mut self, target_name: &Bound<'py, PyAny>) -> PyResult> { + for (name, project) in &self.compiled { + if name.eq(target_name)? { + return Ok(project.clone()); + } + } + let project: Bound<'py, PyAny> = compiled_environment(self.pipeline, target_name)?; + self.compiled.push((target_name.clone(), project.clone())); + Ok(project) + } + + /// The project a target's sources are read from: its `defer_sources_to`, or itself. + fn source_project(&mut self, target_name: &Bound<'py, PyAny>) -> PyResult> { + let read_target: Bound<'py, PyAny> = + read_target_name(&self.pipeline.discovered, target_name)?; + self.project(&read_target) + } +} + +/// The structural compiled project of one target environment. fn compiled_environment<'py>( pipeline: &ClonePipeline<'py>, target_name: &Bound<'py, PyAny>, @@ -57,6 +87,10 @@ fn compiled_environment<'py>( "no_sql_validation", native_field(options, "no_sql_validation")?, ), + ( + "skip_column_inference", + PyBool::new(py, true).to_owned().into_any(), + ), ( "analysis_selection", new_record_with( @@ -91,32 +125,21 @@ fn read_target_name<'py>( Ok(target_name.clone()) } -/// The project its sources are read from: `project` itself unless sources defer elsewhere. -fn source_project<'py>( - pipeline: &ClonePipeline<'py>, - project: &Bound<'py, PyAny>, - target_name: &Bound<'py, PyAny>, -) -> PyResult> { - let read_target: Bound<'py, PyAny> = read_target_name(&pipeline.discovered, target_name)?; - if read_target.eq(target_name)? { - return Ok(project.clone()); - } - compiled_environment(pipeline, &read_target) -} - /// Compile both environments, plan the clone and return the `ClonePipelineResult`. pub(crate) fn prepared_clone_pipeline<'py>( pipeline: &ClonePipeline<'py>, (origin_target, destination_target): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), ) -> PyResult> { let py: Python<'py> = origin_target.py(); - let origin_project: Bound<'py, PyAny> = compiled_environment(pipeline, origin_target)?; - let destination_project: Bound<'py, PyAny> = - compiled_environment(pipeline, destination_target)?; - let origin_source_project: Bound<'py, PyAny> = - source_project(pipeline, &origin_project, origin_target)?; + let mut environments: Environments<'_, 'py> = Environments { + pipeline, + compiled: Vec::new(), + }; + let origin_project: Bound<'py, PyAny> = environments.project(origin_target)?; + let destination_project: Bound<'py, PyAny> = environments.project(destination_target)?; + let origin_source_project: Bound<'py, PyAny> = environments.source_project(origin_target)?; let destination_source_project: Bound<'py, PyAny> = - source_project(pipeline, &destination_project, destination_target)?; + environments.source_project(destination_target)?; let planned: Bound<'py, PyTuple> = run_clone_planning( py, Some(keywords( diff --git a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs index f38cf364fe..e407cbd5d2 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs @@ -14,11 +14,13 @@ use sqlbuild_core::diagnostic_routing::constants::{ SQL_TEXT_FIELD, UNFORMATTABLE_MESSAGE, }; use sqlbuild_core::diagnostic_routing::main::compute_log_admits::compute_log_admits; +use sqlbuild_core::diagnostic_routing::main::console_summary_line::console_summary_line; use sqlbuild_core::diagnostic_routing::main::diagnostic_severity::diagnostic_severity; use sqlbuild_core::diagnostic_routing::main::internal_logger::internal_logger; use sqlbuild_core::diagnostic_routing::main::route_admits::route_admits; use sqlbuild_core::diagnostic_routing::main::sql_digest::sql_digest; -use sqlbuild_core::diagnostic_routing::models::{RecordFacts, RouteOptions}; +use sqlbuild_core::diagnostic_routing::main::third_party_console_form::third_party_console_form; +use sqlbuild_core::diagnostic_routing::models::{RecordFacts, RouteOptions, ThirdPartyConsoleForm}; use sqlbuild_core::redaction::main::redact_text::redact_text; use sqlbuild_host::entries::models::ExecutorHost; @@ -154,14 +156,35 @@ fn redacted_message(record: &Bound<'_, PyAny>) -> PyResult { )) } +/// The redacted formatted traceback of a record's `exc_info`, if it has one that formats. +fn exception_text(record: &Bound<'_, PyAny>) -> PyResult> { + let py: Python<'_> = record.py(); + let exc_info: Bound<'_, PyAny> = native_field(record, "exc_info")?; + if exc_info.is_none() { + return Ok(None); + } + let formatted: PyResult = imported(py, "logging", "Formatter") + .and_then(|formatter| formatter.call0()) + .and_then(|formatter| formatter.call_method1("formatException", (exc_info,))) + .and_then(|text| text.extract::()) + .map(|text| redact_text(&text)); + swallowed(py, formatted) +} + /// A redacted copy of `record.__dict__` for one destination, or `None` when it does not belong. +/// +/// With `summarize_third_party`, records from other libraries follow the non-debug console +/// policy: errors in full, warnings as their first line without a traceback, nothing below. #[pyfunction] -#[pyo3(signature = (*, record, internal_only, allow_internal, include_sql_text))] +#[pyo3(signature = ( + *, record, internal_only, allow_internal, include_sql_text, summarize_third_party = false +))] fn route_diagnostic_log_record<'py>( record: &Bound<'py, PyAny>, internal_only: bool, allow_internal: bool, include_sql_text: bool, + summarize_third_party: bool, ) -> PyResult>> { let py: Python<'py> = record.py(); let values: Bound<'py, PyDict> = record_values(record)?; @@ -179,6 +202,14 @@ fn route_diagnostic_log_record<'py>( if !route_admits(options, facts) { return Ok(None); } + let form: ThirdPartyConsoleForm = if summarize_third_party && !facts.internal { + third_party_console_form(facts.level) + } else { + ThirdPartyConsoleForm::Full + }; + if form == ThirdPartyConsoleForm::Hidden { + return Ok(None); + } let copied: Bound<'py, PyDict> = values.copy()?; let mut message: String = swallowed(py, redacted_message(record))? .unwrap_or_else(|| UNFORMATTABLE_MESSAGE.to_owned()); @@ -186,16 +217,13 @@ fn route_diagnostic_log_record<'py>( if facts.has_sql_digest { REDACTED_SQL_LOG_MESSAGE.clone_into(&mut message); } - let exc_info: Bound<'py, PyAny> = native_field(record, "exc_info")?; - if !exc_info.is_none() { - let formatted: PyResult = imported(py, "logging", "Formatter") - .and_then(|formatter| formatter.call0()) - .and_then(|formatter| formatter.call_method1("formatException", (exc_info,))) - .and_then(|text| text.extract::()) - .map(|text| redact_text(&text)); - if let Some(exception_text) = swallowed(py, formatted)? { - message = format!("{message}\n{exception_text}"); - } + if form == ThirdPartyConsoleForm::Summary { + message = console_summary_line(&message).to_owned(); + copied.set_item("stack_info", py.None())?; + } else if let Some(exception_text) = exception_text(record)? { + message = format!("{message}\n{exception_text}"); + } + if !native_field(record, "exc_info")?.is_none() { copied.set_item("exc_info", py.None())?; copied.set_item("exc_text", py.None())?; } @@ -267,10 +295,13 @@ fn retained<'py>( let py: Python<'py> = record.py(); let contains_sql: bool = facts.has_sql_digest || facts.has_sql_text; if !contains_sql { - let message: String = redacted_message(record)?; + let mut message: String = redacted_message(record)?; let fields: Bound<'py, PyDict> = if facts.internal { fields } else { + if let Some(exception_text) = exception_text(record)? { + message = format!("{message}\n{exception_text}"); + } extra_fields(record)? }; return Ok((message, native_field(record, "name")?, fields)); diff --git a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs index 4648abb8c7..6b6442f6ea 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs @@ -169,11 +169,10 @@ fn model_entry<'py>( fn clone_model_entries<'py>( (project, plan): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), - (adapter, connection): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), - source_project: &Bound<'py, PyAny>, + adapter: &Bound<'py, PyAny>, + resolution: &CloneResolution<'py>, ) -> PyResult> { let py = project.py(); - let resolution = clone_resolution(project, source_project, (adapter, connection))?; let selected = native_field(plan, "selected_keys")?; let entries = PyDict::new(py); for model in native_field(project, "models")?.try_iter()? { @@ -297,11 +296,10 @@ fn clone_source_entries<'py>( fn clone_function_entries<'py>( (project, plan): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), - (adapter, connection): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), - source_project: &Bound<'py, PyAny>, + adapter: &Bound<'py, PyAny>, + resolution: &CloneResolution<'py>, ) -> PyResult> { let py = project.py(); - let resolution = clone_resolution(project, source_project, (adapter, connection))?; let selected = native_field(plan, "selected_keys")?; let entries = PyDict::new(py); for function in native_field(project, "functions")?.try_iter()? { @@ -479,17 +477,10 @@ pub(crate) fn run_clone_planning<'py>( let connection = args.value("connection")?; let destination_sources = args.value("destination_source_project")?; let plan = clone_plan_output(&project, &args.value("select")?, &args.value("exclude")?)?; - let models = clone_model_entries( - (&project, &plan), - (&adapter, &connection), - &destination_sources, - )?; + let resolution = clone_resolution(&project, &destination_sources, (&adapter, &connection))?; + let models = clone_model_entries((&project, &plan), &adapter, &resolution)?; let seeds = seed_entries(&project, "key", &native_field(&plan, "selected_keys")?)?; - let functions = clone_function_entries( - (&project, &plan), - (&adapter, &connection), - &destination_sources, - )?; + let functions = clone_function_entries((&project, &plan), &adapter, &resolution)?; let mut sources = PyTuple::empty(py).into_any(); if native_field(&destination_sources, "effective_target_name")? .eq(native_field(&project, "effective_target_name")?)? diff --git a/src/sqlbuild/_native.pyi b/src/sqlbuild/_native.pyi index b80648b9e4..a11a56b9ad 100644 --- a/src/sqlbuild/_native.pyi +++ b/src/sqlbuild/_native.pyi @@ -6413,6 +6413,7 @@ def route_diagnostic_log_record( internal_only: bool, allow_internal: bool, include_sql_text: bool, + summarize_third_party: bool = False, ) -> dict[str, object] | None: ... def safe_diagnostic_extra_fields(record: logging.LogRecord) -> dict[str, object]: ... def compute_diagnostic_log_fields( diff --git a/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py b/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py index 33eb63115e..ed84073eec 100644 --- a/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py +++ b/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py @@ -5,13 +5,25 @@ import logging import sys +from sqlbuild._native import shared_transient_line_coordinator + class DynamicStderrHandler(logging.StreamHandler): - """Stream handler that follows the current stderr object at emit time.""" + """Stream handler that follows the current stderr object at emit time. + + Writes go through the shared transient line coordinator, which clears a live progress line + before the record and redraws it afterwards. + """ def emit(self, record: logging.LogRecord) -> None: self.stream = sys.stderr - super().emit(record) + try: + text: str = self.format(record) + self.terminator + shared_transient_line_coordinator().write_persistent(stream=self.stream, text=text) + except RecursionError: + raise + except Exception: + self.handleError(record) def handleError(self, record: logging.LogRecord) -> None: """Isolate console failures from the command and avoid recursive fallback logging.""" diff --git a/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py b/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py index a0e24e3c17..3426436942 100644 --- a/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py +++ b/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py @@ -147,6 +147,7 @@ def _build_handlers(self) -> list[logging.Handler]: internal_only=False, allow_internal=self._options.debug_console, include_sql_text=False, + summarize_third_party=not self._options.debug_console, ) ) handlers.append(console_handler) diff --git a/src/sqlbuild/diagnostics/classes/log_record_route_filter.py b/src/sqlbuild/diagnostics/classes/log_record_route_filter.py index b25ce3030b..26e04e358e 100644 --- a/src/sqlbuild/diagnostics/classes/log_record_route_filter.py +++ b/src/sqlbuild/diagnostics/classes/log_record_route_filter.py @@ -16,11 +16,13 @@ def __init__( internal_only: bool, allow_internal: bool, include_sql_text: bool, + summarize_third_party: bool = False, ) -> None: super().__init__() self._internal_only: bool = internal_only self._allow_internal: bool = allow_internal self._include_sql_text: bool = include_sql_text + self._summarize_third_party: bool = summarize_third_party def filter(self, record: logging.LogRecord) -> logging.LogRecord | bool: """Return a safe copy when the record belongs at this destination.""" @@ -30,6 +32,7 @@ def filter(self, record: logging.LogRecord) -> logging.LogRecord | bool: internal_only=self._internal_only, allow_internal=self._allow_internal, include_sql_text=self._include_sql_text, + summarize_third_party=self._summarize_third_party, ) if values is None: return False diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py index c83005ba84..2ba7c750bd 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py @@ -42,3 +42,18 @@ class CloneDeferredSourceFunctionE2ETestCase: description: str expected_stdout_fragments: tuple[str, ...] expected_query_results: tuple[tuple[str, tuple[tuple[object, ...], ...]], ...] + + +@dataclass(frozen=True) +class ClonePreparationE2ETestCase: + description: str + clone_arguments: tuple[str, ...] + expected_assets: tuple[tuple[str, str, str, str | None, str], ...] + expected_query_results: tuple[tuple[str, tuple[tuple[object, ...], ...]], ...] + + +@dataclass(frozen=True) +class CloneTerminalProgressE2ETestCase: + description: str + columns: int + expected_screen_fragments: tuple[str, ...] diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py new file mode 100644 index 0000000000..6f798b1461 --- /dev/null +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py @@ -0,0 +1,474 @@ +"""E2E coverage for which resources sqb clone prepares, where they go, and its terminal output.""" + +from __future__ import annotations + +import json +import shutil +import subprocess +from pathlib import Path +from textwrap import dedent + +import pytest + +from tests.e2e.src.sqlbuild.cli.commands.main.clone._test_types import ( + ClonePreparationE2ETestCase, + CloneTerminalProgressE2ETestCase, +) +from tests.e2e.src.sqlbuild.cli.commands.shared.helpers import ( + SPINNER_GLYPHS, + assert_fragments_in_order, + prepare_inline_project, + query_duckdb, + render_terminal_screen, + run_sqb, + run_sqb_with_pty, +) + +_PROJECT_FILES: dict[str, str] = { + "sqlbuild_project.toml": dedent( + """ + name = "clone_preparation_project" + adapter = "duckdb" + default_target = "dev" + + [connections.local] + database = "clone.duckdb" + + [targets.prod] + schema = "prod" + loader_schema = "raw_prod" + + [targets.prod.vars] + region = "emea" + + [targets.prod.clone] + allow_as_clone_origin = true + + [targets.dev] + schema = "dev" + loader_schema = "raw_dev" + + [targets.dev.vars] + region = "apac" + + [targets.dev.clone] + allow_as_clone_destination = true + + [targets.review] + schema = "review" + loader_schema = "raw_review" + defer_sources_to = "prod" + + [targets.review.vars] + region = "amer" + + [targets.review.clone] + allow_as_clone_destination = true + """ + ).lstrip(), + "python/loaders/raw.py": dedent( + """ + from sqlbuild.loaders import loader + + + @loader + def raw_payments(ctx): + '''Test loader raw_payments.''' + return [{"payment_id": 1, "order_id": 1, "amount_cents": 500}] + """ + ).lstrip(), + "sources/raw.yml": dedent( + """ + sources: + - name: raw_payments + description: Test source raw_payments. + managed: true + write_strategy: table + columns: + - name: payment_id + type: INTEGER + - name: order_id + type: INTEGER + - name: amount_cents + type: INTEGER + - name: raw_orders + description: Test source raw_orders. + expression: | + SELECT * + FROM (VALUES (1, 101, 100), (2, 102, 200)) + AS raw_orders(order_id, customer_id, amount_cents) + """ + ).lstrip(), + "seeds/customers.csv": "customer_id,customer_name\n101,Ada\n102,Grace\n", + "seeds/schema.yml": dedent( + """ + seeds: + - name: customers + description: Test seed customers. + columns: + - name: customer_id + type: INTEGER + - name: customer_name + type: VARCHAR + """ + ).lstrip(), + "models/staging/stg_orders.sql": dedent( + """ + MODEL (description "Test model stg_orders.", materialized view); + + SELECT order_id, customer_id, amount_cents, '@@region' AS region FROM __source("raw_orders") + """ + ).lstrip(), + "models/staging/stg_payments.sql": dedent( + """ + MODEL (description "Test model stg_payments.", materialized view); + + SELECT * FROM __source("raw_payments") + """ + ).lstrip(), + "models/marts/fct_orders.sql": dedent( + """ + MODEL (description "Test model fct_orders.", materialized table); + + SELECT o.order_id, o.amount_cents, c.customer_name + FROM __ref("stg_orders") AS o + JOIN __seed("customers") AS c ON c.customer_id = o.customer_id + """ + ).lstrip(), + "models/marts/fct_order_events.sql": dedent( + """ + MODEL ( + description "Test model fct_order_events.", + materialized incremental, + incremental_strategy append + ); + + SELECT order_id, amount_cents FROM __ref("fct_orders") + """ + ).lstrip(), + "models/marts/orders_summary.sql": dedent( + """ + MODEL (description "Test model orders_summary.", materialized view); + + SELECT f.*, p.amount_cents AS paid_cents + FROM __ref("fct_orders") AS f + LEFT JOIN __ref("stg_payments") AS p ON p.order_id = f.order_id + """ + ).lstrip(), + "models/marts/orders_backlog.sql": dedent( + """ + MODEL (description "Test model orders_backlog.", materialized table); + + SELECT order_id FROM __ref("fct_orders") WHERE amount_cents > 150 + """ + ).lstrip(), + "models/marts/retired_orders.sql": dedent( + """ + MODEL (description "Test model retired_orders.", materialized table, enabled false); + + SELECT order_id FROM __ref("fct_orders") + """ + ).lstrip(), + "functions/sql/cents_to_units.sql": dedent( + """ + FUNCTION (description "Test function cents_to_units.", arguments (amount INTEGER), returns DOUBLE); + + amount / 100.0 + """ + ).lstrip(), +} + +_VIEW_ROWS: str = ( + "SELECT schema_name, view_name, sql FROM duckdb_views() " + "WHERE NOT internal AND schema_name = '{schema}' ORDER BY view_name" +) +_DEV_VIEWS: tuple[tuple[object, ...], ...] = ( + ( + "dev", + "orders_summary", + "CREATE VIEW dev.orders_summary AS SELECT f.*, p.amount_cents AS paid_cents " + "FROM dev.fct_orders AS f LEFT JOIN dev.stg_payments AS p " + "ON ((p.order_id = f.order_id));", + ), + ( + "dev", + "stg_orders", + "CREATE VIEW dev.stg_orders AS SELECT order_id, customer_id, amount_cents, " + "'apac' AS region FROM (SELECT * FROM (SELECT * FROM (VALUES (1, 101, 100), " + "(2, 102, 200)) AS valueslist) AS raw_orders(order_id, customer_id, amount_cents));", + ), + ("dev", "stg_payments", "CREATE VIEW dev.stg_payments AS SELECT * FROM raw_dev.raw_payments;"), +) + + +def _asset( + kind: str, name: str, action: str, origin: str | None, target: str +) -> tuple[str, str, str, str | None, str]: + return (kind, name, action, origin, target) + + +_ALL_DEV_ASSETS: tuple[tuple[str, str, str, str | None, str], ...] = ( + _asset("seed", "customers", "copied", "prod.customers", "dev.customers"), + _asset("model", "stg_orders", "recreated_view", "prod.stg_orders", "dev.stg_orders"), + _asset("model", "fct_orders", "copied", "prod.fct_orders", "dev.fct_orders"), + _asset("model", "fct_order_events", "copied", "prod.fct_order_events", "dev.fct_order_events"), + _asset( + "model", + "orders_backlog", + "warning_missing_source", + "prod.orders_backlog", + "dev.orders_backlog", + ), + _asset("source", "raw_payments", "copied", "raw_prod.raw_payments", "raw_dev.raw_payments"), + _asset("model", "stg_payments", "recreated_view", "prod.stg_payments", "dev.stg_payments"), + _asset( + "model", "orders_summary", "recreated_view", "prod.orders_summary", "dev.orders_summary" + ), + _asset("udf", "cents_to_units", "recreated_function", None, "dev.cents_to_units"), +) + + +def _prepare_origin(tmp_path: Path) -> Path: + project_dir: Path = prepare_inline_project( + tmp_path=tmp_path, project_name="clone_preparation_project", repo_files=_PROJECT_FILES + ) + for command in ( + ("--no-color", "load", "--target", "prod"), + ("--no-color", "build", "--target", "prod", "--exclude", "orders_backlog"), + ): + result: subprocess.CompletedProcess[str] = run_sqb(command=command, project_dir=project_dir) + assert result.returncode == 0, result.stdout + result.stderr + return project_dir + + +@pytest.fixture(scope="module") +def origin_project(tmp_path_factory: pytest.TempPathFactory) -> Path: + """A project whose prod target is built, except `orders_backlog`, shared read-only.""" + + return _prepare_origin(tmp_path_factory.mktemp("clone_preparation_origin")) + + +def _project_copy(*, origin_project: Path, tmp_path: Path) -> Path: + project_dir: Path = tmp_path / origin_project.name + shutil.copytree(origin_project, project_dir) + return project_dir + + +@pytest.mark.parametrize( + "test_case", + ( + ClonePreparationE2ETestCase( + description="whole project clones in graph order and reports the missing origin", + clone_arguments=("--from", "prod", "--to", "dev"), + expected_assets=_ALL_DEV_ASSETS, + expected_query_results=( + (_VIEW_ROWS.format(schema="dev"), _DEV_VIEWS), + ("SELECT DISTINCT region FROM dev.stg_orders", (("apac",),)), + ( + "SELECT order_id, paid_cents FROM dev.orders_summary ORDER BY order_id", + ((1, 500), (2, None)), + ), + ), + ), + ClonePreparationE2ETestCase( + description="graph selector clones the selected view and its ancestors", + clone_arguments=("--from", "prod", "--to", "dev", "--select", "+orders_summary"), + expected_assets=( + _ALL_DEV_ASSETS[0], + _ALL_DEV_ASSETS[1], + _ALL_DEV_ASSETS[2], + _ALL_DEV_ASSETS[5], + _ALL_DEV_ASSETS[6], + _ALL_DEV_ASSETS[7], + ), + expected_query_results=((_VIEW_ROWS.format(schema="dev"), _DEV_VIEWS),), + ), + ClonePreparationE2ETestCase( + description="excluded view and seed are left out", + clone_arguments=( + "--from", + "prod", + "--to", + "dev", + "--exclude", + "orders_summary", + "customers", + ), + expected_assets=( + _ALL_DEV_ASSETS[1], + _ALL_DEV_ASSETS[2], + _ALL_DEV_ASSETS[3], + _ALL_DEV_ASSETS[4], + _ALL_DEV_ASSETS[5], + _ALL_DEV_ASSETS[6], + _ALL_DEV_ASSETS[8], + ), + expected_query_results=( + (_VIEW_ROWS.format(schema="dev"), (_DEV_VIEWS[1], _DEV_VIEWS[2])), + ), + ), + ClonePreparationE2ETestCase( + description="destination deferring sources reads origin sources and skips them", + clone_arguments=("--from", "prod", "--to", "review"), + expected_assets=( + _asset("seed", "customers", "copied", "prod.customers", "review.customers"), + _asset( + "model", "stg_orders", "recreated_view", "prod.stg_orders", "review.stg_orders" + ), + _asset("model", "fct_orders", "copied", "prod.fct_orders", "review.fct_orders"), + _asset( + "model", + "fct_order_events", + "copied", + "prod.fct_order_events", + "review.fct_order_events", + ), + _asset( + "model", + "orders_backlog", + "warning_missing_source", + "prod.orders_backlog", + "review.orders_backlog", + ), + _asset( + "model", + "stg_payments", + "recreated_view", + "prod.stg_payments", + "review.stg_payments", + ), + _asset( + "model", + "orders_summary", + "recreated_view", + "prod.orders_summary", + "review.orders_summary", + ), + _asset( + "udf", "cents_to_units", "recreated_function", None, "review.cents_to_units" + ), + ), + expected_query_results=( + ( + "SELECT sql FROM duckdb_views() " + "WHERE schema_name = 'review' AND view_name = 'stg_payments'", + ( + ( + "CREATE VIEW review.stg_payments AS SELECT * FROM " + "(SELECT CAST(payment_id AS INTEGER) AS payment_id, " + "CAST(order_id AS INTEGER) AS order_id, " + "CAST(amount_cents AS INTEGER) AS amount_cents " + "FROM raw_prod.raw_payments);", + ), + ), + ), + ("SELECT DISTINCT region FROM review.stg_orders", (("amer",),)), + ), + ), + ClonePreparationE2ETestCase( + description="selected model missing in the origin warns beside a copied one", + clone_arguments=( + "--from", + "prod", + "--to", + "dev", + "--select", + "orders_backlog", + "fct_orders", + ), + expected_assets=(_ALL_DEV_ASSETS[2], _ALL_DEV_ASSETS[4]), + expected_query_results=(("SELECT count(*) FROM dev.fct_orders", ((2,),)),), + ), + ), + ids=lambda case: case.description, +) +def test_given_origin_environment_when_cloning_then_items_and_relations_match_selection( + test_case: ClonePreparationE2ETestCase, origin_project: Path, tmp_path: Path +) -> None: + project_dir: Path = _project_copy(origin_project=origin_project, tmp_path=tmp_path) + json_path: Path = tmp_path / "clone.json" + + result: subprocess.CompletedProcess[str] = run_sqb( + command=( + "--no-color", + "clone", + *test_case.clone_arguments, + "--json-output", + str(json_path), + ), + project_dir=project_dir, + ) + + assert result.returncode == 0, result.stdout + result.stderr + assets: list[dict[str, object]] = json.loads(json_path.read_text(encoding="utf-8"))["assets"] + assert ( + tuple( + ( + asset["kind"], + asset["name"], + asset["action"], + asset.get("origin_relation"), + asset["target"], + ) + for asset in assets + ) + == test_case.expected_assets + ) + query: str + expected_rows: tuple[tuple[object, ...], ...] + for query, expected_rows in test_case.expected_query_results: + rows = query_duckdb(db_path=project_dir / "clone.duckdb", sql=query) + assert tuple(tuple(row) for row in rows) == expected_rows + + +@pytest.mark.parametrize( + "test_case", + ( + CloneTerminalProgressE2ETestCase( + description="finished preparation leaves no spinner over the clone output", + columns=120, + expected_screen_fragments=( + "✓ Warehouse connected duckdb", + "Prepared clone plan.", + "sqb clone origin=prod destination=dev (2 resources)", + "fct_orders", + "orders_backlog", + "Completed with warnings", + ), + ), + ), + ids=lambda case: case.description, +) +def test_given_terminal_when_cloning_then_preparation_spinner_stops_before_items( + test_case: CloneTerminalProgressE2ETestCase, origin_project: Path, tmp_path: Path +) -> None: + project_dir: Path = _project_copy(origin_project=origin_project, tmp_path=tmp_path) + + result: subprocess.CompletedProcess[str] = run_sqb_with_pty( + command=( + "clone", + "--from", + "prod", + "--to", + "dev", + "--select", + "fct_orders", + "orders_backlog", + ), + project_dir=project_dir, + columns=test_case.columns, + ) + + screen: tuple[str, ...] = render_terminal_screen( + output=result.stdout, columns=test_case.columns + ) + rendered: str = "\n".join(screen) + assert result.returncode == 0, rendered + assert not any(glyph in rendered for glyph in SPINNER_GLYPHS), rendered + assert_fragments_in_order(rendered, test_case.expected_screen_fragments) + after_preparation: str = result.stdout.split("Prepared clone plan.", maxsplit=1)[1] + assert not any(glyph in after_preparation for glyph in SPINNER_GLYPHS), after_preparation + + +if __name__ == "__main__": + pytest.main([__file__, "-vv"]) diff --git a/tests/integration/src/sqlbuild/cli/recall/_test_types.py b/tests/integration/src/sqlbuild/cli/recall/_test_types.py index ac54d72345..f02f6c2e88 100644 --- a/tests/integration/src/sqlbuild/cli/recall/_test_types.py +++ b/tests/integration/src/sqlbuild/cli/recall/_test_types.py @@ -191,3 +191,11 @@ class SlowReplacementTestCase: shutdown_seconds: float sink_sleep_seconds: str expected_max_seconds: float + + +@dataclass(frozen=True) +class ThirdPartyLogTestCase: + description: str + debug: bool + expected_present: tuple[str, ...] + expected_absent: tuple[str, ...] diff --git a/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py new file mode 100644 index 0000000000..a22ad6d5c5 --- /dev/null +++ b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py @@ -0,0 +1,79 @@ +"""Third-party library logs during a command: what the console shows and what Recall keeps.""" + +import subprocess +from pathlib import Path + +import pytest + +from tests.integration.src.sqlbuild.cli.recall._test_types import ThirdPartyLogTestCase +from tests.integration.src.sqlbuild.cli.recall.helpers import recall_rows, run, write_project + +VENDOR_TASK: str = ( + '"""A task whose client library logs while it runs."""\n\n' + "import logging\n\n" + "from sqlbuild.tasks import task\n\n\n" + "@task()\n" + "def sync_orders(ctx):\n" + ' """Log like a client library: progress, then a recovered failure."""\n\n' + ' logger = logging.getLogger("vendor.client")\n' + ' logger.info("connecting to the orders service")\n' + " try:\n" + ' raise RuntimeError("token expired")\n' + " except RuntimeError:\n" + ' logger.warning("token refresh failed", exc_info=True)\n' + " return ctx.result()\n" +) +TRACEBACK: str = "Traceback (most recent call last):" + + +@pytest.mark.parametrize( + "test_case", + ( + ThirdPartyLogTestCase( + description="normal output hides INFO and shows the warning as one line", + debug=False, + expected_present=("[warning] vendor.client token refresh failed",), + expected_absent=("connecting to the orders service", TRACEBACK, "token expired"), + ), + ThirdPartyLogTestCase( + description="debug output shows every record with its traceback", + debug=True, + expected_present=( + "[info] vendor.client connecting to the orders service", + "[warning] vendor.client token refresh failed", + TRACEBACK, + "RuntimeError: token expired", + ), + expected_absent=(), + ), + ), + ids=lambda case: case.description, +) +def test_given_library_logs_during_build_when_running_then_console_is_quiet_and_recall_keeps_all( + test_case: ThirdPartyLogTestCase, tmp_path: Path +) -> None: + project_dir: Path = write_project(tmp_path / "orders_shop") + (project_dir / "python" / "tasks" / "emit.py").write_text(VENDOR_TASK, encoding="utf-8") + + built: subprocess.CompletedProcess[bytes] = run( + project_dir, *(("--debug",) if test_case.debug else ()), "build" + ) + + stderr: str = built.stderr.decode(errors="replace") + assert built.returncode == 0, stderr + assert stderr.count("[warning] vendor.client token refresh failed") == 1, stderr + fragment: str + for fragment in test_case.expected_present: + assert fragment in stderr, stderr + for fragment in test_case.expected_absent: + assert fragment not in stderr, stderr + rows: list[list[object]] = recall_rows( + project_dir, + "SELECT severity, message FROM diagnostics " + "WHERE logger = 'vendor.client' ORDER BY occurred_at", + ) + assert [row[0] for row in rows] == ["info", "warning"] + assert rows[0][1] == "connecting to the orders service" + warning: str = str(rows[1][1]) + assert warning.startswith("token refresh failed\n" + TRACEBACK), warning + assert "RuntimeError: token expired" in warning diff --git a/tests/unit/src/sqlbuild/diagnostics/_test_types.py b/tests/unit/src/sqlbuild/diagnostics/_test_types.py index eb51dbd1fe..a309111312 100644 --- a/tests/unit/src/sqlbuild/diagnostics/_test_types.py +++ b/tests/unit/src/sqlbuild/diagnostics/_test_types.py @@ -37,3 +37,18 @@ class ConsoleDurationTestCase: subject: object duration_ms: object expected_line: str + + +@dataclass(frozen=True) +class ThirdPartyConsoleTestCase: + description: str + debug: bool + expected_console_lines: tuple[str, ...] + expected_traceback_count: int + + +@dataclass(frozen=True) +class ConsoleProgressLineTestCase: + description: str + message: str + expected_log_line: str diff --git a/tests/unit/src/sqlbuild/diagnostics/test_main.py b/tests/unit/src/sqlbuild/diagnostics/test_main.py index 7460df04bb..4dfd705bf8 100644 --- a/tests/unit/src/sqlbuild/diagnostics/test_main.py +++ b/tests/unit/src/sqlbuild/diagnostics/test_main.py @@ -3,19 +3,36 @@ from __future__ import annotations import logging +import sys from pathlib import Path import pytest +from sqlbuild._native import TransientStatusReporter from sqlbuild.adapters.duckdb.classes.duckdb_adapter import DuckDbAdapter from sqlbuild.diagnostics.main.configure import configure_diagnostics from sqlbuild.diagnostics.main.diagnostics_context import diagnostics_context from sqlbuild.diagnostics.main.log_sql import log_sql from tests.unit.src.sqlbuild.diagnostics._test_types import ( + ConsoleProgressLineTestCase, DiagnosticsContextualSqlTestCase, DiagnosticsLogTestCase, + ThirdPartyConsoleTestCase, ) from tests.unit.src.sqlbuild.diagnostics.helpers import HostRecordingLogHandler +from tests.unit.src.sqlbuild.presentation.classes.helpers import RecordingStream + +_CLEAR_LINE: str = "\r\x1b[K" + + +def _log_vendor_records() -> None: + logger: logging.Logger = logging.getLogger("vendor.client") + logger.info("connecting to the orders service") + try: + raise RuntimeError("token expired") + except RuntimeError: + logger.warning("token refresh failed\nretrying with fallback", exc_info=True) + logger.error("orders service rejected the request", exc_info=True) @pytest.mark.parametrize( @@ -51,6 +68,84 @@ def test_given_diagnostics_without_debug_when_logging_then_internal_records_are_ assert absent_fragment not in console_error +@pytest.mark.parametrize( + "test_case", + ( + ThirdPartyConsoleTestCase( + description="normal console hides INFO and shows WARNING as one line", + debug=False, + expected_console_lines=( + "[warning] vendor.client token refresh failed", + "[error] vendor.client orders service rejected the request", + ), + expected_traceback_count=1, + ), + ThirdPartyConsoleTestCase( + description="debug console shows every record with tracebacks", + debug=True, + expected_console_lines=( + "[info] vendor.client connecting to the orders service", + "[warning] vendor.client token refresh failed", + "retrying with fallback", + "[error] vendor.client orders service rejected the request", + ), + expected_traceback_count=2, + ), + ), + ids=lambda case: case.description, +) +def test_given_third_party_records_when_logging_then_console_follows_debug_policy( + test_case: ThirdPartyConsoleTestCase, + capsys: pytest.CaptureFixture[str], +) -> None: + with configure_diagnostics(debug=test_case.debug): + _log_vendor_records() + + console_error: str = capsys.readouterr().err + lines: tuple[str, ...] = tuple( + line for line in console_error.splitlines() if line.startswith(("[", "retrying")) + ) + + assert lines == test_case.expected_console_lines + assert console_error.count("Traceback (most recent call last):") == ( + test_case.expected_traceback_count + ) + + +@pytest.mark.parametrize( + "test_case", + ( + ConsoleProgressLineTestCase( + description="warning clears the live status line and redraws it afterwards", + message="Preparing clone plan...", + expected_log_line="[warning] vendor.client token refresh failed\n", + ), + ), + ids=lambda case: case.description, +) +def test_given_live_status_line_when_logging_then_line_is_cleared_before_record( + test_case: ConsoleProgressLineTestCase, + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.delenv("SQLBUILD_NO_PROGRESS", raising=False) + events: list[str] = [] + stream: RecordingStream = RecordingStream(events=events, tty=True) + monkeypatch.setattr(sys, "stderr", stream) + reporter: TransientStatusReporter = TransientStatusReporter(stream=stream, use_color=False) + reporter.start(test_case.message) + try: + with configure_diagnostics(debug=False): + logging.getLogger("vendor.client").warning("token refresh failed") + finally: + reporter.close() + + log_index: int = events.index(f"write:{test_case.expected_log_line}") + assert any( + event.startswith(f"write:{_CLEAR_LINE}") for event in events[log_index - 2 : log_index] + ), events + assert any(test_case.message in event for event in events[log_index + 1 :]), events + + @pytest.mark.parametrize( "test_case", [ diff --git a/tests/unit/src/sqlbuild/runtime/compute_logs/classes/test_scoped_compute_log_capture.py b/tests/unit/src/sqlbuild/runtime/compute_logs/classes/test_scoped_compute_log_capture.py index 38fc3c29a7..1ccbc4f839 100644 --- a/tests/unit/src/sqlbuild/runtime/compute_logs/classes/test_scoped_compute_log_capture.py +++ b/tests/unit/src/sqlbuild/runtime/compute_logs/classes/test_scoped_compute_log_capture.py @@ -438,7 +438,7 @@ def emit_records() -> int: prior_user_level: int = user_logger.level user_logger.setLevel(logging.NOTSET) user_logger.debug("user debug access_key=debug-access-key") - user_logger.info( + user_logger.warning( "connected dsn=postgres://user:password@host Authorization: Bearer bearer-value " "authorization=Basic basic-value API-Key=hyphen-api-key " "access_key=visible-access-key private_key='private key with spaces' " From 03f9c98981d13d869181b3659bbf97b880374d8d Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 14:26:25 +0100 Subject: [PATCH 2/7] perf: skip SQL validation and scope source inspection in clone preparation --- .../bindings/_helpers/clone/clone_pipeline.rs | 14 ++-- .../_helpers/planner_entries/clone_plans.rs | 66 +++++++++++++++++-- 2 files changed, 67 insertions(+), 13 deletions(-) diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs index f89182c08b..518e064dd5 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs @@ -37,7 +37,8 @@ pub(crate) struct ClonePipeline<'py> { /// The structural compiled project of each target environment a clone reads, compiled once each. /// /// Clone reads relation names, the dependency graph, configuration and rendered view and -/// function SQL, which compile produces without SQL analysis, so column inference is skipped. +/// function SQL. Compile produces them without SQL validation or column inference, and clone +/// reports no compile diagnostics, so both are skipped. struct Environments<'a, 'py> { pipeline: &'a ClonePipeline<'py>, compiled: Vec<(Bound<'py, PyAny>, Bound<'py, PyAny>)>, @@ -71,6 +72,7 @@ fn compiled_environment<'py>( ) -> PyResult> { let py: Python<'py> = target_name.py(); let options: &Bound<'py, PyAny> = &pipeline.options; + let structural: Bound<'py, PyAny> = PyBool::new(py, true).to_owned().into_any(); build_compiled_project( py, Some(keywords( @@ -83,14 +85,8 @@ fn compiled_environment<'py>( "resolved_connection", native_field(&pipeline.connection, "config")?, ), - ( - "no_sql_validation", - native_field(options, "no_sql_validation")?, - ), - ( - "skip_column_inference", - PyBool::new(py, true).to_owned().into_any(), - ), + ("no_sql_validation", structural.clone()), + ("skip_column_inference", structural), ( "analysis_selection", new_record_with( diff --git a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs index 6b6442f6ea..487f78565a 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs @@ -23,7 +23,7 @@ use crate::bindings::_helpers::planner_resolution::orchestration::{Resolution, r use crate::bindings::_helpers::planner_selection::selectors::resolve_graph_selection; use crate::bindings::_helpers::planner_strategy::strategy::materialization_of; use crate::bindings::_helpers::planner_warehouse::source_columns::gather_source_columns; -use crate::bindings::_helpers::records::construct::new_record; +use crate::bindings::_helpers::records::construct::{enum_member, new_record}; use crate::bindings::_helpers::records::fields::field as native_field; use crate::bindings::_helpers::records::ids::RecordId; use pyo3::PyRef; @@ -99,8 +99,57 @@ struct CloneResolution<'py> { source_warehouse_columns: Bound<'py, PyAny>, } +/// Whether a selected, enabled model is recreated from its SQL rather than copied. +fn recreated_view(model: &Bound<'_, PyAny>, selected: &Bound<'_, PyAny>) -> PyResult { + Ok(selected.contains(model_reads::model_key(model)?)? + && !disabled_model(model)? + && materialization_of(model)?.eq(VIEW_MATERIALIZATION)?) +} + +/// The entries of the sources that recreated views and functions read directly. +/// +/// Only their SQL is resolved against warehouse columns, so other sources need no inspection. +fn resolved_source_entries<'py>( + (project, plan): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), + source_project: &Bound<'py, PyAny>, +) -> PyResult> { + let py = project.py(); + let selected = native_field(plan, "selected_keys")?; + let source_type = enum_member(py, RecordId::CompiledResourceType, "SOURCE")?; + let read = PySet::empty(py)?; + let mut readers: Vec> = Vec::new(); + for model in native_field(project, "models")?.try_iter()? { + let model = model?; + if recreated_view(&model, &selected)? { + readers.push(model); + } + } + for function in native_field(project, "functions")?.try_iter()? { + let function = function?; + if selected.contains(native_field(&function, "key")?)? { + readers.push(function); + } + } + for reader in readers { + for dep in native_field(&reader, "deps")?.try_iter()? { + let dep = dep?; + if native_field(&dep, "resource_type")?.eq(&source_type)? { + read.add(native_field(&dep, "name")?)?; + } + } + } + let mut entries: Vec> = Vec::new(); + for source in native_field(source_project, "sources")?.try_iter()? { + let source = source?; + if read.contains(native_field(&source, "name")?)? { + entries.push(native_field(&source, "source_entry")?); + } + } + tuple_of(py, entries) +} + fn clone_resolution<'py>( - project: &Bound<'py, PyAny>, + (project, plan): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), source_project: &Bound<'py, PyAny>, (adapter, connection): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), ) -> PyResult> { @@ -124,7 +173,12 @@ fn clone_resolution<'py>( } let source_warehouse_columns = object( py, - gather_source_columns(source_project, adapter, connection, None)?, + gather_source_columns( + source_project, + adapter, + connection, + Some(resolved_source_entries((project, plan), source_project)?), + )?, )?; Ok(CloneResolution { model_locations, @@ -477,7 +531,11 @@ pub(crate) fn run_clone_planning<'py>( let connection = args.value("connection")?; let destination_sources = args.value("destination_source_project")?; let plan = clone_plan_output(&project, &args.value("select")?, &args.value("exclude")?)?; - let resolution = clone_resolution(&project, &destination_sources, (&adapter, &connection))?; + let resolution = clone_resolution( + (&project, &plan), + &destination_sources, + (&adapter, &connection), + )?; let models = clone_model_entries((&project, &plan), &adapter, &resolution)?; let seeds = seed_entries(&project, "key", &native_field(&plan, "selected_keys")?)?; let functions = clone_function_entries((&project, &plan), &adapter, &resolution)?; From 0efeee9e46fc3fe9ff6d8331104d4cb3f295e4c1 Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 14:41:25 +0100 Subject: [PATCH 3/7] refactor: satisfy layout rules for clone preparation and console routing --- .../bindings/_helpers/clone/clone_command.rs | 9 +- .../bindings/_helpers/clone/clone_pipeline.rs | 68 +++-- .../_helpers/diagnostics/log_records.rs | 32 ++- .../_helpers/planner_entries/clone_plans.rs | 4 +- .../classes/dynamic_stderr_handler.py | 6 +- .../cli/commands/main/clone/conftest.py | 16 ++ .../cli/commands/main/clone/helpers.py | 191 ++++++++++++++ .../main/clone/test_clone_preparation.py | 238 ++---------------- .../src/sqlbuild/cli/recall/_test_types.py | 2 +- .../cli/recall/test_third_party_logs.py | 8 +- .../src/sqlbuild/diagnostics/_test_types.py | 1 + .../unit/src/sqlbuild/diagnostics/helpers.py | 12 + .../src/sqlbuild/diagnostics/test_main.py | 22 +- 13 files changed, 304 insertions(+), 305 deletions(-) create mode 100644 tests/e2e/src/sqlbuild/cli/commands/main/clone/conftest.py create mode 100644 tests/e2e/src/sqlbuild/cli/commands/main/clone/helpers.py diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs index c7286b3c63..06194488c5 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs @@ -242,7 +242,7 @@ fn prepare<'py>( let py: Python<'py> = request.py(); let progress: Bound<'py, PyAny> = progress_reporter(&invocation.stream, invocation.style)?; let started: Instant = Instant::now(); - let prepared: PyResult> = + let pipeline: Bound<'py, PyAny> = within(&lifecycle(py, ("project", "project_compile"))?, |_| { progress.call_method1("on_progress", ("Preparing clone plan...",))?; let resolver: Bound<'py, PyAny> = resolve_external_sql_reference_resolver( @@ -288,12 +288,7 @@ fn prepare<'py>( ),), )?; Ok(pipeline) - }); - if prepared.is_err() { - // Stop the spinner before the error is reported; the preparation error takes precedence. - let _ = progress.call_method0("finish"); - } - let pipeline: Bound<'py, PyAny> = prepared?; + })?; if destination_entry_count(&pipeline)? == 0 { return Err(user_error(py, NOTHING_TO_CLONE)); } diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs index 518e064dd5..354a5593f5 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs @@ -34,38 +34,25 @@ pub(crate) struct ClonePipeline<'py> { pub(crate) resolver: Bound<'py, PyAny>, } -/// The structural compiled project of each target environment a clone reads, compiled once each. -/// -/// Clone reads relation names, the dependency graph, configuration and rendered view and -/// function SQL. Compile produces them without SQL validation or column inference, and clone -/// reports no compile diagnostics, so both are skipped. -struct Environments<'a, 'py> { - pipeline: &'a ClonePipeline<'py>, - compiled: Vec<(Bound<'py, PyAny>, Bound<'py, PyAny>)>, -} +/// Compiled environments by target name, so each target a clone reads compiles once. +type Environments<'py> = Vec<(Bound<'py, PyAny>, Bound<'py, PyAny>)>; -impl<'py> Environments<'_, 'py> { - /// The compiled project of `target_name`, compiling it on first use. - fn project(&mut self, target_name: &Bound<'py, PyAny>) -> PyResult> { - for (name, project) in &self.compiled { - if name.eq(target_name)? { - return Ok(project.clone()); - } +/// The compiled project of `target_name` among `compiled`. +fn environment<'py>( + compiled: &Environments<'py>, + target_name: &Bound<'py, PyAny>, +) -> PyResult> { + for (name, project) in compiled { + if name.eq(target_name)? { + return Ok(project.clone()); } - let project: Bound<'py, PyAny> = compiled_environment(self.pipeline, target_name)?; - self.compiled.push((target_name.clone(), project.clone())); - Ok(project) - } - - /// The project a target's sources are read from: its `defer_sources_to`, or itself. - fn source_project(&mut self, target_name: &Bound<'py, PyAny>) -> PyResult> { - let read_target: Bound<'py, PyAny> = - read_target_name(&self.pipeline.discovered, target_name)?; - self.project(&read_target) } + Err(pyo3::exceptions::PyKeyError::new_err( + target_name.clone().unbind(), + )) } -/// The structural compiled project of one target environment. +/// One target's compiled project without SQL validation or column inference, which clone never reads. fn compiled_environment<'py>( pipeline: &ClonePipeline<'py>, target_name: &Bound<'py, PyAny>, @@ -127,15 +114,24 @@ pub(crate) fn prepared_clone_pipeline<'py>( (origin_target, destination_target): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), ) -> PyResult> { let py: Python<'py> = origin_target.py(); - let mut environments: Environments<'_, 'py> = Environments { - pipeline, - compiled: Vec::new(), - }; - let origin_project: Bound<'py, PyAny> = environments.project(origin_target)?; - let destination_project: Bound<'py, PyAny> = environments.project(destination_target)?; - let origin_source_project: Bound<'py, PyAny> = environments.source_project(origin_target)?; - let destination_source_project: Bound<'py, PyAny> = - environments.source_project(destination_target)?; + let origin_reads: Bound<'py, PyAny> = read_target_name(&pipeline.discovered, origin_target)?; + let destination_reads: Bound<'py, PyAny> = + read_target_name(&pipeline.discovered, destination_target)?; + let mut compiled: Environments<'py> = Vec::new(); + for target in [ + origin_target, + destination_target, + &origin_reads, + &destination_reads, + ] { + if environment(&compiled, target).is_err() { + compiled.push((target.clone(), compiled_environment(pipeline, target)?)); + } + } + let origin_project: Bound<'py, PyAny> = environment(&compiled, origin_target)?; + let destination_project: Bound<'py, PyAny> = environment(&compiled, destination_target)?; + let origin_source_project: Bound<'py, PyAny> = environment(&compiled, &origin_reads)?; + let destination_source_project: Bound<'py, PyAny> = environment(&compiled, &destination_reads)?; let planned: Bound<'py, PyTuple> = run_clone_planning( py, Some(keywords( diff --git a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs index e407cbd5d2..8a8044653c 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs @@ -172,20 +172,23 @@ fn exception_text(record: &Bound<'_, PyAny>) -> PyResult> { } /// A redacted copy of `record.__dict__` for one destination, or `None` when it does not belong. -/// -/// With `summarize_third_party`, records from other libraries follow the non-debug console -/// policy: errors in full, warnings as their first line without a traceback, nothing below. #[pyfunction] -#[pyo3(signature = ( - *, record, internal_only, allow_internal, include_sql_text, summarize_third_party = false -))] +#[pyo3(signature = (**request))] fn route_diagnostic_log_record<'py>( - record: &Bound<'py, PyAny>, - internal_only: bool, - allow_internal: bool, - include_sql_text: bool, - summarize_third_party: bool, + request: Option<&Bound<'py, PyDict>>, ) -> PyResult>> { + let request: Request<'_, 'py> = Request::new("route_diagnostic_log_record", request)?; + let record: &Bound<'py, PyAny> = &request.get("record")?; + let flag = |name: &str| -> PyResult { request.get(name)?.extract() }; + let options = RouteOptions { + internal_only: flag("internal_only")?, + allow_internal: flag("allow_internal")?, + include_sql_text: flag("include_sql_text")?, + }; + let summarize_third_party: bool = match request.optional("summarize_third_party")? { + Some(value) => value.extract()?, + None => false, + }; let py: Python<'py> = record.py(); let values: Bound<'py, PyDict> = record_values(record)?; let facts = RecordFacts { @@ -194,11 +197,6 @@ fn route_diagnostic_log_record<'py>( has_sql_digest: values.contains(SQL_DIGEST_FIELD)?, has_sql_text: values.contains(SQL_TEXT_FIELD)?, }; - let options = RouteOptions { - internal_only, - allow_internal, - include_sql_text, - }; if !route_admits(options, facts) { return Ok(None); } @@ -234,7 +232,7 @@ fn route_diagnostic_log_record<'py>( copied.set_item(&name, redacted_value(&name, &value)?)?; } } - if !include_sql_text && copied.contains(SQL_TEXT_FIELD)? { + if !options.include_sql_text && copied.contains(SQL_TEXT_FIELD)? { copied.del_item(SQL_TEXT_FIELD)?; } Ok(Some(copied)) diff --git a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs index 487f78565a..eea4e862e7 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/planner_entries/clone_plans.rs @@ -106,9 +106,7 @@ fn recreated_view(model: &Bound<'_, PyAny>, selected: &Bound<'_, PyAny>) -> PyRe && materialization_of(model)?.eq(VIEW_MATERIALIZATION)?) } -/// The entries of the sources that recreated views and functions read directly. -/// -/// Only their SQL is resolved against warehouse columns, so other sources need no inspection. +/// The entries of the sources whose columns recreated view and function SQL resolves against. fn resolved_source_entries<'py>( (project, plan): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), source_project: &Bound<'py, PyAny>, diff --git a/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py b/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py index ed84073eec..a645e3b3f4 100644 --- a/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py +++ b/src/sqlbuild/diagnostics/classes/dynamic_stderr_handler.py @@ -9,11 +9,7 @@ class DynamicStderrHandler(logging.StreamHandler): - """Stream handler that follows the current stderr object at emit time. - - Writes go through the shared transient line coordinator, which clears a live progress line - before the record and redraws it afterwards. - """ + """Stream handler that follows the current stderr and keeps clear of live progress lines.""" def emit(self, record: logging.LogRecord) -> None: self.stream = sys.stderr diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/conftest.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/conftest.py new file mode 100644 index 0000000000..7376e314dc --- /dev/null +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/conftest.py @@ -0,0 +1,16 @@ +"""Fixtures for clone E2E tests.""" + +from __future__ import annotations + +from pathlib import Path + +import pytest + +from tests.e2e.src.sqlbuild.cli.commands.main.clone.helpers import prepare_origin_project + + +@pytest.fixture(scope="module") +def origin_project(tmp_path_factory: pytest.TempPathFactory) -> Path: + """A project whose prod target is built, except `orders_backlog`, shared read-only.""" + + return prepare_origin_project(tmp_path_factory.mktemp("clone_preparation_origin")) diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/helpers.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/helpers.py new file mode 100644 index 0000000000..7b810d14b1 --- /dev/null +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/helpers.py @@ -0,0 +1,191 @@ +"""Synthetic project and origin environment shared by clone preparation E2E tests.""" + +from __future__ import annotations + +import shutil +import subprocess +from pathlib import Path +from textwrap import dedent + +from tests.e2e.src.sqlbuild.cli.commands.shared.helpers import prepare_inline_project, run_sqb + +PROJECT_FILES: dict[str, str] = { + "sqlbuild_project.toml": dedent( + """ + name = "clone_preparation_project" + adapter = "duckdb" + default_target = "dev" + + [connections.local] + database = "clone.duckdb" + + [targets.prod] + schema = "prod" + loader_schema = "raw_prod" + + [targets.prod.vars] + region = "emea" + + [targets.prod.clone] + allow_as_clone_origin = true + + [targets.dev] + schema = "dev" + loader_schema = "raw_dev" + + [targets.dev.vars] + region = "apac" + + [targets.dev.clone] + allow_as_clone_destination = true + + [targets.review] + schema = "review" + loader_schema = "raw_review" + defer_sources_to = "prod" + + [targets.review.vars] + region = "amer" + + [targets.review.clone] + allow_as_clone_destination = true + """ + ).lstrip(), + "python/loaders/raw.py": dedent( + """ + from sqlbuild.loaders import loader + + + @loader + def raw_payments(ctx): + '''Test loader raw_payments.''' + return [{"payment_id": 1, "order_id": 1, "amount_cents": 500}] + """ + ).lstrip(), + "sources/raw.yml": dedent( + """ + sources: + - name: raw_payments + description: Test source raw_payments. + managed: true + write_strategy: table + columns: + - name: payment_id + type: INTEGER + - name: order_id + type: INTEGER + - name: amount_cents + type: INTEGER + - name: raw_orders + description: Test source raw_orders. + expression: | + SELECT * + FROM (VALUES (1, 101, 100), (2, 102, 200)) + AS raw_orders(order_id, customer_id, amount_cents) + """ + ).lstrip(), + "seeds/customers.csv": "customer_id,customer_name\n101,Ada\n102,Grace\n", + "seeds/schema.yml": dedent( + """ + seeds: + - name: customers + description: Test seed customers. + columns: + - name: customer_id + type: INTEGER + - name: customer_name + type: VARCHAR + """ + ).lstrip(), + "models/staging/stg_orders.sql": dedent( + """ + MODEL (description "Test model stg_orders.", materialized view); + + SELECT order_id, customer_id, amount_cents, '@@region' AS region FROM __source("raw_orders") + """ + ).lstrip(), + "models/staging/stg_payments.sql": dedent( + """ + MODEL (description "Test model stg_payments.", materialized view); + + SELECT * FROM __source("raw_payments") + """ + ).lstrip(), + "models/marts/fct_orders.sql": dedent( + """ + MODEL (description "Test model fct_orders.", materialized table); + + SELECT o.order_id, o.amount_cents, c.customer_name + FROM __ref("stg_orders") AS o + JOIN __seed("customers") AS c ON c.customer_id = o.customer_id + """ + ).lstrip(), + "models/marts/fct_order_events.sql": dedent( + """ + MODEL ( + description "Test model fct_order_events.", + materialized incremental, + incremental_strategy append + ); + + SELECT order_id, amount_cents FROM __ref("fct_orders") + """ + ).lstrip(), + "models/marts/orders_summary.sql": dedent( + """ + MODEL (description "Test model orders_summary.", materialized view); + + SELECT f.*, p.amount_cents AS paid_cents + FROM __ref("fct_orders") AS f + LEFT JOIN __ref("stg_payments") AS p ON p.order_id = f.order_id + """ + ).lstrip(), + "models/marts/orders_backlog.sql": dedent( + """ + MODEL (description "Test model orders_backlog.", materialized table); + + SELECT order_id FROM __ref("fct_orders") WHERE amount_cents > 150 + """ + ).lstrip(), + "models/marts/retired_orders.sql": dedent( + """ + MODEL (description "Test model retired_orders.", materialized table, enabled false); + + SELECT order_id FROM __ref("fct_orders") + """ + ).lstrip(), + "functions/sql/cents_to_units.sql": dedent( + """ + FUNCTION ( + description "Test function cents_to_units.", + arguments (amount INTEGER), + returns DOUBLE + ); + + amount / 100.0 + """ + ).lstrip(), +} + + +def prepare_origin_project(tmp_path: Path) -> Path: + """The project with its prod target loaded and built, except `orders_backlog`.""" + + project_dir: Path = prepare_inline_project( + tmp_path=tmp_path, project_name="clone_preparation_project", repo_files=PROJECT_FILES + ) + for command in ( + ("--no-color", "load", "--target", "prod"), + ("--no-color", "build", "--target", "prod", "--exclude", "orders_backlog"), + ): + result: subprocess.CompletedProcess[str] = run_sqb(command=command, project_dir=project_dir) + assert result.returncode == 0, result.stdout + result.stderr + return project_dir + + +def copy_project(*, origin_project: Path, tmp_path: Path) -> Path: + """A private copy of the built origin project for one test.""" + + project_dir: Path = tmp_path / origin_project.name + shutil.copytree(origin_project, project_dir) + return project_dir diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py index 6f798b1461..6e3ad83750 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py @@ -3,10 +3,8 @@ from __future__ import annotations import json -import shutil import subprocess from pathlib import Path -from textwrap import dedent import pytest @@ -14,170 +12,16 @@ ClonePreparationE2ETestCase, CloneTerminalProgressE2ETestCase, ) +from tests.e2e.src.sqlbuild.cli.commands.main.clone.helpers import copy_project from tests.e2e.src.sqlbuild.cli.commands.shared.helpers import ( SPINNER_GLYPHS, assert_fragments_in_order, - prepare_inline_project, query_duckdb, render_terminal_screen, run_sqb, run_sqb_with_pty, ) -_PROJECT_FILES: dict[str, str] = { - "sqlbuild_project.toml": dedent( - """ - name = "clone_preparation_project" - adapter = "duckdb" - default_target = "dev" - - [connections.local] - database = "clone.duckdb" - - [targets.prod] - schema = "prod" - loader_schema = "raw_prod" - - [targets.prod.vars] - region = "emea" - - [targets.prod.clone] - allow_as_clone_origin = true - - [targets.dev] - schema = "dev" - loader_schema = "raw_dev" - - [targets.dev.vars] - region = "apac" - - [targets.dev.clone] - allow_as_clone_destination = true - - [targets.review] - schema = "review" - loader_schema = "raw_review" - defer_sources_to = "prod" - - [targets.review.vars] - region = "amer" - - [targets.review.clone] - allow_as_clone_destination = true - """ - ).lstrip(), - "python/loaders/raw.py": dedent( - """ - from sqlbuild.loaders import loader - - - @loader - def raw_payments(ctx): - '''Test loader raw_payments.''' - return [{"payment_id": 1, "order_id": 1, "amount_cents": 500}] - """ - ).lstrip(), - "sources/raw.yml": dedent( - """ - sources: - - name: raw_payments - description: Test source raw_payments. - managed: true - write_strategy: table - columns: - - name: payment_id - type: INTEGER - - name: order_id - type: INTEGER - - name: amount_cents - type: INTEGER - - name: raw_orders - description: Test source raw_orders. - expression: | - SELECT * - FROM (VALUES (1, 101, 100), (2, 102, 200)) - AS raw_orders(order_id, customer_id, amount_cents) - """ - ).lstrip(), - "seeds/customers.csv": "customer_id,customer_name\n101,Ada\n102,Grace\n", - "seeds/schema.yml": dedent( - """ - seeds: - - name: customers - description: Test seed customers. - columns: - - name: customer_id - type: INTEGER - - name: customer_name - type: VARCHAR - """ - ).lstrip(), - "models/staging/stg_orders.sql": dedent( - """ - MODEL (description "Test model stg_orders.", materialized view); - - SELECT order_id, customer_id, amount_cents, '@@region' AS region FROM __source("raw_orders") - """ - ).lstrip(), - "models/staging/stg_payments.sql": dedent( - """ - MODEL (description "Test model stg_payments.", materialized view); - - SELECT * FROM __source("raw_payments") - """ - ).lstrip(), - "models/marts/fct_orders.sql": dedent( - """ - MODEL (description "Test model fct_orders.", materialized table); - - SELECT o.order_id, o.amount_cents, c.customer_name - FROM __ref("stg_orders") AS o - JOIN __seed("customers") AS c ON c.customer_id = o.customer_id - """ - ).lstrip(), - "models/marts/fct_order_events.sql": dedent( - """ - MODEL ( - description "Test model fct_order_events.", - materialized incremental, - incremental_strategy append - ); - - SELECT order_id, amount_cents FROM __ref("fct_orders") - """ - ).lstrip(), - "models/marts/orders_summary.sql": dedent( - """ - MODEL (description "Test model orders_summary.", materialized view); - - SELECT f.*, p.amount_cents AS paid_cents - FROM __ref("fct_orders") AS f - LEFT JOIN __ref("stg_payments") AS p ON p.order_id = f.order_id - """ - ).lstrip(), - "models/marts/orders_backlog.sql": dedent( - """ - MODEL (description "Test model orders_backlog.", materialized table); - - SELECT order_id FROM __ref("fct_orders") WHERE amount_cents > 150 - """ - ).lstrip(), - "models/marts/retired_orders.sql": dedent( - """ - MODEL (description "Test model retired_orders.", materialized table, enabled false); - - SELECT order_id FROM __ref("fct_orders") - """ - ).lstrip(), - "functions/sql/cents_to_units.sql": dedent( - """ - FUNCTION (description "Test function cents_to_units.", arguments (amount INTEGER), returns DOUBLE); - - amount / 100.0 - """ - ).lstrip(), -} - _VIEW_ROWS: str = ( "SELECT schema_name, view_name, sql FROM duckdb_views() " "WHERE NOT internal AND schema_name = '{schema}' ORDER BY view_name" @@ -201,59 +45,25 @@ def raw_payments(ctx): ) -def _asset( - kind: str, name: str, action: str, origin: str | None, target: str -) -> tuple[str, str, str, str | None, str]: - return (kind, name, action, origin, target) - - _ALL_DEV_ASSETS: tuple[tuple[str, str, str, str | None, str], ...] = ( - _asset("seed", "customers", "copied", "prod.customers", "dev.customers"), - _asset("model", "stg_orders", "recreated_view", "prod.stg_orders", "dev.stg_orders"), - _asset("model", "fct_orders", "copied", "prod.fct_orders", "dev.fct_orders"), - _asset("model", "fct_order_events", "copied", "prod.fct_order_events", "dev.fct_order_events"), - _asset( + ("seed", "customers", "copied", "prod.customers", "dev.customers"), + ("model", "stg_orders", "recreated_view", "prod.stg_orders", "dev.stg_orders"), + ("model", "fct_orders", "copied", "prod.fct_orders", "dev.fct_orders"), + ("model", "fct_order_events", "copied", "prod.fct_order_events", "dev.fct_order_events"), + ( "model", "orders_backlog", "warning_missing_source", "prod.orders_backlog", "dev.orders_backlog", ), - _asset("source", "raw_payments", "copied", "raw_prod.raw_payments", "raw_dev.raw_payments"), - _asset("model", "stg_payments", "recreated_view", "prod.stg_payments", "dev.stg_payments"), - _asset( - "model", "orders_summary", "recreated_view", "prod.orders_summary", "dev.orders_summary" - ), - _asset("udf", "cents_to_units", "recreated_function", None, "dev.cents_to_units"), + ("source", "raw_payments", "copied", "raw_prod.raw_payments", "raw_dev.raw_payments"), + ("model", "stg_payments", "recreated_view", "prod.stg_payments", "dev.stg_payments"), + ("model", "orders_summary", "recreated_view", "prod.orders_summary", "dev.orders_summary"), + ("udf", "cents_to_units", "recreated_function", None, "dev.cents_to_units"), ) -def _prepare_origin(tmp_path: Path) -> Path: - project_dir: Path = prepare_inline_project( - tmp_path=tmp_path, project_name="clone_preparation_project", repo_files=_PROJECT_FILES - ) - for command in ( - ("--no-color", "load", "--target", "prod"), - ("--no-color", "build", "--target", "prod", "--exclude", "orders_backlog"), - ): - result: subprocess.CompletedProcess[str] = run_sqb(command=command, project_dir=project_dir) - assert result.returncode == 0, result.stdout + result.stderr - return project_dir - - -@pytest.fixture(scope="module") -def origin_project(tmp_path_factory: pytest.TempPathFactory) -> Path: - """A project whose prod target is built, except `orders_backlog`, shared read-only.""" - - return _prepare_origin(tmp_path_factory.mktemp("clone_preparation_origin")) - - -def _project_copy(*, origin_project: Path, tmp_path: Path) -> Path: - project_dir: Path = tmp_path / origin_project.name - shutil.copytree(origin_project, project_dir) - return project_dir - - @pytest.mark.parametrize( "test_case", ( @@ -311,42 +121,38 @@ def _project_copy(*, origin_project: Path, tmp_path: Path) -> Path: description="destination deferring sources reads origin sources and skips them", clone_arguments=("--from", "prod", "--to", "review"), expected_assets=( - _asset("seed", "customers", "copied", "prod.customers", "review.customers"), - _asset( - "model", "stg_orders", "recreated_view", "prod.stg_orders", "review.stg_orders" - ), - _asset("model", "fct_orders", "copied", "prod.fct_orders", "review.fct_orders"), - _asset( + ("seed", "customers", "copied", "prod.customers", "review.customers"), + ("model", "stg_orders", "recreated_view", "prod.stg_orders", "review.stg_orders"), + ("model", "fct_orders", "copied", "prod.fct_orders", "review.fct_orders"), + ( "model", "fct_order_events", "copied", "prod.fct_order_events", "review.fct_order_events", ), - _asset( + ( "model", "orders_backlog", "warning_missing_source", "prod.orders_backlog", "review.orders_backlog", ), - _asset( + ( "model", "stg_payments", "recreated_view", "prod.stg_payments", "review.stg_payments", ), - _asset( + ( "model", "orders_summary", "recreated_view", "prod.orders_summary", "review.orders_summary", ), - _asset( - "udf", "cents_to_units", "recreated_function", None, "review.cents_to_units" - ), + ("udf", "cents_to_units", "recreated_function", None, "review.cents_to_units"), ), expected_query_results=( ( @@ -385,7 +191,7 @@ def _project_copy(*, origin_project: Path, tmp_path: Path) -> Path: def test_given_origin_environment_when_cloning_then_items_and_relations_match_selection( test_case: ClonePreparationE2ETestCase, origin_project: Path, tmp_path: Path ) -> None: - project_dir: Path = _project_copy(origin_project=origin_project, tmp_path=tmp_path) + project_dir: Path = copy_project(origin_project=origin_project, tmp_path=tmp_path) json_path: Path = tmp_path / "clone.json" result: subprocess.CompletedProcess[str] = run_sqb( @@ -417,7 +223,9 @@ def test_given_origin_environment_when_cloning_then_items_and_relations_match_se query: str expected_rows: tuple[tuple[object, ...], ...] for query, expected_rows in test_case.expected_query_results: - rows = query_duckdb(db_path=project_dir / "clone.duckdb", sql=query) + rows: list[tuple[object, ...]] = query_duckdb( + db_path=project_dir / "clone.duckdb", sql=query + ) assert tuple(tuple(row) for row in rows) == expected_rows @@ -442,7 +250,7 @@ def test_given_origin_environment_when_cloning_then_items_and_relations_match_se def test_given_terminal_when_cloning_then_preparation_spinner_stops_before_items( test_case: CloneTerminalProgressE2ETestCase, origin_project: Path, tmp_path: Path ) -> None: - project_dir: Path = _project_copy(origin_project=origin_project, tmp_path=tmp_path) + project_dir: Path = copy_project(origin_project=origin_project, tmp_path=tmp_path) result: subprocess.CompletedProcess[str] = run_sqb_with_pty( command=( diff --git a/tests/integration/src/sqlbuild/cli/recall/_test_types.py b/tests/integration/src/sqlbuild/cli/recall/_test_types.py index f02f6c2e88..cf373b1ec6 100644 --- a/tests/integration/src/sqlbuild/cli/recall/_test_types.py +++ b/tests/integration/src/sqlbuild/cli/recall/_test_types.py @@ -196,6 +196,6 @@ class SlowReplacementTestCase: @dataclass(frozen=True) class ThirdPartyLogTestCase: description: str - debug: bool + build_arguments: tuple[str, ...] expected_present: tuple[str, ...] expected_absent: tuple[str, ...] diff --git a/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py index a22ad6d5c5..1853f1c97f 100644 --- a/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py +++ b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py @@ -31,13 +31,13 @@ ( ThirdPartyLogTestCase( description="normal output hides INFO and shows the warning as one line", - debug=False, + build_arguments=("build",), expected_present=("[warning] vendor.client token refresh failed",), expected_absent=("connecting to the orders service", TRACEBACK, "token expired"), ), ThirdPartyLogTestCase( description="debug output shows every record with its traceback", - debug=True, + build_arguments=("--debug", "build"), expected_present=( "[info] vendor.client connecting to the orders service", "[warning] vendor.client token refresh failed", @@ -55,9 +55,7 @@ def test_given_library_logs_during_build_when_running_then_console_is_quiet_and_ project_dir: Path = write_project(tmp_path / "orders_shop") (project_dir / "python" / "tasks" / "emit.py").write_text(VENDOR_TASK, encoding="utf-8") - built: subprocess.CompletedProcess[bytes] = run( - project_dir, *(("--debug",) if test_case.debug else ()), "build" - ) + built: subprocess.CompletedProcess[bytes] = run(project_dir, *test_case.build_arguments) stderr: str = built.stderr.decode(errors="replace") assert built.returncode == 0, stderr diff --git a/tests/unit/src/sqlbuild/diagnostics/_test_types.py b/tests/unit/src/sqlbuild/diagnostics/_test_types.py index a309111312..7b6b6bcd6e 100644 --- a/tests/unit/src/sqlbuild/diagnostics/_test_types.py +++ b/tests/unit/src/sqlbuild/diagnostics/_test_types.py @@ -44,6 +44,7 @@ class ThirdPartyConsoleTestCase: description: str debug: bool expected_console_lines: tuple[str, ...] + expected_absent: tuple[str, ...] expected_traceback_count: int diff --git a/tests/unit/src/sqlbuild/diagnostics/helpers.py b/tests/unit/src/sqlbuild/diagnostics/helpers.py index 1de988b455..604896735d 100644 --- a/tests/unit/src/sqlbuild/diagnostics/helpers.py +++ b/tests/unit/src/sqlbuild/diagnostics/helpers.py @@ -13,3 +13,15 @@ def emit(self, record: logging.LogRecord) -> None: def close(self) -> None: self.was_closed = True super().close() + + +def log_vendor_records() -> None: + """Log like a client library: progress, a recovered failure and an error.""" + + logger: logging.Logger = logging.getLogger("vendor.client") + logger.info("connecting to the orders service") + try: + raise RuntimeError("token expired") + except RuntimeError: + logger.warning("token refresh failed\nretrying with fallback", exc_info=True) + logger.error("orders service rejected the request", exc_info=True) diff --git a/tests/unit/src/sqlbuild/diagnostics/test_main.py b/tests/unit/src/sqlbuild/diagnostics/test_main.py index 4dfd705bf8..5351745d31 100644 --- a/tests/unit/src/sqlbuild/diagnostics/test_main.py +++ b/tests/unit/src/sqlbuild/diagnostics/test_main.py @@ -19,22 +19,12 @@ DiagnosticsLogTestCase, ThirdPartyConsoleTestCase, ) -from tests.unit.src.sqlbuild.diagnostics.helpers import HostRecordingLogHandler +from tests.unit.src.sqlbuild.diagnostics.helpers import HostRecordingLogHandler, log_vendor_records from tests.unit.src.sqlbuild.presentation.classes.helpers import RecordingStream _CLEAR_LINE: str = "\r\x1b[K" -def _log_vendor_records() -> None: - logger: logging.Logger = logging.getLogger("vendor.client") - logger.info("connecting to the orders service") - try: - raise RuntimeError("token expired") - except RuntimeError: - logger.warning("token refresh failed\nretrying with fallback", exc_info=True) - logger.error("orders service rejected the request", exc_info=True) - - @pytest.mark.parametrize( "test_case", [ @@ -78,6 +68,7 @@ def test_given_diagnostics_without_debug_when_logging_then_internal_records_are_ "[warning] vendor.client token refresh failed", "[error] vendor.client orders service rejected the request", ), + expected_absent=("connecting to the orders service", "retrying with fallback"), expected_traceback_count=1, ), ThirdPartyConsoleTestCase( @@ -89,6 +80,7 @@ def test_given_diagnostics_without_debug_when_logging_then_internal_records_are_ "retrying with fallback", "[error] vendor.client orders service rejected the request", ), + expected_absent=(), expected_traceback_count=2, ), ), @@ -99,14 +91,12 @@ def test_given_third_party_records_when_logging_then_console_follows_debug_polic capsys: pytest.CaptureFixture[str], ) -> None: with configure_diagnostics(debug=test_case.debug): - _log_vendor_records() + log_vendor_records() console_error: str = capsys.readouterr().err - lines: tuple[str, ...] = tuple( - line for line in console_error.splitlines() if line.startswith(("[", "retrying")) - ) - assert lines == test_case.expected_console_lines + assert all(line in console_error for line in test_case.expected_console_lines), console_error + assert not any(fragment in console_error for fragment in test_case.expected_absent) assert console_error.count("Traceback (most recent call last):") == ( test_case.expected_traceback_count ) From cdc284efb48f513518adae69fc24a5dc336ad113 Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 15:56:05 +0100 Subject: [PATCH 4/7] fix: end clone preparation spinners on failure, single-bracket clone timing, failed phase messages --- .../main/render_clone_completion.rs | 2 +- .../src/clone_text/tests/test_clone_text.rs | 4 +- .../sqlbuild-core/src/progress/constants.rs | 2 + .../main/is_planning_failure_message.rs | 11 ++++ crates/sqlbuild-core/src/progress/main/mod.rs | 1 + .../src/progress/tests/test_progress_text.rs | 31 +++++++++++ .../build_progress/progress_reporters.rs | 14 +++-- .../bindings/_helpers/clone/clone_command.rs | 52 +++++++++---------- fensu.toml | 2 +- .../cli/commands/main/clone/_test_types.py | 9 ++++ .../main/clone/test_clone_preparation.py | 48 +++++++++++++++++ .../commands/shared/_helpers/_test_types.py | 7 +++ .../shared/_helpers/test_planning_progress.py | 44 ++++++++++++++++ 13 files changed, 191 insertions(+), 36 deletions(-) create mode 100644 crates/sqlbuild-core/src/progress/main/is_planning_failure_message.rs diff --git a/crates/sqlbuild-core/src/clone_text/main/render_clone_completion.rs b/crates/sqlbuild-core/src/clone_text/main/render_clone_completion.rs index 9d31dc66ca..1ddc970fcf 100644 --- a/crates/sqlbuild-core/src/clone_text/main/render_clone_completion.rs +++ b/crates/sqlbuild-core/src/clone_text/main/render_clone_completion.rs @@ -42,7 +42,7 @@ pub fn render_clone_completion( label: "TOTAL".to_owned(), value: count(items, |_| true), }); - let elapsed: Option = elapsed_seconds.map(|seconds| format!("({seconds:.2}s)")); + let elapsed: Option = elapsed_seconds.map(|seconds| format!("{seconds:.2}s")); let footer: String = format_summary_footer(style, &counts, elapsed.as_deref()); let warnings: i64 = count(items, |item| item.status == CloneStatusKind::Warning); let failures: i64 = count(items, |item| item.status == CloneStatusKind::Failed); diff --git a/crates/sqlbuild-core/src/clone_text/tests/test_clone_text.rs b/crates/sqlbuild-core/src/clone_text/tests/test_clone_text.rs index 65d91bb78d..e5640b148f 100644 --- a/crates/sqlbuild-core/src/clone_text/tests/test_clone_text.rs +++ b/crates/sqlbuild-core/src/clone_text/tests/test_clone_text.rs @@ -149,12 +149,12 @@ fn given_items_when_completing_then_reports_messages_counts_and_exit_code() { expected_exit_code: 1, }, CompletionTestCase { - description: "success shows the doubly parenthesised elapsed time", + description: "success shows the elapsed time in one pair of parentheses", items: vec![item("orders", "copied", CloneStatusKind::Success)], elapsed_seconds: Some(1.5), use_color: false, expected_text: "\n\u{2713} Completed successfully CLONED=0 COPIED=1 RECREATED_VIEWS=0 \ - RECREATED_FUNCTIONS=0 PASS=1 WARN=0 FAIL=0 TOTAL=1 ((1.50s))\n", + RECREATED_FUNCTIONS=0 PASS=1 WARN=0 FAIL=0 TOTAL=1 (1.50s)\n", expected_exit_code: 0, }, CompletionTestCase { diff --git a/crates/sqlbuild-core/src/progress/constants.rs b/crates/sqlbuild-core/src/progress/constants.rs index 8c40e39d2a..2fbc23967f 100644 --- a/crates/sqlbuild-core/src/progress/constants.rs +++ b/crates/sqlbuild-core/src/progress/constants.rs @@ -97,6 +97,8 @@ pub(crate) const PLANNING_COMPLETION_PREFIXES: [&str; 15] = [ "Resolved ", "Cloned ", ]; +/// Messages that end a planning phase with a failure. +pub(crate) const PLANNING_FAILURE_PREFIXES: [&str; 1] = ["Failed "]; pub(crate) const ASSERTION_PREFIX: &str = "assertion "; pub(crate) const PASS_OUTCOME: &str = "pass"; pub(crate) const ERROR_OUTCOME: &str = "error"; diff --git a/crates/sqlbuild-core/src/progress/main/is_planning_failure_message.rs b/crates/sqlbuild-core/src/progress/main/is_planning_failure_message.rs new file mode 100644 index 0000000000..d88a6e1781 --- /dev/null +++ b/crates/sqlbuild-core/src/progress/main/is_planning_failure_message.rs @@ -0,0 +1,11 @@ +//! Whether a planning progress message ends its phase with a failure. + +use crate::progress::constants::PLANNING_FAILURE_PREFIXES; + +/// Failure messages start with `Failed `, as in `Failed runtime cursor watermark ...`. +#[must_use] +pub fn is_planning_failure_message(message: &str) -> bool { + PLANNING_FAILURE_PREFIXES + .iter() + .any(|prefix| message.starts_with(prefix)) +} diff --git a/crates/sqlbuild-core/src/progress/main/mod.rs b/crates/sqlbuild-core/src/progress/main/mod.rs index 9b70ca7b90..e8f7c3c6f5 100644 --- a/crates/sqlbuild-core/src/progress/main/mod.rs +++ b/crates/sqlbuild-core/src/progress/main/mod.rs @@ -10,5 +10,6 @@ pub mod format_expectation_name; pub mod format_inspection_record; pub mod format_status_spinner_line; pub mod is_planning_completion_message; +pub mod is_planning_failure_message; pub mod machine_output_mode; pub mod progress_terminal_duration; diff --git a/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs b/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs index b90e70a460..4bee5218ae 100644 --- a/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs +++ b/crates/sqlbuild-core/src/progress/tests/test_progress_text.rs @@ -7,6 +7,7 @@ use crate::progress::main::format_expectation_name::format_expectation_name; use crate::progress::main::format_inspection_record::format_inspection_record; use crate::progress::main::format_status_spinner_line::format_status_spinner_line; use crate::progress::main::is_planning_completion_message::is_planning_completion_message; +use crate::progress::main::is_planning_failure_message::is_planning_failure_message; use crate::progress::main::machine_output_mode::machine_output_mode; use crate::progress::models::{ExpectationStep, InspectionRecord, OutputModeFacts}; @@ -61,6 +62,36 @@ fn given_planning_message_when_classifying_then_completions_are_recognized() { } } +#[test] +fn given_planning_message_when_classifying_then_failures_are_recognized() { + let test_cases = [ + CompletionMessageTestCase { + description: "a failed cursor watermark ends its phase", + message: "Failed runtime cursor watermark (1/1): dev.orders.updated_at [max] (0.10s): boom", + expected_is_completion: true, + }, + CompletionMessageTestCase { + description: "a successful completion is not a failure", + message: "Inspected runtime cursor watermark (1/1): dev.orders.updated_at [max] (0.10s)", + expected_is_completion: false, + }, + CompletionMessageTestCase { + description: "an ongoing phase is not a failure", + message: "Inspecting runtime cursor watermark (1/1): dev.orders.updated_at [max]...", + expected_is_completion: false, + }, + ]; + + for test_case in test_cases { + assert_eq!( + is_planning_failure_message(test_case.message), + test_case.expected_is_completion, + "{}", + test_case.description + ); + } +} + #[test] fn given_connection_and_header_when_formatting_then_lines_match() { let test_cases = [ diff --git a/crates/sqlbuild-python/src/bindings/_helpers/build_progress/progress_reporters.rs b/crates/sqlbuild-python/src/bindings/_helpers/build_progress/progress_reporters.rs index 785eba46c4..960ac92d6b 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/build_progress/progress_reporters.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/build_progress/progress_reporters.rs @@ -11,6 +11,7 @@ use sqlbuild_core::cli_text::models::CliStyle; use sqlbuild_core::progress::main::connection_phase_line::connection_phase_line; use sqlbuild_core::progress::main::connection_start_message::connection_start_message; use sqlbuild_core::progress::main::is_planning_completion_message::is_planning_completion_message; +use sqlbuild_core::progress::main::is_planning_failure_message::is_planning_failure_message; use crate::bindings::_helpers::boundary::python_calls::KeywordArguments; use crate::bindings::_helpers::build_progress::progress::{ @@ -146,7 +147,7 @@ impl PlanningProgressReporter { }) } - fn on_progress(&self, py: Python<'_>, message: &str) -> PyResult<()> { + pub(crate) fn on_progress(&self, py: Python<'_>, message: &str) -> PyResult<()> { if let Some(projector) = &self.projector && projector_operation_active(projector.get(), PROJECT_COMPILE_OPERATION)? { @@ -155,13 +156,16 @@ impl PlanningProgressReporter { if is_planning_completion_message(message) { return self.complete(py, message); } + if is_planning_failure_message(message) { + return self.error(py, message); + } if !self.active.load(Ordering::SeqCst) { return self.start(py, message); } self.update(py, message) } - fn start(&self, py: Python<'_>, message: &str) -> PyResult<()> { + pub(crate) fn start(&self, py: Python<'_>, message: &str) -> PyResult<()> { self.call_status(py, "start", message)?; self.active.store(true, Ordering::SeqCst); Ok(()) @@ -174,14 +178,14 @@ impl PlanningProgressReporter { self.call_status(py, "update", message) } - fn complete(&self, py: Python<'_>, message: &str) -> PyResult<()> { + pub(crate) fn complete(&self, py: Python<'_>, message: &str) -> PyResult<()> { self.call_status_keyword(py, "complete", message)?; self.active.store(false, Ordering::SeqCst); Ok(()) } /// Complete with a pre-styled message written verbatim. - fn complete_styled(&self, py: Python<'_>, message: &str) -> PyResult<()> { + pub(crate) fn complete_styled(&self, py: Python<'_>, message: &str) -> PyResult<()> { self.call_status_keyword(py, "complete_styled", message)?; self.active.store(false, Ordering::SeqCst); Ok(()) @@ -195,7 +199,7 @@ impl PlanningProgressReporter { } #[pyo3(signature = (*, blank_line_after = false))] - fn finish(&self, py: Python<'_>, blank_line_after: bool) -> PyResult<()> { + pub(crate) fn finish(&self, py: Python<'_>, blank_line_after: bool) -> PyResult<()> { self.status.bind(py).call_method0("close")?; self.active.store(false, Ordering::SeqCst); if blank_line_after { diff --git a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs index 06194488c5..075ec0e0dc 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs @@ -87,13 +87,12 @@ fn text<'py>(py: Python<'py>, value: &str) -> Bound<'py, PyAny> { fn progress_reporter<'py>( stream: &Bound<'py, PyAny>, style: CliStyle, -) -> PyResult> { +) -> PyResult> { let py: Python<'py> = stream.py(); - Ok(Bound::new( + Bound::new( py, PlanningProgressReporter::new(py, stream, style.use_color)?, - )? - .into_any()) + ) } fn lifecycle<'py>(py: Python<'py>, (kind, name): (&str, &str)) -> PyResult> { @@ -137,13 +136,13 @@ fn invocation<'py>(py: Python<'py>, request: &Bound<'py, PyAny>) -> PyResult()? && stdout_supports_color(py)?; let style: CliStyle = CliStyle { use_color }; let stream: Bound<'py, PyAny> = py.import("sys")?.getattr("stdout")?; - let progress: Bound<'py, PyAny> = progress_reporter(&stream, style)?; - progress.call_method1("start", ("Discovering project...",))?; + let progress: Bound<'py, PlanningProgressReporter> = progress_reporter(&stream, style)?; + progress.get().start(py, "Discovering project...")?; let discovered: Bound<'py, PyAny> = discover_project_inputs( py, Some(keywords(py, &[("project_dir", project_dir.clone())])?), )?; - progress.call_method1("complete", ("Discovered project.",))?; + progress.get().complete(py, "Discovered project.")?; reject_unit_test_selectors( &native_field(request, "select")?, &native_field(request, "exclude")?, @@ -206,11 +205,11 @@ fn connect<'py>( ], )?), )?; - let progress: Bound<'py, PyAny> = progress_reporter(&invocation.stream, invocation.style)?; - progress.call_method1( - "start", - (format!("Connecting to {}...", invocation.adapter_name),), - )?; + let progress: Bound<'py, PlanningProgressReporter> = + progress_reporter(&invocation.stream, invocation.style)?; + progress + .get() + .start(py, &format!("Connecting to {}...", invocation.adapter_name))?; let started: Instant = Instant::now(); let connection: Bound<'py, PyAny> = within( &lifecycle(py, ("clone", "clone_target_connection"))?, @@ -222,13 +221,9 @@ fn connect<'py>( invocation.adapter_name, started.elapsed().as_secs_f64() ); - progress.call_method1( - "complete_styled", - (format_phase_line( - invocation.style, - true, - ("Warehouse connected", &summary), - ),), + progress.get().complete_styled( + py, + &format_phase_line(invocation.style, true, ("Warehouse connected", &summary)), )?; Ok((config, connection)) } @@ -240,11 +235,12 @@ fn prepare<'py>( (config, connection): (&Bound<'py, PyAny>, &Bound<'py, PyAny>), ) -> PyResult> { let py: Python<'py> = request.py(); - let progress: Bound<'py, PyAny> = progress_reporter(&invocation.stream, invocation.style)?; + let progress: Bound<'py, PlanningProgressReporter> = + progress_reporter(&invocation.stream, invocation.style)?; let started: Instant = Instant::now(); - let pipeline: Bound<'py, PyAny> = + let prepared: PyResult> = within(&lifecycle(py, ("project", "project_compile"))?, |_| { - progress.call_method1("on_progress", ("Preparing clone plan...",))?; + progress.get().on_progress(py, "Preparing clone plan...")?; let resolver: Bound<'py, PyAny> = resolve_external_sql_reference_resolver( invocation.project_dir.clone(), invocation.discovered.clone(), @@ -280,15 +276,17 @@ fn prepare<'py>( &text(py, &invocation.destination), ), )?; - progress.call_method1( - "on_progress", - (format!( + progress.get().on_progress( + py, + &format!( "Prepared clone plan. ({:.2}s)", started.elapsed().as_secs_f64() - ),), + ), )?; Ok(pipeline) - })?; + }); + let pipeline: Bound<'py, PyAny> = + prepared.or_else(|error| progress.get().finish(py, false).and(Err(error)))?; if destination_entry_count(&pipeline)? == 0 { return Err(user_error(py, NOTHING_TO_CLONE)); } diff --git a/fensu.toml b/fensu.toml index ecb8b05d64..f658eb1c5c 100644 --- a/fensu.toml +++ b/fensu.toml @@ -1675,7 +1675,7 @@ pending_budgets = [ "crates/sqlbuild-python/src/bindings/_helpers/cli/namespace.rs=3", "crates/sqlbuild-python/src/bindings/_helpers/cli/observability.rs=21", "crates/sqlbuild-python/src/bindings/_helpers/cli/surrogates.rs=2", - "crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs=18", + "crates/sqlbuild-python/src/bindings/_helpers/clone/clone_command.rs=12", "crates/sqlbuild-python/src/bindings/_helpers/clone/clone_execution.rs=4", "crates/sqlbuild-python/src/bindings/_helpers/clone/clone_pipeline.rs=1", "crates/sqlbuild-python/src/bindings/_helpers/clone/clone_progress.rs=7", diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py index 2ba7c750bd..ed85edd284 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/_test_types.py @@ -57,3 +57,12 @@ class CloneTerminalProgressE2ETestCase: description: str columns: int expected_screen_fragments: tuple[str, ...] + + +@dataclass(frozen=True) +class ClonePreparationFailureE2ETestCase: + description: str + columns: int + broken_model_path: str + broken_model_sql: str + expected_screen_fragments: tuple[str, ...] diff --git a/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py index 6e3ad83750..a64f7f7583 100644 --- a/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py +++ b/tests/e2e/src/sqlbuild/cli/commands/main/clone/test_clone_preparation.py @@ -3,6 +3,7 @@ from __future__ import annotations import json +import re import subprocess from pathlib import Path @@ -10,6 +11,7 @@ from tests.e2e.src.sqlbuild.cli.commands.main.clone._test_types import ( ClonePreparationE2ETestCase, + ClonePreparationFailureE2ETestCase, CloneTerminalProgressE2ETestCase, ) from tests.e2e.src.sqlbuild.cli.commands.main.clone.helpers import copy_project @@ -206,6 +208,7 @@ def test_given_origin_environment_when_cloning_then_items_and_relations_match_se ) assert result.returncode == 0, result.stdout + result.stderr + assert re.search(r"TOTAL=\d+ \(\d+\.\d{2}s\)\n", result.stdout), result.stdout assets: list[dict[str, object]] = json.loads(json_path.read_text(encoding="utf-8"))["assets"] assert ( tuple( @@ -278,5 +281,50 @@ def test_given_terminal_when_cloning_then_preparation_spinner_stops_before_items assert not any(glyph in after_preparation for glyph in SPINNER_GLYPHS), after_preparation +@pytest.mark.parametrize( + "test_case", + ( + ClonePreparationFailureE2ETestCase( + description="compile error stops the preparation spinner before the error prints", + columns=120, + broken_model_path="models/marts/orders_backlog.sql", + broken_model_sql=( + 'MODEL (description "Test model orders_backlog.", materialized table);\n\n' + 'SELECT order_id FROM __ref("missing_orders")\n' + ), + expected_screen_fragments=( + "✓ Warehouse connected duckdb", + "error[P001]: Model file models/marts/orders_backlog.sql references unknown " + "model 'missing_orders'", + ), + ), + ), + ids=lambda case: case.description, +) +def test_given_failing_preparation_in_terminal_when_cloning_then_error_has_no_spinner( + test_case: ClonePreparationFailureE2ETestCase, origin_project: Path, tmp_path: Path +) -> None: + project_dir: Path = copy_project(origin_project=origin_project, tmp_path=tmp_path) + (project_dir / test_case.broken_model_path).write_text( + test_case.broken_model_sql, encoding="utf-8" + ) + + result: subprocess.CompletedProcess[str] = run_sqb_with_pty( + command=("clone", "--from", "prod", "--to", "dev"), + project_dir=project_dir, + columns=test_case.columns, + ) + + screen: tuple[str, ...] = render_terminal_screen( + output=result.stdout, columns=test_case.columns + ) + rendered: str = "\n".join(screen) + assert result.returncode == 1, rendered + assert not any(glyph in rendered for glyph in SPINNER_GLYPHS), rendered + assert_fragments_in_order(rendered, test_case.expected_screen_fragments) + before_error: str = result.stdout.split("error[P001]", maxsplit=1)[0] + assert before_error.rsplit("\x1b[?25", maxsplit=1)[1].startswith("h"), repr(before_error[-80:]) + + if __name__ == "__main__": pytest.main([__file__, "-vv"]) diff --git a/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/_test_types.py b/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/_test_types.py index 969189e0a3..8abd6652c8 100644 --- a/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/_test_types.py +++ b/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/_test_types.py @@ -156,3 +156,10 @@ class SqlTestStatusAlignmentTestCase: expected_models: tuple[str, ...] assertion_names: tuple[str, ...] expected_row_count: int + + +@dataclass(frozen=True) +class PlanningPhaseEndTestCase: + description: str + messages: tuple[str, ...] + expected_lines: tuple[str, ...] diff --git a/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/test_planning_progress.py b/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/test_planning_progress.py index 059fdfa5e3..047c2ec8b5 100644 --- a/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/test_planning_progress.py +++ b/tests/unit/src/sqlbuild/cli/commands/shared/_helpers/test_planning_progress.py @@ -12,8 +12,13 @@ ) from tests.unit.src.sqlbuild.cli.commands.shared._helpers._test_types import ( PlanningFinishTestCase, + PlanningPhaseEndTestCase, PlanningProgressTestCase, ) +from tests.unit.src.sqlbuild.presentation.classes.helpers import ( + RecordingStream, + persistent_lines, +) @pytest.mark.parametrize( @@ -57,6 +62,45 @@ def test_given_planning_messages_when_reporting_then_writes_expected_output( assert stream.getvalue() == test_case.expected_output +@pytest.mark.parametrize( + "test_case", + ( + PlanningPhaseEndTestCase( + description="failed watermark ends its phase before later output", + messages=( + "Inspecting runtime cursor watermark (1/1): dev.orders.updated_at [max]...", + "Failed runtime cursor watermark (1/1): dev.orders.updated_at [max] (0.10s): boom", + ), + expected_lines=( + "Failed runtime cursor watermark (1/1): dev.orders.updated_at [max] (0.10s): boom", + "error[E001]: later output", + "", + ), + ), + PlanningPhaseEndTestCase( + description="prepared clone plan ends its phase before later output", + messages=("Preparing clone plan...", "Prepared clone plan. (0.10s)"), + expected_lines=("Prepared clone plan. (0.10s)", "error[E001]: later output", ""), + ), + ), + ids=lambda case: case.description, +) +def test_given_phase_ending_message_on_terminal_when_reporting_then_spinner_stops( + test_case: PlanningPhaseEndTestCase, + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.delenv("SQLBUILD_NO_PROGRESS", raising=False) + stream: RecordingStream = RecordingStream(events=[], tty=True) + reporter: PlanningProgressReporter = PlanningProgressReporter(stream=stream, use_color=False) + + message: str + for message in test_case.messages: + reporter.on_progress(message) + stream.write("error[E001]: later output\n") + + assert persistent_lines(stream.getvalue()) == test_case.expected_lines + + @pytest.mark.parametrize( "test_case", [ From 129a322b790a9d8e72aade7a1da1bd5236b8204a Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 16:28:16 +0100 Subject: [PATCH 5/7] fix: keep project logs on the console, hide the clone no-op analysis flag, reuse the spinner thread --- .../sqlbuild-cli/src/argv/command_table.json | 4 +- .../argv/tests/test_parse_cli_arguments.rs | 50 ++++++++++- .../sqlbuild-cli/src/argv/tests/test_types.rs | 8 ++ .../src/diagnostic_routing/constants.rs | 2 + .../src/diagnostic_routing/main/mod.rs | 1 + .../main/project_source_path.rs | 18 ++++ .../diagnostic_routing/tests/test_routing.rs | 41 ++++++++- .../diagnostic_routing/tests/test_types.rs | 6 ++ .../build_progress/transient_status.rs | 32 +++++-- .../_helpers/diagnostics/log_records.rs | 20 ++++- .../sqlbuild/references/docs/cli/clone.md | 5 +- src/sqlbuild/_native.pyi | 1 + .../entrypoint/_dispatch_with_compute_logs.py | 4 + .../classes/invocation_diagnostic_routing.py | 1 + .../classes/log_record_route_filter.py | 3 + src/sqlbuild/diagnostics/main/configure.py | 2 + .../main/diagnostic_project_roots.py | 12 +++ src/sqlbuild/diagnostics/models.py | 1 + .../src/sqlbuild/cli/recall/_test_types.py | 1 + .../cli/recall/test_third_party_logs.py | 83 ++++++++++++++----- .../src/sqlbuild/diagnostics/_test_types.py | 7 ++ .../unit/src/sqlbuild/diagnostics/helpers.py | 10 +++ .../src/sqlbuild/diagnostics/test_main.py | 42 +++++++++- website/src/content/docs/docs/cli/clone.mdx | 5 +- 24 files changed, 320 insertions(+), 39 deletions(-) create mode 100644 crates/sqlbuild-core/src/diagnostic_routing/main/project_source_path.rs create mode 100644 src/sqlbuild/diagnostics/main/diagnostic_project_roots.py diff --git a/crates/sqlbuild-cli/src/argv/command_table.json b/crates/sqlbuild-cli/src/argv/command_table.json index 8f0360fb38..fd2f44b5d8 100644 --- a/crates/sqlbuild-cli/src/argv/command_table.json +++ b/crates/sqlbuild-cli/src/argv/command_table.json @@ -2899,7 +2899,9 @@ "nargs": 0, "const": true, "default": false, - "help": "disable SQL syntax, binding, type inference, and semantic validation", + "help": { + "suppress": true + }, "group": 1 }, { diff --git a/crates/sqlbuild-cli/src/argv/tests/test_parse_cli_arguments.rs b/crates/sqlbuild-cli/src/argv/tests/test_parse_cli_arguments.rs index 0e85966e2a..6358fbeb11 100644 --- a/crates/sqlbuild-cli/src/argv/tests/test_parse_cli_arguments.rs +++ b/crates/sqlbuild-cli/src/argv/tests/test_parse_cli_arguments.rs @@ -1,6 +1,6 @@ use crate::argv::models::{ArgvOutcome, Value}; use crate::argv::tests::helpers::{parse, strings}; -use crate::argv::tests::test_types::{ExitTestCase, ParsedValueTestCase}; +use crate::argv::tests::test_types::{ExitTestCase, HelpTextTestCase, ParsedValueTestCase}; #[test] fn given_accepted_arguments_when_parsing_then_attributes_hold_the_parsed_values() { @@ -29,6 +29,12 @@ fn given_accepted_arguments_when_parsing_then_attributes_hold_the_parsed_values( attribute: "dbt_args", expected_value: strings(&["--", "--no-color"]), }, + ParsedValueTestCase { + description: "clone still accepts the hidden --no-sql-analysis flag", + argv: &["clone", "--from", "prod", "--no-sql-analysis"], + attribute: "no_sql_validation", + expected_value: Value::Bool(true), + }, ParsedValueTestCase { description: "a nested sub-command's dest is set", argv: &["contract", "diff", "--from", "prod"], @@ -100,3 +106,45 @@ fn given_help_version_or_rejected_arguments_when_parsing_then_exits_after_writin ); } } + +#[test] +fn given_command_help_when_parsing_then_hidden_options_are_left_out() { + let test_cases = [ + HelpTextTestCase { + description: "clone help omits the no-op SQL analysis flag", + argv: &["clone", "--help"], + expected_present: &["--from FROM_TARGET", "--select"], + expected_absent: &["--no-sql-analysis", "--no-sql-validation"], + }, + HelpTextTestCase { + description: "build help keeps the SQL analysis flag", + argv: &["build", "--help"], + expected_present: &["--no-sql-analysis"], + expected_absent: &[], + }, + ]; + + for test_case in test_cases { + let outcome: ArgvOutcome = parse(test_case.argv); + let help: String = outcome + .writes + .iter() + .map(|(_, text)| text.as_str()) + .collect(); + let present: Vec<&str> = test_case + .expected_present + .iter() + .copied() + .filter(|fragment| help.contains(fragment)) + .collect(); + let absent: Vec<&str> = test_case + .expected_absent + .iter() + .copied() + .filter(|fragment| !help.contains(fragment)) + .collect(); + assert_eq!(outcome.parsed, Err(0), "{}", test_case.description); + assert_eq!(present, test_case.expected_present, "{help}"); + assert_eq!(absent, test_case.expected_absent, "{help}"); + } +} diff --git a/crates/sqlbuild-cli/src/argv/tests/test_types.rs b/crates/sqlbuild-cli/src/argv/tests/test_types.rs index 1be086a89b..4452d1689e 100644 --- a/crates/sqlbuild-cli/src/argv/tests/test_types.rs +++ b/crates/sqlbuild-cli/src/argv/tests/test_types.rs @@ -40,6 +40,14 @@ pub(super) struct ExitTestCase { pub(super) expected_last_write: &'static str, } +/// A help request and fragments its text must and must not contain. +pub(super) struct HelpTextTestCase { + pub(super) description: &'static str, + pub(super) argv: &'static [&'static str], + pub(super) expected_present: &'static [&'static str], + pub(super) expected_absent: &'static [&'static str], +} + /// Text, width and indent for `textwrap.wrap`, and the expected lines. pub(super) struct WrapTestCase { pub(super) description: &'static str, diff --git a/crates/sqlbuild-core/src/diagnostic_routing/constants.rs b/crates/sqlbuild-core/src/diagnostic_routing/constants.rs index a1b74ec18e..3cf4ff16c8 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/constants.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/constants.rs @@ -62,3 +62,5 @@ pub const LEVEL_INFO: i64 = 20; pub const LEVEL_WARNING: i64 = 30; pub const LEVEL_ERROR: i64 = 40; pub const LEVEL_CRITICAL: i64 = 50; +/// Directories that hold installed packages, even inside a project (a project `.venv`). +pub const PACKAGE_DIRECTORIES: [&str; 2] = ["site-packages", "dist-packages"]; diff --git a/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs b/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs index 6d96165983..781c4b7632 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/main/mod.rs @@ -2,6 +2,7 @@ pub mod compute_log_admits; pub mod console_summary_line; pub mod diagnostic_severity; pub mod internal_logger; +pub mod project_source_path; pub mod route_admits; pub mod sql_digest; pub mod third_party_console_form; diff --git a/crates/sqlbuild-core/src/diagnostic_routing/main/project_source_path.rs b/crates/sqlbuild-core/src/diagnostic_routing/main/project_source_path.rs new file mode 100644 index 0000000000..392023ec41 --- /dev/null +++ b/crates/sqlbuild-core/src/diagnostic_routing/main/project_source_path.rs @@ -0,0 +1,18 @@ +//! `project_source_path`: whether a logging call came from the project's own Python. + +use std::path::{Component, Path}; + +use crate::diagnostic_routing::constants::PACKAGE_DIRECTORIES; + +/// Whether `pathname` lies under one of `project_roots` and outside installed packages. +#[must_use] +pub fn project_source_path(pathname: &str, project_roots: &[String]) -> bool { + let path: &Path = Path::new(pathname); + project_roots + .iter() + .any(|root| !root.is_empty() && path.starts_with(root)) + && !path.components().any(|component| { + matches!(component, Component::Normal(name) + if PACKAGE_DIRECTORIES.iter().any(|package| name == *package)) + }) +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs index f2622c7304..f37f69b5ba 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_routing.rs @@ -4,13 +4,14 @@ use crate::diagnostic_routing::main::compute_log_admits::compute_log_admits; use crate::diagnostic_routing::main::console_summary_line::console_summary_line; use crate::diagnostic_routing::main::diagnostic_severity::diagnostic_severity; use crate::diagnostic_routing::main::internal_logger::internal_logger; +use crate::diagnostic_routing::main::project_source_path::project_source_path; use crate::diagnostic_routing::main::route_admits::route_admits; use crate::diagnostic_routing::main::sql_digest::sql_digest; use crate::diagnostic_routing::main::third_party_console_form::third_party_console_form; use crate::diagnostic_routing::models::{RecordFacts, RouteOptions, ThirdPartyConsoleForm}; use crate::diagnostic_routing::tests::test_types::{ - ComputeLogTestCase, ConsoleFormTestCase, DigestTestCase, InternalLoggerTestCase, RouteTestCase, - SeverityTestCase, SummaryLineTestCase, + ComputeLogTestCase, ConsoleFormTestCase, DigestTestCase, InternalLoggerTestCase, + ProjectSourceTestCase, RouteTestCase, SeverityTestCase, SummaryLineTestCase, }; const EXTERNAL_DEBUG: RecordFacts = RecordFacts { @@ -261,3 +262,39 @@ fn given_messages_when_summarizing_then_first_line_remains() { ); } } + +#[test] +fn given_record_paths_when_classifying_then_only_project_files_outside_packages_are_project() { + let roots: Vec = vec!["/work/orders_shop".to_owned()]; + let test_cases = [ + ProjectSourceTestCase { + description: "a project hook file is project code", + pathname: "/work/orders_shop/hooks/python/logs.py", + expected_project: true, + }, + ProjectSourceTestCase { + description: "a package in a project virtual environment is a library", + pathname: "/work/orders_shop/.venv/lib/python3.12/site-packages/vendor/client.py", + expected_project: false, + }, + ProjectSourceTestCase { + description: "a sibling directory sharing the prefix is outside the project", + pathname: "/work/orders_shop_tools/client.py", + expected_project: false, + }, + ProjectSourceTestCase { + description: "the standard library is outside the project", + pathname: "/usr/lib/python3.12/logging/__init__.py", + expected_project: false, + }, + ]; + + for test_case in test_cases { + assert_eq!( + project_source_path(test_case.pathname, &roots), + test_case.expected_project, + "{}", + test_case.description + ); + } +} diff --git a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs index efd5109ad7..b46e1bb8b9 100644 --- a/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs +++ b/crates/sqlbuild-core/src/diagnostic_routing/tests/test_types.rs @@ -43,3 +43,9 @@ pub(super) struct SummaryLineTestCase { pub(super) message: &'static str, pub(super) expected_line: &'static str, } + +pub(super) struct ProjectSourceTestCase { + pub(super) description: &'static str, + pub(super) pathname: &'static str, + pub(super) expected_project: bool, +} diff --git a/crates/sqlbuild-python/src/bindings/_helpers/build_progress/transient_status.rs b/crates/sqlbuild-python/src/bindings/_helpers/build_progress/transient_status.rs index 28661d4698..33c6f16149 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/build_progress/transient_status.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/build_progress/transient_status.rs @@ -243,21 +243,35 @@ impl TransientStatusReporter { Ok(()) } - /// Erase the live status so a persistent line can be written in its place. + /// Erase the live status so a persistent line can be written in its place; the spinner idles. fn clear_transient_line(&self, py: Python<'_>) -> PyResult<()> { - self.exit_status(py) + if std::mem::take(&mut self.state().drawn) { + let stream: &Bound<'_, PyAny> = self.stream.bind(py); + write(stream, &format!("{CLEAR_LINE}{SHOW_CURSOR}"))?; + flush(stream)?; + } + Ok(()) } - /// Restart the live status below persistent output written while it was active. + /// Draw the live status again below persistent output, reusing its running spinner. fn redraw_transient_line(slf: &Bound<'_, Self>) -> PyResult<()> { - let redraw: bool = { - let state = slf.get().state(); - state.message.is_some() && !state.drawn + let reporter: &Self = slf.get(); + let (redraw, spinning) = { + let state = reporter.state(); + ( + state.message.is_some() && !state.drawn, + state.stop_event.is_some(), + ) }; - if redraw { - Self::enter_status(slf)?; + if !redraw { + return Ok(()); } - Ok(()) + if !spinning { + return Self::enter_status(slf); + } + write(reporter.stream.bind(slf.py()), HIDE_CURSOR)?; + reporter.state().drawn = true; + reporter.draw(slf.py()) } /// Render one preflight progress update. diff --git a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs index 8a8044653c..b4026d99a4 100644 --- a/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs +++ b/crates/sqlbuild-python/src/bindings/_helpers/diagnostics/log_records.rs @@ -17,6 +17,7 @@ use sqlbuild_core::diagnostic_routing::main::compute_log_admits::compute_log_adm use sqlbuild_core::diagnostic_routing::main::console_summary_line::console_summary_line; use sqlbuild_core::diagnostic_routing::main::diagnostic_severity::diagnostic_severity; use sqlbuild_core::diagnostic_routing::main::internal_logger::internal_logger; +use sqlbuild_core::diagnostic_routing::main::project_source_path::project_source_path; use sqlbuild_core::diagnostic_routing::main::route_admits::route_admits; use sqlbuild_core::diagnostic_routing::main::sql_digest::sql_digest; use sqlbuild_core::diagnostic_routing::main::third_party_console_form::third_party_console_form; @@ -171,6 +172,20 @@ fn exception_text(record: &Bound<'_, PyAny>) -> PyResult> { swallowed(py, formatted) } +/// Whether the record's logging call is in a file under one of the project roots. +fn project_record(record: &Bound<'_, PyAny>, roots: Option>) -> PyResult { + let Some(roots) = roots.filter(|roots| !roots.is_none()) else { + return Ok(false); + }; + let Ok(pathname) = native_field(record, "pathname")?.extract::() else { + return Ok(false); + }; + Ok(project_source_path( + &pathname, + &roots.extract::>()?, + )) +} + /// A redacted copy of `record.__dict__` for one destination, or `None` when it does not belong. #[pyfunction] #[pyo3(signature = (**request))] @@ -200,7 +215,10 @@ fn route_diagnostic_log_record<'py>( if !route_admits(options, facts) { return Ok(None); } - let form: ThirdPartyConsoleForm = if summarize_third_party && !facts.internal { + let form: ThirdPartyConsoleForm = if summarize_third_party + && !facts.internal + && !project_record(record, request.optional("project_roots")?)? + { third_party_console_form(facts.level) } else { ThirdPartyConsoleForm::Full diff --git a/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md b/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md index 8dd961fa5b..f4fd87f0d8 100644 --- a/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md +++ b/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md @@ -20,6 +20,10 @@ SQLBuild never resolves or opens the origin target's connection, including for d deferred clone. Clone cannot perform a cross-account, cross-server, or cross-file transfer by opening a second connection. +Clone never runs SQL analysis: it reads relation names, dependencies, and rendered view and +function SQL from each target's project, and reports no compile diagnostics. The hidden +`--no-sql-analysis` flag (alias `--no-sql-validation`) is still accepted but has no effect. + ## Usage ```bash @@ -33,7 +37,6 @@ sqb --project-dir clone --from [--to ] [flags] | `--from` | Source target (required) | | `--to` | Destination target; defaults to the active target | | `--hard-copy` | Force physical table copies instead of zero-copy cloning | -| `--no-sql-analysis` | Disable compile-time SQL analysis (`--no-sql-validation` is an alias) | | `--select`, `-s` | Select specific models to clone | | `--exclude` | Exclude specific models from cloning | | `--warehouse ` | Snowflake warehouse for this invocation; overrides the target's `build` [warehouse group](../concepts/project-configuration.md#command-group-warehouses) and the connection warehouse | diff --git a/src/sqlbuild/_native.pyi b/src/sqlbuild/_native.pyi index a11a56b9ad..991ee32b6f 100644 --- a/src/sqlbuild/_native.pyi +++ b/src/sqlbuild/_native.pyi @@ -6414,6 +6414,7 @@ def route_diagnostic_log_record( allow_internal: bool, include_sql_text: bool, summarize_third_party: bool = False, + project_roots: tuple[str, ...] = (), ) -> dict[str, object] | None: ... def safe_diagnostic_extra_fields(record: logging.LogRecord) -> dict[str, object]: ... def compute_diagnostic_log_fields( diff --git a/src/sqlbuild/cli/commands/main/entrypoint/_dispatch_with_compute_logs.py b/src/sqlbuild/cli/commands/main/entrypoint/_dispatch_with_compute_logs.py index c6f6242d35..86aa0fb094 100644 --- a/src/sqlbuild/cli/commands/main/entrypoint/_dispatch_with_compute_logs.py +++ b/src/sqlbuild/cli/commands/main/entrypoint/_dispatch_with_compute_logs.py @@ -18,6 +18,7 @@ ) from sqlbuild.diagnostics.classes.invocation_diagnostic_routing import InvocationDiagnosticRouting from sqlbuild.diagnostics.main.configure import configure_diagnostics +from sqlbuild.diagnostics.main.diagnostic_project_roots import diagnostic_project_roots from sqlbuild.diagnostics.models import DiagnosticRoutingOptions from sqlbuild.runtime.compute_logs.main.run_with_compute_log_capture import ( run_with_compute_log_capture, @@ -39,9 +40,11 @@ def dispatch_with_compute_logs( if creates_project: return operation() project_dir: Path = Path(args.project_dir) if args.project_dir is not None else Path.cwd() + project_roots: tuple[str, ...] = diagnostic_project_roots(project_dir=project_dir) routing_options: DiagnosticRoutingOptions = DiagnosticRoutingOptions( debug_console=args.debug, use_color=(not args.no_color) and supports_color(), + project_roots=project_roots, ) started_at: datetime = datetime.now(UTC) command: str = "unknown" if args.command is None else str(args.command) @@ -72,6 +75,7 @@ def dispatch_with_compute_logs( invocation_id=identity.invocation_id, debug=args.debug, use_color=routing_options.use_color, + project_roots=project_roots, ) with routing: for failure, channel in failures: diff --git a/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py b/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py index 3426436942..b8725d51a3 100644 --- a/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py +++ b/src/sqlbuild/diagnostics/classes/invocation_diagnostic_routing.py @@ -148,6 +148,7 @@ def _build_handlers(self) -> list[logging.Handler]: allow_internal=self._options.debug_console, include_sql_text=False, summarize_third_party=not self._options.debug_console, + project_roots=self._options.project_roots, ) ) handlers.append(console_handler) diff --git a/src/sqlbuild/diagnostics/classes/log_record_route_filter.py b/src/sqlbuild/diagnostics/classes/log_record_route_filter.py index 26e04e358e..de8311e7db 100644 --- a/src/sqlbuild/diagnostics/classes/log_record_route_filter.py +++ b/src/sqlbuild/diagnostics/classes/log_record_route_filter.py @@ -17,12 +17,14 @@ def __init__( allow_internal: bool, include_sql_text: bool, summarize_third_party: bool = False, + project_roots: tuple[str, ...] = (), ) -> None: super().__init__() self._internal_only: bool = internal_only self._allow_internal: bool = allow_internal self._include_sql_text: bool = include_sql_text self._summarize_third_party: bool = summarize_third_party + self._project_roots: tuple[str, ...] = project_roots def filter(self, record: logging.LogRecord) -> logging.LogRecord | bool: """Return a safe copy when the record belongs at this destination.""" @@ -33,6 +35,7 @@ def filter(self, record: logging.LogRecord) -> logging.LogRecord | bool: allow_internal=self._allow_internal, include_sql_text=self._include_sql_text, summarize_third_party=self._summarize_third_party, + project_roots=self._project_roots, ) if values is None: return False diff --git a/src/sqlbuild/diagnostics/main/configure.py b/src/sqlbuild/diagnostics/main/configure.py index a3e1fab6f8..186db19de6 100644 --- a/src/sqlbuild/diagnostics/main/configure.py +++ b/src/sqlbuild/diagnostics/main/configure.py @@ -11,6 +11,7 @@ def configure_diagnostics( debug: bool, use_color: bool = False, invocation_id: str = "programmatic", + project_roots: tuple[str, ...] = (), ) -> InvocationDiagnosticRouting: """Create an explicit scoped diagnostic routing context.""" @@ -19,5 +20,6 @@ def configure_diagnostics( options=DiagnosticRoutingOptions( debug_console=debug, use_color=use_color, + project_roots=project_roots, ), ) diff --git a/src/sqlbuild/diagnostics/main/diagnostic_project_roots.py b/src/sqlbuild/diagnostics/main/diagnostic_project_roots.py new file mode 100644 index 0000000000..d5fc11e4b3 --- /dev/null +++ b/src/sqlbuild/diagnostics/main/diagnostic_project_roots.py @@ -0,0 +1,12 @@ +"""Project roots whose files log as project code rather than as installed libraries.""" + +from __future__ import annotations + +import os +from pathlib import Path + + +def diagnostic_project_roots(*, project_dir: Path) -> tuple[str, ...]: + """The project directory as given and resolved, whose files log as project code.""" + + return tuple(dict.fromkeys((os.path.abspath(project_dir), str(project_dir.resolve())))) diff --git a/src/sqlbuild/diagnostics/models.py b/src/sqlbuild/diagnostics/models.py index 8459b36f3d..8ed5e24a11 100644 --- a/src/sqlbuild/diagnostics/models.py +++ b/src/sqlbuild/diagnostics/models.py @@ -22,3 +22,4 @@ class DiagnosticRoutingOptions: debug_console: bool = False use_color: bool = False include_sql_text: bool = False + project_roots: tuple[str, ...] = () diff --git a/tests/integration/src/sqlbuild/cli/recall/_test_types.py b/tests/integration/src/sqlbuild/cli/recall/_test_types.py index cf373b1ec6..061f25f5ca 100644 --- a/tests/integration/src/sqlbuild/cli/recall/_test_types.py +++ b/tests/integration/src/sqlbuild/cli/recall/_test_types.py @@ -199,3 +199,4 @@ class ThirdPartyLogTestCase: build_arguments: tuple[str, ...] expected_present: tuple[str, ...] expected_absent: tuple[str, ...] + expected_traceback_count: int diff --git a/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py index 1853f1c97f..7aeb3813a8 100644 --- a/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py +++ b/tests/integration/src/sqlbuild/cli/recall/test_third_party_logs.py @@ -1,4 +1,4 @@ -"""Third-party library logs during a command: what the console shows and what Recall keeps.""" +"""Library and project logs during a command: what the console shows and what Recall keeps.""" import subprocess from pathlib import Path @@ -8,12 +8,10 @@ from tests.integration.src.sqlbuild.cli.recall._test_types import ThirdPartyLogTestCase from tests.integration.src.sqlbuild.cli.recall.helpers import recall_rows, run, write_project -VENDOR_TASK: str = ( - '"""A task whose client library logs while it runs."""\n\n' - "import logging\n\n" - "from sqlbuild.tasks import task\n\n\n" - "@task()\n" - "def sync_orders(ctx):\n" +VENDOR_MODULE: str = ( + '"""A client library installed outside the project."""\n\n' + "import logging\n\n\n" + "def sync_orders():\n" ' """Log like a client library: progress, then a recovered failure."""\n\n' ' logger = logging.getLogger("vendor.client")\n' ' logger.info("connecting to the orders service")\n' @@ -21,7 +19,27 @@ ' raise RuntimeError("token expired")\n' " except RuntimeError:\n" ' logger.warning("token refresh failed", exc_info=True)\n' - " return ctx.result()\n" +) +PROJECT_HOOK: str = ( + '"""A project hook that logs and calls the client library."""\n\n' + "import logging\n\n" + "import vendor_client\n\n" + "from sqlbuild.hooks import hook\n\n\n" + "@hook\n" + "def sync_orders(ctx):\n" + ' """Log progress and a recovered failure, then sync through the library."""\n\n' + ' logger = logging.getLogger("orders_shop.sync")\n' + ' logger.info("starting the orders sync")\n' + " try:\n" + ' raise ValueError("stale cursor")\n' + " except ValueError:\n" + ' logger.warning("retrying the orders sync", exc_info=True)\n' + " vendor_client.sync_orders()\n" +) +ORDERS_MODEL: str = ( + 'MODEL (\n description "One row per order",\n materialized table,\n' + ' post_hooks [python("sync_orders")]\n);\n\n' + "SELECT 1 AS order_id, CAST('2026-04-01' AS DATE) AS ordered_on\n" ) TRACEBACK: str = "Traceback (most recent call last):" @@ -30,36 +48,53 @@ "test_case", ( ThirdPartyLogTestCase( - description="normal output hides INFO and shows the warning as one line", + description="normal output keeps project logs and summarises the library", build_arguments=("build",), - expected_present=("[warning] vendor.client token refresh failed",), - expected_absent=("connecting to the orders service", TRACEBACK, "token expired"), + expected_present=( + "[info] orders_shop.sync starting the orders sync", + "[warning] orders_shop.sync retrying the orders sync", + "ValueError: stale cursor", + "[warning] vendor.client token refresh failed", + ), + expected_absent=("connecting to the orders service", "RuntimeError: token expired"), + expected_traceback_count=1, ), ThirdPartyLogTestCase( description="debug output shows every record with its traceback", build_arguments=("--debug", "build"), expected_present=( + "[info] orders_shop.sync starting the orders sync", + "ValueError: stale cursor", "[info] vendor.client connecting to the orders service", "[warning] vendor.client token refresh failed", - TRACEBACK, "RuntimeError: token expired", ), expected_absent=(), + expected_traceback_count=2, ), ), ids=lambda case: case.description, ) -def test_given_library_logs_during_build_when_running_then_console_is_quiet_and_recall_keeps_all( +def test_given_project_and_library_logs_during_build_when_running_then_only_library_is_quiet( test_case: ThirdPartyLogTestCase, tmp_path: Path ) -> None: project_dir: Path = write_project(tmp_path / "orders_shop") - (project_dir / "python" / "tasks" / "emit.py").write_text(VENDOR_TASK, encoding="utf-8") + (project_dir / "models" / "orders.sql").write_text(ORDERS_MODEL, encoding="utf-8") + hook_path: Path = project_dir / "hooks" / "python" / "sync.py" + hook_path.parent.mkdir(parents=True) + hook_path.write_text(PROJECT_HOOK, encoding="utf-8") + library_dir: Path = tmp_path / "installed" + library_dir.mkdir() + (library_dir / "vendor_client.py").write_text(VENDOR_MODULE, encoding="utf-8") - built: subprocess.CompletedProcess[bytes] = run(project_dir, *test_case.build_arguments) + built: subprocess.CompletedProcess[bytes] = run( + project_dir, *test_case.build_arguments, PYTHONPATH=str(library_dir) + ) stderr: str = built.stderr.decode(errors="replace") assert built.returncode == 0, stderr assert stderr.count("[warning] vendor.client token refresh failed") == 1, stderr + assert stderr.count(TRACEBACK) == test_case.expected_traceback_count, stderr fragment: str for fragment in test_case.expected_present: assert fragment in stderr, stderr @@ -67,11 +102,15 @@ def test_given_library_logs_during_build_when_running_then_console_is_quiet_and_ assert fragment not in stderr, stderr rows: list[list[object]] = recall_rows( project_dir, - "SELECT severity, message FROM diagnostics " - "WHERE logger = 'vendor.client' ORDER BY occurred_at", + "SELECT logger, severity, message FROM diagnostics " + "WHERE logger IN ('vendor.client', 'orders_shop.sync') ORDER BY occurred_at", ) - assert [row[0] for row in rows] == ["info", "warning"] - assert rows[0][1] == "connecting to the orders service" - warning: str = str(rows[1][1]) - assert warning.startswith("token refresh failed\n" + TRACEBACK), warning - assert "RuntimeError: token expired" in warning + assert [row[:2] for row in rows] == [ + ["orders_shop.sync", "info"], + ["orders_shop.sync", "warning"], + ["vendor.client", "info"], + ["vendor.client", "warning"], + ] + assert str(rows[1][2]).startswith("retrying the orders sync\n" + TRACEBACK) + assert str(rows[3][2]).startswith("token refresh failed\n" + TRACEBACK) + assert "RuntimeError: token expired" in str(rows[3][2]) diff --git a/tests/unit/src/sqlbuild/diagnostics/_test_types.py b/tests/unit/src/sqlbuild/diagnostics/_test_types.py index 7b6b6bcd6e..160a43ff8f 100644 --- a/tests/unit/src/sqlbuild/diagnostics/_test_types.py +++ b/tests/unit/src/sqlbuild/diagnostics/_test_types.py @@ -53,3 +53,10 @@ class ConsoleProgressLineTestCase: description: str message: str expected_log_line: str + + +@dataclass(frozen=True) +class SpinnerReuseTestCase: + description: str + record_count: int + expected_spinner_threads: int diff --git a/tests/unit/src/sqlbuild/diagnostics/helpers.py b/tests/unit/src/sqlbuild/diagnostics/helpers.py index 604896735d..fe27b8b3d4 100644 --- a/tests/unit/src/sqlbuild/diagnostics/helpers.py +++ b/tests/unit/src/sqlbuild/diagnostics/helpers.py @@ -1,4 +1,5 @@ import logging +import threading class HostRecordingLogHandler(logging.Handler): @@ -25,3 +26,12 @@ def log_vendor_records() -> None: except RuntimeError: logger.warning("token refresh failed\nretrying with fallback", exc_info=True) logger.error("orders service rejected the request", exc_info=True) + + +SPINNER_THREAD_NAME: str = "sqlbuild-progress-spinner" + + +def spinner_threads() -> list[threading.Thread]: + """The live progress spinner threads.""" + + return list(filter(lambda thread: thread.name == SPINNER_THREAD_NAME, threading.enumerate())) diff --git a/tests/unit/src/sqlbuild/diagnostics/test_main.py b/tests/unit/src/sqlbuild/diagnostics/test_main.py index 5351745d31..31f796adec 100644 --- a/tests/unit/src/sqlbuild/diagnostics/test_main.py +++ b/tests/unit/src/sqlbuild/diagnostics/test_main.py @@ -4,6 +4,7 @@ import logging import sys +import threading from pathlib import Path import pytest @@ -17,9 +18,14 @@ ConsoleProgressLineTestCase, DiagnosticsContextualSqlTestCase, DiagnosticsLogTestCase, + SpinnerReuseTestCase, ThirdPartyConsoleTestCase, ) -from tests.unit.src.sqlbuild.diagnostics.helpers import HostRecordingLogHandler, log_vendor_records +from tests.unit.src.sqlbuild.diagnostics.helpers import ( + HostRecordingLogHandler, + log_vendor_records, + spinner_threads, +) from tests.unit.src.sqlbuild.presentation.classes.helpers import RecordingStream _CLEAR_LINE: str = "\r\x1b[K" @@ -136,6 +142,40 @@ def test_given_live_status_line_when_logging_then_line_is_cleared_before_record( assert any(test_case.message in event for event in events[log_index + 1 :]), events +@pytest.mark.parametrize( + "test_case", + ( + SpinnerReuseTestCase( + description="debug records around one status line reuse its spinner thread", + record_count=200, + expected_spinner_threads=1, + ), + ), + ids=lambda case: case.description, +) +def test_given_many_records_during_status_line_when_logging_then_one_spinner_thread_runs( + test_case: SpinnerReuseTestCase, + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.delenv("SQLBUILD_NO_PROGRESS", raising=False) + stream: RecordingStream = RecordingStream(events=[], tty=True) + monkeypatch.setattr(sys, "stderr", stream) + reporter: TransientStatusReporter = TransientStatusReporter(stream=stream, use_color=False) + seen: list[threading.Thread] = [] + reporter.start("Preparing clone plan...") + try: + with configure_diagnostics(debug=True): + for index in range(test_case.record_count): + logging.getLogger("vendor.client").warning("retrying request %d", index) + seen.extend(spinner_threads()) + finally: + reporter.close() + + assert len({id(thread) for thread in seen}) == test_case.expected_spinner_threads + assert spinner_threads() == [] + assert stream.getvalue().count("retrying request") == test_case.record_count + + @pytest.mark.parametrize( "test_case", [ diff --git a/website/src/content/docs/docs/cli/clone.mdx b/website/src/content/docs/docs/cli/clone.mdx index 446ca3b1fd..c4fc6302c0 100644 --- a/website/src/content/docs/docs/cli/clone.mdx +++ b/website/src/content/docs/docs/cli/clone.mdx @@ -19,6 +19,10 @@ SQLBuild never resolves or opens the origin target's connection, including for d deferred clone. Clone cannot perform a cross-account, cross-server, or cross-file transfer by opening a second connection. +Clone never runs SQL analysis: it reads relation names, dependencies, and rendered view and +function SQL from each target's project, and reports no compile diagnostics. The hidden +`--no-sql-analysis` flag (alias `--no-sql-validation`) is still accepted but has no effect. + ## Usage ```bash @@ -32,7 +36,6 @@ sqb --project-dir clone --from [--to ] [flags] | `--from` | Source target (required) | | `--to` | Destination target; defaults to the active target | | `--hard-copy` | Force physical table copies instead of zero-copy cloning | -| `--no-sql-analysis` | Disable compile-time SQL analysis (`--no-sql-validation` is an alias) | | `--select`, `-s` | Select specific models to clone | | `--exclude` | Exclude specific models from cloning | | `--warehouse ` | Snowflake warehouse for this invocation; overrides the target's `build` [warehouse group](/docs/concepts/project-configuration#command-group-warehouses) and the connection warehouse | From 3a36b5b2d357fa0ddcdf57ca72e3f609644a6daa Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 16:34:10 +0100 Subject: [PATCH 6/7] docs: say which clone errors still stop it --- .../.agents/skills/sqlbuild/references/docs/cli/clone.md | 5 +++-- website/src/content/docs/docs/cli/clone.mdx | 5 +++-- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md b/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md index f4fd87f0d8..ac85f9beec 100644 --- a/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md +++ b/src/sqlbuild/.agents/skills/sqlbuild/references/docs/cli/clone.md @@ -21,8 +21,9 @@ deferred clone. Clone cannot perform a cross-account, cross-server, or cross-fil transfer by opening a second connection. Clone never runs SQL analysis: it reads relation names, dependencies, and rendered view and -function SQL from each target's project, and reports no compile diagnostics. The hidden -`--no-sql-analysis` flag (alias `--no-sql-validation`) is still accepted but has no effect. +function SQL from each target's project, so SQL analysis errors never stop it; structural errors, +such as an unknown reference, still do. The hidden `--no-sql-analysis` flag (alias +`--no-sql-validation`) is still accepted but has no effect. ## Usage diff --git a/website/src/content/docs/docs/cli/clone.mdx b/website/src/content/docs/docs/cli/clone.mdx index c4fc6302c0..af79602e17 100644 --- a/website/src/content/docs/docs/cli/clone.mdx +++ b/website/src/content/docs/docs/cli/clone.mdx @@ -20,8 +20,9 @@ deferred clone. Clone cannot perform a cross-account, cross-server, or cross-fil transfer by opening a second connection. Clone never runs SQL analysis: it reads relation names, dependencies, and rendered view and -function SQL from each target's project, and reports no compile diagnostics. The hidden -`--no-sql-analysis` flag (alias `--no-sql-validation`) is still accepted but has no effect. +function SQL from each target's project, so SQL analysis errors never stop it; structural errors, +such as an unknown reference, still do. The hidden `--no-sql-analysis` flag (alias +`--no-sql-validation`) is still accepted but has no effect. ## Usage From 15a1e6141a8769b55b0643bdbc03973c8f4fcad3 Mon Sep 17 00:00:00 2001 From: Kevin Longe <273747162+kvlonge@users.noreply.github.com> Date: Tue, 20 Oct 2026 17:19:30 +0100 Subject: [PATCH 7/7] test: log the CLI user family from a project file Records logged from outside the project now count as library output, so the user family in the stdout-purity test comes from a module inside the test project. --- .../cli/commands/main/entry/helpers.py | 27 +++++++++++++++++++ .../main/entry/test_compute_capture.py | 16 ++++++----- 2 files changed, 36 insertions(+), 7 deletions(-) diff --git a/tests/unit/src/sqlbuild/cli/commands/main/entry/helpers.py b/tests/unit/src/sqlbuild/cli/commands/main/entry/helpers.py index 6821a4d2f6..c8e6d04851 100644 --- a/tests/unit/src/sqlbuild/cli/commands/main/entry/helpers.py +++ b/tests/unit/src/sqlbuild/cli/commands/main/entry/helpers.py @@ -2,8 +2,11 @@ from __future__ import annotations +import importlib.util from collections.abc import Callable +from importlib.machinery import ModuleSpec from pathlib import Path +from types import ModuleType from typing import Any, Protocol, cast from sqlbuild._native import ( @@ -88,3 +91,27 @@ def build_handlers(**overrides: Any) -> CliEntrypointHandlers: run_rules=overrides.get("run_rules", noop_handler), run_scope=overrides.get("run_scope", noop_handler), ) + + +PROJECT_LOGGING_MODULE: str = """import logging + + +def log_user_messages() -> None: + logger = logging.getLogger("project.cli") + prior_level = logger.level + logger.setLevel(logging.DEBUG) + logger.debug("CLI user debug") + logger.info("CLI user info") + logger.setLevel(prior_level) +""" + + +def load_project_module(path: Path) -> ModuleType: + """Import a project file so its log records come from inside the project directory.""" + + spec: ModuleSpec | None = importlib.util.spec_from_file_location(path.stem, path) + assert spec is not None + assert spec.loader is not None + module: ModuleType = importlib.util.module_from_spec(spec) + spec.loader.exec_module(module) + return module diff --git a/tests/unit/src/sqlbuild/cli/commands/main/entry/test_compute_capture.py b/tests/unit/src/sqlbuild/cli/commands/main/entry/test_compute_capture.py index a01f30c0e6..cf76a5b9db 100644 --- a/tests/unit/src/sqlbuild/cli/commands/main/entry/test_compute_capture.py +++ b/tests/unit/src/sqlbuild/cli/commands/main/entry/test_compute_capture.py @@ -1,6 +1,7 @@ import json import logging from pathlib import Path +from types import ModuleType from unittest.mock import Mock, patch import pytest @@ -17,7 +18,11 @@ MainTestCase, ProjectCreationRoutingTestCase, ) -from tests.unit.src.sqlbuild.cli.commands.main.entry.helpers import build_handlers +from tests.unit.src.sqlbuild.cli.commands.main.entry.helpers import ( + PROJECT_LOGGING_MODULE, + build_handlers, + load_project_module, +) @pytest.mark.parametrize( @@ -181,6 +186,7 @@ def test_given_machine_json_and_all_log_families_when_cli_runs_then_stdout_remai capsys: pytest.CaptureFixture[str], ) -> None: private_sql: str = "SELECT 'cli-private-sql'" + _ = (tmp_path / "project_logging.py").write_text(PROJECT_LOGGING_MODULE, encoding="utf-8") def run_compile(_request: CompileCommandRequest) -> int: logging.getLogger("sqlbuild.cli.matrix").debug("plain CLI internal") @@ -189,12 +195,8 @@ def run_compile(_request: CompileCommandRequest) -> int: message="structured CLI internal", sqlbuild_channel="cli_matrix", ) - user_logger: logging.Logger = logging.getLogger("project.cli") - prior_level: int = user_logger.level - user_logger.setLevel(logging.DEBUG) - user_logger.debug("CLI user debug") - user_logger.info("CLI user info") - user_logger.setLevel(prior_level) + project_module: ModuleType = load_project_module(tmp_path / "project_logging.py") + project_module.log_user_messages() log_sql(logger=logging.getLogger("sqlbuild.cli.matrix"), sql=private_sql) print(json.dumps({"status": "ok"}, separators=(",", ":"))) return test_case.expected_exit_code