diff --git a/docs/src/content/docs/cli/test-compare.mdx b/docs/src/content/docs/cli/test-compare.mdx index 4cfb9db..7d9bc43 100644 --- a/docs/src/content/docs/cli/test-compare.mdx +++ b/docs/src/content/docs/cli/test-compare.mdx @@ -21,9 +21,11 @@ Runs tests and compares their output against saved expected results, reporting a For each test: -1. Runs the test and captures output -2. Compares output to the `expected` file in the test directory -3. Reports differences (if any) +1. Runs the test, capturing stdout and stderr separately +2. Compares stdout to the `expected` file and stderr to the `expected_stderr` file in the test directory +3. Reports differences (if any), labeled by stream + +A test fails if either stream differs from its expected file. Comparing the streams separately avoids flaky diffs from stdout/stderr interleaving, since the operating system does not guarantee their relative ordering when captured independently. Use [`spawn test expect`](/cli/test-expect/) to update the expected output. diff --git a/docs/src/content/docs/cli/test-expect.mdx b/docs/src/content/docs/cli/test-expect.mdx index 82bc5cf..dd3474e 100644 --- a/docs/src/content/docs/cli/test-expect.mdx +++ b/docs/src/content/docs/cli/test-expect.mdx @@ -20,8 +20,8 @@ Runs a test and saves its output as the new expected result for future compariso ## Behavior 1. Runs the specified test -2. Captures the output -3. Writes it to `tests//expected.txt` +2. Captures stdout and stderr separately +3. Writes them to `tests//expected` and `tests//expected_stderr` respectively Use this command when test behavior changes intentionally and you want to update the baseline for [`spawn test compare`](/cli/test-compare/). diff --git a/docs/src/content/docs/cli/test-run.mdx b/docs/src/content/docs/cli/test-run.mdx index a3bd3c3..35d38b3 100644 --- a/docs/src/content/docs/cli/test-run.mdx +++ b/docs/src/content/docs/cli/test-run.mdx @@ -19,7 +19,7 @@ Executes one or all tests against the configured database and displays the resul ## Behavior -Runs the SQL for the test against the database, showing the output from that test. +Runs the SQL for the test against the database, showing the output from that test. Stdout is printed first; if the test produced any stderr output (e.g. `NOTICE`/`ERROR` messages from psql), it is shown afterward under a `--- stderr ---` separator. ## Examples diff --git a/src/commands/test/compare.rs b/src/commands/test/compare.rs index bf8d97c..bbeb56f 100644 --- a/src/commands/test/compare.rs +++ b/src/commands/test/compare.rs @@ -46,15 +46,21 @@ impl Command for CompareTests { let tester = Tester::new(config, &test_file); match tester.run_compare(None).await { - Ok(result) => match result.diff { - None => { + Ok(result) => match (&result.stdout_diff, &result.stderr_diff) { + (None, None) => { println!("{}[PASS]{} {}", GREEN, RESET, test_file); } - Some(diff) => { + (stdout_diff, stderr_diff) => { failed = true; println!("\n{}[FAIL]{} {}{}{}", RED, RESET, BOLD, test_file, RESET); - println!("{}--- Diff ---{}", BOLD, RESET); - println!("{}", diff); + if let Some(diff) = stdout_diff { + println!("{}--- stdout diff ---{}", BOLD, RESET); + println!("{}", diff); + } + if let Some(diff) = stderr_diff { + println!("{}--- stderr diff ---{}", BOLD, RESET); + println!("{}", diff); + } println!("{}-------------{}\n", BOLD, RESET); } }, diff --git a/src/commands/test/run.rs b/src/commands/test/run.rs index e95acaa..bb52de1 100644 --- a/src/commands/test/run.rs +++ b/src/commands/test/run.rs @@ -37,7 +37,11 @@ impl Command for RunTest { for test_name in test_names { let tester = Tester::new(config, &test_name); let result = tester.run(None).await?; - println!("{}", result); + println!("{}", result.stdout); + if !result.stderr.is_empty() { + println!("--- stderr ---"); + println!("{}", result.stderr); + } } Ok(Outcome::Success) diff --git a/src/engine/mod.rs b/src/engine/mod.rs index 17cb180..a53dfe7 100644 --- a/src/engine/mod.rs +++ b/src/engine/mod.rs @@ -313,16 +313,15 @@ pub trait Engine: Send + Sync { /// Execute SQL by running the provided writer function. /// - `write_fn`: Closure that writes SQL to the provided Write handle /// - `stdout_writer`: Optional writer to capture stdout. If None, stdout is discarded. - /// - `merge_stderr`: If true and stdout_writer is Some, stderr is merged into stdout - /// at the OS level for true interleaving. Useful for tests. - /// Note: when merged, stderr is not separately available in errors. + /// - `stderr_writer`: Optional writer to capture stderr. If None, stderr is only + /// captured internally for the `ExecutionFailed` error case. /// Engine-specific setup (like psql flags) is handled internally. /// Returns stderr content on failure. async fn execute_with_writer( &self, write_fn: WriterFn, stdout_writer: StdoutWriter, - merge_stderr: bool, + stderr_writer: StdoutWriter, ) -> Result<(), EngineError>; async fn migration_apply( diff --git a/src/engine/postgres_psql.rs b/src/engine/postgres_psql.rs index 65d3f26..943b65a 100644 --- a/src/engine/postgres_psql.rs +++ b/src/engine/postgres_psql.rs @@ -172,88 +172,48 @@ impl Engine for PSQL { &self, write_fn: WriterFn, stdout_writer: StdoutWriter, - merge_stderr: bool, + stderr_writer: StdoutWriter, ) -> Result<(), EngineError> { // 1. Create the pipe for stdin let (reader, mut writer) = std::io::pipe()?; // 2. Configure stdout/stderr and spawn psql - // - // When merge_stderr is true, we create our own pipe and give the - // write end to both stdout and stderr so the OS interleaves them. - // Otherwise, stdout is piped (or null) and stderr is piped separately. - let merge = merge_stderr && stdout_writer.is_some(); - - let (mut child, combined_read) = if merge { - let (out_read, out_write) = std::io::pipe()?; - let out_write_dup = out_write.try_clone()?; - let child = Command::new(&self.psql_command[0]) - .args(&self.psql_command[1..]) - .stdin(Stdio::from(reader)) - .stdout(Stdio::from(out_write)) - .stderr(Stdio::from(out_write_dup)) - .spawn() - .map_err(EngineError::Io)?; - (child, Some(out_read)) + let stdout_config = if stdout_writer.is_some() { + Stdio::piped() } else { - let stdout_config = if stdout_writer.is_some() { - Stdio::piped() - } else { - Stdio::null() - }; - let child = Command::new(&self.psql_command[0]) - .args(&self.psql_command[1..]) - .stdin(Stdio::from(reader)) - .stdout(stdout_config) - .stderr(Stdio::piped()) - .spawn() - .map_err(EngineError::Io)?; - (child, None) + Stdio::null() }; + let mut child = Command::new(&self.psql_command[0]) + .args(&self.psql_command[1..]) + .stdin(Stdio::from(reader)) + .stdout(stdout_config) + .stderr(Stdio::piped()) + .spawn() + .map_err(EngineError::Io)?; // 3. Copy output to stdout_writer if provided let stdout_handle = if let Some(mut stdout_dest) = stdout_writer { - if let Some(mut combined_read) = combined_read { - // Merged mode: read from our combined pipe in a blocking - // thread (it's a std::io::PipeReader, not a tokio type), - // then write to the async destination. - Some(tokio::task::spawn(async move { - let buf = tokio::task::spawn_blocking(move || { - use std::io::Read; - let mut buf = Vec::new(); - let _ = combined_read.read_to_end(&mut buf); - buf - }) - .await - .unwrap_or_default(); - use tokio::io::AsyncWriteExt; - let _ = stdout_dest.write_all(&buf).await; - })) - } else { - let mut stdout = child.stdout.take().expect("stdout should be piped"); - Some(tokio::task::spawn(async move { - use tokio::io::AsyncWriteExt; - let mut buf = Vec::new(); - let _ = stdout.read_to_end(&mut buf).await; - let _ = stdout_dest.write_all(&buf).await; - })) - } - } else { - None - }; - - // 4. Drain stderr in background (prevents deadlock). - // When merged, child.stderr is None (it shares the stdout pipe). - let stderr_handle = if let Some(mut stderr) = child.stderr.take() { - Some(tokio::spawn(async move { + let mut stdout = child.stdout.take().expect("stdout should be piped"); + Some(tokio::task::spawn(async move { + use tokio::io::AsyncWriteExt; let mut buf = Vec::new(); - let _ = stderr.read_to_end(&mut buf).await; - buf + let _ = stdout.read_to_end(&mut buf).await; + let _ = stdout_dest.write_all(&buf).await; })) } else { None }; + // 4. Drain stderr in background (prevents deadlock). It's always + // captured to a buffer so it's available for the ExecutionFailed + // error case, and additionally forwarded to stderr_writer below. + let mut stderr = child.stderr.take().expect("stderr should be piped"); + let stderr_handle = tokio::spawn(async move { + let mut buf = Vec::new(); + let _ = stderr.read_to_end(&mut buf).await; + buf + }); + // 5. Run the writer function in a blocking thread let writer_handle = tokio::task::spawn_blocking(move || -> std::io::Result<()> { // PSQL-specific setup - QUIET must be first to suppress output from other settings @@ -280,10 +240,12 @@ impl Engine for PSQL { // 8. Wait for psql and check result let status = child.wait().await?; - let stderr_bytes = match stderr_handle { - Some(handle) => handle.await.unwrap_or_default(), - None => Vec::new(), - }; + let stderr_bytes = stderr_handle.await.unwrap_or_default(); + + if let Some(mut sink) = stderr_writer { + use tokio::io::AsyncWriteExt; + let _ = sink.write_all(&stderr_bytes).await; + } if !status.success() { return Err(EngineError::ExecutionFailed { @@ -645,7 +607,7 @@ impl PSQL { Ok(()) }), Some(Box::new(SharedBufWriter(stdout_buf_clone))), - false, // Don't merge stderr for internal queries + None, // Not capturing stderr for internal queries ) .await .map_err(|e| anyhow!("SQL execution failed: {}", e))?; @@ -808,7 +770,7 @@ impl PSQL { Ok(()) }), None, - false, // Don't merge stderr for recording migrations + None, // Not capturing stderr for recording migrations ) .await .map_err(|e| match e { @@ -908,7 +870,7 @@ impl PSQL { Ok(()) }), None, - false, // Don't merge stderr for migration apply + None, // Not capturing stderr for migration apply ) .await; diff --git a/src/sqltest/mod.rs b/src/sqltest/mod.rs index 53733d1..dc1f719 100644 --- a/src/sqltest/mod.rs +++ b/src/sqltest/mod.rs @@ -21,7 +21,15 @@ pub struct Tester { #[derive(Debug)] pub struct TestOutcome { - pub diff: Option, + pub stdout_diff: Option, + pub stderr_diff: Option, +} + +/// Captured output of a test run, split by stream. +#[derive(Debug)] +pub struct TestOutput { + pub stdout: String, + pub stderr: String, } impl Tester { @@ -49,6 +57,10 @@ impl Tester { format!("{}/expected", self.test_folder()) } + pub fn expected_stderr_file_path(&self) -> String { + format!("{}/expected_stderr", self.test_folder()) + } + /// Opens the specified script file and generates a test script, compiled /// using minijinja. pub async fn generate(&self, variables: Option) -> Result { @@ -71,14 +83,16 @@ impl Tester { } // Runs the test and compares the actual output to expected. - pub async fn run(&self, variables: Option) -> Result { + pub async fn run(&self, variables: Option) -> Result { let content = self.generate(variables.clone()).await?; let engine = self.config.new_engine().await?; - // Create a shared buffer to capture stdout + // Create shared buffers to capture stdout and stderr independently. let stdout_buf = Arc::new(Mutex::new(Vec::new())); let stdout_buf_clone = stdout_buf.clone(); + let stderr_buf = Arc::new(Mutex::new(Vec::new())); + let stderr_buf_clone = stderr_buf.clone(); match engine .execute_with_writer( @@ -87,45 +101,54 @@ impl Tester { Ok(()) }), Some(Box::new(SharedBufWriter(stdout_buf_clone))), - true, // Merge stderr into stdout for tests + Some(Box::new(SharedBufWriter(stderr_buf_clone))), ) .await { Ok(()) => {} Err(EngineError::ExecutionFailed { .. }) => { // psql exited non-zero (e.g. ON_ERROR_STOP triggered). - // The combined output buffer already has the error output, + // The stderr buffer already has the error output, // so we just continue and return it. } Err(e) => return Err(e).context("failed to write content to test db"), } - let buf = stdout_buf.lock().unwrap(); - let generated = String::from_utf8_lossy(&buf).to_string(); + let stdout = String::from_utf8_lossy(&stdout_buf.lock().unwrap()).to_string(); + let stderr = String::from_utf8_lossy(&stderr_buf.lock().unwrap()).to_string(); - Ok(generated) + Ok(TestOutput { stdout, stderr }) } pub async fn run_compare( &self, variables: Option, ) -> Result { - let generated = self.run(variables).await?; + let output = self.run(variables).await?; + let expected_bytes = self .config .operator() .read(&self.expected_file_path()) .await - .context("unable to read expectations file")? + .context("unable to read expected file")? .to_bytes(); - let expected = String::from_utf8(expected_bytes.to_vec()) + let expected_stdout = String::from_utf8(expected_bytes.to_vec()) .context("expected file is not valid UTF-8")?; - let outcome = match self.compare(&generated, &expected) { - Ok(()) => TestOutcome { diff: None }, - Err(differences) => TestOutcome { - diff: Some(differences.to_string()), - }, + let expected_stderr_bytes = self + .config + .operator() + .read(&self.expected_stderr_file_path()) + .await + .context("unable to read expected_stderr file")? + .to_bytes(); + let expected_stderr = String::from_utf8(expected_stderr_bytes.to_vec()) + .context("expected_stderr file is not valid UTF-8")?; + + let outcome = TestOutcome { + stdout_diff: Self::diff(&expected_stdout, &output.stdout).err(), + stderr_diff: Self::diff(&expected_stderr, &output.stderr).err(), }; Ok(outcome) @@ -135,12 +158,17 @@ impl Tester { &self, variables: Option, ) -> Result<()> { - let content = self.run(variables).await?; + let output = self.run(variables).await?; + self.config + .operator() + .write(&self.expected_file_path(), output.stdout) + .await + .context("unable to write expected file")?; self.config .operator() - .write(&self.expected_file_path(), content) + .write(&self.expected_stderr_file_path(), output.stderr) .await - .context("unable to write expectation file")?; + .context("unable to write expected_stderr file")?; Ok(()) } @@ -157,7 +185,7 @@ impl Tester { Ok(self.script_path.clone()) } - pub fn compare(&self, generated: &str, expected: &str) -> std::result::Result<(), String> { + fn diff(expected: &str, generated: &str) -> std::result::Result<(), String> { let diff = TextDiff::from_lines(expected, generated); let mut diff_display = String::new(); diff --git a/static/example/tests/20250607115200-example-test/expected_stderr b/static/example/tests/20250607115200-example-test/expected_stderr new file mode 100644 index 0000000..e69de29 diff --git a/static/example/tests/20250607115201-example-test/expected_stderr b/static/example/tests/20250607115201-example-test/expected_stderr new file mode 100644 index 0000000..e69de29 diff --git a/static/tests/test_cli_test/tests/20250113000000-simple-test/expected_stderr b/static/tests/test_cli_test/tests/20250113000000-simple-test/expected_stderr new file mode 100644 index 0000000..e69de29 diff --git a/static/tests/test_cli_test/tests/20250113000001-notice-test/expected b/static/tests/test_cli_test/tests/20250113000001-notice-test/expected new file mode 100644 index 0000000..346db02 --- /dev/null +++ b/static/tests/test_cli_test/tests/20250113000001-notice-test/expected @@ -0,0 +1,10 @@ +CREATE DATABASE +You are now connected to database "testclitestnotice" as user "spawn". +DROP TABLE + ok +---- + 1 +(1 row) + +You are now connected to database "postgres" as user "spawn". +DROP DATABASE diff --git a/static/tests/test_cli_test/tests/20250113000001-notice-test/expected_stderr b/static/tests/test_cli_test/tests/20250113000001-notice-test/expected_stderr new file mode 100644 index 0000000..ff8266f --- /dev/null +++ b/static/tests/test_cli_test/tests/20250113000001-notice-test/expected_stderr @@ -0,0 +1 @@ +NOTICE: table "nonexistent_table_xyz" does not exist, skipping diff --git a/static/tests/test_cli_test/tests/20250113000001-notice-test/test.sql b/static/tests/test_cli_test/tests/20250113000001-notice-test/test.sql new file mode 100644 index 0000000..231bc69 --- /dev/null +++ b/static/tests/test_cli_test/tests/20250113000001-notice-test/test.sql @@ -0,0 +1,8 @@ +\set QUIET off +{% set dbname = "testclitestnotice" %} +create database {{dbname|escape_identifier}} with template spawn; +\c {{dbname|escape_identifier}} +drop table if exists nonexistent_table_xyz; +select 1 as ok; +\c postgres +drop database {{dbname|escape_identifier}}; diff --git a/tests/integration_postgres.rs b/tests/integration_postgres.rs index 40e0174..0b209ab 100644 --- a/tests/integration_postgres.rs +++ b/tests/integration_postgres.rs @@ -1381,6 +1381,76 @@ async fn test_cli_test_compare() -> Result<()> { Ok(()) } +/// Companion to `test_cli_test_compare` that exercises the split stderr +/// comparison specifically: the `20250113000001-notice-test` fixture has a +/// non-empty `expected_stderr` (a `NOTICE` from `DROP TABLE IF EXISTS` on a +/// table that doesn't exist), and this confirms a stderr-only regression +/// (stdout output unchanged) is still caught by `spawn test compare`. +#[tokio::test] +#[ignore] +async fn test_cli_test_compare_with_stderr() -> Result<()> { + require_postgres()?; + + let helper = IntegrationTestHelper::new( + "test_cli_test_compare_with_stderr", + Some("./static/tests/test_cli_test"), + ) + .await?; + + let test_name = "20250113000001-notice-test".to_string(); + + // Run compare - it should pass against the checked-in fixture, whose + // expected_stderr is non-empty. + helper.run_test_compare(Some(test_name.clone())).await?; + + // Change only the table name in the DROP TABLE IF EXISTS statement. This + // changes the NOTICE text (stderr) while leaving stdout's shape (command + // tags, result rows) identical, isolating a stderr-only diff. + let new_test = r#"\set QUIET off +{% set dbname = "testclitestnotice" %} +create database {{dbname|escape_identifier}} with template spawn; +\c {{dbname|escape_identifier}} +drop table if exists a_different_missing_table; +select 1 as ok; +\c postgres +drop database {{dbname|escape_identifier}}; +"#; + + helper + .migration_helper + .fs + .write("/db/tests/20250113000001-notice-test/test.sql", new_test) + .await?; + + // Run compare again and confirm it fails, purely due to the stderr diff. + let result = helper.run_test_compare(Some(test_name.clone())).await; + match result { + Ok(_) => { + return Err(anyhow!( + "comparison should have produced a stderr-only diff error" + )); + } + Err(e) => { + let err_str = e.to_string(); + if !err_str.contains("error calling test compare") { + return Err(anyhow!("Unexpected comparison output")); + } + } + } + + // Now expect this, and run again and check pass: + helper + .run_test_expect(test_name.clone()) + .await + .context("failed to update expectation")?; + helper + .run_test_compare(Some(test_name.clone())) + .await + .context("failed to compare after updating expectation")?; + + Ok(()) +} + /// Tests that migrations fail when another session holds the advisory lock. /// This verifies the concurrent migration protection works correctly. #[tokio::test]