summaryrefslogtreecommitdiff
path: root/lib
diff options
context:
space:
mode:
authorStan Hu <stanhu@gmail.com>2018-04-01 00:46:52 -0700
committerStan Hu <stanhu@gmail.com>2018-04-04 05:04:00 -0700
commit6415ac9e994640474eaa5b0fee3914934d85b35b (patch)
tree2640006fbc3745039799bb76bf8a654f5ce592c0 /lib
parenteaed588bf228c833cb666a61bc7d25cf21d5f94b (diff)
downloadgitlab-ce-6415ac9e994640474eaa5b0fee3914934d85b35b.tar.gz
Add support for Sidekiq JSON logging
Closes #20060
Diffstat (limited to 'lib')
-rw-r--r--lib/gitlab/sidekiq_logging/json_formatter.rb21
-rw-r--r--lib/gitlab/sidekiq_logging/structured_logger.rb96
2 files changed, 117 insertions, 0 deletions
diff --git a/lib/gitlab/sidekiq_logging/json_formatter.rb b/lib/gitlab/sidekiq_logging/json_formatter.rb
new file mode 100644
index 00000000000..98f8222fd03
--- /dev/null
+++ b/lib/gitlab/sidekiq_logging/json_formatter.rb
@@ -0,0 +1,21 @@
+module Gitlab
+ module SidekiqLogging
+ class JSONFormatter
+ def call(severity, timestamp, progname, data)
+ output = {
+ severity: severity,
+ time: timestamp.utc.iso8601(3)
+ }
+
+ case data
+ when String
+ output[:message] = data
+ when Hash
+ output.merge!(data)
+ end
+
+ output.to_json + "\n"
+ end
+ end
+ end
+end
diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb
new file mode 100644
index 00000000000..9a89ae70b98
--- /dev/null
+++ b/lib/gitlab/sidekiq_logging/structured_logger.rb
@@ -0,0 +1,96 @@
+module Gitlab
+ module SidekiqLogging
+ class StructuredLogger
+ START_TIMESTAMP_FIELDS = %w[created_at enqueued_at].freeze
+ DONE_TIMESTAMP_FIELDS = %w[started_at retried_at failed_at completed_at].freeze
+
+ def call(job, queue)
+ started_at = current_time
+ base_payload = parse_job(job)
+
+ Sidekiq.logger.info log_job_start(started_at, base_payload)
+
+ yield
+
+ Sidekiq.logger.info log_job_done(started_at, base_payload)
+ rescue => job_exception
+ Sidekiq.logger.warn log_job_done(started_at, base_payload, job_exception)
+
+ raise
+ end
+
+ private
+
+ def base_message(payload)
+ "#{payload['class']} JID-#{payload['jid']}"
+ end
+
+ def log_job_start(started_at, payload)
+ payload['message'] = "#{base_message(payload)}: start"
+ payload['job_status'] = 'start'
+
+ payload
+ end
+
+ def log_job_done(started_at, payload, job_exception = nil)
+ payload = payload.dup
+ payload['duration'] = elapsed(started_at)
+ payload['completed_at'] = Time.now.utc
+
+ message = base_message(payload)
+
+ if job_exception
+ payload['message'] = "#{message}: fail: #{payload['duration']} sec"
+ payload['job_status'] = 'fail'
+ payload['error_message'] = job_exception.message
+ payload['error'] = job_exception.class
+ payload['error_backtrace'] = backtrace_cleaner.clean(job_exception.backtrace)
+ else
+ payload['message'] = "#{message}: done: #{payload['duration']} sec"
+ payload['job_status'] = 'done'
+ end
+
+ convert_to_iso8601(payload, DONE_TIMESTAMP_FIELDS)
+
+ payload
+ end
+
+ def parse_job(job)
+ job = job.dup
+
+ # Add process id params
+ job['pid'] = ::Process.pid
+
+ job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
+
+ convert_to_iso8601(job, START_TIMESTAMP_FIELDS)
+
+ job
+ end
+
+ def convert_to_iso8601(payload, keys)
+ keys.each do |key|
+ payload[key] = format_time(payload[key]) if payload[key]
+ end
+ end
+
+ def elapsed(start)
+ (current_time - start).round(3)
+ end
+
+ def current_time
+ Gitlab::Metrics::System.monotonic_time
+ end
+
+ def backtrace_cleaner
+ @backtrace_cleaner ||= ActiveSupport::BacktraceCleaner.new
+ end
+
+ def format_time(timestamp)
+ return timestamp if timestamp.is_a?(String)
+
+ Time.at(timestamp).utc.iso8601(3)
+ end
+ end
+ end
+end