diff --git a/lib/sidekiq/middleware/server/logging.rb b/lib/sidekiq/middleware/server/logging.rb new file mode 100644 index 00000000..342dc800 --- /dev/null +++ b/lib/sidekiq/middleware/server/logging.rb @@ -0,0 +1,27 @@ +module Sidekiq + module Middleware + module Server + class Logging + def call(*args) + static = "#{args[0].class.to_s} MSG-#{args[0].object_id.to_s(36)}" if logger.info? + start = Time.now + logger.info { "#{static} start" } + yield + logger.info { "#{static} done: #{elapsed(start)} sec" } + rescue + logger.info { "#{static} fail: #{elapsed(start)} sec" } + raise + end + + def elapsed(start) + (Time.now - start).to_f.round(3) + end + + def logger + Sidekiq::Util.logger + end + end + end + end +end + diff --git a/lib/sidekiq/processor.rb b/lib/sidekiq/processor.rb index 4d0ebebe..027caf3b 100644 --- a/lib/sidekiq/processor.rb +++ b/lib/sidekiq/processor.rb @@ -5,6 +5,7 @@ require 'sidekiq/middleware/server/active_record' require 'sidekiq/middleware/server/exception_handler' require 'sidekiq/middleware/server/unique_jobs' require 'sidekiq/middleware/server/failure_jobs' +require 'sidekiq/middleware/server/logging' module Sidekiq class Processor @@ -18,6 +19,7 @@ module Sidekiq def self.default_middleware Middleware::Chain.new do |m| m.add Middleware::Server::ExceptionHandler + m.add Middleware::Server::Logging m.add Middleware::Server::UniqueJobs m.add Middleware::Server::ActiveRecord end diff --git a/lib/sidekiq/util.rb b/lib/sidekiq/util.rb index 9a2908d6..f8b8e991 100644 --- a/lib/sidekiq/util.rb +++ b/lib/sidekiq/util.rb @@ -6,10 +6,18 @@ module Sidekiq # module Util + class Pretty < Logger::Formatter + # Provide a call() method that returns the formatted message. + def call(severity, time, program_name, message) + "#{time.utc.iso8601} #{Process.pid} TID-#{Thread.current.object_id.to_s(36)} #{severity}: #{message}\n" + end + end + def self.logger @logger ||= begin - log = Logger.new(STDERR) + log = Logger.new(STDOUT) log.level = Logger::INFO + log.formatter = Pretty.new log end end