filter: a failed blocklist download names its phase, cause, status, bytes and elapsed time

src/filter/manager.zig

@@ -69,8 +69,13 @@ const log = std.log.scoped(.blocklist_manager);
 const Sha256 = std.crypto.hash.sha2.Sha256;
 
 /// `SourceStatus.last_error` is fixed-size so the failure path allocates
-/// nothing.
-pub const max_error_len: usize = 128;
+/// nothing. Sized so the longest `downloadFailureText` fits whole: the widest
+/// cause name the unwraps can produce is `DetectingNetworkConfigurationFailed`
+/// at 35 bytes, which with a 64 MiB byte count and an hour of milliseconds
+/// makes a 111-byte line. The test below recomputes that worst case from the
+/// std error sets, so a wider name std adds fails the build's test run rather
+/// than silently truncating an operator's only diagnostic.
+pub const max_error_len: usize = 192;
 
 /// `SourceStatus.url` is fixed-size so a copied status borrows nothing. A
 /// blocklist url longer than this is truncated in the status only; the row
@@ -131,6 +136,55 @@ const SourceLabel = struct {
     }
 };
 
+/// The one place the download failure text is formatted. `phase`, `cause` and
+/// the byte count come from the fetcher's record of the concrete fault.
+///
+/// A timeout carries a record like any other failure: `fetchWithin` cancels the
+/// fetch on its way out of the race, and the cancelled fetch records the phase
+/// it was in, the status if a head had arrived and the bytes delivered so far,
+/// all before this function reads it. So an expiry reads
+/// `Timeout (receive_body, cause Canceled, http 200, 5242880 bytes, 300000 ms)`.
+/// `no fetch` and `-` are for a failure that never reached the network at all:
+/// `download` clears the record before anything can fail, so a local fault —
+/// the temporary file, an allocation, a refused task — reads as its own
+/// taxonomy name with nothing borrowed from the source fetched before it.
+fn downloadFailureText(
+    buf: []u8,
+    err: anyerror,
+    failure: ?fetcher.Failure,
+    last_status: ?std.http.Status,
+    elapsed_ms: u64,
+) []const u8 {
+    var status_buf: [8]u8 = undefined;
+    const status_text = if (if (failure) |f| f.status else last_status) |code|
+        std.fmt.bufPrint(&status_buf, "{d}", .{@intFromEnum(code)}) catch "none"
+    else
+        "none";
+
+    var bytes_buf: [24]u8 = undefined;
+    const bytes_text = if (failure) |f|
+        std.fmt.bufPrint(&bytes_buf, "{d}", .{f.bytes_read}) catch "-"
+    else
+        "-";
+
+    if (failure) |f| {
+        return std.fmt.bufPrint(buf, "{s} ({s}, cause {s}, http {s}, {s} bytes, {d} ms)", .{
+            @errorName(err),
+            @tagName(f.phase),
+            @errorName(f.cause),
+            status_text,
+            bytes_text,
+            elapsed_ms,
+        }) catch @errorName(err);
+    }
+    return std.fmt.bufPrint(buf, "{s} (no fetch, http {s}, {s} bytes, {d} ms)", .{
+        @errorName(err),
+        status_text,
+        bytes_text,
+        elapsed_ms,
+    }) catch @errorName(err);
+}
+
 pub const Paths = struct {
     /// `<data_dir>`, owned by the caller and left open for the manager's life.
     dir: std.Io.Dir,
@@ -1169,11 +1223,12 @@ pub const Manager = struct {
         raw_name: []const u8,
         tmp: TempNames,
     ) Error!Prepared {
-        self.download(io, dir, raw_name, row) catch |err| switch (err) {
+        var elapsed_ms: u64 = 0;
+        self.download(io, dir, raw_name, row, &elapsed_ms) catch |err| switch (err) {
             error.OutOfMemory => return error.OutOfMemory,
             error.Canceled => return error.Canceled,
             else => {
-                self.reportFetchFailure(row, status, err);
+                self.reportDownloadFailure(row, status, err, elapsed_ms);
                 return .failed;
             },
         };
@@ -1297,7 +1352,18 @@ pub const Manager = struct {
         dir: std.Io.Dir,
         raw_name: []const u8,
         row: sources_repo.SourceRow,
+        /// Milliseconds the download itself took, set whether it succeeded or
+        /// failed, so the failure line can say how long the peer had.
+        elapsed_ms: *u64,
     ) !void {
+        // Ahead of everything that can fail. The record is the fetcher's, not
+        // this source's, and a local failure here — the create, the allocation,
+        // a refused task — would otherwise leave the PREVIOUS source's network
+        // cause in place for `reportDownloadFailure` to print as this one's.
+        // Cleared here, a null record means no fetch reached the network.
+        self.fetcher.last_failure = null;
+        self.fetcher.last_status = null;
+
         const file = try dir.createFile(io, raw_name, .{ .permissions = .fromMode(0o600) });
         defer file.close(io);
 
@@ -1305,16 +1371,14 @@ pub const Manager = struct {
         defer self.gpa.free(buffer);
 
         var fw = file.writer(io, buffer);
-        const result = self.fetchWithin(io, row.url, &fw.interface) catch |err| {
+        const result = self.fetchWithin(io, row.url, &fw.interface, elapsed_ms) catch |err| {
             // `fetcher.Error.Unexpected` is what a failing sink surfaces as;
             // the concrete cause is on this writer, which the fetcher does not
             // own.
             if (fw.err) |cause| return cause;
-            if (err == error.HttpStatus) {
-                if (self.fetcher.last_status) |status| {
-                    log.warn("blocklist {f}: http status {d}", .{ SourceLabel.of(row), @intFromEnum(status) });
-                }
-            }
+            // The status used to get a second warning of its own. It is a field
+            // of the one download-failure line now, so a second line would only
+            // repeat it.
             return err;
         };
         try fw.interface.flush();
@@ -1332,7 +1396,12 @@ pub const Manager = struct {
         io: std.Io,
         url: []const u8,
         w: *std.Io.Writer,
+        elapsed_ms: *u64,
     ) fetcher.Error!fetcher.Result {
+        // `awake` and not `real`: an operator reading "812 ms" wants the time
+        // the transfer was given, which a stepped wall clock would misreport.
+        const started = std.Io.Clock.awake.now(io);
+
         var outcomes: [2]Outcome = undefined;
         var race: std.Io.Select(Outcome) = .init(io, &outcomes);
         defer race.cancelDiscard();
@@ -1344,7 +1413,12 @@ pub const Manager = struct {
             error.ConcurrencyUnavailable => return error.SystemResources,
         };
 
-        switch (try race.await()) {
+        // Read before the deferred `cancelDiscard`, which tears the loser down:
+        // the number is the time the peer had, not that plus the teardown.
+        const outcome = race.await();
+        elapsed_ms.* = @intCast(@max(0, started.durationTo(std.Io.Clock.awake.now(io)).toMilliseconds()));
+
+        switch (try outcome) {
             .fetch => |result| return result,
             .expiry => |result| {
                 // A canceled sleep means this task is being torn down, not that
@@ -1514,15 +1588,21 @@ pub const Manager = struct {
         return compiledBodiesMatch(list_bytes, wild_bytes, allow_bytes, expected);
     }
 
-    fn reportFetchFailure(
+    /// One line per failed source per pass, and the only place the download
+    /// failure text is built. The Diagnostics event detail gets the same text,
+    /// so an operator reading either can tell a TLS alert from a reset
+    /// connection from a truncated chunk.
+    fn reportDownloadFailure(
         self: *Manager,
         row: sources_repo.SourceRow,
         status: *SourceStatus,
         err: anyerror,
+        elapsed_ms: u64,
     ) void {
-        _ = self;
-        log.warn("blocklist {f}: download failed: {s}", .{ SourceLabel.of(row), @errorName(err) });
-        status.fail(.fetch_failed, @errorName(err));
+        var buf: [max_error_len]u8 = undefined;
+        const text = downloadFailureText(&buf, err, self.fetcher.last_failure, self.fetcher.last_status, elapsed_ms);
+        log.warn("blocklist {f}: download failed: {s}", .{ SourceLabel.of(row), text });
+        status.fail(.fetch_failed, text);
     }
 
     fn reportCompileFailure(
@@ -3580,3 +3660,104 @@ test "setSchedule is what the live schedule readers see" {
     try testing.expectEqual(@as(u16, 6), live.interval_hours);
     try testing.expect(manager.schedule_event.isSet());
 }
+
+test "a download failure line names the concrete cause behind the taxonomy" {
+    var buf: [1024]u8 = undefined;
+    const row: sources_repo.SourceRow = .{
+        .id = 3,
+        .url = "https://lists.example/download/token/hunter2/hosts.txt?apikey=s3cr3t",
+        .name = "ads",
+        .enabled = true,
+        .last_updated = null,
+        .domain_count = 0,
+        .wildcard_count = 0,
+        .skipped_regex_count = 0,
+        .skipped_unsupported_count = 0,
+        .checksum = null,
+    };
+    var text_buf: [max_error_len]u8 = undefined;
+    const text = downloadFailureText(&text_buf, error.ReceiveFailed, .{
+        .phase = .receive_body,
+        .cause = error.HttpChunkTruncated,
+        .status = .ok,
+        .bytes_read = 1024 * 1024,
+    }, .ok, 812);
+
+    const printed = try std.fmt.bufPrint(&buf, "blocklist {f}: download failed: {s}", .{
+        SourceLabel.of(row),
+        text,
+    });
+    try testing.expectEqualStrings(
+        "blocklist source 3 'ads' 'https://lists.example': download failed:" ++
+            " ReceiveFailed (receive_body, cause HttpChunkTruncated, http 200, 1048576 bytes, 812 ms)",
+        printed,
+    );
+    try testing.expect(!std.mem.containsAtLeast(u8, printed, 1, "hunter2"));
+    try testing.expect(!std.mem.containsAtLeast(u8, printed, 1, "s3cr3t"));
+}
+
+test "an expiry names the phase and the progress the cancelled fetch had made" {
+    // `fetchWithin` cancels the fetch before it reports, so a timeout normally
+    // does have a record: the cancellation the fetch saw, under the manager's
+    // own `error.Timeout`.
+    var text_buf: [max_error_len]u8 = undefined;
+    try testing.expectEqualStrings(
+        "Timeout (receive_body, cause Canceled, http 200, 5242880 bytes, 300000 ms)",
+        downloadFailureText(&text_buf, error.Timeout, .{
+            .phase = .receive_body,
+            .cause = error.Canceled,
+            .status = .ok,
+            .bytes_read = 5 * 1024 * 1024,
+        }, .ok, 300000),
+    );
+}
+
+test "a failure that never reached the network says so and borrows nothing" {
+    // `download` clears the fetcher's record before anything can fail, so a
+    // local fault reads as itself. Printing a phase and a cause here would be
+    // printing the previous source's network fault against this source.
+    var text_buf: [max_error_len]u8 = undefined;
+    try testing.expectEqualStrings(
+        "SystemResources (no fetch, http none, - bytes, 0 ms)",
+        downloadFailureText(&text_buf, error.SystemResources, null, null, 0),
+    );
+    try testing.expectEqualStrings(
+        "AccessDenied (no fetch, http none, - bytes, 3 ms)",
+        downloadFailureText(&text_buf, error.AccessDenied, null, null, 3),
+    );
+}
+
+test "max_error_len holds the widest download failure line whole" {
+    // `@errorName` of the unwrapped cause is the only unbounded-looking part.
+    // The two sets below are every set the unwraps in `upstream/transport.zig`
+    // can return a member of.
+    const widest_cause = comptime blk: {
+        var widest: []const u8 = "";
+        for (@typeInfo(std.crypto.tls.Client.ReadError).error_set.?) |member| {
+            if (member.name.len > widest.len) widest = member.name;
+        }
+        for (@typeInfo(std.http.Client.RequestError).error_set.?) |member| {
+            if (member.name.len > widest.len) widest = member.name;
+        }
+        for (@typeInfo(std.http.Reader.BodyError).error_set.?) |member| {
+            if (member.name.len > widest.len) widest = member.name;
+        }
+        break :blk widest;
+    };
+
+    var buf: [max_error_len]u8 = undefined;
+    const text = std.fmt.bufPrint(
+        &buf,
+        "{s} ({s}, cause {s}, http {d}, {d} bytes, {d} ms)",
+        .{
+            "SystemResources",
+            @tagName(fetcher.Phase.receive_body),
+            widest_cause,
+            @as(u16, 599),
+            @as(u64, fetcher.max_body_bytes),
+            @as(u64, std.time.ms_per_hour),
+        },
+    ) catch unreachable;
+    try testing.expect(text.len <= max_error_len);
+    try testing.expectEqualStrings("DetectingNetworkConfigurationFailed", widest_cause);
+}