diff --git a/Appraisals b/Appraisals index fe42abd4c..9fd54712b 100644 --- a/Appraisals +++ b/Appraisals @@ -1,8 +1,3 @@ -appraise "rails-4" do - gem "rails", "~> 4.2" - gem 'activerecord-jdbcsqlite3-adapter', '< 50', platforms: :jruby -end - appraise "rails-5" do gem "rails", "~> 5.2" gem 'activerecord-jdbcsqlite3-adapter', '>= 50', platforms: :jruby diff --git a/Gemfile b/Gemfile index c075c91e5..7cf9174ea 100644 --- a/Gemfile +++ b/Gemfile @@ -14,6 +14,7 @@ end group :test do gem 'minitest' + gem 'minitest-around' gem 'minitest-focus' gem 'minitest-reporters' gem 'simplecov' diff --git a/gemfiles/rails_5.gemfile b/gemfiles/rails_5.gemfile index a3377873c..ea2840aa4 100644 --- a/gemfiles/rails_5.gemfile +++ b/gemfiles/rails_5.gemfile @@ -14,6 +14,7 @@ end group :test do gem "minitest" + gem "minitest-around" gem "minitest-focus" gem "minitest-reporters" gem "simplecov" diff --git a/lib/sidekiq.rb b/lib/sidekiq.rb index b48ed63f4..3f0dddd38 100644 --- a/lib/sidekiq.rb +++ b/lib/sidekiq.rb @@ -3,7 +3,7 @@ require 'sidekiq/version' fail "Sidekiq #{Sidekiq::VERSION} does not support Ruby versions below 2.4.0." if RUBY_PLATFORM != 'java' && Gem::Version.new(RUBY_VERSION) < Gem::Version.new('2.4.0') -require 'sidekiq/logging' +require 'sidekiq/logger' require 'sidekiq/client' require 'sidekiq/worker' require 'sidekiq/redis_connection' @@ -178,11 +178,16 @@ def self.dump_json(object) JSON.generate(object) end + class << self + attr_accessor :logger_formatter + end + def self.logger - Sidekiq::Logging.logger + @logger ||= Sidekiq::Logger.new(STDOUT, level: Logger::INFO) end - def self.logger=(log) - Sidekiq::Logging.logger = log + + def self.logger=(logger) + @logger = logger end # How frequently Redis should be checked by a random Sidekiq process for diff --git a/lib/sidekiq/cli.rb b/lib/sidekiq/cli.rb index b614137dd..ed40fbcd5 100644 --- a/lib/sidekiq/cli.rb +++ b/lib/sidekiq/cli.rb @@ -8,8 +8,8 @@ require 'fileutils' require 'sidekiq' -require 'sidekiq/util' require 'sidekiq/launcher' +require 'sidekiq/util' module Sidekiq class CLI @@ -339,16 +339,11 @@ def parse_options(argv) end def initialize_logger - Sidekiq::Logging.initialize_logger - Sidekiq.logger.level = ::Logger::DEBUG if options[:verbose] end - def parse_config(cfile) - opts = {} - if File.exist?(cfile) - opts = YAML.load(ERB.new(IO.read(cfile)).result) || opts - end + def parse_config(path) + opts = YAML.load(ERB.new(File.read(path)).result) || {} if opts.respond_to? :deep_symbolize_keys! opts.deep_symbolize_keys! diff --git a/lib/sidekiq/job_logger.rb b/lib/sidekiq/job_logger.rb index b43505161..3ba84f898 100644 --- a/lib/sidekiq/job_logger.rb +++ b/lib/sidekiq/job_logger.rb @@ -1,25 +1,52 @@ # frozen_string_literal: true + module Sidekiq class JobLogger def call(item, queue) start = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - logger.info("start") + + Sidekiq.logger.info("start") + yield - logger.info("done: #{elapsed(start)} sec") + + with_elapsed_time_context(start) do + Sidekiq.logger.info("done") + end rescue Exception - logger.info("fail: #{elapsed(start)} sec") + with_elapsed_time_context(start) do + Sidekiq.logger.info("fail") + end + raise end + def with_job_hash_context(job_hash, &block) + Sidekiq.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. + { + class: job_hash['wrapped'] || job_hash["class"], + jid: job_hash['jid'], + bid: job_hash['bid'] + } + end + + def with_elapsed_time_context(start, &block) + Sidekiq.logger.with_context(elapsed_time_context(start), &block) + end + + def elapsed_time_context(start) + { elapsed: "#{elapsed(start)} sec" } + end + private def elapsed(start) (::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - start).round(3) end - - def logger - Sidekiq.logger - end end end diff --git a/lib/sidekiq/logger.rb b/lib/sidekiq/logger.rb new file mode 100644 index 000000000..f572f2b09 --- /dev/null +++ b/lib/sidekiq/logger.rb @@ -0,0 +1,70 @@ +# frozen_string_literal: true + +require 'logger' +require 'time' + +module Sidekiq + class Logger < ::Logger + + def initialize(*args) + super + + formatter_class = case Sidekiq.logger_formatter + when :json + Formatters::JSON + else + ENV['DYNO'] ? Formatters::WithoutTimestamp : Formatters::Pretty + end + + self.formatter = formatter_class.new + end + + def tid + Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36) + end + + def context + 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" + end + + private + + def format_context(context) + ' ' + context.compact.map { |k, v| "#{k.upcase}=#{v}" }.join(' ') if context.any? + 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" + end + end + + class JSON < Logger::Formatter + def call(severity, time, program_name, message) + Sidekiq.dump_json( + ts: time.utc.iso8601(3), + pid: ::Process.pid, + tid: Sidekiq.logger.tid, + ctx: Sidekiq.logger.context, + sev: severity, + msg: message + ) + end + end + end + end +end diff --git a/lib/sidekiq/logging.rb b/lib/sidekiq/logging.rb deleted file mode 100644 index 13ca7cb4f..000000000 --- a/lib/sidekiq/logging.rb +++ /dev/null @@ -1,72 +0,0 @@ -# frozen_string_literal: true -require 'time' -require 'logger' - -module Sidekiq - module Logging - - class Pretty < Logger::Formatter - SPACE = " " - - # Provide a call() method that returns the formatted message. - def call(severity, time, program_name, message) - "#{time.utc.iso8601(3)} #{::Process.pid} TID-#{Sidekiq::Logging.tid}#{context} #{severity}: #{message}\n" - end - - def context - c = Thread.current[:sidekiq_context] - " #{c.join(SPACE)}" if c && c.any? - end - end - - class WithoutTimestamp < Pretty - def call(severity, time, program_name, message) - "#{::Process.pid} TID-#{Sidekiq::Logging.tid}#{context} #{severity}: #{message}\n" - end - end - - def self.tid - Thread.current['sidekiq_tid'] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36) - end - - def self.job_hash_context(job_hash) - # If we're using a wrapper class, like ActiveJob, use the "wrapped" - # attribute to expose the underlying thing. - klass = job_hash['wrapped'] || job_hash["class"] - bid = job_hash['bid'] - "#{klass} JID-#{job_hash['jid']}#{" BID-#{bid}" if bid}" - end - - def self.with_job_hash_context(job_hash, &block) - with_context(job_hash_context(job_hash), &block) - end - - def self.with_context(msg) - Thread.current[:sidekiq_context] ||= [] - Thread.current[:sidekiq_context] << msg - yield - ensure - Thread.current[:sidekiq_context].pop - end - - def self.initialize_logger - return @logger if defined?(@logger) - @logger = Logger.new(STDOUT) - @logger.level = Logger::INFO - @logger.formatter = ENV['DYNO'] ? WithoutTimestamp.new : Pretty.new - @logger - end - - def self.logger - defined?(@logger) ? @logger : initialize_logger - end - - def self.logger=(log) - @logger = (log ? log : Logger.new(File::NULL)) - end - - def logger - Sidekiq::Logging.logger - end - end -end diff --git a/lib/sidekiq/processor.rb b/lib/sidekiq/processor.rb index 82be39d5a..2e1f7f218 100644 --- a/lib/sidekiq/processor.rb +++ b/lib/sidekiq/processor.rb @@ -37,7 +37,7 @@ def initialize(mgr) @thread = nil @strategy = (mgr.options[:fetch] || Sidekiq::BasicFetch).new(mgr.options) @reloader = Sidekiq.options[:reloader] - @logging = (mgr.options[:job_logger] || Sidekiq::JobLogger).new + @job_logger = (mgr.options[:job_logger] || Sidekiq::JobLogger).new @retrier = Sidekiq::JobRetry.new end @@ -121,9 +121,9 @@ def dispatch(job_hash, queue) # job structure to the Web UI pristine = cloned(job_hash) - Sidekiq::Logging.with_job_hash_context(job_hash) do + @job_logger.with_job_hash_context(job_hash) do @retrier.global(pristine, queue) do - @logging.call(job_hash, queue) do + @job_logger.call(job_hash, queue) do stats(pristine, queue) do # Rails 5 requires a Reloader to wrap code execution. In order to # constantize the worker and instantiate an instance, we have to call @@ -236,7 +236,8 @@ def clear WORKER_STATE = SharedWorkerState.new def stats(job_hash, queue) - tid = Sidekiq::Logging.tid + tid = Sidekiq.logger.tid + WORKER_STATE.set(tid, {:queue => queue, :payload => job_hash, :run_at => Time.now.to_i }) begin @@ -267,6 +268,5 @@ def constantize(str) constant.const_defined?(name, false) ? constant.const_get(name, false) : constant.const_missing(name) end end - end end diff --git a/lib/sidekiq/scheduled.rb b/lib/sidekiq/scheduled.rb index d2e5d1a5b..b9aacbb87 100644 --- a/lib/sidekiq/scheduled.rb +++ b/lib/sidekiq/scheduled.rb @@ -24,7 +24,7 @@ def enqueue_jobs(now=Time.now.to_f.to_s, sorted_sets=SETS) # next one. if conn.zrem(sorted_set, job) Sidekiq::Client.push(Sidekiq.load_json(job)) - Sidekiq::Logging.logger.debug { "enqueued #{sorted_set}: #{job}" } + Sidekiq.logger.debug { "enqueued #{sorted_set}: #{job}" } end end end diff --git a/test/test_cli.rb b/test/test_cli.rb index a5feec55b..52d9e6e75 100644 --- a/test/test_cli.rb +++ b/test/test_cli.rb @@ -4,368 +4,347 @@ require 'sidekiq/cli' class TestCLI < Minitest::Test - describe '#parse' do - before do - Sidekiq.options = Sidekiq::DEFAULTS.dup - @logger = Sidekiq.logger - @logdev = StringIO.new - Sidekiq.logger = Logger.new(@logdev) - @cli = Sidekiq::CLI.new - end - - after do - Sidekiq.logger = @logger - end + describe Sidekiq::CLI do + subject { Sidekiq::CLI.new } - describe 'options' do - describe 'require' do - it 'accepts with -r' do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) + let(:logdev) { StringIO.new } - assert_equal './test/fake_env.rb', Sidekiq.options[:require] + around do |test| + Sidekiq.stub :options, Sidekiq::DEFAULTS.dup do + Sidekiq.stub :logger, Sidekiq::Logger.new(logdev) do + test.call end end + end - describe 'concurrency' do - it 'accepts with -c' do - @cli.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb]) + describe '#parse' do + describe 'options' do + describe 'require' do + it 'accepts with -r' do + subject.parse(%w[sidekiq -r ./test/fake_env.rb]) - assert_equal 60, Sidekiq.options[:concurrency] + assert_equal './test/fake_env.rb', Sidekiq.options[:require] + end end - describe 'when concurrency is empty and RAILS_MAX_THREADS env var is set' do - before do - ENV['RAILS_MAX_THREADS'] = '9' - end + describe 'concurrency' do + it 'accepts with -c' do + subject.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb]) - after do - ENV.delete('RAILS_MAX_THREADS') + assert_equal 60, Sidekiq.options[:concurrency] end - it 'sets concurrency from RAILS_MAX_THREADS env var' do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) + describe 'when concurrency is empty and RAILS_MAX_THREADS env var is set' do + before do + ENV['RAILS_MAX_THREADS'] = '9' + end - assert_equal 9, Sidekiq.options[:concurrency] - end + after do + ENV.delete('RAILS_MAX_THREADS') + end - it 'option overrides RAILS_MAX_THREADS env var' do - @cli.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb]) + it 'sets concurrency from RAILS_MAX_THREADS env var' do + subject.parse(%w[sidekiq -r ./test/fake_env.rb]) - assert_equal 60, Sidekiq.options[:concurrency] - end - end - end + assert_equal 9, Sidekiq.options[:concurrency] + end - describe 'queues' do - it 'accepts with -q' do - @cli.parse(%w[sidekiq -q foo -r ./test/fake_env.rb]) + it 'option overrides RAILS_MAX_THREADS env var' do + subject.parse(%w[sidekiq -c 60 -r ./test/fake_env.rb]) - assert_equal ['foo'], Sidekiq.options[:queues] + assert_equal 60, Sidekiq.options[:concurrency] + end + end end - describe 'when weights are not present' do - it 'accepts queues without weights' do - @cli.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb]) + describe 'queues' do + it 'accepts with -q' do + subject.parse(%w[sidekiq -q foo -r ./test/fake_env.rb]) - assert_equal ['foo', 'bar'], Sidekiq.options[:queues] + assert_equal ['foo'], Sidekiq.options[:queues] end - it 'sets strictly ordered queues' do - @cli.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb]) + describe 'when weights are not present' do + it 'accepts queues without weights' do + subject.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb]) - assert_equal true, !!Sidekiq.options[:strict] - end - end + assert_equal ['foo', 'bar'], Sidekiq.options[:queues] + end - describe 'when weights are present' do - it 'accepts queues with weights' do - @cli.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb]) + it 'sets strictly ordered queues' do + subject.parse(%w[sidekiq -q foo -q bar -r ./test/fake_env.rb]) - assert_equal ['foo', 'foo', 'foo', 'bar'], Sidekiq.options[:queues] + assert_equal true, !!Sidekiq.options[:strict] + end end - it 'does not set strictly ordered queues' do - @cli.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb]) + describe 'when weights are present' do + it 'accepts queues with weights' do + subject.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb]) - assert_equal false, !!Sidekiq.options[:strict] - end - end - - it 'accepts queues with multi-word names' do - @cli.parse(%w[sidekiq -q queue_one -q queue-two -r ./test/fake_env.rb]) + assert_equal ['foo', 'foo', 'foo', 'bar'], Sidekiq.options[:queues] + end - assert_equal ['queue_one', 'queue-two'], Sidekiq.options[:queues] - end + it 'does not set strictly ordered queues' do + subject.parse(%w[sidekiq -q foo,3 -q bar -r ./test/fake_env.rb]) - it 'accepts queues with dots in the name' do - @cli.parse(%w[sidekiq -q foo.bar -r ./test/fake_env.rb]) + assert_equal false, !!Sidekiq.options[:strict] + end + end - assert_equal ['foo.bar'], Sidekiq.options[:queues] - end + it 'accepts queues with multi-word names' do + subject.parse(%w[sidekiq -q queue_one -q queue-two -r ./test/fake_env.rb]) - describe 'when duplicate queue names' do - it 'raises an argument error' do - assert_raises(ArgumentError) { @cli.parse(%w[sidekiq -q foo -q foo -r ./test/fake_env.rb]) } - assert_raises(ArgumentError) { @cli.parse(%w[sidekiq -q foo,3 -q foo,1 -r ./test/fake_env.rb]) } + assert_equal ['queue_one', 'queue-two'], Sidekiq.options[:queues] end - end - describe 'when queues are empty' do - it "sets 'default' queue" do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) + it 'accepts queues with dots in the name' do + subject.parse(%w[sidekiq -q foo.bar -r ./test/fake_env.rb]) - assert_equal ['default'], Sidekiq.options[:queues] + assert_equal ['foo.bar'], Sidekiq.options[:queues] end - end - end - describe 'timeout' do - it 'accepts with -t' do - @cli.parse(%w[sidekiq -t 30 -r ./test/fake_env.rb]) - - assert_equal 30, Sidekiq.options[:timeout] - end - end + describe 'when duplicate queue names' do + it 'raises an argument error' do + assert_raises(ArgumentError) { subject.parse(%w[sidekiq -q foo -q foo -r ./test/fake_env.rb]) } + assert_raises(ArgumentError) { subject.parse(%w[sidekiq -q foo,3 -q foo,1 -r ./test/fake_env.rb]) } + end + end - describe 'verbose' do - it 'accepts with -v' do - @cli.parse(%w[sidekiq -v -r ./test/fake_env.rb]) + describe 'when queues are empty' do + it "sets 'default' queue" do + subject.parse(%w[sidekiq -r ./test/fake_env.rb]) - assert_equal Logger::DEBUG, Sidekiq.logger.level + assert_equal ['default'], Sidekiq.options[:queues] + end + end end - end - describe 'config file' do - it 'accepts with -C' do - @cli.parse(%w[sidekiq -C ./test/config.yml]) - - assert_equal './test/config.yml', Sidekiq.options[:config_file] - refute Sidekiq.options[:verbose] - assert_equal './test/fake_env.rb', Sidekiq.options[:require] - assert_nil Sidekiq.options[:environment] - assert_equal 50, Sidekiq.options[:concurrency] - assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } - assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } + describe 'timeout' do + it 'accepts with -t' do + subject.parse(%w[sidekiq -t 30 -r ./test/fake_env.rb]) + + assert_equal 30, Sidekiq.options[:timeout] + end end - it 'accepts stringy keys' do - @cli.parse(%w[sidekiq -C ./test/config_string.yml]) + describe 'verbose' do + it 'accepts with -v' do + subject.parse(%w[sidekiq -v -r ./test/fake_env.rb]) - assert_equal './test/config_string.yml', Sidekiq.options[:config_file] - refute Sidekiq.options[:verbose] - assert_equal './test/fake_env.rb', Sidekiq.options[:require] - assert_nil Sidekiq.options[:environment] - assert_equal 50, Sidekiq.options[:concurrency] - assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } - assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } + assert_equal Logger::DEBUG, Sidekiq.logger.level + end end - it 'accepts environment specific config' do - @cli.parse(%w[sidekiq -e staging -C ./test/config_environment.yml]) + describe 'config file' do + it 'accepts with -C' do + subject.parse(%w[sidekiq -C ./test/config.yml]) - assert_equal './test/config_environment.yml', Sidekiq.options[:config_file] - refute Sidekiq.options[:verbose] - assert_equal './test/fake_env.rb', Sidekiq.options[:require] - assert_equal 'staging', Sidekiq.options[:environment] - assert_equal 50, Sidekiq.options[:concurrency] - assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } - assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } - end + assert_equal './test/config.yml', Sidekiq.options[:config_file] + refute Sidekiq.options[:verbose] + assert_equal './test/fake_env.rb', Sidekiq.options[:require] + assert_nil Sidekiq.options[:environment] + assert_equal 50, Sidekiq.options[:concurrency] + assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } + assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } + end - describe 'when config file is empty' do - it 'sets default options' do - @cli.parse(%w[sidekiq -C ./test/config_empty.yml -r ./test/fake_env.rb]) + it 'accepts stringy keys' do + subject.parse(%w[sidekiq -C ./test/config_string.yml]) - assert_equal './test/config_empty.yml', Sidekiq.options[:config_file] + assert_equal './test/config_string.yml', Sidekiq.options[:config_file] refute Sidekiq.options[:verbose] assert_equal './test/fake_env.rb', Sidekiq.options[:require] assert_nil Sidekiq.options[:environment] - assert_equal 10, Sidekiq.options[:concurrency] - assert_equal ['default'], Sidekiq.options[:queues] + assert_equal 50, Sidekiq.options[:concurrency] + assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } + assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } end - end - describe 'when config file and flags' do - it 'merges options' do - @cli.parse(%w[sidekiq -C ./test/config.yml - -e snoop - -c 100 - -r ./test/fake_env.rb - -q often,7 - -q seldom,3]) + it 'accepts environment specific config' do + subject.parse(%w[sidekiq -e staging -C ./test/config_environment.yml]) - assert_equal './test/config.yml', Sidekiq.options[:config_file] + assert_equal './test/config_environment.yml', Sidekiq.options[:config_file] refute Sidekiq.options[:verbose] assert_equal './test/fake_env.rb', Sidekiq.options[:require] - assert_equal 'snoop', Sidekiq.options[:environment] - assert_equal 100, Sidekiq.options[:concurrency] - assert_equal 7, Sidekiq.options[:queues].count { |q| q == 'often' } - assert_equal 3, Sidekiq.options[:queues].count { |q| q == 'seldom' } + assert_equal 'staging', Sidekiq.options[:environment] + assert_equal 50, Sidekiq.options[:concurrency] + assert_equal 2, Sidekiq.options[:queues].count { |q| q == 'very_often' } + assert_equal 1, Sidekiq.options[:queues].count { |q| q == 'seldom' } end - end - describe 'default config file' do - describe 'when required path is a directory' do - it 'tries config/sidekiq.yml' do - @cli.parse(%w[sidekiq -r ./test/dummy]) + describe 'when config file is empty' do + it 'sets default options' do + subject.parse(%w[sidekiq -C ./test/config_empty.yml -r ./test/fake_env.rb]) - assert_equal 'sidekiq.yml', File.basename(Sidekiq.options[:config_file]) - assert_equal 25, Sidekiq.options[:concurrency] + assert_equal './test/config_empty.yml', Sidekiq.options[:config_file] + refute Sidekiq.options[:verbose] + assert_equal './test/fake_env.rb', Sidekiq.options[:require] + assert_nil Sidekiq.options[:environment] + assert_equal 10, Sidekiq.options[:concurrency] + assert_equal ['default'], Sidekiq.options[:queues] end end - end - end - end - describe 'validation' do - describe 'when required application path does not exist' do - it 'exits with status 1' do - exit = assert_raises(SystemExit) { @cli.parse(%w[sidekiq -r /non/existent/path]) } - assert_equal 1, exit.status + describe 'when config file and flags' do + it 'merges options' do + subject.parse(%w[sidekiq -C ./test/config.yml + -e snoop + -c 100 + -r ./test/fake_env.rb + -q often,7 + -q seldom,3]) + + assert_equal './test/config.yml', Sidekiq.options[:config_file] + refute Sidekiq.options[:verbose] + assert_equal './test/fake_env.rb', Sidekiq.options[:require] + assert_equal 'snoop', Sidekiq.options[:environment] + assert_equal 100, Sidekiq.options[:concurrency] + assert_equal 7, Sidekiq.options[:queues].count { |q| q == 'often' } + assert_equal 3, Sidekiq.options[:queues].count { |q| q == 'seldom' } + end + end + + describe 'default config file' do + describe 'when required path is a directory' do + it 'tries config/sidekiq.yml' do + subject.parse(%w[sidekiq -r ./test/dummy]) + + assert_equal 'sidekiq.yml', File.basename(Sidekiq.options[:config_file]) + assert_equal 25, Sidekiq.options[:concurrency] + end + end + end end end - describe 'when required path is a directory without config/application.rb' do - it 'exits with status 1' do - exit = assert_raises(SystemExit) { @cli.parse(%w[sidekiq -r ./test/fixtures]) } - assert_equal 1, exit.status + describe 'validation' do + describe 'when required application path does not exist' do + it 'exits with status 1' do + exit = assert_raises(SystemExit) { subject.parse(%w[sidekiq -r /non/existent/path]) } + assert_equal 1, exit.status + end end - describe 'when config file path does not exist' do - it 'raises argument error' do - assert_raises(ArgumentError) do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb -C /non/existent/path]) + describe 'when required path is a directory without config/application.rb' do + it 'exits with status 1' do + exit = assert_raises(SystemExit) { subject.parse(%w[sidekiq -r ./test/fixtures]) } + assert_equal 1, exit.status + end + + describe 'when config file path does not exist' do + it 'raises argument error' do + assert_raises(ArgumentError) do + subject.parse(%w[sidekiq -r ./test/fake_env.rb -C /non/existent/path]) + end end end end end end - end - describe '#run' do - before do - Sidekiq.options = Sidekiq::DEFAULTS.dup - Sidekiq.options[:require] = './test/fake_env.rb' - @logger = Sidekiq.logger - @logdev = StringIO.new - Sidekiq.logger = Logger.new(@logdev) - @cli = Sidekiq::CLI.new - end + describe '#run' do + before do + Sidekiq.options[:require] = './test/fake_env.rb' + end - after do - Sidekiq.logger = @logger - end + describe 'require workers' do + describe 'when path is a rails directory' do + before do + Sidekiq.options[:require] = './test/dummy' + subject.environment = 'test' + end - describe 'require workers' do - describe 'when path is a rails directory' do - before do - Sidekiq.options[:require] = './test/dummy' - @cli.environment = 'test' - end + it 'requires sidekiq railtie and rails application with environment' do + subject.stub(:launch, nil) do + subject.run + end - it 'requires sidekiq railtie and rails application with environment' do - @cli.stub(:launch, nil) do - @cli.run + assert defined?(Sidekiq::Rails) + assert defined?(Dummy::Application) end - assert defined?(Sidekiq::Rails) - assert defined?(Dummy::Application) - end + it 'tags with the app directory name' do + subject.stub(:launch, nil) do + subject.run + end - it 'tags with the app directory name' do - @cli.stub(:launch, nil) do - @cli.run + assert_equal 'dummy', Sidekiq.options[:tag] end - - assert_equal 'dummy', Sidekiq.options[:tag] end - end - describe 'when path is file' do - it 'requires application' do - @cli.stub(:launch, nil) do - @cli.run - end + describe 'when path is file' do + it 'requires application' do + subject.stub(:launch, nil) do + subject.run + end - assert $LOADED_FEATURES.any? { |x| x =~ /test\/fake_env/ } + assert $LOADED_FEATURES.any? { |x| x =~ /test\/fake_env/ } + end end end - end - describe 'when development environment and stdout tty' do - it 'prints banner' do - @cli.stub(:environment, 'development') do - assert_output(/#{Regexp.escape(Sidekiq::CLI.banner)}/) do - $stdout.stub(:tty?, true) do - @cli.stub(:launch, nil) do - @cli.run + describe 'when development environment and stdout tty' do + it 'prints banner' do + subject.stub(:environment, 'development') do + assert_output(/#{Regexp.escape(Sidekiq::CLI.banner)}/) do + $stdout.stub(:tty?, true) do + subject.stub(:launch, nil) do + subject.run + end end end end end end end - end - - describe 'signal handling' do - before do - @cli = Sidekiq::CLI.new - Sidekiq.options = Sidekiq::DEFAULTS.dup - @logger = Sidekiq.logger - @logdev = StringIO.new - Sidekiq.logger = Logger.new(@logdev) - end - - after do - Sidekiq.logger = @logger - end - %w(INT TERM).each do |sig| - describe sig do - it 'raises interrupt error' do - assert_raises Interrupt do - @cli.handle_signal(sig) + describe 'signal handling' do + %w(INT TERM).each do |sig| + describe sig do + it 'raises interrupt error' do + assert_raises Interrupt do + subject.handle_signal(sig) + end end end end - end - %w(TSTP USR1).each do |sig| - describe sig do - it 'quiets with a corresponding event' do - quiet = false + %w(TSTP USR1).each do |sig| + describe sig do + it 'quiets with a corresponding event' do + quiet = false - Sidekiq.on(:quiet) do - quiet = true - end + Sidekiq.on(:quiet) do + quiet = true + end - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) - @cli.launcher = Sidekiq::Launcher.new(Sidekiq.options) - @cli.handle_signal(sig) + subject.launcher = Sidekiq::Launcher.new(Sidekiq.options) + subject.handle_signal(sig) - assert_match(/Got #{sig} signal/, @logdev.string) - assert_equal true, quiet + assert_match(/Got #{sig} signal/, logdev.string) + assert_equal true, quiet + end end end - end - describe 'TTIN' do - it 'prints backtraces for all threads in the process to the logfile' do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) - @cli.handle_signal('TTIN') + describe 'TTIN' do + it 'prints backtraces for all threads in the process to the logfile' do + subject.handle_signal('TTIN') - assert_match(/Got TTIN signal/, @logdev.string) - assert_match(/\bbacktrace\b/, @logdev.string) + assert_match(/Got TTIN signal/, logdev.string) + assert_match(/\bbacktrace\b/, logdev.string) + end end - end - describe 'UNKNOWN' do - it 'logs about' do - @cli.parse(%w[sidekiq -r ./test/fake_env.rb]) - @cli.handle_signal('UNKNOWN') + describe 'UNKNOWN' do + it 'logs about' do + # subject.parse(%w[sidekiq -r ./test/fake_env.rb]) + subject.handle_signal('UNKNOWN') - assert_match(/Got UNKNOWN signal/, @logdev.string) - assert_match(/No signal handler for UNKNOWN/, @logdev.string) + assert_match(/Got UNKNOWN signal/, logdev.string) + assert_match(/No signal handler for UNKNOWN/, logdev.string) + end end end end diff --git a/test/test_job_logger.rb b/test/test_job_logger.rb new file mode 100644 index 000000000..332330616 --- /dev/null +++ b/test/test_job_logger.rb @@ -0,0 +1,56 @@ +# frozen_string_literal: true + +require_relative 'helper' +require 'sidekiq/job_logger' + +class TestJobLogger < Minitest::Test + describe Sidekiq::JobLogger do + subject { Sidekiq::JobLogger.new } + + let(:logdev) { StringIO.new } + + 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 + end + + after do + Thread.current[:sidekiq_context] = nil + 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 + end +end diff --git a/test/test_logger.rb b/test/test_logger.rb new file mode 100644 index 000000000..8ccef703f --- /dev/null +++ b/test/test_logger.rb @@ -0,0 +1,235 @@ +# frozen_string_literal: true + +require_relative 'helper' +require 'sidekiq/logger' + +class TestLogger < Minitest::Test + describe Sidekiq::Logger do + let(:logdev) { StringIO.new } + + subject { Sidekiq::Logger.new(logdev) } + + before do + Thread.current[:sidekiq_context] = nil + Thread.current[:sidekiq_tid] = 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 + end + end +end diff --git a/test/test_logging.rb b/test/test_logging.rb deleted file mode 100644 index 7a9d694e1..000000000 --- a/test/test_logging.rb +++ /dev/null @@ -1,35 +0,0 @@ -# frozen_string_literal: true -require_relative 'helper' -require 'sidekiq/logging' - -class TestLogging < Minitest::Test - describe Sidekiq::Logging do - describe "#with_context" do - def ctx - Sidekiq::Logging.logger.formatter.context - end - - it "has no context by default" do - assert_nil ctx - end - - it "can add a context" do - Sidekiq::Logging.with_context "xx" do - assert_equal " xx", ctx - end - assert_nil ctx - end - - it "can use multiple contexts" do - Sidekiq::Logging.with_context "xx" do - assert_equal " xx", ctx - Sidekiq::Logging.with_context "yy" do - assert_equal " xx yy", ctx - end - assert_equal " xx", ctx - end - assert_nil ctx - end - end - end -end diff --git a/test/test_processor.rb b/test/test_processor.rb index 8132bce8e..794f2e22f 100644 --- a/test/test_processor.rb +++ b/test/test_processor.rb @@ -338,7 +338,7 @@ def failed_job end describe 'custom job logger class' do - class CustomJobLogger + class CustomJobLogger < Sidekiq::JobLogger def call(item, queue) yield rescue Exception @@ -348,9 +348,9 @@ def call(item, queue) before do @mgr = Minitest::Mock.new - @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger}) - @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger}) - @mgr.expect(:options, {:queues => ['default'], :job_logger => CustomJobLogger}) + @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger}) + @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger}) + @mgr.expect(:options, {:queues => ['default'], job_logger: CustomJobLogger}) @processor = ::Sidekiq::Processor.new(@mgr) end