feat: queue time capture for Rack (#2838)

* add configuration for capturing queue time

default to true

* Extract, normalize & add queue time to transaction

* Test app for queue time in Sentry

* Fix redos issue

* move test app

* Update CHANGELOG.md

* Update CHANGELOG.md

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

Co-authored-by: Neel Shah <neel.shah@sentry.io>

* Delete sentry_queue_test.rb

* ⏰👮🏻

* change name

* remove upper bounds

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

* fix(rack): Validate t= prefixed values in parse_request_start_header

Non-numeric t= values like "t=invalid" or "t=" were silently converted
to 0.0 by Ruby's String#to_f, resulting in a Unix epoch timestamp and a
queue time of ~56 years instead of nil.

Apply the same numeric regex guard already used for raw timestamps to
the t= branch before calling to_f.

Co-Authored-By: Claude <noreply@anthropic.com>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

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

Co-authored-by: Peter Solnica <peter@solnica.online>

* fix(rack): Handle whitespace and comma-separated X-Request-Start values

parse_request_start_header returned nil for headers that arrived with
leading/trailing whitespace or as comma-separated values (multiple
header occurrences collapsed by a proxy). Strip whitespace from the
token and split on commas, taking the first (earliest) timestamp.

Co-Authored-By: Claude <noreply@anthropic.com>

* fix(rack): Coerce puma.request_body_wait to Float before comparison

When env["puma.request_body_wait"] is a String (e.g. serialized by
middleware), the `> 0` comparison raised ArgumentError, which was
silently swallowed by the broad rescue, causing queue time to be
dropped even with a valid X-Request-Start header.

Call to_f on String values before the comparison. Numeric strings
("40") convert correctly; non-numeric strings ("N/A") become 0.0
and are treated as absent, so total_time_ms is returned unchanged.

Co-Authored-By: Claude <noreply@anthropic.com>

---------

Co-authored-by: Neel Shah <neel.shah@sentry.io>
Co-authored-by: Peter Solnica <peter@solnica.online>
Co-authored-by: Claude <noreply@anthropic.com>

Author: 4 people

CHANGELOG.md

@@ -1,5 +1,7 @@
 ## Unreleased
 
+- Queue time capture for Rack ([#2838](https://github.com/getsentry/sentry-ruby/pull/2838))
+
 ### Features
 
 - Add support for OTLP ingestion in `sentry-opentelemetry` ([#2853](https://github.com/getsentry/sentry-ruby/pull/2853))

sentry-ruby/lib/sentry/configuration.rb

@@ -235,6 +235,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
@@ -513,6 +519,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
 
 
@@ -87,6 +94,81 @@ 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 unless Sentry.configuration&.capture_queue_time
+
+        header_value = env["HTTP_X_REQUEST_START"]
+        return unless header_value
+
+        request_start = parse_request_start_header(header_value)
+        return unless request_start
+
+        total_time_ms = ((Time.now.to_f - request_start) * 1000).round(2)
+
+        # reject negative (clock skew between proxy & app server)
+        return unless total_time_ms >= 0
+
+        puma_wait_ms = env["puma.request_body_wait"]
+        puma_wait_ms = puma_wait_ms.to_f if puma_wait_ms.is_a?(String)
+
+        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
+      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
+
+        # Take the first value if comma-separated (multiple headers collapsed by a proxy)
+        # and strip surrounding whitespace from each token
+        raw = header_value.split(",").first.to_s.strip
+
+        timestamp = if raw.start_with?("t=")
+          value = raw[2..-1].strip
+          return nil unless value.match?(/\A\d+(?:\.\d+)?\z/)
+          value.to_f
+        elsif raw.match?(/\A\d+(?:\.\d+)?\z/)
+          raw.to_f
+        else
+          return
+        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
+
       def status_code_for_exception(exception)
         500
       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,155 @@ 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 "subtracts puma.request_body_wait when given as a string" 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"
+
+          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 "still returns queue time when puma.request_body_wait is a non-numeric string" do
+        Timecop.freeze do
+          timestamp = Time.now.to_f - 0.05  # 50ms ago
+          env["HTTP_X_REQUEST_START"] = "t=#{timestamp}"
+          env["puma.request_body_wait"] = "N/A"
+
+          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
+      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
+
+      it "doesn't add queue time data for malformed t= values" do
+        ["t=invalid", "t=abc", "t="].each do |bad_value|
+          env["HTTP_X_REQUEST_START"] = bad_value
+
+          stack.call(env)
+
+          queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+          expect(queue_time).to be_nil, "expected nil for header #{bad_value.inspect}"
+        end
+      end
+
+      it "handles leading and trailing whitespace" do
+        Timecop.freeze 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_within(10).of(50)
+        end
+      end
+
+      it "uses the first value when header is comma-separated" do
+        Timecop.freeze do
+          earlier = Time.now.to_f - 0.08
+          later   = Time.now.to_f - 0.02
+          env["HTTP_X_REQUEST_START"] = "t=#{earlier}, t=#{later}"
+
+          stack.call(env)
+
+          queue_time = transaction.contexts.dig(:trace, :data, 'http.server.request.time_in_queue')
+          expect(queue_time).to be_within(10).of(80)
+        end
+      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