Improve error handling and logging in HTTP::Server

spec/std/http/server/handlers/error_handler_spec.cr

@@ -1,5 +1,7 @@
 require "spec"
 require "http/server/handler"
+require "../../../../support/log"
+require "../../../../support/io"
 
 describe HTTP::ErrorHandler do
   it "rescues from exception" do
@@ -8,17 +10,39 @@ describe HTTP::ErrorHandler do
     response = HTTP::Server::Response.new(io)
     context = HTTP::Server::Context.new(request, response)
 
+    exception = Exception.new("OH NO!")
     handler = HTTP::ErrorHandler.new(verbose: true)
-    handler.next = ->(ctx : HTTP::Server::Context) { raise "OH NO!" }
-    handler.call(context)
-
+    handler.next = ->(ctx : HTTP::Server::Context) { raise exception }
+    logs = capture_logs("http.server") { handler.call(context) }
     response.close
 
-    io.rewind
-    response2 = HTTP::Client::Response.from_io(io)
-    response2.status_code.should eq(500)
-    response2.status_message.should eq("Internal Server Error")
-    (response2.body =~ /ERROR: OH NO!/).should be_truthy
+    client_response = HTTP::Client::Response.from_io(io.rewind)
+    client_response.status_code.should eq(500)
+    client_response.status_message.should eq("Internal Server Error")
+    client_response.headers["content-type"].should eq("text/plain")
+    client_response.headers.has_key?("content-length").should be_true
+    client_response.body.should match(/^ERROR: OH NO! \(Exception\)/)
+
+    match_logs(logs,
+      {:error, "Unhandled exception", exception}
+    )
+  end
+
+  it "logs to custom logger" do
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(IO::Memory.new)
+    context = HTTP::Server::Context.new(request, response)
+
+    exception = Exception.new("OH NO!")
+    backend = Log::MemoryBackend.new
+    log = Log.new("custom", backend, :info)
+    handler = HTTP::ErrorHandler.new(log: log)
+    handler.next = ->(ctx : HTTP::Server::Context) { raise exception }
+    handler.call(context)
+
+    match_logs(backend.entries,
+      {:error, "Unhandled exception", exception}
+    )
   end
 
   it "can return a generic error message" do
@@ -27,10 +51,62 @@ describe HTTP::ErrorHandler do
     response = HTTP::Server::Response.new(io)
     context = HTTP::Server::Context.new(request, response)
 
+    exception = Exception.new("OH NO!")
     handler = HTTP::ErrorHandler.new
-    handler.next = ->(ctx : HTTP::Server::Context) { raise "OH NO!" }
-    handler.call(context)
-    io.to_s.match(/500 Internal Server Error/).should_not be_nil
-    io.to_s.match(/OH NO/).should be_nil
+    handler.next = ->(ctx : HTTP::Server::Context) { raise exception }
+    logs = capture_logs("http.server") { handler.call(context) }
+
+    client_response = HTTP::Client::Response.from_io(io.rewind)
+    client_response.status_code.should eq(500)
+    client_response.status_message.should eq("Internal Server Error")
+    client_response.headers["content-type"].should eq("text/plain")
+    client_response.body.should eq("500 Internal Server Error\n")
+
+    match_logs(logs,
+      {:error, "Unhandled exception", exception}
+    )
+  end
+
+  it "log debug message when the output is closed" do
+    io = IO::Memory.new
+    io.close
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(io)
+    context = HTTP::Server::Context.new(request, response)
+
+    handler = HTTP::ErrorHandler.new
+    handler.next = ->(ctx : HTTP::Server::Context) { ctx.response.print "Hi!"; ctx.response.flush }
+    logs = capture_logs("http.server") { handler.call(context) }
+
+    match_logs(logs,
+      {:debug, "Error while writing data to the client"}
+    )
+    logs[0].exception.should be_a(IO::Error)
+  end
+
+  it "doesn't write errors when there is some output already sent" do
+    io = IO::Memory.new
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(io)
+    context = HTTP::Server::Context.new(request, response)
+
+    exception = Exception.new("OH NO!")
+    handler = HTTP::ErrorHandler.new
+    handler.next = ->(ctx : HTTP::Server::Context) do
+      ctx.response.print "Hi"
+      ctx.response.flush
+      raise exception
+    end
+    logs = capture_logs("http.server") { handler.call(context) }
+    response.close
+
+    client_response = HTTP::Client::Response.from_io(io.rewind)
+    client_response.status_code.should eq(200)
+    client_response.status_message.should eq("OK")
+    client_response.body.should eq("Hi")
+
+    match_logs(logs,
+      {:error, "Unhandled exception", exception}
+    )
   end
 end

spec/std/http/server/handlers/log_handler_spec.cr

@@ -1,35 +1,71 @@
 require "spec"
 require "http/server/handler"
+require "../../../../support/log"
+require "../../../../support/io"
 
 describe HTTP::LogHandler do
   it "logs" do
     io = IO::Memory.new
     request = HTTP::Request.new("GET", "/")
+    request.remote_address = "192.168.0.1"
     response = HTTP::Server::Response.new(io)
     context = HTTP::Server::Context.new(request, response)
 
     called = false
-    log_io = IO::Memory.new
-    handler = HTTP::LogHandler.new(log_io)
+    handler = HTTP::LogHandler.new
     handler.next = ->(ctx : HTTP::Server::Context) { called = true }
-    handler.call(context)
-    log_io.to_s.should match %r(GET / - 200 \(\d+(\.\d+)?[mµn]s\))
+    logs = capture_logs("http.server") { handler.call(context) }
+    match_logs(logs,
+      {:info, %r(^192.168.0.1 - GET / HTTP/1.1 - 200 \(\d+(\.\d+)?[mµn]s\)$)}
+    )
     called.should be_true
   end
 
-  it "does log errors" do
+  it "logs to custom logger" do
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(IO::Memory.new)
+    context = HTTP::Server::Context.new(request, response)
+
+    backend = Log::MemoryBackend.new
+    log = Log.new("custom", backend, :info)
+    handler = HTTP::LogHandler.new(log)
+    handler.next = ->(ctx : HTTP::Server::Context) {}
+    handler.call(context)
+
+    match_logs(backend.entries,
+      {:info, %r(^- - GET / HTTP/1.1 - 200 \(\d+(\.\d+)?[mµn]s\)$)}
+    )
+  end
+
+  it "logs to io" do
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(IO::Memory.new)
+    context = HTTP::Server::Context.new(request, response)
+
+    backend = Log::MemoryBackend.new
+    io = IO::Memory.new
+    handler = HTTP::LogHandler.new(io)
+    handler.next = ->(ctx : HTTP::Server::Context) {}
+    handler.call(context)
+
+    io.to_s.should match(%r(- - GET / HTTP/1.1 - 200 \(\d+(\.\d+)?[mµn]s\)$))
+  end
+
+  it "log failed request" do
     io = IO::Memory.new
     request = HTTP::Request.new("GET", "/")
     response = HTTP::Server::Response.new(io)
     context = HTTP::Server::Context.new(request, response)
 
-    called = false
-    log_io = IO::Memory.new
-    handler = HTTP::LogHandler.new(log_io)
+    handler = HTTP::LogHandler.new
     handler.next = ->(ctx : HTTP::Server::Context) { raise "foo" }
-    expect_raises(Exception, "foo") do
-      handler.call(context)
+    logs = capture_logs("http.server") do
+      expect_raises(Exception, "foo") do
+        handler.call(context)
+      end
     end
-    (log_io.to_s =~ %r(GET / - Unhandled exception:)).should be_truthy
+    match_logs(logs,
+      {:info, %r(^- - GET / HTTP/1.1 - 200 \(\d+(\.\d+)?[mµn]s\)$)}
+    )
   end
 end

spec/std/http/server/request_processor_spec.cr

@@ -1,18 +1,7 @@
 require "spec"
 require "http/server/request_processor"
-
-private class RaiseIOError < IO
-  def initialize
-  end
-
-  def read(slice : Bytes)
-    raise IO::Error.new("...")
-  end
-
-  def write(slice : Bytes) : Nil
-    raise "not implemented"
-  end
-end
+require "../../../support/log"
+require "../../../support/io"
 
 private def requestize(string)
   string.gsub('\n', "\r\n")
@@ -243,20 +232,97 @@ describe HTTP::Server::RequestProcessor do
     end
   end
 
-  it "handles IO::Error" do
+  it "handles IO::Error while reading" do
     processor = HTTP::Server::RequestProcessor.new { }
     input = RaiseIOError.new
     output = IO::Memory.new
     processor.process(input, output)
     output.rewind.gets_to_end.empty?.should be_true
   end
 
+  it "handles IO::Error while writing" do
+    processor = HTTP::Server::RequestProcessor.new do |context|
+      context.response.content_type = "text/plain"
+      context.response.print "Hello world"
+      context.response.flush
+    end
+    input = IO::Memory.new("GET / HTTP/1.1\r\n\r\n")
+    output = RaiseIOError.new(true)
+    logs = capture_logs("http.server") do
+      processor.process(input, output)
+    end
+    match_logs(logs,
+      {:debug, "Error while writing data to the client"}
+    )
+    logs[0].exception.should be_a(IO::Error)
+  end
+
+  it "handles IO::Error while flushing" do
+    processor = HTTP::Server::RequestProcessor.new do |context|
+      context.response.flush
+    end
+    input = IO::Memory.new("GET / HTTP/1.1\r\n\r\n")
+    output = RaiseIOError.new(false)
+    logs = capture_logs("http.server") do
+      processor.process(input, output)
+    end
+    match_logs(logs,
+      {:debug, "Error while flushing data to the client"}
+    )
+    logs[0].exception.should be_a(IO::Error)
+  end
+
   it "catches raised error on handler" do
-    processor = HTTP::Server::RequestProcessor.new { raise "OH NO" }
+    exception = Exception.new "OH NO"
+    processor = HTTP::Server::RequestProcessor.new { raise exception }
     input = IO::Memory.new("GET / HTTP/1.1\r\n\r\n")
     output = IO::Memory.new
-    error = IO::Memory.new
-    processor.process(input, output, error)
-    output.rewind.gets_to_end.should match(/Internal Server Error/)
+    logs = capture_logs("http.server") do
+      processor.process(input, output)
+    end
+
+    client_response = HTTP::Client::Response.from_io(output.rewind)
+    client_response.status_code.should eq(500)
+    client_response.status_message.should eq("Internal Server Error")
+    client_response.headers["content-type"].should eq("text/plain")
+    client_response.headers.has_key?("content-length").should be_true
+    client_response.body.should eq("500 Internal Server Error\n")
+
+    match_logs(logs,
+      {:error, "Unhandled exception on HTTP::Handler", exception}
+    )
+  end
+
+  it "doesn't respond with error when headers were already sent" do
+    processor = HTTP::Server::RequestProcessor.new do |context|
+      context.response.content_type = "text/plain"
+      context.response.print "Hello world"
+      context.response.flush
+      raise "OH NO"
+    end
+    input = IO::Memory.new("GET / HTTP/1.1\r\n\r\n")
+    output = IO::Memory.new
+    processor.process(input, output)
+
+    client_response = HTTP::Client::Response.from_io(output.rewind)
+    client_response.status_code.should eq(200)
+    client_response.body.should eq("Hello world")
+  end
+
+  it "flushes output buffer when an error happens and some content was already sent" do
+    processor = HTTP::Server::RequestProcessor.new do |context|
+      context.response.content_type = "text/plain"
+      context.response.print "Hello "
+      context.response.flush
+      context.response.print "world"
+      raise "OH NO"
+    end
+    input = IO::Memory.new("GET / HTTP/1.1\r\n\r\n")
+    output = IO::Memory.new
+    processor.process(input, output)
+
+    client_response = HTTP::Client::Response.from_io(output.rewind)
+    client_response.status_code.should eq(200)
+    client_response.body.should eq("Hello world")
   end
 end

spec/std/http/server/response_spec.cr

@@ -214,5 +214,16 @@ describe HTTP::Server::Response do
       response.respond_with_status(HTTP::Status::URI_TOO_LONG, "Request Error")
       io.to_s.should eq("HTTP/1.1 414 Request Error\r\nContent-Type: text/plain\r\nContent-Length: 18\r\n\r\n414 Request Error\n")
     end
+
+    it "closes when it fails to write" do
+      io = IO::Memory.new
+      response = Response.new(io)
+      response.print("Hello")
+      response.flush
+      io.close
+      response.print("Hello")
+      expect_raises(HTTP::Server::ClientError) { response.flush }
+      response.closed?.should be_true
+    end
   end
 end

spec/support/io.cr

@@ -0,0 +1,19 @@
+class RaiseIOError < IO
+  getter writes = 0
+
+  def initialize(@raise_on_write = false)
+  end
+
+  def read(slice : Bytes)
+    raise IO::Error.new("...")
+  end
+
+  def write(slice : Bytes) : Nil
+    @writes += 1
+    raise IO::Error.new("...") if @raise_on_write
+  end
+
+  def flush
+    raise IO::Error.new("...")
+  end
+end