//! 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 the client tracker (`server/clients.zig`). //! //! 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 disk_monitor = @import("disk_monitor.zig"); const events = @import("events.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; /// A consistent copy of the counters, for `/metrics` and the health rollup. pub const Stats = struct { passes: u64 = 0, rows_pruned: u64 = 0, checkpoints: u64 = 0, vacuums: u64 = 0, /// Vacuums the disk monitor refused. The pass still pruned and /// checkpointed, and the vacuum is due again on the next pass. vacuums_gated: u64 = 0, }; /// The live counters. Atomic because the retention task writes them and the web /// task reads them, on different threads, with no lock between the two — the /// same shape the query logger uses for its own counters. const Counters = struct { passes: std.atomic.Value(u64) = .init(0), rows_pruned: std.atomic.Value(u64) = .init(0), checkpoints: std.atomic.Value(u64) = .init(0), vacuums: std.atomic.Value(u64) = .init(0), vacuums_gated: std.atomic.Value(u64) = .init(0), }; /// `logging.retention_days`, shared by its two consumers — this pass and /// `server/clients.zig`'s stale-client prune. One cell rather than a copy in /// each: the two must never prune to different cutoffs, and a settings apply /// stores once. Owned by app-level state and outlives both readers. /// /// `.monotonic` is enough: the value stands alone and orders nothing else, and /// each consumer reads it once per pass. pub const RetentionDays = struct { value: std.atomic.Value(u32), pub fn init(days: u16) RetentionDays { return .{ .value = .init(days) }; } pub fn get(self: *const RetentionDays) u32 { return self.value.load(.monotonic); } pub fn setRetentionDays(self: *RetentionDays, days: u16) void { self.value.store(days, .monotonic); } pub fn seconds(self: *const RetentionDays) i64 { return @as(i64, self.get()) * std.time.s_per_day; } }; pub const Retention = struct { days: *const RetentionDays, counters: Counters, /// Passes since the last vacuum that succeeded. Plain rather than atomic: /// only the retention task reads or writes it, and no consumer reports it. passes_since_vacuum: u32, pub fn init(days: *const RetentionDays) Retention { return .{ .days = days, .counters = .{}, .passes_since_vacuum = 0 }; } /// The counters, read one at a time. A scrape that lands mid-pass can see a /// pass counted before the rows it pruned are; the alternative is a lock on /// the pass itself, which buys a consistency no consumer needs. pub fn snapshotStats(self: *const Retention) Stats { return .{ .passes = self.counters.passes.load(.monotonic), .rows_pruned = self.counters.rows_pruned.load(.monotonic), .checkpoints = self.counters.checkpoints.load(.monotonic), .vacuums = self.counters.vacuums.load(.monotonic), .vacuums_gated = self.counters.vacuums_gated.load(.monotonic), }; } /// 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`. /// /// `monitor` gates the vacuum only. Prune and checkpoint free space, so a /// full disk is a reason to run them rather than a reason to skip them, /// while a `VACUUM` rewrites the whole file on the very filesystem the /// monitor watches and fails `SQLITE_FULL` there. A null monitor means no /// gate, which is the shape the logger's writer takes. pub fn runOnce( self: *Retention, io: std.Io, database: *db.Db, monitor: ?*disk_monitor.Monitor, store: ?*events.Store, ) void { add(&self.counters.passes, 1); const now = std.Io.Clock.real.now(io).toSeconds(); const cutoff = now - self.days.seconds(); // Diagnostics retention rides this pass rather than a schedule of its // own: one daily housekeeping task, and a box restarted every night // still prunes through `Store.init`. if (store) |s| s.prune(io, now); // One operation, not two: the delete and the coverage watermark it // advances commit together or not at all (`queries_repo`). if (queries_repo.pruneOlderThan(database, cutoff)) |pruned| { add(&self.counters.rows_pruned, @intCast(pruned.deleted)); maintenance(store, io, now, "prune", null); } else |err| { log.warn("retention prune before {d} failed: {s}", .{ cutoff, @errorName(err) }); maintenance(store, io, now, "prune", @errorName(err)); } if (queries_repo.checkpointTruncate(database)) { add(&self.counters.checkpoints, 1); maintenance(store, io, now, "checkpoint", null); } else |err| { log.warn("retention checkpoint failed: {s}", .{@errorName(err)}); maintenance(store, io, now, "checkpoint", @errorName(err)); } self.passes_since_vacuum += 1; if (self.passes_since_vacuum < vacuum_every_passes) return; // The counter is not reset here, so a vacuum the monitor refused is due // again on the very next pass rather than seven passes later. if (monitor) |m| if (!m.writesAllowed()) { add(&self.counters.vacuums_gated, 1); log.warn("retention vacuum skipped: the disk monitor refuses writes", .{}); maintenance(store, io, now, "vacuum", "the disk monitor refuses writes"); return; }; if (queries_repo.vacuum(database)) { add(&self.counters.vacuums, 1); self.passes_since_vacuum = 0; maintenance(store, io, now, "vacuum", null); } else |err| { log.warn("retention vacuum failed: {s}", .{@errorName(err)}); maintenance(store, io, now, "vacuum", @errorName(err)); } } /// One step's outcome. `reason` null is the success branch of that same /// step in that same pass, which is what closes its episode; a gated vacuum /// is a failure of the step, because the work it owes is still owed. fn maintenance( store: ?*events.Store, io: std.Io, now_s: i64, operation: []const u8, reason: ?[]const u8, ) void { const s = store orelse return; const text = reason orelse return s.resolve(io, now_s, .query_log_maintenance, operation); var buf: [events.Store.max_detail_len]u8 = undefined; const detail = std.fmt.bufPrint(&buf, "retention {s} failed: {s}", .{ operation, text }) catch buf[0..]; s.report(io, now_s, .query_log_maintenance, operation, operation, .warning, detail); } fn add(counter: *std.atomic.Value(u64), delta: u64) void { _ = counter.fetchAdd(delta, .monotonic); } /// Daily loop, first pass immediately. The composition root starts it as a /// concurrent task (`app.zig`). /// /// `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; the /// composition root opens the second connection with /// `cli.DataDir.reopenQuerylogDb`. 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, monitor: ?*disk_monitor.Monitor, store: ?*events.Store, ) std.Io.Cancelable!void { const interval: std.Io.Clock.Duration = .{ .raw = .fromSeconds(pass_interval_s), .clock = .boot, }; while (true) { self.runOnce(io, database, monitor, store); try interval.sleep(io); } } }; // --------------------------------------------------------------------------- // tests // --------------------------------------------------------------------------- const events_fixture = @import("events_fixture.zig"); 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, .qclass = 1, .rcode = 0, .blocked = false, .response_time_us = null, .cache_hit = null, .upstream = null, .group_id = 1, .group_name = "default", .policy_action = .allow, .policy_reason = .no_match, .matched = null, .source_id = null, .source_name = null, .cname_target = null, .safe_search_target = null, .route_kind = .upstream, .forward_zone = 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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 2), retention.snapshotStats().rows_pruned); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().checkpoints); try testing.expectEqual(@as(u64, 0), retention.snapshotStats().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_days: RetentionDays = .init(7); var keeps: Retention = .init(&keeps_days); keeps.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 0), keeps.snapshotStats().rows_pruned); var prunes_days: RetentionDays = .init(1); var prunes: Retention = .init(&prunes_days); prunes.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 1), prunes.snapshotStats().rows_pruned); } test "setRetentionDays changes the cutoff the next pass prunes by" { 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 - 3 * 86_400}); var days: RetentionDays = .init(7); var pass: Retention = .init(&days); pass.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); days.setRetentionDays(1); pass.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 1), pass.snapshotStats().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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); for (0..6) |_| { retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(u64, 0), retention.snapshotStats().vacuums); } retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(u64, 7), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().vacuums); try testing.expectEqual(@as(u64, 7), retention.snapshotStats().checkpoints); for (0..7) |_| retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(u64, 14), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 2), retention.snapshotStats().vacuums); } test "a gated pass skips the vacuum, counts it, and vacuums on the next pass" { var threaded: std.Io.Threaded = .init(testing.allocator, .{}); defer threaded.deinit(); const io = threaded.io(); var database = try openLog(); defer database.close(); // `.critical` is the one state `writesAllowed` refuses on, and it is // published here directly: no real filesystem has to fill up for it. var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); var gated_days: RetentionDays = .init(30); var gated: Retention = .init(&gated_days); for (0..vacuum_every_passes) |_| gated.runOnce(io, &database, &monitor, null); // Prune and checkpoint ran on every pass; only the vacuum was refused. try testing.expectEqual(@as(u64, vacuum_every_passes), gated.snapshotStats().passes); try testing.expectEqual(@as(u64, vacuum_every_passes), gated.snapshotStats().checkpoints); try testing.expectEqual(@as(u64, 0), gated.snapshotStats().vacuums); try testing.expectEqual(@as(u64, 1), gated.snapshotStats().vacuums_gated); // The vacuum is due again immediately, not seven passes later. monitor.state_raw.store(@intFromEnum(disk_monitor.State.ok), .monotonic); gated.runOnce(io, &database, &monitor, null); try testing.expectEqual(@as(u64, 1), gated.snapshotStats().vacuums); try testing.expectEqual(@as(u64, 1), gated.snapshotStats().vacuums_gated); // And the counter reset, so the next six passes vacuum nothing. for (0..vacuum_every_passes - 1) |_| gated.runOnce(io, &database, &monitor, null); try testing.expectEqual(@as(u64, 1), gated.snapshotStats().vacuums); } test "a warn state still allows the vacuum" { var threaded: std.Io.Threaded = .init(testing.allocator, .{}); defer threaded.deinit(); const io = threaded.io(); var database = try openLog(); defer database.close(); var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); monitor.state_raw.store(@intFromEnum(disk_monitor.State.warn), .monotonic); var retention_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); for (0..vacuum_every_passes) |_| retention.runOnce(io, &database, &monitor, null); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().vacuums); try testing.expectEqual(@as(u64, 0), retention.snapshotStats().vacuums_gated); } 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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 0), retention.snapshotStats().rows_pruned); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 1), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 0), retention.snapshotStats().rows_pruned); // The checkpoint runs whether or not the prune did. try testing.expectEqual(@as(u64, 1), retention.snapshotStats().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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 2), try queries_repo.countRows(&database)); try database.exec("DROP TRIGGER refuse_delete;"); retention.runOnce(io, &database, null, null); try testing.expectEqual(@as(i64, 0), try queries_repo.countRows(&database)); try testing.expectEqual(@as(u64, 2), retention.snapshotStats().passes); try testing.expectEqual(@as(u64, 2), retention.snapshotStats().rows_pruned); } test "a failing prune opens a maintenance episode the next clean pass closes" { var threaded: std.Io.Threaded = .init(testing.allocator, .{}); defer threaded.deinit(); const io = threaded.io(); var database = try openLog(); defer database.close(); var fx: events_fixture.Fixture = .{}; try fx.init(io, 1000); defer fx.deinit(); 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_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, &fx.store); // Only the prune failed; the checkpoint succeeded, and a success writes no // row of its own. try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events")); try testing.expectEqualStrings("query_log.maintenance", try fx.text("SELECT code FROM operational_events")); try testing.expectEqualStrings("prune", try fx.text("SELECT subject_key FROM operational_events")); try testing.expectEqualStrings("warning", try fx.text("SELECT severity FROM operational_events")); try database.exec("DROP TRIGGER refuse_delete;"); retention.runOnce(io, &database, null, &fx.store); try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events")); try testing.expectEqual( @as(i64, 0), try fx.count("SELECT count(*) FROM operational_events WHERE resolved_at IS NULL"), ); } test "a gated vacuum is a maintenance failure the next ungated pass closes" { var threaded: std.Io.Threaded = .init(testing.allocator, .{}); defer threaded.deinit(); const io = threaded.io(); var database = try openLog(); defer database.close(); var fx: events_fixture.Fixture = .{}; try fx.init(io, 1000); defer fx.deinit(); var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null); monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic); var retention_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); for (0..vacuum_every_passes) |_| retention.runOnce(io, &database, &monitor, &fx.store); try testing.expectEqualStrings("vacuum", try fx.text( "SELECT subject_key FROM operational_events WHERE resolved_at IS NULL", )); monitor.state_raw.store(@intFromEnum(disk_monitor.State.ok), .monotonic); retention.runOnce(io, &database, &monitor, &fx.store); try testing.expectEqual(@as(u64, 1), retention.snapshotStats().vacuums); try testing.expectEqual( @as(i64, 0), try fx.count("SELECT count(*) FROM operational_events WHERE resolved_at IS NULL"), ); } test "a pass prunes the diagnostics store once" { var threaded: std.Io.Threaded = .init(testing.allocator, .{}); defer threaded.deinit(); const io = threaded.io(); var database = try openLog(); defer database.close(); var fx: events_fixture.Fixture = .{}; try fx.init(io, 1000); defer fx.deinit(); // Resolved further back than the retention window, so the pass must drop it. const now = std.Io.Clock.real.now(io).toSeconds(); const stale = now - events.Store.resolved_retention_s - 86_400; fx.store.reportResolved(io, stale, .query_log_recreated, "one-shot", "one-shot", .warning, "aside kept"); try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events")); var retention_days: RetentionDays = .init(30); var retention: Retention = .init(&retention_days); retention.runOnce(io, &database, null, &fx.store); try testing.expectEqual(@as(i64, 0), try fx.count("SELECT count(*) FROM operational_events")); }