Better logging, fixes GH-55

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
+

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

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