From 85d78898f8b4b63583ed8146b0617ebe63af5116 Mon Sep 17 00:00:00 2001 From: Hery Date: Tue, 21 Jul 2026 15:32:46 +0200 Subject: [PATCH 1/3] fix: retry startup auto-run while the database worker is unavailable MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit With auto: true the startup migration run was attempted exactly once. When miiigrate registered before the database worker — the common case under docker compose or an engine-managed boot, where registration order is not guaranteed — the run failed with DATABASE_WORKER_UNAVAILABLE and was never retried, silently leaving migrations unapplied until a manual migrate::up. The auto run now retries on DATABASE_WORKER_UNAVAILABLE with capped exponential backoff (1s doubling to 10s, 2-minute budget). Any other error, and budget exhaustion, remain loud and terminal for the auto run only: the worker stays up so migrate::status and migrate::up are available for diagnosis and manual recovery. --- docs/changelog.md | 11 ++++++++ docs/configuration.md | 2 +- src/main.rs | 60 +++++++++++++++++++++++++++++++++++-------- 3 files changed, 61 insertions(+), 12 deletions(-) diff --git a/docs/changelog.md b/docs/changelog.md index d951349..9054b7d 100644 --- a/docs/changelog.md +++ b/docs/changelog.md @@ -1,5 +1,16 @@ # Changelog +## Unreleased + +- `auto: true` now retries the startup migration run while the `database` + worker is unavailable (capped exponential backoff, 2-minute budget). + Previously the run was attempted exactly once: when miiigrate registered + before the database worker — the common case under docker compose or an + engine-managed boot — the auto run failed with + `DATABASE_WORKER_UNAVAILABLE` and was never retried, silently leaving + migrations unapplied. Other errors still fail fast, and the worker stays up + either way. + ## 0.1.1 — 2026-07-20 Documentation release — no functional change. diff --git a/docs/configuration.md b/docs/configuration.md index 2196414..6cb5459 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -25,7 +25,7 @@ config change, restart the worker (or the engine). |-----|---------|---------| | `db` | `primary` | Logical database name in the `database` worker's configuration. | | `dir` | `./migrations` | Migration folder, resolved against the worker's working directory. Only `migrate::create` creates it. | -| `auto` | `false` | Run `migrate::up` once at startup. Best-effort: a failure is logged and the worker stays up, so `migrate::status` remains available for diagnosis. | +| `auto` | `false` | Run `migrate::up` once at startup. If the `database` worker is not registered yet (no ordering guarantee under docker compose or engine-managed boots), the run is retried with capped backoff for up to 2 minutes. Best-effort: any other failure is logged and the worker stays up, so `migrate::status` remains available for diagnosis. | | `types_out` | — | Output path for `migrate::codegen`. Optional; without it, codegen requires `out` in the payload. | | `dialect` | auto | `postgres` or `sqlite`. By default the dialect is detected from the `database` worker's `database::listDatabases` driver field. | diff --git a/src/main.rs b/src/main.rs index f9430ed..e4e3964 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,9 +1,12 @@ +use std::time::Duration; + use anyhow::{Context, Result}; use clap::Parser; use iii_helpers::observability::OtelConfig; use iii_sdk::{register_worker, InitOptions, RegisterFunction}; use miiigrate::config::WorkerConfig; use miiigrate::configuration; +use miiigrate::error::MigrateError; use miiigrate::handlers::{codegen, create, status, up, AppState}; #[derive(Parser, Debug)] @@ -156,17 +159,7 @@ async fn main() -> Result<()> { } if auto { - // Best-effort startup migration: a failure is loud but does not kill - // the worker — migrate::status stays available for diagnosis. - match up::handle(&state, up::UpReq::default()).await { - Ok(resp) => tracing::info!( - applied = resp.applied.len(), - skipped = resp.skipped, - duration_ms = resp.duration_ms, - "auto migration run complete" - ), - Err(e) => tracing::error!(error = %e, "auto migration run failed"), - } + run_auto_migration(&state).await; } tracing::info!("miiigrate worker registered 4 functions, waiting for invocations"); @@ -176,6 +169,51 @@ async fn main() -> Result<()> { Ok(()) } +/// Total window during which the startup auto-run retries while the database +/// worker is unavailable. +const AUTO_RETRY_BUDGET: Duration = Duration::from_secs(120); +/// Backoff ceiling between two auto-run attempts. +const AUTO_RETRY_MAX_DELAY: Duration = Duration::from_secs(10); + +/// Best-effort startup migration. The database worker may register after us +/// (engine-managed boots and docker compose make no ordering guarantee), so +/// `DATABASE_WORKER_UNAVAILABLE` is retried with capped backoff for up to +/// [`AUTO_RETRY_BUDGET`]. Any other error — and exhaustion of the budget — is +/// loud but does not kill the worker: `migrate::status` and `migrate::up` +/// stay available for diagnosis and manual recovery. +async fn run_auto_migration(state: &AppState) { + let started = tokio::time::Instant::now(); + let mut delay = Duration::from_secs(1); + loop { + match up::handle(state, up::UpReq::default()).await { + Ok(resp) => { + tracing::info!( + applied = resp.applied.len(), + skipped = resp.skipped, + duration_ms = resp.duration_ms, + "auto migration run complete" + ); + return; + } + Err(MigrateError::DatabaseWorkerUnavailable { message }) + if started.elapsed() + delay <= AUTO_RETRY_BUDGET => + { + tracing::warn!( + error = %message, + retry_in_s = delay.as_secs(), + "database worker not ready; retrying auto migration run" + ); + tokio::time::sleep(delay).await; + delay = (delay * 2).min(AUTO_RETRY_MAX_DELAY); + } + Err(e) => { + tracing::error!(error = %e, "auto migration run failed"); + return; + } + } + } +} + /// Strip userinfo (username:password) from a URL before logging it. fn redact_url(s: &str) -> String { match url::Url::parse(s) { From b53f6a7757dd5b8f7b07e2a602c805863115248f Mon Sep 17 00:00:00 2001 From: Hery Date: Tue, 21 Jul 2026 16:40:13 +0200 Subject: [PATCH 2/3] =?UTF-8?q?fix:=20clean=20startup=20=E2=80=94=20retry?= =?UTF-8?q?=20configuration=20RPCs,=20silence=20duplicate=20OTel=20connect?= =?UTF-8?q?ion=20errors?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two more sources of apparent errors during a normal cold boot, where the engine and its workers come up in arbitrary order: - configuration::register/get gave up after 3 attempts (~16 s) and crashed the worker with a startup error, leaving the restart policy to try again. Transient failures (timeout, not connected, function not registered yet) are now retried with capped backoff under the same 2-minute budget as the auto run; real configuration-worker errors still fail fast. - iii-helpers' OTel side channel logs every pre-connection attempt at ERROR (hardcoded in the helper, no config knob) while iii-sdk already reports the identical condition as a WARN retry. The default tracing filter now turns that module off; setting RUST_LOG replaces the filter entirely. --- docs/changelog.md | 8 +++++++ src/configuration.rs | 53 +++++++++++++++++++++++++++++++------------- src/main.rs | 11 +++++++-- 3 files changed, 54 insertions(+), 18 deletions(-) diff --git a/docs/changelog.md b/docs/changelog.md index 9054b7d..bd3abb3 100644 --- a/docs/changelog.md +++ b/docs/changelog.md @@ -10,6 +10,14 @@ `DATABASE_WORKER_UNAVAILABLE` and was never retried, silently leaving migrations unapplied. Other errors still fail fast, and the worker stays up either way. +- Clean startup when the engine comes up after miiigrate. The + `configuration::register`/`get` calls now retry transient failures + (timeout, not connected, function not registered yet) with capped backoff + under the same 2-minute budget instead of crashing the worker after ~16 s; + real errors from the configuration worker still fail fast. The default log + filter also silences `iii-helpers`' OTel connection module, which logged + every pre-connection attempt at ERROR while iii-sdk already reports the + same condition as a WARN retry (set `RUST_LOG` to override). ## 0.1.1 — 2026-07-20 diff --git a/src/configuration.rs b/src/configuration.rs index 367ffde..b6cdd73 100644 --- a/src/configuration.rs +++ b/src/configuration.rs @@ -16,7 +16,12 @@ use crate::config::WorkerConfig; pub const CONFIG_ID: &str = "miiigrate"; const CONFIG_TIMEOUT_MS: u64 = 5_000; -const CONFIG_RETRIES: u32 = 3; +/// Total window during which transient failures (engine still starting: +/// timeout, not connected, function not registered yet) are retried before +/// giving up. Aligned with the auto-run retry budget in `main.rs`. +const CONFIG_RETRY_BUDGET: Duration = Duration::from_secs(120); +/// Backoff ceiling between two attempts. +const CONFIG_RETRY_MAX_DELAY: Duration = Duration::from_secs(5); /// Register the `miiigrate` configuration schema with the configuration /// worker. When `seed` is present, its value is installed as `initial_value`. @@ -70,13 +75,30 @@ async fn try_get_config_value(iii: &IIIClient) -> Result, String> } } +/// True for failures that resolve on their own once the engine and its +/// built-in workers finish starting: invocation timeout, socket not yet +/// connected, or the target function not registered yet. Anything else (a +/// real error from the configuration worker, e.g. schema rejection) will not +/// improve with time and must fail fast. +fn is_transient(e: &iii_sdk::errors::Error) -> bool { + use iii_sdk::errors::Error; + match e { + Error::Timeout | Error::NotConnected => true, + Error::Remote { code, .. } => code == "function_not_found", + _ => false, + } +} + async fn trigger_with_retry( iii: &IIIClient, function_id: &str, payload: Value, ) -> Result { - let mut last_err = String::new(); - for attempt in 1..=CONFIG_RETRIES { + let started = tokio::time::Instant::now(); + let mut delay = Duration::from_millis(250); + let mut attempt: u32 = 0; + loop { + attempt += 1; match iii .trigger(TriggerRequest { function_id: function_id.to_string(), @@ -87,21 +109,20 @@ async fn trigger_with_retry( .await { Ok(v) => return Ok(v), + Err(e) if is_transient(&e) && started.elapsed() + delay <= CONFIG_RETRY_BUDGET => { + tracing::warn!( + function_id, + attempt, + error = %e, + retry_in_ms = delay.as_millis() as u64, + "engine not ready for configuration RPC; retrying" + ); + tokio::time::sleep(delay).await; + delay = (delay * 2).min(CONFIG_RETRY_MAX_DELAY); + } Err(e) => { - last_err = e.to_string(); - if attempt < CONFIG_RETRIES { - tracing::warn!( - function_id, - attempt, - error = %last_err, - "configuration RPC failed; retrying" - ); - tokio::time::sleep(Duration::from_millis(250 * u64::from(attempt))).await; - } + return Err(format!("{function_id} failed after {attempt} attempts: {e}")); } } } - Err(format!( - "{function_id} failed after {CONFIG_RETRIES} attempts: {last_err}" - )) } diff --git a/src/main.rs b/src/main.rs index e4e3964..3b23831 100644 --- a/src/main.rs +++ b/src/main.rs @@ -28,8 +28,15 @@ struct Cli { async fn main() -> Result<()> { tracing_subscriber::fmt() .with_env_filter( - tracing_subscriber::EnvFilter::try_from_default_env() - .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")), + tracing_subscriber::EnvFilter::try_from_default_env().unwrap_or_else(|_| { + // The helpers' OTel side channel logs every pre-connection + // attempt at ERROR while iii-sdk already reports the same + // condition as a WARN retry; drop the duplicate noise by + // default. Setting RUST_LOG replaces this filter entirely. + tracing_subscriber::EnvFilter::new( + "info,iii_helpers::observability::telemetry::connection=off", + ) + }), ) .init(); From 9a71ebc1d4782e384e1bf16f1fc522143f43ec8f Mon Sep 17 00:00:00 2001 From: Hery Date: Tue, 21 Jul 2026 16:49:20 +0200 Subject: [PATCH 3/3] style: rustfmt --- src/configuration.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/configuration.rs b/src/configuration.rs index b6cdd73..19fc1d1 100644 --- a/src/configuration.rs +++ b/src/configuration.rs @@ -121,7 +121,9 @@ async fn trigger_with_retry( delay = (delay * 2).min(CONFIG_RETRY_MAX_DELAY); } Err(e) => { - return Err(format!("{function_id} failed after {attempt} attempts: {e}")); + return Err(format!( + "{function_id} failed after {attempt} attempts: {e}" + )); } } }