chore: PR #236 회차 1 리뷰 반영 — sweep 뒤 진행바 복구

리뷰 두 건에서 나온 지적을 반영한다.

1) sweep 이 끝나도 asset 진행바가 복구되지 않았다 (HIGH)

   sweep 은 asset 진행바를 빌려 쓰면서 자기 라벨과 자기(더 작은) 총계를
   씌운다. 그런데 `AssetStarted` 는 위치와 메시지만 세팅하고 길이·스타일은
   건드리지 않는다. 그래서 sweep 이 한 번 돌면 그 뒤 색인 구간 전체가
   `sweep [====] 4213/21` 로 그려졌다 — 라벨도 분모도 틀린다.

   더 나쁜 건 스타일 교체가 v0.26.1 의 커스텀 키 `{asset_elapsed}` 를 같이
   날린다는 점이다. 느린 asset 에서 `(Ns)` 가 도는 게 "멈춘 게 아님"의 유일한
   신호인데 sweep 이 그걸 없앤다. 이 PR 이 sweep 구간에서 없앤 "hang 처럼
   보임" 을 asset 구간에 새로 만드는 셈이었다.

   바 세팅을 `dress_bar_for_assets` 로 빼고 `ScanCompleted` 와
   `SweepCompleted` 양쪽에서 부른다. 스타일을 길이보다 먼저 세팅하는데,
   indicatif 가 두 호출 사이에 다시 그릴 수 있어 과도기 프레임이 최소한
   올바른 라벨을 달게 하기 위해서다.

   TTY 전용이라 비-TTY 실측만 보고 있어서 놓쳤다. pty 로 재현해 고친 뒤
   `ingest [====] 16/17 doc9.md` 로 나오는 것을 확인했다.

2) docs/DOGFOOD.md §1.8 이 갱신되지 않았다 (MEDIUM)

   `--json` 이벤트 순서 목록에 sweep 3종이 빠져 있었다. verify 항목에
   sweep 분모·연속성과 "sweep 뒤 진행바가 asset 분모로 돌아오는가" 를 넣었다
   — 1번이 정확히 그 항목이 있었으면 잡혔을 결함이다.

3) ingest_progress.rs 의 ordering invariant 주석이 stale 했다 (MEDIUM)

   §2.4a 순서 블록에 sweep 이 없었다. 설계 문서 자체는 frozen baseline 이고
   HOTFIXES dated entry 가 있으니 규약상 문제없지만 코드 주석은 living 이다.

4) 잔가지 (LOW)

   - purge 실패가 "디스크에 남아 있어 그냥 뒀다" 와 구분되지 않았다. 둘 다
     `removed: false` 이고 ndjson 에는 아무것도 안 남아,
     `sweep_summary` 의 `checked - purged` 차이로도 못 가른다. 사후 기록이
     로그뿐이라는 게 이 PR 의 전제이므로 `purge_failed` 를 추가했다.
   - `SweepProgress` 가 purge 할 때만 바 메시지를 세팅하고 비우지 않아,
     마지막 purge 경로가 이후 후보를 훑는 내내 남았다. 안 지울 때는 비운다.
   - 주석과 스키마가 신규 이벤트를 `v0.33.0` 이라고 적었는데, CLAUDE.md 의
     bump 규칙상 이 변경은 patch 다 (additive-only wire + 관측성 개선, 새
     명령·플래그·config 없음, 검색·색인 결과 불변 — 선례가 asset_phase).
     `v0.32.1` 로 고쳤다.

미반영: `SweepCompleted` 가 TTY 에서 `bar.println` 대신 stderr 에 직접
쓰는 것 — 기존 `AssetTimings`/`PdfOcr*` 이 같은 패턴이라 신규 회귀가 아니고,
바꾸려면 그 셋을 같이 옮겨야 해서 별 건이다.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_017c9JwQq8ZkGvYjpKXMiDhF
This commit is contained in:
2026-08-16 21:18:15 +09:00
parent 1626a40a28
commit 2c2cbd2b94
8 changed files with 116 additions and 51 deletions

View File

@@ -2224,6 +2224,15 @@ fn sweep_deleted_files(
error = %e, error = %e,
"sweep_deleted_files: purge failed; skipping this path" "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( crate::ingest_progress::emit(
progress, progress,
crate::ingest_progress::IngestEvent::SweepProgress { crate::ingest_progress::IngestEvent::SweepProgress {

View File

@@ -158,6 +158,16 @@ pub enum LogEvent<'a> {
/// zero-byte log and no way to reconstruct afterwards what had been /// zero-byte log and no way to reconstruct afterwards what had been
/// deleted or how long it took. /// deleted or how long it took.
Purge { ts: String, doc_path: &'a str }, 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. /// Sweep phase totals, written once when the phase ends.
SweepSummary { SweepSummary {
ts: String, ts: String,

View File

@@ -47,6 +47,7 @@ pub struct AggregateCounts {
/// ///
/// ```text /// ```text
/// ScanStarted < ScanCompleted /// ScanStarted < ScanCompleted
/// [< SweepStarted < SweepProgress* < SweepCompleted]
/// < ( AssetStarted /// < ( AssetStarted
/// [< (PdfOcrStarted < PdfOcrFinished)*] /// [< (PdfOcrStarted < PdfOcrFinished)*]
/// [< AssetChunked] /// [< AssetChunked]
@@ -55,7 +56,10 @@ pub struct AggregateCounts {
/// < (Completed | Aborted) /// < (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 /// `AssetChunked` / `AssetTimings` are the v0.24.0 asset-internal phase
/// events: `AssetChunked` fires once right after chunking (markdown / /// events: `AssetChunked` fires once right after chunking (markdown /
/// image / PDF); `AssetTimings` reports per-phase wall-clock once /// image / PDF); `AssetTimings` reports per-phase wall-clock once
@@ -136,14 +140,14 @@ pub enum IngestEvent {
#[serde(default)] #[serde(default)]
caption_ms: u64, 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 /// file is gone is starting, with `total` stored paths to examine
/// (paths still in the walker's scope are excluded — they are skipped /// (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 /// 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 /// 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. /// whole sweep and users read it as a hang and killed the run.
SweepStarted { total: u32 }, 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 /// examined. `removed` distinguishes "file really is gone, its document
/// was purged" from "still on disk, left alone" — a sweep can walk /// was purged" from "still on disk, left alone" — a sweep can walk
/// thousands of candidates and purge none, and a bar that only moved /// thousands of candidates and purge none, and a bar that only moved
@@ -156,7 +160,7 @@ pub enum IngestEvent {
path: String, path: String,
removed: bool, 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. /// `purged` documents removed, `ms` wall-clock.
SweepCompleted { checked: u32, purged: u32, ms: u64 }, SweepCompleted { checked: u32, purged: u32, ms: u64 },
/// Run finished normally. `counts` is the final aggregate. /// Run finished normally. `counts` is the final aggregate.

View File

@@ -90,6 +90,7 @@ fn ingest_log_smoke() {
"skip", "skip",
"error", "error",
"purge", "purge",
"purge_failed",
"sweep_summary", "sweep_summary",
"summary", "summary",
]; ];

View File

@@ -87,6 +87,11 @@ pub struct ProgressDisplay {
/// v0.26.1 slowest summary: (path, total_ms) per asset that reported /// v0.26.1 slowest summary: (path, total_ms) per asset that reported
/// `AssetTimings`. Sorted + truncated to top-N on `Completed`. /// `AssetTimings`. Sorted + truncated to top-N on `Completed`.
timings: Vec<(String, u64)>, 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 { impl ProgressDisplay {
@@ -98,6 +103,7 @@ impl ProgressDisplay {
current_path: None, current_path: None,
asset_paths: HashMap::new(), asset_paths: HashMap::new(),
timings: Vec::new(), timings: Vec::new(),
scan_total: 0,
} }
} }
@@ -113,6 +119,58 @@ impl ProgressDisplay {
Ok(()) 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<()> { fn handle(&mut self, event: &IngestEvent) -> anyhow::Result<()> {
match self.mode { match self.mode {
ProgressMode::Json => emit_json(event), ProgressMode::Json => emit_json(event),
@@ -148,45 +206,8 @@ impl ProgressDisplay {
} }
} }
IngestEvent::ScanCompleted { total } => { IngestEvent::ScanCompleted { total } => {
if let Some(bar) = self.bar.as_mut() { self.scan_total = *total;
bar.set_length(u64::from(*total)); self.dress_bar_for_assets(tty, quiet);
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();
}
}
if !tty && !quiet { if !tty && !quiet {
let mut err = std::io::stderr().lock(); let mut err = std::io::stderr().lock();
let _ = writeln!(err, "ingest: scan complete ({total} assets)"); let _ = writeln!(err, "ingest: scan complete ({total} assets)");
@@ -332,9 +353,16 @@ impl ProgressDisplay {
} => { } => {
if let Some(bar) = self.bar.as_mut() { if let Some(bar) = self.bar.as_mut() {
bar.set_position(u64::from(*idx)); bar.set_position(u64::from(*idx));
if *removed { // Named only while something is being removed. Left
bar.set_message(abbreviate_path(path)); // 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 // Non-TTY prints only the purges: one line per examined
// candidate would bury the run's real output under paths // candidate would bury the run's real output under paths
@@ -349,9 +377,10 @@ impl ProgressDisplay {
purged, purged,
ms, ms,
} => { } => {
if let Some(bar) = self.bar.as_mut() { // Hand the bar back to the asset loop. `AssetStarted`
bar.set_message(""); // 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, // Printed even when nothing was purged: "checked 12115,
// purged 0" is the answer to "what was it doing all that // purged 0" is the answer to "what was it doing all that
// time", which is what #228 was really about. // time", which is what #228 was really about.

View File

@@ -267,12 +267,16 @@ echo "# stdin content" | "$RELEASE_BIN" ingest-stdin --title "from stdin" --conf
### §1.8 Ingest progress (wire `ingest_progress.v1`) ### §1.8 Ingest progress (wire `ingest_progress.v1`)
**`--json` mode 의 ndjson stream**: **`--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**: **verify**:
- ordering invariant (design §2.4a). - ordering invariant (design §2.4a).
- per-asset `idx/total/path/media/result/chunks`. - per-asset `idx/total/path/media/result/chunks`.
- aggregate `counts` on `completed` / `aborted`. - 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바이트였다).
--- ---

View File

@@ -2,7 +2,7 @@
"$schema": "https://json-schema.org/draft/2020-12/schema", "$schema": "https://json-schema.org/draft/2020-12/schema",
"$id": "https://kb.local/wire/v1/ingest_progress.schema.json", "$id": "https://kb.local/wire/v1/ingest_progress.schema.json",
"title": "IngestProgressEvent v1", "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", "type": "object",
"required": [ "required": [
"schema_version", "schema_version",

View File

@@ -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바이트 로그가 아니다. `--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배 떨어져 "몇 시간 무표시" 상황이 애초에 안 나온다. 필요해지면 별 건으로 다룬다. 이슈가 참고로 적은 `reset --orphans-only` 는 그대로 뒀다. reset 에는 진행 채널 자체가 없어서 sweep 하나를 위해 배선을 새로 깔아야 하는데, #229#230 이 머지된 지금 이 경로의 문서당 비용이 약 800배 떨어져 "몇 시간 무표시" 상황이 애초에 안 나온다. 필요해지면 별 건으로 다룬다.