diff --git a/specs/milestone-6.md b/specs/milestone-6.md new file mode 100644 index 0000000..f947379 --- /dev/null +++ b/specs/milestone-6.md @@ -0,0 +1,730 @@ +# Milestone 6: Cache, Rate Limiter, Query Logger, Retention, Disk Monitor, Log Sink + +PLAN Phase 6. Build every runtime component between the resolver core and the web layer: the TTL +cache (§8), the per-client DNS rate limiter (§10), the async query logger with backpressure +(§11.4), retention (§11.5), the disk monitor and the rotating log sink with upstream-error dedup +(§11.6). Nothing is wired into the query path — composition is Phase 7. Every component is built +complete, tested standalone, and exposed through accessors Phase 7 and Phase 8 will consume. + +## Sessions + +Eight sessions. Wave 1 starts five in parallel: S1 (cache), S2 (rate limiter), S3 (queries repo), +S5 (statfs + disk monitor), S6 (log sink). Wave 2 starts when S3 verifies: S4 (logger) and S7 +(retention) in parallel — both consume S3's repo and nothing of each other. S8 (integration) runs +last. The orchestrator — not any session — wires `src/tests.zig` and installs the log sink's +`std_options` hook in `src/main.zig`. (`validate.zig:221` already rejects +`rate_window_seconds` outside 1–`max_rate_window_seconds`; no rule is missing.) + +Every later session is written against **this spec**, not against another session's source. Where +this spec and a built file disagree after a session verifies, the built file wins and the +orchestrator records the difference in "## As built". + +## Design invariants + +- **Pure core.** `src/cache/dns_cache.zig` and `src/server/rate_limiter.zig` take timestamps as + parameters and hold no `std.Io`, no clock, no socket. `std.Io` appears only in + `src/storage/logger.zig`, `src/storage/disk_monitor.zig`, `src/storage/retention.zig`, + `src/platform/logging.zig`, `src/platform/statfs.zig` (its test), and the S8 test file. +- **Neither the cache nor the limiter is thread-safe.** Phase 7 decides the locking when it wires + them. Both files state that in their module doc comment. +- **No allocation on the hit path.** `DnsCache.get` and `RateLimiter.check` allocate nothing. + `DnsCache.put` allocates exactly one buffer for the stored response bytes. +- **Every failure mode is counted.** Dropped log entries, refused queries, evictions, expired + entries, deduplicated log lines, failed disk samples — a counter each, readable by Phase 8. +- **No `std.log.err` in any file this milestone writes.** A condition returned as a typed error + logs at `warn` at most. `err` stays reserved for swallowed failures, and this milestone swallows + none. +- **Timestamps follow the house style** (health.zig): `std.Io.Timestamp` parameters, arithmetic on + `.nanoseconds`, wall seconds for DB rows via `Clock.real.now(io).toSeconds()`, monotonic + decisions on `.awake`, long schedules on `.boot`. +- **Background loops follow `manager.runScheduler`'s shape**: `Cancelable!void`, non-cancel + failures log at `warn` and the loop continues, cancellation returns. Phase 7 starts them. + +## Resolved PLAN ambiguities (rulings for this milestone) + +1. **Client-row pruning is Phase 7.** §7.2's "retention drops `hand_edited=0` clients" deletes + from `config.db`, which §3.6 walls off from retention churn. The rows it prunes are created by + auto-materialization, which is Phase 7; the pruning ships with it. §11.5 retention here touches + `querylog.db` only. +2. **Free space drives the thresholds; sizes are gauges.** The monitor samples `statvfs` free + bytes for the warn/critical decision and records DB and log-directory sizes as gauges for + Phase 8's health payload. Both are sampled in the same pass. +3. **Flush tuning is comptime.** `flush_batch = 100`, `flush_interval_ms = 100` as public + constants in `logger.zig`. §12.1 defines no config keys for them and a household deployment + never tunes them. +4. **The SSE seam is the transformed entry.** Privacy transforms run at enqueue, so every entry in + the queue is already presentable. Phase 8 subscribes by wrapping `Logger.log` — no hook, no + callback, no dead vtable. +5. **The positive-TTL sanity ceiling is 86 400 seconds**, the same `max_ttl_seconds` constant + `validate.zig:196` already enforces on `blocking.ttl` and `cache.negative_ttl_max`. Comptime + constant in `dns_cache.zig` with a comment naming that origin. No new config key. +6. **`negative_ttl_max = 0` disables negative caching** (the response is not stored), not the cap. + `validate.zig` already caps the field at `max_ttl_seconds`, so "no cap" would be expressible as + 86 400 anyway; "0 disables" only has meaning as an off switch. +7. **`cache.size` counts entries**, not bytes. 10 000 entries at the observed household response + sizes is single-digit megabytes; a byte budget would add config surface for nothing. +8. **The DNS limiter is a fixed window.** §10 reserves the token bucket for the API (Phase 8); + "1000 per 60 s" plus "stale-key windowed sweep" describes a counter that resets each window. + A fixed window admits at most 2× the limit across a window boundary, which is acceptable for + abuse protection at household scale and costs half the state of a sliding window. +9. **Upstream-error dedup lives in the log sink.** It is a property of how lines reach the + operator, not of the upstream module: `platform/logging.zig` deduplicates warn-and-above lines + from the upstream scopes at one per key per minute. No milestone-3 file is edited. +10. **Schedules: retention daily, checkpoint after every prune, VACUUM every 7th pass.** §11.5 + names no interval. Daily matches the granularity of `retention_days`; `wal_checkpoint + (TRUNCATE)` after each prune keeps the WAL from monopolizing the disk the monitor watches; a + nightly full VACUUM would rewrite the whole file on an SD card every day, so VACUUM runs on + every 7th retention pass. + +## Verified 0.16.0 stdlib facts (see specs/research/zig-0.16-api-notes.md, "Phase 6 verifications") + +- `std.Io.Queue(Elem)` (Io.zig:2184): bounded ring over a caller array. `put(q, io, elems, 0)` + never blocks and returns 0 when full (Io.zig:2218); `getOne` blocks; `close(io)` unblocks it + with `error.Closed`. Elements are copied raw (Io.zig:2189) — **queue elements must be + self-contained values**, no slices into caller memory. +- `std.Io.Condition` has **no `timedWait`**. The timed primitive is `Event.waitTimeout` + (Io.zig:1827). The logger's flush interval uses `Select` racing `getOne` against a + `Clock.Duration` sleep, the `fetchWithin` pattern from manager.zig:722. +- **No statvfs in std.** `src/platform/statfs.zig` declares `extern fn statvfs` against libc + (every build already links libc for sqlite; glibc and musl share the 64-bit POSIX layout). + Free bytes = `f_bavail * f_frsize`. +- **No append mode.** Log sink append: `openFile(io, path, .{ .mode = .write_only })`, + `file.writer(io, &buf)`, `w.seekTo(try file.length(io))`. `Dir.rename` + `Dir.deleteFile` + rotate. One owner per writer — the sink serializes behind its own mutex. +- **No fixed-capacity hash map in std.** Bounded structures use a fixed slot array plus + `std.HashMapUnmanaged` from key to slot index with `ensureTotalCapacity` at init; the CLOCK + hand walks the slot array, never the map. Map modification invalidates live iterators + (hash_map.zig:496). +- `packet.decrementTtls(bytes, elapsed_seconds) ParseError!?u32` (packet.zig:234) ages every + record in place, skips OPT, validates before writing, returns the smallest resulting TTL; on + error the buffer is partly aged and must be discarded. With `elapsed = 0` it is a pure + validate-and-min-TTL pass. `packet.setId` (packet.zig:202) rewrites the transaction ID. +- `db.zig`: `Stmt.reset` clears bindings — rebind everything each iteration. `Db`/`Stmt` are not + thread-safe; the logger's writer task owns its `Db` handle exclusively. A batch is one + `Tx.begin` + reset/rebind/step loop + `commit`. +- `address.NetAddress.Key` is `[17]u8` covering both families; `fromIp` folds IPv4-mapped IPv6 to + `.ip4`, so one client is one key. + +--- + +## Session S1: DNS cache — `src/cache/dns_cache.zig` + +New directory `src/cache/`. Imports: `std`, `../dns/packet.zig`, `../dns/types.zig`, +`../dns/record.zig`, `../config/model.zig`. No `std.Io`. + +### S1.1 Key + +```zig +/// qname (lowercased ASCII, no trailing dot) ++ 0x00 ++ qtype BE ++ qclass BE ++ do byte +/// ++ ecs_len byte ++ ecs bytes. ECS participates only when the caller passes it (Phase 7 +/// passes the forwarded subnet only under ecs_mode=forward, PLAN §8). +pub const max_key_len = 255 + 1 + 2 + 2 + 1 + 1 + 40; +pub fn buildKey(buf: *[max_key_len]u8, qname: []const u8, qtype: u16, qclass: u16, + do_bit: bool, ecs: ?[]const u8) []const u8; +``` + +`buildKey` lowercases `A`–`Z` while copying and strips one trailing dot. Asserts `qname.len <= +255` and `ecs.?.len <= 40` — the caller has already validated both through the packet parser. + +### S1.2 Classification + +```zig +pub const Class = struct { ttl_seconds: u32, negative: bool }; +/// Decides whether a response is cacheable and for how long. Null means do not cache. +pub fn classify(response: []const u8, negative_ttl_max: u32) ?Class; +``` + +Rules, in order: parse the header — rcode NOERROR with at least one answer record is positive; +rcode NXDOMAIN, or NOERROR with zero answers, is negative; every other rcode returns null. +Positive: `ttl = min(packet.decrementTtls(copy, 0) result, max_ttl)` — since `decrementTtls` +mutates, `classify` runs it on a stack copy (`[65535]u8` is too big for the stack; instead compute +the min TTL by iterating records via the parser without mutation — `record` module iteration, skip +OPT). A parse error returns null. Negative: min(SOA record TTL, SOA MINIMUM) from the authority section per RFC 2308 §5, capped by +`negative_ttl_max`; no SOA → null; `negative_ttl_max == 0` → null (ruling 6). A TTL of 0 → null. +A TTL with the top bit set is read as zero per RFC 2181 §8 (packet.zig:220 leaves that to the +caller), on both paths — such a response is not cached. + +### S1.3 Storage and API + +```zig +pub const Config = struct { size: u32, negative_ttl_max: u32 }; +pub const Stats = struct { hits, misses, inserts, evictions, expirations, invalid_hits: u64 = 0 }; +pub const DnsCache = struct { + pub fn init(gpa: Allocator, config: Config) Allocator.Error!DnsCache; // allocates slots + index once + pub fn deinit(self: *DnsCache) void; + /// Stores a clone of `response`. A key already present is replaced in place. + pub fn put(self: *, now_s: i64, key: []const u8, response: []const u8, class: Class) Allocator.Error!void; + /// Copies the entry into `out`, rewrites nothing but the TTLs (caller does setId), + /// returns null on miss/expiry. `out.len >= response len` is the caller's problem; + /// a too-small `out` is a miss counted under `misses`. + pub fn get(self: *, now_s: i64, key: []const u8, out: []u8) ?[]u8; + /// Removes expired entries; returns how many. Phase 7 schedules it. + pub fn sweep(self: *, now_s: i64) u32; + pub fn len(self: *const) u32; + pub fn memoryBytes(self: *const) usize; + stats: Stats, +}; +``` + +Slot: inline key `[max_key_len]u8` + `key_len` (no allocation), `bytes: []u8` (gpa-owned clone), +`stored_at_s: i64`, `expires_at_s: i64`, `negative: bool`, `referenced: bool`, `occupied: bool`. +Index: `HashMapUnmanaged` keyed by the slot's key slice (context hashes the slice) to `u32` slot +index, `ensureTotalCapacity(config.size)` at init — no rehash ever. CLOCK: on `get` hit set +`referenced`; when `put` finds no free slot, advance the hand clearing `referenced` until an +unreferenced slot, evict it (`evictions += 1`). Expired-on-access is freed and counted under +`expirations`, then treated as a miss/free slot. + +`get` computes `elapsed = now_s - stored_at_s`, copies, then `packet.decrementTtls(copy, +elapsed)`. An error from it removes the entry, counts `invalid_hits`, returns null — a poisoned +entry never serves twice. + +### S1.4 Tests (in-file, ≥ 14) + +buildKey lowercases and strips the dot; distinct qtype/qclass/DO/ECS produce distinct keys; ECS +absent vs present differ; classify: positive min-TTL over multiple answers; ceiling applied; NXDOMAIN +uses SOA minimum; capped by negative_ttl_max; `negative_ttl_max = 0` returns null; SERVFAIL null; +zero TTL null; put/get round-trip with TTL decrement asserted via re-parse; expiry is a miss and +counted; CLOCK evicts the unreferenced entry, not the referenced one; replace-in-place does not +grow `len`; sweep removes only expired; `checkAllAllocationFailures` on init+put. + +### S1.5 Acceptance + +- [ ] `zig fmt --check` + `zig ast-check` clean; in-file tests pass standalone via a src/-level + temp root. +- [ ] `grep -n "std.Io" src/cache/dns_cache.zig` hits doc comments at most. +- [ ] `get` performs zero allocations (no allocator parameter exists on it). + +--- + +## Session S2: rate limiter — `src/server/rate_limiter.zig` + +Imports: `std`, `../platform/address.zig`. No `std.Io`. + +```zig +pub const Config = struct { limit: u32, window_seconds: u32 }; +pub const Stats = struct { allowed, refused, untracked: u64 = 0 }; +pub const RateLimiter = struct { + pub fn init(gpa: Allocator, config: Config) Allocator.Error!RateLimiter; // capacity fixed at init + pub fn deinit(self: *) void; + /// True = process the query; false = answer REFUSED. Never errors, never allocates. + pub fn check(self: *, now: std.Io.Timestamp, key: address.NetAddress.Key) bool; + /// Drops entries whose window ended before the previous full window. Phase 7 schedules it. + pub fn sweep(self: *, now: std.Io.Timestamp) u32; + stats: Stats, +}; +pub const max_clients = 4096; +``` + +Fixed window per key: entry `{window_start_ns: i96, count: u32}` in a `HashMapUnmanaged` with +capacity `max_clients` ensured at init. `check`: if the entry's window has ended, reset it to the +current window. `count >= limit` → refused. Map full and key unknown: allow, count `untracked` — +refusing unseen clients because the table is full would let 4096 attackers deny every new device, +and a household LAN never has 4096 honest clients; the counter makes the state visible. `sweep` +walks and removes stale entries (collect keys first — map modification invalidates iterators). + +`std.Io.Timestamp` is a plain value type (`{nanoseconds: i96}`) — using it keeps this file pure; +callers pass `.awake` timestamps. + +Tests (≥ 8): allows up to limit, refuses limit+1; new window resets; v4 and v6 keys independent; +v4-mapped v6 shares the v4 bucket (via `address.fromIp` in the test); sweep removes only stale; +map-full behavior allows and counts; stats add up; window arithmetic at i96 scale (a timestamp far +from zero). + +Acceptance: fmt/ast-check clean; no allocation in `check` (signature proves it); in-file tests +pass standalone. + +--- + +## Session S3: queries repo — `src/storage/repositories/queries_repo.zig` + +Imports: `std`, `../db.zig`. Pure DB code, no `std.Io`. Follows the milestone-4 repository idiom +(free functions over `*db.Db` — read `groups_repo.zig` first), plus one long-lived-statement +struct the flush loop owns (`db.zig:360` names this file as the reason no statement cache exists). + +```zig +pub const Row = struct { + timestamp: i64, + domain: []const u8, // already privacy-transformed by the logger + client_ip: []const u8, // ditto + qtype: ?u16, + blocked: bool, + block_reason: ?[]const u8, + response_time_us: ?i64, + cache_hit: ?bool, + upstream: ?[]const u8, +}; + +/// Owns the prepared statements of the flush loop. Init once, reuse per batch. +pub const BatchWriter = struct { + pub fn init(database: *db.Db) db.Error!BatchWriter; + pub fn deinit(self: *) void; + /// One transaction. Domains are interned via INSERT OR IGNORE + SELECT id. + pub fn writeBatch(self: *, rows: []const Row) db.Error!void; +}; + +pub fn pruneOlderThan(database: *db.Db, cutoff_ts: i64) db.Error!i64; // rows deleted +pub fn checkpointTruncate(database: *db.Db) db.Error!void; // PRAGMA wal_checkpoint(TRUNCATE) +pub fn vacuum(database: *db.Db) db.Error!void; +pub fn countRows(database: *db.Db) db.Error!i64; +pub fn countDomains(database: *db.Db) db.Error!i64; +``` + +`writeBatch` on an empty slice returns without opening a transaction. `pruneOlderThan` deletes +`query_log` rows only — orphaned `domains` rows stay (they are a dimension table; re-interning is +cheaper than referential garbage collection, and §11.3 sets no requirement). Statements: three in +`BatchWriter` (insert-or-ignore domain, select domain id, insert row), reset+rebind per use. + +Tests (≥ 8, all against `:memory:` + `querylog_schema.ddl`): batch inserts rows and interns +domains once; second batch reuses the domain id; nullable columns round-trip null and value; +empty batch writes nothing; prune deletes strictly-older rows only; prune returns the count; +checkpoint and vacuum execute without error on a file DB (use `:memory:` where legal, a tmp file +where WAL is needed — vacuum works on both); countRows/countDomains agree with inserts. + +Acceptance: fmt/ast-check clean; tests pass standalone via src/-level temp root with `-lc +-lsqlite3`. + +--- + +## Session S4: async query logger — `src/storage/logger.zig` (needs S3) + +Imports: `std`, `db.zig`, `repositories/queries_repo.zig`, `../config/model.zig`, +`disk_monitor.zig` (S5's file — wave 2 starts after wave 1 verifies, so it exists). + +### S4.1 Entry — self-contained (Queue copies raw bytes) + +```zig +pub const Entry = struct { + timestamp: i64, + domain_buf: [253]u8, domain_len: u8, + client_buf: [45]u8, client_len: u8, // RFC 5952 text, fits any v6 + qtype: ?u16, + blocked: bool, + reason_buf: [32]u8, reason_len: u8, // "" = null in the DB + response_time_us: ?i64, + cache_hit: ?bool, + upstream_buf: [64]u8, upstream_len: u8, // "" = null + pub fn domain(self: *const) []const u8; // + client/reason/upstream accessors +}; +``` + +### S4.2 Logger + +```zig +pub const flush_batch = 100; +pub const flush_interval_ms = 100; +pub const hidden_marker = "hidden"; + +pub const Logger = struct { + /// `queue_buf.len` is the backpressure cap: pass cfg.query_log_buffer_max entries. + pub fn init(cfg: model.Logging, queue_buf: []Entry) Logger; + /// Applies the privacy transforms, then enqueues without blocking. A full queue drops + /// the OLDEST unflushed entry (PLAN §11.4) and increments `queries_dropped`. + pub fn log(self: *, io: std.Io, entry: Entry) void; + /// The writer task. Owns `database` for its whole life. Runs until `shutdown`. + pub fn runWriter(self: *, io: std.Io, database: *db.Db, monitor: ?*disk_monitor.Monitor) + std.Io.Cancelable!void; + /// Closes the queue; runWriter drains what remains, flushes, and returns. + pub fn shutdown(self: *, io: std.Io) void; + queries_dropped: std.atomic.Value(u64), + rows_written: std.atomic.Value(u64), + batches_gated: std.atomic.Value(u64), +}; +``` + +- Privacy (§11.4): `hide_domains` replaces the domain with `hidden_marker`; `hide_client_ips` + likewise. Applied inside `log`, so the queue never holds the real value — the transform runs + before persistence and before any future SSE fanout by construction (ruling 4). +- Drop-oldest: `put(io, &.{entry}, 0)`; on 0, `get` one entry nonblocking (min 0), count it + dropped, retry the put — until the put succeeds, one drop counted per failed attempt. A fixed + attempt cap is wrong under contention (one call would pay for two old entries plus its own). + The only early exit is a zero-capacity queue, which has nothing to drop. +- `runWriter` loop: `getOne` (blocking; `error.Closed` → final drain + flush + return). Then + accumulate up to `flush_batch` entries: nonblocking `get` first; while short of the batch and + the interval clock (started at the first entry, `.awake`) has time left, race `getOne` against + the remaining interval via `Select` (manager's `fetchWithin` shape). Flush: if + `monitor != null and !monitor.?.writesAllowed()`, do not write — hold the batch, sleep 1 s + (`.awake`), re-check; count each held cycle under `batches_gated`. §11.6: log flushes stop at + critical, the queue keeps dropping oldest behind them. On `writeBatch` error: log at `warn`, + drop the batch (it is expendable log data; blocking would fill the queue), continue. +- Entries convert to `queries_repo.Row` at flush (slices point into the batch array — safe, the + batch lives across the call). + +Tests (≥ 8): transforms applied at enqueue (inspect the queue copy); drop-oldest drops the oldest +and counts; entry accessors round-trip; batch conversion maps "" to null; a `runWriter` +smoke over `:memory:` — enqueue N, shutdown, all N in the DB (single-threaded: run the writer via +`io.concurrent` in the test with a Threaded instance — this is the one in-file test that touches +`std.Io`; keep it gated under a plain `test` since it needs no network); gating holds rows back +and releases them (fake monitor state flip); writeBatch failure drops and continues (close the DB +under the writer? if unreachable in-file, mark for S8). + +Acceptance: fmt/ast-check clean; `grep -c "std.log.err" src/storage/logger.zig` = 0. + +--- + +## Session S5: statfs + disk monitor — `src/platform/statfs.zig`, `src/storage/disk_monitor.zig` + +### S5.1 `src/platform/statfs.zig` + +```zig +pub const StatVfs = extern struct { + f_bsize: c_ulong, f_frsize: c_ulong, + f_blocks: u64, f_bfree: u64, f_bavail: u64, + f_files: u64, f_ffree: u64, f_favail: u64, + f_fsid: c_ulong, f_flag: c_ulong, f_namemax: c_ulong, + __reserved: [6]c_int, +}; +extern fn statvfs(path: [*:0]const u8, buf: *StatVfs) c_int; +pub fn freeBytes(path: [:0]const u8) error{StatFailed}!u64; // f_bavail * f_frsize +``` + +The 64-bit glibc and musl `struct statvfs` layouts agree field-for-field; both build targets are +64-bit. One test: `freeBytes(".")` returns a nonzero value (gated `-Dintegration`? no — it is +hermetic and deterministic-enough: assert `> 0`; a full disk failing CI is a real signal). + +### S5.2 `src/storage/disk_monitor.zig` + +```zig +pub const State = enum(u8) { ok, warn, critical }; +pub const Gauges = struct { free_bytes, db_bytes, log_bytes: u64 }; +pub fn classify(free_bytes: u64, cfg: model.Disk) State; // pure; < min → critical, < warn → warn + +pub const Monitor = struct { + pub fn init(cfg: model.Disk, data_dir: std.Io.Dir, data_path: [:0]const u8, + log_dir_path: ?[:0]const u8) Monitor; + /// One sample: statvfs on data_path, sizes of *.db/-wal/-shm under data_dir and of the + /// log dir. Stores state + gauges atomically. Failures count `sample_failures`, keep the + /// previous state, and log at warn (deduped by the sink). + pub fn sample(self: *, io: std.Io) void; + pub fn state(self: *const) State; // atomic load + pub fn writesAllowed(self: *const) bool; // state != .critical + pub fn gauges(self: *const) Gauges; // atomics, individually consistent + /// Loop: sample, sleep 60 s (.boot), repeat. Phase 7 starts it. + pub fn run(self: *, io: std.Io) std.Io.Cancelable!void; + sample_failures: std.atomic.Value(u64), +}; +pub const sample_interval_s = 60; +``` + +State is `std.atomic.Value(u8)`; a reader never sees a torn value. On the ok↔warn↔critical edges +log one line at `warn` (state changes only, not every sample). The blocklist-update gate (§11.6 +"stop non-essential writes") is consumed by the logger now and by the manager in Phase 7 — no +milestone-5 file is edited here. + +Tests: `classify` boundary cases (exactly min, exactly warn, between, above); state-change +logging is observable via state transitions (assert states, not logs); init leaves `.ok` with +zero gauges; gauge arithmetic (a fixture dir with files of known sizes, using `std.Io.Dir` in a +plain test with a Threaded instance). + +Acceptance: fmt/ast-check clean on both files; `classify` covered exhaustively. + +--- + +## Session S6: log sink — `src/platform/logging.zig` + +The custom `std.log` sink: level filter, stderr or rotating file output, upstream-error dedup +(§11.6). Imports: `std`, `../config/model.zig`. + +```zig +/// Matches std.Options.logFn. Before install(), passes through to stderr formatting. +pub fn logFn(comptime level: std.log.Level, comptime scope: @Type(.enum_literal), + comptime format: []const u8, args: anytype) void; +/// Called once from main() after config parse. Not called by tests. +pub fn install(io: std.Io, cfg: model.Logging) void; +pub fn deinstall() void; // flushes and closes the file; for tests and shutdown +pub const Stats = struct { lines_written, lines_deduped, rotations, sink_errors: u64 }; +pub fn stats() Stats; +``` + +Verify the exact `std.Options.logFn` signature against lib/std/std.zig + log.zig before writing — +do not trust this spec's sketch. + +- Global sink state behind a `std.Thread.Mutex`? **No** — `std.Io.Mutex` needs an io; `logFn` + receives none. Store the installed `std.Io` by value in the global state (it is a plain + interface value); guard the whole sink with `std.debug` -style spinlock? Verify what std.log's + default lock does in 0.16 and mirror it. If std provides no lock for custom logFn, use a + file-scope `std.Thread.Mutex` (std.Thread still exists for this — verify) or an atomic spin + guard; state the choice in a comment. This is the one deliberately-open point in this spec: + resolve it against the stdlib source and record the resolution for "As built". +- Level: drop below `cfg.level` (mapping model's level enum to std.log.Level — write it). +- Dedup: for `warn`+ lines whose scope is one of `.doh_client`, `.dot_client`, `.pool`, + `.forward_client`: key = scope + formatted message truncated to 96 bytes; a key seen within the + last 60 s (`.awake`) is dropped and counted. Fixed 64-entry table, oldest-stamp replacement. +- File mode: append (seekTo end-of-file pattern), byte counter from `file.length` at open; a line + that would cross `cfg.maxLogBytes()` triggers rotation first: delete `.{max_files-1}`, shift + `.N`→`.N+1`, rename live → `.1`, reopen fresh. All under the sink lock. Rotation or write + failure: fall back to stderr for that line, count `sink_errors`, keep trying the file next line. +- stderr mode: format + single `write` per line (std.debug.lockStdErr equivalent — verify). + +Tests: the pure pieces — dedup table admits first, drops repeat inside 60 s, admits after; level +mapping; rotation name arithmetic (`rotatedName(buf, path, n)`). File behavior lands in S8 (needs +a real dir). `logFn` itself is NOT exercised in tests (installing a sink under the test runner +would eat the harness's own logs). + +Acceptance: fmt/ast-check clean; no `std.log` call inside the sink itself (it would recurse); +dedup + rotation arithmetic covered. + +--- + +## Session S7: retention — `src/storage/retention.zig` (needs S3) + +Imports: `std`, `db.zig`, `repositories/queries_repo.zig`, `../config/model.zig`. + +```zig +pub const vacuum_every_passes = 7; +pub const Stats = struct { passes, rows_pruned, checkpoints, vacuums: u64 = 0 }; +pub const Retention = struct { + pub fn init(cfg: model.Logging) Retention; + /// One pass: prune rows older than now - retentionSeconds, checkpoint, and on every 7th + /// pass vacuum. DB errors log at warn and the pass counts as done (next pass retries). + pub fn runOnce(self: *, io: std.Io, database: *db.Db) void; + /// Daily loop (.boot), first pass immediately. `database` must be a dedicated + /// connection no other task uses while the loop runs; Phase 7 opens it. + pub fn run(self: *, io: std.Io, database: *db.Db) std.Io.Cancelable!void; + stats: Stats, +}; +pub const pass_interval_s = 86_400; +``` + +`runOnce` computes the cutoff from `Clock.real.now(io).toSeconds() - cfg.retentionSeconds()`. +Sharing one handle between concurrent tasks is NOT safe: FULLMUTEX serializes single SQLite calls, +but a transaction is connection state — a prune landing between another task's BEGIN and COMMIT +joins that transaction. The contract therefore requires a dedicated connection; cross-connection +isolation is SQLite's own (WAL + busy_timeout), and a pass losing a race sees Busy/Locked, logs at +warn, and retries next interval. + +Tests (`:memory:` + ddl): a pass prunes exactly the old rows; the 7th pass vacuums (assert via +`stats.vacuums` after 7 `runOnce` calls); a pass on an empty DB is a no-op that still counts; +cutoff arithmetic honors `retention_days`. + +Acceptance: fmt/ast-check clean; tests standalone with `-lc -lsqlite3`. + +--- + +## Session S8: integration — `src/storage/phase6_integration_test.zig` (needs all) + +Gated by `build_options.integration` exactly like `storage_integration_test.zig` (same Fixture +idiom over `.zig-cache/tmp/`). Cases, named `"S8 case N: …"`: + +1. logger end-to-end: real file `querylog.db` via `querylog_schema.open`, writer task under + `io.concurrent`, 250 entries → shutdown → 250 rows, domains interned (fewer domain rows than + query rows), fingerprint stamped. +2. flush on interval: one entry, no shutdown; poll until it lands; well under 10× the interval. +3. backpressure: queue capacity 8, enqueue 20 with the writer stalled (gated by a monitor stub at + critical); `queries_dropped >= 12`, the survivors are the NEWEST entries, then un-gate and + confirm the survivors landed. +4. privacy: hide both → every row's domain and client_ip read `hidden`. +5. retention: back-dated rows pruned, fresh rows kept, WAL truncated after checkpoint (assert + `-wal` size 0 or absent). +6. disk thresholds end-to-end (§17 exit criterion): monitor with `min_free_mb` far above the real + free space → `.critical`, `writesAllowed() == false`, logger gates (case-3 machinery), + `batches_gated > 0`; then thresholds far below → `.ok` and flushing resumes. +7. log sink file mode: install to a fixture path with `max_size_mb` tiny (write the size gate via + a test-only override — if `install` takes cfg, a 1 MB minimum makes this slow; add + `pub fn installForTest(io, cfg, max_bytes_override)` if needed and mark it test-only), + emit lines past the limit → `.1` exists, live file small, `max_files` honored, then + `deinstall`. If overriding proves ugly, rotation is proven at the arithmetic level in S6 and + this case shrinks to append+reopen round-trip — say which in the report. +8. cache with real packets: build a response via `ResponseBuilder`, `classify` + `put`, advance + `now_s`, `get` → TTLs visibly decremented (re-parse), expiry at the boundary is a miss. +9. rate limiter + address integration: 1001 checks from one v6-mapped-v4 client inside one window + → exactly one refused… (limit 1000); a second distinct client unaffected. + +Acceptance: `zig build test -Dintegration` exit 0 with all 9 passing; no case sleeps longer than +2 s of wall time; no network. + +--- + +## Module Layout (new files) + +| File | Purpose | +|---|---| +| `src/cache/dns_cache.zig` | pure TTL cache: key, classify, CLOCK-bounded store | +| `src/server/rate_limiter.zig` | pure fixed-window per-client limiter | +| `src/storage/repositories/queries_repo.zig` | query_log/domains writes, prune, checkpoint, vacuum | +| `src/storage/logger.zig` | Io.Queue async logger, privacy, backpressure, disk gate | +| `src/platform/statfs.zig` | libc statvfs wrapper | +| `src/storage/disk_monitor.zig` | free-space thresholds, gauges, 60 s sampler | +| `src/platform/logging.zig` | std.log sink: level, rotation, upstream dedup | +| `src/storage/retention.zig` | daily prune + checkpoint + weekly vacuum | +| `src/storage/phase6_integration_test.zig` | S8 cases | + +## File Ownership + +| Files | Owner | +|---|---| +| `src/cache/dns_cache.zig` | S1 | +| `src/server/rate_limiter.zig` | S2 | +| `src/storage/repositories/queries_repo.zig` | S3 (frozen after S3 verifies) | +| `src/storage/logger.zig` | S4 | +| `src/platform/statfs.zig`, `src/storage/disk_monitor.zig` | S5 (frozen after wave 1) | +| `src/platform/logging.zig` | S6 | +| `src/storage/retention.zig` | S7 | +| `src/storage/phase6_integration_test.zig` | S8 | +| `src/tests.zig`, `build.zig`, `src/main.zig` (std_options) | orchestrator | + +No session touches `src/dns/`, `src/upstream/`, `src/filter/`, `src/local/`, `src/server/handler.zig`, +`src/server/udp_server.zig`, `src/server/tcp_server.zig`, `src/storage/db.zig`, any milestone 4–5 +repository, `src/config/`, or `src/cli.zig`. A needed change there is reported, not made. + +## Acceptance Criteria (Milestone 6 Complete) + +- [ ] `zig build test` exit 0 with all nine new files wired into `src/tests.zig`. +- [ ] `zig build test -Dintegration` exit 0 including the 9 S8 cases and every prior milestone's. +- [ ] `zig build cross` still produces two statically linked executables (statvfs links against + musl). +- [ ] `grep -rn "std.log.err" src/cache/ src/storage/logger.zig src/storage/disk_monitor.zig + src/storage/retention.zig src/server/rate_limiter.zig src/platform/statfs.zig + src/platform/logging.zig` → nothing. +- [ ] `validate.zig` rejects `rate_window_seconds = 0` (rule exists at validate.zig:221; covered + by milestone-4 tests). +- [ ] `DnsCache.get`, `RateLimiter.check` have no allocator in reach — signatures prove the + no-allocation hit path. +- [ ] The disk-degradation integration case (S8 case 6) passes — PLAN §17's Phase 6 exit + criterion. +- [ ] `zig fmt --check` clean repo-wide; GPG-signed lowercase commit. + +## Anti-Requirements + +- **No handler or server wiring.** `handler.zig` keeps its signature; nothing calls the cache, + the limiter, or the logger from the query path. Phase 7. +- **No client-row pruning and no auto-materialization.** Phase 7 (ruling 1). +- **No web/API/SSE/metrics/health payloads.** Phase 8 reads the accessors this milestone exposes. +- **No API token bucket.** §10's API limiter is Phase 8. +- **No cache persistence, no cache serialization.** In-memory only (§8). +- **No ECS parsing.** The cache key accepts ECS bytes the caller extracted; extracting them from + OPT is the handler's job in Phase 7. +- **No statement cache in db.zig.** `BatchWriter` owns its statements; `db.zig` stays as is. +- **No new config keys and no schema change.** Every knob this milestone reads exists in + `model.zig`; flush tuning is comptime (ruling 3). +- **No log sink installation under the test runner.** `install` runs only from `main`. +- **No epoll/timerfd/signalfd.** Loops sleep on `Clock.Duration`; Phase 7 owns lifecycle. + +## As built (S1–S7 and orchestrator wiring) + +Deviations from the text above, recorded after the sessions verified. Where this section and the +session text disagree, this section wins. + +**S1 dns_cache.** `Config` is an alias of `model.Cache`, not a duplicate struct. `classify` +computes the positive min-TTL by iterating records (no mutation, no 64 KiB copy); NODATA (NOERROR, +zero answers) takes the negative path with NXDOMAIN per RFC 2308 §2; a malformed SOA means "do not +cache", not an error; `negative_ttl_max == 0` disables negatives only — positives still cache. A +`put` on an existing key keeps the slot's CLOCK reference bit. A slot the CLOCK hand reclaims +because it expired counts `expirations`, not `evictions`. `size == 0` turns caching off (`put` +no-ops). A backwards clock ages by zero. `misses` covers lookup failure, expiry and a too-small +`out`; a poisoned entry counts `invalid_hits` only. The slot's `negative` flag is stored but has +no accessor yet — Phase 8 adds one if it wants the split. After review: the negative TTL is +min(SOA record TTL, SOA MINIMUM) per RFC 2308 §5, and a top-bit-set TTL reads as zero per RFC 2181 +§8 on every non-OPT record in any section (positive path) and both SOA fields (negative path) — a +zero result means the response is not cached. When `put` stores a negative response it lowers the +clone's first authority SOA record TTL to the entry's lifetime, so a hit at elapsed 0 serves an +SOA TTL equal to the entry TTL and downstream caches do not hold the negative answer past it +(RFC 2308 §3); the caller's buffer is not modified. On the positive path `put` caps every non-OPT +record TTL in the clone at `max_ttl_seconds` for the same reason — the stored bytes never +advertise a lifetime past the entry's ceiling (the cap is our ruling 5, not an RFC rule; unbound's +cache-max-ttl serves the capped value the same way). A negative response's non-SOA records are +deliberately not capped — the clamped SOA is the record that governs negative caching downstream. +The poisoned-packet ageing test's fixture keeps its TTL under `max_ttl_seconds` on purpose, so +`put` stores it unmodified and only the ageing inside `get` breaks it. + +**S2 rate_limiter.** Windows anchor at each client's first query (`.awake` origin is arbitrary). +`sweep` drops entries older than two full windows (exactly two survives). `untracked` is a subset +of `allowed`, so `allowed + refused` equals the number of `check` calls. `init` asserts +`window_seconds != 0` (validate.zig:221 guards real configs). `limit == 0` refuses everything. +Added: `trackedClients()` occupancy accessor. `sweep` collects stale keys into a buffer allocated +at init (~68 KiB), not onto the stack. + +**S3 queries_repo.** Domain interning is INSERT OR IGNORE + SELECT (no `lastInsertRowid` — unset +on ignore); a missing row right after the insert is `error.NotFound`. `select_domain` resets +immediately after the id is read; `errdefer tx.rollback()` is declared before `errdefer +resetAll()` so no cursor is open at ROLLBACK. `checkpointTruncate` treats a blocked checkpoint as +success (SQLite reports it in a discarded row; retention retries next pass). + +**S4 logger.** `Entry.init(Entry.Fields)` builds an entry from borrowed slices, copying and +truncating; `setDomain`/`setClientIp` are public for the privacy transform. **Spec correction:** +the `fetchWithin` shape's `cancelDiscard` is wrong here — a `getOne` that loses the race has +already removed an entry, and discarding its result loses the entry silently. `getWithin` drains +the Select with a `while (race.cancel())` loop; an entry recovered on the cancellation path counts +`queries_dropped`. A batch dropped by a `writeBatch` failure adds its length to `queries_dropped`. +The interval deadline starts at the first entry of a batch. `gate_retry_s = 1` is public. Queue +facts verified: `put` returns `Closed` even with space; `get(min=0)` on a closed non-empty queue +returns elements and reports `Closed` only when empty — that is what makes the shutdown drain +correct. A writer sitting in the disk gate at shutdown holds its batch until un-gated or +canceled (documented on `shutdown`); `Logger` must not move after `init`. After review: `fill` +reports its count through an out-parameter, so a canceled `fill` or `flush` counts every entry +still held in the batch under `queries_dropped` (including the gate-blocked cancellation); a +`BatchWriter.init` failure warns, sets `writer_failed: std.atomic.Value(bool)`, closes the queue +and drains it with `Queue.getUncancelable` — uncancelable specifically so a cancellation racing +the failure cannot leave buffered entries uncounted (no other consumer can reach them at that +point); the writer never pretends to run. The zero-capacity early exit reads +`queue.capacity()`. The prepare-failure path and +the cancellation accounting are both covered in-file (schema-less `:memory:` DB; deterministic +2-entry batch canceled in the gate). + +**S5 statfs + disk_monitor.** The statvfs layout is pinned by `@offsetOf`/`@sizeOf` tests (112 +bytes); musl verified from the zig-shipped headers, glibc from the system's. `init` requires +`data_dir` opened with `.iterate = true` (documented). `log_dir_path` opens via `cwd()` per +sample; null keeps `log_bytes` at 0. A failed statvfs leaves the state untouched; a failed size +scan keeps that gauge's prior value while the state still publishes. A per-file `statFile` failure +inside a size scan fails that whole scan — the gauge keeps its prior value and `sample_failures` +increments once for the scan, not per file; `error.FileNotFound` is the one exception (a file +deleted between `iterate` and `statFile` is normal on rotation or recreate — skipped, scan +continues). `classify` checks min before +warn, so warn-below-min misconfiguration reports the severer state. `run` samples first, then +sleeps. Sizes come from `Dir.statFile`. + +**S6 logging sink.** **Spec corrections:** the `logFn` scope parameter is `comptime scope: +@EnumLiteral()`, and `std.Thread.Mutex` does not exist in 0.16.0. The sink lock is +`std.debug.lockStderr`/`unlockStderr` (the same lock `std.log.defaultLog` uses; documented +recursive; needs no io). Added: `installForTest(io, cfg, max_bytes_override)`; public pure +helpers `toStdLevel`, `enabled`, `isDedupScope`, `buildKey`, `DedupTable`, `rotatedName`. +`max_files` counts the live file (generations `.1`…`.{max_files-1}`); `max_files < 2` truncates +in place. `LogOutput.syslog` routes to stderr (journald captures it — the only supported +deployment). File lines are ` (): \n`, per-line durable (fresh +writer, seekTo, writeAll, flush); write failure closes the file and the next line reopens it; +overlong paths fall back to stderr and count `sink_errors`; cancel protection wraps file work. +After review: `` is escaped on BOTH output paths — `\\`, newline, carriage return and tab as +two-character escapes, every other byte below 0x20 plus DEL as `\xNN` (a deliberate divergence +from `std.log.defaultLog`, which writes raw; these lines are parsed by operators and journald); +`max_escaped_message_bytes = max_message_bytes * 4` is public and the line buffer holds the worst +case. A failed rotation step counts `sink_errors`, sends the line to stderr, and leaves the live +file CLOSED until a later line completes the rotation — the oversized file is never reopened for +append (`rotate_pending`); `rotations` counts completed rotations only. One exception: a single +line longer than `max_bytes` is written to an empty file rather than rotated forever. +`lines_written` counts only lines a sink accepted; each failed write attempt counts one +`sink_errors` (file-fail + stderr-success = one of each). The scope name is truncated to +`max_scope_name_bytes` (32) by `boundedScopeName`, applied once in `logFn` so the file and stderr +paths render the same event identically; the public constant `max_line_header_bytes` (65) bounds +the record header and the file line buffer is `max_escaped_message_bytes + +max_line_header_bytes`. Record construction is `buildLine`, a pure function taking the unix +seconds as a parameter — it returns an error instead of a partial record, and a failure counts +one `sink_error` and sends the line to stderr, so a malformed record never reaches the file. +Counting contract: every path where `prepareFileLocked` returns false has already counted exactly +one `sink_error` at the failing step (the caller never counts again); `rotateLocked` counts its +own failure. + +**S7 retention.** Prune, checkpoint and vacuum are independent within a pass — a failed prune +does not skip the checkpoint (the WAL was filled by the logger, not this pass). `passes` +increments at the top of `runOnce`; vacuum fires at `passes % 7 == 0`. The cutoff is +strictly-less-than (a row exactly at the cutoff survives). `runOnce` opens no transaction; the +contract on `run` requires a dedicated connection (concurrent sharing joins the other task's +transaction — FULLMUTEX does not prevent that); Phase 7 opens it. Sequential use of one handle, +as S8 case 5 does, is permitted. + +**Orchestrator wiring.** All eight new files (S8's included) imported individually by +`src/tests.zig`. `src/main.zig` gained `pub const std_options: std.Options = .{ .logFn = +logging.logFn };` — effective in the executable build, inert under the test runner (tests.zig is +that root); `zig build` type-checks the sink through real call sites. The spec's claim that a +`rate_window_seconds` rule was missing from validate.zig was wrong — the rule exists at +validate.zig:221; nothing was added. + +**S8 integration.** Case 7 runs the full rotation via `installForTest(io, cfg, 256)` with +`max_files = 3`, calling `logging.logFn` directly (the test runner owns `std_options`, so a +`std.log` call would never reach the sink) and comparing counters as before/after deltas +(`install`/`deinstall` do not reset stats); it also proves append-and-reopen byte-identity. Case 3 +enqueues the full burst before the writer starts, making "12 dropped, newest 8 survive" exact, and +starts the writer gated. Cases 3 and 6 un-gate before `shutdown` (the gate-hold documented in S4). +Case 6 samples real `statvfs` against the fixture dir and flips state by swapping `monitor.cfg` +between huge and zero thresholds. Case 5 asserts the WAL was non-empty before the checkpoint, so +truncation is proven, not assumed. Shared-Db reads happen only while the writer sleeps in the gate +or after its future is awaited. All cases use `testing.io`. Per-case wall time stays under 1.5 s; +cases 3 and 6 pay `gate_retry_s`. With `integration = false`, all 9 skip. diff --git a/specs/research/zig-0.16-api-notes.md b/specs/research/zig-0.16-api-notes.md index a0b0a52..4d1457d 100644 --- a/specs/research/zig-0.16-api-notes.md +++ b/specs/research/zig-0.16-api-notes.md @@ -195,3 +195,25 @@ verification name is an IP literal (DoT `tls://1.1.1.1:853`) always fails with as an iPAddress SAN — which is how Cloudflare and Quad9 issue theirs. A DoT upstream therefore needs a DNS `tls_name` for SNI + verification while dialing the IP; verifying by bare IP cannot work on stock 0.16. + +## Phase 6 verifications (concurrency, disk, files) + +- `std.Io.Queue(Elem)` exists (Io.zig:2184): bounded ring buffer over a caller-supplied array. + `put(q, io, elems, min)` with `min = 0` never blocks and returns 0 when full (Io.zig:2218); + `getOne` blocks until an item or `error.Closed` after `close(io)`. Elements are copied as raw + bytes (`@ptrCast`, Io.zig:2189) — an element holding a slice transfers only the pointer, so + queue elements must be self-contained values. +- `std.Io.Condition` has NO `timedWait` (Io.zig:1653 — wait/waitUncancelable/signal/broadcast + only). The timed primitive is `std.Io.Event.waitTimeout` (Io.zig:1827). +- Disk free space: std has NO statvfs/statfs wrapper (no Statfs struct, no `f_bavail` anywhere in + lib/std). Options: `extern fn statvfs` against libc (we always link libc for sqlite) or raw + `std.os.linux.syscall2(.statfs, ...)` with a hand-written struct. +- File append mode does not exist on `Dir.OpenFileOptions`/`CreateFileOptions`. Append pattern: + `openFile(io, path, .{ .mode = .write_only })`, `file.writer(io, &buf)`, then + `w.seekTo(try file.length(io))`; the writer is positional. `File.setLength` truncates; + `Dir.rename` + `Dir.deleteFile` rotate. Positional writes do not serialize — one task owns the + log writer. +- No fixed-capacity hash map in std. Bounded cache shape: fixed slot array plus + `StringHashMapUnmanaged(u32)` from key to slot index (`ensureTotalCapacity` once at init); + a CLOCK hand walks the stable slot array, never the map. Any map modification invalidates + live iterators (hash_map.zig:496). diff --git a/src/cache/dns_cache.zig b/src/cache/dns_cache.zig new file mode 100644 index 0000000..24b9cca --- /dev/null +++ b/src/cache/dns_cache.zig @@ -0,0 +1,1107 @@ +//! The TTL cache (PLAN §8): a bounded, in-memory store of whole DNS response +//! messages keyed by the question they answer. +//! +//! Pure. Every decision that needs a clock takes the current wall-clock second +//! as a parameter, so this file holds no `std.Io`, no clock and no socket. The +//! only allocation happens in `init` and `put`; `get` copies into a caller +//! buffer and allocates nothing. +//! +//! **Not thread-safe.** No lock guards the slots, the index or the counters. +//! Phase 7 decides the locking when it wires the cache into the query path. +//! +//! The store is a fixed array of slots plus a hash index from key bytes to slot +//! number, both sized at `init` and never resized: a household resolver must +//! not grow its memory because a burst of unique names arrived. Replacement is +//! CLOCK — one reference bit per slot, a hand that clears bits as it looks for a +//! victim — which approximates LRU at the cost of a single bit and no list +//! surgery on the hit path. + +const std = @import("std"); +const packet = @import("../dns/packet.zig"); +const record = @import("../dns/record.zig"); +const types = @import("../dns/types.zig"); +const model = @import("../config/model.zig"); + +const Allocator = std.mem.Allocator; + +/// Sanity ceiling on a positive TTL. Same value as `max_ttl_seconds` in +/// `validate.zig`, which already caps `blocking.ttl` and +/// `cache.negative_ttl_max`: one bound on how long nxdns may hold a name. +pub const max_ttl_seconds: u32 = 86_400; + +/// Longest ECS prefix the key accepts: an IPv6 address plus the two-byte family +/// field, the two prefix-length bytes and slack for the option header. +pub const max_ecs_len = 40; + +/// qname (lowercased ASCII, no trailing dot) ++ 0x00 ++ qtype BE ++ qclass BE +/// ++ do byte ++ ecs_len byte ++ ecs bytes. +pub const max_key_len = types.max_name_len + 1 + 2 + 2 + 1 + 1 + max_ecs_len; + +/// Writes the cache key into `buf` and returns the written prefix. +/// +/// ECS participates only when the caller passes it. Phase 7 passes the +/// forwarded subnet under `ecs_mode=forward` and nothing otherwise (PLAN §8), +/// so a deployment that does not forward ECS pays no key-space split for it. +/// +/// The length bounds are assertions, not errors: both values reach here from +/// the packet parser, which has already rejected anything longer. +pub fn buildKey( + buf: *[max_key_len]u8, + qname: []const u8, + qtype: u16, + qclass: u16, + do_bit: bool, + ecs: ?[]const u8, +) []const u8 { + std.debug.assert(qname.len <= types.max_name_len); + if (ecs) |bytes| std.debug.assert(bytes.len <= max_ecs_len); + + var name = qname; + if (name.len > 0 and name[name.len - 1] == '.') name = name[0 .. name.len - 1]; + + var len: usize = 0; + for (name) |c| { + buf[len] = std.ascii.toLower(c); + len += 1; + } + + // The separator keeps a name from running into the fields behind it, so + // "a" with qtype 0x0101 cannot collide with "a\x01" with qtype 0x0100. + buf[len] = 0; + len += 1; + + std.mem.writeInt(u16, buf[len..][0..2], qtype, .big); + len += 2; + std.mem.writeInt(u16, buf[len..][0..2], qclass, .big); + len += 2; + buf[len] = @intFromBool(do_bit); + len += 1; + + const ecs_bytes = ecs orelse &[_]u8{}; + buf[len] = @intCast(ecs_bytes.len); + len += 1; + @memcpy(buf[len..][0..ecs_bytes.len], ecs_bytes); + len += ecs_bytes.len; + + return buf[0..len]; +} + +pub const Class = struct { + ttl_seconds: u32, + negative: bool, +}; + +/// Decides whether a response is cacheable and for how long. Null means do not +/// cache — an unparsable message, an rcode nxdns will not hold, a missing SOA, +/// or a TTL that has already run out. +/// +/// The positive TTL is the smallest TTL in the message, which is what +/// `packet.decrementTtls` would report. It is computed by iterating the +/// sections rather than by calling that function, because `decrementTtls` +/// writes to its buffer and a response worth classifying has not been copied +/// yet. +/// +/// `negative_ttl_max == 0` disables negative caching outright: the response is +/// not stored at all (milestone-6 ruling 6). +pub fn classify(response: []const u8, negative_ttl_max: u32) ?Class { + const p = packet.parse(response) catch return null; + const rcode = p.header.flags.rcode; + + if (rcode == .no_error and p.header.ancount > 0) { + const smallest = (minRecordTtl(p) catch return null) orelse return null; + const ttl = @min(smallest, max_ttl_seconds); + if (ttl == 0) return null; + return .{ .ttl_seconds = ttl, .negative = false }; + } + + // RFC 2308 §2: an empty NOERROR answer is NODATA, a negative answer like + // NXDOMAIN, and both take their lifetime from the authority SOA. + if (rcode == .nx_domain or rcode == .no_error) { + if (negative_ttl_max == 0) return null; + const soa = soaTtls(p) orelse return null; + // RFC 2308 §5: the negative lifetime is the smaller of the SOA record's + // own TTL and its MINIMUM field. + const from_soa = @min(effectiveTtl(soa.record_ttl), effectiveTtl(soa.minimum)); + const ttl = @min(from_soa, negative_ttl_max); + if (ttl == 0) return null; + return .{ .ttl_seconds = ttl, .negative = true }; + } + + return null; +} + +/// RFC 2181 §8: a TTL whose top bit is set is read as zero. This cache does not +/// store a zero TTL, so such a response is not cached at all. +/// `packet.decrementTtls` leaves the rule to its caller, and this is the caller. +fn effectiveTtl(ttl: u32) u32 { + return if (ttl & 0x8000_0000 != 0) 0 else ttl; +} + +/// The smallest TTL over every record in the message, OPT excluded — RFC 6891 +/// §6.1.3 reuses its TTL field for flags. Null when no record carries a TTL +/// that means anything. +fn minRecordTtl(p: packet.Packet) packet.WalkError!?u32 { + var smallest: ?u32 = null; + var iterators = [_]packet.RecordIterator{ + packet.answers(p), + packet.authorities(p), + packet.additionals(p), + }; + for (&iterators) |*it| { + while (try it.next()) |rec| { + if (rec.rtype == .opt) continue; + const ttl = effectiveTtl(rec.ttl); + smallest = if (smallest) |current| @min(current, ttl) else ttl; + } + } + return smallest; +} + +const SoaTtls = struct { + record_ttl: u32, + minimum: u32, +}; + +/// TTL is four bytes and RDLENGTH two, so a record's TTL field starts six bytes +/// before its RDATA. +const ttl_bytes_before_rdata = 6; + +/// Lowers the first authority SOA's TTL to `ttl_seconds` in `bytes`. +/// +/// RFC 2308 §3 makes that TTL the lifetime a downstream cache keeps the +/// negative answer for, and `classify` may have cut the entry's lifetime below +/// it using the SOA MINIMUM field or `negative_ttl_max`. Without this rewrite a +/// hit would advertise a TTL longer than the entry itself lives. +/// +/// It clamps the same SOA that `soaTtls` measured, and it only ever lowers a +/// TTL. Bytes it cannot parse are left alone: `get` refuses an entry that does +/// not survive ageing, so an unparsable clone needs no separate treatment here. +fn clampSoaTtl(bytes: []u8, ttl_seconds: u32) void { + const p = packet.parse(bytes) catch return; + var it = packet.authorities(p); + while (it.next() catch return) |rec| { + if (rec.rtype != .soa) continue; + if (rec.ttl <= ttl_seconds) return; + // The write comes after the last read of the iterator, which walks the + // same bytes: a record rewritten mid-walk could break the walk. + const ttl_offset = rec.rdata.offset - ttl_bytes_before_rdata; + std.mem.writeInt(u32, bytes[ttl_offset..][0..4], ttl_seconds, .big); + return; + } +} + +/// Lowers every record TTL in `bytes` above `max_ttl_seconds` to that ceiling, +/// OPT excluded — RFC 6891 §6.1.3 reuses its TTL field for flags. +/// +/// `classify` caps a positive entry's lifetime at `max_ttl_seconds`, so without +/// this rewrite a hit would advertise a TTL that outlives the entry. A record at +/// or below the ceiling keeps its own TTL, including one longer than the entry's +/// shortest record: per-record lifetimes are what a downstream cache expects. +/// +/// A TTL rewritten here may sit under an owner name that a later record +/// compresses against, and the rewrite can leave that name undecodable. The walk +/// stops there, and `get` discards the entry on the first hit — the same fate +/// `packet.decrementTtls` already gives such a message when it ages it. +fn capRecordTtls(bytes: []u8) void { + const p = packet.parse(bytes) catch return; + var iterators = [_]packet.RecordIterator{ + packet.answers(p), + packet.authorities(p), + packet.additionals(p), + }; + for (&iterators) |*it| { + while (it.next() catch return) |rec| { + if (rec.rtype == .opt) continue; + if (rec.ttl <= max_ttl_seconds) continue; + const ttl_offset = rec.rdata.offset - ttl_bytes_before_rdata; + std.mem.writeInt(u32, bytes[ttl_offset..][0..4], max_ttl_seconds, .big); + } + } +} + +/// The two lifetime fields of the first authority SOA: the record's own TTL and +/// the MINIMUM field of its RDATA (RFC 2308 §4). A malformed SOA is treated as +/// an absent one: the response is simply not cached. +fn soaTtls(p: packet.Packet) ?SoaTtls { + var it = packet.authorities(p); + while (it.next() catch return null) |rec| { + if (rec.rtype != .soa) continue; + const minimum = record.rdataSoaMinimumTtl(p.bytes, rec) catch return null; + return .{ .record_ttl = rec.ttl, .minimum = minimum }; + } + return null; +} + +/// Field-for-field the cache section of the config model. Aliasing it keeps one +/// type for one concept: `size` counts entries, not bytes (ruling 7). +pub const Config = model.Cache; + +pub const Stats = struct { + hits: u64 = 0, + misses: u64 = 0, + inserts: u64 = 0, + evictions: u64 = 0, + expirations: u64 = 0, + /// Entries dropped because aging their bytes made them unparsable. A + /// poisoned entry never serves twice. + invalid_hits: u64 = 0, +}; + +/// The key lives inline so that a slot owns no memory besides its response +/// bytes, and so that the index can key on a slice that stays valid for the +/// life of the cache. +const Slot = struct { + key: [max_key_len]u8, + key_len: u16, + bytes: []u8, + stored_at_s: i64, + expires_at_s: i64, + negative: bool, + referenced: bool, + occupied: bool, + + fn keySlice(self: *const Slot) []const u8 { + return self.key[0..self.key_len]; + } +}; + +/// Key bytes to slot number. The stored key slices point into the slots array, +/// which is allocated once and never moves. +const Index = std.StringHashMapUnmanaged(u32); + +pub const DnsCache = struct { + gpa: Allocator, + slots: []Slot, + index: Index, + /// The CLOCK hand: the next slot the replacement scan will examine. + hand: u32, + occupied: u32, + stats: Stats, + + /// Allocates the slots and the index up front. `ensureTotalCapacity` at the + /// entry count means the index never rehashes, so the key slices it stores + /// stay valid and no insert can allocate. + pub fn init(gpa: Allocator, config: Config) Allocator.Error!DnsCache { + const slots = try gpa.alloc(Slot, config.size); + errdefer gpa.free(slots); + for (slots) |*slot| { + slot.* = .{ + .key = undefined, + .key_len = 0, + .bytes = &.{}, + .stored_at_s = 0, + .expires_at_s = 0, + .negative = false, + .referenced = false, + .occupied = false, + }; + } + + var index: Index = .empty; + errdefer index.deinit(gpa); + try index.ensureTotalCapacity(gpa, config.size); + + return .{ + .gpa = gpa, + .slots = slots, + .index = index, + .hand = 0, + .occupied = 0, + .stats = .{}, + }; + } + + pub fn deinit(self: *DnsCache) void { + for (self.slots) |*slot| { + if (slot.occupied) self.gpa.free(slot.bytes); + } + self.gpa.free(self.slots); + self.index.deinit(self.gpa); + self.* = undefined; + } + + /// Stores a clone of `response` under `key`. A key already present is + /// replaced in place, which keeps the entry count and the CLOCK order + /// unchanged. + /// + /// The clone never advertises a TTL that outlives the entry: a negative + /// response has its SOA TTL lowered to the entry's lifetime, and a positive + /// one has every record above `max_ttl_seconds` lowered to that ceiling. The + /// caller's buffer is not touched. + /// + /// A cache configured with zero entries stores nothing. That is caching + /// switched off, not a failure, so it is not an error. + pub fn put( + self: *DnsCache, + now_s: i64, + key: []const u8, + response: []const u8, + class: Class, + ) Allocator.Error!void { + std.debug.assert(key.len <= max_key_len); + if (self.slots.len == 0) return; + + const bytes = try self.gpa.dupe(u8, response); + errdefer self.gpa.free(bytes); + if (class.negative) clampSoaTtl(bytes, class.ttl_seconds) else capRecordTtls(bytes); + + const expires_at_s = now_s +| @as(i64, class.ttl_seconds); + + if (self.index.get(key)) |existing| { + const slot = &self.slots[existing]; + self.gpa.free(slot.bytes); + slot.bytes = bytes; + slot.stored_at_s = now_s; + slot.expires_at_s = expires_at_s; + slot.negative = class.negative; + self.stats.inserts += 1; + return; + } + + const index = self.acquireSlot(now_s); + const slot = &self.slots[index]; + @memcpy(slot.key[0..key.len], key); + slot.key_len = @intCast(key.len); + slot.bytes = bytes; + slot.stored_at_s = now_s; + slot.expires_at_s = expires_at_s; + slot.negative = class.negative; + slot.referenced = false; + slot.occupied = true; + + const gop = self.index.getOrPutAssumeCapacity(slot.keySlice()); + std.debug.assert(!gop.found_existing); + gop.key_ptr.* = slot.keySlice(); + gop.value_ptr.* = index; + + self.occupied += 1; + self.stats.inserts += 1; + } + + /// Copies the stored response into `out` and ages its TTLs by the time the + /// entry has been held. Nothing else is rewritten — the caller sets the + /// transaction ID with `packet.setId`. + /// + /// Returns null on a miss, on an expired entry, and on an `out` too small + /// to hold the response; all three count as `misses`, because from the + /// caller's side each one means the query must go upstream. + pub fn get(self: *DnsCache, now_s: i64, key: []const u8, out: []u8) ?[]u8 { + const index = self.index.get(key) orelse { + self.stats.misses += 1; + return null; + }; + + const slot = &self.slots[index]; + if (now_s >= slot.expires_at_s) { + self.release(index); + self.stats.expirations += 1; + self.stats.misses += 1; + return null; + } + if (out.len < slot.bytes.len) { + self.stats.misses += 1; + return null; + } + + const copy = out[0..slot.bytes.len]; + @memcpy(copy, slot.bytes); + + // A clock that stepped backwards ages nothing rather than ageing by a + // negative amount. + const elapsed_s = now_s - slot.stored_at_s; + const elapsed: u32 = if (elapsed_s <= 0) + 0 + else + @intCast(@min(elapsed_s, std.math.maxInt(u32))); + + _ = packet.decrementTtls(copy, elapsed) catch { + self.release(index); + self.stats.invalid_hits += 1; + return null; + }; + + slot.referenced = true; + self.stats.hits += 1; + return copy; + } + + /// Removes every expired entry and returns how many. Phase 7 schedules it; + /// expiry is also enforced on access, so this only reclaims memory held by + /// names nobody asks for any more. + pub fn sweep(self: *DnsCache, now_s: i64) u32 { + var removed: u32 = 0; + for (self.slots, 0..) |*slot, index| { + if (!slot.occupied) continue; + if (now_s < slot.expires_at_s) continue; + self.release(@intCast(index)); + removed += 1; + } + self.stats.expirations += removed; + return removed; + } + + pub fn len(self: *const DnsCache) u32 { + return self.occupied; + } + + /// Bytes held: the slot array, the cloned responses, and the index arrays. + /// The index term follows its layout of a key array, a value array and one + /// metadata byte per bucket. + pub fn memoryBytes(self: *const DnsCache) usize { + var total = self.slots.len * @sizeOf(Slot); + for (self.slots) |*slot| { + if (slot.occupied) total += slot.bytes.len; + } + total += @as(usize, self.index.capacity()) * + (@sizeOf([]const u8) + @sizeOf(u32) + 1); + return total; + } + + /// Returns a slot ready for a new entry, freeing whatever held it. + /// + /// An expired slot met on the way is reclaimed as an expiration rather than + /// an eviction: it was already dead, and counting it as an eviction would + /// report cache pressure that is not there. + fn acquireSlot(self: *DnsCache, now_s: i64) u32 { + const capacity: u32 = @intCast(self.slots.len); + // Every occupied slot is examined at most twice: the first pass clears + // the reference bits, the second finds a slot with none set. + const limit = @as(usize, capacity) * 2; + + var steps: usize = 0; + while (steps < limit) : (steps += 1) { + const index = self.hand; + self.hand = (self.hand + 1) % capacity; + const slot = &self.slots[index]; + + if (!slot.occupied) return index; + if (now_s >= slot.expires_at_s) { + self.release(index); + self.stats.expirations += 1; + return index; + } + if (slot.referenced) { + slot.referenced = false; + continue; + } + self.release(index); + self.stats.evictions += 1; + return index; + } + unreachable; + } + + fn release(self: *DnsCache, index: u32) void { + const slot = &self.slots[index]; + std.debug.assert(slot.occupied); + const removed = self.index.remove(slot.keySlice()); + std.debug.assert(removed); + self.gpa.free(slot.bytes); + slot.bytes = &.{}; + slot.key_len = 0; + slot.occupied = false; + slot.referenced = false; + self.occupied -= 1; + } +}; + +const testing = std.testing; + +/// NXDOMAIN for example.com A with one authority SOA whose MINIMUM is 600 and +/// whose record TTL is 3600, so the two are never confused. +const nxdomain_bytes = + "\x00\x01\x81\x83\x00\x01\x00\x00\x00\x01\x00\x00" ++ + "\x07example\x03com\x00\x00\x01\x00\x01" ++ + "\xc0\x0c\x00\x06\x00\x01\x00\x00\x0e\x10\x00\x16" ++ + "\x00\x00" ++ // root MNAME, root RNAME + "\x00\x00\x00\x01\x00\x00\x1c\x20\x00\x00\x0e\x10\x00\x36\xee\x80\x00\x00\x02\x58"; + +/// The same message with rcode NOERROR: an empty answer section, which RFC 2308 +/// §2 calls NODATA and caches negatively too. +const nodata_bytes = + "\x00\x01\x81\x80\x00\x01\x00\x00\x00\x01\x00\x00" ++ + nxdomain_bytes[12..]; + +/// SERVFAIL with nothing else in it. +const servfail_bytes = "\x00\x01\x81\x82\x00\x01\x00\x00\x00\x00\x00\x00" ++ + "\x07example\x03com\x00\x00\x01\x00\x01"; + +/// Builds a NOERROR response for example.com A carrying `ttls.len` answers. +fn buildAnswer(buf: []u8, ttls: []const u32) ![]u8 { + const query = "\x12\x34\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00" ++ + "\x07example\x03com\x00\x00\x01\x00\x01"; + const request = try packet.parse(query); + const q = packet.firstQuestion(request).?; + + var builder = try packet.ResponseBuilder.init(buf, request.header, q); + for (ttls) |ttl| { + try builder.addAnswer(q.name, .a, .in, ttl, "\x0a\x00\x00\x01"); + } + return builder.finish(); +} + +fn firstAuthoritySoaTtl(bytes: []const u8) !u32 { + const p = try packet.parse(bytes); + var it = packet.authorities(p); + while (try it.next()) |rec| { + if (rec.rtype == .soa) return rec.ttl; + } + return error.NoSoaRecord; +} + +fn answerTtls(bytes: []const u8, out: []u32) ![]u32 { + const p = try packet.parse(bytes); + var it = packet.answers(p); + var count: usize = 0; + while (try it.next()) |rec| { + out[count] = rec.ttl; + count += 1; + } + return out[0..count]; +} + +fn firstAnswerTtl(bytes: []const u8) !u32 { + const p = try packet.parse(bytes); + var it = packet.answers(p); + return (try it.next()).?.ttl; +} + +test "buildKey lowercases the name and strips one trailing dot" { + var upper_buf: [max_key_len]u8 = undefined; + var lower_buf: [max_key_len]u8 = undefined; + const upper = buildKey(&upper_buf, "EXAMPLE.CoM.", 1, 1, false, null); + const lower = buildKey(&lower_buf, "example.com", 1, 1, false, null); + try testing.expectEqualSlices(u8, lower, upper); + try testing.expectEqualStrings("example.com", upper[0..11]); + try testing.expectEqual(@as(u8, 0), upper[11]); + try testing.expectEqual(@as(usize, 11 + 1 + 2 + 2 + 1 + 1), upper.len); + + // Only one dot goes: "a.." is a different name from "a.". + var two_dots: [max_key_len]u8 = undefined; + const key = buildKey(&two_dots, "example.com..", 1, 1, false, null); + try testing.expectEqualStrings("example.com.", key[0..12]); +} + +test "buildKey separates every question component" { + var buf_a: [max_key_len]u8 = undefined; + var buf_b: [max_key_len]u8 = undefined; + const base = buildKey(&buf_a, "example.com", 1, 1, false, null); + + const variants = [_][]const u8{ + buildKey(&buf_b, "example.com", 28, 1, false, null), + buildKey(&buf_b, "example.com", 1, 3, false, null), + buildKey(&buf_b, "example.com", 1, 1, true, null), + buildKey(&buf_b, "example.org", 1, 1, false, null), + }; + for (variants) |variant| { + try testing.expect(!std.mem.eql(u8, base, variant)); + } + + // A repeated build of the same question is byte-identical. + try testing.expectEqualSlices(u8, base, buildKey(&buf_b, "example.com", 1, 1, false, null)); +} + +test "buildKey distinguishes absent, empty and present ECS" { + var buf_a: [max_key_len]u8 = undefined; + var buf_b: [max_key_len]u8 = undefined; + var buf_c: [max_key_len]u8 = undefined; + + const absent = buildKey(&buf_a, "example.com", 1, 1, false, null); + const present = buildKey(&buf_b, "example.com", 1, 1, false, "\x0a\x00\x01"); + const other = buildKey(&buf_c, "example.com", 1, 1, false, "\x0a\x00\x02"); + + try testing.expect(!std.mem.eql(u8, absent, present)); + try testing.expect(!std.mem.eql(u8, present, other)); + try testing.expectEqual(absent.len + 3, present.len); + + // An empty ECS slice keys the same as no ECS: both mean no subnet. + var buf_d: [max_key_len]u8 = undefined; + try testing.expectEqualSlices(u8, absent, buildKey(&buf_d, "example.com", 1, 1, false, "")); +} + +test "classify takes the smallest ttl of a positive answer" { + var buf: [512]u8 = undefined; + const response = try buildAnswer(&buf, &.{ 300, 60, 900 }); + const class = classify(response, 3600).?; + try testing.expectEqual(@as(u32, 60), class.ttl_seconds); + try testing.expectEqual(false, class.negative); +} + +test "classify caps a positive ttl at the sanity ceiling" { + var buf: [512]u8 = undefined; + const response = try buildAnswer(&buf, &.{ 1_000_000, 2_000_000 }); + const class = classify(response, 3600).?; + try testing.expectEqual(max_ttl_seconds, class.ttl_seconds); +} + +test "classify refuses a zero ttl and unparsable bytes" { + var buf: [512]u8 = undefined; + const response = try buildAnswer(&buf, &.{ 300, 0 }); + try testing.expectEqual(@as(?Class, null), classify(response, 3600)); + + try testing.expectEqual(@as(?Class, null), classify("\x00\x01\x81", 3600)); + try testing.expectEqual(@as(?Class, null), classify(response[0 .. response.len - 1], 3600)); +} + +test "classify caches NXDOMAIN with the SOA minimum" { + const class = classify(nxdomain_bytes, 3600).?; + try testing.expectEqual(@as(u32, 600), class.ttl_seconds); + try testing.expectEqual(true, class.negative); +} + +test "classify caps a negative ttl at negative_ttl_max" { + const class = classify(nxdomain_bytes, 120).?; + try testing.expectEqual(@as(u32, 120), class.ttl_seconds); + try testing.expectEqual(true, class.negative); +} + +test "negative_ttl_max of zero disables negative caching" { + try testing.expectEqual(@as(?Class, null), classify(nxdomain_bytes, 0)); + try testing.expectEqual(@as(?Class, null), classify(nodata_bytes, 0)); + + // The switch is negative-only: a positive answer still caches. + var buf: [512]u8 = undefined; + const response = try buildAnswer(&buf, &.{60}); + try testing.expectEqual(@as(u32, 60), classify(response, 0).?.ttl_seconds); +} + +/// The SOA record's TTL starts after the 12-byte header, the 17-byte question, +/// and the record's compressed name, type and class. MINIMUM is the last field +/// of the RDATA, which ends the message. +const nxdomain_soa_ttl_offset = 12 + 17 + 2 + 2 + 2; +const nxdomain_soa_minimum_offset = nxdomain_bytes.len - 4; + +fn nxdomainWithSoaTtls( + buf: *[nxdomain_bytes.len]u8, + record_ttl: u32, + minimum: u32, +) []const u8 { + @memcpy(buf, nxdomain_bytes); + std.mem.writeInt(u32, buf[nxdomain_soa_ttl_offset..][0..4], record_ttl, .big); + std.mem.writeInt(u32, buf[nxdomain_soa_minimum_offset..][0..4], minimum, .big); + return buf; +} + +test "classify takes the smaller of the SOA record ttl and MINIMUM" { + var buf: [nxdomain_bytes.len]u8 = undefined; + + // The rewrite reproduces the fixture when it writes the fixture's values. + try testing.expectEqual( + @as(u32, 600), + classify(nxdomainWithSoaTtls(&buf, 3600, 600), 3600).?.ttl_seconds, + ); + + // RFC 2308 §5: the record TTL bounds the negative lifetime too. + try testing.expectEqual( + @as(u32, 120), + classify(nxdomainWithSoaTtls(&buf, 120, 600), 3600).?.ttl_seconds, + ); + try testing.expectEqual( + @as(u32, 300), + classify(nxdomainWithSoaTtls(&buf, 3600, 300), 3600).?.ttl_seconds, + ); + + // negative_ttl_max still caps whichever of the two won. + try testing.expectEqual( + @as(u32, 60), + classify(nxdomainWithSoaTtls(&buf, 120, 600), 60).?.ttl_seconds, + ); + + // A zero in either field means do not cache. + try testing.expectEqual(@as(?Class, null), classify(nxdomainWithSoaTtls(&buf, 0, 600), 3600)); + try testing.expectEqual(@as(?Class, null), classify(nxdomainWithSoaTtls(&buf, 3600, 0), 3600)); +} + +test "classify refuses an answer ttl with the top bit set" { + // RFC 2181 §8 reads such a TTL as zero, and a zero TTL is not cached. + var buf: [512]u8 = undefined; + try testing.expectEqual( + @as(?Class, null), + classify(try buildAnswer(&buf, &.{0x8000_0001}), 3600), + ); + try testing.expectEqual( + @as(?Class, null), + classify(try buildAnswer(&buf, &.{0xffff_ffff}), 3600), + ); + + // One poisoned record spoils the message even beside an ordinary TTL. + try testing.expectEqual( + @as(?Class, null), + classify(try buildAnswer(&buf, &.{ 300, 0x8000_0000 }), 3600), + ); +} + +test "classify refuses an SOA ttl or MINIMUM with the top bit set" { + var buf: [nxdomain_bytes.len]u8 = undefined; + try testing.expectEqual( + @as(?Class, null), + classify(nxdomainWithSoaTtls(&buf, 0x8000_0001, 600), 3600), + ); + try testing.expectEqual( + @as(?Class, null), + classify(nxdomainWithSoaTtls(&buf, 3600, 0x8000_0001), 3600), + ); +} + +test "classify treats an empty NOERROR answer as negative and needs an SOA" { + const class = classify(nodata_bytes, 3600).?; + try testing.expectEqual(@as(u32, 600), class.ttl_seconds); + try testing.expectEqual(true, class.negative); + + // The same NODATA without the authority section caches nothing. + const no_soa = "\x00\x01\x81\x80\x00\x01\x00\x00\x00\x00\x00\x00" ++ + "\x07example\x03com\x00\x00\x01\x00\x01"; + try testing.expectEqual(@as(?Class, null), classify(no_soa, 3600)); +} + +test "classify refuses every other rcode" { + try testing.expectEqual(@as(?Class, null), classify(servfail_bytes, 3600)); + + // REFUSED, with an SOA present, is still not cacheable. + var refused = nxdomain_bytes.*; + refused[3] = 0x85; + try testing.expectEqual(@as(?Class, null), classify(&refused, 3600)); +} + +test "put and get round-trip a response with aged ttls" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 8, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{300}); + const class = classify(response, 3600).?; + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + + try cache.put(1000, key, response, class); + try testing.expectEqual(@as(u32, 1), cache.len()); + + var out: [512]u8 = undefined; + const hit = cache.get(1030, key, &out).?; + try testing.expectEqual(response.len, hit.len); + try testing.expectEqual(@as(u32, 270), try firstAnswerTtl(hit)); + try testing.expectEqual(@as(u64, 1), cache.stats.hits); + + // The stored copy is untouched, so a later hit ages from the same base. + const second = cache.get(1100, key, &out).?; + try testing.expectEqual(@as(u32, 200), try firstAnswerTtl(second)); + + // A key that was never stored is a miss. + var other_buf: [max_key_len]u8 = undefined; + const other = buildKey(&other_buf, "example.org", 1, 1, false, null); + try testing.expectEqual(@as(?[]u8, null), cache.get(1030, other, &out)); + try testing.expectEqual(@as(u64, 1), cache.stats.misses); +} + +test "a cached positive response caps its stored ttls at the sanity ceiling" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{ 1_000_000, 300 }); + const class = classify(response, 3600).?; + try testing.expectEqual(@as(u32, 300), class.ttl_seconds); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(1000, key, response, class); + + // The over-ceiling record comes back at the ceiling; its shorter sibling is + // untouched, because a downstream cache holds each record for its own TTL. + var out: [512]u8 = undefined; + var ttls: [4]u32 = undefined; + try testing.expectEqualSlices( + u32, + &.{ max_ttl_seconds, 300 }, + try answerTtls(cache.get(1000, key, &out).?, &ttls), + ); + + // Only the cache's clone is rewritten; the caller's bytes are untouched. + try testing.expectEqualSlices(u32, &.{ 1_000_000, 300 }, try answerTtls(response, &ttls)); +} + +test "a positive response under the ceiling is stored byte for byte" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{ max_ttl_seconds, 300 }); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(1000, key, response, classify(response, 3600).?); + + // A TTL exactly at the ceiling is not rewritten, so a hit at elapsed zero + // returns the caller's bytes unchanged. + var out: [512]u8 = undefined; + try testing.expectEqualSlices(u8, response, cache.get(1000, key, &out).?); +} + +test "a cached negative response serves the SOA ttl the entry expires at" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + // The fixture's SOA record TTL is 3600 and its MINIMUM is 600, so the entry + // outlives its own SOA TTL unless `put` rewrites the clone. + try testing.expectEqual(@as(u32, 3600), try firstAuthoritySoaTtl(nxdomain_bytes)); + const class = classify(nxdomain_bytes, 3600).?; + try testing.expectEqual(@as(u32, 600), class.ttl_seconds); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(1000, key, nxdomain_bytes, class); + + var out: [512]u8 = undefined; + const fresh = cache.get(1000, key, &out).?; + try testing.expectEqual(@as(u32, 600), try firstAuthoritySoaTtl(fresh)); + + // The clamped TTL then ages with the entry and runs out as the entry does. + const later = cache.get(1500, key, &out).?; + try testing.expectEqual(@as(u32, 100), try firstAuthoritySoaTtl(later)); + try testing.expectEqual(@as(?[]u8, null), cache.get(1600, key, &out)); + + // Only the cache's clone is rewritten; the caller's bytes are untouched. + try testing.expectEqual(@as(u32, 3600), try firstAuthoritySoaTtl(nxdomain_bytes)); +} + +test "the stored SOA ttl follows negative_ttl_max and is never raised" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 120 }); + defer cache.deinit(); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + var out: [512]u8 = undefined; + + try cache.put(0, key, nxdomain_bytes, classify(nxdomain_bytes, 120).?); + try testing.expectEqual(@as(u32, 120), try firstAuthoritySoaTtl(cache.get(0, key, &out).?)); + + // An SOA record TTL already below the entry's lifetime keeps its own value. + var short_buf: [nxdomain_bytes.len]u8 = undefined; + const short = nxdomainWithSoaTtls(&short_buf, 60, 600); + try cache.put(0, key, short, classify(short, 3600).?); + try testing.expectEqual(@as(u32, 60), try firstAuthoritySoaTtl(cache.get(0, key, &out).?)); + + // A positive response has no SOA to clamp and keeps every answer TTL. + var answer_buf: [512]u8 = undefined; + const answer = try buildAnswer(&answer_buf, &.{ 300, 900 }); + try cache.put(0, key, answer, classify(answer, 3600).?); + try testing.expectEqual(@as(u32, 300), try firstAnswerTtl(cache.get(0, key, &out).?)); +} + +test "an out buffer too small for the response is a miss" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{300}); + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(0, key, response, classify(response, 3600).?); + + var small: [8]u8 = undefined; + try testing.expectEqual(@as(?[]u8, null), cache.get(0, key, &small)); + try testing.expectEqual(@as(u64, 1), cache.stats.misses); + // The entry survives a short buffer. + try testing.expectEqual(@as(u32, 1), cache.len()); +} + +test "an expired entry is a miss and is freed on access" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{60}); + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(1000, key, response, classify(response, 3600).?); + + var out: [512]u8 = undefined; + try testing.expect(cache.get(1059, key, &out) != null); + // The entry expires at stored_at + ttl, and that second is already too late. + try testing.expectEqual(@as(?[]u8, null), cache.get(1060, key, &out)); + try testing.expectEqual(@as(u32, 0), cache.len()); + try testing.expectEqual(@as(u64, 1), cache.stats.expirations); + try testing.expectEqual(@as(u64, 1), cache.stats.misses); +} + +test "aging that breaks the packet drops the entry once" { + // The first record's TTL is 82 176, whose last three bytes read as the name + // "A." at offset 18, and the second record's owner name points there: + // ageing that TTL by one second leaves 0xff where the name ended, which is + // an out-of-range compression pointer. packet.zig covers the same case with + // a larger TTL; this one stays under `max_ttl_seconds` so that `put` stores + // it verbatim and only the ageing inside `get` breaks it. + const poisoned = "\x00\x01\x81\x80\x00\x00\x00\x02\x00\x00\x00\x00" ++ + "\x00\x00\x01\x00\x01\x00\x01\x41\x00\x00\x04\x01\x02\x03\x04" ++ + "\xc0\x12\x00\x01\x00\x01\x00\x00\x00\x64\x00\x04\x05\x06\x07\x08"; + + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(0, key, poisoned, classify(poisoned, 3600).?); + + var out: [512]u8 = undefined; + try testing.expectEqual(@as(?[]u8, null), cache.get(1, key, &out)); + try testing.expectEqual(@as(u64, 1), cache.stats.invalid_hits); + try testing.expectEqual(@as(u64, 0), cache.stats.hits); + try testing.expectEqual(@as(u32, 0), cache.len()); +} + +test "CLOCK evicts the unreferenced entry and keeps the referenced one" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 2, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{3600}); + const class = classify(response, 3600).?; + + var buf_a: [max_key_len]u8 = undefined; + var buf_b: [max_key_len]u8 = undefined; + var buf_c: [max_key_len]u8 = undefined; + const a = buildKey(&buf_a, "a.example.com", 1, 1, false, null); + const b = buildKey(&buf_b, "b.example.com", 1, 1, false, null); + const c = buildKey(&buf_c, "c.example.com", 1, 1, false, null); + + try cache.put(0, a, response, class); + try cache.put(0, b, response, class); + + var out: [512]u8 = undefined; + try testing.expect(cache.get(0, a, &out) != null); + + try cache.put(0, c, response, class); + try testing.expectEqual(@as(u32, 2), cache.len()); + try testing.expectEqual(@as(u64, 1), cache.stats.evictions); + try testing.expect(cache.get(0, a, &out) != null); + try testing.expect(cache.get(0, c, &out) != null); + try testing.expectEqual(@as(?[]u8, null), cache.get(0, b, &out)); +} + +test "replacing a key in place does not grow the cache" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var first_buf: [512]u8 = undefined; + var second_buf: [512]u8 = undefined; + const first = try buildAnswer(&first_buf, &.{300}); + const second = try buildAnswer(&second_buf, &.{ 900, 900 }); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + + try cache.put(1000, key, first, classify(first, 3600).?); + try cache.put(2000, key, second, classify(second, 3600).?); + + try testing.expectEqual(@as(u32, 1), cache.len()); + try testing.expectEqual(@as(u64, 2), cache.stats.inserts); + try testing.expectEqual(@as(u64, 0), cache.stats.evictions); + + // The second response replaced the first, and its age counts from 2000. + var out: [512]u8 = undefined; + const hit = cache.get(2100, key, &out).?; + try testing.expectEqual(second.len, hit.len); + try testing.expectEqual(@as(u32, 800), try firstAnswerTtl(hit)); +} + +test "sweep removes only the expired entries" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 8, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var short_buf: [512]u8 = undefined; + var long_buf: [512]u8 = undefined; + const short = try buildAnswer(&short_buf, &.{60}); + const long = try buildAnswer(&long_buf, &.{3600}); + + var buf_a: [max_key_len]u8 = undefined; + var buf_b: [max_key_len]u8 = undefined; + const a = buildKey(&buf_a, "short.example.com", 1, 1, false, null); + const b = buildKey(&buf_b, "long.example.com", 1, 1, false, null); + + try cache.put(0, a, short, classify(short, 3600).?); + try cache.put(0, b, long, classify(long, 3600).?); + + try testing.expectEqual(@as(u32, 0), cache.sweep(59)); + try testing.expectEqual(@as(u32, 2), cache.len()); + + try testing.expectEqual(@as(u32, 1), cache.sweep(60)); + try testing.expectEqual(@as(u32, 1), cache.len()); + try testing.expectEqual(@as(u64, 1), cache.stats.expirations); + + var out: [512]u8 = undefined; + try testing.expect(cache.get(60, b, &out) != null); + // The survivor expires at stored_at + 3600, so that second sweeps it too. + try testing.expectEqual(@as(u32, 1), cache.sweep(3600)); + try testing.expectEqual(@as(u32, 0), cache.len()); + try testing.expectEqual(@as(u64, 2), cache.stats.expirations); +} + +test "a slot freed by eviction is reusable many times over" { + // The index deletes and reinserts on every eviction; this fails loudly if + // deletion ever stopped returning capacity to it. + var cache = try DnsCache.init(testing.allocator, .{ .size = 2, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{3600}); + const class = classify(response, 3600).?; + + var name_buf: [64]u8 = undefined; + var key_buf: [max_key_len]u8 = undefined; + for (0..500) |i| { + const qname = try std.fmt.bufPrint(&name_buf, "host{d}.example.com", .{i}); + try cache.put(0, buildKey(&key_buf, qname, 1, 1, false, null), response, class); + try testing.expect(cache.len() <= 2); + } + try testing.expectEqual(@as(u32, 2), cache.len()); + try testing.expectEqual(@as(u64, 498), cache.stats.evictions); +} + +test "a cache of zero entries stores nothing" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 0, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{300}); + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + + try cache.put(0, key, response, classify(response, 3600).?); + try testing.expectEqual(@as(u32, 0), cache.len()); + + var out: [512]u8 = undefined; + try testing.expectEqual(@as(?[]u8, null), cache.get(0, key, &out)); +} + +test "memoryBytes covers the slots, the responses and the index" { + var cache = try DnsCache.init(testing.allocator, .{ .size = 4, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + const empty_bytes = cache.memoryBytes(); + try testing.expect(empty_bytes >= 4 * @sizeOf(Slot)); + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{300}); + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(0, key, response, classify(response, 3600).?); + + try testing.expectEqual(empty_bytes + response.len, cache.memoryBytes()); +} + +fn initAndPut(gpa: Allocator, response: []const u8) !void { + var cache = try DnsCache.init(gpa, .{ .size = 16, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var key_buf: [max_key_len]u8 = undefined; + const key = buildKey(&key_buf, "example.com", 1, 1, false, null); + try cache.put(0, key, response, classify(response, 3600).?); + try cache.put(0, key, response, classify(response, 3600).?); +} + +test "init and put survive every allocation failure" { + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{300}); + try testing.checkAllAllocationFailures(testing.allocator, initAndPut, .{response}); +} diff --git a/src/main.zig b/src/main.zig index 8a2ba3b..afde3d7 100644 --- a/src/main.zig +++ b/src/main.zig @@ -4,6 +4,12 @@ const std = @import("std"); const cli = @import("cli.zig"); +const logging = @import("platform/logging.zig"); + +/// Routes every `std.log` call through the sink. Before `logging.install` +/// runs (and always under the test runner, which never installs), the sink +/// passes through to the stderr default. +pub const std_options: std.Options = .{ .logFn = logging.logFn }; // `src/tests.zig` imports this file, and this is how `cli.zig`'s tests reach // the same runner. `src/tests.zig` is the orchestrator's file, not this diff --git a/src/platform/logging.zig b/src/platform/logging.zig new file mode 100644 index 0000000..20ea8dd --- /dev/null +++ b/src/platform/logging.zig @@ -0,0 +1,945 @@ +//! The `std.log` sink: runtime level filter, stderr or rotating-file output, +//! and upstream-error deduplication (PLAN §11.6). +//! +//! ## The sink lock +//! +//! `std.Options.logFn` (std.zig:132) receives no `std.Io`, so the sink cannot +//! guard itself with `std.Io.Mutex`: both `lock` and `unlock` (Io.zig:1602, +//! Io.zig:1640) take an `Io` parameter, and before `install` the sink holds +//! none. `std.Thread.Mutex` is not an option either — 0.16.0 has no +//! `lib/std/Thread/` directory and `lib/std/Thread.zig` declares no `Mutex`. +//! +//! The sink therefore takes the lock `std.log.defaultLog` itself takes +//! (log.zig:96-109): `std.debug.lockStderr` / `std.debug.unlockStderr`. Those +//! need no `Io` because they read `std.Options.debug_io` (debug.zig:283), they +//! are documented as recursive (debug.zig:263-270), and `Io/Threaded.zig` +//! implements that recursion per OS thread (Threaded.zig:13787-13796). nxdns +//! runs a `std.Io.Threaded` instance (cli.zig:793), so one task is one thread +//! and the recursion holds. Taking it across the file writes as well keeps the +//! file path and the stderr fallback path from interleaving with each other, +//! with `std.Progress`, or with a panic dump. +//! +//! Every `state` field below is read and written only while that lock is held. +//! +//! Nothing in this file may call `std.log`: this file is what `std.log` calls, +//! and a log line emitted from the sink would recurse. + +const std = @import("std"); +const model = @import("../config/model.zig"); + +/// Two upstream failures with the same key inside this window produce one line. +pub const dedup_window_ns: i96 = 60 * std.time.ns_per_s; +pub const dedup_slots = 64; +pub const max_message_key_bytes = 96; +pub const max_scope_name_bytes = 32; +pub const max_dedup_key_bytes = max_scope_name_bytes + 1 + max_message_key_bytes; + +/// A formatted message longer than this is truncated rather than dropped: a +/// log line must never be a hard failure. +pub const max_message_bytes = 2048; + +/// `writeEscaped` expands one byte to at most four (`\xNN`). +pub const max_escaped_message_bytes = max_message_bytes * 4; + +/// The widest possible file record header and terminator: +/// `-9223372036854775808` + ` ` + `warning` + `(` + a bounded scope name + +/// `)` + `: ` + `\n`. A scope name is bounded by `boundedScopeName`, so a +/// record can never outgrow a buffer of this size plus the escaped message. +pub const max_line_header_bytes = 20 + 1 + 7 + 1 + max_scope_name_bytes + 1 + 2 + 1; + +/// Room for the longest configured path plus the `".255"` rotation suffix. +pub const max_rotated_path_bytes = std.Io.Dir.max_path_bytes + 4; + +pub const Stats = struct { + lines_written: u64 = 0, + lines_deduped: u64 = 0, + rotations: u64 = 0, + sink_errors: u64 = 0, +}; + +// --------------------------------------------------------------------------- +// Level +// --------------------------------------------------------------------------- + +pub fn toStdLevel(level: model.LogLevel) std.log.Level { + return switch (level) { + .err => .err, + .warn => .warn, + .info => .info, + .debug => .debug, + }; +} + +/// `std.log.Level` orders the most severe tag first, so a message passes when +/// its ordinal is at or below the configured threshold's. +pub fn enabled(message_level: std.log.Level, threshold: std.log.Level) bool { + return @intFromEnum(message_level) <= @intFromEnum(threshold); +} + +/// `std.log.Level.asText` takes its level `comptime`; the sink filters at +/// runtime and needs the same strings. +fn levelText(level: std.log.Level) []const u8 { + return switch (level) { + .err => "error", + .warn => "warning", + .info => "info", + .debug => "debug", + }; +} + +/// A scope name reaches the record header, which shares one fixed buffer with +/// the message. Nothing bounds the name of a scope outside the deduplicated +/// four, so the sink bounds it here and both output paths use the result: one +/// event reads the same on stderr as in the file. +pub fn boundedScopeName(scope_name: []const u8) []const u8 { + return scope_name[0..@min(scope_name.len, max_scope_name_bytes)]; +} + +// --------------------------------------------------------------------------- +// Deduplication +// --------------------------------------------------------------------------- + +/// PLAN §11.6 rate-limits exactly the scopes whose failures repeat once per +/// query; every other scope logs unconditionally. +pub fn isDedupScope(comptime scope: @EnumLiteral()) bool { + return scope == .doh_client or scope == .dot_client or + scope == .pool or scope == .forward_client; +} + +pub fn buildKey( + buf: *[max_dedup_key_bytes]u8, + scope_name: []const u8, + message: []const u8, +) []const u8 { + const scope_len = @min(scope_name.len, max_scope_name_bytes); + @memcpy(buf[0..scope_len], scope_name[0..scope_len]); + buf[scope_len] = 0; + const message_len = @min(message.len, max_message_key_bytes); + @memcpy(buf[scope_len + 1 ..][0..message_len], message[0..message_len]); + return buf[0 .. scope_len + 1 + message_len]; +} + +/// Fixed-size and allocation-free: the sink runs inside `logFn`, which has no +/// allocator and must not fail. +pub const DedupTable = struct { + entries: [dedup_slots]Entry = @splat(.{}), + + const Entry = struct { + key: [max_dedup_key_bytes]u8 = undefined, + key_len: u8 = 0, + stamp_ns: i96 = 0, + occupied: bool = false, + }; + + /// True means emit the line. A key seen less than `dedup_window_ns` ago is + /// dropped; a key that is new to a full table replaces the entry with the + /// oldest stamp. `now` is an `.awake` timestamp. + pub fn admit(self: *DedupTable, now: std.Io.Timestamp, key: []const u8) bool { + std.debug.assert(key.len <= max_dedup_key_bytes); + var free_slot: ?usize = null; + var oldest: ?usize = null; + for (&self.entries, 0..) |*entry, i| { + if (!entry.occupied) { + if (free_slot == null) free_slot = i; + continue; + } + if (std.mem.eql(u8, entry.key[0..entry.key_len], key)) { + if (now.nanoseconds - entry.stamp_ns < dedup_window_ns) return false; + entry.stamp_ns = now.nanoseconds; + return true; + } + if (oldest == null or entry.stamp_ns < self.entries[oldest.?].stamp_ns) oldest = i; + } + const slot = free_slot orelse oldest.?; + const entry = &self.entries[slot]; + @memcpy(entry.key[0..key.len], key); + entry.key_len = @intCast(key.len); + entry.stamp_ns = now.nanoseconds; + entry.occupied = true; + return true; + } +}; + +// --------------------------------------------------------------------------- +// Rotation naming +// --------------------------------------------------------------------------- + +/// `nxdns.log` plus generation `n` is `nxdns.log.n`. +pub fn rotatedName(buf: []u8, path: []const u8, n: u8) error{NameTooLong}![]const u8 { + var w: std.Io.Writer = .fixed(buf); + w.print("{s}.{d}", .{ path, n }) catch return error.NameTooLong; + return w.buffered(); +} + +// --------------------------------------------------------------------------- +// Sink state +// --------------------------------------------------------------------------- + +const State = struct { + installed: bool = false, + io: std.Io = undefined, + threshold: std.log.Level = .info, + output: model.LogOutput = .stderr, + path_buf: [std.Io.Dir.max_path_bytes]u8 = undefined, + path_len: usize = 0, + max_files: u8 = 0, + max_bytes: u64 = 0, + file: ?std.Io.File = null, + file_pos: u64 = 0, + /// A rotation step failed. The live file stays closed until a later line + /// completes the rotation: reopening it would append past `max_bytes`. + rotate_pending: bool = false, + dedup: DedupTable = .{}, + stats: Stats = .{}, + + fn path(self: *const State) []const u8 { + return self.path_buf[0..self.path_len]; + } +}; + +var state: State = .{}; + +/// Called once from `main` after the config parse. Never called by tests: a +/// sink installed under the test runner would swallow the harness's own logs. +pub fn install(io: std.Io, cfg: model.Logging) void { + installWithMaxBytes(io, cfg, model.maxLogBytes(cfg)); +} + +/// Test-only entry point. `install`'s smallest possible `max_size_mb` is 1 MiB, +/// which would make the integration rotation case write a megabyte per +/// generation; this overrides only that threshold. +pub fn installForTest(io: std.Io, cfg: model.Logging, max_bytes_override: u64) void { + installWithMaxBytes(io, cfg, max_bytes_override); +} + +fn installWithMaxBytes(io: std.Io, cfg: model.Logging, max_bytes: u64) void { + var stderr_buf: [64]u8 = undefined; + _ = std.debug.lockStderr(&stderr_buf); + defer std.debug.unlockStderr(); + + closeFileLocked(); + state.io = io; + state.threshold = toStdLevel(cfg.level); + state.max_files = cfg.max_files; + state.max_bytes = max_bytes; + state.dedup = .{}; + state.rotate_pending = false; + state.installed = true; + + if (cfg.file_path.len > state.path_buf.len) { + // A path that cannot be stored whole would name a different file. + state.path_len = 0; + state.output = .stderr; + state.stats.sink_errors += 1; + return; + } + state.path_len = cfg.file_path.len; + @memcpy(state.path_buf[0..state.path_len], cfg.file_path); + state.output = cfg.output; + if (state.output == .file) openFileLocked(); +} + +/// Flushes and closes the file, and restores pass-through stderr formatting. +pub fn deinstall() void { + var stderr_buf: [64]u8 = undefined; + _ = std.debug.lockStderr(&stderr_buf); + defer std.debug.unlockStderr(); + + closeFileLocked(); + state.installed = false; + state.output = .stderr; + state.path_len = 0; + state.rotate_pending = false; +} + +pub fn stats() Stats { + var stderr_buf: [64]u8 = undefined; + _ = std.debug.lockStderr(&stderr_buf); + defer std.debug.unlockStderr(); + + return state.stats; +} + +// --------------------------------------------------------------------------- +// logFn +// --------------------------------------------------------------------------- + +/// Matches the `std.Options.logFn` field type verified at std.zig:132-137. +pub fn logFn( + comptime message_level: std.log.Level, + comptime scope: @EnumLiteral(), + comptime format: []const u8, + args: anytype, +) void { + var stderr_buf: [512]u8 = undefined; + const locked = std.debug.lockStderr(&stderr_buf); + defer std.debug.unlockStderr(); + + if (!state.installed) { + // The lock is recursive, so `defaultLog` taking it again is sound. + return std.log.defaultLog(message_level, scope, format, args); + } + if (!enabled(message_level, state.threshold)) return; + + var message_buf: [max_message_bytes]u8 = undefined; + var mw: std.Io.Writer = .fixed(&message_buf); + mw.print(format, args) catch {}; + const message = mw.buffered(); + + if (comptime isDedupScope(scope) and enabled(message_level, .warn)) { + comptime std.debug.assert(@tagName(scope).len <= max_scope_name_bytes); + var key_buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&key_buf, @tagName(scope), message); + if (!state.dedup.admit(std.Io.Clock.awake.now(state.io), key)) { + state.stats.lines_deduped += 1; + return; + } + } + + const scope_name = comptime boundedScopeName(@tagName(scope)); + const is_default = scope == .default; + const emitted = switch (state.output) { + // systemd captures stderr into the journal, which is what `syslog` + // means for the only supported deployment. + .stderr, .syslog => writeTerminalLocked( + locked, + message_level, + scope_name, + is_default, + message, + ), + .file => emitFileLocked(locked, message_level, scope_name, is_default, message), + }; + if (emitted) state.stats.lines_written += 1; +} + +/// A line reaches an operator or it counts as a sink error; it is never both +/// discarded and silent. Each failed write attempt counts once, so a line that +/// fails on the file and again on the stderr fallback counts twice. +fn writeTerminalLocked( + locked: std.Io.LockedStderr, + level: std.log.Level, + scope_name: []const u8, + is_default: bool, + message: []const u8, +) bool { + writeTerminal(locked.terminal(), level, scope_name, is_default, message) catch { + state.stats.sink_errors += 1; + return false; + }; + return true; +} + +/// A formatted message can carry bytes chosen by someone else: a query name, an +/// upstream error string. A raw newline in one would forge a second timestamped +/// record, and other control bytes reach a terminal verbatim. `std.log`'s own +/// `defaultLog` (log.zig:132) writes the message raw; this sink escapes on both +/// paths instead, because operators and journald parse its lines. +/// +/// `\n`, `\r`, `\t` and `\\` become their two-character C escapes; every other +/// byte below 0x20, and DEL, becomes `\xNN`. +fn writeEscaped(w: *std.Io.Writer, message: []const u8) std.Io.Writer.Error!void { + const hex = "0123456789abcdef"; + var plain_start: usize = 0; + for (message, 0..) |byte, i| { + var hex_buf: [4]u8 = undefined; + const escape: []const u8 = switch (byte) { + '\\' => "\\\\", + '\n' => "\\n", + '\r' => "\\r", + '\t' => "\\t", + 0x00...0x08, 0x0b, 0x0c, 0x0e...0x1f, 0x7f => blk: { + hex_buf = .{ '\\', 'x', hex[byte >> 4], hex[byte & 0x0f] }; + break :blk &hex_buf; + }, + else => continue, + }; + try w.writeAll(message[plain_start..i]); + try w.writeAll(escape); + plain_start = i + 1; + } + try w.writeAll(message[plain_start..]); +} + +fn writeTerminal( + t: std.Io.Terminal, + level: std.log.Level, + scope_name: []const u8, + is_default: bool, + message: []const u8, +) std.Io.Writer.Error!void { + t.setColor(switch (level) { + .err => .red, + .warn => .yellow, + .info => .green, + .debug => .magenta, + }) catch {}; + t.setColor(.bold) catch {}; + try t.writer.writeAll(levelText(level)); + t.setColor(.reset) catch {}; + t.setColor(.dim) catch {}; + t.setColor(.bold) catch {}; + if (!is_default) { + try t.writer.writeAll("("); + try t.writer.writeAll(scope_name); + try t.writer.writeAll(")"); + } + try t.writer.writeAll(": "); + t.setColor(.reset) catch {}; + try writeEscaped(t.writer, message); + try t.writer.writeAll("\n"); +} + +fn emitFileLocked( + locked: std.Io.LockedStderr, + level: std.log.Level, + scope_name: []const u8, + is_default: bool, + message: []const u8, +) bool { + // Sized for the longest possible record: an all-`\xNN` message plus the + // widest header. + var line_buf: [max_escaped_message_bytes + max_line_header_bytes]u8 = undefined; + const line = buildLine( + &line_buf, + std.Io.Clock.real.now(state.io).toSeconds(), + level, + scope_name, + is_default, + message, + ) catch { + state.stats.sink_errors += 1; + return writeTerminalLocked(locked, level, scope_name, is_default, message); + }; + + if (!prepareFileLocked(line.len)) { + return writeTerminalLocked(locked, level, scope_name, is_default, message); + } + const file = state.file.?; + writeLineLocked(file, line) catch { + // Closing makes the next line reopen: a sink that gave up on the file + // after one failure would silently stop logging. + state.stats.sink_errors += 1; + closeFileLocked(); + return writeTerminalLocked(locked, level, scope_name, is_default, message); + }; + return true; +} + +/// A record is ` (): \n`. +/// +/// Returns an error rather than a partial record: a line that lost its message +/// or its terminating newline would split or forge an event exactly as an +/// unescaped newline would. With a bounded scope name and a buffer of +/// `max_escaped_message_bytes + max_line_header_bytes` this cannot fail, and +/// the caller treats a failure as a sink error rather than writing the +/// fragment. +fn buildLine( + buf: []u8, + unix_seconds: i64, + level: std.log.Level, + scope_name: []const u8, + is_default: bool, + message: []const u8, +) std.Io.Writer.Error![]const u8 { + var w: std.Io.Writer = .fixed(buf); + try w.print("{d} {s}", .{ unix_seconds, levelText(level) }); + if (!is_default) try w.print("({s})", .{scope_name}); + try w.writeAll(": "); + try writeEscaped(&w, message); + try w.writeAll("\n"); + return w.buffered(); +} + +/// True leaves `state.file` open with room for `line_len` more bytes under +/// `state.max_bytes`. False leaves it closed, and the caller falls back to +/// stderr for that line. +/// +/// Every path that returns false has already counted exactly one `sink_error`, +/// at the step that failed: the caller must not count it again. +fn prepareFileLocked(line_len: usize) bool { + // Two passes at most: the second one exists for a file that is already at + // the bound when it is opened, which rotates before its first line. + for (0..2) |_| { + if (state.rotate_pending) { + if (!rotateLocked()) return false; + state.rotate_pending = false; + state.stats.rotations += 1; + } + if (state.file == null) openFileLocked(); + if (state.file == null) return false; + if (!overLimitLocked(line_len)) return true; + state.rotate_pending = true; + closeFileLocked(); + } + // A rotation succeeded and the fresh file is still over the bound: another + // writer owns the path. No step failed, so nothing has counted yet. + state.stats.sink_errors += 1; + return false; +} + +/// A line that alone exceeds `max_bytes` is written to an empty file rather +/// than rotated forever: the bound governs the file, and a line is never lost. +fn overLimitLocked(line_len: usize) bool { + if (state.max_bytes == 0) return false; + if (state.file_pos == 0) return false; + return state.file_pos + line_len > state.max_bytes; +} + +fn writeLineLocked(file: std.Io.File, line: []const u8) !void { + const prev = state.io.swapCancelProtection(.blocked); + defer _ = state.io.swapCancelProtection(prev); + + var write_buf: [512]u8 = undefined; + var fw = file.writer(state.io, &write_buf); + try fw.seekTo(state.file_pos); + try fw.interface.writeAll(line); + try fw.interface.flush(); + state.file_pos += line.len; +} + +/// 0.16.0 has no append mode: the writer seeks to the current end instead. +fn openFileLocked() void { + // Checked before the cancel-protection swap: an unusable path needs no io. + if (state.path_len == 0) { + state.stats.sink_errors += 1; + return; + } + + const prev = state.io.swapCancelProtection(.blocked); + defer _ = state.io.swapCancelProtection(prev); + + const dir: std.Io.Dir = .cwd(); + const p = state.path(); + const file = dir.openFile(state.io, p, .{ .mode = .write_only }) catch |open_err| switch (open_err) { + error.FileNotFound => dir.createFile(state.io, p, .{ .truncate = false }) catch { + state.stats.sink_errors += 1; + return; + }, + else => { + state.stats.sink_errors += 1; + return; + }, + }; + state.file = file; + state.file_pos = file.length(state.io) catch { + state.stats.sink_errors += 1; + file.close(state.io); + state.file = null; + return; + }; +} + +fn closeFileLocked() void { + const file = state.file orelse return; + file.close(state.io); + state.file = null; + state.file_pos = 0; +} + +/// `max_files` counts the live file, so the highest kept generation is +/// `max_files - 1`. +/// +/// True means the live path is free for a fresh file. False means a step +/// failed and the live path may still hold the oversized file, so the caller +/// must leave it closed: reopening it for append would defeat the disk bound +/// exactly when the filesystem is the thing that failed. +fn rotateLocked() bool { + const prev = state.io.swapCancelProtection(.blocked); + defer _ = state.io.swapCancelProtection(prev); + + closeFileLocked(); + rotateStepsLocked() catch { + // One failed rotation attempt is one sink error, counted here so the + // caller never counts the same failure a second time. + state.stats.sink_errors += 1; + return false; + }; + return true; +} + +const RotateError = error{RotateFailed}; + +fn rotateStepsLocked() RotateError!void { + const dir: std.Io.Dir = .cwd(); + const p = state.path(); + + if (state.max_files < 2) return deleteLocked(dir, p); + + var from_buf: [max_rotated_path_bytes]u8 = undefined; + var to_buf: [max_rotated_path_bytes]u8 = undefined; + const highest = state.max_files - 1; + + const oldest = rotatedName(&to_buf, p, highest) catch return error.RotateFailed; + try deleteLocked(dir, oldest); + + var n: u8 = highest; + while (n > 1) : (n -= 1) { + const from = rotatedName(&from_buf, p, n - 1) catch return error.RotateFailed; + const to = rotatedName(&to_buf, p, n) catch return error.RotateFailed; + try renameLocked(dir, from, to); + } + + const first = rotatedName(&to_buf, p, 1) catch return error.RotateFailed; + try renameLocked(dir, p, first); +} + +/// A generation that does not exist yet is not a failure: the first rotations +/// of a fresh log directory find nothing to delete. +fn deleteLocked(dir: std.Io.Dir, p: []const u8) RotateError!void { + dir.deleteFile(state.io, p) catch |err| switch (err) { + error.FileNotFound => {}, + else => return error.RotateFailed, + }; +} + +fn renameLocked(dir: std.Io.Dir, from: []const u8, to: []const u8) RotateError!void { + dir.rename(from, dir, to, state.io) catch |err| switch (err) { + error.FileNotFound => {}, + else => return error.RotateFailed, + }; +} + +// --------------------------------------------------------------------------- +// Tests +// +// The pure pieces only. `logFn` is never exercised: installing a sink under the +// test runner would eat the harness's own output. File behaviour is S8's, and +// the rotation failure paths (`rotateLocked` returning false, the pending +// rotation that keeps the oversized file closed) stay uncovered: they need a +// filesystem that fails a delete or a rename on demand. +// --------------------------------------------------------------------------- + +const testing = std.testing; + +fn ts(nanoseconds: i96) std.Io.Timestamp { + return .{ .nanoseconds = nanoseconds }; +} + +test "toStdLevel maps every model level" { + try testing.expectEqual(std.log.Level.err, toStdLevel(.err)); + try testing.expectEqual(std.log.Level.warn, toStdLevel(.warn)); + try testing.expectEqual(std.log.Level.info, toStdLevel(.info)); + try testing.expectEqual(std.log.Level.debug, toStdLevel(.debug)); +} + +test "enabled admits at and above the threshold only" { + try testing.expect(enabled(.err, .info)); + try testing.expect(enabled(.warn, .info)); + try testing.expect(enabled(.info, .info)); + try testing.expect(!enabled(.debug, .info)); + try testing.expect(enabled(.err, .err)); + try testing.expect(!enabled(.warn, .err)); + try testing.expect(enabled(.debug, .debug)); +} + +test "isDedupScope selects exactly the four upstream scopes" { + try testing.expect(isDedupScope(.doh_client)); + try testing.expect(isDedupScope(.dot_client)); + try testing.expect(isDedupScope(.pool)); + try testing.expect(isDedupScope(.forward_client)); + try testing.expect(!isDedupScope(.default)); + try testing.expect(!isDedupScope(.cache)); +} + +test "buildKey separates the scope from the message" { + var buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&buf, "pool", "no upstream available"); + try testing.expectEqualStrings("pool\x00no upstream available", key); +} + +test "buildKey truncates the message to 96 bytes" { + var buf: [max_dedup_key_bytes]u8 = undefined; + const long = "x" ** 200; + const key = buildKey(&buf, "pool", long); + try testing.expectEqual(@as(usize, 4 + 1 + max_message_key_bytes), key.len); +} + +test "dedup admits a key it has not seen" { + var table: DedupTable = .{}; + var buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&buf, "pool", "upstream timed out"); + try testing.expect(table.admit(ts(0), key)); +} + +test "dedup drops a repeat inside the window" { + var table: DedupTable = .{}; + var buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&buf, "doh_client", "connect failed"); + try testing.expect(table.admit(ts(1_000), key)); + try testing.expect(!table.admit(ts(1_000), key)); + try testing.expect(!table.admit(ts(1_000 + dedup_window_ns - 1), key)); +} + +test "dedup admits again once the window has passed" { + var table: DedupTable = .{}; + var buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&buf, "dot_client", "handshake failed"); + try testing.expect(table.admit(ts(0), key)); + try testing.expect(table.admit(ts(dedup_window_ns), key)); + // The admitted repeat restamps, so the window restarts from it. + try testing.expect(!table.admit(ts(dedup_window_ns + 1), key)); +} + +test "dedup keys the same message under different scopes apart" { + var table: DedupTable = .{}; + var pool_buf: [max_dedup_key_bytes]u8 = undefined; + var doh_buf: [max_dedup_key_bytes]u8 = undefined; + const pool_key = buildKey(&pool_buf, "pool", "connect failed"); + const doh_key = buildKey(&doh_buf, "doh_client", "connect failed"); + try testing.expect(table.admit(ts(0), pool_key)); + try testing.expect(table.admit(ts(0), doh_key)); + try testing.expect(!table.admit(ts(0), pool_key)); +} + +test "dedup collapses messages sharing their first 96 bytes" { + var table: DedupTable = .{}; + var first_buf: [max_dedup_key_bytes]u8 = undefined; + var second_buf: [max_dedup_key_bytes]u8 = undefined; + const prefix = "y" ** max_message_key_bytes; + const first = buildKey(&first_buf, "pool", prefix ++ " alpha"); + const second = buildKey(&second_buf, "pool", prefix ++ " beta"); + try testing.expect(table.admit(ts(0), first)); + try testing.expect(!table.admit(ts(0), second)); +} + +test "dedup replaces the oldest stamp when the table is full" { + var table: DedupTable = .{}; + var buf: [max_dedup_key_bytes]u8 = undefined; + var message_buf: [16]u8 = undefined; + + for (0..dedup_slots) |i| { + const message = try std.fmt.bufPrint(&message_buf, "failure {d}", .{i}); + const key = buildKey(&buf, "pool", message); + try testing.expect(table.admit(ts(@intCast(i)), key)); + } + + const newcomer = buildKey(&buf, "pool", "failure 999"); + try testing.expect(table.admit(ts(dedup_slots), newcomer)); + + // Slot 0 held the oldest stamp, so its key was forgotten and is admitted + // again inside what would otherwise still be its window. Admitting it + // evicts the next-oldest in turn, so the survivor asserted below is the + // newest of the original set rather than the second-oldest. + const evicted = buildKey(&buf, "pool", "failure 0"); + try testing.expect(table.admit(ts(dedup_slots), evicted)); + + const retained = buildKey(&buf, "pool", "failure 63"); + try testing.expect(!table.admit(ts(dedup_slots), retained)); +} + +test "dedup arithmetic holds at i96 scale" { + var table: DedupTable = .{}; + var buf: [max_dedup_key_bytes]u8 = undefined; + const key = buildKey(&buf, "forward_client", "zone resolver unreachable"); + const far: i96 = 1 << 80; + try testing.expect(table.admit(ts(far), key)); + try testing.expect(!table.admit(ts(far + dedup_window_ns - 1), key)); + try testing.expect(table.admit(ts(far + dedup_window_ns), key)); +} + +// --------------------------------------------------------------------------- +// Escaping +// --------------------------------------------------------------------------- + +fn escapeToBuf(buf: []u8, message: []const u8) ![]const u8 { + var w: std.Io.Writer = .fixed(buf); + try writeEscaped(&w, message); + return w.buffered(); +} + +test "writeEscaped passes printable text through unchanged" { + var buf: [64]u8 = undefined; + try testing.expectEqualStrings( + "upstream 10.0.0.1: timed out", + try escapeToBuf(&buf, "upstream 10.0.0.1: timed out"), + ); +} + +test "writeEscaped denies a forged record" { + // Without the escape this query name would produce a second line that + // parses as its own timestamped record. + var buf: [128]u8 = undefined; + const forged = "blocked\n1700000000 error(pool): all upstreams down"; + const escaped = try escapeToBuf(&buf, forged); + try testing.expect(std.mem.indexOfScalar(u8, escaped, '\n') == null); + try testing.expectEqualStrings( + "blocked\\n1700000000 error(pool): all upstreams down", + escaped, + ); +} + +test "writeEscaped escapes the named control bytes and the backslash" { + var buf: [64]u8 = undefined; + try testing.expectEqualStrings( + "a\\nb\\rc\\td\\\\e", + try escapeToBuf(&buf, "a\nb\rc\td\\e"), + ); +} + +test "writeEscaped hex-escapes every other control byte" { + var buf: [64]u8 = undefined; + try testing.expectEqualStrings("\\x00", try escapeToBuf(&buf, "\x00")); + try testing.expectEqualStrings("\\x1b[31m", try escapeToBuf(&buf, "\x1b[31m")); + try testing.expectEqualStrings("\\x7f", try escapeToBuf(&buf, "\x7f")); + try testing.expectEqualStrings("\\x0b\\x0c", try escapeToBuf(&buf, "\x0b\x0c")); +} + +test "writeEscaped leaves the printable bytes alone" { + var buf: [256]u8 = undefined; + // 0x20 through 0x7e: everything printable, DEL excluded. + var message: [95]u8 = undefined; + for (&message, 0..) |*byte, i| byte.* = @intCast(0x20 + i); + const escaped = try escapeToBuf(&buf, &message); + try testing.expectEqual(message.len + 1, escaped.len); // the one backslash + try testing.expectEqual(@as(usize, 1), std.mem.count(u8, escaped, "\\\\")); +} + +test "writeEscaped never exceeds four bytes per input byte" { + var buf: [max_escaped_message_bytes]u8 = undefined; + const worst = "\x01" ** max_message_bytes; + const escaped = try escapeToBuf(&buf, worst); + try testing.expectEqual(max_message_bytes * 4, escaped.len); +} + +test "writeEscaped handles high bytes and an empty message" { + var buf: [32]u8 = undefined; + try testing.expectEqualStrings("", try escapeToBuf(&buf, "")); + try testing.expectEqualStrings("\xc3\xa9", try escapeToBuf(&buf, "\xc3\xa9")); +} + +// --------------------------------------------------------------------------- +// Record construction +// --------------------------------------------------------------------------- + +test "buildLine writes one record ending in a newline" { + var buf: [256]u8 = undefined; + try testing.expectEqualStrings( + "1700000000 warning(pool): no upstream available\n", + try buildLine(&buf, 1700000000, .warn, "pool", false, "no upstream available"), + ); +} + +test "buildLine omits the scope of the default scope" { + var buf: [256]u8 = undefined; + try testing.expectEqualStrings( + "42 info: listening on 0.0.0.0:53\n", + try buildLine(&buf, 42, .info, "default", true, "listening on 0.0.0.0:53"), + ); +} + +test "buildLine escapes the message, so a record is one line" { + var buf: [256]u8 = undefined; + const line = try buildLine(&buf, 1, .err, "pool", false, "a\nb"); + try testing.expectEqualStrings("1 error(pool): a\\nb\n", line); + try testing.expectEqual(@as(usize, 1), std.mem.count(u8, line, "\n")); +} + +test "boundedScopeName truncates a scope name to the header allowance" { + try testing.expectEqualStrings("pool", boundedScopeName("pool")); + try testing.expectEqual(max_scope_name_bytes, boundedScopeName("s" ** 200).len); +} + +test "an oversized scope name still yields a well-formed record" { + var buf: [max_escaped_message_bytes + max_line_header_bytes]u8 = undefined; + const line = try buildLine( + &buf, + 1700000000, + .warn, + boundedScopeName("s" ** 200), + false, + "the message survives", + ); + try testing.expectEqualStrings( + "1700000000 warning(" ++ "s" ** max_scope_name_bytes ++ "): the message survives\n", + line, + ); +} + +test "the header allowance covers the widest possible header" { + // The longest timestamp, the longest level text, a bounded scope name, and + // the terminator, with no message at all. + var buf: [max_line_header_bytes]u8 = undefined; + const line = try buildLine( + &buf, + std.math.minInt(i64), + .warn, + boundedScopeName("s" ** 200), + false, + "", + ); + try testing.expectEqual(max_line_header_bytes, line.len); +} + +test "buildLine reports a full buffer instead of returning a partial record" { + var buf: [16]u8 = undefined; + try testing.expectError( + error.WriteFailed, + buildLine(&buf, 1700000000, .warn, "pool", false, "this does not fit"), + ); +} + +test "a failed open counts exactly one sink error" { + var stderr_buf: [64]u8 = undefined; + _ = std.debug.lockStderr(&stderr_buf); + const saved_stats = state.stats; + const saved_path_len = state.path_len; + const saved_file = state.file; + const saved_pending = state.rotate_pending; + defer { + state.stats = saved_stats; + state.path_len = saved_path_len; + state.file = saved_file; + state.rotate_pending = saved_pending; + std.debug.unlockStderr(); + } + + // An empty path fails the open before it reaches `state.io`, which no test + // ever installs. One failed attempt is one `sink_error`: the open counts + // it and `prepareFileLocked` leaves it at that. + state.stats = .{}; + state.path_len = 0; + state.file = null; + state.rotate_pending = false; + + try testing.expect(!prepareFileLocked(64)); + try testing.expectEqual(@as(u64, 1), state.stats.sink_errors); + try testing.expectEqual(@as(u64, 0), state.stats.lines_written); +} + +test "rotatedName appends the generation" { + var buf: [max_rotated_path_bytes]u8 = undefined; + try testing.expectEqualStrings( + "/var/log/nxdns/nxdns.log.1", + try rotatedName(&buf, "/var/log/nxdns/nxdns.log", 1), + ); + try testing.expectEqualStrings( + "/var/log/nxdns/nxdns.log.4", + try rotatedName(&buf, "/var/log/nxdns/nxdns.log", 4), + ); + try testing.expectEqualStrings( + "nxdns.log.255", + try rotatedName(&buf, "nxdns.log", 255), + ); +} + +test "rotatedName reports a buffer too small for the name" { + var buf: [4]u8 = undefined; + try testing.expectError(error.NameTooLong, rotatedName(&buf, "nxdns.log", 1)); +} + +test "rotation covers max_files - 1 generations" { + // The shift loop renames .{n-1} to .{n} down to .1, so `max_files` files + // exist in total: the live file plus generations 1 through max_files - 1. + var buf: [max_rotated_path_bytes]u8 = undefined; + const max_files: u8 = 5; + var names: [4][]const u8 = undefined; + var storage: [4][max_rotated_path_bytes]u8 = undefined; + for (1..max_files) |n| { + const name = try rotatedName(&buf, "nxdns.log", @intCast(n)); + @memcpy(storage[n - 1][0..name.len], name); + names[n - 1] = storage[n - 1][0..name.len]; + } + try testing.expectEqualStrings("nxdns.log.1", names[0]); + try testing.expectEqualStrings("nxdns.log.4", names[3]); +} diff --git a/src/platform/statfs.zig b/src/platform/statfs.zig new file mode 100644 index 0000000..d8b3b0f --- /dev/null +++ b/src/platform/statfs.zig @@ -0,0 +1,60 @@ +//! Filesystem free-space query. The Zig standard library has no `statvfs`, so +//! this file declares the libc entry point directly. Every nxdns build links +//! libc for sqlite3, so no target loses this. + +const std = @import("std"); + +/// The 64-bit glibc and musl layouts of `struct statvfs` agree field for field. +/// `__reserved` covers glibc's `f_type` plus `__f_spare[5]` and musl's `f_type` +/// plus `__reserved[5]`; musl's anonymous bitfield before `f_fsid` is +/// zero-width on a 64-bit target. Both nxdns targets are 64-bit. +pub const StatVfs = extern struct { + f_bsize: c_ulong, + f_frsize: c_ulong, + f_blocks: u64, + f_bfree: u64, + f_bavail: u64, + f_files: u64, + f_ffree: u64, + f_favail: u64, + f_fsid: c_ulong, + f_flag: c_ulong, + f_namemax: c_ulong, + __reserved: [6]c_int, +}; + +extern fn statvfs(path: [*:0]const u8, buf: *StatVfs) c_int; + +pub const Error = error{StatFailed}; + +/// Bytes free for an unprivileged writer on the filesystem holding `path`. +/// `f_bavail` excludes the reserved blocks that `f_bfree` counts, so this is +/// the number the disk monitor's thresholds must compare against. +pub fn freeBytes(path: [:0]const u8) Error!u64 { + var buf: StatVfs = undefined; + if (statvfs(path.ptr, &buf) != 0) return error.StatFailed; + return buf.f_bavail * buf.f_frsize; +} + +const testing = std.testing; + +test "freeBytes reports space on the working directory" { + const free = try freeBytes("."); + try testing.expect(free > 0); +} + +test "freeBytes fails on a path that does not exist" { + try testing.expectError(error.StatFailed, freeBytes("./nxdns-no-such-path-9d3f")); +} + +test "the struct matches the C ABI size and offsets" { + // A layout mismatch would silently read the wrong field rather than fail, + // so the offsets are pinned here. + try testing.expectEqual(@as(usize, 0), @offsetOf(StatVfs, "f_bsize")); + try testing.expectEqual(@as(usize, 8), @offsetOf(StatVfs, "f_frsize")); + try testing.expectEqual(@as(usize, 16), @offsetOf(StatVfs, "f_blocks")); + try testing.expectEqual(@as(usize, 32), @offsetOf(StatVfs, "f_bavail")); + try testing.expectEqual(@as(usize, 64), @offsetOf(StatVfs, "f_fsid")); + try testing.expectEqual(@as(usize, 80), @offsetOf(StatVfs, "f_namemax")); + try testing.expectEqual(@as(usize, 112), @sizeOf(StatVfs)); +} diff --git a/src/server/rate_limiter.zig b/src/server/rate_limiter.zig new file mode 100644 index 0000000..5d70493 --- /dev/null +++ b/src/server/rate_limiter.zig @@ -0,0 +1,326 @@ +//! Per-client query rate limiter for the DNS listeners. Pure: the caller passes +//! the timestamp, so this file holds no clock, no `std.Io` operation and no +//! socket. `check` neither allocates nor fails. +//! +//! Not thread-safe. Phase 7 decides the locking when it wires the limiter into +//! the query path. +//! +//! The window is fixed, not sliding (PLAN §10 reserves the token bucket for the +//! API limiter). A fixed window admits at most twice the limit across a window +//! boundary. That is acceptable for abuse protection at household scale and it +//! costs one counter per client instead of a timestamp ring. +//! +//! Each client's window is anchored at that client's first query rather than at +//! an absolute boundary: callers pass `.awake` timestamps, whose origin is +//! arbitrary, so an absolute alignment would carry no meaning. +//! +//! The table is bounded at `max_clients`. When it is full and the key is +//! unknown the query is allowed and counted under `untracked`. Refusing unseen +//! clients instead would let `max_clients` attackers deny service to every new +//! device on the LAN, and a household LAN never holds `max_clients` honest +//! clients. The counter makes the condition visible. + +const std = @import("std"); +const address = @import("../platform/address.zig"); + +const Allocator = std.mem.Allocator; + +/// Upper bound on tracked clients. The table never grows past it, so `check` +/// never allocates. +pub const max_clients = 4096; + +pub const Config = struct { + limit: u32, + window_seconds: u32, +}; + +/// `allowed + refused` equals the number of `check` calls. `untracked` counts +/// the subset of `allowed` that the full table could not attribute to a client. +pub const Stats = struct { + allowed: u64 = 0, + refused: u64 = 0, + untracked: u64 = 0, +}; + +const Window = struct { + start_ns: i96, + count: u32, +}; + +const Table = std.AutoHashMapUnmanaged(address.NetAddress.Key, Window); + +pub const RateLimiter = struct { + gpa: Allocator, + config: Config, + window_ns: i96, + table: Table, + /// `sweep` collects the keys to drop before it removes any of them, because + /// a removal invalidates a live iterator. The buffer is owned so that + /// `sweep` allocates nothing either. + stale_keys: []address.NetAddress.Key, + stats: Stats, + + /// Asserts `config.window_seconds` is nonzero; `validate.zig` rejects a zero + /// window before a config reaches this far. + pub fn init(gpa: Allocator, config: Config) Allocator.Error!RateLimiter { + std.debug.assert(config.window_seconds > 0); + + var table: Table = .empty; + errdefer table.deinit(gpa); + try table.ensureTotalCapacity(gpa, max_clients); + + const stale_keys = try gpa.alloc(address.NetAddress.Key, max_clients); + + return .{ + .gpa = gpa, + .config = config, + .window_ns = @as(i96, config.window_seconds) * std.time.ns_per_s, + .table = table, + .stale_keys = stale_keys, + .stats = .{}, + }; + } + + pub fn deinit(self: *RateLimiter) void { + self.table.deinit(self.gpa); + self.gpa.free(self.stale_keys); + self.* = undefined; + } + + /// True = process the query; false = answer REFUSED. Never errors, never + /// allocates. + pub fn check(self: *RateLimiter, now: std.Io.Timestamp, key: address.NetAddress.Key) bool { + const window = self.table.getPtr(key) orelse unknown: { + if (self.table.count() >= max_clients) { + self.stats.untracked += 1; + self.stats.allowed += 1; + return true; + } + const gop = self.table.getOrPutAssumeCapacity(key); + gop.value_ptr.* = .{ .start_ns = now.nanoseconds, .count = 0 }; + break :unknown gop.value_ptr; + }; + + if (now.nanoseconds - window.start_ns >= self.window_ns) { + window.start_ns = now.nanoseconds; + window.count = 0; + } + if (window.count >= self.config.limit) { + self.stats.refused += 1; + return false; + } + window.count += 1; + self.stats.allowed += 1; + return true; + } + + /// Drops every entry whose window ended more than one full window before + /// `now`, that is `now - start_ns > 2 * window_ns`. Returns how many it + /// dropped. Phase 7 schedules it. + pub fn sweep(self: *RateLimiter, now: std.Io.Timestamp) u32 { + const stale_after = 2 * self.window_ns; + var stale_count: u32 = 0; + + var it = self.table.iterator(); + while (it.next()) |entry| { + if (now.nanoseconds - entry.value_ptr.start_ns > stale_after) { + self.stale_keys[stale_count] = entry.key_ptr.*; + stale_count += 1; + } + } + + for (self.stale_keys[0..stale_count]) |key| { + const removed = self.table.remove(key); + std.debug.assert(removed); + } + return stale_count; + } + + /// Clients currently holding a window. Reaching `max_clients` is what turns + /// unknown clients into `untracked` allowances. + pub fn trackedClients(self: *const RateLimiter) u32 { + return self.table.count(); + } +}; + +const testing = std.testing; + +fn at(seconds: i64) std.Io.Timestamp { + return .{ .nanoseconds = @as(i96, seconds) * std.time.ns_per_s }; +} + +fn v4Key(a: u8, b: u8, c: u8, d: u8) address.NetAddress.Key { + const addr: address.NetAddress = .{ .ip4 = .{ a, b, c, d } }; + return addr.key(); +} + +fn indexedKey(index: u32) address.NetAddress.Key { + var octets: [4]u8 = undefined; + std.mem.writeInt(u32, &octets, index, .big); + const addr: address.NetAddress = .{ .ip4 = octets }; + return addr.key(); +} + +test "allows up to the limit and refuses beyond it" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 3, .window_seconds = 60 }); + defer limiter.deinit(); + + const client = v4Key(192, 168, 1, 10); + for (0..3) |_| try testing.expect(limiter.check(at(0), client)); + try testing.expect(!limiter.check(at(0), client)); + try testing.expect(!limiter.check(at(59), client)); + + try testing.expectEqual(@as(u64, 3), limiter.stats.allowed); + try testing.expectEqual(@as(u64, 2), limiter.stats.refused); +} + +test "a new window resets the count" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 2, .window_seconds = 60 }); + defer limiter.deinit(); + + const client = v4Key(10, 0, 0, 1); + try testing.expect(limiter.check(at(0), client)); + try testing.expect(limiter.check(at(0), client)); + try testing.expect(!limiter.check(at(0), client)); + + // The window is anchored at the first query, so it ends at t = 60. + try testing.expect(!limiter.check(at(59), client)); + try testing.expect(limiter.check(at(60), client)); + try testing.expect(limiter.check(at(119), client)); + try testing.expect(!limiter.check(at(119), client)); +} + +test "ipv4 and ipv6 clients hold independent windows" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 1, .window_seconds = 60 }); + defer limiter.deinit(); + + const v4 = (try address.NetAddress.parse("192.168.1.20")).key(); + const v6 = (try address.NetAddress.parse("fd00::20")).key(); + + try testing.expect(limiter.check(at(0), v4)); + try testing.expect(!limiter.check(at(0), v4)); + try testing.expect(limiter.check(at(0), v6)); + try testing.expect(!limiter.check(at(0), v6)); + try testing.expectEqual(@as(u32, 2), limiter.trackedClients()); +} + +test "an ipv4-mapped ipv6 client shares the ipv4 bucket" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 2, .window_seconds = 60 }); + defer limiter.deinit(); + + const mapped = address.NetAddress.fromIp(try std.Io.net.IpAddress.parse("::ffff:192.168.1.30", 53)).key(); + const plain = v4Key(192, 168, 1, 30); + try testing.expectEqualSlices(u8, &plain, &mapped); + + try testing.expect(limiter.check(at(0), plain)); + try testing.expect(limiter.check(at(0), mapped)); + try testing.expect(!limiter.check(at(0), plain)); + try testing.expectEqual(@as(u32, 1), limiter.trackedClients()); +} + +test "sweep removes only entries stale by more than one full window" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 5, .window_seconds = 60 }); + defer limiter.deinit(); + + const old = v4Key(10, 0, 0, 1); + const boundary = v4Key(10, 0, 0, 2); + const fresh = v4Key(10, 0, 0, 3); + + try testing.expect(limiter.check(at(0), old)); + try testing.expect(limiter.check(at(0), boundary)); + try testing.expect(limiter.check(at(100), fresh)); + try testing.expectEqual(@as(u32, 3), limiter.trackedClients()); + + // At t = 120 the boundary entry is exactly 2 windows old and survives. + try testing.expectEqual(@as(u32, 0), limiter.sweep(at(120))); + try testing.expectEqual(@as(u32, 3), limiter.trackedClients()); + + try testing.expectEqual(@as(u32, 2), limiter.sweep(at(121))); + try testing.expectEqual(@as(u32, 1), limiter.trackedClients()); + try testing.expect(!limiter.table.contains(old)); + try testing.expect(!limiter.table.contains(boundary)); + try testing.expect(limiter.table.contains(fresh)); + + // A swept client starts a fresh window rather than inheriting the old count. + try testing.expect(limiter.check(at(121), old)); + try testing.expectEqual(@as(u32, 2), limiter.trackedClients()); +} + +test "a full table allows unknown clients and counts them untracked" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 1, .window_seconds = 60 }); + defer limiter.deinit(); + + for (0..max_clients) |i| { + try testing.expect(limiter.check(at(0), indexedKey(@intCast(i)))); + } + try testing.expectEqual(@as(u32, max_clients), limiter.trackedClients()); + try testing.expectEqual(@as(u64, 0), limiter.stats.untracked); + + const newcomer = indexedKey(max_clients); + try testing.expect(limiter.check(at(0), newcomer)); + try testing.expect(limiter.check(at(0), newcomer)); + try testing.expectEqual(@as(u64, 2), limiter.stats.untracked); + try testing.expectEqual(@as(u32, max_clients), limiter.trackedClients()); + + // A tracked client is still limited while the table is full. + try testing.expect(!limiter.check(at(0), indexedKey(0))); + + // Sweeping frees room, and the newcomer becomes tracked. + try testing.expectEqual(@as(u32, max_clients), limiter.sweep(at(200))); + try testing.expect(limiter.check(at(200), newcomer)); + try testing.expectEqual(@as(u32, 1), limiter.trackedClients()); + try testing.expectEqual(@as(u64, 2), limiter.stats.untracked); +} + +test "stats account for every check" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 4, .window_seconds = 30 }); + defer limiter.deinit(); + + var checks: u64 = 0; + for (0..10) |i| { + for (0..3) |_| { + _ = limiter.check(at(@intCast(i)), v4Key(172, 16, 0, @intCast(i))); + checks += 1; + } + } + try testing.expectEqual(checks, limiter.stats.allowed + limiter.stats.refused); + try testing.expect(limiter.stats.untracked <= limiter.stats.allowed); +} + +test "window arithmetic holds far from the timestamp origin" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 2, .window_seconds = 60 }); + defer limiter.deinit(); + + // Beyond the range of i64 nanoseconds, so only the i96 arithmetic works. + const base: i96 = 1 << 80; + const window_ns: i96 = 60 * std.time.ns_per_s; + const client = v4Key(10, 1, 2, 3); + + try testing.expect(limiter.check(.{ .nanoseconds = base }, client)); + try testing.expect(limiter.check(.{ .nanoseconds = base + 1 }, client)); + try testing.expect(!limiter.check(.{ .nanoseconds = base + window_ns - 1 }, client)); + try testing.expect(limiter.check(.{ .nanoseconds = base + window_ns }, client)); + try testing.expectEqual(@as(u32, 0), limiter.sweep(.{ .nanoseconds = base + 3 * window_ns })); + try testing.expectEqual(@as(u32, 1), limiter.sweep(.{ .nanoseconds = base + 4 * window_ns })); +} + +test "a limit of zero refuses every query" { + var limiter = try RateLimiter.init(testing.allocator, .{ .limit = 0, .window_seconds = 60 }); + defer limiter.deinit(); + + try testing.expect(!limiter.check(at(0), v4Key(10, 0, 0, 1))); + try testing.expect(!limiter.check(at(0), v4Key(10, 0, 0, 2))); + try testing.expectEqual(@as(u32, 2), limiter.trackedClients()); + try testing.expectEqual(@as(u64, 2), limiter.stats.refused); + try testing.expectEqual(@as(u64, 0), limiter.stats.allowed); +} + +fn initCheckDeinit(allocator: Allocator) !void { + var limiter = try RateLimiter.init(allocator, .{ .limit = 10, .window_seconds = 60 }); + defer limiter.deinit(); + try testing.expect(limiter.check(at(0), v4Key(10, 0, 0, 1))); +} + +test "init surfaces allocation failure without leaking" { + try testing.checkAllAllocationFailures(testing.allocator, initCheckDeinit, .{}); +} diff --git a/src/storage/disk_monitor.zig b/src/storage/disk_monitor.zig new file mode 100644 index 0000000..fe2f0f9 --- /dev/null +++ b/src/storage/disk_monitor.zig @@ -0,0 +1,420 @@ +//! Free-space monitor (PLAN §11.6). Samples the filesystem holding the data +//! directory every 60 seconds, classifies the result against the configured +//! thresholds, and publishes the state plus three size gauges through atomics. +//! +//! The state is the gate other components read before a non-essential write: +//! the query logger holds its batches while `writesAllowed` is false, and +//! Phase 7 gates blocklist updates the same way. Nothing here edits a +//! milestone-5 file; the gate is pulled, not pushed. + +const std = @import("std"); +const model = @import("../config/model.zig"); +const statfs = @import("../platform/statfs.zig"); + +const log = std.log.scoped(.disk_monitor); + +pub const sample_interval_s = 60; + +pub const State = enum(u8) { ok, warn, critical }; + +pub const Gauges = struct { + free_bytes: u64, + db_bytes: u64, + log_bytes: u64, +}; + +/// `min_free_mb` is checked first, so a configuration whose warn threshold sits +/// below its critical threshold still reports the more severe of the two. +pub fn classify(free_bytes: u64, cfg: model.Disk) State { + if (free_bytes < model.minFreeBytes(cfg)) return .critical; + if (free_bytes < model.warnFreeBytes(cfg)) return .warn; + return .ok; +} + +pub const Monitor = struct { + cfg: model.Disk, + data_dir: std.Io.Dir, + data_path: [:0]const u8, + log_dir_path: ?[:0]const u8, + + state_raw: std.atomic.Value(u8), + free_bytes: std.atomic.Value(u64), + db_bytes: std.atomic.Value(u64), + log_bytes: std.atomic.Value(u64), + sample_failures: std.atomic.Value(u64), + + /// `data_dir` must be open with `.iterate = true`; sizing the databases + /// scans it. `data_path` names the filesystem to measure and `data_dir` the + /// directory to size — normally the same place, but `statvfs` takes a path + /// and the scan takes a handle. `log_dir_path` resolves against the process + /// working directory and is null when logs do not go to a file. + pub fn init( + cfg: model.Disk, + data_dir: std.Io.Dir, + data_path: [:0]const u8, + log_dir_path: ?[:0]const u8, + ) Monitor { + return .{ + .cfg = cfg, + .data_dir = data_dir, + .data_path = data_path, + .log_dir_path = log_dir_path, + .state_raw = .init(@intFromEnum(State.ok)), + .free_bytes = .init(0), + .db_bytes = .init(0), + .log_bytes = .init(0), + .sample_failures = .init(0), + }; + } + + pub fn state(self: *const Monitor) State { + return @enumFromInt(self.state_raw.load(.monotonic)); + } + + pub fn writesAllowed(self: *const Monitor) bool { + return self.state() != .critical; + } + + pub fn gauges(self: *const Monitor) Gauges { + return .{ + .free_bytes = self.free_bytes.load(.monotonic), + .db_bytes = self.db_bytes.load(.monotonic), + .log_bytes = self.log_bytes.load(.monotonic), + }; + } + + /// One pass: free space from `statvfs`, then the two size gauges. A failed + /// `statvfs` leaves the state untouched — an unreadable filesystem is not + /// evidence that the disk filled — and a failed size scan leaves that one + /// gauge at its previous reading. Every failure increments + /// `sample_failures` and logs one line at `warn`. + pub fn sample(self: *Monitor, io: std.Io) void { + const free = statfs.freeBytes(self.data_path) catch { + self.countFailure(); + log.warn("statvfs on {s} failed", .{self.data_path}); + return; + }; + self.free_bytes.store(free, .monotonic); + + if (sumDir(io, self.data_dir, isDatabaseFile)) |bytes| { + self.db_bytes.store(bytes, .monotonic); + } else |err| { + self.countFailure(); + log.warn("sizing the data directory failed: {s}", .{@errorName(err)}); + } + + if (self.log_dir_path) |path| { + if (self.sumLogDir(io, path)) |bytes| { + self.log_bytes.store(bytes, .monotonic); + } else |err| { + self.countFailure(); + log.warn("sizing {s} failed: {s}", .{ path, @errorName(err) }); + } + } + + self.publish(classify(free, self.cfg), free); + } + + /// Sample first, then sleep: a process that starts on a full disk must not + /// serve a whole interval believing the state is `.ok`. `.boot` so a + /// suspended box still sees the interval elapse. + pub fn run(self: *Monitor, io: std.Io) std.Io.Cancelable!void { + const interval: std.Io.Clock.Duration = .{ + .raw = .fromSeconds(sample_interval_s), + .clock = .boot, + }; + while (true) { + self.sample(io); + try interval.sleep(io); + } + } + + fn countFailure(self: *Monitor) void { + _ = self.sample_failures.fetchAdd(1, .monotonic); + } + + /// Logs on transitions only. A disk that sits at `.warn` for a week + /// produces one line, not ten thousand. + fn publish(self: *Monitor, next: State, free: u64) void { + const previous: State = @enumFromInt(self.state_raw.swap(@intFromEnum(next), .monotonic)); + if (previous == next) return; + log.warn("disk state {t} -> {t}: {d} bytes free on {s}", .{ + previous, + next, + free, + self.data_path, + }); + } + + fn sumLogDir(self: *Monitor, io: std.Io, path: [:0]const u8) !u64 { + _ = self; + var dir = try std.Io.Dir.cwd().openDir(io, path, .{ .iterate = true }); + defer dir.close(io); + return sumDir(io, dir, everyFile); + } +}; + +fn everyFile(_: []const u8) bool { + return true; +} + +/// The sqlite trio: `x.db`, its write-ahead log and its shared-memory index. +/// All three live on the watched filesystem and all three grow. +fn isDatabaseFile(name: []const u8) bool { + return std.mem.endsWith(u8, name, ".db") or + std.mem.endsWith(u8, name, ".db-wal") or + std.mem.endsWith(u8, name, ".db-shm"); +} + +fn sumDir(io: std.Io, dir: std.Io.Dir, accept: *const fn ([]const u8) bool) !u64 { + var total: u64 = 0; + var it = dir.iterate(); + while (try it.next(io)) |entry| { + if (entry.kind != .file) continue; + if (!accept(entry.name)) continue; + // A file that vanishes between `iterate` and `statFile` is normal: + // rotation and database recreate both delete under a running scan. Any + // other stat failure makes the whole scan fail, because a partial total + // published as a gauge reads as a shrinking database. + const st = dir.statFile(io, entry.name, .{}) catch |err| switch (err) { + error.FileNotFound => continue, + else => return err, + }; + total += st.size; + } + return total; +} + +// --------------------------------------------------------------------------- +// tests +// --------------------------------------------------------------------------- + +const testing = std.testing; + +const mb = 1024 * 1024; + +/// Set by the vanished-file test only: `acceptGoneDeleted` needs a handle and an +/// io, and the `accept` signature carries neither. +var vanish_dir: ?std.Io.Dir = null; +var vanish_io: ?std.Io = null; + +/// Deletes `gone.db` between `iterate` and `statFile`, which is the race the +/// scan must tolerate. +fn acceptGoneDeleted(name: []const u8) bool { + if (!isDatabaseFile(name)) return false; + if (std.mem.eql(u8, name, "gone.db")) { + vanish_dir.?.deleteFile(vanish_io.?, name) catch {}; + } + return true; +} + +test "classify below the critical threshold" { + const cfg: model.Disk = .{ .min_free_mb = 200, .warn_free_mb = 500 }; + try testing.expectEqual(State.critical, classify(0, cfg)); + try testing.expectEqual(State.critical, classify(199 * mb, cfg)); + try testing.expectEqual(State.critical, classify(200 * mb - 1, cfg)); +} + +test "classify at and above the critical threshold" { + const cfg: model.Disk = .{ .min_free_mb = 200, .warn_free_mb = 500 }; + try testing.expectEqual(State.warn, classify(200 * mb, cfg)); + try testing.expectEqual(State.warn, classify(350 * mb, cfg)); + try testing.expectEqual(State.warn, classify(500 * mb - 1, cfg)); +} + +test "classify at and above the warn threshold" { + const cfg: model.Disk = .{ .min_free_mb = 200, .warn_free_mb = 500 }; + try testing.expectEqual(State.ok, classify(500 * mb, cfg)); + try testing.expectEqual(State.ok, classify(64 * 1024 * mb, cfg)); +} + +test "classify with both thresholds at zero never leaves ok" { + const cfg: model.Disk = .{ .min_free_mb = 0, .warn_free_mb = 0 }; + try testing.expectEqual(State.ok, classify(0, cfg)); + try testing.expectEqual(State.ok, classify(1, cfg)); +} + +test "classify reports the more severe state when warn sits below min" { + const cfg: model.Disk = .{ .min_free_mb = 500, .warn_free_mb = 200 }; + try testing.expectEqual(State.critical, classify(300 * mb, cfg)); + try testing.expectEqual(State.ok, classify(500 * mb, cfg)); +} + +test "the database file filter accepts the sqlite trio only" { + try testing.expect(isDatabaseFile("querylog.db")); + try testing.expect(isDatabaseFile("querylog.db-wal")); + try testing.expect(isDatabaseFile("querylog.db-shm")); + try testing.expect(!isDatabaseFile("querylog.db.bak")); + try testing.expect(!isDatabaseFile("nxdns.log")); + try testing.expect(!isDatabaseFile("")); +} + +test "init reports ok with zero gauges and allows writes" { + var monitor: Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); + try testing.expectEqual(State.ok, monitor.state()); + try testing.expect(monitor.writesAllowed()); + try testing.expectEqual(Gauges{ .free_bytes = 0, .db_bytes = 0, .log_bytes = 0 }, monitor.gauges()); + try testing.expectEqual(@as(u64, 0), monitor.sample_failures.load(.monotonic)); +} + +test "writesAllowed is false only at critical" { + var monitor: Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); + monitor.state_raw.store(@intFromEnum(State.warn), .monotonic); + try testing.expect(monitor.writesAllowed()); + monitor.state_raw.store(@intFromEnum(State.critical), .monotonic); + try testing.expect(!monitor.writesAllowed()); +} + +test "a sample sizes the databases and ignores every other file" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + + try tmp.dir.writeFile(io, .{ .sub_path = "querylog.db", .data = &[_]u8{'a'} ** 100 }); + try tmp.dir.writeFile(io, .{ .sub_path = "querylog.db-wal", .data = &[_]u8{'b'} ** 50 }); + try tmp.dir.writeFile(io, .{ .sub_path = "querylog.db-shm", .data = &[_]u8{'c'} ** 10 }); + try tmp.dir.writeFile(io, .{ .sub_path = "notes.txt", .data = &[_]u8{'d'} ** 4096 }); + + var monitor: Monitor = .init(.{ .min_free_mb = 0, .warn_free_mb = 0 }, tmp.dir, ".", null); + monitor.sample(io); + + const g = monitor.gauges(); + try testing.expectEqual(@as(u64, 160), g.db_bytes); + try testing.expectEqual(@as(u64, 0), g.log_bytes); + try testing.expect(g.free_bytes > 0); + try testing.expectEqual(@as(u64, 0), monitor.sample_failures.load(.monotonic)); + try testing.expectEqual(State.ok, monitor.state()); +} + +test "a sample sizes every file in the log directory" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + try tmp.dir.createDirPath(io, "logs"); + + var logs = try tmp.dir.openDir(io, "logs", .{}); + defer logs.close(io); + try logs.writeFile(io, .{ .sub_path = "nxdns.log", .data = &[_]u8{'a'} ** 300 }); + try logs.writeFile(io, .{ .sub_path = "nxdns.log.1", .data = &[_]u8{'b'} ** 700 }); + + var path_buf: [256]u8 = undefined; + const log_path = try std.fmt.bufPrintZ(&path_buf, ".zig-cache/tmp/{s}/logs", .{tmp.sub_path}); + + var monitor: Monitor = .init(.{ .min_free_mb = 0, .warn_free_mb = 0 }, tmp.dir, ".", log_path); + monitor.sample(io); + + try testing.expectEqual(@as(u64, 1000), monitor.gauges().log_bytes); + try testing.expectEqual(@as(u64, 0), monitor.sample_failures.load(.monotonic)); +} + +test "a failed statvfs counts and keeps the previous state" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var monitor: Monitor = .init(.{}, std.Io.Dir.cwd(), "./nxdns-no-such-path-7c21", null); + monitor.state_raw.store(@intFromEnum(State.warn), .monotonic); + monitor.sample(io); + + try testing.expectEqual(State.warn, monitor.state()); + try testing.expectEqual(@as(u64, 1), monitor.sample_failures.load(.monotonic)); + try testing.expectEqual(@as(u64, 0), monitor.gauges().free_bytes); +} + +test "an unreadable log directory counts a failure but still publishes a state" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + + var monitor: Monitor = .init( + .{ .min_free_mb = 0, .warn_free_mb = 0 }, + tmp.dir, + ".", + "./nxdns-no-such-dir-4f8a", + ); + monitor.sample(io); + + try testing.expectEqual(@as(u64, 1), monitor.sample_failures.load(.monotonic)); + try testing.expectEqual(State.ok, monitor.state()); + try testing.expect(monitor.gauges().free_bytes > 0); +} + +test "a file deleted during the scan is skipped and the rest still counts" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + + try tmp.dir.writeFile(io, .{ .sub_path = "gone.db", .data = &[_]u8{'a'} ** 100 }); + try tmp.dir.writeFile(io, .{ .sub_path = "stays.db", .data = &[_]u8{'b'} ** 40 }); + + vanish_dir = tmp.dir; + vanish_io = io; + defer vanish_dir = null; + + try testing.expectEqual(@as(u64, 40), try sumDir(io, tmp.dir, acceptGoneDeleted)); +} + +test "an unreadable data directory fails the scan and keeps the previous gauge" { + // Mode bits do not apply to root, so the denial the test needs cannot happen. + if (std.c.geteuid() == 0) return error.SkipZigTest; + + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + + try tmp.dir.writeFile(io, .{ .sub_path = "querylog.db", .data = &[_]u8{'a'} ** 100 }); + + var monitor: Monitor = .init(.{ .min_free_mb = 0, .warn_free_mb = 0 }, tmp.dir, ".", null); + monitor.db_bytes.store(4096, .monotonic); + + // The handle keeps its read permission from open time, so `iterate` still + // lists the file, but path resolution under the directory now fails. + try tmp.dir.setPermissions(io, .fromMode(0o600)); + monitor.sample(io); + try tmp.dir.setPermissions(io, .fromMode(0o700)); + + try testing.expectEqual(@as(u64, 4096), monitor.gauges().db_bytes); + try testing.expectEqual(@as(u64, 1), monitor.sample_failures.load(.monotonic)); + try testing.expectEqual(State.ok, monitor.state()); +} + +test "a threshold above the real free space drives the state to critical" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var tmp = testing.tmpDir(.{ .iterate = true }); + defer tmp.cleanup(); + + const unreachable_mb = std.math.maxInt(u32); + var monitor: Monitor = .init( + .{ .min_free_mb = unreachable_mb, .warn_free_mb = unreachable_mb }, + tmp.dir, + ".", + null, + ); + monitor.sample(io); + try testing.expectEqual(State.critical, monitor.state()); + try testing.expect(!monitor.writesAllowed()); + + monitor.cfg = .{ .min_free_mb = 0, .warn_free_mb = 0 }; + monitor.sample(io); + try testing.expectEqual(State.ok, monitor.state()); + try testing.expect(monitor.writesAllowed()); + try testing.expectEqual(@as(u64, 0), monitor.sample_failures.load(.monotonic)); +} diff --git a/src/storage/logger.zig b/src/storage/logger.zig new file mode 100644 index 0000000..d0e01c5 --- /dev/null +++ b/src/storage/logger.zig @@ -0,0 +1,833 @@ +//! Async query logger (PLAN §11.4). The query path hands an `Entry` to `log` +//! and never touches the database: one writer task owns the `db.Db` handle, and +//! everything between the two is an `std.Io.Queue`. +//! +//! `Io.Queue` copies elements as raw bytes (`Io.zig:2189`), so an `Entry` owns +//! every byte it carries — a slice into the caller's packet buffer would dangle +//! the moment the query finishes. That is the whole reason this file has fixed +//! buffers instead of slices. +//! +//! The privacy transforms of §11.4 run inside `log`, before the entry is +//! enqueued, so nothing downstream — the database now, Phase 8's event stream +//! later — can observe a value the operator asked to hide. +//! +//! Log rows are expendable. A full queue drops the oldest unflushed entry, a +//! failed batch is dropped whole, and a disk that crossed the critical +//! threshold holds batches back indefinitely. Each of the three has a counter. +//! A writer that cannot prepare its statements closes the queue and marks +//! `writer_failed`, so the loss is visible rather than silent. + +const std = @import("std"); + +const db = @import("db.zig"); +const disk_monitor = @import("disk_monitor.zig"); +const model = @import("../config/model.zig"); +const queries_repo = @import("repositories/queries_repo.zig"); + +/// Named `scope` rather than `log`: `Logger.log` is the enqueue entry point, +/// and the two names collide inside the struct. +const scope = std.log.scoped(.query_logger); + +/// Flush tuning is comptime: §12.1 defines no configuration keys for it and a +/// household deployment has no reason to tune it. +pub const flush_batch = 100; +pub const flush_interval_ms = 100; + +/// What `hide_domains` and `hide_client_ips` store instead of the real value. +pub const hidden_marker = "hidden"; + +/// How long a batch waits before it re-reads the disk monitor. +pub const gate_retry_s = 1; + +const max_domain_len = 253; +/// RFC 5952 text of any IPv6 address, zone identifier included. +const max_client_len = 45; +const max_reason_len = 32; +const max_upstream_len = 64; + +/// One row on its way to `query_log`, carrying its own bytes. +pub const Entry = struct { + timestamp: i64, + domain_buf: [max_domain_len]u8, + domain_len: u8, + client_buf: [max_client_len]u8, + client_len: u8, + qtype: ?u16, + blocked: bool, + reason_buf: [max_reason_len]u8, + reason_len: u8, + response_time_us: ?i64, + cache_hit: ?bool, + upstream_buf: [max_upstream_len]u8, + upstream_len: u8, + + /// The borrowed shape of an entry. `init` copies out of it, so a caller can + /// build one from slices that die with the query. + pub const Fields = struct { + timestamp: i64, + domain: []const u8, + client_ip: []const u8, + qtype: ?u16 = null, + blocked: bool = false, + /// Empty means "no reason", which reaches the database as NULL. + block_reason: []const u8 = "", + response_time_us: ?i64 = null, + cache_hit: ?bool = null, + /// Empty means "no upstream", which reaches the database as NULL. + upstream: []const u8 = "", + }; + + /// Copies each string in, truncated to what its buffer holds. A name longer + /// than 253 bytes is not a valid domain name, so truncation here means the + /// caller skipped the parser, not that a real name was lost. + pub fn init(f: Fields) Entry { + var entry: Entry = .{ + .timestamp = f.timestamp, + .domain_buf = undefined, + .domain_len = 0, + .client_buf = undefined, + .client_len = 0, + .qtype = f.qtype, + .blocked = f.blocked, + .reason_buf = undefined, + .reason_len = 0, + .response_time_us = f.response_time_us, + .cache_hit = f.cache_hit, + .upstream_buf = undefined, + .upstream_len = 0, + }; + entry.setDomain(f.domain); + entry.setClientIp(f.client_ip); + entry.reason_len = copyInto(&entry.reason_buf, f.block_reason); + entry.upstream_len = copyInto(&entry.upstream_buf, f.upstream); + return entry; + } + + pub fn setDomain(self: *Entry, value: []const u8) void { + self.domain_len = copyInto(&self.domain_buf, value); + } + + pub fn setClientIp(self: *Entry, value: []const u8) void { + self.client_len = copyInto(&self.client_buf, value); + } + + pub fn domain(self: *const Entry) []const u8 { + return self.domain_buf[0..self.domain_len]; + } + + pub fn clientIp(self: *const Entry) []const u8 { + return self.client_buf[0..self.client_len]; + } + + pub fn blockReason(self: *const Entry) []const u8 { + return self.reason_buf[0..self.reason_len]; + } + + pub fn upstream(self: *const Entry) []const u8 { + return self.upstream_buf[0..self.upstream_len]; + } +}; + +fn copyInto(buf: []u8, value: []const u8) u8 { + const n = @min(buf.len, value.len); + @memcpy(buf[0..n], value[0..n]); + return @intCast(n); +} + +/// The row borrows from `entry`, which must outlive the `writeBatch` call. +fn toRow(entry: *const Entry) queries_repo.Row { + return .{ + .timestamp = entry.timestamp, + .domain = entry.domain(), + .client_ip = entry.clientIp(), + .qtype = entry.qtype, + .blocked = entry.blocked, + .block_reason = emptyAsNull(entry.blockReason()), + .response_time_us = entry.response_time_us, + .cache_hit = entry.cache_hit, + .upstream = emptyAsNull(entry.upstream()), + }; +} + +fn emptyAsNull(value: []const u8) ?[]const u8 { + return if (value.len == 0) null else value; +} + +const EntryQueue = std.Io.Queue(Entry); + +/// What the flush interval race can produce. `Select` demands that each field +/// type match its task's return type exactly. +const Outcome = union(enum) { + entry: std.Io.Cancelable!?Entry, + expiry: std.Io.Cancelable!void, +}; + +pub const Logger = struct { + cfg: model.Logging, + queue: EntryQueue, + queries_dropped: std.atomic.Value(u64), + rows_written: std.atomic.Value(u64), + batches_gated: std.atomic.Value(u64), + /// Set when `runWriter` gives up before it consumed anything. The queue is + /// closed and every entry counts as dropped from that point, so a caller + /// that sees this must not expect rows. + writer_failed: std.atomic.Value(bool), + + /// `queue_buf.len` is the backpressure cap — Phase 7 passes + /// `cfg.query_log_buffer_max` entries. The queue holds waiting tasks in + /// intrusive lists, so a `Logger` must not be moved once anything has + /// touched it. + pub fn init(cfg: model.Logging, queue_buf: []Entry) Logger { + return .{ + .cfg = cfg, + .queue = .init(queue_buf), + .queries_dropped = .init(0), + .rows_written = .init(0), + .batches_gated = .init(0), + .writer_failed = .init(false), + }; + } + + /// Applies the privacy transforms and enqueues without ever blocking the + /// query path. A full queue loses its oldest unflushed entry (§11.4). + pub fn log(self: *Logger, io: std.Io, entry: Entry) void { + var transformed = entry; + if (self.cfg.hide_domains) transformed.setDomain(hidden_marker); + if (self.cfg.hide_client_ips) transformed.setClientIp(hidden_marker); + self.enqueue(io, transformed); + } + + /// Retries until the put succeeds, and each failed attempt drops exactly + /// one oldest entry. A fixed attempt cap would break the policy under + /// contention: a producer that steals the slot this call freed would make + /// this call pay for two entries, the dropped one and its own. + fn enqueue(self: *Logger, io: std.Io, entry: Entry) void { + while (true) { + // A closed queue or a canceled task means shutdown is underway; + // both leave this entry unwritten, which is what the counter says. + const put = self.queue.put(io, &.{entry}, 0) catch break; + if (put == 1) return; + + // A zero-capacity queue holds nothing to drop: the put above was + // this entry's one chance at a waiting getter. + if (self.queue.capacity() == 0) break; + + var oldest: [1]Entry = undefined; + const got = self.queue.get(io, &oldest, 0) catch break; + if (got == 1) self.countDropped(1); + } + self.countDropped(1); + } + + /// The writer task: owns `database` and its prepared statements for its + /// whole life. Returns when `shutdown` closes the queue and the last batch + /// is flushed, or when the task is canceled. + /// + /// `monitor` is the §11.6 gate. Null disables gating. + pub fn runWriter( + self: *Logger, + io: std.Io, + database: *db.Db, + monitor: ?*disk_monitor.Monitor, + ) std.Io.Cancelable!void { + var writer = queries_repo.BatchWriter.init(database) catch |err| { + scope.warn("query logger: preparing the batch statements failed: {s}", .{@errorName(err)}); + // Without a writer there is no consumer, so leaving the queue open + // would silently swallow every later entry. + self.writer_failed.store(true, .release); + self.queue.close(io); + self.dropRemaining(io); + return; + }; + defer writer.deinit(); + + var batch: [flush_batch]Entry = undefined; + while (true) { + // A closed queue hands over its buffered elements before it reports + // `Closed` (`Io.zig:2118`), so this drains before it returns. + batch[0] = self.queue.getOne(io) catch |err| switch (err) { + error.Closed => return, + error.Canceled => |e| return e, + }; + const deadline: std.Io.Clock.Timestamp = .fromNow(io, .{ + .raw = .fromMilliseconds(flush_interval_ms), + .clock = .awake, + }); + // `n` is live across both calls: entries already taken off the + // queue are lost if either one is canceled, so they must count. + var n: usize = 1; + self.fill(io, &batch, deadline, &n) catch |err| { + self.countDropped(n); + return err; + }; + self.flush(io, &writer, batch[0..n], monitor) catch |err| { + self.countDropped(n); + return err; + }; + } + } + + /// Counts every entry left in a closed queue as dropped. The drain is + /// uncancelable: a cancellation racing the writer's own failure would + /// otherwise abandon the buffered entries without counting them. + fn dropRemaining(self: *Logger, io: std.Io) void { + var leftover: [flush_batch]Entry = undefined; + while (true) { + const n = self.queue.getUncancelable(io, &leftover, 0) catch |err| switch (err) { + error.Closed => break, + }; + if (n == 0) break; + self.countDropped(n); + } + } + + /// Closes the queue. `log` drops from here on and `runWriter` returns once + /// it has flushed what was left. + /// + /// A writer held by the disk gate keeps holding: it flushes when the disk + /// recovers, and Phase 7 cancels the task if it will not wait. A canceled + /// writer counts the batch it holds under `queries_dropped`. + pub fn shutdown(self: *Logger, io: std.Io) void { + self.queue.close(io); + } + + /// Fills `batch` behind the entry already in slot 0, until it is full or + /// `deadline` passes. `n` counts the slots that hold an entry, and stays + /// accurate on the cancellation path so the caller can count what is lost. + fn fill( + self: *Logger, + io: std.Io, + batch: *[flush_batch]Entry, + deadline: std.Io.Clock.Timestamp, + n: *usize, + ) std.Io.Cancelable!void { + n.* += self.drainAvailable(io, batch[n.*..]); + + while (n.* < batch.len) { + const remaining = deadline.durationFromNow(io); + if (remaining.raw.nanoseconds <= 0) break; + const entry = try self.getWithin(io, remaining) orelse break; + batch[n.*] = entry; + n.* += 1; + n.* += self.drainAvailable(io, batch[n.*..]); + } + } + + /// Whatever is already queued, without blocking. + fn drainAvailable(self: *Logger, io: std.Io, room: []Entry) usize { + if (room.len == 0) return 0; + return self.queue.get(io, room, 0) catch 0; + } + + /// Races one blocking `getOne` against the rest of the flush interval — + /// `std.Io.Condition` has no timed wait, so the timer is a task. + /// + /// The loser is drained rather than discarded: a `getOne` that finishes + /// just after the timer has already taken an entry off the queue, and + /// `Select.cancelDiscard` would throw that entry away. + fn getWithin( + self: *Logger, + io: std.Io, + budget: std.Io.Clock.Duration, + ) std.Io.Cancelable!?Entry { + var outcomes: [2]Outcome = undefined; + var race: std.Io.Select(Outcome) = .init(io, &outcomes); + + race.concurrent(.entry, takeOne, .{ &self.queue, io }) catch |err| switch (err) { + // No second unit of concurrency: the caller flushes what it holds + // rather than block past the interval. + error.ConcurrencyUnavailable => return null, + }; + race.concurrent(.expiry, expire, .{ io, budget }) catch |err| switch (err) { + error.ConcurrencyUnavailable => return drainRace(&race), + }; + + const first = race.await() catch |err| { + // Teardown: the entry the getter already took has nowhere to go. + if (drainRace(&race)) |_| self.countDropped(1); + return err; + }; + const late = drainRace(&race); + return outcomeEntry(first) orelse late; + } + + /// One batch, one transaction. A batch is dropped whole on a database + /// failure: these are log rows, and blocking on them would fill the queue + /// and cost live queries instead. + fn flush( + self: *Logger, + io: std.Io, + writer: *queries_repo.BatchWriter, + entries: []const Entry, + monitor: ?*disk_monitor.Monitor, + ) std.Io.Cancelable!void { + if (entries.len == 0) return; + + if (monitor) |m| { + const pause: std.Io.Clock.Duration = .{ + .raw = .fromSeconds(gate_retry_s), + .clock = .awake, + }; + while (!m.writesAllowed()) { + _ = self.batches_gated.fetchAdd(1, .monotonic); + try pause.sleep(io); + } + } + + var rows: [flush_batch]queries_repo.Row = undefined; + for (entries, rows[0..entries.len]) |*entry, *row| row.* = toRow(entry); + + writer.writeBatch(rows[0..entries.len]) catch |err| { + scope.warn("query log batch of {d} rows dropped: {s}", .{ entries.len, @errorName(err) }); + self.countDropped(entries.len); + return; + }; + _ = self.rows_written.fetchAdd(entries.len, .monotonic); + } + + fn countDropped(self: *Logger, n: usize) void { + _ = self.queries_dropped.fetchAdd(n, .monotonic); + } +}; + +fn takeOne(queue: *EntryQueue, io: std.Io) std.Io.Cancelable!?Entry { + const entry = queue.getOne(io) catch |err| switch (err) { + error.Closed => return null, + error.Canceled => |e| return e, + }; + return entry; +} + +fn drainRace(race: *std.Io.Select(Outcome)) ?Entry { + var found: ?Entry = null; + while (race.cancel()) |outcome| { + if (outcomeEntry(outcome)) |entry| found = entry; + } + return found; +} + +fn expire(io: std.Io, budget: std.Io.Clock.Duration) std.Io.Cancelable!void { + return budget.sleep(io); +} + +fn outcomeEntry(outcome: Outcome) ?Entry { + return switch (outcome) { + .entry => |result| result catch null, + .expiry => null, + }; +} + +// --------------------------------------------------------------------------- +// tests +// --------------------------------------------------------------------------- + +const querylog_schema = @import("querylog_schema.zig"); + +const testing = std.testing; + +fn sampleEntry(timestamp: i64, domain: []const u8) Entry { + return .init(.{ + .timestamp = timestamp, + .domain = domain, + .client_ip = "192.0.2.10", + .qtype = 1, + .blocked = false, + .response_time_us = 900, + .cache_hit = false, + .upstream = "9.9.9.9", + }); +} + +fn openLog() !db.Db { + var database = try db.Db.open(":memory:", .{ .mode = .memory }); + errdefer database.close(); + try db.applyPragmas(&database, .{}); + try database.exec(querylog_schema.ddl); + return database; +} + +test "an entry carries its own bytes and reads them back" { + const entry: Entry = .init(.{ + .timestamp = 1700000000, + .domain = "ads.example.com", + .client_ip = "2001:db8::1", + .qtype = 28, + .blocked = true, + .block_reason = "blocklist", + .response_time_us = 42, + .cache_hit = true, + .upstream = "dns.example", + }); + + try testing.expectEqualStrings("ads.example.com", entry.domain()); + try testing.expectEqualStrings("2001:db8::1", entry.clientIp()); + try testing.expectEqualStrings("blocklist", entry.blockReason()); + try testing.expectEqualStrings("dns.example", entry.upstream()); + try testing.expectEqual(@as(?u16, 28), entry.qtype); + try testing.expect(entry.blocked); + try testing.expectEqual(@as(?i64, 42), entry.response_time_us); + try testing.expectEqual(@as(?bool, true), entry.cache_hit); +} + +test "an oversize string is truncated to what its buffer holds" { + const long_domain = "a" ** 400; + const entry: Entry = .init(.{ + .timestamp = 1, + .domain = long_domain, + .client_ip = "192.0.2.1", + .block_reason = "r" ** 64, + .upstream = "u" ** 128, + }); + + try testing.expectEqual(@as(usize, max_domain_len), entry.domain().len); + try testing.expectEqual(@as(usize, max_reason_len), entry.blockReason().len); + try testing.expectEqual(@as(usize, max_upstream_len), entry.upstream().len); + try testing.expectEqualStrings("a" ** max_domain_len, entry.domain()); +} + +test "toRow maps the empty strings to null and passes the rest through" { + const bare: Entry = .init(.{ + .timestamp = 7, + .domain = "example.com", + .client_ip = "192.0.2.5", + }); + const bare_row = toRow(&bare); + try testing.expectEqual(@as(i64, 7), bare_row.timestamp); + try testing.expectEqualStrings("example.com", bare_row.domain); + try testing.expectEqualStrings("192.0.2.5", bare_row.client_ip); + try testing.expectEqual(@as(?[]const u8, null), bare_row.block_reason); + try testing.expectEqual(@as(?[]const u8, null), bare_row.upstream); + try testing.expectEqual(@as(?u16, null), bare_row.qtype); + try testing.expectEqual(@as(?bool, null), bare_row.cache_hit); + + const full: Entry = .init(.{ + .timestamp = 8, + .domain = "blocked.example", + .client_ip = "192.0.2.6", + .blocked = true, + .block_reason = "blocklist", + .upstream = "9.9.9.9", + }); + const full_row = toRow(&full); + try testing.expect(full_row.blocked); + try testing.expectEqualStrings("blocklist", full_row.block_reason.?); + try testing.expectEqualStrings("9.9.9.9", full_row.upstream.?); +} + +test "log applies both privacy transforms before the entry reaches the queue" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var buf: [4]Entry = undefined; + var logger: Logger = .init(.{ .hide_domains = true, .hide_client_ips = true }, &buf); + + logger.log(io, sampleEntry(100, "tracker.example")); + + const queued = try logger.queue.getOne(io); + try testing.expectEqualStrings(hidden_marker, queued.domain()); + try testing.expectEqualStrings(hidden_marker, queued.clientIp()); + try testing.expectEqual(@as(i64, 100), queued.timestamp); + try testing.expectEqual(@as(u64, 0), logger.queries_dropped.load(.monotonic)); +} + +test "log hides only the field its switch names" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var buf: [4]Entry = undefined; + var domains_only: Logger = .init(.{ .hide_domains = true }, &buf); + domains_only.log(io, sampleEntry(1, "tracker.example")); + const hidden_domain = try domains_only.queue.getOne(io); + try testing.expectEqualStrings(hidden_marker, hidden_domain.domain()); + try testing.expectEqualStrings("192.0.2.10", hidden_domain.clientIp()); + + var clients_only: Logger = .init(.{ .hide_client_ips = true }, &buf); + clients_only.log(io, sampleEntry(2, "tracker.example")); + const hidden_client = try clients_only.queue.getOne(io); + try testing.expectEqualStrings("tracker.example", hidden_client.domain()); + try testing.expectEqualStrings(hidden_marker, hidden_client.clientIp()); + + var neither: Logger = .init(.{}, &buf); + neither.log(io, sampleEntry(3, "tracker.example")); + const untouched = try neither.queue.getOne(io); + try testing.expectEqualStrings("tracker.example", untouched.domain()); + try testing.expectEqualStrings("192.0.2.10", untouched.clientIp()); +} + +test "a full queue drops the oldest entry and counts it" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var buf: [2]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + logger.log(io, sampleEntry(1, "first.example")); + logger.log(io, sampleEntry(2, "second.example")); + logger.log(io, sampleEntry(3, "third.example")); + + try testing.expectEqual(@as(u64, 1), logger.queries_dropped.load(.monotonic)); + + const older = try logger.queue.getOne(io); + const newer = try logger.queue.getOne(io); + try testing.expectEqualStrings("second.example", older.domain()); + try testing.expectEqualStrings("third.example", newer.domain()); +} + +test "a zero-capacity queue drops every entry exactly once" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var buf: [0]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + for (0..5) |i| logger.log(io, sampleEntry(@intCast(i), "example.com")); + try testing.expectEqual(@as(u64, 5), logger.queries_dropped.load(.monotonic)); +} + +test "log after shutdown drops instead of blocking" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var buf: [4]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + logger.shutdown(io); + + logger.log(io, sampleEntry(1, "example.com")); + try testing.expectEqual(@as(u64, 1), logger.queries_dropped.load(.monotonic)); +} + +test "the writer drains every entry and shutdown ends it" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + var buf: [512]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var future = try io.concurrent(Logger.runWriter, .{ + &logger, + io, + &database, + @as(?*disk_monitor.Monitor, null), + }); + + var names: [250][32]u8 = undefined; + for (&names, 0..) |*name, i| { + const written = try std.fmt.bufPrint(name, "d{d}.example", .{i % 10}); + logger.log(io, sampleEntry(@intCast(i), written)); + } + logger.shutdown(io); + try future.await(io); + + try testing.expectEqual(@as(u64, 0), logger.queries_dropped.load(.monotonic)); + try testing.expectEqual(@as(u64, 250), logger.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 250), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(i64, 10), try queries_repo.countDomains(&database)); +} + +test "the writer flushes an entry once the interval passes" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + var buf: [8]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var future = try io.concurrent(Logger.runWriter, .{ + &logger, + io, + &database, + @as(?*disk_monitor.Monitor, null), + }); + + logger.log(io, sampleEntry(1, "only.example")); + + const poll: std.Io.Clock.Duration = .{ .raw = .fromMilliseconds(5), .clock = .awake }; + var waited: usize = 0; + while (logger.rows_written.load(.monotonic) == 0) : (waited += 1) { + // Ten times the interval; a flush that has not happened by then is a + // failure, not slowness. + try testing.expect(waited < 200); + try poll.sleep(io); + } + + logger.shutdown(io); + try future.await(io); + try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); +} + +test "a gated flush holds the batch until the disk recovers" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + var writer = try queries_repo.BatchWriter.init(&database); + defer writer.deinit(); + + var buf: [4]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); + monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); + try testing.expect(!monitor.writesAllowed()); + + const entries = [_]Entry{ sampleEntry(1, "held.example"), sampleEntry(2, "held.example") }; + var future = try io.concurrent(Logger.flush, .{ + &logger, + io, + &writer, + @as([]const Entry, &entries), + @as(?*disk_monitor.Monitor, &monitor), + }); + + const poll: std.Io.Clock.Duration = .{ .raw = .fromMilliseconds(5), .clock = .awake }; + var waited: usize = 0; + while (logger.batches_gated.load(.monotonic) == 0) : (waited += 1) { + try testing.expect(waited < 200); + try poll.sleep(io); + } + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); + + monitor.state_raw.store(@intFromEnum(disk_monitor.State.ok), .monotonic); + try future.await(io); + + try testing.expect(logger.batches_gated.load(.monotonic) >= 1); + try testing.expectEqual(@as(u64, 2), logger.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(&database)); +} + +test "a failing batch is dropped whole and the writer stays usable" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + try database.exec( + \\CREATE TRIGGER refuse_boom BEFORE INSERT ON query_log + \\WHEN new.client_ip = 'boom' + \\BEGIN SELECT RAISE(ABORT, 'refused'); END; + ); + + var writer = try queries_repo.BatchWriter.init(&database); + defer writer.deinit(); + + var buf: [4]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var doomed = sampleEntry(10, "poison.example"); + doomed.setClientIp("boom"); + const bad = [_]Entry{ sampleEntry(9, "good.example"), doomed }; + try logger.flush(io, &writer, &bad, null); + + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 0), logger.rows_written.load(.monotonic)); + try testing.expectEqual(@as(u64, 2), logger.queries_dropped.load(.monotonic)); + + const good = [_]Entry{sampleEntry(11, "next.example")}; + try logger.flush(io, &writer, &good, null); + try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 1), logger.rows_written.load(.monotonic)); +} + +test "a writer that cannot prepare closes the queue and counts every entry" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + // No schema: `BatchWriter.init` cannot prepare against a missing table. + var database = try db.Db.open(":memory:", .{ .mode = .memory }); + defer database.close(); + + var buf: [8]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + for (0..3) |i| logger.log(io, sampleEntry(@intCast(i), "early.example")); + + try logger.runWriter(io, &database, null); + + try testing.expect(logger.writer_failed.load(.acquire)); + try testing.expectEqual(@as(u64, 3), logger.queries_dropped.load(.monotonic)); + try testing.expectEqual(@as(u64, 0), logger.rows_written.load(.monotonic)); + + // The queue is closed, so later entries drop and count instead of piling up. + logger.log(io, sampleEntry(99, "late.example")); + try testing.expectEqual(@as(u64, 4), logger.queries_dropped.load(.monotonic)); +} + +test "a canceled writer counts the batch it was holding" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + var buf: [8]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); + monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); + + // Both entries are queued before the writer starts, so the batch it takes + // into the gate holds exactly two. + logger.log(io, sampleEntry(1, "held.example")); + logger.log(io, sampleEntry(2, "held.example")); + + var future = try io.concurrent(Logger.runWriter, .{ + &logger, + io, + &database, + @as(?*disk_monitor.Monitor, &monitor), + }); + + const poll: std.Io.Clock.Duration = .{ .raw = .fromMilliseconds(5), .clock = .awake }; + var waited: usize = 0; + while (logger.batches_gated.load(.monotonic) == 0) : (waited += 1) { + try testing.expect(waited < 400); + try poll.sleep(io); + } + + try testing.expectError(error.Canceled, future.cancel(io)); + + try testing.expectEqual(@as(u64, 2), logger.queries_dropped.load(.monotonic)); + try testing.expectEqual(@as(u64, 0), logger.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); +} + +test "an empty batch touches neither the database nor the counters" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + var writer = try queries_repo.BatchWriter.init(&database); + defer writer.deinit(); + + var buf: [4]Entry = undefined; + var logger: Logger = .init(.{}, &buf); + + var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); + monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); + + // Gated or not, an empty batch returns before it reads the monitor. + try logger.flush(io, &writer, &.{}, &monitor); + + try testing.expectEqual(@as(u64, 0), logger.batches_gated.load(.monotonic)); + try testing.expectEqual(@as(u64, 0), logger.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); +} diff --git a/src/storage/phase6_integration_test.zig b/src/storage/phase6_integration_test.zig new file mode 100644 index 0000000..c216627 --- /dev/null +++ b/src/storage/phase6_integration_test.zig @@ -0,0 +1,609 @@ +//! Milestone-6 integration tests (spec S8): the phase-6 components against real +//! files, a real `querylog.db`, a real filesystem sample and a real log sink. +//! +//! This lives in its own file because it needs `@import("build_options")`, which +//! only exists when the compilation is driven by `build.zig`. The body compiles +//! on every `zig build test` run, so it cannot rot, and every case skips at run +//! time unless `-Dintegration` is passed. +//! +//! Hermetic: every case works inside one `std.testing.tmpDir` and none of them +//! opens a socket or resolves a name. +//! +//! Two mechanisms resolve the same paths here. `std.Io.Dir` calls go through the +//! temporary directory handle, while SQLite and the log sink resolve their +//! filenames through the process working directory. Every path handed to those +//! two is therefore built from `Fixture.root`. + +const std = @import("std"); +const build_options = @import("build_options"); + +const dns_cache = @import("../cache/dns_cache.zig"); +const address = @import("../platform/address.zig"); +const logging = @import("../platform/logging.zig"); +const packet = @import("../dns/packet.zig"); +const rate_limiter = @import("../server/rate_limiter.zig"); +const db = @import("db.zig"); +const disk_monitor = @import("disk_monitor.zig"); +const logger = @import("logger.zig"); +const queries_repo = @import("repositories/queries_repo.zig"); +const querylog_schema = @import("querylog_schema.zig"); +const retention = @import("retention.zig"); + +const testing = std.testing; + +/// `std.testing.tmpDir` creates its directory against `std.testing.io`, so every +/// call into the code under test uses the same `Io` instance. That instance is +/// an `Io.Threaded` (`lib/std/testing.zig:34`), which is what makes +/// `io.concurrent` available to the writer-task cases. +const io = testing.io; + +// --------------------------------------------------------------------------- +// fixture +// --------------------------------------------------------------------------- + +/// Where `std.testing.tmpDir` puts its directories (`lib/std/testing.zig:634`). +const tmp_prefix = ".zig-cache/tmp/"; + +const sub_path_len = @typeInfo(@FieldType(testing.TmpDir, "sub_path")).array.len; + +const path_buf_len = 256; + +const Fixture = struct { + tmp: testing.TmpDir, + root_buf: [tmp_prefix.len + sub_path_len]u8, + + fn init() Fixture { + var self: Fixture = .{ + .tmp = testing.tmpDir(.{ .iterate = true }), + .root_buf = undefined, + }; + @memcpy(self.root_buf[0..tmp_prefix.len], tmp_prefix); + @memcpy(self.root_buf[tmp_prefix.len..], &self.tmp.sub_path); + return self; + } + + fn deinit(self: *Fixture) void { + self.tmp.cleanup(); + } + + /// The temporary directory as a path relative to the process working + /// directory. + fn root(self: *const Fixture) []const u8 { + return &self.root_buf; + } + + fn path(self: *const Fixture, buf: []u8, name: []const u8) ![]const u8 { + return std.fmt.bufPrint(buf, "{s}/{s}", .{ self.root(), name }); + } + + fn pathZ(self: *const Fixture, buf: []u8, name: []const u8) ![:0]const u8 { + return std.fmt.bufPrintZ(buf, "{s}/{s}", .{ self.root(), name }); + } + + fn rootZ(self: *const Fixture, buf: []u8) ![:0]const u8 { + return std.fmt.bufPrintZ(buf, "{s}", .{self.root()}); + } + + fn exists(self: *const Fixture, name: []const u8) !bool { + self.tmp.dir.access(io, name, .{}) catch |e| switch (e) { + error.FileNotFound => return false, + else => |other| return other, + }; + return true; + } + + fn sizeOf(self: *const Fixture, name: []const u8) !u64 { + const stat = try self.tmp.dir.statFile(io, name, .{}); + return stat.size; + } +}; + +/// A fresh `querylog.db` inside the fixture, opened the way the daemon opens it. +const QueryLog = struct { + opened: querylog_schema.OpenResult, + + fn create(f: *const Fixture) !QueryLog { + var buf: [path_buf_len]u8 = undefined; + const path = try f.pathZ(&buf, "querylog.db"); + return .{ .opened = try querylog_schema.open(io, std.Io.Dir.cwd(), path) }; + } + + fn deinit(self: *QueryLog) void { + self.opened.database.close(); + } + + fn database(self: *QueryLog) *db.Db { + return &self.opened.database; + } +}; + +fn entryAt(timestamp: i64, domain: []const u8) logger.Entry { + return .init(.{ + .timestamp = timestamp, + .domain = domain, + .client_ip = "192.0.2.10", + .qtype = 1, + .blocked = false, + .response_time_us = 1200, + .cache_hit = false, + .upstream = "9.9.9.9", + }); +} + +const poll_interval: std.Io.Clock.Duration = .{ .raw = .fromMilliseconds(5), .clock = .awake }; + +/// Waits for `counter` to reach `target`, up to `limit` polls of 5 ms. A +/// deadline that passes is a failure rather than slowness: every case here is +/// bounded well below the 2 s the spec allows. +fn awaitCount(counter: *const std.atomic.Value(u64), target: u64, limit: usize) !void { + var polls: usize = 0; + while (counter.load(.monotonic) < target) : (polls += 1) { + try testing.expect(polls < limit); + try poll_interval.sleep(io); + } +} + +fn writeRows(database: *db.Db, timestamps: []const i64, domain: []const u8) !void { + var writer = try queries_repo.BatchWriter.init(database); + defer writer.deinit(); + + var rows: [16]queries_repo.Row = undefined; + for (timestamps, rows[0..timestamps.len]) |timestamp, *row| { + row.* = .{ + .timestamp = timestamp, + .domain = domain, + .client_ip = "192.0.2.10", + .qtype = 1, + .blocked = false, + .block_reason = null, + .response_time_us = null, + .cache_hit = null, + .upstream = null, + }; + } + try writer.writeBatch(rows[0..timestamps.len]); +} + +/// The timestamps in the log, oldest first. +fn readTimestamps(database: *db.Db, out: []i64) ![]i64 { + var stmt = try database.prepare("SELECT timestamp FROM query_log ORDER BY timestamp"); + defer stmt.deinit(); + var n: usize = 0; + while (try stmt.step()) : (n += 1) { + if (n == out.len) return error.TestUnexpectedResult; + out[n] = stmt.columnInt(0); + } + return out[0..n]; +} + +// --------------------------------------------------------------------------- +// case 1-6: the query logger, retention and the disk gate on a real database +// --------------------------------------------------------------------------- + +test "S8 case 1: the logger writes a real querylog.db end to end" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + try testing.expectEqual(querylog_schema.RecreateReason.missing, log_db.opened.recreated.?); + + var queue_buf: [512]logger.Entry = undefined; + var query_log: logger.Logger = .init(.{}, &queue_buf); + + var future = try io.concurrent(logger.Logger.runWriter, .{ + &query_log, + io, + log_db.database(), + @as(?*disk_monitor.Monitor, null), + }); + + var name_buf: [32]u8 = undefined; + for (0..250) |i| { + const domain = try std.fmt.bufPrint(&name_buf, "d{d}.example", .{i % 10}); + query_log.log(io, entryAt(@intCast(i), domain)); + } + query_log.shutdown(io); + try future.await(io); + + try testing.expectEqual(@as(u64, 0), query_log.queries_dropped.load(.monotonic)); + try testing.expectEqual(@as(u64, 250), query_log.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 250), try queries_repo.countRows(log_db.database())); + try testing.expectEqual(@as(i64, 10), try queries_repo.countDomains(log_db.database())); + try testing.expectEqual( + @as(i64, querylog_schema.fingerprint), + try log_db.database().queryInt("PRAGMA user_version"), + ); +} + +test "S8 case 2: a single entry reaches the file once the flush interval passes" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + + var queue_buf: [8]logger.Entry = undefined; + var query_log: logger.Logger = .init(.{}, &queue_buf); + + var future = try io.concurrent(logger.Logger.runWriter, .{ + &query_log, + io, + log_db.database(), + @as(?*disk_monitor.Monitor, null), + }); + + query_log.log(io, entryAt(1, "only.example")); + + // Ten flush intervals of headroom: a row that has not landed by then is a + // failure of the interval race, not a slow machine. + const limit = 10 * logger.flush_interval_ms / 5; + try awaitCount(&query_log.rows_written, 1, limit); + try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(log_db.database())); + + query_log.shutdown(io); + try future.await(io); +} + +test "S8 case 3: a full queue drops the oldest entries and the newest survive" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + + var root_buf: [path_buf_len]u8 = undefined; + var monitor: disk_monitor.Monitor = .init( + .{}, + f.tmp.dir, + try f.rootZ(&root_buf), + null, + ); + monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); + + var queue_buf: [8]logger.Entry = undefined; + var query_log: logger.Logger = .init(.{}, &queue_buf); + + // The whole burst is enqueued before the writer starts. A writer already + // draining the queue would take entries out of it mid-burst and make the + // number of drops depend on the scheduler. + for (0..20) |i| query_log.log(io, entryAt(@intCast(i), "burst.example")); + try testing.expectEqual(@as(u64, 12), query_log.queries_dropped.load(.monotonic)); + + var future = try io.concurrent(logger.Logger.runWriter, .{ + &query_log, + io, + log_db.database(), + @as(?*disk_monitor.Monitor, &monitor), + }); + + try awaitCount(&query_log.batches_gated, 1, 200); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(log_db.database())); + + // Un-gate before the shutdown: a writer held by the disk gate holds its + // batch, and `shutdown` alone would never release it. + monitor.state_raw.store(@intFromEnum(disk_monitor.State.ok), .monotonic); + try awaitCount(&query_log.rows_written, 8, 300); + query_log.shutdown(io); + try future.await(io); + + var stamps: [16]i64 = undefined; + const kept = try readTimestamps(log_db.database(), &stamps); + try testing.expectEqual(@as(usize, 8), kept.len); + for (kept, 0..) |stamp, i| { + try testing.expectEqual(@as(i64, @intCast(i + 12)), stamp); + } +} + +test "S8 case 4: the privacy transforms reach the stored rows" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + + var queue_buf: [64]logger.Entry = undefined; + var query_log: logger.Logger = .init( + .{ .hide_domains = true, .hide_client_ips = true }, + &queue_buf, + ); + + var future = try io.concurrent(logger.Logger.runWriter, .{ + &query_log, + io, + log_db.database(), + @as(?*disk_monitor.Monitor, null), + }); + + var name_buf: [32]u8 = undefined; + for (0..20) |i| { + const domain = try std.fmt.bufPrint(&name_buf, "private{d}.example", .{i}); + query_log.log(io, entryAt(@intCast(i), domain)); + } + query_log.shutdown(io); + try future.await(io); + + try testing.expectEqual(@as(i64, 20), try queries_repo.countRows(log_db.database())); + // Every name collapsed onto the marker, so the dimension table holds one row. + try testing.expectEqual(@as(i64, 1), try queries_repo.countDomains(log_db.database())); + try testing.expectEqual( + @as(i64, 20), + try log_db.database().queryInt( + \\SELECT count(*) FROM query_log q JOIN domains d ON d.id = q.domain_id + \\ WHERE d.domain = 'hidden' AND q.client_ip = 'hidden' + ), + ); +} + +test "S8 case 5: a retention pass prunes the old rows and truncates the write-ahead log" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + + const now = std.Io.Clock.real.now(io).toSeconds(); + const day = 86_400; + try writeRows(log_db.database(), &.{ now - 40 * day, now - 31 * day }, "old.example"); + try writeRows(log_db.database(), &.{ now - 3 * day, now - 60 }, "fresh.example"); + try testing.expectEqual(@as(i64, 4), try queries_repo.countRows(log_db.database())); + try testing.expect(try f.sizeOf("querylog.db-wal") > 0); + + var pass: retention.Retention = .init(.{ .retention_days = 30 }); + pass.runOnce(io, log_db.database()); + + try testing.expectEqual(@as(u64, 1), pass.stats.passes); + try testing.expectEqual(@as(u64, 2), pass.stats.rows_pruned); + try testing.expectEqual(@as(u64, 1), pass.stats.checkpoints); + try testing.expectEqual(@as(u64, 0), pass.stats.vacuums); + try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(log_db.database())); + // Both names stay: the dimension table is not collected. + try testing.expectEqual(@as(i64, 2), try queries_repo.countDomains(log_db.database())); + + if (try f.exists("querylog.db-wal")) { + try testing.expectEqual(@as(u64, 0), try f.sizeOf("querylog.db-wal")); + } +} + +test "S8 case 6: a critical disk gates the flushes and recovery releases them" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var log_db = try QueryLog.create(&f); + defer log_db.deinit(); + + var root_buf: [path_buf_len]u8 = undefined; + const data_path = try f.rootZ(&root_buf); + + // No filesystem holds this much free space, so the sample classifies + // critical against the real `statvfs` reading rather than a stub. + const unreachable_mb = std.math.maxInt(u32); + var monitor: disk_monitor.Monitor = .init( + .{ .min_free_mb = unreachable_mb, .warn_free_mb = unreachable_mb }, + f.tmp.dir, + data_path, + null, + ); + monitor.sample(io); + try testing.expectEqual(disk_monitor.State.critical, monitor.state()); + try testing.expect(!monitor.writesAllowed()); + try testing.expect(monitor.gauges().free_bytes > 0); + try testing.expect(monitor.gauges().db_bytes > 0); + + var queue_buf: [64]logger.Entry = undefined; + var query_log: logger.Logger = .init(.{}, &queue_buf); + for (0..5) |i| query_log.log(io, entryAt(@intCast(i), "gated.example")); + + var future = try io.concurrent(logger.Logger.runWriter, .{ + &query_log, + io, + log_db.database(), + @as(?*disk_monitor.Monitor, &monitor), + }); + + try awaitCount(&query_log.batches_gated, 1, 200); + try testing.expectEqual(@as(u64, 0), query_log.rows_written.load(.monotonic)); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(log_db.database())); + + monitor.cfg = .{ .min_free_mb = 0, .warn_free_mb = 0 }; + monitor.sample(io); + try testing.expectEqual(disk_monitor.State.ok, monitor.state()); + try testing.expect(monitor.writesAllowed()); + + // The gate re-reads the monitor once per `gate_retry_s`, so the release + // costs at most that one second. + const limit = (logger.gate_retry_s * 1000 + 500) / 5; + try awaitCount(&query_log.rows_written, 5, limit); + + query_log.shutdown(io); + try future.await(io); + + try testing.expect(query_log.batches_gated.load(.monotonic) > 0); + try testing.expectEqual(@as(i64, 5), try queries_repo.countRows(log_db.database())); + try testing.expectEqual(@as(u64, 0), monitor.sample_failures.load(.monotonic)); +} + +// --------------------------------------------------------------------------- +// case 7: the log sink against a real file +// --------------------------------------------------------------------------- + +test "S8 case 7: the log sink appends, rotates and honours max_files" { + if (!build_options.integration) return error.SkipZigTest; + + var f: Fixture = .init(); + defer f.deinit(); + + var path_buf: [path_buf_len]u8 = undefined; + const log_path = try f.path(&path_buf, "nxdns.log"); + + const before = logging.stats(); + + // `install` would take the 1 MiB floor of `max_size_mb`, which is a + // megabyte of writes per generation; `installForTest` overrides that one + // threshold and nothing else. + const max_bytes = 256; + logging.installForTest(io, .{ + .level = .info, + .output = .file, + .file_path = log_path, + .max_files = 3, + }, max_bytes); + defer logging.deinstall(); + + // `logFn` is called directly: the test runner installs its own + // `std_options`, so a `std.log` call here would never reach this sink. + for (0..40) |i| logging.logFn(.warn, .s8_sink, "rotation line {d}", .{i}); + for (0..5) |i| logging.logFn(.info, .s8_sink, "tail line {d}", .{i}); + // Below the configured threshold, so it is filtered rather than written. + logging.logFn(.debug, .s8_sink, "never written", .{}); + + logging.deinstall(); + + const after = logging.stats(); + try testing.expectEqual(@as(u64, 45), after.lines_written - before.lines_written); + try testing.expect(after.rotations > before.rotations); + try testing.expectEqual(@as(u64, 0), after.sink_errors - before.sink_errors); + try testing.expectEqual(@as(u64, 0), after.lines_deduped - before.lines_deduped); + + try testing.expect(try f.exists("nxdns.log")); + try testing.expect(try f.sizeOf("nxdns.log") <= max_bytes); + try testing.expect(try f.exists("nxdns.log.1")); + try testing.expect(try f.exists("nxdns.log.2")); + // `max_files` counts the live file, so generation 3 is never created. + try testing.expect(!try f.exists("nxdns.log.3")); + + // The live file holds the newest lines, and it is reopened rather than + // truncated: a second install appends behind what is already there. + const kept = try f.tmp.dir.readFileAlloc(io, "nxdns.log", testing.allocator, .limited(4096)); + defer testing.allocator.free(kept); + try testing.expect(std.mem.count(u8, kept, "tail line 4") == 1); + try testing.expect(std.mem.count(u8, kept, "(s8_sink)") >= 1); + + const live_bytes = kept.len; + logging.installForTest(io, .{ + .level = .info, + .output = .file, + .file_path = log_path, + .max_files = 3, + }, max_bytes * 16); + logging.logFn(.info, .s8_sink, "after reopen", .{}); + logging.deinstall(); + + const reopened = try f.tmp.dir.readFileAlloc(io, "nxdns.log", testing.allocator, .limited(8192)); + defer testing.allocator.free(reopened); + try testing.expect(reopened.len > live_bytes); + try testing.expectEqualStrings(kept, reopened[0..live_bytes]); + try testing.expect(std.mem.count(u8, reopened, "after reopen") == 1); +} + +// --------------------------------------------------------------------------- +// case 8-9: the pure components against real packets and real addresses +// --------------------------------------------------------------------------- + +/// A NOERROR response for example.com A carrying one answer per TTL. +fn buildAnswer(buf: []u8, ttls: []const u32) ![]u8 { + const query = "\x12\x34\x01\x00\x00\x01\x00\x00\x00\x00\x00\x00" ++ + "\x07example\x03com\x00\x00\x01\x00\x01"; + const request = try packet.parse(query); + const q = packet.firstQuestion(request).?; + + var builder = try packet.ResponseBuilder.init(buf, request.header, q); + for (ttls) |ttl| { + try builder.addAnswer(q.name, .a, .in, ttl, "\x0a\x00\x00\x01"); + } + return builder.finish(); +} + +fn firstAnswerTtl(bytes: []const u8) !u32 { + const p = try packet.parse(bytes); + var it = packet.answers(p); + return (try it.next()).?.ttl; +} + +test "S8 case 8: the cache ages a real response and expires it at the boundary" { + if (!build_options.integration) return error.SkipZigTest; + + var response_buf: [512]u8 = undefined; + const response = try buildAnswer(&response_buf, &.{ 300, 600 }); + const class = dns_cache.classify(response, 3600).?; + try testing.expectEqual(@as(u32, 300), class.ttl_seconds); + try testing.expectEqual(false, class.negative); + + var cache = try dns_cache.DnsCache.init(testing.allocator, .{ .size = 16, .negative_ttl_max = 3600 }); + defer cache.deinit(); + + var key_buf: [dns_cache.max_key_len]u8 = undefined; + const key = dns_cache.buildKey(&key_buf, "example.com", 1, 1, false, null); + + try cache.put(1000, key, response, class); + try testing.expectEqual(@as(u32, 1), cache.len()); + + var out: [512]u8 = undefined; + const hit = cache.get(1120, key, &out).?; + try testing.expectEqual(response.len, hit.len); + try testing.expectEqual(@as(u32, 180), try firstAnswerTtl(hit)); + + // The stored copy keeps its own age, so a later hit ages from the same base. + const later = cache.get(1290, key, &out).?; + try testing.expectEqual(@as(u32, 10), try firstAnswerTtl(later)); + + // The transaction ID is the caller's to set, and the aged bytes still parse. + packet.setId(later, 0xbeef); + try testing.expectEqual(@as(u16, 0xbeef), (try packet.parse(later)).header.id); + + // The entry expires at stored_at + ttl, and that second is already too late. + try testing.expectEqual(@as(?[]u8, null), cache.get(1300, key, &out)); + try testing.expectEqual(@as(u32, 0), cache.len()); + try testing.expectEqual(@as(u64, 2), cache.stats.hits); + try testing.expectEqual(@as(u64, 1), cache.stats.expirations); +} + +test "S8 case 9: the limiter refuses the query past the limit and only that client" { + if (!build_options.integration) return error.SkipZigTest; + + var limiter = try rate_limiter.RateLimiter.init( + testing.allocator, + .{ .limit = 1000, .window_seconds = 60 }, + ); + defer limiter.deinit(); + + const mapped = address.NetAddress.fromIp( + try std.Io.net.IpAddress.parse("::ffff:192.168.1.40", 53), + ).key(); + const plain = (try address.NetAddress.parse("192.168.1.40")).key(); + // One client, whichever family the socket reported it under. + try testing.expectEqualSlices(u8, &plain, &mapped); + + const start: std.Io.Timestamp = .{ .nanoseconds = 1 << 80 }; + for (0..1000) |i| { + const now: std.Io.Timestamp = .{ .nanoseconds = start.nanoseconds + @as(i96, @intCast(i)) }; + try testing.expect(limiter.check(now, mapped)); + } + try testing.expect(!limiter.check(start, plain)); + + try testing.expectEqual(@as(u64, 1000), limiter.stats.allowed); + try testing.expectEqual(@as(u64, 1), limiter.stats.refused); + try testing.expectEqual(@as(u64, 0), limiter.stats.untracked); + try testing.expectEqual(@as(u32, 1), limiter.trackedClients()); + + const other = (try address.NetAddress.parse("fd00::40")).key(); + try testing.expect(limiter.check(start, other)); + try testing.expectEqual(@as(u32, 2), limiter.trackedClients()); + + // The next window admits the refused client again. + const next: std.Io.Timestamp = .{ .nanoseconds = start.nanoseconds + 60 * std.time.ns_per_s }; + try testing.expect(limiter.check(next, mapped)); + try testing.expectEqual(@as(u64, 1), limiter.stats.refused); +} diff --git a/src/storage/repositories/queries_repo.zig b/src/storage/repositories/queries_repo.zig new file mode 100644 index 0000000..04c64e2 --- /dev/null +++ b/src/storage/repositories/queries_repo.zig @@ -0,0 +1,468 @@ +//! `query_log` and its `domains` dimension table in `querylog.db`. +//! +//! Two shapes live here. The free functions follow the milestone-4 repository +//! idiom — prepare, use, finalize — because retention runs them a handful of +//! times per day. The flush loop is the one hot path in the program, so it gets +//! `BatchWriter`, which owns its three statements for its whole life +//! (`db.zig:360` names this file as the reason `db.zig` carries no statement +//! cache). +//! +//! Every string in a `Row` is borrowed for the duration of the call only: +//! `Stmt.bindText` binds with `SQLITE_TRANSIENT`, so SQLite copies before +//! `writeBatch` returns. +//! +//! The rows are expendable log data. Nothing here retries, and the caller +//! decides what a failed batch means. + +const std = @import("std"); + +const db = @import("../db.zig"); + +/// One `query_log` row. The logger applies the privacy transforms of PLAN +/// §11.4 before it builds this, so `domain` and `client_ip` are already +/// whatever the operator agreed to store. +pub const Row = struct { + timestamp: i64, + domain: []const u8, + client_ip: []const u8, + qtype: ?u16, + blocked: bool, + block_reason: ?[]const u8, + response_time_us: ?i64, + cache_hit: ?bool, + upstream: ?[]const u8, +}; + +const insert_domain_sql = "INSERT OR IGNORE INTO domains (domain) VALUES (?1)"; + +const select_domain_sql = "SELECT id FROM domains WHERE domain = ?1"; + +const insert_row_sql = + \\INSERT INTO query_log + \\ (timestamp, domain_id, client_ip, qtype, blocked, block_reason, + \\ response_time_us, cache_hit, upstream) + \\VALUES (?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9) +; + +/// Owns the prepared statements of the flush loop. Init once, reuse per batch. +/// +/// `database` must outlive the writer and must not move: every `Stmt` holds a +/// `*Db`. Neither `Db` nor `Stmt` is thread-safe, so one writer belongs to one +/// task. +pub const BatchWriter = struct { + database: *db.Db, + insert_domain: db.Stmt, + select_domain: db.Stmt, + insert_row: db.Stmt, + + pub fn init(database: *db.Db) db.Error!BatchWriter { + var insert_domain = try database.prepare(insert_domain_sql); + errdefer insert_domain.deinit(); + var select_domain = try database.prepare(select_domain_sql); + errdefer select_domain.deinit(); + const insert_row = try database.prepare(insert_row_sql); + return .{ + .database = database, + .insert_domain = insert_domain, + .select_domain = select_domain, + .insert_row = insert_row, + }; + } + + pub fn deinit(self: *BatchWriter) void { + self.insert_row.deinit(); + self.select_domain.deinit(); + self.insert_domain.deinit(); + } + + /// One transaction for the whole batch. Domains are interned through + /// `INSERT OR IGNORE` followed by `SELECT id`. + /// + /// On any failure the transaction rolls back, so a batch is all or + /// nothing, and the writer stays usable for the next batch. + pub fn writeBatch(self: *BatchWriter, rows: []const Row) db.Error!void { + if (rows.len == 0) return; + + var tx = try db.Tx.begin(self.database); + // `errdefer`s run in reverse: the statements are released before the + // ROLLBACK, so no read cursor is still open when it runs. + errdefer tx.rollback(); + errdefer self.resetAll(); + + for (rows) |row| { + const domain_id = try self.internDomain(row.domain); + try self.write(row, domain_id); + } + try tx.commit(); + } + + fn internDomain(self: *BatchWriter, domain: []const u8) db.Error!i64 { + try self.insert_domain.reset(); + try self.insert_domain.bindText(1, domain); + try self.insert_domain.exec(); + + try self.select_domain.reset(); + try self.select_domain.bindText(1, domain); + // The insert above either created the row or found it already there, + // so a miss means the table changed under this connection. + if (!try self.select_domain.step()) return error.NotFound; + const id = self.select_domain.columnInt(0); + // A statement stopped on a row keeps its cursor open until it is + // reset; the transaction must not carry that to the next row. + try self.select_domain.reset(); + return id; + } + + fn write(self: *BatchWriter, row: Row, domain_id: i64) db.Error!void { + var stmt = &self.insert_row; + try stmt.reset(); + try stmt.bindInt(1, row.timestamp); + try stmt.bindInt(2, domain_id); + try stmt.bindText(3, row.client_ip); + try bindIntOrNull(stmt, 4, if (row.qtype) |v| @as(i64, v) else null); + try stmt.bindBool(5, row.blocked); + try stmt.bindTextOrNull(6, row.block_reason); + try bindIntOrNull(stmt, 7, row.response_time_us); + try bindIntOrNull(stmt, 8, if (row.cache_hit) |v| @as(i64, @intFromBool(v)) else null); + try stmt.bindTextOrNull(9, row.upstream); + try stmt.exec(); + } + + /// Best effort: this runs on the failure path, where the error that + /// matters is the one already on its way to the caller. + fn resetAll(self: *BatchWriter) void { + self.insert_row.reset() catch {}; + self.select_domain.reset() catch {}; + self.insert_domain.reset() catch {}; + } +}; + +fn bindIntOrNull(stmt: *db.Stmt, idx: c_int, value: ?i64) db.Error!void { + if (value) |v| return stmt.bindInt(idx, v); + return stmt.bindNull(idx); +} + +/// Deletes every `query_log` row strictly older than `cutoff_ts` and returns +/// how many went. +/// +/// Orphaned `domains` rows stay: it is a dimension table, re-interning a name +/// costs one indexed insert, and §11.3 asks for no collection. +pub fn pruneOlderThan(database: *db.Db, cutoff_ts: i64) db.Error!i64 { + var stmt = try database.prepare("DELETE FROM query_log WHERE timestamp < ?1"); + defer stmt.deinit(); + try stmt.bindInt(1, cutoff_ts); + try stmt.exec(); + return database.changes(); +} + +/// `PRAGMA wal_checkpoint(TRUNCATE)`: moves the WAL into the database and +/// truncates it to zero bytes, which is what keeps a day of log writes from +/// growing the WAL past the free space the disk monitor watches. +/// +/// SQLite reports a checkpoint blocked by a concurrent reader in the row it +/// returns, not as an error code, so a blocked checkpoint is not an error +/// here. Retention checkpoints after every prune, so the next pass retries. +/// On a database that is not in WAL mode the pragma is a no-op. +pub fn checkpointTruncate(database: *db.Db) db.Error!void { + return database.exec("PRAGMA wal_checkpoint(TRUNCATE);"); +} + +/// Rewrites the whole file. Retention runs this rarely by design — on an SD +/// card a full rewrite is the most expensive thing this program does. +pub fn vacuum(database: *db.Db) db.Error!void { + return database.exec("VACUUM;"); +} + +pub fn countRows(database: *db.Db) db.Error!i64 { + return database.queryInt("SELECT count(*) FROM query_log"); +} + +pub fn countDomains(database: *db.Db) db.Error!i64 { + return database.queryInt("SELECT count(*) FROM domains"); +} + +// --------------------------------------------------------------------------- +// tests +// --------------------------------------------------------------------------- + +const querylog_schema = @import("../querylog_schema.zig"); + +const testing = std.testing; + +fn openLog() !db.Db { + var database = try db.Db.open(":memory:", .{ .mode = .memory }); + errdefer database.close(); + try db.applyPragmas(&database, .{}); + try database.exec(querylog_schema.ddl); + return database; +} + +fn plainRow(timestamp: i64, domain: []const u8) Row { + return .{ + .timestamp = timestamp, + .domain = domain, + .client_ip = "192.0.2.10", + .qtype = 1, + .blocked = false, + .block_reason = null, + .response_time_us = 1200, + .cache_hit = false, + .upstream = "9.9.9.9", + }; +} + +fn domainIdOf(database: *db.Db, domain: []const u8) !i64 { + var stmt = try database.prepare(select_domain_sql); + defer stmt.deinit(); + try stmt.bindText(1, domain); + try testing.expect(try stmt.step()); + return stmt.columnInt(0); +} + +test "writeBatch inserts every row and interns each domain once" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try writer.writeBatch(&.{ + plainRow(100, "example.com"), + plainRow(101, "example.com"), + plainRow(102, "ads.example.net"), + }); + + try testing.expectEqual(@as(i64, 3), try countRows(&database)); + try testing.expectEqual(@as(i64, 2), try countDomains(&database)); + + const first = try domainIdOf(&database, "example.com"); + try testing.expectEqual( + @as(i64, 2), + try database.queryInt("SELECT count(*) FROM query_log WHERE domain_id = 1"), + ); + try testing.expectEqual(@as(i64, 1), first); +} + +test "a second batch reuses the interned domain id" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try writer.writeBatch(&.{plainRow(100, "example.com")}); + const before = try domainIdOf(&database, "example.com"); + + try writer.writeBatch(&.{ plainRow(200, "example.com"), plainRow(201, "other.example") }); + const after = try domainIdOf(&database, "example.com"); + + try testing.expectEqual(before, after); + try testing.expectEqual(@as(i64, 3), try countRows(&database)); + try testing.expectEqual(@as(i64, 2), try countDomains(&database)); + try testing.expectEqual( + @as(i64, 2), + try database.queryInt("SELECT count(*) FROM query_log WHERE domain_id = 1"), + ); +} + +test "nullable columns round-trip a value and a null" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try writer.writeBatch(&.{ + .{ + .timestamp = 10, + .domain = "blocked.example", + .client_ip = "2001:db8::1", + .qtype = 28, + .blocked = true, + .block_reason = "blocklist", + .response_time_us = 42, + .cache_hit = true, + .upstream = "dns.example", + }, + .{ + .timestamp = 11, + .domain = "quiet.example", + .client_ip = "hidden", + .qtype = null, + .blocked = false, + .block_reason = null, + .response_time_us = null, + .cache_hit = null, + .upstream = null, + }, + }); + + var stmt = try database.prepare( + \\SELECT d.domain, q.client_ip, q.qtype, q.blocked, q.block_reason, + \\ q.response_time_us, q.cache_hit, q.upstream + \\ FROM query_log q JOIN domains d ON d.id = q.domain_id + \\ ORDER BY q.timestamp + ); + defer stmt.deinit(); + + try testing.expect(try stmt.step()); + try testing.expectEqualStrings("blocked.example", stmt.columnText(0)); + try testing.expectEqualStrings("2001:db8::1", stmt.columnText(1)); + try testing.expectEqual(@as(i64, 28), stmt.columnInt(2)); + try testing.expect(stmt.columnBool(3)); + try testing.expectEqualStrings("blocklist", stmt.columnText(4)); + try testing.expectEqual(@as(i64, 42), stmt.columnInt(5)); + try testing.expect(stmt.columnBool(6)); + try testing.expectEqualStrings("dns.example", stmt.columnText(7)); + + try testing.expect(try stmt.step()); + try testing.expectEqualStrings("quiet.example", stmt.columnText(0)); + try testing.expectEqualStrings("hidden", stmt.columnText(1)); + try testing.expect(stmt.isNull(2)); + try testing.expect(!stmt.columnBool(3)); + try testing.expect(stmt.isNull(4)); + try testing.expect(stmt.isNull(5)); + try testing.expect(stmt.isNull(6)); + try testing.expect(stmt.isNull(7)); + + try testing.expect(!try stmt.step()); +} + +test "an empty batch writes nothing and opens no transaction" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + // A transaction is already open, so a `BEGIN IMMEDIATE` from `writeBatch` + // would fail: this is what proves the empty batch returns before it. + var tx = try db.Tx.begin(&database); + try writer.writeBatch(&.{}); + tx.rollback(); + + try testing.expectEqual(@as(i64, 0), try countRows(&database)); + try testing.expectEqual(@as(i64, 0), try countDomains(&database)); +} + +test "pruneOlderThan deletes strictly older rows and returns the count" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try writer.writeBatch(&.{ + plainRow(100, "old.example"), + plainRow(199, "old.example"), + plainRow(200, "edge.example"), + plainRow(300, "fresh.example"), + }); + + try testing.expectEqual(@as(i64, 2), try pruneOlderThan(&database, 200)); + try testing.expectEqual(@as(i64, 2), try countRows(&database)); + // The row exactly at the cutoff stays. + try testing.expectEqual( + @as(i64, 1), + try database.queryInt("SELECT count(*) FROM query_log WHERE timestamp = 200"), + ); + // A second pass over the same cutoff finds nothing left to do. + try testing.expectEqual(@as(i64, 0), try pruneOlderThan(&database, 200)); +} + +test "pruneOlderThan leaves the domains dimension table intact" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try writer.writeBatch(&.{ plainRow(10, "a.example"), plainRow(11, "b.example") }); + try testing.expectEqual(@as(i64, 2), try pruneOlderThan(&database, 1000)); + + try testing.expectEqual(@as(i64, 0), try countRows(&database)); + try testing.expectEqual(@as(i64, 2), try countDomains(&database)); +} + +test "a failing row rolls the whole batch back and the writer survives it" { + var database = try openLog(); + defer database.close(); + try database.exec( + \\CREATE TRIGGER refuse_boom BEFORE INSERT ON query_log + \\WHEN new.client_ip = 'boom' + \\BEGIN SELECT RAISE(ABORT, 'refused'); END; + ); + + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + var doomed = plainRow(20, "second.example"); + doomed.client_ip = "boom"; + try testing.expectError(error.Constraint, writer.writeBatch(&.{ + plainRow(10, "first.example"), + doomed, + })); + + // The interned domain of the row that did insert is gone with it. + try testing.expectEqual(@as(i64, 0), try countRows(&database)); + try testing.expectEqual(@as(i64, 0), try countDomains(&database)); + + try writer.writeBatch(&.{plainRow(30, "third.example")}); + try testing.expectEqual(@as(i64, 1), try countRows(&database)); + try testing.expectEqual(@as(i64, 1), try countDomains(&database)); +} + +test "countRows and countDomains agree with what the batches wrote" { + var database = try openLog(); + defer database.close(); + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + + try testing.expectEqual(@as(i64, 0), try countRows(&database)); + try testing.expectEqual(@as(i64, 0), try countDomains(&database)); + + var rows: [50]Row = undefined; + var names: [50][16]u8 = undefined; + for (&rows, &names, 0..) |*row, *name, i| { + const written = std.fmt.bufPrint(name, "d{d}.example", .{i % 7}) catch unreachable; + row.* = plainRow(@intCast(i), written); + } + try writer.writeBatch(&rows); + + try testing.expectEqual(@as(i64, 50), try countRows(&database)); + try testing.expectEqual(@as(i64, 7), try countDomains(&database)); +} + +// `PRAGMA wal_checkpoint` needs a real WAL, which an in-memory database cannot +// have. `std.testing.tmpDir` creates its directory under `.zig-cache/tmp/` +// relative to the process working directory, which is also how SQLite's VFS +// resolves the filename it is handed (`storage_integration_test.zig:44`). +const tmp_prefix = ".zig-cache/tmp/"; +const sub_path_len = @typeInfo(@FieldType(testing.TmpDir, "sub_path")).array.len; + +test "checkpointTruncate and vacuum run against a WAL file database" { + var tmp = testing.tmpDir(.{}); + defer tmp.cleanup(); + + var path_buf: [tmp_prefix.len + sub_path_len + 32]u8 = undefined; + const path = try std.fmt.bufPrintZ(&path_buf, "{s}{s}/querylog.db", .{ tmp_prefix, &tmp.sub_path }); + + var database = try db.Db.open(path, .{ .mode = .read_write_create }); + defer database.close(); + try db.applyPragmas(&database, .{}); + { + var stmt = try database.prepare("PRAGMA journal_mode"); + defer stmt.deinit(); + try testing.expect(try stmt.step()); + // `columnText` is borrowed until the next call on the statement, so it + // is compared here rather than carried out of this block. + try testing.expectEqualStrings("wal", stmt.columnText(0)); + } + try database.exec(querylog_schema.ddl); + + var writer = try BatchWriter.init(&database); + defer writer.deinit(); + try writer.writeBatch(&.{ plainRow(10, "a.example"), plainRow(20, "b.example") }); + + try checkpointTruncate(&database); + try testing.expectEqual(@as(i64, 1), try pruneOlderThan(&database, 20)); + try checkpointTruncate(&database); + try vacuum(&database); + + try testing.expectEqual(@as(i64, 1), try countRows(&database)); + try testing.expectEqual(@as(i64, 2), try countDomains(&database)); +} diff --git a/src/storage/retention.zig b/src/storage/retention.zig new file mode 100644 index 0000000..1ed2435 --- /dev/null +++ b/src/storage/retention.zig @@ -0,0 +1,284 @@ +//! Query-log retention (PLAN §11.5): a daily pass over `querylog.db` that +//! deletes rows older than `logging.retention_days`, truncates the WAL, and +//! rewrites the file on every seventh pass. +//! +//! The pass touches `querylog.db` only. §3.6 walls `config.db` off from +//! retention churn, and the `hand_edited=0` client rows of §7.2 are pruned by +//! whatever creates them, which is Phase 7. +//! +//! Nothing here retries within a pass. A failed step logs at `warn` and the +//! next pass, a day later, does the same work again against the same data. + +const std = @import("std"); + +const db = @import("db.zig"); +const model = @import("../config/model.zig"); +const queries_repo = @import("repositories/queries_repo.zig"); + +const log = std.log.scoped(.retention); + +/// A full `VACUUM` rewrites the whole database file. On the SD card of a +/// household box that is the most expensive write this program makes, so it +/// runs on every seventh pass rather than every night. +pub const vacuum_every_passes = 7; + +/// One day. `retention_days` is the finest granularity the configuration +/// expresses, so a finer schedule would prune nothing new. +pub const pass_interval_s = 86_400; + +pub const Stats = struct { + passes: u64 = 0, + rows_pruned: u64 = 0, + checkpoints: u64 = 0, + vacuums: u64 = 0, +}; + +pub const Retention = struct { + cfg: model.Logging, + stats: Stats, + + pub fn init(cfg: model.Logging) Retention { + return .{ .cfg = cfg, .stats = .{} }; + } + + /// One pass: prune, checkpoint, and on every seventh pass vacuum. + /// + /// The three steps are independent. A failed prune does not skip the + /// checkpoint, because the WAL that the checkpoint truncates was filled by + /// the query logger rather than by this pass. + /// + /// Every failure is a database error, and every database error logs at + /// `warn` and leaves the pass counted as done: a pass that returned early + /// on the first failure would still be a day away from its retry. + /// + /// `database` must be a connection no other task uses; see `run`. + pub fn runOnce(self: *Retention, io: std.Io, database: *db.Db) void { + self.stats.passes += 1; + const cutoff = std.Io.Clock.real.now(io).toSeconds() - model.retentionSeconds(self.cfg); + + if (queries_repo.pruneOlderThan(database, cutoff)) |deleted| { + self.stats.rows_pruned += @intCast(deleted); + } else |err| { + log.warn("retention prune before {d} failed: {s}", .{ cutoff, @errorName(err) }); + } + + if (queries_repo.checkpointTruncate(database)) { + self.stats.checkpoints += 1; + } else |err| { + log.warn("retention checkpoint failed: {s}", .{@errorName(err)}); + } + + if (self.stats.passes % vacuum_every_passes != 0) return; + if (queries_repo.vacuum(database)) { + self.stats.vacuums += 1; + } else |err| { + log.warn("retention vacuum failed: {s}", .{@errorName(err)}); + } + } + + /// Daily loop, first pass immediately. Phase 7 starts it. + /// + /// `boot` rather than `awake`: a box that suspends overnight must still see + /// its day elapse. + /// + /// `database` must be a connection dedicated to retention: no other task + /// may use the same handle while this loop runs. `FULLMUTEX` (`db.zig:218`) + /// serializes one SQLite call against another, but a transaction is + /// connection state, not call state. On a handle shared with the query + /// logger's writer, a prune that lands between that writer's BEGIN and + /// COMMIT runs inside the writer's transaction and commits or rolls back + /// with the batch, and a checkpoint or a `VACUUM` can land inside a + /// transaction that is still open. + /// + /// Retention takes `database` per call and opens nothing itself; Phase 7 + /// opens the second connection. Isolation across the two connections is + /// SQLite's own — WAL plus the `busy_timeout` of `db.zig`'s open options — + /// so a pass that still loses a race sees `error.Busy` or `error.Locked`, + /// logs at `warn`, and repeats the work on the next interval. + pub fn run(self: *Retention, io: std.Io, database: *db.Db) std.Io.Cancelable!void { + const interval: std.Io.Clock.Duration = .{ + .raw = .fromSeconds(pass_interval_s), + .clock = .boot, + }; + while (true) { + self.runOnce(io, database); + try interval.sleep(io); + } + } +}; + +// --------------------------------------------------------------------------- +// tests +// --------------------------------------------------------------------------- + +const querylog_schema = @import("querylog_schema.zig"); + +const testing = std.testing; + +fn openLog() !db.Db { + var database = try db.Db.open(":memory:", .{ .mode = .memory }); + errdefer database.close(); + try db.applyPragmas(&database, .{}); + try database.exec(querylog_schema.ddl); + return database; +} + +fn writeRows(database: *db.Db, timestamps: []const i64) !void { + var writer = try queries_repo.BatchWriter.init(database); + defer writer.deinit(); + var rows: [8]queries_repo.Row = undefined; + for (timestamps, rows[0..timestamps.len]) |timestamp, *row| { + row.* = .{ + .timestamp = timestamp, + .domain = "example.com", + .client_ip = "192.0.2.10", + .qtype = 1, + .blocked = false, + .block_reason = null, + .response_time_us = null, + .cache_hit = null, + .upstream = null, + }; + } + try writer.writeBatch(rows[0..timestamps.len]); +} + +test "a pass prunes the rows past the retention window and keeps the rest" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + const now = std.Io.Clock.real.now(io).toSeconds(); + const day = 86_400; + try writeRows(&database, &.{ now - 40 * day, now - 31 * day, now - 29 * day, now - 60 }); + + var retention: Retention = .init(.{ .retention_days = 30 }); + retention.runOnce(io, &database); + + try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 1), retention.stats.passes); + try testing.expectEqual(@as(u64, 2), retention.stats.rows_pruned); + try testing.expectEqual(@as(u64, 1), retention.stats.checkpoints); + try testing.expectEqual(@as(u64, 0), retention.stats.vacuums); +} + +test "the cutoff follows retention_days" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + const now = std.Io.Clock.real.now(io).toSeconds(); + const day = 86_400; + // The same row is inside the window of one configuration and outside the + // window of the other. + try writeRows(&database, &.{now - 3 * day}); + + var keeps: Retention = .init(.{ .retention_days = 7 }); + keeps.runOnce(io, &database); + try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 0), keeps.stats.rows_pruned); + + var prunes: Retention = .init(.{ .retention_days = 1 }); + prunes.runOnce(io, &database); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 1), prunes.stats.rows_pruned); +} + +test "the seventh pass vacuums and the six before it do not" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + var retention: Retention = .init(.{}); + for (0..6) |_| { + retention.runOnce(io, &database); + try testing.expectEqual(@as(u64, 0), retention.stats.vacuums); + } + retention.runOnce(io, &database); + + try testing.expectEqual(@as(u64, 7), retention.stats.passes); + try testing.expectEqual(@as(u64, 1), retention.stats.vacuums); + try testing.expectEqual(@as(u64, 7), retention.stats.checkpoints); + + for (0..7) |_| retention.runOnce(io, &database); + try testing.expectEqual(@as(u64, 14), retention.stats.passes); + try testing.expectEqual(@as(u64, 2), retention.stats.vacuums); +} + +test "a pass over an empty database still counts" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + var retention: Retention = .init(.{}); + retention.runOnce(io, &database); + + try testing.expectEqual(@as(u64, 1), retention.stats.passes); + try testing.expectEqual(@as(u64, 0), retention.stats.rows_pruned); + try testing.expectEqual(@as(u64, 1), retention.stats.checkpoints); + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); +} + +test "a failing prune counts the pass and leaves the rows alone" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + const now = std.Io.Clock.real.now(io).toSeconds(); + try writeRows(&database, &.{now - 40 * 86_400}); + try database.exec( + \\CREATE TRIGGER refuse_delete BEFORE DELETE ON query_log + \\BEGIN SELECT RAISE(ABORT, 'refused'); END; + ); + + var retention: Retention = .init(.{ .retention_days = 30 }); + retention.runOnce(io, &database); + + try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 1), retention.stats.passes); + try testing.expectEqual(@as(u64, 0), retention.stats.rows_pruned); + // The checkpoint runs whether or not the prune did. + try testing.expectEqual(@as(u64, 1), retention.stats.checkpoints); +} + +test "the next pass retries what the failed one could not do" { + var threaded: std.Io.Threaded = .init(testing.allocator, .{}); + defer threaded.deinit(); + const io = threaded.io(); + + var database = try openLog(); + defer database.close(); + + const now = std.Io.Clock.real.now(io).toSeconds(); + try writeRows(&database, &.{ now - 40 * 86_400, now - 39 * 86_400 }); + try database.exec( + \\CREATE TRIGGER refuse_delete BEFORE DELETE ON query_log + \\BEGIN SELECT RAISE(ABORT, 'refused'); END; + ); + + var retention: Retention = .init(.{ .retention_days = 30 }); + retention.runOnce(io, &database); + try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(&database)); + + try database.exec("DROP TRIGGER refuse_delete;"); + retention.runOnce(io, &database); + + try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); + try testing.expectEqual(@as(u64, 2), retention.stats.passes); + try testing.expectEqual(@as(u64, 2), retention.stats.rows_pruned); +} diff --git a/src/tests.zig b/src/tests.zig index 8c84b93..b88365c 100644 --- a/src/tests.zig +++ b/src/tests.zig @@ -63,6 +63,15 @@ comptime { _ = @import("local/records.zig"); _ = @import("local/forward_zones.zig"); _ = @import("local/forward_client.zig"); + _ = @import("cache/dns_cache.zig"); + _ = @import("server/rate_limiter.zig"); + _ = @import("storage/repositories/queries_repo.zig"); + _ = @import("storage/logger.zig"); + _ = @import("platform/statfs.zig"); + _ = @import("storage/disk_monitor.zig"); + _ = @import("platform/logging.zig"); + _ = @import("storage/retention.zig"); + _ = @import("storage/phase6_integration_test.zig"); } extern fn sqlite3_libversion() [*:0]const u8;