Fix request id tracking and show it only logs that are emitted during a Rails request

ndbroadbent · ndbroadbent · commit ebea73a26ce8 · 2026-01-23T19:16:16.000+13:00
diff --git a/lib/log_struct/enums/log_field.rb b/lib/log_struct/enums/log_field.rb
@@ -32,7 +32,7 @@ class LogField < T::Enum
       SourceIp = new(:source_ip)
       UserAgent = new(:user_agent)
       Referer = new(:referer)
-      RequestId = new(:request_id)
+      RequestId = new(:req_id)
       Host = new(:host)
       ContentType = new(:content_type)
       Accept = new(:accept)
diff --git a/lib/log_struct/integrations.rb b/lib/log_struct/integrations.rb
@@ -2,6 +2,7 @@
 # frozen_string_literal: true
 
 require_relative "integrations/integration_interface"
+require_relative "integrations/request_context"
 require_relative "integrations/active_job"
 require_relative "integrations/active_record"
 require_relative "integrations/rack_error_handler"
@@ -77,6 +78,7 @@ def self.setup_non_middleware_integrations(config)
 
     sig { params(config: LogStruct::Configuration).void }
     def self.setup_middleware_integrations(config)
+      Integrations::RequestContext.setup(config)
       Integrations::HostAuthorization.setup(config) if config.integrations.enable_host_authorization
       Integrations::RackErrorHandler.setup(config) if config.integrations.enable_rack_error_handler
     end
diff --git a/lib/log_struct/integrations/action_mailer/metadata_collection.rb b/lib/log_struct/integrations/action_mailer/metadata_collection.rb
@@ -54,12 +54,6 @@ def self.add_current_tags_to_log_data(log_data)
           end
           log_data[:tags] = tags if tags.present?
 
-          # Get request_id from ActionDispatch if available
-          if ::ActionDispatch::Request.respond_to?(:current_request_id) &&
-              T.unsafe(::ActionDispatch::Request).current_request_id.present?
-            log_data[:request_id] = T.unsafe(::ActionDispatch::Request).current_request_id
-          end
-
           # Get job_id from ActiveJob if available
           if defined?(::ActiveJob::Logging) && ::ActiveJob::Logging.respond_to?(:job_id) &&
               T.unsafe(::ActiveJob::Logging).job_id.present?
diff --git a/lib/log_struct/integrations/host_authorization.rb b/lib/log_struct/integrations/host_authorization.rb
@@ -63,7 +63,6 @@ def self.setup(config)
             source_ip: request.ip,
             user_agent: request.user_agent,
             referer: request.referer,
-            request_id: request.request_id,
             x_forwarded_for: request.x_forwarded_for,
             allowed_hosts: allowed_hosts_array&.empty? ? nil : allowed_hosts_array,
             allow_ip_hosts: allow_ip_hosts_value
diff --git a/lib/log_struct/integrations/lograge.rb b/lib/log_struct/integrations/lograge.rb
@@ -101,6 +101,12 @@ def process_headers(event, options)
           headers = event.payload[:headers]
           return if headers.blank?
 
+          # Rails' ActionDispatch::RequestId middleware stores request_id in headers
+          # Only set if not already present in payload (payload takes precedence)
+          if options[:request_id].blank? && headers["action_dispatch.request_id"].present?
+            options[:request_id] = headers["action_dispatch.request_id"]
+          end
+
           options[:user_agent] = headers["HTTP_USER_AGENT"]
           options[:referer] = headers["HTTP_REFERER"]
           options[:content_type] = headers["CONTENT_TYPE"]
@@ -144,7 +150,6 @@ def build_request_log(data)
             view: view,
             database: db,
             params: params,
-            request_id: normalized_data[:request_id]&.to_s,
             source_ip: normalized_data[:source_ip]&.to_s,
             user_agent: normalized_data[:user_agent]&.to_s,
             referer: normalized_data[:referer]&.to_s,
diff --git a/lib/log_struct/integrations/rack_error_handler/middleware.rb b/lib/log_struct/integrations/rack_error_handler/middleware.rb
@@ -71,7 +71,6 @@ def call(env)
               http_method: env["REQUEST_METHOD"],
               user_agent: env["HTTP_USER_AGENT"],
               referer: env["HTTP_REFERER"],
-              request_id: request.request_id,
               message: ip_spoof_error.message,
               client_ip: env["HTTP_CLIENT_IP"],
               x_forwarded_for: env["HTTP_X_FORWARDED_FOR"],
@@ -90,7 +89,6 @@ def call(env)
                 source_ip: request.remote_ip,
                 user_agent: request.user_agent,
                 referer: request.referer,
-                request_id: request.request_id,
                 message: error.message,
                 timestamp: Time.now
               )
@@ -137,7 +135,6 @@ def perform_remote_ip_check!(request)
         def extract_request_context(env, request = nil)
           request ||= ::ActionDispatch::Request.new(env)
           {
-            request_id: request.request_id,
             path: request.path,
             method: request.method,
             user_agent: request.user_agent,
diff --git a/lib/log_struct/integrations/request_context.rb b/lib/log_struct/integrations/request_context.rb
@@ -0,0 +1,27 @@
+# typed: strict
+# frozen_string_literal: true
+
+require_relative "request_context/middleware"
+
+module LogStruct
+  module Integrations
+    # Request context integration that captures request_id for all logs
+    module RequestContext
+      extend T::Sig
+      extend IntegrationInterface
+
+      sig { override.params(config: LogStruct::Configuration).returns(T.nilable(T::Boolean)) }
+      def self.setup(config)
+        return nil unless config.enabled
+
+        # Insert after RequestId middleware so request_id is available
+        ::Rails.application.middleware.insert_after(
+          ::ActionDispatch::RequestId,
+          Integrations::RequestContext::Middleware
+        )
+
+        true
+      end
+    end
+  end
+end
diff --git a/lib/log_struct/integrations/request_context/middleware.rb b/lib/log_struct/integrations/request_context/middleware.rb
@@ -0,0 +1,28 @@
+# typed: strict
+# frozen_string_literal: true
+
+module LogStruct
+  module Integrations
+    module RequestContext
+      # Middleware that captures request_id and stores it in SemanticLogger's
+      # named_tags so all logs during the request include the request_id.
+      class Middleware
+        extend T::Sig
+
+        sig { params(app: T.untyped).void }
+        def initialize(app)
+          @app = app
+        end
+
+        sig { params(env: T.untyped).returns(T.untyped) }
+        def call(env)
+          request = ::ActionDispatch::Request.new(env)
+          ::SemanticLogger.push_named_tags(request_id: request.request_id)
+          @app.call(env)
+        ensure
+          ::SemanticLogger.pop_named_tags
+        end
+      end
+    end
+  end
+end
diff --git a/lib/log_struct/log/request.rb b/lib/log_struct/log/request.rb
@@ -33,7 +33,6 @@ class Request < T::Struct
       const :source_ip, T.nilable(String), default: nil
       const :user_agent, T.nilable(String), default: nil
       const :referer, T.nilable(String), default: nil
-      const :request_id, T.nilable(String), default: nil
 
       # Event-specific fields
       const :format, T.nilable(Symbol), default: nil
@@ -69,7 +68,6 @@ def to_h
         h[LogField::SourceIp] = source_ip unless source_ip.nil?
         h[LogField::UserAgent] = user_agent unless user_agent.nil?
         h[LogField::Referer] = referer unless referer.nil?
-        h[LogField::RequestId] = request_id unless request_id.nil?
         h[LogField::Format] = format unless format.nil?
         h[LogField::Controller] = controller unless controller.nil?
         h[LogField::Action] = action unless action.nil?
diff --git a/lib/log_struct/log/security.rb b/lib/log_struct/log/security.rb
@@ -20,16 +20,14 @@ class BaseFields < T::Struct
         const :source_ip, T.nilable(String), default: nil
         const :user_agent, T.nilable(String), default: nil
         const :referer, T.nilable(String), default: nil
-        const :request_id, T.nilable(String), default: nil
 
         Kwargs = T.type_alias do
           {
             path: T.nilable(String),
             http_method: T.nilable(String),
             source_ip: T.nilable(String),
             user_agent: T.nilable(String),
-            referer: T.nilable(String),
-            request_id: T.nilable(String)
+            referer: T.nilable(String)
           }
         end
 
@@ -40,8 +38,7 @@ def to_kwargs
             http_method: http_method,
             source_ip: source_ip,
             user_agent: user_agent,
-            referer: referer,
-            request_id: request_id
+            referer: referer
           }
         end
       end
diff --git a/lib/log_struct/log/security/blocked_host.rb b/lib/log_struct/log/security/blocked_host.rb
@@ -34,7 +34,6 @@ class BlockedHost < T::Struct
         const :source_ip, T.nilable(String), default: nil
         const :user_agent, T.nilable(String), default: nil
         const :referer, T.nilable(String), default: nil
-        const :request_id, T.nilable(String), default: nil
 
         # Event-specific fields
         const :message, T.nilable(String), default: nil
@@ -65,7 +64,6 @@ def to_h
           h[LogField::SourceIp] = source_ip unless source_ip.nil?
           h[LogField::UserAgent] = user_agent unless user_agent.nil?
           h[LogField::Referer] = referer unless referer.nil?
-          h[LogField::RequestId] = request_id unless request_id.nil?
           h[LogField::Message] = message unless message.nil?
           h[LogField::BlockedHost] = blocked_host unless blocked_host.nil?
           h[LogField::BlockedHosts] = blocked_hosts unless blocked_hosts.nil?
diff --git a/lib/log_struct/log/security/csrf_violation.rb b/lib/log_struct/log/security/csrf_violation.rb
@@ -34,7 +34,6 @@ class CSRFViolation < T::Struct
         const :source_ip, T.nilable(String), default: nil
         const :user_agent, T.nilable(String), default: nil
         const :referer, T.nilable(String), default: nil
-        const :request_id, T.nilable(String), default: nil
 
         # Event-specific fields
         const :message, T.nilable(String), default: nil
@@ -60,7 +59,6 @@ def to_h
           h[LogField::SourceIp] = source_ip unless source_ip.nil?
           h[LogField::UserAgent] = user_agent unless user_agent.nil?
           h[LogField::Referer] = referer unless referer.nil?
-          h[LogField::RequestId] = request_id unless request_id.nil?
           h[LogField::Message] = message unless message.nil?
           h
         end
diff --git a/lib/log_struct/log/security/ip_spoof.rb b/lib/log_struct/log/security/ip_spoof.rb
@@ -34,7 +34,6 @@ class IPSpoof < T::Struct
         const :source_ip, T.nilable(String), default: nil
         const :user_agent, T.nilable(String), default: nil
         const :referer, T.nilable(String), default: nil
-        const :request_id, T.nilable(String), default: nil
 
         # Event-specific fields
         const :message, T.nilable(String), default: nil
@@ -62,7 +61,6 @@ def to_h
           h[LogField::SourceIp] = source_ip unless source_ip.nil?
           h[LogField::UserAgent] = user_agent unless user_agent.nil?
           h[LogField::Referer] = referer unless referer.nil?
-          h[LogField::RequestId] = request_id unless request_id.nil?
           h[LogField::Message] = message unless message.nil?
           h[LogField::ClientIp] = client_ip unless client_ip.nil?
           h[LogField::XForwardedFor] = x_forwarded_for unless x_forwarded_for.nil?
diff --git a/lib/log_struct/semantic_logger/formatter.rb b/lib/log_struct/semantic_logger/formatter.rb
@@ -79,6 +79,15 @@ def call(log, logger)
           )
           @logstruct_formatter.call(log.level, log.time, log.name, plain_log)
         end
+
+        # Add request_id from named_tags if present
+        request_id = log.named_tags[:request_id]
+        if request_id
+          data = JSON.parse(json)
+          data["req_id"] = request_id
+          json = data.to_json
+        end
+
         # SemanticLogger appenders typically add their own newline. Avoid double newlines by stripping ours.
         json.end_with?("\n") ? json.chomp : json
       end
diff --git a/lib/log_struct/shared/add_request_fields.rb b/lib/log_struct/shared/add_request_fields.rb
@@ -20,7 +20,6 @@ def add_request_fields(hash)
           hash[LogField::SourceIp.serialize] = source_ip if source_ip
           hash[LogField::UserAgent.serialize] = user_agent if user_agent
           hash[LogField::Referer.serialize] = referer if referer
-          hash[LogField::RequestId.serialize] = request_id if request_id
         end
       end
     end
diff --git a/lib/log_struct/shared/interfaces/request_fields.rb b/lib/log_struct/shared/interfaces/request_fields.rb
@@ -29,10 +29,6 @@ def user_agent
         sig { abstract.returns(T.nilable(String)) }
         def referer
         end
-
-        sig { abstract.returns(T.nilable(String)) }
-        def request_id
-        end
       end
     end
   end
diff --git a/rails_test_app/templates/test/integration/request_logging_test.rb b/rails_test_app/templates/test/integration/request_logging_test.rb
@@ -81,4 +81,37 @@ def test_request_log_contains_controller_and_action
     assert_equal "test_basic", parsed["action"], "Must have action field"
     assert_equal "/logging/basic", parsed["path"], "Must have correct path"
   end
+
+  def test_all_logs_during_request_have_request_id
+    get "/logging/basic"
+
+    assert_response :success
+
+    ::SemanticLogger.flush
+    @log_output.rewind
+    output = @log_output.read.to_s
+
+    # Parse all JSON log lines
+    json_logs = output.lines.filter_map do |line|
+      JSON.parse(line) if line.strip.start_with?("{")
+    rescue JSON::ParserError
+      nil
+    end
+
+    assert_operator json_logs.size, :>=, 1, "Expected at least 1 JSON log line"
+
+    # Find the request log to get the request_id
+    request_log = json_logs.find { |log| log["evt"] == "request" }
+
+    assert request_log, "Expected a request log"
+
+    request_id = request_log["req_id"]
+
+    assert request_id, "Request log must have req_id"
+
+    # All logs during the request should have the same req_id
+    json_logs.each do |log|
+      assert_equal request_id, log["req_id"], "All logs must have req_id. Log missing it: #{log.inspect}"
+    end
+  end
 end
diff --git a/test/log_struct/integrations/action_mailer/metadata_collection_test.rb b/test/log_struct/integrations/action_mailer/metadata_collection_test.rb
@@ -24,19 +24,16 @@ class ActionMailerMetadataCollectionTest < ActiveSupport::TestCase
     assert_equal 0, data[:attachment_count]
   end
 
-  test "add_context_metadata gathers tags and request_id when available" do
+  test "add_context_metadata gathers tags when available" do
     data = {}
 
     # Stub ActiveSupport::TaggedLogging.current_tags
     ActiveSupport::TaggedLogging.define_singleton_method(:current_tags) { ["req:abc"] }
 
-    # Stub ActionDispatch::Request.current_request_id
-    ActionDispatch::Request.define_singleton_method(:current_request_id) { "rid-123" }
-
     MetadataCollection.add_context_metadata(Object.new, data)
 
     assert_equal ["req:abc"], data[:tags]
-    assert_equal "rid-123", data[:request_id]
+    # Note: request_id is now handled centrally by serialize_common via LogStruct::Current
   end
 
   test "add_context_metadata includes job_id when ActiveJob::Logging.job_id is available" do
diff --git a/test/log_struct/integrations/lograge_formatter_test.rb b/test/log_struct/integrations/lograge_formatter_test.rb
@@ -96,7 +96,6 @@ def test_includes_custom_options_and_request_metadata
 
         log = @formatter.call(data)
 
-        assert_equal "req-123", log.request_id
         assert_equal "10.0.0.1", log.source_ip
         assert_equal "TestAgent/1.0", log.user_agent
         assert_equal "example.test", log.host
@@ -106,6 +105,7 @@ def test_includes_custom_options_and_request_metadata
         additional_data = T.must(log.additional_data)
 
         assert_equal "abc-123", additional_data[:user_id]
+        # request_id is now handled by SemanticLogger named_tags, not stored on struct or in additional_data
         refute additional_data.key?(:request_id)
         refute additional_data.key?(:extra_nil)
 
@@ -140,6 +140,46 @@ def test_default_options_include_referer_header
         assert_equal "application/json", options[:content_type]
         assert_equal "application/json", options[:accept]
       end
+
+      def test_extracts_request_id_from_action_dispatch_header
+        event = ActiveSupport::Notifications::Event.new(
+          "process_action.action_controller",
+          Time.now.to_f,
+          Time.now.to_f,
+          "event-id",
+          {
+            host: "example.test",
+            headers: {
+              "action_dispatch.request_id" => "abc-123-request-id",
+              "HTTP_USER_AGENT" => "TestAgent/1.0"
+            }
+          }
+        )
+
+        options = LogStruct::Integrations::Lograge.lograge_default_options(event)
+
+        assert_equal "abc-123-request-id", options[:request_id]
+      end
+
+      def test_prefers_payload_request_id_over_header
+        # If request_id is in both payload and headers, prefer payload
+        event = ActiveSupport::Notifications::Event.new(
+          "process_action.action_controller",
+          Time.now.to_f,
+          Time.now.to_f,
+          "event-id",
+          {
+            request_id: "payload-request-id",
+            headers: {
+              "action_dispatch.request_id" => "header-request-id"
+            }
+          }
+        )
+
+        options = LogStruct::Integrations::Lograge.lograge_default_options(event)
+
+        assert_equal "payload-request-id", options[:request_id]
+      end
     end
   end
 end
diff --git a/tools/codegen/schema_loader.rb b/tools/codegen/schema_loader.rb
