Massive logging, improve connection closing/timeout handling

packages/web/src/Worker.zig

@@ -9,6 +9,8 @@ const RequestHandler = @import("RequestHandler.zig");
 const Response = @import("Response.zig");
 const Server = @import("Server.zig");
 
+const log = std.log.scoped(.Worker);
+
 /// Integer unique for this worker. Has no functional meaning. Can be used for
 /// debugging and profiling.
 worker_id: usize,
@@ -61,6 +63,8 @@ pub fn init(allocator: std.mem.Allocator, options: Options) !Worker {
 }
 
 pub fn deinit(self: *Worker, allocator: std.mem.Allocator) void {
+    log.debug("[#{d}] Deinitializing Worker.", .{self.worker_id});
+
     allocator.free(self.header_value_buffer);
     self.header_hash_map.deinit(allocator);
 
@@ -72,26 +76,43 @@ pub fn worker(
     server: *Server,
     running: *const std.atomic.Value(bool),
 ) void {
+    log.debug("[#{d}] Acquiring mutex.", .{self.worker_id});
     server.mutex.lock();
-    defer server.mutex.unlock();
+    log.debug("[#{d}] Acquired mutex.", .{self.worker_id});
+    defer {
+        log.debug("[#{d}] Unlocking mutex.", .{self.worker_id});
+        server.mutex.unlock();
+    }
 
     while (running.load(.acquire)) {
         if (server.connection_queue.pop()) |node| {
             const connection: *Connection = @fieldParentPtr("node", node);
+            log.debug("[#{d}] Popped connection to {f} from the connection queue.", .{ self.worker_id, connection.address });
 
+            log.debug("[#{d}] Unlocking mutex.", .{self.worker_id});
             server.mutex.unlock();
             defer {
+                log.debug("[#{d}] Acquiring mutex.", .{self.worker_id});
                 server.mutex.lock();
+                log.debug("[#{d}] Acquired mutex.", .{self.worker_id});
+
+                log.debug("[#{d}] Returning connection to connection pool.", .{self.worker_id});
                 server.connection_pool.append(&connection.node);
+                log.debug("[#{d}] Signaling connection freed condition variable.", .{self.worker_id});
                 server.cond_connection_freed.signal();
             }
 
+            log.debug("[#{d}] Handling connection to {f}.", .{ self.worker_id, connection.address });
             self.handleConnection(server.request_handler, connection, running) catch |err| {
-                std.log.err("Error while handling connection: {}", .{err});
+                log.err("[#{d}] Error while handling connection: {}", .{ self.worker_id, err });
             };
         } else {
+            log.debug("[#{d}] Waiting on connection queued condition variable.", .{self.worker_id});
             server.cond_connection_queued.wait(&server.mutex);
+            log.debug("[#{d}] Woken up on connection queued condition variable.", .{self.worker_id});
         }
+    } else {
+        log.debug("[#{d}] Loaded `false` from running, the worker loop exited.", .{self.worker_id});
     }
 }
 
@@ -105,11 +126,16 @@ fn handleConnection(
 
     while (running.load(.acquire)) {
         const res = self.handleRequest(request_handler, connection) catch |err| {
-            std.log.err("Error while handling request: {}", .{err});
+            log.err("[#{d}] Error while handling request: {}", .{ self.worker_id, err });
             return err;
         };
 
-        if (!res) break;
+        if (!res) {
+            log.debug("[#{d}] Request handler indicated to stop handling the connection to {f}.", .{ self.worker_id, connection.address });
+            break;
+        }
+    } else {
+        log.debug("[#{d}] Loaded `false` from running, the connection handler loop exited.", .{self.worker_id});
     }
 }
 
@@ -131,6 +157,7 @@ fn handleRequest(
 
     var next_header_index: usize = 0;
     var ignore: bool = false;
+    var client_closed: bool = false;
 
     var leftover_bytes = self.read_tail - self.read_head;
     const max_read_tail = self.read_head + self.read_buffer_size;
@@ -145,7 +172,17 @@ fn handleRequest(
             leftover_bytes = 0;
         } else {
             const read_tail = self.read_tail;
-            bytes_read = try connection.read(self.read_buffer_ptr[read_tail..max_read_tail]);
+            bytes_read = connection.read(self.read_buffer_ptr[read_tail..max_read_tail]) catch |err| switch (err) {
+                error.Timeout => {
+                    log.debug("[#{d}] Connection to {f} timed out.", .{ self.worker_id, connection.address });
+                    return false;
+                },
+                else => return err,
+            };
+            if (bytes_read == 0) {
+                log.debug("[#{d}] Read zero bytes from connection to {f}.", .{ self.worker_id, connection.address });
+                return false;
+            }
             chunk = self.read_buffer_ptr[read_tail .. read_tail + bytes_read];
             self.read_tail += bytes_read;
         }
@@ -175,6 +212,10 @@ fn handleRequest(
                 .method => |method| request.method = method,
                 .pathname => |pathname| request.pathname = pathname,
                 .header => |header| blk: {
+                    if (header.isNamedKnown(.Connection) and std.mem.eql(u8, header.value, "close")) {
+                        client_closed = true;
+                    }
+
                     if (ignore) {
                         break :blk;
                     }
@@ -258,7 +299,7 @@ fn handleRequest(
                     leftover_bytes = bytes_read - res.consumed;
                     self.read_head = (self.read_tail - leftover_bytes) & ~(self.read_buffer_size - 1);
                     self.read_tail = self.read_head + leftover_bytes;
-                    return true;
+                    return !client_closed;
                 },
             }
         }