From dbc05416d42f2acf850899adcde97cd1b15dd43f Mon Sep 17 00:00:00 2001 From: Nigel Tatschner Date: Sun, 26 Jul 2026 19:15:52 +0100 Subject: [PATCH] fix(server): log the full anyhow cause chain at mailer failure sites MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `Display` on an anyhow::Error prints ONLY the outermost context, so `error = %e` logs the wrapper and silently discards the actual cause. Every mail path wraps its errors (`.context("parse To address")`, `.context("SMTP send failed")`, …), so every mail failure has been logged as its wrapper alone. That is why the waitlist invite outage read as a broken transport for as long as it did: the logs only ever said `parse To address`, never which address or why. The cause — that a display name containing `@` is not a valid RFC 5322 atom — was one context layer down and never printed. Switches the 8 sites that log a `Mailer` error to `%format!("{e:#}")`, whose alternate Display flattens the whole chain onto ONE line. Single line matters: `?e` (Debug) also carries the chain but emits multi-line output, which is hostile to the JSON log pipeline. This is not a new idiom — `format!("{e:#}")` is already used for exactly this in smtp_admin_routes.rs:351 and telemetry.rs:63. The SMTP test-send site is included here because its code used `?e` while the comment directly above it prescribed `{e:#}`; code and comment now agree. Deliberately NOT a repo-wide sweep. There are 392 `error = %e` sites; most log a thiserror enum whose Display already interpolates its source (e.g. `WaitlistError::Database(#[from] sqlx::Error)` renders as "database error: {0}"), so `{:#}` would add nothing. Only anyhow errors lose information this way, and the Mailer trait is where that bit. Adds a test pinning the difference: plain Display yields only "send_waitlist_invite failed" while `{e:#}` carries every layer down to the root cause, and stays single-line. --- crates/starstats-server/src/auth_routes.rs | 8 ++-- .../starstats-server/src/magic_link_routes.rs | 2 +- crates/starstats-server/src/mail.rs | 42 +++++++++++++++++++ .../starstats-server/src/smtp_admin_routes.rs | 2 +- .../starstats-server/src/waitlist_routes.rs | 6 +-- 5 files changed, 51 insertions(+), 9 deletions(-) diff --git a/crates/starstats-server/src/auth_routes.rs b/crates/starstats-server/src/auth_routes.rs index 1846f07d..afc843bd 100644 --- a/crates/starstats-server/src/auth_routes.rs +++ b/crates/starstats-server/src/auth_routes.rs @@ -370,7 +370,7 @@ pub async fn signup( .send_verification(&user.email, &user.claimed_handle, &token) .await { - tracing::warn!(error = %e, user_id = %user.id, "send verification email failed"); + tracing::warn!(error = %format!("{e:#}"), user_id = %user.id, "send verification email failed"); } issue_token(&issuer, &user.id.to_string(), &user.claimed_handle) @@ -580,7 +580,7 @@ pub async fn resend_verification( .send_verification(&user.email, &user.claimed_handle, &token) .await { - tracing::warn!(error = %e, user_id = %user.id, "send verification email failed"); + tracing::warn!(error = %format!("{e:#}"), user_id = %user.id, "send verification email failed"); } if let Err(e) = audit @@ -947,7 +947,7 @@ pub async fn password_reset_start( .send_password_reset(&user.email, &user.claimed_handle, &token) .await { - tracing::warn!(error = %e, user_id = %user.id, "send reset email failed"); + tracing::warn!(error = %format!("{e:#}"), user_id = %user.id, "send reset email failed"); } } else { // Sleep briefly to flatten the timing oracle — a fast @@ -1127,7 +1127,7 @@ pub async fn email_change_start( .send_email_change_verify(&new_email, &auth.preferred_username, &token) .await { - tracing::warn!(error = %e, "send email-change verify failed"); + tracing::warn!(error = %format!("{e:#}"), "send email-change verify failed"); } ( StatusCode::OK, diff --git a/crates/starstats-server/src/magic_link_routes.rs b/crates/starstats-server/src/magic_link_routes.rs index ff4c6341..6bab3bbc 100644 --- a/crates/starstats-server/src/magic_link_routes.rs +++ b/crates/starstats-server/src/magic_link_routes.rs @@ -139,7 +139,7 @@ pub async fn start( .send_magic_link(&user.email, &user.claimed_handle, &token) .await { - tracing::warn!(error = %e, "send magic link failed (best-effort)"); + tracing::warn!(error = %format!("{e:#}"), "send magic link failed (best-effort)"); } Json(MagicLinkStartResponse { sent: true }).into_response() diff --git a/crates/starstats-server/src/mail.rs b/crates/starstats-server/src/mail.rs index 395bce2f..17445b9b 100644 --- a/crates/starstats-server/src/mail.rs +++ b/crates/starstats-server/src/mail.rs @@ -703,6 +703,48 @@ pub mod test_support { mod tests { use super::*; + /// Why the mailer log sites format with `{e:#}` and not `%e`. + /// + /// `Display` on an `anyhow::Error` prints ONLY the outermost context. + /// Every mail failure is wrapped (`.context("parse To address")`, + /// `.context("SMTP send failed")`, …), so `error = %e` logs the wrapper + /// and silently discards the actual cause. That is exactly how the + /// waitlist invite outage read as "the mail transport is broken" for as + /// long as it did — the logs only ever said `parse To address`, never + /// which address or why. + /// + /// The alternate form `{e:#}` flattens the whole chain onto one line, + /// which keeps it greppable in the JSON log pipeline (unlike `?e`, + /// whose `Debug` output is multi-line). + #[test] + fn alternate_display_surfaces_the_cause_chain_that_plain_display_hides() { + let err = anyhow::anyhow!("invalid email address: a@b.com ") + .context("parse To address") + .context("send_waitlist_invite failed"); + + let plain = format!("{err}"); + let chained = format!("{err:#}"); + + // What `%e` would have logged: the wrapper only. + assert_eq!(plain, "send_waitlist_invite failed"); + assert!( + !plain.contains("invalid email address"), + "plain Display hides the root cause — this is the bug being guarded against" + ); + + // What `{e:#}` logs: every layer, root cause included. + assert!(chained.contains("send_waitlist_invite failed")); + assert!(chained.contains("parse To address")); + assert!( + chained.contains("invalid email address: a@b.com "), + "the root cause must survive into the log line, got {chained}" + ); + assert!( + !chained.contains('\n'), + "must stay single-line for the JSON log pipeline, got {chained}" + ); + } + /// Repro for the production failure: every waitlist invite/resend /// died with `parse To address`. /// diff --git a/crates/starstats-server/src/smtp_admin_routes.rs b/crates/starstats-server/src/smtp_admin_routes.rs index b433e17d..42af66d0 100644 --- a/crates/starstats-server/src/smtp_admin_routes.rs +++ b/crates/starstats-server/src/smtp_admin_routes.rs @@ -344,7 +344,7 @@ pub async fn test_smtp( // without it the user only sees the outermost wrap ("SMTP send // failed") and the actual cause (auth rejected, TLS handshake, // connection refused, …) is invisible. - tracing::warn!(error = ?e, "smtp test send failed"); + tracing::warn!(error = %format!("{e:#}"), "smtp test send failed"); return error( StatusCode::BAD_GATEWAY, "smtp_send_failed", diff --git a/crates/starstats-server/src/waitlist_routes.rs b/crates/starstats-server/src/waitlist_routes.rs index a7317171..69b51645 100644 --- a/crates/starstats-server/src/waitlist_routes.rs +++ b/crates/starstats-server/src/waitlist_routes.rs @@ -198,7 +198,7 @@ pub async fn join( // and the row looks perfectly admitted from the DB side. if let Err(e) = mailer.send_waitlist_invite(&req.email, invite_token).await { tracing::error!( - error = %e, + error = %format!("{e:#}"), email = %req.email, "waitlist invite send FAILED — admitted user has no link; re-admit from /admin/waitlist" ); @@ -331,7 +331,7 @@ pub async fn admin_admit( .await { tracing::error!( - error = %e, + error = %format!("{e:#}"), email = %inv.email, "waitlist invite send FAILED for an admitted user — they have no link" ); @@ -387,7 +387,7 @@ pub async fn admin_resend( .await { tracing::error!( - error = %e, + error = %format!("{e:#}"), email = %inv.email, "waitlist invite RESEND failed — the mail transport is still broken" );