fabi/EventSnap
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(ops): bound logs, drain ffmpeg's stderr, and stop three silent hangs

Browse Source 
Six independent operational defects, none of which needed a new feature to fix.

Log rotation. Docker's json-file driver is unbounded by default, and those files
land on the HOST filesystem — outside every deploy.resources.limits in the compose
file, and on the same disk as postgres_data and media_data. A full disk stops
Postgres writing WAL, which takes the event down. Capped at 10m x 3 per service.

Log level. RUST_LOG was set in neither .env.example nor docker-compose.yml, so the
code fallback WAS the production level — and it was `debug`, with tower_http=debug
emitting a line per request and per response into that unrotated file. Now info,
with tower_http=warn to state that those spans are diagnostics, not an access log.

ffmpeg pipe deadlock. run_ffmpeg piped stdout and stderr and then called wait(),
which drains neither. Once the ~64 KiB pipe buffer filled, ffmpeg blocked writing
and wait() never returned — burning the full 120s timeout, twice per seek position,
three times per compression attempt. And the timeout is an Err, so the end state was
a soft-deleted upload: a guest's playable video destroyed by a poster-frame failure.
Now stdout is null (nothing ever read it) and stderr is drained by wait_with_output,
whose tail is logged on a non-zero exit. Note wait_with_output consumes the child, so
the old kill-on-timeout is gone; kill_on_drop(true) already covers it.

Readiness probe. /health never touched the pool, so the disk-full endgame above
stayed green all the way down. Adds /health/ready (SELECT 1 under 2s) as a SECOND
route — the compose healthcheck deliberately keeps pointing at /health, because
caddy gates its startup on it and a DB-dependent probe would turn a Postgres blip
into the reverse proxy refusing to start.

api.ts request timeout. The abort timer was cleared in a finally around fetch(),
which resolves on the response HEAD — leaving res.text() uncovered and no longer
abortable. An upstream that sends headers then stalls the body hung the call
forever. The timer now lives until the body is read, including the 204 path (which
otherwise leaked a live 20s timer per no-content request).

Upload XHR watchdog. The XHR had no timeout while processQueue held the
isProcessing latch across it; on a half-open socket neither error nor abort ever
fires, so the latch pinned and the queue wedged. Bounds SILENCE rather than total
duration — a 500 MB video over a venue uplink legitimately runs 30+ minutes while
making steady progress. Rejects as NetworkError, which is already the retryable
branch, so a stalled upload now recovers like any network blip.

IndexedDB failures. addToQueue called getDb() unguarded and handleSubmit had no
catch, so a private-mode refusal or a QuotaExceededError on a large blob left a
permanent "Wird hochgeladen…" spinner, no toast, and — for an in-app camera
capture — the only copy of the photo gone. Now reported as 'failed', which keeps
the staged files on screen and stays on the page.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
MechaCat02
2026-07-31 22:25:23 +02:00
parent 7d0334bf22
commit 6fd75adb27
11 changed files with 394 additions and 32 deletions
Download Patch File Download Diff File Expand all files Collapse all files

43
backend/src/handlers/health.rs Normal file
View File

@@ -0,0 +1,43 @@
use std::time::Duration;
use axum::extract::State;
use axum::http::StatusCode;
use crate::state::AppState;
/// How long a readiness probe waits for the database before calling the app not-ready.
///
/// Deliberately shorter than the pool's own `acquire_timeout`: a saturated pool IS a
/// not-ready condition, and reporting it as such is the point. Do not "fix" the two to
/// match — that would make the probe wait out the very saturation it exists to surface.
const READY_TIMEOUT: Duration = Duration::from_secs(2);
/// Readiness: can this instance actually serve a request end to end?
///
/// Separate from `/health` (liveness) ON PURPOSE, and the compose healthcheck must keep
/// pointing at `/health`. `caddy` declares `depends_on: app: {condition: service_healthy}`,
/// so a DB-dependent healthcheck would turn a transient Postgres hiccup during boot into
/// the reverse proxy refusing to start — converting a blip into a total outage. This route
/// is for an external monitor, which should page rather than restart.
///
/// The gap this closes: every request path touches the database, so with a dead or
/// saturated pool the app is useless while `/health` still answers "ok" — the disk-full
/// endgame (media volume fills, Postgres cannot write WAL) stayed green all the way down.
pub async fn ready(State(state): State<AppState>) -> (StatusCode, &'static str) {
let probe = sqlx::query_scalar::<_, i32>("SELECT 1").fetch_one(&state.pool);
match tokio::time::timeout(READY_TIMEOUT, probe).await {
Ok(Ok(_)) => (StatusCode::OK, "ready"),
Ok(Err(e)) => {
tracing::warn!(error = ?e, "readiness probe failed: database unreachable");
(StatusCode::SERVICE_UNAVAILABLE, "database unavailable")
}
Err(_) => {
tracing::warn!(
timeout_secs = READY_TIMEOUT.as_secs(),
"readiness probe timed out; the pool is saturated or the database is hung"
);
(StatusCode::SERVICE_UNAVAILABLE, "database timeout")
}
}
}

1
backend/src/handlers/mod.rs
View File

@@ -1,5 +1,6 @@
pub mod admin;
pub mod feed;
pub mod health;
pub mod host;
pub mod me;
pub mod public;

13
backend/src/main.rs
View File

@@ -27,8 +27,15 @@ async fn main() -> Result<()> {
tracing_subscriber::registry()
.with(
// `info`, not `debug`. A stock deploy sets RUST_LOG nowhere (it is absent from
// .env.example and was absent from docker-compose.yml), so this fallback IS the
// production level — and at `debug` the TraceLayer below emits a line per request
// AND per response, into a log file that had no rotation. `tower_http=warn`
// rather than `info` states the intent: those spans are diagnostics, not an
// access log, and a future `DefaultOnResponse::new().level(Level::INFO)` should
// not silently re-enable them.
tracing_subscriber::EnvFilter::try_from_default_env()
.unwrap_or_else(|_| "eventsnap_backend=debug,tower_http=debug".into()),
.unwrap_or_else(|_| "eventsnap_backend=info,tower_http=warn".into()),
)
.with(tracing_subscriber::fmt::layer())
.init();
@@ -248,7 +255,11 @@ async fn main() -> Result<()> {
// four subtrees. Deleting the route removes the vector outright rather than racing the
// decoder; `/media/**` now 404s regardless of encoding.
let router = Router::new()
// Liveness. Stays dependency-free — the compose healthcheck gates Caddy's startup
// on it, so anything that can fail transiently must NOT be in here.
.route("/health", get(|| async { "ok" }))
// Readiness. Touches the pool; for an external monitor, not for the compose gate.
.route("/health/ready", get(handlers::health::ready))
.merge(api)
.layer(TraceLayer::new_for_http())
.with_state(state);

113
backend/src/services/video.rs
View File

@@ -71,7 +71,7 @@ pub async fn extract_poster_frame(src: &Path, dest: &Path, width: u32) -> Result
/// Run one ffmpeg attempt. A non-zero exit is NOT an error here — the artifact check above is the
/// authority, and a corrupt input that fails at 1 s may still yield a frame at 0.
async fn run_ffmpeg(src: &Path, dest: &Path, width: u32, seek: &str) -> Result<()> {
let mut child = tokio::process::Command::new("ffmpeg")
let child = tokio::process::Command::new("ffmpeg")
.args([
// BEFORE -i: an input-side seek. See SEEK_POSITIONS.
"-ss",
@@ -85,24 +85,56 @@ async fn run_ffmpeg(src: &Path, dest: &Path, width: u32, seek: &str) -> Result<(
"-y",
dest.to_str().unwrap_or_default(),
])
.stdout(std::process::Stdio::piped())
// ffmpeg writes the poster to `dest` itself; nothing here ever reads stdout, so
// giving it a pipe only created something that could fill.
.stdout(std::process::Stdio::null())
// stderr IS piped — it is the only diagnostic when a clip yields no frame — but it
// must be DRAINED, which is the whole point of `wait_with_output` below.
.stderr(std::process::Stdio::piped())
.kill_on_drop(true)
.spawn()
.context("failed to spawn ffmpeg")?;
match tokio::time::timeout(FFMPEG_TIMEOUT, child.wait()).await {
Ok(res) => {
res.context("ffmpeg wait failed")?;
}
Err(_) => {
let _ = child.kill().await;
anyhow::bail!("ffmpeg timed out after {}s", FFMPEG_TIMEOUT.as_secs());
}
// `wait_with_output`, NOT `wait`. ffmpeg is verbose on stderr (banner, stream info,
// per-frame progress) and `wait()` reads neither pipe — so once the ~64 KiB pipe buffer
// filled, ffmpeg blocked writing, `wait()` never returned, and the call burned the full
// timeout. That is not merely slow: the timeout is an `Err`, so after 2 seek positions x
// 3 compression attempts the caller soft-deletes a perfectly playable video for a
// poster-frame failure. `wait_with_output` polls the pipe and the exit status together.
//
// It also CONSUMES the child, so the explicit `child.kill()` that used to sit on the
// timeout arm cannot exist here — and is not needed: `kill_on_drop(true)` is set above,
// and dropping the future on timeout drops the child with it.
let out = match tokio::time::timeout(FFMPEG_TIMEOUT, child.wait_with_output()).await {
Ok(res) => res.context("ffmpeg wait failed")?,
Err(_) => anyhow::bail!("ffmpeg timed out after {}s", FFMPEG_TIMEOUT.as_secs()),
};
// A non-zero exit is not an error (see the doc comment) — the artifact check in
// `extract_poster_frame` is the authority. Log the tail so a systematically failing
// format is diagnosable without turning it into data loss.
if !out.status.success() {
tracing::debug!(
seek,
status = ?out.status,
stderr = %tail_lines(&out.stderr, 10),
"ffmpeg exited non-zero; the artifact check decides"
);
}
Ok(())
}
/// Last `n` lines of a child's stderr, lossily decoded.
///
/// Bounded on purpose: ffmpeg's stderr is unbounded, and the reason we now drain it is that
/// unbounded output used to be a hazard. Emitting all of it into a log line — into container
/// logs that are themselves size-capped — would just move the problem.
fn tail_lines(bytes: &[u8], n: usize) -> String {
let text = String::from_utf8_lossy(bytes);
let lines: Vec<&str> = text.lines().filter(|l| !l.trim().is_empty()).collect();
lines[lines.len().saturating_sub(n)..].join(" | ")
}
#[cfg(test)]
mod tests {
use super::*;
@@ -137,4 +169,65 @@ mod tests {
);
let _ = std::fs::remove_dir_all(&dir);
}
#[test]
fn the_stderr_tail_is_bounded_and_survives_invalid_utf8() {
let noisy: Vec<u8> = (0..500)
.map(|i| format!("line {i}\n"))
.collect::<String>()
.into_bytes();
let got = tail_lines(&noisy, 3);
assert_eq!(got, "line 497 | line 498 | line 499");
// ffmpeg emits filenames verbatim, so its stderr is not guaranteed to be UTF-8.
assert_eq!(tail_lines(&[b'o', b'k', 0xff], 5), "ok\u{fffd}");
assert_eq!(tail_lines(b"", 5), "");
}
/// A real extraction must finish in a small fraction of `FFMPEG_TIMEOUT`.
///
/// Wall-clock is the ONLY observable of the bug this guards: piping stderr and then
/// calling `wait()` (which drains nothing) blocks ffmpeg on a full pipe buffer until the
/// timeout fires, and the timeout is an `Err`, so the upload is soft-deleted. The
/// assertion is deliberately on elapsed time, not on the exit status.
///
/// Honest limitation: our fixture is quiet enough not to fill a 64 KiB pipe on its own,
/// so this catches a regression to `wait()` only in combination with a verbose input. It
/// is still worth pinning — a reverted drain plus any chatty clip is data loss.
#[tokio::test]
async fn a_real_clip_yields_a_poster_well_inside_the_timeout() {
if tokio::process::Command::new("ffmpeg")
.arg("-version")
.stdout(std::process::Stdio::null())
.stderr(std::process::Stdio::null())
.status()
.await
.is_err()
{
eprintln!("skipping: ffmpeg not on PATH");
return;
}
let src = Path::new("../e2e/fixtures/media/sample.mp4");
if !src.exists() {
eprintln!("skipping: {} missing", src.display());
return;
}
let dir = std::env::temp_dir().join(format!("es-video-ok-{}", std::process::id()));
std::fs::create_dir_all(&dir).unwrap();
let dest = dir.join("poster.jpg");
let started = std::time::Instant::now();
let got = extract_poster_frame(src, &dest, 400).await;
let elapsed = started.elapsed();
assert!(matches!(got, Ok(true)), "expected a poster, got {got:?}");
assert!(dest.metadata().unwrap().len() > 0);
assert!(
elapsed < FFMPEG_TIMEOUT / 4,
"extraction took {elapsed:?}; a drained stderr finishes in well under \
{FFMPEG_TIMEOUT:?} — this is the pipe-deadlock regression guard"
);
let _ = std::fs::remove_dir_all(&dir);
}
}