fix(tracing): establish tracing capture context early enough

sentry-rails/lib/sentry/rails/capture_context.rb

@@ -0,0 +1,22 @@
+# frozen_string_literal: true
+
+module Sentry
+  module Rails
+    # Establishes the propagation context as early as possible, so anything
+    # logged before +CaptureExceptions+ runs shares the request's trace_id.
+    class CaptureContext
+      def initialize(app)
+        @app = app
+      end
+
+      def call(env)
+        return @app.call(env) unless Sentry.initialized?
+
+        Sentry.clone_hub_to_current_thread
+        Sentry.get_current_scope.generate_propagation_context(env)
+
+        @app.call(env)
+      end
+    end
+  end
+end

sentry-rails/lib/sentry/rails/capture_exceptions.rb

@@ -42,6 +42,10 @@ def capture_exception(exception, env)
         end
       end
 
+      def establish_propagation_context(env)
+        # no-op because it was already set by CaptureContext
+      end
+
       def start_transaction(env, scope)
         options = {
           name: scope.transaction_name,
@@ -52,10 +56,7 @@ def start_transaction(env, scope)
 
         options.merge!(sampled: false) if @assets_regexp && scope.transaction_name.match?(@assets_regexp)
 
-        transaction = Sentry.continue_trace(env, **options)
-        transaction = Sentry.start_transaction(transaction: transaction, custom_sampling_context: { env: env }, **options)
-        attach_queue_time(transaction, env)
-        transaction
+        start_request_transaction(env, scope, options)
       end
 
       def show_exceptions?(exception, env)

sentry-rails/lib/sentry/rails/railtie.rb

@@ -1,5 +1,6 @@
 # frozen_string_literal: true
 
+require "sentry/rails/capture_context"
 require "sentry/rails/capture_exceptions"
 require "sentry/rails/rescued_exception_interceptor"
 require "sentry/rails/backtrace_cleaner"
@@ -8,6 +9,7 @@ module Sentry
   class Railtie < ::Rails::Railtie
     # middlewares can't be injected after initialize
     initializer "sentry.use_rack_middleware" do |app|
+      app.config.middleware.insert_after ActionDispatch::Executor, Sentry::Rails::CaptureContext
       # placed after all the file-sending middlewares so we can avoid unnecessary transactions
       app.config.middleware.insert_after ActionDispatch::ShowExceptions, Sentry::Rails::CaptureExceptions
       # need to place as close to DebugExceptions as possible to intercept most of the exceptions, including those raised by middlewares

sentry-rails/spec/sentry/rails/capture_context_spec.rb

@@ -0,0 +1,102 @@
+# frozen_string_literal: true
+
+require "spec_helper"
+
+RSpec.describe Sentry::Rails::CaptureContext do
+  class CaptureContextSpecProbe
+    def self.captured_trace_ids
+      @captured_trace_ids ||= []
+    end
+
+    def initialize(app)
+      @app = app
+    end
+
+    def call(env)
+      self.class.captured_trace_ids << Sentry.get_current_scope.get_trace_context[:trace_id]
+      @app.call(env)
+    end
+  end
+
+  describe "#call" do
+    before do
+      make_basic_app
+    end
+
+    def propagation_context_in_app(env)
+      context_in_app = nil
+
+      app = lambda do |_env|
+        context_in_app = Sentry.get_current_scope.propagation_context
+        [200, {}, ["ok"]]
+      end
+
+      described_class.new(app).call(env)
+
+      context_in_app
+    end
+
+    it "starts a new trace for every request served by the same thread" do
+      first = propagation_context_in_app(Rack::MockRequest.env_for("/test"))
+      second = propagation_context_in_app(Rack::MockRequest.env_for("/test"))
+
+      expect(second.trace_id).not_to eq(first.trace_id)
+    end
+  end
+
+  context "when composed with CaptureExceptions", type: :request do
+    before do
+      CaptureContextSpecProbe.captured_trace_ids.clear
+    end
+
+    context "without tracing enabled" do
+      before do
+        make_basic_app do |config, app|
+          app.config.middleware.insert_before(Sentry::Rails::CaptureExceptions, CaptureContextSpecProbe)
+          app.config.middleware.insert_after(Sentry::Rails::CaptureExceptions, CaptureContextSpecProbe)
+        end
+      end
+
+      it "keeps the same trace_id before and after CaptureExceptions runs" do
+        get "/world"
+
+        early_trace_id, late_trace_id = CaptureContextSpecProbe.captured_trace_ids
+
+        expect(early_trace_id).to be_a(String)
+        expect(late_trace_id).to eq(early_trace_id)
+      end
+    end
+
+    context "with tracing enabled" do
+      let(:transport) { Sentry.get_current_client.transport }
+
+      before do
+        make_basic_app do |config, app|
+          config.traces_sample_rate = 1.0
+          app.config.middleware.insert_before(Sentry::Rails::CaptureExceptions, CaptureContextSpecProbe)
+          app.config.middleware.insert_after(Sentry::Rails::CaptureExceptions, CaptureContextSpecProbe)
+        end
+      end
+
+      it "keeps the same trace_id from before CaptureExceptions through the started transaction" do
+        get "/world"
+
+        early_trace_id, late_trace_id = CaptureContextSpecProbe.captured_trace_ids
+
+        expect(early_trace_id).to be_a(String)
+        expect(late_trace_id).to eq(early_trace_id)
+      end
+
+      it "continues the incoming trace" do
+        incoming_transaction = Sentry::Transaction.new(op: "pageload", status: "ok", sampled: true, name: "a/path")
+
+        get "/world", headers: { "sentry-trace" => incoming_transaction.to_sentry_trace }
+
+        trace = transport.events.last.contexts[:trace]
+        expect(trace[:trace_id]).to eq(incoming_transaction.trace_id)
+        expect(trace[:parent_span_id]).to eq(incoming_transaction.span_id)
+        expect(CaptureContextSpecProbe.captured_trace_ids.first).to eq(incoming_transaction.trace_id)
+      end
+    end
+  end
+end

sentry-rails/spec/sentry/rails_spec.rb

@@ -28,6 +28,13 @@
       expect(app.middleware.find_index(Sentry::Rails::RescuedExceptionInterceptor)).to eq(index_of_debug_exceptions + 1)
     end
 
+    it "leaves requests served above the app boundary untouched" do
+      middleware = Rails.application.middleware
+
+      expect(middleware.find_index(Sentry::Rails::CaptureContext))
+        .to be > middleware.find_index(ActionDispatch::Executor)
+    end
+
     it "propagates timezone to cron config" do
       # cron.default_timezone is set to nil by default
       expect(Sentry.configuration.cron.default_timezone).to eq("Etc/UTC")

sentry-ruby/lib/sentry/hub.rb

@@ -388,14 +388,7 @@ def continue_trace(env, **options)
       propagation_context = current_scope.propagation_context
       return nil unless propagation_context.incoming_trace
 
-      Transaction.new(
-        trace_id: propagation_context.trace_id,
-        parent_span_id: propagation_context.parent_span_id,
-        parent_sampled: propagation_context.parent_sampled,
-        baggage: propagation_context.baggage,
-        sample_rand: propagation_context.sample_rand,
-        **options
-      )
+      Transaction.new(**propagation_context.transaction_options, **options)
     end
 
     private

sentry-ruby/lib/sentry/propagation_context.rb

@@ -160,6 +160,16 @@ def initialize(scope, env = nil)
       @sample_rand ||= self.class.generate_sample_rand(@baggage, @trace_id, @parent_sampled)
     end
 
+    def transaction_options
+      {
+        trace_id: trace_id,
+        parent_span_id: parent_span_id,
+        parent_sampled: parent_sampled,
+        baggage: baggage,
+        sample_rand: sample_rand
+      }
+    end
+
     # Returns the trace context that can be used to embed in an Event.
     # @return [Hash]
     def get_trace_context

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

@@ -14,8 +14,7 @@ def initialize(app)
       def call(env)
         return @app.call(env) unless Sentry.initialized?
 
-        # make sure the current thread has a clean hub
-        Sentry.clone_hub_to_current_thread
+        establish_propagation_context(env)
 
         Sentry.with_scope do |scope|
           Sentry.with_session_tracking do
@@ -63,6 +62,11 @@ def capture_exception(exception, env)
         end
       end
 
+      def establish_propagation_context(env)
+        Sentry.clone_hub_to_current_thread
+        Sentry.get_current_scope.generate_propagation_context(env)
+      end
+
       def start_transaction(env, scope)
         options = {
           name: scope.transaction_name,
@@ -71,8 +75,16 @@ def start_transaction(env, scope)
           origin: SPAN_ORIGIN
         }
 
-        transaction = Sentry.continue_trace(env, **options)
-        transaction = Sentry.start_transaction(transaction: transaction, custom_sampling_context: { env: env }, **options)
+        start_request_transaction(env, scope, options)
+      end
+
+      def start_request_transaction(env, scope, options)
+        transaction = Sentry.start_transaction(
+          custom_sampling_context: { env: env },
+          **scope.propagation_context.transaction_options,
+          **options
+        )
+
         attach_queue_time(transaction, env)
         transaction
       end

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

@@ -93,6 +93,46 @@
       expect(env.key?("sentry.error_event_id")).to eq(false)
     end
 
+    context "propagation context" do
+      def propagation_context_in_app(stack_env)
+        context_in_app = nil
+
+        app = lambda do |_e|
+          context_in_app = Sentry.get_current_scope.propagation_context
+          [200, {}, ['okay']]
+        end
+
+        Sentry::Rack::CaptureExceptions.new(app).call(stack_env)
+
+        context_in_app
+      end
+
+      it "starts a new trace for every request served by the same thread" do
+        first = propagation_context_in_app(env)
+        second = propagation_context_in_app(Rack::MockRequest.env_for("/test"))
+
+        expect(second.trace_id).not_to eq(first.trace_id)
+      end
+
+      context "with tracing enabled" do
+        before do
+          perform_basic_setup do |config|
+            config.traces_sample_rate = 1.0
+          end
+        end
+
+        it "starts the transaction from the request's propagation context" do
+          context_in_app = propagation_context_in_app(env)
+
+          transaction = last_sentry_event
+
+          expect(transaction.type).to eq("transaction")
+          expect(transaction.contexts.dig(:trace, :trace_id)).to eq(context_in_app.trace_id)
+          expect(transaction.contexts.dig(:trace, :parent_span_id)).to be_nil
+        end
+      end
+    end
+
     context "with config.data_collection.stack_frame_variables = true" do
       before do
         perform_basic_setup do |config|

spec/apps/rails-mini/app.rb

@@ -18,6 +18,20 @@
 redis_url = ENV.fetch("REDIS_URL", "redis://localhost:6379")
 Resque.redis = redis_url if defined?(Resque)
 
+class EarlyRequestLogMiddleware
+  PATH = "/trace_context"
+
+  def initialize(app)
+    @app = app
+  end
+
+  def call(env)
+    Sentry.logger.info("early middleware log", source: "middleware") if env["PATH_INFO"] == PATH
+
+    @app.call(env)
+  end
+end
+
 class RailsMiniApp < Rails::Application
   config.hosts = nil
   config.secret_key_base = "test_secret_key_base_for_rails_mini_app"
@@ -49,6 +63,8 @@ class RailsMiniApp < Rails::Application
   end
 
   config.active_job.queue_adapter = SUPPORTED_ACTIVE_JOB_ADAPTERS[adapter_name]
+
+  config.middleware.insert_before Rails::Rack::Logger, EarlyRequestLogMiddleware
   config.x.active_job_adapter_name = adapter_name
 
   def debug_log_path
@@ -74,6 +90,7 @@ def debug_log_path
       config.sdk_debug_transport_log_file = debug_log_path.join("sentry_debug_events.log")
       config.background_worker_threads = 0
 
+      config.max_log_events = 1
       config.structured_logging.logger_class = Sentry::DebugStructuredLogger
       config.structured_logging.file_path = debug_log_path.join("sentry_e2e_tests.log")
 
@@ -238,6 +255,24 @@ def set_cors_headers
   end
 end
 
+class TraceContextController < ActionController::Base
+  before_action :set_cors_headers
+
+  def show
+    Sentry.logger.info("controller log", source: "controller")
+
+    render json: { trace: Sentry.get_current_scope.get_trace_context }
+  end
+
+  private
+
+  def set_cors_headers
+    response.headers["Access-Control-Allow-Origin"] = "*"
+    response.headers["Access-Control-Allow-Methods"] = "GET, POST, PUT, DELETE, OPTIONS"
+    response.headers["Access-Control-Allow-Headers"] = "Content-Type, Authorization, sentry-trace, baggage"
+  end
+end
+
 class JobsController < ActionController::Base
   before_action :set_cors_headers
 
@@ -359,6 +394,7 @@ def set_cors_headers
   get '/health', to: 'events#health'
   get '/error', to: 'error#error'
   get '/trace_headers', to: 'events#trace_headers'
+  get '/trace_context', to: 'trace_context#show'
   get '/logged_events', to: 'events#logged_events'
   post '/clear_logged_events', to: 'events#clear_logged_events'