Embrace Crystal standard Log for logging. (#705)

* Embrace Crystal standard Log for logging.

Kemal uses a LogHandler to log requests, this code predates the
Crystal Log class so while the Kemal documentation says that logging is
done using Log class, the http request log is done in a different way.

This patch deprecates:
- Kemal::Config#logger
- Kemal::Config#logger=(Kemal::BaseLogHandler)
- log(String)
- Kemal::LogHandler.initialize(IO)
- NullLogHandler

and changes:

- Add Kemal::Log (Log = ::Log.for(self))
- Kemal::LogHandler now uses Log.
- No handler is created if logging is set to false.

Old code using custom log handlers must work as before.

* Let ExceptionHandler use Log instead of log.

* Deprecate Kemal::LogHandler and adds Kemal::RequestLogHandler.

* Don't break API on Kemal#logger.

* Add test for Kemal::RequestLogHandler.

* Do not log redundant informations like timestamp and exception message.

* Use ex.message on unexpected exceptions log message.

Author: hugopl

spec/config_spec.cr

@@ -29,7 +29,7 @@ describe "Config" do
     config = Kemal.config
     config.add_handler CustomTestHandler.new
     Kemal.config.setup
-    config.handlers.size.should eq(8)
+    config.handlers.size.should eq(7)
   end
 
   it "toggles the shutdown message" do

spec/helpers_spec.cr

@@ -13,7 +13,7 @@ describe "Macros" do
     it "adds a custom handler" do
       add_handler CustomTestHandler.new
       Kemal.config.setup
-      Kemal.config.handlers.size.should eq 8
+      Kemal.config.handlers.size.should eq 7
     end
   end
 
@@ -151,7 +151,7 @@ describe "Macros" do
     it "adds HTTP::CompressHandler to handlers" do
       gzip true
       Kemal.config.setup
-      Kemal.config.handlers[5].should be_a(HTTP::CompressHandler)
+      Kemal.config.handlers[4].should be_a(HTTP::CompressHandler)
     end
   end
 

spec/log_handler_spec.cr

@@ -1,13 +1,6 @@
 require "./spec_helper"
 
 describe "Kemal::LogHandler" do
-  it "logs to the given IO" do
-    io = IO::Memory.new
-    logger = Kemal::LogHandler.new io
-    logger.write "Something"
-    io.to_s.should eq "Something"
-  end
-
   it "creates log message for each request" do
     request = HTTP::Request.new("GET", "/")
     io = IO::Memory.new

spec/request_log_handler_spec.cr

@@ -0,0 +1,17 @@
+require "log/spec"
+require "./spec_helper"
+
+describe Kemal::RequestLogHandler do
+  it "creates log message for each request" do
+    Log.setup(:none)
+
+    request = HTTP::Request.new("GET", "/")
+    response = HTTP::Server::Response.new(IO::Memory.new)
+    context = HTTP::Server::Context.new(request, response)
+    logger = Kemal::RequestLogHandler.new
+    Log.capture do |logs|
+      logger.call(context)
+      logs.check(:info, /404 GET \/ \d+.*s/)
+    end
+  end
+end

src/kemal.cr

@@ -1,11 +1,14 @@
 require "http"
 require "json"
+require "log"
 require "uri"
 require "./kemal/*"
 require "./kemal/ext/*"
 require "./kemal/helpers/*"
 
 module Kemal
+  Log = ::Log.for(self)
+
   # Overload of `self.run` with the default startup logging.
   def self.run(port : Int32?, args = ARGV, trap_signal : Bool = true)
     self.run(port, args, trap_signal) { }
@@ -68,9 +71,9 @@ module Kemal
   def self.display_startup_message(config, server)
     if config.env != "test"
       addresses = server.addresses.join ", " { |address| "#{config.scheme}://#{address}" }
-      log "[#{config.env}] #{config.app_name} is ready to lead at #{addresses}"
+      Log.info { "[#{config.env}] #{config.app_name} is ready to lead at #{addresses}" }
     else
-      log "[#{config.env}] #{config.app_name} is running in test mode. Server not listening"
+      Log.info { "[#{config.env}] #{config.app_name} is running in test mode. Server not listening" }
     end
   end
 
@@ -94,7 +97,7 @@ module Kemal
 
   private def self.setup_trap_signal
     Process.on_terminate do
-      log "#{Kemal.config.app_name} is going to take a rest!" if Kemal.config.shutdown_message
+      Log.info { "#{Kemal.config.app_name} is going to take a rest!" } if Kemal.config.shutdown_message
       Kemal.stop
       exit
     end

src/kemal/config.cr

@@ -45,10 +45,17 @@ module Kemal
       @handler_position = 0
     end
 
+    @[Deprecated("Use standard library Log")]
     def logger
-      @logger.not_nil!
+      @logger || NullLogHandler.new
     end
 
+    # :nodoc:
+    def logger?
+      @logger
+    end
+
+    @[Deprecated("Use standard library Log")]
     def logger=(logger : Kemal::BaseLogHandler)
       @logger = logger
     end
@@ -134,12 +141,11 @@ module Kemal
     end
 
     private def setup_log_handler
-      @logger ||= if @logging
-                    Kemal::LogHandler.new
-                  else
-                    Kemal::NullLogHandler.new
-                  end
-      HANDLERS.insert(@handler_position, @logger.not_nil!)
+      return unless @logging
+
+      log_handler = @logger || Kemal::RequestLogHandler.new
+
+      HANDLERS.insert(@handler_position, log_handler)
       @handler_position += 1
     end
 

src/kemal/exception_handler.cr

@@ -21,7 +21,7 @@ module Kemal
         end
       end
 
-      log("Exception: #{ex.inspect_with_backtrace}")
+      Log.error(exception: ex) { ex.message }
       # Else use generic 500 handler if defined
       return call_exception_with_status_code(context, ex, 500) if Kemal.config.error_handlers.has_key?(500)
       verbosity = Kemal.config.env == "production" ? false : true

src/kemal/helpers/helpers.cr

@@ -32,8 +32,14 @@ end
 
 # Logs the output via `logger`.
 # This is the built-in `Kemal::LogHandler` by default which uses STDOUT.
+@[Deprecated("Use standard library Log")]
 def log(message : String)
-  Kemal.config.logger.write "#{message}\n"
+  logger = Kemal.config.logger?
+  if logger
+    logger.write "#{message}\n"
+  else
+    Log.info { message }
+  end
 end
 
 # Enables / Disables logging.
@@ -70,6 +76,7 @@ end
 # ```
 # logger MyCustomLogger.new
 # ```
+@[Deprecated("Use standard library Log")]
 def logger(logger : Kemal::BaseLogHandler)
   Kemal.config.logger = logger
 end

src/kemal/log_handler.cr

@@ -1,5 +1,6 @@
 module Kemal
   # Uses `STDOUT` by default and handles the logging of request/response process time.
+  @[Deprecated("Setup Log instead.")]
   class LogHandler < Kemal::BaseLogHandler
     def initialize(@io : IO = STDOUT)
     end

src/kemal/null_log_handler.cr

@@ -1,5 +1,6 @@
 module Kemal
   # This is here to represent the logger corresponding to Null Object Pattern.
+  @[Deprecated("Use standard library Log")]
   class NullLogHandler < Kemal::BaseLogHandler
     def call(context : HTTP::Server::Context)
       call_next(context)

src/kemal/request_log_handler.cr

@@ -0,0 +1,20 @@
+module Kemal
+  # :nodoc:
+  class RequestLogHandler
+    include HTTP::Handler
+
+    def call(context : HTTP::Server::Context)
+      elapsed_time = Time.measure { call_next(context) }
+      elapsed_text = elapsed_text(elapsed_time)
+      Log.info { "#{context.response.status_code} #{context.request.method} #{context.request.resource} #{elapsed_text}" }
+      context
+    end
+
+    private def elapsed_text(elapsed)
+      millis = elapsed.total_milliseconds
+      return "#{millis.round(2)}ms" if millis >= 1
+
+      "#{(millis * 1000).round(2)}µs"
+    end
+  end
+end