milestone 28: query provenance — every logged query is exactly explainable
Gates / frontend (push) Successful in 1m36s
Gates / test (push) Successful in 1m56s
Gates / test-aarch64 (push) Successful in 7m37s
Gates / package (push) Successful in 9m12s
Gates / container (push) Successful in 13s
CI / gates (push) Successful in 19m4s
Gates / frontend (push) Successful in 1m36s
Gates / test (push) Successful in 1m56s
Gates / test-aarch64 (push) Successful in 7m37s
Gates / package (push) Successful in 9m12s
Gates / container (push) Successful in 13s
CI / gates (push) Successful in 19m4s
query rows gain qclass, rcode, group, policy action and reason, the matched rule or list entry with its source, cname and safe-search targets, route kind, forward zone, and the resolver that actually answered — the pool and local markers die. servfails are logged and name the resolver that lost; post-parse protocol refusals become rows. a detail page at /queries/:id renders the ordered explanation, and coverage watermarks distinguish an empty history from a missing one. the schema fingerprint changes: existing query history is recreated with the old file kept aside and the reset filed as a resolved diagnostic. fixes an oversized udp reply being rebuilt as noerror, which handed clients a truncated nxdomain as success.
This commit is contained in:
+245
-23
@@ -61,7 +61,9 @@ const migrations = @import("storage/migrations.zig");
|
||||
const model = @import("config/model.zig");
|
||||
const pause = @import("server/pause.zig");
|
||||
const pool_mod = @import("upstream/pool.zig");
|
||||
const queries_repo = @import("storage/repositories/queries_repo.zig");
|
||||
const query_sink = @import("server/query_sink.zig");
|
||||
const querylog_schema = @import("storage/querylog_schema.zig");
|
||||
const rate_limiter = @import("server/rate_limiter.zig");
|
||||
const reconcile = @import("config/reconcile.zig");
|
||||
const retention_mod = @import("storage/retention.zig");
|
||||
@@ -631,29 +633,7 @@ fn serve(r: cli.Runner, args: cli.RunArgs) !u8 {
|
||||
var querylog_writer_db = querylog_opened.database;
|
||||
defer querylog_writer_db.close();
|
||||
|
||||
// One-shot and already over: the file was recreated during this boot, and
|
||||
// there is nothing to recover from. Never emitted for `.missing` — a first
|
||||
// creation renames nothing aside, so the event would carry an aside path
|
||||
// that does not exist and would greet every fresh install with a warning.
|
||||
if (querylog_opened.recreated) |cause| {
|
||||
if (cause != .missing) {
|
||||
if (event_store) |store| {
|
||||
var detail_buf: [events.Store.max_detail_len]u8 = undefined;
|
||||
const detail = std.fmt.bufPrint(&detail_buf, "previous file kept as '{s}'", .{
|
||||
querylog_opened.aside(),
|
||||
}) catch detail_buf[0..];
|
||||
store.reportResolved(
|
||||
io,
|
||||
boot_now_s,
|
||||
.query_log_recreated,
|
||||
@tagName(cause),
|
||||
@tagName(cause),
|
||||
.warning,
|
||||
detail,
|
||||
);
|
||||
}
|
||||
}
|
||||
}
|
||||
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);
|
||||
@@ -1357,9 +1337,251 @@ fn parseBind(
|
||||
return addr;
|
||||
}
|
||||
|
||||
/// Files the one-shot `query_log.recreated` event for a boot that replaced the
|
||||
/// query log.
|
||||
///
|
||||
/// One-shot and already over: the file was recreated during this boot, and
|
||||
/// there is nothing to recover from. Never emitted for `.missing` — a first
|
||||
/// creation renames nothing aside, so the event would carry an aside path that
|
||||
/// does not exist and would greet every fresh install with a warning.
|
||||
///
|
||||
/// `database` is the connection to the file that was just created; the coverage
|
||||
/// start is read from it rather than recomputed, so the event states the value
|
||||
/// the API will.
|
||||
fn reportQuerylogRecreated(
|
||||
store: ?*events.Store,
|
||||
io: std.Io,
|
||||
now_s: i64,
|
||||
opened: *const querylog_schema.OpenResult,
|
||||
database: *db.Db,
|
||||
) void {
|
||||
const cause = opened.recreated orelse return;
|
||||
if (cause == .missing) return;
|
||||
const s = store orelse return;
|
||||
|
||||
// The coverage start belongs in this detail: the recreate is exactly the
|
||||
// moment the history the operator had stops existing, and the watermark is
|
||||
// the answer to "from when can I still ask?".
|
||||
const coverage_start: ?i64 = queries_repo.availableSince(database) catch null;
|
||||
var detail_buf: [events.Store.max_detail_len]u8 = undefined;
|
||||
const detail = recreatedDetail(&detail_buf, opened.aside(), coverage_start);
|
||||
s.reportResolved(io, now_s, .query_log_recreated, @tagName(cause), @tagName(cause), .warning, detail);
|
||||
}
|
||||
|
||||
/// The `query_log.recreated` detail line: what was kept, and from when the new
|
||||
/// file can answer.
|
||||
///
|
||||
/// The coverage start is the operator's actual remedy information — the event
|
||||
/// says "this history is gone" and this says "and here is where the new history
|
||||
/// begins". Null only when the fresh file would not answer, which is already a
|
||||
/// separate failure; the line still names the aside rather than saying nothing.
|
||||
///
|
||||
/// The aside is a full path under the data directory, which can be longer than
|
||||
/// the whole detail column, so the two facts compete for the buffer. The
|
||||
/// watermark always wins and the name degrades in whole steps: full path, then
|
||||
/// basename — which the event's own database directory disambiguates — then no
|
||||
/// name at all. Never a path cut mid-string, which names no file on disk and
|
||||
/// reads as if it did.
|
||||
fn recreatedDetail(
|
||||
buf: *[events.Store.max_detail_len]u8,
|
||||
aside: []const u8,
|
||||
coverage_start: ?i64,
|
||||
) []const u8 {
|
||||
const names = [_][]const u8{ aside, std.fs.path.basename(aside) };
|
||||
const since = coverage_start orelse {
|
||||
for (names) |name| {
|
||||
return std.fmt.bufPrint(buf, "previous file kept as '{s}'", .{name}) catch continue;
|
||||
}
|
||||
return "previous file kept aside";
|
||||
};
|
||||
for (names) |name| {
|
||||
return std.fmt.bufPrint(
|
||||
buf,
|
||||
"previous file kept as '{s}'; query history is available from {d}",
|
||||
.{ name, since },
|
||||
) catch continue;
|
||||
}
|
||||
// The buffer is `max_detail_len`, which no i64 can overrun on its own.
|
||||
return std.fmt.bufPrint(buf, "query history is available from {d}", .{since}) catch unreachable;
|
||||
}
|
||||
|
||||
const events_fixture = @import("storage/events_fixture.zig");
|
||||
const testing = std.testing;
|
||||
|
||||
test "the recreated detail names the aside and the new coverage start" {
|
||||
var buf: [events.Store.max_detail_len]u8 = undefined;
|
||||
|
||||
try std.testing.expectEqualStrings(
|
||||
"previous file kept as 'querylog.db.schema-changed-1700000000'; " ++
|
||||
"query history is available from 1700000001",
|
||||
recreatedDetail(&buf, "querylog.db.schema-changed-1700000000", 1700000001),
|
||||
);
|
||||
|
||||
// A fresh file that will not answer is a separate failure; the line still
|
||||
// says what was kept rather than reporting nothing.
|
||||
try std.testing.expectEqualStrings(
|
||||
"previous file kept as 'querylog.db.corrupt-1700000000'",
|
||||
recreatedDetail(&buf, "querylog.db.corrupt-1700000000", null),
|
||||
);
|
||||
|
||||
// A data directory deep enough that its path alone would fill the column:
|
||||
// the watermark is complete and the name degrades to the basename, which
|
||||
// still names a real file.
|
||||
const deep = "/srv/" ++ ("d" ** 60 ++ "/") ** 8 ++ "querylog.db.corrupt-1700000000";
|
||||
try std.testing.expectEqualStrings(
|
||||
"previous file kept as 'querylog.db.corrupt-1700000000'; " ++
|
||||
"query history is available from 1700000001",
|
||||
recreatedDetail(&buf, deep, 1700000001),
|
||||
);
|
||||
try std.testing.expectEqualStrings(
|
||||
"previous file kept as 'querylog.db.corrupt-1700000000'",
|
||||
recreatedDetail(&buf, deep, null),
|
||||
);
|
||||
|
||||
// No filesystem produces a name this long, but a truncated one would name
|
||||
// nothing: the watermark survives alone rather than half-named.
|
||||
const unnameable = "/srv/" ++ "n" ** 500;
|
||||
try std.testing.expectEqualStrings(
|
||||
"query history is available from 1700000001",
|
||||
recreatedDetail(&buf, unnameable, 1700000001),
|
||||
);
|
||||
try std.testing.expectEqualStrings(
|
||||
"previous file kept aside",
|
||||
recreatedDetail(&buf, unnameable, null),
|
||||
);
|
||||
}
|
||||
|
||||
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();
|
||||
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();
|
||||
|
||||
// A fresh install: the file was missing, nothing was set aside, and the
|
||||
// event would name a path that does not exist.
|
||||
var created = try querylog_schema.open(io, std.Io.Dir.cwd(), path);
|
||||
reportQuerylogRecreated(&fx.store, io, 1000, &created, &created.database);
|
||||
created.database.close();
|
||||
try testing.expectEqual(@as(i64, 0), try fx.count("SELECT count(*) FROM operational_events"));
|
||||
|
||||
// A healthy file this build's DDL no longer matches, which is what an
|
||||
// upgrade that edits the schema produces.
|
||||
{
|
||||
var stamped = try db.Db.open(path, .{ .mode = .read_write_existing });
|
||||
defer stamped.close();
|
||||
var sql_buf: [64]u8 = undefined;
|
||||
try stamped.exec(try std.fmt.bufPrintZ(
|
||||
&sql_buf,
|
||||
"PRAGMA user_version = {d};",
|
||||
.{querylog_schema.fingerprint +% 1},
|
||||
));
|
||||
}
|
||||
|
||||
var recreated = try querylog_schema.open(io, std.Io.Dir.cwd(), path);
|
||||
defer recreated.database.close();
|
||||
try testing.expectEqual(querylog_schema.RecreateReason.fingerprint_mismatch, recreated.recreated.?);
|
||||
|
||||
reportQuerylogRecreated(&fx.store, io, 2000, &recreated, &recreated.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"));
|
||||
try testing.expectEqualStrings("warning", try fx.text("SELECT severity FROM operational_events"));
|
||||
// One-shot: already over when it is filed, so it never becomes an open
|
||||
// episode `/api/health` counts.
|
||||
try testing.expectEqual(
|
||||
@as(i64, 0),
|
||||
try fx.count("SELECT count(*) FROM operational_events WHERE resolved_at IS NULL"),
|
||||
);
|
||||
|
||||
// The detail carries the path that is actually on disk and the watermark
|
||||
// the API will serve, both read back from the recreate rather than from
|
||||
// the arguments the event was built with.
|
||||
try tmp.dir.access(io, std.fs.path.basename(recreated.aside()), .{});
|
||||
const coverage = try queries_repo.availableSince(&recreated.database);
|
||||
var expected_buf: [events.Store.max_detail_len]u8 = undefined;
|
||||
const expected = try std.fmt.bufPrint(
|
||||
&expected_buf,
|
||||
"previous file kept as '{s}'; query history is available from {d}",
|
||||
.{ recreated.aside(), coverage },
|
||||
);
|
||||
try testing.expectEqualStrings(expected, try fx.text("SELECT detail FROM operational_events"));
|
||||
|
||||
// A boot with no diagnostics store configured is not a failure path.
|
||||
reportQuerylogRecreated(null, io, 2000, &recreated, &recreated.database);
|
||||
try testing.expectEqual(@as(i64, 1), try fx.count("SELECT count(*) FROM operational_events"));
|
||||
}
|
||||
|
||||
test "a recreate under a long data directory keeps the watermark and a usable name" {
|
||||
var threaded: std.Io.Threaded = .init(testing.allocator, .{});
|
||||
defer threaded.deinit();
|
||||
const io = threaded.io();
|
||||
|
||||
var tmp = testing.tmpDir(.{ .iterate = true });
|
||||
defer tmp.cleanup();
|
||||
|
||||
// Deep enough that the aside outgrows the detail column, shallow enough
|
||||
// that SQLite's unix VFS still opens the file: it caps a path at 512 bytes.
|
||||
const nested = ("d" ** 60 ++ "/") ** 6 ++ "d" ** 60;
|
||||
try tmp.dir.createDirPath(io, nested);
|
||||
|
||||
var path_buf: [1024]u8 = undefined;
|
||||
const path = try std.fmt.bufPrintZ(
|
||||
&path_buf,
|
||||
".zig-cache/tmp/{s}/{s}/querylog.db",
|
||||
.{ tmp.sub_path, nested },
|
||||
);
|
||||
|
||||
var fx: events_fixture.Fixture = .{};
|
||||
try fx.init(io, 1000);
|
||||
defer fx.deinit();
|
||||
|
||||
{
|
||||
var created = try querylog_schema.open(io, std.Io.Dir.cwd(), path);
|
||||
defer created.database.close();
|
||||
var sql_buf: [64]u8 = undefined;
|
||||
try created.database.exec(try std.fmt.bufPrintZ(
|
||||
&sql_buf,
|
||||
"PRAGMA user_version = {d};",
|
||||
.{querylog_schema.fingerprint +% 1},
|
||||
));
|
||||
}
|
||||
|
||||
var recreated = try querylog_schema.open(io, std.Io.Dir.cwd(), path);
|
||||
defer recreated.database.close();
|
||||
try testing.expectEqual(querylog_schema.RecreateReason.fingerprint_mismatch, recreated.recreated.?);
|
||||
const line_overhead = "previous file kept as ''; query history is available from ".len;
|
||||
try testing.expect(recreated.aside().len + line_overhead > events.Store.max_detail_len);
|
||||
|
||||
reportQuerylogRecreated(&fx.store, io, 2000, &recreated, &recreated.database);
|
||||
|
||||
const detail = try fx.text("SELECT detail FROM operational_events");
|
||||
const coverage = try queries_repo.availableSince(&recreated.database);
|
||||
const name = std.fs.path.basename(recreated.aside());
|
||||
var expected_buf: [events.Store.max_detail_len]u8 = undefined;
|
||||
const expected = try std.fmt.bufPrint(
|
||||
&expected_buf,
|
||||
"previous file kept as '{s}'; query history is available from {d}",
|
||||
.{ name, coverage },
|
||||
);
|
||||
// The watermark is whole — the fact that would be lost to a mid-string cut
|
||||
// — and the name it kept is the file's, not a prefix of its path.
|
||||
try testing.expectEqualStrings(expected, detail);
|
||||
try testing.expect(detail.len <= events.Store.max_detail_len);
|
||||
|
||||
var deep = try tmp.dir.openDir(io, nested, .{});
|
||||
defer deep.close(io);
|
||||
try deep.access(io, name, .{});
|
||||
}
|
||||
|
||||
test "parseBind refuses a bind address of the wrong family" {
|
||||
var out_buf: [8]u8 = undefined;
|
||||
var err_buf: [256]u8 = undefined;
|
||||
|
||||
Reference in New Issue
Block a user