diff --git a/Cargo.lock b/Cargo.lock index 898d05a6caf06..29f62705f9ecd 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4483,6 +4483,7 @@ dependencies = [ "futures-util", "glob", "indexmap 2.12.0", + "notify", "quickcheck", "tempfile", "tokio", diff --git a/Cargo.toml b/Cargo.toml index c4ffc1a65f1b5..76db85c17779c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -188,6 +188,7 @@ metrics-tracing-context = { version = "0.17.0", default-features = false } metrics-util = { version = "0.18.0", default-features = false, features = ["registry"] } mlua = { version = "0.11", default-features = false, features = ["lua54", "send", "vendored"] } nom = { version = "8.0.0", default-features = false } +notify = { version = "8.1.0", default-features = false, features = ["macos_fsevent"] } ordered-float = { version = "5.3.0", default-features = false } pastey = { version = "0.2", default-features = false } pin-project = { version = "1.1.11", default-features = false } @@ -443,7 +444,7 @@ mongodb = { version = "3.7.0", default-features = false, optional = true, featur async-nats = { version = "0.49.0", default-features = false, optional = true, features = ["ring", "websockets", "jetstream", "nkeys"] } nkeys = { version = "0.4.5", default-features = false, optional = true } nom = { workspace = true, optional = true } -notify = { version = "8.1.0", default-features = false, features = ["macos_fsevent"] } +notify.workspace = true openssl = { version = "0.10.73", default-features = false, features = ["vendored"] } openssl-probe = { version = "0.1.6", default-features = false } ordered-float.workspace = true diff --git a/changelog.d/3567_file_source_notify_discovery.enhancement.md b/changelog.d/3567_file_source_notify_discovery.enhancement.md new file mode 100644 index 0000000000000..09c9f9f0a4317 --- /dev/null +++ b/changelog.d/3567_file_source_notify_discovery.enhancement.md @@ -0,0 +1,13 @@ +The `file` source now supports an opt-in `file_discovery_mode: notify` setting that uses OS-level +file system event notifications (inotify on Linux, FSEvents on macOS, `ReadDirectoryChangesW` on +Windows) instead of periodic glob re-scanning to discover new files and wake up reads. This avoids +the cost of re-globbing and re-fingerprinting every matched file on a fixed interval. A much less +frequent periodic reconciliation pass (`reconcile_interval_secs`) still runs as a correctness +backstop. The default remains the existing polling-based `file_discovery_mode: polling` behavior. + +Separately (and independently of `file_discovery_mode`), a new `idle_timeout_secs` option (default: +60 seconds) closes a file's handle once it has reached EOF and received no new data for that long, +avoiding holding a large number of open file handles for files that are being watched but aren't +actively being written to. See the `idle_timeout_secs` documentation for details. + +authors: sashamelentiev diff --git a/lib/file-source-common/Cargo.toml b/lib/file-source-common/Cargo.toml index c17b031815832..c7a892e7d7a1d 100644 --- a/lib/file-source-common/Cargo.toml +++ b/lib/file-source-common/Cargo.toml @@ -11,7 +11,7 @@ workspace = true [target.'cfg(windows)'.dependencies] libc.workspace = true -winapi = { version = "0.3", features = ["winioctl"] } +winapi = { version = "0.3", features = ["winioctl", "ioapiset"] } [dependencies] chrono.workspace = true diff --git a/lib/file-source-common/src/fingerprinter.rs b/lib/file-source-common/src/fingerprinter.rs index 3216d8c2178d4..c7e1668984c66 100644 --- a/lib/file-source-common/src/fingerprinter.rs +++ b/lib/file-source-common/src/fingerprinter.rs @@ -690,6 +690,8 @@ mod test { fn emit_files_open(&self, _: usize) {} + fn emit_files_idle(&self, _: usize) {} + fn emit_path_globbing_failed(&self, _: &Path, _: &Error) { panic!() } diff --git a/lib/file-source-common/src/internal_events.rs b/lib/file-source-common/src/internal_events.rs index 3077a51d8cab9..353d228465a65 100644 --- a/lib/file-source-common/src/internal_events.rs +++ b/lib/file-source-common/src/internal_events.rs @@ -25,8 +25,16 @@ pub trait FileSourceInternalEvents: Send + Sync + Clone + 'static { fn emit_file_checkpoint_write_error(&self, error: Error); + /// Number of files with an actually-open file handle (i.e. `Active` + /// watchers). Distinct from the total number of tracked files, which may + /// also include `Idle` watchers that hold no handle at all. fn emit_files_open(&self, count: usize); + /// Number of tracked files currently in the passive `Idle` state: no open + /// file handle, checkpoint retained, polled only via cheap `fs::metadata` + /// stats. See . + fn emit_files_idle(&self, count: usize); + fn emit_path_globbing_failed(&self, path: &Path, error: &Error); fn emit_file_line_too_long( @@ -35,4 +43,20 @@ pub trait FileSourceInternalEvents: Send + Sync + Clone + 'static { configured_limit: usize, encountered_size_so_far: usize, ); + + /// Emitted when the OS-level filesystem event watcher (if in use) reports that its + /// internal event queue overflowed, meaning some events may have been silently dropped. + /// Implementors should log this loudly, since it means the event-driven discovery path + /// may have missed file creations/modifications until the next reconciliation pass. + fn emit_file_watch_events_overflowed(&self) {} + + /// Emitted when the OS-level filesystem event watcher itself fails (e.g. the watched + /// directory disappears, or the OS notification API errors out). The event-driven + /// discovery path will keep relying on the periodic reconciliation pass until watching + /// can be re-established. + fn emit_file_watch_backend_error(&self, _error: &Error) {} + + /// Emitted once at startup (or when watched directories change) to report how many + /// directories are being watched via OS-level notifications. + fn emit_file_watch_directories(&self, _count: usize) {} } diff --git a/lib/file-source/Cargo.toml b/lib/file-source/Cargo.toml index ab758f181076c..7b299888773f1 100644 --- a/lib/file-source/Cargo.toml +++ b/lib/file-source/Cargo.toml @@ -20,6 +20,7 @@ futures-util.workspace = true vector-common = { path = "../vector-common", default-features = false } file-source-common = { path = "../file-source-common" } async-compression.workspace = true +notify.workspace = true [dev-dependencies] tokio = { workspace = true, features = ["full"] } diff --git a/lib/file-source/src/file_server.rs b/lib/file-source/src/file_server.rs index 17d80cf1586a4..2335ff9dea99e 100644 --- a/lib/file-source/src/file_server.rs +++ b/lib/file-source/src/file_server.rs @@ -1,7 +1,7 @@ use std::{ cmp, - collections::{BTreeMap, HashMap}, - path::PathBuf, + collections::{BTreeMap, HashMap, HashSet}, + path::{Path, PathBuf}, sync::Arc, time::{self, Duration}, }; @@ -24,22 +24,203 @@ use tokio::{ time::sleep, }; -use tracing::{debug, error, info, trace}; +use tracing::{debug, error, info, trace, warn}; use crate::{ file_watcher::{FileWatcher, RawLineResult}, + notify_watcher::{NotifyDiscovery, NotifyMessage}, paths_provider::PathsProvider, }; +/// How long to briefly wait for more OS-level file events to arrive, after the first one, before +/// running a reconciliation pass -- so a burst of events (e.g. an editor doing several small +/// writes) collapses into one pass instead of one per event. Deliberately a small, fixed +/// constant rather than derived from user-facing config: `glob_minimum_cooldown`/ +/// `reconcile_interval` control how *rarely* discovery runs, which is the opposite of what this +/// value is for. In particular, a user who sets a large `glob_minimum_cooldown`/ +/// `reconcile_interval` specifically to make the (expensive) backstop reconciliation pass rare +/// under `FileDiscoveryMode::Notify` must not have that same value silently become the debounce +/// window and delay every single notify-driven discovery by that same large amount. +const NOTIFY_EVENT_DEBOUNCE: Duration = Duration::from_millis(50); + +/// How often the background checkpoint-writer task persists checkpoints to disk. Kept independent +/// of `glob_minimum_cooldown`, which is documented as ignored under `Notify` mode -- otherwise a +/// large `glob_minimum_cooldown` would silently also throttle checkpoint persistence. +const CHECKPOINT_WRITE_INTERVAL: Duration = Duration::from_secs(1); + +/// Minimum time between two full glob+fingerprint reconciliation passes (`discover`) triggered by +/// notify events. Without this, a file under sustained writes would trigger a full re-glob on +/// every `NOTIFY_EVENT_DEBOUNCE` window indefinitely. Doesn't delay reads of already-tracked +/// files (those run every main-loop iteration regardless), but does delay +/// `FileWatcher::mark_ready_to_read`'s nudge by up to this much, since that only happens inside +/// `discover`. +const MIN_NOTIFY_DISCOVERY_INTERVAL: Duration = Duration::from_millis(500); + +/// Above this many distinct paths accumulated from notify events since the last reconciliation +/// pass, stop tracking them individually and fall back to treating the wakeup as "something +/// changed, go check everything" (`NotifyWakeup::All`). This bounds the memory a burst of events +/// across many different paths can make `NotifyWakeup::Paths` hold onto, and avoids the +/// per-watcher `HashSet` lookups in `discover`'s hot loop becoming worse than just nudging every +/// watcher once the set is large enough that "every watcher" and "every named path" are close in +/// size anyway. +const NOTIFY_WAKEUP_PATH_LIMIT: usize = 1024; + +/// Accumulates, between reconciliation passes, which specific paths (if known) notify events have +/// named -- so that `discover`'s "nudge this watcher past its read-pacing timers" step (see +/// `FileWatcher::mark_ready_to_read`) only touches watchers a concrete event actually named, +/// instead of every currently-tracked watcher on every single notify event regardless of which +/// path it was about. The latter is an O(N) cost (N = number of tracked files) per event, which +/// under a large `include` glob turns "one file got appended to" into "redundantly reconsider +/// every other file's read pacing too." +#[derive(Debug, Default)] +enum NotifyWakeup { + /// No notify event has arrived since the last reconciliation pass. + #[default] + None, + /// One or more notify events arrived, each naming specific paths (`PathsChanged`/ + /// `PathsRemoved`), and the total distinct path count so far has stayed at or under + /// `NOTIFY_WAKEUP_PATH_LIMIT`. + Paths(HashSet), + /// A notify event arrived that doesn't name specific paths at all (`Overflow`, + /// `BackendError`), or the accumulated path count exceeded `NOTIFY_WAKEUP_PATH_LIMIT`: treat + /// every currently-tracked watcher as possibly needing a nudge, same as the pre-existing + /// coarse "just rerun discovery" behavior. + All, +} + +impl NotifyWakeup { + fn is_pending(&self) -> bool { + !matches!(self, NotifyWakeup::None) + } + + fn add_paths(&mut self, paths: impl IntoIterator) { + match self { + NotifyWakeup::All => {} + NotifyWakeup::None => { + let set: HashSet = paths.into_iter().collect(); + *self = if set.len() > NOTIFY_WAKEUP_PATH_LIMIT { + NotifyWakeup::All + } else { + NotifyWakeup::Paths(set) + }; + } + NotifyWakeup::Paths(existing) => { + existing.extend(paths); + if existing.len() > NOTIFY_WAKEUP_PATH_LIMIT { + *self = NotifyWakeup::All; + } + } + } + } + + fn mark_all(&mut self) { + *self = NotifyWakeup::All; + } + + fn take(&mut self) -> NotifyWakeup { + std::mem::take(self) + } + + /// Whether `path` should have its watcher nudged past its own read-pacing timers (see + /// `FileWatcher::mark_ready_to_read`) for this reconciliation pass. + fn names(&self, path: &Path) -> bool { + match self { + NotifyWakeup::None => false, + NotifyWakeup::All => true, + NotifyWakeup::Paths(paths) => paths.contains(path), + } + } +} + +/// Absolutize `path` the same way the `notify` crate does internally before using a path passed +/// to `watch()`: if it's already absolute, leave it as-is; otherwise join it onto `cwd`. This +/// matters because `notify` always reports its events using the absolute form it resolved +/// `watch()`'s argument to, but a glob-based `PathsProvider` can yield a relative path unchanged +/// if the configured `include` pattern was itself relative -- without this, comparing such a path +/// directly against a notify-reported path would never match. `cwd` is `None` only if +/// `std::env::current_dir()` itself failed (e.g. the working directory was removed out from under +/// the process); in that rare case `path` is returned unchanged, since there's no well-defined way +/// to absolutize it, which merely reproduces the not-nudged-this-pass degradation this function +/// exists to avoid rather than introducing a new failure mode. +fn absolutize_for_notify_comparison(path: &Path, cwd: Option<&Path>) -> PathBuf { + if path.is_absolute() { + return path.to_path_buf(); + } + match cwd { + Some(cwd) => cwd.join(path), + None => path.to_path_buf(), + } +} + +/// Whether a watcher that `discover`'s glob/fingerprint pass just marked unfindable should be +/// reaped (`set_dead`) on this cycle. +/// +/// An `Active` watcher left unfindable keeps getting read (and, on EOF, marked dead) every cycle +/// regardless of `rotate_wait`, so `rotate_wait` only matters there as a grace period against a +/// premature `unwatch`; this function's `false` result for such a watcher (until `rotate_wait` +/// elapses) preserves that pre-existing behavior unchanged. +/// +/// An `Idle` watcher, by contrast, is never read while unfindable (`poll_idle_watchers` skips +/// unfindable watchers outright, to avoid reactivating against a different file that's since +/// appeared at the same path -- see that function's doc comment), so it has no other path to +/// reaping at all. Waiting out the full `rotate_wait` (whose default is effectively unlimited) +/// before reaping it would let every rotation past an `include` glob permanently add another +/// watcher/checkpoint to `fp_map`. But reaping it the instant it's first seen unfindable is also +/// wrong: a rename's target might not be fingerprint-matched back to this watcher in the exact +/// same `discover()` pass that saw it disappear (a slow/partial rename, or -- under `Notify` mode +/// -- the create/rename-to event simply hasn't been delivered/debounced through yet), in which +/// case it would still be matched on a *later* pass if given the chance. This grants an `Idle` +/// watcher at least one full `discovery_interval` -- the same cadence `discover()` itself already +/// runs on -- to be rediscovered before reaping it: long enough to survive a rename spanning one +/// discovery pass, but nowhere near `rotate_wait`'s effectively-unlimited default. +fn should_reap_unfindable_watcher( + is_idle: bool, + unfindable_for: Duration, + discovery_interval: Duration, + rotate_wait: Duration, +) -> bool { + (is_idle && unfindable_for > discovery_interval) || unfindable_for > rotate_wait +} + +/// Salvage `watcher`'s final unterminated line, if any, into `lines`. Call this right before +/// every `set_dead()` that doesn't already go through `read_line` first (which has its own flush +/// for the `Active` case) -- otherwise a trailing record with no delimiter is lost for good. +fn salvage_final_partial_line( + watcher: &mut FileWatcher, + file_id: FileFingerprint, + lines: &mut Vec, +) { + let Some(line) = watcher.take_final_partial_line() else { + return; + }; + let end_offset = line.offset + line.bytes.len() as u64; + lines.push(Line { + text: line.bytes, + filename: watcher.path.to_str().expect("not a valid path").to_owned(), + file_id, + start_offset: line.offset, + end_offset, + }); +} + /// `FileServer` is a Source which cooperatively schedules reads over files, -/// converting the lines of said files into `LogLine` structures. As -/// `FileServer` is intended to be useful across multiple operating systems with -/// POSIX filesystem semantics `FileServer` must poll for changes. That is, no -/// event notification is used by `FileServer`. +/// converting the lines of said files into `LogLine` structures. /// /// `FileServer` is configured on a path to watch. The files do _not_ need to -/// exist at startup. `FileServer` will discover new files which match -/// its path in at most 60 seconds. +/// exist at startup. +/// +/// By default (see [`FileDiscoveryMode::PollingOnly`]) `FileServer` discovers changes by polling: +/// it re-globs its configured paths on a fixed interval (`glob_minimum_cooldown`), so new files +/// are discovered in at most that interval. This works identically across every OS with POSIX-ish +/// filesystem semantics, at the cost of holding an open file handle for, and periodically +/// re-fingerprinting, every matched file regardless of activity. +/// +/// Optionally (see [`FileDiscoveryMode::Notify`]), `FileServer` can instead use OS-level file +/// system event notifications (inotify/FSEvents/`ReadDirectoryChangesW`, via the `notify` crate) +/// to discover changes promptly, without needing to poll. A much less frequent polling pass +/// (`reconcile_interval`) still runs as a correctness backstop. Discovering files quickly doesn't +/// by itself stop them from holding an open handle once discovered; that's controlled separately +/// by `idle_timeout`, which applies regardless of discovery mode. pub struct FileServer where PP: PathsProvider, @@ -58,6 +239,57 @@ where pub remove_after: Option, pub emitter: E, pub rotate_wait: Duration, + /// Controls whether `FileServer` uses OS-level file system event notifications (via the + /// `notify` crate) to drive discovery/read-wakeups, in addition to the periodic glob + /// rescan. See [`FileDiscoveryMode`] for details. `FileDiscoveryMode` itself implements + /// [`Default`] (yielding [`FileDiscoveryMode::PollingOnly`]), so `FileDiscoveryMode::default()` + /// can be used by callers who don't want to opt into notify-based discovery. + pub discovery_mode: FileDiscoveryMode, + /// How often to run the full glob+fingerprint reconciliation pass when + /// [`FileDiscoveryMode::Notify`] is in use. This exists purely as a correctness backstop + /// (OS notification queues can silently overflow, and there's a startup TOCTOU window + /// before the watch is established) so it can be much less frequent than + /// `glob_minimum_cooldown` was under the old polling-only model. Ignored when + /// `discovery_mode` is `PollingOnly`, in which case `glob_minimum_cooldown` is used as + /// before. + pub reconcile_interval: Duration, + /// How long an actively-open, EOF'd file must go without new writes before its file handle + /// is closed and it is moved to the passive "Idle" watching state (still checkpointed, still + /// polled for new data via cheap `fs::metadata` stats, but no open file descriptor). `None` + /// disables this behavior entirely, i.e. files are never deactivated -- restoring the + /// pre-existing, always-open behavior -- both at runtime (the `deactivate()` transition + /// gated on this field directly) and at startup (`FileWatcher::new`'s fast path for + /// `ignore_older`-excluded files, gated via `idle_on_startup = self.idle_timeout.is_some()`, + /// since that path is a separate mechanism from `deactivate()` and would otherwise still + /// start such files `Idle` regardless of this setting). Applies under both + /// `FileDiscoveryMode::PollingOnly` and `FileDiscoveryMode::Notify`: notify-based discovery + /// makes finding files fast, but doesn't by itself stop already-discovered, + /// `ignore_older`-excluded files from holding a handle open for as long as they exist on + /// disk -- this option is what does that, addressing the other half of + /// . + pub idle_timeout: Option, +} + +/// Controls how `FileServer` discovers new files, renames, and wakes up reads of existing +/// files. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Default)] +pub enum FileDiscoveryMode { + /// The original behavior: re-glob and re-fingerprint every matched file every + /// `glob_minimum_cooldown`. Simple, and works identically on every platform, but expensive + /// when a very large number of files match the `include` patterns (see + /// ), since every matched file is kept + /// open and re-fingerprinted every cycle regardless of activity. + #[default] + PollingOnly, + /// Event-driven discovery: watch the directories implied by the `include` patterns for + /// OS-level create/modify/rename/remove notifications (via the `notify` crate) and use + /// those to trigger discovery/read-wakeups promptly, instead of waiting for the next fixed + /// poll interval. A full glob+fingerprint reconciliation pass still runs on + /// `reconcile_interval` as a correctness backstop for dropped/overflowed OS events and the + /// startup TOCTOU window. If the underlying OS watcher fails to initialize (e.g. platform + /// resource limits), `FileServer` logs a warning and transparently falls back to + /// polling-only behavior using `reconcile_interval` as the poll interval. + Notify, } /// `FileServer` as Source @@ -71,8 +303,8 @@ where /// before `FileServer` is able to open it the contents will be lost. This should be a /// rare occurrence. /// -/// Specific operating systems support evented interfaces that correct this -/// problem but your intrepid authors know of no generic solution. +/// Specific operating systems support evented interfaces that correct this problem; see +/// [`FileDiscoveryMode::Notify`] for `FileServer`'s (opt-in) use of one via the `notify` crate. impl FileServer where PP: PathsProvider, @@ -105,6 +337,46 @@ where let mut known_small_files = HashMap::new(); + // If we're using notify-driven discovery, establish the OS-level watch(es) *before* + // doing the initial glob scan below. This closes (or at least drastically narrows) the + // classic TOCTOU gap where a file changes between an initial scan and when the watch is + // actually established: any change that lands in that window will still generate a + // notify event, which will be sitting in the channel by the time the main loop starts + // selecting on it, and will trigger a reconciliation pass that picks it up. The + // alternative order (scan first, then watch) has a real gap in which changes are simply + // lost until the next backstop reconciliation interval. + // + // If notify initialization fails (e.g. platform resource limits like hitting the + // inotify instance cap), we log and transparently fall back to polling-only behavior + // using `reconcile_interval` as the poll interval, rather than failing the whole file + // source. + let include_patterns = self.paths_provider.watch_roots(); + let mut notify_discovery = match self.discovery_mode { + FileDiscoveryMode::Notify if !include_patterns.is_empty() => { + match NotifyDiscovery::new(&include_patterns, &self.emitter) { + Ok(discovery) => Some(discovery), + Err(error) => { + warn!( + message = "Failed to initialize OS-level file watcher; falling back to periodic polling.", + %error, + ); + self.emitter + .emit_file_watch_backend_error(&std::io::Error::other( + error.to_string(), + )); + None + } + } + } + FileDiscoveryMode::Notify => { + warn!( + message = "Notify-based discovery requested but the configured paths provider does not expose watch roots; falling back to periodic polling.", + ); + None + } + FileDiscoveryMode::PollingOnly => None, + }; + let mut existing_files = Vec::new(); for path in self.paths_provider.paths().into_iter() { if let Some(file_id) = self @@ -143,14 +415,14 @@ where self.watch_new_file(path, file_id, &mut fp_map, &checkpoints, true) .await; } - self.emitter.emit_files_open(fp_map.len()); + self.emit_open_and_idle_counts(&fp_map); let mut stats = TimingStats::default(); // Spawn the checkpoint writer task let checkpoint_task_handle = vector_common::spawn_in_current_span(checkpoint_writer( checkpointer, - self.glob_minimum_cooldown, + CHECKPOINT_WRITE_INTERVAL, shutdown_checkpointer, self.emitter.clone(), )); @@ -164,13 +436,66 @@ where // exponential fashion to some hard-coded cap. To reduce time using glob, // we do not re-scan for major file changes (new files, moves, deletes), // or write new checkpoints, on every iteration. + // + // Discovery trigger, discovery_mode == PollingOnly: re-scan on a fixed interval + // (`glob_minimum_cooldown`), exactly as before. + // + // Discovery trigger, discovery_mode == Notify: re-scan is triggered by (a) an OS-level + // filesystem event arriving (in which case we still run the *same* full glob+fingerprint + // reconciliation logic below -- we deliberately don't try to interpret notify's event + // payload and update state incrementally, since that would duplicate/risk diverging from + // the already-correct reconciliation logic; a full reconcile pass is cheap enough to run + // on every event since it's no longer gated by a tiny fixed interval), or (b) the much + // longer `reconcile_interval` backstop timer firing, to catch anything notify missed + // (queue overflow, pre-watch-establishment changes, or platforms/paths where notify + // can't watch for some reason). let mut next_glob_time = time::Instant::now(); + // The very first loop iteration always runs a discovery pass regardless of discovery + // mode: `next_glob_time` was just set to `Instant::now()` above, and `now_time` inside the + // loop is captured strictly later, so `next_glob_time <= now_time` is unconditionally true + // on that first check -- no separate "force the first pass" flag is needed. This pass must + // not be treated as notify-triggered (that would wrongly nudge every watcher's read pacing + // via `NotifyWakeup::All`/`Paths` on startup, and under `PollingOnly` a notify-triggered + // pass should never happen at all), so `pending_notify_wakeup` starts at `None`. + let mut pending_notify_wakeup = NotifyWakeup::None; + // Throttles notify-triggered full reconciliation passes independently of the backstop + // timer (`next_glob_time`/`discovery_interval`): see `MIN_NOTIFY_DISCOVERY_INTERVAL`'s + // doc comment for why. Starts at "now" so the very first notify event, whenever it + // arrives, is handled immediately rather than waiting out this interval from process + // start for no reason. + let mut next_notify_discovery_time = time::Instant::now(); loop { - // Glob find files to follow, but not too often. + // Use `reconcile_interval` whenever `Notify` mode was configured, even if the notify + // watcher isn't currently live (it failed to initialize, or died mid-run and was set + // to `None`): `glob_minimum_cooldown` is documented as ignored in `Notify` mode, so a + // user relying on that must still get `reconcile_interval`'s cadence during a fallback + // rather than silently reverting to whatever `glob_minimum_cooldown` happens to be set + // to (which, precisely because it's documented as ignored, may be tuned very + // differently than the intended discovery cadence). + let discovery_interval = if self.discovery_mode == FileDiscoveryMode::Notify { + self.reconcile_interval + } else { + self.glob_minimum_cooldown + }; + + // Glob find files to follow, but not too often. A pending notify wakeup only + // triggers this early (ahead of `next_glob_time`) once `next_notify_discovery_time` + // has also elapsed -- see `MIN_NOTIFY_DISCOVERY_INTERVAL`. let now_time = time::Instant::now(); - if next_glob_time <= now_time { - // Schedule the next glob time. - next_glob_time = now_time.checked_add(self.glob_minimum_cooldown).unwrap(); + let notify_wakeup_ready = + pending_notify_wakeup.is_pending() && next_notify_discovery_time <= now_time; + if next_glob_time <= now_time || notify_wakeup_ready { + // Leave the wakeup queued (don't take it) if we're here only because the backstop + // timer fired while the notify throttle hasn't elapsed yet. + let woken_by_notify_event = if notify_wakeup_ready { + next_notify_discovery_time = + now_time.checked_add(MIN_NOTIFY_DISCOVERY_INTERVAL).unwrap(); + pending_notify_wakeup.take() + } else { + NotifyWakeup::None + }; + // Schedule the next backstop reconciliation time. + next_glob_time = now_time.checked_add(discovery_interval).unwrap(); if stats.started_at.elapsed() > Duration::from_secs(1) { stats.report(); @@ -180,63 +505,20 @@ where stats = TimingStats::default(); } - // Search (glob) for files to detect major file changes. let start = time::Instant::now(); - for (_file_id, watcher) in &mut fp_map { - watcher.set_file_findable(false); // assume not findable until found - } - for path in self.paths_provider.paths().into_iter() { - if let Some(file_id) = self - .fingerprinter - .fingerprint_or_emit(&path, &mut known_small_files, &self.emitter) - .await - { - if let Some(watcher) = fp_map.get_mut(&file_id) { - // file fingerprint matches a watched file - let was_found_this_cycle = watcher.file_findable(); - watcher.set_file_findable(true); - if watcher.path == path { - trace!( - message = "Continue watching file.", - path = ?path, - ); - } else if !was_found_this_cycle { - // matches a file with a different path - info!( - message = "Watched file has been renamed.", - path = ?path, - old_path = ?watcher.path - ); - watcher.update_path(path).await.ok(); // ok if this fails: might fix next cycle - } else { - info!( - message = "More than one file has the same fingerprint.", - path = ?path, - old_path = ?watcher.path - ); - let (old_path, new_path) = (&watcher.path, &path); - if let (Ok(old_modified_time), Ok(new_modified_time)) = ( - fs::metadata(old_path).await.and_then(|m| m.modified()), - fs::metadata(new_path).await.and_then(|m| m.modified()), - ) && old_modified_time < new_modified_time - { - info!( - message = "Switching to watch most recently modified file.", - new_modified_time = ?new_modified_time, - old_modified_time = ?old_modified_time, - ); - watcher.update_path(path).await.ok(); // ok if this fails: might fix next cycle - } - } - } else { - // untracked file fingerprint - self.watch_new_file(path, file_id, &mut fp_map, &checkpoints, false) - .await; - self.emitter.emit_files_open(fp_map.len()); - } - } - } + self.discover( + &mut fp_map, + &mut known_small_files, + &checkpoints, + notify_discovery.as_mut(), + &woken_by_notify_event, + ) + .await; stats.record("discovery", start.elapsed()); + + let start = time::Instant::now(); + self.poll_idle_watchers(&mut fp_map, &mut lines).await; + stats.record("idle-poll", start.elapsed()); } // Cleanup the known_small_files @@ -338,6 +620,7 @@ where match remove_file(&watcher.path).await { Ok(()) => { self.emitter.emit_file_deleted(&watcher.path); + salvage_final_partial_line(watcher, file_id, &mut lines); watcher.set_dead(); } Err(error) => { @@ -346,6 +629,22 @@ where } } } + + // The file has reached EOF and produced nothing this + // cycle. If it's been quiet (no successful reads) for + // `idle_timeout`, close its handle and move it to the + // passive `Idle` state: we keep the checkpoint and keep + // polling cheaply via `fs::metadata`, but stop holding a + // file descriptor open for a file nobody is writing to. + // This is the runtime (as opposed to startup) half of the + // fix for https://github.com/vectordotdev/vector/issues/3567. + if !watcher.dead() + && let Some(idle_timeout) = self.idle_timeout + && watcher.reached_eof() + && watcher.idle_for().is_some_and(|idle| idle >= idle_timeout) + { + watcher.deactivate().await; + } } // Do not move on to newer files if we are behind on an older file @@ -354,8 +653,19 @@ where } } - for (_, watcher) in &mut fp_map { - if !watcher.file_findable() && watcher.last_seen().elapsed() > self.rotate_wait { + for (&file_id, watcher) in &mut fp_map { + if watcher.file_findable() { + continue; + } + // See `should_reap_unfindable_watcher`'s doc comment for why `Idle` and `Active` + // watchers need different grace periods here. + if should_reap_unfindable_watcher( + watcher.is_idle(), + watcher.last_seen().elapsed(), + discovery_interval, + self.rotate_wait, + ) { + salvage_final_partial_line(watcher, file_id, &mut lines); watcher.set_dead(); } } @@ -372,7 +682,7 @@ where true } }); - self.emitter.emit_files_open(fp_map.len()); + self.emit_open_and_idle_counts(&fp_map); let start = time::Instant::now(); let to_send = std::mem::take(&mut lines); @@ -404,13 +714,83 @@ where // call. Also since we are using block_on here and in the above code, // this should be run in its own thread. `spawn_blocking` fulfills // all of these requirements. - let sleep = async move { + let sleep_fut = async move { if backoff > 0 { sleep(Duration::from_millis(backoff as u64)).await; } }; - futures::pin_mut!(sleep); - match select(shutdown_data, sleep).await { + futures::pin_mut!(sleep_fut); + + // When notify-based discovery is active, race the backoff sleep against both + // shutdown and the notify event channel, so a filesystem event can cut the sleep + // short and trigger a prompt reconciliation pass instead of waiting out the (small, + // but nonzero) backoff. `shutdown_data: S1: Future + Unpin` so it's safe to poll by + // mutable reference across loop iterations without re-pinning. + if let Some(discovery) = notify_discovery.as_mut() { + let mut shutdown = false; + let mut channel_closed = false; + tokio::select! { + biased; + _ = &mut shutdown_data => { + shutdown = true; + } + msg = discovery.recv() => { + channel_closed = msg.is_none(); + self.handle_notify_message(msg, discovery, &mut pending_notify_wakeup); + // Briefly drain/debounce further events so a burst of writes collapses + // into a single reconciliation pass. Each drained message still goes + // through the same handling as the message above (not just discarded): + // a `BackendError`/`Overflow` arriving inside this window must still + // trigger `forget_watches`/overflow telemetry, or those effects would be + // silently dropped whenever they happen to land within + // `NOTIFY_EVENT_DEBOUNCE` of another event, which -- for a backend error + // specifically -- would leave `forget_watches` never called and the lost + // watch registration never re-established. + if !channel_closed { + let drain_result = tokio::time::timeout(NOTIFY_EVENT_DEBOUNCE, async { + loop { + let msg = discovery.recv().await; + let is_none = msg.is_none(); + self.handle_notify_message(msg, discovery, &mut pending_notify_wakeup); + if is_none { + break; + } + } + }) + .await; + // A timeout just means the debounce window elapsed while events were + // still arriving, which is the expected/common case. If the drain loop + // instead broke out on its own, the channel closed. + channel_closed = drain_result.is_ok(); + } + } + _ = &mut sleep_fut => {} + } + if channel_closed { + // The notify watcher task/thread went away entirely (e.g. panicked). Fall + // back to relying solely on the backstop reconcile interval from here on; do + // not treat this as fatal to the file source. + warn!("Notify event channel closed; relying on periodic reconciliation only."); + notify_discovery = None; + } + stats.record("sleeping", start.elapsed()); + if shutdown { + chans + .close() + .await + .expect("error closing file_server data channel."); + let checkpointer = checkpoint_task_handle + .await + .expect("checkpoint task has panicked"); + if let Err(error) = checkpointer.write_checkpoints().await { + error!(?error, "Error writing checkpoints before shutdown"); + } + return Ok(Shutdown); + } + continue; + } + + match select(shutdown_data, sleep_fut).await { Either::Left((_shutdown_token, _)) => { chans .close() @@ -432,6 +812,309 @@ where } } + /// Handle a single message received from `discovery`, both for the initial message that woke + /// up the `tokio::select!` in `run` and for each message drained from the channel during the + /// subsequent debounce window. `None` (the channel having closed) is intentionally not + /// matched here: the caller is responsible for detecting that (it needs to stop the drain + /// loop and fall back off notify entirely), whereas every other variant is handled + /// identically regardless of whether it arrived as the "woke us up" message or as one drained + /// during debounce -- in particular, a `BackendError`'s `forget_watches()` call and an + /// `Overflow`'s telemetry must fire even when they land inside the debounce window, not just + /// on the message that started it. + fn handle_notify_message( + &self, + msg: Option, + discovery: &mut NotifyDiscovery, + pending_notify_wakeup: &mut NotifyWakeup, + ) { + match msg { + Some(NotifyMessage::PathsChanged(paths)) => { + trace!(message = "Received file change notification.", ?paths); + // Named paths only: `discover`'s per-watcher nudge (`FileWatcher::mark_ready_to_read`) + // should only touch watchers this event actually concerns, not every tracked file -- + // see `NotifyWakeup`'s docs for why nudging everything on every event doesn't scale. + pending_notify_wakeup.add_paths(paths); + } + Some(NotifyMessage::PathsRemoved(paths)) => { + trace!(message = "Received file removal notification.", ?paths); + // If one of the removed paths is itself a directory we're watching (as opposed to + // a file inside one), the watch on it may have been invalidated at the OS level + // (this is inotify's behavior on Linux: removing a watched directory invalidates + // the watch on that inode, even if a new directory is later created at the same + // path). Forget our bookkeeping for it so the reconciliation pass's + // `resync_watches` call re-`watch`es it once it exists again, rather than + // wrongly believing it's still watched and skipping it forever. See + // `NotifyDiscovery::forget_watch` for details. + for path in &paths { + if discovery.is_watched_dir(path) { + discovery.forget_watch(path); + } + } + pending_notify_wakeup.add_paths(paths); + } + Some(NotifyMessage::Overflow) => { + self.emitter.emit_file_watch_events_overflowed(); + // No specific paths are known to have changed; treat every tracked watcher as + // possibly needing a nudge, same as the pre-existing coarse behavior. + pending_notify_wakeup.mark_all(); + } + Some(NotifyMessage::BackendError(error)) => { + self.emitter + .emit_file_watch_backend_error(&std::io::Error::other(error)); + // A backend error can mean the watcher silently dropped a watch (e.g. a watched + // directory was removed and recreated). Forget our bookkeeping of which + // directories are watched so the upcoming reconciliation pass's `resync_watches` + // call re-`watch`s everything from scratch, rather than skipping paths it + // incorrectly still believes are watched. See `NotifyDiscovery::forget_watches` + // for why this is necessary. + discovery.forget_watches(); + // No specific paths are known to have changed here either. + pending_notify_wakeup.mark_all(); + } + None => {} + } + } + + /// Perform a full glob+fingerprint reconciliation pass: re-glob the configured `include` + /// patterns and detect new files, renames (a known fingerprint appearing at a new path), and + /// duplicate-fingerprint conflicts (picking the most recently modified file). + /// + /// This is the same logic that used to run unconditionally on every `glob_minimum_cooldown` + /// tick. It's now called either on a fixed interval (`PollingOnly` mode, or as the + /// `Notify`-mode backstop via `reconcile_interval`), or on-demand when the OS-level notify + /// watcher reports a change -- throttled to at most once per `MIN_NOTIFY_DISCOVERY_INTERVAL` + /// regardless of how often notify events arrive, since sustained writes to even a single file + /// would otherwise trigger this full pass on every `NOTIFY_EVENT_DEBOUNCE` window indefinitely + /// (see that constant's doc comment). We deliberately keep this as one unified, full pass + /// rather than writing a separate "apply this one notify event incrementally" code path: + /// reusing the already-correct logic avoids a second, potentially divergent implementation of + /// rename/duplicate-fingerprint handling, and the throttle above keeps its cost bounded + /// without needing that split. + /// + /// `notify_wakeup` distinguishes a pass triggered by an actual OS-level filesystem event from + /// one triggered by the periodic timer alone (`glob_minimum_cooldown` in `PollingOnly` mode, + /// or the `reconcile_interval` backstop in `Notify` mode): only for a watcher whose path + /// `notify_wakeup` actually names (`NotifyWakeup::Paths`) or when it's `NotifyWakeup::All` + /// (an event that didn't name specific paths, e.g. `Overflow`/`BackendError`, or more distinct + /// paths than `NOTIFY_WAKEUP_PATH_LIMIT`) does an already-tracked, still-`Active` watcher get + /// nudged past its own independent read-pacing timers (see the "same path" branch below and + /// `FileWatcher::mark_ready_to_read`) -- a concrete "this path changed" signal justifies + /// reading it sooner than those timers would otherwise allow, but the periodic timer firing on + /// its own doesn't, and nudging every watcher on every pass regardless (the pre-fix behavior) + /// meant a single notify event under a large `include` glob cost an O(N) sweep of every other + /// tracked file's read pacing too, not just the one path that actually changed. + /// + /// `notify_wakeup.names(&path)` compares paths as reported by the OS notify backend against + /// `path` as yielded by `paths_provider.paths()`. The `notify` crate always resolves the path + /// it was asked to `watch()` to an absolute one internally (via the current working directory) + /// before using it, and reports its events using that same absolute form -- but a glob-based + /// `PathsProvider` can yield a relative path unchanged if the configured `include` pattern was + /// itself relative. Without accounting for this, `notify_wakeup.names(&path)` would compare a + /// relative `path` against an absolute event path and never match, silently defeating the + /// nudge for every file matched by a relative `include` pattern. `discover` absolutizes `path` + /// (via `absolutize_for_notify_comparison`) the same way `notify` would before comparing. + /// + /// **Known limitation**: this only accounts for relative-vs-absolute, not full + /// canonicalization (symlink resolution): canonicalizing every tracked file's path on every + /// pass, just to cover a much rarer case, would cost a `stat`-like syscall per file per pass + /// for a benefit that's purely about read-latency, not correctness. If an `include` pattern + /// traverses a symlink and the two sides resolve it differently even after absolutizing, the + /// nudge can still silently not fire for that watcher on that pass. This degrades gracefully: + /// `should_read`'s own timers still fire eventually, and the periodic + /// `reconcile_interval`/`glob_minimum_cooldown` backstop still runs regardless of this nudge, + /// so the affected file falls back to ordinary polling-like latency rather than losing data or + /// getting stuck. + async fn discover( + &mut self, + fp_map: &mut IndexMap, + known_small_files: &mut HashMap, + checkpoints: &CheckpointsView, + notify_discovery: Option<&mut NotifyDiscovery>, + notify_wakeup: &NotifyWakeup, + ) { + // Defensive resync: cheap to call, and covers the (rare) case where the set of + // directories implied by `include` patterns needs to change -- e.g. a literal include + // path's directory didn't exist at startup and now does, or the `PathsProvider` + // implementation's `watch_roots()` otherwise changes over time. New files created + // *inside* an already-recursively-watched directory tree don't need this: the OS + // backend (inotify/FSEvents/ReadDirectoryChangesW) follows new subdirectories on its + // own once a recursive watch is established on their ancestor. + if let Some(discovery) = notify_discovery { + discovery.resync_watches(&self.paths_provider.watch_roots(), &self.emitter); + } + + for (_file_id, watcher) in &mut *fp_map { + watcher.set_file_findable(false); // assume not findable until found + } + + // Computed once per pass (not once per file) and only when there's actually a pending + // notify wakeup to compare against -- the common case, a backstop-timer-only pass with + // `NotifyWakeup::None`, skips this (and every `.names()` call below) entirely, since + // `None` never matches regardless of what `path` is compared against. + let cwd_for_notify_comparison = notify_wakeup + .is_pending() + .then(|| std::env::current_dir().ok()) + .flatten(); + + for path in self.paths_provider.paths().into_iter() { + if let Some(file_id) = self + .fingerprinter + .fingerprint_or_emit(&path, known_small_files, &self.emitter) + .await + { + if let Some(watcher) = fp_map.get_mut(&file_id) { + // file fingerprint matches a watched file + let was_found_this_cycle = watcher.file_findable(); + watcher.set_file_findable(true); + if watcher.path == path { + trace!( + message = "Continue watching file.", + path = ?path, + ); + let absolutized_path = absolutize_for_notify_comparison( + &path, + cwd_for_notify_comparison.as_deref(), + ); + if notify_wakeup.names(&absolutized_path) { + // A concrete filesystem event named this exact path (or we can't tell + // which paths changed, e.g. `Overflow`), so this watcher may have new + // data waiting even if it's currently mid-EOF-backoff or past the + // quiet-file throttle window (both of which exist only to pace + // *unprompted* polling, not to delay a read a real signal just + // justified). See `FileWatcher::mark_ready_to_read`. + watcher.mark_ready_to_read(); + } + } else if !was_found_this_cycle { + // matches a file with a different path + info!( + message = "Watched file has been renamed.", + path = ?path, + old_path = ?watcher.path + ); + watcher.update_path(path).await.ok(); // ok if this fails: might fix next cycle + } else { + info!( + message = "More than one file has the same fingerprint.", + path = ?path, + old_path = ?watcher.path + ); + let (old_path, new_path) = (&watcher.path, &path); + if let (Ok(old_modified_time), Ok(new_modified_time)) = ( + fs::metadata(old_path).await.and_then(|m| m.modified()), + fs::metadata(new_path).await.and_then(|m| m.modified()), + ) && old_modified_time < new_modified_time + { + info!( + message = "Switching to watch most recently modified file.", + new_modified_time = ?new_modified_time, + old_modified_time = ?old_modified_time, + ); + watcher.update_path(path).await.ok(); // ok if this fails: might fix next cycle + } + } + } else { + // untracked file fingerprint + self.watch_new_file(path, file_id, fp_map, checkpoints, false) + .await; + self.emit_open_and_idle_counts(fp_map); + } + } + } + } + + /// Cheaply poll `Idle` watchers (no open file handle) for new data by stat-ing them, reusing + /// the same discovery cadence (`discover`'s caller) rather than adding a whole separate + /// polling loop. Promotes any that changed back to `Active` so the read loop picks them up. + /// + /// Skips watchers that `discover`'s glob/fingerprint pass just marked unfindable. An `Idle` + /// watcher holds no handle, so unlike an `Active` one it has no OS-level pin on the specific + /// inode it was watching: if its old path was renamed away (rotation) and something new was + /// created at that same path before `rotate_wait` elapses and the stale watcher is reaped, a + /// stat against `watcher.path` here would be observing the *new* file. Reactivating in that + /// case would seek the new file to the old, unrelated checkpoint offset -- silently skipping + /// or re-reading data. Findable watchers are exactly the ones `discover`'s fingerprint match + /// confirmed still refer to the same file, so only those are safe to promote here. + async fn poll_idle_watchers( + &self, + fp_map: &mut IndexMap, + lines: &mut Vec, + ) { + for (&file_id, watcher) in &mut *fp_map { + if !watcher.is_idle() || !watcher.file_findable() { + continue; + } + match watcher.check_for_new_data().await { + Ok(true) => { + if let Err(error) = watcher.reactivate().await { + self.emitter.emit_file_watch_error(&watcher.path, error); + // check_for_new_data already recorded the size/mtime it just observed + // before we got here. Without this, a transient reactivate() failure + // (the file exists and changed, per the stat we just did, but couldn't be + // opened for some other reason) would strand the watcher: the next poll + // would compare against the state recorded from *this* failed attempt, + // see no further difference, and never retry. + watcher.invalidate_idle_bookkeeping(); + } else { + debug!( + message = "Idle file has new data; resuming active watch.", + path = ?watcher.path, + ); + } + } + Ok(false) => { + // Still idle and still unchanged. Idle files are eligible for `remove_after` + // cleanup just like active ones, driven off how long they've sat unchanged + // rather than "time since last successful read" (which is meaningless for a + // watcher that, by construction, isn't reading). + if let Some(grace_period) = self.remove_after + && watcher + .idle_since() + .is_some_and(|idle| idle >= grace_period) + { + match remove_file(&watcher.path).await { + Ok(()) => { + self.emitter.emit_file_deleted(&watcher.path); + salvage_final_partial_line(watcher, file_id, lines); + watcher.set_dead(); + } + Err(error) => { + self.emitter.emit_file_delete_error(&watcher.path, error); + } + } + } + } + Err(error) => { + if error.kind() == std::io::ErrorKind::NotFound { + // Deletion of idle files is handled uniformly below via + // `file_findable`/`rotate_wait`, so nothing more to do here; the next + // discovery pass will mark this watcher unfindable. + } else { + self.emitter.emit_file_watch_error(&watcher.path, error); + } + } + } + } + } + + /// Emit the `files_open`/`files_idle` gauges from the current contents of `fp_map`. + /// `files_open` reflects only watchers that actually hold an open file handle (`Active` + /// state); `files_idle` reflects watchers that are tracked (checkpointed, polled) but hold no + /// handle (`Idle` state). Prior to the idle-watching feature these were always identical to + /// `fp_map.len()`; splitting them out is what makes the fix for + /// observable. + fn emit_open_and_idle_counts(&self, fp_map: &IndexMap) { + let (mut open, mut idle) = (0usize, 0usize); + for watcher in fp_map.values() { + if watcher.is_idle() { + idle += 1; + } else { + open += 1; + } + } + self.emitter.emit_files_open(open); + self.emitter.emit_files_idle(idle); + } + async fn watch_new_file( &self, path: PathBuf, @@ -472,6 +1155,7 @@ where self.ignore_before, self.max_line_bytes, self.line_delimiter.clone(), + self.idle_timeout.is_some(), ) .await { @@ -599,3 +1283,216 @@ pub struct Line { pub start_offset: u64, pub end_offset: u64, } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn notify_wakeup_starts_none_and_reports_not_pending() { + let wakeup = NotifyWakeup::default(); + assert!(!wakeup.is_pending()); + assert!(!wakeup.names(&PathBuf::from("/var/log/a.log"))); + } + + #[test] + fn notify_wakeup_names_only_the_specific_paths_added() { + // Regression test for a bug found in review: a single notify event must not cause + // `discover` to nudge every tracked watcher's read pacing -- only the watcher(s) whose + // path the event actually named. Otherwise one changed file among many thousands turns + // into an O(N) sweep on every single event. + let mut wakeup = NotifyWakeup::default(); + wakeup.add_paths([PathBuf::from("/var/log/a.log")]); + + assert!(wakeup.is_pending()); + assert!(wakeup.names(&PathBuf::from("/var/log/a.log"))); + assert!( + !wakeup.names(&PathBuf::from("/var/log/b.log")), + "a path the event didn't name must not be reported as needing a nudge" + ); + } + + #[test] + fn notify_wakeup_accumulates_paths_across_multiple_add_calls() { + let mut wakeup = NotifyWakeup::default(); + wakeup.add_paths([PathBuf::from("/var/log/a.log")]); + wakeup.add_paths([PathBuf::from("/var/log/b.log")]); + + assert!(wakeup.names(&PathBuf::from("/var/log/a.log"))); + assert!(wakeup.names(&PathBuf::from("/var/log/b.log"))); + assert!(!wakeup.names(&PathBuf::from("/var/log/c.log"))); + } + + #[test] + fn notify_wakeup_mark_all_names_everything() { + // `Overflow`/`BackendError` don't carry specific paths, so every tracked watcher must be + // treated as possibly needing a nudge -- this is the pre-existing coarse behavior, + // preserved for the cases where no finer-grained information is available. + let mut wakeup = NotifyWakeup::default(); + wakeup.mark_all(); + + assert!(wakeup.is_pending()); + assert!(wakeup.names(&PathBuf::from("/var/log/anything.log"))); + } + + #[test] + fn notify_wakeup_falls_back_to_all_past_the_path_limit() { + // Bounds the memory (and, in `discover`, the per-watcher `HashSet` lookup cost) a burst of + // events touching many distinct paths can accumulate: past `NOTIFY_WAKEUP_PATH_LIMIT`, + // tracking individual paths stops being worth it and `NotifyWakeup` falls back to `All`. + let mut wakeup = NotifyWakeup::default(); + let many_paths = + (0..=NOTIFY_WAKEUP_PATH_LIMIT).map(|i| PathBuf::from(format!("/var/log/{i}.log"))); + wakeup.add_paths(many_paths); + + assert!(matches!(wakeup, NotifyWakeup::All)); + assert!(wakeup.names(&PathBuf::from("/var/log/anything-else.log"))); + } + + #[test] + fn notify_wakeup_take_resets_to_none() { + let mut wakeup = NotifyWakeup::default(); + wakeup.add_paths([PathBuf::from("/var/log/a.log")]); + + let taken = wakeup.take(); + assert!(taken.is_pending()); + assert!( + !wakeup.is_pending(), + "take() must reset the original to None" + ); + } + + #[test] + fn idle_unfindable_watcher_survives_one_discovery_interval() { + // Regression test for a bug found in review: an `Idle` watcher whose file's rename target + // isn't fingerprint-matched back to it in the very same `discover()` pass that saw it + // disappear (a slow/partial rename, or a notify event that simply hasn't been delivered + // yet) must still get a chance to be rediscovered on a later pass, rather than having its + // checkpoint dropped on the very first pass that finds it unfindable. + let discovery_interval = Duration::from_secs(5); + let rotate_wait = Duration::from_secs(3600); + + assert!( + !should_reap_unfindable_watcher( + true, + Duration::from_millis(1), + discovery_interval, + rotate_wait, + ), + "an idle watcher must not be reaped the instant it's first seen unfindable" + ); + assert!( + !should_reap_unfindable_watcher( + true, + discovery_interval - Duration::from_millis(1), + discovery_interval, + rotate_wait, + ), + "an idle watcher must survive at least one full discovery interval unfindable" + ); + assert!( + should_reap_unfindable_watcher( + true, + discovery_interval + Duration::from_millis(1), + discovery_interval, + rotate_wait, + ), + "an idle watcher must be reaped once it's been unfindable longer than a discovery \ + interval, rather than waiting out the (possibly effectively-infinite) rotate_wait" + ); + } + + #[test] + fn active_unfindable_watcher_keeps_its_rotate_wait_grace_period() { + // The pre-existing behavior for `Active` watchers (which keep getting read, and on EOF + // marked dead, every cycle regardless of this check) must be unchanged: only `rotate_wait` + // governs reaping for them, not `discovery_interval`. + let discovery_interval = Duration::from_secs(5); + let rotate_wait = Duration::from_secs(3600); + + assert!( + !should_reap_unfindable_watcher( + false, + discovery_interval + Duration::from_secs(1), + discovery_interval, + rotate_wait, + ), + "an active watcher must not be reaped just because a discovery interval elapsed" + ); + assert!( + should_reap_unfindable_watcher( + false, + rotate_wait + Duration::from_millis(1), + discovery_interval, + rotate_wait, + ), + "an active watcher must still be reaped once rotate_wait elapses" + ); + } + + #[test] + fn absolutize_leaves_absolute_paths_unchanged() { + let cwd = PathBuf::from("/home/user/project"); + let absolute = PathBuf::from("/var/log/app.log"); + assert_eq!( + absolutize_for_notify_comparison(&absolute, Some(&cwd)), + absolute + ); + } + + #[test] + fn absolutize_joins_relative_paths_onto_cwd() { + // Regression test for a bug found in review: `notify` always resolves the path it's + // asked to `watch()` to an absolute one internally (via the current working directory) + // before using it in the events it reports, but `Glob::paths()` (paths_provider.rs) can + // yield a relative path unchanged when the configured `include` pattern is itself + // relative (e.g. `include: ["logs/*.log"]`). Comparing such a relative path directly + // against notify's absolute event path -- as `NotifyWakeup::names` used to do -- would + // never match, silently defeating `mark_ready_to_read`'s nudge for every file matched by + // a relative `include` pattern, delaying their reads until the next backoff/backstop tick + // instead of the promised prompt notify wakeup. + let cwd = PathBuf::from("/home/user/project"); + let relative = PathBuf::from("logs/app.log"); + assert_eq!( + absolutize_for_notify_comparison(&relative, Some(&cwd)), + PathBuf::from("/home/user/project/logs/app.log") + ); + } + + #[test] + fn absolutize_falls_back_to_the_relative_path_when_cwd_is_unknown() { + // If `std::env::current_dir()` itself failed, there's no well-defined way to absolutize; + // returning the path unchanged merely reproduces the pre-fix "doesn't match" degradation + // (nudge doesn't fire, `should_read`'s own timers and the periodic backstop still apply) + // rather than introducing a new failure mode (e.g. panicking). + let relative = PathBuf::from("logs/app.log"); + assert_eq!(absolutize_for_notify_comparison(&relative, None), relative); + } + + #[test] + fn notify_wakeup_matches_relative_include_path_once_absolutized() { + // End-to-end regression test for the same bug covered by `absolutize_joins_relative_paths_onto_cwd`, + // exercised through the exact `NotifyWakeup` API `discover` calls: a notify event names an + // absolute path (as `notify` always reports), while the glob-discovered path for the same + // file is relative (as `Glob::paths()` yields for a relative `include` pattern). Without + // absolutizing the glob path first, `names()` would report `false` even though both sides + // refer to the same file. + let cwd = PathBuf::from("/home/user/project"); + let mut wakeup = NotifyWakeup::default(); + wakeup.add_paths([PathBuf::from("/home/user/project/logs/app.log")]); + + let glob_discovered_path = PathBuf::from("logs/app.log"); + assert!( + !wakeup.names(&glob_discovered_path), + "sanity check: comparing the raw relative path against the absolute notify path \ + must not match" + ); + + let absolutized = absolutize_for_notify_comparison(&glob_discovered_path, Some(&cwd)); + assert!( + wakeup.names(&absolutized), + "after absolutizing the glob-discovered relative path the same way notify resolves \ + its own watch paths, it must match the notify-reported absolute path" + ); + } +} diff --git a/lib/file-source/src/file_watcher/mod.rs b/lib/file-source/src/file_watcher/mod.rs index a1d7ded0e8259..27446cbf10062 100644 --- a/lib/file-source/src/file_watcher/mod.rs +++ b/lib/file-source/src/file_watcher/mod.rs @@ -3,7 +3,7 @@ use chrono::{DateTime, Utc}; use std::{ io::{self, SeekFrom}, path::PathBuf, - time::Duration, + time::{Duration, SystemTime}, }; use tokio::{ fs::File, @@ -42,6 +42,78 @@ pub struct RawLineResult { pub discarded_for_size_and_truncated: Vec, } +/// The read-oriented state of a [`FileWatcher`]. +/// +/// `Active` is the traditional, always-has-been state: an open file handle is +/// held and reads are attempted against it. +/// +/// `Idle` is new: no file handle is held at all. This is used both for files +/// which are old/fully-read at discovery time (so we never have to open them) +/// and for files which used to be `Active` but have gone quiet (reached EOF +/// and had no new writes for `idle_timeout`). While `Idle`, the watcher is +/// polled cheaply via `fs::metadata` (no `File::open`) to detect growth, +/// truncation, or deletion, and is transparently promoted back to `Active` +/// (reopening the file and seeking to `file_position`) when new data shows up. +enum WatcherState { + Active { + reader: Box, + reached_eof: bool, + last_read_attempt: Instant, + last_read_success: Instant, + read_retry_delay: Duration, + buf: BytesMut, + }, + Idle { + /// Last known size of the file, as of the last successful stat. + last_known_size: u64, + /// Last known mtime of the file, as of the last successful stat. Used, + /// together with `last_known_size`, to cheaply detect whether the file + /// has been written to (or truncated) since we last looked, without + /// opening it. + last_known_mtime: Option, + /// The time from which this watcher's current idle streak should be measured: either the + /// last successful read before `deactivate` closed the handle (not the later moment + /// `deactivate` itself ran, which would double-count `idle_timeout`), or the time + /// `check_for_new_data` most recently observed a change while already `Idle`. Used by + /// `FileServer` to drive `remove_after`-style grace-period cleanup for idle files, since + /// idle watchers never perform reads and so can't rely on "time since last successful + /// read" the way `Active` watchers do. + idle_since: Instant, + /// Set once `check_for_new_data` ever observes the file shrink while `Idle`, and never + /// cleared until the next `deactivate()` starts a fresh `Idle` period. `reactivate`'s own + /// point-in-time size check (current size vs. `file_position`) alone isn't enough: a + /// truncate followed by a fast refill *past* the old `file_position` (e.g. read up to + /// 1000, truncated to 0, then filled back past 1000 with new content, all before the next + /// poll) looks, at the moment of reactivation, exactly like ordinary growth -- the + /// current size is >= `file_position`, so nothing about that single comparison reveals + /// that a truncation happened in between. Remembering that *some* poll along the way saw + /// a shrink, even if the file has since grown past the old position again, is what lets + /// `reactivate` still reset to 0 in that case instead of seeking into what looks like + /// "the same file, just grown" but is actually unrelated new content sharing old bytes' + /// former offsets. + truncated_while_idle: bool, + /// Set by `invalidate_idle_bookkeeping` to force the next `check_for_new_data` call to + /// report `changed`, regardless of what it actually observes -- see that function's doc + /// comment for why. Deliberately a separate flag rather than clobbering + /// `last_known_size`/`last_known_mtime` with an impossible sentinel (an earlier version of + /// this did that): doing so destroys the one real baseline `check_for_new_data`'s own + /// shrink detection needs, so a genuine truncation occurring *after* the sentinel was set + /// but *before* the next poll would go completely undetected -- not just fail to latch + /// `truncated_while_idle`, but be invisible to the size comparison entirely, since there's + /// no longer a real "last known size" for the new, smaller size to compare against. + /// Keeping the real baseline intact and layering this flag on top lets `check_for_new_data` + /// still correctly detect a real shrink on the very poll that also honors the forced + /// retry, instead of having to choose between the two. + force_recheck: bool, + /// A line that was buffered but never saw its delimiter before `deactivate` closed the + /// handle, kept (with its starting offset) so `take_final_partial_line` can salvage it if + /// this watcher is reaped while still `Idle`, without ever reactivating. Ignored by + /// `reactivate` itself: `deactivate` already rewinds `file_position` behind these bytes, + /// so a successful reactivation just re-reads them from disk. + pending_partial_line: Option<(FilePosition, Bytes)>, + }, +} + /// The `FileWatcher` struct defines the polling based state machine which reads /// from a file path, transparently updating the underlying file descriptor when /// the file has been rolled over, as is common for logs. @@ -52,19 +124,37 @@ pub struct RawLineResult { pub struct FileWatcher { pub path: PathBuf, findable: bool, - reader: Box, + state: WatcherState, file_position: FilePosition, - devno: u64, - inode: u64, + /// Device and inode of the underlying file, once known. `None` only for a + /// watcher that started `Idle` and has never been opened: there is no + /// portable way to learn a file's identity without a handle + /// (`GetFileInformationByHandle` is required even on Windows), so we + /// can't populate this until the first `reactivate`/`update_path` open. + /// Callers that need identity to detect renames (`update_path`) already + /// treat "identity unknown" the same as "identity changed", which is the + /// correct, safe behavior: it forces a fresh open rather than risking a + /// stale-offset read against the wrong file. + identity: Option<(u64, u64)>, + /// Whether the current gzip stream (if any) was deliberately left unread, rather than being + /// positioned wherever it is because we've actually decoded up to that point. Distinct from + /// "`file_position == 0`," which is ambiguous: `0` also means "haven't decoded anything yet + /// because we're about to start at the beginning," a completely different situation this flag + /// exists so `reactivate` can tell apart. Set whenever `FileWatcher::new`/`reactivate`/ + /// `update_path` choose a null reader over the real gzip decoder (an already-compressed file + /// with `read_from: end`, or with `read_from: checkpoint` pointing at a non-zero -- and thus + /// unresumable -- gzip byte offset); cleared whenever they instead install a real decoder. + /// Without this, an idle gzip watcher skipped via `read_from: end` (file position ends up `0`, + /// same as "start of file") gets misread on reactivation as "never started decoding, so start + /// decoding from the beginning," installing a real decoder and emitting the entire backlog + /// that `read_from: end` was supposed to skip -- even though nothing about a mere mtime bump + /// means the file is safe to resume decoding (gzip streams can't be resumed from an arbitrary + /// point anyway, which is exactly why this was skipped in the first place). + gzip_read_skipped: bool, is_dead: bool, - reached_eof: bool, - last_read_attempt: Instant, - last_read_success: Instant, - read_retry_delay: Duration, last_seen: Instant, max_line_bytes: usize, line_delimiter: Bytes, - buf: BytesMut, } impl FileWatcher { @@ -73,13 +163,96 @@ impl FileWatcher { /// The input path will be used by `FileWatcher` to prime its state /// machine. A `FileWatcher` tracks _only one_ file. This function returns /// None if the path does not exist or is not readable by the current process. + /// + /// If the file is old enough to be excluded by `ignore_before` and its size + /// on disk already matches the position we'd resume reading from (i.e. + /// there's no new data waiting), and `idle_on_startup` is `true`, the file + /// is *not* opened at all: the watcher starts in the `Idle` state, holding + /// no file handle. This is the core of the fix for + /// https://github.com/vectordotdev/vector/issues/3567, where a large + /// number of `ignore_older`-excluded files would otherwise each hold open + /// an unused file handle for as long as they existed on disk. + /// + /// `idle_on_startup` should be `false` whenever `FileServer::idle_timeout` + /// is `None` (the user has explicitly opted out of idle-handle-closing + /// entirely): without gating this fast path on it too, an + /// `ignore_older`-excluded file would still start `Idle` at discovery + /// time regardless of `idle_timeout`, since this startup path is a + /// separate mechanism from the runtime `deactivate()` transition that + /// `idle_timeout` alone controls -- silently defeating the documented + /// promise that `idle_timeout: null` restores the prior always-open + /// behavior. pub async fn new( path: PathBuf, read_from: ReadFrom, ignore_before: Option>, max_line_bytes: usize, line_delimiter: Bytes, + idle_on_startup: bool, ) -> Result { + // Cheap stat-only pass first. This lets us avoid ever calling + // `File::open` for files that are both old (per `ignore_before`) and + // fully read already (size == checkpointed position), which is + // exactly the "12,000 idle files" scenario from #3567. + let stat = tokio::fs::metadata(&path).await?; + let modified_time = stat.modified().ok(); + let too_old = + if let (Some(ignore_before), Some(modified_time)) = (ignore_before, modified_time) { + DateTime::::from(modified_time) < ignore_before + } else { + false + }; + + if too_old && idle_on_startup { + // For a *non-gzip* file that's too old, the read position ends up + // being the same regardless of `read_from`: `(false, true, _)` + // below always seeks straight to EOF unconditionally, ignoring + // `Beginning`/`End`, and even a `Checkpoint` position that + // doesn't match the current size. So the only thing we need + // before we can decide to stay closed is confirming the file + // isn't gzip: a gzip file's "too old" handling starts back at + // position 0 rather than EOF (`(true, true, _)` below), so those + // still need the full open+decode path to get that right. + let gzip_check = peek_is_gzipped(&path).await; + if let Some(false) = gzip_check { + debug!( + message = "Starting file watcher in idle state; no unread data and file is older than `ignore_older`.", + ?path, + file_position = %stat.len(), + ); + return Ok(FileWatcher { + path, + findable: true, + state: WatcherState::Idle { + last_known_size: stat.len(), + last_known_mtime: modified_time, + idle_since: Instant::now(), + truncated_while_idle: false, + force_recheck: false, + pending_partial_line: None, + }, + file_position: stat.len(), + // We haven't kept the file open, so we don't yet know its + // dev/inode; the first reopen (triggered by the + // idle->active transition, or by `update_path` on a + // rename) will populate it. + identity: None, + // Confirmed non-gzip by `gzip_check` above. + gzip_read_skipped: false, + is_dead: false, + last_seen: Instant::now(), + max_line_bytes, + line_delimiter, + }); + } + // Either it's gzip (needs the full open+decode path below to get + // position 0 vs EOF right) or the file vanished/became + // unreadable between the stat above and `peek_is_gzipped`'s open + // (`gzip_check` is `None`) -- either way, fall through to the + // normal open path, which handles both correctly (and will + // surface a real error for the latter case). + } + let f = File::open(&path).await?; let file_info = f.file_info().await?; let (devno, ino) = (file_info.portable_dev(), file_info.portable_ino()); @@ -91,66 +264,62 @@ impl FileWatcher { let mut reader = BufReader::new(f); - let too_old = if let (Some(ignore_before), Ok(modified_time)) = ( - ignore_before, - metadata.modified().map(DateTime::::from), - ) { - modified_time < ignore_before - } else { - false - }; - let gzipped = is_gzipped(&mut reader).await?; // Determine the actual position at which we should start reading - let (reader, file_position): (Box, FilePosition) = - match (gzipped, too_old, read_from) { - (true, true, _) => { - debug!( - message = "Not reading gzipped file older than `ignore_older`.", - ?path, - ); - (Box::new(null_reader()), 0) - } - (true, _, ReadFrom::Checkpoint(file_position)) => { - debug!( - message = "Not re-reading gzipped file with existing stored offset.", - ?path, - %file_position - ); - (Box::new(null_reader()), file_position) - } - // TODO: This may become the default, leading us to stop reading gzipped files that - // we were reading before. Should we merge this and the next branch to read - // compressed file from the beginning even when `read_from = "end"` (implicitly via - // default or explicitly via config)? - (true, _, ReadFrom::End) => { - debug!( - message = "Can't read from the end of already-compressed file.", - ?path, - ); - (Box::new(null_reader()), 0) - } - (true, false, ReadFrom::Beginning) => { - (Box::new(BufReader::new(gzip_multiple_decoder(reader))), 0) - } - (false, true, _) => { - let pos = reader.seek(SeekFrom::End(0)).await.unwrap(); - (Box::new(reader), pos) - } - (false, false, ReadFrom::Checkpoint(file_position)) => { - let pos = reader.seek(SeekFrom::Start(file_position)).await.unwrap(); - (Box::new(reader), pos) - } - (false, false, ReadFrom::Beginning) => { - let pos = reader.seek(SeekFrom::Start(0)).await.unwrap(); - (Box::new(reader), pos) - } - (false, false, ReadFrom::End) => { - let pos = reader.seek(SeekFrom::End(0)).await.unwrap(); - (Box::new(reader), pos) - } - }; + let (reader, file_position, gzip_read_skipped): ( + Box, + FilePosition, + bool, + ) = match (gzipped, too_old, read_from) { + (true, true, _) => { + debug!( + message = "Not reading gzipped file older than `ignore_older`.", + ?path, + ); + (Box::new(null_reader()), 0, true) + } + (true, _, ReadFrom::Checkpoint(file_position)) => { + debug!( + message = "Not re-reading gzipped file with existing stored offset.", + ?path, + %file_position + ); + (Box::new(null_reader()), file_position, true) + } + // TODO: This may become the default, leading us to stop reading gzipped files that + // we were reading before. Should we merge this and the next branch to read + // compressed file from the beginning even when `read_from = "end"` (implicitly via + // default or explicitly via config)? + (true, _, ReadFrom::End) => { + debug!( + message = "Can't read from the end of already-compressed file.", + ?path, + ); + (Box::new(null_reader()), 0, true) + } + (true, false, ReadFrom::Beginning) => ( + Box::new(BufReader::new(gzip_multiple_decoder(reader))), + 0, + false, + ), + (false, true, _) => { + let pos = reader.seek(SeekFrom::End(0)).await.unwrap(); + (Box::new(reader), pos, false) + } + (false, false, ReadFrom::Checkpoint(file_position)) => { + let pos = reader.seek(SeekFrom::Start(file_position)).await.unwrap(); + (Box::new(reader), pos, false) + } + (false, false, ReadFrom::Beginning) => { + let pos = reader.seek(SeekFrom::Start(0)).await.unwrap(); + (Box::new(reader), pos, false) + } + (false, false, ReadFrom::End) => { + let pos = reader.seek(SeekFrom::End(0)).await.unwrap(); + (Box::new(reader), pos, false) + } + }; let ts = metadata .modified() @@ -162,51 +331,110 @@ impl FileWatcher { Ok(FileWatcher { path, findable: true, - reader, + state: WatcherState::Active { + reader, + reached_eof: false, + last_read_attempt: ts, + last_read_success: ts, + read_retry_delay: EOF_READ_BACKOFF_MIN, + buf: BytesMut::new(), + }, file_position, - devno, - inode: ino, + identity: Some((devno, ino)), + gzip_read_skipped, is_dead: false, - reached_eof: false, - last_read_attempt: ts, - last_read_success: ts, - read_retry_delay: EOF_READ_BACKOFF_MIN, last_seen: ts, max_line_bytes, line_delimiter, - buf: BytesMut::new(), }) } + /// Update the path this watcher tracks after `FileServer`'s glob-rescan + /// detects that the same fingerprint now resolves to a different path + /// (i.e. the file was renamed/rotated). + /// + /// This briefly opens the file to re-verify identity (dev/inode) and, if + /// the identity changed, to determine the correct read position/gzip + /// state for the new path -- there is no portable way to compare file + /// identity without a handle (`GetFileInformationByHandle` is required on + /// Windows even for files we've never read). If the watcher was `Idle` + /// before this call and remains eligible to be idle afterwards (the + /// resolved dev/inode is unchanged, i.e. this was a pure rename with no + /// new data), the handle opened here is not retained: we transition back + /// to `Idle` immediately rather than leaving it `Active`. This keeps a + /// pure rename of an idle file from permanently pinning a handle open, + /// while still guaranteeing we never resume reading a *different* file's + /// content from a stale offset (the concern `update_path` exists to + /// address in the first place). pub async fn update_path(&mut self, path: PathBuf) -> io::Result<()> { + let was_idle = self.is_idle(); + let file_handle = File::open(&path).await?; let file_info = file_handle.file_info().await?; - if (file_info.portable_dev(), file_info.portable_ino()) != (self.devno, self.inode) { + let new_identity = (file_info.portable_dev(), file_info.portable_ino()); + if Some(new_identity) != self.identity { let mut reader = BufReader::new(File::open(&path).await?); let gzipped = is_gzipped(&mut reader).await?; let new_reader: Box = if gzipped { if self.file_position != 0 { + self.gzip_read_skipped = true; Box::new(null_reader()) } else { + self.gzip_read_skipped = false; Box::new(BufReader::new(gzip_multiple_decoder(reader))) } } else { + self.gzip_read_skipped = false; reader.seek(io::SeekFrom::Start(self.file_position)).await?; Box::new(reader) }; - self.reader = new_reader; let file_info = file_handle.file_info().await?; - self.devno = file_info.portable_dev(); - self.inode = file_info.portable_ino(); + self.identity = Some((file_info.portable_dev(), file_info.portable_ino())); + + self.state = WatcherState::Active { + reader: new_reader, + reached_eof: false, + last_read_attempt: Instant::now(), + last_read_success: Instant::now(), + read_retry_delay: EOF_READ_BACKOFF_MIN, + buf: BytesMut::new(), + }; + } else if was_idle { + // Same file (dev/inode unchanged), just renamed, and it was + // `Idle` before we got here: don't let re-verifying identity + // above leave us stuck `Active`. Drop the handle we just opened + // and go straight back to `Idle` under the new path. `deactivate` + // stats `self.path`, so update it first. + drop(file_handle); + self.path = path; + self.deactivate().await; + return Ok(()); + } else if let WatcherState::Active { + reached_eof, + read_retry_delay, + .. + } = &mut self.state + { + *reached_eof = false; + *read_retry_delay = EOF_READ_BACKOFF_MIN; } - self.reached_eof = false; - self.read_retry_delay = EOF_READ_BACKOFF_MIN; self.path = path; Ok(()) } + /// Whether this watcher currently holds an open file handle. + #[inline] + pub fn is_active(&self) -> bool { + matches!(self.state, WatcherState::Active { .. }) + } + + #[inline] + pub fn is_idle(&self) -> bool { + matches!(self.state, WatcherState::Idle { .. }) + } + pub fn set_file_findable(&mut self, f: bool) { self.findable = f; if f { @@ -230,6 +458,372 @@ impl FileWatcher { self.file_position } + /// Cheaply (via `fs::metadata`, no `File::open`) check whether an `Idle` + /// watcher's file has changed since we last looked (grown, shrunk, or had + /// its mtime bumped). Returns `Ok(true)` if the watcher should be promoted + /// back to `Active` (i.e. reopened) by the caller. No-ops (returns + /// `Ok(false)`) for `Active` watchers. + /// + /// This does not perform the reopen itself: `FileServer` calls + /// `reactivate` to do that once it decides to, since the reopen also + /// needs to handle the "the file was replaced by a same-named different + /// file" case, which is otherwise already handled by the fingerprint-based + /// rename detection in `FileServer`. + pub async fn check_for_new_data(&mut self) -> io::Result { + let WatcherState::Idle { + last_known_size, + last_known_mtime, + idle_since, + truncated_while_idle, + force_recheck, + pending_partial_line, + .. + } = &mut self.state + else { + return Ok(false); + }; + + let stat = tokio::fs::metadata(&self.path).await?; + let new_size = stat.len(); + let new_mtime = stat.modified().ok(); + + // The real baseline (`last_known_size`/`last_known_mtime`) is never destroyed to force a + // retry -- see `invalidate_idle_bookkeeping`'s doc comment for why an earlier version of + // this that clobbered it with a sentinel was wrong. So the size/mtime comparison here is + // always a genuine one, and `force_recheck` only affects whether `changed` is reported as + // `true` on top of that; it never suppresses or replaces the real shrink check below. + let sizes_or_mtimes_differ = new_size != *last_known_size || new_mtime != *last_known_mtime; + let changed = sizes_or_mtimes_differ || *force_recheck; + *force_recheck = false; + + // Latch, don't overwrite: a truncate seen on *this* poll must still be remembered even if + // a later poll (or `reactivate`'s own final check) finds the file has since grown back + // past `file_position` again, since that "grown past the old position" state is exactly + // what an ordinary, never-truncated append would also look like. See the field doc on + // `WatcherState::Idle::truncated_while_idle` for why a point-in-time comparison alone, + // taken only at reactivation time, isn't sufficient. This check is against the real + // baseline (never a sentinel), so it correctly fires for a genuine truncation regardless + // of whether `force_recheck` also happens to be set on this same poll. + if new_size < *last_known_size { + *truncated_while_idle = true; + // The pre-truncation offset/bytes no longer correspond to anything on disk. + *pending_partial_line = None; + } + + // Always keep our idle bookkeeping current so that a subsequent + // truncation-then-refill (or vice versa) is still detected relative + // to what we most recently observed. + *last_known_size = new_size; + *last_known_mtime = new_mtime; + if changed { + // Reset the idle clock: something happened, so this file is not + // eligible for idle-driven removal right now even though it's + // about to be promoted back to `Active` by the caller anyway. + *idle_since = Instant::now(); + } + + Ok(changed) + } + + /// Force the next `check_for_new_data` call to report a change, regardless of what it + /// actually observes. + /// + /// Call this after a failed `reactivate()` that followed a `check_for_new_data` reporting + /// `true`. `check_for_new_data` unconditionally records whatever size/mtime it just observed + /// (so that a subsequent truncate-then-refill is still detected relative to the most recent + /// state, not stale pre-truncation values) *before* the caller has had a chance to act on the + /// "changed" result. If the caller's `reactivate()` then fails (e.g. a transient permission + /// or I/O error) and the file doesn't change again in the meantime, the next poll would + /// compare against the size/mtime already recorded from the failed attempt, see no + /// difference, and never retry -- silently stranding the watcher `Idle` with unread data + /// sitting on disk. Setting `force_recheck` guarantees the next poll reports a change and + /// retries, no matter what it actually observes. + /// + /// Deliberately does *not* touch `last_known_size`/`last_known_mtime` (an earlier version of + /// this clobbered `last_known_size` with an impossible `u64::MAX` sentinel instead of using a + /// separate flag). Destroying the real baseline that way meant a genuine truncation occurring + /// *after* this was called but *before* the next poll would be completely undetectable on + /// that poll: `check_for_new_data`'s shrink comparison has nothing real left to compare the + /// new, smaller size against, since the "last known size" it would be comparing against is + /// itself a fabricated value, not the file's actual prior size. Keeping the real baseline + /// intact and layering `force_recheck` on top instead lets `check_for_new_data` still + /// correctly detect a real shrink on the very poll that also honors this forced retry. + /// + /// No-op if the watcher isn't `Idle` (e.g. it was already promoted back to `Active` by the + /// time this is called). + pub fn invalidate_idle_bookkeeping(&mut self) { + if let WatcherState::Idle { force_recheck, .. } = &mut self.state { + *force_recheck = true; + } + } + + /// Promote an `Idle` watcher back to `Active`: (re)open the file and seek + /// to `file_position`. Also handles (re-)detecting gzip compression, + /// since that detection was deferred when we skipped the initial open. + /// + /// If the reopened file's identity (dev/inode) doesn't match what this watcher *previously + /// confirmed by having actually opened the file* (i.e. `self.identity` was `Some`, not + /// `None`), the file at this path has been replaced since we went idle: the same-path + /// rotation case (`discover`'s fingerprint-based rename detection only catches renames, i.e. + /// a path change; a rewrite-in-place under an unchanged path -- possible if the new content's + /// fingerprint happens to collide with the old one, since the default strategy only hashes + /// the first line -- looks identical to "nothing happened" from `discover`'s point of view). + /// In that case we must not seek to the stale `file_position`: it's a byte offset into a file + /// that no longer exists, so seeking to it on the new file would silently skip (if the new + /// file is longer) or read nothing until it grows past that point (if shorter) -- either way + /// losing the new file's opening bytes. Start over from position 0 instead. + /// + /// A `self.identity` of `None`, by contrast, means this watcher has *never* opened the file: + /// it started `Idle` straight out of `FileWatcher::new`'s startup fast path for an + /// `ignore_older`-excluded file, without ever confirming any identity at all. That's not + /// evidence of a replacement -- it's simply "unconfirmed" -- so unlike a real identity + /// mismatch, it must not reset `file_position`: doing so would re-read a file's entire old + /// content (which `ignore_older` deliberately skipped) the very first time it receives new + /// data, since `file_position` in that case holds the file's size *as of discovery*, not a + /// checkpoint from a previous read. This reactivation is simply the first time we're + /// confirming identity, not a change of it. + /// + /// **Known limitation**, an accepted trade-off of the startup fast path rather than something + /// this function can fix on its own: because a never-opened watcher has no identity to compare + /// against, this function cannot distinguish "an `ignore_older`-excluded file received its + /// first append" from "that file was replaced (not renamed) by a different, larger file at + /// the same path, whose content happens to fingerprint identically to the old one under the + /// default first-line-only strategy" before its first reactivation. The former (by far the + /// common case) requires resuming from the retained `file_position`; the latter would need + /// resuming from 0. Since a replacement can't be told apart from a growth here, and 0 would be + /// wrong far more often (re-sending the entire skipped backlog on every single first + /// reactivation, defeating the point of the fast path), this function assumes growth. Getting + /// this case exactly right would require either opening the file at startup after all + /// (eliminating the fast path this exists to provide) or a fingerprinting strategy strong + /// enough to make same-content-prefix collisions practically impossible, neither of which is + /// a change this function is positioned to make locally. + /// + /// Separately, even when the identity is unchanged (the same inode is still at this path -- + /// no rename/replace happened), the file can still have been truncated in place while idle + /// (e.g. `logrotate`'s `copytruncate`, or an application that truncates and rewrites its own + /// log). A truncation must reset `file_position` to 0 just as a real identity change does -- + /// seeking to a stale `file_position` on a file that's been truncated (whether or not it's + /// since grown back past that same offset with unrelated new content) means either seeking + /// past EOF (silently losing everything written until the file grows past the old position + /// again) or, worse, silently reading unrelated new bytes as if they were a continuation of + /// the old content. This is why `truncated_while_idle` is a latch set by `check_for_new_data` + /// across the *whole* idle period rather than something `reactivate` could reliably re-derive + /// from a single point-in-time size comparison of its own: a truncate observed by one poll, + /// followed by a refill past the old `file_position` observed by a later poll, would otherwise + /// look identical to ordinary growth by the time `reactivate` gets a chance to look. + /// + /// **Known limitation**: this still can't help if the truncate *and* the regrowth both happen + /// between two polls, with neither `check_for_new_data` call ever independently observing the + /// intermediate (truncated) state -- there is, at that point, no state left on disk to detect + /// it from after the fact. This is a fundamental limit of polling for changes, not something + /// specific to this idle-handle-closing mechanism: `file_discovery_mode: polling`'s pre-existing + /// handling of *active* (never-idle) files has the same blind spot for a within-one-interval + /// truncate-then-refill, and no polling-based approach (as opposed to synchronous OS-level + /// notification of every write, which isn't what `fs::metadata`-based polling provides even + /// under `file_discovery_mode: notify`, since that only wakes up the same poll sooner, it + /// doesn't add fidelity to what a single poll can observe) can close this gap. + /// + /// No-op if the watcher is already `Active`. + pub async fn reactivate(&mut self) -> io::Result<()> { + if self.is_active() { + return Ok(()); + } + + let truncated_while_idle = matches!( + self.state, + WatcherState::Idle { + truncated_while_idle: true, + .. + } + ); + + let f = File::open(&self.path).await?; + let file_info = f.file_info().await?; + let new_identity = (file_info.portable_dev(), file_info.portable_ino()); + let identity_changed = matches!(self.identity, Some(old) if old != new_identity); + self.identity = Some(new_identity); + // Also fall back to a direct, final check against the file we just opened: this covers + // reactivation paths that don't go through `check_for_new_data` first (e.g. a caller that + // calls `reactivate` directly, as some tests do), where `truncated_while_idle` was never + // given a chance to latch. + let truncated_at_reactivation = f + .metadata() + .await + .is_ok_and(|m| m.len() < self.file_position); + if identity_changed { + debug!( + message = "Idle watcher's file identity changed on reactivation; \ + the file at this path was replaced while idle. Resuming \ + from the start rather than the stale checkpoint offset.", + path = ?self.path, + ); + self.file_position = 0; + // A different file is now at this path: whatever was true of the old file's gzip + // stream (skipped or not) says nothing about this one, which we haven't looked at + // yet. Clear the flag so the check below falls through to installing a real decoder, + // the same as `FileWatcher::new` would for a freshly-discovered gzip file. + self.gzip_read_skipped = false; + } else if truncated_while_idle || truncated_at_reactivation { + debug!( + message = "Idle watcher's file was truncated in place while idle (same \ + identity). Resuming from the start rather than seeking past \ + stale, since-invalidated content.", + path = ?self.path, + ); + self.file_position = 0; + // Same reasoning as the identity-changed case above: the truncated content + // invalidates whatever "skipped" state applied to the pre-truncation stream. + self.gzip_read_skipped = false; + } + + let mut reader = BufReader::new(f); + let gzipped = is_gzipped(&mut reader).await?; + + let (reader, file_position, gzip_read_skipped): ( + Box, + FilePosition, + bool, + ) = if gzipped { + if self.gzip_read_skipped || self.file_position != 0 { + // Either this gzip stream was deliberately left unread (e.g. `read_from: end` + // skipped it entirely, leaving `file_position` at `0`) rather than actually + // decoded up to `file_position` -- a mtime/size change alone doesn't make it safe + // to resume, since gzip streams can't be resumed from an arbitrary offset + // regardless, which is exactly why this was skipped in the first place -- or + // `file_position` is genuinely non-zero, which is the pre-existing "can't resume + // a gzip stream from an arbitrary byte offset" case. Either way, behave like the + // "already read, ignore" case `FileWatcher::new` uses for gzip + checkpoint. + (Box::new(null_reader()), self.file_position, true) + } else { + ( + Box::new(BufReader::new(gzip_multiple_decoder(reader))), + 0, + false, + ) + } + } else { + // Propagate a seek failure instead of pretending it succeeded: swallowing it (an + // earlier version of this used `.unwrap_or(self.file_position)`) would report the + // stale checkpoint offset as the new position while the reader's actual cursor stays + // wherever `is_gzipped`'s `fill_buf` peek left it -- typically near the start of the + // file, not `self.file_position` -- so the watcher would go `Active` and immediately + // start reading from the wrong place: duplicating old content under the wrong + // offsets, or skipping data, depending on which is larger. Letting this error surface + // instead leaves the watcher `Idle` (this function's caller, `poll_idle_watchers`, + // already retries via `invalidate_idle_bookkeeping` on any `Err`), which is a strictly + // safer outcome than silently reading from an unknown position. + let pos = reader.seek(SeekFrom::Start(self.file_position)).await?; + (Box::new(reader), pos, false) + }; + self.gzip_read_skipped = gzip_read_skipped; + + self.file_position = file_position; + self.state = WatcherState::Active { + reader, + reached_eof: false, + last_read_attempt: Instant::now(), + last_read_success: Instant::now(), + read_retry_delay: EOF_READ_BACKOFF_MIN, + buf: BytesMut::new(), + }; + + debug!( + message = "File watcher reactivated from idle state.", + path = ?self.path, + file_position = %self.file_position, + ); + + Ok(()) + } + + /// Transition an `Active` watcher to `Idle`, closing its file handle. + /// No-op if already `Idle`. + pub async fn deactivate(&mut self) { + let WatcherState::Active { + buf, + last_read_success, + .. + } = &self.state + else { + return; + }; + // Preserve the time of the last successful read (i.e. last-observed activity), not + // "now" (the moment of deactivation): `FileServer` only calls `deactivate` once a watcher + // has already been sitting EOF'd and quiet for `idle_timeout`, so by the time we get here + // `last_read_success` is already well in the past. Stamping `idle_since` with `Instant::now()` + // instead would silently add another `idle_timeout`'s worth of delay on top of the + // documented `remove_after`-since-EOF grace period every time `remove_after_secs` exceeds + // `idle_timeout_secs`. + let idle_since = *last_read_success; + + // `buf` holds bytes already consumed from the reader (and counted + // into `file_position`) for a line that hasn't seen its delimiter + // yet -- `read_until_with_max_size` advances `position` for every + // byte it reads into `buf`, delimiter or not, on the assumption that + // the very next call will pick up exactly where it left off and + // eventually complete the line. Idle-izing throws `buf` away (it's + // part of the `Active` state we're about to replace), so unless we + // rewind `file_position` back behind those bytes here, `reactivate` + // would resume reading *after* them: the partial line would never be + // completed, and its bytes -- still sitting on disk -- would simply + // never be read. Rewinding means we'll read them again from disk + // once new data (including, at minimum, this file's own trailing + // delimiter) shows up, same as if we'd never buffered them at all. + // Saturating, not a bare subtraction: if the file was truncated out + // from under an `Active` read (a pre-existing sharp edge of file + // watching in general, not something this rewind introduces), the + // buffered byte count could in principle exceed `file_position`. In + // that case there's nothing meaningful to rewind to; clamping to 0 + // is at least as safe as what an in-progress read would already be + // dealing with (`read_until_with_max_size` doesn't special-case + // mid-read truncation either). + // + // Also clone the buffered bytes themselves (not just their count) before rewinding: + // `pending_partial_line` retains them, paired with the offset they started at (i.e. + // `file_position` *before* the rewind below), purely so `FileServer` can salvage them as + // a final record if this watcher is later reaped while still `Idle` -- see that field's + // doc comment for why an `Idle` watcher has no other way to flush them, unlike an + // `Active` one. A no-op clone (empty `Bytes`) when there's nothing buffered. + let unterminated_bytes = buf.len() as u64; + let rewound_file_position = self.file_position.saturating_sub(unterminated_bytes); + let pending_partial_line = if buf.is_empty() { + None + } else { + Some((rewound_file_position, buf.clone().freeze())) + }; + self.file_position = rewound_file_position; + + // Best-effort stat so our idle bookkeeping starts accurate; if this + // fails (e.g. file was just deleted) fall back to what we already + // know from `file_position`, which will simply cause the next + // `check_for_new_data` poll to treat any discrepancy as "changed", + // which is a safe (if slightly wasteful) default. + let (last_known_size, last_known_mtime) = match tokio::fs::metadata(&self.path).await { + Ok(stat) => (stat.len(), stat.modified().ok()), + Err(_) => (self.file_position, None), + }; + + debug!( + message = "File watcher deactivated to idle state; file handle closed.", + path = ?self.path, + file_position = %self.file_position, + rewound_unterminated_bytes = %unterminated_bytes, + ); + + self.state = WatcherState::Idle { + last_known_size, + last_known_mtime, + idle_since, + // A fresh Idle period starts here: `file_position` above already reflects the + // buffered-but-unterminated-line rewind (if any), which is a correction to where we + // resume reading, not evidence the file itself was truncated on disk. There's nothing + // yet for a subsequent `check_for_new_data` poll to have observed shrinking. + truncated_while_idle: false, + force_recheck: false, + pending_partial_line, + }; + } + /// Read a single line from the underlying file /// /// This function will attempt to read a new line from its file, blocking, @@ -238,27 +832,43 @@ impl FileWatcher { pub(super) async fn read_line(&mut self) -> io::Result { self.track_read_attempt(); - let reader = &mut self.reader; - let file_position = &mut self.file_position; - let initial_position = *file_position; - match read_until_with_max_size( + let WatcherState::Active { reader, buf, .. } = &mut self.state else { + // Should not be called while idle; `FileServer` gates calls to + // `read_line` on `should_read`, which is false for idle watchers. + return Ok(RawLineResult { + raw_line: None, + discarded_for_size_and_truncated: Vec::new(), + }); + }; + + let initial_position = self.file_position; + let read_result = read_until_with_max_size( reader.as_mut(), - file_position, + &mut self.file_position, self.line_delimiter.as_ref(), - &mut self.buf, + buf, self.max_line_bytes, ) - .await - { + .await; + // The borrow of `self.state` (via `reader`/`buf` above) ends here, + // once `read_until_with_max_size` returns; everything below is free + // to borrow `self` again, including re-matching on `self.state` to + // get at `buf`/`reached_eof`, which is guaranteed to still be + // `Active` since nothing else runs concurrently on this watcher. + match read_result { Ok(ReadResult { successfully_read: Some(_), discarded_for_size_and_truncated, }) => { + let WatcherState::Active { buf, .. } = &mut self.state else { + unreachable!("state is Active: nothing transitions it mid-read") + }; + let bytes = buf.split().freeze(); self.track_read_success(); Ok(RawLineResult { raw_line: Some(RawLine { offset: initial_position, - bytes: self.buf.split().freeze(), + bytes, }), discarded_for_size_and_truncated, }) @@ -272,10 +882,16 @@ impl FileWatcher { // File has been deleted, so return what we have in the buffer, even though it // didn't end with a newline. This is not a perfect signal for when we should // give up waiting for a newline, but it's decent. - let buf = self.buf.split().freeze(); + let WatcherState::Active { + buf, reached_eof, .. + } = &mut self.state + else { + unreachable!("state is Active: nothing transitions it mid-read") + }; + let buf = buf.split().freeze(); if buf.is_empty() { // EOF - self.reached_eof = true; + *reached_eof = true; Ok(RawLineResult { raw_line: None, discarded_for_size_and_truncated, @@ -308,42 +924,114 @@ impl FileWatcher { #[inline] fn track_read_attempt(&mut self) { - self.last_read_attempt = Instant::now(); + if let WatcherState::Active { + last_read_attempt, .. + } = &mut self.state + { + *last_read_attempt = Instant::now(); + } } #[inline] fn track_read_success(&mut self) { - self.reached_eof = false; - self.read_retry_delay = EOF_READ_BACKOFF_MIN; - self.last_read_success = Instant::now(); + if let WatcherState::Active { + reached_eof, + read_retry_delay, + last_read_success, + .. + } = &mut self.state + { + *reached_eof = false; + *read_retry_delay = EOF_READ_BACKOFF_MIN; + *last_read_success = Instant::now(); + } } #[inline] fn track_read_eof(&mut self) { - self.read_retry_delay = if self.reached_eof { - std::cmp::min( - self.read_retry_delay.saturating_mul(2), - EOF_READ_BACKOFF_MAX, - ) - } else { - EOF_READ_BACKOFF_MIN - }; - self.reached_eof = true; + if let WatcherState::Active { + reached_eof, + read_retry_delay, + .. + } = &mut self.state + { + *read_retry_delay = if *reached_eof { + std::cmp::min(read_retry_delay.saturating_mul(2), EOF_READ_BACKOFF_MAX) + } else { + EOF_READ_BACKOFF_MIN + }; + *reached_eof = true; + } } + /// Time of the last successful read. For `Idle` watchers (which cannot be + /// actively reading), this is always "now", so that `remove_after`-style + /// grace-period logic in `FileServer` does not immediately consider an + /// idle file eligible for removal purely because it went idle; removal + /// eligibility for idle files is instead driven by `last_seen`/findability + /// via the normal glob-rescan path. #[inline] pub fn last_read_success(&self) -> Instant { - self.last_read_success + match &self.state { + WatcherState::Active { + last_read_success, .. + } => *last_read_success, + WatcherState::Idle { .. } => Instant::now(), + } + } + + /// Clear any backoff/throttle state so the very next `should_read` check returns `true` + /// (unless the watcher is `Idle`, which this is a no-op for). Call this when an external + /// signal (a notify filesystem event naming this watcher's path) indicates new data may be + /// available, so `should_read`'s EOF backoff and quiet-file throttle -- both of which exist to + /// pace *unprompted* polling -- don't delay a read that a concrete signal just justified. + /// + /// Without this, a notify event arriving for a watcher that: (a) is mid-EOF-backoff (up to + /// `EOF_READ_BACKOFF_MAX` = 250ms stale), or (b) has been quiet for over 10 seconds and was + /// merely polled (not necessarily successfully) within the last 10 seconds -- the "throttle + /// further attempts to once per 10s" branch of `should_read` -- would still have its read + /// suppressed until that independent timer elapsed on its own, defeating notify mode's promise + /// of prompt wakeups for however long is left on it. + #[inline] + pub fn mark_ready_to_read(&mut self) { + if let WatcherState::Active { + reached_eof, + last_read_attempt, + read_retry_delay, + .. + } = &mut self.state + { + *reached_eof = false; + *read_retry_delay = EOF_READ_BACKOFF_MIN; + // Back-date rather than leaving as-is: `should_read`'s quiet-file throttle requires + // `last_read_attempt.elapsed() > 10s` as one of its two ways to pass, so simply + // clearing `reached_eof` isn't sufficient on its own to guarantee the very next check + // passes. + *last_read_attempt = Instant::now() - Duration::from_secs(11); + } } #[inline] pub fn should_read(&self) -> bool { - if self.reached_eof && self.last_read_attempt.elapsed() < self.read_retry_delay { + let WatcherState::Active { + reached_eof, + last_read_attempt, + last_read_success, + read_retry_delay, + .. + } = &self.state + else { + // Idle watchers hold no reader; `FileServer` polls them via + // `check_for_new_data` on the glob-rescan cadence instead. + return false; + }; + + if *reached_eof && last_read_attempt.elapsed() < *read_retry_delay { return false; } - self.last_read_success.elapsed() < Duration::from_secs(10) - || self.last_read_attempt.elapsed() > Duration::from_secs(10) + last_read_success.elapsed() < Duration::from_secs(10) + || last_read_attempt.elapsed() > Duration::from_secs(10) } #[inline] @@ -353,7 +1041,62 @@ impl FileWatcher { #[inline] pub fn reached_eof(&self) -> bool { - self.reached_eof + matches!( + self.state, + WatcherState::Active { + reached_eof: true, + .. + } + ) + } + + /// How long it has been since this watcher last successfully read data + /// while `Active`, or since it became `Active` if it has never + /// successfully read anything yet. Used by `FileServer` to decide when an + /// `Active`-but-quiet watcher should be moved to `Idle`. + #[inline] + pub fn idle_for(&self) -> Option { + match &self.state { + WatcherState::Active { + last_read_success, .. + } => Some(last_read_success.elapsed()), + WatcherState::Idle { .. } => None, + } + } + + /// How long this watcher has been sitting in the `Idle` state without any + /// detected change (growth, truncation, or mtime bump). `None` if the + /// watcher is `Active`. Used to drive `remove_after`-style cleanup for + /// idle files. + #[inline] + pub fn idle_since(&self) -> Option { + match &self.state { + WatcherState::Idle { idle_since, .. } => Some(idle_since.elapsed()), + WatcherState::Active { .. } => None, + } + } + + /// Take the unterminated line this watcher is holding onto, if any (buffered-but-undelimited + /// bytes, for either `Active` or `Idle`). Call this right before permanently reaping a watcher + /// via a path that doesn't already go through `read_line` (which has its own flush for the + /// `Active` case) -- otherwise these bytes are lost for good. + pub fn take_final_partial_line(&mut self) -> Option { + match &mut self.state { + WatcherState::Idle { + pending_partial_line, + .. + } => pending_partial_line + .take() + .map(|(offset, bytes)| RawLine { offset, bytes }), + WatcherState::Active { buf, .. } => { + if buf.is_empty() { + return None; + } + let bytes = buf.split().freeze(); + let offset = self.file_position - bytes.len() as u64; + Some(RawLine { offset, bytes }) + } + } } } @@ -364,6 +1107,24 @@ async fn is_gzipped(r: &mut BufReader) -> io::Result { Ok(header_bytes.starts_with(GZIP_MAGIC)) } +/// Cheaply check whether a file starts with the gzip magic bytes, opening and +/// immediately closing it rather than keeping a `FileWatcher`-owned handle +/// around. Used by the `too_old` fast path in `FileWatcher::new` to decide +/// whether a file can safely start `Idle` without going through the full +/// open-and-decode path below: unlike a fully-open `FileWatcher`, this never +/// outlives the single `.await` here, so it doesn't reintroduce the +/// long-lived handle the `Idle` state exists to avoid. +/// +/// Returns `Ok(None)` if the file couldn't be opened or read (e.g. deleted or +/// permissions changed since the earlier `fs::metadata` call); callers should +/// treat that the same as "unknown, fall back to the full open path" rather +/// than assuming either gzip or not. +async fn peek_is_gzipped(path: &std::path::Path) -> Option { + let f = File::open(path).await.ok()?; + let mut reader = BufReader::new(f); + is_gzipped(&mut reader).await.ok() +} + fn null_reader() -> impl AsyncBufRead { io::Cursor::new(Vec::new()) } diff --git a/lib/file-source/src/file_watcher/tests/experiment.rs b/lib/file-source/src/file_watcher/tests/experiment.rs index 15bb8dcdc6bc8..c080e41db22b5 100644 --- a/lib/file-source/src/file_watcher/tests/experiment.rs +++ b/lib/file-source/src/file_watcher/tests/experiment.rs @@ -34,6 +34,7 @@ async fn experiment(actions: Vec) { None, 100_000, Bytes::from("\n"), + true, ) .await .expect("must be able to create"); diff --git a/lib/file-source/src/file_watcher/tests/experiment_no_truncations.rs b/lib/file-source/src/file_watcher/tests/experiment_no_truncations.rs index 935df9299541c..92f2f441c6407 100644 --- a/lib/file-source/src/file_watcher/tests/experiment_no_truncations.rs +++ b/lib/file-source/src/file_watcher/tests/experiment_no_truncations.rs @@ -22,6 +22,7 @@ async fn experiment_no_truncations(actions: Vec) { None, 100_000, Bytes::from("\n"), + true, ) .await .expect("must be able to create"); diff --git a/lib/file-source/src/file_watcher/tests/mod.rs b/lib/file-source/src/file_watcher/tests/mod.rs index 08ac75e6e020c..ee74590f1ffad 100644 --- a/lib/file-source/src/file_watcher/tests/mod.rs +++ b/lib/file-source/src/file_watcher/tests/mod.rs @@ -7,7 +7,7 @@ use bytes::{Bytes, BytesMut}; use quickcheck::{Arbitrary, Gen}; use tokio::time::Instant; -use super::{EOF_READ_BACKOFF_MAX, EOF_READ_BACKOFF_MIN, FileWatcher, null_reader}; +use super::{EOF_READ_BACKOFF_MAX, EOF_READ_BACKOFF_MIN, FileWatcher, WatcherState, null_reader}; // Welcome. // @@ -201,6 +201,7 @@ async fn gzip_multi_stream_reads_all_members() { None, 100_000, Bytes::from("\n"), + true, ) .await .expect("FileWatcher::new failed"); @@ -226,19 +227,30 @@ fn watcher_for_timing() -> FileWatcher { FileWatcher { path: PathBuf::new(), findable: true, - reader: Box::new(null_reader()), + state: WatcherState::Active { + reader: Box::new(null_reader()), + reached_eof: false, + last_read_attempt: now, + last_read_success: now, + read_retry_delay: EOF_READ_BACKOFF_MIN, + buf: BytesMut::new(), + }, file_position: 0, - devno: 0, - inode: 0, + identity: None, + gzip_read_skipped: false, is_dead: false, - reached_eof: false, - last_read_attempt: now, - last_read_success: now, - read_retry_delay: EOF_READ_BACKOFF_MIN, last_seen: now, max_line_bytes: 1024, line_delimiter: Bytes::from_static(b"\n"), - buf: BytesMut::new(), + } +} + +fn read_retry_delay(watcher: &FileWatcher) -> std::time::Duration { + match &watcher.state { + WatcherState::Active { + read_retry_delay, .. + } => *read_retry_delay, + WatcherState::Idle { .. } => panic!("watcher is idle, expected active"), } } @@ -249,7 +261,7 @@ fn backs_off_after_eof() { watcher.track_read_attempt(); watcher.track_read_eof(); - assert_eq!(watcher.read_retry_delay, EOF_READ_BACKOFF_MIN); + assert_eq!(read_retry_delay(&watcher), EOF_READ_BACKOFF_MIN); assert!(!watcher.should_read()); thread::sleep(EOF_READ_BACKOFF_MIN); @@ -260,7 +272,7 @@ fn backs_off_after_eof() { watcher.track_read_eof(); assert_eq!( - watcher.read_retry_delay, + read_retry_delay(&watcher), EOF_READ_BACKOFF_MIN.saturating_mul(2) ); } @@ -274,14 +286,1279 @@ fn caps_and_resets_eof_backoff() { watcher.track_read_eof(); } - assert_eq!(watcher.read_retry_delay, EOF_READ_BACKOFF_MAX); + assert_eq!(read_retry_delay(&watcher), EOF_READ_BACKOFF_MAX); watcher.track_read_success(); - assert_eq!(watcher.read_retry_delay, EOF_READ_BACKOFF_MIN); + assert_eq!(read_retry_delay(&watcher), EOF_READ_BACKOFF_MIN); assert!(!watcher.reached_eof()); } +#[test] +fn mark_ready_to_read_overrides_eof_backoff() { + // Regression test for a bug found in review: a notify filesystem event naming an already- + // tracked, still-`Active` watcher's path should let it read promptly even if it's currently + // mid-EOF-backoff, rather than leaving it to wait out its own independent backoff timer (up + // to `EOF_READ_BACKOFF_MAX`) despite a concrete "something changed" signal having just + // arrived. + let mut watcher = watcher_for_timing(); + + watcher.track_read_attempt(); + watcher.track_read_eof(); + assert!( + !watcher.should_read(), + "sanity check: freshly backed off, should not read yet" + ); + + watcher.mark_ready_to_read(); + assert!( + watcher.should_read(), + "mark_ready_to_read must override EOF backoff immediately" + ); +} + +#[test] +fn mark_ready_to_read_overrides_quiet_file_throttle() { + // Regression test for a bug found in review: `should_read` throttles a *quiet* (long since + // successfully read) file to at most one attempt per 10 seconds, to avoid needlessly + // hammering `read_line` on files nobody is writing to. But that throttle is meant to pace + // *unprompted* polling -- it must not also delay a read that a genuine notify event, naming + // this exact path, just justified. Before this fix, notify mode's "prompt wakeup" promise + // could be defeated for up to 10 seconds by this throttle alone. + let mut watcher = watcher_for_timing(); + + // Simulate "quiet for a while, but an attempt was just made:" long past last_read_success, + // recent last_read_attempt -- the one combination `should_read` throttles. + if let WatcherState::Active { + last_read_success, + last_read_attempt, + .. + } = &mut watcher.state + { + *last_read_success = Instant::now() - std::time::Duration::from_secs(20); + *last_read_attempt = Instant::now(); + } else { + unreachable!("watcher_for_timing() always returns an Active watcher"); + } + assert!( + !watcher.should_read(), + "sanity check: quiet file, recent attempt, should be throttled" + ); + + watcher.mark_ready_to_read(); + assert!( + watcher.should_read(), + "mark_ready_to_read must override the quiet-file throttle immediately" + ); +} + +// --- Idle-state tests ------------------------------------------------- +// +// These exercise the fix for https://github.com/vectordotdev/vector/issues/3567: +// old, fully-read files should never get an open file handle, and +// actively-open files that go quiet should have their handle closed and be +// polled cheaply instead. + +use chrono::Utc; +use file_source_common::ReadFrom; +use std::fs; +use tempfile::tempdir; + +/// Write a file and return an `ignore_before` timestamp that is guaranteed to +/// postdate it -- i.e. this file counts as "too old" per `ignore_older` +/// relative to the returned cutoff. We can't reliably backdate a freshly +/// written file's mtime without a filesystem-timestamp-manipulation crate +/// (not a dependency here), so instead we push `ignore_before` into the +/// future relative to the write, which is equivalent for the purposes of the +/// `too_old` comparison in `FileWatcher::new` (`modified_time < ignore_before`). +fn write_file_and_ignore_before(path: &std::path::Path, contents: &[u8]) -> chrono::DateTime { + fs::write(path, contents).unwrap(); + Utc::now() + chrono::Duration::seconds(60) +} + +#[tokio::test] +async fn new_old_fully_read_file_starts_idle_without_opening() { + let dir = tempdir().unwrap(); + let path = dir.path().join("old.log"); + let contents = b"line one\nline two\n"; + let ignore_before = Some(write_file_and_ignore_before(&path, contents)); + + // Checkpoint position equal to the full file size: nothing new to read. + let checkpoint = contents.len() as u64; + + let watcher = FileWatcher::new( + path.clone(), + ReadFrom::Checkpoint(checkpoint), + ignore_before, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + assert!( + watcher.is_idle(), + "old, fully-read file should start in the Idle state" + ); + assert!(!watcher.is_active()); + assert_eq!(watcher.get_file_position(), checkpoint); +} + +#[tokio::test] +async fn idle_on_startup_false_keeps_old_file_active() { + // Regression test for a bug found in review: `idle_timeout: null` is documented as + // restoring the prior always-open behavior entirely, but the startup fast path (this same + // scenario as `new_old_fully_read_file_starts_idle_without_opening` above) used to ignore + // that opt-out completely -- it's a separate mechanism from the runtime `deactivate()` + // transition that `idle_timeout` alone gates, so an `ignore_older`-excluded file would still + // start `Idle` at discovery time regardless of `idle_timeout` being disabled. Passing + // `idle_on_startup: false` (what `FileServer` does when `self.idle_timeout.is_none()`) must + // skip the fast path and open the file normally instead. + let dir = tempdir().unwrap(); + let path = dir.path().join("old_but_idle_disabled.log"); + let contents = b"line one\nline two\n"; + let ignore_before = Some(write_file_and_ignore_before(&path, contents)); + let checkpoint = contents.len() as u64; + + let watcher = FileWatcher::new( + path.clone(), + ReadFrom::Checkpoint(checkpoint), + ignore_before, + 1024, + Bytes::from_static(b"\n"), + false, + ) + .await + .expect("FileWatcher::new failed"); + + assert!( + watcher.is_active(), + "idle_on_startup: false must keep even an ignore_older-excluded file Active, not \ + silently start it Idle regardless of the opt-out" + ); + assert!(!watcher.is_idle()); +} + +#[tokio::test] +async fn new_old_uncompressed_file_starts_idle_regardless_of_checkpoint() { + // For a *non-gzip* file, once it's deemed `too_old` (per `ignore_before`), + // the pre-existing open path always seeks straight to EOF regardless of + // any stored checkpoint -- old files are simply not read from, whether + // there's unread data behind a stale checkpoint or not. Because that + // outcome doesn't depend on the checkpoint at all, the fast (stat-only, + // no-open) idle path doesn't need to match against it either: it only + // needs to confirm the file isn't gzip (see the gzip-specific test + // below). So even with a checkpoint well behind the actual file size, an + // old non-gzip file should still start Idle without ever being opened, + // parked at the file's current size (== where an open would have left + // it). + let dir = tempdir().unwrap(); + let path = dir.path().join("old_with_new_data.log"); + let contents = b"line one\nline two\n"; + let ignore_before = Some(write_file_and_ignore_before(&path, contents)); + + // Checkpoint position well behind the actual file size. + let checkpoint = 5u64; + + let watcher = FileWatcher::new( + path.clone(), + ReadFrom::Checkpoint(checkpoint), + ignore_before, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + assert!( + watcher.is_idle(), + "an old, non-gzip file should start idle even with a stale checkpoint, \ + since a full open would end up at EOF regardless" + ); + assert_eq!(watcher.get_file_position(), contents.len() as u64); +} + +#[tokio::test] +async fn new_old_uncompressed_file_without_checkpoint_starts_idle() { + // The "cold start" case: no stored checkpoint at all (e.g. first run, or + // `ignore_checkpoints`), just `ReadFrom::Beginning`. An old, non-gzip + // file should still start Idle without being opened -- this is what + // keeps a large `include` glob of old files cheap even when Vector has + // never seen them before, not just on restart with existing checkpoints. + let dir = tempdir().unwrap(); + let path = dir.path().join("old_cold_start.log"); + let contents = b"line one\nline two\n"; + let ignore_before = Some(write_file_and_ignore_before(&path, contents)); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + ignore_before, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + assert!( + watcher.is_idle(), + "an old, non-gzip file with no checkpoint should still start idle" + ); + assert_eq!(watcher.get_file_position(), contents.len() as u64); + + // Regression coverage for a bug found in review: this watcher has never opened the file (it + // took the startup fast path, so `identity` is still `None`), which must not be confused with + // "the file was replaced" the first time it reactivates. Append new data and confirm + // reactivation resumes from where the old content ended, rather than resetting to 0 and + // re-sending the content `ignore_older` deliberately skipped in the first place. + let mut f = std::fs::OpenOptions::new() + .append(true) + .open(&path) + .unwrap(); + use std::io::Write as _; + writeln!(f, "line three").unwrap(); + f.flush().unwrap(); + drop(f); + + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "growth should be detected via cheap stat"); + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher.get_file_position(), + contents.len() as u64, + "the first reactivation of a never-opened idle watcher must resume from the \ + position recorded at discovery, not reset to 0 and re-read the old, \ + ignore_older-excluded content" + ); + + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("line three".to_string()), + "must read only the newly appended line, not re-send the old content" + ); +} + +#[tokio::test] +async fn new_old_gzip_file_without_checkpoint_starts_active() { + // Gzip is the one case the fast path must not take: an old gzip file's + // "too old" handling starts back at position 0 (not EOF, unlike the + // uncompressed case), which requires actually decoding the gzip header, + // so it must go through the full open path. + use async_compression::tokio::bufread::GzipEncoder; + use tokio::io::AsyncReadExt as _; + + let dir = tempdir().unwrap(); + let path = dir.path().join("old.log.gz"); + + let mut encoder = GzipEncoder::new(std::io::Cursor::new(b"line one\n".to_vec())); + let mut compressed = Vec::new(); + encoder.read_to_end(&mut compressed).await.unwrap(); + let ignore_before = Some(write_file_and_ignore_before(&path, &compressed)); + + let watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + ignore_before, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + assert!( + watcher.is_active(), + "gzip files must always go through the full open path, even when old" + ); +} + +#[tokio::test] +async fn new_file_without_ignore_before_starts_active() { + // Sanity check: without `ignore_before` configured at all, nothing + // should ever start idle, regardless of checkpoint/size. + let dir = tempdir().unwrap(); + let path = dir.path().join("recent.log"); + let contents = b"only line\n"; + fs::write(&path, contents).unwrap(); + + let watcher = FileWatcher::new( + path.clone(), + ReadFrom::Checkpoint(contents.len() as u64), + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + assert!(watcher.is_active()); +} + +#[tokio::test] +async fn deactivate_closes_handle_and_retains_checkpoint() { + let dir = tempdir().unwrap(); + let path = dir.path().join("goes_idle.log"); + fs::write(&path, b"hello\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_active()); + + // Read the one line so the watcher has a real position to preserve. + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_some()); + let position_before = watcher.get_file_position(); + assert!(position_before > 0); + + watcher.deactivate().await; + + assert!( + watcher.is_idle(), + "deactivate() should transition Active -> Idle" + ); + assert_eq!( + watcher.get_file_position(), + position_before, + "checkpoint position must survive deactivation" + ); +} + +#[tokio::test] +async fn deactivate_rewinds_past_unterminated_partial_line() { + // `read_until_with_max_size` advances `file_position` for every byte it + // reads into its buffer, delimiter or not: a partial line with no + // trailing delimiter yet is bytes-read-but-not-yet-emitted, tracked in + // the watcher's internal `buf`, waiting for a future call to complete it. + // If `deactivate` naively idle-izes on top of that -- discarding `buf` + // (it's part of the `Active` state being replaced) without rewinding + // `file_position` back behind those bytes -- the partial line is gone: + // `reactivate` would resume reading from *after* it, and since those + // bytes were already counted as read, they'd never be retried. The fix + // is for `deactivate` to rewind `file_position` by exactly `buf.len()`, + // so the unterminated bytes get read again from disk (along with + // whatever completes them) once the watcher reactivates. + let dir = tempdir().unwrap(); + let path = dir.path().join("partial_line.log"); + // No trailing newline: `partial` is the entire, unterminated content of + // the file at this point. + let partial = b"unterminated-line-no-newline-yet"; + fs::write(&path, partial).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_active()); + + // Attempt a read: hits EOF with no delimiter, so nothing is emitted, but + // (per `read_until_with_max_size`'s contract) the bytes are still + // consumed from the reader and counted into `file_position`, buffered + // internally awaiting the delimiter. + let result = watcher.read_line().await.expect("read_line error"); + assert!( + result.raw_line.is_none(), + "no delimiter yet, so nothing should be emitted" + ); + assert_eq!( + watcher.get_file_position(), + partial.len() as u64, + "position should advance past the buffered-but-unterminated bytes" + ); + + watcher.deactivate().await; + assert!(watcher.is_idle()); + assert_eq!( + watcher.get_file_position(), + 0, + "deactivate must rewind position back behind the unterminated partial line" + ); + + // Complete the line and confirm reactivation reads the *whole* line back + // from disk, not just the newly-appended suffix. + let mut file = std::fs::OpenOptions::new() + .append(true) + .open(&path) + .unwrap(); + use std::io::Write as _; + writeln!(file).unwrap(); // just the trailing newline + drop(file); + + let changed = watcher + .check_for_new_data() + .await + .expect("check_for_new_data error"); + assert!(changed, "appending the delimiter should be detected"); + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + + let result = watcher.read_line().await.expect("read_line error"); + let line = result.raw_line.expect("expected a complete line now"); + assert_eq!( + &line.bytes[..], + &partial[..], + "the full original line must be read back, not just the appended newline" + ); +} + +#[tokio::test] +async fn take_final_partial_line_salvages_unterminated_bytes_when_idle_is_reaped() { + // Regression test for a bug found in review: unlike an `Active` watcher (whose `read_line` + // flushes a buffered-but-unterminated line the moment its file is found unfindable), an + // `Idle` watcher is never read at all while unfindable (`FileServer::poll_idle_watchers` + // skips it outright), so it has no path of its own to flush a trailing record with no final + // delimiter. Before this fix, such a record was silently dropped whenever the watcher was + // reaped (e.g. its file was rotated out of the include glob) while still `Idle`. + // `take_final_partial_line` gives `FileServer`'s reap path a way to recover it as a + // last-resort measure right before the watcher is discarded for good. + let dir = tempdir().unwrap(); + let path = dir.path().join("partial_line_reaped_while_idle.log"); + let partial = b"unterminated-line-lost-if-not-salvaged"; + fs::write(&path, partial).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_active()); + + // Consume the unterminated bytes into the buffer, exactly as in + // `deactivate_rewinds_past_unterminated_partial_line` above. + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_none()); + + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Simulate the file being rotated out of the include glob and the watcher being reaped, + // without ever getting a chance to reactivate: take the salvaged line instead. + let line = watcher + .take_final_partial_line() + .expect("the buffered-but-unterminated line must be salvageable after deactivate()"); + assert_eq!( + &line.bytes[..], + &partial[..], + "the salvaged line must contain exactly the bytes that were buffered, unterminated" + ); + assert_eq!( + line.offset, 0, + "the salvaged line's offset must be where it started in the file, not the rewound \ + (post-deactivate) file_position" + ); + + assert!( + watcher.take_final_partial_line().is_none(), + "take_final_partial_line must not return the same line twice" + ); +} + +#[tokio::test] +async fn take_final_partial_line_salvages_from_active_watcher_too() { + // Regression test for a bug found in review: `remove_after`-driven removal of an `Active` + // watcher that wasn't read this cycle (e.g. `should_read()` was false) can also discard a + // buffered-but-unterminated line without `read_line`'s own not-`file_findable` flush ever + // running. `take_final_partial_line` must salvage it for `Active` watchers too, not just + // `Idle` ones. + let dir = tempdir().unwrap(); + let path = dir.path().join("partial_line_active.log"); + let partial = b"unterminated-active-line"; + fs::write(&path, partial).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_active()); + + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_none()); + + let line = watcher + .take_final_partial_line() + .expect("an Active watcher's buffered-but-unterminated bytes must be salvageable too"); + assert_eq!(&line.bytes[..], &partial[..]); + assert_eq!(line.offset, 0); + + assert!(watcher.take_final_partial_line().is_none()); +} + +#[tokio::test] +async fn idle_watcher_detects_new_data_and_resumes_from_correct_offset() { + let dir = tempdir().unwrap(); + let path = dir.path().join("resumes.log"); + fs::write(&path, b"first\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + // Drain what's there, then go idle. + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("first".to_string()) + ); + let position_before = watcher.get_file_position(); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // No new data yet: check_for_new_data should report no change and the + // watcher should remain idle. + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(!changed); + assert!(watcher.is_idle()); + + // Now append new data while idle (no handle held). + use std::io::Write; + let mut f = fs::OpenOptions::new().append(true).open(&path).unwrap(); + writeln!(f, "second").unwrap(); + f.flush().unwrap(); + drop(f); + + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "growth should be detected via cheap stat"); + + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher.get_file_position(), + position_before, + "reactivation must seek back to the retained checkpoint" + ); + + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("second".to_string()), + "resumed read must pick up exactly the new content, not re-read old data" + ); +} + +#[tokio::test] +async fn invalidate_idle_bookkeeping_forces_next_check_to_report_changed() { + // Regression test for a bug found in review: check_for_new_data unconditionally records + // whatever size/mtime it just observed, before the caller has decided what to do about a + // reported change. If the caller's subsequent reactivate() attempt then fails (e.g. a + // transient permission or I/O error) and the file doesn't change *again* in the meantime, a + // naive next poll would compare against the size/mtime already recorded from that failed + // attempt, see no difference, and never retry -- silently stranding the watcher Idle with + // unread data sitting on disk. invalidate_idle_bookkeeping exists to force the next poll to + // report a change (and thus retry) regardless of what it actually observes. + // + // Rather than trying to simulate a reactivate() failure via filesystem tricks (unreliable: + // filesystem timestamp granularity means a file swapped out and back can easily end up with a + // different mtime even with identical content, which would make check_for_new_data correctly + // report "changed" on its own, independent of whether invalidate_idle_bookkeeping does + // anything -- exactly the kind of test that would still pass with a no-op implementation), + // this tests the property directly: two consecutive check_for_new_data calls with genuinely + // nothing happening to the file in between. Without invalidate_idle_bookkeeping, the second + // call is guaranteed to report `false` (nothing changed, correctly). With it called in + // between, the second call must report `true` even though nothing on disk actually changed. + let dir = tempdir().unwrap(); + let path = dir.path().join("flaky.log"); + fs::write(&path, b"first\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + let _ = watcher.read_line().await.expect("read_line error"); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Grow the file so check_for_new_data reports a change; this also records the file's current + // size/mtime as the watcher's new "last known" baseline -- the state that a failed + // reactivate() would otherwise leave stale and un-retried. + fs::write(&path, b"first\nsecond\n").unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "growth should be detected via cheap stat"); + + // Sanity check the premise: with nothing touching the file in between, a second consecutive + // check must report no change (this is what a stranded-forever watcher would keep seeing). + let changed_again = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!( + !changed_again, + "sanity check: with nothing touching the file, a second check must see no change" + ); + + // Now invalidate, still with nothing touching the file, and confirm the next check reports a + // change anyway -- this is the exact retry-after-a-failed-reactivate behavior being tested. + watcher.invalidate_idle_bookkeeping(); + let changed_after_invalidate = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!( + changed_after_invalidate, + "invalidate_idle_bookkeeping must force the next check to report a change and retry, \ + even though nothing on disk actually changed" + ); + + // Regression coverage for a bug found in review: invalidate_idle_bookkeeping's forced retry + // must not be mistaken by check_for_new_data for "the file shrank." An earlier version of + // this achieved the forced retry by clobbering last_known_size with a u64::MAX sentinel, + // which any real size always compared as smaller than, wrongly latching + // truncated_while_idle on every retry and causing reactivate to discard the correct, + // still-at-the-end-of-"first" position and re-read the file from byte 0, re-emitting "first" + // as a duplicate (it was already read and emitted before this watcher went idle) instead of + // correctly resuming to pick up only "second", the genuinely new line. + let position_before_reactivate = watcher.get_file_position(); + watcher + .reactivate() + .await + .expect("reactivate should succeed"); + assert!(watcher.is_active()); + assert_eq!( + watcher.get_file_position(), + position_before_reactivate, + "a retry after invalidate_idle_bookkeeping, with no real truncation involved, must \ + resume from where it left off, not discard the position and re-read from the start" + ); + + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("second".to_string()), + "must read exactly the new line, not re-emit \"first\" (already read before this \ + watcher went idle) as a duplicate" + ); +} + +#[tokio::test] +async fn idle_watcher_detects_truncation() { + let dir = tempdir().unwrap(); + let path = dir.path().join("truncated.log"); + fs::write(&path, b"0123456789\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + let _ = watcher.read_line().await.expect("read_line error"); + let position_before = watcher.get_file_position(); + assert!(position_before > 0); + watcher.deactivate().await; + + // Truncate the file down to nothing while idle. + fs::write(&path, b"").unwrap(); + + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!( + changed, + "truncation (shrink) must be detected, not just growth" + ); +} + +#[tokio::test] +async fn truncation_invalidates_pending_partial_line() { + // Regression test for a bug found in review: a partial line buffered by `deactivate` refers + // to an offset in the pre-truncation file. If the file is then truncated while idle, + // `check_for_new_data` must drop that stale buffer -- otherwise, if the watcher is later + // reaped without ever reactivating, `take_final_partial_line` would hand back bytes/offset + // that no longer correspond to anything on disk. + let dir = tempdir().unwrap(); + let path = dir.path().join("truncated_with_partial_line.log"); + // No trailing newline, so the bytes end up buffered as an unterminated partial line. + let partial = b"unterminated-before-truncate"; + fs::write(&path, partial).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_none()); + + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Truncate the file while idle. + fs::write(&path, b"").unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed); + + assert!( + watcher.take_final_partial_line().is_none(), + "check_for_new_data must invalidate the stale pre-truncation partial line" + ); +} + +#[tokio::test] +async fn idle_watcher_reads_correctly_after_same_inode_truncation() { + // Regression test for a bug found in review: check_for_new_data only reports a bare + // "changed," not which direction the size moved, so reactivate() must independently notice a + // shrink and reset file_position -- identity alone isn't enough to catch this, since a + // truncate-in-place (e.g. `logrotate`'s `copytruncate`, or an application truncating and + // rewriting its own log file) keeps the same inode throughout. Without checking the size + // directly, reactivate() would seek to the old (now past-EOF) position; a seek past EOF + // doesn't error, it just means every read sees nothing until the file grows past the old + // position again, silently losing everything written to the truncated file in the meantime. + let dir = tempdir().unwrap(); + let path = dir.path().join("truncated_rewrite.log"); + fs::write(&path, b"0123456789\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + let _ = watcher.read_line().await.expect("read_line error"); + let position_before = watcher.get_file_position(); + assert!(position_before > 0); + let identity_before = watcher_identity(&watcher); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Truncate the file in place (same inode on both Unix and Windows: this opens the existing + // file with O_TRUNC/equivalent rather than creating a new one) and write new, shorter + // content -- shorter than `position_before`, so a stale seek would land past this file's end. + fs::write(&path, b"short\n").unwrap(); + + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "truncation must be detected"); + + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher_identity(&watcher), + identity_before, + "sanity check: this must be a same-inode truncation, not a same-path replacement \ + (which is covered by a separate test) -- otherwise this test wouldn't be exercising \ + the code path it's meant to" + ); + assert_eq!( + watcher.get_file_position(), + 0, + "reactivating after a same-inode truncation must reset the read position, not seek \ + to the old (now past-EOF) offset" + ); + + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("short".to_string()), + "must read the truncated file's new content from the start, not silently lose it" + ); +} + +#[tokio::test] +async fn idle_watcher_reads_correctly_after_truncate_then_refill_past_old_position() { + // Regression test for a bug found in review: reactivate()'s previous fix only compared the + // file's size *at the moment of reactivation* against file_position. That misses a truncate + // that gets refilled *past* the old file_position again before reactivation, e.g.: read up + // to offset 1000, the file gets truncated to 0 (observed by one check_for_new_data poll), + // then rewritten with 1500 bytes of unrelated new content before the watcher reactivates. At + // reactivation time the file's current size (1500) is >= file_position (1000), which looks + // exactly like ordinary growth: nothing about a single point-in-time comparison reveals that + // a truncation happened at some point along the way. Without remembering that a poll *did* + // see a shrink at some point, reactivate would seek to byte 1000 of the *new* content and + // treat it as a continuation of the old file, silently fabricating a bogus resumption point. + // + // Note this specifically requires the shrink and the eventual regrowth to be observed by + // *separate* check_for_new_data polls: if both file writes happen between two polls with + // nothing in between ever observing the intermediate empty state, no polling-based approach + // (this one included, and this isn't specific to Vector) can tell that apart from ordinary + // growth -- there's no state on disk left behind to detect it from after the fact. That's a + // fundamental limitation of polling for changes rather than something reactivate could + // special-case around, and applies identically to `file_discovery_mode: polling`'s pre-existing + // handling of *active* (never-idle) files, not something this idle-handle-closing feature + // introduces. This test instead models the realistic case the fix actually addresses: a + // truncation slow enough to be independently observed by its own poll, followed by unrelated + // regrowth observed later, which is exactly what FileServer's own poll_idle_watchers does on + // every discovery cycle in production. + let dir = tempdir().unwrap(); + let path = dir.path().join("truncate_then_refill.log"); + // A single 999-byte line plus its newline: file_position after reading it lands at exactly + // 1000, a clean, known value to assert against once reactivated. + fs::write(&path, format!("{}\n", "a".repeat(999))).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 4096, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_some()); + let position_before = watcher.get_file_position(); + assert_eq!( + position_before, 1000, + "sanity check on the test's own setup" + ); + let identity_before = watcher_identity(&watcher); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // First poll: observe the truncation to nothing. This is what latches + // `truncated_while_idle`. + fs::write(&path, "").unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "the truncation to empty must be detected"); + + // Refill with new content longer than `position_before`, observed by a second poll before + // reactivation -- by this point the file looks, size-wise, like it simply grew past its old + // position, exactly as ordinary (non-truncating) growth would. + fs::write(&path, format!("{}\n", "z".repeat(1499))).unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "the regrowth must also be detected"); + + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher_identity(&watcher), + identity_before, + "sanity check: same inode throughout, exercising the same-identity truncation path" + ); + assert_eq!( + watcher.get_file_position(), + 0, + "must reset to 0 even though the file's *final* size is larger than the old \ + file_position -- a truncate happened in between, which a single point-in-time \ + size comparison at reactivation time can't see on its own" + ); + + let result = watcher.read_line().await.expect("read_line error"); + let line = result.raw_line.expect("expected a line"); + assert_eq!( + line.bytes.len(), + 1499, + "must read the new content from its actual start (byte 0), not from the stale \ + offset 1000 into what is now unrelated data" + ); + assert!( + line.bytes.iter().all(|&b| b == b'z'), + "must not splice together old and new content: every byte of the line read back \ + must be from the new content, none from the old" + ); +} + +#[tokio::test] +async fn idle_watcher_detects_truncation_observed_on_the_forced_retry_poll() { + // Regression test for a bug found in review, one step further than the truncate-then-refill + // test above. An earlier fix for invalidate_idle_bookkeeping's forced retry worked by + // clobbering last_known_size with a u64::MAX sentinel so the next check_for_new_data would + // always report `changed`. That broke the shrink-detection this same function is responsible + // for: on the very next poll, `new_size < *last_known_size` compared the real (possibly + // already-refilled) size against u64::MAX, which is *always* true regardless of whether the + // file actually shrank -- so a guard (`had_valid_baseline`) was added to skip the + // shrink-check whenever the baseline was the sentinel. But that guard traded one bug for + // another: it went from "always false-positive" to "always skip," which means a *real* + // truncation observed on exactly that first post-invalidate poll would go completely + // undetected, not just misreported. Concretely: + // 1. watcher reads up to file_position 1000, then goes idle. + // 2. reactivate() fails for some transient reason (e.g. a permissions error), and the + // caller calls invalidate_idle_bookkeeping() to force a retry on the next poll. + // 3. before that next poll runs, the file is truncated down to 200 bytes -- smaller than + // the old file_position, and still observably smaller than it by the time the forced + // retry poll actually samples the file. + // 4. the next check_for_new_data poll is the forced retry from step 2. With the buggy + // guard, it would skip the shrink check entirely (because a retry was pending) and so + // never latch `truncated_while_idle`, even though the shrink was plainly visible on this + // exact poll. + // 5. the file is then refilled past the old file_position (to 1500 bytes) and observed by a + // second, ordinary poll -- at which point, without the latch from step 4, nothing + // remains to distinguish this from ordinary growth. + // 6. reactivate() must still resume from byte 0, not treat the final size (1500) as + // ordinary growth past the old file_position (1000) and resume reading stale data. + // + // The current fix (a dedicated `force_recheck` flag, separate from `last_known_size`) keeps + // last_known_size holding the *real* last observed size (1000, from before going idle) + // through invalidate_idle_bookkeeping, so the forced-retry poll's shrink check compares the + // real new size (200) against the real old baseline (1000) like any other poll, correctly + // latching `truncated_while_idle` -- the forced-retry behavior comes entirely from the + // separate flag instead of from corrupting the baseline. + let dir = tempdir().unwrap(); + let path = dir.path().join("truncate_observed_on_forced_retry.log"); + fs::write(&path, format!("{}\n", "a".repeat(999))).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 4096, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_some()); + assert_eq!( + watcher.get_file_position(), + 1000, + "sanity check on the test's own setup" + ); + let identity_before = watcher_identity(&watcher); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Simulate a failed reactivate() attempt forcing a retry, without needing to actually break + // the filesystem to trigger one. + watcher.invalidate_idle_bookkeeping(); + + // Truncate to a size still smaller than the old file_position (1000), and have this exact + // poll -- the forced retry from invalidate_idle_bookkeeping -- be the one that observes it. + fs::write(&path, "b".repeat(200)).unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!( + changed, + "must report changed, both because of the forced retry and because the size differs \ + from the last known baseline" + ); + + // Refill past the old file_position, observed by a second, ordinary poll -- by itself this + // looks exactly like ordinary growth, the same as in the test above. + fs::write(&path, format!("{}\n", "z".repeat(1499))).unwrap(); + let changed = watcher + .check_for_new_data() + .await + .expect("stat should succeed"); + assert!(changed, "the regrowth must also be detected"); + + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher_identity(&watcher), + identity_before, + "sanity check: same inode throughout, exercising the same-identity truncation path" + ); + assert_eq!( + watcher.get_file_position(), + 0, + "must reset to 0: the file was truncated while idle and that truncation was observed on \ + the very poll that also served as the forced retry from invalidate_idle_bookkeeping, \ + even though the file's final size (1500) is larger than the old file_position (1000)" + ); + + let result = watcher.read_line().await.expect("read_line error"); + let line = result.raw_line.expect("expected a line"); + assert_eq!( + line.bytes.len(), + 1499, + "must read the new content from its actual start (byte 0), not from the stale \ + offset 1000 into what is now unrelated data" + ); + assert!( + line.bytes.iter().all(|&b| b == b'z'), + "must not splice together old and new content: every byte of the line read back \ + must be from the new content, none from the old" + ); +} + +#[tokio::test] +async fn idle_watcher_survives_rotation_without_reading_wrong_file() { + // A rotation while idle: the original file is renamed away and a new, + // unrelated file is created at the same path. `FileServer`'s + // fingerprint-based identity tracking is what actually prevents + // misattributing content across this rename in production; here we + // verify the pieces `FileWatcher` itself is responsible for: identity + // (dev/inode) is checked on reactivation via `update_path`/`reactivate`, + // so a same-path-different-file swap cannot silently resume from a + // stale offset into unrelated content. + let dir = tempdir().unwrap(); + let path = dir.path().join("rotated.log"); + fs::write(&path, b"original content here\n").unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Beginning, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + let original_identity = watcher_identity(&watcher); + + let _ = watcher.read_line().await.expect("read_line error"); + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Simulate rotation: move the original file away, create a new one in + // its place with different (shorter) content. + let archived = dir.path().join("rotated.log.1"); + fs::rename(&path, &archived).unwrap(); + fs::write(&path, b"new\n").unwrap(); + + // A cheap stat-only poll will very likely see *some* difference (size + // and/or mtime), prompting reactivation. + let changed = watcher.check_for_new_data().await.unwrap_or(true); + if changed { + watcher.reactivate().await.expect("reactivate failed"); + let new_identity = watcher_identity(&watcher); + assert_ne!( + original_identity, new_identity, + "reactivating onto a rotated path must pick up the new file's identity" + ); + // Regression coverage for a bug found in review: identity alone isn't enough -- + // reactivate() must also reset file_position to 0 when the identity changes, + // rather than seeking the new file to the old file's stale offset (which, for a + // file rotated at the same path, would skip the new file's opening bytes, or -- + // if the new file happens to be shorter than the old offset -- read nothing at + // all until it grows past that point). Assert on the observable behavior (what + // gets read), not just the internal position field, since that's what would + // actually be lost in production. + assert_eq!( + watcher.get_file_position(), + 0, + "reactivating onto a file with a different identity must reset the read \ + position, not seek to the old file's stale offset" + ); + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("new".to_string()), + "must read the rotated-in file's own content from the start, not skip past it" + ); + } +} + +/// Test-only accessor into the private dev/inode identity, used to assert +/// that reactivation onto a rotated file picks up a genuinely different +/// identity rather than silently continuing to treat it as the same file. +fn watcher_identity(watcher: &FileWatcher) -> Option<(u64, u64)> { + watcher.identity +} + +#[tokio::test] +async fn idle_gzip_file_detected_correctly_on_reactivation() { + use async_compression::tokio::bufread::GzipEncoder; + use tokio::io::AsyncReadExt as _; + + let dir = tempdir().unwrap(); + let path = dir.path().join("idle.gz"); + + async fn encode(data: &[u8]) -> Vec { + let mut out = Vec::new(); + GzipEncoder::new(data).read_to_end(&mut out).await.unwrap(); + out + } + + // Start with an empty file (so the watcher, if it were to open it, + // wouldn't see gzip magic yet), matching a plausible "log rotated to a + // fresh, not-yet-compressed placeholder" scenario is overkill here -- + // simpler: start idle via an old, checkpoint-complete plain file, then + // have the "new data" that appears actually be a gzip stream. This + // covers "gzip detection must be deferred until reopen" from an idle + // watcher that never inspected the file's content at all. + let ignore_before = Some(write_file_and_ignore_before(&path, b"")); + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::Checkpoint(0), + ignore_before, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_idle(), "empty, old, fully-read file starts idle"); + + // Now replace the empty file's content with a gzip stream (simulating + // a log manager compressing a rotated-in file in place). + let gz = encode(b"compressed line\n").await; + fs::write(&path, &gz).unwrap(); + + let changed = watcher.check_for_new_data().await.unwrap(); + assert!(changed); + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + + let result = watcher.read_line().await.expect("read_line error"); + assert_eq!( + result + .raw_line + .map(|l| String::from_utf8(l.bytes.to_vec()).unwrap()), + Some("compressed line".to_string()), + "gzip must be transparently detected and decoded on reactivation" + ); +} + +#[tokio::test] +async fn idle_gzip_read_from_end_stays_skipped_on_reactivation() { + // Regression test for a bug found in review: `read_from: end` on a gzip file installs a + // null reader and leaves `file_position` at `0` (the "already read, ignore" case in + // `FileWatcher::new`, since a gzip stream can't be resumed from an arbitrary offset and + // skipping to the actual end isn't possible without decoding it). If the watcher goes idle + // (EOF timeout) and is later reactivated by a bare mtime bump, `file_position == 0` alone is + // indistinguishable from "never started decoding, safe to start from the beginning" -- so + // without tracking that this stream was deliberately skipped, reactivation would install a + // real gzip decoder and emit the entire backlog `read_from: end` was supposed to skip. + use async_compression::tokio::bufread::GzipEncoder; + use tokio::io::AsyncReadExt as _; + + async fn encode(data: &[u8]) -> Vec { + let mut out = Vec::new(); + GzipEncoder::new(data).read_to_end(&mut out).await.unwrap(); + out + } + + let dir = tempdir().unwrap(); + let path = dir.path().join("skip_from_end.gz"); + let gz = encode(b"backlog line that should stay skipped\n").await; + fs::write(&path, &gz).unwrap(); + + let mut watcher = FileWatcher::new( + path.clone(), + ReadFrom::End, + None, + 1024, + Bytes::from_static(b"\n"), + true, + ) + .await + .expect("FileWatcher::new failed"); + assert!(watcher.is_active()); + assert_eq!( + watcher.get_file_position(), + 0, + "read_from: end on a gzip file resolves to position 0 (can't seek into a gzip stream)" + ); + + // Nothing should be readable: the stream was deliberately skipped, not actually positioned + // at the (nonexistent, for gzip) "end". + let result = watcher.read_line().await.expect("read_line error"); + assert!(result.raw_line.is_none()); + + watcher.deactivate().await; + assert!(watcher.is_idle()); + + // Simulate the file being touched (e.g. the log manager appending another compressed + // member, or just an mtime bump) without changing the fact that this stream was skipped. + let mut gz_touched = gz.clone(); + gz_touched.extend_from_slice(&encode(b"appended after going idle\n").await); + fs::write(&path, &gz_touched).unwrap(); + + let changed = watcher.check_for_new_data().await.unwrap(); + assert!(changed); + watcher.reactivate().await.expect("reactivate failed"); + assert!(watcher.is_active()); + + let result = watcher.read_line().await.expect("read_line error"); + assert!( + result.raw_line.is_none(), + "a gzip stream skipped via `read_from: end` must stay skipped after an idle \ + reactivation triggered by a mere mtime/size change, not suddenly decode and emit \ + the backlog it was supposed to skip" + ); +} + #[inline] pub fn delay(attempts: u32) { let delay = match attempts { diff --git a/lib/file-source/src/lib.rs b/lib/file-source/src/lib.rs index 97991f9b0a183..ca81c7ef5708f 100644 --- a/lib/file-source/src/lib.rs +++ b/lib/file-source/src/lib.rs @@ -3,4 +3,5 @@ pub mod file_server; pub mod file_watcher; +pub mod notify_watcher; pub mod paths_provider; diff --git a/lib/file-source/src/notify_watcher.rs b/lib/file-source/src/notify_watcher.rs new file mode 100644 index 0000000000000..117607f06aadc --- /dev/null +++ b/lib/file-source/src/notify_watcher.rs @@ -0,0 +1,891 @@ +//! An OS-level, event-driven alternative/augmentation to the periodic glob-rescan discovery +//! mechanism in [`crate::file_server::FileServer`]. +//! +//! # Design +//! +//! [`FileServer`] traditionally re-globs its `include` patterns on a fixed interval +//! (`glob_minimum_cooldown_ms`, historically defaulting to tens of milliseconds) in order to: +//! 1. discover new files, +//! 2. detect renames (a known fingerprint appearing at a new path), +//! 3. wake up reads for files that have new data. +//! +//! On systems with a large number of matched files (see +//! ), this is expensive: every rescan +//! opens/fingerprints every matched file, and every matched file keeps an open handle for its +//! entire lifetime on disk, even files excluded from reading by `ignore_older`. +//! +//! This module instead watches the *parent directories* of the configured `include` globs using +//! the cross-platform [`notify`] crate (inotify on Linux, FSEvents on macOS, +//! `ReadDirectoryChangesW` on Windows) and turns OS-level create/modify/rename/remove +//! notifications into a stream of [`NotifyMessage`]s that [`FileServer::run`] selects on, +//! alongside a much-less-frequent periodic reconciliation pass (a full glob+fingerprint pass, +//! functionally identical to the old fixed-interval rescan) that exists purely as a correctness +//! backstop: OS-level notification queues can silently overflow under heavy event bursts, and +//! there is an inherent TOCTOU gap between an initial directory scan and when the watch on that +//! directory is actually established. +//! +//! # Directory selection +//! +//! `notify` watches directories (optionally recursively), not glob patterns. For each `include` +//! pattern we compute the longest literal (non-glob) path prefix and watch that directory. If any +//! glob metacharacter appears after that prefix in a path component *below* another path +//! component (i.e. the pattern can match files nested arbitrarily deep, such as with `**`), we +//! watch recursively; otherwise (e.g. a single trailing `*.log` segment) we watch +//! non-recursively. This mirrors, approximately, how far the glob can "reach" beneath the +//! literal prefix. +//! +//! If that literal prefix doesn't exist on disk yet (e.g. `/var/log/newapp/*.log` before +//! `newapp` has been created), it can't be `watch()`-ed directly; [`NotifyDiscovery`] instead +//! watches the nearest existing ancestor recursively as a stand-in, so the prefix directory's +//! eventual creation is still observed promptly. Once it exists, the next `resync_watches` call +//! upgrades to watching it directly and drops the broader ancestor watch. +//! +//! # Bridging into async/tokio +//! +//! `notify`'s watcher delivers events via a synchronous callback, invoked on a thread owned by +//! the OS backend (this is the same shape used elsewhere in this workspace for config file +//! watching, see `src/config/watcher.rs`). We bridge this into the async world with a +//! `tokio::sync::mpsc::UnboundedSender`, doing a blocking (but very cheap, non-blocking-in-practice) +//! send from the notify callback. + +use std::{ + collections::HashMap, + path::{Path, PathBuf}, +}; + +use file_source_common::internal_events::FileSourceInternalEvents; +use notify::{ + Config, Event, EventKind, RecommendedWatcher, RecursiveMode, Watcher as NotifyWatcherTrait, + event::{CreateKind, ModifyKind, RemoveKind, RenameMode}, +}; +use tokio::sync::mpsc; +use tracing::{debug, trace, warn}; + +/// A message delivered from the OS-level file watcher to [`FileServer`](crate::file_server::FileServer). +#[derive(Debug)] +pub enum NotifyMessage { + /// One or more paths were created, modified, or renamed. This is intentionally coarse: we + /// don't try to fully interpret notify's (platform-dependent, sometimes ambiguous) event + /// semantics. Instead we treat any of these as "something changed near this path; go check + /// it," and let the existing fingerprinting/read logic in `FileServer` figure out the rest. + /// This is deliberately conservative -- it trades a few spurious wakeups (cheap: a stat + + /// maybe a fingerprint read) for never having to trust notify's event *kind* classification, + /// which varies across inotify/FSEvents/ReadDirectoryChangesW. + PathsChanged(Vec), + /// One or more paths were removed. Handled the same way as `PathsChanged` today (the + /// reconciliation logic in `FileServer` determines liveness by whether the path still globs, + /// not by trusting the removal event alone), but kept distinct so `FileServer` and telemetry + /// can reason about it explicitly in the future. + PathsRemoved(Vec), + /// The OS-level event queue overflowed: some events were dropped. The caller MUST trigger a + /// full reconciliation pass in response; this is not optional. + Overflow, + /// The watcher backend itself hit an unrecoverable-for-this-event error (e.g. it lost a + /// watch because a directory was removed out from under it). The caller should keep relying + /// on periodic reconciliation; recovery (re-establishing the watch) happens on the next + /// reconciliation-triggered call to [`NotifyDiscovery::resync_watches`]. + BackendError(String), +} + +/// Owns the live `notify` watcher and the receiving end of the bridge channel. +/// +/// Dropping this stops the watcher thread (via `notify`'s own `Drop` impl on the underlying +/// watcher) and closes the channel. +pub struct NotifyDiscovery { + watcher: RecommendedWatcher, + watched_dirs: WantedDirs, + /// For a wanted directory that doesn't exist yet (so it can't be `watch()`-ed directly), + /// tracks the nearest existing ancestor we're watching recursively instead, keyed by the + /// *wanted* directory. `resync_watches` uses this to notice once the wanted directory has + /// been created and upgrade to watching it directly (dropping the broader, more expensive + /// ancestor watch) rather than watching the ancestor forever. See `resync_watches` for + /// details. + fallback_watches: HashMap, + receiver: mpsc::UnboundedReceiver, +} + +impl NotifyDiscovery { + /// Create a new [`NotifyDiscovery`], watching the directories implied by `include_patterns`. + /// + /// Returns `Err` if the underlying OS watcher could not be constructed at all (e.g. platform + /// resource exhaustion, like hitting the inotify instance limit). Callers should treat this + /// as "notify-based discovery is unavailable" and fall back to relying solely on the + /// periodic reconciliation pass -- they should NOT treat it as fatal to the file source as a + /// whole. + pub fn new( + include_patterns: &[PathBuf], + emitter: &E, + ) -> notify::Result { + let (tx, receiver) = mpsc::unbounded_channel(); + + let watcher = RecommendedWatcher::new( + move |res: notify::Result| { + // This closure runs on a thread owned by the OS notification backend (e.g. the + // inotify reader thread). It must not block meaningfully; an unbounded channel + // send is effectively non-blocking (it only allocates). + let msg = match res { + Ok(event) => classify_event(event), + Err(error) => { + if is_overflow(&error) { + Some(NotifyMessage::Overflow) + } else { + Some(NotifyMessage::BackendError(error.to_string())) + } + } + }; + if let Some(msg) = msg { + // The only way this fails is if every receiver has been dropped, i.e. + // FileServer has shut down or was never polling; either way, there's + // nothing useful to do with the error. + drop(tx.send(msg)); + } + }, + Config::default(), + )?; + + let mut discovery = Self { + watcher, + watched_dirs: WantedDirs::new(), + fallback_watches: HashMap::new(), + receiver, + }; + discovery.resync_watches(include_patterns, emitter); + Ok(discovery) + } + + /// Recompute the set of directories that should be watched from `include_patterns`, and + /// add/remove watches to match. Cheap to call repeatedly (e.g. from the periodic + /// reconciliation pass), since it diffs against the currently-watched set rather than + /// tearing everything down. + /// + /// If a wanted directory doesn't exist yet (e.g. an `include` pattern like + /// `/var/log/newapp/*.log` where `newapp` hasn't been created yet), `watch()`-ing it directly + /// fails; this falls back to recursively watching the nearest existing ancestor instead, so + /// that creating the wanted directory (and anything under it) is still noticed promptly + /// rather than only on the next `reconcile_interval` backstop. Once the wanted directory + /// exists, a later call upgrades to watching it directly and drops the broader ancestor watch + /// (unless some other wanted directory still needs that same ancestor as its own fallback). + pub fn resync_watches( + &mut self, + include_patterns: &[PathBuf], + emitter: &E, + ) { + let wanted = compute_watch_directories(include_patterns); + + // Directories we're not already watching under the mode we now want. This also catches + // a directory that's currently watched `NonRecursive` but now needs `Recursive` (a + // second, overlapping `include` pattern started requiring it): re-`watch`-ing with a + // different mode replaces the previous registration in `notify`, it doesn't stack, so + // there's no need to `unwatch` first. + for (path, mode) in &wanted { + // If some other not-yet-existing wanted directory already depends on `path` as its + // fallback ancestor (necessarily `Recursive`: see `watch_fallback_ancestor`), that + // requirement must be merged in here too. Without this, a directory that is *both* a + // directly-wanted `NonRecursive` directory *and* someone else's fallback ancestor + // could have its watch silently downgraded to `NonRecursive` below -- depending on + // this `HashMap`'s unspecified iteration order, `path` may be processed only after + // `watch_fallback_ancestor` already installed the `Recursive` watch it needs, and + // `self.watched_dirs.get(path) == Some(mode)` (comparing directly against the plain + // `NonRecursive` `wanted` for this path) would then be `false`, causing a re-`watch` + // that replaces the existing `Recursive` registration with a weaker `NonRecursive` + // one. That leaves creation of files nested under `path` unnoticed until the next + // `reconcile_interval` backstop, defeating the very purpose of the fallback watch. + let mode = if self + .fallback_watches + .values() + .any(|fallback_ancestor| fallback_ancestor == path) + { + mode.merge(WatchMode::Recursive) + } else { + *mode + }; + if self.watched_dirs.get(path) == Some(&mode) { + continue; + } + match self.watcher.watch(path, mode.mode()) { + Ok(()) => { + trace!(message = "Watching directory for file events.", path = ?path, ?mode); + // Only record success: if `watch` failed, leaving this path out of + // `watched_dirs` means the next `resync_watches` call (from the backstop + // reconciliation pass) will see it as still "wanted but not yet watched" and + // retry, rather than wrongly concluding the watch is already in place and + // never trying again. + self.watched_dirs.insert(path.clone(), mode); + // The real directory is now watched directly; drop any record of it having + // depended on a fallback ancestor. The ancestor's own watch, if now unused, + // is cleaned up below. + self.fallback_watches.remove(path); + } + Err(error) => { + // Always try the ancestor fallback on any `watch` failure, rather than first + // branching on `path.is_dir()` to decide whether the directory "doesn't exist + // yet" (fallback) versus "exists but couldn't be watched" (no fallback, e.g. a + // permissions problem or platform resource limit): checking `is_dir()` only + // *after* `watch` has already failed is a TOCTOU race -- if the directory is + // created in the gap between the two calls, `is_dir()` now reports `true` for + // what was, at `watch`-time, a missing directory, wrongly skipping the fallback + // that would otherwise have watched its (now-populated) parent. Attempting the + // fallback unconditionally is safe either way: if the directory does exist and + // the failure is permanent (permissions, resource limits), watching its parent + // recursively still lets us notice changes to it (a recursive watch on a + // directory observes events inside its children too, so this isn't a no-op), + // it's simply broader/more expensive than directly watching `path`. That's a + // strictly better outcome than reporting the error and doing nothing further + // until the next `reconcile_interval` backstop. + match find_existing_ancestor(path) { + Some(ancestor) => self.watch_fallback_ancestor(path, ancestor, emitter), + None => { + warn!(message = "Failed to watch directory.", path = ?path, %error); + emitter.emit_file_watch_backend_error(&std::io::Error::other( + error.to_string(), + )); + } + } + } + } + } + + self.fallback_watches + .retain(|path, _ancestor| wanted.contains_key(path)); + // A directory stays watched if it's directly wanted, or if some still-wanted directory + // depends on it as its fallback ancestor; anything else (no longer wanted, or a fallback + // ancestor whose dependent either got its own direct watch or was dropped above) is + // unwatched and forgotten. + let ancestors_in_use: std::collections::HashSet<&PathBuf> = + self.fallback_watches.values().collect(); + self.watched_dirs.retain(|path, _mode| { + if wanted.contains_key(path) || ancestors_in_use.contains(path) { + return true; + } + // Best-effort: if the directory is already gone, unwatch will simply error, which we + // can ignore -- there's nothing left to watch. + drop(self.watcher.unwatch(path)); + false + }); + + emitter.emit_file_watch_directories(self.watched_dirs.len()); + } + + /// Watch `ancestor` (recursively, so creation of `wanted` underneath it is observed) as a + /// stand-in for the not-yet-existing `wanted` directory, recording the substitution in + /// `fallback_watches` so a later `resync_watches` call can detect once `wanted` exists and + /// upgrade to watching it directly. + fn watch_fallback_ancestor( + &mut self, + wanted: &Path, + ancestor: PathBuf, + emitter: &E, + ) { + if self.watched_dirs.get(&ancestor) == Some(&WatchMode::Recursive) { + // Some other wanted directory already caused us to watch this same ancestor + // recursively; nothing more to do beyond recording that this wanted directory now + // also depends on it. + self.fallback_watches.insert(wanted.to_path_buf(), ancestor); + return; + } + match self.watcher.watch(&ancestor, RecursiveMode::Recursive) { + Ok(()) => { + debug!( + message = "Configured directory does not exist yet; watching nearest existing ancestor instead.", + wanted = ?wanted, + ancestor = ?ancestor, + ); + self.watched_dirs + .insert(ancestor.clone(), WatchMode::Recursive); + self.fallback_watches.insert(wanted.to_path_buf(), ancestor); + } + Err(error) => { + warn!(message = "Failed to watch directory.", path = ?ancestor, %error); + emitter.emit_file_watch_backend_error(&std::io::Error::other(error.to_string())); + } + } + } + + /// Await the next batch of filesystem events. + pub async fn recv(&mut self) -> Option { + self.receiver.recv().await + } + + /// Forget which directories we believe are currently watched, without touching the + /// underlying OS-level watcher. The next `resync_watches` call will then treat every + /// directory implied by `include_patterns` as unwatched and re-`watch` it. + /// + /// Call this after a [`NotifyMessage::BackendError`], which signals that the watcher backend + /// itself hit a problem (e.g. it silently dropped a watch because the directory it was + /// watching was removed and recreated, or some other backend-specific hiccup). Without this, + /// `resync_watches`'s "only `watch()` a path if we don't already believe it's watched" check + /// (necessary so it doesn't uselessly re-`watch` paths on every call) means a watch lost this + /// way is never re-established: `include_patterns` hasn't changed, so the set of "wanted" + /// directories is identical to what's already recorded in `watched_dirs`, and the loop skips + /// every one of them. Re-`watch`-ing a path notify still has registered correctly is a + /// harmless no-op, so clearing all bookkeeping on any backend error, rather than trying to + /// determine which specific watch was affected (which notify's error doesn't tell us), is the + /// simple, safe choice here. + pub fn forget_watches(&mut self) { + self.watched_dirs.clear(); + } + + /// Forget bookkeeping for a single watched directory, without touching the underlying OS-level + /// watcher, so the next `resync_watches` call re-`watch`es it if it's still (or again) wanted. + /// + /// Call this when a [`NotifyMessage::PathsRemoved`] reports the removal of a path that is + /// itself one of our watched directories (as opposed to a file inside one). On Linux/inotify, + /// removing a watched directory invalidates the kernel-side watch on that inode; if the + /// directory is later recreated (e.g. an application that removes and recreates its log + /// directory, or `logrotate`-style directory rotation), `notify` has no watch left to fire + /// events from, but `resync_watches`'s "only `watch()` a path we don't already believe is + /// watched" check still sees this directory in `watched_dirs` (removal doesn't change + /// `include_patterns`, so the "wanted" set is unchanged) and skips re-`watch`-ing it forever. + /// Without this, such a directory falls back to being noticed only by the much-less-frequent + /// backstop reconciliation, same as a lost `BackendError`-reported watch. + pub fn forget_watch(&mut self, path: &Path) { + self.watched_dirs.remove(path); + } + + /// Whether `path` is currently believed to be a watched directory (as opposed to, say, a file + /// inside one). Used to decide whether a [`NotifyMessage::PathsRemoved`] path warrants + /// `forget_watch`. + pub fn is_watched_dir(&self, path: &Path) -> bool { + self.watched_dirs.contains_key(path) + } +} + +#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)] +enum WatchMode { + Recursive, + NonRecursive, +} + +impl WatchMode { + fn mode(self) -> RecursiveMode { + match self { + WatchMode::Recursive => RecursiveMode::Recursive, + WatchMode::NonRecursive => RecursiveMode::NonRecursive, + } + } + + /// Combine the modes wanted for the same directory by two different (overlapping) `include` + /// patterns. `Recursive` always wins: it observes a strict superset of what `NonRecursive` + /// would, so it's the only mode that satisfies both patterns' requirements at once. + fn merge(self, other: WatchMode) -> WatchMode { + if self == WatchMode::Recursive || other == WatchMode::Recursive { + WatchMode::Recursive + } else { + WatchMode::NonRecursive + } + } +} + +/// Walk up from `path` to find the nearest ancestor directory that currently exists on disk. +/// Returns `None` only if no ancestor exists at all (e.g. even the filesystem root couldn't be +/// stat-ed, which in practice shouldn't happen). +/// +/// For a relative `path` with only one component (e.g. `logs` from an `include` pattern like +/// `logs/*.log`), `Path::ancestors()` yields that component and then an empty path (`""`) -- +/// there is no further parent to walk up to for a relative path. `Path::is_dir()` on `""` is +/// always `false` regardless of the actual current directory (unlike `"."`, which `is_dir()` +/// correctly reports as the current directory), so without special-casing it, a relative +/// top-level root that doesn't exist yet would find no existing ancestor at all -- silently +/// forgoing the fallback-ancestor watch and leaving that `include` pattern's eventual root +/// creation unnoticed until the next `reconcile_interval` backstop. Treat the empty ancestor as +/// `.` (the current directory), which is what it actually denotes. +fn find_existing_ancestor(path: &Path) -> Option { + path.ancestors().skip(1).find_map(|ancestor| { + let ancestor = if ancestor.as_os_str().is_empty() { + Path::new(".") + } else { + ancestor + }; + ancestor.is_dir().then(|| ancestor.to_path_buf()) + }) +} + +/// A directory to `WatchMode` mapping. A `HashMap` keyed on the path alone -- not a set of +/// `(PathBuf, WatchMode)` pairs -- is deliberate: two different `include` patterns can imply the +/// same directory under two different modes (e.g. `/var/log/*.log` wants it `NonRecursive` while +/// `/var/log/**/*.log` wants it `Recursive`), and a directory can only actually be watched one +/// way at a time. Keying on the pair would let both "versions" of the same directory coexist as +/// distinct set members, which doesn't correspond to any real state `notify` can be in. +type WantedDirs = HashMap; + +/// Compute, for a set of glob include patterns, the directories that should be watched (and +/// whether each should be watched recursively) in order to observe every path that could +/// possibly match one of the patterns. +/// +/// For each pattern, this walks its path components, stopping at the first component containing +/// a glob metacharacter (`*`, `?`, `[`, `{`). The path made up of the components before that +/// point is the directory to watch. If the pattern contains a `**` component, or has any +/// directory separator after the first glob metacharacter (meaning matches can be nested +/// arbitrarily deep below the watched directory), the watch is recursive; otherwise (a single +/// glob component with no further nesting, e.g. `/var/log/*.log`) a non-recursive watch +/// suffices and is preferred, since it's cheaper (particularly on inotify, where recursive +/// watching means watching every subdirectory individually) and matches the "flat glob" +/// intent. +fn compute_watch_directories(include_patterns: &[PathBuf]) -> WantedDirs { + let mut result = WantedDirs::new(); + + for pattern in include_patterns { + let mut literal_prefix = PathBuf::new(); + let mut remainder_has_glob = false; + let mut remainder_has_separator_after_glob = false; + let mut seen_glob = false; + + for component in pattern.components() { + let comp_str = component.as_os_str().to_string_lossy(); + let is_glob_component = contains_glob_metachar(&comp_str); + + if !seen_glob && !is_glob_component { + literal_prefix.push(component.as_os_str()); + continue; + } + + // Any component from here on -- glob or literal -- appearing after the *first* glob + // component means matches can be nested at least one level below the watched + // directory (e.g. `*/*.log` or `*/sub/*.log`), which recursion is needed to observe. + // Checking only for a literal-after-glob (an earlier version of this) missed the + // equally common two-glob-components case (`*/*.log`): its second component is itself + // a glob, not a literal, so it never hit the literal-only branch, silently leaving + // such patterns NonRecursive. + if seen_glob { + remainder_has_separator_after_glob = true; + } + + seen_glob = true; + if is_glob_component { + remainder_has_glob = true; + // `**` means "any depth of nesting" on its own, regardless of what (if anything) + // follows it in the pattern -- a standalone trailing `**` (e.g. `/var/log/**`, + // with nothing after it) needs recursion just as much as `**/*.log` does, but the + // "something follows the first glob component" check above doesn't fire for it + // since there's nothing after it to be "something." Check for it explicitly too. + if comp_str.contains("**") { + remainder_has_separator_after_glob = true; + } + } + } + + // If the whole pattern was literal (no glob at all), watch its parent directory + // non-recursively so we notice the file itself being created/modified/removed. + if !seen_glob { + let dir = literal_prefix + .parent() + .map(Path::to_path_buf) + .unwrap_or_else(|| PathBuf::from(".")); + insert_merging_mode(&mut result, dir, WatchMode::NonRecursive); + continue; + } + + let dir = if literal_prefix.as_os_str().is_empty() { + PathBuf::from(".") + } else { + literal_prefix + }; + + let mode = if remainder_has_glob && remainder_has_separator_after_glob { + WatchMode::Recursive + } else { + WatchMode::NonRecursive + }; + + insert_merging_mode(&mut result, dir, mode); + } + + result +} + +/// Insert `(dir, mode)` into `result`, merging with any existing entry for the same directory +/// (via [`WatchMode::merge`]) rather than overwriting it -- so that two different `include` +/// patterns implying the same directory under different modes correctly end up with the one +/// mode (`Recursive`) that satisfies both, instead of one silently clobbering the other +/// depending on iteration order. +fn insert_merging_mode(result: &mut WantedDirs, dir: PathBuf, mode: WatchMode) { + result + .entry(dir) + .and_modify(|existing| *existing = existing.merge(mode)) + .or_insert(mode); +} + +fn contains_glob_metachar(component: &str) -> bool { + component.contains(['*', '?', '[', '{']) +} + +/// Collapse the wide variety of notify [`EventKind`]s we care about into the coarse +/// [`NotifyMessage`] variants `FileServer` acts on. Returns `None` for event kinds we +/// deliberately ignore (e.g. bare `Access` events, which fire far too often to be useful and +/// carry no information our fingerprint-based reconciliation needs). +fn classify_event(event: Event) -> Option { + match event.kind { + EventKind::Create(CreateKind::Any | CreateKind::File | CreateKind::Folder) => { + Some(NotifyMessage::PathsChanged(event.paths)) + } + EventKind::Modify(ModifyKind::Any | ModifyKind::Data(_) | ModifyKind::Metadata(_)) => { + Some(NotifyMessage::PathsChanged(event.paths)) + } + // Rename events: notify (when it can correlate From/To pairs, which is + // platform-dependent) still gives us the paths involved; treat both ends as "changed" + // since the safest thing to do is let FileServer's reconciliation logic figure out + // what's alive at each path via a fingerprint/stat check. + EventKind::Modify(ModifyKind::Name( + RenameMode::Any | RenameMode::Both | RenameMode::From | RenameMode::To, + )) => Some(NotifyMessage::PathsChanged(event.paths)), + EventKind::Remove(RemoveKind::Any | RemoveKind::File | RemoveKind::Folder) => { + Some(NotifyMessage::PathsRemoved(event.paths)) + } + EventKind::Create(CreateKind::Other) + | EventKind::Modify(ModifyKind::Other | ModifyKind::Name(RenameMode::Other)) + | EventKind::Remove(RemoveKind::Other) => Some(NotifyMessage::PathsChanged(event.paths)), + EventKind::Any | EventKind::Other => { + // Deliberately conservative: an event we can't classify might still be relevant + // (some backends report generic "Any" for things we care about), so treat it as a + // change rather than silently dropping it. Access events are the only kind we + // intentionally ignore below. + if event.paths.is_empty() { + None + } else { + Some(NotifyMessage::PathsChanged(event.paths)) + } + } + EventKind::Access(_) => { + debug!(message = "Ignoring filesystem access event.", paths = ?event.paths); + None + } + } +} + +fn is_overflow(error: ¬ify::Error) -> bool { + matches!(error.kind, notify::ErrorKind::MaxFilesWatch) + || error.to_string().to_lowercase().contains("overflow") +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn literal_pattern_watches_parent_non_recursive() { + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/vector.log")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::NonRecursive)); + } + + #[test] + fn single_star_watches_dir_non_recursive() { + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/*.log")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::NonRecursive)); + } + + #[test] + fn double_star_watches_recursively() { + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/**/*.log")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::Recursive)); + } + + #[test] + fn standalone_trailing_double_star_watches_recursively() { + // Regression test for a bug found in review: a `**` with nothing after it in the pattern + // (as opposed to `**/*.log`, covered above) means "any depth of nesting" on its own, so + // it needs a recursive watch just as much as the with-a-suffix case does. The + // "something follows the first glob component" check that handles `*/*.log` and + // `*/sub/*.log` doesn't fire here, since there's nothing after the lone `**` component to + // be "something" -- this pattern needs the explicit "this component itself contains '**'" + // check to be recognized as recursive. + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/**")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::Recursive)); + } + + #[test] + fn nested_literal_after_glob_watches_recursively() { + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/*/app.log")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::Recursive)); + } + + #[test] + fn nested_glob_after_glob_watches_recursively() { + // Two glob components in a row (`*/*.log`), as opposed to a literal component after a + // glob (`*/app.log`, covered above) or a `**` component. Both the directory-matching `*` + // and the file-matching `*.log` are themselves globs, so neither the old "does this + // component contain '**'" check nor the old "is this a literal component after a glob" + // check caught this pattern -- it was silently left NonRecursive, meaning writes to files + // in subdirectories that already existed when the watch was established would never be + // noticed by the notify event path (only by the much-less-frequent reconcile-interval + // backstop). + let dirs = compute_watch_directories(&[PathBuf::from("/var/log/*/*.log")]); + assert_eq!(dirs.len(), 1); + let (path, mode) = dirs.into_iter().next().unwrap(); + assert_eq!(path, PathBuf::from("/var/log")); + assert!(matches!(mode, WatchMode::Recursive)); + } + + #[test] + fn multiple_patterns_produce_multiple_dirs() { + let dirs = compute_watch_directories(&[ + PathBuf::from("/var/log/*.log"), + PathBuf::from("/opt/app/logs/*.log"), + ]); + assert_eq!(dirs.len(), 2); + } + + #[test] + fn overlapping_patterns_for_same_dir_merge_to_one_recursive_entry() { + // `*.log` alone would only need `/var/log` watched non-recursively, but the second, + // overlapping pattern needs it recursive (nested subdirectories can match too). The two + // patterns must resolve to exactly one entry for `/var/log`, watched `Recursive` (which + // covers what `NonRecursive` would have caught too) -- not two separate entries for the + // same directory under different modes, which isn't a state `notify` can actually be in + // (a directory is watched one way or the other, never both at once). + let dirs = compute_watch_directories(&[ + PathBuf::from("/var/log/*.log"), + PathBuf::from("/var/log/**/*.log"), + ]); + assert_eq!( + dirs.len(), + 1, + "overlapping patterns for the same directory must merge into a single entry, \ + not coexist as separate (path, mode) pairs" + ); + assert_eq!( + dirs.get(&PathBuf::from("/var/log")), + Some(&WatchMode::Recursive) + ); + } + + #[test] + fn watch_mode_merge_prefers_recursive() { + assert_eq!( + WatchMode::NonRecursive.merge(WatchMode::Recursive), + WatchMode::Recursive + ); + assert_eq!( + WatchMode::Recursive.merge(WatchMode::NonRecursive), + WatchMode::Recursive + ); + assert_eq!( + WatchMode::NonRecursive.merge(WatchMode::NonRecursive), + WatchMode::NonRecursive + ); + assert_eq!( + WatchMode::Recursive.merge(WatchMode::Recursive), + WatchMode::Recursive + ); + } + + #[derive(Clone)] + struct NoopEmitter; + + impl FileSourceInternalEvents for NoopEmitter { + fn emit_file_added(&self, _path: &std::path::Path) {} + fn emit_file_resumed(&self, _path: &std::path::Path, _file_position: u64) {} + fn emit_file_watch_error(&self, _path: &std::path::Path, _error: std::io::Error) {} + fn emit_file_unwatched(&self, _path: &std::path::Path, _reached_eof: bool) {} + fn emit_file_deleted(&self, _path: &std::path::Path) {} + fn emit_file_delete_error(&self, _path: &std::path::Path, _error: std::io::Error) {} + fn emit_file_fingerprint_read_error( + &self, + _path: &std::path::Path, + _error: std::io::Error, + ) { + } + fn emit_file_checkpointed(&self, _count: usize, _duration: std::time::Duration) {} + fn emit_file_checksum_failed(&self, _path: &std::path::Path) {} + fn emit_file_checkpoint_write_error(&self, _error: std::io::Error) {} + fn emit_files_open(&self, _count: usize) {} + fn emit_files_idle(&self, _count: usize) {} + fn emit_path_globbing_failed(&self, _path: &std::path::Path, _error: &std::io::Error) {} + fn emit_file_line_too_long(&self, _buf: &bytes::BytesMut, _max_size: usize, _size: usize) {} + } + + #[test] + fn forget_watches_makes_resync_re_watch_everything() { + // Regression test for a bug found in review: on `NotifyMessage::BackendError` (the + // watcher backend silently dropping a watch, e.g. because a watched directory was + // removed and recreated out from under it), `FileServer` used to just trigger a + // reconciliation pass without clearing `NotifyDiscovery`'s own bookkeeping first. + // `resync_watches` only calls `watch()` on a directory it doesn't already believe is + // watched -- necessary so it doesn't uselessly re-`watch` every directory on every call + // -- so with `include_patterns` unchanged, the "wanted" set is identical to what's + // already recorded, and the loop would skip re-`watch`-ing the directory that actually + // lost its watch. The watch would then never be re-established until Vector restarted. + // + // This can't easily be tested by actually breaking notify's underlying watch (that's + // backend- and OS-specific, and not something the `notify` crate exposes a way to + // simulate), but the property that matters is `NotifyDiscovery`-internal and doesn't + // require one: `forget_watches` must leave `resync_watches` believing every directory is + // unwatched, so it re-`watch`es all of them. Re-`watch`-ing a path the backend actually + // still has registered correctly is a harmless no-op, so this is the right (and only + // practical) recovery strategy regardless of which specific watch was actually lost. + let dir = tempfile::tempdir().unwrap(); + let pattern = dir.path().join("*.log"); + let mut discovery = + NotifyDiscovery::new(std::slice::from_ref(&pattern), &NoopEmitter).unwrap(); + + assert_eq!( + discovery.watched_dirs.len(), + 1, + "resync_watches (called from `new`) should have recorded the one watched directory" + ); + + discovery.forget_watches(); + assert!( + discovery.watched_dirs.is_empty(), + "forget_watches must clear the watched-directories bookkeeping" + ); + + // With bookkeeping cleared but `include_patterns` unchanged, resync_watches must + // re-`watch` (not skip) the directory, ending up back where it started. + discovery.resync_watches(&[pattern], &NoopEmitter); + assert_eq!( + discovery.watched_dirs.len(), + 1, + "resync_watches must re-establish the watch after bookkeeping was forgotten" + ); + assert_eq!( + discovery.watched_dirs.get(dir.path()), + Some(&WatchMode::NonRecursive) + ); + } + + #[test] + fn forget_watch_makes_resync_re_watch_one_directory() { + // Regression test for a bug found in review: removing a watched *directory* on + // Linux/inotify invalidates the watch on that inode, but a `PathsRemoved` notification for + // it used to be handled the same as any other path event (just triggering a reconciliation + // pass), leaving the directory recorded in `watched_dirs`. `resync_watches`'s "only + // `watch()` a directory we don't already believe is watched" check would then skip + // re-`watch`-ing it even after it was recreated, permanently falling back to the + // much-less-frequent backstop reconciliation for that directory. + let dir = tempfile::tempdir().unwrap(); + let pattern = dir.path().join("*.log"); + let mut discovery = + NotifyDiscovery::new(std::slice::from_ref(&pattern), &NoopEmitter).unwrap(); + + assert!(discovery.is_watched_dir(dir.path())); + + discovery.forget_watch(dir.path()); + assert!( + !discovery.is_watched_dir(dir.path()), + "forget_watch must remove just this directory's bookkeeping" + ); + + discovery.resync_watches(&[pattern], &NoopEmitter); + assert!( + discovery.is_watched_dir(dir.path()), + "resync_watches must re-establish the watch after it was forgotten" + ); + } + + #[test] + fn missing_root_falls_back_to_watching_existing_ancestor() { + // Regression test for a bug found in review: if the literal prefix of an `include` + // pattern doesn't exist yet at startup (e.g. `/var/log/newapp/*.log` before `newapp` has + // been created), `watch()`-ing it directly fails and, prior to this fix, nothing was + // watched at all for that pattern -- its creation would only be noticed on the next + // `reconcile_interval` backstop tick (potentially minutes away), rather than promptly via + // a notify event. + let root = tempfile::tempdir().unwrap(); + let missing_dir = root.path().join("newapp"); + let pattern = missing_dir.join("*.log"); + let mut discovery = + NotifyDiscovery::new(std::slice::from_ref(&pattern), &NoopEmitter).unwrap(); + + assert!( + !discovery.is_watched_dir(&missing_dir), + "the not-yet-existing directory itself should not be directly watched" + ); + assert_eq!( + discovery.watched_dirs.get(root.path()), + Some(&WatchMode::Recursive), + "the nearest existing ancestor should be watched recursively as a stand-in" + ); + + // Once the directory is created, the next resync should upgrade to watching it directly + // and drop the broader ancestor watch. + std::fs::create_dir(&missing_dir).unwrap(); + discovery.resync_watches(&[pattern], &NoopEmitter); + assert_eq!( + discovery.watched_dirs.get(&missing_dir), + Some(&WatchMode::NonRecursive), + "resync_watches must upgrade to watching the now-existing directory directly" + ); + assert!( + !discovery.is_watched_dir(root.path()), + "the fallback ancestor watch should be dropped once no longer needed" + ); + } + + #[test] + fn find_existing_ancestor_treats_relative_top_level_root_as_current_dir() { + // Regression test for a bug found in review: for a relative `include` pattern with a + // single-component root (e.g. `logs/*.log`, whose literal prefix is just `logs`), + // `Path::ancestors()` on a not-yet-existing `logs` yields `logs` then an empty path + // (`""`) -- there's no further parent for a relative path to walk up to. `Path::is_dir()` + // on `""` is always `false`, even though `""` denotes the current directory (same as + // `"."`, which `is_dir()` correctly reports as existing). Before this fix, + // `find_existing_ancestor` would therefore return `None` for a missing relative + // top-level root, silently skipping the fallback-ancestor watch entirely: creating + // `logs` could never be noticed via notify, only via the `reconcile_interval` backstop. + let missing_relative_root = PathBuf::from("logs"); + let ancestor = find_existing_ancestor(&missing_relative_root) + .expect("the current directory must be found as an existing ancestor"); + assert!( + ancestor.is_dir(), + "the returned ancestor must actually exist and be a directory" + ); + } + + #[test] + fn fallback_ancestor_that_is_also_directly_wanted_stays_recursive() { + // Regression test for a bug found in review: `root` is both (a) a fallback ancestor for + // `missing_dir`, which doesn't exist yet and needs `root` watched `Recursive` so its + // eventual creation is noticed, and (b) itself a directly-wanted directory from a second, + // unrelated `include` pattern that on its own would only need `NonRecursive`. + // `HashMap`'s unspecified iteration order means the main loop in `resync_watches` could + // process `root` (as the plain `NonRecursive`-wanted directory) either before or after + // `missing_dir` triggers the `Recursive` fallback watch on it. Before this fix, whichever + // order put the direct `NonRecursive` `watch()` call *last* would silently downgrade + // `root`'s registration from `Recursive` to `NonRecursive`, since the "already watched + // under the wanted mode" skip-check compared only against the plain per-pattern mode, not + // the merged requirement. That leaves file creation nested under `root` (which is what the + // `missing_dir` fallback exists to observe) unnoticed until the next `reconcile_interval` + // backstop. + let root = tempfile::tempdir().unwrap(); + let missing_dir = root.path().join("newapp"); + let missing_pattern = missing_dir.join("*.log"); + let direct_pattern = root.path().join("*.log"); + let mut discovery = NotifyDiscovery::new( + &[missing_pattern.clone(), direct_pattern.clone()], + &NoopEmitter, + ) + .unwrap(); + + assert_eq!( + discovery.watched_dirs.get(root.path()), + Some(&WatchMode::Recursive), + "root must stay Recursive: it's both directly wanted (NonRecursive on its own) and \ + a fallback ancestor (Recursive) for the not-yet-existing missing_dir" + ); + + // Re-running resync_watches (e.g. the periodic backstop, with nothing on disk having + // changed) must not downgrade it either, regardless of `wanted`'s iteration order on this + // second pass. + discovery.resync_watches(&[missing_pattern, direct_pattern], &NoopEmitter); + assert_eq!( + discovery.watched_dirs.get(root.path()), + Some(&WatchMode::Recursive), + "root must remain Recursive across repeated resync_watches calls" + ); + } +} diff --git a/lib/file-source/src/paths_provider.rs b/lib/file-source/src/paths_provider.rs index 3c4fd65d66a89..a5cf2c2e28e4c 100644 --- a/lib/file-source/src/paths_provider.rs +++ b/lib/file-source/src/paths_provider.rs @@ -29,6 +29,17 @@ pub trait PathsProvider { /// Provides a set of paths. fn paths(&self) -> Self::IntoIter; + + /// Provides the raw patterns (or literal roots) this provider globs/scans from, for use by + /// event-driven discovery (see [`crate::notify_watcher`]) to compute which directories to + /// watch for OS-level filesystem notifications. + /// + /// Defaults to an empty vec, meaning "no known roots" -- implementors that don't override + /// this simply won't participate in notify-based discovery (`FileServer` will fall back to + /// polling-only behavior for such providers, since it has nothing to watch). + fn watch_roots(&self) -> Vec { + Vec::new() + } } /// A glob-based path provider. @@ -74,6 +85,10 @@ impl Glob { impl PathsProvider for Glob { type IntoIter = Vec; + fn watch_roots(&self) -> Vec { + self.include_patterns.iter().map(PathBuf::from).collect() + } + fn paths(&self) -> Self::IntoIter { self.include_patterns .iter() diff --git a/lib/vector-common/src/internal_event/metric_name.rs b/lib/vector-common/src/internal_event/metric_name.rs index 93f587717bd06..bfb9c79a62fd9 100644 --- a/lib/vector-common/src/internal_event/metric_name.rs +++ b/lib/vector-common/src/internal_event/metric_name.rs @@ -197,6 +197,7 @@ pub enum GaugeName { Utilization, ComponentAllocatedBytes, OpenFiles, + IdleFiles, UptimeSeconds, BuildInfo, KafkaQueueMessages, @@ -239,6 +240,7 @@ impl GaugeName { Self::Utilization => "utilization", Self::ComponentAllocatedBytes => "component_allocated_bytes", Self::OpenFiles => "open_files", + Self::IdleFiles => "idle_files", Self::UptimeSeconds => "uptime_seconds", Self::BuildInfo => "build_info", Self::KafkaQueueMessages => "kafka_queue_messages", diff --git a/src/internal_events/file.rs b/src/internal_events/file.rs index 66def9a921ef6..95a8578e81c3a 100644 --- a/src/internal_events/file.rs +++ b/src/internal_events/file.rs @@ -41,6 +41,22 @@ impl InternalEvent for FileOpen { } } +/// Number of tracked files currently in the passive "idle" state: checkpoint +/// retained, but no open file handle (see +/// ). Reported alongside +/// [`FileOpen`] so that the effect of moving idle files out of the "open +/// handle" count is directly observable. +#[derive(Debug, NamedInternalEvent)] +pub struct FilesIdle { + pub count: usize, +} + +impl InternalEvent for FilesIdle { + fn emit(self) { + gauge!(GaugeName::IdleFiles).set(self.count as f64); + } +} + #[derive(Debug, NamedInternalEvent)] pub struct FileBytesSent<'a> { pub byte_size: usize, @@ -152,7 +168,7 @@ mod source { json_size::JsonSize, }; - use super::{FileOpen, InternalEvent}; + use super::{FileOpen, FilesIdle, InternalEvent}; #[derive(Debug, NamedInternalEvent)] pub struct FileBytesReceived<'a> { @@ -560,6 +576,65 @@ mod source { } } + #[derive(Debug, NamedInternalEvent)] + pub struct FileWatchEventsOverflowed {} + + impl InternalEvent for FileWatchEventsOverflowed { + fn emit(self) { + warn!( + message = "OS-level file watch event queue overflowed; some file changes may have been missed. Relying on periodic reconciliation to catch up.", + error_code = "watch_overflow", + error_type = error_type::READER_FAILED, + stage = error_stage::RECEIVING, + ); + counter!( + CounterName::ComponentErrorsTotal, + "error_code" => "watch_overflow", + "error_type" => error_type::READER_FAILED, + "stage" => error_stage::RECEIVING, + ) + .increment(1); + } + } + + #[derive(Debug, NamedInternalEvent)] + pub struct FileWatchBackendError { + pub error: String, + } + + impl InternalEvent for FileWatchBackendError { + fn emit(self) { + error!( + message = "OS-level file watch backend failed. Falling back to periodic reconciliation until watching is re-established.", + error = %self.error, + error_code = "watch_backend_failed", + error_type = error_type::COMMAND_FAILED, + stage = error_stage::RECEIVING, + ); + counter!( + CounterName::ComponentErrorsTotal, + "error_code" => "watch_backend_failed", + "error_type" => error_type::COMMAND_FAILED, + "stage" => error_stage::RECEIVING, + ) + .increment(1); + } + } + + #[derive(Debug, NamedInternalEvent)] + pub struct FileWatchDirectories { + pub count: usize, + } + + impl InternalEvent for FileWatchDirectories { + fn emit(self) { + debug!( + message = "Watching directories for file system events.", + count = %self.count, + ); + } + } + #[derive(Clone)] pub struct FileSourceInternalEventsEmitter { pub include_file_metric_tag: bool, @@ -639,6 +714,10 @@ mod source { emit!(FileOpen { count }); } + fn emit_files_idle(&self, count: usize) { + emit!(FilesIdle { count }); + } + fn emit_path_globbing_failed(&self, path: &Path, error: &Error) { emit!(PathGlobbingError { path, error }); } @@ -655,5 +734,19 @@ mod source { encountered_size_so_far }); } + + fn emit_file_watch_events_overflowed(&self) { + emit!(FileWatchEventsOverflowed {}); + } + + fn emit_file_watch_backend_error(&self, error: &Error) { + emit!(FileWatchBackendError { + error: error.to_string(), + }); + } + + fn emit_file_watch_directories(&self, count: usize) { + emit!(FileWatchDirectories { count }); + } } } diff --git a/src/sources/file.rs b/src/sources/file.rs index 1b8283a50463a..5619086f97224 100644 --- a/src/sources/file.rs +++ b/src/sources/file.rs @@ -14,7 +14,7 @@ use vector_lib::{ config::{LegacyKey, LogNamespace}, configurable::configurable_component, file_source::{ - file_server::{FileServer, Line, calculate_ignore_before}, + file_server::{FileDiscoveryMode, FileServer, Line, calculate_ignore_before}, paths_provider::{Glob, MatchOptions}, }, file_source_common::{ @@ -36,7 +36,7 @@ use crate::{ event::{BatchNotifier, BatchStatus, LogEvent}, internal_events::{ FileBytesReceived, FileEventsReceived, FileInternalMetricsConfig, FileOpen, - FileSourceInternalEventsEmitter, StreamClosedError, + FileSourceInternalEventsEmitter, FilesIdle, StreamClosedError, }, line_agg::{self, LineAgg}, serde::bool_or_struct, @@ -237,6 +237,89 @@ pub struct FileConfig { #[configurable(metadata(docs::type_unit = "seconds"))] #[serde(default = "default_rotate_wait", rename = "rotate_wait_secs")] pub rotate_wait: Duration, + + /// The mechanism used to discover new files, detect renames, and wake up reads of existing + /// files. + /// + /// `polling` (the default) re-scans the `include` glob patterns on a fixed interval + /// (`glob_minimum_cooldown_ms`) and keeps an open file handle for every matched file for as + /// long as it exists on disk, even files excluded from reading by `ignore_older`. This is + /// simple and works identically everywhere, but can be expensive when a very large number of + /// files match `include`. + /// + /// `notify` uses OS-level file system event notifications (inotify on Linux, FSEvents on + /// macOS, `ReadDirectoryChangesW` on Windows) to discover files and wake up reads promptly, + /// without needing to re-scan or hold a handle open for inactive files. A much less frequent + /// periodic reconciliation pass (`reconcile_interval_secs`) still runs as a correctness + /// backstop, since OS-level notification queues can silently overflow. This mode is newer + /// and has had less production exposure than `polling`. + #[serde(default)] + pub file_discovery_mode: FileDiscoveryModeConfig, + + /// How often to run the full glob+fingerprint reconciliation pass when + /// `file_discovery_mode` is `notify`. This exists purely as a correctness backstop for + /// OS-level file watch events that were dropped (e.g. due to queue overflow) or that + /// occurred before the watch was established. Ignored when `file_discovery_mode` is + /// `polling`. + #[serde_as(as = "serde_with::DurationSeconds")] + #[configurable(metadata(docs::type_unit = "seconds"))] + #[serde( + default = "default_reconcile_interval_secs", + rename = "reconcile_interval_secs" + )] + pub reconcile_interval: Duration, + + /// How long to wait, after a file has been fully read (reached EOF) and stops receiving new + /// data, before closing its file handle. + /// + /// Vector keeps polling the file's metadata (size and modification time) cheaply, without + /// holding the handle open, and transparently reopens the file if new data arrives. This + /// avoids holding a large number of open file handles for files that are being watched (for + /// example, due to `ignore_older_secs` not yet excluding them, or simply because they haven't + /// rotated out of the `include` glob yet) but are not actively being written to. Applies + /// regardless of `file_discovery_mode`: `notify` makes *discovering* files fast, but doesn't + /// by itself stop an already-discovered file from holding a handle open indefinitely -- this + /// option is what does that. + /// + /// This also applies at startup: a file that also matches `ignore_older_secs` is never opened + /// in the first place, as long as Vector can determine without opening it that there is no + /// new data to read (either because its on-disk size already matches its stored checkpoint + /// position, or because it isn't gzip-compressed, in which case an old file is never read + /// from regardless of checkpoint). + /// + /// Defaults to 60 seconds. Set this explicitly to `null` to disable idle-timeout-based closing + /// entirely, so that active file handles are only ever closed by other means (for example, + /// rotation via `rotate_wait_secs`), matching Vector's behavior prior to this option's + /// introduction. + #[serde(default = "default_idle_timeout_secs")] + #[configurable(metadata(docs::type_unit = "seconds"))] + #[configurable(metadata(docs::examples = 60))] + #[configurable(metadata(docs::human_name = "Idle Timeout"))] + pub idle_timeout_secs: Option, +} + +/// The mechanism `file` uses to discover new files, detect renames, and wake up reads of +/// existing files. +#[configurable_component] +#[derive(Clone, Copy, Debug, PartialEq, Eq, Default)] +#[serde(rename_all = "snake_case")] +pub enum FileDiscoveryModeConfig { + /// Re-scan the `include` glob patterns on a fixed interval (`glob_minimum_cooldown_ms`). + #[default] + Polling, + /// Use OS-level file system event notifications to discover files and wake up reads + /// promptly, falling back to a periodic reconciliation pass (`reconcile_interval_secs`) as a + /// correctness backstop. + Notify, +} + +impl From for FileDiscoveryMode { + fn from(config: FileDiscoveryModeConfig) -> FileDiscoveryMode { + match config { + FileDiscoveryModeConfig::Polling => FileDiscoveryMode::PollingOnly, + FileDiscoveryModeConfig::Notify => FileDiscoveryMode::Notify, + } + } } fn default_max_line_bytes() -> usize { @@ -271,6 +354,27 @@ const fn default_rotate_wait() -> Duration { Duration::from_secs(u64::MAX / 2) } +/// Justification: this is meant to be a correctness backstop, not the primary discovery +/// mechanism, when `file_discovery_mode = notify`. It only needs to be frequent enough to +/// recover promptly from a dropped/overflowed OS event queue or a missed pre-watch change, +/// not frequent enough to serve as the main polling loop the way `glob_minimum_cooldown_ms` +/// did. Five minutes bounds the worst-case "silently missed a file" window to something +/// operators can reason about, while keeping the reconciliation pass (a full glob + fingerprint +/// scan over every matched file) rare enough that it doesn't reintroduce the cost this mode +/// exists to avoid. +const fn default_reconcile_interval_secs() -> Duration { + Duration::from_secs(300) +} + +/// Default `idle_timeout_secs`: 60 seconds of no new data after reaching EOF before a file's +/// handle is closed. This is deliberately much longer than the read backoff (which tops out at +/// 250ms) so that ordinary, bursty log writers don't cause handles to be repeatedly closed and +/// reopened; it is deliberately not "no limit" (unlike `rotate_wait`) because the entire point of +/// this option is to bound the number of concurrently open handles by default. +const fn default_idle_timeout_secs() -> Option { + Some(60) +} + /// Configuration for how files should be identified. /// /// This is important for `checkpointing` when file rotation is used. @@ -377,6 +481,9 @@ impl Default for FileConfig { log_namespace: None, internal_metrics: Default::default(), rotate_wait: default_rotate_wait(), + file_discovery_mode: FileDiscoveryModeConfig::default(), + reconcile_interval: default_reconcile_interval_secs(), + idle_timeout_secs: default_idle_timeout_secs(), } } } @@ -543,6 +650,9 @@ pub fn file_source( remove_after: config.remove_after_secs.map(Duration::from_secs), emitter, rotate_wait: config.rotate_wait, + discovery_mode: FileDiscoveryMode::from(config.file_discovery_mode), + reconcile_interval: config.reconcile_interval, + idle_timeout: config.idle_timeout_secs.map(Duration::from_secs), }; let event_metadata = EventMetadata { @@ -683,6 +793,7 @@ pub fn file_source( let result = rt.block_on(file_server.run(tx, shutdown, shutdown_checkpointer, checkpointer)); emit!(FileOpen { count: 0 }); + emit!(FilesIdle { count: 0 }); // Panic if we encounter any error originating from the file server. // We're at the `spawn_blocking` call, the panic will be caught and // passed to the `JoinHandle` error, similar to the usual threads. @@ -2510,6 +2621,315 @@ mod tests { } } + // --- Idle-watching tests --------------------------------------------- + // + // These exercise the fix for https://github.com/vectordotdev/vector/issues/3567: + // Vector previously held an open file handle for every matched file for + // as long as it existed on disk, even files excluded by `ignore_older` + // or long past EOF with no new writes. `idle_timeout_secs` (runtime) and + // the startup fast-path in `FileWatcher::new` (see + // lib/file-source/src/file_watcher/mod.rs) address this, independently + // of `file_discovery_mode` -- these tests use the default `polling` + // discovery mode (see the separate `notify_discovery` module below for + // tests specifically covering the `notify` discovery mode, which is an + // orthogonal concern: `notify` speeds up *finding* files, idle_timeout + // stops *already-found* files from holding a handle open). These are + // end-to-end tests through the full `file_source`/`FileServer` pipeline, + // asserting on observable behavior (events received, and correct + // resumption) rather than internal `FileWatcher` state, complementing + // the lower-level state-transition tests in + // lib/file-source/src/file_watcher/tests/mod.rs. + + #[tokio::test] + async fn idle_timeout_closes_handle_and_resumes_on_new_data() { + let n = 3; + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + // Aggressively short idle timeout so the watcher goes idle + // quickly within the test's time budget. + idle_timeout_secs: Some(0), + ..test_default_file_config(&dir) + }; + + let path = dir.path().join("file"); + let counter = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&counter)), + async { + let mut file = File::create(&path).unwrap(); + for i in 0..n { + writeln!(&mut file, "first-batch {i}").unwrap(); + } + file.flush().unwrap(); + + // Wait for the first batch to be received... + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= n, 5_000).await; + + // ...then wait long enough for the watcher to reach EOF, sit + // idle past `idle_timeout_secs: 0`, and be deactivated + // (handle closed) by `FileServer`. A few glob-rescan/read + // cycles at the 100ms `glob_minimum_cooldown_ms` used by + // `test_default_file_config` is more than enough. + sleep(Duration::from_millis(750)).await; + + // Now write more data. If the idle->active transition and + // checkpoint-resume work correctly, this must be picked up + // and read starting from exactly where we left off (no + // duplicate replay of the first batch, no gap). + for i in 0..n { + writeln!(&mut file, "second-batch {i}").unwrap(); + } + file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 2 * n, 5_000).await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines.len(), 2 * n); + for i in 0..n { + assert_eq!(lines[i], format!("first-batch {i}")); + } + for i in 0..n { + assert_eq!(lines[n + i], format!("second-batch {i}")); + } + } + + #[tokio::test] + async fn idle_old_fully_read_file_is_not_reread_on_restart() { + // A file that is: (a) older than `ignore_older_secs`, and (b) whose + // on-disk size already matches its stored checkpoint (nothing new to + // read) must, per the startup fast-path in `FileWatcher::new`, be + // tracked without ever being opened. Observably: it must produce no + // events on a restart, and the data dir's checkpoint must be + // unaffected (no re-read from the beginning). + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ..test_default_file_config(&dir) + }; + + let path = dir.path().join("file"); + let mut file = File::create(&path).unwrap(); + writeln!(&mut file, "only line").unwrap(); + file.flush().unwrap(); + + // First run: read the one line and checkpoint it. + { + let received = + run_file_source(&config, true, Acks, LogNamespace::Legacy, None, async { + sleep_500_millis().await; + }) + .await; + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["only line"]); + } + + // Second run: `ignore_older_secs` set aggressively low so `file` + // (unmodified since the first run, so at least a little bit old by + // now) is excluded. Combined with the checkpoint from the first run + // matching its actual size, `file` must take the idle fast-path at + // startup and yield no new events for it -- but must NOT lose its + // checkpoint or get treated as newly-discovered. A second, freshly + // written file is included in the same run so the harness's + // component-compliance check (which requires at least one event) has + // something to observe, letting us assert on `file` specifically + // being absent from the output rather than the run producing nothing + // at all. + { + let other_path = dir.path().join("other_file"); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ignore_older_secs: Some(1), + ..test_default_file_config(&dir) + }; + let counter = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + true, + Acks, + LogNamespace::Legacy, + Some(Arc::clone(&counter)), + async { + let mut other_file = File::create(&other_path).unwrap(); + writeln!(&mut other_file, "fresh line").unwrap(); + other_file.flush().unwrap(); + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 1, 5_000).await; + }, + ) + .await; + let lines = extract_messages_string(received); + assert_eq!( + lines, + vec!["fresh line"], + "old, fully-checkpointed `file` must not be re-read, \ + only the newly written `other_file` should produce events" + ); + } + } + + #[tokio::test] + async fn idle_file_deletion_is_handled_without_reopening() { + // A file that goes idle (handle closed) and is then deleted must be + // unwatched just like an actively-open file that gets deleted -- + // without ever needing to reopen it to notice the deletion. + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + idle_timeout_secs: Some(0), + ..test_default_file_config(&dir) + }; + + let path = dir.path().join("file"); + let counter = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&counter)), + async { + let mut file = File::create(&path).unwrap(); + writeln!(&mut file, "hello").unwrap(); + file.flush().unwrap(); + drop(file); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 1, 5_000).await; + + // Give it time to go idle (handle closed) before deleting. + sleep(Duration::from_millis(750)).await; + + std::fs::remove_file(&path).unwrap(); + + // Give the glob-rescan loop a chance to notice the deletion + // and unwatch the file; there's no new event to wait on + // here, so just sleep a bit past a few rescan cycles. + sleep(Duration::from_millis(750)).await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["hello"]); + } + + #[tokio::test] + async fn idle_file_rotation_reads_new_file_not_stale_offset() { + // A file that goes idle, then gets rotated (renamed away, replaced + // by a new file at the same path) must pick up the *new* file's + // content from the correct (fresh) position, not silently resume + // reading into the new file from the old file's stale offset. This + // relies on fingerprint-based identity in `FileServer` plus + // `FileWatcher::update_path`'s dev/inode re-verification on + // reactivation. + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + idle_timeout_secs: Some(0), + ..test_default_file_config(&dir) + }; + + let path = dir.path().join("file"); + let archive_path = dir.path().join("file.1"); + let counter = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&counter)), + async { + let mut file = File::create(&path).unwrap(); + writeln!(&mut file, "old file content").unwrap(); + file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 1, 5_000).await; + + // Let it go idle. + sleep(Duration::from_millis(750)).await; + + // Rotate: move the old file aside, create a new, + // content-different file at the same path. + fs::rename(&path, &archive_path).expect("could not rename"); + let mut new_file = File::create(&path).unwrap(); + writeln!(&mut new_file, "brand new file content").unwrap(); + new_file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 2, 5_000).await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["old file content", "brand new file content"]); + } + + #[tokio::test] + async fn idle_file_rotation_behind_narrow_glob_reads_new_file_not_stale_offset() { + // Same scenario as `idle_file_rotation_reads_new_file_not_stale_offset`, + // but with an `include` glob narrow enough that the archived file left + // behind by rotation does *not* match it (a common real-world setup, + // e.g. `*.log` with rotated files renamed to `*.log.1`). In that case + // the old watcher never gets an `update_path` call pointing it at the + // archive -- its fingerprint simply isn't found under any matched path + // during the glob rescan -- so it's marked unfindable and left exactly + // where it was: watching the *original path*, which now refers to a + // brand new file on disk. An `Idle` watcher holds no handle, so unlike + // an `Active` one it has no OS-level pin on the specific inode it was + // watching; if `FileServer`'s idle-poll pass doesn't also check + // findability before stat-ing and reactivating, it will observe the + // new file's size/mtime differing from what it last knew, reactivate + // by reopening the (new) file at the *old* checkpoint offset, and + // silently skip or corrupt the new file's content. + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*.log")], + idle_timeout_secs: Some(0), + ..test_default_file_config(&dir) + }; + + let path = dir.path().join("app.log"); + let archive_path = dir.path().join("app.log.1"); // does NOT match `*.log` + let counter = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&counter)), + async { + let mut file = File::create(&path).unwrap(); + writeln!(&mut file, "old file content").unwrap(); + file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 1, 5_000).await; + + // Let it go idle (handle closed). + sleep(Duration::from_millis(750)).await; + + // Rotate: move the old file to a path outside the `include` + // glob, then create a new, content-different file at the + // original path. + fs::rename(&path, &archive_path).expect("could not rename"); + let mut new_file = File::create(&path).unwrap(); + writeln!(&mut new_file, "brand new file content").unwrap(); + new_file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&counter), |c| c >= 2, 5_000).await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["old file content", "brand new file content"]); + } + #[derive(Clone, Copy, Eq, PartialEq)] enum AckingMode { NoAcks, // No acknowledgement handling and no finalization @@ -2629,4 +3049,222 @@ mod tests { .map(|log| log.get_message().unwrap().clone()) .collect() } + + /// Tests covering `file_discovery_mode: notify`, the OS-level filesystem-event-driven + /// discovery mode. These reuse `run_file_source`/`test_default_file_config` from above but + /// set a very long `glob_minimum_cooldown_ms`/`reconcile_interval_secs`, so that the + /// periodic backstop reconciliation pass cannot plausibly fire within the test's timeout. + /// If a test still observes prompt discovery/read behavior under those settings, that + /// behavior must be coming from the notify event path, not the polling fallback -- this is + /// what distinguishes these tests from the equivalent polling-mode tests above. + mod notify_discovery { + use super::*; + + fn test_notify_file_config(dir: &tempfile::TempDir) -> file::FileConfig { + file::FileConfig { + file_discovery_mode: FileDiscoveryModeConfig::Notify, + // Deliberately huge: if the backstop reconciliation pass were doing the work in + // these tests, they would time out (the tests use short, second-scale timeouts) + // well before this interval ever elapses. + reconcile_interval: Duration::from_secs(3600), + // Likewise huge and, in `Notify` mode, unused for discovery timing: set high to + // double-check no code path (including the notify-event debounce window, which + // is its own fixed, small constant -- NOTIFY_EVENT_DEBOUNCE -- specifically so it + // can't inherit an unrelated-in-intent large value like this one) is silently + // relying on it as a polling or debounce interval. + glob_minimum_cooldown_ms: Duration::from_secs(3600), + ..test_default_file_config(dir) + } + } + + /// (a) A new file appearing after startup is picked up promptly via a create event, not + /// a fixed polling interval that -- per `test_notify_file_config` -- is set to an hour. + #[tokio::test] + async fn new_file_discovered_promptly_via_event() { + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ..test_notify_file_config(&dir) + }; + + let path = dir.path().join("new_file"); + let event_count = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&event_count)), + async { + // The file doesn't exist yet at FileServer startup. + let mut file = File::create(&path).unwrap(); + writeln!(&mut file, "hello from a brand new file").unwrap(); + file.flush().unwrap(); + + // If this resolves, discovery + read happened well within the (hour-long) + // fallback reconcile interval, i.e. via the notify event path. + wait_for_atomic_usize_timeout_ms(Arc::clone(&event_count), |n| n >= 1, 5_000) + .await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["hello from a brand new file"]); + } + + /// (b) A write to an already-tracked file triggers a prompt read via a modify event. + #[tokio::test] + async fn write_to_existing_file_triggers_prompt_read() { + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ..test_notify_file_config(&dir) + }; + + let path = dir.path().join("existing_file"); + File::create(&path).unwrap(); + + let event_count = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&event_count)), + async { + // Give the file server a brief moment to complete startup and establish its + // watch before we write, but well under the reconcile interval. + sleep(Duration::from_millis(200)).await; + + let mut file = std::fs::OpenOptions::new() + .append(true) + .open(&path) + .unwrap(); + writeln!(&mut file, "a new line was written").unwrap(); + file.flush().unwrap(); + + wait_for_atomic_usize_timeout_ms(Arc::clone(&event_count), |n| n >= 1, 5_000) + .await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert_eq!(lines, vec!["a new line was written"]); + } + + /// (d) Rotation (rename) is still handled correctly under notify-based discovery: the + /// fingerprint (not the path) identifies the file being tailed, and post-rotation writes + /// to the recreated path are picked up as a new file. + #[tokio::test] + async fn rotation_handled_correctly() { + let n = 5; + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ..test_notify_file_config(&dir) + }; + + let path = dir.path().join("file"); + let archive_path = dir.path().join("file.old"); + let received = + run_file_source(&config, false, NoAcks, LogNamespace::Legacy, None, async { + let mut file = File::create(&path).unwrap(); + for i in 0..n { + writeln!(&mut file, "prerot {i}").unwrap(); + } + file.flush().unwrap(); + sleep(Duration::from_millis(500)).await; + + fs::rename(&path, &archive_path).expect("could not rename"); + file.sync_all().unwrap(); + + let mut file = File::create(&path).unwrap(); + file.sync_all().unwrap(); + sleep(Duration::from_millis(500)).await; + + for i in 0..n { + writeln!(&mut file, "postrot {i}").unwrap(); + } + file.flush().unwrap(); + sleep(Duration::from_millis(500)).await; + }) + .await; + + let mut i = 0; + let mut pre_rot = true; + for event in received { + let line = event.as_log()[log_schema().message_key().unwrap().to_string()] + .to_string_lossy(); + if pre_rot { + assert_eq!(line, format!("prerot {}", i)); + } else { + assert_eq!(line, format!("postrot {}", i)); + } + i += 1; + if i == n { + i = 0; + pre_rot = false; + } + } + } + + /// (c) No file handle is held for files that never receive any activity: unlike the + /// polling model (which re-fingerprints, and therefore re-opens, every matched file on + /// every cooldown tick), notify-driven discovery only opens files at startup (for the + /// initial scan) or in response to a create/modify event. A file that sits untouched + /// after being discovered is read to EOF once and then left alone -- the read loop does + /// not touch it again absent a new event, so no repeated open/fingerprint cost is paid. + /// + /// This test can't directly inspect the process's open file descriptor table in a + /// portable way, so instead it asserts on the behavior that open-handle-avoidance is + /// meant to buy us: a large number of untouched files do not prevent, or measurably + /// delay, prompt discovery and reading of one actively-written file. Under the old + /// polling design this same scenario would still work, but would pay an O(n) glob + + /// fingerprint cost on every single tick; here, with the reconcile interval set to an + /// hour, that cost structurally cannot be paid within the test, so a prompt result + /// demonstrates the write path isn't depending on scanning the inactive files at all. + #[tokio::test] + async fn inactive_files_do_not_block_prompt_discovery() { + let dir = tempdir().unwrap(); + let config = file::FileConfig { + include: vec![dir.path().join("*")], + ..test_notify_file_config(&dir) + }; + + // Create a bunch of files that will never be written to again. + for i in 0..200 { + let mut f = File::create(dir.path().join(format!("inactive_{i}"))).unwrap(); + writeln!(&mut f, "inactive content {i}").unwrap(); + f.flush().unwrap(); + } + + let active_path = dir.path().join("active_file"); + let event_count = Arc::new(AtomicUsize::new(0)); + let received = run_file_source( + &config, + false, + NoAcks, + LogNamespace::Legacy, + Some(Arc::clone(&event_count)), + async { + let mut file = File::create(&active_path).unwrap(); + writeln!(&mut file, "active line").unwrap(); + file.flush().unwrap(); + + // 200 pre-existing untouched files + 1 new active file. All 201 lines + // (200 inactive + 1 active) get read once during the startup scan / the + // active file's create event; we just need to see them all arrive promptly. + wait_for_atomic_usize_timeout_ms(Arc::clone(&event_count), |n| n >= 201, 5_000) + .await; + }, + ) + .await; + + let lines = extract_messages_string(received); + assert!(lines.contains(&"active line".to_string())); + assert_eq!(lines.len(), 201); + } + } } diff --git a/src/sources/kubernetes_logs/mod.rs b/src/sources/kubernetes_logs/mod.rs index 6b11fdf09d1bc..9ac953e65814a 100644 --- a/src/sources/kubernetes_logs/mod.rs +++ b/src/sources/kubernetes_logs/mod.rs @@ -27,7 +27,8 @@ use vector_lib::{ config::{LegacyKey, LogNamespace}, configurable::configurable_component, file_source::file_server::{ - FileServer, Line, Shutdown as FileServerShutdown, calculate_ignore_before, + FileDiscoveryMode, FileServer, Line, Shutdown as FileServerShutdown, + calculate_ignore_before, }, file_source_common::{ Checkpointer, FingerprintStrategy, Fingerprinter, ReadFrom, ReadFromConfig, @@ -898,6 +899,17 @@ impl Source { }, // A handle to the current tokio runtime rotate_wait, + // Kubernetes log discovery goes through the k8s API (this source's own + // `paths_provider`), not glob-watched directories, so there's no directory-level + // OS-level watch to establish; keep the original polling-based discovery cadence. + discovery_mode: FileDiscoveryMode::PollingOnly, + reconcile_interval: glob_minimum_cooldown, + // Kubernetes' log file set is bounded and kubelet-managed rather than open-ended + // like an arbitrary `include` glob, so the handle-count pressure this option exists + // to relieve (see file_server::FileServer::idle_timeout's docs, and + // https://github.com/vectordotdev/vector/issues/3567) doesn't apply here; preserve + // this source's existing always-open behavior. + idle_timeout: None, }; let (file_source_tx, file_source_rx) = futures::channel::mpsc::channel::>(2);