Merge pull request 'feat(app): #228 삭제 sweep 을 진행바·ndjson 로그에 노출' (#236) from feat/sweep-progress-events into main

This commit was merged in pull request #236.
This commit is contained in:
2026-08-16 13:08:23 +00:00
12 changed files with 990 additions and 100 deletions

View File

@@ -84,6 +84,10 @@ pub fn ingest(scope: SourceScope, opts: IngestOpts) -> anyhow::Result<IngestRepo
///
/// - The current in-flight asset finishes (rollback would break
/// idempotent re-run). Subsequent assets are skipped.
/// - The deleted-file sweep, which runs before the asset loop, checks
/// the same flag between candidates and stops at the next one
/// (issue #228). Documents it already purged stay purged, and the
/// buffered vector deletes are still flushed on the way out.
/// - Cancellation is a normal exit, not an error — `Result::Err` is
/// reserved for actual failures.
/// - Partial commits in SQLite are kept; the next `kebab ingest` run
@@ -298,6 +302,9 @@ pub fn ingest_with_config(
&app,
&scanned_paths,
vector_store.as_ref().map(std::convert::AsRef::as_ref),
progress,
log_writer.as_ref(),
&cancelled,
)?;
let started_at = time::OffsetDateTime::now_utc();
@@ -325,7 +332,14 @@ pub fn ingest_with_config(
// p9-fb-04: track whether the loop exited via cancellation (vs
// running to completion) so we can emit `Aborted` rather than
// `Completed` and surface the right summary.
let mut was_cancelled = false;
// Seeded from the flag rather than only from the asset loop: the loop
// body is what normally sets this, and it never runs when the scan
// found nothing. That is exactly the case where the sweep is largest
// — a scan of zero assets means every stored path is a sweep
// candidate — so "wipe the indexed directory, re-ingest, Ctrl-C
// during the long sweep" would otherwise end by reporting Completed
// to a user who cancelled.
let mut was_cancelled = cancelled();
for (zero_idx, asset) in assets.into_iter().enumerate() {
// Step boundary check (p9-fb-04). Designed §10 invariant: the
@@ -2121,14 +2135,18 @@ fn store_document_records(
///
/// Returns the number of documents purged.
///
/// Non-fatal design: individual purge failures are logged and counted
/// as errors on the per-file level but do NOT abort the sweep — a
/// partial failure is preferable to blocking the rest of ingest. The
/// return value only counts successful purges.
/// Non-fatal design: an individual purge failure is logged (tracing plus
/// a `purge_failed` ndjson line) and skipped, and does NOT abort the
/// sweep — a partial failure is preferable to blocking the rest of
/// ingest. It is not counted in `IngestReport.errors`, which tracks the
/// per-asset loop; the return value counts successful purges only.
fn sweep_deleted_files(
app: &App,
scanned_paths: &std::collections::HashSet<kebab_core::WorkspacePath>,
vector_store: Option<&kebab_store_vector::LanceVectorStore>,
progress: Option<&std::sync::mpsc::Sender<crate::ingest_progress::IngestEvent>>,
log_writer: Option<&Arc<Mutex<crate::ingest_log::IngestLogWriter>>>,
cancelled: &dyn Fn() -> bool,
) -> anyhow::Result<u32> {
use kebab_core::DocumentStore as _;
@@ -2141,6 +2159,25 @@ fn sweep_deleted_files(
return Ok(0);
}
// Narrow to the paths this sweep will actually stat before announcing
// a total, so the denominator the user sees is the work remaining —
// not the store's whole path list, most of which is normally in scope
// and dismissed by a set lookup. Issue #228 asked for exactly this
// (`all_workspace_paths` minus the scanned set).
let candidates: Vec<kebab_core::WorkspacePath> = stored_paths
.into_iter()
.filter(|p| !scanned_paths.contains(p))
.collect();
let total = u32::try_from(candidates.len()).unwrap_or(u32::MAX);
if candidates.is_empty() {
return Ok(0);
}
let sweep_started = std::time::Instant::now();
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepStarted { total },
);
let workspace_root = app.config.resolve_workspace_root();
let mut purged: u32 = 0;
// Vector deletes are batched instead of issued per file. Each
@@ -2158,11 +2195,19 @@ fn sweep_deleted_files(
// magnitude.
let mut doomed_chunk_ids: Vec<kebab_core::ChunkId> = Vec::new();
for stored_path in stored_paths {
if scanned_paths.contains(&stored_path) {
continue; // still in scope — skip
let mut examined: u32 = 0;
for (i, stored_path) in candidates.into_iter().enumerate() {
// The CLI's first Ctrl-C prints "aborting after current asset"
// and flips this flag. Before this check the sweep ignored it,
// so during a long sweep that message was simply untrue and the
// user's only recourse was a second Ctrl-C — which is `exit(130)`
// and strands whatever is buffered below. Issue #228 is literally
// a report of someone pressing Ctrl-C three times here.
if cancelled() {
break;
}
let idx = u32::try_from(i + 1).unwrap_or(u32::MAX);
examined = idx;
// Resolve to an absolute path and check existence on disk.
// Use `try_exists` + `unwrap_or(true)` so transient FS errors
// (EACCES on a path we lack read on, NFS hiccups, ownership
@@ -2181,6 +2226,15 @@ fn sweep_deleted_files(
path = %stored_path.0,
"sweep_deleted_files: file on disk but out of scope — leaving in store"
);
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepProgress {
idx,
total,
path: stored_path.0.clone(),
removed: false,
},
);
continue;
}
@@ -2195,6 +2249,24 @@ 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 {
idx,
total,
path: stored_path.0.clone(),
removed: false,
},
);
continue;
}
};
@@ -2212,12 +2284,52 @@ fn sweep_deleted_files(
"sweep_deleted_files: purged document for deleted file"
);
purged = purged.saturating_add(1);
if let Some(lw) = log_writer
&& let Ok(mut w) = lw.lock()
{
let _ = w.write_event(&crate::ingest_log::LogEvent::Purge {
ts: crate::ingest_log::now_ts(),
doc_path: &stored_path.0,
});
}
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepProgress {
idx,
total,
path: stored_path.0.clone(),
removed: true,
},
);
}
if let Some(vec) = vector_store {
flush_vector_deletes(vec, &mut doomed_chunk_ids, purged);
}
let ms = u64::try_from(sweep_started.elapsed().as_millis()).unwrap_or(u64::MAX);
if let Some(lw) = log_writer
&& let Ok(mut w) = lw.lock()
{
let _ = w.write_event(&crate::ingest_log::LogEvent::SweepSummary {
ts: crate::ingest_log::now_ts(),
checked: examined,
purged,
ms,
});
}
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepCompleted {
// The candidates actually examined, which is short of `total`
// when the run was cancelled mid-sweep. Reporting `total`
// there would claim work that did not happen.
checked: examined,
purged,
ms,
},
);
Ok(purged)
}

View File

@@ -152,6 +152,29 @@ pub enum LogEvent<'a> {
code: &'a str,
message: &'a str,
},
/// A document was removed because its source file is gone from disk
/// (the post-scan sweep). Issue #228: the sweep wrote nothing here,
/// so a run that spent most of its wall-clock purging left 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,
checked: u32,
purged: u32,
ms: u64,
},
}
/// Final summary record — always the last line of the log file.

View File

@@ -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,6 +140,31 @@ pub enum IngestEvent {
#[serde(default)]
caption_ms: u64,
},
/// 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.32.1 (additive): the `idx`-th sweep candidate (1-based) has been
/// examined. `removed` is true only when the file really was gone and
/// its document was purged; it is false both for a file still on disk
/// (left alone) and for a purge that failed. A sweep can walk
/// thousands of candidates and purge none, and a bar that only moved
/// on purges would look frozen in exactly that case. (Named `removed`
/// rather than `purged` so the wire key keeps one type: `purged` is
/// the integer total on `sweep_completed`.)
SweepProgress {
idx: u32,
total: u32,
path: String,
removed: bool,
},
/// v0.32.1 (additive): sweep finished. `checked` candidates examined,
/// `purged` documents removed, `ms` wall-clock. `checked` falls short
/// of the announced `total` when the run was cancelled mid-sweep.
SweepCompleted { checked: u32, purged: u32, ms: u64 },
/// Run finished normally. `counts` is the final aggregate.
Completed { counts: AggregateCounts },
/// Run finished by user cancellation. `counts` is the partial

View File

@@ -495,7 +495,7 @@ pub fn doctor_with_config_path(
// Opened, but the probe failed. Do not report this as
// health: a check whose whole point is to surface a silent
// failure must not swallow its own.
Some(None) | Some(Some((_, Err(_)))) => (
Some(None | Some((_, Err(_)))) => (
true,
"점검하지 못했다".to_string(),
Some(

View File

@@ -84,7 +84,16 @@ fn ingest_log_smoke() {
let lines: Vec<&str> = body.lines().collect();
assert!(!lines.is_empty(), "log file should not be empty");
let valid_kinds = ["ocr", "parse_error", "skip", "error", "summary"];
let valid_kinds = [
"ocr",
"parse_error",
"skip",
"error",
"purge",
"purge_failed",
"sweep_summary",
"summary",
];
for line in &lines {
let v: Value = serde_json::from_str(line)
.unwrap_or_else(|e| panic!("line is not valid JSON: {e}\nline: {line}"));
@@ -169,3 +178,81 @@ fn ingest_log_disabled_emits_no_file() {
"no ingest-*.ndjson file should be created when disabled"
);
}
/// Issue #228: the deleted-file sweep wrote nothing to the ndjson log, so
/// a run whose whole wall-clock went into purging left a zero-byte file
/// and no way to reconstruct afterwards what had been deleted. The log is
/// the only post-hoc record — tracing goes to stderr and is gone.
#[test]
fn ingest_log_records_the_deleted_file_sweep() {
let tmp = TempDir::new().unwrap();
let workspace = tmp.path().join("kb");
std::fs::create_dir_all(&workspace).unwrap();
let log_dir = tmp.path().join("logs");
let doomed = workspace.join("doomed.md");
std::fs::write(&doomed, "# doomed\n\nthis file is about to vanish\n").unwrap();
std::fs::write(workspace.join("kept.md"), "# kept\n\nthis one stays\n").unwrap();
let scope = SourceScope {
root: workspace.clone(),
include: vec!["**/*.md".to_string()],
exclude: Vec::new(),
};
ingest_with_config(
minimal_config(&workspace, &log_dir),
scope.clone(),
IngestOpts::default(),
)
.expect("first ingest should succeed");
std::fs::remove_file(&doomed).unwrap();
let report = ingest_with_config(
minimal_config(&workspace, &log_dir),
scope,
IngestOpts::default(),
)
.expect("second ingest should succeed");
assert_eq!(report.purged_deleted_files, 1);
// The second run's log is the later one; both runs write into log_dir.
let mut logs: Vec<PathBuf> = std::fs::read_dir(&log_dir)
.unwrap()
.filter_map(Result::ok)
.map(|e| e.path())
.filter(|p| p.extension().is_some_and(|x| x == "ndjson"))
.collect();
logs.sort();
let body = std::fs::read_to_string(logs.last().expect("a log per run")).unwrap();
let events: Vec<Value> = body
.lines()
.map(|l| serde_json::from_str(l).expect("each line is JSON"))
.collect();
let kind = |v: &Value| v.get("kind").and_then(Value::as_str).unwrap_or("").to_string();
let purges: Vec<&Value> = events.iter().filter(|v| kind(v) == "purge").collect();
assert_eq!(purges.len(), 1, "one purge line for the deleted file: {body}");
assert_eq!(
purges[0].get("doc_path").and_then(Value::as_str),
Some("doomed.md"),
"and it names which document went: {body}"
);
let sweep = events
.iter()
.find(|v| kind(v) == "sweep_summary")
.unwrap_or_else(|| panic!("the phase totals must be recorded: {body}"));
assert_eq!(sweep.get("purged").and_then(Value::as_u64), Some(1));
assert_eq!(
sweep.get("checked").and_then(Value::as_u64),
Some(1),
"one candidate examined: {body}"
);
assert!(
sweep.get("ms").is_some(),
"with a duration, which is what tells a user whether the phase was \
the run's bottleneck: {body}"
);
}

View File

@@ -0,0 +1,282 @@
//! Issue #228: the deleted-file sweep runs between the scan and the asset
//! loop and used to emit nothing at all — no progress events, no ndjson
//! log lines. A sweep that took 32 hours in dogfooding was externally
//! indistinguishable from a hang, and users killed the run three times in
//! a row. These tests pin the observability, not the purging (which
//! `file_deletion_auto_purge.rs` already covers).
mod common;
use std::sync::mpsc;
use common::TestEnv;
use kebab_app::{IngestEvent, IngestOpts, ingest_with_config};
use kebab_core::SourceScope;
/// Ingest whatever is in the workspace, collecting progress events.
fn ingest_collecting(env: &TestEnv) -> Vec<IngestEvent> {
let (tx, rx) = mpsc::channel::<IngestEvent>();
ingest_with_config(
env.config.clone(),
env.scope(),
IngestOpts {
progress: Some(tx),
..Default::default()
},
)
.expect("ingest must succeed");
let mut events = Vec::new();
while let Ok(ev) = rx.recv() {
events.push(ev);
}
events
}
fn sweep_bounds(events: &[IngestEvent]) -> (Option<u32>, Option<(u32, u32)>) {
let started = events.iter().find_map(|e| match e {
IngestEvent::SweepStarted { total } => Some(*total),
_ => None,
});
let completed = events.iter().find_map(|e| match e {
IngestEvent::SweepCompleted {
checked, purged, ..
} => Some((*checked, *purged)),
_ => None,
});
(started, completed)
}
#[test]
fn sweep_emits_a_bounded_phase_with_one_event_per_candidate() {
let env = TestEnv::lexical_only();
for i in 0..4 {
std::fs::write(
env.workspace_root.join(format!("gone{i}.rs")),
format!("// file {i}\nfn f{i}() {{}}\n"),
)
.unwrap();
}
let first = ingest_collecting(&env);
assert!(
matches!(sweep_bounds(&first), (None, None)),
"a first ingest has no stored paths outside its own scan, so there \
is no sweep phase to announce: {first:?}"
);
for i in 0..4 {
std::fs::remove_file(env.workspace_root.join(format!("gone{i}.rs"))).unwrap();
}
let second = ingest_collecting(&env);
let (total, done) = sweep_bounds(&second);
let total = total.expect("second ingest must announce the sweep phase");
let (checked, purged) = done.expect("and must announce its end");
assert_eq!(total, 4, "the four deleted files are the candidates");
assert_eq!(checked, total, "every announced candidate is examined");
assert_eq!(purged, 4, "all four are truly gone");
// A denominator is only useful if the numerator actually walks it.
let mut indices: Vec<u32> = second
.iter()
.filter_map(|e| match e {
IngestEvent::SweepProgress { idx, total: t, .. } => {
assert_eq!(*t, total, "every progress event carries the same total");
Some(*idx)
}
_ => None,
})
.collect();
indices.sort_unstable();
assert_eq!(
indices,
(1..=total).collect::<Vec<_>>(),
"one event per candidate, 1-based and contiguous: {second:?}"
);
// Ordering is what makes the phase legible: the bar has to be told the
// length before it is told a position.
let start_at = second
.iter()
.position(|e| matches!(e, IngestEvent::SweepStarted { .. }))
.unwrap();
let end_at = second
.iter()
.position(|e| matches!(e, IngestEvent::SweepCompleted { .. }))
.unwrap();
let first_progress = second
.iter()
.position(|e| matches!(e, IngestEvent::SweepProgress { .. }))
.unwrap();
assert!(
start_at < first_progress && first_progress < end_at,
"SweepStarted < SweepProgress* < SweepCompleted: {second:?}"
);
}
/// The reported case was a sweep that purged thousands of documents, but
/// the same silence happens when a narrowed `include` glob leaves stored
/// paths out of scope: the sweep still stats every one of them and purges
/// none. "checked 12115, purged 0" is precisely the answer the user was
/// missing, so a zero-purge sweep must still announce itself.
#[test]
fn a_sweep_that_purges_nothing_still_announces_itself() {
let env = TestEnv::lexical_only();
std::fs::write(
env.workspace_root.join("kept.rs"),
"// still here\nfn kept() {}\n",
)
.unwrap();
ingest_collecting(&env);
// Narrow the scan so the fixtures are stored but out of scope. They
// are still on disk, so the sweep must examine each and leave it alone.
let narrowed = SourceScope {
root: env.workspace_root.clone(),
include: vec!["kept.rs".to_string()],
exclude: env.config.workspace.exclude.clone(),
};
let (tx, rx) = mpsc::channel::<IngestEvent>();
ingest_with_config(
env.config.clone(),
narrowed,
IngestOpts {
progress: Some(tx),
..Default::default()
},
)
.expect("narrowed ingest must succeed");
let events: Vec<IngestEvent> = rx.into_iter().collect();
let (total, done) = sweep_bounds(&events);
let total = total.expect("the phase is announced even when it purges nothing");
let (checked, purged) = done.expect("and it reports its end");
assert!(total > 0, "the out-of-scope fixtures are candidates");
assert_eq!(checked, total);
assert_eq!(purged, 0, "nothing was deleted from disk: {events:?}");
assert!(
events
.iter()
.any(|e| matches!(e, IngestEvent::SweepProgress { removed: false, .. })),
"and the candidates it left alone are still reported: {events:?}"
);
}
/// The CLI's first Ctrl-C prints "aborting after current asset" and flips
/// the cancel flag. The sweep did not look at it, so during a long sweep
/// that message was simply untrue — and the user's only recourse was a
/// second Ctrl-C, which is `exit(130)` and strands whatever vector deletes
/// are buffered. Issue #228 is a report of someone pressing Ctrl-C three
/// times in exactly this phase.
#[test]
fn a_cancelled_sweep_stops_and_reports_only_what_it_examined() {
let env = TestEnv::lexical_only();
for i in 0..6 {
std::fs::write(
env.workspace_root.join(format!("bye{i}.rs")),
format!("// file {i}\nfn g{i}() {{}}\n"),
)
.unwrap();
}
ingest_collecting(&env);
for i in 0..6 {
std::fs::remove_file(env.workspace_root.join(format!("bye{i}.rs"))).unwrap();
}
// Pre-cancelled: the sweep must stop at the top of its first
// iteration rather than walk every candidate.
let cancel = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(true));
let (tx, rx) = mpsc::channel::<IngestEvent>();
let report = ingest_with_config(
env.config.clone(),
env.scope(),
IngestOpts {
progress: Some(tx),
cancel: Some(cancel),
..Default::default()
},
)
.expect("a cancelled ingest still returns a report");
let events: Vec<IngestEvent> = rx.into_iter().collect();
assert_eq!(
report.purged_deleted_files, 0,
"nothing is purged after the flag is already set: {report:?}"
);
let (total, done) = sweep_bounds(&events);
assert!(
total.expect("the phase is still announced") > 0,
"the candidates were counted before the check: {events:?}"
);
let (checked, purged) = done.expect("and it still reports its end");
assert_eq!(
(checked, purged),
(0, 0),
"a cancelled sweep must not claim work it did not do — reporting \
the announced total here would be a lie: {events:?}"
);
}
/// The scan finding nothing is the case where the sweep is largest —
/// zero assets means every stored path is a candidate. It is also the
/// case where the asset loop body never runs, and that body is what
/// normally records "this run was cancelled". So "wipe the indexed
/// directory, re-ingest, Ctrl-C during the long sweep" used to end by
/// telling the user the run had Completed.
#[test]
fn cancelling_a_sweep_with_nothing_left_to_scan_still_reports_aborted() {
let env = TestEnv::lexical_only();
std::fs::write(
env.workspace_root.join("temporary.rs"),
"// here for one ingest\nfn t() {}\n",
)
.unwrap();
ingest_collecting(&env);
// Empty the workspace, so the next scan finds no assets at all and
// every stored path becomes a sweep candidate. Recursive: the test
// fixtures sit in subdirectories, and leaving one behind gives the
// asset loop an iteration to run — which is precisely the iteration
// this test needs to not happen.
fn clear(dir: &std::path::Path) {
for entry in std::fs::read_dir(dir).unwrap() {
let p = entry.unwrap().path();
if p.is_dir() {
clear(&p);
} else {
std::fs::remove_file(p).unwrap();
}
}
}
clear(&env.workspace_root);
let cancel = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(true));
let (tx, rx) = mpsc::channel::<IngestEvent>();
ingest_with_config(
env.config.clone(),
env.scope(),
IngestOpts {
progress: Some(tx),
cancel: Some(cancel),
..Default::default()
},
)
.expect("a cancelled ingest still returns a report");
let events: Vec<IngestEvent> = rx.into_iter().collect();
assert!(
matches!(
events
.iter()
.find(|e| matches!(e, IngestEvent::ScanCompleted { .. })),
Some(IngestEvent::ScanCompleted { total: 0 })
),
"the premise: this run must find nothing to index, or the asset \
loop runs an iteration and records the cancel by itself: {events:?}"
);
assert!(
matches!(events.last(), Some(IngestEvent::Aborted { .. })),
"a cancelled run must end in Aborted even when the asset loop \
never ran a single iteration: {:?}",
events.last()
);
}

View File

@@ -746,7 +746,7 @@ mod tests {
}
_ => panic!("expected Page"),
}
assert!(c.policy_hash.len() == POLICY_HASH_HEX_LEN);
assert_eq!(c.policy_hash.len(), POLICY_HASH_HEX_LEN);
assert!(c.policy_hash.bytes().all(|b| b.is_ascii_hexdigit()));
}
}

View File

@@ -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)");
@@ -304,6 +325,74 @@ impl ProgressDisplay {
let _ = writeln!(err, " ⏱ {}", parts.join(" · "));
}
}
// Issue #228: the sweep runs between the scan and the asset
// loop and used to draw nothing, so the bar sat at `0/N` for
// the whole phase. It gets its own bar here rather than
// borrowing the asset bar's counter — a sweep of 12k
// candidates and an ingest of 12k assets are different work
// with different totals, and sharing one counter would make
// the second phase appear to restart.
IngestEvent::SweepStarted { total } => {
if let Some(bar) = self.bar.as_mut() {
bar.set_length(u64::from(*total));
bar.set_position(0);
bar.set_style(
ProgressStyle::with_template("sweep [{bar:30}] {pos}/{len} {wide_msg}")
.unwrap()
.progress_chars("=> "),
);
bar.set_message("");
}
if !tty && !quiet {
let mut err = std::io::stderr().lock();
let _ = writeln!(err, "ingest: sweeping {total} deleted-file candidates…");
}
}
IngestEvent::SweepProgress {
idx, path, removed, ..
} => {
if let Some(bar) = self.bar.as_mut() {
bar.set_position(u64::from(*idx));
// 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
// that were left exactly as they were.
if *removed && !tty && !quiet {
let mut err = std::io::stderr().lock();
let _ = writeln!(err, " purged {path}");
}
}
IngestEvent::SweepCompleted {
checked,
purged,
ms,
} => {
// 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.
if !quiet {
let mut err = std::io::stderr().lock();
let _ = writeln!(
err,
"ingest: sweep complete (checked={checked} purged={purged} in {})",
fmt_ms(*ms)
);
}
}
IngestEvent::Completed { counts } => {
if let Some(bar) = self.bar.take() {
bar.finish_and_clear();
@@ -458,6 +547,67 @@ pub(crate) fn now_rfc3339() -> anyhow::Result<String> {
mod tests {
use super::*;
/// The sweep phase (issue #228) borrows the asset bar and puts its
/// own, smaller total on it. If it does not hand the bar back, every
/// asset drawn afterwards carries the sweep's denominator — that
/// shipped once already, so it is pinned here.
///
/// Scope: length and position only. The same bug also dropped the
/// `{asset_elapsed}` heartbeat key along with the style, and
/// indicatif exposes no way to read a bar's style back, so that half
/// rests on `dress_bar_for_assets` being the single place either
/// phase dresses the bar.
#[test]
fn sweep_hands_the_bar_back_to_the_asset_loop() {
let mut d = ProgressDisplay::new(ProgressMode::Human {
tty: false,
quiet: true,
});
for e in [
IngestEvent::ScanStarted {
root: "/ws".to_string(),
},
IngestEvent::ScanCompleted { total: 17 },
IngestEvent::SweepStarted { total: 3 },
IngestEvent::SweepProgress {
idx: 3,
total: 3,
path: "gone.md".to_string(),
removed: true,
},
] {
d.handle(&e).expect("handle");
}
assert_eq!(
d.bar.as_ref().and_then(indicatif::ProgressBar::length),
Some(3),
"during the sweep the bar counts sweep candidates"
);
assert_eq!(
d.bar.as_ref().map(indicatif::ProgressBar::position),
Some(3),
"and tracks them"
);
d.handle(&IngestEvent::SweepCompleted {
checked: 3,
purged: 3,
ms: 12,
})
.expect("handle");
assert_eq!(
d.bar.as_ref().and_then(indicatif::ProgressBar::length),
Some(17),
"once the sweep ends the bar counts assets again"
);
assert_eq!(
d.bar.as_ref().map(indicatif::ProgressBar::position),
Some(0),
"from the start — leaving the sweep's position would make the \
asset loop look part-done before it began"
);
}
#[test]
fn from_flags_json_takes_priority_over_tty() {
assert_eq!(

View File

@@ -184,14 +184,8 @@ fn extract_fn_name<'a>(decl_node: tree_sitter::Node, src: &'a str) -> Option<&'a
// pointer_declarator, function_declarator, array_declarator,
// attributed_declarator, parenthesized_declarator —
// all carry a `declarator` field pointing deeper.
_ => {
if let Some(inner) = cur.child_by_field_name("declarator") {
cur = inner;
} else {
// No further `declarator` field; give up.
return None;
}
}
// No further `declarator` field to follow; give up.
_ => cur = cur.child_by_field_name("declarator")?,
}
}
}

View File

@@ -267,12 +267,17 @@ 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바이트였다). purge 실패 시 `purge_failed`.
- sweep 중 Ctrl-C 한 번에 실제로 멈추는가. `sweep_completed.checked` 가 예고한 `total` 이 아니라 실제 검사한 수로 나와야 한다.
---

View File

@@ -2,11 +2,17 @@
"$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.",
"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", "kind", "ts"],
"required": [
"schema_version",
"kind",
"ts"
],
"properties": {
"schema_version": { "const": "ingest_progress.v1" },
"schema_version": {
"const": "ingest_progress.v1"
},
"kind": {
"type": "string",
"enum": [
@@ -21,53 +27,200 @@
"embed_batch_finished",
"pdf_ocr_started",
"pdf_ocr_finished",
"sweep_started",
"sweep_progress",
"sweep_completed",
"completed",
"aborted"
]
},
"ts": { "type": "string", "format": "date-time", "description": "RFC 3339 timestamp at the moment the event was emitted." },
"root": { "type": "string", "description": "scan_started: workspace root being walked." },
"total": { "type": "integer", "minimum": 0, "description": "scan_completed / asset_started / asset_finished: total assets discovered." },
"idx": { "type": "integer", "minimum": 1, "description": "asset_started / asset_finished: 1-based index of the current asset within the scan." },
"path": { "type": "string", "description": "asset_started: workspace-relative path of the asset being processed." },
"media": { "type": "string", "description": "asset_started: media kind label (e.g. `markdown`, `pdf`, `image`)." },
"result": {
"ts": {
"type": "string",
"enum": ["new", "updated", "skipped", "error"],
"format": "date-time",
"description": "RFC 3339 timestamp at the moment the event was emitted."
},
"root": {
"type": "string",
"description": "scan_started: workspace root being walked."
},
"total": {
"type": "integer",
"minimum": 0,
"description": "scan_completed / asset_started / asset_finished: total assets discovered. sweep_started / sweep_progress: total stored paths the deleted-file sweep will examine (the store's paths minus the ones this scan covered)."
},
"idx": {
"type": "integer",
"minimum": 1,
"description": "asset_started / asset_finished: 1-based index of the current asset within the scan. sweep_progress: 1-based index of the current sweep candidate."
},
"path": {
"type": "string",
"description": "asset_started: workspace-relative path of the asset being processed. sweep_progress: workspace path of the candidate examined."
},
"media": {
"type": "string",
"description": "asset_started: media kind label (e.g. `markdown`, `pdf`, `image`)."
},
"result": {
"type": "string",
"enum": [
"new",
"updated",
"skipped",
"error"
],
"description": "asset_finished: per-asset outcome (mirrors `ingest_report.v1.items[].kind`)."
},
"chunks": { "type": "integer", "minimum": 0, "description": "asset_finished / asset_chunked (v0.24.0): chunk count produced for this asset." },
"phase": { "type": "string", "enum": ["ocr", "caption", "embed"], "description": "asset_phase (v0.26.1): the slow internal phase the asset just entered. Short phases (parse/chunk/store) are not emitted." },
"model": { "type": ["string", "null"], "description": "asset_phase (v0.26.1): model performing the phase — vision LLM id for ocr/caption, embedder model_id for embed. null when the phase runs without a configured model." },
"parse_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): parse phase wall-clock (ms). Emitted by markdown / image / PDF paths." },
"chunk_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): chunk phase wall-clock (ms). Emitted by markdown / image / PDF paths." },
"expansion_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): retained for wire compatibility but always 0 — doc-side expansion was removed (HOTFIXES 2026-06-03)." },
"embed_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): embed + vector phase wall-clock (ms) — embedding, vector upsert, and stale-vector purge." },
"store_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): SQLite persist phase wall-clock (ms) — put_asset/document/blocks/chunks only." },
"ocr_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.26.1, additive, default 0): image/PDF OCR phase wall-clock (ms). 0 on the markdown path (no OCR)." },
"caption_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.26.1, additive, default 0): image caption phase wall-clock (ms). 0 on markdown / PDF paths." },
"n_chunks": { "type": "integer", "minimum": 0, "description": "embed_batch_started / embed_batch_finished: chunks in this embedding batch." },
"ms": { "type": "integer", "minimum": 0, "description": "embed_batch_finished / pdf_ocr_finished: wall-clock duration (ms). pdf_ocr_finished skip path 의 의미는 mixed (DCTDecode 부재 시 0, engine 실패 시 latency-before-bail)." },
"chars": { "type": "integer", "minimum": 0, "description": "pdf_ocr_finished: char count of OCR result. Skip 시 0." },
"page": { "type": "integer", "minimum": 1, "description": "pdf_ocr_started / pdf_ocr_finished: 1-based PDF page number under OCR." },
"ocr_engine": { "type": "string", "description": "pdf_ocr_finished: engine_name (e.g. 'ollama-vision')." },
"skipped": { "type": "boolean", "description": "pdf_ocr_finished: true 일 시 OCR 미수행 (DCTDecode 부재 또는 engine 실패). chars=0 만으로는 skip 과 0-char result 구분 불가." },
"image_byte_size": { "type": "integer", "minimum": 0, "description": "pdf_ocr_finished (optional, v0.20.x): raster image byte size." },
"image_width": { "type": "integer", "minimum": 0, "description": "pdf_ocr_finished (optional, v0.20.x): raster image width px." },
"image_height": { "type": "integer", "minimum": 0, "description": "pdf_ocr_finished (optional, v0.20.x): raster image height px." },
"failure_reason": { "type": "string", "description": "pdf_ocr_finished (optional, v0.20.x): OCR failure reason. Present iff skipped=true due to engine error. Values: timeout | ocr_error | network_error | other." },
"counts": {
"chunks": {
"type": "integer",
"minimum": 0,
"description": "asset_finished / asset_chunked (v0.24.0): chunk count produced for this asset."
},
"phase": {
"type": "string",
"enum": [
"ocr",
"caption",
"embed"
],
"description": "asset_phase (v0.26.1): the slow internal phase the asset just entered. Short phases (parse/chunk/store) are not emitted."
},
"model": {
"type": [
"string",
"null"
],
"description": "asset_phase (v0.26.1): model performing the phase — vision LLM id for ocr/caption, embedder model_id for embed. null when the phase runs without a configured model."
},
"parse_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.24.0, additive): parse phase wall-clock (ms). Emitted by markdown / image / PDF paths."
},
"chunk_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.24.0, additive): chunk phase wall-clock (ms). Emitted by markdown / image / PDF paths."
},
"expansion_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.24.0, additive): retained for wire compatibility but always 0 — doc-side expansion was removed (HOTFIXES 2026-06-03)."
},
"embed_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.24.0, additive): embed + vector phase wall-clock (ms) — embedding, vector upsert, and stale-vector purge."
},
"store_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.24.0, additive): SQLite persist phase wall-clock (ms) — put_asset/document/blocks/chunks only."
},
"ocr_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.26.1, additive, default 0): image/PDF OCR phase wall-clock (ms). 0 on the markdown path (no OCR)."
},
"caption_ms": {
"type": "integer",
"minimum": 0,
"description": "asset_timings (v0.26.1, additive, default 0): image caption phase wall-clock (ms). 0 on markdown / PDF paths."
},
"n_chunks": {
"type": "integer",
"minimum": 0,
"description": "embed_batch_started / embed_batch_finished: chunks in this embedding batch."
},
"ms": {
"type": "integer",
"minimum": 0,
"description": "embed_batch_finished / pdf_ocr_finished: wall-clock duration (ms). pdf_ocr_finished skip path 의 의미는 mixed (DCTDecode 부재 시 0, engine 실패 시 latency-before-bail). sweep_completed: wall-clock of the whole sweep phase."
},
"chars": {
"type": "integer",
"minimum": 0,
"description": "pdf_ocr_finished: char count of OCR result. Skip 시 0."
},
"page": {
"type": "integer",
"minimum": 1,
"description": "pdf_ocr_started / pdf_ocr_finished: 1-based PDF page number under OCR."
},
"ocr_engine": {
"type": "string",
"description": "pdf_ocr_finished: engine_name (e.g. 'ollama-vision')."
},
"skipped": {
"type": "boolean",
"description": "pdf_ocr_finished: true 일 시 OCR 미수행 (DCTDecode 부재 또는 engine 실패). chars=0 만으로는 skip 과 0-char result 구분 불가."
},
"image_byte_size": {
"type": "integer",
"minimum": 0,
"description": "pdf_ocr_finished (optional, v0.20.x): raster image byte size."
},
"image_width": {
"type": "integer",
"minimum": 0,
"description": "pdf_ocr_finished (optional, v0.20.x): raster image width px."
},
"image_height": {
"type": "integer",
"minimum": 0,
"description": "pdf_ocr_finished (optional, v0.20.x): raster image height px."
},
"failure_reason": {
"type": "string",
"description": "pdf_ocr_finished (optional, v0.20.x): OCR failure reason. Present iff skipped=true due to engine error. Values: timeout | ocr_error | network_error | other."
},
"counts": {
"type": "object",
"description": "completed / aborted: aggregate counters at the moment the run ended (mirrors fields on `ingest_report.v1`).",
"properties": {
"scanned": { "type": "integer", "minimum": 0 },
"new": { "type": "integer", "minimum": 0 },
"updated": { "type": "integer", "minimum": 0 },
"skipped": { "type": "integer", "minimum": 0 },
"errors": { "type": "integer", "minimum": 0 },
"chunks_indexed": { "type": "integer", "minimum": 0 },
"embeddings_indexed": { "type": "integer", "minimum": 0 }
"scanned": {
"type": "integer",
"minimum": 0
},
"new": {
"type": "integer",
"minimum": 0
},
"updated": {
"type": "integer",
"minimum": 0
},
"skipped": {
"type": "integer",
"minimum": 0
},
"errors": {
"type": "integer",
"minimum": 0
},
"chunks_indexed": {
"type": "integer",
"minimum": 0
},
"embeddings_indexed": {
"type": "integer",
"minimum": 0
}
}
},
"removed": {
"type": "boolean",
"description": "sweep_progress: true when the file was truly absent and its document was purged; false when it is still on disk (left untouched) or the purge failed."
},
"checked": {
"type": "integer",
"minimum": 0,
"description": "sweep_completed: sweep candidates examined."
},
"purged": {
"type": "integer",
"minimum": 0,
"description": "sweep_completed: documents removed because their source file is gone."
}
}
}

View File

@@ -14,6 +14,61 @@ historical contract that was implemented; this file accumulates the
deltas so phase 5+ readers can find the live behavior without diffing
git history.
## 2026-08-16 — #228 sweep 구간이 진행바·로그에 표시되지 않음
### 무엇이 문제였나
`sweep_deleted_files` 는 walker 가 끝난 직후, asset 루프가 시작되기 전에 돈다. 이 구간이 **관측 가능한 신호를 하나도 내지 않았다**. 진행바는 walker 총계(`0/12115`)를 표시한 채 멈춰 보이고, ndjson 로그는 0바이트로 남는다. `tracing::info!` 은 나가지만 wire 이벤트가 아니라 사용자가 볼 산출물이 없다.
프로세스는 CPU 100% 로 정상 동작 중인데 밖에서는 hang 과 구별할 수 없다. 실제 도그푸딩에서 세 번 연속 Ctrl-C 로 죽였다.
### 무엇을 고쳤나
`ingest_progress.v1` 에 세 이벤트를 **추가**했다 (additive — 기존 소비자는 모르는 kind 를 무시한다).
- `sweep_started { total }` — 검사할 후보 수. `all_workspace_paths()` 에서 이번 스캔이 덮은 경로를 뺀 값이라 루프 진입 전에 확정 분모가 나온다. 이슈 제안 1 그대로다.
- `sweep_progress { idx, total, path, removed }` — 후보 하나를 검사할 때마다. `removed` 는 "정말 없어서 문서를 지웠다" 와 "아직 디스크에 있어서 그대로 뒀다" 를 가른다. 수천 건을 훑고 하나도 안 지우는 sweep 이 있으므로, 지울 때만 움직이는 진행바는 바로 그 경우에 다시 멈춰 보인다.
- `sweep_completed { checked, purged, ms }` — 구간 총계.
`purged` 를 두 이벤트에서 다른 타입으로 쓰지 않으려고 `sweep_progress` 쪽은 `removed`(bool) 로, `sweep_completed` 쪽은 `purged`(정수) 로 이름을 나눴다. 같은 wire 키가 두 타입을 갖는 건 소비자 입장에서 함정이다.
ndjson 로그에는 `purge { ts, doc_path }``sweep_summary { ts, checked, purged, ms }` 를 추가했다. 이슈 제안 2 가 요청한 형태 그대로다. 로그가 유일한 사후 기록이다 — tracing 은 stderr 로 흘러가고 남지 않는다. 리뷰 지적을 받아 `purge_failed { ts, doc_path, message }` 도 넣었다. 실패는 진행 이벤트에서 "디스크에 남아 있어 그냥 뒀다" 와 똑같이 `removed: false` 로 나가고, `sweep_summary``checked - purged` 차이로도 못 가르기 때문이다.
sweep 루프가 취소 플래그도 본다. CLI 의 첫 Ctrl-C 는 "aborting after current asset" 을 찍고 플래그를 세우는데, sweep 은 그걸 보지 않아서 **긴 sweep 중에는 그 안내가 사실이 아니었다**. 사용자에게 남은 수단은 두 번째 Ctrl-C 뿐이고 그건 `exit(130)` 이라 버퍼에 쌓인 벡터 삭제가 고아로 남는다. 이 이슈 자체가 "sweep 중 Ctrl-C 를 세 번 눌러 죽였다" 는 보고다. 취소로 중단하면 `checked` 는 실제로 검사한 수로 나간다 — 예고한 `total` 을 그대로 쓰면 하지 않은 일을 했다고 보고하는 셈이다.
CLI 는 sweep 을 asset 진행바와 **별 phase** 로 그린다. 후보 12k 를 훑는 일과 asset 12k 를 색인하는 일은 분모가 다른 별개의 작업이라, 카운터를 공유하면 두 번째 구간이 처음부터 다시 시작하는 것처럼 보인다. 비-TTY 는 실제로 지운 것만 줄로 찍는다 — 검사한 후보마다 한 줄이면 그대로 둔 경로들이 run 의 진짜 출력을 덮는다.
### 실측
문서 30건을 색인하고 21건을 지운 뒤 재색인:
```
ingest: sweeping 21 deleted-file candidates…
purged doc11.md
… (21줄)
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배 떨어져 "몇 시간 무표시" 상황이 애초에 안 나온다. 필요해지면 별 건으로 다룬다.
### 곁다리: clippy 게이트가 붉었다
`cargo clippy --workspace --all-targets -- -D warnings` 가 main 에서 실패하고 있었다. 툴체인이 올라가면서 새 lint 두 개(`question_mark`, `manual_assert_eq`)가 기존 코드에 걸린 것이다. 각각 한 줄이라 여기서 같이 고쳤다.
방치하면 안 되는 이유를 이번에 겪었다. `kebab-parse-code` 가 먼저 실패해서 뒤 크레이트가 아예 컴파일되지 않았고, 그 그늘에 **PR #235 에서 내가 넣은 `unnested_or_patterns` 위반**이 숨어 있었다. 게이트가 붉으면 새 위반이 안 보인다.
## 2026-08-16 — #229 chunks_fts 삭제가 FTS5 전체 스캔 (V016)
### 무엇이 문제였나