#255 - Improve and extend development log entries

spec/marten/conf/global_settings_spec.cr

@@ -177,6 +177,19 @@ describe Marten::Conf::GlobalSettings do
     end
   end
 
+  describe "#debug?" do
+    it "returns false by default" do
+      global_settings = Marten::Conf::GlobalSettings.new
+      global_settings.debug?.should be_false
+    end
+
+    it "returns true if debug mode is enabled" do
+      global_settings = Marten::Conf::GlobalSettings.new
+      global_settings.debug = true
+      global_settings.debug?.should be_true
+    end
+  end
+
   describe "#debug=" do
     it "allows to enable or disable the debug mode" do
       global_settings = Marten::Conf::GlobalSettings.new
@@ -251,6 +264,50 @@ describe Marten::Conf::GlobalSettings do
       global_settings.log_backend.should be_a ::Log::IOBackend
     end
 
+    it "sets the expected IOBackend formatter in debug mode" do
+      global_settings = Marten::Conf::GlobalSettings.new
+      global_settings.debug = true
+
+      io = IO::Memory.new
+
+      global_settings.log_backend.as(Log::IOBackend).formatter.format(
+        Log::Entry.new(
+          source: "test",
+          severity: Log::Severity::Info,
+          message: "This is a test",
+          data: Log::Metadata.empty,
+          exception: nil,
+        ),
+        io: io,
+      )
+
+      io.rewind.gets_to_end.should eq "This is a test"
+    end
+
+    it "sets the expected IOBackend formatter in non-debug mode" do
+      global_settings = Marten::Conf::GlobalSettings.new
+      global_settings.debug = false
+
+      dt = Time.local
+
+      Timecop.freeze(Time.local) do
+        io = IO::Memory.new
+
+        global_settings.log_backend.as(Log::IOBackend).formatter.format(
+          Log::Entry.new(
+            source: "test",
+            severity: Log::Severity::Info,
+            message: "This is a test",
+            data: Log::Metadata.empty,
+            exception: nil,
+          ),
+          io: io,
+        )
+
+        io.rewind.gets_to_end.should eq "[I] [#{dt.to_utc}] [Server] This is a test"
+      end
+    end
+
     it "returns the configured log backend if explicitely set" do
       global_settings = Marten::Conf::GlobalSettings.new
       global_settings.log_backend = ::Log::MemoryBackend.new

spec/marten/core/debug_mode_loggable_spec.cr

@@ -0,0 +1,47 @@
+require "./spec_helper"
+
+describe Marten::Core::DebugModeLoggable do
+  describe "::debug_mode_debug_log" do
+    it "logs a debug message when the debug mode is enabled" do
+      Log.capture do |logs|
+        with_overridden_setting("debug", true) do
+          Marten::Core::DebugModeLoggable.debug_mode_debug_log("Test message")
+        end
+
+        logs.check(:debug, /Test message/)
+      end
+    end
+
+    it "does not log a debug message when the debug mode is not enabled" do
+      Log.capture do |logs|
+        with_overridden_setting("debug", false) do
+          Marten::Core::DebugModeLoggable.debug_mode_debug_log("Test message")
+        end
+
+        logs.empty
+      end
+    end
+  end
+
+  describe "::debug_mode_info_log" do
+    it "logs an info message when the debug mode is enabled" do
+      Log.capture do |logs|
+        with_overridden_setting("debug", true) do
+          Marten::Core::DebugModeLoggable.debug_mode_info_log("Test message")
+        end
+
+        logs.check(:info, /Test message/)
+      end
+    end
+
+    it "does not log an info message when the debug mode is not enabled" do
+      Log.capture do |logs|
+        with_overridden_setting("debug", false) do
+          Marten::Core::DebugModeLoggable.debug_mode_info_log("Test message")
+        end
+
+        logs.empty
+      end
+    end
+  end
+end

spec/marten/handlers/base_spec.cr

@@ -959,6 +959,29 @@ describe Marten::Handlers::Base do
       response.content_type.should eq "text/plain"
       response.content.strip.should eq "Hello World, John Doe!"
     end
+
+    it "logs an entry indicating the rendered template in debug mode" do
+      request = Marten::HTTP::Request.new(
+        ::HTTP::Request.new(
+          method: "GET",
+          resource: "",
+          headers: HTTP::Headers{"Host" => "example.com"}
+        )
+      )
+
+      handler = Marten::Handlers::BaseSpec::Test5Handler.new(request)
+
+      with_overridden_setting("debug", true) do
+        Log.capture do |logs|
+          handler.render(
+            "specs/handlers/base/test.html",
+            context: Marten::Template::Context{"name" => "John Doe"}
+          )
+
+          logs.check(:info, /Rendering template: specs\/handlers\/base\/test.html/)
+        end
+      end
+    end
   end
 
   describe "#respond" do

spec/marten/server/handlers/debug_logger_spec.cr

@@ -0,0 +1,92 @@
+require "./spec_helper"
+
+describe Marten::Server::Handlers::DebugLogger do
+  describe "#call" do
+    it "generates the expected log entries before and after the request completion" do
+      output_io = IO::Memory.new
+
+      ctx = HTTP::Server::Context.new(
+        request: ::HTTP::Request.new(
+          method: "GET",
+          resource: "/foo/bar",
+          headers: HTTP::Headers{"Host" => "example.com", "Accept-Language" => "FR,en;q=0.5"}
+        ),
+        response: ::HTTP::Server::Response.new(io: IO::Memory.new)
+      )
+
+      handler = Marten::Server::Handlers::DebugLogger.new
+      handler.next = HTTP::Handler::HandlerProc.new do |handler_ctx|
+        handler_ctx.response.output = output_io
+        handler_ctx.response.print("It works")
+      end
+
+      Log.capture do |logs|
+        with_overridden_setting("debug", true) do
+          handler.call(ctx)
+        end
+
+        logs.check(:info, /Started \"GET \/foo\/bar\"/i)
+        logs.next(:info, /Completed with \"200\"/i)
+      end
+    end
+
+    it "generates additional log entries when data is present" do
+      output_io = IO::Memory.new
+
+      ctx = HTTP::Server::Context.new(
+        request: ::HTTP::Request.new(
+          method: "GET",
+          resource: "/foo/bar",
+          headers: HTTP::Headers{"Host" => "example.com", "Content-Type" => "application/x-www-form-urlencoded"},
+          body: "foo=bar&test=xyz"
+        ),
+        response: ::HTTP::Server::Response.new(io: IO::Memory.new)
+      )
+
+      handler = Marten::Server::Handlers::DebugLogger.new
+      handler.next = HTTP::Handler::HandlerProc.new do |handler_ctx|
+        handler_ctx.response.output = output_io
+        handler_ctx.response.print("It works")
+      end
+
+      Log.capture do |logs|
+        with_overridden_setting("debug", true) do
+          handler.call(ctx)
+        end
+
+        logs.check(:info, /Started \"GET \/foo\/bar\"/i)
+        logs.next(:info, /Data: {\"foo\" => \[\"bar\"\], \"test\" => \[\"xyz\"\]}/i)
+        logs.next(:info, /Completed with \"200\"/i)
+      end
+    end
+
+    it "generates additional log entries when query params are present" do
+      output_io = IO::Memory.new
+
+      ctx = HTTP::Server::Context.new(
+        request: ::HTTP::Request.new(
+          method: "GET",
+          resource: "/foo/bar?foo=bar&test=xyz",
+          headers: HTTP::Headers{"Host" => "example.com"},
+        ),
+        response: ::HTTP::Server::Response.new(io: IO::Memory.new)
+      )
+
+      handler = Marten::Server::Handlers::DebugLogger.new
+      handler.next = HTTP::Handler::HandlerProc.new do |handler_ctx|
+        handler_ctx.response.output = output_io
+        handler_ctx.response.print("It works")
+      end
+
+      Log.capture do |logs|
+        with_overridden_setting("debug", true) do
+          handler.call(ctx)
+        end
+
+        logs.check(:info, /Started \"GET \/foo\/bar\"/i)
+        logs.next(:info, /Query params: {\"foo\" => \[\"bar\"\], \"test\" => \[\"xyz\"\]}/i)
+        logs.next(:info, /Completed with \"200\"/i)
+      end
+    end
+  end
+end

spec/marten/server/handlers/routing_spec.cr

@@ -36,6 +36,29 @@ describe Marten::Server::Handlers::Routing do
       context.marten.response.not_nil!.content.should eq "It works!"
     end
 
+    it "logs an entry indicating the matched handler in debug mode" do
+      handler = Marten::Server::Handlers::Routing.new
+
+      context = HTTP::Server::Context.new(
+        request: ::HTTP::Request.new(
+          method: "GET",
+          resource: "/dummy",
+          headers: HTTP::Headers{"Host" => "example.com", "Accept-Language" => "FR,en;q=0.5"}
+        ),
+        response: ::HTTP::Server::Response.new(io: IO::Memory.new)
+      )
+
+      with_overridden_setting("debug", true) do
+        Log.capture do |logs|
+          handler.call(context)
+
+          logs.check(:info, /Routed to: DummyHandler/i)
+        end
+
+        context.marten.response.not_nil!.content.should eq "It works!"
+      end
+    end
+
     context "with the trailing_slash setting set to do_nothing" do
       it "raises Marten::Routing::Errors::NoResolveMatch if the requested route cannot be resolved" do
         handler = Marten::Server::Handlers::Routing.new

spec/marten/server_spec.cr

@@ -0,0 +1,29 @@
+require "./spec_helper"
+
+describe Marten::Server do
+  describe "#handlers" do
+    it "returns the expected handlers in non-debug mode" do
+      with_overridden_setting("debug", false) do
+        Marten::Server.handlers.size.should eq 5
+
+        Marten::Server.handlers[0].should be_a HTTP::ErrorHandler
+        Marten::Server.handlers[1].should be_a Marten::Server::Handlers::Logger
+        Marten::Server.handlers[2].should be_a Marten::Server::Handlers::Error
+        Marten::Server.handlers[3].should be_a Marten::Server::Handlers::Middleware
+        Marten::Server.handlers[4].should be_a Marten::Server::Handlers::Routing
+      end
+    end
+
+    it "returns the expected handlers in debug mode" do
+      with_overridden_setting("debug", true) do
+        Marten::Server.handlers.size.should eq 5
+
+        Marten::Server.handlers[0].should be_a HTTP::ErrorHandler
+        Marten::Server.handlers[1].should be_a Marten::Server::Handlers::DebugLogger
+        Marten::Server.handlers[2].should be_a Marten::Server::Handlers::Error
+        Marten::Server.handlers[3].should be_a Marten::Server::Handlers::Middleware
+        Marten::Server.handlers[4].should be_a Marten::Server::Handlers::Routing
+      end
+    end
+  end
+end

spec/spec_helper.cr

@@ -1,6 +1,7 @@
 ENV["MARTEN_ENV"] = "test"
 
 require "json"
+require "log/spec"
 require "spec"
 require "timecop"
 

src/marten/conf/global_settings.cr

@@ -9,7 +9,7 @@ module Marten
       @handler403 : Handlers::Base.class
       @handler404 : Handlers::Base.class
       @handler500 : Handlers::Base.class
-      @log_backend : ::Log::Backend
+      @log_backend : ::Log::Backend | Nil
       @request_max_parameters : Nil | Int32
       @root_path : String?
       @target_env : String?
@@ -27,6 +27,9 @@ module Marten
       # Returns a boolean indicating whether the application runs in debug mode.
       getter debug
 
+      # :ditto:
+      getter? debug
+
       # Returns the configured handler class that should generate responses for Bad Request responses (HTTP 400).
       getter handler400
 
@@ -45,9 +48,6 @@ module Marten
       # Returns the third-party applications used by the project.
       getter installed_apps
 
-      # Returns the log backend used by the application.
-      getter log_backend
-
       # The default log level used by the application.
       getter log_level
 
@@ -194,18 +194,6 @@ module Marten
         @handler500 = Handlers::Defaults::ServerError
         @host = "127.0.0.1"
         @installed_apps = Array(Marten::Apps::Config.class).new
-        @log_backend = ::Log::IOBackend.new(
-          formatter: ::Log::Formatter.new do |entry, io|
-            io << "[#{entry.severity.to_s[0]}] "
-            io << "[#{entry.timestamp.to_utc}] "
-            io << "[Server] "
-            io << entry.message
-
-            entry.data.each do |k, v|
-              io << "\n  #{k}: #{v}"
-            end
-          end
-        )
         @log_level = ::Log::Severity::Info
         @middleware = Array(Marten::Middleware.class).new
         @port = 8000
@@ -271,6 +259,30 @@ module Marten
         @installed_apps.concat(v)
       end
 
+      # Returns the log backend used by the application.
+      def log_backend
+        @log_backend ||= if debug?
+                           ::Log::IOBackend.new(
+                             formatter: ::Log::Formatter.new do |entry, io|
+                               io << entry.message
+                             end
+                           )
+                         else
+                           ::Log::IOBackend.new(
+                             formatter: ::Log::Formatter.new do |entry, io|
+                               io << "[#{entry.severity.to_s[0]}] "
+                               io << "[#{entry.timestamp.to_utc}] "
+                               io << "[Server] "
+                               io << entry.message
+
+                               entry.data.each do |k, v|
+                                 io << "\n  #{k}: #{v}"
+                               end
+                             end
+                           )
+                         end
+      end
+
       # Allows to set the log backend used by the application.
       def log_backend=(log_backend : ::Log::Backend)
         @log_backend = log_backend