Ensure correct logging for intersecting fibers

lib/rage/controller/api.rb

@@ -155,11 +155,11 @@ def __run_#{action}
                 context = {}
                 append_info_to_payload(context)
 
-                log_context = Thread.current[:rage_logger][:context]
+                log_context = Fiber[:__rage_logger_context]
                 if log_context.empty?
-                  Thread.current[:rage_logger][:context] = context
+                  Fiber[:__rage_logger_context] = context
                 else
-                  Thread.current[:rage_logger][:context] = log_context.merge(context)
+                  Fiber[:__rage_logger_context] = log_context.merge(context)
                 end
               RUBY
             end}

lib/rage/deferred/context.rb

@@ -7,15 +7,13 @@
 # @private
 class Rage::Deferred::Context
   def self.build(task, args, kwargs)
-    logger = Thread.current[:rage_logger]
-
     [
       task,
       args.empty? ? nil : args,
       kwargs.empty? ? nil : kwargs,
       nil,
-      logger&.dig(:tags),
-      logger&.dig(:context),
+      Fiber[:__rage_logger_tags],
+      Fiber[:__rage_logger_context],
       nil
     ]
   end

lib/rage/deferred/task.rb

@@ -93,10 +93,10 @@ def __perform(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 }
+      Fiber[:__rage_logger_tags], Fiber[:__rage_logger_context] = log_tags, log_context
     elsif log_tags
       # support the previous format where only `request_id` was passed
-      Thread.current[:rage_logger] = { tags: [log_tags], context: {} }
+      Fiber[:__rage_logger_tags], Fiber[:__rage_logger_context] = [log_tags], {}
     end
   end
 

lib/rage/fiber_scheduler.rb

@@ -126,10 +126,7 @@ def fiber(&block)
       end
     else
       # the fiber was created in the user code
-      logger = Thread.current[:rage_logger]
-
       Fiber.new(blocking: false) do
-        Thread.current[:rage_logger] = logger
         Rage::Telemetry.tracer.span_core_fiber_spawn(parent:) do
           Fiber.current.__set_result(block.call)
         end

lib/rage/log_processor.rb

@@ -21,15 +21,13 @@ def add_custom_tags(tag_objects)
   end
 
   def finalize_request_logger(env, response, params)
-    logger = Thread.current[:rage_logger]
-
     duration = (
-      (Process.clock_gettime(Process::CLOCK_MONOTONIC) - logger[:request_start]) * 1000
+      (Process.clock_gettime(Process::CLOCK_MONOTONIC) - Fiber[:__rage_logger_request_start]) * 1000
     ).round(2)
 
-    logger[:final] = { env:, params:, response:, duration: }
+    Fiber[:__rage_logger_final] = { env:, params:, response:, duration: }
     Rage.logger.info(nil)
-    logger[:final] = nil
+    Fiber[:__rage_logger_final] = nil
   end
 
   private
@@ -106,11 +104,9 @@ def rebuild!
       def init_request_logger(env)
         env["rage.request_id"] ||= Iodine::Rack::Utils.gen_request_tag
 
-        Thread.current[:rage_logger] = {
-          tags: #{build_static_tags},
-          context: #{build_static_context},
-          request_start: Process.clock_gettime(Process::CLOCK_MONOTONIC)
-        }
+        Fiber[:__rage_logger_tags] = #{build_static_tags}
+        Fiber[:__rage_logger_context] = #{build_static_context}
+        Fiber[:__rage_logger_request_start] = Process.clock_gettime(Process::CLOCK_MONOTONIC)
       end
     RUBY
   end

lib/rage/logger/json_formatter.rb

@@ -26,8 +26,7 @@ def initialize
   end
 
   def call(severity, timestamp, _, message)
-    logger = Thread.current[:rage_logger] || { tags: [], context: {} }
-    tags, context = logger[:tags], logger[:context]
+    tags, context = Fiber[:__rage_logger_tags] || [], Fiber[:__rage_logger_context] || {}
 
     if !context.empty?
       context_msg = ""
@@ -50,7 +49,7 @@ def call(severity, timestamp, _, message)
       msg << "],"
     end
 
-    if (final = logger[:final])
+    if (final = Fiber[:__rage_logger_final])
       params, env = final[:params], final[:env]
       if params && params[:controller]
         return "#{tags_msg}\"timestamp\":\"#{timestamp}\",\"pid\":\"#{@pid}\",\"level\":\"info\",\"method\":\"#{env["REQUEST_METHOD"]}\",\"path\":\"#{env["PATH_INFO"]}\",\"controller\":\"#{Rage::Router::Util.path_to_name(params[:controller])}\",\"action\":\"#{params[:action]}\",#{context_msg}\"status\":#{final[:response][0]},\"duration\":#{final[:duration]}}\n"

lib/rage/logger/logger.rb

@@ -140,17 +140,17 @@ def dynamic_context=(dynamic_context)
   #     Rage.logger.info "cache miss"
   #   end
   def with_context(context)
-    old_context = (Thread.current[:rage_logger] ||= { tags: [], context: {} })[:context]
+    old_context = (Fiber[:__rage_logger_context] ||= {})
 
     if old_context.empty? # there's nothing in the context yet
-      Thread.current[:rage_logger][:context] = context
+      Fiber[:__rage_logger_context] = context
     else # it's not the first `with_context` call in the chain
-      Thread.current[:rage_logger][:context] = old_context.merge(context)
+      Fiber[:__rage_logger_context] = old_context.merge(context)
     end
 
     yield(self)
   ensure
-    Thread.current[:rage_logger][:context] = old_context
+    Fiber[:__rage_logger_context] = old_context
   end
 
   # Add a custom tag to an entry.
@@ -161,11 +161,11 @@ def with_context(context)
   #     Rage.logger.info "success"
   #   end
   def tagged(*tags)
-    old_tags = (Thread.current[:rage_logger] ||= { tags: [], context: {} })[:tags]
-    Thread.current[:rage_logger][:tags] = old_tags + tags
+    old_tags = (Fiber[:__rage_logger_tags] ||= [])
+    Fiber[:__rage_logger_tags] = old_tags + tags
     yield(self)
   ensure
-    Thread.current[:rage_logger][:tags] = old_tags
+    Fiber[:__rage_logger_tags] = old_tags
   end
 
   alias_method :with_tag, :tagged
@@ -217,17 +217,16 @@ def #{level_name}(msg = nil)
 
         parameters = Rage::Internal.build_arguments(call_method, {
           severity: ":#{level_name}",
-          tags: "logger[:tags].freeze",
-          context: "logger[:context].freeze",
+          tags: "Fiber[:__rage_logger_tags].freeze",
+          context: "Fiber[:__rage_logger_context].freeze",
           message: "block_given? ? yield : msg",
-          request_info: "logger[:final].freeze"
+          request_info: "Fiber[:__rage_logger_final].freeze"
         })
 
         <<~RUBY
           def #{level_name}(msg = nil)
             #{with_dynamic_tags_and_context do
               <<~RUBY
-                logger = Thread.current[:rage_logger] || { tags: [], context: {} }
                 @external_logger.wrapped.call(#{parameters})
               RUBY
             end}

lib/rage/logger/text_formatter.rb

@@ -24,15 +24,14 @@ def initialize
   end
 
   def call(severity, timestamp, _, message)
-    logger = Thread.current[:rage_logger] || { tags: [], context: {} }
-    tags, context = logger[:tags], logger[:context]
+    tags, context = Fiber[:__rage_logger_tags] || [], Fiber[:__rage_logger_context] || {}
 
     if !context.empty?
       context_msg = ""
       context.each { |k, v| context_msg << "#{k}=#{v} " }
     end
 
-    if (final = logger[:final])
+    if (final = Fiber[:__rage_logger_final])
       params, env = final[:params], final[:env]
       tags = tags.map { |tag| "[#{tag}]" }.join
 

spec/deferred/context_spec.rb

@@ -5,10 +5,10 @@
     let(:kwargs) { { key: "value" } }
 
     after do
-      Thread.current[:rage_logger] = nil
+      Fiber[:__rage_logger_tags] = nil
     end
 
-    context "when Thread.current[:rage_logger] is not set" do
+    context "when rage_logger is not set" do
       it "builds context with nil request_id" do
         context = described_class.build(task, args, kwargs)
         expect(context[0]).to eq(task)
@@ -25,9 +25,9 @@
       end
     end
 
-    context "when Thread.current[:rage_logger] is set" do
+    context "when rage_logger is set" do
       before do
-        Thread.current[:rage_logger] = { tags: ["req-123", "test"] }
+        Fiber[:__rage_logger_tags] = ["req-123", "test"]
       end
 
       it "builds context including log tags" do

spec/deferred/task_spec.rb

@@ -86,7 +86,8 @@ def perform(arg, kwarg:)
       end
 
       after do
-        Thread.current[:rage_logger] = nil
+        Fiber[:__rage_logger_tags] = nil
+        Fiber[:__rage_logger_context] = nil
       end
 
       it "calls perform with correct arguments" do
@@ -97,7 +98,8 @@ 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(Thread.current[:rage_logger]).to eq({ tags: ["request-id"], context: {} })
+        expect(Fiber[:__rage_logger_tags]).to eq(["request-id"])
+        expect(Fiber[:__rage_logger_context]).to eq({})
       end
 
       it "returns true" do

spec/json_formatter_spec.rb

@@ -8,7 +8,9 @@
   let(:message) { "test message" }
 
   after do
-    Thread.current[:rage_logger] = nil
+    Fiber[:__rage_logger_tags] = nil
+    Fiber[:__rage_logger_context] = nil
+    Fiber[:__rage_logger_final] = nil
   end
 
   context "with no logger info" do
@@ -37,7 +39,8 @@
 
   context "with one tag" do
     before do
-      Thread.current[:rage_logger] = { tags: ["json-test-tag"], context: {} }
+      Fiber[:__rage_logger_tags] = ["json-test-tag"]
+      Fiber[:__rage_logger_context] = {}
     end
 
     it "correctly formats the message" do
@@ -52,7 +55,8 @@
 
     context "with custom context" do
       before do
-        Thread.current[:rage_logger] = { tags: ["json-test-tag"], context: { user_id: "test-1", account_id: "test-2" } }
+        Fiber[:__rage_logger_tags] = ["json-test-tag"]
+        Fiber[:__rage_logger_context] = { user_id: "test-1", account_id: "test-2" }
       end
 
       it "correctly formats the message" do
@@ -71,10 +75,8 @@
 
   context "with multiple tags" do
     before do
-      Thread.current[:rage_logger] = {
-        tags: ["json-test-tag-1", "json-test-tag-2"],
-        context: {}
-      }
+      Fiber[:__rage_logger_tags] = ["json-test-tag-1", "json-test-tag-2"]
+      Fiber[:__rage_logger_context] = {}
     end
 
     it "correctly formats the message" do
@@ -89,10 +91,8 @@
 
     context "with custom context" do
       before do
-        Thread.current[:rage_logger] = {
-          tags: ["json-test-tag-1", "json-test-tag-2"],
-          context: { user_id: "test-1", account_id: "test-2" }
-        }
+        Fiber[:__rage_logger_tags] = ["json-test-tag-1", "json-test-tag-2"]
+        Fiber[:__rage_logger_context] = { user_id: "test-1", account_id: "test-2" }
       end
 
       it "correctly formats the message" do
@@ -113,15 +113,13 @@
     before do
       stub_const("UserProfilesController", double(name: "UserProfilesController"))
 
-      Thread.current[:rage_logger] = {
-        tags: ["json-test-tag"],
-        context: {},
-        final: {
-          env: { "REQUEST_METHOD" => "POST", "PATH_INFO" => "/user_profiles/12345" },
-          params: { controller: "user_profiles", action: "create" },
-          response: [207, {}, []],
-          duration: 1.234
-        }
+      Fiber[:__rage_logger_tags] = ["json-test-tag"]
+      Fiber[:__rage_logger_context] = {}
+      Fiber[:__rage_logger_final] = {
+        env: { "REQUEST_METHOD" => "POST", "PATH_INFO" => "/user_profiles/12345" },
+        params: { controller: "user_profiles", action: "create" },
+        response: [207, {}, []],
+        duration: 1.234
       }
     end
 
@@ -142,7 +140,7 @@
 
     context "with custom tags" do
       before do
-        Thread.current[:rage_logger][:tags] << "custom-tag-1" << "custom-tag-2"
+        Fiber[:__rage_logger_tags] << "custom-tag-1" << "custom-tag-2"
       end
 
       it "correctly formats the message" do
@@ -162,7 +160,7 @@
 
       context "with custom context" do
         before do
-          Thread.current[:rage_logger][:context] = { user_id: "test-1", account_id: "test-2" }
+          Fiber[:__rage_logger_context] = { user_id: "test-1", account_id: "test-2" }
         end
 
         it "correctly formats the message" do
@@ -186,7 +184,7 @@
 
     context "with custom context" do
       before do
-        Thread.current[:rage_logger][:context] = { user_id: "test-1", account_id: "test-2" }
+        Fiber[:__rage_logger_context] = { user_id: "test-1", account_id: "test-2" }
       end
 
       it "correctly formats the message" do
@@ -209,15 +207,13 @@
 
     context "with no controller/action info" do
       before do
-        Thread.current[:rage_logger] = {
-          tags: ["json-test-tag"],
-          context: {},
-          final: {
-            env: { "REQUEST_METHOD" => "POST", "PATH_INFO" => "/user_profiles/12345" },
-            params: nil,
-            response: [207, {}, []],
-            duration: 1.234
-          }
+        Fiber[:__rage_logger_tags] = ["json-test-tag"]
+        Fiber[:__rage_logger_context] = {}
+        Fiber[:__rage_logger_final] = {
+          env: { "REQUEST_METHOD" => "POST", "PATH_INFO" => "/user_profiles/12345" },
+          params: nil,
+          response: [207, {}, []],
+          duration: 1.234
         }
       end
 
@@ -236,8 +232,8 @@
 
       context "with custom tags and context" do
         before do
-          Thread.current[:rage_logger][:tags] << "custom-tag"
-          Thread.current[:rage_logger][:context] = { user_id: "test-1", account_id: "test-2" }
+          Fiber[:__rage_logger_tags] << "custom-tag"
+          Fiber[:__rage_logger_context] = { user_id: "test-1", account_id: "test-2" }
         end
 
         it "correctly formats the message" do

spec/log_processor_spec.rb

@@ -4,7 +4,13 @@
 RSpec.describe Rage::LogProcessor do
   describe "#init_request_logger" do
     let(:log_processor) { described_class.new }
-    let(:log_context) { Thread.current[:rage_logger] }
+    let(:log_context) do
+      {
+        tags: Fiber[:__rage_logger_tags],
+        context: Fiber[:__rage_logger_context],
+        request_start: Fiber[:__rage_logger_request_start]
+      }
+    end
 
     let(:env) { {} }
     let(:request_tag) { "test-request-id-tag" }
@@ -22,7 +28,9 @@
     end
 
     after do
-      Thread.current[:rage_logger] = nil
+      Fiber[:__rage_logger_tags] = nil
+      Fiber[:__rage_logger_context] = nil
+      Fiber[:__rage_logger_request_start] = nil
     end
 
     it "correctly initializes static logger" do