Adding new Event to track when a request is complete. Refactor the Lo…

…gHandler to use Time.measure. (#1601)

spec/lucky/log_handler_spec.cr

@@ -42,6 +42,20 @@ describe Lucky::LogHandler do
     log_output = log_io.to_s
     log_output.should contain("an error")
   end
+
+  it "publishes the request_complete_event" do
+    Lucky::Events::RequestCompleteEvent.subscribe do |event|
+      event.duration.should_not be_nil
+    end
+
+    called = false
+    log_io = IO::Memory.new
+    context = build_context_with_io(log_io)
+
+    call_log_handler_with(log_io, context) { called = true }
+
+    called.should be_true
+  end
 end
 
 private def call_log_handler_with(io : IO, context : HTTP::Server::Context, &block)

src/lucky/events/request_complete_event.cr

@@ -0,0 +1,6 @@
+class Lucky::Events::RequestCompleteEvent < Pulsar::Event
+  getter :duration
+
+  def initialize(@duration : Time::Span)
+  end
+end

src/lucky/log_handler.cr

@@ -21,18 +21,26 @@ class Lucky::LogHandler
   delegate logger, to: Lucky
 
   def call(context)
-    start = Time.monotonic
-    should_skip = settings.skip_if.try &.call(context)
+    should_skip_logging = settings.skip_if.try &.call(context)
 
-    log_request_start(context) unless should_skip
-    call_next(context)
-    log_request_end(context, duration: Time.monotonic - start) unless should_skip
+    if should_skip_logging
+      call_next(context)
+    else
+      log_request_start(context)
+
+      duration = Time.measure do
+        call_next(context)
+      end
+
+      log_request_end(context, duration: duration)
+      Lucky::Events::RequestCompleteEvent.publish(duration)
+    end
   rescue e
     log_exception(context, Time.utc, e)
     raise e
   end
 
-  private def log_request_start(context) : Nil
+  private def log_request_start(context : HTTP::Server::Context) : Nil
     Lucky::Log.dexter.info do
       {
         REQUEST_START_KEYS[:method] => context.request.method,
@@ -41,7 +49,7 @@ class Lucky::LogHandler
     end
   end
 
-  private def log_request_end(context, duration) : Nil
+  private def log_request_end(context : HTTP::Server::Context, duration : Time::Span) : Nil
     Lucky::Log.dexter.info do
       {
         REQUEST_END_KEYS[:status]   => context.response.status_code,