milestone 30: overview as a dashboard, explicit health contract, period aggregations

This commit is contained in:
2026-08-22 16:45:15 +02:00
parent 0e83477d80
commit 623667e475
89 changed files with 7222 additions and 4239 deletions
+167 -23
View File
@@ -49,7 +49,6 @@ const faults = @import("config/faults.zig");
const fetcher = @import("filter/fetcher.zig");
const forward_zones = @import("local/forward_zones.zig");
const handler = @import("server/handler.zig");
const history_mod = @import("upstream/history.zig");
const http_util = @import("web/http_util.zig");
const loader = @import("config/loader.zig");
const local_records = @import("local/records.zig");
@@ -72,7 +71,6 @@ const shutdown = @import("server/shutdown.zig");
const sse = @import("web/sse.zig");
const static = @import("web/static.zig");
const tcp_server = @import("server/tcp_server.zig");
const upstream_history_repo = @import("storage/repositories/upstream_history_repo.zig");
const transport = @import("upstream/transport.zig");
const udp_server = @import("server/udp_server.zig");
const validate = @import("config/validate.zig");
@@ -544,13 +542,6 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
@truncate(@as(u96, @bitCast(std.Io.Clock.real.now(io).nanoseconds))),
);
// On the heap, not in this frame: the accumulator carries its pending cells
// and the flush task's buffer inline, which is about a megabyte.
const history = try gpa.create(history_mod.Accumulator);
defer gpa.destroy(history);
history.* = .init;
history.diagnostics = event_store;
pool.history = history;
pool.diagnostics = event_store;
// -----------------------------------------------------------------------
@@ -636,8 +627,6 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
reportQuerylogRecreated(event_store, io, boot_now_s, &querylog_opened, &querylog_writer_db);
var querylog_retention_db = try data.reopenQuerylogDb(io);
defer querylog_retention_db.close();
var querylog_history_db = try data.reopenQuerylogDb(io);
defer querylog_history_db.close();
var tracker_db = try data.openConfigDb(io);
defer tracker_db.close();
@@ -797,7 +786,6 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
.local_tables = &tables,
.logger = &query_logger,
.retention = &retention,
.history = history,
.sessions = if (sessions) |*s| s else null,
.limiter = if (web_limiter) |*l| l else null,
.hub = hub,
@@ -921,22 +909,19 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
// Ruling 4's shutdown order, on the one path every exit from here takes:
// every producer stops and is joined, then the queue closes, then the
// writer is awaited — so the last batch is written rather than raced — and
// only then does the final history flush run, with no recording task left
// that could add a cell after it. A writer the disk gate will not let write
// counts its batch as dropped instead of holding the exit open
// (`logger.zig`), so this wait always ends.
// writer is awaited — so the last batch is written rather than raced. A
// writer the disk gate will not let write counts its batch as dropped
// instead of holding the exit open (`logger.zig`), so this wait always
// ends.
//
// A `defer` and not straight-line code after `shutdown.wait`, because a
// `concurrent` spawn below can fail with the DNS listeners already
// serving; an orderly error teardown owes the operator the same drain a
// signal gets. The `querylog_history_db` this flush writes through is
// declared above, so its `close` runs after it.
// signal gets.
defer {
group.cancel(io);
query_logger.shutdown(io);
writer_future.await(io) catch {};
history.flushOnce(io, &querylog_history_db, upstream_history_repo.flush);
}
if (udp6) |*s| try group.concurrent(io, udp_server.UdpServer.serve, .{ s, io });
@@ -949,9 +934,6 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
if (dot_certs) |*store| try group.concurrent(io, cert_store.CertStore.watch, .{ store, io });
try group.concurrent(io, retention_mod.Retention.run, .{ &retention, io, &querylog_retention_db, gate, event_store });
// Ungated: a flush writes at most one row per upstream per minute, the same
// category as the query logger's own writes, which are ungated too.
try group.concurrent(io, history_mod.Accumulator.run, .{ history, io, &querylog_history_db });
try group.concurrent(io, disk_monitor.Monitor.run, .{ &monitor, io, event_store });
try group.concurrent(io, manager_mod.Manager.runScheduler, .{ &manager, io });
try group.concurrent(io, clients.Tracker.run, .{ &tracker, io, &tracker_db, gate, &client_names_resolver });
@@ -1451,6 +1433,168 @@ test "the recreated detail names the aside and the new coverage start" {
);
}
/// The `querylog.db` schema as milestone 29 shipped it, verbatim from
/// `querylog_schema.zig` at commit fa323c7. A literal and not this build's DDL
/// with the deleted tables appended: the appended form drifts the moment the
/// surviving tables change, and its fingerprint was never the one an m29 file
/// on disk actually carries. The transition under test is that exact byte
/// sequence meeting this build.
/// The `PRAGMA user_version` an m29 file on disk carries, written down rather
/// than recomputed from the literal below. A CRC taken over the fixture
/// validates whatever the fixture happens to say, so a slip in the "byte-exact"
/// literal would still self-certify; pinning the historical number turns that
/// slip into a failure. Its value is `Crc32` over `querylog_schema.ddl` at
/// commit fa323c7.
const m29_fingerprint: i32 = 603440875;
/// A watermark from long before this test runs. Both schemas seed
/// `available_since` from `unixepoch()`, so a fixture left at its own default
/// would satisfy "the new file's coverage is not older" even if recreation
/// copied the replaced file's promise straight across.
const m29_available_since: i64 = 1_600_000_000;
const m29_ddl: [:0]const u8 =
\\CREATE TABLE domains (
\\ id INTEGER PRIMARY KEY,
\\ domain TEXT NOT NULL UNIQUE
\\);
\\
\\CREATE TABLE query_log (
\\ id INTEGER PRIMARY KEY,
\\ timestamp INTEGER NOT NULL,
\\ domain_id INTEGER NOT NULL REFERENCES domains(id),
\\ client_ip TEXT NOT NULL, -- text, not a FK: log rows are immutable facts
\\ qtype INTEGER,
\\ blocked INTEGER NOT NULL,
\\ response_time_us INTEGER,
\\ cache_hit INTEGER,
\\ upstream TEXT,
\\ qclass INTEGER NOT NULL,
\\ rcode INTEGER NOT NULL,
\\ group_id INTEGER, -- text/id pairs, not FKs: a renamed
\\ group_name TEXT, -- group must not rewrite history
\\ policy_action TEXT NOT NULL,
\\ policy_reason TEXT NOT NULL,
\\ matched TEXT,
\\ source_id INTEGER,
\\ source_name TEXT,
\\ cname_target TEXT,
\\ safe_search_target TEXT,
\\ route_kind TEXT NOT NULL,
\\ forward_zone TEXT,
\\ CHECK (rcode BETWEEN 0 AND 4095) -- twelve bits (RFC 6891 6.1.3)
\\);
\\CREATE INDEX idx_query_log_ts ON query_log(timestamp);
\\CREATE INDEX idx_query_log_client ON query_log(client_ip);
\\CREATE INDEX idx_query_log_domain ON query_log(domain_id);
\\
\\CREATE TABLE upstream_targets (
\\ id INTEGER PRIMARY KEY,
\\ url TEXT NOT NULL UNIQUE -- the historical identity: config.db ids cannot cross database files
\\);
\\
\\CREATE TABLE upstream_minute (
\\ upstream_id INTEGER NOT NULL REFERENCES upstream_targets(id),
\\ minute_ts INTEGER NOT NULL,
\\ successes INTEGER NOT NULL,
\\ failures INTEGER NOT NULL,
\\ last_failure_ts INTEGER,
\\ last_error TEXT,
\\ PRIMARY KEY (upstream_id, minute_ts),
\\ CHECK (successes >= 0),
\\ CHECK (failures >= 0)
\\) WITHOUT ROWID;
\\CREATE INDEX idx_upstream_minute_ts ON upstream_minute(minute_ts);
\\
\\CREATE TABLE querylog_meta (
\\ id INTEGER PRIMARY KEY CHECK (id = 1), -- one row, enforced by the schema
\\ created_at INTEGER NOT NULL,
\\ available_since INTEGER NOT NULL
\\);
\\INSERT INTO querylog_meta (id, created_at, available_since)
\\VALUES (1, unixepoch(), unixepoch() + 1);
;
test "an m29 query log is set aside and recreated without the upstream-history tables" {
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 path_buf: [256]u8 = undefined;
const path = try std.fmt.bufPrintZ(&path_buf, ".zig-cache/tmp/{s}/querylog.db", .{tmp.sub_path});
var fx: events_fixture.Fixture = .{};
try fx.init(io, 1000);
defer fx.deinit();
// The fixture is only worth anything while it is still a *different*
// schema from this build's, and one that carries the deleted tables.
try testing.expect(!std.mem.eql(u8, m29_ddl, querylog_schema.ddl));
try testing.expect(std.mem.indexOf(u8, m29_ddl, "CREATE TABLE upstream_minute") != null);
try testing.expect(std.mem.indexOf(u8, querylog_schema.ddl, "upstream_minute") == null);
// And only while it is still m29's bytes: this is the one check that an
// edit to the literal cannot satisfy by changing what it is compared to.
try testing.expectEqual(m29_fingerprint, @as(i32, @bitCast(std.hash.Crc32.hash(m29_ddl))));
// A healthy m29 file, stamped with the fingerprint m29's own DDL produced
// and backdated so its coverage promise is visibly the older one.
const m29_coverage = blk: {
var m29 = try db.Db.open(path, .{ .mode = .read_write_create });
defer m29.close();
try db.applyPragmas(&m29, .{});
try m29.exec(m29_ddl);
try m29.exec("INSERT INTO upstream_targets (url) VALUES ('https://dns.example/dns-query');");
var meta_buf: [128]u8 = undefined;
try m29.exec(try std.fmt.bufPrintZ(
&meta_buf,
"UPDATE querylog_meta SET created_at = {d}, available_since = {d};",
.{ m29_available_since, m29_available_since },
));
var version_buf: [64]u8 = undefined;
try m29.exec(try std.fmt.bufPrintZ(
&version_buf,
"PRAGMA user_version = {d};",
.{m29_fingerprint},
));
break :blk try m29.queryInt("SELECT available_since FROM querylog_meta");
};
try testing.expectEqual(m29_available_since, m29_coverage);
var opened = try querylog_schema.open(io, std.Io.Dir.cwd(), path);
defer opened.database.close();
// Set aside under the name that says the file was healthy and this build
// moved, and still on disk for an operator who wants it.
try testing.expectEqual(querylog_schema.RecreateReason.fingerprint_mismatch, opened.recreated.?);
try testing.expect(std.mem.indexOf(u8, opened.aside(), ".schema-changed-") != null);
try tmp.dir.access(io, std.fs.path.basename(opened.aside()), .{});
// The two tables are gone from the file this process will write to.
for ([_][]const u8{ "upstream_targets", "upstream_minute", "idx_upstream_minute_ts" }) |name| {
var stmt = try opened.database.prepare("SELECT count(*) FROM sqlite_schema WHERE name = ?1");
defer stmt.deinit();
try stmt.bindText(1, name);
try testing.expect(try stmt.step());
try testing.expectEqual(@as(i64, 0), stmt.columnInt(0));
}
// Coverage restarts: the new file does not inherit the replaced one's
// promise about what it can answer. Strictly newer, not merely not-older —
// a recreation that copied the watermark across would pass the weaker test.
const coverage = try queries_repo.availableSince(&opened.database);
try testing.expect(coverage > m29_coverage);
reportQuerylogRecreated(&fx.store, io, 2000, &opened, &opened.database);
try testing.expectEqualStrings("query_log.recreated", try fx.text("SELECT code FROM operational_events"));
try testing.expectEqualStrings(
"fingerprint_mismatch",
try fx.text("SELECT subject_key FROM operational_events"),
);
}
test "a fingerprint recreate files a resolved event naming the real aside and watermark" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
+4 -4
View File
@@ -343,10 +343,10 @@ pub const DataDir = struct {
}
/// An additional connection to a `querylog.db` that `openQuerylogDb` has
/// already established. A running server needs three background ones — the
/// log writer, the retention pass and the upstream-history flush each own
/// one (`retention.zig`'s contract) — plus a fourth for the web task when
/// the web interface is enabled.
/// already established. A running server needs two background ones — the
/// log writer and the retention pass each own one (`retention.zig`'s
/// contract) — plus a third for the web task when the web interface is
/// enabled.
pub fn reopenQuerylogDb(self: *const DataDir, io: std.Io) !db.Db {
_ = io;
var database = try db.Db.open(self.querylog_db_path, .{ .mode = .read_write_existing });
+225
View File
@@ -16,6 +16,7 @@
//! opaque, matching `src/platform/tls_server.zig`'s Mbed TLS approach.
const std = @import("std");
const builtin = @import("builtin");
const assert = std.debug.assert;
const log = std.log.scoped(.db);
@@ -844,6 +845,137 @@ pub const Tx = struct {
}
};
/// A read transaction: one consistent view of the file across several
/// statements.
///
/// `BEGIN DEFERRED`, not `Tx`'s `BEGIN IMMEDIATE`. A reader that took the write
/// lock would stall the logger and retention for the length of an HTTP
/// response; a deferred transaction that only ever reads never upgrades, so it
/// cannot hit the mid-way `SQLITE_BUSY` the `Tx` doc warns about. In WAL mode it
/// pins the snapshot at the first read, which is the point: an aggregate and the
/// coverage watermark beside it describe the same database state even when
/// retention prunes between them.
///
/// Ending it is fallible, and the caller must treat it that way. A connection
/// left inside a transaction refuses the next `BEGIN`, so a swallowed failure
/// here does not cost one response — it costs every later one on the same
/// connection, and they would each be a correct-looking answer over a foreign
/// snapshot or an outright error the client was never told about.
///
/// ```zig
/// var tx = try ReadTx.begin(db);
/// errdefer tx.rollback();
/// ... // reads only
/// try tx.commit();
/// ```
pub const ReadTx = struct {
db: *Db,
active: bool,
pub fn begin(db: *Db) Error!ReadTx {
try db.exec("BEGIN DEFERRED;");
return .{ .db = db, .active = true };
}
/// Ends the transaction, and says so. A read transaction has nothing to
/// conflict over, so a failed COMMIT means the connection is in a state
/// this code did not put it in: the ROLLBACK below is the attempt to hand
/// the next caller a usable connection anyway, and the error is returned so
/// the response it was serving fails rather than reporting success over a
/// database whose state nobody can name.
pub fn commit(self: *ReadTx) Error!void {
assert(self.active);
self.active = false;
self.execCommit() catch |err| {
self.reportFault("COMMIT");
self.forceRollback();
return err;
};
}
fn execCommit(self: *ReadTx) Error!void {
if (commitFaultTripped()) return error.Internal;
return self.db.exec("COMMIT;");
}
/// Safe in `errdefer` and after `commit`. Never returns an error: it runs
/// on the path where something has already gone wrong, and that error is
/// the one worth reporting.
pub fn rollback(self: *ReadTx) void {
if (!self.active) return;
self.active = false;
self.forceRollback();
}
/// A ROLLBACK that fails leaves the connection inside a transaction with no
/// way left to get it out. Every later `begin` on it fails, which is the
/// visible symptom this reports the cause of.
fn forceRollback(self: *ReadTx) void {
self.db.exec("ROLLBACK;") catch {
self.reportFault("ROLLBACK");
};
}
/// The only record that this connection may be unusable, so in a real build
/// it is `err`. A test that deliberately causes the fault captures it
/// instead — see `read_tx_faults`.
fn reportFault(self: *ReadTx, comptime what: []const u8) void {
var buf: [256]u8 = undefined;
const message = self.db.lastError(&buf);
if (faultCaptured()) return;
log.err("read-transaction " ++ what ++ " failed: {s}", .{message});
}
};
/// Drives and observes the read-transaction teardown faults, which a unit test
/// cannot arrange against a healthy SQLite connection. Test builds only; it
/// reduces to nothing everywhere else — the rotation seam's shape
/// (logging.zig).
const read_tx_seam = if (builtin.is_test) struct {
var fail_next_commit: bool = false;
var capturing: bool = false;
var faults: usize = 0;
} else struct {};
fn commitFaultTripped() bool {
if (!builtin.is_test) return false;
if (!read_tx_seam.fail_next_commit) return false;
read_tx_seam.fail_next_commit = false;
return true;
}
/// True when a test has said it is expecting this fault and will assert on it.
/// Capture is opt-in for exactly one reason: the test runner fails a test that
/// logs at `err`, so a blanket silence would turn an unexpected teardown fault
/// in some unrelated test into a silent pass.
fn faultCaptured() bool {
if (!builtin.is_test) return false;
if (!read_tx_seam.capturing) return false;
read_tx_seam.faults += 1;
return true;
}
/// The seam's controls, for tests in this file and in the web layer.
pub const read_tx_faults = if (builtin.is_test) struct {
/// Fails the next `ReadTx.commit` before it issues COMMIT, so the
/// transaction is still open when the recovery path runs — which is the
/// shape of a real COMMIT failure.
pub fn failNextCommit() void {
read_tx_seam.fail_next_commit = true;
}
pub fn beginCapture() void {
read_tx_seam.capturing = true;
read_tx_seam.faults = 0;
}
/// Stops capturing and answers how many faults were reported meanwhile.
pub fn endCapture() usize {
read_tx_seam.capturing = false;
return read_tx_seam.faults;
}
} else struct {};
const testing = std.testing;
fn openMemory() Error!Db {
@@ -1029,6 +1161,99 @@ test "rollback after commit is a no-op" {
try testing.expectEqual(@as(i64, 1), try db.queryInt("SELECT count(*) FROM t"));
}
test "a read transaction sees one state and frees the connection when it commits" {
var db = try openMemory();
defer db.close();
try applyPragmas(&db, .{});
try db.exec("CREATE TABLE t (id INTEGER PRIMARY KEY);");
try db.exec("INSERT INTO t (id) VALUES (1);");
var tx = try ReadTx.begin(&db);
try testing.expectEqual(@as(i64, 1), try db.queryInt("SELECT count(*) FROM t"));
try tx.commit();
try testing.expect(!tx.active);
// Committed, so the connection takes a fresh transaction again.
var second = try ReadTx.begin(&db);
second.rollback();
try testing.expect(!second.active);
// Idempotent, so an `errdefer` that survives a successful rollback is a
// no-op rather than a stray ROLLBACK against the next transaction.
second.rollback();
var third = try ReadTx.begin(&db);
try third.commit();
}
test "a connection left inside a transaction refuses the next begin" {
var db = try openMemory();
defer db.close();
try applyPragmas(&db, .{});
// The poisoned connection, reached the only way it can be: a transaction
// that was opened and never ended. This is what a swallowed COMMIT failure
// would leave behind, and the point is that it is *loud* — the next reader
// gets an error it must report, never a silent read outside a snapshot.
try db.exec("BEGIN DEFERRED;");
try testing.expectError(error.Unexpected, ReadTx.begin(&db));
// And it is recoverable: ending the stray transaction restores the
// connection, which is what `commit`'s rollback attempt is reaching for.
try db.exec("ROLLBACK;");
var tx = try ReadTx.begin(&db);
try tx.commit();
}
test "a failed commit is reported, rolled back, and leaves the connection usable" {
var db = try openMemory();
defer db.close();
try applyPragmas(&db, .{});
try db.exec("CREATE TABLE t (id INTEGER PRIMARY KEY);");
try db.exec("INSERT INTO t (id) VALUES (1);");
read_tx_faults.beginCapture();
defer _ = read_tx_faults.endCapture();
var tx = try ReadTx.begin(&db);
try testing.expectEqual(@as(i64, 1), try db.queryInt("SELECT count(*) FROM t"));
// The failure lands where a real one does: the transaction is still open
// when the recovery path runs.
read_tx_faults.failNextCommit();
try testing.expectError(error.Internal, tx.commit());
try testing.expect(!tx.active);
// Exactly one fault: the COMMIT. The ROLLBACK behind it succeeded, which is
// the whole point of attempting it.
try testing.expectEqual(@as(usize, 1), read_tx_faults.endCapture());
// The connection is not poisoned — the next reader gets a transaction
// rather than inheriting the fault.
read_tx_faults.beginCapture();
var next = try ReadTx.begin(&db);
try testing.expectEqual(@as(i64, 1), try db.queryInt("SELECT count(*) FROM t"));
try next.commit();
try testing.expectEqual(@as(usize, 0), read_tx_faults.endCapture());
}
test "an armed commit fault fires once and no further" {
var db = try openMemory();
defer db.close();
try applyPragmas(&db, .{});
read_tx_faults.beginCapture();
defer _ = read_tx_faults.endCapture();
read_tx_faults.failNextCommit();
var first = try ReadTx.begin(&db);
try testing.expectError(error.Internal, first.commit());
// The seam disarms itself, so it cannot leak into a later test in the same
// binary and fail a commit nobody asked to fail.
var second = try ReadTx.begin(&db);
try second.commit();
try testing.expectEqual(@as(usize, 1), read_tx_faults.endCapture());
}
test "a row-producing statement reports its row through step" {
var db = try openMemory();
defer db.close();
+113 -10
View File
@@ -20,9 +20,8 @@
//! having no store.
//!
//! **Time is a parameter, not a seam.** Every method that stamps a row takes
//! `now_s` (`purge`/`purgeAll` only delete, so they take none),
//! matching `upstream/history.zig` and `storage/logger.zig`. Production callers
//! read `Clock.real`; tests pass literals. There is no clock in here and no
//! `now_s` (`purge`/`purgeAll` only delete, so they take none), matching
//! `storage/logger.zig`. Production callers read `Clock.real`; tests pass literals. There is no clock in here and no
//! function pointer standing in for one.
//!
//! **`resolve` is on the DNS hot path.** `pool.recordSuccess` calls it after
@@ -39,9 +38,15 @@ const events_repo = @import("repositories/events_repo.zig");
const log = std.log.scoped(.events);
/// Every failure episode nxdns can record. **The enum is the truth**: its
/// cardinality is what the exhaustive tests, the API and the frontend copy map
/// all count, and the dotted string is only its wire form.
/// Every failure episode nxdns can **emit**, and nothing else. **The enum is
/// the truth** about what a running process writes: the exhaustive tests count
/// it, and the dotted string is only its wire form.
///
/// It is not the whole documented union. The API and the frontend copy map hold
/// these plus `legacy_wire_codes`, because a stored row outlives its producer —
/// see there. A code whose producer is gone moves to that list rather than
/// staying here: a member here is a code `Store.report` accepts, and a report
/// under a dead code opens an episode nothing can ever resolve.
pub const Code = enum {
disk_space,
disk_probe,
@@ -52,7 +57,6 @@ pub const Code = enum {
query_log_write,
query_log_maintenance,
query_log_recreated,
upstream_history_write,
upstream_exchange,
client_names_storage,
clients_storage,
@@ -75,7 +79,6 @@ pub fn wire(code: Code) []const u8 {
.query_log_write => "query_log.write",
.query_log_maintenance => "query_log.maintenance",
.query_log_recreated => "query_log.recreated",
.upstream_history_write => "upstream_history.write",
.upstream_exchange => "upstream.exchange",
.client_names_storage => "client_names.storage",
.clients_storage => "clients.storage",
@@ -92,7 +95,6 @@ pub fn component(code: Code) []const u8 {
.blocklist_refresh, .blocklist_snapshot, .blocklist_storage => "blocklist",
.certificate_reload => "certificate",
.query_log_write, .query_log_maintenance, .query_log_recreated => "query_log",
.upstream_history_write => "upstream_history",
.upstream_exchange => "upstream",
.client_names_storage => "client_names",
.clients_storage => "clients",
@@ -101,6 +103,21 @@ pub fn component(code: Code) []const u8 {
};
}
/// Wire codes that stored rows still carry and no code emits.
///
/// They live as text, not as `Code` members, because the read path is the only
/// path that meets them: the list endpoint passes a stored code straight
/// through, and `events_repo.componentOf` derives the component from the text.
/// The one thing the store must still do with them is close whatever a past
/// release left open — see `Store.init`.
///
/// The documented event-code union is these plus every `Code`, which is what
/// keeps a real response describing an old row inside the contract.
pub const legacy_wire_codes = [_][]const u8{
// Milestone 30 deleted the upstream-minute history subsystem.
"upstream_history.write",
};
/// Fixed per emit call, not per code: the same disk monitor reports a
/// transition to `warn` as a warning and one to `critical` as an error.
///
@@ -198,6 +215,17 @@ pub const Store = struct {
pub fn init(io: std.Io, database: *db.Db, now_s: i64) db.Error!Store {
var store: Store = .{ .database = database };
// Before the mirror load and the prune, both of which would otherwise
// read a state this is about to change: an episode left open here would
// sit in the mirror forever and hold `untracked_active_count` above
// zero, and one resolved after the prune would keep its row for another
// ninety days. `now_s` is the resolution time on purpose — the store's
// own open time, not the episode's stale `last_seen`, which a database
// older than the retention window would prune in this very call.
for (legacy_wire_codes) |code| {
_ = try events_repo.resolveActiveByCode(database, now_s, code);
}
var chunk: [16]events_repo.ActiveRow = undefined;
var after: i64 = 0;
while (store.active.len < mirror_capacity) {
@@ -688,7 +716,7 @@ const testing = std.testing;
test "wire and component are exhaustive, unique and agree with each other" {
const all = std.enums.values(Code);
try testing.expectEqual(@as(usize, 15), all.len);
try testing.expectEqual(@as(usize, 14), all.len);
for (all, 0..) |code, i| {
const text = wire(code);
@@ -722,6 +750,7 @@ const Fixture = struct {
io: std.Io = undefined,
database: db.Db = undefined,
store: Store = undefined,
text_buf: [256]u8 = undefined,
fn init(self: *Fixture, now_s: i64) !void {
self.threaded = .init(testing.allocator, .{});
@@ -744,8 +773,82 @@ const Fixture = struct {
fn count(self: *Fixture, sql: []const u8) !i64 {
return self.database.queryInt(sql);
}
fn text(self: *Fixture, sql: []const u8) ![]const u8 {
var stmt = try self.database.prepare(sql);
defer stmt.deinit();
if (!try stmt.step()) return error.NoRow;
const value = stmt.columnText(0);
@memcpy(self.text_buf[0..value.len], value);
return self.text_buf[0..value.len];
}
};
test "an m29 flush-failure episode is resolved once at init and stays listable" {
var fx: Fixture = .{};
try fx.init(1000);
defer fx.deinit();
// The state an m29 database is left in: a live episode under a code that no
// producer emits any more, so nothing will ever resolve it. Seeded through
// the repository and not through `report`, because the live emitter cannot
// name this code — that it cannot is half of what m30 changed.
_ = try events_repo.insertActive(
&fx.database,
1000,
legacy_wire_codes[0],
"history",
"history",
"warning",
"Busy",
);
try testing.expectEqual(
@as(i64, 1),
try fx.count("SELECT count(*) FROM operational_events WHERE resolved_at IS NULL"),
);
// Reopening is what m30 upgrades on. Ninety days later, so a resolution
// stamped with the episode's own `last_seen` would be pruned by this very
// call rather than left for an operator to read.
const reopened_at = 1000 + Store.resolved_retention_s + 86_400;
const upgraded = try Store.init(fx.io, &fx.database, reopened_at);
try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events"));
try testing.expectEqual(
@as(i64, reopened_at),
try fx.count("SELECT resolved_at FROM operational_events"),
);
try testing.expectEqualStrings(
"upstream_history.write",
try fx.text("SELECT code FROM operational_events"),
);
// Nothing is open, so the mirror is empty and the SQL slow path is off.
try testing.expectEqual(@as(u32, 0), upgraded.active.len);
try testing.expectEqual(@as(u32, 0), upgraded.untracked_active_count);
// A second start finds nothing left to close, and the sweep is idempotent.
const again = try Store.init(fx.io, &fx.database, reopened_at + 60);
try testing.expectEqual(@as(u32, 0), again.active.len);
try testing.expectEqual(
@as(i64, reopened_at),
try fx.count("SELECT resolved_at FROM operational_events"),
);
}
test "a legacy wire code is not something the live emitter can name" {
for (legacy_wire_codes) |legacy| {
try testing.expectEqual(@as(?Code, null), parseWire(legacy));
for (std.enums.values(Code)) |code| {
try testing.expect(!std.mem.eql(u8, legacy, wire(code)));
}
// The read path still has to answer for it, and does so from the text.
const dot = std.mem.indexOfScalar(u8, legacy, '.') orelse
return error.TestUnexpectedResult;
try testing.expectEqualStrings(legacy[0..dot], events_repo.componentOf(legacy));
try testing.expect(legacy.len <= events_repo.code_capacity);
}
}
test "a failure opens one episode and repeats of it count rather than multiply" {
var fx: Fixture = .{};
try fx.init(1000);
+384 -16
View File
@@ -30,6 +30,7 @@
//! `writer_failed`, so the loss is visible rather than silent.
const std = @import("std");
const builtin = @import("builtin");
const db = @import("db.zig");
const disk_monitor = @import("disk_monitor.zig");
@@ -335,12 +336,85 @@ const Outcome = union(enum) {
expiry: std.Io.Cancelable!void,
};
/// Where the disk gate stands right now, as a state rather than a tally.
///
/// `open` is the steady state. `gated` says the gate is holding writes back but
/// nothing has been lost to it yet, and `losing` says this episode has already
/// cost rows. A cumulative drop counter cannot say any of that: it only ever
/// grows, so a rollup computed from it would latch on the first overflow.
pub const GateEpisode = enum(u8) { open, gated, losing };
/// The episode state and the identity of the episode it belongs to, in one
/// word so a compare-and-swap can test both at once.
///
/// The identity is what the state alone cannot carry. A producer decides a row
/// is lost, stalls, and wakes after the gate has closed, reopened and closed
/// again; a bare `gated -> losing` swap would then mark an episode that has
/// cost nothing. `generation` rises every time an episode opens, so that swap
/// fails against the newer episode and the stale loss is discarded.
const Gate = packed struct(u64) {
episode: GateEpisode,
generation: u56,
const initial: Gate = .{ .episode = .open, .generation = 0 };
fn bits(self: Gate) u64 {
return @bitCast(self);
}
fn of(bits_value: u64) Gate {
return @bitCast(bits_value);
}
};
/// Parks a producer immediately before it evicts an entry, so a test can move
/// the disk gate while that producer is still inside `enqueue` and the row it
/// is about to lose is still queued.
///
/// Nothing else reaches that point. `enqueue` never suspends, so from outside a
/// gate read before its loop and one read at the eviction give the same answer,
/// and no test could tell the two apart — which is exactly the difference that
/// decides whether a discard can join an episode that opened after the producer
/// started.
///
/// Before the eviction and not after it: parking after the row is already gone
/// would let a test open an episode and then file an earlier loss under it,
/// which is the misattribution the sampling rule exists to prevent. The loss
/// has to happen inside the episode for the episode to own it. The storage
/// exists in a test build only, and `park` reduces to nothing everywhere else —
/// the settings hash seam's shape (`web/handlers/settings.zig`).
const discard_stall = if (builtin.is_test) struct {
var armed: bool = false;
var parked: std.Io.Event = .unset;
var release: std.Io.Event = .unset;
fn park(io: std.Io) void {
if (!armed) return;
parked.set(io);
release.waitUncancelable(io);
}
} else struct {
fn park(io: std.Io) void {
_ = io;
}
};
pub const Logger = struct {
cfg: model.Logging,
queue: EntryQueue,
queries_dropped: std.atomic.Value(u64),
/// When the newest drop happened, in unix seconds; 0 means none yet. Read
/// through `lastDropSeconds`, which is what turns the sentinel into a null.
last_drop_s: std.atomic.Value(i64),
rows_written: std.atomic.Value(u64),
batches_gated: std.atomic.Value(u64),
/// The gating episode `/api/health` reports as `query_history.losing`, as
/// `Gate` bits. Moved only by `gateHolds`/`gateReopened`, which the writer
/// calls as it observes the monitor, and raised to `losing` by a drop that
/// carries the identity of the episode still holding.
///
/// Read it through `gateEpisode` or `sampleGate`, never as a raw integer.
gate: 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.
@@ -363,8 +437,10 @@ pub const Logger = struct {
.cfg = cfg,
.queue = .init(queue_buf),
.queries_dropped = .init(0),
.last_drop_s = .init(0),
.rows_written = .init(0),
.batches_gated = .init(0),
.gate = .init(Gate.initial.bits()),
.writer_failed = .init(false),
.draining = .init(false),
};
@@ -422,10 +498,17 @@ pub const Logger = struct {
if (self.queue.capacity() == 0) break;
var oldest: [1]Entry = undefined;
discard_stall.park(io);
const got = self.queue.get(io, &oldest, 0) catch break;
if (got == 1) self.countDropped(1);
// Sampled after the eviction and not before the loop: the row is
// lost on the line above, and a sample taken while the gate was
// still open would let an episode that opened during `put` escape
// being marked for a row it really cost. Reading it here cannot
// misattribute in the other direction either — a sample the gate
// outruns fails `countDropped`'s generation check.
if (got == 1) self.countDropped(io, 1, self.sampleGate());
}
self.countDropped(1);
self.countDropped(io, 1, self.sampleGate());
}
/// The writer task: owns `database` and its prepared statements for its
@@ -453,7 +536,7 @@ pub const Logger = struct {
// life of the process, so the row stays active, which is the truth.
self.reportWrite(io, "writer", "preparing the batch statements failed", @errorName(err), 0);
self.queue.close(io);
_ = self.dropRemaining(io);
_ = self.dropRemaining(io, self.sampleGate());
return;
};
defer writer.deinit();
@@ -466,17 +549,24 @@ pub const Logger = struct {
error.Closed => return,
error.Canceled => |e| return e,
};
// Before `fill`, not only inside `flush`: `fill` spends the whole
// flush interval taking entries off the queue, and a producer that
// overflows the queue during that wait is losing rows to the gate
// just as surely as the held batch is. Observing here is what makes
// the episode start cover those drops instead of misfiling them as
// ordinary overflow.
const at = self.observeGate(monitor);
const deadline = self.flushDeadline(io);
// `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);
self.fill(io, &batch, deadline, &n, at) catch |err| {
self.countDropped(io, n, at);
return err;
};
self.flush(io, &writer, batch[0..n], monitor) catch |err| switch (err) {
error.Canceled => |e| {
self.countDropped(n);
self.countDropped(io, n, at);
return e;
},
// Nothing will open the gate now. Everything still queued is
@@ -484,8 +574,12 @@ pub const Logger = struct {
// announced once — a per-chunk report would write to the very
// disk that is out of space, dozens of times, on the way out.
error.GatedAtShutdown => {
self.countDropped(n);
const lost = n + self.dropRemaining(io);
// Re-sampled rather than reusing `at`: `flush` observed the
// gate again on its way to this error, so the episode that
// is costing these rows is the one holding now.
const gated_at = self.sampleGate();
self.countDropped(io, n, gated_at);
const lost = n + self.dropRemaining(io, gated_at);
scope.warn(
"query log: {d} rows dropped at shutdown, the disk gate was closed",
.{lost},
@@ -521,7 +615,7 @@ pub const Logger = struct {
/// many. 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) usize {
fn dropRemaining(self: *Logger, io: std.Io, at: Gate) usize {
var total: usize = 0;
var leftover: [flush_batch]Entry = undefined;
while (true) {
@@ -529,7 +623,7 @@ pub const Logger = struct {
error.Closed => break,
};
if (n == 0) break;
self.countDropped(n);
self.countDropped(io, n, at);
total += n;
}
return total;
@@ -559,13 +653,14 @@ pub const Logger = struct {
batch: *[flush_batch]Entry,
deadline: std.Io.Clock.Timestamp,
n: *usize,
at: Gate,
) 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;
const entry = try self.getWithin(io, remaining, at) orelse break;
batch[n.*] = entry;
n.* += 1;
n.* += self.drainAvailable(io, batch[n.*..]);
@@ -588,6 +683,7 @@ pub const Logger = struct {
self: *Logger,
io: std.Io,
budget: std.Io.Clock.Duration,
at: Gate,
) std.Io.Cancelable!?Entry {
var outcomes: [2]Outcome = undefined;
var race: std.Io.Select(Outcome) = .init(io, &outcomes);
@@ -603,7 +699,7 @@ pub const Logger = struct {
const first = race.await() catch |err| {
// Teardown: the entry the getter already took has nowhere to go.
if (drainRace(&race)) |_| self.countDropped(1);
if (drainRace(&race)) |_| self.countDropped(io, 1, at);
return err;
};
const late = drainRace(&race);
@@ -628,6 +724,7 @@ pub const Logger = struct {
.clock = .awake,
};
while (!m.writesAllowed()) {
self.gateHolds();
// Waiting for the disk to recover is right while the process
// runs and wrong once it is stopping: nothing is going to free
// space during shutdown, so the batch is lost either way and
@@ -638,6 +735,7 @@ pub const Logger = struct {
_ = self.batches_gated.fetchAdd(1, .monotonic);
try pause.sleep(io);
}
self.gateReopened();
}
var rows: [flush_batch]queries_repo.Row = undefined;
@@ -645,7 +743,10 @@ pub const Logger = struct {
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);
// Sampled here, so a batch the gate already let through is counted
// against whatever episode is open now — a database failure is not
// a gating loss.
self.countDropped(io, entries.len, self.sampleGate());
self.reportWrite(io, "batch", "a query log batch was dropped", @errorName(err), entries.len);
return;
};
@@ -683,8 +784,92 @@ pub const Logger = struct {
);
}
fn countDropped(self: *Logger, n: usize) void {
/// Counts `n` lost rows, stamps the loss, and raises the episode `at` to
/// `losing` if that episode is still the current one.
///
/// `at` is sampled where the rows were lost, not here: see `Gate`. A caller
/// that lost rows outside any episode passes what `sampleGate` gave it and
/// the raise is simply a no-op.
///
/// The stamp is a second atomic rather than a field beside the count, so a
/// reader can briefly see the new total against the previous timestamp. The
/// health contract says so: `dropped_total` above zero with a null
/// `last_drop_s` is a legal, momentary answer.
fn countDropped(self: *Logger, io: std.Io, n: usize, at: Gate) void {
_ = self.queries_dropped.fetchAdd(n, .monotonic);
self.stampDrop(std.Io.Clock.real.now(io).toSeconds());
if (at.episode != .gated) return;
const losing: Gate = .{ .episode = .losing, .generation = at.generation };
_ = self.gate.cmpxchgStrong(at.bits(), losing.bits(), .acq_rel, .monotonic);
}
/// Moves the stamp forward only. Two producers can reach `countDropped` out
/// of order, and a plain store would let the older one publish its
/// timestamp over the newer drop's — a `last_drop_s` that walks backwards
/// while drops are still arriving.
fn stampDrop(self: *Logger, at_s: i64) void {
var seen = self.last_drop_s.load(.monotonic);
while (at_s > seen) {
seen = self.last_drop_s.cmpxchgWeak(seen, at_s, .monotonic, .monotonic) orelse return;
}
}
/// When the newest drop happened, or null while nothing has been dropped.
pub fn lastDropSeconds(self: *const Logger) ?i64 {
const stamped = self.last_drop_s.load(.monotonic);
return if (stamped == 0) null else stamped;
}
/// Where the gate stands right now, for a reader that only wants the state.
pub fn gateEpisode(self: *const Logger) GateEpisode {
return Gate.of(self.gate.load(.acquire)).episode;
}
/// The identity a caller must carry with rows it loses.
///
/// Take it where the loss actually happens. A producer discarding one entry
/// samples at the discard; the writer samples once at `observeGate`,
/// because the batch it is holding belongs to the episode that was open
/// while it filled. Sampling earlier than the loss hides episodes that
/// opened in between; sampling later cannot misattribute, because the
/// generation makes an outrun sample fail its swap.
fn sampleGate(self: *const Logger) Gate {
return Gate.of(self.gate.load(.acquire));
}
/// Opens a gating episode under a fresh generation, or leaves one that is
/// already holding alone — `losing` must not fall back to `gated`, and a
/// second observation of the same gate must not look like a new episode.
fn gateHolds(self: *Logger) void {
var current = self.sampleGate();
while (current.episode == .open) {
const next: Gate = .{ .episode = .gated, .generation = current.generation +% 1 };
const raced = self.gate.cmpxchgWeak(current.bits(), next.bits(), .acq_rel, .acquire) orelse
return;
current = Gate.of(raced);
}
}
/// Ends the episode, keeping its generation so the next one gets a number
/// no stale producer holds. A drop sampled during the episode that lands
/// after this reopen finds its generation gone and is discarded.
fn gateReopened(self: *Logger) void {
var current = self.sampleGate();
while (current.episode != .open) {
const next: Gate = .{ .episode = .open, .generation = current.generation };
const raced = self.gate.cmpxchgWeak(current.bits(), next.bits(), .acq_rel, .acquire) orelse
return;
current = Gate.of(raced);
}
}
/// Moves the episode to wherever the monitor says the gate is, and returns
/// the episode the caller's rows now belong to. A null monitor is no gating
/// at all, so the episode stays `open`.
fn observeGate(self: *Logger, monitor: ?*disk_monitor.Monitor) Gate {
const m = monitor orelse return self.sampleGate();
if (m.writesAllowed()) self.gateReopened() else self.gateHolds();
return self.sampleGate();
}
};
@@ -1189,7 +1374,7 @@ test "entries that arrive inside one window reach the database in one batch" {
var batch: [flush_batch]Entry = undefined;
batch[0] = try logger.queue.getOne(io);
var n: usize = 1;
try logger.fill(io, &batch, logger.flushDeadline(io), &n);
try logger.fill(io, &batch, logger.flushDeadline(io), &n, logger.sampleGate());
try testing.expectEqual(@as(usize, 6), n);
// One `writeBatch` call, which is one transaction (`queries_repo.zig`).
@@ -1214,7 +1399,7 @@ test "a zero interval takes what is queued and waits for nothing" {
var n: usize = 1;
// The queue is open and the batch has room: any non-zero interval blocks
// here until it expires. Zero returns with what was already queued.
try logger.fill(io, &batch, logger.flushDeadline(io), &n);
try logger.fill(io, &batch, logger.flushDeadline(io), &n, logger.sampleGate());
try testing.expectEqual(@as(usize, 2), n);
}
@@ -1404,6 +1589,189 @@ test "a writer that cannot prepare closes the queue and counts every entry" {
try testing.expectEqual(@as(u64, 4), logger.queries_dropped.load(.monotonic));
}
test "a queue overflow stamps the drop and leaves the gate episode open" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
// No writer and no monitor: nothing consumes the queue, so the third entry
// has to displace the oldest, and no gate is involved in the loss.
var buf: [2]Entry = undefined;
var logger: Logger = .init(.{}, &buf);
try testing.expectEqual(@as(?i64, null), logger.lastDropSeconds());
for (0..3) |i| logger.log(io, sampleEntry(@intCast(i), "overflow.example"));
try testing.expectEqual(@as(u64, 1), logger.queries_dropped.load(.monotonic));
const stamped = logger.lastDropSeconds() orelse return error.TestUnexpectedResult;
try testing.expect(stamped > 1_700_000_000);
// Cumulative loss is not a current fault: the episode never opened.
try testing.expectEqual(GateEpisode.open, logger.gateEpisode());
}
test "the gating episode opens on the gate, turns losing on a drop, and clears on recovery" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
// Small enough that the entries logged below have to displace each other,
// which is the gate-caused overflow this episode is meant to catch.
var buf: [4]Entry = undefined;
var logger: Logger = .init(.{ .query_log_flush_interval_s = 0 }, &buf);
var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null);
monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic);
logger.log(io, sampleEntry(1, "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);
}
// The gate is holding and nothing has been lost yet, which is not a fault:
// the batch is still going to be written if the disk recovers.
try testing.expectEqual(GateEpisode.gated, logger.gateEpisode());
try testing.expectEqual(@as(u64, 0), logger.queries_dropped.load(.monotonic));
// Now overflow the queue behind the held batch. These drops belong to the
// episode, and that is what turns it from held to losing.
for (0..32) |i| logger.log(io, sampleEntry(@intCast(i + 2), "queued.example"));
try testing.expect(logger.queries_dropped.load(.monotonic) > 0);
try testing.expectEqual(GateEpisode.losing, logger.gateEpisode());
try testing.expect(logger.lastDropSeconds() != null);
// The disk recovers: the held batch goes out and the episode ends.
monitor.state_raw.store(@intFromEnum(disk_monitor.State.ok), .monotonic);
waited = 0;
while (logger.gateEpisode() != .open) : (waited += 1) {
try testing.expect(waited < 400);
try poll.sleep(io);
}
try testing.expect(logger.rows_written.load(.monotonic) > 0);
// The count keeps the history the state does not.
try testing.expect(logger.queries_dropped.load(.monotonic) > 0);
logger.shutdown(io);
try future.await(io);
}
// The two tests below drive the gate primitives directly. A threaded test
// cannot prove the absence of the race they close — it can only fail to hit it
// — so they pin the mechanism instead: the generation a drop must match, and
// the direction the stamp may move.
test "a drop sampled in one episode cannot mark the next one losing" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var queue_buf: [2]Entry = undefined;
var logger: Logger = .init(.{}, &queue_buf);
logger.gateHolds();
// What a producer holds while it stalls: episode one, still holding.
const stalled_in = logger.sampleGate();
try testing.expectEqual(GateEpisode.gated, stalled_in.episode);
// The gate opens and closes again while that producer is descheduled.
logger.gateReopened();
logger.gateHolds();
const episode_two = logger.sampleGate();
try testing.expectEqual(GateEpisode.gated, episode_two.episode);
try testing.expect(episode_two.generation != stalled_in.generation);
// The stale drop still counts as a lost row — it was one — but episode two
// has cost nothing and must not be told it has.
logger.countDropped(io, 1, stalled_in);
try testing.expectEqual(@as(u64, 1), logger.queries_dropped.load(.monotonic));
try testing.expectEqual(GateEpisode.gated, logger.gateEpisode());
// A drop that really belongs to episode two does raise it.
logger.countDropped(io, 1, episode_two);
try testing.expectEqual(GateEpisode.losing, logger.gateEpisode());
// And a second hold of a gate that never opened is the same episode, not a
// new one: `losing` must not fall back to `gated`.
logger.gateHolds();
try testing.expectEqual(GateEpisode.losing, logger.gateEpisode());
try testing.expectEqual(episode_two.generation, logger.sampleGate().generation);
}
fn logOne(logger: *Logger, io: std.Io) void {
logger.log(io, sampleEntry(2, "second.example"));
}
test "a gate that closes mid-enqueue still gets the discard that follows it" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
// Capacity one and no writer, so the second entry has to evict the first
// and the producer discards inside `enqueue`.
var queue_buf: [1]Entry = undefined;
var logger: Logger = .init(.{}, &queue_buf);
logger.log(io, sampleEntry(1, "first.example"));
try testing.expectEqual(GateEpisode.open, logger.gateEpisode());
discard_stall.parked = .unset;
discard_stall.release = .unset;
discard_stall.armed = true;
defer discard_stall.armed = false;
// The producer enters `enqueue` with the gate open — which is the reading a
// sample taken before the loop would keep for the rest of the call.
var producer = try io.concurrent(logOne, .{ &logger, io });
discard_stall.parked.waitUncancelable(io);
// The producer is parked with the row it will evict still on the queue, so
// the episode opens strictly before the loss rather than after it. Nothing
// has been dropped yet, and that is what makes the row this episode's.
try testing.expectEqual(@as(u64, 0), logger.queries_dropped.load(.monotonic));
logger.gateHolds();
discard_stall.armed = false;
discard_stall.release.set(io);
producer.await(io);
try testing.expectEqual(@as(u64, 1), logger.queries_dropped.load(.monotonic));
// The assertion the pre-loop sample fails: it would still be holding
// `open`, `countDropped` would return before its swap, and the episode
// would sit at `gated` having silently cost a row.
try testing.expectEqual(GateEpisode.losing, logger.gateEpisode());
}
test "the drop stamp only ever moves forward" {
var queue_buf: [2]Entry = undefined;
var logger: Logger = .init(.{}, &queue_buf);
try testing.expectEqual(@as(?i64, null), logger.lastDropSeconds());
logger.stampDrop(1_700_000_100);
try testing.expectEqual(@as(?i64, 1_700_000_100), logger.lastDropSeconds());
// A producer that read its clock earlier but arrives later: the newer drop
// already published its time and must keep it.
logger.stampDrop(1_700_000_050);
try testing.expectEqual(@as(?i64, 1_700_000_100), logger.lastDropSeconds());
logger.stampDrop(1_700_000_200);
try testing.expectEqual(@as(?i64, 1_700_000_200), logger.lastDropSeconds());
}
test "a canceled writer counts the batch it was holding" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
+6 -26
View File
@@ -71,24 +71,6 @@ pub const ddl: [:0]const u8 =
\\CREATE INDEX idx_query_log_client ON query_log(client_ip);
\\CREATE INDEX idx_query_log_domain ON query_log(domain_id);
\\
\\CREATE TABLE upstream_targets (
\\ id INTEGER PRIMARY KEY,
\\ url TEXT NOT NULL UNIQUE -- the historical identity: config.db ids cannot cross database files
\\);
\\
\\CREATE TABLE upstream_minute (
\\ upstream_id INTEGER NOT NULL REFERENCES upstream_targets(id),
\\ minute_ts INTEGER NOT NULL,
\\ successes INTEGER NOT NULL,
\\ failures INTEGER NOT NULL,
\\ last_failure_ts INTEGER,
\\ last_error TEXT,
\\ PRIMARY KEY (upstream_id, minute_ts),
\\ CHECK (successes >= 0),
\\ CHECK (failures >= 0)
\\) WITHOUT ROWID;
\\CREATE INDEX idx_upstream_minute_ts ON upstream_minute(minute_ts);
\\
\\CREATE TABLE querylog_meta (
\\ id INTEGER PRIMARY KEY CHECK (id = 1), -- one row, enforced by the schema
\\ created_at INTEGER NOT NULL,
@@ -121,9 +103,9 @@ const set_user_version = std.fmt.comptimePrint("PRAGMA user_version = {d};", .{f
///
/// - Commit never fsyncs at `synchronous = NORMAL`; the checkpoint's fsync is
/// the only guaranteed durability boundary. This moves that boundary from
/// ~40 min to ~5 h of querylog data (query rows plus upstream-history
/// minutes) under power loss or kernel panic. Typical loss stays far smaller
/// because of kernel writeback, but that is not a guarantee.
/// ~40 min to ~5 h of querylog data under power loss or kernel panic.
/// Typical loss stays far smaller because of kernel writeback, but that is
/// not a guarantee.
/// - Process crash or clean stop loses nothing committed, at any threshold.
/// Consistency is never at risk: recovery replays the longest valid WAL
/// prefix atomically.
@@ -325,22 +307,20 @@ test "fingerprint matches a fresh hash of the DDL" {
try testing.expectEqual(fingerprint, @as(i32, @bitCast(std.hash.Crc32.hash(ddl))));
}
test "ddl creates the query-log tables, the upstream-history tables and every index" {
test "ddl creates the query-log tables and every index" {
var database = try db.Db.open(":memory:", .{ .mode = .memory });
defer database.close();
try db.applyPragmas(&database, .{});
try database.exec(ddl);
try testing.expectEqual(
@as(i64, 5),
@as(i64, 3),
try database.queryInt("SELECT count(*) FROM sqlite_schema WHERE type='table'"),
);
const objects = [_][]const u8{
"domains", "query_log",
"idx_query_log_ts", "idx_query_log_client",
"idx_query_log_domain", "upstream_targets",
"upstream_minute", "idx_upstream_minute_ts",
"querylog_meta",
"idx_query_log_domain", "querylog_meta",
};
for (objects) |name| {
var stmt = try database.prepare("SELECT count(*) FROM sqlite_schema WHERE name = ?1");
+18
View File
@@ -172,6 +172,24 @@ pub fn resolveActiveByKey(
return database.changes() != 0;
}
const resolve_by_code_sql =
\\UPDATE operational_events SET resolved_at = ?2
\\ WHERE code = ?1 AND resolved_at IS NULL
;
/// Closes every open episode of `code`, and returns how many. The store uses it
/// once at init for a code no emitter writes any more: an episode whose producer
/// no longer exists can never demonstrate recovery, so nothing but this would
/// ever close it.
pub fn resolveActiveByCode(database: *db.Db, now_s: i64, code: []const u8) db.Error!i64 {
var stmt = try database.prepare(resolve_by_code_sql);
defer stmt.deinit();
try stmt.bindText(1, code);
try stmt.bindInt(2, now_s);
try stmt.exec();
return database.changes();
}
const select_active_id_sql =
"SELECT id FROM operational_events WHERE code = ?1 AND subject_key = ?2 AND resolved_at IS NULL";
+541 -8
View File
@@ -547,7 +547,6 @@ fn likePattern(arena: Allocator, needle: []const u8) Allocator.Error![]const u8
pub const StatsTotals = struct {
queries: u64,
blocked: u64,
cached: u64,
distinct_clients: u64,
avg_response_time_us: ?i64,
};
@@ -557,7 +556,6 @@ pub const StatsTotals = struct {
const stats_totals_sql =
\\SELECT count(*),
\\ coalesce(sum(blocked <> 0), 0),
\\ coalesce(sum(cache_hit = 1), 0),
\\ count(DISTINCT client_ip),
\\ coalesce(sum(response_time_us), 0),
\\ count(response_time_us)
@@ -577,13 +575,12 @@ pub fn statsTotals(database: *db.Db, since: i64, until: i64) db.Error!StatsTotal
// statement is not the one this function prepared.
if (!try stmt.step()) return error.Misuse;
const timed = stmt.columnInt(5);
const timed = stmt.columnInt(4);
return .{
.queries = try countOf(stmt.columnInt(0)),
.blocked = try countOf(stmt.columnInt(1)),
.cached = try countOf(stmt.columnInt(2)),
.distinct_clients = try countOf(stmt.columnInt(3)),
.avg_response_time_us = if (timed == 0) null else @divTrunc(stmt.columnInt(4), timed),
.distinct_clients = try countOf(stmt.columnInt(2)),
.avg_response_time_us = if (timed == 0) null else @divTrunc(stmt.columnInt(3), timed),
};
}
@@ -653,10 +650,217 @@ pub fn timeseries(database: *db.Db, since: i64, bucket_seconds: u32, out: []Buck
return out.len;
}
/// One row of `/api/stats/types`. `qtype` is nullable in the schema, so the
/// rows that carry no type group into a row of their own rather than
/// disappearing from a breakdown that claims to add up.
///
/// No name field: the only qtype-name table lives in the admin, and a second
/// copy here would drift out of agreement with it.
pub const TypeCount = struct {
qtype: ?u16,
count: u64,
};
/// `qtype IS NULL` sorts 0 before 1, which puts the null row last within a tie.
/// The ordering is total, so two reads of one window return the same list in
/// the same order — which is what makes the goldens byte-stable. It is an
/// order, not an identity: a caller keys on the `qtype` value, never on a row's
/// position, because a rank change between refreshes moves rows and must not
/// move what they mean.
const stats_types_sql =
\\SELECT qtype, count(*)
\\ FROM query_log
\\ WHERE timestamp >= ?1 AND timestamp < ?2
\\ GROUP BY qtype
\\ ORDER BY count(*) DESC, qtype IS NULL, qtype ASC
;
/// The query-type breakdown of `[since, until)`. No zero rows: a type absent
/// from the window is absent from the list.
pub fn statsTypes(
database: *db.Db,
arena: Allocator,
since: i64,
until: i64,
) db.Error!std.ArrayList(TypeCount) {
var out: std.ArrayList(TypeCount) = .empty;
var stmt = try database.prepare(stats_types_sql);
defer stmt.deinit();
try stmt.bindInt(1, since);
try stmt.bindInt(2, until);
while (try stmt.step()) {
try out.append(arena, .{
.qtype = if (stmt.isNull(0)) null else try columnU16(&stmt, 0),
.count = try countOf(stmt.columnInt(1)),
});
}
return out;
}
/// One row of `/api/stats/routes`: how a slice of the window was answered.
///
/// `source` is the answering resolver's identity and nothing else — the
/// upstream url for `upstream` rows, the zone for `forward_zone` rows, null
/// everywhere else. It is deliberately not `source_name`, which names the
/// blocklist a block came from and would read as an upstream here.
pub const RouteCount = struct {
route: provenance.RouteKind,
source: ?[]const u8,
count: u64,
};
/// A null upstream on an `upstream` row is its own group, not a dropped row: it
/// is a real state of the log and the caller labels it.
const stats_routes_sql =
\\SELECT route_kind,
\\ CASE route_kind
\\ WHEN 'upstream' THEN upstream
\\ WHEN 'forward_zone' THEN forward_zone
\\ END AS source,
\\ count(*)
\\ FROM query_log
\\ WHERE timestamp >= ?1 AND timestamp < ?2
\\ GROUP BY route_kind, source
\\ ORDER BY count(*) DESC, route_kind ASC, source IS NULL, source ASC
;
/// The answering-route breakdown of `[since, until)`. Strings are copied into
/// `arena`, which outlives the statement.
pub fn statsRoutes(
database: *db.Db,
arena: Allocator,
since: i64,
until: i64,
) db.Error!std.ArrayList(RouteCount) {
var out: std.ArrayList(RouteCount) = .empty;
var stmt = try database.prepare(stats_routes_sql);
defer stmt.deinit();
try stmt.bindInt(1, since);
try stmt.bindInt(2, until);
while (try stmt.step()) {
try out.append(arena, .{
.route = try provenance.parse(provenance.RouteKind, stmt.columnText(0)),
.source = try stmt.columnTextAllocOrNull(arena, 1),
.count = try countOf(stmt.columnInt(2)),
});
}
return out;
}
/// How many clients `/api/stats/clients` names before the rest become `other`.
/// Eight is what one legend can carry without becoming a second table.
pub const max_client_series = 8;
/// One named client's series. `buckets` is always the caller's bucket count
/// long, zero-filled, and aligned exactly like `timeseries`.
pub const ClientSeries = struct {
client: []const u8,
buckets: []const u64,
};
/// `other` is always present and always bucket-count sized — including for an
/// empty window and for a window with eight clients or fewer. A caller charting
/// a stack must not have to invent the residual series.
pub const ClientsBreakdown = struct {
clients: []const ClientSeries,
other: []const u64,
};
/// Ranked by in-window total, ties broken by address, so the cut at eight is
/// the same cut on every request over the same data.
const stats_clients_rank_sql =
\\SELECT client_ip
\\ FROM query_log
\\ WHERE timestamp >= ?1 AND timestamp < ?2
\\ GROUP BY client_ip
\\ ORDER BY count(*) DESC, client_ip ASC
\\ LIMIT ?3
;
const stats_clients_buckets_sql =
\\SELECT client_ip, (timestamp - ?1) / ?2, count(*)
\\ FROM query_log
\\ WHERE timestamp >= ?1 AND timestamp < ?3
\\ GROUP BY 1, 2
;
/// Per-client counts over `bucket_count` buckets of `bucket_seconds` starting
/// at `since`. Everything outside the top `max_client_series` sums into
/// `other`, so the series still add up to the window's total.
///
/// Two statements, one ranking and one bucketing: the caller runs them inside
/// one read transaction, so the rank and the buckets describe one state.
pub fn statsClients(
database: *db.Db,
arena: Allocator,
since: i64,
bucket_seconds: u32,
bucket_count: u32,
) db.Error!ClientsBreakdown {
if (bucket_seconds == 0 or bucket_count == 0) return error.Misuse;
const width: i64 = bucket_seconds;
const span = std.math.mul(i64, width, bucket_count) catch return error.Misuse;
const until = std.math.add(i64, since, span) catch return error.Misuse;
var names: std.ArrayList([]const u8) = .empty;
var series: std.ArrayList([]u64) = .empty;
{
var stmt = try database.prepare(stats_clients_rank_sql);
defer stmt.deinit();
try stmt.bindInt(1, since);
try stmt.bindInt(2, until);
try stmt.bindInt(3, max_client_series);
while (try stmt.step()) {
try names.append(arena, try stmt.columnTextAlloc(arena, 0));
try series.append(arena, try zeroedBuckets(arena, bucket_count));
}
}
const other = try zeroedBuckets(arena, bucket_count);
var stmt = try database.prepare(stats_clients_buckets_sql);
defer stmt.deinit();
try stmt.bindInt(1, since);
try stmt.bindInt(2, width);
try stmt.bindInt(3, until);
while (try stmt.step()) {
// The WHERE clause bounds the index already; the check keeps a schema
// surprise from writing past the slice.
const index = std.math.cast(usize, stmt.columnInt(1)) orelse return error.Mismatch;
if (index >= bucket_count) return error.Mismatch;
const count = try countOf(stmt.columnInt(2));
const client = stmt.columnText(0);
const target = for (names.items, series.items) |name_, buckets| {
if (std.mem.eql(u8, name_, client)) break buckets;
} else other;
target[index] += count;
}
const clients = try arena.alloc(ClientSeries, names.items.len);
for (clients, names.items, series.items) |*entry, name_, buckets| {
entry.* = .{ .client = name_, .buckets = buckets };
}
return .{ .clients = clients, .other = other };
}
fn zeroedBuckets(arena: Allocator, bucket_count: u32) Allocator.Error![]u64 {
const buckets = try arena.alloc(u64, bucket_count);
@memset(buckets, 0);
return buckets;
}
// ---------------------------------------------------------------------------
// tests
// ---------------------------------------------------------------------------
const logger = @import("../logger.zig");
const querylog_schema = @import("../querylog_schema.zig");
const testing = std.testing;
@@ -1469,7 +1673,6 @@ test "statsTotals aggregates the window and averages only the timed rows" {
const totals = try statsTotals(&database, 100, 200);
try testing.expectEqual(@as(u64, 3), totals.queries);
try testing.expectEqual(@as(u64, 1), totals.blocked);
try testing.expectEqual(@as(u64, 1), totals.cached);
try testing.expectEqual(@as(u64, 2), totals.distinct_clients);
// (100 + 200) / 2 — the untimed row is not in the divisor.
try testing.expectEqual(@as(?i64, 150), totals.avg_response_time_us);
@@ -1484,7 +1687,6 @@ test "statsTotals over an empty window is zeros with a null average" {
const totals = try statsTotals(&database, window[0], window[1]);
try testing.expectEqual(@as(u64, 0), totals.queries);
try testing.expectEqual(@as(u64, 0), totals.blocked);
try testing.expectEqual(@as(u64, 0), totals.cached);
try testing.expectEqual(@as(u64, 0), totals.distinct_clients);
try testing.expectEqual(@as(?i64, null), totals.avg_response_time_us);
}
@@ -1588,3 +1790,334 @@ test "likePattern wraps the needle and neutralises every metacharacter" {
try testing.expectEqualStrings("%a\\\\b%", try likePattern(arena, "a\\b"));
try testing.expectEqualStrings("%%", try likePattern(arena, ""));
}
// ---------------------------------------------------------------------------
// period aggregations (milestone 30)
// ---------------------------------------------------------------------------
const agg_since: i64 = 1_700_000_000;
const agg_width: u32 = 60;
const agg_buckets: u32 = 10;
const agg_until: i64 = agg_since + agg_width * agg_buckets;
/// One row of the aggregation fixtures. Everything the three breakdowns read
/// is a parameter; everything else is the same on every row, so a test that
/// changes an outcome names the reason it changed.
fn aggRow(offset: i64, client: []const u8, qtype: ?u16, kind: provenance.RouteKind, source: ?[]const u8) Row {
return .{
.timestamp = agg_since + offset,
.domain = "example.com",
.client_ip = client,
.qtype = qtype,
.qclass = 1,
.rcode = 0,
.blocked = kind == .blocked,
.response_time_us = 1000,
.cache_hit = kind == .cache,
.upstream = if (kind == .upstream) source else null,
.group_id = 1,
.group_name = "default",
.policy_action = if (kind == .blocked) .block else .allow,
.policy_reason = if (kind == .blocked) .blocklist_domain else .no_match,
.matched = null,
.source_id = null,
// Blocklist provenance, deliberately set on every row: the routes
// breakdown must never group by it.
.source_name = "StevenBlack",
.cname_target = null,
.safe_search_target = null,
.route_kind = kind,
.forward_zone = if (kind == .forward_zone) source else null,
};
}
test "the type breakdown groups by qtype, keeps the null row and orders it last" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const arena = arena_state.allocator();
try seed(&database, &.{
aggRow(0, "192.0.2.10", 1, .upstream, "9.9.9.9"),
aggRow(1, "192.0.2.10", 1, .upstream, "9.9.9.9"),
aggRow(2, "192.0.2.10", 1, .upstream, "9.9.9.9"),
aggRow(3, "192.0.2.10", 28, .upstream, "9.9.9.9"),
aggRow(4, "192.0.2.10", 28, .upstream, "9.9.9.9"),
// Ties with qtype 28, so the tie-break puts the lower code first.
aggRow(5, "192.0.2.10", 16, .upstream, "9.9.9.9"),
aggRow(6, "192.0.2.10", 16, .upstream, "9.9.9.9"),
// A row with no type at all: its own group, never a dropped row.
aggRow(7, "192.0.2.10", null, .upstream, "9.9.9.9"),
aggRow(8, "192.0.2.10", null, .upstream, "9.9.9.9"),
// Outside the window.
aggRow(-1, "192.0.2.10", 255, .upstream, "9.9.9.9"),
});
const rows = (try statsTypes(&database, arena, agg_since, agg_until)).items;
try testing.expectEqual(@as(usize, 4), rows.len);
try testing.expectEqual(@as(?u16, 1), rows[0].qtype);
try testing.expectEqual(@as(u64, 3), rows[0].count);
try testing.expectEqual(@as(?u16, 16), rows[1].qtype);
try testing.expectEqual(@as(?u16, 28), rows[2].qtype);
try testing.expectEqual(@as(?u16, null), rows[3].qtype);
try testing.expectEqual(@as(u64, 2), rows[3].count);
}
test "an empty window has no type rows at all" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const rows = (try statsTypes(&database, arena_state.allocator(), agg_since, agg_until)).items;
try testing.expectEqual(@as(usize, 0), rows.len);
}
test "the route breakdown keys on the answering resolver, not on blocklist provenance" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const arena = arena_state.allocator();
try seed(&database, &.{
aggRow(0, "192.0.2.10", 1, .upstream, "https://a.example/dns-query"),
aggRow(1, "192.0.2.10", 1, .upstream, "https://a.example/dns-query"),
aggRow(2, "192.0.2.10", 1, .upstream, "https://b.example/dns-query"),
// An upstream row whose resolver the log did not record: its own group.
aggRow(3, "192.0.2.10", 1, .upstream, null),
aggRow(4, "192.0.2.10", 1, .forward_zone, "lan"),
aggRow(5, "192.0.2.10", 1, .blocked, null),
aggRow(6, "192.0.2.10", 1, .cache, null),
aggRow(7, "192.0.2.10", 1, .local, null),
aggRow(8, "192.0.2.10", 1, .rejected, null),
});
const rows = (try statsRoutes(&database, arena, agg_since, agg_until)).items;
// Two upstreams, one null-source upstream, one forward zone and four
// source-less kinds. Every row carries the same `source_name`, so a
// breakdown that grouped by it would collapse to one row.
try testing.expectEqual(@as(usize, 8), rows.len);
try testing.expectEqual(provenance.RouteKind.upstream, rows[0].route);
try testing.expectEqualStrings("https://a.example/dns-query", rows[0].source.?);
try testing.expectEqual(@as(u64, 2), rows[0].count);
// The seven remaining rows all count 1, so the tie-break orders them:
// route ascending, then source ascending with nulls last.
for (rows[1..]) |row| try testing.expectEqual(@as(u64, 1), row.count);
try testing.expectEqual(provenance.RouteKind.blocked, rows[1].route);
try testing.expectEqual(@as(?[]const u8, null), rows[1].source);
try testing.expectEqual(provenance.RouteKind.cache, rows[2].route);
try testing.expectEqual(provenance.RouteKind.forward_zone, rows[3].route);
try testing.expectEqualStrings("lan", rows[3].source.?);
try testing.expectEqual(provenance.RouteKind.local, rows[4].route);
try testing.expectEqual(provenance.RouteKind.rejected, rows[5].route);
try testing.expectEqual(provenance.RouteKind.upstream, rows[6].route);
try testing.expectEqualStrings("https://b.example/dns-query", rows[6].source.?);
try testing.expectEqual(provenance.RouteKind.upstream, rows[7].route);
try testing.expectEqual(@as(?[]const u8, null), rows[7].source);
}
test "an empty window has no route rows at all" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const rows = (try statsRoutes(&database, arena_state.allocator(), agg_since, agg_until)).items;
try testing.expectEqual(@as(usize, 0), rows.len);
}
test "an empty window still has a zero-filled other series and no named clients" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const result = try statsClients(&database, arena_state.allocator(), agg_since, agg_width, agg_buckets);
try testing.expectEqual(@as(usize, 0), result.clients.len);
try testing.expectEqual(@as(usize, agg_buckets), result.other.len);
for (result.other) |count| try testing.expectEqual(@as(u64, 0), count);
}
test "client series are bucket-aligned, zero-filled and ranked by in-window total" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
try seed(&database, &.{
aggRow(0, "192.0.2.20", 1, .upstream, "9.9.9.9"),
aggRow(1, "192.0.2.20", 1, .upstream, "9.9.9.9"),
aggRow(agg_width * 3, "192.0.2.20", 1, .upstream, "9.9.9.9"),
aggRow(agg_width * 3, "192.0.2.10", 1, .upstream, "9.9.9.9"),
// Outside the window on both sides.
aggRow(-1, "192.0.2.20", 1, .upstream, "9.9.9.9"),
aggRow(agg_width * agg_buckets, "192.0.2.10", 1, .upstream, "9.9.9.9"),
});
const result = try statsClients(&database, arena_state.allocator(), agg_since, agg_width, agg_buckets);
try testing.expectEqual(@as(usize, 2), result.clients.len);
try testing.expectEqualStrings("192.0.2.20", result.clients[0].client);
try testing.expectEqualStrings("192.0.2.10", result.clients[1].client);
for (result.clients) |series| try testing.expectEqual(@as(usize, agg_buckets), series.buckets.len);
try testing.expectEqual(@as(u64, 2), result.clients[0].buckets[0]);
try testing.expectEqual(@as(u64, 1), result.clients[0].buckets[3]);
try testing.expectEqual(@as(u64, 0), result.clients[0].buckets[9]);
try testing.expectEqual(@as(u64, 1), result.clients[1].buckets[3]);
for (result.other) |count| try testing.expectEqual(@as(u64, 0), count);
}
test "the ninth client folds into other and the cut is the same on every read" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const arena = arena_state.allocator();
// Nine clients, each with one more query than the next, so the ranking is
// total and the ninth is unambiguously the one that folds.
var address: [16]u8 = undefined;
var index: u32 = 0;
while (index < 9) : (index += 1) {
const client = try std.fmt.bufPrint(&address, "192.0.2.{d}", .{100 + index});
var repeat: u32 = 0;
while (repeat <= index) : (repeat += 1) {
try seed(&database, &.{aggRow(@intCast(repeat), client, 1, .upstream, "9.9.9.9")});
}
}
const result = try statsClients(&database, arena, agg_since, agg_width, agg_buckets);
try testing.expectEqual(@as(usize, max_client_series), result.clients.len);
// The busiest is 192.0.2.108 with nine rows; the lone folded client is
// 192.0.2.100 with one.
try testing.expectEqualStrings("192.0.2.108", result.clients[0].client);
for (result.clients) |series| {
try testing.expect(!std.mem.eql(u8, "192.0.2.100", series.client));
}
var other_total: u64 = 0;
for (result.other) |count| other_total += count;
try testing.expectEqual(@as(u64, 1), other_total);
}
test "the three breakdowns conserve the window's total" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
const arena = arena_state.allocator();
// A matrix that exercises every branch the aggregations partition on: null
// and non-null qtypes, every route kind, a null resolver identity, and ten
// clients so the top-eight cut has a residual to carry.
const kinds = [_]provenance.RouteKind{ .blocked, .local, .forward_zone, .upstream, .cache, .rejected };
var address: [16]u8 = undefined;
var index: u32 = 0;
while (index < 40) : (index += 1) {
const client = try std.fmt.bufPrint(&address, "192.0.2.{d}", .{100 + index % 10});
const kind = kinds[index % kinds.len];
try seed(&database, &.{aggRow(
@intCast(index % (agg_width * agg_buckets)),
client,
if (index % 7 == 0) null else @intCast(1 + index % 3),
kind,
if (index % 11 == 0) null else "9.9.9.9",
)});
}
const totals = try statsTotals(&database, agg_since, agg_until);
try testing.expect(totals.queries > 0);
var typed: u64 = 0;
for ((try statsTypes(&database, arena, agg_since, agg_until)).items) |row| typed += row.count;
try testing.expectEqual(totals.queries, typed);
var routed: u64 = 0;
for ((try statsRoutes(&database, arena, agg_since, agg_until)).items) |row| routed += row.count;
try testing.expectEqual(totals.queries, routed);
var buckets: [agg_buckets]Bucket = undefined;
_ = try timeseries(&database, agg_since, agg_width, &buckets);
const clients = try statsClients(&database, arena, agg_since, agg_width, agg_buckets);
// Per bucket, not just in total: a series misaligned by one bucket would
// still sum correctly over the window.
for (buckets, 0..) |bucket, at| {
var summed: u64 = clients.other[at];
for (clients.clients) |series| summed += series.buckets[at];
try testing.expectEqual(bucket.queries, summed);
}
}
test "the aggregations pass a redacted client through as the log stored it" {
var database = try openLog();
defer database.close();
var arena_state: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena_state.deinit();
// `hide_client_ips` is applied by the logger before the row is written, so
// the read path has nothing to transform — and must not invent anything
// either. The marker is the client's whole identity here.
try seed(&database, &.{
aggRow(0, logger.hidden_marker, 1, .upstream, "9.9.9.9"),
aggRow(1, logger.hidden_marker, 1, .upstream, "9.9.9.9"),
});
const result = try statsClients(&database, arena_state.allocator(), agg_since, agg_width, agg_buckets);
try testing.expectEqual(@as(usize, 1), result.clients.len);
try testing.expectEqualStrings(logger.hidden_marker, result.clients[0].client);
try testing.expectEqual(@as(u64, 2), result.clients[0].buckets[0]);
}
test "a prune committed mid-read is invisible to the reader's transaction" {
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 reader = try db.Db.open(path, .{ .mode = .read_write_create });
defer reader.close();
try db.applyPragmas(&reader, .{});
try reader.exec(querylog_schema.ddl);
// The seeded watermark is the file's creation second, which is now; the
// fixtures below are in 2023, so the prune's cutoff would never advance it.
try reader.exec(
\\UPDATE querylog_meta SET created_at = 1700000000, available_since = 1700000000 WHERE id = 1
);
try seed(&reader, &.{
plainRow(agg_since, "a.example"),
plainRow(agg_since + 1, "b.example"),
plainRow(agg_since + 300, "c.example"),
});
// A second connection to the same file, as retention has in production.
var pruner = try db.Db.open(path, .{ .mode = .read_write_create });
defer pruner.close();
try db.applyPragmas(&pruner, .{});
var tx = try db.ReadTx.begin(&reader);
const before = try statsTotals(&reader, agg_since, agg_since + 1000);
const watermark_before = try availableSince(&reader);
try testing.expectEqual(@as(u64, 3), before.queries);
// The prune commits while the reader's transaction is open.
const pruned = try pruneOlderThan(&pruner, agg_since + 200);
try testing.expectEqual(@as(i64, 2), pruned.deleted);
try testing.expect(pruned.available_since > watermark_before);
// Neither half of the answer moved: the rows the reader would report and
// the watermark it would tag them with still describe one state.
const during = try statsTotals(&reader, agg_since, agg_since + 1000);
try testing.expectEqual(before.queries, during.queries);
try testing.expectEqual(watermark_before, try availableSince(&reader));
try tx.commit();
// The next response sees the prune — both halves of it.
const after = try statsTotals(&reader, agg_since, agg_since + 1000);
try testing.expectEqual(@as(u64, 1), after.queries);
try testing.expectEqual(pruned.available_since, try availableSince(&reader));
}
@@ -1,493 +0,0 @@
//! `upstream_minute` and its `upstream_targets` dimension table in
//! `querylog.db` (milestone-26 rulings 2, 4, 5).
//!
//! One row per upstream per wall-clock UTC minute that had at least one
//! attempt. Rows are additive facts: a flush adds to whatever is already there,
//! so a restart inside a minute continues that minute's row rather than
//! replacing it, and nothing here can lower a stored count.
//!
//! Identity is the url, not the `config.db` upstream id: ids cannot be foreign
//! keys across database files and may be deleted or reused. Editing an
//! upstream's url deliberately starts a new history.
//!
//! Nothing here retries. The accumulator owns what a failed flush means
//! (`upstream/history.zig`).
const std = @import("std");
const db = @import("../db.zig");
const health = @import("../../upstream/health.zig");
/// How far back `Retention` keeps minute rows. A fixed window, not a knob
/// (m26 anti-requirements), and deliberately wider than the widest dashboard
/// period: `stats.window` derives `since = until - width * count` with
/// `until > now`, so a 30-day window never asks for anything older than
/// `now - 30d`. The extra day is slack for a retention pass that runs late.
///
/// `logging.retention_days` does not apply here. It bounds the query log, whose
/// rows are per-query; these are per-minute aggregates whose whole purpose is
/// to outlive them.
pub const retention_window_s: i64 = 31 * 86_400;
/// One minute of one upstream's outcomes, as the accumulator hands it over.
/// Every string is borrowed for the duration of the call: `Stmt.bindText` binds
/// with `SQLITE_TRANSIENT`, so SQLite copies before `flush` returns.
pub const FlushRow = struct {
url: []const u8,
minute_ts: i64,
successes: u32,
failures: u32,
last_failure_ts: ?i64,
/// Empty when the minute held no failure.
last_error: []const u8,
};
const insert_target_sql = "INSERT OR IGNORE INTO upstream_targets (url) VALUES (?1)";
const select_target_sql = "SELECT id FROM upstream_targets WHERE url = ?1";
/// Additive, and the timestamp columns are max-wins, which is what makes a
/// flush safe to repeat against a row another process already wrote.
///
/// `max()` over a NULL is NULL in SQLite, so the coalesce is what keeps an
/// existing `last_failure_ts` when the incoming row carries none. The `CASE`
/// moves `last_error` with the timestamp it belongs to: a success-only upsert
/// leaves the stored failure and its name exactly as they were.
const upsert_minute_sql =
\\INSERT INTO upstream_minute (upstream_id, minute_ts, successes, failures, last_failure_ts, last_error)
\\VALUES (?1, ?2, ?3, ?4, ?5, ?6)
\\ON CONFLICT(upstream_id, minute_ts) DO UPDATE SET
\\ successes = successes + excluded.successes,
\\ failures = failures + excluded.failures,
\\ last_failure_ts = coalesce(max(last_failure_ts, excluded.last_failure_ts), last_failure_ts, excluded.last_failure_ts),
\\ last_error = CASE
\\ WHEN excluded.last_failure_ts IS NOT NULL
\\ AND (last_failure_ts IS NULL OR excluded.last_failure_ts >= last_failure_ts)
\\ THEN excluded.last_error
\\ ELSE last_error
\\ END
;
/// One transaction for the whole batch: either every minute of the pass lands
/// or none of it does, so a failed flush leaves nothing half-written for the
/// caller's merge-back to double-count.
pub fn flush(database: *db.Db, rows: []const FlushRow) db.Error!void {
if (rows.len == 0) return;
var insert_target = try database.prepare(insert_target_sql);
defer insert_target.deinit();
var select_target = try database.prepare(select_target_sql);
defer select_target.deinit();
var upsert = try database.prepare(upsert_minute_sql);
defer upsert.deinit();
var tx = try db.Tx.begin(database);
errdefer tx.rollback();
for (rows) |row| {
const upstream_id = try internTarget(&insert_target, &select_target, row.url);
try upsert.reset();
try upsert.bindInt(1, upstream_id);
try upsert.bindInt(2, row.minute_ts);
try upsert.bindInt(3, row.successes);
try upsert.bindInt(4, row.failures);
if (row.last_failure_ts) |at| try upsert.bindInt(5, at) else try upsert.bindNull(5);
try upsert.bindText(6, row.last_error);
try upsert.exec();
}
try tx.commit();
}
fn internTarget(insert: *db.Stmt, select: *db.Stmt, url: []const u8) db.Error!i64 {
try insert.reset();
try insert.bindText(1, url);
try insert.exec();
try select.reset();
try select.bindText(1, url);
// The insert above either created the row or found it already there, so a
// miss means the table changed under this connection.
if (!try select.step()) return error.NotFound;
const id = select.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 select.reset();
return id;
}
/// What `GET /api/upstream/health` reports for one upstream over one window.
pub const WindowStats = struct {
attempts: u64,
successes: u64,
failures: u64,
last_failure_ts: ?i64,
/// The error name of the row holding the newest `last_failure_ts` in the
/// window; empty when the window holds no failure.
///
/// By value rather than by slice: the caller loops over upstreams and
/// reuses one `WindowStats`, so a borrowed slice would dangle into the
/// storage the next iteration overwrites.
last_failure_error_buf: [health.error_name_capacity]u8,
last_failure_error_len: u8,
pub fn lastFailureError(self: *const WindowStats) []const u8 {
return self.last_failure_error_buf[0..self.last_failure_error_len];
}
};
/// **One statement, deliberately.** Two statements would not share a SQLite
/// snapshot: the flush connection can commit between them, and the read would
/// then pair a `max(last_failure_ts)` taken from one state with an error text
/// taken from another.
///
/// The error lookup is a scalar subquery for the same reason it is not a bare
/// column: `SELECT max(last_failure_ts), last_error` lets SQLite return the
/// `last_error` of an arbitrary row of the group. `ORDER BY ... DESC, minute_ts
/// DESC` makes the choice deterministic when two minutes share a timestamp.
const window_stats_sql =
\\SELECT coalesce(sum(m.successes), 0), coalesce(sum(m.failures), 0), max(m.last_failure_ts),
\\ (SELECT e.last_error FROM upstream_minute e
\\ WHERE e.upstream_id = m.upstream_id AND e.minute_ts >= ?2 AND e.minute_ts < ?3
\\ AND e.last_failure_ts IS NOT NULL
\\ ORDER BY e.last_failure_ts DESC, e.minute_ts DESC LIMIT 1)
\\ FROM upstream_minute m JOIN upstream_targets t ON t.id = m.upstream_id
\\ WHERE t.url = ?1 AND m.minute_ts >= ?2 AND m.minute_ts < ?3
;
/// Aggregates `[since, until)` by `minute_ts`. An unknown url or an empty
/// window is zeros, a null timestamp and the empty error — not an error.
pub fn windowStats(database: *db.Db, url: []const u8, since: i64, until: i64) db.Error!WindowStats {
var stmt = try database.prepare(window_stats_sql);
defer stmt.deinit();
try stmt.bindText(1, url);
try stmt.bindInt(2, since);
try stmt.bindInt(3, until);
// A bare aggregate always produces exactly one row; no row means the
// statement is not the one this function prepared.
if (!try stmt.step()) return error.Misuse;
const successes = try countOf(stmt.columnInt(0));
const failures = try countOf(stmt.columnInt(1));
var out: WindowStats = .{
.attempts = successes + failures,
.successes = successes,
.failures = failures,
.last_failure_ts = if (stmt.isNull(2)) null else stmt.columnInt(2),
.last_failure_error_buf = @splat(0),
.last_failure_error_len = 0,
};
const name = stmt.columnText(3);
const copied = @min(name.len, out.last_failure_error_buf.len);
@memcpy(out.last_failure_error_buf[0..copied], name[0..copied]);
out.last_failure_error_len = @intCast(copied);
return out;
}
/// `sum` over `CHECK (… >= 0)` columns cannot go negative; a negative value
/// means the row came from something other than this schema.
fn countOf(value: i64) db.Error!u64 {
if (value < 0) return error.Mismatch;
return @intCast(value);
}
/// Deletes every `upstream_minute` row strictly older than `cutoff_ts`, then
/// the targets no surviving row references, and returns how many **minute**
/// rows went.
///
/// One transaction: a target dropped without its rows, or rows dropped while
/// the target delete failed, would leave the foreign key pointing at nothing.
/// The count is minute rows only, so the metric an operator watches counts
/// aggregates rather than dimension-table housekeeping.
pub fn pruneOlderThan(database: *db.Db, cutoff_ts: i64) db.Error!i64 {
var tx = try db.Tx.begin(database);
errdefer tx.rollback();
var minutes = try database.prepare("DELETE FROM upstream_minute WHERE minute_ts < ?1");
defer minutes.deinit();
try minutes.bindInt(1, cutoff_ts);
try minutes.exec();
const deleted = database.changes();
try database.exec(
\\DELETE FROM upstream_targets
\\ WHERE id NOT IN (SELECT upstream_id FROM upstream_minute);
);
try tx.commit();
return deleted;
}
pub fn countMinutes(database: *db.Db) db.Error!i64 {
return database.queryInt("SELECT count(*) FROM upstream_minute");
}
pub fn countTargets(database: *db.Db) db.Error!i64 {
return database.queryInt("SELECT count(*) FROM upstream_targets");
}
// ---------------------------------------------------------------------------
// 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;
}
/// `columnText` is borrowed until the statement is finalized, so the stored
/// error name is copied out rather than returned as a slice.
const StoredMinute = struct {
successes: u32,
failures: u32,
last_failure_ts: ?i64,
error_buf: [health.error_name_capacity]u8,
error_len: u8,
fn lastError(self: *const StoredMinute) []const u8 {
return self.error_buf[0..self.error_len];
}
};
fn readMinute(database: *db.Db, url: []const u8, minute_ts: i64) !StoredMinute {
var stmt = try database.prepare(
\\SELECT m.successes, m.failures, m.last_failure_ts, m.last_error
\\ FROM upstream_minute m JOIN upstream_targets t ON t.id = m.upstream_id
\\ WHERE t.url = ?1 AND m.minute_ts = ?2
);
defer stmt.deinit();
try stmt.bindText(1, url);
try stmt.bindInt(2, minute_ts);
try testing.expect(try stmt.step());
var out: StoredMinute = .{
.successes = @intCast(stmt.columnInt(0)),
.failures = @intCast(stmt.columnInt(1)),
.last_failure_ts = if (stmt.isNull(2)) null else stmt.columnInt(2),
.error_buf = @splat(0),
.error_len = 0,
};
const name = stmt.columnText(3);
@memcpy(out.error_buf[0..name.len], name);
out.error_len = @intCast(name.len);
return out;
}
test "the upsert adds to the row already there rather than replacing it" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 3, .failures = 1, .last_failure_ts = 70, .last_error = "Timeout" },
});
// The shape a restart inside one minute takes: a second process writes the
// same (url, minute) and the counts continue.
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 2, .failures = 4, .last_failure_ts = 90, .last_error = "ConnectFailed" },
});
const row = try readMinute(&database, "https://a.example", 60);
try testing.expectEqual(@as(u32, 5), row.successes);
try testing.expectEqual(@as(u32, 5), row.failures);
try testing.expectEqual(@as(?i64, 90), row.last_failure_ts);
try testing.expectEqualStrings("ConnectFailed", row.lastError());
// One row and one target, not two of either.
try testing.expectEqual(@as(i64, 1), try countMinutes(&database));
try testing.expectEqual(@as(i64, 1), try countTargets(&database));
}
test "a success-only upsert keeps the failure timestamp and its error" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 0, .failures = 1, .last_failure_ts = 70, .last_error = "Timeout" },
});
// `max()` over a NULL is NULL in SQLite, so without the coalesce this
// upsert would erase the timestamp it knows nothing about.
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 5, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
const row = try readMinute(&database, "https://a.example", 60);
try testing.expectEqual(@as(u32, 5), row.successes);
try testing.expectEqual(@as(u32, 1), row.failures);
try testing.expectEqual(@as(?i64, 70), row.last_failure_ts);
try testing.expectEqualStrings("Timeout", row.lastError());
}
test "an older failure does not overwrite the newer error already stored" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 0, .failures = 1, .last_failure_ts = 90, .last_error = "Timeout" },
});
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 0, .failures = 1, .last_failure_ts = 70, .last_error = "ConnectFailed" },
});
const row = try readMinute(&database, "https://a.example", 60);
try testing.expectEqual(@as(?i64, 90), row.last_failure_ts);
try testing.expectEqualStrings("Timeout", row.lastError());
}
test "flush interns each url once and writes every minute of the batch" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://a.example", .minute_ts = 120, .successes = 2, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://b.example", .minute_ts = 60, .successes = 3, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
try testing.expectEqual(@as(i64, 3), try countMinutes(&database));
try testing.expectEqual(@as(i64, 2), try countTargets(&database));
// An empty batch opens no transaction: one is already open here, so a
// `BEGIN IMMEDIATE` would fail.
var tx = try db.Tx.begin(&database);
try flush(&database, &.{});
tx.rollback();
}
test "windowStats sums only the window and pairs the newest failure with its own error" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
// Before the window.
.{ .url = "https://a.example", .minute_ts = 0, .successes = 9, .failures = 9, .last_failure_ts = 30, .last_error = "Outside" },
.{ .url = "https://a.example", .minute_ts = 60, .successes = 2, .failures = 1, .last_failure_ts = 100, .last_error = "ConnectFailed" },
.{ .url = "https://a.example", .minute_ts = 120, .successes = 4, .failures = 2, .last_failure_ts = 170, .last_error = "Timeout" },
// A later minute with no failure at all: the error must still come from
// the minute holding the newest `last_failure_ts`, not from this one.
.{ .url = "https://a.example", .minute_ts = 180, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
// At the exclusive end of the window.
.{ .url = "https://a.example", .minute_ts = 240, .successes = 7, .failures = 7, .last_failure_ts = 250, .last_error = "After" },
// A different upstream in the same minutes.
.{ .url = "https://b.example", .minute_ts = 120, .successes = 5, .failures = 5, .last_failure_ts = 175, .last_error = "Other" },
});
const stats = try windowStats(&database, "https://a.example", 60, 240);
try testing.expectEqual(@as(u64, 7), stats.successes);
try testing.expectEqual(@as(u64, 3), stats.failures);
try testing.expectEqual(@as(u64, 10), stats.attempts);
try testing.expectEqual(@as(?i64, 170), stats.last_failure_ts);
try testing.expectEqualStrings("Timeout", stats.lastFailureError());
}
test "two minutes sharing the newest failure timestamp resolve to the later minute" {
// The tiebreak the subquery's ORDER BY owns. `max(last_failure_ts)` alone
// cannot choose between these two rows, so without a deterministic second
// key the answer is whichever row SQLite happened to visit.
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 0, .failures = 1, .last_failure_ts = 100, .last_error = "Earlier" },
.{ .url = "https://a.example", .minute_ts = 120, .successes = 0, .failures = 1, .last_failure_ts = 100, .last_error = "Later" },
});
const stats = try windowStats(&database, "https://a.example", 0, 1000);
try testing.expectEqual(@as(?i64, 100), stats.last_failure_ts);
try testing.expectEqualStrings("Later", stats.lastFailureError());
}
test "windowStats over an unknown url or an empty window is zeros and no error" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 1, .failures = 1, .last_failure_ts = 70, .last_error = "Timeout" },
});
for ([_][3]i64{ .{ 0, 60, 0 }, .{ 120, 180, 0 }, .{ 60, 60, 0 } }) |window| {
const stats = try windowStats(&database, "https://a.example", window[0], window[1]);
try testing.expectEqual(@as(u64, 0), stats.attempts);
try testing.expectEqual(@as(u64, 0), stats.successes);
try testing.expectEqual(@as(u64, 0), stats.failures);
try testing.expectEqual(@as(?i64, null), stats.last_failure_ts);
try testing.expectEqualStrings("", stats.lastFailureError());
}
const unknown = try windowStats(&database, "https://never.example", 0, 1000);
try testing.expectEqual(@as(u64, 0), unknown.attempts);
try testing.expectEqual(@as(?i64, null), unknown.last_failure_ts);
try testing.expectEqualStrings("", unknown.lastFailureError());
}
test "a window whose only failures are outside it reports no failure at all" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 0, .successes = 0, .failures = 1, .last_failure_ts = 30, .last_error = "Timeout" },
.{ .url = "https://a.example", .minute_ts = 60, .successes = 4, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
const stats = try windowStats(&database, "https://a.example", 60, 120);
try testing.expectEqual(@as(u64, 4), stats.attempts);
try testing.expectEqual(@as(?i64, null), stats.last_failure_ts);
try testing.expectEqualStrings("", stats.lastFailureError());
}
test "pruneOlderThan counts minute rows only and drops the orphaned target" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://old.example", .minute_ts = 60, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://old.example", .minute_ts = 120, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://kept.example", .minute_ts = 120, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://kept.example", .minute_ts = 300, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
// Three minute rows go; the two target deletes must not join the count.
try testing.expectEqual(@as(i64, 3), try pruneOlderThan(&database, 300));
try testing.expectEqual(@as(i64, 1), try countMinutes(&database));
// "old.example" has nothing left, "kept.example" still does.
try testing.expectEqual(@as(i64, 1), try countTargets(&database));
// The row exactly at the cutoff stays, and a second pass finds nothing.
try testing.expectEqual(@as(i64, 0), try pruneOlderThan(&database, 300));
try testing.expectEqual(@as(i64, 1), try countMinutes(&database));
}
test "a failed prune leaves both tables as they were" {
var database = try openLog();
defer database.close();
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
try database.exec(
\\CREATE TRIGGER refuse_target_delete BEFORE DELETE ON upstream_targets
\\BEGIN SELECT RAISE(ABORT, 'refused'); END;
);
// The minute delete succeeds and the target delete does not; one
// transaction means neither survives.
try testing.expectError(error.Constraint, pruneOlderThan(&database, 300));
try testing.expectEqual(@as(i64, 1), try countMinutes(&database));
try testing.expectEqual(@as(i64, 1), try countTargets(&database));
}
test "an error name longer than the buffer is truncated, not overflowed" {
var database = try openLog();
defer database.close();
const long = "A" ** 200;
try flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = 60, .successes = 0, .failures = 1, .last_failure_ts = 70, .last_error = long },
});
const stats = try windowStats(&database, "https://a.example", 60, 120);
try testing.expectEqual(@as(usize, health.error_name_capacity), stats.lastFailureError().len);
try testing.expectEqualStrings(long[0..health.error_name_capacity], stats.lastFailureError());
}
+2 -102
View File
@@ -16,7 +16,6 @@ const disk_monitor = @import("disk_monitor.zig");
const events = @import("events.zig");
const model = @import("../config/model.zig");
const queries_repo = @import("repositories/queries_repo.zig");
const upstream_history_repo = @import("repositories/upstream_history_repo.zig");
const log = std.log.scoped(.retention);
@@ -33,10 +32,6 @@ pub const pass_interval_s = 86_400;
pub const Stats = struct {
passes: u64 = 0,
rows_pruned: u64 = 0,
/// Upstream-history minute rows, counted apart from `rows_pruned`: that
/// counter is the query log's, and an operator watching it must not see it
/// move because a different table was tidied.
upstream_rows_pruned: u64 = 0,
checkpoints: u64 = 0,
vacuums: u64 = 0,
/// Vacuums the disk monitor refused. The pass still pruned and
@@ -50,7 +45,6 @@ pub const Stats = struct {
const Counters = struct {
passes: std.atomic.Value(u64) = .init(0),
rows_pruned: std.atomic.Value(u64) = .init(0),
upstream_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),
@@ -74,7 +68,6 @@ pub const Retention = struct {
return .{
.passes = self.counters.passes.load(.monotonic),
.rows_pruned = self.counters.rows_pruned.load(.monotonic),
.upstream_rows_pruned = self.counters.upstream_rows_pruned.load(.monotonic),
.checkpoints = self.counters.checkpoints.load(.monotonic),
.vacuums = self.counters.vacuums.load(.monotonic),
.vacuums_gated = self.counters.vacuums_gated.load(.monotonic),
@@ -124,22 +117,6 @@ pub const Retention = struct {
maintenance(store, io, now, "prune", @errorName(err));
}
// Before the vacuum-cadence logic below, which returns early on six
// passes out of seven and again whenever the monitor refuses the
// vacuum. A step placed after it would almost never run.
//
// `logging.retention_days` is not the window here: these are per-minute
// aggregates whose whole purpose is to outlive the per-query rows, so
// the window is the repository's own constant.
const history_cutoff = now - upstream_history_repo.retention_window_s;
if (upstream_history_repo.pruneOlderThan(database, history_cutoff)) |deleted| {
add(&self.counters.upstream_rows_pruned, @intCast(deleted));
maintenance(store, io, now, "history_prune", null);
} else |err| {
log.warn("upstream history prune before {d} failed: {s}", .{ history_cutoff, @errorName(err) });
maintenance(store, io, now, "history_prune", @errorName(err));
}
if (queries_repo.checkpointTruncate(database)) {
add(&self.counters.checkpoints, 1);
maintenance(store, io, now, "checkpoint", null);
@@ -443,83 +420,6 @@ test "a failing prune counts the pass and leaves the rows alone" {
try testing.expectEqual(@as(u64, 1), retention.snapshotStats().checkpoints);
}
test "the upstream-history window is its own, and a one-day query log does not shrink it" {
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 - 2 * day, now - 60 });
try upstream_history_repo.flush(&database, &.{
.{ .url = "https://gone.example", .minute_ts = now - 32 * day, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = "https://kept.example", .minute_ts = now - 29 * day, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
// A query log kept for one day, and 30 days of upstream minutes beside it.
var retention: Retention = .init(.{ .retention_days = 1 });
retention.runOnce(io, &database, null, null);
const stats = retention.snapshotStats();
// One query-log row is older than one day; one minute row is older than the
// fixed 31-day upstream window. Each counter moved by its own amount.
try testing.expectEqual(@as(u64, 1), stats.rows_pruned);
try testing.expectEqual(@as(u64, 1), stats.upstream_rows_pruned);
try testing.expectEqual(@as(i64, 1), try upstream_history_repo.countMinutes(&database));
// The day-29 row is exactly what a 30-day dashboard window asks for.
const kept = try upstream_history_repo.windowStats(
&database,
"https://kept.example",
now - 30 * day,
now,
);
try testing.expectEqual(@as(u64, 1), kept.attempts);
// And the emptied target went with its rows.
try testing.expectEqual(@as(i64, 1), try upstream_history_repo.countTargets(&database));
}
test "the history prune runs on the passes where the vacuum logic returns early" {
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 old_minute = now - 40 * 86_400;
// The first pass: `passes_since_vacuum` is 1, so the vacuum block returns
// before it does anything. A prune placed after that block would never run
// on six passes out of seven.
try upstream_history_repo.flush(&database, &.{
.{ .url = "https://a.example", .minute_ts = old_minute, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
var early: Retention = .init(.{});
early.runOnce(io, &database, null, null);
try testing.expectEqual(@as(u64, 1), early.snapshotStats().upstream_rows_pruned);
try testing.expectEqual(@as(i64, 0), try upstream_history_repo.countMinutes(&database));
// The gated pass: the disk monitor refuses the vacuum and that branch
// returns too, and the prune still has to have happened before it.
var monitor: disk_monitor.Monitor = .init(.{}, std.Io.Dir.cwd(), ".", null);
monitor.state_raw.store(@intFromEnum(disk_monitor.State.critical), .monotonic);
var gated: Retention = .init(.{});
for (0..vacuum_every_passes - 1) |_| gated.runOnce(io, &database, &monitor, null);
try upstream_history_repo.flush(&database, &.{
.{ .url = "https://b.example", .minute_ts = old_minute, .successes = 1, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
gated.runOnce(io, &database, &monitor, null);
try testing.expectEqual(@as(u64, 1), gated.snapshotStats().vacuums_gated);
try testing.expectEqual(@as(u64, 1), gated.snapshotStats().upstream_rows_pruned);
try testing.expectEqual(@as(i64, 0), try upstream_history_repo.countMinutes(&database));
}
test "the next pass retries what the failed one could not do" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
@@ -569,8 +469,8 @@ test "a failing prune opens a maintenance episode the next clean pass closes" {
var retention: Retention = .init(.{});
retention.runOnce(io, &database, null, &fx.store);
// Only the prune failed; checkpoint and history prune succeeded, and a
// success writes no row of its own.
// 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"));
-3
View File
@@ -77,11 +77,9 @@ comptime {
_ = @import("cache/dns_cache.zig");
_ = @import("server/rate_limiter.zig");
_ = @import("storage/repositories/queries_repo.zig");
_ = @import("storage/repositories/upstream_history_repo.zig");
_ = @import("storage/repositories/events_repo.zig");
_ = @import("storage/events.zig");
_ = @import("storage/events_fixture.zig");
_ = @import("upstream/history.zig");
_ = @import("storage/logger.zig");
_ = @import("platform/statfs.zig");
_ = @import("storage/disk_monitor.zig");
@@ -109,7 +107,6 @@ comptime {
_ = @import("web/handlers/queries.zig");
_ = @import("web/handlers/diagnostics.zig");
_ = @import("web/handlers/lookup.zig");
_ = @import("web/handlers/upstream_health.zig");
_ = @import("web/handlers/health.zig");
_ = @import("web/handlers/version.zig");
_ = @import("web/handlers/mutations.zig");
+1 -4
View File
@@ -45,10 +45,7 @@ pub const Config = struct {
/// `State.window`.
pub const window_len = 32;
/// Bytes kept of an `@errorName`, truncated to fit. Shared rather than repeated:
/// `history.Accumulator.Cell` and `upstream_history_repo.WindowStats` carry the
/// same name through the minute aggregates, and three buffers of three different
/// sizes would truncate one error name three ways.
/// Bytes kept of an `@errorName`, truncated to fit.
pub const error_name_capacity = 48;
/// The shift is capped so `base_backoff_ms << shift` cannot run away; by then
-716
View File
@@ -1,716 +0,0 @@
//! Per-minute upstream outcome history (milestone-26 rulings 1, 3, 4).
//!
//! Outcomes are aggregated into their wall-clock UTC minute at the moment the
//! pool records them, and the aggregates are flushed to `querylog.db` once a
//! minute. **Nothing samples a lifetime counter and subtracts.** That is what
//! makes the stored numbers additive facts: a restart inside a minute adds to
//! the same row, a crash loses at most the cells that had not flushed yet, and
//! no path anywhere can produce a negative delta.
//!
//! The query path may not touch SQLite, so recording is memory-only under this
//! module's own mutex and the writing happens on a task of its own.
//!
//! Two failure modes, deliberately kept apart:
//!
//! * **Overflow.** More live `(url, minute)` pairs than `max_pending`. The
//! oldest minute is dropped, `rows_dropped` counts it and
//! `last_drop_minute` remembers how new the newest lost minute was, so a
//! window that starts after it can still be reported as complete.
//! * **A failed flush.** Nothing is dropped: the rows go back into the
//! accumulator and the next pass writes them again.
//!
//! The wall clock, not `.awake`: history participates in wall-clock periods, so
//! a minute here is the same minute the dashboard's period picker means.
//! Routing state (`health.zig`) stays on `.awake` and is untouched by this
//! file.
const std = @import("std");
const db = @import("../storage/db.zig");
const events = @import("../storage/events.zig");
const health = @import("health.zig");
const upstream_history_repo = @import("../storage/repositories/upstream_history_repo.zig");
const log = std.log.scoped(.upstream_history);
/// Live `(url, minute)` cells. Not a knob (m26 anti-requirements). A household
/// pool is a handful of upstreams, so the bound is only reachable when flushing
/// has been failing for hours.
pub const max_pending = 4096;
/// One flush pass per minute, so an unflushed cell is at most about a minute
/// old. `.boot` rather than `.awake`, for `retention.zig`'s reason: a box that
/// suspends must still see its interval elapse.
pub const flush_interval_s = 60;
/// The UTC minute `wall_s` falls in, as its start in seconds. `@divFloor`, not
/// `@divTrunc`: a negative second belongs to the minute before it.
pub fn minuteOf(wall_s: i64) i64 {
return @divFloor(wall_s, 60) * 60;
}
/// The write seam. Production passes `upstream_history_repo.flush`; a test
/// passes a stub that fails, or one that records what it was handed.
pub const WriteFn = *const fn (*db.Db, []const upstream_history_repo.FlushRow) db.Error!void;
pub const Accumulator = struct {
pub const Cell = struct {
/// Borrowed from the pool entry's endpoint, which lives as long as the
/// process. Nothing here copies it, and nothing here may outlive it.
url: []const u8,
minute_ts: i64,
/// Both counters saturate instead of wrapping: every write site uses
/// `+|=` — `recordSuccess`, `recordFailure`, and `mergeBack`, which
/// sums a failed flush's copy back into the live cell. The saturation
/// is deliberate and unreachable: a cell counts one upstream's
/// outcomes inside a single wall-clock minute, so filling a `u32`
/// would take about 72 million exchanges per second with that one
/// upstream. Nothing reports it, by design — `last_drop_minute` and
/// the `complete` flag it feeds describe capacity drops, and a
/// saturated counter is not a drop.
successes: u32,
failures: u32,
last_failure_ts: ?i64,
last_error_buf: [health.error_name_capacity]u8,
last_error_len: u8,
fn lastError(self: *const Cell) []const u8 {
return self.last_error_buf[0..self.last_error_len];
}
};
/// A consistent copy for `/metrics`, `/api/health` and the API layer.
pub const Stats = struct {
flushes: u64 = 0,
flush_failures: u64 = 0,
rows_dropped: u64 = 0,
pending: u32 = 0,
/// The newest minute capacity has ever cost this process, or null when
/// nothing was ever dropped. A window that starts after it is complete
/// again, so one historical overflow does not mark every later answer.
last_drop_minute: ?i64 = null,
/// Current state, not a count: set by a failed flush and cleared by the
/// next successful one. Feeds the `/api/health` rollup.
last_flush_failed: bool = false,
};
/// Atomic for the reason `retention.zig`'s are: the flush task writes them
/// and the web task reads them, on different threads. They are bumped
/// outside the mutex, so the lock is not what orders them.
const Counters = struct {
flushes: std.atomic.Value(u64) = .init(0),
flush_failures: std.atomic.Value(u64) = .init(0),
rows_dropped: std.atomic.Value(u64) = .init(0),
};
mutex: std.Io.Mutex = .init,
cells: [max_pending]Cell,
count: u32,
last_drop_minute: ?i64,
last_flush_failed: bool,
counters: Counters,
/// Owned by whichever task runs `flushOnce`, which is one task. It is a
/// field rather than a local so that the megabyte it costs lives wherever
/// the accumulator was placed instead of on a task's stack.
flush_cells: [max_pending]Cell,
flush_rows: [max_pending]upstream_history_repo.FlushRow,
flush_count: u32,
/// Set once by the composition root after `init`, following the
/// `gate: ?*disk_monitor.Monitor` idiom. Null everywhere else, and every
/// emit site below is inert when it is.
diagnostics: ?*events.Store = null,
/// `cells` and `flush_cells` are `undefined`: a cell is always written
/// before it is read, and `count` is what says which ones exist.
pub const init: Accumulator = .{
.mutex = .init,
.cells = undefined,
.count = 0,
.last_drop_minute = null,
.last_flush_failed = false,
.counters = .{},
.flush_cells = undefined,
.flush_rows = undefined,
.flush_count = 0,
};
pub fn recordSuccess(self: *Accumulator, io: std.Io, url: []const u8, wall_s: i64) void {
// Uncancelable for the reason the pool's health sections are: this
// takes no Io and never blocks on a peer, and losing the record of a
// completed exchange to a cancellation would undercount for good.
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
const cell = self.cellFor(url, minuteOf(wall_s));
cell.successes +|= 1;
}
pub fn recordFailure(
self: *Accumulator,
io: std.Io,
url: []const u8,
wall_s: i64,
error_name: []const u8,
) void {
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
const cell = self.cellFor(url, minuteOf(wall_s));
cell.failures +|= 1;
noteFailure(cell, wall_s, error_name);
}
/// The only read surface. Every field above is private to this module, so
/// no consumer can read one of them without the mutex.
pub fn snapshotStats(self: *Accumulator, io: std.Io) Stats {
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
return .{
.flushes = self.counters.flushes.load(.monotonic),
.flush_failures = self.counters.flush_failures.load(.monotonic),
.rows_dropped = self.counters.rows_dropped.load(.monotonic),
.pending = self.count,
.last_drop_minute = self.last_drop_minute,
.last_flush_failed = self.last_flush_failed,
};
}
/// The cell for `(url, minute_ts)`, created if it is not there yet. The
/// caller holds the mutex.
///
/// Linear: the live set is one cell per upstream per unflushed minute,
/// which at household scale is a handful. A miss at capacity evicts the
/// oldest minute — see `evictOldest`.
fn cellFor(self: *Accumulator, url: []const u8, minute_ts: i64) *Cell {
for (self.cells[0..self.count]) |*cell| {
if (cell.minute_ts != minute_ts) continue;
// Pointer equality first: every call from the pool passes the same
// `Entry.endpoint.url`, so the byte compare is the cold path.
if (cell.url.ptr == url.ptr and cell.url.len == url.len) return cell;
if (std.mem.eql(u8, cell.url, url)) return cell;
}
const slot = if (self.count < max_pending) fresh: {
const index = self.count;
self.count += 1;
break :fresh &self.cells[index];
} else self.evictOldest();
slot.* = .{
.url = url,
.minute_ts = minute_ts,
.successes = 0,
.failures = 0,
.last_failure_ts = null,
.last_error_buf = @splat(0),
.last_error_len = 0,
};
return slot;
}
/// Frees the cell holding the oldest minute and accounts for what it cost.
///
/// `last_drop_minute` moves through `@max` and never through assignment: a
/// merge-back after a failed flush can evict a cell older than one already
/// dropped, and a watermark that moved backwards would report a window as
/// complete when outcomes inside it are gone.
fn evictOldest(self: *Accumulator) *Cell {
var oldest: usize = 0;
for (self.cells[1..self.count], 1..) |*cell, i| {
if (cell.minute_ts < self.cells[oldest].minute_ts) oldest = i;
}
const evicted = self.cells[oldest].minute_ts;
self.last_drop_minute = @max(self.last_drop_minute orelse evicted, evicted);
_ = self.counters.rows_dropped.fetchAdd(1, .monotonic);
return &self.cells[oldest];
}
/// One flush pass: swap the dirty cells out, write them, and on failure put
/// them back.
///
/// **A swap, never a subtraction.** SQLite runs outside the mutex, so while
/// it does, a full accumulator can evict a cell that was copied out and
/// then recreate the same `(url, minute_ts)`. A post-flush subtract would
/// then destroy outcomes recorded during the write. Moving the cells out
/// makes the flush own them: what is recorded beside it is new data, and a
/// failure merges the two additively.
///
/// Every failure is counted and warned about once; nothing here returns an
/// error, because there is no caller that could do anything the next pass
/// will not do anyway.
pub fn flushOnce(self: *Accumulator, io: std.Io, database: *db.Db, write: WriteFn) void {
{
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
if (self.count == 0) return;
@memcpy(self.flush_cells[0..self.count], self.cells[0..self.count]);
self.flush_count = self.count;
self.count = 0;
}
const rows = self.flush_rows[0..self.flush_count];
for (self.flush_cells[0..self.flush_count], rows) |*cell, *row| {
row.* = .{
.url = cell.url,
.minute_ts = cell.minute_ts,
.successes = cell.successes,
.failures = cell.failures,
.last_failure_ts = cell.last_failure_ts,
.last_error = cell.lastError(),
};
}
if (write(database, rows)) {
_ = self.counters.flushes.fetchAdd(1, .monotonic);
if (self.diagnostics) |store| {
store.resolve(io, std.Io.Clock.real.now(io).toSeconds(), .upstream_history_write, flush_key);
}
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
self.last_flush_failed = false;
return;
} else |err| {
_ = self.counters.flush_failures.fetchAdd(1, .monotonic);
log.warn("flushing {d} upstream history rows failed: {s}", .{ rows.len, @errorName(err) });
if (self.diagnostics) |store| {
var buf: [events.Store.max_detail_len]u8 = undefined;
const detail = std.fmt.bufPrint(&buf, "flushing {d} upstream history rows failed: {s}", .{
rows.len,
@errorName(err),
}) catch buf[0..];
store.report(
io,
std.Io.Clock.real.now(io).toSeconds(),
.upstream_history_write,
flush_key,
"upstream history flush",
.warning,
detail,
);
}
self.mergeBack(io);
}
}
/// Puts a failed pass's cells back through the rules recording uses: a cell
/// recorded during the write keeps its outcomes and the merge sums into it,
/// and a merge that overflows follows the ordinary drop policy.
fn mergeBack(self: *Accumulator, io: std.Io) void {
self.mutex.lockUncancelable(io);
defer self.mutex.unlock(io);
self.last_flush_failed = true;
for (self.flush_cells[0..self.flush_count]) |*saved| {
const cell = self.cellFor(saved.url, saved.minute_ts);
cell.successes +|= saved.successes;
cell.failures +|= saved.failures;
if (saved.last_failure_ts) |at| noteFailure(cell, at, saved.lastError());
}
}
/// Daily-loop shape (`retention.zig`): flush first, then sleep, so a
/// process that is about to be canceled has already written once.
pub fn run(self: *Accumulator, io: std.Io, database: *db.Db) std.Io.Cancelable!void {
const interval: std.Io.Clock.Duration = .{
.raw = .fromSeconds(flush_interval_s),
.clock = .boot,
};
while (true) {
self.flushOnce(io, database, upstream_history_repo.flush);
try interval.sleep(io);
}
}
};
/// One accumulator, one flush task, one table: the subject of every
/// `upstream_history.write` episode is that single writer.
const flush_key = "flush";
/// Max-wins, matching the SQL upsert exactly: the newest failure in the minute
/// is the one whose name the cell keeps.
fn noteFailure(cell: *Accumulator.Cell, at: i64, error_name: []const u8) void {
if (cell.last_failure_ts) |existing| {
if (at < existing) return;
}
cell.last_failure_ts = at;
const copied = @min(error_name.len, cell.last_error_buf.len);
@memcpy(cell.last_error_buf[0..copied], error_name[0..copied]);
cell.last_error_len = @intCast(copied);
}
// ---------------------------------------------------------------------------
// tests
// ---------------------------------------------------------------------------
const events_fixture = @import("../storage/events_fixture.zig");
const querylog_schema = @import("../storage/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;
}
/// The accumulator is about a megabyte, which is more than a test frame should
/// carry.
fn newAccumulator() !*Accumulator {
const acc = try testing.allocator.create(Accumulator);
acc.* = .init;
return acc;
}
fn failingWrite(_: *db.Db, _: []const upstream_history_repo.FlushRow) db.Error!void {
return error.Busy;
}
/// What the last stubbed flush was handed, copied out so an assertion can read
/// it after the pass returned.
var recorded: [8]upstream_history_repo.FlushRow = undefined;
var recorded_len: usize = 0;
fn recordingWrite(_: *db.Db, rows: []const upstream_history_repo.FlushRow) db.Error!void {
recorded_len = @min(rows.len, recorded.len);
@memcpy(recorded[0..recorded_len], rows[0..recorded_len]);
}
/// The interleaving of ruling 4: a flush is in flight, and the recording side
/// recreates a swapped-out cell and then fills the accumulator to overflow.
var interleaved: ?*Accumulator = null;
var interleave_io: ?std.Io = null;
var interleave_urls: [max_pending][8]u8 = undefined;
fn interleavingWrite(_: *db.Db, _: []const upstream_history_repo.FlushRow) db.Error!void {
const acc = interleaved.?;
const io = interleave_io.?;
// The very `(url, minute_ts)` the flush is holding, recorded again while
// the write runs.
acc.recordSuccess(io, "https://a.example", 60);
// And then enough distinct minutes to fill the accumulator and evict.
for (&interleave_urls, 0..) |*name, i| {
const url = std.fmt.bufPrint(name, "u{d:0>6}", .{i}) catch unreachable;
acc.recordSuccess(io, url, @as(i64, @intCast(i)) * 600 + 6000);
}
return error.Busy;
}
test "minuteOf floors to the minute, including before the epoch" {
try testing.expectEqual(@as(i64, 0), minuteOf(0));
try testing.expectEqual(@as(i64, 0), minuteOf(59));
try testing.expectEqual(@as(i64, 60), minuteOf(60));
try testing.expectEqual(@as(i64, 120), minuteOf(179));
try testing.expectEqual(@as(i64, -60), minuteOf(-1));
}
test "outcomes land in the cell of their own minute and upstream" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordSuccess(io, "https://a.example", 65);
acc.recordSuccess(io, "https://a.example", 119);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.recordSuccess(io, "https://a.example", 130);
acc.recordSuccess(io, "https://b.example", 70);
// Three cells: a/60, a/120 and b/60.
try testing.expectEqual(@as(u32, 3), acc.snapshotStats(io).pending);
const first = acc.cellFor("https://a.example", 60);
try testing.expectEqual(@as(u32, 2), first.successes);
try testing.expectEqual(@as(u32, 1), first.failures);
try testing.expectEqual(@as(?i64, 100), first.last_failure_ts);
try testing.expectEqualStrings("Timeout", first.lastError());
const second = acc.cellFor("https://a.example", 120);
try testing.expectEqual(@as(u32, 1), second.successes);
try testing.expectEqual(@as(u32, 0), second.failures);
try testing.expectEqual(@as(?i64, null), second.last_failure_ts);
}
test "a cell keeps the newest failure's error and ignores an older one" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.recordFailure(io, "https://a.example", 80, "ConnectFailed");
const cell = acc.cellFor("https://a.example", 60);
try testing.expectEqual(@as(u32, 2), cell.failures);
try testing.expectEqual(@as(?i64, 100), cell.last_failure_ts);
try testing.expectEqualStrings("Timeout", cell.lastError());
acc.recordFailure(io, "https://a.example", 110, "BadResponse");
try testing.expectEqual(@as(?i64, 110), cell.last_failure_ts);
try testing.expectEqualStrings("BadResponse", cell.lastError());
const long = "A" ** 200;
acc.recordFailure(io, "https://a.example", 115, long);
try testing.expectEqual(@as(usize, health.error_name_capacity), cell.lastError().len);
}
test "at capacity the oldest minute is dropped, counted, and the watermark only moves forward" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
var names: [max_pending][8]u8 = undefined;
for (&names, 0..) |*name, i| {
const url = std.fmt.bufPrint(name, "u{d:0>6}", .{i}) catch unreachable;
// Minute 600 is the oldest; every later cell is newer.
acc.recordSuccess(io, url, 600 + @as(i64, @intCast(i)) * 60);
}
try testing.expectEqual(@as(u32, max_pending), acc.snapshotStats(io).pending);
try testing.expectEqual(@as(u64, 0), acc.snapshotStats(io).rows_dropped);
try testing.expectEqual(@as(?i64, null), acc.snapshotStats(io).last_drop_minute);
// One more cell evicts the oldest minute and nothing else.
acc.recordSuccess(io, "https://new.example", 10_000_000);
const after = acc.snapshotStats(io);
try testing.expectEqual(@as(u32, max_pending), after.pending);
try testing.expectEqual(@as(u64, 1), after.rows_dropped);
try testing.expectEqual(@as(?i64, 600), after.last_drop_minute);
// A later eviction of an *older* minute must not move the watermark back.
acc.recordSuccess(io, "https://older.example", 120);
const back = acc.snapshotStats(io);
try testing.expectEqual(@as(u64, 2), back.rows_dropped);
try testing.expectEqual(@as(?i64, 660), back.last_drop_minute);
acc.recordSuccess(io, "https://newer.example", 20_000_000);
const forward = acc.snapshotStats(io);
try testing.expectEqual(@as(u64, 3), forward.rows_dropped);
// The minute just evicted is 120, older than the 660 already recorded.
try testing.expectEqual(@as(?i64, 660), forward.last_drop_minute);
}
test "a successful flush hands over every cell, empties the accumulator and counts once" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordSuccess(io, "https://a.example", 65);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.flushOnce(io, &database, recordingWrite);
try testing.expectEqual(@as(usize, 1), recorded_len);
try testing.expectEqualStrings("https://a.example", recorded[0].url);
try testing.expectEqual(@as(i64, 60), recorded[0].minute_ts);
try testing.expectEqual(@as(u32, 1), recorded[0].successes);
try testing.expectEqual(@as(u32, 1), recorded[0].failures);
try testing.expectEqual(@as(?i64, 100), recorded[0].last_failure_ts);
try testing.expectEqualStrings("Timeout", recorded[0].last_error);
const stats = acc.snapshotStats(io);
try testing.expectEqual(@as(u32, 0), stats.pending);
try testing.expectEqual(@as(u64, 1), stats.flushes);
try testing.expectEqual(@as(u64, 0), stats.flush_failures);
try testing.expect(!stats.last_flush_failed);
}
test "a pass with nothing pending counts neither a flush nor a failure" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.flushOnce(io, &database, failingWrite);
acc.flushOnce(io, &database, recordingWrite);
const stats = acc.snapshotStats(io);
try testing.expectEqual(@as(u64, 0), stats.flushes);
try testing.expectEqual(@as(u64, 0), stats.flush_failures);
try testing.expect(!stats.last_flush_failed);
}
test "a failed flush keeps the rows, sets the flag, and the next success clears it" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordSuccess(io, "https://a.example", 65);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.flushOnce(io, &database, failingWrite);
const failed = acc.snapshotStats(io);
try testing.expectEqual(@as(u64, 0), failed.flushes);
try testing.expectEqual(@as(u64, 1), failed.flush_failures);
try testing.expectEqual(@as(u64, 0), failed.rows_dropped);
try testing.expect(failed.last_flush_failed);
// Nothing was lost: the cell is back, whole.
try testing.expectEqual(@as(u32, 1), failed.pending);
const cell = acc.cellFor("https://a.example", 60);
try testing.expectEqual(@as(u32, 1), cell.successes);
try testing.expectEqual(@as(u32, 1), cell.failures);
try testing.expectEqualStrings("Timeout", cell.lastError());
// The retry writes what the failed pass could not.
acc.recordSuccess(io, "https://a.example", 70);
acc.flushOnce(io, &database, recordingWrite);
const cleared = acc.snapshotStats(io);
try testing.expectEqual(@as(u64, 1), cleared.flushes);
try testing.expectEqual(@as(u64, 1), cleared.flush_failures);
try testing.expect(!cleared.last_flush_failed);
try testing.expectEqual(@as(usize, 1), recorded_len);
try testing.expectEqual(@as(u32, 2), recorded[0].successes);
try testing.expectEqual(@as(u32, 1), recorded[0].failures);
}
test "a merge-back sums into what was recorded beside the flush" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
// The write recreates the swapped-out cell before it fails, which is the
// interleaving the swap makes possible.
interleaved = acc;
interleave_io = io;
defer {
interleaved = null;
interleave_io = null;
}
acc.recordSuccess(io, "https://a.example", 65);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.flushOnce(io, &database, interleavingWrite);
const stats = acc.snapshotStats(io);
try testing.expect(stats.last_flush_failed);
try testing.expectEqual(@as(u64, 1), stats.flush_failures);
// Two drops, and they are different drops: filling to capacity during the
// write evicted the recreated minute 60, and the merge-back then found no
// room either and evicted the oldest of what the write had left, 6000.
// Overflow loss is the specced policy; what matters is that it is counted.
try testing.expectEqual(@as(u32, max_pending), stats.pending);
try testing.expectEqual(@as(u64, 2), stats.rows_dropped);
// Forward only: the second eviction was the newer minute of the two.
try testing.expectEqual(@as(?i64, 6000), stats.last_drop_minute);
// The merged cell is back, carrying what the failed flush was holding.
const merged = acc.cellFor("https://a.example", 60);
try testing.expectEqual(@as(u32, 1), merged.successes);
try testing.expectEqual(@as(u32, 1), merged.failures);
try testing.expectEqualStrings("Timeout", merged.lastError());
// The flush-owned buffer was not touched by any of the recording that
// happened beside it: it still holds exactly what was swapped out.
try testing.expectEqual(@as(u32, 1), acc.flush_count);
try testing.expectEqual(@as(u32, 1), acc.flush_cells[0].successes);
try testing.expectEqual(@as(u32, 1), acc.flush_cells[0].failures);
try testing.expectEqual(@as(i64, 60), acc.flush_cells[0].minute_ts);
}
test "a flush against the real repository writes the minute rows" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordSuccess(io, "https://a.example", 65);
acc.recordFailure(io, "https://a.example", 100, "Timeout");
acc.recordSuccess(io, "https://b.example", 130);
acc.flushOnce(io, &database, upstream_history_repo.flush);
// The second pass is the restart shape: the same minute, added to.
acc.recordSuccess(io, "https://a.example", 90);
acc.flushOnce(io, &database, upstream_history_repo.flush);
const stats = try upstream_history_repo.windowStats(&database, "https://a.example", 0, 200);
try testing.expectEqual(@as(u64, 2), stats.successes);
try testing.expectEqual(@as(u64, 1), stats.failures);
try testing.expectEqual(@as(u64, 3), stats.attempts);
try testing.expectEqual(@as(?i64, 100), stats.last_failure_ts);
try testing.expectEqualStrings("Timeout", stats.lastFailureError());
try testing.expectEqual(@as(i64, 2), try upstream_history_repo.countMinutes(&database));
try testing.expectEqual(@as(u64, 2), acc.snapshotStats(io).flushes);
}
test "a failed flush opens one episode and the next successful flush closes it" {
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 acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.diagnostics = &fx.store;
acc.recordFailure(io, "https://a.example", 1_700_000_000, "Timeout");
acc.flushOnce(io, &database, failingWrite);
try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events"));
try testing.expectEqualStrings("upstream_history.write", try fx.text("SELECT code FROM operational_events"));
try testing.expectEqualStrings("flush", try fx.text("SELECT subject_key FROM operational_events"));
try testing.expectEqualStrings("warning", try fx.text("SELECT severity FROM operational_events"));
try testing.expectEqual(
@as(i64, 1),
try fx.count("SELECT count(*) FROM operational_events WHERE resolved_at IS NULL"),
);
acc.flushOnce(io, &database, upstream_history_repo.flush);
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 flush with no store attached records nothing and still flushes" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const acc = try newAccumulator();
defer testing.allocator.destroy(acc);
acc.recordFailure(io, "https://a.example", 1_700_000_000, "Timeout");
acc.flushOnce(io, &database, failingWrite);
acc.flushOnce(io, &database, upstream_history_repo.flush);
try testing.expectEqual(@as(u64, 1), acc.counters.flushes.load(.monotonic));
}
+15 -98
View File
@@ -49,7 +49,6 @@ const std = @import("std");
const events = @import("../storage/events.zig");
const health = @import("health.zig");
const history_mod = @import("history.zig");
const safe_url = @import("../safe_url.zig");
const transport = @import("transport.zig");
@@ -90,14 +89,13 @@ pub const Entry = struct {
busy: std.Io.Mutex = .init,
};
/// A copy of one entry's health, taken under the mutex. Feeds
/// `GET /api/upstream/health`.
/// A copy of one entry's health, taken under the mutex. Feeds `/metrics` and
/// the `/api/health` upstream condition.
pub const Snapshot = struct {
/// Whole, not redacted. `GET /api/upstream/health` returns this to a session
/// that `GET /api/upstreams` already serves the same url to in full, so
/// redacting here would hide nothing from that reader and would make two
/// responses of one API disagree. A consumer reachable without a session has
/// to redact it itself.
/// Whole, not redacted. `GET /api/upstreams` already serves the same url in
/// full to a session, so redacting here would hide nothing from that reader
/// and would make two responses of one API disagree. A consumer reachable
/// without a session has to redact it itself.
url: []const u8,
enabled: bool,
available: bool,
@@ -131,14 +129,11 @@ pub const Pool = struct {
timeouts: Timeouts,
mutex: std.Io.Mutex,
rng: std.Random.DefaultPrng,
/// Where recorded outcomes also go, as per-minute aggregates for the
/// dashboard's ranged view (m26). Defaulted rather than an `init`
/// parameter: the composition root wires it after the pool exists, and the
/// pool is fully usable without it — `nxdns check` and every unit test here
/// run with no history at all.
history: ?*history_mod.Accumulator = null,
/// The diagnostics store, wired the same way and for the same reason as
/// `history`. Every emit here sits outside `mutex`; see `recordHistory`.
/// The diagnostics store. Defaulted rather than an `init` parameter: the
/// composition root wires it after the pool exists, and the pool is fully
/// usable without it — `nxdns check` and every unit test here run with no
/// store at all. Every emit here sits outside `mutex`; see
/// `recordDiagnostics`.
diagnostics: ?*events.Store = null,
pub fn init(
@@ -345,9 +340,8 @@ pub const Pool = struct {
entry.health.recordSuccess(at);
}
// The block above closes before this line, and that ordering is the
// constraint: the accumulator takes a mutex of its own, and no task may
// hold one of the two while it takes the other.
self.recordHistory(io, entry, .success);
// constraint: the store takes a mutex of its own, and no task may hold
// one of the two while it takes the other.
self.recordDiagnostics(io, entry, .success);
}
@@ -365,26 +359,13 @@ pub const Pool = struct {
}
// After the pool mutex is released, for the reason `recordSuccess`
// states.
self.recordHistory(io, entry, .{ .failure = @errorName(err) });
self.recordDiagnostics(io, entry, .{ .failure = @errorName(err) });
}
const Outcome = union(enum) { success, failure: []const u8 };
/// The wall clock, not the `.awake` timestamp the health state runs on:
/// history is aggregated into wall-clock minutes so a dashboard period
/// means the same thing here as everywhere else on the page.
fn recordHistory(self: *Pool, io: std.Io, entry: *Entry, outcome: Outcome) void {
const history = self.history orelse return;
const wall_s = std.Io.Clock.real.now(io).toSeconds();
switch (outcome) {
.success => history.recordSuccess(io, entry.endpoint.url, wall_s),
.failure => |name| history.recordFailure(io, entry.endpoint.url, wall_s, name),
}
}
/// The same placement discipline as `recordHistory`: the store takes a
/// mutex of its own, so this runs after the pool's is released.
/// The store takes a mutex of its own, so this runs after the pool's is
/// released.
///
/// A success is the steady state of the whole program, so `resolve` is
/// built to issue no SQL when nothing is open (`storage/events.zig`).
@@ -408,10 +389,7 @@ pub const Pool = struct {
}
};
const db = @import("../storage/db.zig");
const events_fixture = @import("../storage/events_fixture.zig");
const querylog_schema = @import("../storage/querylog_schema.zig");
const upstream_history_repo = @import("../storage/repositories/upstream_history_repo.zig");
const testing = std.testing;
@@ -921,67 +899,6 @@ test "every entry disabled yields ConnectFailed without waiting out the total bu
try testing.expectEqual(@as(usize, 0), two.calls);
}
test "a wired accumulator receives both outcomes the pool records" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var bad: Fake = .{ .behavior = .{ .fail = error.Timeout } };
var good: Fake = .{ .behavior = .{ .reply = response_bytes } };
var entries = [_]Entry{
testEntry("https://bad.example/dns-query", &bad, 10),
testEntry("https://good.example/dns-query", &good, 20),
};
var pool: Pool = .init(&entries, test_cfg, test_timeouts, 1);
const acc = try testing.allocator.create(history_mod.Accumulator);
defer testing.allocator.destroy(acc);
acc.* = .init;
pool.history = acc;
var buf: [512]u8 = undefined;
// One exchange: the first entry fails over into the second, so this drives
// one failure and one success.
var selected: ?[]const u8 = null;
_ = try pool.exchange(io, query_bytes, &buf, &selected);
// Two cells, one per url, in whatever minute the wall clock is in.
try testing.expectEqual(@as(u32, 2), acc.snapshotStats(io).pending);
// Read back through the flush path rather than through the accumulator's
// private cells: the whole point of the hook is that these outcomes reach
// storage under the right url.
var database = try db.Db.open(":memory:", .{ .mode = .memory });
defer database.close();
try db.applyPragmas(&database, .{});
try database.exec(querylog_schema.ddl);
acc.flushOnce(io, &database, upstream_history_repo.flush);
// A window wide enough that a minute boundary crossed mid-test changes
// nothing about what it contains.
const now = std.Io.Clock.real.now(io).toSeconds();
const failing = try upstream_history_repo.windowStats(
&database,
"https://bad.example/dns-query",
now - 3600,
now + 3600,
);
try testing.expectEqual(@as(u64, 1), failing.failures);
try testing.expectEqual(@as(u64, 0), failing.successes);
try testing.expect(failing.last_failure_ts != null);
try testing.expectEqualStrings("Timeout", failing.lastFailureError());
const succeeding = try upstream_history_repo.windowStats(
&database,
"https://good.example/dns-query",
now - 3600,
now + 3600,
);
try testing.expectEqual(@as(u64, 1), succeeding.successes);
try testing.expectEqual(@as(u64, 0), succeeding.failures);
try testing.expectEqual(@as(?i64, null), succeeding.last_failure_ts);
}
test "snapshot reports the counters in pool order" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
+299 -200
View File
@@ -6,6 +6,13 @@
//!
//! Unauthenticated and rate-limit exempt, like `/metrics`.
//!
//! **Nothing may degrade the rollup without appearing in the response.** The
//! body is five condition objects and a status computed from exactly their
//! states, so an operator reading it can always name the condition that
//! degraded the box. Anything a counter already records — gated refreshes,
//! disk sample failures, the snapshot generation — stays in `/metrics` and in
//! Diagnostics rather than becoming a sixth hidden input here.
//!
//! `rollup` is pure so the whole degraded matrix is testable without a running
//! server; `handle` only gathers the inputs.
@@ -13,16 +20,39 @@ const std = @import("std");
const disk_monitor = @import("../../storage/disk_monitor.zig");
const http_util = @import("../http_util.zig");
const logger_mod = @import("../../storage/logger.zig");
const metrics = @import("../metrics.zig");
const pause_mod = @import("../../server/pause.zig");
const pool_mod = @import("../../upstream/pool.zig");
const server = @import("../server.zig");
pub const Disk = struct {
/// Is filtering in force. `unavailable` is not an operator's doing: it is the
/// state in which the query path has no filter snapshot to evaluate against,
/// which `handler.zig` records as the `snapshot_unavailable` provenance.
pub const Protection = struct {
state: []const u8,
free_bytes: u64,
db_bytes: u64,
log_bytes: u64,
sample_failures: u64,
/// The second filtering resumes at. Null for both an indefinite pause and
/// every non-paused state, which the state field already tells apart.
until: ?i64,
};
pub const Upstreams = struct {
state: []const u8,
available: u32,
/// Enabled upstreams: the pool is built from those alone, so this is what
/// `available` is out of.
total: u32,
};
/// Whether Activity can be trusted. `dropped_total` is cumulative and does not
/// decide the state — a drop that happened an hour ago is not a fault now.
pub const QueryHistory = struct {
state: []const u8,
dropped_total: u64,
/// The newest drop, or null while nothing has been dropped. Stamped by a
/// separate atomic from the count, so a reader can momentarily see a
/// non-zero `dropped_total` beside a null here.
last_drop_s: ?i64,
};
/// The diagnostics store's own state, not a summary of what it holds: `state`
@@ -34,21 +64,18 @@ pub const Diagnostics = struct {
active_errors: u32,
};
pub const Upstreams = struct {
available: u32,
total: u32,
pub const Disk = struct {
state: []const u8,
free_bytes: u64,
};
pub const Body = struct {
status: []const u8,
disk: Disk,
protection: Protection,
upstreams: Upstreams,
query_history: QueryHistory,
diagnostics: Diagnostics,
queries_dropped: u64,
writer_failed: bool,
refreshes_gated: u64,
/// Null before the first filter snapshot is published.
snapshot_generation: ?u64,
disk: Disk,
};
/// What the rollup is computed from. Every field has a defined value even when
@@ -56,41 +83,79 @@ pub const Body = struct {
/// server should report: no disk reading, no upstreams, nothing published.
pub const Input = struct {
disk_state: disk_monitor.State = .ok,
disk: disk_monitor.Gauges = .{ .free_bytes = 0, .db_bytes = 0, .log_bytes = 0 },
disk_sample_failures: u64 = 0,
disk_free_bytes: u64 = 0,
upstreams_available: u32 = 0,
upstreams_total: u32 = 0,
queries_dropped: u64 = 0,
last_drop_s: ?i64 = null,
writer_failed: bool = false,
/// Current state, not a count: the upstream-history flush is failing right
/// now. Cleared by the next flush that succeeds (m26 ruling 7).
///
/// `rows_dropped` deliberately does not appear here. It is cumulative, and
/// a rollup that is computed statelessly cannot ask whether a counter grew
/// — so feeding it in would latch `/api/health` to degraded forever after
/// one overflow. Drops surface through the metric and through the API's
/// per-window `complete` instead.
history_flush_failing: bool = false,
/// The logger's disk-gating episode. `losing` is the only state that
/// degrades: it means the gate is holding writes back *and* has already
/// cost rows in the episode that is open now.
gate_episode: logger_mod.GateEpisode = .open,
/// A filter snapshot exists for the query path to evaluate against. The
/// benign default matches every other field here, and `collect` assigns it
/// explicitly for the same reason `diagnostics_present` is assigned there.
snapshot_available: bool = true,
/// `pause.Pause.until` verbatim: 0 not paused, -1 indefinite, otherwise the
/// second filtering resumes at. Raw rather than a decided boolean so the
/// expiry rule stays `pause.Pause`'s and is exercised by these tests.
pause_until: i64 = 0,
/// The clock the pause is compared against.
now_s: i64 = 0,
/// The diagnostics store exists. The benign default matches every other
/// field here — a half-wired `Input` reports a box with nothing wrong — but
/// `collect` must assign it explicitly, because in a serving process an
/// absent store means `Store.init` failed.
diagnostics_present: bool = true,
/// The last diagnostics write failed. Current state, cleared by the next
/// write that succeeds, like `history_flush_failing`.
/// write that succeeds.
diagnostics_write_failed: bool = false,
diagnostics_active_warnings: u32 = 0,
diagnostics_active_errors: u32 = 0,
refreshes_gated: u64 = 0,
snapshot_generation: ?u64 = null,
};
pub const status_ok = "ok";
pub const status_degraded = "degraded";
pub const protection_active = "active";
pub const protection_paused = "paused";
pub const protection_unavailable = "unavailable";
pub const upstreams_ok = "ok";
pub const upstreams_unavailable = "unavailable";
pub const query_history_recording = "recording";
pub const query_history_losing = "losing";
pub const query_history_failed = "failed";
pub const diagnostics_recording = "recording";
pub const diagnostics_unavailable = "unavailable";
pub const disk_ok = "ok";
pub const disk_low = "low";
pub const disk_critical = "critical";
/// Precedence `unavailable` → `paused` → `active`. With no snapshot the pause
/// flag says nothing an operator can act on: filtering is off either way, and
/// resuming would not turn it back on.
pub fn protection(input: Input) Protection {
if (!input.snapshot_available) return .{ .state = protection_unavailable, .until = null };
const state: pause_mod.Pause = .{ .until = .init(input.pause_until) };
if (!state.isPaused(input.now_s)) return .{ .state = protection_active, .until = null };
return .{
.state = protection_paused,
.until = if (input.pause_until > 0) input.pause_until else null,
};
}
pub fn queryHistoryState(input: Input) []const u8 {
if (input.writer_failed) return query_history_failed;
if (input.gate_episode == .losing) return query_history_losing;
return query_history_recording;
}
/// The operational log is not recording — either the store never opened or its
/// writes are failing. Both mean the same thing to an operator: the record of
/// what went wrong is not being kept.
@@ -98,37 +163,51 @@ pub fn diagnosticsUnavailable(input: Input) bool {
return !input.diagnostics_present or input.diagnostics_write_failed;
}
/// Conditions an operator must act on, and every one of them is a fact about
/// now rather than a count of the past: a disk that is filling stops the query
/// log, a pool with nothing available stops resolution, a failed writer means
/// rows are being lost right now, and a failing history flush means the
/// dashboard's upstream numbers are not being recorded. Each clears itself when
/// the underlying condition does.
/// `warn` reads as a log level rather than as a quantity of disk. The monitor
/// keeps its own name; the wire says what an operator sees on the page.
pub fn diskState(state: disk_monitor.State) []const u8 {
return switch (state) {
.ok => disk_ok,
.warn => disk_low,
.critical => disk_critical,
};
}
/// The degrading set, named rather than gestured at: protection `unavailable`,
/// upstreams `unavailable`, query history `losing` or `failed`, diagnostics
/// `unavailable`, disk `low` or `critical`.
///
/// A pause is deliberately not in it. It is an operator's own choice, and a
/// monitor that pages on it would be paging on a button the operator pressed.
pub fn degraded(input: Input) bool {
return input.disk_state != .ok or input.upstreams_available == 0 or
input.writer_failed or input.history_flush_failing or diagnosticsUnavailable(input);
const history = queryHistoryState(input);
return !input.snapshot_available or
input.upstreams_available == 0 or
!std.mem.eql(u8, history, query_history_recording) or
diagnosticsUnavailable(input) or
input.disk_state != .ok;
}
pub fn rollup(input: Input) Body {
return .{
.status = if (degraded(input)) status_degraded else status_ok,
.disk = .{
.state = @tagName(input.disk_state),
.free_bytes = input.disk.free_bytes,
.db_bytes = input.disk.db_bytes,
.log_bytes = input.disk.log_bytes,
.sample_failures = input.disk_sample_failures,
.protection = protection(input),
.upstreams = .{
.state = if (input.upstreams_available == 0) upstreams_unavailable else upstreams_ok,
.available = input.upstreams_available,
.total = input.upstreams_total,
},
.query_history = .{
.state = queryHistoryState(input),
.dropped_total = input.queries_dropped,
.last_drop_s = input.last_drop_s,
},
.upstreams = .{ .available = input.upstreams_available, .total = input.upstreams_total },
.diagnostics = .{
.state = if (diagnosticsUnavailable(input)) diagnostics_unavailable else diagnostics_recording,
.active_warnings = input.diagnostics_active_warnings,
.active_errors = input.diagnostics_active_errors,
},
.queries_dropped = input.queries_dropped,
.writer_failed = input.writer_failed,
.refreshes_gated = input.refreshes_gated,
.snapshot_generation = input.snapshot_generation,
.disk = .{ .state = diskState(input.disk_state), .free_bytes = input.disk_free_bytes },
};
}
@@ -143,10 +222,11 @@ pub fn handle(
pub fn collect(state: *server.WebState, io: std.Io) Input {
var input: Input = .{};
input.now_s = std.Io.Clock.real.now(io).toSeconds();
if (state.monitor) |monitor| {
input.disk_state = monitor.state();
input.disk = monitor.gauges();
input.disk_sample_failures = monitor.sample_failures.load(.monotonic);
input.disk_free_bytes = monitor.gauges().free_bytes;
}
if (state.pool) |pool| {
@@ -160,9 +240,13 @@ pub fn collect(state: *server.WebState, io: std.Io) Input {
if (state.logger) |logger| {
input.queries_dropped = logger.queries_dropped.load(.monotonic);
input.last_drop_s = logger.lastDropSeconds();
input.writer_failed = logger.writer_failed.load(.monotonic);
input.gate_episode = logger.gateEpisode();
}
if (state.pause) |paused| input.pause_until = paused.until.load(.monotonic);
// Assigned before the `if`, not inside it: the field's benign default is
// `true`, so the natural `if (state.events) |store|` shape would report an
// absent store as recording — the one case that must degrade.
@@ -174,15 +258,13 @@ pub fn collect(state: *server.WebState, io: std.Io) Input {
input.diagnostics_active_errors = counts.errors;
}
if (state.history) |history| {
input.history_flush_failing = history.snapshotStats(io).last_flush_failed;
}
// The generation itself is not in the body — the UI-facing fact is whether
// protection has a snapshot at all, and `/metrics` keeps the number.
input.snapshot_available = false;
if (state.manager) |manager| {
input.refreshes_gated = manager.refreshesGated();
if (manager.acquire(io)) |acquired| {
defer acquired.release(io);
input.snapshot_generation = acquired.snapshot.generation;
input.snapshot_available = true;
}
}
@@ -196,104 +278,175 @@ pub fn collect(state: *server.WebState, io: std.Io) Input {
const db = @import("../../storage/db.zig");
const events_mod = @import("../../storage/events.zig");
const migrations = @import("../../storage/migrations.zig");
const history_mod = @import("../../upstream/history.zig");
const logger_mod = @import("../../storage/logger.zig");
const upstream_history_repo = @import("../../storage/repositories/upstream_history_repo.zig");
const testing = std.testing;
/// A box with nothing wrong with it: one upstream up, disk ok, writer alive.
/// A box with nothing wrong with it: one upstream up, disk ok, writer alive,
/// a snapshot published and filtering unpaused.
const healthy: Input = .{
.disk_state = .ok,
.upstreams_available = 1,
.upstreams_total = 1,
.writer_failed = false,
.snapshot_available = true,
};
test "the degraded matrix covers disk state, availability and the writer" {
const cases = [_]struct { input: Input, degraded: bool }{
.{ .input = healthy, .degraded = false },
.{ .input = withDisk(healthy, .warn), .degraded = true },
.{ .input = withDisk(healthy, .critical), .degraded = true },
.{ .input = withAvailable(healthy, 0), .degraded = true },
.{ .input = withWriterFailed(healthy), .degraded = true },
// A failing upstream-history flush is losing the dashboard's numbers
// right now, and it recovers on its own the moment a flush succeeds.
.{ .input = withHistoryFailing(healthy, true), .degraded = true },
.{ .input = withHistoryFailing(healthy, false), .degraded = false },
// The operational log not recording is itself a fault an operator must
// act on: whatever fails next will leave no record of having failed.
.{ .input = withDiagnostics(healthy, false, false), .degraded = true },
.{ .input = withDiagnostics(healthy, true, true), .degraded = true },
.{ .input = withDiagnostics(healthy, true, false), .degraded = false },
// Two faults at once still report one status.
.{ .input = withWriterFailed(withDisk(healthy, .critical)), .degraded = true },
// Some upstreams down is not degraded while one still answers.
.{ .input = .{ .upstreams_available = 1, .upstreams_total = 3 }, .degraded = false },
};
fn with(input: Input, comptime field: []const u8, value: anytype) Input {
var out = input;
@field(out, field) = value;
return out;
}
for (cases, 0..) |case, i| {
errdefer std.debug.print("case {d}\n", .{i});
try testing.expectEqual(case.degraded, degraded(case.input));
try testing.expectEqualStrings(
if (case.degraded) status_degraded else status_ok,
rollup(case.input).status,
);
test "each degrading condition degrades on its own and says so in the body" {
try testing.expectEqualStrings(status_ok, rollup(healthy).status);
{
const body = rollup(with(healthy, "snapshot_available", false));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(protection_unavailable, body.protection.state);
}
{
const body = rollup(with(healthy, "upstreams_available", @as(u32, 0)));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(upstreams_unavailable, body.upstreams.state);
}
{
const body = rollup(with(healthy, "gate_episode", .losing));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(query_history_losing, body.query_history.state);
}
{
const body = rollup(with(healthy, "writer_failed", true));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(query_history_failed, body.query_history.state);
}
{
const body = rollup(with(healthy, "diagnostics_present", false));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(diagnostics_unavailable, body.diagnostics.state);
}
{
const body = rollup(with(healthy, "diagnostics_write_failed", true));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(diagnostics_unavailable, body.diagnostics.state);
}
for ([_]struct { disk_monitor.State, []const u8 }{
.{ .warn, disk_low },
.{ .critical, disk_critical },
}) |case| {
const body = rollup(with(healthy, "disk_state", case[0]));
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(case[1], body.disk.state);
}
}
fn withDisk(input: Input, state: disk_monitor.State) Input {
var out = input;
out.disk_state = state;
return out;
test "conditions that are not faults leave the status ok" {
// Some upstreams down while one still answers.
const partial = rollup(.{ .upstreams_available = 1, .upstreams_total = 3 });
try testing.expectEqualStrings(status_ok, partial.status);
try testing.expectEqualStrings(upstreams_ok, partial.upstreams.state);
// A gate holding writes that has not cost a row yet.
const holding = rollup(with(healthy, "gate_episode", .gated));
try testing.expectEqualStrings(status_ok, holding.status);
try testing.expectEqualStrings(query_history_recording, holding.query_history.state);
// Drops that already happened. The counter is cumulative and the rollup is
// stateless, so feeding it in would latch the box to degraded forever.
var dropped = with(healthy, "queries_dropped", @as(u64, 9));
dropped.last_drop_s = 1_700_000_000;
const body = rollup(dropped);
try testing.expectEqualStrings(status_ok, body.status);
try testing.expectEqualStrings(query_history_recording, body.query_history.state);
try testing.expectEqual(@as(u64, 9), body.query_history.dropped_total);
try testing.expectEqual(@as(?i64, 1_700_000_000), body.query_history.last_drop_s);
// Open diagnostics episodes are what the box is doing, not a fault of the
// log that recorded them.
var open = healthy;
open.diagnostics_active_warnings = 3;
open.diagnostics_active_errors = 1;
const with_episodes = rollup(open);
try testing.expectEqualStrings(status_ok, with_episodes.status);
try testing.expectEqualStrings(diagnostics_recording, with_episodes.diagnostics.state);
try testing.expectEqual(@as(u32, 3), with_episodes.diagnostics.active_warnings);
try testing.expectEqual(@as(u32, 1), with_episodes.diagnostics.active_errors);
}
fn withAvailable(input: Input, available: u32) Input {
var out = input;
out.upstreams_available = available;
return out;
test "a pause is surfaced, never alarmed, and an expired one is over" {
var indefinite = healthy;
indefinite.pause_until = -1;
indefinite.now_s = 1_000;
const forever = rollup(indefinite);
try testing.expectEqualStrings(status_ok, forever.status);
try testing.expectEqualStrings(protection_paused, forever.protection.state);
try testing.expectEqual(@as(?i64, null), forever.protection.until);
var timed = healthy;
timed.pause_until = 1_060;
timed.now_s = 1_000;
const live = rollup(timed);
try testing.expectEqualStrings(status_ok, live.status);
try testing.expectEqualStrings(protection_paused, live.protection.state);
try testing.expectEqual(@as(?i64, 1_060), live.protection.until);
// The stored second is when filtering is back on, so at it the pause is over.
timed.now_s = 1_060;
const expired = rollup(timed);
try testing.expectEqualStrings(protection_active, expired.protection.state);
try testing.expectEqual(@as(?i64, null), expired.protection.until);
}
fn withWriterFailed(input: Input) Input {
var out = input;
out.writer_failed = true;
return out;
test "protection unavailable wins over a live pause" {
var both = healthy;
both.snapshot_available = false;
both.pause_until = -1;
const body = rollup(both);
try testing.expectEqualStrings(protection_unavailable, body.protection.state);
try testing.expectEqual(@as(?i64, null), body.protection.until);
try testing.expectEqualStrings(status_degraded, body.status);
}
fn withHistoryFailing(input: Input, failing: bool) Input {
var out = input;
out.history_flush_failing = failing;
return out;
test "a failed writer outranks a losing gate" {
var both = healthy;
both.writer_failed = true;
both.gate_episode = .losing;
try testing.expectEqualStrings(query_history_failed, rollup(both).query_history.state);
}
fn withDiagnostics(input: Input, present: bool, write_failed: bool) Input {
var out = input;
out.diagnostics_present = present;
out.diagnostics_write_failed = write_failed;
return out;
test "two faults at once still report one status" {
var both = with(healthy, "disk_state", disk_monitor.State.critical);
both.writer_failed = true;
try testing.expectEqualStrings(status_degraded, rollup(both).status);
}
test "the diagnostics block reports the state and the open counts" {
const recording = rollup(.{
.upstreams_available = 1,
.diagnostics_active_warnings = 3,
.diagnostics_active_errors = 1,
test "the body reports every input verbatim" {
const body = rollup(.{
.disk_state = .warn,
.disk_free_bytes = 100,
.upstreams_available = 2,
.upstreams_total = 4,
.queries_dropped = 9,
.last_drop_s = 1_700_000_000,
.snapshot_available = true,
});
try testing.expectEqualStrings(diagnostics_recording, recording.diagnostics.state);
try testing.expectEqual(@as(u32, 3), recording.diagnostics.active_warnings);
try testing.expectEqual(@as(u32, 1), recording.diagnostics.active_errors);
// Open episodes are what the box is doing, not a fault of the log: they do
// not degrade on their own.
try testing.expectEqualStrings(status_ok, recording.status);
// Failing writes: the counts are whatever was last read, and the state is
// the honest one.
const failing = rollup(.{ .upstreams_available = 1, .diagnostics_write_failed = true });
try testing.expectEqualStrings(diagnostics_unavailable, failing.diagnostics.state);
try testing.expectEqualStrings(status_degraded, failing.status);
try testing.expectEqualStrings(status_degraded, body.status);
try testing.expectEqualStrings(disk_low, body.disk.state);
try testing.expectEqual(@as(u64, 100), body.disk.free_bytes);
try testing.expectEqual(@as(u32, 2), body.upstreams.available);
try testing.expectEqual(@as(u32, 4), body.upstreams.total);
try testing.expectEqualStrings(upstreams_ok, body.upstreams.state);
try testing.expectEqual(@as(u64, 9), body.query_history.dropped_total);
try testing.expectEqual(@as(?i64, 1_700_000_000), body.query_history.last_drop_s);
try testing.expectEqualStrings(protection_active, body.protection.state);
}
const absent = rollup(.{ .upstreams_available = 1, .diagnostics_present = false });
try testing.expectEqualStrings(diagnostics_unavailable, absent.diagnostics.state);
try testing.expectEqualStrings(status_degraded, absent.status);
test "an unstamped drop time serializes as null, not as zero" {
var buffer: [1024]u8 = undefined;
var writer: std.Io.Writer = .fixed(&buffer);
try std.json.Stringify.value(rollup(.{}), .{}, &writer);
try testing.expect(std.mem.containsAtLeast(u8, writer.buffered(), 1, "\"last_drop_s\":null"));
try testing.expect(std.mem.containsAtLeast(u8, writer.buffered(), 1, "\"until\":null"));
}
test "collect reports an absent store as unavailable rather than as recording" {
@@ -307,6 +460,10 @@ test "collect reports an absent store as unavailable rather than as recording" {
const absent = collect(&state, io);
try testing.expect(!absent.diagnostics_present);
try testing.expectEqualStrings(diagnostics_unavailable, rollup(absent).diagnostics.state);
// And a bare state has no snapshot either, which is the honest reading of a
// process that has published nothing.
try testing.expect(!absent.snapshot_available);
try testing.expectEqualStrings(protection_unavailable, rollup(absent).protection.state);
var database = try db.Db.open(":memory:", .{ .mode = .memory });
defer database.close();
@@ -325,76 +482,7 @@ test "collect reports an absent store as unavailable rather than as recording" {
try testing.expectEqualStrings(diagnostics_recording, rollup(present).diagnostics.state);
}
test "a history overflow that already happened does not degrade the rollup" {
// `rows_dropped` is cumulative and the rollup is stateless, so the only
// thing it could do with a drop count is latch on it. The accumulator's
// drops reach an operator through `/metrics` and through the per-window
// `complete` flag, and never through this.
const dropped: Input = .{
.upstreams_available = 1,
.upstreams_total = 1,
.history_flush_failing = false,
};
try testing.expect(!degraded(dropped));
try testing.expectEqualStrings(status_ok, rollup(dropped).status);
}
test "collect reads the accumulator's current flush state" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
const acc = try testing.allocator.create(history_mod.Accumulator);
defer testing.allocator.destroy(acc);
acc.* = .init;
var state: server.WebState = .{ .gpa = testing.allocator, .history = acc };
try testing.expect(!collect(&state, io).history_flush_failing);
var database = try db.Db.open(":memory:", .{ .mode = .memory });
defer database.close();
acc.recordSuccess(io, "https://a.example", 60);
// No schema in this database, so the real write fails and the flag is set
// by the production path rather than by a test poking a field.
acc.flushOnce(io, &database, upstream_history_repo.flush);
try testing.expect(collect(&state, io).history_flush_failing);
try testing.expectEqualStrings("degraded", rollup(collect(&state, io)).status);
}
test "the body reports every input verbatim" {
const body = rollup(.{
.disk_state = .warn,
.disk = .{ .free_bytes = 100, .db_bytes = 20, .log_bytes = 3 },
.disk_sample_failures = 2,
.upstreams_available = 2,
.upstreams_total = 4,
.queries_dropped = 9,
.writer_failed = false,
.refreshes_gated = 1,
.snapshot_generation = 12,
});
try testing.expectEqualStrings("degraded", body.status);
try testing.expectEqualStrings("warn", body.disk.state);
try testing.expectEqual(@as(u64, 100), body.disk.free_bytes);
try testing.expectEqual(@as(u64, 20), body.disk.db_bytes);
try testing.expectEqual(@as(u64, 3), body.disk.log_bytes);
try testing.expectEqual(@as(u64, 2), body.disk.sample_failures);
try testing.expectEqual(@as(u32, 2), body.upstreams.available);
try testing.expectEqual(@as(u32, 4), body.upstreams.total);
try testing.expectEqual(@as(u64, 9), body.queries_dropped);
try testing.expectEqual(@as(u64, 1), body.refreshes_gated);
try testing.expectEqual(@as(?u64, 12), body.snapshot_generation);
}
test "an unpublished snapshot serializes as null, not as zero" {
var buffer: [512]u8 = undefined;
var writer: std.Io.Writer = .fixed(&buffer);
try std.json.Stringify.value(rollup(.{}), .{}, &writer);
try testing.expect(std.mem.containsAtLeast(u8, writer.buffered(), 1, "\"snapshot_generation\":null"));
}
test "collect reads the logger's counters and reports a bare state as degraded" {
test "collect reads the logger's counters and the pause flag" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
@@ -402,14 +490,25 @@ test "collect reads the logger's counters and reports a bare state as degraded"
var queue_buf: [2]logger_mod.Entry = undefined;
var query_logger: logger_mod.Logger = .init(.{}, &queue_buf);
query_logger.queries_dropped.store(4, .monotonic);
query_logger.last_drop_s.store(1_700_000_000, .monotonic);
query_logger.writer_failed.store(true, .monotonic);
var state: server.WebState = .{ .gpa = testing.allocator, .logger = &query_logger };
var paused: pause_mod.Pause = .{};
paused.pauseFor(0, null);
var state: server.WebState = .{
.gpa = testing.allocator,
.logger = &query_logger,
.pause = &paused,
};
const input = collect(&state, io);
try testing.expectEqual(@as(u64, 4), input.queries_dropped);
try testing.expectEqual(@as(?i64, 1_700_000_000), input.last_drop_s);
try testing.expect(input.writer_failed);
try testing.expectEqual(@as(i64, -1), input.pause_until);
try testing.expectEqual(@as(u32, 0), input.upstreams_total);
try testing.expectEqual(@as(?u64, null), input.snapshot_generation);
try testing.expectEqualStrings("degraded", rollup(input).status);
try testing.expectEqualStrings(status_degraded, rollup(input).status);
// No snapshot manager either, so protection outranks the pause here too.
try testing.expectEqualStrings(protection_unavailable, rollup(input).protection.state);
}
+36 -6
View File
@@ -126,8 +126,6 @@ pub fn list(
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
_ = io;
var buffers: Buffers = .{};
const filter = parseFilter(request.query, &buffers) catch |err| {
return http_util.respondError(request, .bad_request, message(err));
@@ -136,7 +134,7 @@ pub fn list(
const database = state.querylog_db orelse
return http_util.respondError(request, .service_unavailable, "query log unavailable");
const result = page(database, request.arena, filter) catch |err| {
const result = readPage(state, io, database, request.arena, filter) catch |err| {
// The one thing this handler logs: a database fault is a property of
// the box, not of the request, and the client is told nothing about it.
log.warn("query log read failed: {s}", .{@errorName(err)});
@@ -156,12 +154,10 @@ pub fn detail(
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
_ = io;
const database = state.querylog_db orelse
return http_util.respondError(request, .service_unavailable, "query log unavailable");
const row = queries_repo.detailById(database, request.arena, request.id.?) catch |err| {
const row = detailRow(state, io, database, request.arena, request.id.?) catch |err| {
log.warn("query log read failed: {s}", .{@errorName(err)});
return http_util.respondError(request, .internal_server_error, "internal error");
};
@@ -172,6 +168,40 @@ pub fn detail(
return http_util.respondJson(request, .ok, provenance_view.fromDetail(found), &.{});
}
/// The rows and the coverage watermark come from one database state, so a
/// prune between them cannot tag pre-prune rows with a post-prune
/// `available_since`.
fn readPage(
state: *server.WebState,
io: std.Io,
database: *db.Db,
arena: Allocator,
filter: queries_repo.QueryFilter,
) db.Error!Page {
var scope = try server.QuerylogRead.open(state, io, database);
errdefer scope.abort();
const result = try page(database, arena, filter);
try scope.commit();
return result;
}
/// One row, read under the shared lock. There is nothing to keep consistent
/// with a second statement here; the lock is what keeps this read out of
/// another response's open transaction.
fn detailRow(
state: *server.WebState,
io: std.Io,
database: *db.Db,
arena: Allocator,
id: i64,
) db.Error!?queries_repo.QueryDetail {
var scope = try server.QuerylogRead.open(state, io, database);
errdefer scope.abort();
const row = try queries_repo.detailById(database, arena, id);
try scope.commit();
return row;
}
// ---------------------------------------------------------------------------
// tests
// ---------------------------------------------------------------------------
+231 -23
View File
@@ -1,8 +1,16 @@
//! `GET /api/stats` and `GET /api/stats/timeseries` (ruling 13).
//! The five period endpoints: `GET /api/stats` and `/api/stats/timeseries`
//! (ruling 13), and `/api/stats/types`, `/api/stats/routes` and
//! `/api/stats/clients` (milestone 30).
//!
//! One period grammar, four widths, and one window shared by both endpoints:
//! the totals cover exactly the span the chart draws, so a dashboard cannot
//! show a sum that disagrees with the bars above it.
//! One period grammar, four widths, and one window shared by all five: a
//! request for the same period gets the same `since`/`until` from every
//! endpoint, so the totals describe exactly the span the charts draw rather
//! than a neighbouring one.
//!
//! That is window coherence, not identical counts. Each endpoint is its own
//! request against its own snapshot, so queries logged between two of them move
//! one panel and not the other. Only a box with nothing writing to it — a test
//! — can expect the breakdowns to sum to the totals exactly.
//!
//! Buckets are aligned to the UTC grid, not to the moment of the request. Every
//! width divides a day, so flooring the current time to a multiple of the width
@@ -10,7 +18,19 @@
//! requests a second apart return the same bucket starts. The last bucket is
//! the one in progress; it fills as the period runs.
//!
//! The aggregates run on the web task's own query-log connection (m7 ruling 21).
//! The aggregates run on the web task's own query-log connection (m7 ruling 21),
//! which every connection task shares. SQLite's serialized mode makes one call
//! safe; it does not make a transaction safe, so `WebState.querylog_lock` covers
//! the whole read and a second BEGIN can never land inside the first. Each
//! response takes one deferred read transaction, so its aggregate and the
//! `coverage` beside it describe one database state: retention cannot prune
//! between them and hand a client pre-prune rows tagged with a post-prune
//! watermark. Deferred, not `db.Tx`'s BEGIN IMMEDIATE, which would stall the
//! logger and retention behind an HTTP response.
//!
//! The lock is released before the response is written: the body is already
//! built in the request arena, and holding a database lock across a socket
//! write would let one slow client serialize every other reader.
const std = @import("std");
@@ -97,7 +117,6 @@ pub const TotalsBody = struct {
until: i64,
queries: u64,
blocked: u64,
cached: u64,
clients: u64,
avg_response_time_us: ?i64,
/// Judged against `since`, which is the window this body reports on — so a
@@ -115,6 +134,135 @@ pub const TimeseriesBody = struct {
coverage: coverage.Coverage,
};
pub const TypesBody = struct {
period: []const u8,
since: i64,
until: i64,
types: []const queries_repo.TypeCount,
coverage: coverage.Coverage,
};
pub const RoutesBody = struct {
period: []const u8,
since: i64,
until: i64,
routes: []const queries_repo.RouteCount,
coverage: coverage.Coverage,
};
pub const ClientsBody = struct {
period: []const u8,
since: i64,
until: i64,
bucket_seconds: u32,
clients: []const queries_repo.ClientSeries,
other: []const u64,
coverage: coverage.Coverage,
};
/// Everything one response reads from the query log, so the caller can end the
/// transaction and drop the lock before it serializes anything.
fn Read(comptime T: type) type {
return struct {
data: T,
coverage: coverage.Coverage,
};
}
const ReadScope = server.QuerylogRead;
fn readTotals(
state: *server.WebState,
io: std.Io,
database: *db.Db,
span: Window,
) db.Error!Read(queries_repo.StatsTotals) {
var scope = try ReadScope.open(state, io, database);
errdefer scope.abort();
const read: Read(queries_repo.StatsTotals) = .{
.data = try queries_repo.statsTotals(database, span.since, span.until),
.coverage = try coverage.read(database, span.since),
};
try scope.commit();
return read;
}
fn readTimeseries(
state: *server.WebState,
io: std.Io,
database: *db.Db,
span: Window,
out: []queries_repo.Bucket,
) db.Error!Read(usize) {
var scope = try ReadScope.open(state, io, database);
errdefer scope.abort();
const read: Read(usize) = .{
.data = try queries_repo.timeseries(database, span.since, span.bucket_seconds, out),
.coverage = try coverage.read(database, span.since),
};
try scope.commit();
return read;
}
fn readTypes(
state: *server.WebState,
io: std.Io,
database: *db.Db,
arena: std.mem.Allocator,
span: Window,
) db.Error!Read([]const queries_repo.TypeCount) {
var scope = try ReadScope.open(state, io, database);
errdefer scope.abort();
const list = try queries_repo.statsTypes(database, arena, span.since, span.until);
const read: Read([]const queries_repo.TypeCount) = .{
.data = list.items,
.coverage = try coverage.read(database, span.since),
};
try scope.commit();
return read;
}
fn readRoutes(
state: *server.WebState,
io: std.Io,
database: *db.Db,
arena: std.mem.Allocator,
span: Window,
) db.Error!Read([]const queries_repo.RouteCount) {
var scope = try ReadScope.open(state, io, database);
errdefer scope.abort();
const list = try queries_repo.statsRoutes(database, arena, span.since, span.until);
const read: Read([]const queries_repo.RouteCount) = .{
.data = list.items,
.coverage = try coverage.read(database, span.since),
};
try scope.commit();
return read;
}
fn readClients(
state: *server.WebState,
io: std.Io,
database: *db.Db,
arena: std.mem.Allocator,
span: Window,
) db.Error!Read(queries_repo.ClientsBreakdown) {
var scope = try ReadScope.open(state, io, database);
errdefer scope.abort();
const read: Read(queries_repo.ClientsBreakdown) = .{
.data = try queries_repo.statsClients(
database,
arena,
span.since,
span.bucket_seconds,
span.bucket_count,
),
.coverage = try coverage.read(database, span.since),
};
try scope.commit();
return read;
}
pub fn totals(
state: *server.WebState,
io: std.Io,
@@ -124,23 +272,19 @@ pub fn totals(
const database = state.querylog_db orelse return unavailable(request);
const span = window(period, std.Io.Clock.real.now(io).toSeconds());
const result = queries_repo.statsTotals(database, span.since, span.until) catch |err| {
const read = readTotals(state, io, database, span) catch |err| {
return internal(request, "stats totals", err);
};
const covered = coverage.read(database, span.since) catch |err| {
return internal(request, "stats coverage", err);
};
return http_util.respondJson(request, .ok, TotalsBody{
.period = period.label(),
.since = span.since,
.until = span.until,
.queries = result.queries,
.blocked = result.blocked,
.cached = result.cached,
.clients = result.distinct_clients,
.avg_response_time_us = result.avg_response_time_us,
.coverage = covered,
.queries = read.data.queries,
.blocked = read.data.blocked,
.clients = read.data.distinct_clients,
.avg_response_time_us = read.data.avg_response_time_us,
.coverage = read.coverage,
}, &.{});
}
@@ -155,20 +299,85 @@ pub fn timeseries(
var buckets: [max_buckets]queries_repo.Bucket = undefined;
const out = buckets[0..span.bucket_count];
const written = queries_repo.timeseries(database, span.since, span.bucket_seconds, out) catch |err| {
const read = readTimeseries(state, io, database, span, out) catch |err| {
return internal(request, "stats timeseries", err);
};
const covered = coverage.read(database, span.since) catch |err| {
return internal(request, "stats coverage", err);
};
return http_util.respondJson(request, .ok, TimeseriesBody{
.period = period.label(),
.since = span.since,
.until = span.until,
.bucket_seconds = span.bucket_seconds,
.buckets = out[0..written],
.coverage = covered,
.buckets = out[0..read.data],
.coverage = read.coverage,
}, &.{});
}
pub fn types(
state: *server.WebState,
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
const period = periodParam(request.query) catch return badPeriod(request);
const database = state.querylog_db orelse return unavailable(request);
const span = window(period, std.Io.Clock.real.now(io).toSeconds());
const read = readTypes(state, io, database, request.arena, span) catch |err| {
return internal(request, "stats types", err);
};
return http_util.respondJson(request, .ok, TypesBody{
.period = period.label(),
.since = span.since,
.until = span.until,
.types = read.data,
.coverage = read.coverage,
}, &.{});
}
pub fn routes(
state: *server.WebState,
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
const period = periodParam(request.query) catch return badPeriod(request);
const database = state.querylog_db orelse return unavailable(request);
const span = window(period, std.Io.Clock.real.now(io).toSeconds());
const read = readRoutes(state, io, database, request.arena, span) catch |err| {
return internal(request, "stats routes", err);
};
return http_util.respondJson(request, .ok, RoutesBody{
.period = period.label(),
.since = span.since,
.until = span.until,
.routes = read.data,
.coverage = read.coverage,
}, &.{});
}
pub fn clients(
state: *server.WebState,
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
const period = periodParam(request.query) catch return badPeriod(request);
const database = state.querylog_db orelse return unavailable(request);
const span = window(period, std.Io.Clock.real.now(io).toSeconds());
const read = readClients(state, io, database, request.arena, span) catch |err| {
return internal(request, "stats clients", err);
};
return http_util.respondJson(request, .ok, ClientsBody{
.period = period.label(),
.since = span.since,
.until = span.until,
.bucket_seconds = span.bucket_seconds,
.clients = read.data.clients,
.other = read.data.other,
.coverage = read.coverage,
}, &.{});
}
@@ -321,7 +530,6 @@ test "the totals and the buckets agree over the same window" {
const result = try queries_repo.statsTotals(&database, span.since, span.until);
try testing.expectEqual(@as(u64, 3), result.queries);
try testing.expectEqual(@as(u64, 1), result.blocked);
try testing.expectEqual(@as(u64, 1), result.cached);
try testing.expectEqual(@as(u64, 1), result.distinct_clients);
try testing.expectEqual(@as(?i64, 1000), result.avg_response_time_us);
-585
View File
@@ -1,585 +0,0 @@
//! `GET /api/upstream/health?period=` — the pool's upstreams over the window
//! the dashboard's period picker selected (milestone-26 ruling 6).
//!
//! Two kinds of fact, kept apart on the wire because they answer different
//! questions. `enabled`/`available` are live routing state, read from the pool
//! under its mutex: what the resolver would do with this upstream right now.
//! Everything under `period` is history, aggregated out of `upstream_minute`
//! over `[since, until)` — the same window `/api/stats` reports, so a page
//! cannot show a rate that disagrees with the chart beside it.
//!
//! Nothing here reads a process-lifetime counter. The lifetime totals, the
//! last-32-exchange window and the consecutive-failure count still live in
//! `health.State` for routing and in `/metrics`; they are not this response's
//! business, because a number that starts at process start cannot be scoped to
//! a period and a dashboard that shows one beside a picker lies about it.
//!
//! The aggregation runs on the web task's own query-log connection (m7 ruling
//! 21) and this file owns no SQL: `upstream_history_repo` does.
const std = @import("std");
const Allocator = std.mem.Allocator;
const db = @import("../../storage/db.zig");
const history_mod = @import("../../upstream/history.zig");
const http_util = @import("../http_util.zig");
const metrics = @import("../metrics.zig");
const pool_mod = @import("../../upstream/pool.zig");
const server = @import("../server.zig");
const stats = @import("stats.zig");
const upstream_history_repo = @import("../../storage/repositories/upstream_history_repo.zig");
const log = std.log.scoped(.web_upstream_health);
/// One upstream's outcomes inside the selected window.
pub const PeriodStats = struct {
attempts: u64,
successes: u64,
failures: u64,
/// Null when `attempts == 0`. No observations is not perfect reliability,
/// and a `100.0%` from an idle upstream is the exact misreading this
/// milestone exists to remove.
success_rate: ?f32,
/// The newest failure inside the window, on the wall clock the minute rows
/// are stamped with. Null when the window holds no failure, even if the
/// upstream failed before it.
last_failure_at: ?i64,
/// The error name belonging to `last_failure_at`; null exactly when it is.
last_failure_error: ?[]const u8,
};
pub const Upstream = struct {
url: []const u8,
/// Live: configuration, not history.
enabled: bool,
/// Live: false while the upstream is backing off.
available: bool,
period: PeriodStats,
};
pub const Body = struct {
period: []const u8,
since: i64,
until: i64,
available: u32,
total: u32,
/// See `isComplete`.
complete: bool,
upstreams: []const Upstream,
};
/// The same text `/api/stats` sends (`stats.zig`'s `badPeriod`). One period
/// grammar serves the whole dashboard, so the two routes must not disagree
/// about what a typo means.
pub const bad_period_message = "period must be one of 1h, 24h, 7d, 30d";
pub fn handle(
state: *server.WebState,
io: std.Io,
request: *http_util.Request,
) http_util.HandlerError!void {
const period = stats.periodParam(request.query) catch
return http_util.respondError(request, .bad_request, bad_period_message);
const pool = state.pool orelse
return http_util.respondError(request, .service_unavailable, "no upstream pool");
const database = state.querylog_db orelse
return http_util.respondError(request, .service_unavailable, "query log unavailable");
const now = std.Io.Clock.real.now(io).toSeconds();
const body = collect(request.arena, io, pool, state.history, database, period, now) catch |err| {
if (err == error.OutOfMemory) return error.OutOfMemory;
// A failed aggregate is a fault in the box, not a property of the
// request (ruling 8, PLAN §19).
log.warn("upstream health window failed: {s}", .{@errorName(err)});
return http_util.respondError(request, .internal_server_error, "internal error");
};
return http_util.respondJson(request, .ok, body, &.{});
}
/// `db.Error` already carries `OutOfMemory`, so the arena's failures and
/// SQLite's share one set.
pub const Error = Allocator.Error || db.Error;
pub fn collect(
arena: Allocator,
io: std.Io,
pool: *pool_mod.Pool,
history: ?*history_mod.Accumulator,
database: *db.Db,
period: stats.Period,
now_unix: i64,
) Error!Body {
const span = stats.window(period, now_unix);
var raw: [metrics.max_upstreams]pool_mod.Snapshot = undefined;
const count = metrics.poolSnapshot(pool, io, &raw);
const out = try arena.alloc(Upstream, count);
var available: u32 = 0;
for (raw[0..count], out) |entry, *slot| {
if (entry.available) available += 1;
// Rows come from the current pool only: an upstream deleted from the
// configuration keeps its history in storage until retention takes it,
// and nothing joins it back into this response.
const window_stats = try upstream_history_repo.windowStats(
database,
entry.url,
span.since,
span.until,
);
slot.* = .{
.url = try arena.dupe(u8, entry.url),
.enabled = entry.enabled,
.available = entry.available,
.period = .{
.attempts = window_stats.attempts,
.successes = window_stats.successes,
.failures = window_stats.failures,
.success_rate = successRate(window_stats),
.last_failure_at = window_stats.last_failure_ts,
// `WindowStats` carries its error name by value, in storage this
// loop is done with as soon as the iteration ends. The copy into
// the arena is what keeps the response from pointing at bytes
// the next upstream's row overwrites.
.last_failure_error = if (window_stats.last_failure_ts == null)
null
else
try arena.dupe(u8, window_stats.lastFailureError()),
},
};
}
return .{
.period = period.label(),
.since = span.since,
.until = span.until,
.available = available,
.total = @intCast(count),
.complete = isComplete(history, io, span.since),
.upstreams = out,
};
}
fn successRate(window_stats: upstream_history_repo.WindowStats) ?f32 {
if (window_stats.attempts == 0) return null;
const successes: f32 = @floatFromInt(window_stats.successes);
const attempts: f32 = @floatFromInt(window_stats.attempts);
return successes / attempts;
}
/// Per-window and stateless (ruling 6): false iff capacity has cost this
/// process a minute that falls inside the window. A window that starts after
/// the newest such minute is complete again, so one historical overflow does
/// not mark every later response.
///
/// It says nothing about the newest outcomes, which may not have flushed yet,
/// and nothing about an unclean shutdown, which is not detectable here — the
/// openapi description spells both out.
fn isComplete(history: ?*history_mod.Accumulator, io: std.Io, since: i64) bool {
const accumulator = history orelse return true;
const dropped = accumulator.snapshotStats(io).last_drop_minute orelse return true;
return dropped < since;
}
// ---------------------------------------------------------------------------
// tests
// ---------------------------------------------------------------------------
const querylog_schema = @import("../../storage/querylog_schema.zig");
const transport = @import("../../upstream/transport.zig");
const testing = std.testing;
/// The client is never called: every test here reads health, not answers.
fn testEntry(url: []const u8, enabled: bool) pool_mod.Entry {
return .{
.endpoint = transport.Endpoint.parse(url) catch unreachable,
.client = .{ .ptr = undefined, .exchangeFn = undefined },
.priority = 1,
.enabled = enabled,
.health = .init,
};
}
fn testPool(entries: []pool_mod.Entry) pool_mod.Pool {
return .init(entries, .{}, .{
.attempt = .{ .raw = .fromMilliseconds(50), .clock = .awake },
.total = .{ .raw = .fromMilliseconds(100), .clock = .awake },
}, 1);
}
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;
}
const url_a = "https://a.test/dns-query";
const url_b = "https://b.test/dns-query";
/// A minute-aligned instant, so a window derived from it lands on round
/// numbers the assertions below can name.
const aligned_now: i64 = 1_699_999_980;
test "the window sums the minutes inside it and nothing outside" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"1h", aligned_now);
try upstream_history_repo.flush(&database, &.{
// One minute before the window.
.{ .url = url_a, .minute_ts = span.since - 60, .successes = 100, .failures = 100, .last_failure_ts = span.since - 30, .last_error = "Outside" },
.{ .url = url_a, .minute_ts = span.since, .successes = 3, .failures = 1, .last_failure_ts = span.since + 10, .last_error = "Timeout" },
.{ .url = url_a, .minute_ts = span.until - 60, .successes = 5, .failures = 0, .last_failure_ts = null, .last_error = "" },
// The window's exclusive end.
.{ .url = url_a, .minute_ts = span.until, .successes = 200, .failures = 200, .last_failure_ts = span.until + 5, .last_error = "After" },
});
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", aligned_now);
try testing.expectEqualStrings("1h", body.period);
try testing.expectEqual(span.since, body.since);
try testing.expectEqual(span.until, body.until);
try testing.expectEqual(@as(u32, 1), body.total);
try testing.expectEqual(@as(u32, 1), body.available);
const period = body.upstreams[0].period;
try testing.expectEqual(@as(u64, 8), period.successes);
try testing.expectEqual(@as(u64, 1), period.failures);
try testing.expectEqual(@as(u64, 9), period.attempts);
try testing.expectEqual(@as(?i64, span.since + 10), period.last_failure_at);
try testing.expectEqualStrings("Timeout", period.last_failure_error.?);
}
test "an upstream with no attempts in the window reports null, never a perfect rate" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"1h", aligned_now);
// Only `b` has history, and only outside the window.
try upstream_history_repo.flush(&database, &.{
.{ .url = url_b, .minute_ts = span.since - 600, .successes = 4, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
var entries = [_]pool_mod.Entry{ testEntry(url_a, true), testEntry(url_b, true) };
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", aligned_now);
for (body.upstreams) |upstream| {
try testing.expectEqual(@as(u64, 0), upstream.period.attempts);
try testing.expectEqual(@as(u64, 0), upstream.period.successes);
try testing.expectEqual(@as(u64, 0), upstream.period.failures);
try testing.expectEqual(@as(?f32, null), upstream.period.success_rate);
try testing.expectEqual(@as(?i64, null), upstream.period.last_failure_at);
try testing.expectEqual(@as(?[]const u8, null), upstream.period.last_failure_error);
}
}
test "the success rate is the window's own, not a lifetime one" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"1h", aligned_now);
try upstream_history_repo.flush(&database, &.{
// A clean past that a lifetime rate would average into the window.
.{ .url = url_a, .minute_ts = span.since - 600, .successes = 1000, .failures = 0, .last_failure_ts = null, .last_error = "" },
.{ .url = url_a, .minute_ts = span.since, .successes = 1, .failures = 3, .last_failure_ts = span.since + 1, .last_error = "Timeout" },
});
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", aligned_now);
try testing.expectEqual(@as(?f32, 0.25), body.upstreams[0].period.success_rate);
}
test "the newest failure inside the window wins over an older one outside it" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"1h", aligned_now);
try upstream_history_repo.flush(&database, &.{
.{ .url = url_a, .minute_ts = span.since - 120, .successes = 0, .failures = 1, .last_failure_ts = span.since - 100, .last_error = "Older" },
.{ .url = url_a, .minute_ts = span.since, .successes = 0, .failures = 1, .last_failure_ts = span.since + 5, .last_error = "Newer" },
// A later minute with no failure at all must not blank the error.
.{ .url = url_a, .minute_ts = span.since + 60, .successes = 2, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", aligned_now);
try testing.expectEqual(@as(?i64, span.since + 5), body.upstreams[0].period.last_failure_at);
try testing.expectEqualStrings("Newer", body.upstreams[0].period.last_failure_error.?);
}
test "two upstreams keep their own last-failure errors" {
// The by-value `WindowStats` buffer is reused per iteration, so a response
// that borrowed it would show the second upstream's error on the first, or
// point at stack storage that is gone by the time it is serialized.
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"1h", aligned_now);
try upstream_history_repo.flush(&database, &.{
.{ .url = url_a, .minute_ts = span.since, .successes = 1, .failures = 1, .last_failure_ts = span.since + 1, .last_error = "ConnectFailed" },
.{ .url = url_b, .minute_ts = span.since, .successes = 0, .failures = 2, .last_failure_ts = span.since + 2, .last_error = "TlsHandshakeFailed" },
});
var entries = [_]pool_mod.Entry{ testEntry(url_a, true), testEntry(url_b, true) };
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", aligned_now);
try testing.expectEqual(@as(usize, 2), body.upstreams.len);
try testing.expectEqualStrings(url_a, body.upstreams[0].url);
try testing.expectEqualStrings("ConnectFailed", body.upstreams[0].period.last_failure_error.?);
try testing.expectEqualStrings(url_b, body.upstreams[1].url);
try testing.expectEqualStrings("TlsHandshakeFailed", body.upstreams[1].period.last_failure_error.?);
// Serializing after every row is read is what a real response does; the
// texts must still be the ones their own rows carried.
var allocating: std.Io.Writer.Allocating = .init(testing.allocator);
defer allocating.deinit();
try std.json.Stringify.value(body, .{}, &allocating.writer);
const text = allocating.written();
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "\"last_failure_error\":\"ConnectFailed\""));
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "\"last_failure_error\":\"TlsHandshakeFailed\""));
}
test "a disabled upstream is not counted available and still gets its window" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
const span = stats.window(.@"24h", aligned_now);
try upstream_history_repo.flush(&database, &.{
.{ .url = url_b, .minute_ts = span.since, .successes = 2, .failures = 0, .last_failure_ts = null, .last_error = "" },
});
var entries = [_]pool_mod.Entry{ testEntry(url_a, true), testEntry(url_b, false) };
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, null, &database, .@"24h", aligned_now);
try testing.expectEqual(@as(u32, 2), body.total);
try testing.expectEqual(@as(u32, 1), body.available);
try testing.expect(!body.upstreams[1].enabled);
try testing.expect(!body.upstreams[1].available);
try testing.expectEqual(@as(u64, 2), body.upstreams[1].period.attempts);
}
/// Fills the accumulator and then overflows it, so `last_drop_minute` is
/// `minute` — the only way to set it, because the accumulator's fields are
/// private to its module and `snapshotStats` is the read surface.
fn accumulatorDroppingAt(
io: std.Io,
minute: i64,
names: *[history_mod.max_pending][8]u8,
) !*history_mod.Accumulator {
const accumulator = try testing.allocator.create(history_mod.Accumulator);
accumulator.* = .init;
for (names, 0..) |*name, i| {
const url = std.fmt.bufPrint(name, "u{d:0>6}", .{i}) catch unreachable;
accumulator.recordSuccess(io, url, minute);
}
// One more cell than capacity: the oldest minute goes, and every cell above
// holds `minute`.
accumulator.recordSuccess(io, "https://overflow.test", minute + 60);
return accumulator;
}
test "complete is false only while a dropped minute falls inside the window" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
// Two `now`s one minute apart, so the same drop is inside the first
// window and one minute before the second.
const inside_now = aligned_now;
const inside = stats.window(.@"1h", inside_now);
const after = stats.window(.@"1h", inside_now + 60);
try testing.expectEqual(inside.since + 60, after.since);
var names: [history_mod.max_pending][8]u8 = undefined;
const accumulator = try accumulatorDroppingAt(io, inside.since, &names);
defer testing.allocator.destroy(accumulator);
try testing.expectEqual(@as(?i64, inside.since), accumulator.snapshotStats(io).last_drop_minute);
const flagged = try collect(arena.allocator(), io, &pool, accumulator, &database, .@"1h", inside_now);
try testing.expect(!flagged.complete);
const recovered = try collect(arena.allocator(), io, &pool, accumulator, &database, .@"1h", inside_now + 60);
try testing.expect(recovered.complete);
// No accumulator at all is no known drop, not an incomplete window.
const unwired = try collect(arena.allocator(), io, &pool, null, &database, .@"1h", inside_now);
try testing.expect(unwired.complete);
}
test "a drop with no overflow leaves every window complete" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
const accumulator = try testing.allocator.create(history_mod.Accumulator);
defer testing.allocator.destroy(accumulator);
accumulator.* = .init;
accumulator.recordFailure(io, url_a, aligned_now, "Timeout");
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
const body = try collect(arena.allocator(), io, &pool, accumulator, &database, .@"1h", aligned_now);
try testing.expect(body.complete);
}
test "the route's period grammar and its 400 text are the ones /api/stats serves" {
// The picker scopes the whole page, so one bad spelling must mean the same
// thing on every route it drives.
try testing.expectEqual(stats.default_period, try stats.periodParam(""));
try testing.expectEqual(stats.Period.@"24h", try stats.periodParam(""));
try testing.expectEqual(stats.Period.@"7d", try stats.periodParam("period=7d"));
try testing.expectError(error.BadPeriod, stats.periodParam("period=12h"));
try testing.expectError(error.BadPeriod, stats.periodParam("period=1hhhhhhhhhh"));
try testing.expectEqualStrings("period must be one of 1h, 24h, 7d, 30d", bad_period_message);
}
test "every period the grammar accepts produces the window that period names" {
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
defer threaded.deinit();
const io = threaded.io();
var database = try openLog();
defer database.close();
var entries = [_]pool_mod.Entry{testEntry(url_a, true)};
var pool = testPool(&entries);
var arena: std.heap.ArenaAllocator = .init(testing.allocator);
defer arena.deinit();
for (std.enums.values(stats.Period)) |period| {
const span = stats.window(period, aligned_now);
const body = try collect(arena.allocator(), io, &pool, null, &database, period, aligned_now);
try testing.expectEqualStrings(period.label(), body.period);
try testing.expectEqual(span.since, body.since);
try testing.expectEqual(span.until, body.until);
}
}
test "the body serializes exactly the ranged field set" {
const upstreams = [_]Upstream{ .{
.url = url_a,
.enabled = true,
.available = false,
.period = .{
.attempts = 8,
.successes = 6,
.failures = 2,
.success_rate = 0.75,
.last_failure_at = 1_700_000_000,
.last_failure_error = "ConnectFailed",
},
}, .{
.url = url_b,
.enabled = false,
.available = false,
.period = .{
.attempts = 0,
.successes = 0,
.failures = 0,
.success_rate = null,
.last_failure_at = null,
.last_failure_error = null,
},
} };
var allocating: std.Io.Writer.Allocating = .init(testing.allocator);
defer allocating.deinit();
try std.json.Stringify.value(Body{
.period = "1h",
.since = 1_699_996_400,
.until = 1_700_000_000,
.available = 0,
.total = 2,
.complete = true,
.upstreams = &upstreams,
}, .{}, &allocating.writer);
try testing.expectEqualStrings(
\\{"period":"1h","since":1699996400,"until":1700000000,"available":0,"total":2,"complete":true,"upstreams":[{"url":"https://a.test/dns-query","enabled":true,"available":false,"period":{"attempts":8,"successes":6,"failures":2,"success_rate":0.75,"last_failure_at":1700000000,"last_failure_error":"ConnectFailed"}},{"url":"https://b.test/dns-query","enabled":false,"available":false,"period":{"attempts":0,"successes":0,"failures":0,"success_rate":null,"last_failure_at":null,"last_failure_error":null}}]}
, allocating.written());
// The lifetime fields m26 removed. They still exist in `health.State` and in
// `/metrics`; a client of this route must not find them here and start
// reading them as if they were scoped to the period.
for ([_][]const u8{
"consecutive_failures",
"total_successes",
"total_failures",
"last_error_age_s",
"\"last_error\"",
}) |gone| {
try testing.expect(!std.mem.containsAtLeast(u8, allocating.written(), 1, gone));
}
}
+1 -62
View File
@@ -31,7 +31,6 @@ const dns_handler = @import("../server/handler.zig");
const disk_monitor = @import("../storage/disk_monitor.zig");
const dot_server = @import("../server/dot_server.zig");
const events_mod = @import("../storage/events.zig");
const history_mod = @import("../upstream/history.zig");
const http_util = @import("http_util.zig");
const logging = @import("../platform/logging.zig");
const pool_mod = @import("../upstream/pool.zig");
@@ -136,9 +135,6 @@ pub const Sample = struct {
tracker: ?TrackerSample = null,
client_names: ?client_names.Resolver.Stats = null,
retention: ?retention_mod.Stats = null,
/// The upstream-history flush loop's counters (m26 ruling 7). Absent while
/// no accumulator is wired, like every other collaborator.
history: ?history_mod.Accumulator.Stats = null,
/// The diagnostics store's open episodes and its failed writes. Absent
/// while no store is wired, like every other collaborator — an operator
/// distinguishes "no series" from "zero episodes" through `/api/health`,
@@ -218,8 +214,6 @@ pub fn collect(state: *server.WebState, io: std.Io, arena: Allocator) Allocator.
if (state.retention) |retention| sample.retention = retention.snapshotStats();
if (state.history) |history| sample.history = history.snapshotStats(io);
if (state.events) |store| {
const counts = store.activeCounts(io);
sample.diagnostics = .{
@@ -382,36 +376,6 @@ pub fn render(w: *std.Io.Writer, sample: Sample) std.Io.Writer.Error!void {
try counterGroup(w, "nxdns_retention_", "Query log retention counter", retention);
}
if (sample.history) |history| {
// Written out rather than reflected over `Accumulator.Stats`: three of
// its fields are counters, one is a gauge, and two — the drop watermark
// and the current flush state — are not exposition numbers at all.
try counter(
w,
"nxdns_upstream_history_flushes_total",
"Upstream history flush transactions that committed.",
history.flushes,
);
try counter(
w,
"nxdns_upstream_history_flush_failures_total",
"Upstream history flush attempts that failed; the rows are retried on the next pass.",
history.flush_failures,
);
try counter(
w,
"nxdns_upstream_history_rows_dropped_total",
"Upstream history minutes dropped because the accumulator was full.",
history.rows_dropped,
);
try gauge(
w,
"nxdns_upstream_history_pending",
"Upstream history minutes recorded but not yet flushed.",
history.pending,
);
}
if (sample.diagnostics) |diagnostics| {
try gauge(
w,
@@ -638,7 +602,7 @@ fn writeUpstreamLabels(
/// through this function too, so the guarantee cannot be one caller away.
/// `UpstreamSample.url` stays whole for the same reason it is safe to: nothing
/// but this function reads it, and the session-authenticated
/// `GET /api/upstream/health` reports the same pool with the same urls whole.
/// `GET /api/upstreams` reports the same urls whole.
///
/// **`redact` output is not safe to interpolate into a label value, and this
/// function is the reason it never has to be.** Do not delete the second layer
@@ -803,31 +767,6 @@ test "a full sample renders the whole exposition, byte for byte" {
));
}
test "the upstream-history family renders three counters and one gauge" {
const text = try renderToString(testing.allocator, .{
.history = .{
.flushes = 12,
.flush_failures = 2,
.rows_dropped = 5,
.pending = 3,
.last_drop_minute = 1_700_000_040,
.last_flush_failed = true,
},
});
defer testing.allocator.free(text);
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "nxdns_upstream_history_flushes_total 12\n"));
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "nxdns_upstream_history_flush_failures_total 2\n"));
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "nxdns_upstream_history_rows_dropped_total 5\n"));
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "# TYPE nxdns_upstream_history_pending gauge\n"));
try testing.expect(std.mem.containsAtLeast(u8, text, 1, "nxdns_upstream_history_pending 3\n"));
// No accumulator is an absent family, not a family of zeros.
const bare = try renderToString(testing.allocator, .{});
defer testing.allocator.free(bare);
try testing.expect(!std.mem.containsAtLeast(u8, bare, 1, "nxdns_upstream_history_"));
}
test "the diagnostics family renders two gauges and one counter" {
const text = try renderToString(testing.allocator, .{
.diagnostics = .{ .active_warnings = 3, .active_errors = 1, .write_failures = 7 },
+289 -131
View File
@@ -65,8 +65,11 @@ paths:
get:
summary: Health rollup
description: |
Always 200; `status` is `degraded` when the disk is not ok, no
upstream is available, or the query-log writer failed. Always
Always 200. `status` is `degraded` when, and only when, one of the five
condition objects is in a degrading state: protection `unavailable`,
upstreams `unavailable`, query history `losing` or `failed`,
diagnostics `unavailable`, or disk `low` or `critical`. A paused
protection is an operator's own choice and does not degrade. Always
unauthenticated and never rate limited.
security: []
responses:
@@ -465,6 +468,99 @@ paths:
"503":
$ref: "#/components/responses/Unavailable"
/api/stats/types:
get:
summary: Query-type breakdown for a period
description: |
How many queries of each DNS type the period's window holds, over the
same UTC-aligned window `/api/stats` reports for. Rows carry the numeric
type only: the type-name table lives in the admin, and a second copy
here would drift out of agreement with it. `qtype` is nullable in the
query log, so the rows that carry no type group into a row of their own
rather than vanishing from a breakdown that claims to add up. Ordered by
count descending, then type ascending with the null row last. Types
absent from the window are absent from the list.
parameters:
- $ref: "#/components/parameters/Period"
responses:
"200":
description: The type breakdown.
content:
application/json:
schema:
$ref: "#/components/schemas/StatsTypes"
"400":
$ref: "#/components/responses/BadRequest"
"401":
$ref: "#/components/responses/Unauthorized"
"429":
$ref: "#/components/responses/RateLimited"
"500":
$ref: "#/components/responses/Internal"
"503":
$ref: "#/components/responses/Unavailable"
/api/stats/routes:
get:
summary: How the period's queries were answered
description: |
A breakdown by answering route over the same window `/api/stats`
reports for. `source` is the answering resolver's identity — the
upstream url on `upstream` rows, the zone on `forward_zone` rows, null
on every other kind and on rows whose identity the log did not record.
It is not the blocklist a block came from. Ordered by count descending,
then route ascending, then source ascending with nulls last.
parameters:
- $ref: "#/components/parameters/Period"
responses:
"200":
description: The route breakdown.
content:
application/json:
schema:
$ref: "#/components/schemas/StatsRoutes"
"400":
$ref: "#/components/responses/BadRequest"
"401":
$ref: "#/components/responses/Unauthorized"
"429":
$ref: "#/components/responses/RateLimited"
"500":
$ref: "#/components/responses/Internal"
"503":
$ref: "#/components/responses/Unavailable"
/api/stats/clients:
get:
summary: Per-client bucketed counts for a period
description: |
One zero-filled series per client, bucketed exactly like
`/api/stats/timeseries` so the two charts share an x-axis. The eight
clients with the most queries in the window are named, ranked by count
descending then address ascending; every other client sums into
`other`, which is always present and always holds one entry per bucket
in the window — including when `clients` is empty, when no client fell
outside the named eight, and when the window holds no queries at all.
parameters:
- $ref: "#/components/parameters/Period"
responses:
"200":
description: The per-client series.
content:
application/json:
schema:
$ref: "#/components/schemas/StatsClients"
"400":
$ref: "#/components/responses/BadRequest"
"401":
$ref: "#/components/responses/Unauthorized"
"429":
$ref: "#/components/responses/RateLimited"
"500":
$ref: "#/components/responses/Internal"
"503":
$ref: "#/components/responses/Unavailable"
/api/lookup:
get:
summary: Explain a domain
@@ -498,35 +594,6 @@ paths:
"503":
$ref: "#/components/responses/Unavailable"
/api/upstream/health:
get:
summary: Upstream pool health for a period
description: |
Each upstream's live routing state beside its recorded outcomes over
the period's window, which is the same UTC-aligned window `/api/stats`
reports for that period. The outcome counts come from per-minute
history in the query log, not from process-lifetime counters, so they
scope to the period and survive a restart.
parameters:
- $ref: "#/components/parameters/Period"
responses:
"200":
description: Per-upstream state and the availability rollup.
content:
application/json:
schema:
$ref: "#/components/schemas/UpstreamHealth"
"400":
$ref: "#/components/responses/BadRequest"
"401":
$ref: "#/components/responses/Unauthorized"
"429":
$ref: "#/components/responses/RateLimited"
"500":
$ref: "#/components/responses/Internal"
"503":
$ref: "#/components/responses/Unavailable"
/api/groups:
get:
summary: List groups
@@ -1822,45 +1889,100 @@ components:
Health:
type: object
required: [status, disk, upstreams, diagnostics, queries_dropped, writer_failed, refreshes_gated, snapshot_generation]
required: [status, protection, upstreams, query_history, diagnostics, disk]
properties:
status:
type: string
enum: [ok, degraded]
diagnostics:
type: object
required: [state, active_warnings, active_errors]
properties:
state:
type: string
enum: [recording, unavailable]
description: unavailable when the event store failed to open or its writes are failing; either state degrades health.
active_warnings: { type: integer }
active_errors: { type: integer }
disk:
type: object
required: [state, free_bytes, db_bytes, log_bytes, sample_failures]
properties:
state:
type: string
enum: [ok, warn, critical]
free_bytes: { type: integer }
db_bytes: { type: integer }
log_bytes: { type: integer }
sample_failures: { type: integer }
protection:
$ref: "#/components/schemas/HealthProtection"
upstreams:
type: object
required: [available, total]
properties:
available: { type: integer }
total: { type: integer }
queries_dropped: { type: integer }
writer_failed: { type: boolean }
refreshes_gated: { type: integer }
snapshot_generation:
$ref: "#/components/schemas/HealthUpstreams"
query_history:
$ref: "#/components/schemas/HealthQueryHistory"
diagnostics:
$ref: "#/components/schemas/HealthDiagnostics"
disk:
$ref: "#/components/schemas/HealthDisk"
HealthProtection:
type: object
required: [state, until]
properties:
state:
type: string
enum: [active, paused, unavailable]
description: >
unavailable when no filter snapshot exists for the query path to
evaluate against, which outranks any pause and is the only one of
the three that degrades health. An expired timed pause is active.
until:
type: integer
nullable: true
description: Null until the first filter snapshot is published.
description: >
The second filtering resumes at. Null for an indefinite pause and
for every state other than paused.
HealthUpstreams:
type: object
required: [state, available, total]
properties:
state:
type: string
enum: [ok, unavailable]
description: unavailable exactly when `available` is 0; that degrades health.
available: { type: integer }
total:
type: integer
description: Enabled upstreams, which is what the routing pool is built from.
HealthQueryHistory:
type: object
required: [state, dropped_total, last_drop_s]
properties:
state:
type: string
enum: [recording, losing, failed]
description: >
failed when the query-log writer never started; losing while the
disk gate is holding writes back and has already cost rows in the
episode open now. Both degrade health. Drops from an earlier
episode do not change the state - they are reported by the two
fields below.
dropped_total:
type: integer
description: Query rows lost since this process started, cumulative.
last_drop_s:
type: integer
nullable: true
description: >
The newest drop, unix seconds; null until one happens. Stamped by a
separate atomic from the count, so a non-zero `dropped_total` beside
a null here is a legal momentary answer.
HealthDiagnostics:
type: object
required: [state, active_warnings, active_errors]
properties:
state:
type: string
enum: [recording, unavailable]
description: unavailable when the event store failed to open or its writes are failing; either state degrades health.
active_warnings: { type: integer }
active_errors: { type: integer }
HealthDisk:
type: object
required: [state, free_bytes]
properties:
state:
type: string
enum: [ok, low, critical]
description: >
The disk monitor's own states; its `warn` is renamed `low` here,
because `warn` reads as a log level rather than as a quantity of
disk. Both `low` and `critical` degrade health.
free_bytes: { type: integer }
Version:
type: object
@@ -2119,6 +2241,9 @@ components:
- query_log.write
- query_log.maintenance
- query_log.recreated
# Legacy: nothing emits this any more (milestone 30 deleted the
# upstream-minute history subsystem), but stored rows survive and
# the list endpoint passes their code through.
- upstream_history.write
- upstream.exchange
- client_names.storage
@@ -2187,7 +2312,7 @@ components:
StatsTotals:
type: object
required: [period, since, until, queries, blocked, cached, clients, avg_response_time_us, coverage]
required: [period, since, until, queries, blocked, clients, avg_response_time_us, coverage]
properties:
period:
type: string
@@ -2200,7 +2325,6 @@ components:
description: Window end, unix seconds, exclusive.
queries: { type: integer }
blocked: { type: integer }
cached: { type: integer }
clients:
type: integer
description: Distinct client addresses in the window.
@@ -2239,6 +2363,106 @@ components:
coverage:
$ref: "#/components/schemas/Coverage"
TypeCount:
type: object
required: [qtype, count]
properties:
qtype:
type: integer
nullable: true
description: |
The numeric DNS type. Null is the group of logged queries that
recorded no type, not an absent row.
count: { type: integer }
StatsTypes:
type: object
required: [period, since, until, types, coverage]
properties:
period:
type: string
enum: [1h, 24h, 7d, 30d]
since: { type: integer }
until: { type: integer }
types:
type: array
items:
$ref: "#/components/schemas/TypeCount"
coverage:
$ref: "#/components/schemas/Coverage"
RouteCount:
type: object
required: [route, source, count]
properties:
route:
$ref: "#/components/schemas/RouteKind"
source:
type: string
nullable: true
description: |
The answering upstream's url or the forward zone, and null on every
other route kind. Also null when an `upstream` or `forward_zone`
row recorded no identity.
count: { type: integer }
StatsRoutes:
type: object
required: [period, since, until, routes, coverage]
properties:
period:
type: string
enum: [1h, 24h, 7d, 30d]
since: { type: integer }
until: { type: integer }
routes:
type: array
items:
$ref: "#/components/schemas/RouteCount"
coverage:
$ref: "#/components/schemas/Coverage"
ClientSeries:
type: object
required: [client, buckets]
properties:
client:
type: string
description: The client address as the log recorded it, redaction included.
buckets:
type: array
description: |
One count per bucket in the window, zero-filled. Every series in a
response has this same length, `other` included.
items:
type: integer
StatsClients:
type: object
required: [period, since, until, bucket_seconds, clients, other, coverage]
properties:
period:
type: string
enum: [1h, 24h, 7d, 30d]
since: { type: integer }
until: { type: integer }
bucket_seconds: { type: integer }
clients:
type: array
items:
$ref: "#/components/schemas/ClientSeries"
other:
type: array
description: |
Every client outside the named eight, summed per bucket. Always
present, and always one entry per bucket in the window — including
when `clients` is empty, when no client fell outside the named
eight, and when the window holds no queries at all.
items:
type: integer
coverage:
$ref: "#/components/schemas/Coverage"
Lookup:
type: object
required: [domain, group_id, local_records, forward_zone, blocked, reason, matched, source_url, safe_search_rewrite]
@@ -2267,72 +2491,6 @@ components:
type: string
nullable: true
UpstreamPeriodStats:
type: object
required: [attempts, successes, failures, success_rate, last_failure_at, last_failure_error]
properties:
attempts:
type: integer
description: Exchanges recorded against this upstream inside the window.
successes: { type: integer }
failures: { type: integer }
success_rate:
type: number
nullable: true
description: >
`successes / attempts`, from 0 to 1. Null when `attempts` is 0: no
observations is not perfect reliability.
last_failure_at:
type: integer
nullable: true
description: >
The newest failure inside the window, unix seconds. Null when the
window holds no failure, even if the upstream failed before it.
last_failure_error:
type: string
nullable: true
description: The error name belonging to `last_failure_at`; null exactly when it is.
UpstreamHealth:
type: object
required: [period, since, until, available, total, complete, upstreams]
properties:
period:
type: string
enum: [1h, 24h, 7d, 30d]
since:
type: integer
description: Window start, unix seconds, inclusive.
until:
type: integer
description: Window end, unix seconds, exclusive.
available:
type: integer
description: How many upstreams the pool would route to right now.
total: { type: integer }
complete:
type: boolean
description: >
No capacity drops known in this process within the selected window;
up to about a minute of the newest outcomes may not have flushed
yet, and outcomes lost in an unclean shutdown are not detectable.
upstreams:
type: array
description: The upstreams configured now; a deleted upstream's history is not returned.
items:
type: object
required: [url, enabled, available, period]
properties:
url: { type: string }
enabled:
type: boolean
description: Live configuration, not history.
available:
type: boolean
description: Live state, not history; false while the upstream is backing off.
period:
$ref: "#/components/schemas/UpstreamPeriodStats"
Group:
type: object
required: [id, name, safe_search]
+4 -3
View File
@@ -49,7 +49,6 @@ const queries = @import("handlers/queries.zig");
const rules = @import("handlers/rules.zig");
const settings = @import("handlers/settings.zig");
const stats = @import("handlers/stats.zig");
const upstream_health = @import("handlers/upstream_health.zig");
const upstreams = @import("handlers/upstreams.zig");
const version = @import("handlers/version.zig");
@@ -73,8 +72,10 @@ pub const table: []const router.RouteInfo = &.{
.{ .method = .GET, .pattern = "/api/queries/{id}", .auth = .session, .policy = .read, .handler = queries.detail },
.{ .method = .GET, .pattern = "/api/stats", .auth = .session, .policy = .read, .handler = stats.totals },
.{ .method = .GET, .pattern = "/api/stats/timeseries", .auth = .session, .policy = .read, .handler = stats.timeseries },
.{ .method = .GET, .pattern = "/api/stats/types", .auth = .session, .policy = .read, .handler = stats.types },
.{ .method = .GET, .pattern = "/api/stats/routes", .auth = .session, .policy = .read, .handler = stats.routes },
.{ .method = .GET, .pattern = "/api/stats/clients", .auth = .session, .policy = .read, .handler = stats.clients },
.{ .method = .GET, .pattern = "/api/lookup", .auth = .session, .policy = .read, .handler = lookup.handle },
.{ .method = .GET, .pattern = "/api/upstream/health", .auth = .session, .policy = .read, .handler = upstream_health.handle },
// Diagnostics: the operational event log (milestone 27). The two purges are
// `runtime_action` — the event log is runtime state no configuration file
@@ -156,7 +157,7 @@ const std = @import("std");
const testing = std.testing;
test "the table carries every endpoint of the milestone" {
try testing.expectEqual(@as(usize, 61), table.len);
try testing.expectEqual(@as(usize, 63), table.len);
}
test "no two entries claim the same method and pattern" {
+77 -5
View File
@@ -40,7 +40,6 @@ const logger_mod = @import("../storage/logger.zig");
const manager_mod = @import("../filter/manager.zig");
const model = @import("../config/model.zig");
const pause_mod = @import("../server/pause.zig");
const history_mod = @import("../upstream/history.zig");
const pool_mod = @import("../upstream/pool.zig");
const query_sink = @import("../server/query_sink.zig");
const retention_mod = @import("../storage/retention.zig");
@@ -137,10 +136,6 @@ pub const WebState = struct {
client_names: ?*client_names.Resolver = null,
manager: ?*manager_mod.Manager = null,
pool: ?*pool_mod.Pool = null,
/// The upstream-outcome accumulator, for `metrics.collect` and the
/// `/api/health` rollup (m26 ruling 7). The ranged endpoint reads the
/// flushed rows through `querylog_db`, not through this.
history: ?*history_mod.Accumulator = null,
monitor: ?*disk_monitor.Monitor = null,
/// The local records and forward zones the DNS path reads. The
/// local-records and forward-zones handlers rebuild and swap them
@@ -184,6 +179,13 @@ pub const WebState = struct {
/// concurrent writes would misread each other's row counts.
config_lock: std.Io.Mutex = .init,
querylog_db: ?*db.Db = null,
/// Serializes the web layer's work on `querylog_db`, for the same reason
/// `config_lock` exists and one more: the read handlers wrap their several
/// statements in a transaction, and SQLite's serialized mode protects a
/// single call, not a transaction. Without this, two concurrent BEGINs on
/// the shared connection would fail and a third task's reads would land
/// inside someone else's snapshot.
querylog_lock: std.Io.Mutex = .init,
/// The diagnostics event store, which owns a third connection of its own
/// and serializes every access — read and write — through its mutex. Null
/// when `Store.init` failed, which `/api/health` reports as `unavailable`
@@ -219,6 +221,76 @@ pub const WebState = struct {
reload_fn: ?ReloadFn = null,
};
/// One response's hold on the query log: `querylog_lock` plus one deferred read
/// transaction, opened and closed together so no reader can hold one without
/// the other.
///
/// Every web-layer read of `querylog_db` goes through this. The transaction is
/// what makes an aggregate and the coverage watermark beside it describe one
/// database state, and the lock is what makes the transaction meaningful on a
/// connection several tasks share.
///
/// `commit` is fallible and must be called before the response is written: a
/// connection still inside a transaction refuses the next `BEGIN`, so a handler
/// that answered 200 over a failed commit would leave every later query-log
/// request failing for a reason nothing on the wire ever named.
///
/// **The lock is always released, even when the transaction could not be
/// ended.** `lockUncancelable` cannot be interrupted, so holding it against a
/// connection that will not leave its transaction would park every later
/// query-log task forever, with no status and no way out but a kill. Releasing
/// it turns the same fault into a 500 per request: bounded, visible, and
/// recoverable by a restart.
/// **The lock is released exactly once, on every path.** The usage shape below
/// runs `abort` after a failed `commit` — an `errdefer` cannot know the error
/// came from the commit itself — so `release` is the single owner of the
/// unlock and `held` is what makes the second call a no-op. Unlocking an
/// already-unlocked `std.Io.Mutex` is `unreachable`, and under contention it
/// would hand away a hold another task had just taken, so the bounded 500 this
/// type promises would instead be a crash or a corrupted mutex.
///
/// ```zig
/// var scope = try QuerylogRead.open(state, io, database);
/// errdefer scope.abort();
/// ... // reads only
/// try scope.commit();
/// ```
pub const QuerylogRead = struct {
state: *WebState,
io: std.Io,
tx: db.ReadTx,
held: bool,
pub fn open(state: *WebState, io: std.Io, database: *db.Db) db.Error!QuerylogRead {
state.querylog_lock.lockUncancelable(io);
errdefer state.querylog_lock.unlock(io);
return .{
.state = state,
.io = io,
.tx = try db.ReadTx.begin(database),
.held = true,
};
}
pub fn commit(self: *QuerylogRead) db.Error!void {
defer self.release();
return self.tx.commit();
}
/// Safe in `errdefer`, and safe after `commit` however that ended: both the
/// rollback and the release are idempotent.
pub fn abort(self: *QuerylogRead) void {
self.tx.rollback();
self.release();
}
fn release(self: *QuerylogRead) void {
if (!self.held) return;
self.held = false;
self.state.querylog_lock.unlock(self.io);
}
};
/// Ruling 17. Authentication is enabled iff a password hash is set — the live
/// one, so a password set through the API locks the routes without a restart.
/// With it set but no session store wired, every session route is refused: the
+438 -11
View File
@@ -32,6 +32,7 @@ const clients_repo = @import("../storage/repositories/clients_repo.zig");
const db = @import("../storage/db.zig");
const dns_handler = @import("../server/handler.zig");
const events_mod = @import("../storage/events.zig");
const events_repo = @import("../storage/repositories/events_repo.zig");
const fetcher = @import("../filter/fetcher.zig");
const groups_repo = @import("../storage/repositories/groups_repo.zig");
const header = @import("../dns/header.zig");
@@ -72,7 +73,6 @@ const handlers_pause = @import("handlers/pause.zig");
const handlers_queries = @import("handlers/queries.zig");
const handlers_settings = @import("handlers/settings.zig");
const handlers_stats = @import("handlers/stats.zig");
const handlers_upstream_health = @import("handlers/upstream_health.zig");
const handlers_version = @import("handlers/version.zig");
const testing = std.testing;
@@ -282,6 +282,13 @@ const EnvOptions = struct {
/// `logging.query_log = false` operator runs. Every query-log route then
/// answers 503 rather than an empty page, which would be a lie.
querylog: bool = true,
/// Seeds a handful of rows inside the *live* period window, on top of the
/// fixed 2023 seed. The stats windows are cut from the real clock, so an
/// aggregation over a fixed seed is always an empty window — and an empty
/// array witnesses no field at all. Only the tests that need populated
/// aggregations ask for it: the rows are newer than every fixed row, so
/// they would otherwise move the query-log page out from under its golden.
recent_traffic: bool = false,
};
/// Heap-allocated because `state` and the listener hold pointers into it.
@@ -334,13 +341,14 @@ const Env = struct {
errdefer self.querylog_db.close();
try self.querylog_db.exec(querylog_schema.ddl);
try seedQueryLog(&self.querylog_db);
if (options.recent_traffic) try seedRecentTraffic(&self.querylog_db, std.Io.Clock.real.now(ioh).toSeconds());
self.events_db = try db.Db.open(":memory:", .{ .mode = .memory });
errdefer self.events_db.close();
try db.applyPragmas(&self.events_db, .{});
_ = try migrations.migrate(&self.events_db);
self.events_store = try events_mod.Store.init(ioh, &self.events_db, seeded_now);
seedEvents(ioh, &self.events_store);
try seedEvents(ioh, &self.events_store, &self.events_db);
// Real fetcher wiring; nothing in this suite downloads (the one
// refreshAll in the contract walk runs with zero source rows).
@@ -381,7 +389,8 @@ const Env = struct {
self.pool_entries = .{.{
.endpoint = transport.Endpoint.parse("https://dns.example/dns-query") catch unreachable,
// Never exchanged with: the pool feeds /api/upstream/health only.
// Never exchanged with: the pool feeds `/metrics` and the
// `/api/health` upstream condition only.
.client = .{ .ptr = undefined, .exchangeFn = undefined },
.priority = 1,
.enabled = true,
@@ -588,6 +597,66 @@ fn seedQueryLog(database: *db.Db) !void {
}});
}
/// The matrix the three period aggregations are read against: three clients,
/// three query types including a row with none, five route kinds, two named
/// upstreams and one upstream row whose resolver the log did not record.
///
/// `now` is the real clock, so these rows land in the live window of every
/// period. Only their timestamps come from it; the counts are fixed, and the
/// contract samples canonicalize every number to zero anyway.
const recent_clients = 3;
fn seedRecentTraffic(database: *db.Db, now: i64) !void {
var writer = try queries_repo.BatchWriter.init(database);
defer writer.deinit();
const Shape = struct {
client: []const u8,
qtype: ?u16,
kind: provenance.RouteKind,
source: ?[]const u8,
};
const shapes = [_]Shape{
.{ .client = "192.0.2.30", .qtype = 1, .kind = .upstream, .source = "https://dns.example/dns-query" },
.{ .client = "192.0.2.30", .qtype = 1, .kind = .upstream, .source = "https://dns.example/dns-query" },
.{ .client = "192.0.2.30", .qtype = 28, .kind = .upstream, .source = "https://dns2.example/dns-query" },
.{ .client = "192.0.2.30", .qtype = 1, .kind = .upstream, .source = null },
.{ .client = "192.0.2.31", .qtype = 28, .kind = .blocked, .source = null },
.{ .client = "192.0.2.31", .qtype = 1, .kind = .cache, .source = null },
.{ .client = "192.0.2.31", .qtype = null, .kind = .local, .source = null },
.{ .client = "192.0.2.32", .qtype = 1, .kind = .forward_zone, .source = "lan" },
.{ .client = "192.0.2.32", .qtype = 1, .kind = .rejected, .source = null },
};
for (shapes, 0..) |shape, index| {
// Inside the narrowest bucket of the narrowest period, so every period
// sees the whole matrix however close to a boundary the clock is.
try writer.writeBatch(&.{.{
.timestamp = now - @as(i64, @intCast(index)) - 1,
.domain = "recent.example",
.client_ip = shape.client,
.qtype = shape.qtype,
.qclass = 1,
.rcode = 0,
.blocked = shape.kind == .blocked,
.response_time_us = 1500,
.cache_hit = shape.kind == .cache,
.upstream = if (shape.kind == .upstream) shape.source else null,
.group_id = 1,
.group_name = "default",
.policy_action = if (shape.kind == .blocked) .block else .allow,
.policy_reason = if (shape.kind == .blocked) .blocklist_domain else .no_match,
.matched = null,
.source_id = null,
.source_name = null,
.cname_target = null,
.safe_search_target = null,
.route_kind = shape.kind,
.forward_zone = if (shape.kind == .forward_zone) shape.source else null,
}});
}
}
/// A fixed instant, like every other seeded timestamp here: the contract
/// samples are byte-compared, so nothing the walk writes may come from a clock.
const seeded_now: i64 = 1_787_118_000;
@@ -595,12 +664,17 @@ const seeded_now: i64 = 1_787_118_000;
/// One active episode and one resolved one, so `/api/diagnostics` answers with
/// both states and the committed contract sample describes a real page rather
/// than an empty one.
fn seedEvents(io: std.Io, store: *events_mod.Store) void {
fn seedEvents(io: std.Io, store: *events_mod.Store, database: *db.Db) !void {
store.report(io, seeded_now, .blocklist_refresh, "https://lists.example/ads.txt", "StevenBlack", .warning, "download failed: ConnectionTimedOut");
store.report(io, seeded_now + 300, .blocklist_refresh, "https://lists.example/ads.txt", "StevenBlack", .warning, "download failed: ConnectionTimedOut");
store.report(io, seeded_now + 60, .upstream_history_write, "history", "history", .warning, "Busy");
store.resolve(io, seeded_now + 120, .upstream_history_write, "history");
// A legacy code no producer emits any more. Rows written by an m29 process
// survive, and the read path has to keep passing their code through — this
// is the resolved episode that proves it. Written through the repository
// because the emitter enum no longer has the code at all.
const legacy = events_mod.legacy_wire_codes[0];
_ = try events_repo.insertActive(database, seeded_now + 60, legacy, "history", "history", "warning", "Busy");
_ = try events_repo.resolveActiveByCode(database, seeded_now + 120, legacy);
}
// ---------------------------------------------------------------------------
@@ -750,7 +824,9 @@ const contract = [_]Contract{
.{ .method = .GET, .pattern = "/api/queries/live", .auth = .session, .policy = .read, .rate_limit = .exempt, .target = "/api/queries/live", .status = 200, .kind = .sse },
.{ .method = .GET, .pattern = "/api/stats", .auth = .session, .policy = .read, .target = "/api/stats?period=1h", .status = 200, .check = jsonShape(handlers_stats.TotalsBody) },
.{ .method = .GET, .pattern = "/api/stats/timeseries", .auth = .session, .policy = .read, .target = "/api/stats/timeseries?period=1h", .status = 200, .check = jsonShape(handlers_stats.TimeseriesBody) },
.{ .method = .GET, .pattern = "/api/upstream/health", .auth = .session, .policy = .read, .target = "/api/upstream/health", .status = 200, .check = jsonShape(handlers_upstream_health.Body) },
.{ .method = .GET, .pattern = "/api/stats/types", .auth = .session, .policy = .read, .target = "/api/stats/types?period=1h", .status = 200, .check = jsonShape(handlers_stats.TypesBody) },
.{ .method = .GET, .pattern = "/api/stats/routes", .auth = .session, .policy = .read, .target = "/api/stats/routes?period=1h", .status = 200, .check = jsonShape(handlers_stats.RoutesBody) },
.{ .method = .GET, .pattern = "/api/stats/clients", .auth = .session, .policy = .read, .target = "/api/stats/clients?period=1h", .status = 200, .check = jsonShape(handlers_stats.ClientsBody) },
// Diagnostics. The seeded store holds one active episode (id 1) and one
// resolved one, so both the page and the detail answer with real rows.
@@ -1977,7 +2053,16 @@ fn detailUnavailable(io: std.Io, env: *Env) anyerror!void {
defer conn.close(io);
var body_buf: [8 * 1024]u8 = undefined;
for ([_][]const u8{ "/api/queries/1", "/api/queries?limit=1", "/api/stats", "/api/stats/timeseries" }) |target| {
const targets = [_][]const u8{
"/api/queries/1",
"/api/queries?limit=1",
"/api/stats",
"/api/stats/timeseries",
"/api/stats/types",
"/api/stats/routes",
"/api/stats/clients",
};
for (targets) |target| {
try conn.request("GET", target, null, null);
const response = try conn.receive(&body_buf);
try testing.expectEqual(@as(u16, 503), response.status);
@@ -2064,6 +2149,260 @@ fn coverageWalk(io: std.Io, env: *Env) anyerror!void {
try testing.expectEqual(totals.coverage.complete, series.coverage.complete);
}
fn getJson(
comptime T: type,
arena: Allocator,
conn: *Conn,
target: []const u8,
body_buf: []u8,
) !T {
try conn.request("GET", target, null, null);
const response = try conn.receive(body_buf);
if (response.status != 200) {
std.debug.print("{s}: status {d}: {s}\n", .{ target, response.status, response.body });
return error.TestUnexpectedResult;
}
return std.json.parseFromSliceLeaky(T, arena, response.body, .{ .ignore_unknown_fields = false });
}
fn emptyAggregations(io: std.Io, env: *Env) anyerror!void {
var arena_state: std.heap.ArenaAllocator = .init(env.gpa);
defer arena_state.deinit();
const arena = arena_state.allocator();
var conn: Conn = undefined;
try conn.connect(io, env.addr);
defer conn.close(io);
var body_buf: [256 * 1024]u8 = undefined;
// This environment's only rows are the fixed 2023 seed, so every live
// window is empty. The empty bodies are exact, not merely parseable.
const types_body = try getJson(handlers_stats.TypesBody, arena, &conn, "/api/stats/types?period=1h", &body_buf);
try testing.expectEqualStrings("1h", types_body.period);
try testing.expectEqual(@as(usize, 0), types_body.types.len);
const routes_body = try getJson(handlers_stats.RoutesBody, arena, &conn, "/api/stats/routes?period=1h", &body_buf);
try testing.expectEqual(@as(usize, 0), routes_body.routes.len);
// `other` is present and bucket-count sized even here: a chart must never
// have to invent the residual series.
const clients = try getJson(handlers_stats.ClientsBody, arena, &conn, "/api/stats/clients?period=1h", &body_buf);
try testing.expectEqual(@as(usize, 0), clients.clients.len);
try testing.expectEqual(@as(u32, 60), clients.bucket_seconds);
try testing.expectEqual(@as(usize, 60), clients.other.len);
for (clients.other) |count| try testing.expectEqual(@as(u64, 0), count);
// A window nobody covers is still reported as such, not as a quiet hour.
try testing.expectEqual(seeded_available_since, types_body.coverage.available_since);
try testing.expect(types_body.coverage.complete);
for ([_][]const u8{ "/api/stats/types", "/api/stats/routes", "/api/stats/clients" }) |path| {
var target_buf: [64]u8 = undefined;
const target = try std.fmt.bufPrint(&target_buf, "{s}?period=12h", .{path});
try conn.request("GET", target, null, null);
const bad = try conn.receive(&body_buf);
try testing.expectEqual(@as(u16, 400), bad.status);
try testing.expect(std.mem.containsAtLeast(u8, bad.body, 1, "period must be one of"));
}
}
test "W10 milestone 30: an empty window answers exact empty aggregations, and a bad period is a 400" {
if (!build_options.integration) return error.SkipZigTest;
const gpa = testing.allocator;
var env = try Env.create(gpa, .{});
defer env.destroy();
try bounded(env.io(), default_budget, emptyAggregations, .{ env.io(), env });
}
fn populatedAggregations(io: std.Io, env: *Env) anyerror!void {
var arena_state: std.heap.ArenaAllocator = .init(env.gpa);
defer arena_state.deinit();
const arena = arena_state.allocator();
var conn: Conn = undefined;
try conn.connect(io, env.addr);
defer conn.close(io);
var body_buf: [256 * 1024]u8 = undefined;
const totals = try getJson(handlers_stats.TotalsBody, arena, &conn, "/api/stats?period=1h", &body_buf);
const series = try getJson(handlers_stats.TimeseriesBody, arena, &conn, "/api/stats/timeseries?period=1h", &body_buf);
const types_body = try getJson(handlers_stats.TypesBody, arena, &conn, "/api/stats/types?period=1h", &body_buf);
const routes_body = try getJson(handlers_stats.RoutesBody, arena, &conn, "/api/stats/routes?period=1h", &body_buf);
const clients = try getJson(handlers_stats.ClientsBody, arena, &conn, "/api/stats/clients?period=1h", &body_buf);
// Nothing writes to this box between the five requests, so the window is
// one state and conservation is a real assertion rather than a race.
try testing.expectEqual(totals.since, series.since);
try testing.expectEqual(totals.since, types_body.since);
try testing.expectEqual(totals.since, routes_body.since);
try testing.expectEqual(totals.since, clients.since);
try testing.expect(totals.queries > 0);
var typed: u64 = 0;
var null_qtype_rows: usize = 0;
for (types_body.types) |row| {
typed += row.count;
if (row.qtype == null) null_qtype_rows += 1;
}
try testing.expectEqual(totals.queries, typed);
// The seeded matrix holds one typeless row, and it must be its own group.
try testing.expectEqual(@as(usize, 1), null_qtype_rows);
var routed: u64 = 0;
var null_source_upstreams: usize = 0;
var named_upstreams: usize = 0;
for (routes_body.routes) |row| {
routed += row.count;
if (row.route != .upstream) continue;
if (row.source == null) null_source_upstreams += 1 else named_upstreams += 1;
}
try testing.expectEqual(totals.queries, routed);
try testing.expectEqual(@as(usize, 1), null_source_upstreams);
try testing.expectEqual(@as(usize, 2), named_upstreams);
try testing.expectEqual(@as(usize, recent_clients), clients.clients.len);
try testing.expectEqual(series.buckets.len, clients.other.len);
for (clients.clients) |entry| try testing.expectEqual(series.buckets.len, entry.buckets.len);
// Per bucket, not just over the window: a series off by one bucket would
// still sum correctly in total.
for (series.buckets, 0..) |bucket, at| {
var summed: u64 = clients.other[at];
for (clients.clients) |entry| summed += entry.buckets[at];
try testing.expectEqual(bucket.queries, summed);
}
}
test "W10 milestone 30: the three breakdowns conserve the totals over one window" {
if (!build_options.integration) return error.SkipZigTest;
const gpa = testing.allocator;
var env = try Env.create(gpa, .{ .recent_traffic = true });
defer env.destroy();
try bounded(env.io(), default_budget, populatedAggregations, .{ env.io(), env });
}
/// One connection walking every query-log endpoint several times over.
fn hammerQuerylog(io: std.Io, env: *Env) anyerror!void {
var conn: Conn = undefined;
try conn.connect(io, env.addr);
defer conn.close(io);
var body_buf: [256 * 1024]u8 = undefined;
const targets = [_][]const u8{
"/api/stats?period=1h",
"/api/stats/timeseries?period=1h",
"/api/stats/types?period=1h",
"/api/stats/routes?period=1h",
"/api/stats/clients?period=1h",
"/api/queries?limit=5",
"/api/queries/27",
};
for (0..3) |_| {
for (targets) |target| {
try conn.request("GET", target, null, null);
const response = try conn.receive(&body_buf);
if (response.status != 200) {
std.debug.print("{s}: status {d}: {s}\n", .{ target, response.status, response.body });
return error.TestUnexpectedResult;
}
}
}
}
fn concurrentQuerylogReads(io: std.Io, env: *Env) anyerror!void {
// Six tasks on six connections against the one shared query-log
// connection. Without `querylog_lock` this is exactly the shape that makes
// a second BEGIN fail and a foreign read land inside someone else's
// transaction; every response here must still be a 200.
var futures: [6]std.Io.Future(anyerror!void) = undefined;
for (&futures) |*future| future.* = try io.concurrent(hammerQuerylog, .{ io, env });
var failure: ?anyerror = null;
for (&futures) |*future| future.await(io) catch |err| {
failure = err;
};
if (failure) |err| return err;
}
fn failedCommitIsBounded(io: std.Io, env: *Env) anyerror!void {
var conn: Conn = undefined;
try conn.connect(io, env.addr);
defer conn.close(io);
var body_buf: [256 * 1024]u8 = undefined;
// A read that cannot end its transaction. The three things that must hold
// are all observable from here: the client is told (500, not a 200 over a
// state nobody can name), the process survives (the lock is released
// exactly once — releasing twice is `unreachable` in `std.Io.Mutex`), and
// the connection recovers (the rollback attempt worked, so the next
// `BEGIN` is not refused).
db.read_tx_faults.failNextCommit();
try conn.request("GET", "/api/stats/types?period=1h", null, null);
const failed = try conn.receive(&body_buf);
try testing.expectEqual(@as(u16, 500), failed.status);
try testing.expect(std.mem.containsAtLeast(u8, failed.body, 1, "internal error"));
// Same connection, same shared query-log handle: a request after the fault
// is an ordinary 200. This is the assertion the double-unlock bug failed —
// it panicked here instead of answering.
try conn.request("GET", "/api/stats/types?period=1h", null, null);
const recovered = try conn.receive(&body_buf);
try testing.expectEqual(@as(u16, 200), recovered.status);
// And every other query-log route still works on that connection.
for ([_][]const u8{
"/api/stats?period=1h",
"/api/stats/timeseries?period=1h",
"/api/stats/routes?period=1h",
"/api/stats/clients?period=1h",
"/api/queries?limit=5",
"/api/queries/27",
}) |target| {
try conn.request("GET", target, null, null);
const response = try conn.receive(&body_buf);
if (response.status != 200) {
std.debug.print("{s} after the fault: status {d}\n", .{ target, response.status });
return error.TestUnexpectedResult;
}
}
}
test "W10 milestone 30: a read that cannot commit answers 500 and leaves the connection usable" {
if (!build_options.integration) return error.SkipZigTest;
const gpa = testing.allocator;
var env = try Env.create(gpa, .{ .recent_traffic = true });
defer env.destroy();
// The teardown fault is reported at `err`, which the test runner counts as
// a failure; this test causes it deliberately and asserts the count.
db.read_tx_faults.beginCapture();
defer _ = db.read_tx_faults.endCapture();
try bounded(env.io(), default_budget, failedCommitIsBounded, .{ env.io(), env });
// Exactly the one COMMIT fault: the ROLLBACK behind it succeeded, and no
// later request tripped a fault of its own.
try testing.expectEqual(@as(usize, 1), db.read_tx_faults.endCapture());
}
test "W10 milestone 30: concurrent query-log reads all answer 200 on the shared connection" {
if (!build_options.integration) return error.SkipZigTest;
const gpa = testing.allocator;
var env = try Env.create(gpa, .{ .recent_traffic = true });
defer env.destroy();
try bounded(env.io(), default_budget, concurrentQuerylogReads, .{ env.io(), env });
}
test "W10 milestone 28: every window-bounded endpoint reports its own coverage" {
if (!build_options.integration) return error.SkipZigTest;
@@ -2876,12 +3215,33 @@ fn documentedType(comptime T: type) ?[]const u8 {
.bool => "boolean",
// A closed enum is a string on the wire, documented as its own schema.
.@"enum" => null,
.pointer => "string",
// `[]const u8` is a string; every other slice is a JSON array, whose
// element type `elementType` below holds the `items:` block to.
.pointer => |ptr| if (ptr.child == u8) "string" else "array",
.@"struct" => null,
else => @compileError("no documented type for " ++ @typeName(Payload)),
};
}
/// The element type of a field that serializes as a JSON array, or null when
/// the field is not one. `[]const u8` is a string, not an array of integers.
fn elementType(comptime T: type) ?type {
const Payload = switch (@typeInfo(T)) {
.optional => |o| o.child,
else => T,
};
return switch (@typeInfo(Payload)) {
.pointer => |ptr| if (ptr.child == u8) null else ptr.child,
else => null,
};
}
/// The `items:` sub-block of an array property.
fn yamlItems(property: []const u8) ?[]const u8 {
const at = std.mem.indexOf(u8, property, "items:") orelse return null;
return property[at..];
}
fn isOptional(comptime T: type) bool {
return @typeInfo(T) == .optional;
}
@@ -2933,6 +3293,30 @@ fn expectSchemaMatches(gpa: Allocator, comptime T: type, schema_name: []const u8
std.debug.print("{s}.{s}: not documented as {s}\n", .{ schema_name, field.name, wanted });
return error.TestUnexpectedResult;
}
// An array is only as documented as its elements are: without this
// an array of one object would match an array of another.
if (comptime elementType(field.type)) |Element| {
const items = yamlItems(property) orelse {
std.debug.print("{s}.{s}: array with no items\n", .{ schema_name, field.name });
return error.TestUnexpectedResult;
};
switch (@typeInfo(Element)) {
.int => if (!std.mem.containsAtLeast(u8, items, 1, "type: integer")) {
std.debug.print("{s}.{s}: items not documented as integer\n", .{ schema_name, field.name });
return error.TestUnexpectedResult;
},
else => {
const target = refTarget(items) orelse {
std.debug.print("{s}.{s}: items are not a $ref\n", .{ schema_name, field.name });
return error.TestUnexpectedResult;
};
switch (@typeInfo(Element)) {
.@"enum" => try expectEnumMatches(gpa, Element, target),
else => try expectSchemaMatches(gpa, Element, target),
}
},
}
}
} else {
const target = refTarget(property) orelse {
std.debug.print("{s}.{s}: not a $ref\n", .{ schema_name, field.name });
@@ -2981,6 +3365,25 @@ fn expectEnumMatches(gpa: Allocator, comptime T: type, schema_name: []const u8)
}
}
test "drift guard c: the health rollup matches the five objects it documents" {
const gpa = testing.allocator;
// Recurses through the five `$ref`s, so a condition object that gains,
// loses or retypes a field fails here — which is the whole contract: no
// condition may degrade the rollup without appearing in the response.
try expectSchemaMatches(gpa, handlers_health.Body, "Health");
}
test "drift guard c: the stats schemas match the structs that serialize them" {
// Guard b counts operations and guard a matches paths, so neither noticed
// that `cached` outlived the field it documented. This one would have.
const gpa = testing.allocator;
try expectSchemaMatches(gpa, handlers_stats.TotalsBody, "StatsTotals");
try expectSchemaMatches(gpa, handlers_stats.TimeseriesBody, "StatsTimeseries");
try expectSchemaMatches(gpa, handlers_stats.TypesBody, "StatsTypes");
try expectSchemaMatches(gpa, handlers_stats.RoutesBody, "StatsRoutes");
try expectSchemaMatches(gpa, handlers_stats.ClientsBody, "StatsClients");
}
test "drift guard c: the query-log schemas match the structs that serialize them" {
const gpa = testing.allocator;
try expectSchemaMatches(gpa, queries_repo.QueryRow, "QueryRow");
@@ -3134,7 +3537,6 @@ const contract_sample_walk = [_]ContractSample{
.{ .name = "list_upstreams", .ts_type = "{ upstreams: Upstream[] }", .method = "GET", .target = "/api/upstreams", .status = 200 },
.{ .name = "create_upstream", .ts_type = "UpstreamEcho", .method = "POST", .target = "/api/upstreams", .body = "{\"url\":\"https://dns2.example/dns-query\"}", .status = 201 },
.{ .name = "update_upstream", .ts_type = "UpstreamEcho", .method = "PUT", .target = "/api/upstreams/1", .body = "{\"url\":\"https://dns.example/dns-query\",\"priority\":5}", .status = 200 },
.{ .name = "get_upstream_health", .ts_type = "UpstreamHealth", .method = "GET", .target = "/api/upstream/health", .status = 200 },
// Query log and stats. `limit=5` reaches seeded row 21, the blocked one, so
// the page carries both the null-bearing and the populated row shape.
@@ -3163,6 +3565,15 @@ const contract_sample_walk = [_]ContractSample{
.{ .name = "error_not_found", .ts_type = "ErrorEnvelope", .method = "GET", .target = "/api/nope", .status = 404 },
};
/// The three period aggregations, captured against an environment with live
/// traffic in it: over the fixed 2023 seed every one of them would answer with
/// an empty array, which describes no field at all.
const stats_sample_walk = [_]ContractSample{
.{ .name = "get_stats_types", .ts_type = "StatsTypes", .method = "GET", .target = "/api/stats/types?period=1h", .status = 200 },
.{ .name = "get_stats_routes", .ts_type = "StatsRoutes", .method = "GET", .target = "/api/stats/routes?period=1h", .status = 200 },
.{ .name = "get_stats_clients", .ts_type = "StatsClients", .method = "GET", .target = "/api/stats/clients?period=1h", .status = 200 },
};
/// A session-authenticated environment answers this without a cookie.
const unauthorized_sample: ContractSample = .{
.name = "error_unauthorized",
@@ -3314,7 +3725,9 @@ const regen_command =
/// exactly the import list the generated file needs.
fn writeSampleImports(arena: Allocator, w: *std.Io.Writer) !void {
var names: std.ArrayList([]const u8) = .empty;
for (contract_sample_walk ++ [_]ContractSample{ unauthorized_sample, rate_limited_sample }) |sample| {
for (contract_sample_walk ++ stats_sample_walk ++
[_]ContractSample{ unauthorized_sample, rate_limited_sample }) |sample|
{
var index: usize = 0;
while (index < sample.ts_type.len) {
if (!std.ascii.isUpper(sample.ts_type[index])) {
@@ -3397,6 +3810,15 @@ fn sampleWalk(io: std.Io, env: *Env, out: *std.Io.Writer) anyerror!void {
for (contract_sample_walk) |sample| try captureSample(env.gpa, &conn, out, sample, &body_buf);
}
fn statsSampleWalk(io: std.Io, env: *Env, out: *std.Io.Writer) anyerror!void {
var conn: Conn = undefined;
try conn.connect(io, env.addr);
defer conn.close(io);
var body_buf: [128 * 1024]u8 = undefined;
for (stats_sample_walk) |sample| try captureSample(env.gpa, &conn, out, sample, &body_buf);
}
fn sampleUnauthorized(io: std.Io, env: *Env, out: *std.Io.Writer) anyerror!void {
var conn: Conn = undefined;
try conn.connect(io, env.addr);
@@ -3437,6 +3859,11 @@ test "W10 milestone 17: the committed contract samples still describe live respo
defer env.destroy();
try bounded(env.io(), default_budget, sampleWalk, .{ env.io(), env, &rendered.writer });
}
{
var env = try Env.create(gpa, .{ .recent_traffic = true });
defer env.destroy();
try bounded(env.io(), default_budget, statsSampleWalk, .{ env.io(), env, &rendered.writer });
}
{
var hash_buf: [256]u8 = undefined;
const hash = try hashTestPassword(gpa, &hash_buf);