diff --git a/CHANGELOG.md b/CHANGELOG.md index 62448291a..b43500109 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index b09f8ad62..8b27699cb 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/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) diff --git a/sentry-ruby/lib/sentry/rack/capture_exceptions.rb b/sentry-ruby/lib/sentry/rack/capture_exceptions.rb index 40cdfb4f8..239d9407f 100644 --- a/sentry-ruby/lib/sentry/rack/capture_exceptions.rb +++ b/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,76 @@ 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 nil 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 + nil + end end end end diff --git a/sentry-ruby/lib/sentry/span.rb b/sentry-ruby/lib/sentry/span.rb index 5ba4b7cf8..0d35e4fab 100644 --- a/sentry-ruby/lib/sentry/span.rb +++ b/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 = { diff --git a/sentry-ruby/spec/sentry/configuration_spec.rb b/sentry-ruby/spec/sentry/configuration_spec.rb index c84de8e99..e8aab303a 100644 --- a/sentry-ruby/spec/sentry/configuration_spec.rb +++ b/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' diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index 976d87984..a5671264e 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/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