feat: queue time capture for Rack

CHANGELOG.md

@@ -1,3 +1,7 @@
+## Unreleased
+
+- Queue time capture for Rack ([#2838](https://github.com/getsentry/sentry-ruby/pull/2838))
+
 ## 6.3.0
 
 ### Features

sentry-ruby/lib/sentry/configuration.rb

@@ -234,6 +234,12 @@ class Configuration
     # @return [Boolean]
     attr_accessor :send_default_pii
 
+    # Capture queue time from X-Request-Start header set by reverse proxies.
+    # Works with any Rack app behind Nginx, HAProxy, Heroku router, etc.
+    # Defaults to true.
+    # @return [Boolean]
+    attr_accessor :capture_queue_time
+
     # Allow to skip Sentry emails within rake tasks
     # @return [Boolean]
     attr_accessor :skip_rake_integration
@@ -512,6 +518,7 @@ def initialize
       self.enable_backpressure_handling = false
       self.trusted_proxies = []
       self.dsn = ENV["SENTRY_DSN"]
+      self.capture_queue_time = true
 
       spotlight_env = ENV["SENTRY_SPOTLIGHT"]
       spotlight_bool = Sentry::Utils::EnvHelper.env_to_bool(spotlight_env, strict: true)

sentry-ruby/lib/sentry/rack/capture_exceptions.rb

@@ -72,7 +72,14 @@ def start_transaction(env, scope)
         }
 
         transaction = Sentry.continue_trace(env, **options)
-        Sentry.start_transaction(transaction: transaction, custom_sampling_context: { env: env }, **options)
+        transaction = Sentry.start_transaction(transaction: transaction, custom_sampling_context: { env: env }, **options)
+
+        # attach queue time if available
+        if transaction && (queue_time = extract_queue_time(env))
+          transaction.set_data(Span::DataConventions::HTTP_QUEUE_TIME_MS, queue_time)
+        end
+
+        transaction
       end
 
 
@@ -86,6 +93,75 @@ def finish_transaction(transaction, status_code)
       def mechanism
         Sentry::Mechanism.new(type: MECHANISM_TYPE, handled: false)
       end
+
+      # Extracts queue time from the request environment.
+      # Calculates the time (in milliseconds) the request spent waiting in the
+      # web server queue before processing began.
+      #
+      # Subtracts puma.request_body_wait to account for time spent waiting for
+      # slow clients to send the request body, isolating actual queue time.
+      # See: https://github.com/puma/puma/blob/master/docs/architecture.md
+      #
+      # @param env [Hash] Rack env
+      # @return [Float, nil] queue time in milliseconds or nil
+      def extract_queue_time(env)
+        return nil unless Sentry.configuration&.capture_queue_time
+
+        header_value = env["HTTP_X_REQUEST_START"]
+        return nil unless header_value
+
+        request_start = parse_request_start_header(header_value)
+        return nil unless request_start
+
+        total_time_ms = ((Time.now.to_f - request_start) * 1000).round(2)
+
+        # reject negative (clock skew between proxy & app server)
+        return nil unless total_time_ms >= 0
+
+        puma_wait_ms = env["puma.request_body_wait"]
+
+        if puma_wait_ms && puma_wait_ms > 0
+          queue_time_ms = total_time_ms - puma_wait_ms
+          queue_time_ms >= 0 ? queue_time_ms : 0.0 # more sanity check
+        else
+          total_time_ms
+        end
+      rescue StandardError
+        nil
+      end
+
+      # Parses X-Request-Start header value to extract a timestamp.
+      # Supports multiple formats:
+      #   - Nginx: "t=1234567890.123" (seconds with decimal)
+      #   - Heroku, HAProxy 1.9+: "t=1234567890123456" (microseconds)
+      #   - HAProxy < 1.9: "t=1234567890" (seconds)
+      #   - Generic: "1234567890.123" (raw timestamp)
+      #
+      # @param header_value [String] The X-Request-Start header value
+      # @return [Float, nil] Timestamp in seconds since epoch or nil
+      def parse_request_start_header(header_value)
+        return unless header_value
+
+        timestamp = if header_value.start_with?("t=")
+          header_value[2..-1].to_f
+        elsif header_value.match?(/\A\d+(?:\.\d+)?\z/)
+          header_value.to_f
+        else
+          return nil
+        end
+
+        # normalize: timestamps can be in seconds, milliseconds or microseconds
+        # any timestamp > 10 trillion = microseconds
+        if timestamp > 10_000_000_000_000
+          timestamp / 1_000_000.0
+        # timestamp > 10 billion & < 10 trillion = milliseconds
+        elsif timestamp > 10_000_000_000
+          timestamp / 1_000.0
+        else
+          timestamp # assume seconds
+        end
+      rescue StandardError
+      end
     end
   end
 end

sentry-ruby/lib/sentry/span.rb

@@ -49,6 +49,9 @@ module DataConventions
       MESSAGING_DESTINATION_NAME = "messaging.destination.name"
       MESSAGING_MESSAGE_RECEIVE_LATENCY = "messaging.message.receive.latency"
       MESSAGING_MESSAGE_RETRY_COUNT = "messaging.message.retry.count"
+
+      # Time in ms the request spent in the server queue before processing began.
+      HTTP_QUEUE_TIME_MS = "http.server.request.time_in_queue"
     end
 
     STATUS_MAP = {

sentry-ruby/spec/sentry/configuration_spec.rb

@@ -329,6 +329,17 @@
     expect { subject.before_breadcrumb = true }.to raise_error(ArgumentError, "before_breadcrumb must be callable (or nil to disable)")
   end
 
+  describe "#capture_queue_time" do
+    it "defaults to true" do
+      expect(subject.capture_queue_time).to eq(true)
+    end
+
+    it "can be set to false" do
+      subject.capture_queue_time = false
+      expect(subject.capture_queue_time).to eq(false)
+    end
+  end
+
   context 'being initialized with a current environment' do
     before(:each) do
       subject.environment = 'test'

sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb

@@ -660,6 +660,93 @@ def will_be_sampled_by_sdk
     end
   end
 
+  describe "queue time capture" do
+    let(:stack) do
+      app = ->(_) { [200, {}, ['ok']] }
+      Sentry::Rack::CaptureExceptions.new(app)
+    end
+
+    before do
+      perform_basic_setup do |config|
+        config.traces_sample_rate = 1.0
+      end
+    end
+
+    let(:transaction) { last_sentry_event }
+
+    context "with X-Request-Start header" do
+      it "attaches queue time to transaction" do
+        timestamp = Time.now.to_f - 0.05  # 50ms ago
+        env["HTTP_X_REQUEST_START"] = "t=#{timestamp}"
+
+        stack.call(env)
+
+        queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+        expect(queue_time).to be_within(10).of(50)
+      end
+
+      it "subtracts puma.request_body_wait" do
+        Timecop.freeze do
+          timestamp = Time.now.to_f - 0.1  # 100ms ago
+          env["HTTP_X_REQUEST_START"] = "t=#{timestamp}"
+          env["puma.request_body_wait"] = 40  # 40ms waiting for client
+
+          stack.call(env)
+
+          queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+          expect(queue_time).to be_within(10).of(60)  # 100 - 40
+        end
+      end
+
+      it "handles different timestamp formats" do
+        # Heroku/HAProxy microseconds format
+        timestamp_us = ((Time.now.to_f - 0.03) * 1_000_000).to_i
+        env["HTTP_X_REQUEST_START"] = "t=#{timestamp_us}"
+
+        stack.call(env)
+
+        queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+        expect(queue_time).to be_within(10).of(30)
+      end
+    end
+
+    context "without X-Request-Start header" do
+      it "doesn't add queue time data" do
+        stack.call(env)
+
+        queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+        expect(queue_time).to be_nil
+      end
+    end
+
+    context "with invalid header" do
+      it "doesn't add queue time data" do
+        env["HTTP_X_REQUEST_START"] = "invalid"
+
+        stack.call(env)
+
+        queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+        expect(queue_time).to be_nil
+      end
+    end
+
+    context "when capture_queue_time is disabled" do
+      before do
+        Sentry.configuration.capture_queue_time = false
+      end
+
+      it "doesn't capture queue time" do
+        timestamp = Time.now.to_f - 0.05
+        env["HTTP_X_REQUEST_START"] = "t=#{timestamp}"
+
+        stack.call(env)
+
+        queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+        expect(queue_time).to be_nil
+      end
+    end
+  end
+
   describe "tracing without performance" do
     let(:incoming_prop_context) { Sentry::PropagationContext.new(Sentry::Scope.new) }
     let(:env) do