Merge pull request #173 from rage-rb/deferred-log-context

Pass all of log data to deferred tasks

Author: rsamoilov

lib/rage/deferred/context.rb

@@ -6,14 +6,15 @@
 #
 class Rage::Deferred::Context
   def self.build(task, args, kwargs, storage: nil)
-    request_id = Thread.current[:rage_logger][:tags][0] if Thread.current[:rage_logger]
+    logger = Thread.current[:rage_logger]
 
     [
       task,
       args.empty? ? nil : args,
       kwargs.empty? ? nil : kwargs,
       nil,
-      request_id
+      logger&.dig(:tags),
+      logger&.dig(:context)
     ]
   end
 
@@ -37,7 +38,11 @@ def self.inc_attempts(context)
     context[3] = context[3].to_i + 1
   end
 
-  def self.get_request_id(context)
+  def self.get_log_tags(context)
     context[4]
   end
+
+  def self.get_log_context(context)
+    context[5]
+  end
 end

lib/rage/deferred/task.rb

@@ -40,35 +40,37 @@ module Rage::Deferred::Task
   def perform
   end
 
-  # @private
-  def __with_optional_log_tag(tag)
-    if tag
-      Rage.logger.tagged(tag) { yield }
-    else
-      yield
-    end
-  end
-
   # @private
   def __perform(context)
     args = Rage::Deferred::Context.get_args(context)
     kwargs = Rage::Deferred::Context.get_kwargs(context)
     attempts = Rage::Deferred::Context.get_attempts(context)
-    request_id = Rage::Deferred::Context.get_request_id(context)
 
-    log_context = { task: self.class.name }
-    log_context[:attempt] = attempts + 1 if attempts
+    restore_log_info(context)
+
+    task_log_context = { task: self.class.name }
+    task_log_context[:attempt] = attempts + 1 if attempts
 
-    Rage.logger.with_context(log_context) do
-      __with_optional_log_tag(request_id) do
-        perform(*args, **kwargs)
-        true
-      rescue Rage::Deferred::TaskFailed
-        false
-      rescue Exception => e
-        Rage.logger.error("Deferred task failed with exception: #{e.class} (#{e.message}):\n#{e.backtrace.join("\n")}")
-        false
-      end
+    Rage.logger.with_context(task_log_context) do
+      perform(*args, **kwargs)
+      true
+    rescue Rage::Deferred::TaskFailed
+      false
+    rescue Exception => e
+      Rage.logger.error("Deferred task failed with exception: #{e.class} (#{e.message}):\n#{e.backtrace.join("\n")}")
+      false
+    end
+  end
+
+  private def restore_log_info(context)
+    log_tags = Rage::Deferred::Context.get_log_tags(context)
+    log_context = Rage::Deferred::Context.get_log_context(context)
+
+    if log_tags.is_a?(Array)
+      Thread.current[:rage_logger] = { tags: log_tags, context: log_context }
+    elsif log_tags
+      # support the previous format where only `request_id` was passed
+      Thread.current[:rage_logger] = { tags: [log_tags], context: {} }
     end
   end
 
@@ -83,6 +85,8 @@ def enqueue(*args, delay: nil, delay_until: nil, **kwargs)
         delay:,
         delay_until:
       )
+
+      nil
     end
 
     # @private

lib/rage/logger/logger.rb

@@ -125,10 +125,11 @@ def with_context(context)
   #     Rage.logger.info "success"
   #   end
   def tagged(tag)
-    (Thread.current[:rage_logger] ||= { tags: [], context: {} })[:tags] << tag
+    old_tags = (Thread.current[:rage_logger] ||= { tags: [], context: {} })[:tags]
+    Thread.current[:rage_logger][:tags] = [*old_tags, tag]
     yield(self)
   ensure
-    Thread.current[:rage_logger][:tags].pop
+    Thread.current[:rage_logger][:tags] = old_tags
   end
 
   alias_method :with_tag, :tagged

spec/deferred/context_spec.rb

@@ -27,12 +27,12 @@
 
     context "when Thread.current[:rage_logger] is set" do
       before do
-        Thread.current[:rage_logger] = { tags: ["req-123"] }
+        Thread.current[:rage_logger] = { tags: ["req-123", "test"] }
       end
 
-      it "builds context including request_id" do
+      it "builds context including log tags" do
         context = described_class.build(task, args, kwargs)
-        expect(context[4]).to eq("req-123")
+        expect(context[4]).to eq(["req-123", "test"])
       end
     end
   end
@@ -65,10 +65,17 @@
     end
   end
 
-  describe ".get_request_id" do
-    it "returns the request id from context" do
-      context = [nil, nil, nil, nil, "req-456"]
-      expect(described_class.get_request_id(context)).to eq("req-456")
+  describe ".get_log_tags" do
+    it "returns log tags from context" do
+      context = [nil, nil, nil, nil, ["tag-1", "tag-2"]]
+      expect(described_class.get_log_tags(context)).to eq(["tag-1", "tag-2"])
+    end
+  end
+
+  describe ".get_log_context" do
+    it "returns log tags from context" do
+      context = [nil, nil, nil, nil, nil, { test: true }]
+      expect(described_class.get_log_context(context)).to eq({ test: true })
     end
   end
 

spec/deferred/task_spec.rb

@@ -30,6 +30,11 @@ def perform(arg, kwarg:)
       expect(queue).to have_received(:enqueue).with(context, delay: 10, delay_until: nil)
     end
 
+    it "returns nil" do
+      result = task_class.enqueue("value", kwarg: "value2", delay: 10)
+      expect(result).to be_nil
+    end
+
     it "correctly passes delay_until" do
       time = Time.now
       task_class.enqueue(delay_until: time)
@@ -75,7 +80,8 @@ def perform(arg, kwarg:)
 
     context "when task succeeds" do
       before do
-        allow(Rage::Deferred::Context).to receive(:get_request_id).with(context).and_return("request-id")
+        allow(Rage::Deferred::Context).to receive(:get_log_tags).with(context).and_return(["request-id"])
+        allow(Rage::Deferred::Context).to receive(:get_log_context).with(context).and_return({})
         allow(task).to receive(:perform)
       end
 
@@ -87,7 +93,7 @@ def perform(arg, kwarg:)
       it "logs with context and tag" do
         task.__perform(context)
         expect(logger).to have_received(:with_context).with({ task: "MyTask", attempt: 2 })
-        expect(logger).to have_received(:tagged).with("request-id")
+        expect(Thread.current[:rage_logger]).to eq({ tags: ["request-id"], context: {} })
       end
 
       it "returns true" do
@@ -102,7 +108,8 @@ def perform(arg, kwarg:)
 
     context "when request_id is not present" do
       before do
-        allow(Rage::Deferred::Context).to receive(:get_request_id).with(context).and_return(nil)
+        allow(Rage::Deferred::Context).to receive(:get_log_tags).with(context).and_return(nil)
+        allow(Rage::Deferred::Context).to receive(:get_log_context).with(context).and_return({})
         allow(task).to receive(:perform)
       end
 
@@ -116,7 +123,8 @@ def perform(arg, kwarg:)
       let(:error) { StandardError.new("Something went wrong") }
 
       before do
-        allow(Rage::Deferred::Context).to receive(:get_request_id).with(context).and_return(nil)
+        allow(Rage::Deferred::Context).to receive(:get_log_tags).with(context).and_return(nil)
+        allow(Rage::Deferred::Context).to receive(:get_log_context).with(context).and_return({})
         allow(task).to receive(:perform).and_raise(error)
         allow(error).to receive(:backtrace).and_return(["line 1", "line 2"])
       end

spec/logger_spec.rb

@@ -108,6 +108,19 @@
 
       expect(result).to eq(:success)
     end
+
+    context "with other process referencing the tags" do
+      it "doesn't mutate the tags storage" do
+        referenced_tags = nil
+
+        subject.tagged("rspec") do
+          referenced_tags = Thread.current[:rage_logger][:tags]
+          subject.info "test passed"
+        end
+
+        expect(referenced_tags).to eq(["my_test_tag", "rspec"])
+      end
+    end
   end
 
   context "with context" do
@@ -153,6 +166,19 @@
 
       expect(result).to eq(:ok)
     end
+
+    context "with other process referencing the context" do
+      it "doesn't mutate the context storage" do
+        referenced_context = nil
+
+        subject.with_context(rspec: true) do
+          referenced_context = Thread.current[:rage_logger][:context]
+          subject.info "text"
+        end
+
+        expect(referenced_context).to eq({ rspec: true })
+      end
+    end
   end
 
   context "outside the request/response cycle" do