feat(app): #228 삭제 sweep 을 진행바·ndjson 로그에 노출

`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 }
  sweep_progress  { idx, total, path, removed }
  sweep_completed { checked, purged, ms }

`total` 은 `all_workspace_paths()` 에서 이번 스캔이 덮은 경로를 뺀 값이라
루프 진입 전에 확정 분모가 나온다 (이슈 제안 1). `removed` 는 "정말 없어서
문서를 지웠다" 와 "아직 디스크에 있어 그대로 뒀다" 를 가른다 — 수천 건을
훑고 하나도 안 지우는 sweep 이 있으므로, 지울 때만 움직이는 진행바는 바로
그 경우에 다시 멈춰 보인다.

`purged` 를 두 이벤트에서 다른 타입으로 쓰지 않으려고 sweep_progress 쪽은
`removed`(bool), sweep_completed 쪽은 `purged`(정수) 로 이름을 나눴다.
같은 wire 키가 두 타입을 갖는 건 소비자 입장에서 함정이다.

ndjson 로그에는 `purge { ts, doc_path }` 와 `sweep_summary { ts, checked,
purged, ms }` 를 추가한다 (이슈 제안 2 가 요청한 형태). 로그가 유일한 사후
기록이다 — tracing 은 stderr 로 흘러가고 남지 않는다.

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` 은 세 이벤트를 ingest_progress.v1 로 내보내고, ndjson 로그에는
purge 21줄 + sweep_summary 1줄이 남는다.

이슈가 참고로 적은 `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` 위반이 숨어 있었다. 셋 다 여기서 고친다.

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 20:57:34 +09:00
parent 2cbac4d4e8
commit 1626a40a28
11 changed files with 666 additions and 55 deletions

View File

@@ -298,6 +298,8 @@ pub fn ingest_with_config(
&app,
&scanned_paths,
vector_store.as_ref().map(std::convert::AsRef::as_ref),
progress,
log_writer.as_ref(),
)?;
let started_at = time::OffsetDateTime::now_utc();
@@ -2129,6 +2131,8 @@ 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>>>,
) -> anyhow::Result<u32> {
use kebab_core::DocumentStore as _;
@@ -2141,6 +2145,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 +2181,8 @@ 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
}
for (i, stored_path) in candidates.into_iter().enumerate() {
let idx = u32::try_from(i + 1).unwrap_or(u32::MAX);
// 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 +2201,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 +2224,15 @@ fn sweep_deleted_files(
error = %e,
"sweep_deleted_files: purge failed; skipping this path"
);
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepProgress {
idx,
total,
path: stored_path.0.clone(),
removed: false,
},
);
continue;
}
};
@@ -2212,12 +2250,49 @@ 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: total,
purged,
ms,
});
}
crate::ingest_progress::emit(
progress,
crate::ingest_progress::IngestEvent::SweepCompleted {
checked: total,
purged,
ms,
},
);
Ok(purged)
}

View File

@@ -152,6 +152,19 @@ 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 },
/// 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

@@ -136,6 +136,29 @@ pub enum IngestEvent {
#[serde(default)]
caption_ms: u64,
},
/// v0.33.0 (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
/// 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
/// 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.33.0 (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.
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,15 @@ 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",
"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 +177,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,162 @@
//! 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:?}"
);
}

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

@@ -304,6 +304,66 @@ 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));
if *removed {
bar.set_message(abbreviate_path(path));
}
}
// 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,
} => {
if let Some(bar) = self.bar.as_mut() {
bar.set_message("");
}
// 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();

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

@@ -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.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).",
"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,51 @@ 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 로 흘러가고 남지 않는다.
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바이트 로그가 아니다.
### 범위 밖
이슈가 참고로 적은 `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)
### 무엇이 문제였나