feat(job_start_log): flag to enable logging of job start (#13)

README.md

@@ -68,6 +68,11 @@ Sidekiq::Logstash.configure do |config|
   # it works just like rails params filtering (http://guides.rubyonrails.org/action_controller_overview.html#parameters-filtering)
   config.filter_args << 'foo'
 
+  # by default, the "job started" logs are omitted from the logs
+  # to have one-line logs for each log (following Lograge), but you can
+  # enable job start logs by setting the following flag:
+  config.job_start_log = true
+
   # custom_option is a Proc that will be called before logging the payload, allowing you to add fields to it
   config.custom_options = lambda do |payload|
     payload['my_custom_field'] = 'my_custom_value'

lib/sidekiq/logging/shared.rb

@@ -3,7 +3,10 @@ module Logging
     module Shared
       ENCRYPTED = '[ENCRYPTED]'.freeze
 
-      def log_job(payload, started_at, exc = nil)
+      def log_job(payload, started_at, exc = nil, start = false)
+        # skip start logs for retrying jobs
+        return if start && payload['failed_at']
+
         # Create a copy of the payload using JSON
         # This should always be possible since Sidekiq store it in Redis
         payload = JSON.parse(JSON.unparse(payload))
@@ -13,22 +16,28 @@ def log_job(payload, started_at, exc = nil)
           payload[key] = parse_time(payload[key]) if payload[key]
         end
 
+        message = "#{payload['class']} JID-#{payload['jid']}"
+
         # Add process id params
         payload['pid']      = ::Process.pid
-        payload['duration'] = elapsed(started_at)
 
-        message = "#{payload['class']} JID-#{payload['jid']}"
-
-        if exc
-          payload['message']         = "#{message}: fail: #{payload['duration']} sec"
-          payload['job_status']      = 'fail'
-          payload['error_message']   = exc.message
-          payload['error']           = exc.class
-          payload['error_backtrace'] = %('#{exc.backtrace.join("\n")}')
+        if start
+          payload['job_status'] = 'started'
+          payload['message'] = "#{message}: started"
         else
-          payload['message']      = "#{message}: done: #{payload['duration']} sec"
-          payload['job_status']   = 'done'
-          payload['completed_at'] = Time.now.utc
+          payload['duration'] = elapsed(started_at)
+
+          if exc
+            payload['message']         = "#{message}: fail: #{payload['duration']} sec"
+            payload['job_status']      = 'fail'
+            payload['error_message']   = exc.message
+            payload['error']           = exc.class
+            payload['error_backtrace'] = %('#{exc.backtrace.join("\n")}')
+          else
+            payload['message']      = "#{message}: done: #{payload['duration']} sec"
+            payload['job_status']   = 'done'
+            payload['completed_at'] = Time.now.utc
+          end
         end
 
         # Filter sensitive parameters

lib/sidekiq/logstash/configuration.rb

@@ -1,10 +1,11 @@
 module Sidekiq
   module Logstash
     class Configuration
-      attr_accessor :custom_options, :filter_args
+      attr_accessor :custom_options, :filter_args, :job_start_log
 
       def initialize
         @filter_args = []
+        @job_start_log = false
       end
 
       # Added to ensure custom_options is a Proc
@@ -14,4 +15,4 @@ def custom_options=(proc)
       end
     end
   end
-end
+end

lib/sidekiq/logstash_job_logger.rb

@@ -6,6 +6,10 @@ class LogstashJobLogger
 
     def call(job, _queue)
       started_at = Time.now.utc
+      if Sidekiq::Logstash.configuration.job_start_log
+        payload = log_job(job, started_at, nil, true)
+        Sidekiq.logger.info payload if payload
+      end
       yield
       Sidekiq.logger.info log_job(job, started_at)
     rescue => exc
@@ -20,4 +24,4 @@ def call(job, _queue)
       raise
     end
   end
-end
+end

spec/sidekiq/logstash_spec.rb

@@ -24,6 +24,16 @@
     end
   end
 
+  it 'logs only a single line (doesn\'t have a "started" log by default)' do
+    buffer = StringIO.new
+    Sidekiq.logger = Logger.new(buffer)
+
+    log_job = Sidekiq::LogstashJobLogger.new.call(job, :default) {}
+
+    expect(buffer.string.split("\n").length).to eq(1)
+    expect(buffer.string).not_to include('"job_status"=>"started"')
+  end
+
   it 'filter args' do
     Sidekiq::Logstash.configure do |config|
       config.filter_args << 'a_secret_param'
@@ -51,4 +61,34 @@
       expect(log_job['args'][2]).to include('[ENCRYPTED]')
     end
   end
+
+  context 'enable job_start_log' do
+    it 'generates log with job_status=started' do
+      buffer = StringIO.new
+      Sidekiq.logger = Logger.new(buffer)
+
+      Sidekiq::Logstash.configure do |config|
+        config.job_start_log = true
+      end
+
+      log_job = Sidekiq::Middleware::Server::LogstashLogging.new.log_job(job, Time.now.utc, exc = nil, start = true)
+
+      expect(log_job['job_status']).to eq('started')
+    end
+
+    it 'logs both the starting and finished logs' do
+      buffer = StringIO.new
+      Sidekiq.logger = Logger.new(buffer)
+
+      Sidekiq::Logstash.configure do |config|
+        config.job_start_log = true
+      end
+
+      log_job = Sidekiq::LogstashJobLogger.new.call(job, :default) {}
+
+      expect(buffer.string.split("\n").length).to eq(2)
+      expect(buffer.string).to include('"job_status"=>"started"')
+      expect(buffer.string).to include('"job_status"=>"done"')
+    end
+  end
 end