log slow requests

build.zig.zon

@@ -14,8 +14,8 @@
             .hash = "httpz-0.0.0-PNVzrLjJCAD37S0CcrXpsjSqr86hVjK0rsALTDJ98AAJ",
         },
         .zfin = .{
-            .url = "git+https://git.lerch.org/lobo/zfin#641a88b0b768769a33e3f95fa6f1736fa58e4a6f",
-            .hash = "zfin-0.0.0-J-B21mEEPACavg9MPzB402B3DIzfIxXhNv3UOAyFHBxK",
+            .url = "git+https://git.lerch.org/lobo/zfin#4d65cc45f4fd7c71a4222d2d3c7c41100acd7069",
+            .hash = "zfin-0.0.0-J-B21ls4PADNXleWi_cuaAYNjBWEO0FfO3qyBnCPtE3R",
         },
     },
 }

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 {
@@ -416,8 +464,8 @@ fn upperDupe(allocator: std.mem.Allocator, s: []const u8) ![]u8 {
     return d;
 }
 
-fn printRateLimitWait(svc: *zfin.DataService, stdout: *std.Io.Writer) !void {
-    if (svc.estimateWaitSeconds()) |wait| {
+fn printRateLimitWait(svc: *zfin.DataService, data_type: zfin.cache.DataType, stdout: *std.Io.Writer) !void {
+    if (svc.estimateWaitSeconds(data_type)) |wait| {
         if (wait > 0) {
             try stdout.print("\n  (rate limit -- waiting {d}s)\n  ", .{wait});
             try stdout.flush();
@@ -558,7 +606,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
     // handlers to serve. Per-symbol `getEtfMetrics` calls below
     // also rely on these maps being loaded.
     {
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .tickers_funds, stdout);
         if (svc.loadMutualFundTickerMap(.{})) |mut_map| {
             var m = mut_map;
             m.deinit();
@@ -566,7 +614,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         } else |err| {
             try stdout.print("EDGAR mutual-fund ticker map FAILED ({t})\n", .{err});
         }
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .tickers_companies, stdout);
         if (svc.loadCompanyTickerMap(.{})) |co_map| {
             var m = co_map;
             m.deinit();
@@ -586,7 +634,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         var sym_ok = true;
 
         // Candles
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .candles_daily, stdout);
         if (svc.getCandles(sym, .{})) |result| {
             defer result.deinit();
             try stdout.print("candles ok ({s})", .{@tagName(result.source)});
@@ -604,7 +652,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         }
 
         // Dividends
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .dividends, stdout);
         if (svc.getDividends(sym, .{})) |result| {
             defer result.deinit();
             try stdout.print(", dividends ok ({s})", .{@tagName(result.source)});
@@ -614,7 +662,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         }
 
         // Splits
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .splits, stdout);
         if (svc.getSplits(sym, .{})) |result| {
             defer result.deinit();
             try stdout.print(", splits ok ({s})", .{@tagName(result.source)});
@@ -624,7 +672,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         }
 
         // Earnings
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .earnings, stdout);
         if (svc.getEarnings(sym, .{})) |result| {
             defer result.deinit();
             try stdout.print(", earnings ok ({s})", .{@tagName(result.source)});
@@ -639,7 +687,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         // Wikidata entry) and doesn't flip sym_ok.
         var cik_buf: ?[]u8 = null;
         defer if (cik_buf) |b| allocator.free(b);
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .classification, stdout);
         if (svc.getClassification(sym, .{})) |result| {
             defer result.deinit();
             if (result.data.len > 0) {
@@ -660,7 +708,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         // non-funds (NPORT-P only exists for funds + UITs); a
         // negative-cache entry suppresses retries. Logged as
         // `n/a` and doesn't flip sym_ok.
-        try printRateLimitWait(&svc, stdout);
+        try printRateLimitWait(&svc, .etf_metrics, stdout);
         if (svc.getEtfMetrics(sym, .{})) |result| {
             defer result.deinit();
             try stdout.print(", etf_metrics ok ({s})", .{@tagName(result.source)});
@@ -679,7 +727,7 @@ fn refresh(io: std.Io, allocator: std.mem.Allocator, environ: *const std.process
         // zfin chains entity_facts off Wikidata's CIK, so the
         // server warms the cache the same way).
         if (cik_buf) |cik| {
-            try printRateLimitWait(&svc, stdout);
+            try printRateLimitWait(&svc, .entity_facts, stdout);
             if (svc.getEntityFacts(cik, .{})) |result| {
                 defer result.deinit();
                 try stdout.print(", entity_facts ok ({s})", .{@tagName(result.source)});
@@ -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));
+}