test(e2e): cover establishing trace context

Author: solnic

sentry-ruby/lib/sentry/transport/debug_transport.rb

@@ -27,6 +27,11 @@ def send_event(event)
       backend.send_event(event)
     end
 
+    def send_envelope(envelope)
+      log_envelope(envelope)
+      backend.send_envelope(envelope)
+    end
+
     def log_envelope(envelope)
       envelope_json = {
         timestamp: Time.now.utc.iso8601,

spec/apps/rails-mini/app.rb

@@ -18,6 +18,24 @@
 redis_url = ENV.fetch("REDIS_URL", "redis://localhost:6379")
 Resque.redis = redis_url if defined?(Resque)
 
+# Emits a Sentry log from above Sentry::Rails::CaptureExceptions - the same window
+# Rails::Rack::Logger writes its "Started GET ..." line from, and the window where a
+# request used to pick up an unrelated or stale trace_id. Scoped to one path so the
+# other e2e scenarios keep a quiet log stream.
+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 +67,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
@@ -75,6 +95,7 @@ def debug_log_path
       config.background_worker_threads = 0
 
       config.enable_logs = true
+      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")
 
@@ -239,6 +260,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
 
@@ -360,6 +399,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'
 

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

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,31 @@ def logged_events
       end
     end
 
+    # The SDK instruments Net::HTTP and stamps its own sentry-trace on every outgoing
+    # request, so by default the app continues this process's trace. Turn that off to
+    # exercise requests that arrive without an incoming trace.
+    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
+
+    # Log events travel in their own envelope type rather than as events, so they are
+    # not part of logged_events[:events].
+    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