From cf9329bf444556ca077c5a19f7ec74d9c8d39895 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Fri, 30 Oct 2026 22:54:28 +0000 Subject: [PATCH 01/14] feat(migrations): apply a catalog's pending migrations at startup [server] catalog_upgrade sets what serve does with a catalog that is behind the binary. refuse, the default in a production build, exits 3 as before. apply, the default in a dev build, migrates the catalog and then serves. serve --migrate sets apply for one run, and EXTENDDB__SERVER__CATALOG_UPGRADE sets it from the environment. Every other status is refused under both values with the code it had, and no value serves a catalog the binary cannot use. Under apply the server migrates through run_with_lock, which migrate --yes now calls too: it takes the migration lock, waiting up to [server] catalog_upgrade_lock_timeout (60 s by default, at most a day) for another migration and for running servers, reads the status again under the lock, runs detect for every pending code body, takes the SQLite copy, applies the migrations and releases the lock. A catalog that another process migrated while this one waited is served as it is. When the lock is still held at the timeout, the status is read once more: a catalog that is current by then is served, and any other exits 6. Under apply serve does not read the notes migrate --yes checks before it takes the lock, so a body that fails on a table the role does not own stops the run with the same note. serve reads the status, and under apply runs the migrations, before it forks, on a current-thread runtime it shuts down first, so in daemon mode the exit code and the message reach the invoking shell. After the fork the server reads the status again and registers, and exits 6 when a migration holds the lock. While it migrates it prints a line on stderr for each step, each starting with "catalog migration: ", and one every 5 s until the run ends. A server's refusal of a catalog behind it ends with "or start this server with --migrate". The SQLite factory no longer migrates a Behind catalog in a dev build: the startup policy does that before the factory runs. An in-memory SQLite database is created by its server and is not read before it starts. MongoCatalogMigrations can name its databases, so the integration tests run the policy on databases of their own. init writes both keys, commented out, into the config it generates. --- crates/app/src/cmd_migrate_runner.rs | 7 +- crates/app/src/cmd_migrate_runner_tests.rs | 1 + crates/app/src/cmd_serve.rs | 48 +++ crates/app/src/init_helpers.rs | 6 + crates/app/src/lib.rs | 1 + crates/app/src/serve_catalog.rs | 83 ++++ crates/config/Cargo.toml | 3 +- crates/config/src/catalog_upgrade.rs | 135 +++++++ crates/config/src/display.rs | 8 + crates/config/src/lib.rs | 16 + crates/server/src/serve.rs | 3 +- crates/storage-cassandra/tests/migrations.rs | 7 +- .../tests/migrations/startup.rs | 267 +++++++++++++ crates/storage-mongodb/src/lib.rs | 6 +- .../src/migrations/commands.rs | 63 ++- .../tests/migrations_startup.rs | 226 +++++++++++ .../tests/migrations_startup.rs | 211 ++++++++++ crates/storage-sqlite/src/lib.rs | 5 +- .../storage-sqlite/src/migrations/commands.rs | 6 + crates/storage-sqlite/src/migrations/mod.rs | 16 +- .../src/migrations/serve_tests.rs | 201 +++++++++- crates/storage/src/migrations/advice.rs | 67 +++- crates/storage/src/migrations/catalog.rs | 32 ++ crates/storage/src/migrations/mod.rs | 6 +- crates/storage/src/migrations/startup.rs | 214 ++++++++++ .../storage/src/migrations/startup_tests.rs | 375 ++++++++++++++++++ 26 files changed, 1964 insertions(+), 49 deletions(-) create mode 100644 crates/app/src/serve_catalog.rs create mode 100644 crates/config/src/catalog_upgrade.rs create mode 100644 crates/storage-cassandra/tests/migrations/startup.rs create mode 100644 crates/storage-mongodb/tests/migrations_startup.rs create mode 100644 crates/storage-postgres/tests/migrations_startup.rs create mode 100644 crates/storage/src/migrations/startup.rs create mode 100644 crates/storage/src/migrations/startup_tests.rs diff --git a/crates/app/src/cmd_migrate_runner.rs b/crates/app/src/cmd_migrate_runner.rs index ec4d4f35f..7dbbf4cf3 100644 --- a/crates/app/src/cmd_migrate_runner.rs +++ b/crates/app/src/cmd_migrate_runner.rs @@ -22,7 +22,7 @@ use extenddb_config as config; use extenddb_storage::migrations::advice::{self, Advice, AdviceFor}; use extenddb_storage::migrations::{ AdminRole, CatalogMigrations, CatalogStatus, Listed, MigrationError, MigrationId, Pending, - RunKind, RunReport, Target, before_lock, behind_line, exit, forget_locked, run_locked, + RunKind, RunReport, Target, before_lock, behind_line, exit, forget_locked, run_with_lock, stores_behind, }; @@ -312,10 +312,7 @@ async fn apply( "--- Taking the migration lock (waiting up to {} s for a server or another migration)...", lock_timeout.as_secs() ); - let lock = migrations.lock(target, lock_timeout).await?; - let report = run_locked(migrations, target, &lock, release, kind).await; - migrations.release(lock).await; - let report = report?; + let report = run_with_lock(migrations, target, release, kind, lock_timeout).await?; print_report(&report, kind); if report.applied.is_empty() && kind == RunKind::Migrate { // A catalog ahead by additive migrations has nothing to apply and diff --git a/crates/app/src/cmd_migrate_runner_tests.rs b/crates/app/src/cmd_migrate_runner_tests.rs index feed9cb4a..2e3534674 100644 --- a/crates/app/src/cmd_migrate_runner_tests.rs +++ b/crates/app/src/cmd_migrate_runner_tests.rs @@ -100,6 +100,7 @@ const ADVICE: Advice<'static> = Advice { backup: "back up db", config: Some("extenddb.toml"), assignment: None, + serving: false, }; fn behind() -> CatalogStatus { diff --git a/crates/app/src/cmd_serve.rs b/crates/app/src/cmd_serve.rs index a754aa4c2..2f958e17d 100755 --- a/crates/app/src/cmd_serve.rs +++ b/crates/app/src/cmd_serve.rs @@ -46,6 +46,17 @@ pub struct ServeArgs { /// always writes one. #[arg(long)] write_pid_file: bool, + + /// Apply the catalog's pending migrations before serving, for this run + /// only, as `[server] catalog_upgrade = "apply"` does. + /// + /// The server takes the migration lock, waiting up to + /// `catalog_upgrade_lock_timeout` seconds (60 by default) for another + /// migration or a running server, and exits 6 if it is not free in time. + /// A catalog that needs a person, or that this binary cannot use, is + /// refused as without the flag. + #[arg(long)] + migrate: bool, } /// Bind the listening socket, daemonize, then start the tokio runtime. @@ -94,6 +105,14 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { ); } + if app_config.server.catalog_upgrade_lock_timeout > config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT { + anyhow::bail!( + "server.catalog_upgrade_lock_timeout is {} s; it may be at most {} s (a day)", + app_config.server.catalog_upgrade_lock_timeout, + config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT + ); + } + // Fail fast, before binding the port, when no backend is installed. let backend = &app_config.storage.backend; extenddb_storage::backend_name() @@ -192,6 +211,25 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { print_dev_mode_banner(&app_config, args.foreground)?; } + // The catalog's status, and under `apply` its migrations, before the + // fork, so that in daemon mode a refusal's exit code and message reach + // the invoking shell. The server checks the catalog again when it + // registers. + let upgrade = if args.migrate { + config::CatalogUpgrade::Apply + } else { + app_config.server.catalog_upgrade + }; + let code = crate::serve_catalog::check_catalog( + &app_config, + upgrade, + build.version, + config_exists.then_some(args.config.as_str()), + )?; + if code != extenddb_storage::migrations::exit::OK { + std::process::exit(i32::from(code)); + } + // D-3: A PID file lets `extenddb status` and `extenddb stop` find the // process. Daemon mode always writes one. Foreground mode writes one only on // request, so by default it needs no run directory at all and the container @@ -450,6 +488,16 @@ mod tests { assert!(args.foreground); } + /// `--migrate` applies the catalog's pending migrations for this run; + /// without it the server follows `[server] catalog_upgrade`. + #[test] + fn migrate_flag_is_recognized_and_off_by_default() { + assert!(!parse(&["extenddb-serve"]).migrate); + let args = parse(&["extenddb-serve", "--migrate", "--foreground"]); + assert!(args.migrate); + assert!(args.foreground); + } + #[test] fn no_daemon_alias_is_recognized() { // The issue proposed either `--foreground` or `--no-daemon`; make diff --git a/crates/app/src/init_helpers.rs b/crates/app/src/init_helpers.rs index 406db8b0e..e8504e855 100755 --- a/crates/app/src/init_helpers.rs +++ b/crates/app/src/init_helpers.rs @@ -212,6 +212,10 @@ pub(crate) fn generate_config( let tls_cert = extenddb_config::expand_tilde("~/.extenddb/tls/cert.pem"); let tls_key = extenddb_config::expand_tilde("~/.extenddb/tls/key.pem"); let run_dir = extenddb_config::expand_tilde("~/.extenddb/run"); + // `refuse`, or `apply` in a dev build. + let catalog_upgrade = extenddb_config::ServerConfig::default() + .catalog_upgrade + .as_str(); // Compute docs_dir line before the template so it lands in the top-level // TOML section (before any [section] header). @@ -250,6 +254,8 @@ bind_addr = "{bind_addr}" # region = "us-east-1" # AWS region for ARN generation # run_dir = "{run_dir}" # Directory for PID file # throttling_enabled = false # Enable provisioned throughput throttling +# catalog_upgrade = "{catalog_upgrade}" # "apply" migrates a catalog behind this binary at startup +# catalog_upgrade_lock_timeout = 60 # Seconds serve waits for the migration lock under "apply" [server.tls] # TLS is mandatory. The server refuses to start with enabled = false. diff --git a/crates/app/src/lib.rs b/crates/app/src/lib.rs index 157f29d9b..19c28b73a 100644 --- a/crates/app/src/lib.rs +++ b/crates/app/src/lib.rs @@ -37,6 +37,7 @@ mod cmd_verify; mod init_helpers; mod manage_http; mod manage_types; +mod serve_catalog; mod serve_helpers; mod util; diff --git a/crates/app/src/serve_catalog.rs b/crates/app/src/serve_catalog.rs new file mode 100644 index 000000000..379ee573b --- /dev/null +++ b/crates/app/src/serve_catalog.rs @@ -0,0 +1,83 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! The catalog check `extenddb serve` makes before it daemonizes: the +//! status, read by the startup policy (`[server] catalog_upgrade`, or +//! `--migrate` for one run), and under `apply` the run that migrates a +//! catalog behind this binary. It runs in the invoking process, on a +//! runtime that is shut down before the server forks, so in daemon mode the +//! exit code and the message of a refusal reach the invoking shell as they +//! do in the foreground. The server checks the catalog again when it +//! registers, after the fork. + +use std::time::Duration; + +use extenddb_config::{self as config, AppConfig, CatalogUpgrade}; +use extenddb_storage::migrations::advice::{self, AdviceFor}; +use extenddb_storage::migrations::{Startup, Target, exit, installed, prepare_to_serve}; + +/// The start of every line `serve` prints on stderr while it migrates the +/// catalog. The npm launcher's startup timeout restarts at each one. +pub(crate) const PROGRESS_PREFIX: &str = "catalog migration: "; + +/// Check the catalog of `app_config` before the server starts, printing +/// the lines of a run and any refusal on stderr. Returns the status's exit +/// code: 0 when the server may start, else the code `serve` exits with. +/// `config_file` is the config file the server was started with, named in +/// the command a refusal prints. +/// +/// # Errors +/// +/// The runtime could not be built. +pub(crate) fn check_catalog( + app_config: &AppConfig, + upgrade: CatalogUpgrade, + release: &str, + config_file: Option<&str>, +) -> anyhow::Result { + let Some(migrations) = installed() else { + return Ok(exit::OK); + }; + let location = app_config.storage.connection_config(); + let target = Target::at(location); + let startup = Startup { + apply: upgrade == CatalogUpgrade::Apply, + // A dev build's server creates its catalog in a missing or empty + // database file. + creates_uninitialized: cfg!(feature = "dev-mode"), + release, + lock_timeout: Duration::from_secs(app_config.server.catalog_upgrade_lock_timeout), + heartbeat: Startup::HEARTBEAT, + }; + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build()?; + let result = runtime.block_on(prepare_to_serve(migrations, &target, &startup, &|line| { + eprintln!("{PROGRESS_PREFIX}{line}"); + })); + // The fork that follows copies only the thread that calls it: every + // task and blocking thread of this runtime ends first. + runtime.shutdown_timeout(Duration::from_secs(10)); + match result { + Ok(prepared) => { + if let Some(warning) = prepared.warning { + eprintln!("WARNING: {warning}"); + } + Ok(exit::OK) + } + Err(error) => { + let advice = AdviceFor::new( + release, + config::redact_password(location), + Some(migrations), + &target, + config_file, + ) + .for_server(); + eprintln!("Error: {}", advice::error_message(&error, &advice.advice())); + // A refusal never lets the server start, whatever its status's + // code. + Ok(error.exit_code().max(exit::ERROR)) + } + } +} diff --git a/crates/config/Cargo.toml b/crates/config/Cargo.toml index 1c2c59ebf..a3776b3ca 100644 --- a/crates/config/Cargo.toml +++ b/crates/config/Cargo.toml @@ -9,7 +9,8 @@ license.workspace = true [features] # Developer mode: `is_tls_enabled` reports plain HTTP regardless of the -# configured TLS state. Enabled only through the app crate's `dev-mode` feature. +# configured TLS state, and `server.catalog_upgrade` defaults to "apply". +# Enabled only through the app crate's `dev-mode` feature. dev-mode = [] [dependencies] diff --git a/crates/config/src/catalog_upgrade.rs b/crates/config/src/catalog_upgrade.rs new file mode 100644 index 000000000..09fc990d8 --- /dev/null +++ b/crates/config/src/catalog_upgrade.rs @@ -0,0 +1,135 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! `[server] catalog_upgrade` and `catalog_upgrade_lock_timeout`: what +//! `serve` does with a catalog that is behind this binary. + +use serde::Deserialize; + +/// `[server] catalog_upgrade`: what `serve` does with a catalog that is +/// behind this binary. Every other status a server cannot serve is refused +/// under both values. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Deserialize)] +#[serde(rename_all = "lowercase")] +pub enum CatalogUpgrade { + /// Exit 3, printing the pending migrations and the command that + /// applies them. + Refuse, + /// Apply the pending migrations under the migration lock, as + /// `migrate --yes` does, then serve. + Apply, +} + +impl CatalogUpgrade { + /// The value as the config file spells it. + #[must_use] + pub const fn as_str(self) -> &'static str { + match self { + Self::Refuse => "refuse", + Self::Apply => "apply", + } + } +} + +/// The longest `catalog_upgrade_lock_timeout`, a day, as `migrate`'s +/// `--lock-timeout` allows. +pub const MAX_CATALOG_UPGRADE_LOCK_TIMEOUT: u64 = 86_400; + +/// A dev-mode build migrates its database at startup, since the dev image +/// and the npm launcher run no `migrate`; a production build refuses. +pub(crate) fn default_catalog_upgrade() -> CatalogUpgrade { + if cfg!(feature = "dev-mode") { + CatalogUpgrade::Apply + } else { + CatalogUpgrade::Refuse + } +} + +pub(crate) fn default_catalog_upgrade_lock_timeout() -> u64 { + 60 +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::ServerConfig; + + /// `[server]` as `load` reads it: the file's table, then the + /// `EXTENDDB__` variables in `env` over it. The variables are given to + /// the source instead of set in the process, which other tests share. + fn server_from(file: &str, env: &[(&str, &str)]) -> Result { + #[derive(Deserialize)] + struct File { + #[serde(default)] + server: ServerConfig, + } + let vars = env + .iter() + .map(|(k, v)| ((*k).to_owned(), (*v).to_owned())) + .collect(); + config::Config::builder() + .add_source(config::File::from_str(file, config::FileFormat::Toml)) + .add_source( + config::Environment::with_prefix("EXTENDDB") + .separator("__") + .source(Some(vars)), + ) + .build() + .and_then(config::Config::try_deserialize::) + .map(|f| f.server) + .map_err(|e| e.to_string()) + } + + /// A production build refuses a catalog behind it unless told to apply, + /// and waits 60 s for the lock under `apply`; a dev-mode build applies. + #[test] + fn catalog_upgrade_defaults_to_refuse_and_a_60_s_lock_timeout() { + let server = server_from("", &[]).expect("defaults"); + let expected = if cfg!(feature = "dev-mode") { + CatalogUpgrade::Apply + } else { + CatalogUpgrade::Refuse + }; + assert_eq!(server.catalog_upgrade, expected); + assert_eq!(server.catalog_upgrade_lock_timeout, 60); + assert_eq!(ServerConfig::default().catalog_upgrade, expected); + assert_eq!(ServerConfig::default().catalog_upgrade_lock_timeout, 60); + } + + #[test] + fn catalog_upgrade_is_read_from_the_file_and_the_environment() { + let server = server_from( + "[server]\ncatalog_upgrade = \"apply\"\ncatalog_upgrade_lock_timeout = 5\n", + &[], + ) + .expect("file"); + assert_eq!(server.catalog_upgrade, CatalogUpgrade::Apply); + assert_eq!(server.catalog_upgrade_lock_timeout, 5); + // The environment wins over the file, as for every other key. + let server = server_from( + "[server]\ncatalog_upgrade = \"apply\"\n", + &[ + ("EXTENDDB__SERVER__CATALOG_UPGRADE", "refuse"), + ("EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT", "120"), + ], + ) + .expect("environment"); + assert_eq!(server.catalog_upgrade, CatalogUpgrade::Refuse); + assert_eq!(server.catalog_upgrade_lock_timeout, 120); + let server = server_from("", &[("EXTENDDB__SERVER__CATALOG_UPGRADE", "apply")]) + .expect("environment alone"); + assert_eq!(server.catalog_upgrade, CatalogUpgrade::Apply); + } + + #[test] + fn catalog_upgrade_refuses_any_other_value() { + let error = + server_from("[server]\ncatalog_upgrade = \"ignore\"\n", &[]).expect_err("not a value"); + assert!(error.contains("ignore"), "{error}"); + let error = server_from("", &[("EXTENDDB__SERVER__CATALOG_UPGRADE", "always")]) + .expect_err("not a value"); + assert!(error.contains("always"), "{error}"); + assert_eq!(CatalogUpgrade::Refuse.as_str(), "refuse"); + assert_eq!(CatalogUpgrade::Apply.as_str(), "apply"); + } +} diff --git a/crates/config/src/display.rs b/crates/config/src/display.rs index f626b75a2..de5408c01 100644 --- a/crates/config/src/display.rs +++ b/crates/config/src/display.rs @@ -84,6 +84,14 @@ pub fn build_config_entries(cfg: &AppConfig) -> Vec<(String, String)> { .throttling_enabled .map_or("none".into(), |b| b.to_string()), ), + ( + "server.catalog_upgrade".into(), + cfg.server.catalog_upgrade.as_str().to_owned(), + ), + ( + "server.catalog_upgrade_lock_timeout".into(), + cfg.server.catalog_upgrade_lock_timeout.to_string(), + ), ( format!("storage.{backend}.connection_string"), r("connection_string", cfg.storage.connection_config()), diff --git a/crates/config/src/lib.rs b/crates/config/src/lib.rs index 4cc5cf123..fcd68dfdf 100644 --- a/crates/config/src/lib.rs +++ b/crates/config/src/lib.rs @@ -75,6 +75,17 @@ pub struct ServerConfig { /// Enable provisioned throughput throttling via token buckets. /// When `None` or `false`, all requests are allowed regardless of capacity. pub throttling_enabled: Option, + /// What `serve` does with a catalog that is behind this binary: refuse + /// it, or apply its pending migrations before it serves. `refuse` by + /// default, `apply` in a dev-mode build. `serve --migrate` sets `apply` + /// for one run. + #[serde(default = "catalog_upgrade::default_catalog_upgrade")] + pub catalog_upgrade: CatalogUpgrade, + /// Seconds `serve` waits under `catalog_upgrade = "apply"` for the + /// migration lock and for running servers before it exits 6 (default + /// 60, at most 86400). + #[serde(default = "catalog_upgrade::default_catalog_upgrade_lock_timeout")] + pub catalog_upgrade_lock_timeout: u64, } impl Default for ServerConfig { @@ -86,6 +97,8 @@ impl Default for ServerConfig { run_dir: default_run_dir(), tls: TlsConfig::default(), throttling_enabled: None, + catalog_upgrade: catalog_upgrade::default_catalog_upgrade(), + catalog_upgrade_lock_timeout: catalog_upgrade::default_catalog_upgrade_lock_timeout(), } } } @@ -495,6 +508,9 @@ pub fn pid_file_path_default(port: u16) -> PathBuf { pid_file_path(&ServerConfig::default().run_dir, port) } +mod catalog_upgrade; +pub use catalog_upgrade::{CatalogUpgrade, MAX_CATALOG_UPGRADE_LOCK_TIMEOUT}; + mod display; pub use display::{MASK, build_config_entries, should_redact}; diff --git a/crates/server/src/serve.rs b/crates/server/src/serve.rs index 37cc11f0d..baf2b803f 100644 --- a/crates/server/src/serve.rs +++ b/crates/server/src/serve.rs @@ -375,7 +375,8 @@ async fn serve_inner(params: ServeParams, port: u16) -> anyhow::Result<()> { installed(), &named, config_path.as_deref(), - ); + ) + .for_server(); return Err(CatalogRefusal { exit_code: error.exit_code(), message: advice::error_message(&error, &advice.advice()), diff --git a/crates/storage-cassandra/tests/migrations.rs b/crates/storage-cassandra/tests/migrations.rs index 27558c177..acb94f771 100644 --- a/crates/storage-cassandra/tests/migrations.rs +++ b/crates/storage-cassandra/tests/migrations.rs @@ -3,8 +3,9 @@ //! The catalog migrations against a live node: migration 1's definitions, //! the status of keyspaces that are not catalogs, the ledger, the migration -//! lock's lease, the serving registration and CreateAccount's account -//! migrations. Each test uses keyspaces of its own prefix and drops them. +//! lock's lease, the serving registration, CreateAccount's account +//! migrations and the startup policy `serve` runs before it opens the +//! catalog. Each test uses keyspaces of its own prefix and drops them. //! Skipped without a node unless `EXTENDDB_TEST_CASSANDRA=required`. //! //! With `EXTENDDB_BLESS_EXPECTED=1`, @@ -17,6 +18,8 @@ mod helpers; #[path = "migrations/lock.rs"] mod lock; mod migrations_support; +#[path = "migrations/startup.rs"] +mod startup; use std::sync::Arc; diff --git a/crates/storage-cassandra/tests/migrations/startup.rs b/crates/storage-cassandra/tests/migrations/startup.rs new file mode 100644 index 000000000..3fb82e9d7 --- /dev/null +++ b/crates/storage-cassandra/tests/migrations/startup.rs @@ -0,0 +1,267 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! The startup policy `serve` runs before it opens the catalog +//! (`[server] catalog_upgrade`, or `serve --migrate`): under `apply` a +//! legacy catalog is migrated through the lock `migrate --yes` takes, a +//! current one is served with nothing written, one that needs a person +//! exits 5 with nothing written, a held lock makes the server wait and then +//! exit 6, and two servers started together, whose connection strings name +//! the two nodes of a two-node cluster when the job has one, migrate once. + +use std::sync::Arc; +use std::time::{Duration, Instant}; + +use extenddb_storage::management_store::{ManagementStore, SettingsStore}; +use extenddb_storage::migrations::{ + CatalogMigrations, CatalogStatus, LedgerRow, MigrationError, MigrationId, Prepared, Startup, + StoreKind, Target, exit, prepare_to_serve, +}; +use extenddb_storage_cassandra::CassandraCatalogStore; +use extenddb_storage_cassandra::cassandra_util::CassandraSession; +use extenddb_storage_cassandra::migrations::{ + CassandraCatalogMigrations, LeaseTimes, MigrationLock, catalog_status, run_baseline_unrecorded, +}; + +use super::{deployment, target_of}; +use crate::helpers; +use crate::migrations_support::{TIMEOUT, cql, keyspace, new_prefix, pinned_session, session}; + +const ACCOUNT: &str = "111111111111"; + +fn startup(apply: bool, lock_timeout: Duration) -> Startup<'static> { + Startup { + apply, + creates_uninitialized: false, + release: "1.0.0-test", + lock_timeout, + heartbeat: Startup::HEARTBEAT, + } +} + +/// The policy as `serve` runs it, on the connection string the config +/// file gives. +async fn prepare(target: &Target, startup: &Startup<'_>) -> Result { + prepare_to_serve(&CassandraCatalogMigrations, target, startup, &|_| {}).await +} + +/// The node `EXTENDDB_TEST_CASSANDRA_SECOND_CONTACT_POINT` names, the second +/// node of a two-node cluster; the test node when it is not set. +fn second_contact_point() -> String { + std::env::var("EXTENDDB_TEST_CASSANDRA_SECOND_CONTACT_POINT") + .unwrap_or_else(|_| helpers::test_contact_point()) +} + +/// [`target_of`] with [`second_contact_point`] as its contact point. +fn second_target_of(prefix: &str) -> Target { + let config = helpers::test_config(); + Target::at(format!( + "{}:{}@{}/{prefix}", + config.username.unwrap_or_default(), + config.password.unwrap_or_default(), + second_contact_point(), + )) +} + +/// A catalog as a release before 1.0 left it: migration 1's tables with no +/// ledger rows, and `catalog_version` 0.0.4. +async fn legacy_catalog(session: &Arc, prefix: &str) { + let catalog = format!("{prefix}_catalog"); + keyspace(session, &catalog).await; + run_baseline_unrecorded(session, &catalog, StoreKind::Catalog) + .await + .expect("the legacy tables"); + cql( + session, + &format!("INSERT INTO {catalog}.settings (key, value) VALUES ('catalog_version', '0.0.4')"), + ) + .await; +} + +/// What a run could change in the catalog: its ledger rows with the time +/// each was applied, its `catalog_version` row, and the lock row. +async fn state( + session: &Arc, + prefix: &str, +) -> (Vec, Option, Option) { + let rows = CassandraCatalogMigrations + .catalog_ledger(&target_of(prefix)) + .await + .expect("the ledger"); + let store = CassandraCatalogStore::catalog_only(session.clone(), prefix.to_owned()); + let version = store.get_setting("catalog_version").await.expect("read"); + let lock = store.get_setting("migration_lock").await.expect("read"); + (rows, version, lock) +} + +#[tokio::test] +async fn apply_migrates_a_legacy_catalog_and_refuse_writes_nothing() { + if helpers::skip_without_cassandra() { + return; + } + let session = session().await; + let (prefix, _drops) = new_prefix("start_apply"); + legacy_catalog(&session, &prefix).await; + let target = target_of(&prefix); + let before = state(&session, &prefix).await; + let err = prepare(&target, &startup(false, TIMEOUT)) + .await + .expect_err("refused"); + assert_eq!(err.exit_code(), exit::PENDING, "{err:?}"); + assert_eq!(state(&session, &prefix).await, before, "refuse wrote"); + + let prepared = prepare(&target, &startup(true, TIMEOUT)) + .await + .expect("applied"); + let report = prepared.run.expect("a run"); + assert_eq!(report.applied.len(), MigrationId::ALL.len(), "{report:?}"); + assert_eq!( + catalog_status(session.clone(), &prefix) + .await + .expect("status"), + CatalogStatus::Current { + version: MigrationId::LATEST.number() + } + ); +} + +#[tokio::test] +async fn apply_on_a_current_catalog_writes_nothing() { + if helpers::skip_without_cassandra() { + return; + } + let session = session().await; + let (prefix, _drops) = new_prefix("start_current"); + deployment(&session, &prefix).await; + let before = state(&session, &prefix).await; + let prepared = prepare(&target_of(&prefix), &startup(true, TIMEOUT)) + .await + .expect("served"); + assert_eq!(prepared, Prepared::default()); + assert_eq!( + state(&session, &prefix).await, + before, + "a current catalog was written to" + ); +} + +#[tokio::test] +async fn apply_on_a_catalog_that_needs_attention_exits_5_and_writes_nothing() { + if helpers::skip_without_cassandra() { + return; + } + let session = session().await; + let (prefix, _drops) = new_prefix("start_attention"); + legacy_catalog(&session, &prefix).await; + cql( + &session, + &format!( + "INSERT INTO {prefix}_catalog.accounts (account_id, account_name, created_at) VALUES \ + ('{ACCOUNT}', 'one', toTimestamp(now()))" + ), + ) + .await; + // A policy migration 2 cannot rewrite: both forms of one tag key, with + // different values. + let colliding: serde_json::Value = serde_json::from_str( + r#"{"Version":"2012-10-17","Statement":[{"Effect":"Deny","Action":"dynamodb:*","Resource":"*","Condition":{"StringEquals":{"aws:ResourceTag/env":"prod","dynamodb:ResourceTag/env":"dev"}}}]}"#, + ) + .expect("json"); + let store = CassandraCatalogStore::catalog_only(session.clone(), prefix.clone()); + store.create_user(ACCOUNT, "dev", None).await.expect("user"); + store + .put_policy(ACCOUNT, "user", "dev", "colliding", &colliding) + .await + .expect("policy"); + let target = target_of(&prefix); + let before = state(&session, &prefix).await; + let err = prepare(&target, &startup(true, TIMEOUT)) + .await + .expect_err("refused"); + assert!( + matches!( + err, + MigrationError::Status(CatalogStatus::NeedsAttention { .. }) + ), + "{err:?}" + ); + assert_eq!(err.exit_code(), exit::ATTENTION); + assert_eq!( + state(&session, &prefix).await, + before, + "a refused run wrote" + ); +} + +/// Another process holds the migration lock: the server waits for it up +/// to the timeout, then exits 6 with the catalog unchanged. +#[tokio::test] +async fn apply_waits_for_a_held_migration_lock_and_exits_6() { + if helpers::skip_without_cassandra() { + return; + } + let session = session().await; + let (prefix, _drops) = new_prefix("start_locked"); + legacy_catalog(&session, &prefix).await; + let holder = MigrationLock::acquire( + session.clone(), + &format!("{prefix}_catalog"), + LeaseTimes::DEFAULT, + TIMEOUT, + ) + .await + .expect("another process's lock"); + let before = state(&session, &prefix).await; + let started = Instant::now(); + let err = prepare(&target_of(&prefix), &startup(true, Duration::from_secs(3))) + .await + .expect_err("locked"); + assert!( + started.elapsed() >= Duration::from_millis(2800), + "it waited {:?}", + started.elapsed() + ); + assert!(matches!(err, MigrationError::Locked(_)), "{err:?}"); + assert_eq!(err.exit_code(), exit::LOCKED); + assert_eq!( + state(&session, &prefix).await, + before, + "a server that waited wrote" + ); + holder.release().await; +} + +/// Two servers started together under `apply` on a legacy catalog, their +/// connection strings naming different nodes when the job has two: one +/// migrates it, and the other waits for the lock and finds nothing to do. +/// Each server's session reaches the cluster at the node its connection +/// string names and then sends requests to both nodes in turn, as a +/// server's session does. +#[tokio::test] +async fn two_servers_started_together_with_apply_migrate_a_legacy_catalog_once() { + if helpers::skip_without_cassandra() { + return; + } + let session = session().await; + let (prefix, _drops) = new_prefix("start_two"); + legacy_catalog(&session, &prefix).await; + let apply = startup(true, TIMEOUT); + let (first, second) = (target_of(&prefix), second_target_of(&prefix)); + let (a, b) = tokio::join!(prepare(&first, &apply), prepare(&second, &apply)); + let applied: Vec = [a.expect("first"), b.expect("second")] + .iter() + .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .collect(); + assert!( + applied.contains(&0) && applied.iter().any(|n| *n > 0), + "one migrates and the other finds nothing to do: {applied:?}" + ); + assert_eq!( + catalog_status(pinned_session(&second_contact_point()).await, &prefix) + .await + .expect("status"), + CatalogStatus::Current { + version: MigrationId::LATEST.number() + } + ); +} diff --git a/crates/storage-mongodb/src/lib.rs b/crates/storage-mongodb/src/lib.rs index 787f503dc..f1af19dde 100644 --- a/crates/storage-mongodb/src/lib.rs +++ b/crates/storage-mongodb/src/lib.rs @@ -303,10 +303,14 @@ pub fn backend() -> extenddb_storage::Backend { }) }, server_components: server_components_factory, - catalog_migrations: &migrations::MongoCatalogMigrations, + catalog_migrations: &CATALOG_MIGRATIONS, } } +/// The catalog migrations of every deployment this backend serves. +static CATALOG_MIGRATIONS: migrations::MongoCatalogMigrations = + migrations::MongoCatalogMigrations::new(); + // ============================================================================ // MongoEngine // ============================================================================ diff --git a/crates/storage-mongodb/src/migrations/commands.rs b/crates/storage-mongodb/src/migrations/commands.rs index 8344b8cb7..256f6fdbe 100644 --- a/crates/storage-mongodb/src/migrations/commands.rs +++ b/crates/storage-mongodb/src/migrations/commands.rs @@ -24,12 +24,46 @@ use extenddb_storage::migrations::{ use super::foreign::foreign_unless_a_catalog; use super::{ - CATALOG_DATABASE, DATA_DATABASE, Lease, MigrationLock, MongoMigrations, MongoTarget, Timing, - catalog_status, status_holding, + Lease, MigrationLock, MongoMigrations, MongoTarget, Timing, catalog_status, status_holding, }; -/// The MongoDB backend's catalog migrations for the commands. -pub struct MongoCatalogMigrations; +/// The MongoDB backend's catalog migrations for the commands, on the +/// databases `extenddb_catalog` and `extenddb_data` of the deployment a +/// [`Target`] names. +#[derive(Debug, Default)] +pub struct MongoCatalogMigrations { + /// The catalog and data databases' names instead of those two, for + /// tests that share one server. + databases: Option<(String, String)>, +} + +impl MongoCatalogMigrations { + /// The catalog migrations of a deployment's two databases. + #[must_use] + pub const fn new() -> Self { + Self { databases: None } + } + + /// The catalog migrations of a deployment in databases of other names, + /// for tests that share one server. + #[cfg(any(test, feature = "test-util"))] + #[must_use] + pub fn with_databases(catalog: impl Into, data: impl Into) -> Self { + Self { + databases: Some((catalog.into(), data.into())), + } + } + + /// The deployment at `location`, in this value's databases. + fn target(&self, location: &str) -> MongoTarget { + let mut target = MongoTarget::new(location); + if let Some((catalog, data)) = &self.databases { + target.catalog.clone_from(catalog); + target.data.clone_from(data); + } + target + } +} /// What the migration lock carries for [`CatalogMigrations::run`] and /// [`CatalogMigrations::forget`]. @@ -56,15 +90,16 @@ impl CatalogMigrations for MongoCatalogMigrations { Listed::of(&super::migration(id)) } - fn backup_advice(&self, _target: &Target) -> String { + fn backup_advice(&self, target: &Target) -> String { + let MongoTarget { catalog, data, .. } = self.target(&target.location); format!( - "back up both MongoDB databases, the catalog database {CATALOG_DATABASE} and the data \ - database {DATA_DATABASE}" + "back up both MongoDB databases, the catalog database {catalog} and the data \ + database {data}" ) } async fn status(&self, target: &Target) -> Result { - catalog_status(&MongoTarget::new(&target.location)).await + catalog_status(&self.target(&target.location)).await } /// Read as the holder, so the requests of a long status read are @@ -79,7 +114,7 @@ impl CatalogMigrations for MongoCatalogMigrations { } async fn catalog_ledger(&self, target: &Target) -> Result, MigrationError> { - let migrations = MongoMigrations::open(&MongoTarget::new(&target.location), None).await?; + let migrations = MongoMigrations::open(&self.target(&target.location), None).await?; let rows = Runner::new(&migrations, "").catalog_ledger().await; migrations.close().await; rows @@ -87,7 +122,7 @@ impl CatalogMigrations for MongoCatalogMigrations { async fn lock(&self, target: &Target, timeout: Duration) -> Result { lock( - &MongoTarget::new(&target.location), + &self.target(&target.location), target.data_connection.is_some(), timeout, Timing::PRODUCTION, @@ -186,11 +221,17 @@ mod tests { #[test] fn the_backup_advice_names_both_databases_and_no_password() { let target = Target::at("mongodb://app:s3cret@localhost:27017/?replicaSet=rs0"); - let advice = MongoCatalogMigrations.backup_advice(&target); + let advice = MongoCatalogMigrations::new().backup_advice(&target); assert_eq!( advice, "back up both MongoDB databases, the catalog database extenddb_catalog and the data \ database extenddb_data" ); + let advice = + MongoCatalogMigrations::with_databases("t_catalog", "t_data").backup_advice(&target); + assert!( + advice.contains("t_catalog and the data database t_data"), + "{advice}" + ); } } diff --git a/crates/storage-mongodb/tests/migrations_startup.rs b/crates/storage-mongodb/tests/migrations_startup.rs new file mode 100644 index 000000000..dbd560f4b --- /dev/null +++ b/crates/storage-mongodb/tests/migrations_startup.rs @@ -0,0 +1,226 @@ +// SPDX-License-Identifier: Apache-2.0 + +//! The startup policy `serve` runs before it opens the catalog +//! (`[server] catalog_upgrade`, or `serve --migrate`), on released +//! catalogs: under `apply` a catalog behind the binary is migrated through +//! the lock `migrate --yes` takes, a current one is served with nothing +//! written, one that needs a person exits 5 with nothing written, a held +//! migration lock makes the server wait and then exit 6, and two servers +//! started together migrate once. + +mod migrations_support; + +use std::time::{Duration, Instant}; + +use bson::{Document, doc}; +use extenddb_storage::migrations::{ + CatalogStatus, MigrationError, Prepared, Startup, Target, exit, prepare_to_serve, +}; +use extenddb_storage_mongodb::migrations::MongoCatalogMigrations; +use migrations_support::{Deployment, fixture, server}; + +fn startup(apply: bool, lock_timeout: Duration) -> Startup<'static> { + Startup { + apply, + creates_uninitialized: false, + release: "1.0.0-test", + lock_timeout, + heartbeat: Startup::HEARTBEAT, + } +} + +/// The policy as `serve` runs it, through the backend's catalog migrations +/// on the deployment's databases. +async fn prepare(d: &Deployment, startup: &Startup<'_>) -> Result { + let migrations = MongoCatalogMigrations::with_databases(&d.target.catalog, &d.target.data); + let target = Target::at(&d.target.connection_string); + prepare_to_serve(&migrations, &target, startup, &|_| {}).await +} + +/// What a run could change: every document of every collection of both +/// databases. +async fn state(d: &Deployment) -> Vec<(String, Vec)> { + let mut found = Vec::new(); + for db in [d.catalog(), d.data()] { + for name in Deployment::collections(&db).await { + let documents = Deployment::documents(&db, &name).await; + found.push((format!("{}.{name}", db.name()), documents)); + } + } + found +} + +#[tokio::test(flavor = "multi_thread")] +async fn apply_migrates_a_released_catalog_and_refuse_writes_nothing() { + let Some(uri) = server() else { return }; + let d = Deployment::new(&uri, "start_apply").await; + fixture::load(&d, &fixture::read("0.1.14")).await; + let before = state(&d).await; + let err = prepare(&d, &startup(false, Duration::from_secs(10))) + .await + .expect_err("refused"); + assert_eq!(err.exit_code(), exit::PENDING, "{err:?}"); + assert!(state(&d).await == before, "refuse wrote to the catalog"); + + let prepared = prepare(&d, &startup(true, Duration::from_secs(10))) + .await + .expect("applied"); + let report = prepared.run.expect("a run"); + assert_eq!(report.applied.len(), 5, "{report:?}"); + assert_eq!(d.status().await, CatalogStatus::Current { version: 4 }); + d.drop_databases().await; +} + +#[tokio::test(flavor = "multi_thread")] +async fn apply_on_a_current_catalog_writes_nothing() { + let Some(uri) = server() else { return }; + let d = Deployment::new(&uri, "start_current").await; + fixture::load(&d, &fixture::read("0.1.14")).await; + d.migrate().await.expect("migrate"); + let before = state(&d).await; + let prepared = prepare(&d, &startup(true, Duration::from_secs(10))) + .await + .expect("served"); + assert_eq!(prepared, Prepared::default()); + assert!( + state(&d).await == before, + "a current catalog was written to" + ); + d.drop_databases().await; +} + +#[tokio::test(flavor = "multi_thread")] +async fn apply_on_a_catalog_that_needs_attention_exits_5_and_writes_nothing() { + let Some(uri) = server() else { return }; + let d = Deployment::new(&uri, "start_attention").await; + fixture::load(&d, &fixture::read("0.1.14")).await; + // An IAM user whose policy migration 2 cannot rewrite: both forms of + // one tag key, with different values. + let catalog = d.catalog(); + let account = catalog + .collection::("accounts") + .find_one(doc! {}) + .await + .expect("read accounts") + .expect("an account"); + let account = account + .get_str("account_id") + .or_else(|_| account.get_str("_id")) + .expect("an account id") + .to_owned(); + let now = bson::DateTime::now(); + catalog + .collection::("iam_users") + .insert_one(doc! { + "account_id": &account, + "user_name": "collider", + "user_arn": format!("arn:aws:iam::{account}:user/collider"), + "created_at": now, + }) + .await + .expect("a user"); + catalog + .collection::("iam_policies") + .insert_one(doc! { + "account_id": &account, + "principal_type": "user", + "principal_name": "collider", + "policy_name": "p", + "policy_document": { + "Version": "2012-10-17", + "Statement": [{ + "Effect": "Deny", + "Action": "dynamodb:*", + "Resource": "*", + "Condition": { "StringEquals": { + "aws:ResourceTag/env": "prod", + "dynamodb:ResourceTag/env": "dev", + } }, + }], + }, + "created_at": now, + }) + .await + .expect("a colliding policy"); + assert!( + matches!(d.status().await, CatalogStatus::NeedsAttention { .. }), + "the policy does not collide" + ); + let before = state(&d).await; + let err = prepare(&d, &startup(true, Duration::from_secs(10))) + .await + .expect_err("refused"); + assert!( + matches!( + err, + MigrationError::Status(CatalogStatus::NeedsAttention { .. }) + ), + "{err:?}" + ); + assert_eq!(err.exit_code(), exit::ATTENTION); + assert!( + state(&d).await == before, + "a refused run wrote to the catalog" + ); + d.drop_databases().await; +} + +/// Another migration's lock, as its claim writes it: the server waits for +/// it up to the timeout, then exits 6 with the catalog unchanged. +#[tokio::test(flavor = "multi_thread")] +async fn apply_waits_for_a_held_migration_lock_and_exits_6() { + let Some(uri) = server() else { return }; + let d = Deployment::new(&uri, "start_locked").await; + fixture::load(&d, &fixture::read("0.1.14")).await; + d.catalog() + .collection::("settings") + .insert_one(doc! { + "_id": "migration_lock", + "owner": "another", + "expires_at": bson::DateTime::from_millis( + bson::DateTime::now().timestamp_millis() + 120_000 + ), + }) + .await + .expect("another migration's lock"); + let before = state(&d).await; + let started = Instant::now(); + let err = prepare(&d, &startup(true, Duration::from_secs(2))) + .await + .expect_err("locked"); + assert!( + started.elapsed() >= Duration::from_millis(1800), + "it waited {:?}", + started.elapsed() + ); + assert!(matches!(err, MigrationError::Locked(_)), "{err:?}"); + assert_eq!(err.exit_code(), exit::LOCKED); + assert!( + state(&d).await == before, + "a server that waited wrote to the catalog" + ); + d.drop_databases().await; +} + +/// Two servers started together under `apply` on a released catalog: one +/// migrates it, and the other waits for the lock and finds nothing to do. +#[tokio::test(flavor = "multi_thread")] +async fn two_servers_started_together_with_apply_migrate_once() { + let Some(uri) = server() else { return }; + let d = Deployment::new(&uri, "start_two").await; + fixture::load(&d, &fixture::read("0.1.12")).await; + let apply = startup(true, Duration::from_secs(60)); + let (a, b) = tokio::join!(prepare(&d, &apply), prepare(&d, &apply)); + let mut applied: Vec = [a.expect("first"), b.expect("second")] + .iter() + .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .collect(); + applied.sort_unstable(); + assert_eq!( + applied, + [0, 5], + "one migrates and the other finds nothing to do" + ); + assert_eq!(d.status().await, CatalogStatus::Current { version: 4 }); + d.drop_databases().await; +} diff --git a/crates/storage-postgres/tests/migrations_startup.rs b/crates/storage-postgres/tests/migrations_startup.rs new file mode 100644 index 000000000..b0b3fc47a --- /dev/null +++ b/crates/storage-postgres/tests/migrations_startup.rs @@ -0,0 +1,211 @@ +// SPDX-License-Identifier: Apache-2.0 +//! The startup policy `serve` runs before it opens the catalog +//! (`[server] catalog_upgrade`, or `serve --migrate`), on released +//! catalogs: under `apply` a catalog behind the binary is migrated through +//! the lock `migrate --yes` takes, a current one is served with nothing +//! written, one that needs a person exits 5 with nothing written, a held +//! migration lock makes the server wait and then exit 6, and two servers +//! started together migrate once. See `migrations_support` for the +//! database these tests need. + +mod migrations_support; + +use std::time::{Duration, Instant}; + +use extenddb_storage::migrations::{ + CatalogStatus, MigrationError, Prepared, Startup, Target, exit, prepare_to_serve, +}; +use extenddb_storage_postgres::migrations::{Definitions, PostgresCatalogMigrations}; +use migrations_support::{ + LATEST, Scratch, base_conn, describe_pool, ledger, settings, skip, step_count, +}; + +/// The advisory key of the migration lock, `NAMESPACE` and `MIGRATION_KEY` +/// in `src/migrations/locks.rs`. +const NAMESPACE: i32 = 0x0045_4442; +const MIGRATION_KEY: i32 = 1; + +fn startup(apply: bool, lock_timeout: Duration) -> Startup<'static> { + Startup { + apply, + creates_uninitialized: false, + release: "1.0.0-test", + lock_timeout, + heartbeat: Startup::HEARTBEAT, + } +} + +/// The policy as `serve` runs it, on the catalog database's URL, which is +/// all the config file gives. +async fn prepare(s: &Scratch, startup: &Startup<'_>) -> Result { + let target = Target::at(s.catalog_url()); + prepare_to_serve(&PostgresCatalogMigrations, &target, startup, &|_| {}).await +} + +/// What a run could change: both databases' definitions, the catalog's +/// settings, and each ledger row with the time it was applied. +async fn state(s: &Scratch) -> (Definitions, Definitions, Vec<(String, String)>, Vec) { + let (catalog, data) = (s.catalog().await, s.data().await); + let mut rows = Vec::new(); + for p in [&catalog, &data] { + let applied: Vec<(i32, String)> = + sqlx::query_as("SELECT id, applied_at::text FROM extenddb_migrations ORDER BY id") + .fetch_all(p) + .await + .unwrap_or_default(); + rows.extend(applied.into_iter().map(|(id, at)| format!("{id} {at}"))); + } + let found = ( + describe_pool(&catalog).await, + describe_pool(&data).await, + settings(&catalog).await.into_iter().collect(), + rows, + ); + catalog.close().await; + data.close().await; + found +} + +#[tokio::test] +async fn apply_migrates_a_released_catalog_and_refuse_writes_nothing() { + let Some(base) = base_conn() else { + return skip("startup apply"); + }; + let s = Scratch::new(&base, "pgs_apply").await; + s.load("0.1.14").await; + let before = state(&s).await; + let err = prepare(&s, &startup(false, Duration::from_secs(10))) + .await + .expect_err("refused"); + assert_eq!(err.exit_code(), exit::PENDING, "{err:?}"); + assert!(state(&s).await == before, "refuse wrote to the catalog"); + + let prepared = prepare(&s, &startup(true, Duration::from_secs(10))) + .await + .expect("applied"); + let report = prepared.run.expect("a run"); + assert_eq!(report.applied.len(), step_count()); + assert_eq!(report.to, Some(LATEST)); + assert_eq!(s.status().await, CatalogStatus::Current { version: LATEST }); +} + +#[tokio::test] +async fn apply_on_a_current_catalog_writes_nothing() { + let Some(base) = base_conn() else { + return skip("startup current"); + }; + let s = Scratch::new(&base, "pgs_current").await; + s.load("0.1.14").await; + s.migrate_through(extenddb_storage::migrations::MigrationId::LATEST) + .await; + let before = state(&s).await; + let prepared = prepare(&s, &startup(true, Duration::from_secs(10))) + .await + .expect("served"); + assert_eq!(prepared, Prepared::default()); + assert!( + state(&s).await == before, + "a current catalog was written to" + ); +} + +#[tokio::test] +async fn apply_on_a_catalog_that_needs_attention_exits_5_and_writes_nothing() { + let Some(base) = base_conn() else { + return skip("startup attention"); + }; + let s = Scratch::new(&base, "pgs_attention").await; + s.load("0.1.14").await; + let catalog = s.catalog().await; + let both = r#"{"Version":"2012-10-17","Statement":[{"Effect":"Deny","Action":"dynamodb:*","Resource":"*","Condition":{"StringEquals":{"dynamodb:ResourceTag/env":"prod","aws:ResourceTag/env":"dev"}}}]}"#; + sqlx::query( + "UPDATE iam_policies SET policy_document = $1::jsonb WHERE principal_name = 'tester'", + ) + .bind(both) + .execute(&catalog) + .await + .unwrap(); + catalog.close().await; + let before = state(&s).await; + let err = prepare(&s, &startup(true, Duration::from_secs(10))) + .await + .expect_err("refused"); + assert!( + matches!( + err, + MigrationError::Status(CatalogStatus::NeedsAttention { .. }) + ), + "{err:?}" + ); + assert_eq!(err.exit_code(), exit::ATTENTION); + assert!( + state(&s).await == before, + "a refused run wrote to the catalog" + ); +} + +/// Another session holds the migration lock's key, as a running migration +/// does: the server waits for it up to the timeout, then exits 6 with the +/// catalog unchanged. +#[tokio::test] +async fn apply_waits_for_a_held_migration_lock_and_exits_6() { + let Some(base) = base_conn() else { + return skip("startup locked"); + }; + let s = Scratch::new(&base, "pgs_locked").await; + s.load("0.1.14").await; + let before = state(&s).await; + let holder = s.catalog().await; + let mut tx = holder.begin().await.unwrap(); + sqlx::query("SELECT pg_advisory_xact_lock($1, $2)") + .bind(NAMESPACE) + .bind(MIGRATION_KEY) + .execute(&mut *tx) + .await + .unwrap(); + let started = Instant::now(); + let err = prepare(&s, &startup(true, Duration::from_secs(2))) + .await + .expect_err("locked"); + assert!( + started.elapsed() >= Duration::from_millis(1800), + "it waited {:?}", + started.elapsed() + ); + assert!(matches!(err, MigrationError::Locked(_)), "{err:?}"); + assert_eq!(err.exit_code(), exit::LOCKED); + tx.rollback().await.unwrap(); + holder.close().await; + assert!( + state(&s).await == before, + "a server that waited wrote to the catalog" + ); +} + +/// Two servers started together under `apply` on a released catalog: one +/// migrates it, and the other waits for the lock and finds nothing to do. +#[tokio::test] +async fn two_servers_started_together_with_apply_migrate_once() { + let Some(base) = base_conn() else { + return skip("startup two"); + }; + let s = Scratch::new(&base, "pgs_two").await; + s.load("0.1.14").await; + let apply = startup(true, Duration::from_secs(60)); + let (a, b) = tokio::join!(prepare(&s, &apply), prepare(&s, &apply)); + let applied: Vec = [a.expect("first"), b.expect("second")] + .iter() + .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .collect(); + assert!( + applied.contains(&0) && applied.contains(&step_count()), + "one migrates and the other finds nothing to do: {applied:?}" + ); + let catalog = s.catalog().await; + assert_eq!( + ledger(&catalog).await.len(), + extenddb_storage::migrations::MigrationId::ALL.len() + ); + catalog.close().await; + assert_eq!(s.status().await, CatalogStatus::Current { version: LATEST }); +} diff --git a/crates/storage-sqlite/src/lib.rs b/crates/storage-sqlite/src/lib.rs index 567343611..ad128530c 100644 --- a/crates/storage-sqlite/src/lib.rs +++ b/crates/storage-sqlite/src/lib.rs @@ -226,8 +226,9 @@ fn sqlite_server_components_factory( std::sync::Arc::new(lock) }); // The catalog's status is read before the engine opens the file, so - // a server that refuses has written nothing. A dev build migrates - // instead, as `migrate --yes` would, copy included. + // a server that refuses has written nothing. `serve` has applied a + // catalog behind this binary already when its startup policy says + // to; a dev build creates a catalog in a missing or empty file. let dev = options.bootstrap_if_uninitialized; if let Some(lock) = &serve_lock { migrations::prepare_for_serve(&db_path, options.release, lock, dev) diff --git a/crates/storage-sqlite/src/migrations/commands.rs b/crates/storage-sqlite/src/migrations/commands.rs index 51fcc1a41..517c5c419 100644 --- a/crates/storage-sqlite/src/migrations/commands.rs +++ b/crates/storage-sqlite/src/migrations/commands.rs @@ -51,6 +51,12 @@ impl CatalogMigrations for SqliteCatalogMigrations { std::env::var_os("EXTENDDB__STORAGE__SQLITE__PATH").is_some_and(|v| !v.is_empty()) } + /// An in-memory database, which exists only on the connection of the + /// server that opened it. + fn in_process(&self, target: &Target) -> bool { + matches!(crate::serve_lock::database_file(&target.location), Ok(None)) + } + async fn status(&self, target: &Target) -> Result { catalog_status(&target.location).await } diff --git a/crates/storage-sqlite/src/migrations/mod.rs b/crates/storage-sqlite/src/migrations/mod.rs index 63252433f..430d7f03e 100644 --- a/crates/storage-sqlite/src/migrations/mod.rs +++ b/crates/storage-sqlite/src/migrations/mod.rs @@ -220,11 +220,13 @@ pub(crate) async fn migrate_holding( /// Decide whether a server may open the file database at `location`, whose /// lock the server holds: `Current` and `AheadCompatible` serve (the second /// with a warning naming the migrations above this binary's), and in a dev -/// build `Behind` and an `Uninitialized` file with no tables (missing or -/// empty) are migrated first. An `Uninitialized` file that holds tables is -/// another program's database, and is refused as the commands refuse it, -/// naming `extenddb init`, before anything writes to it. Every other status -/// refuses with [`MigrationError::Status`], in a dev build too. +/// build an `Uninitialized` file with no tables (missing or empty) is +/// created first. An `Uninitialized` file that holds tables is another +/// program's database, and is refused as the commands refuse it, naming +/// `extenddb init`, before anything writes to it. Every other status +/// refuses with [`MigrationError::Status`], in a dev build too: `serve` +/// applies a catalog behind this binary before it calls the factory, when +/// its startup policy says to (`[server] catalog_upgrade`). /// /// # Errors /// @@ -248,10 +250,6 @@ pub(crate) async fn prepare_for_serve( log_report(&migrate_holding(location, release, held).await?); Ok(()) } - CatalogStatus::Behind { .. } if dev => { - log_report(&migrate_holding(location, release, held).await?); - Ok(()) - } status => Err(MigrationError::Status(status)), } } diff --git a/crates/storage-sqlite/src/migrations/serve_tests.rs b/crates/storage-sqlite/src/migrations/serve_tests.rs index 5b432edcb..536156cc2 100644 --- a/crates/storage-sqlite/src/migrations/serve_tests.rs +++ b/crates/storage-sqlite/src/migrations/serve_tests.rs @@ -2,24 +2,29 @@ // SPDX-License-Identifier: Apache-2.0 //! The server factory reads the catalog status before it opens the -//! database: a production build serves only `Current` and `AheadCompatible` -//! and writes nothing when it refuses; a dev build migrates `Uninitialized` -//! and `Behind` first, and refuses the rest; an in-memory database is -//! created by the runner every time. The lock that keeps a migrator, a -//! second migrator and a server apart is tested here too. +//! database: it serves only `Current` and `AheadCompatible` and writes +//! nothing when it refuses; a dev build creates a missing or empty +//! database first; an in-memory database is created by the runner every +//! time. The startup policy `serve` applies before the factory, which +//! migrates a catalog behind the binary under `catalog_upgrade = "apply"`, +//! and the lock that keeps a migrator, a second migrator and a server +//! apart are tested here too. use std::path::Path; use std::time::Duration; -use extenddb_storage::migrations::{CatalogStatus, MigrationError, MigrationId, exit}; +use extenddb_storage::migrations::{ + CatalogMigrations, CatalogStatus, MigrationError, MigrationId, Prepared, Startup, Target, exit, + prepare_to_serve, +}; use extenddb_storage::server_components::{ BackendError, ServerComponents, ServerComponentsOptions, }; -use super::migrate; use super::tests::{ DEV_0_1_14, LATEST, RELEASE, copies, exec, load_dump, plain_pool, run, status, temp_db, }; +use super::{SqliteCatalogMigrations, migrate}; const COLLIDING: &str = r#"{"Version":"2012-10-17","Statement":[{"Effect":"Deny","Action":"dynamodb:*","Resource":"*","Condition":{"StringEquals":{"aws:ResourceTag/env":"prod","dynamodb:ResourceTag/env":"dev"}}}]}"#; @@ -125,13 +130,27 @@ async fn a_production_server_refuses_a_released_catalog_and_writes_nothing() { assert!(copies(&db).is_empty()); } +/// A dev build defaults to `catalog_upgrade = "apply"`: `serve` migrates a +/// released catalog through the startup policy, copy included, and the +/// factory then serves it. The factory alone refuses it, as in a +/// production build, so the policy is the one place that migrates. #[tokio::test] async fn a_dev_server_migrates_a_released_catalog_with_its_copy_and_serves() { let db = temp_db("serve-dev-released"); load_dump(&db, DEV_0_1_14).await; + let before = bytes(&db); + let err = refusal(start(&db.to_string_lossy(), true).await); + assert_eq!(err.exit_code(), exit::PENDING, "{err:?}"); + assert_eq!(bytes(&db), before, "the factory wrote to the database"); + let dev = Startup { + creates_uninitialized: true, + ..startup(true, Duration::from_secs(5)) + }; + let prepared = prepare(&db, &dev).await.expect("the policy migrates"); + assert!(!prepared.run.expect("a run").applied.is_empty()); let components = start(&db.to_string_lossy(), true) .await - .expect("a dev server migrates and starts"); + .expect("a dev server starts"); drop(components); assert_eq!( status(&db).await, @@ -144,6 +163,156 @@ async fn a_dev_server_migrates_a_released_catalog_with_its_copy_and_serves() { ); } +fn startup(apply: bool, lock_timeout: Duration) -> Startup<'static> { + Startup { + apply, + creates_uninitialized: false, + release: RELEASE, + lock_timeout, + heartbeat: Startup::HEARTBEAT, + } +} + +/// The startup policy `serve` runs before the factory, on the file at `db`. +async fn prepare(db: &Path, startup: &Startup<'_>) -> Result { + let target = Target::at(db.to_string_lossy()); + prepare_to_serve(&SqliteCatalogMigrations, &target, startup, &|_| {}).await +} + +/// `apply` migrates a released catalog before the server opens it, taking +/// the copy first, and a production server then serves it; `refuse` exits +/// 3 and writes nothing. +#[tokio::test] +async fn apply_migrates_a_released_catalog_before_the_server_opens_it() { + let db = temp_db("startup-apply"); + load_dump(&db, DEV_0_1_14).await; + let before = bytes(&db); + let err = prepare(&db, &startup(false, Duration::from_secs(5))) + .await + .expect_err("refused"); + assert_eq!(err.exit_code(), exit::PENDING, "{err:?}"); + assert_eq!(bytes(&db), before, "refuse wrote to the database"); + assert!(copies(&db).is_empty()); + + let prepared = prepare(&db, &startup(true, Duration::from_secs(5))) + .await + .expect("applied"); + let report = prepared.run.expect("a run"); + assert_eq!(report.from, None); + assert_eq!(report.to, Some(LATEST)); + assert_eq!(report.applied.len(), MigrationId::ALL.len()); + assert_eq!(copies(&db).len(), 1, "the copy is taken before the run"); + drop( + start(&db.to_string_lossy(), false) + .await + .expect("a production server serves the migrated catalog"), + ); + assert_eq!( + status(&db).await, + CatalogStatus::Current { version: LATEST } + ); +} + +#[tokio::test] +async fn apply_on_a_current_catalog_writes_nothing() { + let db = temp_db("startup-current"); + current_catalog(&db).await; + let before = bytes(&db); + let prepared = prepare(&db, &startup(true, Duration::from_secs(5))) + .await + .expect("served"); + assert_eq!(prepared, Prepared::default()); + assert_eq!(bytes(&db), before, "a current catalog was written to"); + assert!(copies(&db).is_empty()); +} + +#[tokio::test] +async fn apply_on_a_catalog_that_needs_attention_exits_5_and_writes_nothing() { + let db = temp_db("startup-attention"); + load_dump(&db, DEV_0_1_14).await; + collide(&db).await; + let before = bytes(&db); + let err = prepare(&db, &startup(true, Duration::from_secs(5))) + .await + .expect_err("refused"); + assert!( + matches!( + err, + MigrationError::Status(CatalogStatus::NeedsAttention { .. }) + ), + "{err:?}" + ); + assert_eq!(err.exit_code(), exit::ATTENTION); + assert_eq!(bytes(&db), before); + assert!(copies(&db).is_empty()); +} + +/// Another process holds the database's lock: `apply` waits for it up to +/// the timeout, then exits 6 with the catalog still behind and unchanged. +#[cfg(unix)] +#[tokio::test] +async fn apply_waits_for_a_held_lock_and_exits_6() { + let db = temp_db("startup-locked"); + load_dump(&db, DEV_0_1_14).await; + let before = bytes(&db); + let holder = crate::serve_lock::ServeLock::acquire(&db).expect("another process's lock"); + let started = std::time::Instant::now(); + let err = prepare(&db, &startup(true, Duration::from_millis(800))) + .await + .expect_err("locked"); + assert!( + started.elapsed() >= Duration::from_millis(700), + "it waited {:?}", + started.elapsed() + ); + assert!(matches!(err, MigrationError::Locked(_)), "{err:?}"); + assert_eq!(err.exit_code(), exit::LOCKED); + assert_eq!(bytes(&db), before); + assert!(copies(&db).is_empty()); + drop(holder); +} + +/// Two servers started together under `apply` on a released catalog: one +/// migrates it, and the other waits for the lock and finds nothing to do. +#[tokio::test] +async fn two_servers_started_together_with_apply_migrate_once() { + let db = temp_db("startup-two"); + load_dump(&db, DEV_0_1_14).await; + let apply = startup(true, Duration::from_secs(30)); + let (a, b) = tokio::join!(prepare(&db, &apply), prepare(&db, &apply)); + let applied: Vec = [a.expect("first"), b.expect("second")] + .iter() + .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .collect(); + assert!( + applied.contains(&0) && applied.contains(&MigrationId::ALL.len()), + "one migrates and the other finds nothing to do: {applied:?}" + ); + assert_eq!(copies(&db).len(), 1); + assert_eq!( + status(&db).await, + CatalogStatus::Current { version: LATEST } + ); +} + +/// An in-memory database belongs to the server that opens it: the policy +/// reads nothing, and the server creates the catalog. +#[tokio::test] +async fn an_in_memory_database_is_left_to_its_server() { + let target = Target::at(":memory:"); + assert!(SqliteCatalogMigrations.in_process(&target)); + assert!(!SqliteCatalogMigrations.in_process(&Target::at("/srv/x.sqlite"))); + let prepared = prepare_to_serve( + &SqliteCatalogMigrations, + &target, + &startup(true, Duration::from_secs(5)), + &|_| {}, + ) + .await + .expect("left to the server"); + assert_eq!(prepared, Prepared::default()); +} + #[tokio::test] async fn a_dev_server_creates_a_missing_catalog_and_its_rows() { let db = temp_db("serve-dev-missing"); @@ -164,11 +333,10 @@ async fn a_dev_server_creates_a_missing_catalog_and_its_rows() { assert!(copies(&db).is_empty(), "a new database has nothing to copy"); } -#[tokio::test] -async fn a_dev_server_refuses_a_catalog_that_needs_attention() { - let db = temp_db("serve-dev-attention"); - load_dump(&db, DEV_0_1_14).await; - let pool = plain_pool(&db).await; +/// Give a released catalog's first IAM user a policy migration 2 cannot +/// rewrite, so its status is `NeedsAttention`. +async fn collide(db: &Path) { + let pool = plain_pool(db).await; let (account, user): (String, String) = sqlx::query_as("SELECT account_id, user_name FROM iam_users LIMIT 1") .fetch_one(&pool) @@ -185,6 +353,13 @@ async fn a_dev_server_refuses_a_catalog_that_needs_attention() { .await .expect("policy"); pool.close().await; +} + +#[tokio::test] +async fn a_dev_server_refuses_a_catalog_that_needs_attention() { + let db = temp_db("serve-dev-attention"); + load_dump(&db, DEV_0_1_14).await; + collide(&db).await; let before = bytes(&db); let err = refusal(start(&db.to_string_lossy(), true).await); assert!( diff --git a/crates/storage/src/migrations/advice.rs b/crates/storage/src/migrations/advice.rs index a93528b7a..1f21aa89c 100644 --- a/crates/storage/src/migrations/advice.rs +++ b/crates/storage/src/migrations/advice.rs @@ -33,6 +33,10 @@ pub struct Advice<'a> { /// store wherever it runs and whatever `extenddb.toml` the directory /// holds. pub assignment: Option<&'a str>, + /// The message is a server's refusal: for a catalog behind the binary + /// it also names `serve --migrate`, which applies the migrations at + /// startup. + pub serving: bool, } impl Advice<'_> { @@ -101,6 +105,7 @@ pub struct AdviceFor { backup: String, config: Option, assignment: Option, + serving: bool, } impl AdviceFor { @@ -133,9 +138,17 @@ impl AdviceFor { }) }) .and_then(|m| m.location_assignment(target)), + serving: false, } } + /// The advice for a server's refusal ([`Advice::serving`]). + #[must_use] + pub fn for_server(mut self) -> Self { + self.serving = true; + self + } + /// The advice, borrowing these values. #[must_use] pub fn advice(&self) -> Advice<'_> { @@ -145,6 +158,7 @@ impl AdviceFor { backup: &self.backup, config: self.config.as_deref(), assignment: self.assignment.as_deref(), + serving: self.serving, } } } @@ -174,14 +188,18 @@ pub fn status_message(status: &CatalogStatus, advice: &Advice<'_>) -> String { is not detected while it runs.", ), }; - format!( + let mut message = format!( "{at}, and ExtendDB {release} needs migration {latest}.\n{}\n{stop}\n{backup}, \ then run:\n{}", pending_line(pending), advice.command("--yes"), release = advice.release, backup = capitalized(advice.backup), - ) + ); + if advice.serving { + message.push_str("\nor start this server with --migrate."); + } + message } // `init --config ` refuses a config file that exists, and this // catalog was found through one, so the command is named alone. @@ -291,7 +309,7 @@ pub fn stores_label(pending: &Pending, stores: usize) -> String { /// `Pending (all breaking): 2 name (catalog), ...`, or each kind beside its /// migration when the kinds differ. -fn pending_line(pending: &[Pending]) -> String { +pub(crate) fn pending_line(pending: &[Pending]) -> String { let groups = grouped(pending); let same = groups.windows(2).all(|w| w[0].0.kind == w[1].0.kind); let items: Vec = groups @@ -329,6 +347,7 @@ mod tests { backup: "back up the SQLite database file /var/lib/extenddb/extenddb.sqlite", config: Some("/etc/extenddb/extenddb.toml"), assignment: None, + serving: false, }; fn pending(kind: Kind) -> Vec { @@ -374,6 +393,48 @@ mod tests { ); } + /// A server's refusal of a catalog behind it ends with the other way to + /// apply the migrations, starting the server with `--migrate`. `migrate` + /// and `verify` print the same message without that line. + #[test] + fn a_server_refusing_a_catalog_behind_it_names_migrate() { + let status = CatalogStatus::Behind { + version: Some(1), + pending: pending(Kind::Breaking), + }; + let serving = Advice { + serving: true, + ..ADVICE + }; + let message = status_message(&status, &serving); + assert!( + message.ends_with( + "\n extenddb migrate --config /etc/extenddb/extenddb.toml --yes\nor start this \ + server with --migrate." + ), + "{message}" + ); + assert!(!status_message(&status, &ADVICE).contains("--migrate")); + // Only a catalog behind the binary can be migrated at startup: every + // other refusal is the same for a server. + let attention = CatalogStatus::NeedsAttention { + items: vec!["migration 2: a collision".to_owned()], + }; + assert_eq!( + status_message(&attention, &serving), + status_message(&attention, &ADVICE) + ); + let shown = super::AdviceFor::new( + "1.0.1", + "/srv/x.sqlite".to_owned(), + None, + &crate::migrations::Target::at("/srv/x.sqlite"), + Some("/etc/extenddb/extenddb.toml"), + ); + assert!(!shown.advice().serving); + assert!(shown.for_server().advice().serving); + } + #[test] fn a_catalog_with_no_ledger_says_to_stop_every_server() { let message = status_message( diff --git a/crates/storage/src/migrations/catalog.rs b/crates/storage/src/migrations/catalog.rs index 4c85389c8..4a168ddc7 100644 --- a/crates/storage/src/migrations/catalog.rs +++ b/crates/storage/src/migrations/catalog.rs @@ -185,6 +185,16 @@ pub trait CatalogMigrations: Send + Sync { false } + /// Whether the store at `target` exists only inside the server process + /// that opens it, as an in-memory SQLite database does: that server + /// creates the catalog when it starts, and no other process can read + /// its status, so `serve` reads none before it starts. Opens nothing; + /// `false` (the default) for every store another process can open. + fn in_process(&self, target: &Target) -> bool { + let _ = target; + false + } + /// The catalog status. Takes no lock and writes nothing, so it runs /// beside a server. async fn status(&self, target: &Target) -> Result; @@ -399,6 +409,28 @@ pub async fn run_with_status( migrations.run(lock, release, kind).await } +/// Take the migration lock for `target`, waiting up to `timeout` for +/// another migration and for running servers, run `kind` under it +/// ([`run_locked`]), and release it on every exit path. `migrate --yes` +/// and a server starting under `catalog_upgrade = "apply"` both run this. +/// +/// # Errors +/// +/// [`MigrationError::Locked`] (exit 6) when the lock or a running server +/// outlasted `timeout`, or as [`run_locked`]. +pub async fn run_with_lock( + migrations: &dyn CatalogMigrations, + target: &Target, + release: &str, + kind: RunKind, + timeout: Duration, +) -> Result { + let lock = migrations.lock(target, timeout).await?; + let report = run_locked(migrations, target, &lock, release, kind).await; + migrations.release(lock).await; + report +} + /// Delete the ledger rows of `id` under `lock`, which `migrations` took for /// `target`, after reading the status under the lock as [`run_locked`] /// does: a store that is not a catalog (`Uninitialized`) is refused, naming diff --git a/crates/storage/src/migrations/mod.rs b/crates/storage/src/migrations/mod.rs index aca1136e2..f8e39d5cb 100644 --- a/crates/storage/src/migrations/mod.rs +++ b/crates/storage/src/migrations/mod.rs @@ -14,6 +14,8 @@ //! - [`Runner::status`] computes the [`CatalogStatus`] that `serve`, //! `migrate` and `verify` act on, and [`CatalogStatus::exit_code`] maps it //! to the process exit status. +//! - [`prepare_to_serve`] is what `serve` does with the status before it +//! opens the catalog, by its startup policy (`[server] catalog_upgrade`). //! //! A backend implements [`MigrationBackend`]: reading and writing its ledgers, //! running one body inside one store's commit, and whatever its store needs @@ -28,6 +30,7 @@ mod ledger; mod record; mod registry; mod runner; +mod startup; mod status; mod table; @@ -41,7 +44,7 @@ pub use backend::{MigrationBackend, Step, StoreRef}; pub use catalog::{ AdminRole, CatalogMigrations, HeldLock, Listed, RunKind, StatusNote, Target, before_lock, binary_catalog_label, forget_locked, installed, policy_rewrite_lines, policy_rewrite_pending, - run_locked, run_with_status, + run_locked, run_with_lock, run_with_status, }; #[cfg(any(test, feature = "test-util"))] pub use checksum::check_released; @@ -51,6 +54,7 @@ pub use ledger::{CatalogTraces, LedgerColumns, LedgerRow, Outcome}; pub use record::{LedgerWrites, in_transaction, record_rows, sql_ledger_ddl}; pub use registry::{MigrationId, RELEASED_THROUGH}; pub use runner::Runner; +pub use startup::{Prepared, Startup, prepare_to_serve}; pub use status::{ AppliedStep, CatalogStatus, MigrationError, Pending, RunReport, behind_line, exit, stores_behind, diff --git a/crates/storage/src/migrations/startup.rs b/crates/storage/src/migrations/startup.rs new file mode 100644 index 000000000..eb2915c9a --- /dev/null +++ b/crates/storage/src/migrations/startup.rs @@ -0,0 +1,214 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! What `serve` does with the catalog before it opens it: the startup +//! policy, `[server] catalog_upgrade`, which `serve --migrate` sets to +//! `apply` for one run. +//! +//! The status is read with no lock. `Current` serves, and so does +//! `AheadCompatible`, with a warning. Under `apply` a catalog behind this +//! binary is migrated first, by the run `migrate --yes` makes +//! ([`run_with_lock`]): the migration lock, which waits for another +//! migration and for running servers, the status read again under it, so a +//! catalog another process migrated meanwhile is left as it is, `detect` +//! for every pending code body before the first write, the SQLite copy, the +//! runner, and the release. Under `refuse`, and under `apply` for every +//! other status, the server stops with the status's exit code: no setting +//! serves a catalog this binary cannot use. +//! +//! A dev build serves a store that is not a catalog yet, which its server +//! creates. A store that exists only inside the server (an in-memory SQLite +//! database) is created by the server when it starts and is not read here. + +use std::time::Duration; + +use tokio::time::Instant; + +use super::advice::pending_line; +use super::catalog::{CatalogMigrations, RunKind, Target, run_with_lock}; +use super::registry::MigrationId; +use super::status::{CatalogStatus, MigrationError, RunReport}; + +/// How a server starts on the catalog. +#[derive(Debug, Clone, Copy)] +pub struct Startup<'a> { + /// Apply the migrations of a catalog behind this binary instead of + /// refusing it (`catalog_upgrade = "apply"`). + pub apply: bool, + /// Leave a store that is not a catalog yet to the server, which creates + /// it: a dev build, which needs no `init`. + pub creates_uninitialized: bool, + /// The ExtendDB release, recorded in the ledger rows the run writes. + pub release: &'a str, + /// How long the run waits for the migration lock and for running + /// servers before it stops with exit 6. + pub lock_timeout: Duration, + /// How often a line says that the run is still going. Greater than + /// zero. + pub heartbeat: Duration, +} + +impl Startup<'_> { + /// How often a server says that its run is still going: well inside + /// the 15 s the npm launcher waits after the last such line. + pub const HEARTBEAT: Duration = Duration::from_secs(5); +} + +/// What [`prepare_to_serve`] did. +#[derive(Debug, Clone, Default, PartialEq, Eq)] +pub struct Prepared { + /// What the run under the migration lock did, or `None` when no run was + /// made. A report with no step applied means another process applied + /// the migrations while this one waited for the lock. + pub run: Option, + /// For the operator: the catalog is ahead of this binary by additive + /// migrations only, which this binary serves. + pub warning: Option, +} + +/// Read the status of the catalog at `target` and decide whether a server +/// may open it, applying its pending migrations first when `startup` says +/// so. `progress` receives a line for each step of a run, and one every +/// [`Startup::heartbeat`] while it goes on, which the server prints on +/// stderr. +/// +/// # Errors +/// +/// [`MigrationError::Status`] with the status a server refuses, which +/// carries its exit code; [`MigrationError::Locked`] (exit 6) when the lock +/// or a running server outlasted the timeout and the catalog is still +/// behind; or as [`run_with_lock`]. +pub async fn prepare_to_serve( + migrations: &dyn CatalogMigrations, + target: &Target, + startup: &Startup<'_>, + progress: &(dyn Fn(&str) + Send + Sync), +) -> Result { + if migrations.in_process(target) { + return Ok(Prepared::default()); + } + let status = migrations.status(target).await?; + match &status { + CatalogStatus::Current { .. } => Ok(Prepared::default()), + CatalogStatus::AheadCompatible { .. } => Ok(served_ahead(&status)), + CatalogStatus::Uninitialized if startup.creates_uninitialized => Ok(Prepared::default()), + CatalogStatus::Behind { version, pending } if startup.apply => { + let latest = MigrationId::LATEST.number(); + progress(&match version { + Some(v) => format!( + "the catalog is at migration {v} and this binary needs migration {latest}; \ + applying the pending migrations before the server starts" + ), + None => format!( + "the catalog has no migration ledger (a release before 1.0 created it); \ + applying migrations 1 to {latest} before the server starts" + ), + }); + progress(&pending_line(pending)); + apply(migrations, target, startup, progress).await + } + _ => Err(MigrationError::Status(status)), + } +} + +/// A catalog ahead of this binary by additive migrations, which it serves. +fn served_ahead(status: &CatalogStatus) -> Prepared { + Prepared { + run: None, + warning: Some(format!( + "{status}; serving it, because a binary may serve migrations it does not know when \ + every one of them is additive" + )), + } +} + +/// The run under the lock, with a line every heartbeat while it goes on. +async fn apply( + migrations: &dyn CatalogMigrations, + target: &Target, + startup: &Startup<'_>, + progress: &(dyn Fn(&str) + Send + Sync), +) -> Result { + progress(&format!( + "taking the migration lock, waiting up to {} s for a server or another migration", + startup.lock_timeout.as_secs() + )); + let started = Instant::now(); + let run = run_with_lock( + migrations, + target, + startup.release, + RunKind::Migrate, + startup.lock_timeout, + ); + let mut run = std::pin::pin!(run); + let mut heartbeat = tokio::time::interval_at(started + startup.heartbeat, startup.heartbeat); + let result = loop { + tokio::select! { + result = &mut run => break result, + _ = heartbeat.tick() => { + progress(&format!("in progress for {} s", started.elapsed().as_secs())); + } + } + }; + match result { + Ok(report) => { + for line in report_lines(&report) { + progress(&line); + } + Ok(Prepared { + run: Some(report), + warning: None, + }) + } + // A process that migrated the catalog while this one waited, and + // then started serving it, holds what the lock waits for. The + // catalog then needs nothing, and the server starts as `serve` + // would on it; the server's own checks decide whether it may. + Err(MigrationError::Locked(message)) => match migrations.status(target).await { + Ok(CatalogStatus::Current { .. }) => { + progress(MIGRATED_ELSEWHERE); + Ok(Prepared::default()) + } + Ok(status @ CatalogStatus::AheadCompatible { .. }) => { + progress(MIGRATED_ELSEWHERE); + Ok(served_ahead(&status)) + } + _ => Err(MigrationError::Locked(message)), + }, + Err(error) => Err(error), + } +} + +/// The line for a run that found the catalog migrated by another process. +const MIGRATED_ELSEWHERE: &str = + "nothing to apply: another process migrated the catalog while this one waited for the lock"; + +/// What a run did, one line each: the backend's lines (the SQLite copy's +/// path), each step with its notes indented below it, and the version the +/// catalog is at. +fn report_lines(report: &RunReport) -> Vec { + let mut lines = report.notes.clone(); + let several = report + .applied + .windows(2) + .any(|w| w[0].store_name != w[1].store_name); + for step in &report.applied { + lines.push(if several { + format!("applied {} {} in {}", step.id, step.name, step.store_name) + } else { + format!("applied {} {}", step.id, step.name) + }); + lines.extend(step.notes.iter().map(|note| format!(" {note}"))); + } + if report.applied.is_empty() { + lines.push(MIGRATED_ELSEWHERE.to_owned()); + } else if let Some(to) = report.to { + lines.push(format!("the catalog is at migration {to}")); + } + lines +} + +#[cfg(test)] +#[path = "startup_tests.rs"] +mod tests; diff --git a/crates/storage/src/migrations/startup_tests.rs b/crates/storage/src/migrations/startup_tests.rs new file mode 100644 index 000000000..971d39091 --- /dev/null +++ b/crates/storage/src/migrations/startup_tests.rs @@ -0,0 +1,375 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! The startup policy on a backend that records what it is asked: which +//! statuses serve, refuse or migrate, when the lock is taken, and the lines +//! a run prints. + +use std::collections::VecDeque; +use std::sync::Mutex; +use std::time::Duration; + +use async_trait::async_trait; + +use super::{Prepared, Startup, prepare_to_serve}; +use crate::migrations::{ + AppliedStep, CatalogMigrations, CatalogStatus, HeldLock, Kind, LedgerRow, Listed, + MigrationError, MigrationId, Pending, RunKind, RunReport, StoreKind, Target, exit, +}; + +struct Fake { + /// The statuses the next reads return, the last one repeated. + statuses: Mutex>, + lock: Result<(), MigrationError>, + report: RunReport, + run_takes: Duration, + in_process: bool, + calls: Mutex>, +} + +impl Fake { + fn new(statuses: &[CatalogStatus]) -> Self { + Self { + statuses: Mutex::new(statuses.iter().cloned().collect()), + lock: Ok(()), + report: applied_report(), + run_takes: Duration::ZERO, + in_process: false, + calls: Mutex::new(Vec::new()), + } + } + + fn calls(&self) -> Vec<&'static str> { + self.calls.lock().unwrap().clone() + } + + fn call(&self, name: &'static str) { + self.calls.lock().unwrap().push(name); + } +} + +#[async_trait] +impl CatalogMigrations for Fake { + fn listed(&self, _id: MigrationId) -> Listed { + Listed::NotApplicable("fake") + } + fn backup_advice(&self, target: &Target) -> String { + format!("back up {}", target.location) + } + fn in_process(&self, _target: &Target) -> bool { + self.in_process + } + async fn status(&self, _target: &Target) -> Result { + self.call("status"); + let mut statuses = self.statuses.lock().unwrap(); + let status = statuses.front().cloned().expect("a status"); + if statuses.len() > 1 { + statuses.pop_front(); + } + Ok(status) + } + async fn catalog_ledger(&self, _: &Target) -> Result, MigrationError> { + Ok(Vec::new()) + } + async fn lock(&self, target: &Target, _: Duration) -> Result { + self.call("lock"); + self.lock + .clone() + .map(|()| HeldLock::new(target.location.as_str(), ())) + } + async fn run( + &self, + _lock: &HeldLock, + _release: &str, + kind: RunKind, + ) -> Result { + assert_eq!(kind, RunKind::Migrate); + self.call("run"); + tokio::time::sleep(self.run_takes).await; + Ok(self.report.clone()) + } + async fn forget(&self, _lock: &HeldLock, _id: u32) -> Result<(), MigrationError> { + unreachable!("a server forgets nothing") + } + async fn release(&self, lock: HeldLock) { + self.call("release"); + drop(lock); + } +} + +fn behind() -> CatalogStatus { + CatalogStatus::Behind { + version: Some(1), + pending: MigrationId::ALL + .iter() + .skip(1) + .map(|id| Pending { + id: id.number(), + name: id.name(), + store: StoreKind::Catalog, + store_name: "db".to_owned(), + kind: Kind::Breaking, + }) + .collect(), + } +} + +fn current() -> CatalogStatus { + CatalogStatus::Current { + version: MigrationId::LATEST.number(), + } +} + +fn applied_report() -> RunReport { + RunReport { + from: Some(1), + to: Some(MigrationId::LATEST.number()), + applied: MigrationId::ALL + .iter() + .skip(1) + .map(|id| AppliedStep { + id: id.number(), + name: id.name(), + store_name: "db".to_owned(), + notes: Vec::new(), + }) + .collect(), + notes: vec!["copied the database to db.pre-migration-1-to-4-x".to_owned()], + } +} + +const fn startup(apply: bool) -> Startup<'static> { + Startup { + apply, + creates_uninitialized: false, + release: "1.0.0-test", + lock_timeout: Duration::from_secs(1), + heartbeat: Duration::from_millis(50), + } +} + +/// Run the policy, returning its outcome and the lines it reported. +async fn prepare( + fake: &Fake, + startup: &Startup<'_>, +) -> (Result, Vec) { + let lines = Mutex::new(Vec::new()); + let result = prepare_to_serve(fake, &Target::at("db"), startup, &|line| { + lines.lock().unwrap().push(line.to_owned()); + }) + .await; + (result, lines.into_inner().unwrap()) +} + +#[tokio::test] +async fn refuse_stops_a_catalog_behind_with_exit_3_and_takes_no_lock() { + let fake = Fake::new(&[behind()]); + let (result, lines) = prepare(&fake, &startup(false)).await; + let error = result.expect_err("refused"); + assert_eq!(error, MigrationError::Status(behind())); + assert_eq!(error.exit_code(), exit::PENDING); + assert_eq!(fake.calls(), ["status"]); + assert!(lines.is_empty(), "{lines:?}"); +} + +/// Under `apply` the run is `migrate --yes`'s: the lock, the status read +/// again under it, the run, and the release. +#[tokio::test] +async fn apply_migrates_a_catalog_behind_under_the_lock_and_releases_it() { + let fake = Fake::new(&[behind()]); + let (result, lines) = prepare(&fake, &startup(true)).await; + let prepared = result.expect("applied"); + assert_eq!(prepared.run, Some(applied_report())); + assert_eq!(prepared.warning, None); + assert_eq!(fake.calls(), ["status", "lock", "status", "run", "release"]); + let latest = MigrationId::LATEST.number(); + assert_eq!( + lines[0], + format!( + "the catalog is at migration 1 and this binary needs migration {latest}; applying \ + the pending migrations before the server starts" + ) + ); + assert!( + lines[1].starts_with("Pending (all breaking): 2 "), + "{lines:?}" + ); + assert_eq!( + lines[2], + "taking the migration lock, waiting up to 1 s for a server or another migration" + ); + assert_eq!(lines[3], "copied the database to db.pre-migration-1-to-4-x"); + assert_eq!(lines[4], "applied 2 resource_tag_condition_keys"); + assert_eq!( + lines.last().map(String::as_str), + Some(format!("the catalog is at migration {latest}").as_str()) + ); +} + +#[tokio::test] +async fn a_current_catalog_serves_with_no_lock_and_no_run() { + for apply in [false, true] { + let fake = Fake::new(&[current()]); + let (result, lines) = prepare(&fake, &startup(apply)).await; + assert_eq!(result, Ok(Prepared::default())); + assert_eq!(fake.calls(), ["status"]); + assert!(lines.is_empty(), "{lines:?}"); + } +} + +#[tokio::test] +async fn a_catalog_ahead_by_additive_migrations_serves_with_a_warning() { + let ahead = CatalogStatus::AheadCompatible { + version: MigrationId::LATEST.number() + 1, + unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], + }; + for apply in [false, true] { + let fake = Fake::new(&[ahead.clone()]); + let (result, _) = prepare(&fake, &startup(apply)).await; + let prepared = result.expect("served"); + assert_eq!(prepared.run, None); + let warning = prepared.warning.expect("a warning"); + assert!(warning.contains("additive"), "{warning}"); + assert_eq!(fake.calls(), ["status"]); + } +} + +/// No setting serves a catalog this binary cannot use: under `apply` every +/// status but `Behind` is refused as under `refuse`, before any lock. +#[tokio::test] +async fn apply_refuses_every_other_status_with_its_code_and_takes_no_lock() { + let cases = [ + ( + CatalogStatus::NeedsAttention { + items: vec!["migration 2: a collision".to_owned()], + }, + exit::ATTENTION, + ), + ( + CatalogStatus::Changed { + id: 1, + store_name: "db".to_owned(), + recorded: "a".to_owned(), + expected: "b".to_owned(), + }, + exit::ATTENTION, + ), + ( + CatalogStatus::WrittenByOlderRelease { + trace: "catalog_version is 0.0.4".to_owned(), + }, + exit::ATTENTION, + ), + ( + CatalogStatus::AheadIncompatible { + unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], + }, + exit::AHEAD_INCOMPATIBLE, + ), + (CatalogStatus::Uninitialized, exit::ERROR), + ]; + for (status, code) in cases { + for apply in [false, true] { + let fake = Fake::new(&[status.clone()]); + let (result, lines) = prepare(&fake, &startup(apply)).await; + let error = result.expect_err("refused"); + assert_eq!(error, MigrationError::Status(status.clone())); + assert_eq!(error.exit_code(), code, "{status:?}"); + assert_eq!(fake.calls(), ["status"], "{status:?}"); + assert!(lines.is_empty(), "{lines:?}"); + } + } +} + +/// A dev build serves a store that is not a catalog yet, which its server +/// creates; a production build refuses it with exit 1. +#[tokio::test] +async fn a_dev_build_leaves_an_uninitialized_store_to_the_server() { + let fake = Fake::new(&[CatalogStatus::Uninitialized]); + let dev = Startup { + creates_uninitialized: true, + ..startup(false) + }; + let (result, _) = prepare(&fake, &dev).await; + assert_eq!(result, Ok(Prepared::default())); + assert_eq!(fake.calls(), ["status"]); +} + +/// An in-memory store is created by the server that opens it: nothing is +/// read before. +#[tokio::test] +async fn an_in_process_store_is_not_read() { + let mut fake = Fake::new(&[behind()]); + fake.in_process = true; + let (result, _) = prepare(&fake, &startup(true)).await; + assert_eq!(result, Ok(Prepared::default())); + assert!(fake.calls().is_empty(), "{:?}", fake.calls()); +} + +/// A lock that stays held past the timeout stops the server with exit 6 +/// while the catalog is still behind. +#[tokio::test] +async fn a_lock_held_past_the_timeout_exits_6() { + let mut fake = Fake::new(&[behind()]); + fake.lock = Err(MigrationError::Locked( + "another migration holds it".to_owned(), + )); + let (result, _) = prepare(&fake, &startup(true)).await; + let error = result.expect_err("locked"); + assert_eq!(error.exit_code(), exit::LOCKED); + assert_eq!(error.to_string(), "another migration holds it"); + // The status is read again after the wait, and the backend ran nothing. + assert_eq!(fake.calls(), ["status", "lock", "status"]); +} + +/// Another process migrated the catalog while this one waited, and holds +/// what the lock waits for because it serves: the catalog needs nothing, +/// and the server starts as `serve` would. +#[tokio::test] +async fn a_catalog_migrated_by_another_process_during_the_wait_serves() { + let mut fake = Fake::new(&[behind(), current()]); + fake.lock = Err(MigrationError::Locked("a server serves it".to_owned())); + let (result, lines) = prepare(&fake, &startup(true)).await; + assert_eq!(result, Ok(Prepared::default())); + assert_eq!(fake.calls(), ["status", "lock", "status"]); + assert_eq!( + lines.last().map(String::as_str), + Some(super::MIGRATED_ELSEWHERE) + ); +} + +/// The status read under the lock finds the catalog migrated: the run +/// applies nothing, and says so. +#[tokio::test] +async fn a_run_that_finds_the_catalog_migrated_under_the_lock_applies_nothing() { + let mut fake = Fake::new(&[behind(), current()]); + fake.report = RunReport { + from: Some(MigrationId::LATEST.number()), + to: Some(MigrationId::LATEST.number()), + ..RunReport::default() + }; + let (result, lines) = prepare(&fake, &startup(true)).await; + let prepared = result.expect("served"); + assert!(prepared.run.expect("a run").applied.is_empty()); + assert_eq!(fake.calls(), ["status", "lock", "status", "run", "release"]); + assert_eq!( + lines.last().map(String::as_str), + Some(super::MIGRATED_ELSEWHERE) + ); +} + +/// While the run goes on, a line says so every heartbeat, which is what +/// keeps the npm launcher waiting through a long migration. +#[tokio::test] +async fn a_long_run_reports_that_it_is_in_progress_every_heartbeat() { + let mut fake = Fake::new(&[behind()]); + fake.run_takes = Duration::from_millis(400); + let (result, lines) = prepare(&fake, &startup(true)).await; + result.expect("applied"); + let beats = lines + .iter() + .filter(|l| l.starts_with("in progress for ")) + .count(); + // Eight at the 50 ms heartbeat; fewer only when the host is loaded. + assert!(beats >= 4, "{beats} heartbeats: {lines:?}"); +} From 5d7e9b153299ec260757066f95d9993de71d0392 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Fri, 30 Oct 2026 22:54:35 +0000 Subject: [PATCH 02/14] feat(npm): count the startup timeout from the last migration progress line A dev server applies a catalog's pending migrations before it serves, which on a large database takes longer than the launcher's startup timeout. The server prints a line on stderr for each step of the run, each starting with "catalog migration: ", and one every 5 s while it goes on. The launcher now counts startupTimeoutMs, 15 s by default, from the later of its start and the last such line, so it waits for a server that reports progress and gives up on one that prints nothing. The wait moves to startup.js, which the package ships. The launcher test runs a stand-in server that answers /health after 20 s: with a progress line every 2 s it is waited for, and with none the wait ends at 15 s. --- packaging/npm/README.md | 2 +- packaging/npm/index.js | 46 +++---------- packaging/npm/package.json | 1 + packaging/npm/startup.js | 101 ++++++++++++++++++++++++++++ packaging/npm/test/fake-server.js | 42 ++++++++++++ packaging/npm/test/launcher.test.js | 67 +++++++++++++++++- 6 files changed, 221 insertions(+), 38 deletions(-) create mode 100644 packaging/npm/startup.js create mode 100644 packaging/npm/test/fake-server.js diff --git a/packaging/npm/README.md b/packaging/npm/README.md index cbacb5e8e..7d7de08b4 100644 --- a/packaging/npm/README.md +++ b/packaging/npm/README.md @@ -50,7 +50,7 @@ calls in an async function (top-level `await` is ESM-only). | `dbPath` | data dir | SQLite file location (file mode only). | | `port` | ephemeral | Fixed port instead of an OS-assigned one. | | `binary` | bundled | Path to an `extenddb` binary, overriding the bundled one. | -| `startupTimeoutMs` | `15000` | How long to wait for the server to become healthy. | +| `startupTimeoutMs` | `15000` | How long to wait for the server to become healthy, counted from the last line of catalog migration progress it prints. | The returned object carries `endpoint`, `port`, `credentials`, `region`, `storage`, and `stop()`, which shuts the server down and resolves when the diff --git a/packaging/npm/index.js b/packaging/npm/index.js index 5afba35a8..8ea981350 100644 --- a/packaging/npm/index.js +++ b/packaging/npm/index.js @@ -5,10 +5,10 @@ const { spawn } = require("node:child_process"); const net = require("node:net"); -const http = require("node:http"); const os = require("node:os"); const path = require("node:path"); const fs = require("node:fs"); +const { waitForStartup } = require("./startup.js"); // AWS's documented example credential: the dev server seeds it as the // well-known default signing credential (dev-mode builds only). @@ -63,31 +63,6 @@ function freePort() { }); } -function waitHealthy(endpoint, timeoutMs) { - const deadline = Date.now() + timeoutMs; - return new Promise((resolve, reject) => { - const probe = () => { - const req = http.get(`${endpoint}/health`, (res) => { - res.resume(); - if (res.statusCode === 200) return resolve(); - retry(); - }); - req.on("error", retry); - req.setTimeout(1000, () => { - req.destroy(); - retry(); - }); - }; - const retry = () => { - if (Date.now() > deadline) { - return reject(new Error(`extenddb did not become healthy within ${timeoutMs}ms`)); - } - setTimeout(probe, 100); - }; - probe(); - }); -} - /** * Resolve the storage location from the options. * @@ -123,7 +98,9 @@ function resolveStorage(options) { * default ./.extenddb/data.db). * @param {number} [options.port] Fixed port (default: ephemeral). * @param {string} [options.binary] Path to the extenddb dev binary. - * @param {number} [options.startupTimeoutMs] Readiness timeout (default 15000). + * @param {number} [options.startupTimeoutMs] Readiness timeout (default + * 15000), counted from the start or from the last catalog migration line + * the server printed, whichever is later. * @returns {Promise<{endpoint: string, port: number, credentials: object, * region: string, storage: string, stop: () => Promise}>} */ @@ -145,10 +122,6 @@ async function start(options = {}) { cwd, stdio: ["ignore", "ignore", "pipe"], }); - let stderrTail = ""; - child.stderr.on("data", (d) => { - stderrTail = (stderrTail + d.toString()).slice(-4000); - }); const endpoint = `http://127.0.0.1:${port}`; const spawned = new Promise((_, reject) => { @@ -169,12 +142,13 @@ async function start(options = {}) { } reject(err); }); - child.on("exit", (code) => - reject(new Error(`extenddb exited during startup (code ${code}): ${stderrTail}`)) - ); }); - await Promise.race([waitHealthy(endpoint, options.startupTimeoutMs ?? 15000), spawned]); - child.removeAllListeners("exit"); + // A dev server migrates an existing database before it serves; while it + // reports progress, the timeout waits. + await Promise.race([ + waitForStartup(child, endpoint, options.startupTimeoutMs ?? 15000), + spawned, + ]); let stopped = false; const stop = () => diff --git a/packaging/npm/package.json b/packaging/npm/package.json index b629ec979..95a79d6ba 100644 --- a/packaging/npm/package.json +++ b/packaging/npm/package.json @@ -15,6 +15,7 @@ }, "files": [ "index.js", + "startup.js", "bin/", "NOTICE" ], diff --git a/packaging/npm/startup.js b/packaging/npm/startup.js new file mode 100644 index 000000000..2655056bc --- /dev/null +++ b/packaging/npm/startup.js @@ -0,0 +1,101 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +"use strict"; + +const http = require("node:http"); + +// The server starts each line it prints on stderr while it migrates its +// database before serving with this. A dev build applies pending catalog +// migrations at startup, and a large database can take longer than the +// startup timeout, so the timeout counts from the last such line. +const PROGRESS_PREFIX = "catalog migration: "; + +/** + * Wait for `child`, a server spawned to listen on `endpoint`, to answer + * GET /health with 200. + * + * Rejects when the child exits first, naming its exit code and the end of + * its stderr, or when `timeoutMs` pass without an answer, counted from the + * start or from the last migration progress line the child printed on + * stderr, whichever is later. + * + * @param {import("node:child_process").ChildProcess} child Spawned with a piped stderr. + * @param {string} endpoint The server's base URL. + * @param {number} timeoutMs How long to wait after the start or the last progress line. + * @returns {Promise} + */ +function waitForStartup(child, endpoint, timeoutMs) { + return new Promise((resolve, reject) => { + let tail = ""; + let partial = ""; + let lastProgressAt = Date.now(); + let progressSeen = false; + let settled = false; + let timer = null; + + // stderr stays drained after startup too, or a full pipe would stop + // the server at its next log line. + child.stderr.on("data", (d) => { + const text = d.toString(); + tail = (tail + text).slice(-4000); + const lines = (partial + text).split("\n"); + // The start of an unfinished line is all the prefix check needs. + partial = lines.pop().slice(0, 4096); + if (lines.some((line) => line.startsWith(PROGRESS_PREFIX))) { + lastProgressAt = Date.now(); + progressSeen = true; + } + }); + + const onExit = (code) => + finish(reject, new Error(`extenddb exited during startup (code ${code}): ${tail}`)); + child.once("exit", onExit); + + function finish(settle, value) { + if (settled) return; + settled = true; + clearTimeout(timer); + child.removeListener("exit", onExit); + settle(value); + } + + function retry() { + if (settled) return; + if (Date.now() > lastProgressAt + timeoutMs) { + const after = progressSeen ? " of its last catalog migration progress line" : ""; + finish(reject, new Error(`extenddb did not become healthy within ${timeoutMs}ms${after}`)); + return; + } + timer = setTimeout(probe, 100); + } + + function probe() { + if (settled) return; + let answered = false; + const next = () => { + if (answered) return; + answered = true; + retry(); + }; + const req = http.get(`${endpoint}/health`, (res) => { + res.resume(); + if (res.statusCode === 200) { + answered = true; + finish(resolve); + return; + } + next(); + }); + req.on("error", next); + req.setTimeout(1000, () => { + req.destroy(); + next(); + }); + } + + probe(); + }); +} + +module.exports = { PROGRESS_PREFIX, waitForStartup }; diff --git a/packaging/npm/test/fake-server.js b/packaging/npm/test/fake-server.js new file mode 100644 index 000000000..2ff7d217e --- /dev/null +++ b/packaging/npm/test/fake-server.js @@ -0,0 +1,42 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +// A stand-in for a dev server that migrates its database before it serves, +// for the launcher's startup timeout tests. Run with node: +// FAKE_PORT= FAKE_READY_AFTER_MS= FAKE_PROGRESS_EVERY_MS= node fake-server.js +// It prints a migration progress line on stderr every FAKE_PROGRESS_EVERY_MS +// (none when 0) until FAKE_READY_AFTER_MS have passed, then answers GET +// /health with 200 on 127.0.0.1:FAKE_PORT until it is killed. + +"use strict"; + +const http = require("node:http"); + +// What `extenddb serve` starts each of these lines with (PROGRESS_PREFIX +// in crates/app/src/serve_catalog.rs), written out here rather than read +// from the launcher, so a launcher that stopped matching the server's +// lines fails the test. +const PROGRESS_PREFIX = "catalog migration: "; + +const port = Number(process.env.FAKE_PORT); +const readyAfter = Number(process.env.FAKE_READY_AFTER_MS); +const progressEvery = Number(process.env.FAKE_PROGRESS_EVERY_MS); +const started = Date.now(); + +let progress = null; +if (progressEvery > 0) { + progress = setInterval(() => { + const seconds = Math.floor((Date.now() - started) / 1000); + process.stderr.write(`${PROGRESS_PREFIX}in progress for ${seconds} s\n`); + }, progressEvery); +} + +setTimeout(() => { + if (progress) clearInterval(progress); + http + .createServer((req, res) => { + res.writeHead(req.url === "/health" ? 200 : 404); + res.end(); + }) + .listen(port, "127.0.0.1"); +}, readyAfter); diff --git a/packaging/npm/test/launcher.test.js b/packaging/npm/test/launcher.test.js index 02188caa0..f15376627 100644 --- a/packaging/npm/test/launcher.test.js +++ b/packaging/npm/test/launcher.test.js @@ -15,14 +15,21 @@ // if memory mode silently fell back to a file, it would fail. // 3. dbPath + memory together are refused: silently ignoring the path a // caller asked to persist to would be data loss by configuration. +// 4. The startup timeout counts from the last line of catalog migration +// progress the server prints: a dev server migrating a large database +// reports progress for longer than the timeout and then serves. The +// server here is test/fake-server.js, which can take 20 s to start. "use strict"; const assert = require("node:assert"); const fs = require("node:fs"); +const net = require("node:net"); const os = require("node:os"); const path = require("node:path"); +const { spawn } = require("node:child_process"); const { start } = require("../index.js"); +const { waitForStartup } = require("../startup.js"); if (!process.env.EXTENDDB_BINARY) { console.error("EXTENDDB_BINARY must point at a dev-mode extenddb binary"); @@ -124,6 +131,42 @@ async function createProbeTable(eb) { } } +function freePort() { + return new Promise((resolve, reject) => { + const srv = net.createServer(); + srv.listen(0, "127.0.0.1", () => { + const { port } = srv.address(); + srv.close((err) => (err ? reject(err) : resolve(port))); + }); + srv.on("error", reject); + }); +} + +// Wait, with the launcher's 15 s default, for a fake server that answers +// /health after 20 s and prints a progress line every `progressEveryMs` +// until then (none when 0). Resolves with the outcome and how long it took. +async function fakeStartup(progressEveryMs) { + const port = await freePort(); + const child = spawn(process.execPath, [path.join(__dirname, "fake-server.js")], { + env: { + ...process.env, + FAKE_PORT: String(port), + FAKE_READY_AFTER_MS: "20000", + FAKE_PROGRESS_EVERY_MS: String(progressEveryMs), + }, + stdio: ["ignore", "ignore", "pipe"], + }); + const started = Date.now(); + try { + await waitForStartup(child, `http://127.0.0.1:${port}`, 15000); + return { error: null, elapsed: Date.now() - started }; + } catch (error) { + return { error, elapsed: Date.now() - started }; + } finally { + child.kill(); + } +} + async function main() { const scratch = fs.mkdtempSync(path.join(os.tmpdir(), "extenddb-launcher-test-")); const dbPath = path.join(scratch, "persisted.db"); @@ -216,7 +259,29 @@ async function main() { ); } - console.log("launcher tests: 4 scenarios passed"); + // 5. The startup timeout applies after the last migration progress line: + // a server that reports progress every 2 s for 20 s is waited for, and + // one that prints nothing for 20 s is given up on at 15 s. + { + const [reporting, silent] = await Promise.all([fakeStartup(2000), fakeStartup(0)]); + assert.strictEqual( + reporting.error, + null, + `a server reporting migration progress must be waited for: ${reporting.error}` + ); + assert.ok( + reporting.elapsed > 15000, + `the reporting server answered after ${reporting.elapsed}ms, within the plain timeout` + ); + assert.ok(silent.error, "a server that prints nothing must time out"); + assert.match(silent.error.message, /did not become healthy within 15000ms$/); + assert.ok( + silent.elapsed >= 15000 && silent.elapsed < 18000, + `the silent server was given up on after ${silent.elapsed}ms, not at 15 s` + ); + } + + console.log("launcher tests: 5 scenarios passed"); } main().catch((err) => { From 46333c7866bbddd441b8743165c78a7fc9898983 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Fri, 30 Oct 2026 22:54:35 +0000 Subject: [PATCH 03/14] ci: check serve's startup policy in the catalog lock scripts On each backend the catalog lock script puts the catalog behind the release binary and checks that serve exits 3 with a message that names --migrate. In daemon mode the exit code and the message reach the invoking process. The script then holds the migration lock and checks that serve --migrate waits until catalog_upgrade_lock_timeout and exits 6. Once the lock is free serve --migrate applies the migration and serves. The SQLite script also checks catalog_upgrade = "apply" in the config file, EXTENDDB__SERVER__CATALOG_UPGRADE=apply and serve --migrate in daemon mode. It checks that serve --migrate writes nothing to a current catalog, exits 5 with nothing written on a catalog that needs a person, and that two serve --migrate started together on a released catalog migrate it once, with one copy. devtools/run-mongodb-tests runs the startup policy tests against its replica set and the PostgreSQL job without pgvector runs them too. --- .github/workflows/integration.yml | 1 + devtools/check-cassandra-catalog-lock | 65 ++++++++ devtools/check-mongodb-catalog-lock | 32 ++++ devtools/check-postgres-catalog-lock | 66 ++++++++ devtools/check-sqlite-catalog-lock | 216 ++++++++++++++++++++++++++ devtools/run-mongodb-tests | 3 +- 6 files changed, 382 insertions(+), 1 deletion(-) diff --git a/.github/workflows/integration.yml b/.github/workflows/integration.yml index dd26dae46..8d928b80f 100644 --- a/.github/workflows/integration.yml +++ b/.github/workflows/integration.yml @@ -495,6 +495,7 @@ jobs: cargo test --release -p extenddb-storage-postgres --test migrations_fresh --test migrations_released --test migrations_crash --test migrations_golden --test migrations_guards --test migrations_runs + --test migrations_startup # The daemonized server logs to syslog; dump it so server-side failures # are diagnosable from the job log. diff --git a/devtools/check-cassandra-catalog-lock b/devtools/check-cassandra-catalog-lock index d27061206..219395d20 100755 --- a/devtools/check-cassandra-catalog-lock +++ b/devtools/check-cassandra-catalog-lock @@ -32,6 +32,11 @@ with `init` and removes them at the end. and neither 2, which is not convergent, nor 3 and 4, which do not apply on Cassandra; migrate --forget 2 and the migrate --yes that applies 2 again run, and serve runs; +- the startup policy on a catalog behind this binary: serve exits 3 and + names --migrate, and in daemon mode the invoking process exits 3 with the + message on its stderr; while another session holds the migration lock, + serve --migrate waits for catalog_upgrade_lock_timeout and exits 6; serve + --migrate applies the migration and serves; - with the node paused, a server that cannot renew its registration answers 503 within 40 s of the pause, before its row can expire (45 s after its last renewal, which came up to 5 s before the pause), then tries to @@ -165,6 +170,64 @@ def not_a_catalog(binary: str, env: dict, container: str, config: str, stem: str ) +def startup_policy( + binary: str, env: dict, container: str, config: str, keyspace: str, port: int, work: str, + servers: list, +) -> None: + """`serve`'s startup policy on a catalog behind this binary, in the + foreground and in daemon mode.""" + hint = "or start this server with --migrate" + serve = [binary, "serve", "--config", config, "--foreground", "--port", str(port)] + daemon = [binary, "serve", "--config", config, "--port", str(port)] + code, output = cqlsh( + container, f"CONSISTENCY QUORUM;\nDELETE FROM {keyspace}.extenddb_migrations WHERE id = 4;\n" + ) + report(code == 0, "the catalog is behind this binary by migration 4", output) + expect_exit(3, "serve on a catalog behind this binary", serve, env, contains=hint) + # The parent reads the status before it forks, so the code and the + # message reach the invoking shell. + done = subprocess.run(daemon, env=env, capture_output=True, text=True, timeout=120, check=False) + report( + done.returncode == 3 and hint in done.stderr, + f"exit {done.returncode}: serve in daemon mode on a catalog behind this binary, the " + "message on stderr", + done.stdout + done.stderr, + ) + code, output = cqlsh( + container, + "CONSISTENCY QUORUM;\nSERIAL CONSISTENCY SERIAL;\n" + f"INSERT INTO {keyspace}.settings (key, value) VALUES ('migration_lock', " + "'held-by-check') IF NOT EXISTS USING TTL 300;\n", + ) + report(code == 0 and "True" in output, "the script holds the migration lock", output) + started = time.monotonic() + expect_exit( + 6, + "serve --migrate while another session holds the migration lock", + serve + ["--migrate"], + dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT="3"), + contains="migration lock", + ) + waited = time.monotonic() - started + report(waited >= 3, f"serve --migrate waited {waited:.1f} s for the lock, its 3 s timeout") + code, output = cqlsh( + container, + "CONSISTENCY QUORUM;\nSERIAL CONSISTENCY SERIAL;\n" + f"DELETE FROM {keyspace}.settings WHERE key = 'migration_lock' IF value = " + "'held-by-check';\n", + ) + report(code == 0 and "True" in output, "the script releases the lock", output) + log = os.path.join(work, "serve-migrate.log") + server = start(serve + ["--migrate"], env, log) + servers.append(server) + up = healthy(f"https://127.0.0.1:{port}/health", server) + stop(server) + with open(log, encoding="utf-8") as f: + report(up, "serve --migrate applies the pending migration and serves", f.read()) + expect_exit(0, "verify after serve --migrate", [binary, "verify", "--config", config], env, + contains="OK: Current") + + def main(binary: str, container: str, contact_point: str, port: int) -> int: binary = os.path.realpath(binary) stem = f"eddb_lock_{secrets.token_hex(4)}" @@ -279,6 +342,8 @@ def main(binary: str, container: str, contact_point: str, port: int) -> int: contains="Applied 2 resource_tag_condition_keys", ) + startup_policy(binary, env, container, config, keyspace, port, work, servers) + server = start(serve, env, log) servers.append(server) if not report(healthy(f"https://127.0.0.1:{port}/health", server), "serve once the lock is free"): diff --git a/devtools/check-mongodb-catalog-lock b/devtools/check-mongodb-catalog-lock index f13f764e6..86d5eabae 100755 --- a/devtools/check-mongodb-catalog-lock +++ b/devtools/check-mongodb-catalog-lock @@ -19,6 +19,11 @@ extenddb-check-lock-, published on 127.0.0.1 only: migrate --yes exits 6, and the preview still runs; - a server refuses a catalog behind this binary with 3, and the command it prints, run exactly as printed, applies what is missing; +- the startup policy on a catalog behind this binary: serve names + --migrate, and in daemon mode the invoking process exits 3 with the + message on its stderr; while another migration holds the lock, serve + --migrate waits for catalog_upgrade_lock_timeout and exits 6; serve + --migrate applies the migration and serves; - a server killed with SIGKILL keeps migrate --yes waiting until its registration expires, at most 45 s after its last renewal; - a server whose database stops answering answers 503 within 40 s, before @@ -137,6 +142,33 @@ def main(binary: str, mongo_port: int, api_port: int) -> int: expect_exit(0, "the printed command, run as printed", [binary, *words[1:]], env) expect_exit(0, "verify after the printed command", verify, env) + # The startup policy on a catalog behind this binary. + mongosh(container, mongo_port, "db.getSiblingDB('extenddb_catalog').extenddb_migrations.deleteOne({_id: 4})") + expect_exit(3, "serve on a catalog behind this binary", serve, env, timeout=60, + contains="or start this server with --migrate") + # The parent reads the status before it forks, so the code and the + # message reach the invoking shell. + daemon = [binary, "serve", "--config", "extenddb.toml", "--port", str(api_port)] + done = subprocess.run(daemon, env=env, capture_output=True, text=True, timeout=120, check=False) + report(done.returncode == 3 and "or start this server with --migrate" in done.stderr, + f"exit {done.returncode}: serve in daemon mode on a catalog behind this binary, " + "the message on stderr", done.stdout + done.stderr) + mongosh(container, mongo_port, "db.getSiblingDB('extenddb_catalog').settings.insertOne(" + "{_id: 'migration_lock', owner: 'check', expires_at: new Date(Date.now() + 120000)})") + started = time.monotonic() + expect_exit(6, "serve --migrate while another migration holds the lock", serve + ["--migrate"], + dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT="3"), timeout=60) + waited = time.monotonic() - started + report(waited >= 3, f"serve --migrate waited {waited:.1f} s for the lock, its 3 s timeout") + mongosh(container, mongo_port, "db.getSiblingDB('extenddb_catalog').settings.deleteOne({_id: 'migration_lock'})") + server = start(serve + ["--migrate"], env, "serve-migrate.log") + servers.append(server) + up = healthy(url, server, 60) + stop(server) + with open("serve-migrate.log", encoding="utf-8") as f: + report(up, "serve --migrate applies the pending migration and serves", f.read()) + expect_exit(0, "verify after serve --migrate", verify, env, contains="OK: Current") + # A server killed without deleting its registration blocks # migrate --yes until the registration expires, 45 s after its last # renewal. diff --git a/devtools/check-postgres-catalog-lock b/devtools/check-postgres-catalog-lock index e57eca247..72d902062 100755 --- a/devtools/check-postgres-catalog-lock +++ b/devtools/check-postgres-catalog-lock @@ -20,6 +20,11 @@ given as `--data-db=`, so `init` has to create the database it names. exit 6, migrate --yes --lock-timeout 0 exits 6 within 10 s, and the preview exits 0; - once the lock is free, migrate --yes and serve run; +- the startup policy on a catalog behind this binary: serve exits 3 and + names --migrate, and in daemon mode the invoking process exits 3 with the + message on its stderr; serve --migrate applies the migration and serves; + while another session holds the migration lock, serve --migrate waits for + catalog_upgrade_lock_timeout and exits 6; - a server whose registration session the database ends registers again on a new session and goes on serving, and migrate --yes exits 6 naming it; - a server whose registration session ends while a migration holds both @@ -114,6 +119,66 @@ def just_renewed(admin_url: str, stem: str, seconds: float = 40) -> bool: conn.close() return False +MIGRATE_HINT = "or start this server with --migrate" + + +def behind(admin_url: str, stem: str) -> None: + """Delete the catalog's last ledger row, so the catalog is behind this + binary.""" + conn = psycopg2.connect(f"{admin_url.rstrip('/')}/{stem}_catalog") + conn.autocommit = True + with conn.cursor() as cur: + cur.execute( + "DELETE FROM extenddb_migrations WHERE id = (SELECT max(id) FROM extenddb_migrations)" + ) + conn.close() + + +def startup_policy( + binary: str, env: dict, config: str, port: int, admin_url: str, stem: str, servers: list +) -> None: + """`serve`'s startup policy on a catalog behind this binary, in the + foreground and in daemon mode.""" + serve = [binary, "serve", "--config", config, "--foreground", "--port", str(port)] + daemon = [binary, "serve", "--config", config, "--port", str(port)] + url = f"https://127.0.0.1:{port}/health" + behind(admin_url, stem) + expect_exit(3, "serve on a catalog behind this binary", serve, env, contains=MIGRATE_HINT) + # The parent reads the status before it forks, so the code and the + # message reach the invoking shell. + done = subprocess.run(daemon, env=env, capture_output=True, text=True, timeout=120, check=False) + report( + done.returncode == 3 and MIGRATE_HINT in done.stderr, + f"exit {done.returncode}: serve in daemon mode on a catalog behind this binary, the " + "message on stderr", + done.stdout + done.stderr, + ) + # Another session holds the migration lock: serve --migrate waits for + # catalog_upgrade_lock_timeout, then exits 6. + holder = psycopg2.connect(f"{admin_url.rstrip('/')}/{stem}_catalog") + with holder.cursor() as cur: + cur.execute("SELECT pg_advisory_xact_lock(%s, %s)", (NAMESPACE, MIGRATION_KEY)) + started = time.monotonic() + expect_exit( + 6, + "serve --migrate while another session holds the migration lock", + serve + ["--migrate"], + dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT="3"), + contains="another migrator holds the migration lock", + ) + waited = time.monotonic() - started + report(waited >= 3, f"serve --migrate waited {waited:.1f} s for the lock, its 3 s timeout") + holder.rollback() + holder.close() + log = os.path.join(os.path.dirname(config), "serve-migrate.log") + server = start(serve + ["--migrate"], env, log) + servers.append(server) + up = healthy(url, server) + stop(server) + with open(log, encoding="utf-8") as f: + report(up, "serve --migrate applies the pending migration and serves", f.read()) + expect_exit(0, "verify after serve --migrate", [binary, "verify", "--config", config], env, + contains="OK: Current") def main(binary: str, admin_url: str, port: int) -> int: binary = os.path.realpath(binary) @@ -197,6 +262,7 @@ def main(binary: str, admin_url: str, port: int) -> int: holder = None expect_exit(0, "migrate --yes once the lock is free", migrate + ["--yes", "--lock-timeout", "5"], env) + startup_policy(binary, env, config, port, admin_url, stem, servers) server = start(serve, env, log) servers.append(server) report(healthy(f"https://127.0.0.1:{port}/health", server), "serve once the lock is free") diff --git a/devtools/check-sqlite-catalog-lock b/devtools/check-sqlite-catalog-lock index 779a76def..4ffe0bd77 100755 --- a/devtools/check-sqlite-catalog-lock +++ b/devtools/check-sqlite-catalog-lock @@ -14,6 +14,15 @@ - once the database is free, migrate --yes and serve run; - on a catalog behind this binary, verify and the preview exit 3, and migrate --yes applies what is missing; +- the startup policy on a catalog behind this binary: serve exits 3 and + names --migrate, and in daemon mode the invoking process exits 3 with the + message on its stderr; serve --migrate, catalog_upgrade = "apply" in the + config file, EXTENDDB__SERVER__CATALOG_UPGRADE=apply and serve --migrate in + daemon mode each apply the migration and serve; serve --migrate on a + current catalog writes nothing; on a catalog that needs a person it exits + 5 and writes nothing; while another process holds the database's lock it + waits for catalog_upgrade_lock_timeout and exits 6; and two serve --migrate + started together on a released catalog migrate it once; - on a config whose database does not exist, migrate --yes exits 1, names extenddb init, and creates neither the database nor its directory. @@ -22,15 +31,27 @@ it so its TLS certificate is not written to the caller's home. The server binds 127.0.0.1 only. """ import fcntl +import glob import os import re import shutil import sqlite3 +import subprocess import sys import tempfile +import time from catalog_checks import expect_exit, finish, healthy, report, run, start, stop +REPO = os.path.dirname(os.path.dirname(os.path.realpath(__file__))) +RELEASED = os.path.join(REPO, "crates/storage-sqlite/tests/fixtures/released/dev-image-0.1.14.sql") +MIGRATE_HINT = "or start this server with --migrate" +COLLIDING = ( + '{"Version":"2012-10-17","Statement":[{"Effect":"Deny","Action":"dynamodb:*",' + '"Resource":"*","Condition":{"StringEquals":{"aws:ResourceTag/env":"prod",' + '"dynamodb:ResourceTag/env":"dev"}}}]}' +) + def with_path(config: str, database: str, out: str) -> None: """Write `config` to `out` with its `path = ` line naming `database`.""" @@ -40,6 +61,198 @@ def with_path(config: str, database: str, out: str) -> None: f.write(re.sub(r"(?m)^path = .*$", f'path = "{database}"', text)) +def with_server_line(config: str, line: str, out: str) -> None: + """Write `config` to `out` with `line` added to its [server] table.""" + with open(config, encoding="utf-8") as f: + text = f.read() + with open(out, "w", encoding="utf-8") as f: + f.write(re.sub(r"(?m)^\[server\]$", f"[server]\n{line}", text, count=1)) + os.chmod(out, 0o600) + + +def behind(database: str, first: int | None = None) -> None: + """Delete the catalog's last ledger row, or every row from id `first` + on, so the catalog is behind this binary.""" + # The copy a run takes before it migrates is named by the second it is + # taken in and never replaced, so two runs from the same migration need + # a second between them. + time.sleep(1.1) + conn = sqlite3.connect(database) + if first is None: + conn.execute( + "DELETE FROM extenddb_migrations WHERE id = (SELECT MAX(id) FROM extenddb_migrations)" + ) + else: + conn.execute("DELETE FROM extenddb_migrations WHERE id >= ?", (first,)) + conn.commit() + conn.close() + + +def ledger(database: str) -> list: + conn = sqlite3.connect(database) + rows = conn.execute("SELECT id, applied_at FROM extenddb_migrations ORDER BY id").fetchall() + conn.close() + return rows + + +def copies(database: str) -> list: + return sorted(glob.glob(f"{glob.escape(database)}.pre-migration-*")) + + +def run_split(cmd: list[str], env: dict | None, timeout: float = 120) -> tuple[int, str, str]: + """Run `cmd` and return its exit code, stdout and stderr apart.""" + try: + done = subprocess.run(cmd, env=env, capture_output=True, text=True, timeout=timeout, check=False) + except subprocess.TimeoutExpired: + return -1, "", f"still running after {timeout:g} s" + return done.returncode, done.stdout, done.stderr + + +def serves(cmd: list[str], env: dict | None, url: str, log: str, what: str, servers: list) -> bool: + """Start a foreground server, report whether it becomes healthy, and stop it.""" + server = start(cmd, env, log) + servers.append(server) + up = healthy(url, server, 60) + stop(server) + with open(log, encoding="utf-8") as f: + return report(up, what, f.read()) + + +def startup_policy(binary: str, database: str, port: int, env: dict, servers: list) -> None: + """`serve`'s startup policy on catalogs behind this binary and on one + that is current, in the foreground and in daemon mode.""" + url = f"https://127.0.0.1:{port}/health" + serve = [binary, "serve", "--config", "extenddb.toml", "--foreground", "--port", str(port)] + daemon = [binary, "serve", "--config", "extenddb.toml", "--port", str(port)] + verify = [binary, "verify", "--config", "extenddb.toml"] + + behind(database) + expect_exit(3, "serve on a catalog behind this binary", serve, env, contains=MIGRATE_HINT) + # The parent reads the status before it forks, so the code and the + # message reach the invoking shell. + code, out, err = run_split(daemon, env) + report( + code == 3 and MIGRATE_HINT in err, + f"exit {code}: serve in daemon mode on a catalog behind this binary, the message on stderr", + out + err, + ) + serves(serve + ["--migrate"], env, url, "serve-migrate.log", + "serve --migrate applies the pending migration and serves", servers) + expect_exit(0, "verify after serve --migrate", verify, env, contains="OK: Current") + + behind(database) + with_server_line("extenddb.toml", 'catalog_upgrade = "apply"', "apply.toml") + serves([binary, "serve", "--config", "apply.toml", "--foreground", "--port", str(port)], env, url, + "serve-apply.log", 'catalog_upgrade = "apply" applies the pending migration and serves', + servers) + expect_exit(0, 'verify after catalog_upgrade = "apply"', verify, env, contains="OK: Current") + + behind(database) + serves(serve, dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE="apply"), url, "serve-env.log", + "EXTENDDB__SERVER__CATALOG_UPGRADE=apply applies the pending migration and serves", servers) + expect_exit(0, "verify after EXTENDDB__SERVER__CATALOG_UPGRADE=apply", verify, env, + contains="OK: Current") + + # Daemon mode applies before it forks, reporting progress on stderr. + behind(database) + code, out, err = run_split(daemon + ["--migrate"], env) + up = code == 0 and healthy(url, None, 30) + expect_exit(0, "stop the daemon", [binary, "stop", "--config", "extenddb.toml", "--port", str(port)], env) + report( + up and "catalog migration: applied " in err, + f"exit {code}: serve --migrate in daemon mode applies before it forks and serves", + out + err, + ) + expect_exit(0, "verify after serve --migrate in daemon mode", verify, env, contains="OK: Current") + + # A current catalog: serve --migrate takes no lock and writes nothing. + rows, taken = ledger(database), copies(database) + serves(serve + ["--migrate"], env, url, "serve-current.log", + "serve --migrate on a current catalog serves", servers) + report(ledger(database) == rows and copies(database) == taken, + "serve --migrate on a current catalog wrote no ledger row and took no copy") + + # A catalog that needs a person: exit 5, and nothing written. + behind(database, first=2) + conn = sqlite3.connect(database) + account = conn.execute("SELECT account_id FROM accounts LIMIT 1").fetchone()[0] + conn.execute( + "INSERT INTO iam_users (account_id, user_name, user_arn) VALUES (?, 'collider', ?)", + (account, f"arn:aws:iam::{account}:user/collider"), + ) + conn.execute( + "INSERT INTO iam_policies (account_id, principal_type, principal_name, policy_name, " + "policy_document) VALUES (?, 'user', 'collider', 'colliding', ?)", + (account, COLLIDING), + ) + conn.commit() + conn.close() + with open(database, "rb") as f: + before = f.read() + expect_exit(5, "serve --migrate on a catalog that needs a person", serve + ["--migrate"], env, + contains="needs a person") + with open(database, "rb") as f: + report(f.read() == before and copies(database) == taken, + "serve --migrate on a catalog that needs a person wrote nothing") + conn = sqlite3.connect(database) + conn.execute("DELETE FROM iam_policies WHERE policy_name = 'colliding'") + conn.execute("DELETE FROM iam_users WHERE user_name = 'collider'") + conn.commit() + conn.close() + expect_exit(0, "migrate --yes once the collision is gone", + [binary, "migrate", "--config", "extenddb.toml", "--yes", "--lock-timeout", "5"], env) + + # Another process holds the database's lock: serve --migrate waits for + # catalog_upgrade_lock_timeout, then exits 6. + behind(database) + holder = open(os.path.realpath(database) + ".lock", "a+b") + fcntl.flock(holder, fcntl.LOCK_EX | fcntl.LOCK_NB) + started = time.monotonic() + expect_exit(6, "serve --migrate while another process holds the database's lock", + serve + ["--migrate"], dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT="3"), + contains="another extenddb process") + waited = time.monotonic() - started + report(waited >= 3, f"serve --migrate waited {waited:.1f} s for the lock, its 3 s timeout") + fcntl.flock(holder, fcntl.LOCK_UN) + holder.close() + expect_exit(0, "migrate --yes once the lock is free", + [binary, "migrate", "--config", "extenddb.toml", "--yes", "--lock-timeout", "5"], env) + + +def two_servers(binary: str, work: str, port: int, env: dict, servers: list) -> None: + """Two serve --migrate started together on a released catalog: one + migrates it and serves; the other waits for the lock, finds nothing to + apply, and serves or exits 6 on the lock the first server holds.""" + database = os.path.join(work, "released.sqlite") + conn = sqlite3.connect(database) + with open(RELEASED, encoding="utf-8") as f: + conn.executescript(f.read()) + conn.commit() + conn.close() + os.chmod(database, 0o600) + with_path("extenddb.toml", database, "released.toml") + timeout = dict(env, EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT="10") + procs = [] + for i, p in enumerate((port, port + 1)): + cmd = [binary, "serve", "--config", "released.toml", "--foreground", "--migrate", "--port", str(p)] + proc = start(cmd, timeout, f"two-{i}.log") + servers.append(proc) + procs.append(proc) + for p, proc in zip((port, port + 1), procs): + healthy(f"https://127.0.0.1:{p}/health", proc, 60) + logs = [] + for i, proc in enumerate(procs): + stop(proc) + with open(f"two-{i}.log", encoding="utf-8") as f: + logs.append(f.read()) + applied = [log for log in logs if "catalog migration: applied 1 baseline" in log] + report(len(applied) == 1, f"one of two serve --migrate applied the migrations ({len(applied)} did)", + "\n---\n".join(logs)) + report(len(copies(database)) == 1, "the released catalog was copied once", "\n".join(copies(database))) + expect_exit(0, "verify after two serve --migrate", [binary, "verify", "--config", "released.toml"], env, + contains="OK: Current") + + def main(binary: str, port: int) -> int: binary = os.path.realpath(binary) work = tempfile.mkdtemp() @@ -107,6 +320,9 @@ def main(binary: str, port: int) -> int: expect_exit(3, "migrate preview on a catalog behind this binary", migrate) expect_exit(0, "migrate --yes applies what is missing", migrate + ["--yes", "--lock-timeout", "5"]) + startup_policy(binary, database, port, env, servers) + two_servers(binary, work, port, env, servers) + # A config whose database does not exist: migrate --yes refuses with # 1, names init, and creates neither the database nor its directory. missing = os.path.join(work, "missing") diff --git a/devtools/run-mongodb-tests b/devtools/run-mongodb-tests index 6c69e6993..8db33a9aa 100755 --- a/devtools/run-mongodb-tests +++ b/devtools/run-mongodb-tests @@ -295,7 +295,8 @@ if [[ " ${RUN_TESTS_ARGS[*]} " == *" --rust"* ]]; then EXTENDDB_TEST_MONGODB_URI="mongodb://localhost:$MONGO_PORT/?replicaSet=rs0&directConnection=true" \ EXTENDDB_TEST_MONGODB_REQUIRED=1 \ cargo test -p extenddb-storage-mongodb --test migrations_fresh --test migrations_guards \ - --test migrations_holders --test migrations_locks --test migrations_released + --test migrations_holders --test migrations_locks --test migrations_released \ + --test migrations_startup echo "" fi echo "=== Running test suite via devtools/run-tests --backend mongodb ===" From 9ee12f38358640a86d0f190e1a9fb2b4a9b86e75 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Fri, 30 Oct 2026 22:54:35 +0000 Subject: [PATCH 04/14] docs: serve --migrate, catalog_upgrade and the deployment recipes The upgrade manual describes the startup policy: [server] catalog_upgrade and its defaults, serve --migrate, the environment variables, the steps serve takes under apply, the progress lines, and the statuses serve refuses under both values. It gives the recipes for a single host, for Docker Compose, which needs no change, and for Kubernetes: one replica with the Deployment strategy Recreate and a migration Job applied in the same release, with the reasons the recipe uses no Helm pre-upgrade hook and does not migrate in the pod. It lists the exit codes of serve, which in daemon mode reach the invoking shell. The deployment guide gives the Kubernetes recipe, and its upgrade checklist names serve --migrate. docker/README.md says what the serving container does with a catalog behind its image. The admin guide lists the two keys, and the sample config, the process lifecycle in the architecture guide and the troubleshooting entry for exit 6 follow the change. --- docker/README.md | 11 ++++++ docs/manuals/01-architecture-guide.md | 21 ++++++----- docs/manuals/05-admin-guide.md | 4 +- docs/manuals/07-upgrade-manual.md | 53 ++++++++++++++++++++++++--- docs/manuals/11-deployment-guide.md | 4 +- docs/troubleshooting.md | 4 +- extenddb.sample.toml | 3 ++ 7 files changed, 82 insertions(+), 18 deletions(-) diff --git a/docker/README.md b/docker/README.md index 45b66d359..fd2bc68f8 100644 --- a/docker/README.md +++ b/docker/README.md @@ -162,6 +162,17 @@ whether pgvector is available and goes on. A backup taken by a 0.1.x release can restore without its secondary indexes, so take a new backup of each table after the upgrade. +The serving container refuses a catalog behind its image: `serve` exits 3 and +prints the pending migrations, what to back up, and the command above. +`serve --migrate`, or `EXTENDDB__SERVER__CATALOG_UPGRADE=apply` in the serving +container's environment, makes the server apply the migrations itself before it +serves, through the same lock the Job takes. It exits 6 when the lock is not +free within `[server] catalog_upgrade_lock_timeout` seconds (60 by default). On +Kubernetes keep the Job: the +[upgrade manual](../docs/manuals/07-upgrade-manual.md#deployment-recipes) gives +the reasons, and lists the +[exit codes of serve](../docs/manuals/07-upgrade-manual.md#exit-codes-of-serve). + ### Steady state Run only: diff --git a/docs/manuals/01-architecture-guide.md b/docs/manuals/01-architecture-guide.md index 1d1c9016a..39d3b7d80 100755 --- a/docs/manuals/01-architecture-guide.md +++ b/docs/manuals/01-architecture-guide.md @@ -182,21 +182,24 @@ expect. 1. Parse CLI arguments and load configuration 2. Bind TCP socket (port conflicts reported before forking) -3. Fork to background via `daemonize`, writing a PID file to `run_dir` +3. Read the catalog's status, and under `[server] catalog_upgrade = "apply"` + or `serve --migrate` apply its pending migrations. A catalog the server + cannot serve stops it here, before the fork, with the status's exit code +4. Fork to background via `daemonize`, writing a PID file to `run_dir` (skipped entirely in `--foreground` mode, so no run directory is needed and the root filesystem can be read-only) -4. Initialize logging — syslog when daemonized, stderr in `--foreground` -5. Connect to the storage backend -6. Verify catalog version matches binary expectation -7. Start axum server on the pre-bound socket +5. Initialize logging: syslog when daemonized, stderr in `--foreground` +6. Connect to the storage backend +7. Verify catalog version matches binary expectation +8. Start axum server on the pre-bound socket Because `--foreground` writes no PID file, `extenddb stop` cannot signal a foreground server; stop it through whatever supervises it. `extenddb status` still reports it as running, with the PID shown as unknown. Pass `serve --foreground --write-pid-file` to write one anyway, which restores both commands at the cost of needing a writable `run_dir`. -8. Spawn background tasks (log level polling, throttling polling, GSI delay polling, stream cleanup, TTL expiry, metrics persistence) -9. On SIGTERM/SIGINT: drain connections (5s timeout), exit +9. Spawn background tasks (log level polling, throttling polling, GSI delay polling, stream cleanup, TTL expiry, metrics persistence) +10. On SIGTERM/SIGINT: drain connections (5s timeout), exit ## Catalog Model @@ -205,8 +208,8 @@ extenddb uses a dual-database architecture: - **Catalog database** (e.g., `extenddb_catalog`): Stores table metadata, account/user/group/role/policy definitions, access keys, settings, stream metadata, and metrics. Shared across all accounts. - **Data database** (e.g., `extenddb_catalog_data`): Stores user items, GSI/LSI data, and stream records. Each table gets its own PostgreSQL table. -On PostgreSQL, SQLite, Cassandra and MongoDB the catalog is versioned by its migration ledger, the `extenddb_migrations` table (on MongoDB a collection, in the catalog database and in the data database): the catalog version is the highest migration recorded in every store, migration 4 for this release, and `serve` reads the catalog's status at startup and refuses a catalog that is behind it or carries a breaking migration it does not know. On Cassandra every account keyspace has a ledger beside the catalog keyspace's. -A mismatch between the binary's migrations and the catalog's ledger prevents a server from starting; run `extenddb migrate` to upgrade. +On PostgreSQL, SQLite, Cassandra and MongoDB the catalog is versioned by its migration ledger, the `extenddb_migrations` table (on MongoDB a collection, in the catalog database and in the data database): the catalog version is the highest migration recorded in every store, migration 4 for this release, and `serve` reads the catalog's status at startup and refuses a catalog that carries a breaking migration it does not know, and one that is behind it unless it runs under `[server] catalog_upgrade = "apply"` or `--migrate`. On Cassandra every account keyspace has a ledger beside the catalog keyspace's. +A mismatch between the binary's migrations and the catalog's ledger prevents a server from starting; run `extenddb migrate --yes` to upgrade a catalog that is behind, or start the server with `--migrate`. ## Pluggable Architecture diff --git a/docs/manuals/05-admin-guide.md b/docs/manuals/05-admin-guide.md index 31fe07abd..7285345f0 100755 --- a/docs/manuals/05-admin-guide.md +++ b/docs/manuals/05-admin-guide.md @@ -91,6 +91,8 @@ These settings require a server restart to take effect. | `bind_addr` | `127.0.0.1` | Network interface to bind | | `port` | `18443` | HTTP port | | `region` | `us-east-1` | AWS region for ARN generation. Baked into every backup ARN the server issues, so it must stay within `[a-z0-9-]` (a value outside that class makes the server's own backup ARNs "not valid"; the server logs a warning at startup). A backup ARN of the caller's account in another region is resolved in the server's region first, then as written; see the upgrade manual before changing this on a deployment with backups | +| `catalog_upgrade` | `refuse` (`apply` in a dev build) | What `serve` does with a catalog behind the binary: `refuse` exits 3 and names the pending migrations, and `apply` runs them at startup as `migrate --yes` does. `serve --migrate` sets `apply` for one run. Every status `serve` cannot serve is refused under both values; see the [upgrade manual](07-upgrade-manual.md#applying-migrations-at-startup) | +| `catalog_upgrade_lock_timeout` | `60` | Seconds `serve` waits under `apply` for the migration lock and for running servers before it exits 6; at most 86400 | #### [storage] @@ -925,7 +927,7 @@ Check that PostgreSQL is running and the connection string in `extenddb.toml` is **The catalog has pending migrations, or is ahead of the binary:** -On PostgreSQL, SQLite, Cassandra and MongoDB, `serve` reads the catalog's migration status before it opens the engine and refuses a catalog it cannot serve, printing the status and the command that resolves it. A catalog with pending migrations exits 3, for example `the catalog is at migration 3, and ExtendDB needs migration 4`, followed by the pending migrations and `extenddb migrate --config extenddb.toml --yes`. A catalog that a newer release migrated with a breaking migration exits 4 and names that release's migrations; upgrade the binary rather than the catalog. The [Upgrade Manual](07-upgrade-manual.md#the-catalog-status) lists every status with its exit code and the stop / migrate / start sequence. +On PostgreSQL, SQLite, Cassandra and MongoDB, `serve` reads the catalog's migration status before it opens the engine and refuses a catalog it cannot serve, printing the status and the command that resolves it. A catalog with pending migrations exits 3, for example `the catalog is at migration 3, and ExtendDB needs migration 4`, followed by the pending migrations, `extenddb migrate --config extenddb.toml --yes` and `or start this server with --migrate`. Under `[server] catalog_upgrade = "apply"`, or started with `--migrate`, the server applies the pending migrations and serves. A catalog that a newer release migrated with a breaking migration exits 4 and names that release's migrations; upgrade the binary rather than the catalog. The [Upgrade Manual](07-upgrade-manual.md#the-catalog-status) lists every status with its exit code and the stop / migrate / start sequence. ### Authentication Errors diff --git a/docs/manuals/07-upgrade-manual.md b/docs/manuals/07-upgrade-manual.md index 2832d45da..bed7f394d 100755 --- a/docs/manuals/07-upgrade-manual.md +++ b/docs/manuals/07-upgrade-manual.md @@ -4,7 +4,7 @@ ## Current Status -This release versions the PostgreSQL, SQLite, Cassandra and MongoDB catalogs by a migration ledger and carries catalog migrations 1 to 4, which `extenddb migrate --list` prints. **Every deployment created by a 0.1.x release runs `extenddb migrate --yes` once** before a server of this release starts on it: the server refuses a catalog with pending migrations. Migration 1 brings the catalog of every 0.1.x release to the v1.0 schema. +This release versions the PostgreSQL, SQLite, Cassandra and MongoDB catalogs by a migration ledger and carries catalog migrations 1 to 4, which `extenddb migrate --list` prints. **Every deployment created by a 0.1.x release runs `extenddb migrate --yes` once** before a server of this release starts on it, or starts that server once with `extenddb serve --migrate` ([Applying migrations at startup](#applying-migrations-at-startup)): by default a server refuses a catalog with pending migrations. Migration 1 brings the catalog of every 0.1.x release to the v1.0 schema. A backup that a 0.1.x release took can restore without its global and local secondary indexes: a SQLite backup taken by 0.1.14 records only the table's key schema and attribute definitions, and its restore creates the table with its items and no index. Take a new backup of each table after upgrading to v1.0, and keep the 0.1.x backups for their items only. @@ -27,7 +27,7 @@ Running `extenddb migrate --yes` on an up-to-date catalog changes nothing. | Status | Meaning | `serve` | `migrate` | `migrate --yes` | `verify` | |--------|---------|---------|-----------|-----------------|----------| | Current | Every migration this binary carries is recorded | serves | 0 | 0 | 0 | -| Behind | Migrations are pending | 3 | 3 | applies them, 0 | 3 | +| Behind | Migrations are pending | 3; applies them and serves under `catalog_upgrade = "apply"` or `--migrate` | 3 | applies them, 0 | 3 | | AheadCompatible | The catalog has migrations this binary does not know, all additive | serves, with a warning | 0 | 0 | 0 | | AheadIncompatible | The catalog has a migration this binary does not know that is breaking | 4 | 4 | 4 | 4 | | NeedsAttention | A pending migration found data that a person must fix; each item is named | 5 | 5 | 5 | 5 | @@ -35,12 +35,53 @@ Running `extenddb migrate --yes` on an up-to-date catalog changes nothing. | WrittenByOlderRelease | A 0.1.x release wrote to the catalog after it was migrated | 5 | 5 | 5; `--yes --reconverge` repairs it | 5 | | Uninitialized | Not a catalog; `extenddb init` creates one | 1 | 1 | 1 | 1 | -Exit status 6 means the migration lock, or a running server, was still held when `--lock-timeout` ran out; run the command again once it is free. Every refusal prints the command that resolves it. A dev build's `serve` applies a Behind or Uninitialized catalog at startup instead of refusing it. The `serve` codes are those of `serve --foreground`; in daemon mode `serve` exits 1 and writes the refusal to syslog. +Exit status 6 means the migration lock, or a running server, was still held when `--lock-timeout` ran out (for `serve`, `[server] catalog_upgrade_lock_timeout`); run the command again once it is free. Every refusal prints the command that resolves it. A dev build's `serve` applies a Behind catalog at startup instead of refusing it, by its default `catalog_upgrade = "apply"`, and creates a catalog in a missing or empty database file. `serve` has the same codes in daemon mode, its default, and with `--foreground`: [Exit codes of serve](#exit-codes-of-serve) gives the one case where they differ. `verify` also checks the connection to the data database. When that check fails, `verify` exits 1 on a Behind catalog instead of 3, because `migrate --yes` cannot apply the pending migrations while the data database cannot be reached. It still exits 4 or 5 for the statuses that need a person. A migration is additive when the previous release serves the catalog correctly with it applied, and breaking otherwise. Migrations 1 to 4 are breaking: do not run a 0.1.x server against a migrated catalog. A 0.1.x binary that writes to a migrated catalog (its `migrate --yes`, or a SQLite dev server) leaves it WrittenByOlderRelease. `migrate --yes --reconverge` repairs it by running the convergent migrations again. Migration 2, which rewrites stored policies, is not convergent: the repair skips it and prints a line that says so (see the v0.1.14 notes below). +### Applying Migrations at Startup + +`serve` reads the catalog's status before it opens the catalog. The `[server]` key `catalog_upgrade` sets what it does with a catalog that is behind it: + +| Value | A catalog behind the binary | +|-------|-----------------------------| +| `refuse` | `serve` exits 3. The message lists the pending migrations, says which servers to stop and what to back up, gives the `migrate --yes` command, and ends with `or start this server with --migrate`. The default in a production build | +| `apply` | `serve` applies the pending migrations, then serves. The default in a dev build, which the dev image and the npm launcher run | + +`serve --migrate` sets `apply` for one run. `EXTENDDB__SERVER__CATALOG_UPGRADE` sets the key from the environment and overrides the config file, as it does for every key. `serve` refuses any other value with a configuration error. + +Under `apply`, `serve` migrates the catalog before it opens it, through the same run as `migrate --yes`: + +1. It takes the migration lock, waiting up to `[server] catalog_upgrade_lock_timeout` seconds (60 by default, at most 86400) for another migration and for running servers. `EXTENDDB__SERVER__CATALOG_UPGRADE_LOCK_TIMEOUT` sets the timeout from the environment. +2. It reads the status again under the lock. When another process migrated the catalog while this one waited, the server releases the lock and starts. +3. It runs the `detect` step of every pending code migration. When one finds items, `serve` exits 5 and names them, having written nothing. +4. On SQLite it copies the database, as `migrate --yes` does. +5. It applies the migrations, releases the lock, registers as the catalog's server, and serves. + +When the lock is still held at the timeout, the server reads the status once more. It starts on a catalog that another process migrated in the meantime, and exits 6 on any other. Of two servers started together with `--migrate`, one applies the migrations. The other waits until the timeout, because the lock waits for the first server's registration to end, then finds the catalog migrated and starts. On SQLite it exits 6 instead, because one server at a time can hold the database file. + +While it migrates, the server prints a line on stderr for each step, each starting with `catalog migration: `, and one every 5 seconds until the run ends. The npm launcher's startup timeout of 15 seconds counts from the last of these lines. The server binds its port before the run and answers no request until the migrations are done. + +`apply` changes only what `serve` does with a Behind catalog. Under both values `serve` serves a Current or AheadCompatible catalog, and refuses every other status with its code from the [status table](#the-catalog-status) before it takes the lock: NeedsAttention, Changed and WrittenByOlderRelease with 5, AheadIncompatible with 4, and Uninitialized with 1, except that a dev build creates a catalog in a missing or empty database file. No setting or flag makes `serve` open a catalog in any of these states. + +`serve` connects with the credentials in the config file, as `migrate` does, and that role does all the schema work. It has no admin role. On PostgreSQL it tries to create the pgvector extension as the application role and prints the result, as `migrate --yes` does without `--pg-user`; run `extenddb migrate --yes --pg-user ` when the extension needs an admin. `serve` does not read the ownership notes that `migrate --yes` checks before it takes the lock, so a migration that fails on a table the application role does not own stops the run, commits nothing of that migration in that database, and prints the same note. + +`serve --migrate` does not detect a running server of a release before 1.0, and neither does `migrate --yes`. Stop every server before the upgrade from 0.1.x, as step 1 of the [general upgrade procedure](#general-upgrade-procedure) says. + +#### Deployment Recipes + +- Single host: stop the server and take the backup the general upgrade procedure describes, then start the new binary with `extenddb serve --migrate --config extenddb.toml`, or run `extenddb migrate --config extenddb.toml --yes` before `serve`. +- Docker Compose: no change. The `extenddb-bootstrap` service runs `migrate --yes` before the server starts. +- Kubernetes: one replica, the Deployment strategy `Recreate`, and a migration Job that runs `extenddb migrate --yes` with the serving Secret, applied in the same release as the new Deployment. The Job can start while the old pod is still in its termination grace period, because `migrate --yes` waits for that server's registration to end, for up to its `--lock-timeout`. A pod of the new release that starts before the Job finishes exits 3, and Kubernetes restarts it. Do not run the Job as a Helm pre-upgrade hook. Helm runs that hook while the old pod still serves, so from 1.0 on its `migrate --yes` would exit 6 on every upgrade, and on the upgrade from 0.1.x it would adopt the catalog while the old server, which it cannot see, still serves it. Run the Job rather than `serve --migrate` in the pod: the server answers no request while the migrations run, and a liveness probe would restart the pod during a long migration. + +#### Exit Codes of serve + +`serve` exits with the codes of the [status table](#the-catalog-status): 1 for an error, and in a production build for a store that is not a catalog; 3 for a catalog behind it under `refuse`; 4 and 5 as listed there; and 6 under `apply` when the lock or a running server outlasted `catalog_upgrade_lock_timeout`. Under both values a server also exits 6, without waiting, when a migration holds the lock as it registers. + +In daemon mode, the default, `serve` reads the status before it forks, and under `apply` it migrates before it forks too, so the invoking shell receives these codes and the message on stderr. After the fork the server reads the status again and registers. A server that stops there, for example with 6 because a `migrate --yes` started between the two reads, writes its message to syslog. The invoking shell then sees exit status 1 when the server stopped within about 3 seconds of the fork, and 0 when it stopped later. Under `--foreground` every code and message reaches the caller. + ## Writing a New Migration Writing a catalog migration is contributor work. The procedure, with a worked example and the tests to run on each backend, is in the [catalog migration section](../../CONTRIBUTING.md#adding-a-catalog-migration) of `CONTRIBUTING.md` in the repository root. `extenddb migrate --list` prints the migrations the binary carries, with each one's kind on its backend. @@ -78,6 +119,8 @@ extenddb migrate --config extenddb.toml extenddb migrate --config extenddb.toml --yes ``` +The server can apply them instead: start it in step 6 with `extenddb serve --migrate --config extenddb.toml`, which applies the pending migrations as `migrate --yes` does before it serves, and run the `verify` of step 5 once it has started ([Applying migrations at startup](#applying-migrations-at-startup)). + `migrate` connects as the application role in the config file, which does all the schema work. On PostgreSQL that role must own every table, view and sequence in the public schema of both databases, and may create tables there, as it does after `init`. A catalog restored by another role (for example from a `pg_dump --no-owner` dump loaded by an admin) is not owned by it, and such a dump carries no grants, so the role cannot read the restored tables either: the preview, `verify` and `migrate --yes` exit 1 with the database's `permission denied for table settings` followed by the catalog database's note. The data database's name is a row of the catalog's `settings`, which the role cannot read, so the commands do not guess it and print a line saying so after the note. Run the catalog database's statements first, and the next run prints the data database's note, or pass `migrate --data-db ` to see both notes at once. When the role can read the tables but does not own them, the preview and `verify` print a note per database, and `migrate --yes` refuses with exit status 1 before it takes the lock, printing one note per line. Each note names the objects the role does not own, with their owners, and the statements to run in that database, numbered in the order they run, each with the role that runs it. For each owner a `DO` block, run by that owner or by a superuser, changes the owner of that owner's objects with `ALTER ... OWNER TO` and of nothing else. Where no superuser exists, as on a managed service, PostgreSQL lets an owner give an object only to a role it is a member of, and only when that role may create objects in the object's schema. Call the role that owns the restored objects ``. When it is not a superuser, the note first prints `GRANT "" TO ""`, run by an administrator that may grant the application role (on PostgreSQL 16, a role with `ADMIN OPTION` on it, which the role that created it holds; the application role cannot grant itself to ``). Then it prints `GRANT CREATE ON SCHEMA public TO ""` when the application role may not create tables there, run by the public schema's owner, then the `DO` blocks, and last `REVOKE "" FROM ""`, which takes back the membership the `DO` blocks needed. Skip that last statement if `` was already a member of ``. A superuser can run every statement as printed. The note does not use `REASSIGN OWNED BY`, which would also give the role the old owner's other databases and its objects in other schemas. A migration that still fails on a privilege (`must be owner of table ...`) stops, commits nothing in that database, and prints the same note. `--pg-user `, with the password in `EXTENDDB_PG_PASSWORD`, names an admin role for one step only, creating the pgvector extension in the data database, on that database's server; without it `migrate --yes` reports whether pgvector is available and goes on. `migrate` finds the data database through the name `init` recorded in the catalog's `settings` (`data_database_name`), and connects to it with the connection string `init` recorded beside it (`data_database_connection_string`), which the server connects with. A catalog that has no recorded name falls back to the catalog database name without its `_catalog` suffix. `--data-db ` overrides both and uses that database on the recorded connection string's server. When the two rows name different databases and `--data-db` is not given, `migrate`, `verify` and `serve` refuse with exit status 1 and name both; correct the row that is wrong. @@ -95,7 +138,7 @@ The two transactions that hold the keys, the server's registration and the migra On MongoDB, `migrate` connects with the connection string in the config file, which the server uses too. A user with the `readWrite` role on `extenddb_catalog` and on `extenddb_data` and no other role can run `init`, `migrate --yes`, `verify` and `serve`. `migrate --yes` takes the migration lock, a document in the catalog's `settings` collection, and then waits for the registration every running server keeps in the catalog's `extenddb_servers` collection, and after `--lock-timeout` exits 6 naming each server's host and pid. A server renews its registration every 5 s, and every second after a renewal failed, and deletes it when it stops, once every background worker has ended (it leaves it to expire when one could not be stopped); a server that was killed leaves it until it expires, at most 45 s after its last renewal. A server whose registration was deleted, or that has not renewed it for 30 s, for example because the primary stopped answering, answers new requests with `ServiceUnavailable` and registers again, as a PostgreSQL server does after its session ends (above): it serves again once it holds a new registration and the catalog's status is the one it started with, and it stops with exit 1 when a migration holds the lock, when the status changed, or when 30 s pass without a registration. The lock and the registrations expire by the clock of the replica set's primary, so keep the clocks of its members in sync with NTP. Migration 1 deletes the `resource_tag_migration` settings document in the transaction that records its catalog step, so a 0.1.14 server refuses the migrated catalog, and a run that fails before that transaction leaves the document in place. 0.1.12 and 0.1.13 servers read neither that document nor the catalog version, so they start on a migrated catalog and serve it: do not run them against it. To go back to a 0.1.x release, restore the backup taken before `migrate --yes`. A 0.1.x `migrate` on a migrated catalog reports a pending change, and its `--yes` writes the settings document back; this release's status then reports the catalog as written by an older release, and `migrate --yes --reconverge` repairs it. -On Cassandra, `migrate` connects as the role the config file names, which the server connects as too. `--cassandra-user ` connects as another role, with its password in `EXTENDDB_CASSANDRA_PASSWORD` or `--cassandra-pass`; a wrong password is reported as a connection timeout. Migration 1 adopts a 0.1.x catalog: it keeps every setting except the `resource_tag_migration` row, which it deletes, and records itself in a ledger in the catalog keyspace and in every account keyspace. On a cluster that runs `CassandraAuthorizer`, `init` grants the application role SELECT, MODIFY, CREATE and ALTER on the catalog keyspace, those four and DROP on the default account's keyspace, and CREATE ON ALL KEYSPACES, which CreateAccount needs to create a keyspace per account and which also lets the role create tables in every keyspace on the cluster; a run of `migrate --yes --cassandra-user ` that creates a missing account keyspace grants the application role the five permissions on it. A 0.1.x `init` granted the application role nothing, so a deployment created before 1.0 on such a cluster needs the statements below before `migrate`. `migrate --yes` takes the migration lock, a row in the catalog's `settings` table written by lightweight transactions, and then waits for the registration every running server of this release keeps in the catalog's `extenddb_servers` table, and after `--lock-timeout` exits 6 naming each server. A server renews its registration every 5 s, and every second after a renewal failed, and deletes it when it stops, once every background worker has ended (it leaves it to expire when one could not be stopped); a server that was killed leaves it until it expires, at most 45 s after its last renewal. A server tries its renewals for 30 s after the last one that succeeded, so it keeps serving through an outage of 25 to 30 s, depending on when the outage starts, for example while the only replica of the catalog restarts. After that, 30 to 35 s after its last successful renewal, it answers new requests with `ServiceUnavailable` and registers again, as a PostgreSQL server does after its session ends (above), and stops with exit 1 when a migration holds the lock, when the status changed, or when 30 s pass without a registration. A migration needs every replica of the catalog keyspace reachable: the lock is written at `SERIAL`, the registrations are read at `ALL`, and after each schema statement the runner waits until every live node reports the same schema version. `serve` refuses a catalog with pending migrations, exiting 3 under `--foreground` with the pending migrations and the `extenddb migrate --config --yes` command to run. A 0.1.x server refuses a migrated catalog. +On Cassandra, `migrate` connects as the role the config file names, which the server connects as too. `--cassandra-user ` connects as another role, with its password in `EXTENDDB_CASSANDRA_PASSWORD` or `--cassandra-pass`; a wrong password is reported as a connection timeout. Migration 1 adopts a 0.1.x catalog: it keeps every setting except the `resource_tag_migration` row, which it deletes, and records itself in a ledger in the catalog keyspace and in every account keyspace. On a cluster that runs `CassandraAuthorizer`, `init` grants the application role SELECT, MODIFY, CREATE and ALTER on the catalog keyspace, those four and DROP on the default account's keyspace, and CREATE ON ALL KEYSPACES, which CreateAccount needs to create a keyspace per account and which also lets the role create tables in every keyspace on the cluster; a run of `migrate --yes --cassandra-user ` that creates a missing account keyspace grants the application role the five permissions on it. A 0.1.x `init` granted the application role nothing, so a deployment created before 1.0 on such a cluster needs the statements below before `migrate`. `migrate --yes` takes the migration lock, a row in the catalog's `settings` table written by lightweight transactions, and then waits for the registration every running server of this release keeps in the catalog's `extenddb_servers` table, and after `--lock-timeout` exits 6 naming each server. A server renews its registration every 5 s, and every second after a renewal failed, and deletes it when it stops, once every background worker has ended (it leaves it to expire when one could not be stopped); a server that was killed leaves it until it expires, at most 45 s after its last renewal. A server tries its renewals for 30 s after the last one that succeeded, so it keeps serving through an outage of 25 to 30 s, depending on when the outage starts, for example while the only replica of the catalog restarts. After that, 30 to 35 s after its last successful renewal, it answers new requests with `ServiceUnavailable` and registers again, as a PostgreSQL server does after its session ends (above), and stops with exit 1 when a migration holds the lock, when the status changed, or when 30 s pass without a registration. A migration needs every replica of the catalog keyspace reachable: the lock is written at `SERIAL`, the registrations are read at `ALL`, and after each schema statement the runner waits until every live node reports the same schema version. `serve` refuses a catalog with pending migrations, exiting 3 with the pending migrations and the `extenddb migrate --config --yes` command to run, unless it runs under `catalog_upgrade = "apply"` or `--migrate`. A 0.1.x server refuses a migrated catalog. On a deployment created before 1.0 on a cluster that runs `CassandraAuthorizer`, this release's `migrate`, `verify` and `serve`, connected as the application role, fail with `Unauthorized ... has no SELECT permission on _catalog.accounts>` until the role holds its permissions. With every server stopped, run the statements below in `cqlsh` as a superuser; the application role cannot grant them to itself. `` and `` are `username` and `keyspace_prefix` under `[storage.cassandra]` in the config file. Each account has its own keyspace, so list the accounts first: @@ -227,7 +270,7 @@ The 0.1.x binaries named the rebuild in the preview, as `Pending: catalog 0.0.3 To roll back, stop the server, put the copied files back in place of the current ones (remove the current `-wal` and `-shm` first), and start the previous binary. -On SQLite, `extenddb serve` reads the catalog's migration ledger before it opens the database and refuses a catalog with pending migrations, exiting 3 under `--foreground` with each pending migration and the `extenddb migrate --config --yes` command to run (in daemon mode it exits 1 and writes the refusal to syslog); a dev build applies them at startup instead, taking the same copy. +On SQLite, `extenddb serve` reads the catalog's migration ledger before it opens the database and refuses a catalog with pending migrations, exiting 3 with each pending migration and the `extenddb migrate --config --yes` command to run; started with `--migrate`, and in a dev build by default, it applies them at startup instead, taking the same copy. The `extenddb migrate` command that `serve`, `migrate` and `verify` advise names the config file by its absolute path, quoted for a POSIX shell, so it can be pasted as printed. A relative `path` in `[storage.sqlite]`, such as the `extenddb.sqlite` that `init` writes, resolves against the directory a command runs in. So when the config file names the database by a relative `path`, or names none, the advised command starts with `EXTENDDB__STORAGE__SQLITE__PATH=`, and it reaches the same database from any directory. diff --git a/docs/manuals/11-deployment-guide.md b/docs/manuals/11-deployment-guide.md index 419a123d4..4b1e2aa80 100755 --- a/docs/manuals/11-deployment-guide.md +++ b/docs/manuals/11-deployment-guide.md @@ -139,6 +139,8 @@ exists, treat backend failures as something clients retry through. For Kubernetes, run `extenddb init` as an init container or a one-time Job, then deploy extenddb as a Deployment with the generated `extenddb.toml` mounted as a ConfigMap or Secret. +To upgrade on Kubernetes, run one replica with the Deployment strategy `Recreate`, and apply the new release's Deployment together with a migration Job that runs `extenddb migrate --yes` with the serving Secret. The Job's `migrate --yes` waits for the old pod's registration to end while that pod finishes its termination grace period. A pod of the new release that starts before the Job finishes exits 3, and Kubernetes restarts it. Do not run the Job as a Helm pre-upgrade hook: Helm runs the hook while the old pod still serves, so its `migrate --yes` would exit 6. Do not migrate in the pod either. Leave the `migrate` line out of the entrypoint above, and leave `catalog_upgrade` at its default, `refuse`, with no `EXTENDDB__SERVER__CATALOG_UPGRADE` in the pod's environment: a server answers no request while it migrates, and a liveness probe would restart the pod during a long migration. The [upgrade manual](07-upgrade-manual.md#deployment-recipes) describes the recipe and the upgrade from 0.1.x. + ### Air-Gapped ExtendDB requires no internet connectivity. All functionality is self-contained in the binary. Build on a connected host, transfer the binary and `extenddb.toml` to the air-gapped environment, and run. @@ -236,7 +238,7 @@ extenddb init \ ### Upgrades - [ ] Test upgrades in a staging environment first -- [ ] Run `extenddb migrate --config extenddb.toml` after binary upgrade +- [ ] Run `extenddb migrate --config extenddb.toml --yes` after the binary upgrade, or start the new server once with `extenddb serve --migrate --config extenddb.toml` ([Upgrade Manual](07-upgrade-manual.md#applying-migrations-at-startup)) - [ ] Verify catalog version matches: `extenddb verify --config extenddb.toml` ## systemd Service diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index f22a2c4d1..62c97b02b 100755 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -67,9 +67,9 @@ See `docs/local-postgres-setup.md` for full setup instructions. ### `serve`, `migrate` or `verify` exits 3, 4, 5 or 6 naming the catalog -**Cause:** The catalog's status, read from its migration ledgers, is not one this binary serves: exit 3 means migrations are pending, 4 that the catalog has a breaking migration this binary does not know, 5 that a person must act, and 6 that the migration lock or a running server outlasted `--lock-timeout`. The [status table](manuals/07-upgrade-manual.md#the-catalog-status) of the upgrade manual lists each status with its exit codes. +**Cause:** The catalog's status, read from its migration ledgers, is not one this binary serves: exit 3 means migrations are pending, 4 that the catalog has a breaking migration this binary does not know, 5 that a person must act, and 6 that the migration lock or a running server outlasted `--lock-timeout` (for `serve`, `[server] catalog_upgrade_lock_timeout`). The [status table](manuals/07-upgrade-manual.md#the-catalog-status) of the upgrade manual lists each status with its exit codes. -**Fix:** Run the command the message prints. For pending migrations that is `extenddb migrate --config extenddb.toml --yes`, after the backup the message names. +**Fix:** Run the command the message prints. For pending migrations that is `extenddb migrate --config extenddb.toml --yes`, after the backup the message names, or start the server with `--migrate`. ### `the catalog at is not initialized; create it with 'extenddb init'` diff --git a/extenddb.sample.toml b/extenddb.sample.toml index 91869028a..82dce4c2c 100755 --- a/extenddb.sample.toml +++ b/extenddb.sample.toml @@ -27,6 +27,9 @@ # port = 18443 # HTTP port # region = "us-east-1" # AWS region for ARN generation # run_dir = "~/.extenddb/run" # Directory for PID file (~ is expanded to $HOME) +# catalog_upgrade = "refuse" # A catalog behind this binary: "refuse" exits 3, "apply" runs its +# # migrations at startup ("apply" by default in a dev build) +# catalog_upgrade_lock_timeout = 60 # Seconds `serve` waits for the migration lock under "apply" [storage] # backend = "postgres" # Storage backend: "postgres" (default), "mongodb", or "sqlite". From de4b0bf6bf8735c8e03aac7cb7224e56a433b73d Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:38:49 +0000 Subject: [PATCH 05/14] fix(mongodb): release the migration lock with the lock's own client MongoCatalogMigrations now overrides release: it deletes the lock document through the client that took the lock, on the caller's runtime, and sets an atomic released flag, so dropping the lock afterwards does nothing. Before, the release in run_with_lock dropped the lock, and Drop blocked the runtime's thread, connected a new client on a thread of its own and ignored a failed delete. A failed delete left the document until its lease ended, up to 60 s, and the server serve --migrate starts after its run found the document when it registered and exited 6. --- .../src/migrations/commands.rs | 9 +++++++ .../storage-mongodb/src/migrations/locks.rs | 26 ++++++++++++++----- 2 files changed, 28 insertions(+), 7 deletions(-) diff --git a/crates/storage-mongodb/src/migrations/commands.rs b/crates/storage-mongodb/src/migrations/commands.rs index 256f6fdbe..eead1330e 100644 --- a/crates/storage-mongodb/src/migrations/commands.rs +++ b/crates/storage-mongodb/src/migrations/commands.rs @@ -157,6 +157,15 @@ impl CatalogMigrations for MongoCatalogMigrations { migrations.close().await; result } + + /// Delete the lock document with the lock's own client, on this + /// runtime, so the next migration or server need not wait for its + /// lease. Dropping the lock afterwards does nothing. + async fn release(&self, lock: HeldLock) { + if let Ok(held) = held(&lock) { + held.lock.release_held().await; + } + } } /// Take the migration lock on `target`, waiting up to `timeout` for another diff --git a/crates/storage-mongodb/src/migrations/locks.rs b/crates/storage-mongodb/src/migrations/locks.rs index 7d92c8f6e..3bf568689 100644 --- a/crates/storage-mongodb/src/migrations/locks.rs +++ b/crates/storage-mongodb/src/migrations/locks.rs @@ -31,6 +31,7 @@ //! own first and then looks for the other, so two that start together //! cannot both miss each other. +use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::{Arc, Mutex}; use std::time::{Duration, Instant}; @@ -250,7 +251,8 @@ pub struct MigrationLock { token: String, lease: Arc, renewal: JoinHandle<()>, - released: bool, + /// Set by the first release, so a later one and `Drop` do nothing. + released: AtomicBool, } impl MigrationLock { @@ -285,7 +287,7 @@ impl MigrationLock { token, lease, renewal, - released: false, + released: AtomicBool::new(false), }); } if started.elapsed() >= timeout { @@ -344,9 +346,19 @@ impl MigrationLock { } /// Delete the lock document if this process still owns it. - pub async fn release(mut self) { + pub async fn release(self) { + self.release_held().await; + } + + /// [`MigrationLock::release`] for a caller that holds the lock behind a + /// shared reference, as the commands' `HeldLock` does: the delete goes + /// through this lock's own client, on the caller's runtime. Only the + /// first call deletes, and `Drop` then does nothing. + pub(crate) async fn release_held(&self) { self.renewal.abort(); - self.released = true; + if self.released.swap(true, Ordering::SeqCst) { + return; + } let _ = tokio::time::timeout( REQUEST_TIMEOUT, self.settings @@ -358,9 +370,9 @@ impl MigrationLock { /// Stop renewing and keep the document, as a process that was killed /// does: the lock then ends when its lease does. #[cfg(feature = "test-util")] - pub fn abandon(mut self) { + pub fn abandon(self) { self.renewal.abort(); - self.released = true; + self.released.store(true, Ordering::SeqCst); } } @@ -371,7 +383,7 @@ impl Drop for MigrationLock { /// on a thread of its own with a client of its own. fn drop(&mut self) { self.renewal.abort(); - if self.released { + if *self.released.get_mut() { return; } let target = self.target.clone(); From 1642e83f510b2bd6df64a06dede4a3778ade0ebd Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:38:49 +0000 Subject: [PATCH 06/14] fix(migrations): serve a catalog found current under the lock without a run The startup policy's run under apply changes in these ways. - When the status read under the lock is Current or AheadCompatible, the server releases the lock and serves the catalog without calling the backend's run, so on PostgreSQL it makes no pgvector attempt and opens no runner session. run_with_lock takes a WhenCurrent argument for this: Release on the server's path, and Run for migrate --yes, which keeps its pgvector attempt on every run. - After a run that applied nothing, the status is read again, and a catalog ahead of this binary by additive migrations gets the warning that migrate --yes prints after such a run. - Before it takes the lock, the server checks the status notes that migrate --yes checks (before_lock). A note that refuses runs stops the server with exit 1 and the same notes before any change, and the refusal names serve with --migrate or catalog_upgrade = "apply", which before_lock now takes as an argument. Notes that do not refuse are printed as progress lines. The PostgreSQL ownership note names both commands. - A dev build refuses, before the server starts, an uninitialized store that its server would refuse, as Uninitialized with exit 1. The new CatalogMigrations::server_creates_catalog says which stores: on SQLite, a database file that holds tables. In daemon mode the refusal and its message now reach the invoking shell; before, the factory refused the file after the fork, and the shell saw exit 1 with no message. - A progress line comes before the first status read, which runs detect for every pending code body, and before the status read that follows a wait that reached the lock timeout. - The PostgreSQL pgvector notice names the full command, extenddb migrate --yes --pg-user , so the notice is correct when serve prints it. The doc comments now say that the lines of what a run did come when the run ends, with a heartbeat line every 5 s while it goes on. The startup unit tests pass std::slice::from_ref to the fake, as clippy's cloned_ref_to_slice_refs requires, and cover each change: a dev build refuses every status its server cannot serve, the fallback after a wait serves a catalog ahead by additive migrations, a run on a catalog found current under the lock calls no backend run, and a refusing note stops the run before the lock. The PostgreSQL ownership test checks the server's refusal too. --- crates/app/src/cmd_migrate_runner.rs | 19 +- crates/storage-cassandra/tests/migrations.rs | 1 + .../src/migrations/sessions.rs | 10 +- .../src/migrations/vector_extension.rs | 4 +- .../tests/migrations_guards.rs | 31 +- .../storage-sqlite/src/migrations/commands.rs | 10 +- crates/storage/src/migrations/advice_tests.rs | 1 + crates/storage/src/migrations/catalog.rs | 88 ++++- crates/storage/src/migrations/mod.rs | 6 +- crates/storage/src/migrations/startup.rs | 117 +++++-- .../storage/src/migrations/startup_tests.rs | 322 ++++++++++++++---- 11 files changed, 478 insertions(+), 131 deletions(-) diff --git a/crates/app/src/cmd_migrate_runner.rs b/crates/app/src/cmd_migrate_runner.rs index 7dbbf4cf3..5e7e1dab8 100644 --- a/crates/app/src/cmd_migrate_runner.rs +++ b/crates/app/src/cmd_migrate_runner.rs @@ -22,8 +22,8 @@ use extenddb_config as config; use extenddb_storage::migrations::advice::{self, Advice, AdviceFor}; use extenddb_storage::migrations::{ AdminRole, CatalogMigrations, CatalogStatus, Listed, MigrationError, MigrationId, Pending, - RunKind, RunReport, Target, before_lock, behind_line, exit, forget_locked, run_with_lock, - stores_behind, + RunKind, RunReport, Target, WhenCurrent, before_lock, behind_line, exit, forget_locked, + run_with_lock, stores_behind, }; use crate::cmd_migrate::MigrateArgs; @@ -305,14 +305,25 @@ async fn apply( kind: RunKind, lock_timeout: Duration, ) -> Result { - for note in before_lock(migrations, target, kind).await? { + for note in before_lock(migrations, target, kind, "migrate --yes").await? { println!("Note: {}", note.text); } println!( "--- Taking the migration lock (waiting up to {} s for a server or another migration)...", lock_timeout.as_secs() ); - let report = run_with_lock(migrations, target, release, kind, lock_timeout).await?; + // On a current catalog the backend's run still goes ahead: it makes the + // steps the backend takes beside the ledger (PostgreSQL's pgvector + // attempt), which an operator who installs pgvector later relies on. + let report = run_with_lock( + migrations, + target, + release, + kind, + lock_timeout, + WhenCurrent::Run, + ) + .await?; print_report(&report, kind); if report.applied.is_empty() && kind == RunKind::Migrate { // A catalog ahead by additive migrations has nothing to apply and diff --git a/crates/storage-cassandra/tests/migrations.rs b/crates/storage-cassandra/tests/migrations.rs index acb94f771..0e1d27995 100644 --- a/crates/storage-cassandra/tests/migrations.rs +++ b/crates/storage-cassandra/tests/migrations.rs @@ -891,6 +891,7 @@ async fn a_create_account_stopped_before_its_row_leaves_a_current_catalog_a_retr backup: "back up the keyspaces", config: None, assignment: None, + serving: false, }; let message = status_message(&status, &advice); assert!( diff --git a/crates/storage-postgres/src/migrations/sessions.rs b/crates/storage-postgres/src/migrations/sessions.rs index aa6fb12b3..3a591db5e 100644 --- a/crates/storage-postgres/src/migrations/sessions.rs +++ b/crates/storage-postgres/src/migrations/sessions.rs @@ -428,7 +428,8 @@ fn give_to( /// they run and each with the role that runs it ([`give_to`]). Every /// migration that alters such an object fails with SQLSTATE 42501, and so /// does one that creates a table where the role may not, so the note -/// refuses `migrate --yes` before it takes the lock. +/// refuses `migrate --yes`, and a server under `catalog_upgrade = "apply"`, +/// before they take the lock. /// /// # Errors /// @@ -501,9 +502,10 @@ pub(crate) async fn ownership_note( .join(" "); Ok(Some(StatusNote { text: format!( - "{}. Migrations run as {role}, so migrate --yes refuses to apply any while this \ - holds. Connected to {name}, run these statements in this order, each as the role \ - named before it: {steps}", + "{}. Migrations run as {role}, so migrate --yes, and serve with --migrate or \ + catalog_upgrade = \"apply\", refuse to apply any while this holds. Connected to \ + {name}, run these statements in this order, each as the role named before it: \ + {steps}", found.join("; "), ), refuses_runs: true, diff --git a/crates/storage-postgres/src/migrations/vector_extension.rs b/crates/storage-postgres/src/migrations/vector_extension.rs index d8e40a3d0..6bcd6c383 100644 --- a/crates/storage-postgres/src/migrations/vector_extension.rs +++ b/crates/storage-postgres/src/migrations/vector_extension.rs @@ -95,8 +95,8 @@ pub async fn try_create_vector_extension( failures.push(format!("as the application role: {e}")); format!( "NOTICE: could not create the pgvector extension ({}). Vector indexes are \ - unavailable until it is installed; pass --pg-user with a role that may create \ - it to retry.", + unavailable until it is installed; to retry, run extenddb migrate --yes \ + --pg-user with a role that may create it.", failures.join("; ") ) } diff --git a/crates/storage-postgres/tests/migrations_guards.rs b/crates/storage-postgres/tests/migrations_guards.rs index e13886aed..972bc44fb 100644 --- a/crates/storage-postgres/tests/migrations_guards.rs +++ b/crates/storage-postgres/tests/migrations_guards.rs @@ -16,7 +16,8 @@ use std::time::{Duration, Instant}; use async_trait::async_trait; use extenddb_storage::migrations::{ CodeBody, Done, HasManagementStore, Kind, LedgerRow, MigrationBackend, MigrationError, - MigrationId, Outcome, RunKind, Runner, Step, StoreKind, StoreRef, Target, before_lock, exit, + MigrationId, Outcome, RunKind, Runner, Startup, Step, StoreKind, StoreRef, Target, before_lock, + exit, prepare_to_serve, }; use extenddb_storage_postgres::migrations::{ MigrationLock, PostgresCatalogMigrations, PostgresMigrations, PostgresStores, PostgresTarget, @@ -500,6 +501,7 @@ async fn a_role_that_does_not_own_the_tables_is_told_what_to_run() { &PostgresCatalogMigrations, &Target::at(location.as_str()), RunKind::Migrate, + "migrate --yes", ) .await .expect_err("migrate --yes refuses before the lock"); @@ -508,6 +510,33 @@ async fn a_role_that_does_not_own_the_tables_is_told_what_to_run() { refused.to_string().contains("no lock was taken"), "{refused}" ); + // A server under `catalog_upgrade = "apply"` checks the same notes + // before it takes the lock, and refuses with them and the same code, + // naming itself. + let startup = Startup { + apply: true, + creates_uninitialized: false, + release: "1.0.0-test", + lock_timeout: Duration::from_secs(5), + heartbeat: Startup::HEARTBEAT, + }; + let refused = prepare_to_serve( + &PostgresCatalogMigrations, + &Target::at(location.as_str()), + &startup, + &|_| {}, + ) + .await + .expect_err("a server under apply refuses before the lock"); + assert_eq!(refused.exit_code(), exit::ERROR); + let shown = refused.to_string(); + assert!( + shown.starts_with( + "serve with --migrate or catalog_upgrade = \"apply\" refuses to apply migrations" + ) && shown.contains(&format!("the application role {role} does not own")) + && shown.contains("no lock was taken"), + "{shown}" + ); let err = migrate(&target, "test", Duration::from_secs(5)) .await .expect_err("the role cannot alter tables it does not own"); diff --git a/crates/storage-sqlite/src/migrations/commands.rs b/crates/storage-sqlite/src/migrations/commands.rs index 517c5c419..9d8303727 100644 --- a/crates/storage-sqlite/src/migrations/commands.rs +++ b/crates/storage-sqlite/src/migrations/commands.rs @@ -14,7 +14,8 @@ use extenddb_storage::migrations::{ }; use super::{ - MigrationLock, SqliteMigrations, catalog_status, in_memory_refusal, lock_for_migration, + MigrationLock, SqliteMigrations, catalog_status, holds_tables, in_memory_refusal, + lock_for_migration, }; /// The SQLite backend's catalog migrations for the commands. @@ -57,6 +58,13 @@ impl CatalogMigrations for SqliteCatalogMigrations { matches!(crate::serve_lock::database_file(&target.location), Ok(None)) } + /// A dev server creates its catalog in a missing or empty file, and its + /// factory refuses a file that holds tables, another program's database, + /// as `Uninitialized` (`prepare_for_serve`). + async fn server_creates_catalog(&self, target: &Target) -> Result { + Ok(!holds_tables(&target.location).await?) + } + async fn status(&self, target: &Target) -> Result { catalog_status(&target.location).await } diff --git a/crates/storage/src/migrations/advice_tests.rs b/crates/storage/src/migrations/advice_tests.rs index a9746bce9..d46eefb94 100644 --- a/crates/storage/src/migrations/advice_tests.rs +++ b/crates/storage/src/migrations/advice_tests.rs @@ -114,6 +114,7 @@ fn the_config_path_is_quoted_for_a_posix_shell() { backup: "back up /srv/x.sqlite", config: Some("/srv/sp ace's dir/extenddb.toml"), assignment: None, + serving: false, }; assert_eq!( advised(&written_by_older_release(), &advice), diff --git a/crates/storage/src/migrations/catalog.rs b/crates/storage/src/migrations/catalog.rs index 4a168ddc7..0e2ff4f62 100644 --- a/crates/storage/src/migrations/catalog.rs +++ b/crates/storage/src/migrations/catalog.rs @@ -195,6 +195,18 @@ pub trait CatalogMigrations: Send + Sync { false } + /// Whether a dev build's server creates its catalog in the store at + /// `target`, whose status is `Uninitialized`. `true` (the default) when + /// the backend's server factory creates the catalog in any such store. + /// A backend whose factory refuses an uninitialized store that holds + /// another program's data, as `Uninitialized`, returns `false` for one + /// (SQLite: a database file with tables), so `serve` refuses it before + /// it forks with the refusal the factory gives after. Read-only. + async fn server_creates_catalog(&self, target: &Target) -> Result { + let _ = target; + Ok(true) + } + /// The catalog status. Takes no lock and writes nothing, so it runs /// beside a server. async fn status(&self, target: &Target) -> Result; @@ -242,10 +254,11 @@ pub trait CatalogMigrations: Send + Sync { } /// Notes about the deployment that its status does not show, for the - /// preview and `verify` to print and `migrate --yes` to check before it - /// takes the lock ([`before_lock`]). On PostgreSQL: tables and sequences - /// the application role does not own. Read-only, like the status. None - /// by default. + /// preview and `verify` to print, and for `migrate --yes` and a server + /// under `catalog_upgrade = "apply"` to check before they take the lock + /// ([`before_lock`]). On PostgreSQL: tables and sequences the + /// application role does not own. Read-only, like the status. None by + /// default. async fn status_notes(&self, target: &Target) -> Result, MigrationError> { let _ = target; Ok(Vec::new()) @@ -315,16 +328,19 @@ pub async fn policy_rewrite_lines( pub struct StatusNote { /// The line the preview and `verify` print. pub text: String, - /// Whether `migrate --yes` refuses before it takes the lock while the - /// note holds and the run would apply something. + /// Whether `migrate --yes`, and a server under `catalog_upgrade = + /// "apply"`, refuse before they take the lock while the note holds and + /// the run would apply something. pub refuses_runs: bool, } -/// What `migrate --yes` checks before it takes the lock: the backend's -/// status notes, returned for the operator to read, or a refusal (exit 1) -/// when a note refuses runs and the run would apply something, which is -/// every `--reconverge` and a `migrate` whose status is not `Current` or -/// `AheadCompatible`. `init` creates its objects and checks nothing. +/// What `migrate --yes`, and a server under `catalog_upgrade = "apply"`, +/// check before they take the lock: the backend's status notes, returned +/// for the operator to read, or a refusal (exit 1) when a note refuses runs +/// and the run would apply something, which is every `--reconverge` and a +/// `migrate` whose status is not `Current` or `AheadCompatible`. The +/// refusal names `command`, the command that checks (`migrate --yes`). +/// `init` creates its objects and checks nothing. /// /// # Errors /// @@ -334,6 +350,7 @@ pub async fn before_lock( migrations: &dyn CatalogMigrations, target: &Target, kind: RunKind, + command: &str, ) -> Result, MigrationError> { if kind == RunKind::Create { return Ok(Vec::new()); @@ -359,7 +376,7 @@ pub async fn before_lock( // One note per line, as the preview prints them, so the statements // each note ends with can be copied on their own. Err(MigrationError::Refused(format!( - "migrate --yes refuses to apply migrations while these notes hold:\n{}\nNothing was \ + "{command} refuses to apply migrations while these notes hold:\n{}\nNothing was \ changed and no lock was taken.", refusing .iter() @@ -384,8 +401,48 @@ pub async fn run_locked( lock: &HeldLock, release: &str, kind: RunKind, +) -> Result { + locked_run(migrations, target, lock, release, kind, WhenCurrent::Run).await +} + +/// What [`run_with_lock`] does with a `migrate` run when the status it +/// reads under the lock is `Current` or `AheadCompatible`, so the run has +/// nothing to apply. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum WhenCurrent { + /// Call the backend's run, which records nothing and makes the steps + /// the backend takes beside the ledger on every run (PostgreSQL's + /// pgvector attempt): `migrate --yes`. + Run, + /// Release the lock without calling the backend's run, and return a + /// report with no step: a server starting under `catalog_upgrade = + /// "apply"`, which serves the catalog as it is. + Release, +} + +/// [`run_locked`], returning a report with no step instead of calling the +/// backend's run when `when_current` says so and the status under the lock +/// leaves a `migrate` run nothing to apply. +async fn locked_run( + migrations: &dyn CatalogMigrations, + target: &Target, + lock: &HeldLock, + release: &str, + kind: RunKind, + when_current: WhenCurrent, ) -> Result { let status = migrations.status_under_lock(lock, target).await?; + if when_current == WhenCurrent::Release + && kind == RunKind::Migrate + && let CatalogStatus::Current { version } | CatalogStatus::AheadCompatible { version, .. } = + &status + { + return Ok(RunReport { + from: Some(*version), + to: Some(*version), + ..RunReport::default() + }); + } run_with_status(migrations, &status, lock, release, kind).await } @@ -412,7 +469,9 @@ pub async fn run_with_status( /// Take the migration lock for `target`, waiting up to `timeout` for /// another migration and for running servers, run `kind` under it /// ([`run_locked`]), and release it on every exit path. `migrate --yes` -/// and a server starting under `catalog_upgrade = "apply"` both run this. +/// and a server starting under `catalog_upgrade = "apply"` both run this; +/// `when_current` says what a `migrate` run does when the status under the +/// lock leaves it nothing to apply. /// /// # Errors /// @@ -424,9 +483,10 @@ pub async fn run_with_lock( release: &str, kind: RunKind, timeout: Duration, + when_current: WhenCurrent, ) -> Result { let lock = migrations.lock(target, timeout).await?; - let report = run_locked(migrations, target, &lock, release, kind).await; + let report = locked_run(migrations, target, &lock, release, kind, when_current).await; migrations.release(lock).await; report } diff --git a/crates/storage/src/migrations/mod.rs b/crates/storage/src/migrations/mod.rs index f8e39d5cb..1bc871307 100644 --- a/crates/storage/src/migrations/mod.rs +++ b/crates/storage/src/migrations/mod.rs @@ -42,9 +42,9 @@ pub mod m0002_resource_tag_condition_keys; pub use backend::{MigrationBackend, Step, StoreRef}; pub use catalog::{ - AdminRole, CatalogMigrations, HeldLock, Listed, RunKind, StatusNote, Target, before_lock, - binary_catalog_label, forget_locked, installed, policy_rewrite_lines, policy_rewrite_pending, - run_locked, run_with_lock, run_with_status, + AdminRole, CatalogMigrations, HeldLock, Listed, RunKind, StatusNote, Target, WhenCurrent, + before_lock, binary_catalog_label, forget_locked, installed, policy_rewrite_lines, + policy_rewrite_pending, run_locked, run_with_lock, run_with_status, }; #[cfg(any(test, feature = "test-util"))] pub use checksum::check_released; diff --git a/crates/storage/src/migrations/startup.rs b/crates/storage/src/migrations/startup.rs index eb2915c9a..808768c58 100644 --- a/crates/storage/src/migrations/startup.rs +++ b/crates/storage/src/migrations/startup.rs @@ -7,25 +7,28 @@ //! //! The status is read with no lock. `Current` serves, and so does //! `AheadCompatible`, with a warning. Under `apply` a catalog behind this -//! binary is migrated first, by the run `migrate --yes` makes +//! binary is migrated first: the status notes `migrate --yes` checks before +//! it takes the lock ([`before_lock`]), then the run `migrate --yes` makes //! ([`run_with_lock`]): the migration lock, which waits for another //! migration and for running servers, the status read again under it, so a -//! catalog another process migrated meanwhile is left as it is, `detect` -//! for every pending code body before the first write, the SQLite copy, the -//! runner, and the release. Under `refuse`, and under `apply` for every -//! other status, the server stops with the status's exit code: no setting -//! serves a catalog this binary cannot use. +//! catalog another process migrated meanwhile is served as it is without +//! the backend's run, `detect` for every pending code body before the first +//! write, the SQLite copy, the runner, and the release. Under `refuse`, and +//! under `apply` for every other status, the server stops with the status's +//! exit code: no setting serves a catalog this binary cannot use. //! //! A dev build serves a store that is not a catalog yet, which its server -//! creates. A store that exists only inside the server (an in-memory SQLite -//! database) is created by the server when it starts and is not read here. +//! creates, unless the backend's server refuses that store +//! ([`CatalogMigrations::server_creates_catalog`]). A store that exists only +//! inside the server (an in-memory SQLite database) is created by the +//! server when it starts and is not read here. use std::time::Duration; use tokio::time::Instant; use super::advice::pending_line; -use super::catalog::{CatalogMigrations, RunKind, Target, run_with_lock}; +use super::catalog::{CatalogMigrations, RunKind, Target, WhenCurrent, before_lock, run_with_lock}; use super::registry::MigrationId; use super::status::{CatalogStatus, MigrationError, RunReport}; @@ -36,7 +39,9 @@ pub struct Startup<'a> { /// refusing it (`catalog_upgrade = "apply"`). pub apply: bool, /// Leave a store that is not a catalog yet to the server, which creates - /// it: a dev build, which needs no `init`. + /// it: a dev build, which needs no `init`. A store the backend's server + /// would refuse ([`CatalogMigrations::server_creates_catalog`]) is + /// refused here. pub creates_uninitialized: bool, /// The ExtendDB release, recorded in the ledger rows the run writes. pub release: &'a str, @@ -66,18 +71,32 @@ pub struct Prepared { pub warning: Option, } +/// The command a refusal before the lock names on the server's path. +const SERVER_APPLYING: &str = "serve with --migrate or catalog_upgrade = \"apply\""; + +/// The line before the first status read. +const READING: &str = "reading the catalog status"; + +/// The line before the status read that follows a wait that reached the +/// lock timeout. +const READING_AGAIN: &str = "the wait reached the lock timeout; reading the catalog status again"; + /// Read the status of the catalog at `target` and decide whether a server /// may open it, applying its pending migrations first when `startup` says -/// so. `progress` receives a line for each step of a run, and one every -/// [`Startup::heartbeat`] while it goes on, which the server prints on -/// stderr. +/// so. `progress` receives the lines the server prints on stderr: one +/// before the status is read; for a run, the pending migrations, the status +/// notes the run checks before the lock, the wait for the lock, and one +/// line every [`Startup::heartbeat`] while the run goes on; and when the +/// run ends, the lines of what it did: the SQLite copy, each migration it +/// applied, and the migration the catalog is at. /// /// # Errors /// /// [`MigrationError::Status`] with the status a server refuses, which -/// carries its exit code; [`MigrationError::Locked`] (exit 6) when the lock -/// or a running server outlasted the timeout and the catalog is still -/// behind; or as [`run_with_lock`]. +/// carries its exit code; [`MigrationError::Refused`] (exit 1) when a status +/// note refuses the run ([`before_lock`]); [`MigrationError::Locked`] +/// (exit 6) when the lock or a running server outlasted the timeout and the +/// catalog is still behind; or as [`run_with_lock`]. pub async fn prepare_to_serve( migrations: &dyn CatalogMigrations, target: &Target, @@ -87,11 +106,20 @@ pub async fn prepare_to_serve( if migrations.in_process(target) { return Ok(Prepared::default()); } + // The read runs `detect` for every pending code body, which can take a + // while on a large catalog. + progress(READING); let status = migrations.status(target).await?; match &status { CatalogStatus::Current { .. } => Ok(Prepared::default()), CatalogStatus::AheadCompatible { .. } => Ok(served_ahead(&status)), - CatalogStatus::Uninitialized if startup.creates_uninitialized => Ok(Prepared::default()), + CatalogStatus::Uninitialized if startup.creates_uninitialized => { + if migrations.server_creates_catalog(target).await? { + Ok(Prepared::default()) + } else { + Err(MigrationError::Status(CatalogStatus::Uninitialized)) + } + } CatalogStatus::Behind { version, pending } if startup.apply => { let latest = MigrationId::LATEST.number(); progress(&match version { @@ -105,6 +133,12 @@ pub async fn prepare_to_serve( ), }); progress(&pending_line(pending)); + // The notes `migrate --yes` checks before it takes the lock: a + // note that refuses runs stops the server here, before any + // change, with the refusal `migrate --yes` gives. + for note in before_lock(migrations, target, RunKind::Migrate, SERVER_APPLYING).await? { + progress(&format!("note: {}", note.text)); + } apply(migrations, target, startup, progress).await } _ => Err(MigrationError::Status(status)), @@ -134,12 +168,16 @@ async fn apply( startup.lock_timeout.as_secs() )); let started = Instant::now(); + // A catalog that another process migrated while this one waited is + // served as it is: the backend's run, which on PostgreSQL makes the + // pgvector attempt and opens the runner's sessions, is not called. let run = run_with_lock( migrations, target, startup.release, RunKind::Migrate, startup.lock_timeout, + WhenCurrent::Release, ); let mut run = std::pin::pin!(run); let mut heartbeat = tokio::time::interval_at(started + startup.heartbeat, startup.heartbeat); @@ -156,30 +194,53 @@ async fn apply( for line in report_lines(&report) { progress(&line); } + // A run that applied nothing found the catalog migrated by + // another process, which may have left it ahead of this binary + // by additive migrations: the status says so, as `migrate --yes` + // reads it after such a run. + let warning = if report.applied.is_empty() { + ahead_warning(migrations, target).await + } else { + None + }; Ok(Prepared { run: Some(report), - warning: None, + warning, }) } // A process that migrated the catalog while this one waited, and // then started serving it, holds what the lock waits for. The // catalog then needs nothing, and the server starts as `serve` // would on it; the server's own checks decide whether it may. - Err(MigrationError::Locked(message)) => match migrations.status(target).await { - Ok(CatalogStatus::Current { .. }) => { - progress(MIGRATED_ELSEWHERE); - Ok(Prepared::default()) - } - Ok(status @ CatalogStatus::AheadCompatible { .. }) => { - progress(MIGRATED_ELSEWHERE); - Ok(served_ahead(&status)) + Err(MigrationError::Locked(message)) => { + progress(READING_AGAIN); + match migrations.status(target).await { + Ok(CatalogStatus::Current { .. }) => { + progress(MIGRATED_ELSEWHERE); + Ok(Prepared::default()) + } + Ok(status @ CatalogStatus::AheadCompatible { .. }) => { + progress(MIGRATED_ELSEWHERE); + Ok(served_ahead(&status)) + } + _ => Err(MigrationError::Locked(message)), } - _ => Err(MigrationError::Locked(message)), - }, + } Err(error) => Err(error), } } +/// The warning for a catalog ahead of this binary by additive migrations, +/// read after a run that applied nothing. `None` for any other status, and +/// when the read fails: the server reads the status again when it +/// registers. +async fn ahead_warning(migrations: &dyn CatalogMigrations, target: &Target) -> Option { + match migrations.status(target).await { + Ok(status @ CatalogStatus::AheadCompatible { .. }) => served_ahead(&status).warning, + _ => None, + } +} + /// The line for a run that found the catalog migrated by another process. const MIGRATED_ELSEWHERE: &str = "nothing to apply: another process migrated the catalog while this one waited for the lock"; diff --git a/crates/storage/src/migrations/startup_tests.rs b/crates/storage/src/migrations/startup_tests.rs index 971d39091..049fec0d5 100644 --- a/crates/storage/src/migrations/startup_tests.rs +++ b/crates/storage/src/migrations/startup_tests.rs @@ -11,10 +11,10 @@ use std::time::Duration; use async_trait::async_trait; -use super::{Prepared, Startup, prepare_to_serve}; +use super::{MIGRATED_ELSEWHERE, Prepared, READING, Startup, prepare_to_serve}; use crate::migrations::{ AppliedStep, CatalogMigrations, CatalogStatus, HeldLock, Kind, LedgerRow, Listed, - MigrationError, MigrationId, Pending, RunKind, RunReport, StoreKind, Target, exit, + MigrationError, MigrationId, Pending, RunKind, RunReport, StatusNote, StoreKind, Target, exit, }; struct Fake { @@ -24,6 +24,9 @@ struct Fake { report: RunReport, run_takes: Duration, in_process: bool, + /// What `server_creates_catalog` answers. + creates: bool, + notes: Vec, calls: Mutex>, } @@ -35,6 +38,8 @@ impl Fake { report: applied_report(), run_takes: Duration::ZERO, in_process: false, + creates: true, + notes: Vec::new(), calls: Mutex::new(Vec::new()), } } @@ -59,6 +64,10 @@ impl CatalogMigrations for Fake { fn in_process(&self, _target: &Target) -> bool { self.in_process } + async fn server_creates_catalog(&self, _target: &Target) -> Result { + self.call("creates"); + Ok(self.creates) + } async fn status(&self, _target: &Target) -> Result { self.call("status"); let mut statuses = self.statuses.lock().unwrap(); @@ -95,6 +104,10 @@ impl CatalogMigrations for Fake { self.call("release"); drop(lock); } + async fn status_notes(&self, _target: &Target) -> Result, MigrationError> { + self.call("notes"); + Ok(self.notes.clone()) + } } fn behind() -> CatalogStatus { @@ -120,6 +133,49 @@ fn current() -> CatalogStatus { } } +/// A catalog a newer binary migrated, ahead of this one by an additive +/// migration. +fn ahead() -> CatalogStatus { + CatalogStatus::AheadCompatible { + version: MigrationId::LATEST.number() + 1, + unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], + } +} + +/// The statuses no server serves under either value of the policy, with +/// their exit codes, apart from `Uninitialized`, which a dev build serves. +fn unservable() -> Vec<(CatalogStatus, u8)> { + vec![ + ( + CatalogStatus::NeedsAttention { + items: vec!["migration 2: a collision".to_owned()], + }, + exit::ATTENTION, + ), + ( + CatalogStatus::Changed { + id: 1, + store_name: "db".to_owned(), + recorded: "a".to_owned(), + expected: "b".to_owned(), + }, + exit::ATTENTION, + ), + ( + CatalogStatus::WrittenByOlderRelease { + trace: "catalog_version is 0.0.4".to_owned(), + }, + exit::ATTENTION, + ), + ( + CatalogStatus::AheadIncompatible { + unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], + }, + exit::AHEAD_INCOMPATIBLE, + ), + ] +} + fn applied_report() -> RunReport { RunReport { from: Some(1), @@ -131,6 +187,7 @@ fn applied_report() -> RunReport { id: id.number(), name: id.name(), store_name: "db".to_owned(), + outcome: crate::migrations::Outcome::Applied, notes: Vec::new(), }) .collect(), @@ -148,6 +205,15 @@ const fn startup(apply: bool) -> Startup<'static> { } } +/// A dev build's policy: the server creates a catalog in a store that is +/// not one yet. +const fn dev(apply: bool) -> Startup<'static> { + Startup { + creates_uninitialized: true, + ..startup(apply) + } +} + /// Run the policy, returning its outcome and the lines it reported. async fn prepare( fake: &Fake, @@ -169,11 +235,12 @@ async fn refuse_stops_a_catalog_behind_with_exit_3_and_takes_no_lock() { assert_eq!(error, MigrationError::Status(behind())); assert_eq!(error.exit_code(), exit::PENDING); assert_eq!(fake.calls(), ["status"]); - assert!(lines.is_empty(), "{lines:?}"); + assert_eq!(lines, [READING]); } -/// Under `apply` the run is `migrate --yes`'s: the lock, the status read -/// again under it, the run, and the release. +/// Under `apply` the run is `migrate --yes`'s: the status notes, the lock, +/// the status read again under it, the run, and the release. A line comes +/// before the first status read, which runs `detect`. #[tokio::test] async fn apply_migrates_a_catalog_behind_under_the_lock_and_releases_it() { let fake = Fake::new(&[behind()]); @@ -181,25 +248,29 @@ async fn apply_migrates_a_catalog_behind_under_the_lock_and_releases_it() { let prepared = result.expect("applied"); assert_eq!(prepared.run, Some(applied_report())); assert_eq!(prepared.warning, None); - assert_eq!(fake.calls(), ["status", "lock", "status", "run", "release"]); + assert_eq!( + fake.calls(), + ["status", "notes", "lock", "status", "run", "release"] + ); let latest = MigrationId::LATEST.number(); + assert_eq!(lines[0], READING); assert_eq!( - lines[0], + lines[1], format!( "the catalog is at migration 1 and this binary needs migration {latest}; applying \ the pending migrations before the server starts" ) ); assert!( - lines[1].starts_with("Pending (all breaking): 2 "), + lines[2].starts_with("Pending (all breaking): 2 "), "{lines:?}" ); assert_eq!( - lines[2], + lines[3], "taking the migration lock, waiting up to 1 s for a server or another migration" ); - assert_eq!(lines[3], "copied the database to db.pre-migration-1-to-4-x"); - assert_eq!(lines[4], "applied 2 resource_tag_condition_keys"); + assert_eq!(lines[4], "copied the database to db.pre-migration-1-to-4-x"); + assert_eq!(lines[5], "applied 2 resource_tag_condition_keys"); assert_eq!( lines.last().map(String::as_str), Some(format!("the catalog is at migration {latest}").as_str()) @@ -213,18 +284,15 @@ async fn a_current_catalog_serves_with_no_lock_and_no_run() { let (result, lines) = prepare(&fake, &startup(apply)).await; assert_eq!(result, Ok(Prepared::default())); assert_eq!(fake.calls(), ["status"]); - assert!(lines.is_empty(), "{lines:?}"); + assert_eq!(lines, [READING]); } } #[tokio::test] async fn a_catalog_ahead_by_additive_migrations_serves_with_a_warning() { - let ahead = CatalogStatus::AheadCompatible { - version: MigrationId::LATEST.number() + 1, - unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], - }; + let ahead = ahead(); for apply in [false, true] { - let fake = Fake::new(&[ahead.clone()]); + let fake = Fake::new(std::slice::from_ref(&ahead)); let (result, _) = prepare(&fake, &startup(apply)).await; let prepared = result.expect("served"); assert_eq!(prepared.run, None); @@ -238,45 +306,17 @@ async fn a_catalog_ahead_by_additive_migrations_serves_with_a_warning() { /// status but `Behind` is refused as under `refuse`, before any lock. #[tokio::test] async fn apply_refuses_every_other_status_with_its_code_and_takes_no_lock() { - let cases = [ - ( - CatalogStatus::NeedsAttention { - items: vec!["migration 2: a collision".to_owned()], - }, - exit::ATTENTION, - ), - ( - CatalogStatus::Changed { - id: 1, - store_name: "db".to_owned(), - recorded: "a".to_owned(), - expected: "b".to_owned(), - }, - exit::ATTENTION, - ), - ( - CatalogStatus::WrittenByOlderRelease { - trace: "catalog_version is 0.0.4".to_owned(), - }, - exit::ATTENTION, - ), - ( - CatalogStatus::AheadIncompatible { - unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], - }, - exit::AHEAD_INCOMPATIBLE, - ), - (CatalogStatus::Uninitialized, exit::ERROR), - ]; + let mut cases = unservable(); + cases.push((CatalogStatus::Uninitialized, exit::ERROR)); for (status, code) in cases { for apply in [false, true] { - let fake = Fake::new(&[status.clone()]); + let fake = Fake::new(std::slice::from_ref(&status)); let (result, lines) = prepare(&fake, &startup(apply)).await; let error = result.expect_err("refused"); assert_eq!(error, MigrationError::Status(status.clone())); assert_eq!(error.exit_code(), code, "{status:?}"); assert_eq!(fake.calls(), ["status"], "{status:?}"); - assert!(lines.is_empty(), "{lines:?}"); + assert_eq!(lines, [READING]); } } } @@ -286,13 +326,59 @@ async fn apply_refuses_every_other_status_with_its_code_and_takes_no_lock() { #[tokio::test] async fn a_dev_build_leaves_an_uninitialized_store_to_the_server() { let fake = Fake::new(&[CatalogStatus::Uninitialized]); - let dev = Startup { - creates_uninitialized: true, - ..startup(false) - }; - let (result, _) = prepare(&fake, &dev).await; + let (result, _) = prepare(&fake, &dev(false)).await; assert_eq!(result, Ok(Prepared::default())); + assert_eq!(fake.calls(), ["status", "creates"]); +} + +/// A dev build serves only what any server serves, and a store its server +/// creates: every other status is refused with its code under both values, +/// and `Behind` under `refuse`, before any lock. `Behind` under `apply` is +/// migrated. +#[tokio::test] +async fn a_dev_build_refuses_every_status_its_server_cannot_serve() { + for (status, code) in unservable() { + for apply in [false, true] { + let fake = Fake::new(std::slice::from_ref(&status)); + let (result, _) = prepare(&fake, &dev(apply)).await; + let error = result.expect_err("refused"); + assert_eq!(error, MigrationError::Status(status.clone())); + assert_eq!(error.exit_code(), code, "{status:?}"); + assert_eq!(fake.calls(), ["status"], "{status:?}"); + } + } + let fake = Fake::new(&[behind()]); + let (result, _) = prepare(&fake, &dev(false)).await; + assert_eq!(result.expect_err("refused").exit_code(), exit::PENDING); assert_eq!(fake.calls(), ["status"]); + + for status in [current(), ahead(), CatalogStatus::Uninitialized] { + for apply in [false, true] { + let fake = Fake::new(std::slice::from_ref(&status)); + let (result, _) = prepare(&fake, &dev(apply)).await; + assert_eq!(result.expect("served").run, None, "{status:?}"); + assert!(!fake.calls().contains(&"lock"), "{status:?}"); + } + } + let fake = Fake::new(&[behind()]); + let (result, _) = prepare(&fake, &dev(true)).await; + assert_eq!(result.expect("applied").run, Some(applied_report())); +} + +/// A store the backend's server would refuse, such as a SQLite file that +/// holds another program's tables, is refused before the server starts, +/// as `Uninitialized` with exit 1, in a dev build too. +#[tokio::test] +async fn a_dev_build_refuses_a_store_its_server_would_refuse() { + let mut fake = Fake::new(&[CatalogStatus::Uninitialized]); + fake.creates = false; + for apply in [false, true] { + let (result, _) = prepare(&fake, &dev(apply)).await; + let error = result.expect_err("refused"); + assert_eq!(error, MigrationError::Status(CatalogStatus::Uninitialized)); + assert_eq!(error.exit_code(), exit::ERROR); + } + assert!(!fake.calls().contains(&"lock"), "{:?}", fake.calls()); } /// An in-memory store is created by the server that opens it: nothing is @@ -301,9 +387,10 @@ async fn a_dev_build_leaves_an_uninitialized_store_to_the_server() { async fn an_in_process_store_is_not_read() { let mut fake = Fake::new(&[behind()]); fake.in_process = true; - let (result, _) = prepare(&fake, &startup(true)).await; + let (result, lines) = prepare(&fake, &startup(true)).await; assert_eq!(result, Ok(Prepared::default())); assert!(fake.calls().is_empty(), "{:?}", fake.calls()); + assert!(lines.is_empty(), "{lines:?}"); } /// A lock that stays held past the timeout stops the server with exit 6 @@ -314,12 +401,14 @@ async fn a_lock_held_past_the_timeout_exits_6() { fake.lock = Err(MigrationError::Locked( "another migration holds it".to_owned(), )); - let (result, _) = prepare(&fake, &startup(true)).await; + let (result, lines) = prepare(&fake, &startup(true)).await; let error = result.expect_err("locked"); assert_eq!(error.exit_code(), exit::LOCKED); assert_eq!(error.to_string(), "another migration holds it"); - // The status is read again after the wait, and the backend ran nothing. - assert_eq!(fake.calls(), ["status", "lock", "status"]); + // The status is read again after the wait, after a line saying so, and + // the backend ran nothing. + assert_eq!(fake.calls(), ["status", "notes", "lock", "status"]); + assert_eq!(lines.last().map(String::as_str), Some(super::READING_AGAIN)); } /// Another process migrated the catalog while this one waited, and holds @@ -331,31 +420,116 @@ async fn a_catalog_migrated_by_another_process_during_the_wait_serves() { fake.lock = Err(MigrationError::Locked("a server serves it".to_owned())); let (result, lines) = prepare(&fake, &startup(true)).await; assert_eq!(result, Ok(Prepared::default())); - assert_eq!(fake.calls(), ["status", "lock", "status"]); - assert_eq!( - lines.last().map(String::as_str), - Some(super::MIGRATED_ELSEWHERE) - ); + assert_eq!(fake.calls(), ["status", "notes", "lock", "status"]); + assert_eq!(lines.last().map(String::as_str), Some(MIGRATED_ELSEWHERE)); +} + +/// The same, with a newer binary that left the catalog ahead of this one +/// by additive migrations: it is served with the warning. +#[tokio::test] +async fn the_fallback_after_the_wait_serves_a_catalog_ahead_by_additive_migrations() { + let mut fake = Fake::new(&[behind(), ahead()]); + fake.lock = Err(MigrationError::Locked("a server serves it".to_owned())); + let (result, lines) = prepare(&fake, &startup(true)).await; + let prepared = result.expect("served"); + assert_eq!(prepared.run, None); + let warning = prepared.warning.expect("a warning"); + assert!(warning.contains("additive"), "{warning}"); + assert_eq!(fake.calls(), ["status", "notes", "lock", "status"]); + assert_eq!(lines.last().map(String::as_str), Some(MIGRATED_ELSEWHERE)); } -/// The status read under the lock finds the catalog migrated: the run -/// applies nothing, and says so. +/// The status read under the lock finds the catalog migrated: the lock is +/// released and the catalog served without the backend's run, which on +/// PostgreSQL would make the pgvector attempt and open the runner's +/// sessions. #[tokio::test] async fn a_run_that_finds_the_catalog_migrated_under_the_lock_applies_nothing() { - let mut fake = Fake::new(&[behind(), current()]); - fake.report = RunReport { - from: Some(MigrationId::LATEST.number()), - to: Some(MigrationId::LATEST.number()), - ..RunReport::default() - }; + let fake = Fake::new(&[behind(), current()]); let (result, lines) = prepare(&fake, &startup(true)).await; let prepared = result.expect("served"); + let latest = MigrationId::LATEST.number(); + assert_eq!( + prepared.run, + Some(RunReport { + from: Some(latest), + to: Some(latest), + ..RunReport::default() + }) + ); + assert_eq!(prepared.warning, None); + // The status read after the run looks for a catalog ahead by additive + // migrations. + assert_eq!( + fake.calls(), + ["status", "notes", "lock", "status", "release", "status"] + ); + assert_eq!(lines.last().map(String::as_str), Some(MIGRATED_ELSEWHERE)); +} + +/// A newer binary migrated the catalog while this one waited, ahead of it +/// by an additive migration: the run under the lock applies nothing, and +/// the status read after it gives the warning `migrate --yes` prints. +#[tokio::test] +async fn a_run_that_applied_nothing_warns_of_a_catalog_ahead_by_additive_migrations() { + let fake = Fake::new(&[behind(), ahead()]); + let (result, _) = prepare(&fake, &startup(true)).await; + let prepared = result.expect("served"); assert!(prepared.run.expect("a run").applied.is_empty()); - assert_eq!(fake.calls(), ["status", "lock", "status", "run", "release"]); + let warning = prepared.warning.expect("a warning"); + assert!(warning.contains("additive"), "{warning}"); assert_eq!( - lines.last().map(String::as_str), - Some(super::MIGRATED_ELSEWHERE) + fake.calls(), + ["status", "notes", "lock", "status", "release", "status"] + ); +} + +/// Under `apply` the server checks the status notes `migrate --yes` checks +/// before it takes the lock: a note that refuses runs stops it with exit 1 +/// and the same notes, naming the server's command, before any lock. A +/// note that does not refuse is printed as a progress line. +#[tokio::test] +async fn a_note_that_refuses_runs_stops_apply_before_the_lock() { + let note = StatusNote { + text: "the role does not own the tables".to_owned(), + refuses_runs: true, + }; + let mut fake = Fake::new(&[behind()]); + fake.notes = vec![note.clone()]; + let (result, lines) = prepare(&fake, &startup(true)).await; + let error = result.expect_err("refused"); + assert_eq!(error.exit_code(), exit::ERROR); + assert_eq!( + error.to_string().lines().collect::>(), + [ + "serve with --migrate or catalog_upgrade = \"apply\" refuses to apply migrations \ + while these notes hold:", + "Note: the role does not own the tables", + "Nothing was changed and no lock was taken.", + ] + ); + assert_eq!(fake.calls(), ["status", "notes", "status"]); + assert!( + !lines + .iter() + .any(|l| l.starts_with("taking the migration lock")), + "{lines:?}" + ); + + let mut fake = Fake::new(&[behind()]); + fake.notes = vec![StatusNote { + refuses_runs: false, + ..note + }]; + let (result, lines) = prepare(&fake, &startup(true)).await; + result.expect("applied"); + assert!( + lines + .iter() + .any(|l| l == "note: the role does not own the tables"), + "{lines:?}" ); + assert!(fake.calls().contains(&"run"), "{:?}", fake.calls()); } /// While the run goes on, a line says so every heartbeat, which is what From 9df3f5d942cc3d3772fb281cf51bdbffdaf7a8b0 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:38:49 +0000 Subject: [PATCH 07/14] fix(serve): check the catalog before the bind, log during it, bound its shutdown serve now starts in this order: the config checks, the refusal of daemon mode on a platform without it, the catalog check, the bind, the banner and the fork. The platform check used to come after the catalog check, so serve without --foreground on such a platform read the status, and under apply migrated, before it failed. The bind used to come before the catalog check, so during a long migration the kernel accepted connections that got no answer until the server started. A port conflict is still reported before the fork, and the banner still follows the bind. The catalog check runs under a stderr subscriber built as the one migrate --yes uses, set with tracing::subscriber::with_default for the check alone, so the warnings the backends log during a run reach stderr and the global default stays free for the server. Before, the run came before the server installed its subscriber, and PostgreSQL's lock retry warnings and Cassandra's lease warnings were dropped. The check times the shutdown of its runtime. When the shutdown reaches its 10 s cap, a blocking thread may still be running, and a lock that thread holds would stay held in the child after a fork. In daemon mode serve then prints the cause on stderr and exits 1 instead of forking. Each line of a progress message is printed with the "catalog migration: " prefix, so a message that spans lines counts as progress on each line. The check takes its inputs in ServeStart, and its core takes the backend and the output, so the tests run it on a fake. They cover --migrate over catalog_upgrade = "refuse", the prefix on every line, the exit code of a refusal, which is never 0, the cap on the shutdown, the bound of a day on catalog_upgrade_lock_timeout, and the prefix the npm launcher matches in packaging/npm/startup.js. --- crates/app/src/cmd_serve.rs | 76 +++--- crates/app/src/serve_catalog.rs | 171 ++++++++++---- crates/app/src/serve_catalog_tests.rs | 327 ++++++++++++++++++++++++++ 3 files changed, 495 insertions(+), 79 deletions(-) create mode 100644 crates/app/src/serve_catalog_tests.rs diff --git a/crates/app/src/cmd_serve.rs b/crates/app/src/cmd_serve.rs index 2f958e17d..4a82019c5 100755 --- a/crates/app/src/cmd_serve.rs +++ b/crates/app/src/cmd_serve.rs @@ -59,9 +59,11 @@ pub struct ServeArgs { migrate: bool, } -/// Bind the listening socket, daemonize, then start the tokio runtime. -/// Binding before forking ensures port conflicts are reported to stderr -/// before the parent process exits (D-4). +/// Check the catalog, bind the listening socket, daemonize, then start the +/// tokio runtime. The catalog check comes first, so the port accepts no +/// connection while the catalog migrates; binding before forking ensures +/// port conflicts are reported to stderr before the parent process exits +/// (D-4). pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { // Load config early so bind address is known before fork. A dev-mode // build serves with built-in defaults when no config file exists @@ -105,13 +107,7 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { ); } - if app_config.server.catalog_upgrade_lock_timeout > config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT { - anyhow::bail!( - "server.catalog_upgrade_lock_timeout is {} s; it may be at most {} s (a day)", - app_config.server.catalog_upgrade_lock_timeout, - config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT - ); - } + crate::serve_catalog::lock_timeout(&app_config.server)?; // Fail fast, before binding the port, when no backend is installed. let backend = &app_config.storage.backend; @@ -119,6 +115,19 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { .ok_or_else(|| anyhow::anyhow!("no storage backend installed"))?; let catalog_version = extenddb_storage::migrations::binary_catalog_label(); + // Daemon mode (double fork, PID file, syslog) is POSIX-only. On Windows + // the server must be run with `--foreground` under an external + // supervisor (a terminal, a service wrapper, or the npm launcher, which + // always passes `--foreground`). Refused before the catalog is read, so + // a server that cannot start migrates nothing. + #[cfg(not(unix))] + if !args.foreground { + anyhow::bail!( + "daemon mode is not supported on this platform; \ + run `extenddb serve --foreground`" + ); + } + let port = args.port.unwrap_or(app_config.server.port); // Dev mode serves plain HTTP with relaxed authorization; confine it to @@ -160,6 +169,23 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { let bind_addr = format!("{}:{}", app_config.server.bind_addr, port); + // The catalog's status, and under `apply` its migrations: before the + // port is bound, so the port accepts no connection while the catalog + // migrates, and before the fork, so that in daemon mode a refusal's exit + // code and message reach the invoking shell. The server checks the + // catalog again when it registers. + let code = crate::serve_catalog::check_catalog(&crate::serve_catalog::ServeStart { + server: &app_config.server, + location: app_config.storage.connection_config(), + migrate: args.migrate, + release: build.version, + config_file: config_exists.then_some(args.config.as_str()), + daemonizes: !args.foreground, + })?; + if code != extenddb_storage::migrations::exit::OK { + std::process::exit(i32::from(code)); + } + // Bind in sync context — errors go to stderr before daemonizing. let std_listener = TcpListener::bind(&bind_addr) .map_err(|e| anyhow::anyhow!("Failed to bind {bind_addr}: {e}"))?; @@ -211,25 +237,6 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { print_dev_mode_banner(&app_config, args.foreground)?; } - // The catalog's status, and under `apply` its migrations, before the - // fork, so that in daemon mode a refusal's exit code and message reach - // the invoking shell. The server checks the catalog again when it - // registers. - let upgrade = if args.migrate { - config::CatalogUpgrade::Apply - } else { - app_config.server.catalog_upgrade - }; - let code = crate::serve_catalog::check_catalog( - &app_config, - upgrade, - build.version, - config_exists.then_some(args.config.as_str()), - )?; - if code != extenddb_storage::migrations::exit::OK { - std::process::exit(i32::from(code)); - } - // D-3: A PID file lets `extenddb status` and `extenddb stop` find the // process. Daemon mode always writes one. Foreground mode writes one only on // request, so by default it needs no run directory at all and the container @@ -251,16 +258,7 @@ pub fn run(args: &ServeArgs, build: BuildInfo) -> anyhow::Result<()> { // can be supervised by Docker, Kubernetes, systemd Type=simple, etc. // Graceful shutdown on SIGINT/SIGTERM still works. if !args.foreground { - // Daemon mode (double fork, PID file, syslog) is POSIX-only. On - // Windows the server must be run with `--foreground` under an - // external supervisor (a terminal, a service wrapper, or the npm - // launcher, which always passes `--foreground`). - #[cfg(not(unix))] - anyhow::bail!( - "daemon mode is not supported on this platform; \ - run `extenddb serve --foreground`" - ); - + // Daemon mode is POSIX-only; other platforms were refused above. #[cfg(unix)] { let pid_file = pid_file diff --git a/crates/app/src/serve_catalog.rs b/crates/app/src/serve_catalog.rs index 379ee573b..f2a42a7a5 100644 --- a/crates/app/src/serve_catalog.rs +++ b/crates/app/src/serve_catalog.rs @@ -1,83 +1,174 @@ // Copyright 2026 ExtendDB contributors // SPDX-License-Identifier: Apache-2.0 -//! The catalog check `extenddb serve` makes before it daemonizes: the -//! status, read by the startup policy (`[server] catalog_upgrade`, or -//! `--migrate` for one run), and under `apply` the run that migrates a -//! catalog behind this binary. It runs in the invoking process, on a -//! runtime that is shut down before the server forks, so in daemon mode the -//! exit code and the message of a refusal reach the invoking shell as they -//! do in the foreground. The server checks the catalog again when it -//! registers, after the fork. +//! The catalog check `extenddb serve` makes before it binds its port and +//! daemonizes: the status, read by the startup policy (`[server] +//! catalog_upgrade`, or `--migrate` for one run), and under `apply` the run +//! that migrates a catalog behind this binary. It runs in the invoking +//! process, on a runtime that is shut down before the server forks, so in +//! daemon mode the exit code and the message of a refusal reach the +//! invoking shell as they do in the foreground. The server checks the +//! catalog again when it registers, after the fork. -use std::time::Duration; +use std::time::{Duration, Instant}; -use extenddb_config::{self as config, AppConfig, CatalogUpgrade}; +use extenddb_config::{self as config, CatalogUpgrade, ServerConfig}; use extenddb_storage::migrations::advice::{self, AdviceFor}; -use extenddb_storage::migrations::{Startup, Target, exit, installed, prepare_to_serve}; +use extenddb_storage::migrations::{ + CatalogMigrations, Startup, Target, exit, installed, prepare_to_serve, +}; -/// The start of every line `serve` prints on stderr while it migrates the -/// catalog. The npm launcher's startup timeout restarts at each one. +/// The start of every line `serve` prints on stderr while it checks and +/// migrates the catalog. The npm launcher's startup timeout restarts at +/// each one. pub(crate) const PROGRESS_PREFIX: &str = "catalog migration: "; -/// Check the catalog of `app_config` before the server starts, printing -/// the lines of a run and any refusal on stderr. Returns the status's exit -/// code: 0 when the server may start, else the code `serve` exits with. -/// `config_file` is the config file the server was started with, named in -/// the command a refusal prints. +/// How long the check's runtime may take to stop. A blocking thread still +/// running after it keeps a daemon from forking. +const SHUTDOWN_CAP: Duration = Duration::from_secs(10); + +/// How `serve` was started, as the catalog check reads it. +pub(crate) struct ServeStart<'a> { + /// The `[server]` section: `catalog_upgrade` and its lock timeout. + pub(crate) server: &'a ServerConfig, + /// The storage location the config gives. + pub(crate) location: &'a str, + /// `serve --migrate`, which sets `catalog_upgrade = "apply"` for this + /// run. + pub(crate) migrate: bool, + /// The ExtendDB release, recorded in the ledger rows a run writes. + pub(crate) release: &'a str, + /// The config file the server was started with, named in the command a + /// refusal prints. + pub(crate) config_file: Option<&'a str>, + /// Whether the server forks once the check has passed (daemon mode). + pub(crate) daemonizes: bool, +} + +/// `[server] catalog_upgrade_lock_timeout`, refused above a day. /// /// # Errors /// -/// The runtime could not be built. -pub(crate) fn check_catalog( - app_config: &AppConfig, - upgrade: CatalogUpgrade, - release: &str, - config_file: Option<&str>, -) -> anyhow::Result { +/// The timeout is above a day. +pub(crate) fn lock_timeout(server: &ServerConfig) -> anyhow::Result { + let secs = server.catalog_upgrade_lock_timeout; + if secs > config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT { + anyhow::bail!( + "server.catalog_upgrade_lock_timeout is {secs} s; it may be at most {} s (a day)", + config::MAX_CATALOG_UPGRADE_LOCK_TIMEOUT + ); + } + Ok(Duration::from_secs(secs)) +} + +/// Check the catalog `start` names before the server binds its port, +/// printing on stderr the lines of the check and of a run, and any +/// refusal. Returns the exit code: 0 when the server may start, else the +/// code `serve` exits with. +/// +/// The warnings the backends log during the check, such as PostgreSQL's +/// retries after a lock timeout, go to stderr through a subscriber set for +/// the check alone, as `migrate --yes` prints them. The global default stays +/// free for the server's own subscriber. +/// +/// # Errors +/// +/// The lock timeout is above a day, or the runtime could not be built. +pub(crate) fn check_catalog(start: &ServeStart<'_>) -> anyhow::Result { let Some(migrations) = installed() else { return Ok(exit::OK); }; - let location = app_config.storage.connection_config(); - let target = Target::at(location); + let subscriber = tracing_subscriber::fmt() + .with_writer(std::io::stderr) + .finish(); + tracing::subscriber::with_default(subscriber, || { + check(migrations, start, SHUTDOWN_CAP, &|line| eprintln!("{line}")) + }) +} + +/// [`check_catalog`] on `migrations`, writing each line to `out`, with +/// `shutdown_cap` for the check's runtime to stop. +fn check( + migrations: &dyn CatalogMigrations, + start: &ServeStart<'_>, + shutdown_cap: Duration, + out: &(dyn Fn(&str) + Send + Sync), +) -> anyhow::Result { + let upgrade = if start.migrate { + CatalogUpgrade::Apply + } else { + start.server.catalog_upgrade + }; + let target = Target::at(start.location); let startup = Startup { apply: upgrade == CatalogUpgrade::Apply, // A dev build's server creates its catalog in a missing or empty // database file. creates_uninitialized: cfg!(feature = "dev-mode"), - release, - lock_timeout: Duration::from_secs(app_config.server.catalog_upgrade_lock_timeout), + release: start.release, + lock_timeout: lock_timeout(start.server)?, heartbeat: Startup::HEARTBEAT, }; let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .build()?; - let result = runtime.block_on(prepare_to_serve(migrations, &target, &startup, &|line| { - eprintln!("{PROGRESS_PREFIX}{line}"); - })); - // The fork that follows copies only the thread that calls it: every - // task and blocking thread of this runtime ends first. - runtime.shutdown_timeout(Duration::from_secs(10)); + // Each line of a progress message gets the prefix, so a note that spans + // several lines counts as progress to the launcher on each of them. + let progress = |text: &str| { + for line in text.lines() { + out(&format!("{PROGRESS_PREFIX}{line}")); + } + }; + let result = runtime.block_on(prepare_to_serve(migrations, &target, &startup, &progress)); + let capped = shut_down(runtime, shutdown_cap); match result { Ok(prepared) => { if let Some(warning) = prepared.warning { - eprintln!("WARNING: {warning}"); + out(&format!("WARNING: {warning}")); + } + if capped && start.daemonizes { + out(&format!( + "Error: a blocking thread of the catalog check, such as a host name lookup, \ + was still running {} s after the check ended. The server does not fork \ + while it runs, since a lock that thread holds would stay held in the \ + child, where the thread does not exist. Run extenddb serve again, or with \ + --foreground.", + shutdown_cap.as_secs() + )); + return Ok(exit::ERROR); } Ok(exit::OK) } Err(error) => { let advice = AdviceFor::new( - release, - config::redact_password(location), + start.release, + config::redact_password(start.location), Some(migrations), &target, - config_file, + start.config_file, ) .for_server(); - eprintln!("Error: {}", advice::error_message(&error, &advice.advice())); + out(&format!( + "Error: {}", + advice::error_message(&error, &advice.advice()) + )); // A refusal never lets the server start, whatever its status's // code. Ok(error.exit_code().max(exit::ERROR)) } } } + +/// Shut `runtime` down, waiting up to `cap` for its tasks and blocking +/// threads to end. `true` when the wait reached the cap, so a blocking +/// thread may still be running: a fork copies only the thread that calls +/// it, and a lock such a thread holds would stay held in the child. +fn shut_down(runtime: tokio::runtime::Runtime, cap: Duration) -> bool { + let started = Instant::now(); + runtime.shutdown_timeout(cap); + started.elapsed() >= cap +} + +#[cfg(test)] +#[path = "serve_catalog_tests.rs"] +mod tests; diff --git a/crates/app/src/serve_catalog_tests.rs b/crates/app/src/serve_catalog_tests.rs new file mode 100644 index 000000000..e4b29c793 --- /dev/null +++ b/crates/app/src/serve_catalog_tests.rs @@ -0,0 +1,327 @@ +// Copyright 2026 ExtendDB contributors +// SPDX-License-Identifier: Apache-2.0 + +//! The catalog check `serve` makes before it binds its port: `--migrate` +//! over `[server] catalog_upgrade`, the prefix on every line it prints, the +//! exit code of a refusal, the lock timeout's bound, and a runtime that +//! does not stop in time before a fork. + +use std::collections::VecDeque; +use std::sync::Mutex; +use std::time::Duration; + +use async_trait::async_trait; +use extenddb_config::{CatalogUpgrade, ServerConfig}; +use extenddb_storage::migrations::{ + AppliedStep, CatalogMigrations, CatalogStatus, HeldLock, Kind, LedgerRow, Listed, + MigrationError, MigrationId, Pending, RunKind, RunReport, StoreKind, Target, exit, +}; + +use super::{PROGRESS_PREFIX, ServeStart, check, lock_timeout}; + +/// The cap the tests give the check's runtime to stop. +const CAP: Duration = Duration::from_secs(10); + +struct Fake { + /// What the next status reads return, the last one repeated. + statuses: Mutex>>, + lock: Result<(), MigrationError>, + report: RunReport, + /// A blocking thread the run starts and does not wait for sleeps this + /// long. + leaves_thread: Option, + calls: Mutex>, +} + +impl Fake { + fn new(statuses: Vec>) -> Self { + Self { + statuses: Mutex::new(statuses.into()), + lock: Ok(()), + report: applied_report(), + leaves_thread: None, + calls: Mutex::new(Vec::new()), + } + } + + fn calls(&self) -> Vec<&'static str> { + self.calls.lock().unwrap().clone() + } + + fn call(&self, name: &'static str) { + self.calls.lock().unwrap().push(name); + } +} + +#[async_trait] +impl CatalogMigrations for Fake { + fn listed(&self, _id: MigrationId) -> Listed { + Listed::NotApplicable("fake") + } + fn backup_advice(&self, target: &Target) -> String { + format!("back up {}", target.location) + } + async fn status(&self, _target: &Target) -> Result { + self.call("status"); + let mut statuses = self.statuses.lock().unwrap(); + let status = statuses.front().cloned().expect("a status"); + if statuses.len() > 1 { + statuses.pop_front(); + } + status + } + async fn catalog_ledger(&self, _: &Target) -> Result, MigrationError> { + Ok(Vec::new()) + } + async fn lock(&self, target: &Target, _: Duration) -> Result { + self.call("lock"); + self.lock + .clone() + .map(|()| HeldLock::new(target.location.as_str(), ())) + } + async fn run( + &self, + _lock: &HeldLock, + _release: &str, + _kind: RunKind, + ) -> Result { + self.call("run"); + if let Some(sleep) = self.leaves_thread { + drop(tokio::task::spawn_blocking(move || { + std::thread::sleep(sleep) + })); + } + Ok(self.report.clone()) + } + async fn forget(&self, _lock: &HeldLock, _id: u32) -> Result<(), MigrationError> { + unreachable!("a server forgets nothing") + } + async fn release(&self, lock: HeldLock) { + self.call("release"); + drop(lock); + } +} + +fn behind() -> CatalogStatus { + CatalogStatus::Behind { + version: Some(1), + pending: MigrationId::ALL + .iter() + .skip(1) + .map(|id| Pending { + id: id.number(), + name: id.name(), + store: StoreKind::Catalog, + store_name: "db".to_owned(), + kind: Kind::Breaking, + }) + .collect(), + } +} + +/// A run's report whose copy note spans two lines. +fn applied_report() -> RunReport { + RunReport { + from: Some(1), + to: Some(MigrationId::LATEST.number()), + applied: MigrationId::ALL + .iter() + .skip(1) + .map(|id| AppliedStep { + id: id.number(), + name: id.name(), + store_name: "db".to_owned(), + notes: vec!["a note\nthat spans two lines".to_owned()], + }) + .collect(), + notes: vec!["copied the database to db.pre-migration-1-to-4-x".to_owned()], + } +} + +fn server(upgrade: CatalogUpgrade) -> ServerConfig { + ServerConfig { + catalog_upgrade: upgrade, + catalog_upgrade_lock_timeout: 1, + ..ServerConfig::default() + } +} + +fn start(server: &ServerConfig, migrate: bool, daemonizes: bool) -> ServeStart<'_> { + ServeStart { + server, + location: "db", + migrate, + release: "1.0.0-test", + config_file: Some("/etc/extenddb/extenddb.toml"), + daemonizes, + } +} + +/// Run the check, returning its exit code and every line it printed, one +/// entry per line. +fn run_check(fake: &Fake, start: &ServeStart<'_>, cap: Duration) -> (u8, Vec) { + let printed = Mutex::new(Vec::new()); + let code = check(fake, start, cap, &|text| { + printed.lock().unwrap().push(text.to_owned()); + }) + .expect("the check runs"); + let lines = printed + .into_inner() + .unwrap() + .iter() + .flat_map(|text| text.lines().map(str::to_owned).collect::>()) + .collect(); + (code, lines) +} + +/// The launcher matches this string at the start of a line and restarts +/// its startup timeout at each line that has it: `PROGRESS_PREFIX` in +/// packaging/npm/startup.js, and the copy in its test server, must change +/// with this one. +#[test] +fn the_prefix_is_the_one_the_npm_launcher_matches() { + assert_eq!(PROGRESS_PREFIX, "catalog migration: "); +} + +/// `--migrate` applies a catalog behind this binary for one run under +/// `catalog_upgrade = "refuse"`, which without it exits 3 and takes no +/// lock; `catalog_upgrade = "apply"` applies it without the flag. +#[test] +fn migrate_applies_a_catalog_behind_for_one_run() { + let refuse = server(CatalogUpgrade::Refuse); + let fake = Fake::new(vec![Ok(behind())]); + let (code, _) = run_check(&fake, &start(&refuse, false, false), CAP); + assert_eq!(code, exit::PENDING); + assert_eq!(fake.calls(), ["status"]); + + let fake = Fake::new(vec![Ok(behind())]); + let (code, lines) = run_check(&fake, &start(&refuse, true, false), CAP); + assert_eq!(code, exit::OK, "{lines:?}"); + assert_eq!(fake.calls(), ["status", "lock", "status", "run", "release"]); + + let apply = server(CatalogUpgrade::Apply); + let fake = Fake::new(vec![Ok(behind())]); + let (code, lines) = run_check(&fake, &start(&apply, false, false), CAP); + assert_eq!(code, exit::OK, "{lines:?}"); + assert!(fake.calls().contains(&"run"), "{:?}", fake.calls()); +} + +/// Every line a run prints starts with the prefix, the lines of a note that +/// spans several included, so the launcher counts each of them. +#[test] +fn every_progress_line_starts_with_the_prefix() { + let refuse = server(CatalogUpgrade::Refuse); + let fake = Fake::new(vec![Ok(behind())]); + let (code, lines) = run_check(&fake, &start(&refuse, true, false), CAP); + assert_eq!(code, exit::OK, "{lines:?}"); + assert_eq!(lines[0], "catalog migration: reading the catalog status"); + assert!( + lines.contains(&"catalog migration: that spans two lines".to_owned()), + "{lines:?}" + ); + for line in &lines { + assert!(line.starts_with(PROGRESS_PREFIX), "{line:?} in {lines:?}"); + } +} + +/// A refusal prints its message on stderr and exits with its status's +/// code, and never with 0: an error whose code would be 0 exits 1. +#[test] +fn a_refusal_exits_with_its_code_and_never_with_0() { + let refuse = server(CatalogUpgrade::Refuse); + let cases = [ + (Ok(behind()), exit::PENDING), + ( + Ok(CatalogStatus::NeedsAttention { + items: vec!["migration 2: a collision".to_owned()], + }), + exit::ATTENTION, + ), + ( + Ok(CatalogStatus::AheadIncompatible { + unknown: vec![(MigrationId::LATEST.number() + 1, "later".to_owned())], + }), + exit::AHEAD_INCOMPATIBLE, + ), + ( + Ok(CatalogStatus::Uninitialized), + if cfg!(feature = "dev-mode") { + exit::OK + } else { + exit::ERROR + }, + ), + ( + Err(MigrationError::Status(CatalogStatus::Current { + version: MigrationId::LATEST.number(), + })), + exit::ERROR, + ), + ]; + for (status, code) in cases { + let fake = Fake::new(vec![status.clone()]); + let (got, lines) = run_check(&fake, &start(&refuse, false, false), CAP); + assert_eq!(got, code, "{status:?}: {lines:?}"); + if code != exit::OK { + assert!( + lines.iter().any(|l| l.starts_with("Error: ")), + "{status:?}: {lines:?}" + ); + } + } + + // A lock that stays held: exit 6 once the wait reaches the timeout. + let mut fake = Fake::new(vec![Ok(behind())]); + fake.lock = Err(MigrationError::Locked("another migration holds it".into())); + let (code, lines) = run_check(&fake, &start(&refuse, true, false), CAP); + assert_eq!(code, exit::LOCKED, "{lines:?}"); +} + +/// A blocking thread of the check still running when the runtime's +/// shutdown reaches its cap keeps a daemon from forking: the check prints +/// the cause and exits 1. A foreground server does not fork, and starts. +#[test] +fn a_thread_still_running_after_the_check_keeps_a_daemon_from_forking() { + let refuse = server(CatalogUpgrade::Refuse); + let mut fake = Fake::new(vec![Ok(behind())]); + fake.leaves_thread = Some(Duration::from_millis(500)); + let cap = Duration::from_millis(50); + let (code, lines) = run_check(&fake, &start(&refuse, true, true), cap); + assert_eq!(code, exit::ERROR, "{lines:?}"); + let last = lines.last().expect("a line"); + assert!( + last.starts_with("Error: a blocking thread of the catalog check") + && last.contains("still running"), + "{lines:?}" + ); + + let (code, lines) = run_check(&fake, &start(&refuse, true, false), cap); + assert_eq!(code, exit::OK, "{lines:?}"); + + // A check whose threads end in time forks. + let fake = Fake::new(vec![Ok(behind())]); + let (code, lines) = run_check(&fake, &start(&refuse, true, true), CAP); + assert_eq!(code, exit::OK, "{lines:?}"); +} + +/// `serve` refuses a lock timeout above a day, as `migrate --lock-timeout` +/// does, before anything reads the catalog. +#[test] +fn a_lock_timeout_above_a_day_is_refused() { + let over = ServerConfig { + catalog_upgrade_lock_timeout: 86_401, + ..ServerConfig::default() + }; + let err = lock_timeout(&over).expect_err("above a day"); + assert!(err.to_string().contains("at most 86400 s"), "{err}"); + let day = ServerConfig { + catalog_upgrade_lock_timeout: 86_400, + ..ServerConfig::default() + }; + assert_eq!(lock_timeout(&day).ok(), Some(Duration::from_secs(86_400))); + + let fake = Fake::new(vec![Ok(behind())]); + let refused = check(&fake, &start(&over, true, false), CAP, &|_| {}); + assert!(refused.is_err(), "{refused:?}"); + assert!(fake.calls().is_empty(), "{:?}", fake.calls()); +} From b23da5ea8b589ece0adebe689614126149510fb5 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:38:49 +0000 Subject: [PATCH 08/14] test(migrations): rename the two-run startup tests, and add the missing ones The four two_servers_started_together tests ran two prepare_to_serve calls and never started a server, and counted a run whose first status read already saw the catalog current as one that waited for the lock. They are now two_prepare_to_serve_runs_under_apply_migrate_once, with migrate_a_legacy_catalog_once at the end on Cassandra. Each holds the lock as another process until both runs wait for it, then frees it, and asserts that one run applied the migrations and the other took the lock after it and applied nothing: a report with no step. New tests on PostgreSQL: a zero lock timeout exits 6 at once through the server's run and through the run migrate --yes makes, while another session holds the migration key or the serving key; and a run that waits for both keys exits 6 once one timeout has passed in all. New tests on SQLite, in process: a catalog another process migrates during the wait is served with nothing written and no backend run, and a dev build's policy refuses a file that holds another program's tables with the refusal the factory gives. --- .../tests/migrations/startup.rs | 63 +++++-- .../tests/migrations_startup.rs | 73 ++++++-- .../tests/migrations_startup.rs | 175 ++++++++++++++++-- .../src/migrations/serve_tests.rs | 172 +++++++++++++++-- 4 files changed, 422 insertions(+), 61 deletions(-) diff --git a/crates/storage-cassandra/tests/migrations/startup.rs b/crates/storage-cassandra/tests/migrations/startup.rs index 3fb82e9d7..1e3be7c1d 100644 --- a/crates/storage-cassandra/tests/migrations/startup.rs +++ b/crates/storage-cassandra/tests/migrations/startup.rs @@ -6,10 +6,12 @@ //! legacy catalog is migrated through the lock `migrate --yes` takes, a //! current one is served with nothing written, one that needs a person //! exits 5 with nothing written, a held lock makes the server wait and then -//! exit 6, and two servers started together, whose connection strings name -//! the two nodes of a two-node cluster when the job has one, migrate once. +//! exit 6, and two `prepare_to_serve` runs that wait for the lock together, +//! whose connection strings name the two nodes of a two-node cluster when +//! the job has one, migrate once. use std::sync::Arc; +use std::sync::atomic::{AtomicUsize, Ordering}; use std::time::{Duration, Instant}; use extenddb_storage::management_store::{ManagementStore, SettingsStore}; @@ -231,30 +233,61 @@ async fn apply_waits_for_a_held_migration_lock_and_exits_6() { holder.release().await; } -/// Two servers started together under `apply` on a legacy catalog, their -/// connection strings naming different nodes when the job has two: one -/// migrates it, and the other waits for the lock and finds nothing to do. -/// Each server's session reaches the cluster at the node its connection -/// string names and then sends requests to both nodes in turn, as a -/// server's session does. +/// Two `prepare_to_serve` runs under `apply` on a legacy catalog, their +/// connection strings naming different nodes when the job has two, both +/// waiting for the lock another process holds, as the checks of two servers +/// started together do after their first status read: once it is free, one +/// migrates the catalog, and the other takes the lock after it and applies +/// nothing. Each run's session reaches the cluster at the node its +/// connection string names and then sends requests to both nodes in turn, +/// as a server's session does. The servers are not started here; one of two +/// servers started together can exit 6 when it registers while the other +/// holds the lock. #[tokio::test] -async fn two_servers_started_together_with_apply_migrate_a_legacy_catalog_once() { +async fn two_prepare_to_serve_runs_under_apply_migrate_a_legacy_catalog_once() { if helpers::skip_without_cassandra() { return; } let session = session().await; let (prefix, _drops) = new_prefix("start_two"); legacy_catalog(&session, &prefix).await; - let apply = startup(true, TIMEOUT); + let holder = MigrationLock::acquire( + session.clone(), + &format!("{prefix}_catalog"), + LeaseTimes::DEFAULT, + TIMEOUT, + ) + .await + .expect("another process's lock"); + let waiting = AtomicUsize::new(0); + let progress = |line: &str| { + if line.starts_with("taking the migration lock") { + waiting.fetch_add(1, Ordering::SeqCst); + } + }; + // Each run waits for the holder, and the second also for the first + // one's migration. + let apply = startup(true, TIMEOUT * 2); let (first, second) = (target_of(&prefix), second_target_of(&prefix)); - let (a, b) = tokio::join!(prepare(&first, &apply), prepare(&second, &apply)); - let applied: Vec = [a.expect("first"), b.expect("second")] + let free = async { + while waiting.load(Ordering::SeqCst) < 2 { + tokio::time::sleep(Duration::from_millis(20)).await; + } + holder.release().await; + }; + let (a, b, ()) = tokio::join!( + prepare_to_serve(&CassandraCatalogMigrations, &first, &apply, &progress), + prepare_to_serve(&CassandraCatalogMigrations, &second, &apply, &progress), + free, + ); + let mut applied: Vec = [a.expect("first"), b.expect("second")] .iter() - .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .map(|p| p.run.as_ref().expect("each took the lock").applied.len()) .collect(); + applied.sort_unstable(); assert!( - applied.contains(&0) && applied.iter().any(|n| *n > 0), - "one migrates and the other finds nothing to do: {applied:?}" + applied[0] == 0 && applied[1] > 0, + "one migrates, and the other takes the lock after it and applies nothing: {applied:?}" ); assert_eq!( catalog_status(pinned_session(&second_contact_point()).await, &prefix) diff --git a/crates/storage-mongodb/tests/migrations_startup.rs b/crates/storage-mongodb/tests/migrations_startup.rs index dbd560f4b..633b5339c 100644 --- a/crates/storage-mongodb/tests/migrations_startup.rs +++ b/crates/storage-mongodb/tests/migrations_startup.rs @@ -5,11 +5,12 @@ //! catalogs: under `apply` a catalog behind the binary is migrated through //! the lock `migrate --yes` takes, a current one is served with nothing //! written, one that needs a person exits 5 with nothing written, a held -//! migration lock makes the server wait and then exit 6, and two servers -//! started together migrate once. +//! migration lock makes the server wait and then exit 6, and two +//! `prepare_to_serve` runs that wait for the lock together migrate once. mod migrations_support; +use std::sync::atomic::{AtomicUsize, Ordering}; use std::time::{Duration, Instant}; use bson::{Document, doc}; @@ -172,17 +173,7 @@ async fn apply_waits_for_a_held_migration_lock_and_exits_6() { let Some(uri) = server() else { return }; let d = Deployment::new(&uri, "start_locked").await; fixture::load(&d, &fixture::read("0.1.14")).await; - d.catalog() - .collection::("settings") - .insert_one(doc! { - "_id": "migration_lock", - "owner": "another", - "expires_at": bson::DateTime::from_millis( - bson::DateTime::now().timestamp_millis() + 120_000 - ), - }) - .await - .expect("another migration's lock"); + another_migrations_lock(&d).await; let before = state(&d).await; let started = Instant::now(); let err = prepare(&d, &startup(true, Duration::from_secs(2))) @@ -202,24 +193,68 @@ async fn apply_waits_for_a_held_migration_lock_and_exits_6() { d.drop_databases().await; } -/// Two servers started together under `apply` on a released catalog: one -/// migrates it, and the other waits for the lock and finds nothing to do. +/// Another migration's lock document, as its claim writes it, for two +/// minutes. +async fn another_migrations_lock(d: &Deployment) { + d.catalog() + .collection::("settings") + .insert_one(doc! { + "_id": "migration_lock", + "owner": "another", + "expires_at": bson::DateTime::from_millis( + bson::DateTime::now().timestamp_millis() + 120_000 + ), + }) + .await + .expect("another migration's lock"); +} + +/// Two `prepare_to_serve` runs under `apply` on a released catalog, both +/// waiting for the lock another migration holds, as the checks of two +/// servers started together do after their first status read: once it is +/// free, one migrates the catalog, and the other takes the lock after it +/// and applies nothing. The servers are not started here; one of two +/// servers started together can exit 6 when it registers while the other +/// holds the lock. #[tokio::test(flavor = "multi_thread")] -async fn two_servers_started_together_with_apply_migrate_once() { +async fn two_prepare_to_serve_runs_under_apply_migrate_once() { let Some(uri) = server() else { return }; let d = Deployment::new(&uri, "start_two").await; fixture::load(&d, &fixture::read("0.1.12")).await; + another_migrations_lock(&d).await; + let migrations = MongoCatalogMigrations::with_databases(&d.target.catalog, &d.target.data); + let target = Target::at(&d.target.connection_string); + let waiting = AtomicUsize::new(0); + let progress = |line: &str| { + if line.starts_with("taking the migration lock") { + waiting.fetch_add(1, Ordering::SeqCst); + } + }; let apply = startup(true, Duration::from_secs(60)); - let (a, b) = tokio::join!(prepare(&d, &apply), prepare(&d, &apply)); + let free = async { + while waiting.load(Ordering::SeqCst) < 2 { + tokio::time::sleep(Duration::from_millis(20)).await; + } + d.catalog() + .collection::("settings") + .delete_one(doc! { "_id": "migration_lock", "owner": "another" }) + .await + .expect("the other migration releases its lock"); + }; + let (a, b, ()) = tokio::join!( + prepare_to_serve(&migrations, &target, &apply, &progress), + prepare_to_serve(&migrations, &target, &apply, &progress), + free, + ); let mut applied: Vec = [a.expect("first"), b.expect("second")] .iter() - .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .map(|p| p.run.as_ref().expect("each took the lock").applied.len()) .collect(); applied.sort_unstable(); assert_eq!( applied, [0, 5], - "one migrates and the other finds nothing to do" + "one migrates, and the other takes the lock after it and applies nothing" ); assert_eq!(d.status().await, CatalogStatus::Current { version: 4 }); d.drop_databases().await; diff --git a/crates/storage-postgres/tests/migrations_startup.rs b/crates/storage-postgres/tests/migrations_startup.rs index b0b3fc47a..7d8db99f8 100644 --- a/crates/storage-postgres/tests/migrations_startup.rs +++ b/crates/storage-postgres/tests/migrations_startup.rs @@ -4,26 +4,31 @@ //! catalogs: under `apply` a catalog behind the binary is migrated through //! the lock `migrate --yes` takes, a current one is served with nothing //! written, one that needs a person exits 5 with nothing written, a held -//! migration lock makes the server wait and then exit 6, and two servers -//! started together migrate once. See `migrations_support` for the -//! database these tests need. +//! migration lock makes the server wait and then exit 6, a zero lock +//! timeout tries each key once, the waits of a run share one timeout, and +//! two `prepare_to_serve` runs that wait for the lock together migrate +//! once. See `migrations_support` for the database these tests need. mod migrations_support; +use std::sync::atomic::{AtomicUsize, Ordering}; use std::time::{Duration, Instant}; use extenddb_storage::migrations::{ - CatalogStatus, MigrationError, Prepared, Startup, Target, exit, prepare_to_serve, + CatalogStatus, MigrationError, Prepared, RunKind, Startup, Target, WhenCurrent, exit, + prepare_to_serve, run_with_lock, }; use extenddb_storage_postgres::migrations::{Definitions, PostgresCatalogMigrations}; use migrations_support::{ LATEST, Scratch, base_conn, describe_pool, ledger, settings, skip, step_count, }; -/// The advisory key of the migration lock, `NAMESPACE` and `MIGRATION_KEY` -/// in `src/migrations/locks.rs`. +/// The advisory keys of the migration lock and the serving registration, +/// `NAMESPACE`, `MIGRATION_KEY` and `SERVING_KEY` in +/// `src/migrations/locks.rs`. const NAMESPACE: i32 = 0x0045_4442; const MIGRATION_KEY: i32 = 1; +const SERVING_KEY: i32 = 2; fn startup(apply: bool, lock_timeout: Duration) -> Startup<'static> { Startup { @@ -182,24 +187,52 @@ async fn apply_waits_for_a_held_migration_lock_and_exits_6() { ); } -/// Two servers started together under `apply` on a released catalog: one -/// migrates it, and the other waits for the lock and finds nothing to do. +/// Two `prepare_to_serve` runs under `apply` on a released catalog, both +/// waiting for the migration lock another session holds, as the checks of +/// two servers started together do after their first status read: once it +/// is free, one migrates the catalog, and the other takes the lock after it +/// and applies nothing. The servers are not started here; one of two +/// servers started together can exit 6 when it registers while the other +/// holds the lock. #[tokio::test] -async fn two_servers_started_together_with_apply_migrate_once() { +async fn two_prepare_to_serve_runs_under_apply_migrate_once() { let Some(base) = base_conn() else { return skip("startup two"); }; let s = Scratch::new(&base, "pgs_two").await; s.load("0.1.14").await; + let holder = s.catalog().await; + let mut tx = holder.begin().await.unwrap(); + hold(&mut tx, "pg_advisory_xact_lock", MIGRATION_KEY).await; + let waiting = AtomicUsize::new(0); + let progress = |line: &str| { + if line.starts_with("taking the migration lock") { + waiting.fetch_add(1, Ordering::SeqCst); + } + }; + let target = Target::at(s.catalog_url()); let apply = startup(true, Duration::from_secs(60)); - let (a, b) = tokio::join!(prepare(&s, &apply), prepare(&s, &apply)); - let applied: Vec = [a.expect("first"), b.expect("second")] + let free = async { + while waiting.load(Ordering::SeqCst) < 2 { + tokio::time::sleep(Duration::from_millis(20)).await; + } + tx.rollback().await.unwrap(); + }; + let (a, b, ()) = tokio::join!( + prepare_to_serve(&PostgresCatalogMigrations, &target, &apply, &progress), + prepare_to_serve(&PostgresCatalogMigrations, &target, &apply, &progress), + free, + ); + holder.close().await; + let mut applied: Vec = [a.expect("first"), b.expect("second")] .iter() - .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .map(|p| p.run.as_ref().expect("each took the lock").applied.len()) .collect(); - assert!( - applied.contains(&0) && applied.contains(&step_count()), - "one migrates and the other finds nothing to do: {applied:?}" + applied.sort_unstable(); + assert_eq!( + applied, + [0, step_count()], + "one migrates, and the other takes the lock after it and applies nothing" ); let catalog = s.catalog().await; assert_eq!( @@ -209,3 +242,115 @@ async fn two_servers_started_together_with_apply_migrate_once() { catalog.close().await; assert_eq!(s.status().await, CatalogStatus::Current { version: LATEST }); } + +/// Hold an advisory key of the catalog in `tx`, as another migrator +/// (`pg_advisory_xact_lock` on the migration key) or a running server +/// (`pg_advisory_xact_lock_shared` on the serving key) does. +async fn hold(tx: &mut sqlx::Transaction<'static, sqlx::Postgres>, function: &str, key: i32) { + sqlx::query(&format!("SELECT {function}($1, $2)")) + .bind(NAMESPACE) + .bind(key) + .execute(&mut **tx) + .await + .unwrap(); +} + +/// A zero lock timeout tries each key once. While another migrator holds +/// the migration key, or a server the serving key, the server's run and the +/// run `migrate --yes` makes exit 6 at once, with the catalog unchanged. +/// PostgreSQL reads a `lock_timeout` of 0 as no limit, so a wait would last +/// as long as the holder keeps its key. +#[tokio::test] +async fn a_zero_lock_timeout_tries_each_key_once() { + let Some(base) = base_conn() else { + return skip("startup zero timeout"); + }; + let s = Scratch::new(&base, "pgs_zero").await; + s.load("0.1.14").await; + let before = state(&s).await; + let target = Target::at(s.catalog_url()); + for (function, key) in [ + ("pg_advisory_xact_lock", MIGRATION_KEY), + ("pg_advisory_xact_lock_shared", SERVING_KEY), + ] { + let holder = s.catalog().await; + let mut tx = holder.begin().await.unwrap(); + hold(&mut tx, function, key).await; + let started = Instant::now(); + let served = tokio::time::timeout( + Duration::from_secs(20), + prepare(&s, &startup(true, Duration::ZERO)), + ) + .await + .expect("the server's run waited for the key"); + let err = served.expect_err("locked"); + assert_eq!(err.exit_code(), exit::LOCKED, "{function}: {err:?}"); + let migrated = tokio::time::timeout( + Duration::from_secs(20), + run_with_lock( + &PostgresCatalogMigrations, + &target, + "1.0.0-test", + RunKind::Migrate, + Duration::ZERO, + WhenCurrent::Run, + ), + ) + .await + .expect("migrate --yes waited for the key"); + let err = migrated.expect_err("locked"); + assert_eq!(err.exit_code(), exit::LOCKED, "{function}: {err:?}"); + assert!( + started.elapsed() < Duration::from_secs(10), + "{function}: {:?}", + started.elapsed() + ); + tx.rollback().await.unwrap(); + holder.close().await; + } + assert!(state(&s).await == before, "a run at a zero timeout wrote"); +} + +/// The waits of one run share its lock timeout: a server's run that waits +/// for another migrator's key, and then for a running server's key, exits 6 +/// once the timeout has passed in all, not after a timeout for each wait. +#[tokio::test] +async fn the_waits_of_a_run_share_one_lock_timeout() { + let Some(base) = base_conn() else { + return skip("startup one bound"); + }; + let s = Scratch::new(&base, "pgs_bound").await; + s.load("0.1.14").await; + // A server serves the catalog for the whole test, and another migrator + // holds the migration key for 6 s of the run's 8 s. + let server = s.catalog().await; + let mut serving = server.begin().await.unwrap(); + hold(&mut serving, "pg_advisory_xact_lock_shared", SERVING_KEY).await; + let migrator = s.catalog().await; + let mut migrating = migrator.begin().await.unwrap(); + hold(&mut migrating, "pg_advisory_xact_lock", MIGRATION_KEY).await; + let apply = startup(true, Duration::from_secs(8)); + let started = Instant::now(); + let other_finishes = async { + tokio::time::sleep(Duration::from_secs(6)).await; + migrating.rollback().await.unwrap(); + }; + let (locked, ()) = tokio::join!(prepare(&s, &apply), other_finishes); + let waited = started.elapsed(); + let err = locked.expect_err("locked"); + assert_eq!(err.exit_code(), exit::LOCKED, "{err:?}"); + assert!( + err.to_string() + .starts_with("servers are serving this catalog"), + "{err}" + ); + // 8 s in all, plus the status reads; 8 s for each key would end after + // 14 s. + assert!( + waited >= Duration::from_millis(7500) && waited < Duration::from_secs(13), + "it waited {waited:?}" + ); + serving.rollback().await.unwrap(); + server.close().await; + migrator.close().await; +} diff --git a/crates/storage-sqlite/src/migrations/serve_tests.rs b/crates/storage-sqlite/src/migrations/serve_tests.rs index 536156cc2..87cc8a932 100644 --- a/crates/storage-sqlite/src/migrations/serve_tests.rs +++ b/crates/storage-sqlite/src/migrations/serve_tests.rs @@ -11,11 +11,13 @@ //! apart are tested here too. use std::path::Path; +use std::sync::atomic::{AtomicUsize, Ordering}; use std::time::Duration; +use async_trait::async_trait; use extenddb_storage::migrations::{ - CatalogMigrations, CatalogStatus, MigrationError, MigrationId, Prepared, Startup, Target, exit, - prepare_to_serve, + CatalogMigrations, CatalogStatus, HeldLock, LedgerRow, Listed, MigrationError, MigrationId, + Prepared, RunKind, RunReport, Startup, Target, exit, prepare_to_serve, }; use extenddb_storage::server_components::{ BackendError, ServerComponents, ServerComponentsOptions, @@ -272,21 +274,46 @@ async fn apply_waits_for_a_held_lock_and_exits_6() { drop(holder); } -/// Two servers started together under `apply` on a released catalog: one -/// migrates it, and the other waits for the lock and finds nothing to do. +/// Two `prepare_to_serve` runs under `apply` on a released catalog, both +/// waiting for a lock another process holds, as the checks of two servers +/// started together do after their first status read: once it is free, one +/// migrates the catalog, and the other takes the lock after it and applies +/// nothing. The servers are not started here; one of two servers started +/// together can exit 6 when it registers while the other holds the lock. +#[cfg(unix)] #[tokio::test] -async fn two_servers_started_together_with_apply_migrate_once() { +async fn two_prepare_to_serve_runs_under_apply_migrate_once() { let db = temp_db("startup-two"); load_dump(&db, DEV_0_1_14).await; - let apply = startup(true, Duration::from_secs(30)); - let (a, b) = tokio::join!(prepare(&db, &apply), prepare(&db, &apply)); - let applied: Vec = [a.expect("first"), b.expect("second")] + let holder = crate::serve_lock::ServeLock::acquire(&db).expect("another process's lock"); + let waiting = AtomicUsize::new(0); + let progress = |line: &str| { + if line.starts_with("taking the migration lock") { + waiting.fetch_add(1, Ordering::SeqCst); + } + }; + let target = Target::at(db.to_string_lossy()); + let apply = startup(true, Duration::from_secs(60)); + let free = async { + while waiting.load(Ordering::SeqCst) < 2 { + tokio::time::sleep(Duration::from_millis(20)).await; + } + drop(holder); + }; + let (a, b, ()) = tokio::join!( + prepare_to_serve(&SqliteCatalogMigrations, &target, &apply, &progress), + prepare_to_serve(&SqliteCatalogMigrations, &target, &apply, &progress), + free, + ); + let mut applied: Vec = [a.expect("first"), b.expect("second")] .iter() - .map(|p| p.run.as_ref().map_or(0, |r| r.applied.len())) + .map(|p| p.run.as_ref().expect("each took the lock").applied.len()) .collect(); - assert!( - applied.contains(&0) && applied.contains(&MigrationId::ALL.len()), - "one migrates and the other finds nothing to do: {applied:?}" + applied.sort_unstable(); + assert_eq!( + applied, + [0, MigrationId::ALL.len()], + "one migrates, and the other takes the lock after it and applies nothing" ); assert_eq!(copies(&db).len(), 1); assert_eq!( @@ -295,6 +322,127 @@ async fn two_servers_started_together_with_apply_migrate_once() { ); } +/// The SQLite backend, counting the runs it is asked to make. +#[derive(Default)] +struct CountingRuns { + runs: AtomicUsize, +} + +#[async_trait] +impl CatalogMigrations for CountingRuns { + fn listed(&self, id: MigrationId) -> Listed { + SqliteCatalogMigrations.listed(id) + } + fn backup_advice(&self, target: &Target) -> String { + SqliteCatalogMigrations.backup_advice(target) + } + fn in_process(&self, target: &Target) -> bool { + SqliteCatalogMigrations.in_process(target) + } + async fn server_creates_catalog(&self, target: &Target) -> Result { + SqliteCatalogMigrations.server_creates_catalog(target).await + } + async fn status(&self, target: &Target) -> Result { + SqliteCatalogMigrations.status(target).await + } + async fn catalog_ledger(&self, target: &Target) -> Result, MigrationError> { + SqliteCatalogMigrations.catalog_ledger(target).await + } + async fn lock(&self, target: &Target, timeout: Duration) -> Result { + SqliteCatalogMigrations.lock(target, timeout).await + } + async fn run( + &self, + lock: &HeldLock, + release: &str, + kind: RunKind, + ) -> Result { + self.runs.fetch_add(1, Ordering::SeqCst); + SqliteCatalogMigrations.run(lock, release, kind).await + } + async fn forget(&self, lock: &HeldLock, id: u32) -> Result<(), MigrationError> { + SqliteCatalogMigrations.forget(lock, id).await + } +} + +/// Another process migrates the catalog while this one waits for the lock: +/// under the lock this one finds it current, and releases the lock and +/// serves it without the backend's run, so it writes nothing to the +/// database and takes no copy. +#[cfg(unix)] +#[tokio::test] +async fn a_catalog_migrated_during_the_wait_is_served_with_nothing_written() { + let db = temp_db("startup-migrated-meanwhile"); + load_dump(&db, DEV_0_1_14).await; + let location = db.to_string_lossy().into_owned(); + let other = crate::serve_lock::ServeLock::acquire(&db).expect("another process's lock"); + let backend = CountingRuns::default(); + let waiting = AtomicUsize::new(0); + let progress = |line: &str| { + if line.starts_with("taking the migration lock") { + waiting.fetch_add(1, Ordering::SeqCst); + } + }; + let target = Target::at(location.as_str()); + let apply = startup(true, Duration::from_secs(60)); + let other_process = async { + while waiting.load(Ordering::SeqCst) < 1 { + tokio::time::sleep(Duration::from_millis(20)).await; + } + super::migrate_holding(&location, RELEASE, &other) + .await + .expect("the other process migrates"); + let written = (bytes(&db), copies(&db)); + drop(other); + written + }; + let (prepared, (after_other, copies_after_other)) = tokio::join!( + prepare_to_serve(&backend, &target, &apply, &progress), + other_process, + ); + let report = prepared.expect("served").run.expect("a run under the lock"); + assert!(report.applied.is_empty(), "{report:?}"); + assert_eq!(report.to, Some(LATEST)); + assert_eq!(backend.runs.load(Ordering::SeqCst), 0, "the backend ran"); + assert_eq!(bytes(&db), after_other, "the waiting process wrote"); + assert_eq!(copies(&db), copies_after_other); + assert_eq!(copies(&db).len(), 1, "only the other process's copy"); + assert_eq!( + status(&db).await, + CatalogStatus::Current { version: LATEST } + ); +} + +/// A dev build's policy refuses, before the server starts, a file that +/// holds another program's tables, with the refusal the server's factory +/// gives it, and writes nothing; an empty file is left to the server, which +/// creates the catalog in it. +#[tokio::test] +async fn a_dev_policy_refuses_a_file_that_holds_another_programs_tables() { + let db = temp_db("startup-dev-foreign"); + exec( + &db, + "CREATE TABLE notes (id INTEGER PRIMARY KEY, body TEXT)", + ) + .await; + let before = bytes(&db); + let dev = Startup { + creates_uninitialized: true, + ..startup(true, Duration::from_secs(5)) + }; + let err = prepare(&db, &dev).await.expect_err("refused"); + assert_eq!(err, MigrationError::Status(CatalogStatus::Uninitialized)); + assert_eq!(err.exit_code(), exit::ERROR); + assert_eq!(err, refusal(start(&db.to_string_lossy(), true).await)); + assert_eq!(bytes(&db), before, "the policy wrote to the file"); + assert!(copies(&db).is_empty()); + + let empty = temp_db("startup-dev-empty"); + std::fs::write(&empty, b"").expect("an empty file"); + let prepared = prepare(&empty, &dev).await.expect("left to the server"); + assert_eq!(prepared, Prepared::default()); +} + /// An in-memory database belongs to the server that opens it: the policy /// reads nothing, and the server creates the catalog. #[tokio::test] From b0d5906e167cce99eb9440e9343ae6379cb1e874 Mon Sep 17 00:00:00 2001 From: Lee Hannigan <29015211+LeeroyHannigan@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:42:57 +0000 Subject: [PATCH 09/14] fix(npm): stop a server that fails to start, and report its exit code Each /health probe has a 1 s limit that starts before the connect. The old limit started once the socket connected, so a probe of a port that is bound but does not accept waited for the agent's socket timeout instead: 5 s with Node 22, measured against a listener with a full accept queue. start() stops the server before it rejects, because the caller has no handle to a server that failed to start. When the server exits first, the error carries its exit code as exitCode and its signal as signal. The error is built on "close", after the server's stderr has ended, so it holds the last lines the server printed. A new onProgress option receives each catalog migration line while the server starts. extenddb start writes those lines to its stderr and exits with the server's exit code. test/start.test.js runs start() and extenddb start against test/fake-server.js through a replaced child_process.spawn, with startupTimeoutMs unset. A server that reports progress for 20 s is waited for, one that prints nothing is given up on at 15 s and stopped, and the exit code and the signal reach the error. The silent stand-in answers after 60 s, so a deadline check that runs late still ends in a timeout. The scenario that called waitForStartup directly leaves test/launcher.test.js. The launcher workflow and the npm build matrix run the new file. The README says when the startup timeout counts from, documents onProgress and the error's fields, and says that a migrated database keeps the copy taken before the migration beside it. --- .github/workflows/launcher.yml | 1 + .github/workflows/npm-build-matrix.yml | 1 + packaging/npm/README.md | 12 +- packaging/npm/bin/extenddb-launcher.js | 7 +- packaging/npm/index.js | 53 +++++-- packaging/npm/package.json | 2 +- packaging/npm/startup.js | 34 +++-- packaging/npm/test/fake-server.js | 44 ++++-- packaging/npm/test/launcher.test.js | 70 +-------- packaging/npm/test/start.test.js | 193 +++++++++++++++++++++++++ packaging/npm/test/stub-spawn.js | 50 +++++++ 11 files changed, 359 insertions(+), 108 deletions(-) create mode 100644 packaging/npm/test/start.test.js create mode 100644 packaging/npm/test/stub-spawn.js diff --git a/.github/workflows/launcher.yml b/.github/workflows/launcher.yml index 2bcbb9f10..4699f0d94 100644 --- a/.github/workflows/launcher.yml +++ b/.github/workflows/launcher.yml @@ -43,3 +43,4 @@ jobs: set -euo pipefail cd packaging/npm node test/launcher.test.js + node test/start.test.js diff --git a/.github/workflows/npm-build-matrix.yml b/.github/workflows/npm-build-matrix.yml index db58cd508..e012b1919 100644 --- a/.github/workflows/npm-build-matrix.yml +++ b/.github/workflows/npm-build-matrix.yml @@ -160,6 +160,7 @@ jobs: set -euo pipefail cd packaging/npm node test/launcher.test.js + node test/start.test.js - name: Portability gate - the binary must run on the oldest libc we support if: contains(matrix.target, 'musl') diff --git a/packaging/npm/README.md b/packaging/npm/README.md index 7d7de08b4..395dd3fff 100644 --- a/packaging/npm/README.md +++ b/packaging/npm/README.md @@ -50,12 +50,22 @@ calls in an async function (top-level `await` is ESM-only). | `dbPath` | data dir | SQLite file location (file mode only). | | `port` | ephemeral | Fixed port instead of an OS-assigned one. | | `binary` | bundled | Path to an `extenddb` binary, overriding the bundled one. | -| `startupTimeoutMs` | `15000` | How long to wait for the server to become healthy, counted from the last line of catalog migration progress it prints. | +| `startupTimeoutMs` | `15000` | How long to wait for the server to become healthy, counted from launch, or from the last catalog migration line the server prints if that is later. The server prints one every 5 s while it migrates, so a value under 5000 can give up during a migration. | +| `onProgress` | none | A function called with each catalog migration line the server prints on stderr while it starts. `extenddb start` writes these lines to its stderr. | The returned object carries `endpoint`, `port`, `credentials`, `region`, `storage`, and `stop()`, which shuts the server down and resolves when the process has exited. +When the server does not become healthy, `start()` stops it and rejects. If +the server exited first, the error's `exitCode` and `signal` are the server's, +and `extenddb start` exits with the server's exit code. + +In file mode, when an older release created the database, the server migrates +it before serving it. Before its first change it copies the database to +`.pre-migration--to--