From 1217f5136d82eea4d42dbc84fa64e0edd4f29aa4 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Mon, 21 Sep 2026 09:10:59 +0000 Subject: [PATCH 1/4] test: reproduce SQLite pool waits matching the 30s runner Add failing regressions for issue #743: a full file-backed SQLite pool and a close with an outstanding connection both wait past 8s, which the Windows integration runner reports as TIMEOUT. Co-authored-by: logbie --- tests/database_transaction_test.rs | 79 ++++++++++++++++++++++++++++++ 1 file changed, 79 insertions(+) diff --git a/tests/database_transaction_test.rs b/tests/database_transaction_test.rs index e5b0a7d9..8fb17ec6 100644 --- a/tests/database_transaction_test.rs +++ b/tests/database_transaction_test.rs @@ -8,11 +8,18 @@ // production. Every atomicity assertion here therefore runs against a temp file. use std::path::{Path, PathBuf}; +use std::time::Duration; +use wfl::interpreter::database::{self, DbPool}; use wfl::interpreter::value::Value; mod common; use common::{expect_number, get_global, run_wfl}; +/// Shorter than the integration runner's 30-second program deadline. A pool +/// that still uses sqlx's default 30-second acquire wait, or an unbounded +/// `close`, matches that deadline and is reported as a runner TIMEOUT. +const RUNNER_VISIBLE_BOUND: Duration = Duration::from_secs(8); + fn expect_list(value: &Value) -> Vec { match value { Value::List(list) => list.borrow().clone(), @@ -657,3 +664,75 @@ end count "a `break` is an ordinary exit from the block, so its work commits" ); } + +// --------------------------------------------------------------------------- +// Lifecycle bounds (issue #743): file-backed SQLite must not wait the +// integration runner's 30-second deadline when the pool is busy or a +// connection has not been returned. Isolated runs of +// TestPrograms/database_transaction_test.wfl can finish; the suite then +// reports TIMEOUT because a single 30-second acquire/close wait is +// indistinguishable from a hung program once the runner has discarded +// child logs. +// --------------------------------------------------------------------------- + +#[tokio::test] +async fn file_backed_pool_does_not_wait_the_runner_deadline_when_busy() { + let db = TempDb::new("acquire_bound"); + let pool = match database::connect(&db.url) + .await + .expect("file-backed pool should open") + { + DbPool::Sqlite(pool) => pool, + _ => panic!("expected a SQLite pool"), + }; + + let mut held = Vec::new(); + for index in 0..5 { + held.push(pool.acquire().await.unwrap_or_else(|error| { + panic!("connection {index} should come from the pool: {error}") + })); + } + + let sixth = tokio::time::timeout(RUNNER_VISIBLE_BOUND, pool.acquire()).await; + drop(held); + + let result = sixth.unwrap_or_else(|_| { + panic!( + "issue #743: acquiring a sixth connection waited longer than {:?}; \ + that matches the Windows integration runner deadline and is \ + reported as TIMEOUT database_transaction_test.wfl", + RUNNER_VISIBLE_BOUND + ) + }); + assert!( + result.is_err(), + "a full pool must fail the extra acquire instead of handing out a sixth connection" + ); +} + +#[tokio::test] +async fn closing_a_file_backed_pool_does_not_wait_the_runner_deadline() { + let db = TempDb::new("close_bound"); + let pool = database::connect(&db.url) + .await + .expect("file-backed pool should open"); + let held = match &pool { + DbPool::Sqlite(inner) => inner + .acquire() + .await + .expect("one outstanding connection should be enough to stall an unbounded close"), + _ => panic!("expected a SQLite pool"), + }; + + let closed = tokio::time::timeout(RUNNER_VISIBLE_BOUND, database::close(pool)).await; + drop(held); + + closed.unwrap_or_else(|_| { + panic!( + "issue #743: closing a file-backed pool with an outstanding \ + connection waited longer than {:?}; the Windows integration \ + runner then reports TIMEOUT instead of a close error", + RUNNER_VISIBLE_BOUND + ) + }); +} From 62da7f844627380214bd1d9adfc0fbe585577af9 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Mon, 21 Sep 2026 09:17:44 +0000 Subject: [PATCH 2/4] fix: bound SQLite pool waits and exit --test cleanly File-backed SQLite now uses WAL, a five-second busy/acquire wait, and a bounded close so a contended pool fails instead of matching the 30-second integration runner deadline. The CLI closes leftover pools after a run and a successful --test process exits the same way a failing one already did, so leftover workers cannot hang only the green path. Co-authored-by: logbie --- src/interpreter/database.rs | 39 +++++++- src/interpreter/database/schema.rs | 6 +- src/interpreter/mod.rs | 33 +++++++ src/main.rs | 22 ++++- tests/database_transaction_cli_test.rs | 128 +++++++++++++++++++++++++ 5 files changed, 216 insertions(+), 12 deletions(-) create mode 100644 tests/database_transaction_cli_test.rs diff --git a/src/interpreter/database.rs b/src/interpreter/database.rs index 0abb48bd..f9e897f7 100644 --- a/src/interpreter/database.rs +++ b/src/interpreter/database.rs @@ -19,18 +19,30 @@ use super::value::Value; use sqlx::mysql::{MySqlPoolOptions, MySqlRow}; use sqlx::postgres::{PgPoolOptions, PgRow}; -use sqlx::sqlite::{SqliteConnectOptions, SqlitePoolOptions, SqliteRow}; +use sqlx::sqlite::{ + SqliteConnectOptions, SqliteJournalMode, SqlitePoolOptions, SqliteRow, SqliteSynchronous, +}; use sqlx::{Column, Row, TypeInfo, ValueRef}; use std::cell::RefCell; use std::collections::HashMap; use std::rc::Rc; use std::sync::Arc; +use std::time::Duration; mod schema; pub use schema::SchemaTransaction; const MAX_POOL_CONNECTIONS: u32 = 5; +/// Bound for SQLite acquire, busy, and close waits. +/// +/// sqlx defaults `acquire_timeout` to 30 seconds and `Pool::close` waits until +/// every connection is returned. Both match the integration runner's unchanged +/// 30-second program deadline, so a contended file-backed pool is reported as +/// `TIMEOUT database_transaction_test.wfl` instead of a database error +/// (issue #743). Schema transactions already use this same five-second bound. +pub const SQLITE_LOCK_WAIT: Duration = Duration::from_secs(5); + /// A connection pool to one of the supported database backends. #[derive(Clone)] pub enum DbPool { @@ -109,15 +121,23 @@ pub fn value_to_sql_param(value: &Value) -> Result { pub async fn connect(url: &str) -> Result { if url.starts_with("sqlite:") { let options = if url == "sqlite::memory:" || url == "sqlite://:memory:" { - SqliteConnectOptions::new().in_memory(true) + SqliteConnectOptions::new() + .in_memory(true) + .busy_timeout(SQLITE_LOCK_WAIT) } else { let path = url .strip_prefix("sqlite://") .or_else(|| url.strip_prefix("sqlite:")) .unwrap_or(url); + // WAL lets the five-connection pool share one file without stacking + // reserved-lock waits; DELETE journal mode on Windows is what turns + // those waits into a runner TIMEOUT (issue #743). SqliteConnectOptions::new() .filename(path) .create_if_missing(true) + .journal_mode(SqliteJournalMode::Wal) + .synchronous(SqliteSynchronous::Normal) + .busy_timeout(SQLITE_LOCK_WAIT) }; // In-memory SQLite databases exist per connection, so the pool must // not hand out more than one. @@ -128,6 +148,7 @@ pub async fn connect(url: &str) -> Result { }; SqlitePoolOptions::new() .max_connections(max_connections) + .acquire_timeout(SQLITE_LOCK_WAIT) .connect_with(options) .await .map(DbPool::Sqlite) @@ -414,11 +435,23 @@ pub async fn rollback(tx: DbTransaction) -> Result<(), String> { } /// Close the pool, ending all connections. +/// +/// SQLite `close` is bounded: an outstanding connection must not keep the +/// process alive until the integration runner's 30-second deadline. pub async fn close(pool: DbPool) { match pool { DbPool::Postgres(pool) => pool.close().await, DbPool::MySql(pool) => pool.close().await, - DbPool::Sqlite(pool) => pool.close().await, + DbPool::Sqlite(pool) => { + if tokio::time::timeout(SQLITE_LOCK_WAIT, pool.close()) + .await + .is_err() + { + // Dropping the pool after the deadline lets the process finish + // instead of matching the runner TIMEOUT. Remaining workers are + // reaped when the process exits. + } + } } } diff --git a/src/interpreter/database/schema.rs b/src/interpreter/database/schema.rs index b429b360..91652ca3 100644 --- a/src/interpreter/database/schema.rs +++ b/src/interpreter/database/schema.rs @@ -2,11 +2,9 @@ //! //! The foreign-key switch must happen before BEGIN. A checked commit validates //! all references before making the schema and its migration ledger durable. +use super::SQLITE_LOCK_WAIT; use sqlx::pool::PoolConnection; use sqlx::{Row, Sqlite, SqliteConnection, SqlitePool}; -use std::time::Duration; - -const LOCK_WAIT: Duration = Duration::from_secs(5); pub struct SchemaTransaction { connection: Option>, @@ -42,7 +40,7 @@ impl SchemaTransaction { .await?; Ok::<_, sqlx::Error>(transaction) }; - match tokio::time::timeout(LOCK_WAIT, begin).await { + match tokio::time::timeout(SQLITE_LOCK_WAIT, begin).await { Ok(Ok(transaction)) => Ok(transaction), Ok(Err(error)) => Err(format!( "Cannot start schema transaction: {error}. Another writer may hold the database; finish that operation and retry the migration. Lock acquisition waits at most 5 seconds." diff --git a/src/interpreter/mod.rs b/src/interpreter/mod.rs index f60068cf..4de2f6d4 100644 --- a/src/interpreter/mod.rs +++ b/src/interpreter/mod.rs @@ -2919,6 +2919,28 @@ impl IoClient { Ok(()) } + /// Roll back leftover transactions and close every open pool. + /// + /// Called on interpreter start (REPL reuse) and on every program exit so a + /// file-backed SQLite worker cannot outlive the run and keep the process + /// from exiting before the integration runner's deadline (issue #743). + async fn close_open_databases(&self) { + let leftover: Vec<(u64, String)> = self + .db_transactions + .lock() + .unwrap_or_else(|error| error.into_inner()) + .keys() + .cloned() + .collect(); + for (scope, handle) in leftover { + let _ = self.rollback_transaction(scope, &handle).await; + } + let handles: Vec = self.db_handles.lock().await.keys().cloned().collect(); + for handle in handles { + let _ = self.close_database(&handle).await; + } + } + /// Open a transaction on `handle_id`, pinning one pooled connection to it. async fn begin_transaction( &self, @@ -5837,6 +5859,17 @@ impl Interpreter { self.close_http_streams(&owner); } + /// Close leftover database pools after a CLI run. + /// + /// Not called from [`Self::interpret`]: the REPL reuses one interpreter + /// across commands and a handle opened in one line must still work in the + /// next. The process-exit path in `main` calls this so a file-backed + /// SQLite worker cannot keep `wfl --test` alive past the integration + /// runner deadline (issue #743). + pub async fn close_open_databases(&self) { + self.io_client.close_open_databases().await; + } + /// Stop tracking an outbound stream id as handler-owned — it has already left /// `IoClient.stream_handles` (EOF, error, or an explicit `close`), so the /// handler-exit cleanup must not try to (re-)drop it. diff --git a/src/main.rs b/src/main.rs index 3827be59..ad6e43a2 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1118,6 +1118,11 @@ async fn run() -> io::Result<()> { }; let interpret_result = interpreter.interpret(&program).await; + // CLI-only: the REPL reuses an interpreter across commands and + // must keep database handles. A process that is about to exit + // has to close file-backed SQLite pools so their workers cannot + // outlive the integration runner's 30-second deadline (#743). + interpreter.close_open_databases().await; // Calculate and display execution time if timing was requested if let Some(start) = start_time { @@ -1175,11 +1180,18 @@ async fn run() -> io::Result<()> { println!("\n{}", "=".repeat(60)); - // Exit with error code if tests failed - if results.failed_tests > 0 { - drop(interpreter); - process::exit(1); - } + // Flush before `_exit`: redirected runner logs are + // the only evidence when a leftover SQLite worker + // would otherwise keep the process alive past the + // 30-second integration deadline (issue #743). + // Successful `--test` runs must exit the same way + // failing ones already do, so shutdown cannot hang + // only when every assertion passed. + let test_exit = if results.failed_tests > 0 { 1 } else { 0 }; + drop(interpreter); + let _ = io::stdout().flush(); + let _ = io::stderr().flush(); + process::exit(test_exit); } let program_exit_code = interpreter.program_exit_code(); if program_exit_code != 0 { diff --git a/tests/database_transaction_cli_test.rs b/tests/database_transaction_cli_test.rs new file mode 100644 index 00000000..dcd5045c --- /dev/null +++ b/tests/database_transaction_cli_test.rs @@ -0,0 +1,128 @@ +//! Real-CLI lifecycle bound for file-backed transactions (issue #743). +//! +//! The Windows integration runner's 30-second deadline is the public contract +//! this protects: a program that opens, transacts on, and closes a file-backed +//! SQLite pool must exit with its test report visible, not sit in pool +//! acquire/close until the runner reports TIMEOUT. + +use std::fs; +use std::process::{Child, Command, Output, Stdio}; +use std::time::{Duration, Instant}; +use tempfile::{NamedTempFile, TempDir}; + +mod common; + +/// Must stay below the integration runner's unchanged 30-second program limit. +const PROCESS_BOUND: Duration = Duration::from_secs(15); + +struct ChildGuard(Child); + +impl Drop for ChildGuard { + fn drop(&mut self) { + let _ = self.0.kill(); + let _ = self.0.wait(); + } +} + +#[test] +fn file_backed_transaction_program_exits_before_runner_deadline() { + let directory = TempDir::new().expect("isolated transaction fixture"); + fs::write( + directory.path().join("tx.test.wfl"), + r#" +store db_url as "sqlite://tx.db" + +describe "file-backed transactions exit": + test "a failed block rolls back": + open database at db_url as db + store made as execute db with "CREATE TABLE rollback_case (slug TEXT)" + store failed as no + try: + in transaction on db: + store ins as execute db with "INSERT INTO rollback_case (slug) VALUES ('should-vanish')" + store boom as execute db with "INSERT INTO no_such_table (x) VALUES (1)" + end transaction + when error: + change failed to yes + end try + expect failed to be yes + store rows as query db with "SELECT slug FROM rollback_case" + expect length of rows to equal 0 + close database db + end test + + test "a finished block commits": + open database at db_url as db + store made as execute db with "CREATE TABLE commit_case (slug TEXT)" + in transaction on db: + store a as execute db with "INSERT INTO commit_case (slug) VALUES ('kept-one')" + store b as execute db with "INSERT INTO commit_case (slug) VALUES ('kept-two')" + end transaction + store rows as query db with "SELECT slug FROM commit_case" + expect length of rows to equal 2 + close database db + end test +end describe +"#, + ) + .expect("write transaction program"); + + let global_config = NamedTempFile::new().expect("isolated global configuration"); + fs::write( + global_config.path(), + "logging_enabled = false\nexecution_logging = false\ndebug_report_enabled = false\n", + ) + .expect("disable unrelated log artifacts"); + let stdout = NamedTempFile::new().expect("stdout capture"); + let stderr = NamedTempFile::new().expect("stderr capture"); + + let mut child = ChildGuard( + Command::new(common::wfl_exe()) + .args(["--test", "tx.test.wfl"]) + .current_dir(directory.path()) + .env("WFL_GLOBAL_CONFIG_PATH", global_config.path()) + .stdin(Stdio::null()) + .stdout(stdout.reopen().expect("open stdout capture")) + .stderr(stderr.reopen().expect("open stderr capture")) + .spawn() + .expect("start WFL CLI"), + ); + + let start = Instant::now(); + let status = loop { + if let Some(status) = child.0.try_wait().expect("poll WFL CLI") { + break status; + } + if start.elapsed() >= PROCESS_BOUND { + child.0.kill().expect("kill timed-out WFL CLI"); + child.0.wait().expect("reap timed-out WFL CLI"); + panic!( + "issue #743: file-backed transaction --test exceeded {:?}\nstdout: {}\nstderr: {}", + PROCESS_BOUND, + fs::read_to_string(stdout.path()).unwrap_or_default(), + fs::read_to_string(stderr.path()).unwrap_or_default(), + ); + } + std::thread::sleep(Duration::from_millis(10)); + }; + + let output = Output { + status, + stdout: fs::read(stdout.path()).expect("read stdout capture"), + stderr: fs::read(stderr.path()).expect("read stderr capture"), + }; + let combined = format!( + "{}{}", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr) + ); + assert!( + output.status.success(), + "transaction program should pass: {:?}\n{combined}", + output.status + ); + assert!( + combined.contains("Passed: 2"), + "test report must be visible after shutdown, got:\n{combined}" + ); +} From 88ec495d2d1e29a484764460f0df74f6aec19bee Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Mon, 21 Sep 2026 09:17:49 +0000 Subject: [PATCH 3/4] fix: retain integration runner child logs on timeout Keep stdout/stderr under target/test-artifacts/integration-runner/ and print the last 40 lines when a WFL program times out or fails, so a 30-second SQLite wait is no longer discarded as a silent TIMEOUT. Co-authored-by: logbie --- scripts/run_integration_tests.ps1 | 28 +++++++++++++++++++++++++--- scripts/run_integration_tests.sh | 28 ++++++++++++++++++++++++++-- 2 files changed, 51 insertions(+), 5 deletions(-) diff --git a/scripts/run_integration_tests.ps1 b/scripts/run_integration_tests.ps1 index cbcfcf51..c89440fd 100644 --- a/scripts/run_integration_tests.ps1 +++ b/scripts/run_integration_tests.ps1 @@ -230,9 +230,9 @@ if (-not (Test-Path "TestPrograms")) { # Run with timeout to prevent hangs. Start-Process requires DISTINCT # file targets for stdout and stderr — PowerShell 7 errors when the same # path is reused for both, and "NUL" is not a valid redirect target - # there — so redirect to two temp files and discard them. (Redirecting - # both to a single "NUL" left the whole Windows integration command - # unrunnable, so its assertions never actually ran.) + # there. Keep copies under target/test-artifacts on timeout/failure + # so a 30-second SQLite wait is not mistaken for a silent hang + # (issue #743). $outFile = New-TemporaryFile $errFile = New-TemporaryFile $process = Start-Process -FilePath ".\$BinaryPath" -ArgumentList $wflArgs -NoNewWindow -PassThru -RedirectStandardOutput $outFile.FullName -RedirectStandardError $errFile.FullName @@ -245,23 +245,45 @@ if (-not (Test-Path "TestPrograms")) { $isExpectedFail = ($ExpectedFailTests -contains $wflFile.Name) -or ($wflFile.FullName -match '[\\/]TestPrograms[\\/]error_examples[\\/]') + $keepLogs = $false if (-not $completed) { # Test timed out $process.Kill() Write-Host "[ERROR] TIMEOUT $($wflFile.Name) (exceeded ${TestTimeout}s)" -ForegroundColor Red $failedPrograms++ + $keepLogs = $true } elseif ($isExpectedFail) { if ($process.ExitCode -ne 0) { Write-Host "[SUCCESS] PASS $($wflFile.Name) (expected failure, exit code: $($process.ExitCode))" -ForegroundColor Green } else { Write-Host "[ERROR] FAIL $($wflFile.Name) (expected a nonzero exit, got 0)" -ForegroundColor Red $failedPrograms++ + $keepLogs = $true } } elseif ($process.ExitCode -eq 0) { Write-Host "[SUCCESS] PASS $($wflFile.Name)" -ForegroundColor Green } else { Write-Host "[ERROR] FAIL $($wflFile.Name) (exit code: $($process.ExitCode))" -ForegroundColor Red $failedPrograms++ + $keepLogs = $true + } + + if ($keepLogs) { + $logDir = Join-Path "target\test-artifacts\integration-runner" $wflFile.Name + New-Item -ItemType Directory -Force -Path $logDir | Out-Null + Copy-Item $outFile.FullName (Join-Path $logDir "stdout.log") -ErrorAction SilentlyContinue + Copy-Item $errFile.FullName (Join-Path $logDir "stderr.log") -ErrorAction SilentlyContinue + Write-Host "[INFO] Retained child logs: $logDir" -ForegroundColor Yellow + $stdoutTail = Get-Content $outFile.FullName -Tail 40 -ErrorAction SilentlyContinue + $stderrTail = Get-Content $errFile.FullName -Tail 40 -ErrorAction SilentlyContinue + if ($stdoutTail) { + Write-Host "[INFO] stdout (last 40 lines):" -ForegroundColor Yellow + $stdoutTail | ForEach-Object { Write-Host $_ } + } + if ($stderrTail) { + Write-Host "[INFO] stderr (last 40 lines):" -ForegroundColor Yellow + $stderrTail | ForEach-Object { Write-Host $_ } + } } Remove-Item $outFile.FullName, $errFile.FullName -ErrorAction SilentlyContinue } diff --git a/scripts/run_integration_tests.sh b/scripts/run_integration_tests.sh index 44261f29..25346a9a 100755 --- a/scripts/run_integration_tests.sh +++ b/scripts/run_integration_tests.sh @@ -198,10 +198,14 @@ run_test_programs() { print_status "Testing: $test_name" # Run with timeout to prevent hangs (guarded so 'set -e' does not - # abort the whole run on a failing test) + # abort the whole run on a failing test). Capture child logs so a + # timeout can be diagnosed instead of discarded (issue #743). exit_code=0 - timeout "${TEST_TIMEOUT}s" "./$WFL_BINARY" "${extra_flags[@]}" "$wfl_file" > /dev/null 2>&1 || exit_code=$? + out_file=$(mktemp) + err_file=$(mktemp) + timeout "${TEST_TIMEOUT}s" "./$WFL_BINARY" "${extra_flags[@]}" "$wfl_file" >"$out_file" 2>"$err_file" || exit_code=$? + keep_logs=0 if is_expected_fail "$test_name" || [[ "$wfl_file" == TestPrograms/error_examples/* ]]; then # These programs intentionally end with an error if [ $exit_code -ne 0 ] && [ $exit_code -ne 124 ]; then @@ -210,9 +214,11 @@ run_test_programs() { elif [ $exit_code -eq 124 ]; then print_error "TIMEOUT $test_name (exceeded ${TEST_TIMEOUT}s, expected a real failure)" failed_programs=$((failed_programs + 1)) + keep_logs=1 else print_error "FAIL $test_name (expected a nonzero exit, got $exit_code)" failed_programs=$((failed_programs + 1)) + keep_logs=1 fi elif [ $exit_code -eq 0 ]; then print_success "PASS $test_name" @@ -224,7 +230,25 @@ run_test_programs() { print_error "FAIL $test_name (exit code: $exit_code)" fi failed_programs=$((failed_programs + 1)) + keep_logs=1 fi + + if [ "$keep_logs" -eq 1 ]; then + log_dir="target/test-artifacts/integration-runner/${test_name}" + mkdir -p "$log_dir" + cp "$out_file" "$log_dir/stdout.log" + cp "$err_file" "$log_dir/stderr.log" + print_status "Retained child logs: $log_dir" + if [ -s "$out_file" ]; then + print_status "stdout (last 40 lines):" + tail -n 40 "$out_file" + fi + if [ -s "$err_file" ]; then + print_status "stderr (last 40 lines):" + tail -n 40 "$err_file" + fi + fi + rm -f "$out_file" "$err_file" fi done From 0aa535798f1f93ca45e2835e1f955d8992c768d6 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Mon, 21 Sep 2026 09:17:49 +0000 Subject: [PATCH 4/4] docs: record #743 SQLite runner timeout cause and bounds Document WAL and five-second file-backed SQLite waits, and keep the Red-to-Green evidence for the Windows integration TIMEOUT. Co-authored-by: logbie --- Docs/04-advanced-features/databases.md | 10 ++- ...-issue-743-database-transaction-timeout.md | 64 +++++++++++++++++++ ...21-database-transaction-windows-timeout.md | 21 ++++++ 3 files changed, 93 insertions(+), 2 deletions(-) create mode 100644 Engineering/evidence/2026-09-21-issue-743-database-transaction-timeout.md create mode 100644 History/dev-diary/2026/2026-09-21-database-transaction-windows-timeout.md diff --git a/Docs/04-advanced-features/databases.md b/Docs/04-advanced-features/databases.md index 172cc4d0..4e1e50a6 100644 --- a/Docs/04-advanced-features/databases.md +++ b/Docs/04-advanced-features/databases.md @@ -25,8 +25,13 @@ connect to database at "postgres://user:password@localhost:5432/mydb" as db Notes: - SQLite files are created automatically if they do not exist. +- File-backed SQLite uses WAL (`-wal` / `-shm` sidecar files) and a + five-second busy and acquire wait. A contended file fails with a database + error instead of waiting long enough to look like a hung program. Closing a + SQLite pool is bounded to the same five seconds. - `sqlite::memory:` opens a temporary in-memory database that disappears when - the connection closes. + the connection closes. In-memory pools stay at one connection and do not + create WAL files. - `mariadb://` URLs are accepted as an alias for `mysql://` — MariaDB speaks the MySQL protocol. - Connection failures (bad URL, unreachable server, wrong credentials) raise @@ -138,7 +143,8 @@ end try - **One connection for the whole block.** `open database` maintains a pool of connections, and outside a transaction each statement takes whichever one is free. Inside the block, every statement runs on the same connection — that is - what makes the group atomic. + what makes the group atomic. File-backed SQLite pools wait at most five + seconds to acquire a connection or a write lock. - **Reads see the block's own writes.** A `query` inside the block sees rows the block has inserted but not yet committed. Other connections do not see them until the block commits. diff --git a/Engineering/evidence/2026-09-21-issue-743-database-transaction-timeout.md b/Engineering/evidence/2026-09-21-issue-743-database-transaction-timeout.md new file mode 100644 index 00000000..c3d3d035 --- /dev/null +++ b/Engineering/evidence/2026-09-21-issue-743-database-transaction-timeout.md @@ -0,0 +1,64 @@ +# Issue #743 — Windows `database_transaction_test.wfl` TIMEOUT + +## Risk class + +R3 — lifecycle, timeouts, database locks, process shutdown. + +## Cause + +The suite-versus-isolated discrepancy is a 30-second SQLite pool wait that +coincides with `scripts/run_integration_tests.ps1`'s unchanged program +deadline: + +- sqlx default `acquire_timeout` is 30 seconds. +- `Pool::close` waits indefinitely for outstanding connections. +- File-backed pools used DELETE journal mode with five connections. +- The runner discarded child stdout/stderr, so a completed test report or a + database error could not be distinguished from a hang. + +Isolated runs finish because they do not contend with a prior suite's file +locks, antivirus scan backlog, or leftover `tx.db` sidecars. The full Windows +suite does. + +## Red + +Commit `1217f513` (`test: reproduce SQLite pool waits matching the 30s runner`). + +```text +cargo test --test database_transaction_test runner_deadline -- --nocapture --test-threads=1 +``` + +Both new tests failed for the intended reason after ~8 seconds: + +- `file_backed_pool_does_not_wait_the_runner_deadline_when_busy` — sixth acquire + waited longer than 8s. +- `closing_a_file_backed_pool_does_not_wait_the_runner_deadline` — close with + an outstanding connection waited longer than 8s. + +## Green + +After bounding acquire/close, enabling WAL, closing leftover CLI pools, and +exiting 0 after a successful `--test` run: + +```text +cargo test --test database_transaction_test -- --test-threads=1 +# 23 passed (including the two previously failing runner-deadline tests) + +cargo test --test database_transaction_cli_test -- --nocapture +# 1 passed in 0.04s + +cargo test --test database_test -- --test-threads=1 +# 20 passed + +target/debug/wfl --test TestPrograms/database_transaction_test.wfl +# Total: 8 Passed: 8 exit 0 in 0.073s +``` + +Clippy (`--test database_transaction_test --test database_transaction_cli_test --bin wfl -- -D warnings`) and `python3 scripts/check_repo_hygiene.py --mode static` passed. The runner deadline remains 30 seconds. + +## Residual risk + +Windows Defender or a leftover WAL from a killed process can still slow the +first open of a file-backed database. The five-second bound turns that into a +reported error plus retained child logs instead of a runner TIMEOUT. REPL +database handles are intentionally left open across commands. diff --git a/History/dev-diary/2026/2026-09-21-database-transaction-windows-timeout.md b/History/dev-diary/2026/2026-09-21-database-transaction-windows-timeout.md new file mode 100644 index 00000000..2d4c8e97 --- /dev/null +++ b/History/dev-diary/2026/2026-09-21-database-transaction-windows-timeout.md @@ -0,0 +1,21 @@ +# 2026-09-21 — File-backed SQLite waits vs the Windows integration runner (#743) + +The canonical Windows runner timed out `TestPrograms/database_transaction_test.wfl` +after its unchanged 30-second deadline. Isolated runs of the same program +passed all eight assertions. The runner then deleted the child's stdout and +stderr, so a 30-second pool wait looked exactly like a hung process. + +sqlx's default `acquire_timeout` is 30 seconds and `Pool::close` waits until +every connection is returned. A full file-backed pool, or a close with an +outstanding connection, therefore matches the runner deadline. File-backed +SQLite also used DELETE journal mode with a five-connection pool, which on +Windows stacks reserved-lock waits. + +The failing regressions hold all five connections and then acquire or close; +both waited past 8 seconds before the runtime change. File-backed pools now +use WAL, a five-second busy/acquire wait, and a bounded close. The interpreter +closes leftover pools at shutdown, and a successful `--test` run exits the +process the same way a failing one already did. The runner keeps child logs +under `target/test-artifacts/integration-runner/` on timeout or failure. + +Transaction commit and rollback rules are unchanged.