Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Adding new Event to track when a request is complete #1601

Merged
merged 1 commit into from
Nov 1, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 14 additions & 0 deletions spec/lucky/log_handler_spec.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
6 changes: 6 additions & 0 deletions src/lucky/events/request_complete_event.cr
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
class Lucky::Events::RequestCompleteEvent < Pulsar::Event
getter :duration

def initialize(@duration : Time::Span)
end
end
22 changes: 15 additions & 7 deletions src/lucky/log_handler.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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,
Expand Down