more expressive cache logging

src/browser/HttpClient.zig

@@ -375,16 +375,8 @@ fn processRequest(self: *Client, req: Request) !void {
                 .timestamp = std.time.timestamp(),
                 .request_headers = req_header_list.items,
             })) |cached| {
-                log.debug(.browser, "http.cache.get", .{
-                    .url = req.url,
-                    .found = true,
-                    .metadata = cached.metadata,
-                });
-
                 defer req.headers.deinit();
                 return serveFromCache(req, &cached);
-            } else {
-                log.debug(.browser, "http.cache.get", .{ .url = req.url, .found = false });
             }
         }
     }
@@ -972,12 +964,9 @@ fn processOneMessage(self: *Client, msg: http.Handles.MultiMessage, transfer: *T
 
     if (transfer._pending_cache_metadata) |metadata| {
         const cache = &self.network.cache.?;
-        log.debug(.browser, "http cache", .{ .url = transfer.req.url, .metadata = metadata });
-
         cache.put(metadata, body) catch |err| {
-            log.warn(.http, "cache put failed", .{ .err = err });
+            log.warn(.cache, "cache put failed", .{ .err = err });
         };
-        log.debug(.browser, "http.cache.put", .{ .url = transfer.req.url });
     }
 
     // release conn ASAP so that it's available; some done_callbacks
@@ -1157,6 +1146,13 @@ pub const Response = struct {
             .cached => {},
         }
     }
+
+    pub fn format(self: Response, writer: *std.Io.Writer) !void {
+        return switch (self.inner) {
+            .transfer => |t| try t.format(writer),
+            .cached => |c| try c.format(writer),
+        };
+    }
 };
 
 pub const Transfer = struct {

src/network/cache/Cache.zig

@@ -138,11 +138,25 @@ pub const CachedData = union(enum) {
         offset: usize,
         len: usize,
     },
+
+    pub fn format(self: CachedData, writer: *std.Io.Writer) !void {
+        switch (self) {
+            .buffer => |buf| try writer.print("buffer({d} bytes)", .{buf.len}),
+            .file => |f| try writer.print("file(offset={d}, len={d} bytes)", .{ f.offset, f.len }),
+        }
+    }
 };
 
 pub const CachedResponse = struct {
     metadata: CachedMetadata,
     data: CachedData,
+
+    pub fn format(self: *const CachedResponse, writer: *std.Io.Writer) !void {
+        try writer.print("metadata=(", .{});
+        try self.metadata.format(writer);
+        try writer.print("), data=", .{});
+        try self.data.format(writer);
+    }
 };
 
 pub fn tryCache(

src/network/cache/FsCache.zig

@@ -97,7 +97,7 @@ pub fn get(self: *FsCache, arena: std.mem.Allocator, req: CacheRequest) ?Cache.C
     const file = self.dir.openFile(&cache_p, .{ .mode = .read_only }) catch |e| {
         switch (e) {
             std.fs.File.OpenError.FileNotFound => {
-                log.debug(.cache, "miss", .{ .url = req.url, .hash = &hashed_key });
+                log.debug(.cache, "miss", .{ .url = req.url, .hash = &hashed_key, .reason = "missing" });
             },
             else => |err| {
                 log.warn(.cache, "open file err", .{ .url = req.url, .err = err });
@@ -141,13 +141,19 @@ pub fn get(self: *FsCache, arena: std.mem.Allocator, req: CacheRequest) ?Cache.C
         &json_reader,
         .{ .allocate = .alloc_always },
     ) catch |e| {
-        log.warn(.cache, "metadata parse", .{ .url = req.url, .err = e });
+        // Warn because malformed metadata can be a deeper symptom.
+        log.warn(.cache, "miss", .{ .url = req.url, .err = e, .reason = "malformed metadata" });
         cleanup = true;
         return null;
     };
 
     if (cache_file.version != CACHE_VERSION) {
-        log.warn(.cache, "version", .{ .url = req.url, .expected = CACHE_VERSION, .got = cache_file.version });
+        log.debug(.cache, "miss", .{
+            .url = req.url,
+            .reason = "version mismatch",
+            .expected = CACHE_VERSION,
+            .got = cache_file.version,
+        });
         cleanup = true;
         return null;
     }
@@ -158,7 +164,7 @@ pub fn get(self: *FsCache, arena: std.mem.Allocator, req: CacheRequest) ?Cache.C
     const now = req.timestamp;
     const age = (now - metadata.stored_at) + @as(i64, @intCast(metadata.age_at_store));
     if (age < 0 or @as(u64, @intCast(age)) >= metadata.cache_control.max_age) {
-        log.debug(.cache, "expired", .{ .url = req.url });
+        log.debug(.cache, "miss", .{ .url = req.url, .reason = "expired" });
         cleanup = true;
         return null;
     }
@@ -173,7 +179,13 @@ pub fn get(self: *FsCache, arena: std.mem.Allocator, req: CacheRequest) ?Cache.C
         } else "";
 
         if (!std.ascii.eqlIgnoreCase(value, incoming)) {
-            log.debug(.cache, "vary mismatch", .{ .url = req.url, .header = name });
+            log.debug(.cache, "miss", .{
+                .url = req.url,
+                .reason = "vary mismatch",
+                .header = name,
+                .expected = value,
+                .got = incoming,
+            });
             return null;
         }
     }
@@ -185,6 +197,8 @@ pub fn get(self: *FsCache, arena: std.mem.Allocator, req: CacheRequest) ?Cache.C
         return null;
     }
 
+    log.debug(.cache, "hit", .{ .url = req.url, .hash = &hashed_key });
+
     return .{
         .metadata = metadata,
         .data = .{
@@ -206,27 +220,45 @@ pub fn put(self: *FsCache, meta: CachedMetadata, body: []const u8) !void {
     lock.lock();
     defer lock.unlock();
 
-    const file = try self.dir.createFile(&cache_tmp_p, .{ .truncate = true });
+    const file = self.dir.createFile(&cache_tmp_p, .{ .truncate = true }) catch |e| {
+        log.err(.cache, "create file", .{ .url = meta.url, .file = &cache_tmp_p, .err = e });
+        return e;
+    };
     defer file.close();
 
     var writer_buf: [1024]u8 = undefined;
-
     var file_writer = file.writer(&writer_buf);
     var file_writer_iface = &file_writer.interface;
 
     var len_buf: [8]u8 = undefined;
     std.mem.writeInt(u64, &len_buf, body.len, .little);
-    try file_writer_iface.writeAll(&len_buf);
-    try file_writer_iface.writeAll(body);
 
-    try std.json.Stringify.value(
+    file_writer_iface.writeAll(&len_buf) catch |e| {
+        log.err(.cache, "write body len", .{ .url = meta.url, .err = e });
+        return e;
+    };
+    file_writer_iface.writeAll(body) catch |e| {
+        log.err(.cache, "write body", .{ .url = meta.url, .err = e });
+        return e;
+    };
+    std.json.Stringify.value(
         CacheMetadataJson{ .version = CACHE_VERSION, .metadata = meta },
         .{ .whitespace = .minified },
         file_writer_iface,
-    );
+    ) catch |e| {
+        log.err(.cache, "write metadata", .{ .url = meta.url, .err = e });
+        return e;
+    };
+    file_writer_iface.flush() catch |e| {
+        log.err(.cache, "flush", .{ .url = meta.url, .err = e });
+        return e;
+    };
+    self.dir.rename(&cache_tmp_p, &cache_p) catch |e| {
+        log.err(.cache, "rename", .{ .url = meta.url, .from = &cache_tmp_p, .to = &cache_p, .err = e });
+        return e;
+    };
 
-    try file_writer_iface.flush();
+    log.debug(.cache, "put", .{ .url = meta.url, .hash = &hashed_key, .body_len = body.len });
-    try self.dir.rename(&cache_tmp_p, &cache_p);
 }
 
 const testing = std.testing;