milestone 16: behavioral fixes for silent failures, locks, counters and the query log

src/platform/logging.zig

@@ -102,10 +102,12 @@ pub fn boundedScopeName(scope_name: []const u8) []const u8 {
 // ---------------------------------------------------------------------------
 
 /// PLAN §11.6 rate-limits exactly the scopes whose failures repeat once per
-/// query; every other scope logs unconditionally.
+/// query; every other scope logs unconditionally. `.tls_server` joins them
+/// (milestone-16 ruling 16): its warnings are peer-driven, so an unhappy client
+/// could otherwise evict genuine warnings from the rotating log.
 pub fn isDedupScope(comptime scope: @EnumLiteral()) bool {
     return scope == .doh_client or scope == .dot_client or
-        scope == .pool or scope == .forward_client;
+        scope == .pool or scope == .forward_client or scope == .tls_server;
 }
 
 pub fn buildKey(
@@ -651,13 +653,16 @@ test "enabled admits at and above the threshold only" {
     try testing.expect(enabled(.debug, .debug));
 }
 
-test "isDedupScope selects exactly the four upstream scopes" {
+test "isDedupScope selects exactly the four upstream scopes and tls_server" {
     try testing.expect(isDedupScope(.doh_client));
     try testing.expect(isDedupScope(.dot_client));
     try testing.expect(isDedupScope(.pool));
     try testing.expect(isDedupScope(.forward_client));
+    try testing.expect(isDedupScope(.tls_server));
     try testing.expect(!isDedupScope(.default));
     try testing.expect(!isDedupScope(.cache));
+    try testing.expect(!isDedupScope(.dot_server));
+    try testing.expect(!isDedupScope(.doh_server));
 }
 
 test "buildKey separates the scope from the message" {

src/platform/tls_server.zig

@@ -212,6 +212,12 @@ pub const ServerStream = struct {
     read_code: c_int,
     /// Most recent negative Mbed TLS code behind `error.WriteFailed`.
     write_code: c_int,
+    /// The transport failure behind the last failed `bioRecv`. Mbed TLS only
+    /// forwards its own generic code, so without this stash a routine idle
+    /// cancel and a peer reset are indistinguishable to the caller.
+    recv_cause: ?anyerror,
+    /// The transport failure behind the last failed `bioSend`.
+    send_cause: ?anyerror,
 
     pub const ReadError = error{
         /// The peer closed the transport without sending close_notify. Any
@@ -220,6 +226,9 @@ pub const ServerStream = struct {
         TlsConnectionTruncated,
         /// Mbed TLS rejected the record; `read_code` holds its code.
         TlsFailed,
+        /// nxdns canceled the read — an idle budget expiring or a shutdown,
+        /// never a TLS fault. Kept distinct so callers do not count it.
+        Canceled,
     };
 
     /// Zero-length transport buffers: Mbed TLS keeps its own record buffers, so
@@ -274,6 +283,8 @@ pub const ServerStream = struct {
             .read_err = null,
             .read_code = 0,
             .write_code = 0,
+            .recv_cause = null,
+            .send_cause = null,
         };
 
         try check(mbedtls_ssl_setup(self.ssl.ptr, ctx.config.ptr), "ssl_setup", error.SetupFailed);
@@ -284,7 +295,9 @@ pub const ServerStream = struct {
             if (rc == 0) return;
             if (isRetry(rc)) continue;
             if (rc == err_conn_eof or rc == err_peer_close_notify) return error.PeerClosed;
-            report("ssl_handshake", rc);
+            // A probe that connects and then drops reaches this on every
+            // attempt, so a peer-driven handshake failure logs at debug.
+            report("ssl_handshake", rc, self.level(self.recv_cause orelse self.send_cause));
             return error.HandshakeFailed;
         }
     }
@@ -308,7 +321,9 @@ pub const ServerStream = struct {
         while (true) {
             const rc = mbedtls_ssl_close_notify(self.ssl.ptr);
             if (isRetry(rc)) continue;
-            if (rc != 0) report("ssl_close_notify", rc);
+            // close_notify against a socket the peer already dropped fails
+            // every time; that is the peer's doing, not a fault worth a warn.
+            if (rc != 0) report("ssl_close_notify", rc, self.level(self.send_cause orelse self.recv_cause));
             break;
         }
         mbedtls_ssl_free(self.ssl.ptr);
@@ -365,8 +380,9 @@ pub const ServerStream = struct {
                 return self.failRead(error.TlsConnectionTruncated, rc);
             }
             if (rc < 0) {
-                report("ssl_read", rc);
-                return self.failRead(error.TlsFailed, rc);
+                const err = readErrorFor(self.recv_cause);
+                report("ssl_read", rc, self.level(self.recv_cause));
+                return self.failRead(err, rc);
             }
             r.end += @intCast(rc);
             return 0;
@@ -379,6 +395,10 @@ pub const ServerStream = struct {
         return error.ReadFailed;
     }
 
+    fn level(self: *const ServerStream, cause: ?anyerror) std.log.Level {
+        return causeLevel(self.peer_closed, cause);
+    }
+
     fn writerDrain(w: *Writer, data: []const []const u8, splat: usize) Writer.Error!usize {
         const self: *ServerStream = @alignCast(@fieldParentPtr("writer_interface", w));
 
@@ -408,7 +428,7 @@ pub const ServerStream = struct {
             if (isRetry(rc)) continue;
             if (rc < 0) {
                 self.write_code = rc;
-                report("ssl_write", rc);
+                report("ssl_write", rc, self.level(self.send_cause));
                 return error.WriteFailed;
             }
             return @intCast(rc);
@@ -418,18 +438,30 @@ pub const ServerStream = struct {
     fn bioSend(bio: ?*anyopaque, buf: [*]const u8, len: usize) callconv(.c) c_int {
         const self: *ServerStream = @ptrCast(@alignCast(bio.?));
         const w = &self.net_writer.interface;
-        w.writeAll(buf[0..len]) catch return err_net_send_failed;
-        w.flush() catch return err_net_send_failed;
+        w.writeAll(buf[0..len]) catch return self.sendFailed();
+        w.flush() catch return self.sendFailed();
         return @intCast(len);
     }
 
+    /// Mbed TLS only ever sees `err_net_send_failed`, so the concrete cause is
+    /// kept here for the caller and for the log level.
+    fn sendFailed(self: *ServerStream) c_int {
+        if (self.net_writer.err) |cause| self.send_cause = cause;
+        return err_net_send_failed;
+    }
+
+    fn recvFailed(self: *ServerStream) c_int {
+        if (self.net_reader.err) |cause| self.recv_cause = cause;
+        return err_net_recv_failed;
+    }
+
     fn bioRecv(bio: ?*anyopaque, buf: [*]u8, len: usize) callconv(.c) c_int {
         const self: *ServerStream = @ptrCast(@alignCast(bio.?));
         if (len == 0) return 0;
         var data: [1][]u8 = .{buf[0..len]};
         const n = self.net_reader.interface.readVec(&data) catch |err| switch (err) {
             error.EndOfStream => return 0,
-            error.ReadFailed => return err_net_recv_failed,
+            error.ReadFailed => return self.recvFailed(),
         };
         // A zero-length transport buffer makes a short read impossible, but the
         // interface permits it; ask Mbed TLS to come back rather than reporting EOF.
@@ -468,14 +500,55 @@ fn isRetry(rc: c_int) bool {
 
 fn check(rc: c_int, comptime op: []const u8, comptime failure: anytype) @TypeOf(failure)!void {
     if (rc == 0) return;
-    report(op, rc);
+    // Setup and configuration failures are nxdns's own; no peer can cause them.
+    report(op, rc, .warn);
     return failure;
 }
 
-fn report(comptime op: []const u8, rc: c_int) void {
+fn report(comptime op: []const u8, rc: c_int, level: std.log.Level) void {
     var text: [160]u8 = undefined;
     mbedtls_strerror(rc, &text, text.len);
-    log.warn("mbedtls_{s} failed: {s} ({d})", .{ op, std.mem.sliceTo(&text, 0), rc });
+    const args = .{ op, std.mem.sliceTo(&text, 0), rc };
+    switch (level) {
+        .err => log.err("mbedtls_{s} failed: {s} ({d})", args),
+        .warn => log.warn("mbedtls_{s} failed: {s} ({d})", args),
+        .info => log.info("mbedtls_{s} failed: {s} ({d})", args),
+        .debug => log.debug("mbedtls_{s} failed: {s} ({d})", args),
+    }
+}
+
+/// A transport failure the peer or an nxdns shutdown produced, as opposed to a
+/// local resource or configuration failure. The names come from
+/// `std.Io.net.Stream.Reader.Error` and `.Writer.Error`.
+fn isPeerCause(cause: ?anyerror) bool {
+    const concrete = cause orelse return false;
+    return switch (concrete) {
+        error.Canceled,
+        error.ConnectionResetByPeer,
+        error.ConnectionRefused,
+        error.Timeout,
+        error.SocketUnconnected,
+        error.HostUnreachable,
+        error.NetworkUnreachable,
+        => true,
+        else => false,
+    };
+}
+
+/// Peer-driven and shutdown-driven failures log at debug, for the reason the
+/// truncation path already records: any client can reach these sites at will,
+/// so a louder level is a log-spam vector. Local and configuration failures —
+/// which no peer can provoke — keep warn.
+fn causeLevel(peer_closed: bool, cause: ?anyerror) std.log.Level {
+    if (peer_closed) return .debug;
+    return if (isPeerCause(cause)) .debug else .warn;
+}
+
+/// A canceled transport read is nxdns closing the connection, not a TLS fault,
+/// so it keeps its own error instead of collapsing into `TlsFailed`.
+fn readErrorFor(cause: ?anyerror) ServerStream.ReadError {
+    const concrete = cause orelse return error.TlsFailed;
+    return if (concrete == error.Canceled) error.Canceled else error.TlsFailed;
 }
 
 // -- Mbed TLS 3.6.7 surface ------------------------------------------------
@@ -663,6 +736,34 @@ test "the shim agrees with the alignment contexts are allocated at" {
     try std.testing.expect(nx_sizeof_ctr_drbg_context() > 0);
 }
 
+test "readErrorFor keeps a canceled read out of the TLS failure bucket" {
+    try std.testing.expectEqual(ServerStream.ReadError.Canceled, readErrorFor(error.Canceled));
+    try std.testing.expectEqual(ServerStream.ReadError.TlsFailed, readErrorFor(error.ConnectionResetByPeer));
+    try std.testing.expectEqual(ServerStream.ReadError.TlsFailed, readErrorFor(error.SystemResources));
+    try std.testing.expectEqual(ServerStream.ReadError.TlsFailed, readErrorFor(null));
+}
+
+test "causeLevel logs peer misbehavior at debug and local faults at warn" {
+    // Ruling 16: close_notify against a socket the peer already dropped.
+    try std.testing.expectEqual(std.log.Level.debug, causeLevel(true, null));
+    try std.testing.expectEqual(std.log.Level.debug, causeLevel(false, error.ConnectionResetByPeer));
+    try std.testing.expectEqual(std.log.Level.debug, causeLevel(false, error.Canceled));
+    try std.testing.expectEqual(std.log.Level.warn, causeLevel(false, error.SystemResources));
+    // No stashed cause means Mbed TLS rejected the record itself.
+    try std.testing.expectEqual(std.log.Level.warn, causeLevel(false, null));
+}
+
+test "isPeerCause separates peer and shutdown failures from local ones" {
+    try std.testing.expect(isPeerCause(error.Canceled));
+    try std.testing.expect(isPeerCause(error.ConnectionResetByPeer));
+    try std.testing.expect(isPeerCause(error.Timeout));
+    try std.testing.expect(isPeerCause(error.SocketUnconnected));
+    try std.testing.expect(!isPeerCause(error.SystemResources));
+    try std.testing.expect(!isPeerCause(error.AccessDenied));
+    try std.testing.expect(!isPeerCause(error.NetworkDown));
+    try std.testing.expect(!isPeerCause(null));
+}
+
 /// Drops the second half of a PEM document, keeping the header intact so the
 /// parser fails on the body rather than on a missing "-----BEGIN" line.
 fn truncate(gpa: std.mem.Allocator, pem: [:0]const u8) ![:0]const u8 {
@@ -764,6 +865,109 @@ test "a transport EOF without close_notify reads as a truncated stream" {
     try server_result;
 }
 
+test "a canceled read stashes Canceled, not TlsFailed" {
+    const build_options = @import("build_options");
+    if (!build_options.integration) return error.SkipZigTest;
+
+    const fixtures = @import("test_fixtures");
+    const gpa = std.testing.allocator;
+
+    var threaded: Io.Threaded = .init(gpa, .{});
+    defer threaded.deinit();
+    const io = threaded.io();
+
+    var ctx = try ServerContext.init(gpa, fixtures.cert_pem, fixtures.key_pem, null);
+    defer ctx.deinit(gpa);
+
+    const listen_address: Io.net.IpAddress = .{ .ip4 = .loopback(0) };
+    var server = try listen_address.listen(io, .{ .reuse_address = true });
+    defer server.deinit(io);
+
+    // Set once the server task is about to block in `readIntoBuffer`, so the
+    // cancellation below lands on the read and not on the handshake.
+    var reading: Io.Event = .unset;
+    var server_task = try io.concurrent(expectCanceledRead, .{ gpa, &ctx, io, &server, &reading });
+
+    var client = runIdleClient(io, server.socket.address) catch |err| {
+        server_task.cancel(io) catch {};
+        return err;
+    };
+    defer client.close(io);
+
+    reading.waitUncancelable(io);
+    try server_task.cancel(io);
+}
+
+/// Handshakes, then blocks in a plaintext read that only the cancel can end.
+fn expectCanceledRead(
+    gpa: std.mem.Allocator,
+    ctx: *ServerContext,
+    io: Io,
+    server: *Io.net.Server,
+    reading: *Io.Event,
+) anyerror!void {
+    var stream = try server.accept(io);
+    defer stream.close(io);
+
+    var read_buffer: [4096]u8 = undefined;
+    var write_buffer: [4096]u8 = undefined;
+    var tls: ServerStream = undefined;
+    try tls.accept(gpa, ctx, io, &stream, &read_buffer, &write_buffer);
+    defer tls.close(gpa);
+
+    reading.set(io);
+
+    var byte: [1]u8 = undefined;
+    try std.testing.expectError(error.ReadFailed, tls.reader().readSliceAll(&byte));
+    try std.testing.expectEqual(ServerStream.ReadError.Canceled, tls.read_err.?);
+    try std.testing.expectEqual(@as(?anyerror, error.Canceled), tls.recv_cause);
+    // A cancel is nxdns's own doing, never the peer ending the stream.
+    try std.testing.expect(!tls.peer_closed);
+}
+
+/// A client that completes the handshake and then sends nothing. The caller
+/// keeps it alive so the server's read has no other way to end.
+const IdleClient = struct {
+    stream: Io.net.Stream,
+
+    fn close(self: *IdleClient, io: Io) void {
+        self.stream.close(io);
+    }
+};
+
+fn runIdleClient(io: Io, address: Io.net.IpAddress) !IdleClient {
+    const tls = std.crypto.tls;
+
+    var stream = try address.connect(io, .{ .mode = .stream });
+    errdefer stream.close(io);
+
+    // The handshake buffers die with this function; the connection outlives it
+    // because nothing more is ever read from or written to it.
+    var transport_read_buffer: [tls.Client.min_buffer_len]u8 = undefined;
+    var transport_write_buffer: [tls.Client.min_buffer_len]u8 = undefined;
+    var net_reader = stream.reader(io, &transport_read_buffer);
+    var net_writer = stream.writer(io, &transport_write_buffer);
+
+    var entropy: [tls.Client.Options.entropy_len]u8 = undefined;
+    io.random(&entropy);
+
+    var plaintext_read_buffer: [4096]u8 = undefined;
+    var plaintext_write_buffer: [4096]u8 = undefined;
+
+    var client = try tls.Client.init(&net_reader.interface, &net_writer.interface, .{
+        .host = .no_verification,
+        .ca = .no_verification,
+        .read_buffer = &plaintext_read_buffer,
+        .write_buffer = &plaintext_write_buffer,
+        .entropy = &entropy,
+        .realtime_now = Io.Timestamp.now(io, .real),
+    });
+    _ = &client;
+    try net_writer.interface.flush();
+
+    return .{ .stream = stream };
+}
+
 fn expectTruncation(
     gpa: std.mem.Allocator,
     ctx: *ServerContext,