kotovalexarian-likes-github/mperham--sidekiq
1
0
Fork 0
mirror of https://github.com/mperham/sidekiq.git synced 2022-11-09 13:52:34 -05:00
Code Releases Activity

Rework logger changes a bit

Browse source 
* logger_formatter -> log_format
* avoid touching global Sidekiq.logger in JobLogger
* rewrite tests for compactness and coverage
* hide banner in JSON
This commit is contained in:
Mike Perham 2018-12-29 07:54:05 -08:00
parent 3845832c20
commit 022c63d86f
10 changed files with 202 additions and 304 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
6.0-Upgrade.md
View file

@ -10,7 +10,7 @@ This release has major breaking changes. Read and test carefully in production.
- Include **new JSON log format** for use where you want machine-ingestible log output. Enable with:
```
Sidekiq.configure_server do |config|
config.logger_format = :json # or :default
config.log_format = :json # or nil for default
end
```
- **Remove the daemonization, logfile and pidfile command line arguments**.

2
lib/sidekiq.rb
View file

@ -179,7 +179,7 @@ module Sidekiq
end
class << self
attr_accessor :logger_formatter
attr_accessor :log_format
end
def self.logger

2
lib/sidekiq/cli.rb
View file

@ -42,7 +42,7 @@ module Sidekiq
# test coverage of Sidekiq::CLI are welcomed.
def run
boot_system
print_banner if environment == 'development' && $stdout.tty?
print_banner if environment == 'development' && $stdout.tty? && Sidekiq.log_format == nil
self_read, self_write = IO.pipe
sigs = %w(INT TERM TTIN TSTP)

22
lib/sidekiq/job_logger.rb
View file

@ -3,44 +3,48 @@
module Sidekiq
class JobLogger
def initialize(logger=Sidekiq.logger)
@logger = logger
end
def call(item, queue)
start = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
Sidekiq.logger.info("start")
@logger.info("start")
yield
with_elapsed_time_context(start) do
Sidekiq.logger.info("done")
@logger.info("done")
end
rescue Exception
with_elapsed_time_context(start) do
Sidekiq.logger.info("fail")
@logger.info("fail")
end
raise
end
def with_job_hash_context(job_hash, &block)
Sidekiq.logger.with_context(job_hash_context(job_hash), &block)
@logger.with_context(job_hash_context(job_hash), &block)
end
def job_hash_context(job_hash)
# If we're using a wrapper class, like ActiveJob, use the "wrapped"
# attribute to expose the underlying thing.
{
h = {
class: job_hash['wrapped'] || job_hash["class"],
jid: job_hash['jid'],
bid: job_hash['bid']
}
h[:bid] = job_hash['bid'] if job_hash['bid']
h
end
def with_elapsed_time_context(start, &block)
Sidekiq.logger.with_context(elapsed_time_context(start), &block)
@logger.with_context(elapsed_time_context(start), &block)
end
def elapsed_time_context(start)
{ elapsed: "#{elapsed(start)} sec" }
{ elapsed: "#{elapsed(start)}" }
end
private

55
lib/sidekiq/logger.rb
View file

@ -9,7 +9,7 @@ module Sidekiq
def initialize(*args)
super
formatter_class = case Sidekiq.logger_formatter
formatter_class = case Sidekiq.log_format
when :json
Formatters::JSON
else
@ -19,50 +19,57 @@ module Sidekiq
self.formatter = formatter_class.new
end
def tid
Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
def with_context(hash)
ctx.merge!(hash)
yield
ensure
hash.keys.each { |key| ctx.delete(key) }
end
def context
def ctx
Thread.current[:sidekiq_context] ||= {}
end
def with_context(hash)
context.merge!(hash)
yield
ensure
hash.keys.each { |key| context.delete(key) }
end
module Formatters
class Pretty < Logger::Formatter
def call(severity, time, program_name, message)
"#{time.utc.iso8601(3)} #{::Process.pid} TID-#{Sidekiq.logger.tid}#{format_context(Sidekiq.logger.context)} #{severity}: #{message}\n"
class Base < ::Logger::Formatter
def tid
Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
end
private
def ctx
Thread.current[:sidekiq_context] ||= {}
end
def format_context(context)
' ' + context.compact.map { |k, v| "#{k.upcase}=#{v}" }.join(' ') if context.any?
def format_context
' ' + ctx.compact.map { |k, v| "#{k}=#{v}" }.join(' ') if ctx.any?
end
end
class Pretty < Base
def call(severity, time, program_name, message)
"#{time.utc.iso8601(3)} pid=#{::Process.pid} tid=#{tid}#{format_context} #{severity}: #{message}\n"
end
end
class WithoutTimestamp < Pretty
def call(severity, time, program_name, message)
"#{::Process.pid} TID-#{Sidekiq.logger.tid}#{format_context(Sidekiq.logger.context)} #{severity}: #{message}\n"
"pid=#{::Process.pid} tid=#{tid}#{format_context} #{severity}: #{message}\n"
end
end
class JSON < Logger::Formatter
class JSON < Base
def call(severity, time, program_name, message)
Sidekiq.dump_json(
hash = {
ts: time.utc.iso8601(3),
pid: ::Process.pid,
tid: Sidekiq.logger.tid,
ctx: Sidekiq.logger.context,
sev: severity,
tid: tid,
lvl: severity,
msg: message
)
}
c = ctx
hash["ctx"] = c unless c.empty?
Sidekiq.dump_json(hash) << "\n"
end
end
end

3
lib/sidekiq/processor.rb
View file

@ -23,7 +23,6 @@ module Sidekiq
# to replace itself and exits.
#
class Processor
include Util
attr_reader :thread
@ -236,8 +235,6 @@ module Sidekiq
WORKER_STATE = SharedWorkerState.new
def stats(job_hash, queue)
tid = Sidekiq.logger.tid
WORKER_STATE.set(tid, {:queue => queue, :payload => job_hash, :run_at => Time.now.to_i })
begin

4
lib/sidekiq/util.rb
View file

@ -34,6 +34,10 @@ module Sidekiq
Sidekiq.redis(&block)
end
def tid
Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
end
def hostname
ENV['DYNO'] || Socket.gethostname
end

2
sidekiq.gemspec
View file

@ -12,7 +12,7 @@ Gem::Specification.new do |gem|
gem.files = `git ls-files | grep -Ev '^(test|myapp|examples)'`.split("\n")
gem.name = "sidekiq"
gem.version = Sidekiq::VERSION
gem.required_ruby_version = ">= 2.2.2"
gem.required_ruby_version = ">= 2.4.0"
gem.add_dependency 'redis', '>= 3.3.5', '< 5'
gem.add_dependency 'connection_pool', '~> 2.2', '>= 2.2.2'

94
test/test_job_logger.rb
View file

@ -4,53 +4,63 @@ require_relative 'helper'
require 'sidekiq/job_logger'
class TestJobLogger < Minitest::Test
describe Sidekiq::JobLogger do
subject { Sidekiq::JobLogger.new }
def setup
@old = Sidekiq.logger
@output = StringIO.new
@logger = Sidekiq::Logger.new(@output)
let(:logdev) { StringIO.new }
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
end
around do |test|
Sidekiq.stub :logger, Sidekiq::Logger.new(logdev) do
Sidekiq.logger.stub :tid, 'ouy7z76mx' do
Process.stub :pid, 4710 do
Time.stub :now, Time.utc(2020, 1, 1) do
test.call
end
end
end
end
def teardown
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
end
def test_pretty_output
jl = Sidekiq::JobLogger.new(@logger)
# pretty
p = @logger.formatter = Sidekiq::Logger::Formatters::Pretty.new
job = {"jid"=>"1234abc", "wrapped"=>"FooWorker", "class"=>"Wrapper"}
# this mocks what Processor does
jl.with_job_hash_context(job) do
jl.call(job, 'queue') {}
end
after do
Thread.current[:sidekiq_context] = nil
a, b = @output.string.lines
assert a
assert b
expected = /pid=#{$$} tid=#{p.tid} class=FooWorker jid=1234abc/
assert_match(expected, a)
assert_match(expected, b)
assert_match(/#{Time.now.utc.to_date}.+Z pid=#{$$} tid=#{p.tid} .+INFO: done/, b)
end
def test_json_output
# json
@logger.formatter = Sidekiq::Logger::Formatters::JSON.new
jl = Sidekiq::JobLogger.new(@logger)
job = {"jid"=>"1234abc", "wrapped"=>"Wrapper", "class"=>"FooWorker", "bid"=>"b-xyz"}
# this mocks what Processor does
jl.with_job_hash_context(job) do
jl.call(job, 'queue') {}
end
a, b = @output.string.lines
assert a
assert b
hsh = JSON.parse(a)
keys = hsh.keys.sort
assert_equal(["ctx", "lvl", "msg", "pid", "tid", "ts"], keys)
keys = hsh["ctx"].keys.sort
assert_equal(["bid", "class", "jid"], keys)
end
describe '#call' do
describe 'when pretty formatter' do
before do
Sidekiq.logger.formatter = Sidekiq::Logger::Formatters::Pretty.new
end
it 'logs elapsed time as context' do
subject.call('item', 'queue') {}
assert_match(/2020-01-01T00:00:00\.000Z 4710 TID-ouy7z76mx INFO: start/, logdev.string)
assert_match(/2020-01-01T00:00:00\.000Z 4710 TID-ouy7z76mx ELAPSED=.+ sec INFO: done/, logdev.string)
end
end
describe 'when json formatter' do
before do
Sidekiq.logger.formatter = Sidekiq::Logger::Formatters::JSON.new
end
it 'logs elapsed time as context' do
subject.call('item', 'queue') {}
assert_match(/ctx.+msg.+start/, logdev.string)
assert_match(/ctx.+elapsed.+sec.+msg.+done/, logdev.string)
end
end
end
def reset(io)
io.truncate(0)
io.rewind
end
end

320
test/test_logger.rb
View file

@ -4,232 +4,108 @@ require_relative 'helper'
require 'sidekiq/logger'
class TestLogger < Minitest::Test
describe Sidekiq::Logger do
let(:logdev) { StringIO.new }
def setup
@output = StringIO.new
@logger = Sidekiq::Logger.new(@output)
subject { Sidekiq::Logger.new(logdev) }
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
end
before do
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
def teardown
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
end
def test_format_selection
assert_kind_of Sidekiq::Logger::Formatters::Pretty, Sidekiq::Logger.new(STDOUT).formatter
begin
ENV['DYNO'] = 'dyno identifier'
assert_kind_of Sidekiq::Logger::Formatters::WithoutTimestamp, Sidekiq::Logger.new(STDOUT).formatter
ensure
ENV['DYNO'] = nil
end
after do
Thread.current[:sidekiq_context] = nil
Thread.current[:sidekiq_tid] = nil
end
describe 'initialization' do
describe 'formatter' do
subject { Sidekiq::Logger.new(logdev).formatter }
describe 'default formatter' do
it 'sets pretty formatter' do
assert_kind_of Sidekiq::Logger::Formatters::Pretty, subject
end
end
describe 'when DYNO env var is present' do
around do |test|
ENV['DYNO'] = 'dyno identifier'
test.call
ENV['DYNO'] = nil
end
it 'sets without timestamp formatter' do
assert_kind_of Sidekiq::Logger::Formatters::WithoutTimestamp, subject
end
end
describe 'when logger formatter :json' do
around do |test|
Sidekiq.stub :logger_formatter, :json do
test.call
end
end
it 'sets json formatter' do
assert_kind_of Sidekiq::Logger::Formatters::JSON, subject
end
end
end
end
describe '#tid' do
describe 'default' do
it 'returns formatted thread id' do
Thread.current.stub :object_id, 70286338772540 do
Process.stub :pid, 6363 do
assert_equal 'owx3jd7mv', subject.tid
end
end
end
end
describe 'memoization' do
before do
Thread.current[:sidekiq_tid] = 'abcdefjhi'
end
it 'current thread :sidekiq_tid attribute reference' do
Thread.current.stub :object_id, 70286338772540 do
Process.stub :pid, 6363 do
assert_equal 'abcdefjhi', subject.tid
end
end
end
end
end
describe '#context' do
describe 'default' do
it 'returns empty hash' do
assert_equal({}, subject.context)
end
end
describe 'memoization' do
before do
Thread.current[:sidekiq_context] = { a: 1 }
end
it 'returns current thread :sidekiq_context attribute reference' do
assert_equal({ a: 1 }, subject.context)
end
end
end
describe '#with_context' do
it 'adds context to the current thread' do
assert_equal({}, subject.context)
subject.with_context(a: 1) do
assert_equal({ a: 1 }, subject.context)
end
assert_equal({}, subject.context)
end
describe 'nested contexts' do
it 'adds multiple contexts to the current thread' do
assert_equal({}, subject.context)
subject.with_context(a: 1) do
assert_equal({ a: 1 }, subject.context)
subject.with_context(b: 2, c: 3) do
assert_equal({ a: 1, b: 2, c: 3 }, subject.context)
end
assert_equal({ a: 1 }, subject.context)
end
assert_equal({}, subject.context)
end
end
end
describe 'formatters' do
let(:severity) { 'INFO' }
let(:utc_time) { Time.utc(2020, 1, 1) }
let(:prg) { 'sidekiq' }
let(:msg) { 'Old pond frog jumps in sound of water' }
around do |test|
Process.stub :pid, 4710 do
Sidekiq.logger.stub :tid, 'ouy7z76mx' do
test.call
end
end
end
describe 'with context' do
subject { Sidekiq::Logger::Formatters::Pretty.new.call(severity, utc_time, prg, msg) }
let(:context) { { class: 'HaikuWorker', bid: nil } }
around do |test|
Sidekiq.logger.stub :context, context do
test.call
end
end
it 'skips context with nil values' do
assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx CLASS=HaikuWorker INFO: Old pond frog jumps in sound of water\n", subject
end
end
describe Sidekiq::Logger::Formatters::Pretty do
describe '#call' do
subject { Sidekiq::Logger::Formatters::Pretty.new.call(severity, utc_time, prg, msg) }
it 'formats with timestamp, pid, tid, severity, message' do
assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx INFO: Old pond frog jumps in sound of water\n", subject
end
describe 'with context' do
let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
around do |test|
Sidekiq.logger.stub :context, context do
test.call
end
end
it 'formats with timestamp, pid, tid, context, severity, message' do
assert_equal "2020-01-01T00:00:00.000Z 4710 TID-ouy7z76mx CLASS=HaikuWorker JID=dac39c70844dc0ee3f157ced INFO: Old pond frog jumps in sound of water\n", subject
end
end
end
end
describe Sidekiq::Logger::Formatters::WithoutTimestamp do
describe '#call' do
subject { Sidekiq::Logger::Formatters::WithoutTimestamp.new.call(severity, utc_time, prg, msg) }
it 'formats with pid, tid, severity, message' do
assert_equal "4710 TID-ouy7z76mx INFO: Old pond frog jumps in sound of water\n", subject
end
describe 'with context' do
let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
around do |test|
Sidekiq.logger.stub :context, context do
test.call
end
end
it 'formats with pid, tid, context, severity, message' do
assert_equal "4710 TID-ouy7z76mx CLASS=HaikuWorker JID=dac39c70844dc0ee3f157ced INFO: Old pond frog jumps in sound of water\n", subject
end
end
end
end
describe Sidekiq::Logger::Formatters::JSON do
describe '#call' do
subject { Sidekiq::Logger::Formatters::JSON.new.call(severity, utc_time, prg, msg) }
it 'formats with pid, tid, severity, message' do
assert_equal %q|{"ts":"2020-01-01T00:00:00.000Z","pid":4710,"tid":"ouy7z76mx","ctx":{},"sev":"INFO","msg":"Old pond frog jumps in sound of water"}|, subject
end
describe 'with context' do
let(:context) { { class: 'HaikuWorker', jid: 'dac39c70844dc0ee3f157ced' } }
around do |test|
Sidekiq.logger.stub :context, context do
test.call
end
end
it 'formats with pid, tid, context, severity, message' do
assert_equal %q|{"ts":"2020-01-01T00:00:00.000Z","pid":4710,"tid":"ouy7z76mx","ctx":{"class":"HaikuWorker","jid":"dac39c70844dc0ee3f157ced"},"sev":"INFO","msg":"Old pond frog jumps in sound of water"}|, subject
end
end
end
end
begin
Sidekiq.log_format = :json
assert_kind_of Sidekiq::Logger::Formatters::JSON, Sidekiq::Logger.new(STDOUT).formatter
ensure
Sidekiq.log_format = nil
end
end
def test_with_context
subject = @logger
assert_equal({}, subject.ctx)
subject.with_context(a: 1) do
assert_equal({ a: 1 }, subject.ctx)
end
assert_equal({}, subject.ctx)
end
def test_nested_contexts
subject = @logger
assert_equal({}, subject.ctx)
subject.with_context(a: 1) do
assert_equal({ a: 1 }, subject.ctx)
subject.with_context(b: 2, c: 3) do
assert_equal({ a: 1, b: 2, c: 3 }, subject.ctx)
end
assert_equal({ a: 1 }, subject.ctx)
end
assert_equal({}, subject.ctx)
end
def test_formatted_output
@logger.info("hello world")
assert_match(/INFO: hello world/, @output.string)
reset(@output)
formats = [ Sidekiq::Logger::Formatters::Pretty,
Sidekiq::Logger::Formatters::WithoutTimestamp,
Sidekiq::Logger::Formatters::JSON, ]
formats.each do |fmt|
@logger.formatter = fmt.new
@logger.with_context(class: 'HaikuWorker', bid: 'b-1234abc') do
@logger.info("hello context")
end
assert_match(/INFO/, @output.string)
assert_match(/hello context/, @output.string)
assert_match(/b-1234abc/, @output.string)
reset(@output)
end
end
def test_json_output_is_parsable
@logger.formatter = Sidekiq::Logger::Formatters::JSON.new
@logger.debug("boom")
@logger.with_context(class: 'HaikuWorker', jid: '1234abc') do
@logger.info("json format")
end
a, b = @output.string.lines
hash = JSON.parse(a)
keys = hash.keys.sort
assert_equal ["lvl", "msg", "pid", "tid", "ts"], keys
assert_nil hash["ctx"]
assert_equal hash["lvl"], "DEBUG"
hash = JSON.parse(b)
keys = hash.keys.sort
assert_equal ["ctx", "lvl", "msg", "pid", "tid", "ts"], keys
refute_nil hash["ctx"]
assert_equal "1234abc", hash["ctx"]["jid"]
assert_equal "INFO", hash["lvl"]
end
def reset(io)
io.truncate(0)
io.rewind
end
end