diff --git a/sentry-rails/lib/sentry/rails/capture_context.rb b/sentry-rails/lib/sentry/rails/capture_context.rb new file mode 100644 index 000000000..bfb746b22 --- /dev/null +++ b/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 diff --git a/sentry-rails/lib/sentry/rails/capture_exceptions.rb b/sentry-rails/lib/sentry/rails/capture_exceptions.rb index 756990ee7..030855e54 100644 --- a/sentry-rails/lib/sentry/rails/capture_exceptions.rb +++ b/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) diff --git a/sentry-rails/lib/sentry/rails/railtie.rb b/sentry-rails/lib/sentry/rails/railtie.rb index d997e5c46..a62d46f1f 100644 --- a/sentry-rails/lib/sentry/rails/railtie.rb +++ b/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 diff --git a/sentry-rails/spec/sentry/rails/capture_context_spec.rb b/sentry-rails/spec/sentry/rails/capture_context_spec.rb new file mode 100644 index 000000000..46fb0162e --- /dev/null +++ b/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 diff --git a/sentry-rails/spec/sentry/rails_spec.rb b/sentry-rails/spec/sentry/rails_spec.rb index b93435cdd..5a8b89464 100644 --- a/sentry-rails/spec/sentry/rails_spec.rb +++ b/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") diff --git a/sentry-ruby/lib/sentry/hub.rb b/sentry-ruby/lib/sentry/hub.rb index f8730e517..4f7c83df4 100644 --- a/sentry-ruby/lib/sentry/hub.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/propagation_context.rb b/sentry-ruby/lib/sentry/propagation_context.rb index 45dbd4d78..ff7ec5092 100644 --- a/sentry-ruby/lib/sentry/propagation_context.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/rack/capture_exceptions.rb b/sentry-ruby/lib/sentry/rack/capture_exceptions.rb index a97f93079..ac93020da 100644 --- a/sentry-ruby/lib/sentry/rack/capture_exceptions.rb +++ b/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 diff --git a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb b/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb index 7c87376f4..7b1111de7 100644 --- a/sentry-ruby/spec/sentry/rack/capture_exceptions_spec.rb +++ b/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| diff --git a/spec/apps/rails-mini/app.rb b/spec/apps/rails-mini/app.rb index be8114d4c..727f9430d 100644 --- a/spec/apps/rails-mini/app.rb +++ b/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' diff --git a/spec/features/trace_context_spec.rb b/spec/features/trace_context_spec.rb new file mode 100644 index 000000000..fb8138e3c --- /dev/null +++ b/spec/features/trace_context_spec.rb @@ -0,0 +1,37 @@ +# frozen_string_literal: true + +RSpec.describe "Trace context", type: :e2e do + def early_middleware_logs + logged_log_events.select { |log| log["body"] == "early middleware log" } + end + + def request_transaction + logged_events[:events].find do |event| + event["type"] == "transaction" && event.dig("contexts", "trace", "op") == "http.server" + end + end + + it "gives a log emitted before CaptureExceptions the transaction's trace_id" do + without_trace_propagation { make_request("/trace_context") } + + expect(early_middleware_logs.first["trace_id"]) + .to eq(request_transaction.dig("contexts", "trace", "trace_id")) + end + + it "continues an incoming distributed trace in a log emitted before CaptureExceptions" do + incoming_trace_id = propagated_trace_id + + make_request("/trace_context") + + expect(early_middleware_logs.first["trace_id"]).to eq(incoming_trace_id) + end + + it "starts a new trace for every request that arrives without one" do + without_trace_propagation { 2.times { make_request("/trace_context") } } + + trace_ids = early_middleware_logs.map { |log| log["trace_id"] } + + expect(trace_ids.length).to eq(2) + expect(trace_ids.uniq.length).to eq(2) + end +end diff --git a/spec/support/test_helper.rb b/spec/support/test_helper.rb index 4cceef141..d10e1a370 100644 --- a/spec/support/test_helper.rb +++ b/spec/support/test_helper.rb @@ -11,8 +11,12 @@ def rails_app_url ENV.fetch("SENTRY_E2E_RAILS_APP_URL") end - def make_request(path) - Net::HTTP.get_response(URI("#{rails_app_url}#{path}")) + def make_request(path, headers = {}) + uri = URI("#{rails_app_url}#{path}") + + Net::HTTP.start(uri.host, uri.port) do |http| + http.request(Net::HTTP::Get.new(uri, headers)) + end end def logged_events @@ -42,6 +46,26 @@ def logged_events end end + def without_trace_propagation + original = Sentry.configuration.propagate_traces + Sentry.configuration.propagate_traces = false + yield + ensure + Sentry.configuration.propagate_traces = original + end + + def propagated_trace_id + Sentry.get_trace_propagation_headers["sentry-trace"].split("-").first + end + + def logged_log_events + logged_events[:envelopes].flat_map do |envelope| + envelope["items"] + .select { |item| item["headers"]["type"] == "log" } + .flat_map { |item| item["payload"]["items"] } + end + end + def clear_logged_events Sentry.get_current_client.transport.clear end