Steps in the traces of the disk sweep, episode lists and DeadAir (#187)

A 47 s reap had a trace of one span, so whether the time went on checking
every file on disk, the database or deleting could not be told. The reap's
steps are spans now, with what it removed on the reap span; an episode
list's query, sanitising, DeadAir and count are steps; and DeadAir's work
on a file is a trace of its own (probe, silencedetect, frame_bytes,
store_plans), only for files it looks at, not the idle passes.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

CHANGELOG.md

@@ -14,6 +14,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Changed
 
+- Traces of the disk sweep, episode lists and DeadAir's work on each file show each step, and the sweep's trace says what it removed (#187).
 - DeadAir is in the same box as a show's download settings, below them, and stays there when automatic downloads are off (#185).
 - The container is built on Debian 13 (trixie) instead of 12, so DeadAir uses ffmpeg 7.1 instead of 5.1 (#177).
 - DeadAir no longer makes a shortened copy of each episode. It plays the original with its long silences left out, ready a few seconds after the download, with no gap where a silence was cut and no extra disk space (#181).

src/deadair.rs

@@ -18,6 +18,10 @@ use std::fmt::Write as _;
 use std::path::Path;
 use std::sync::Arc;
 
+use tracing::Instrument;
+
+use crate::db::step;
+
 use anyhow::{Context, Result, bail};
 use serde::{Deserialize, Serialize};
 
@@ -420,7 +424,10 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet<i64>) -> Result<
         }
         let src = crate::download::playable(Path::new(&t.path));
         let started = std::time::Instant::now();
-        let plans = match analyse(&src).await {
+        // A trace of its own for each file looked at, not for the passes that find nothing to do,
+        // which are most of them.
+        let span = tracing::info_span!("deadair", feed = t.feed_id, enclosure = t.id, cuts = tracing::field::Empty);
+        let plans = match analyse(&src).instrument(span.clone()).await {
             Ok(p) => p.unwrap_or_default(),
             Err(e) => {
                 tracing::warn!(path = %src.display(), error = %format!("{e:#}"), "DeadAir could not read a file");
@@ -428,8 +435,9 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet<i64>) -> Result<
                 return Ok(true);
             }
         };
-        ctx.db.store_plans(t.id, &serde_json::to_string(&plans)?).await?;
+        ctx.db.store_plans(t.id, &serde_json::to_string(&plans)?).instrument(span.in_scope(|| step("store_plans"))).await?;
         let usual = plans.get(&DEFAULT_PAUSE);
+        span.record("cuts", usual.map_or(0, |p| p.cuts.len()));
         let saved_ms = usual.map_or(0, Plan::saved_ms);
         ctx.out.emit(crate::ipc::Event::DeadairDone { feed: t.feed_id.clone(), enclosure: t.id, saved_s: saved_ms / 1000 });
         // The event says it too (ev="deadair_done"); this line has how long it took and how many cuts.
@@ -450,16 +458,17 @@ async fn next(ctx: &Ctx, failed: &mut std::collections::HashSet<i64>) -> Result<
 /// anything but MP3 or AAC on its own (ADTS; AAC in MP4 has no byte ranges a playlist can
 /// use), or one with no silence long enough to cut.
 pub async fn analyse(src: &Path) -> Result<Option<BTreeMap<i64, Plan>>> {
-    let Some((first, frame)) = probe(src).await? else { return Ok(None) };
+    let Some((first, frame)) = probe(src).instrument(step("probe")).await? else { return Ok(None) };
     let path = src.display().to_string();
     let log = ffmpeg(&[
         "-hide_banner", "-nostats", "-i", &path, "-map", "0:a:0",
         "-af", &format!("silencedetect=n={THRESHOLD}:d={MIN_SILENCE}"), "-f", "null", "-",
     ])
+    .instrument(step("silencedetect"))
     .await
     .context("finding the silences")?;
     let silences = parse_silences(&log);
-    let frames = frame_bytes(&path).await?;
+    let frames = frame_bytes(&path).instrument(step("frame_bytes")).await?;
     let plans: BTreeMap<i64, Plan> = PAUSES
         .iter()
         .map(|&pause| {

src/main.rs

@@ -1137,12 +1137,16 @@ async fn clean_directory(ctx: &Ctx) -> Result<()> {
 /// `standalone` false means this is the sweep that runs before a scan: it reports what it
 /// deleted, but must not emit the terminal ReapDone, or a client waiting on its `fetch`
 /// would stop reading before the scan had even started.
-#[tracing::instrument(name = "reap", skip_all, fields(dry_run = dry_run))]
+#[tracing::instrument(name = "reap", skip_all, fields(dry_run = dry_run, files = tracing::field::Empty, bytes = tracing::field::Empty, entries = tracing::field::Empty))]
 async fn reap(ctx: &Ctx, dry_run: bool, standalone: bool) -> Result<()> {
     let r = retention::run(&ctx.cfg(), &ctx.db, dry_run).await?;
+    let span = tracing::Span::current();
+    span.record("files", r.aged_out.len() + r.over_quota.len());
+    span.record("bytes", r.bytes_freed);
+    span.record("entries", r.entries_pruned);
     if !dry_run {
-        clean_directory(ctx).await?;
-        let gone = art::trim(&art::dir(), ctx.cfg().general.art_cache_mb * 1_048_576);
+        tracing::Instrument::instrument(clean_directory(ctx), db::step("clean_directory")).await?;
+        let gone = db::step("trim_artwork").in_scope(|| art::trim(&art::dir(), ctx.cfg().general.art_cache_mb * 1_048_576));
         if gone > 0 {
             tracing::debug!(gone, "trimmed the artwork kept on disk");
         }

src/retention.rs

@@ -1,9 +1,10 @@
 //! Disk quota and age sweeps. Replaces iPXQuotaManager.py ("SmartSpace").
 
 use anyhow::Result;
+use tracing::Instrument;
 
 use crate::config::Config;
-use crate::db::{Candidate, Db, now};
+use crate::db::{Candidate, Db, now, step};
 
 /// Headroom kept below the quota, as getToQuota()'s `1048576 * 50` did.
 pub const PAD_BYTES: u64 = 50 * 1024 * 1024;
@@ -49,7 +50,8 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result<Report> {
     let mut report = Report::default();
 
     // Someone may have deleted a file by hand; the row must stop claiming it exists.
-    for (id, path) in db.missing_files().await? {
+    // Each step is a span of the reap's trace, so a slow one says which part was slow.
+    for (id, path) in db.missing_files().instrument(step("missing_files")).await? {
         if !dry_run {
             db.mark_reaped(id).await?;
         }
@@ -57,20 +59,20 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result<Report> {
         report.reconciled += 1;
     }
 
-    for id in db.prune_abandoned_failures().await? {
+    for id in db.prune_abandoned_failures().instrument(step("prune_abandoned_failures")).await? {
         tracing::info!(feed = id, "forgot a failing feed nobody subscribes to");
     }
 
-    let candidates = db.reap_candidates().await?;
+    let candidates = db.reap_candidates().instrument(step("reap_candidates")).await?;
 
     if cfg.general.max_age_days > 0 {
         let cutoff = now() - (cfg.general.max_age_days * 86_400) as i64;
         report.aged_out = aged(&candidates, cutoff);
         for c in &report.aged_out {
-            report.bytes_freed += remove(db, c, dry_run).await?;
+            report.bytes_freed += remove(db, c, dry_run).instrument(step("remove_aged")).await?;
         }
         if !dry_run {
-            report.entries_pruned = db.prune_entries(cutoff).await?;
+            report.entries_pruned = db.prune_entries(cutoff).instrument(step("prune_entries")).await?;
         }
     }
 
@@ -85,7 +87,7 @@ pub async fn run(cfg: &Config, db: &Db, dry_run: bool) -> Result<Report> {
         let total: u64 = remaining.iter().map(|c| c.bytes.max(0) as u64).sum();
         report.over_quota = pick(&remaining, total, limit);
         for c in &report.over_quota {
-            report.bytes_freed += remove(db, c, dry_run).await?;
+            report.bytes_freed += remove(db, c, dry_run).instrument(step("remove_over_quota")).await?;
         }
     }
 

src/web.rs

@@ -21,6 +21,8 @@ use std::sync::Arc;
 use tokio::sync::{broadcast, mpsc};
 
 use crate::Ctx;
+use crate::db::step;
+use tracing::Instrument;
 use crate::ipc::{Command, Event};
 
 const COOKIE: &str = "ipx_token";
@@ -833,8 +835,6 @@ async fn feeds(
 /// The feed list as this person sees it, or with `only` the one row for that feed: what a live
 /// update sends after the feed changes, so the page redraws a row instead of reloading the list.
 async fn feed_rows(state: &WebState, user: &crate::db::User, only: Option<&str>) -> anyhow::Result<Vec<FeedRow>> {
-    use crate::db::step;
-    use tracing::Instrument;
     let cfg = state.ctx.cfg();
     // Config entries plus the feeds derived from OPML subscriptions -- the catalogue.
     // What comes back is only the part of it this person subscribes to.
@@ -1468,16 +1468,20 @@ async fn entry_page(
     let search = page.q.as_deref().map(str::trim).filter(|q| !q.is_empty());
     let db = &state.ctx.db;
     let order = crate::db::order_sql(page.sort.as_deref().unwrap_or("published"), page.dir.as_deref().unwrap_or("desc"));
-    let mut rows =
-        db.entries_in(user_id, feed, filter, search, page.offset, page.limit.clamp(1, 200), &order).await?;
-    let mut sanitizer = feed_sanitizer();
-    for row in &mut rows {
-        if let Some(d) = &row.description {
-            row.description = Some(clean_description(&mut sanitizer, d, row.link.as_deref()));
+    let mut rows = db
+        .entries_in(user_id, feed, filter, search, page.offset, page.limit.clamp(1, 200), &order)
+        .instrument(step("entries_in"))
+        .await?;
+    step("sanitize").in_scope(|| {
+        let mut sanitizer = feed_sanitizer();
+        for row in &mut rows {
+            if let Some(d) = &row.description {
+                row.description = Some(clean_description(&mut sanitizer, d, row.link.as_deref()));
+            }
         }
-    }
-    crate::deadair::for_reader(&state.ctx, user_id, &mut rows).await?;
-    let total = db.count_in(user_id, feed, filter, search).await?;
+    });
+    crate::deadair::for_reader(&state.ctx, user_id, &mut rows).instrument(step("deadair")).await?;
+    let total = db.count_in(user_id, feed, filter, search).instrument(step("count_in")).await?;
     Ok(Json(EntryPage { total, entries: rows }))
 }
 
@@ -1960,7 +1964,7 @@ async fn media_deadair(State(state): State<WebState>, Path(id): Path<i64>, user:
     if let Err(e) = subscribed(&state, &user, &enc.feed_id).await {
         return e.into_response();
     }
-    let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).await {
+    let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).instrument(step("plan")).await {
         Ok(Some(p)) => p,
         Ok(None) => return (StatusCode::NOT_FOUND, "DeadAir has nothing to cut in this file for you").into_response(),
         Err(e) => return (StatusCode::INTERNAL_SERVER_ERROR, format!("{e:#}")).into_response(),
@@ -1988,7 +1992,7 @@ async fn media_save(State(state): State<WebState>, Path(id): Path<i64>, user: cr
     let Some(path) = enc.path else {
         return (StatusCode::NOT_FOUND, "not downloaded").into_response();
     };
-    let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).await {
+    let plan = match crate::deadair::plan_for(&state.ctx, user.id, &enc.feed_id, id).instrument(step("plan")).await {
         Ok(Some(p)) => p,
         Ok(None) => return (StatusCode::NOT_FOUND, "DeadAir has nothing to cut in this file for you").into_response(),
         Err(e) => return (StatusCode::INTERNAL_SERVER_ERROR, format!("{e:#}")).into_response(),