fix: bound SQLite pool waits so Windows integration does not timeout

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.

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.

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.

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
         }

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
 

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<SqlParam, String> {
 pub async fn connect(url: &str) -> Result<DbPool, String> {
     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<DbPool, String> {
         };
         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.
+            }
+        }
     }
 }
 

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<PoolConnection<Sqlite>>,
@@ -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."

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<String> = 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.