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.

Sign up for GitHub

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

Jump to bottom

Add log level error #16

Merged
merged 3 commits into from
Sep 7, 2020
Merged

Add log level error #16

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
92f16ea
Add log level error
sabaraouf Aug 24, 2020
3e74933
fix test
sabaraouf Aug 24, 2020
f1219d5
upcase log level ERROR
sabaraouf Aug 27, 2020
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
5 changes: 5 additions & 0 deletions lib/kiev/logger.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,8 @@ class Logger
def_delegators(*([:@logger] + ::Logger.instance_methods(false)))

DEFAULT_EVENT_NAME = "log"
LOG_ERROR = "ERROR"
ERROR_STATUS = 500

FORMATTER = proc do |severity, time, event_name, data|
entry =
Expand Down Expand Up @@ -54,8 +56,11 @@ class Logger
entry.merge!(data)
elsif !data.nil?
entry[:message] = data.to_s
entry[:status] = ERROR_STATUS if data.to_s.downcase.include?(LOG_ERROR)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a rather weak condition, as it's entirely possible to get a log body with a word error over the course of a successful request.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tested with different scenarios and it comes in the else statement only in case of an error. I haven't found any success case that was in the else statement.

end

entry[:level] = LOG_ERROR if entry[:status].to_i.between?(400, 599)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This formatter should not be coupled to HTTP, as it is also used in background jobs that do not adhere to HTTP's statuses.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, log level is already passed in from the outside as severity, why does this need to be set here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, log level is already passed in from the outside as severity, why does this need to be set here?

Log level that is passed from the outside, sets the log level at app level e.g.

module Severity
    # Low-level information, mostly for developers.
    DEBUG = 0
    # Generic (useful) information about system operation.
    INFO = 1
    # A warning.
    WARN = 2
    # A handleable error condition.
    ERROR = 3
    # An unhandleable error that results in a program crash.
    FATAL = 4
    # An unknown message that should always be logged.
    UNKNOWN = 5
  end

I need to set the level as in string so it can be filtered in datadog logs.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This formatter should not be coupled to HTTP, as it is also used in background jobs that do not adhere to HTTP's statuses.

For this reason, I custom set the status https://github.com/blacklane/kiev/pull/16/files#diff-65ff7abd2edd51bd17339cf140e85b2eR59 so if it is not HTTP, it can still set level error, maybe not optimal, I'm open for suggestions.


# Save some disk space
entry.reject! { |_, value| value.nil? }

Expand Down
2 changes: 2 additions & 0 deletions lib/kiev/que/job.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ def _run
private

NEW_LINE = "\n"
LOG_ERROR = "ERROR"

def kiev_run
args = attrs[:args]
Expand Down Expand Up @@ -69,6 +70,7 @@ def kiev_run
data[:error_class] = error.class.name
data[:error_message] = error.message[0..5000]
data[:error_backtrace] = Array(error.backtrace).join(NEW_LINE)[0..5000]
data[:level] = LOG_ERROR
end

Kiev.event(:job_finished, data)
Expand Down
4 changes: 4 additions & 0 deletions lib/kiev/rack/request_logger.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ class RequestLogger
ERROR_STATUS = 500
ERROR_HEADERS = [].freeze
ERROR_BODY = [""].freeze
LOG_ERROR = "ERROR"

def initialize(app)
@app = app
Expand Down Expand Up @@ -96,6 +97,8 @@ def form_data(request:, began_at:, status:, env:, body:, response:, exception:)
route: extract_route(env)
}

data[:level] = LOG_ERROR if data[:status].to_i.between?(400, 599)

if env[HTTP_X_REQUEST_START]
data[:request_latency] = ((began_at - env[HTTP_X_REQUEST_START].to_f) * 1000).round(3)
end
Expand Down Expand Up @@ -133,6 +136,7 @@ def form_data(request:, began_at:, status:, env:, body:, response:, exception:)
data[:error_class] = exception.class.name
data[:error_message] = exception.message[0..5000]
data[:error_backtrace] = Array(exception.backtrace).join(NEW_LINE)[0..5000]
data[:level] = LOG_ERROR
end
data
end
Expand Down
2 changes: 2 additions & 0 deletions lib/kiev/request_logger.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ module Kiev
module RequestLogger
module Mixin
NEW_LINE = "\n"
LOG_ERROR = "ERROR"

def wrap_request_logger(event, **data, &_block)
began_at = Time.now
Expand All @@ -21,6 +22,7 @@ def wrap_request_logger(event, **data, &_block)
data[:error_class] = error.class.name
data[:error_message] = error.message[0..5000]
data[:error_backtrace] = Array(error.backtrace).join(NEW_LINE)[0..5000]
data[:level] = LOG_ERROR
end

Kiev.event(event, data)
Expand Down
2 changes: 1 addition & 1 deletion spec/lib/kiev/que/job_spec.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,7 @@ def run(*argument)
expect(log_first["application"]).to eq("test_app")
expect(log_first["event"]).to eq("job_finished")
expect(log_first["job_name"]).to eq("ErrorJob")
expect(log_first["level"]).to eq("INFO")
expect(log_first["level"]).to eq("error")
expect(log_first["params"]).to eq("[\"Hello world!\"]")
expect(log_first["request_depth"]).to eq(1)
expect(log_first["request_id"]).to eq("test")
Expand Down
14 changes: 7 additions & 7 deletions spec/lib/kiev/rack/request_logger_spec.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,15 +70,15 @@ def request_finished(options = {})
context "html" do
let(:rack_app) { proc { [401, { "Content-Type" => "text/html" }, "body"] } }
it "does not log body" do
expect(subject).to have_received(:event).with(*request_finished(status: 401))
expect(subject).to have_received(:event).with(*request_finished(status: 401, level: "error"))
end
end

context "json" do
let(:rack_app) { proc { [401, { "Content-Type" => "application/json" }, ["{\"secret\":\"not filtered\"}"]] } }
it "logs body" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 401, body: "{\"secret\":\"not filtered\"}"))
.with(*request_finished(status: 401, body: "{\"secret\":\"not filtered\"}", level: "error"))
end
end

Expand All @@ -88,7 +88,7 @@ def request_finished(options = {})
end
it "logs body" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 401, body: "<xml><secret>not filtered</secret></xml>"))
.with(*request_finished(status: 401, body: "<xml><secret>not filtered</secret></xml>", level: "error"))
end
end
end
Expand All @@ -98,7 +98,7 @@ def request_finished(options = {})
let(:rack_app) { proc { [404, { "Content-Type": "text/html" }, "body"] } }
it "does not log body" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 404))
.with(*request_finished(status: 404, level: "error"))
end
end

Expand All @@ -107,7 +107,7 @@ def request_finished(options = {})
let(:rack_app) { proc { [404, { "Content-Type" => "application/json" }, [payload]] } }
it "logs body" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 404, body: payload))
.with(*request_finished(status: 404, body: payload, level: "error"))
end
end
end
Expand All @@ -129,7 +129,7 @@ def request_finished(options = {})
}
it "logs body" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 404, body: raw_payload))
.with(*request_finished(status: 404, body: raw_payload, level: "error"))
end
end

Expand All @@ -142,7 +142,7 @@ def request_finished(options = {})
}
it "logs gzip pars error" do
expect(subject).to have_received(:event)
.with(*request_finished(status: 404, body: raw_payload, gzip_parse_error: "not in gzip format"))
.with(*request_finished(status: 404, body: raw_payload, gzip_parse_error: "not in gzip format", level: "error"))
end
end
end
Expand Down