From 297c1c8bb898562b96d6aaf1794c13de49f0da03 Mon Sep 17 00:00:00 2001
From: Emil Lerch <emil@lerch.org>
Date: Mon, 1 Jun 2026 12:58:52 -0700
Subject: [PATCH] log slow requests

---
 src/main.zig | 79 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 79 insertions(+)

diff --git a/src/main.zig b/src/main.zig
index cfdfa0a..8f19584 100644
--- a/src/main.zig
+++ b/src/main.zig
@@ -22,16 +22,26 @@ const App = struct {
     allocator: std.mem.Allocator,
     config: zfin.Config,
     svc: zfin.DataService,
+    /// Threshold in milliseconds above which a request is logged
+    /// as slow. Tunable via `ZFIN_SERVER_SLOW_MS` env var; defaults
+    /// to 500ms. Captured once at App.init so the dispatch hot path
+    /// doesn't re-parse on every request.
+    slow_threshold_ms: u64,
 
     fn init(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process.Environ.Map) App {
         const config = zfin.Config.fromEnv(io, allocator, environ);
         const svc = zfin.DataService.init(io, allocator, config);
+        const slow_threshold_ms = if (environ.get("ZFIN_SERVER_SLOW_MS")) |s|
+            std.fmt.parseInt(u64, s, 10) catch 500
+        else
+            500;
         return .{
             .io = io,
             .environ = environ,
             .allocator = allocator,
             .config = config,
             .svc = svc,
+            .slow_threshold_ms = slow_threshold_ms,
         };
     }
 
@@ -39,8 +49,46 @@ const App = struct {
         self.svc.deinit();
         self.config.deinit();
     }
+
+    /// httpz dispatch hook: every request flows through here so we
+    /// have a single place to wrap timing and error logging without
+    /// modifying every handler. Slow requests (above
+    /// `slow_threshold_ms`) and error responses (status >= 400)
+    /// emit a structured stderr line; everything else stays silent.
+    pub fn dispatch(self: *App, action: httpz.Action(*App), req: *httpz.Request, res: *httpz.Response) !void {
+        // wall-clock required: per-request elapsed for slow-request
+        // logging. `.awake` (monotonic) avoids spurious negatives
+        // on system clock skew.
+        const start_ns = std.Io.Timestamp.now(self.io, .awake).nanoseconds;
+        try action(self, req, res);
+
+        // using defer here so we execute unconditionally
+        defer {
+            const elapsed_ns = std.Io.Timestamp.now(self.io, .awake).nanoseconds - start_ns;
+            const elapsed_ms: u64 = @intCast(@divTrunc(elapsed_ns, std.time.ns_per_ms));
+            if (shouldLogRequest(elapsed_ms, res.status, self.slow_threshold_ms)) {
+                // wall-clock required: ts in stderr line lets the
+                // operator correlate slow requests with cron / system
+                // events using `date -d @<ts>`.
+                const ts = std.Io.Timestamp.now(self.io, .real).toSeconds();
+                log.warn("ts={d} elapsed_ms={d} status={d} method={s} path={s}", .{
+                    ts,
+                    elapsed_ms,
+                    res.status,
+                    @tagName(req.method),
+                    req.url.path,
+                });
+            }
+        }
+    }
 };
 
+/// Pure predicate: should this request emit a stderr log line?
+/// Logs slow successes (above threshold) and any error response.
+fn shouldLogRequest(elapsed_ms: u64, status: u16, threshold_ms: u64) bool {
+    return elapsed_ms > threshold_ms or status >= 400;
+}
+
 // ── Route handlers ───────────────────────────────────────────
 
 fn handleIndex(_: *App, _: *httpz.Request, res: *httpz.Response) !void {
@@ -814,3 +862,34 @@ test "upperDupe" {
     defer std.testing.allocator.free(result);
     try std.testing.expectEqualStrings("AAPL", result);
 }
+
+test "shouldLogRequest: fast 2xx is silent" {
+    try std.testing.expect(!shouldLogRequest(10, 200, 500));
+    try std.testing.expect(!shouldLogRequest(499, 200, 500));
+    try std.testing.expect(!shouldLogRequest(0, 204, 500));
+}
+
+test "shouldLogRequest: slow 2xx logs" {
+    try std.testing.expect(shouldLogRequest(501, 200, 500));
+    try std.testing.expect(shouldLogRequest(2000, 200, 500));
+    // Boundary: == threshold is NOT logged (strict >).
+    try std.testing.expect(!shouldLogRequest(500, 200, 500));
+}
+
+test "shouldLogRequest: any error response logs regardless of timing" {
+    try std.testing.expect(shouldLogRequest(1, 400, 500));
+    try std.testing.expect(shouldLogRequest(1, 404, 500));
+    try std.testing.expect(shouldLogRequest(1, 500, 500));
+    try std.testing.expect(shouldLogRequest(1, 503, 500));
+    // 3xx is not flagged as error.
+    try std.testing.expect(!shouldLogRequest(1, 301, 500));
+    try std.testing.expect(!shouldLogRequest(1, 304, 500));
+}
+
+test "shouldLogRequest: custom threshold respected" {
+    try std.testing.expect(!shouldLogRequest(50, 200, 100));
+    try std.testing.expect(shouldLogRequest(150, 200, 100));
+    // Higher threshold (e.g. user sets ZFIN_SERVER_SLOW_MS=2000).
+    try std.testing.expect(!shouldLogRequest(1500, 200, 2000));
+    try std.testing.expect(shouldLogRequest(2500, 200, 2000));
+}