serve loops forever on Linux: its own stale checks overflow the watcher queue (IN_OPEN events are enqueued unfiltered) #151

Summary

On Linux, tgrep serve with the default --watcher-queue-cap (16,384) never settles on a tree with a few thousand watched directories. The startup stale check overflows the watcher queue, the overflow recovery runs another stale check, that walk overflows the queue again, and so on — one cycle every ~1.6 s, indefinitely. The server keeps answering queries, but burns ~150 % CPU and its RSS grows from 73 MB to 263 MB within minutes.

Root cause: notify's inotify backend subscribes with a mask that includes IN_OPEN, serve enqueues every event into the bounded channel before filtering by kind, and tgrep's own tree walks (stale check, recursive watch registration, "rechecked N newly watched directories") open every directory — each open yields an Access(Open) event on the directory's own watch and on its parent's. One walk of the tree therefore produces far more events than the queue holds.

Environment

• tgrep 1.0.5, prebuilt x86_64-unknown-linux-musl installed with scripts/install.sh (SHA-256 verified). Source references below are against 50f5d8f6a54e9e4d16d021954cfcd4e77d342d7b (fix: print search stats after matches (#146), 2026-09-08).
• Linux 7.2.2-arch1-1 x86_64 (Arch Linux), ext4 home filesystem.
• fs.inotify.max_queued_events = 16384, fs.inotify.max_user_watches = 524288.
• notify 7.0.0, inotify 0.10.2 (from Cargo.lock).
• Tree: ~/Escritorio/PROYECTOS — 28,184 directories total; after --exclude node_modules --exclude .venv --exclude venv --exclude __pycache__ and 54 nested .gitignore files (--no-require-git, the root is not a git repo) the index holds 25,247 text files and the watcher subscribes 5,682 directories. 48 GB RAM, nothing else touching the tree.

Steps to reproduce

tgrep index ~/Escritorio/PROYECTOS --no-require-git \
  --exclude node_modules --exclude .venv --exclude venv --exclude __pycache__
# Index built successfully — 25,247 files, 591,065 trigrams, 5.5 s, peak 147 MiB

tgrep serve ~/Escritorio/PROYECTOS --no-require-git \
  --exclude node_modules --exclude .venv --exclude venv --exclude __pycache__ --max-cpu 50
# (run under a systemd user unit; stderr goes to the journal)

Then watch stderr and CPU for a couple of minutes. Any tree with a few thousand directories should do; the trigger is the number of watched directories, not the file contents.

Actual behaviour

stderr, ~4 minutes after start (timestamps from journalctl -o short-precise):

[trace] stale check: comparing index against filesystem...
[trace] gitignore matcher built from stale walk in 11.8ms (54 .gitignore + 0 .ignore files)
[trace] stale check: index is up-to-date (25341 files checked in 179ms)
[trace] watcher queue overflowed (cap 16384); reconciling with a stale check
[trace] stale check: comparing index against filesystem...
[trace] gitignore matcher built from stale walk in 14.4ms (54 .gitignore + 0 .ignore files)
[trace] stale check: index is up-to-date (25341 files checked in 184ms)
[trace] watcher queue overflowed (cap 16384); reconciling with a stale check
...

Overflow lines, consecutive:

Sep 09 10:21:10.004801  watcher queue overflowed (cap 16384); reconciling with a stale check
Sep 09 10:21:11.591615  watcher queue overflowed (cap 16384); reconciling with a stale check
Sep 09 10:21:13.168248  watcher queue overflowed (cap 16384); reconciling with a stale check
Sep 09 10:21:14.744069  watcher queue overflowed (cap 16384); reconciling with a stale check
Sep 09 10:21:16.323631  watcher queue overflowed (cap 16384); reconciling with a stale check

• 62 overflow lines in the first ~4 minutes, period ≈ 1.58 s, no external filesystem activity (find -newermt '-3 minutes' outside .tgrep/ returned nothing).
• ps: 147–151 % CPU sustained; RSS 73 MB → 263 MB in ~100 s.
• Per-process CPU sampled over 3 s: 477 ticks (≈ 1.6 cores).
• tgrep status alternates Reconcile: running / idle, Last reconcile duration: 547–552ms, Watcher: active, Watch mode: native (requested: auto), Indexing: complete. Queries keep working.

Expected behaviour

After the initial stale check the watcher should go idle. A stale check triggered by an overflow must not itself cause the next overflow.

Root-cause analysis

1. The inotify mask includes IN_OPEN. /proc/<pid>/fdinfo/<inotify fd> shows every watch registered with mask:fee = IN_MODIFY | IN_ATTRIB | IN_CLOSE_WRITE | IN_OPEN | IN_MOVED_FROM | IN_MOVED_TO | IN_CREATE | IN_DELETE | IN_DELETE_SELF | IN_MOVE_SELF. That is notify 7's default; IN_OPEN (0x20) surfaces as EventKind::Access(AccessKind::Open).

2. Every event is enqueued before any kind filtering. In start_file_watcher_using (tgrep-cli/src/serve.rs, ~L2492–2516) the notify callback does tx.try_send(event) on a sync_channel::<Event>(queue_cap) for every Ok(event). The consumer only acts on Create/Modify/Remove, so Access events are pure queue pressure that still counts against WATCHER_QUEUE_CAP (const WATCHER_QUEUE_CAP: usize = 16_384;, L74).

3. tgrep's own maintenance walks the watched tree and opens every directory. The stale check (read_dir per directory), notify's recursive watch registration (inotify has no recursive mode, so the tree is walked to add per-directory watches) and the post-registration pass logged as watcher: rechecked N newly watched directories (L3701) all open every directory. On inotify, opening a watched directory delivers IN_OPEN|IN_ISDIR on that directory's own watch and on its parent's watch; every file the walk opens adds another event on its parent's watch.

4. Measured volume. I placed an independent inotify instance (IN_OPEN only) on 1,632 of the 5,682 directories tgrep was watching (resolved from the inode numbers in /proc/<pid>/fdinfo) and restarted tgrep serve. In the 15 s after the restart that subset alone produced 201,825 IN_OPEN events — 192,067 directory opens and 9,758 file opens — versus a baseline of 133 events in the 3 s before. That is ≈12× the default queue cap on less than a third of the watched set. (Probe script in the appendix.)

5. The recovery path closes the loop. On TrySendError::Full the callback sets overflowed; recover_watcher_overflow (L2386–2406) logs the overflow and calls background_refresh_stale, whose walk generates the next flood, which sets overflowed again. Nothing in the cycle drains or discards the events the walk itself produced, so the loop is self-sustaining. The 1.58 s period is one stale walk (≈186 ms) plus delta application (≈0.5 s) plus queue processing.

Related work (does not cover this case)

• Process watcher events off-thread to avoid dropping them during flushes #89 introduced the bounded mpsc channel between the notify callback and the worker. It fixed events being dropped during flushes; the overflow reported here happens with the worker idle, because the producer is tgrep's own walk.
• Coalesce duplicate file watcher events #130 coalesces events into 25 ms bursts, but that runs on the consumer side, after try_send. The queue overflows before coalescing gets a chance, so it does not help here.
• Fall back to polling when native watch capacity is exhausted #142 falls back to polling when native watch registration exceeds the 8,192-subscription budget. This tree fits the budget (5,682 directories), registration succeeds, and the failure is queue pressure, not capacity — so the fallback never triggers.

Workarounds that I verified

• --watcher-queue-cap 131072 (8× default): the startup still overflows once on some starts (observed 0 and 1 overflow on two starts) but the loop breaks — afterwards 0 CPU ticks over 3 s at rest, RSS 53–57 MB, new files visible to queries within ~2 s. Cost is the larger preallocated channel (~6 MB).
• --watch-mode poll --poll-interval N: immune, at the cost of freshness ≤ N s.

Neither is discoverable from the symptom: the README suggests raising --watcher-queue-cap for "bulk changes (branch switches, builds)", but here there are no external changes at all.

Suggested fix

1. Filter before enqueueing. In the notify callback, return early for kinds the worker never uses, so the bounded queue only holds events that can change the index:

   Ok(event) => {
       if matches!(event.kind, EventKind::Access(_) | EventKind::Other) {
           return;
       }
       match tx.try_send(event) { /* unchanged */ }
   }

   This alone removes the self-triggering: a directory walk then produces no queued events on Linux (IN_OPEN and IN_CLOSE_NOWRITE-style events are the only ones a read-only walk generates).

2. Make overflow recovery idempotent. After an overflow-triggered stale check finishes, drain the channel and clear overflowed before re-arming, so events produced by the check itself cannot schedule the next one. Alternatively, ignore watcher events for paths tgrep is itself walking while a stale check is in flight.

3. Optionally, if notify ever exposes the mask, drop IN_OPEN at the source; with notify 7.0.0 that is not possible from the public API, which is why (1) filters by kind instead.

Happy to test a patched build on this tree — the loop reproduces within seconds of startup.

Appendix A — probe used for the measurement in §4

Python 3, no dependencies (ctypes → libc). Registers IN_OPEN-only watches on the directories tgrep itself watches, restarts the service, and counts events for 15 s.

import os, re, ctypes, struct, threading, time, subprocess
libc = ctypes.CDLL("libc.so.6", use_errno=True)
IN_OPEN=0x20; IN_ISDIR=0x40000000; IN_Q_OVERFLOW=0x4000; IN_NONBLOCK=0o4000; IN_CLOEXEC=0o2000000
ROOT="/home/desabada/Escritorio/PROYECTOS"
pid=int(subprocess.check_output(["systemctl","--user","show","-p","MainPID","--value","tgrep-proyectos"]).strip())
watched=set()
for fdn in os.listdir(f"/proc/{pid}/fdinfo"):
    try: txt=open(f"/proc/{pid}/fdinfo/{fdn}").read()
    except OSError: continue
    for m in re.finditer(r"inotify wd:(\d+) ino:([0-9a-f]+) sdev:([0-9a-f]+) mask:([0-9a-f]+)", txt):
        watched.add(int(m.group(2),16))
ino2path={}
for dp,_,_ in os.walk(ROOT):
    try: ino2path[os.stat(dp).st_ino]=dp
    except OSError: pass
paths=[ino2path[i] for i in watched if i in ino2path]
fd=libc.inotify_init1(IN_NONBLOCK|IN_CLOEXEC)
for p in paths: libc.inotify_add_watch(fd, p.encode(), IN_OPEN)
c={"open_dir":0,"open_file":0,"qoverflow":0}; stop=False
def reader():
    while not stop:
        try: data=os.read(fd,1<<20)
        except BlockingIOError: time.sleep(0.002); continue
        off=0
        while off<len(data):
            wd,mask,cookie,ln=struct.unpack_from("iIII",data,off); off+=16+ln
            if mask & IN_Q_OVERFLOW: c["qoverflow"]+=1
            elif mask & IN_OPEN: c["open_dir" if mask & IN_ISDIR else "open_file"]+=1
t=threading.Thread(target=reader,daemon=True); t.start()
time.sleep(3); base=dict(c)
subprocess.run(["systemctl","--user","restart","tgrep-proyectos"],check=True)
time.sleep(15); stop=True; t.join(1)
print(len(paths), "watched dirs probed;", {k:c[k]-base[k] for k in c})

Output on this machine: 1632 watched dirs probed; {'open_dir': 192067, 'open_file': 9758, 'qoverflow': 0}.

Appendix B — tgrep status during the loop

Server status for /home/desabada/Escritorio/PROYECTOS
  PID:        76296
  Port:       45841
  Files:      25247
  Trigrams:   591067
  Cache:      0/50000
  Watcher:    active
  Watch mode: native (requested: auto)
  Watch budget: 8192
  Poll interval: 120s (after completion)
  Reconcile:  running
  Last successful reconcile: 1s ago
  Reconcile pending: no
  Reconcile overdue: no
  Last reconcile duration: 552ms
  Indexing:   complete