diff --git a/crates/kebab-app/src/ingest.rs b/crates/kebab-app/src/ingest.rs index 75f4e99..b045283 100644 --- a/crates/kebab-app/src/ingest.rs +++ b/crates/kebab-app/src/ingest.rs @@ -2224,6 +2224,15 @@ fn sweep_deleted_files( error = %e, "sweep_deleted_files: purge failed; skipping this path" ); + if let Some(lw) = log_writer + && let Ok(mut w) = lw.lock() + { + let _ = w.write_event(&crate::ingest_log::LogEvent::PurgeFailed { + ts: crate::ingest_log::now_ts(), + doc_path: &stored_path.0, + message: e.to_string(), + }); + } crate::ingest_progress::emit( progress, crate::ingest_progress::IngestEvent::SweepProgress { diff --git a/crates/kebab-app/src/ingest_log.rs b/crates/kebab-app/src/ingest_log.rs index 79630ee..7b519c5 100644 --- a/crates/kebab-app/src/ingest_log.rs +++ b/crates/kebab-app/src/ingest_log.rs @@ -158,6 +158,16 @@ pub enum LogEvent<'a> { /// zero-byte log and no way to reconstruct afterwards what had been /// deleted or how long it took. Purge { ts: String, doc_path: &'a str }, + /// A sweep candidate whose file is gone but whose purge failed. The + /// sweep logs it and moves on, so without this line the only trace is + /// a `tracing::warn` on stderr — and `sweep_summary`'s + /// `checked - purged` gap cannot tell a failure apart from a file + /// that is simply still on disk. + PurgeFailed { + ts: String, + doc_path: &'a str, + message: String, + }, /// Sweep phase totals, written once when the phase ends. SweepSummary { ts: String, diff --git a/crates/kebab-app/src/ingest_progress.rs b/crates/kebab-app/src/ingest_progress.rs index bd5c5bc..1a80622 100644 --- a/crates/kebab-app/src/ingest_progress.rs +++ b/crates/kebab-app/src/ingest_progress.rs @@ -47,6 +47,7 @@ pub struct AggregateCounts { /// /// ```text /// ScanStarted < ScanCompleted +/// [< SweepStarted < SweepProgress* < SweepCompleted] /// < ( AssetStarted /// [< (PdfOcrStarted < PdfOcrFinished)*] /// [< AssetChunked] @@ -55,7 +56,10 @@ pub struct AggregateCounts { /// < (Completed | Aborted) /// ``` /// -/// `[]` = optional. `PdfOcr*` is per-PDF asset only (v0.20.0 sub-item 1). +/// `[]` = optional. The `Sweep*` block (v0.32.1, issue #228) appears only +/// when the store holds paths this scan did not cover — a first ingest has +/// none, so it goes straight from `ScanCompleted` to the asset loop. +/// `PdfOcr*` is per-PDF asset only (v0.20.0 sub-item 1). /// `AssetChunked` / `AssetTimings` are the v0.24.0 asset-internal phase /// events: `AssetChunked` fires once right after chunking (markdown / /// image / PDF); `AssetTimings` reports per-phase wall-clock once @@ -136,14 +140,14 @@ pub enum IngestEvent { #[serde(default)] caption_ms: u64, }, - /// v0.33.0 (additive): the post-scan sweep for documents whose source + /// v0.32.1 (additive): the post-scan sweep for documents whose source /// file is gone is starting, with `total` stored paths to examine /// (paths still in the walker's scope are excluded — they are skipped /// by a set lookup and cost nothing). Issue #228: this phase used to /// emit nothing at all, so a progress bar sat frozen at `0/N` for the /// whole sweep and users read it as a hang and killed the run. SweepStarted { total: u32 }, - /// v0.33.0 (additive): the `idx`-th sweep candidate (1-based) has been + /// v0.32.1 (additive): the `idx`-th sweep candidate (1-based) has been /// examined. `removed` distinguishes "file really is gone, its document /// was purged" from "still on disk, left alone" — a sweep can walk /// thousands of candidates and purge none, and a bar that only moved @@ -156,7 +160,7 @@ pub enum IngestEvent { path: String, removed: bool, }, - /// v0.33.0 (additive): sweep finished. `checked` candidates examined, + /// v0.32.1 (additive): sweep finished. `checked` candidates examined, /// `purged` documents removed, `ms` wall-clock. SweepCompleted { checked: u32, purged: u32, ms: u64 }, /// Run finished normally. `counts` is the final aggregate. diff --git a/crates/kebab-app/tests/ingest_log_smoke.rs b/crates/kebab-app/tests/ingest_log_smoke.rs index d74e3b9..798e724 100644 --- a/crates/kebab-app/tests/ingest_log_smoke.rs +++ b/crates/kebab-app/tests/ingest_log_smoke.rs @@ -90,6 +90,7 @@ fn ingest_log_smoke() { "skip", "error", "purge", + "purge_failed", "sweep_summary", "summary", ]; diff --git a/crates/kebab-cli/src/progress.rs b/crates/kebab-cli/src/progress.rs index d715e6f..36a2fdb 100644 --- a/crates/kebab-cli/src/progress.rs +++ b/crates/kebab-cli/src/progress.rs @@ -87,6 +87,11 @@ pub struct ProgressDisplay { /// v0.26.1 slowest summary: (path, total_ms) per asset that reported /// `AssetTimings`. Sorted + truncated to top-N on `Completed`. timings: Vec<(String, u64)>, + /// Assets announced by `ScanCompleted`. Remembered because the sweep + /// phase (issue #228) repurposes the same bar with its own label and + /// its own, smaller total; without this the asset phase would keep + /// drawing `sweep [====] 16/3` after the sweep ended. + scan_total: u32, } impl ProgressDisplay { @@ -98,6 +103,7 @@ impl ProgressDisplay { current_path: None, asset_paths: HashMap::new(), timings: Vec::new(), + scan_total: 0, } } @@ -113,6 +119,58 @@ impl ProgressDisplay { Ok(()) } + /// Put the shared bar into asset-loop dress: the scan's total as the + /// length, position back to zero, and the `ingest [...]` template with + /// its per-asset elapsed key. + /// + /// Called twice — once when the scan finishes, and again when the + /// sweep phase ends, because the sweep borrows this same bar and + /// leaves its own label and its own (smaller) total behind. + fn dress_bar_for_assets(&mut self, tty: bool, quiet: bool) { + let Some(bar) = self.bar.as_mut() else { + return; + }; + // Style before length: indicatif can redraw between these calls, + // and a transitional frame that carries the right label with a + // stale count reads better than one labelled `sweep` with the + // asset count. + // v0.26.1: a custom `{asset_elapsed}` key reads the shared + // per-asset start `Instant` and appends ` (Ns)`. Combined + // with the steady tick below, the elapsed counter advances + // even while the drain loop is blocked on `recv()` waiting + // for the next (possibly very slow) phase event. + let asset_start = Arc::clone(&self.asset_start); + bar.set_style( + ProgressStyle::with_template("ingest [{bar:30}] {pos}/{len} {wide_msg}{asset_elapsed}") + .unwrap() + .with_key( + "asset_elapsed", + move |_: &ProgressState, w: &mut dyn std::fmt::Write| { + if let Ok(guard) = asset_start.lock() + && let Some(started) = *guard + { + let secs = started.elapsed().as_secs(); + // Only show once the asset has been running + // a moment — avoids `(0s)` flicker on fast + // assets. + if secs >= 1 { + let _ = write!(w, " ({secs}s)"); + } + } + }, + ) + .progress_chars("=> "), + ); + bar.set_length(u64::from(self.scan_total)); + bar.set_position(0); + bar.set_message(""); + if tty && !quiet { + bar.enable_steady_tick(std::time::Duration::from_secs(1)); + } else { + bar.disable_steady_tick(); + } + } + fn handle(&mut self, event: &IngestEvent) -> anyhow::Result<()> { match self.mode { ProgressMode::Json => emit_json(event), @@ -148,45 +206,8 @@ impl ProgressDisplay { } } IngestEvent::ScanCompleted { total } => { - if let Some(bar) = self.bar.as_mut() { - bar.set_length(u64::from(*total)); - bar.set_position(0); - // v0.26.1: a custom `{asset_elapsed}` key reads the shared - // per-asset start `Instant` and appends ` (Ns)`. Combined - // with the steady tick below, the elapsed counter advances - // even while the drain loop is blocked on `recv()` waiting - // for the next (possibly very slow) phase event. - let asset_start = Arc::clone(&self.asset_start); - bar.set_style( - ProgressStyle::with_template( - "ingest [{bar:30}] {pos}/{len} {wide_msg}{asset_elapsed}", - ) - .unwrap() - .with_key( - "asset_elapsed", - move |_: &ProgressState, w: &mut dyn std::fmt::Write| { - if let Ok(guard) = asset_start.lock() - && let Some(started) = *guard - { - let secs = started.elapsed().as_secs(); - // Only show once the asset has been running - // a moment — avoids `(0s)` flicker on fast - // assets. - if secs >= 1 { - let _ = write!(w, " ({secs}s)"); - } - } - }, - ) - .progress_chars("=> "), - ); - bar.set_message(""); - if tty && !quiet { - bar.enable_steady_tick(std::time::Duration::from_secs(1)); - } else { - bar.disable_steady_tick(); - } - } + self.scan_total = *total; + self.dress_bar_for_assets(tty, quiet); if !tty && !quiet { let mut err = std::io::stderr().lock(); let _ = writeln!(err, "ingest: scan complete ({total} assets)"); @@ -332,9 +353,16 @@ impl ProgressDisplay { } => { if let Some(bar) = self.bar.as_mut() { bar.set_position(u64::from(*idx)); - if *removed { - bar.set_message(abbreviate_path(path)); - } + // Named only while something is being removed. Left + // set, the last purged path would sit on the bar for + // however long the sweep spends walking candidates it + // does not touch — reading as "still working on that + // file" when that file is long gone. + bar.set_message(if *removed { + abbreviate_path(path) + } else { + String::new() + }); } // Non-TTY prints only the purges: one line per examined // candidate would bury the run's real output under paths @@ -349,9 +377,10 @@ impl ProgressDisplay { purged, ms, } => { - if let Some(bar) = self.bar.as_mut() { - bar.set_message(""); - } + // Hand the bar back to the asset loop. `AssetStarted` + // only sets a position and a message, so without this the + // rest of the run would draw `sweep [====] 16/3`. + self.dress_bar_for_assets(tty, quiet); // Printed even when nothing was purged: "checked 12115, // purged 0" is the answer to "what was it doing all that // time", which is what #228 was really about. diff --git a/docs/DOGFOOD.md b/docs/DOGFOOD.md index 0b54127..4f4b11c 100644 --- a/docs/DOGFOOD.md +++ b/docs/DOGFOOD.md @@ -267,12 +267,16 @@ echo "# stdin content" | "$RELEASE_BIN" ingest-stdin --title "from stdin" --conf ### §1.8 Ingest progress (wire `ingest_progress.v1`) **`--json` mode 의 ndjson stream**: -- `scan_started` → `scan_completed` → `(asset_started → [pdf_ocr_*]* → asset_finished)+` → `completed` | `aborted`. +- `scan_started` → `scan_completed` → `[sweep_started → sweep_progress* → sweep_completed]` → `(asset_started → [pdf_ocr_*]* → asset_finished)+` → `completed` | `aborted`. +- `sweep_*` (v0.32.1, issue #228) 는 스토어에 이번 스캔이 덮지 않은 경로가 있을 때만 나온다. 첫 ingest 에는 없다. **verify**: - ordering invariant (design §2.4a). - per-asset `idx/total/path/media/result/chunks`. - aggregate `counts` on `completed` / `aborted`. +- sweep 구간: `sweep_started.total` 이 후보 수와 맞고, `sweep_progress.idx` 가 1..=total 로 연속이며, `sweep_completed.checked == total`. +- sweep 이 끝난 뒤 진행바가 asset 분모·라벨로 돌아오는가 (TTY). sweep 이 같은 바를 빌려 쓰므로 복구가 빠지면 색인 구간 내내 `sweep [..] 4213/21` 로 그려진다. +- ndjson 로그에 `purge` 줄과 `sweep_summary` 가 남는가 (이슈 #228 이전에는 이 구간이 0바이트였다). --- diff --git a/docs/wire-schema/v1/ingest_progress.schema.json b/docs/wire-schema/v1/ingest_progress.schema.json index 9a124ae..d87d6a0 100644 --- a/docs/wire-schema/v1/ingest_progress.schema.json +++ b/docs/wire-schema/v1/ingest_progress.schema.json @@ -2,7 +2,7 @@ "$schema": "https://json-schema.org/draft/2020-12/schema", "$id": "https://kb.local/wire/v1/ingest_progress.schema.json", "title": "IngestProgressEvent v1", - "description": "Streaming progress event emitted by `kebab ingest --json`. One event per line (line-delimited JSON). Discriminated by `kind`. The terminal events are `completed` and `aborted` — every ingest run ends with exactly one of them. The final stdout line of a `--json` ingest is still the existing `ingest_report.v1` for backwards compatibility; progress events stream above it. `sweep_*` events (v0.33.0) cover the deleted-file sweep that runs between the scan and the asset loop; before them that phase emitted nothing and a long sweep was indistinguishable from a hang (issue #228).", + "description": "Streaming progress event emitted by `kebab ingest --json`. One event per line (line-delimited JSON). Discriminated by `kind`. The terminal events are `completed` and `aborted` — every ingest run ends with exactly one of them. The final stdout line of a `--json` ingest is still the existing `ingest_report.v1` for backwards compatibility; progress events stream above it. `sweep_*` events (v0.32.1) cover the deleted-file sweep that runs between the scan and the asset loop; before them that phase emitted nothing and a long sweep was indistinguishable from a hang (issue #228).", "type": "object", "required": [ "schema_version", diff --git a/tasks/HOTFIXES.md b/tasks/HOTFIXES.md index bcb6a89..70dd4c2 100644 --- a/tasks/HOTFIXES.md +++ b/tasks/HOTFIXES.md @@ -49,6 +49,14 @@ ingest: sweep complete (checked=21 purged=21 in 134ms) `--json` 은 `sweep_started` → `sweep_progress` × 21 → `sweep_completed` 를 `ingest_progress.v1` 로 내보내고, ndjson 로그에는 `purge` 21줄 + `sweep_summary` 1줄이 남는다. 이슈가 보고한 0바이트 로그가 아니다. +### 진행바를 빌려 쓸 때의 함정 + +리뷰에서 잡힌 것이다. sweep 은 asset 진행바를 그대로 빌려 쓰면서 자기 라벨과 자기(더 작은) 총계를 씌운다. 그런데 `AssetStarted` 는 위치와 메시지만 세팅하고 길이·스타일은 건드리지 않으므로, sweep 이 한 번 돌면 **그 뒤 색인 구간 전체가 `sweep [====] 4213/21` 로 그려진다**. 라벨도 분모도 틀린다. + +더 나쁜 건 스타일 교체가 v0.26.1 의 커스텀 키 `{asset_elapsed}` 를 같이 날린다는 점이다. 느린 asset 에서 `(Ns)` 가 도는 게 "멈춘 게 아님"의 유일한 신호인데, sweep 이 그걸 없애면 이 항목이 sweep 구간에서 없앤 "hang 처럼 보임" 을 asset 구간에 새로 만드는 셈이 된다. TTY 전용이라 비-TTY 실측만 보고 있었으면 놓쳤을 것이다. + +바 세팅을 `dress_bar_for_assets` 로 빼고 `ScanCompleted` 와 `SweepCompleted` 양쪽에서 부른다. 스타일을 길이보다 먼저 세팅하는데, indicatif 가 두 호출 사이에 다시 그릴 수 있어서 과도기 프레임이 최소한 올바른 라벨을 달게 하기 위해서다. + ### 범위 밖 이슈가 참고로 적은 `reset --orphans-only` 는 그대로 뒀다. reset 에는 진행 채널 자체가 없어서 sweep 하나를 위해 배선을 새로 깔아야 하는데, #229 와 #230 이 머지된 지금 이 경로의 문서당 비용이 약 800배 떨어져 "몇 시간 무표시" 상황이 애초에 안 나온다. 필요해지면 별 건으로 다룬다.