Add set_job_tags support for better job logs

README.md

@@ -234,6 +234,44 @@ Sidekiq.configure_server do |config|
 end
 ```
 
+For most jobs, you'll want to set log tags. Use `with_log_tags` to set tags for a block.
+
+```rb
+class MyJob
+  def perform
+    Appydays::Loggable::SidekiqJobLogger.with_log_tags(some_tag: 'some value') do
+      MyApp.do_thing
+    end
+  end
+end
+# Log messages from MyApp#do_thing include the tag {some_tag: 'some value'}
+```
+
+You can also set fields that are logged in the `job_done` (or `job_fail`) message
+that is output when the job is finished.
+This is useful when you want to log the output of the job,
+but not redundantly. Ie, `logger.info "finished_doing_thing", user_id: user.id` along
+with a `"job_done"` message after that (missing `user_id`) is redundant.
+Instead, use `set_job_tags` within the job, so the `"job_done"` message includes them:
+
+```rb
+# WRONG, will result in two messages, "job_done" will not have 'done_count' field
+class MyJob
+  def perform
+    count = MyApp.do_thing
+    self.logger.info "finished_my_thing", done_count: count 
+  end
+end
+
+# RIGHT, will result in one "job_done" message, which will include the 'done_count' field
+class MyJob
+  def perform
+    count = MyApp.do_thing
+    Appydays::Loggable::SidekiqJobLogger.set_job_tags(done_count: count)
+  end
+end
+```
+
 ### HTTParty
 
 Well structured logs for HTTParty!

lib/appydays/loggable/sidekiq_job_logger.rb

@@ -43,11 +43,13 @@ def call(item, _queue, &)
     yield
     duration = self.elapsed(start)
     log_method = duration >= self.slow_job_seconds ? :warn : :info
-    self.logger.send(log_method, "job_done", duration: duration * 1000)
+    self.logger.send(log_method, "job_done", duration: duration * 1000, **self.class.job_tags)
   rescue StandardError
     # Do not log the error since it is probably a sidekiq retry error
-    self.logger.error("job_fail", duration: self.elapsed(start) * 1000)
+    self.logger.error("job_fail", duration: self.elapsed(start) * 1000, **self.class.job_tags)
     raise
+  ensure
+    self.class.job_tags.clear
   end
 
   protected def elapsed(start)
@@ -58,6 +60,18 @@ def call(item, _queue, &)
     return ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
   end
 
+  # Set job tags that get logged out in the "job_done" and "job_fail" messages.
+  # See README for more info.
+  # We do NOT merge the job_tags in with critical errors (death and job_error),
+  # since those will log the job args, and they aren't properly tested right now.
+  # We may add support in the future.
+  def self.set_job_tags(**tags)
+    Thread.current[:appydays_sidekiq_job_logger_job_tags] ||= {}
+    Thread.current[:appydays_sidekiq_job_logger_job_tags].merge!(tags)
+  end
+
+  def self.job_tags = Thread.current[:appydays_sidekiq_job_logger_job_tags] || {}
+
   def self.error_handler(ex, ctx)
     # ctx looks like:
     # {

spec/appydays/loggable_spec.rb

@@ -349,6 +349,53 @@ def log(&block)
       )
       expect(lines[0]).to_not include("exception")
     end
+
+    it "can add log fields to the job_done message" do
+      lines = log do
+        described_class.set_job_tags(tag1: "hi")
+      end
+      expect(lines).to contain_exactly(
+        include_json(
+          level: "info",
+          name: "TestLogger",
+          message: "job_done",
+          context: include("tag1" => "hi"),
+        ),
+      )
+    end
+
+    it "can add log fields to the job_fail message" do
+      lines = log do
+        described_class.set_job_tags(tag1: "hi")
+        raise "hello"
+      end
+      expect(lines).to contain_exactly(
+        include_json(
+          level: "error",
+          name: "TestLogger",
+          message: "job_fail",
+          context: include("tag1" => "hi"),
+        ),
+      )
+    end
+
+    it "clears job tags after the job" do
+      lines = log do
+        described_class.set_job_tags(tag1: "hi")
+      end
+      expect(lines).to contain_exactly(
+        include_json(
+          context: include("tag1" => "hi"),
+        ),
+      )
+
+      lines = log
+      expect(lines).to contain_exactly(
+        include_json(
+          context: not_include("tag1"),
+        ),
+      )
+    end
   end
 
   describe "Sequel Logging" do