diff --git a/sentry-rails/Gemfile b/sentry-rails/Gemfile index ea1d6ac51..b34f03e8f 100644 --- a/sentry-rails/Gemfile +++ b/sentry-rails/Gemfile @@ -56,6 +56,26 @@ end gem "mini_magick" +# Sidekiq is a dev-only dependency, used by the common ActiveJob spec +# suite to verify the AJ tracing extension works against the :sidekiq +# adapter independent of sentry-sidekiq's native middleware. +# +# Gated on Ruby/Rails/platform because: +# - The sidekiq_adapter_spec only passes on Rails > 7.0. +# - Sidekiq 8 requires Ruby >= 3.2; older Rubies fall back to Sidekiq 7. +# - Sidekiq does not reliably support JRuby. +# +# sidekiq_adapter_spec.rb also rescues LoadError and re-checks the +# Rails version, so matrices that don't bundle Sidekiq skip the spec +# cleanly without any other gating. +unless RUBY_PLATFORM.include?("java") + if rails_version > Gem::Version.new("7.0.0") && ruby_version >= Gem::Version.new("3.2") + gem "sidekiq", "~> 8.0" + elsif rails_version > Gem::Version.new("7.0.0") + gem "sidekiq", "~> 7.0" + end +end + gem "sprockets-rails" gem "benchmark-ips" diff --git a/sentry-rails/lib/sentry/rails/active_job.rb b/sentry-rails/lib/sentry/rails/active_job.rb index df7f27ecd..abb32b800 100644 --- a/sentry-rails/lib/sentry/rails/active_job.rb +++ b/sentry-rails/lib/sentry/rails/active_job.rb @@ -5,13 +5,62 @@ module Sentry module Rails module ActiveJobExtensions + SENTRY_PAYLOAD_KEY = "_sentry" + + USER_FIELDS_ALLOWLIST = %w[id email username].freeze + + def self.prepended(base) + base.attr_accessor :_sentry + end + def perform_now if !Sentry.initialized? || already_supported_by_sentry_integration? super else - SentryReporter.record(self) do - super + data = _sentry || {} + SentryReporter.record( + self, + trace_headers: data["trace_propagation_headers"], + user: data["user"] + ) { super } + end + end + + def serialize + payload = super + return payload if !Sentry.initialized? || already_supported_by_sentry_integration? + + begin + sentry_data = {} + if Sentry.configuration.rails.active_job_propagate_traces + headers = Sentry.get_trace_propagation_headers + sentry_data["trace_propagation_headers"] = headers if headers && !headers.empty? end + + if Sentry.configuration.send_default_pii + user = Sentry.get_current_scope.user || {} + allowed = user.each_with_object({}) do |(k, v), acc| + acc[k.to_s] = v if USER_FIELDS_ALLOWLIST.include?(k.to_s) + end + sentry_data["user"] = allowed unless allowed.empty? + end + + payload[SENTRY_PAYLOAD_KEY] = sentry_data unless sentry_data.empty? + rescue StandardError => e + Sentry.sdk_logger&.error("sentry-rails: failed to inject _sentry payload: #{e.class}: #{e.message}\n #{Array(e.backtrace).first(5).join("\n ")}") + end + + payload + end + + def deserialize(job_data) + super + return if !Sentry.initialized? || already_supported_by_sentry_integration? + + begin + self._sentry = job_data[SENTRY_PAYLOAD_KEY] + rescue StandardError => e + Sentry.sdk_logger&.error("sentry-rails: failed to extract _sentry payload: #{e.class}: #{e.message}\n #{Array(e.backtrace).first(5).join("\n ")}") end end @@ -28,19 +77,67 @@ class SentryReporter } class << self - def record(job, &block) + def producer_callback_registered? + @producer_callback_registered ||= false + end + + def producer_callback_registered! + @producer_callback_registered = true + end + + def record_producer_span(job) + return yield if !Sentry.initialized? || job.already_supported_by_sentry_integration? + + Sentry.with_child_span(op: "queue.publish", description: job.class.name) do |span| + if span + span.set_origin(SPAN_ORIGIN) + span.set_data(Sentry::Span::DataConventions::MESSAGING_MESSAGE_ID, job.job_id) + span.set_data(Sentry::Span::DataConventions::MESSAGING_DESTINATION_NAME, job.queue_name) + end + yield + end + end + + def record(job, trace_headers: nil, user: nil, &block) + # Always give this thread a fresh hub cloned from the main hub so + # the job's events are fully isolated. Save and restore whatever + # hub was on the thread before (e.g. the Rack request hub set by + # CaptureExceptions, or a stale hub left by a recycled thread-pool + # thread) so the outer context continues working correctly after + # the job finishes. + original_hub = Thread.current.thread_variable_get(Sentry::THREAD_LOCAL) + Sentry.clone_hub_to_current_thread + Sentry.with_scope do |scope| begin + scope.set_user(user) if user && !user.empty? scope.set_transaction_name(job.class.name, source: :task) + scope.set_tags(queue: job.queue_name) + scope.set_contexts(active_job: { + job_class: job.class.name, + job_id: job.job_id, + queue: job.queue_name, + provider_job_id: job.provider_job_id + }) - transaction = Sentry.start_transaction( + transaction_options = { name: scope.transaction_name, source: scope.transaction_source, op: OP_NAME, origin: SPAN_ORIGIN - ) + } + + transaction = if trace_headers && !trace_headers.empty? + continued = Sentry.continue_trace(trace_headers, **transaction_options) + Sentry.start_transaction(transaction: continued, **transaction_options) + else + Sentry.start_transaction(**transaction_options) + end - scope.set_span(transaction) if transaction + if transaction + set_messaging_data(transaction, job) + scope.set_span(transaction) + end yield.tap do finish_sentry_transaction(transaction, 200) @@ -53,6 +150,25 @@ def record(job, &block) raise end end + ensure + Thread.current.thread_variable_set(Sentry::THREAD_LOCAL, original_hub) + end + + def set_messaging_data(transaction, job) + transaction.set_data(Sentry::Span::DataConventions::MESSAGING_MESSAGE_ID, job.job_id) + transaction.set_data(Sentry::Span::DataConventions::MESSAGING_DESTINATION_NAME, job.queue_name) + transaction.set_data(Sentry::Span::DataConventions::MESSAGING_MESSAGE_RETRY_COUNT, [job.executions.to_i - 1, 0].max) + + if (latency = compute_latency(job)) + transaction.set_data(Sentry::Span::DataConventions::MESSAGING_MESSAGE_RECEIVE_LATENCY, latency) + end + end + + def compute_latency(job) + return unless job.respond_to?(:enqueued_at) && job.enqueued_at + + enqueued_time = job.enqueued_at.is_a?(String) ? Time.parse(job.enqueued_at) : job.enqueued_at + ((Time.now.to_f - enqueued_time.to_f) * 1000).round end def capture_exception(job, e) diff --git a/sentry-rails/lib/sentry/rails/configuration.rb b/sentry-rails/lib/sentry/rails/configuration.rb index a37c4446c..9e4c1e7ef 100644 --- a/sentry-rails/lib/sentry/rails/configuration.rb +++ b/sentry-rails/lib/sentry/rails/configuration.rb @@ -172,6 +172,11 @@ class Configuration # Set this option to true if you want Sentry to capture each retry failure attr_accessor :active_job_report_on_retry_error + # Whether we should inject trace propagation headers into the serialized job + # payload in order to have a connected trace between producer and consumer. + # Defaults to true. Set to false to opt out. + attr_accessor :active_job_propagate_traces + # Configuration for structured logging feature # @return [StructuredLoggingConfiguration] attr_reader :structured_logging @@ -193,6 +198,7 @@ def initialize @db_query_source_threshold_ms = 100 @active_support_logger_subscription_items = Sentry::Rails::ACTIVE_SUPPORT_LOGGER_SUBSCRIPTION_ITEMS_DEFAULT.dup @active_job_report_on_retry_error = false + @active_job_propagate_traces = true @structured_logging = StructuredLoggingConfiguration.new end end diff --git a/sentry-rails/lib/sentry/rails/railtie.rb b/sentry-rails/lib/sentry/rails/railtie.rb index a86093768..a234e95a9 100644 --- a/sentry-rails/lib/sentry/rails/railtie.rb +++ b/sentry-rails/lib/sentry/rails/railtie.rb @@ -21,6 +21,13 @@ class Railtie < ::Rails::Railtie ActiveSupport.on_load(:active_job) do require "sentry/rails/active_job" prepend Sentry::Rails::ActiveJobExtensions + + unless Sentry::Rails::ActiveJobExtensions::SentryReporter.producer_callback_registered? + around_enqueue do |job, block| + Sentry::Rails::ActiveJobExtensions::SentryReporter.record_producer_span(job, &block) + end + Sentry::Rails::ActiveJobExtensions::SentryReporter.producer_callback_registered! + end end end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/consumer_transaction.rb b/sentry-rails/spec/active_job/shared_examples/tracing/consumer_transaction.rb index 5cc2d1fb3..715a2d5b6 100644 --- a/sentry-rails/spec/active_job/shared_examples/tracing/consumer_transaction.rb +++ b/sentry-rails/spec/active_job/shared_examples/tracing/consumer_transaction.rb @@ -32,6 +32,43 @@ def perform expect(transaction.contexts.dig(:trace, :status)).to eq("ok") end + it "sets queue scope tag on the consumer transaction" do + successful_job.set(queue: "important").perform_later + drain + + transaction = sentry_events.find { |e| e.is_a?(Sentry::TransactionEvent) } + expect(transaction).not_to be_nil + expect(transaction.tags[:queue]).to eq("important") + end + + it "sets active_job context on the consumer transaction" do + successful_job.perform_later + drain + + transaction = sentry_events.find { |e| e.is_a?(Sentry::TransactionEvent) } + expect(transaction).not_to be_nil + + ctx = transaction.contexts[:active_job] + expect(ctx).not_to be_nil + expect(ctx[:job_class]).to eq(successful_job.name) + expect(ctx[:job_id]).to be_a(String).and(satisfy { |v| !v.empty? }) + expect(ctx[:queue]).to eq("default") + end + + it "sets active_job context on the error event" do + expect do + failing_job.perform_later + drain + end.to raise_error(RuntimeError, /boom from tracing spec/) + + error_event = sentry_events.find { |e| e.is_a?(Sentry::ErrorEvent) } + expect(error_event).not_to be_nil + + ctx = error_event.contexts[:active_job] + expect(ctx).not_to be_nil + expect(ctx[:job_class]).to eq(failing_job.name) + end + it "records a db.sql.active_record child span when the job performs a query" do query_job = job_fixture do def perform diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/distributed_tracing.rb b/sentry-rails/spec/active_job/shared_examples/tracing/distributed_tracing.rb new file mode 100644 index 000000000..8dac36d55 --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/distributed_tracing.rb @@ -0,0 +1,9 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that supports distributed tracing" do + it_behaves_like "an ActiveJob backend that emits a producer span on enqueue" + it_behaves_like "an ActiveJob backend that propagates trace context through the job payload" + it_behaves_like "an ActiveJob backend that records messaging span data on the consumer transaction" + it_behaves_like "an ActiveJob backend that propagates Sentry user context through job payloads" + it_behaves_like "an ActiveJob backend that isolates Sentry context per worker thread" +end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/messaging_span_data.rb b/sentry-rails/spec/active_job/shared_examples/tracing/messaging_span_data.rb new file mode 100644 index 000000000..eca15e905 --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/messaging_span_data.rb @@ -0,0 +1,84 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that records messaging span data on the consumer transaction" do + include ActiveSupport::Testing::TimeHelpers + + let(:successful_job) do + job_fixture do + def perform; end + end + end + + let(:configure_sentry) { proc { |config| config.traces_sample_rate = 1.0 } } + + it "records messaging.message.id and messaging.destination.name on the consumer transaction" do + successful_job.set(queue: "critical").perform_later + drain + + data = consumer_transaction.contexts.dig(:trace, :data) + expect(data["messaging.message.id"]).to be_a(String).and(satisfy { |v| !v.empty? }) + expect(data["messaging.destination.name"]).to eq("critical") + end + + it "records messaging.message.retry.count = 0 for non-retryable jobs" do + successful_job.perform_later + drain + + data = consumer_transaction.contexts.dig(:trace, :data) + expect(data["messaging.message.retry.count"]).to eq(0) + end + + context "when the job is retryable" do + let(:retryable_job) do + job_fixture do + retry_on StandardError, attempts: 3, wait: 0 + + def perform; end + end + end + + it "records messaging.message.retry.count = 0 on the first execution" do + retryable_job.perform_later + drain + + data = consumer_transaction.contexts.dig(:trace, :data) + expect(data["messaging.message.retry.count"]).to eq(0) + end + + it "records messaging.message.retry.count across real retried executions", skip: RAILS_VERSION < 6.0 do + retried_job = job_fixture do + retry_on StandardError, attempts: 3, wait: 0 + + def perform + raise StandardError, "trigger retry" if executions < 3 + end + end + + retried_job.perform_later + drain + + consumer_txns = transactions.select { |t| t.contexts.dig(:trace, :op) == "queue.active_job" } + retry_counts = consumer_txns.map { |t| t.contexts.dig(:trace, :data, "messaging.message.retry.count") } + expect(retry_counts).to eq([0, 0, 1]) + end + end + + it "records messaging.message.receive.latency in milliseconds", skip: RAILS_VERSION < 6.1 do + successful_job.perform_later + + # Older Rails versions truncate Time.now to whole seconds inside `travel` + # (no `with_usec:` option until 7.0+), so the measured latency can be up + # to ~999ms below the travel delta. Widen the tolerance accordingly. + if RAILS_VERSION > 7.0 + travel(5.seconds, with_usec: true) { drain } + tolerance = 50 + else + travel(5.seconds) { drain } + tolerance = 1100 + end + + latency = consumer_transaction.contexts.dig(:trace, :data, "messaging.message.receive.latency") + expect(latency).to be_a(Integer) + expect(latency).to be_within(tolerance).of(5_000) + end +end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/producer_span.rb b/sentry-rails/spec/active_job/shared_examples/tracing/producer_span.rb new file mode 100644 index 000000000..9a52460f5 --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/producer_span.rb @@ -0,0 +1,50 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that emits a producer span on enqueue" do + let(:successful_job) do + job_fixture do + def perform; end + end + end + + context "with traces_sample_rate = 1.0" do + let(:configure_sentry) { proc { |config| config.traces_sample_rate = 1.0 } } + + it "adds a queue.publish child span to the active parent transaction" do + within_parent_transaction do + successful_job.set(queue: "events").perform_later + end + + parent = transactions.find { |t| t.contexts.dig(:trace, :op) == "test" } + expect(parent).not_to be_nil + + publish_span = parent.spans.find { |s| s[:op] == "queue.publish" } + expect(publish_span).not_to be_nil + expect(publish_span[:description]).to eq(successful_job.name) + expect(publish_span[:origin]).to eq("auto.queue.active_job") + expect(publish_span[:data]["messaging.message.id"]).to be_a(String).and(satisfy { |v| !v.empty? }) + expect(publish_span[:data]["messaging.destination.name"]).to eq("events") + expect(publish_span[:timestamp]).not_to be_nil + end + + it "does not raise or capture an orphan span when no parent transaction is active" do + expect { successful_job.perform_later }.not_to raise_error + + orphan_publish = transactions.flat_map(&:spans).find { |s| s[:op] == "queue.publish" } + expect(orphan_publish).to be_nil + end + end + + context "with traces_sample_rate = 0" do + let(:configure_sentry) { proc { |config| config.traces_sample_rate = 0 } } + + it "does not capture a queue.publish span" do + within_parent_transaction do + successful_job.perform_later + end + + publish_spans = transactions.flat_map(&:spans).select { |s| s[:op] == "queue.publish" } + expect(publish_spans).to be_empty + end + end +end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/trace_propagation.rb b/sentry-rails/spec/active_job/shared_examples/tracing/trace_propagation.rb new file mode 100644 index 000000000..d0324afb9 --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/trace_propagation.rb @@ -0,0 +1,82 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that propagates trace context through the job payload" do + let(:successful_job) do + job_fixture do + def perform; end + end + end + + let(:configure_sentry) { proc { |config| config.traces_sample_rate = 1.0 } } + + it "produces a consumer transaction whose trace_id matches the parent transaction" do + parent_trace_id = nil + publish_span_id = nil + + within_parent_transaction do |parent| + parent_trace_id = parent.trace_id + successful_job.perform_later + publish_span_id = parent.span_recorder.spans.find { |s| s.op == "queue.publish" }&.span_id + end + + drain + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.contexts.dig(:trace, :trace_id)).to eq(parent_trace_id) + expect(consumer_transaction.contexts.dig(:trace, :parent_span_id)).to eq(publish_span_id) + end + + it "captures a consumer transaction without raising when no parent transaction was active at enqueue" do + expect { successful_job.perform_later }.not_to raise_error + expect { drain }.not_to raise_error + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.contexts.dig(:trace, :trace_id)).to be_a(String) + end + + it "survives a JSON round-trip of the serialized payload" do + parent_trace_id = nil + + within_parent_transaction do |parent| + parent_trace_id = parent.trace_id + payload = successful_job.new.serialize + round_tripped = JSON.parse(JSON.generate(payload)) + ::ActiveJob::Base.execute(round_tripped) + end + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.contexts.dig(:trace, :trace_id)).to eq(parent_trace_id) + end + + context "when active_job_propagate_traces is false" do + let(:configure_sentry) do + proc do |config| + config.traces_sample_rate = 1.0 + config.rails.active_job_propagate_traces = false + end + end + + it "does not inject trace headers into the job payload" do + within_parent_transaction do + successful_job.perform_later + end + + sentry_payload = last_enqueued_payload["_sentry"] + expect(sentry_payload&.dig("trace_propagation_headers")).to be_nil + end + + it "starts a new unconnected consumer transaction" do + parent_trace_id = nil + + within_parent_transaction do |parent| + parent_trace_id = parent.trace_id + successful_job.perform_later + end + + drain + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.contexts.dig(:trace, :trace_id)).not_to eq(parent_trace_id) + end + end +end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/user_propagation.rb b/sentry-rails/spec/active_job/shared_examples/tracing/user_propagation.rb new file mode 100644 index 000000000..8619f743e --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/user_propagation.rb @@ -0,0 +1,95 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that propagates Sentry user context through job payloads" do + let(:successful_job) do + job_fixture do + def perform; end + end + end + + let(:failing_job) do + job_fixture do + def perform + raise "boom from user_propagation spec" + end + end + end + + let(:full_user) do + { + id: "u1", + email: "alice@example.com", + username: "alice", + ip_address: "1.2.3.4", + segment: "vip" + } + end + + context "when send_default_pii is true" do + let(:configure_sentry) do + proc do |config| + config.traces_sample_rate = 1.0 + config.send_default_pii = true + end + end + + it "propagates only id, email, and username to the consumer transaction" do + Sentry.set_user(full_user) + + successful_job.perform_later + + # Simulate the cross-process boundary by clearing the producer scope + # before the consumer runs. Without this the consumer's with_scope + # inherits the user from the test thread and the test cannot tell + # whether propagation actually happened. + Sentry.set_user({}) + + drain + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.user).to eq( + "id" => "u1", + "email" => "alice@example.com", + "username" => "alice" + ) + end + + it "propagates the whitelisted user to a captured error event" do + Sentry.set_user(full_user) + + failing_job.perform_later + Sentry.set_user({}) + + expect { drain }.to raise_error(RuntimeError, /boom from user_propagation spec/) + + error_event = sentry_events.find { |e| e.is_a?(Sentry::ErrorEvent) } + expect(error_event).not_to be_nil + expect(error_event.user).to eq( + "id" => "u1", + "email" => "alice@example.com", + "username" => "alice" + ) + end + end + + context "when send_default_pii is false" do + let(:configure_sentry) do + proc do |config| + config.traces_sample_rate = 1.0 + config.send_default_pii = false + end + end + + it "does not propagate user context to the consumer transaction" do + Sentry.set_user(full_user) + + successful_job.perform_later + Sentry.set_user({}) + + drain + + expect(consumer_transaction).not_to be_nil + expect(consumer_transaction.user).to eq({}) + end + end +end diff --git a/sentry-rails/spec/active_job/shared_examples/tracing/worker_hub_isolation.rb b/sentry-rails/spec/active_job/shared_examples/tracing/worker_hub_isolation.rb new file mode 100644 index 000000000..c868a22d8 --- /dev/null +++ b/sentry-rails/spec/active_job/shared_examples/tracing/worker_hub_isolation.rb @@ -0,0 +1,77 @@ +# frozen_string_literal: true + +RSpec.shared_examples "an ActiveJob backend that isolates Sentry context per worker thread" do + let(:configure_sentry) { proc { |config| config.traces_sample_rate = 1.0 } } + + it "creates an isolated hub per worker thread when run concurrently" do + barrier = Concurrent::CyclicBarrier.new(2) + results_mutex = Mutex.new + results = {} + + capture = lambda do |tag| + hub_id = Thread.current.thread_variable_get(Sentry::THREAD_LOCAL).object_id + Sentry.get_current_scope.set_tags(job: tag) + raise "barrier timeout in thread #{tag}" unless barrier.wait(5) + observed_tag = Sentry.get_current_scope.tags[:job] + results_mutex.synchronize do + results[tag] = { hub_id: hub_id, observed_tag: observed_tag } + end + end + + job_a = job_fixture { define_method(:perform) { capture.call("A") } } + job_b = job_fixture { define_method(:perform) { capture.call("B") } } + + Sentry.get_current_scope.set_tags(test_thread: true) + + t_a = worker_thread { job_a.perform_now } + t_b = worker_thread { job_b.perform_now } + t_a.join + t_b.join + + expect(results["A"][:hub_id]).not_to eq(results["B"][:hub_id]) + expect(results["A"][:observed_tag]).to eq("A") + expect(results["B"][:observed_tag]).to eq("B") + + # The test thread's own scope is unchanged. + expect(Sentry.get_current_scope.tags[:test_thread]).to be_truthy + expect(Sentry.get_current_scope.tags).not_to have_key(:job) + end + + it "restores the prior thread-local hub when the job runs on a thread that already has one" do + hubs = {} + job = job_fixture do + define_method(:perform) do + hubs[:inside_job] = Thread.current.thread_variable_get(Sentry::THREAD_LOCAL) + end + end + + Sentry.get_current_scope # force the lazy clone so the test thread has a hub + hubs[:before] = Thread.current.thread_variable_get(Sentry::THREAD_LOCAL) + + job.perform_now + + hubs[:after] = Thread.current.thread_variable_get(Sentry::THREAD_LOCAL) + + expect(hubs[:before]).not_to be_nil + + expect(hubs[:inside_job]).not_to equal(hubs[:before]) + expect(hubs[:after]).to equal(hubs[:before]) + end + + it "restores a stale thread-local hub left by a previous job on the same worker thread" do + job = job_fixture do + def perform; end + end + + hubs = Thread.new do + stale = Sentry.get_main_hub.clone + Thread.current.thread_variable_set(Sentry::THREAD_LOCAL, stale) + + job.perform_now + + { stale: stale, after: Thread.current.thread_variable_get(Sentry::THREAD_LOCAL) } + end.value + + expect(hubs[:after]).to equal(hubs[:stale]) + end +end diff --git a/sentry-rails/spec/active_job/sidekiq_adapter_spec.rb b/sentry-rails/spec/active_job/sidekiq_adapter_spec.rb new file mode 100644 index 000000000..be7b15fd7 --- /dev/null +++ b/sentry-rails/spec/active_job/sidekiq_adapter_spec.rb @@ -0,0 +1,32 @@ +# frozen_string_literal: true + +require "spec_helper" + +# These specs only pass on Rails > 7.0 — older Rails/Sidekiq adapter +# combinations expose differences (e.g. enqueue payload shape, retry +# wiring) that the shared examples don't tolerate. Bail out before +# loading Sidekiq so older matrices don't trip on the gem either. +return if RAILS_VERSION <= 7.0 + +# Sidekiq is also gated in the Gemfile by Ruby version and platform. +# Matrices that don't bundle Sidekiq won't have it available — rescue +# LoadError and skip the whole file so they don't blow up on the +# `include_context "sidekiq adapter"` below. +begin + require "sidekiq" + if ::Sidekiq.respond_to?(:testing!) + ::Sidekiq.testing!(:fake) + else + require "sidekiq/testing" + end +rescue LoadError + return +end + +RSpec.describe "Sentry + ActiveJob on the sidekiq adapter", type: :job do + include_context "active_job backend harness", adapter: :sidekiq + include_context "sidekiq adapter" + + it_behaves_like "a Sentry-instrumented ActiveJob backend" + it_behaves_like "an ActiveJob backend that supports distributed tracing" +end diff --git a/sentry-rails/spec/active_job/support/harness.rb b/sentry-rails/spec/active_job/support/harness.rb index 4e489fb20..ac78f3922 100644 --- a/sentry-rails/spec/active_job/support/harness.rb +++ b/sentry-rails/spec/active_job/support/harness.rb @@ -1,50 +1,122 @@ # frozen_string_literal: true +# Backend-agnostic harness for the common ActiveJob spec suite. +# +# This file contains zero knowledge of any specific queue adapter. Each +# adapter spec composes this shared context with its own adapter shared +# context (e.g. "test adapter", "sidekiq adapter") that fills in the +# adapter-specific hooks below. +# +# Adapter selection goes through ActiveJob::TestHelper's official +# +queue_adapter_for_test+ hook. TestHelper's +before_setup+ reads it +# and installs the returned adapter as Base's +_test_adapter+, which the +# +queue_adapter+ reader prefers over the underlying +_queue_adapter+. +# This avoids fighting with the railtie/dummy-app defaults and keeps the +# harness from reaching past TestHelper into private internals. RSpec.shared_context "active_job backend harness" do |adapter:| let(:adapter) { adapter } let(:configure_sentry) { proc { } } + # Boot the dummy Rails app ONCE per example group. Each +make_basic_app+ + # call creates a new +Rails::Application+ subclass and re-runs every + # initializer — including Sidekiq's railtie (which appends two entries + # to +Sidekiq.@config_blocks+) and Rails' route-drawing (which also + # accumulates). Repeating that for every example caused per-example + # time to grow ~3× over the run, which is what pushed the + # Ruby 3.4 + Rails 8.1.3 CI matrix past the 15-min timeout. + # + # We reproduce the relevant per-example pieces of the Sentry/Rails + # railtie's +config.after_initialize+ block below (re-init Sentry, + # re-activate tracing/structured logging, re-register AJ event + # handlers) so each example still gets a fresh Sentry configuration. + before(:all) do + make_basic_app + end + around do |example| - make_basic_app(&configure_sentry) - setup_sentry_test + Sentry.init do |config| + config.release = "beta" + config.dsn = "http://12345:67890@sentry.localdomain:3000/sentry/42" + config.transport.transport_class = Sentry::DummyTransport + config.background_worker_threads = 0 + config.include_local_variables = true + configure_sentry.call(config, ::Rails.application) if configure_sentry + end + + # Mirror the bits of Sentry::Rails::Railtie's after_initialize hook + # that need to run AFTER Sentry.init each example — the one-time + # extensions (controller methods, streaming reporter, backtrace + # cleanup callback, etc.) were already wired up by the initial + # make_basic_app in before(:all) and persist for the rest of the + # group. + if Sentry.configuration.tracing_enabled? && Sentry.configuration.instrumenter == :sentry + Sentry::Rails::Tracing.register_subscribers(Sentry.configuration.rails.tracing_subscribers) + Sentry::Rails::Tracing.subscribe_tracing_events + Sentry::Rails::Tracing.patch_active_support_notifications + end + + if Sentry.configuration.rails.structured_logging.enabled? && Sentry.configuration.enable_logs + Sentry::Rails::StructuredLogging.attach(Sentry.configuration.rails.structured_logging) + end + + if defined?(Sentry::Rails::ActiveJobExtensions) + Sentry::Rails::ActiveJobExtensions::SentryReporter.register_event_handlers + end - ::ActiveJob::Base.queue_adapter = adapter + setup_sentry_test boot_adapter(adapter) - example.run + with_adapter_active { example.run } ensure reset_adapter(adapter) - teardown_sentry_test end + # ActiveJob::TestHelper hook. Returning a non-nil adapter instance + # causes TestHelper to install it as Base's +_test_adapter+ for the + # duration of each example. Adapter contexts override this. + def queue_adapter_for_test + end + + # Optional block wrapper around +example.run+. The default just yields. + # Adapter contexts override this when the adapter needs a scoped + # runtime mode active during enqueue + drain (e.g. wrapping the + # example in +Sidekiq::Testing.fake!+ so fake mode is scoped per + # example without touching global state). + def with_adapter_active(&block) + yield + end + + # Per-adapter environment setup hook. Backends extend this when they + # need to load schemas, start supervisors, or otherwise prepare the + # environment. def boot_adapter(_adapter) - # Per-adapter setup hook. Backends extend this when they need to load - # schemas, start supervisors, or otherwise prepare the environment. end + # Per-adapter environment teardown hook. Backends extend this to + # truncate tables or otherwise clean up state between examples. def reset_adapter(_adapter) - # Per-adapter teardown hook. Backends extend this to truncate tables - # or otherwise clean up state between examples. end + # Drive the adapter to completion. Each adapter context must override + # this with a strategy that drains its queue (and any retried/scheduled + # jobs cascaded by the drain) to completion. def drain(at: nil) - case adapter - when :test - if RAILS_VERSION < 6.0 - # Rails 5.2: perform_enqueued_jobs always requires a block and only runs - # jobs enqueued *inside* the block. Manually flush already-enqueued jobs. - jobs = queue_adapter.enqueued_jobs.dup - queue_adapter.enqueued_jobs.clear - jobs.each { |payload| send(:instantiate_job, payload).perform_now } - else - kwargs = at ? { at: at } : {} - perform_enqueued_jobs(**kwargs) - end - else - raise NotImplementedError, "active_job backend harness has no drain strategy for adapter: #{adapter.inspect}" - end + raise NotImplementedError, + "active_job backend harness has no drain strategy for adapter: #{adapter.inspect}. " \ + "Include the matching adapter shared context (e.g. 'test adapter', 'sidekiq adapter')." + end + + # Return the most recently enqueued job's serialized payload as a Hash + # keyed by ActiveJob's stringified field names (so callers can read + # +payload["_sentry"]+, +payload["arguments"]+, etc.). Each adapter + # context must override this since the on-the-wire shape differs per + # backend. + def last_enqueued_payload + raise NotImplementedError, + "active_job backend harness has no last_enqueued_payload accessor for adapter: #{adapter.inspect}. " \ + "Include the matching adapter shared context (e.g. 'test adapter', 'sidekiq adapter')." end def job_fixture(name = nil, &block) @@ -53,4 +125,28 @@ def job_fixture(name = nil, &block) stub_const(name, klass) klass end + + def transactions + sentry_events.select { |e| e.is_a?(Sentry::TransactionEvent) } + end + + def consumer_transaction + transactions.find { |t| t.contexts.dig(:trace, :op) == "queue.active_job" } + end + + def within_parent_transaction(name: "parent.test", op: "test") + txn = Sentry.start_transaction(name: name, op: op) + Sentry.get_current_scope.set_span(txn) if txn + yield(txn) + ensure + txn&.finish + end + + # Hook used by the worker_hub_isolation shared example. The default + # is a plain Thread.new — adapters that need extra setup (e.g. an + # isolated database per worker thread, like :solid_queue on SQLite) + # override this to wrap the block in their isolation scope. + def worker_thread(&block) + Thread.new(&block) + end end diff --git a/sentry-rails/spec/active_job/support/sidekiq_adapter_context.rb b/sentry-rails/spec/active_job/support/sidekiq_adapter_context.rb new file mode 100644 index 000000000..76e99cdcf --- /dev/null +++ b/sentry-rails/spec/active_job/support/sidekiq_adapter_context.rb @@ -0,0 +1,89 @@ +# frozen_string_literal: true + +# Adapter context for the :sidekiq ActiveJob backend. +# +# Composes with "active_job backend harness" to drive Sidekiq via its +# in-memory testing mode. No Redis required: jobs are JSON-round-tripped +# into Sidekiq's class-keyed jobs hash at enqueue time and run in-process +# by drain_all. +# +# This context deliberately does NOT require sentry-sidekiq. Loading +# sentry-sidekiq would install Sidekiq's client/server middleware (which +# emits its own queue.process transactions) and register SidekiqAdapter +# in skippable_job_adapters (which short-circuits the AJ extension under +# test). +begin + require "sidekiq" + # Sidekiq 8.1+ deprecates `require "sidekiq/testing"` in favor of + # `Sidekiq.testing!`, which loads the same test API without the + # implicit side effect of activating :fake mode at require time. + if ::Sidekiq.respond_to?(:testing!) + ::Sidekiq.testing!(:fake) + else + require "sidekiq/testing" + end +rescue LoadError + # Sidekiq isn't bundled on this matrix (e.g. Rails 5.2). The matching + # spec file is gated on RAILS_VERSION so it won't try to use this + # context; skip defining it. + return +end + +RSpec.shared_context "sidekiq adapter" do + # Instantiated once. Each SidekiqAdapter.new appends blocks to + # Sidekiq's internal @config_blocks list (configure_server) and adds + # an on(:quiet) callback (configure_client). Creating a fresh + # adapter per example accumulated several hundred entries across a + # full suite run and showed up as compounding per-example slowdown. + SIDEKIQ_ADAPTER_FOR_TEST = ::ActiveJob::QueueAdapters::SidekiqAdapter.new + + def queue_adapter_for_test + SIDEKIQ_ADAPTER_FOR_TEST + end + + # Scope fake mode to this example only — the block form of +fake!+ + # uses a per-thread flag that auto-restores when the block exits, so + # parallel specs and any global Sidekiq mode set elsewhere are left + # untouched. Wrapping +example.run+ ensures both the +perform_later+ + # (enqueue) and +drain+ (consume) paths see fake mode. + def with_adapter_active(&block) + if ::Sidekiq.respond_to?(:testing!) + ::Sidekiq.testing!(:fake, &block) + else + ::Sidekiq::Testing.fake!(&block) + end + end + + def drain(at: nil) + # +drain_all+ loops +while jobs.any?+, so retried jobs (re-enqueued + # by ActiveJob's +retry_on+ during a drain pass) cascade within a + # single call. Exceptions raised by the worker propagate out — + # preserving the +expect { drain }.to raise_error(...)+ semantics + # the shared examples rely on. + sidekiq_job_class.drain_all + end + + def reset_adapter(_adapter) + sidekiq_job_class.clear_all + end + + def last_enqueued_payload + job = ::ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper.jobs.last + return nil if job.nil? + + # The AJ-on-Sidekiq adapter wraps the AJ payload as the first + # element of the Sidekiq job's args array (see + # +Sidekiq::ActiveJob::Wrapper#perform+ / + # +SidekiqAdapter::JobWrapper#perform+). + job["args"].first + end + + private + + # Sidekiq 8 renamed +Sidekiq::Worker+ to +Sidekiq::Job+ (with a + # back-compat alias). Reach for whichever is canonical on the + # installed version. + def sidekiq_job_class + defined?(::Sidekiq::Job) ? ::Sidekiq::Job : ::Sidekiq::Worker + end +end diff --git a/sentry-rails/spec/active_job/support/test_adapter_context.rb b/sentry-rails/spec/active_job/support/test_adapter_context.rb new file mode 100644 index 000000000..6b609d688 --- /dev/null +++ b/sentry-rails/spec/active_job/support/test_adapter_context.rb @@ -0,0 +1,95 @@ +# frozen_string_literal: true + +# Adapter context for the :test ActiveJob backend. +# +# Composes with "active_job backend harness". The harness owns the +# example lifecycle; this context owns everything specific to +# ActiveJob::QueueAdapters::TestAdapter (the Rails-5.2 payload- +# preservation shim, the drain loop, and the enqueued-payload +# accessor). + +# Rails 5.2's TestAdapter stores a minimal hash per enqueued job (only +# job class, args, queue) and its +instantiate_job+ recreates jobs via +# +.new(*args)+ — never calling our +deserialize+ override. That means +# the +_sentry+ payload injected by +serialize+ is silently discarded +# before the consumer ever sees it, breaking distributed-tracing +# propagation. +# +# This adapter subclass calls +job.serialize+ a second time after +super+ +# has stored the minimal hash and saves the full output alongside it. +# The drain then drives each job through +ActiveJob::Base.execute(full_payload)+, +# which goes through the normal deserialize → perform_now path and picks +# up the Sentry trace headers and user context that were captured at +# enqueue time. +class Rails52FullPayloadTestAdapter < ::ActiveJob::QueueAdapters::TestAdapter + def enqueue(job) + prev = enqueued_jobs.length + super + enqueued_jobs.last[:_sentry_full_payload] = job.serialize if enqueued_jobs.length > prev + end + + def enqueue_at(job, timestamp) + prev = enqueued_jobs.length + super + enqueued_jobs.last[:_sentry_full_payload] = job.serialize if enqueued_jobs.length > prev + end +end + +RSpec.shared_context "test adapter" do + def queue_adapter_for_test + # On Rails 5.2 swap in the augmented adapter so the drain can replay + # the full serialize payload. On Rails 6.0+ returning nil lets + # TestHelper install its own TestAdapter — the standard path. + Rails52FullPayloadTestAdapter.new if RAILS_VERSION < 6.0 + end + + def drain(at: nil) + # Loop until the queue is empty so retries (which re-enqueue during + # a drain pass) are cascaded through to completion. Both Rails 5.2's + # manual flush and Rails 6+'s +perform_enqueued_jobs(no block)+ + # operate on a snapshot, so a single pass would only run jobs that + # existed before draining started. + loop do + break if queue_adapter.enqueued_jobs.empty? + + if RAILS_VERSION < 6.1 + # Rails 5.2 and 6.0 both need a manual flush: + # - 5.2's +perform_enqueued_jobs+ always requires a block and + # only runs jobs enqueued *inside* the block, so it can't + # drain a pre-existing queue at all. + # - 6.0's +flush_enqueued_jobs+ iterates with +perform_now+ + # but doesn't remove payloads from +enqueued_jobs+ (the + # +delete(payload)+ call was only added in 6.1), so looping + # on +enqueued_jobs.empty?+ would spin forever. + # On 5.2 with Rails52FullPayloadTestAdapter, each payload also + # carries a +:_sentry_full_payload+ key with the complete + # serialize output. Drive those jobs through +Base.execute+ so + # our deserialize override runs and populates +_sentry+ + # before +perform_now+. + jobs = queue_adapter.enqueued_jobs.dup + queue_adapter.enqueued_jobs.clear + jobs.each do |payload| + if (full = payload[:_sentry_full_payload]) + ::ActiveJob::Base.execute(full) + else + send(:instantiate_job, payload).perform_now + end + end + else + kwargs = at ? { at: at } : {} + perform_enqueued_jobs(**kwargs) + end + end + end + + def last_enqueued_payload + payload = queue_adapter.enqueued_jobs.last + return nil if payload.nil? + + # On Rails < 6.0 we mirror the full serialize output under a side + # key (see Rails52FullPayloadTestAdapter above). Prefer that when + # present so callers see the same string-keyed shape they'd see on + # 6.0+. + payload[:_sentry_full_payload] || payload + end +end diff --git a/sentry-rails/spec/active_job/test_adapter_spec.rb b/sentry-rails/spec/active_job/test_adapter_spec.rb index 4d5e704de..e3093d938 100644 --- a/sentry-rails/spec/active_job/test_adapter_spec.rb +++ b/sentry-rails/spec/active_job/test_adapter_spec.rb @@ -4,6 +4,8 @@ RSpec.describe "Sentry + ActiveJob on the test adapter", type: :job do include_context "active_job backend harness", adapter: :test + include_context "test adapter" it_behaves_like "a Sentry-instrumented ActiveJob backend" + it_behaves_like "an ActiveJob backend that supports distributed tracing" end diff --git a/sentry-rails/spec/sentry/rails/configuration_spec.rb b/sentry-rails/spec/sentry/rails/configuration_spec.rb index 7c64a12cd..6988d205d 100644 --- a/sentry-rails/spec/sentry/rails/configuration_spec.rb +++ b/sentry-rails/spec/sentry/rails/configuration_spec.rb @@ -72,6 +72,12 @@ class MySubscriber; end end end + describe "#active_job_propagate_traces" do + it "has correct default value" do + expect(subject.active_job_propagate_traces).to be(true) + end + end + describe "#structured_logging" do let(:config) { Sentry.configuration.rails } diff --git a/sentry-rails/spec/sentry/rails/tracing/active_storage_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/tracing/active_storage_subscriber_spec.rb index f41b379e1..ec74550f3 100644 --- a/sentry-rails/spec/sentry/rails/tracing/active_storage_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/tracing/active_storage_subscriber_spec.rb @@ -44,14 +44,13 @@ request_transaction = transport.events.last.to_h expect(request_transaction[:type]).to eq("transaction") - expect(request_transaction[:spans].count).to eq(2) - - span = request_transaction[:spans][1] - expect(span[:op]).to eq("file.service_upload.active_storage") - expect(span[:origin]).to eq("auto.file.rails") - expect(span[:description]).to eq("Disk") - expect(span.dig(:data, :key)).to be_nil - expect(span[:trace_id]).to eq(request_transaction.dig(:contexts, :trace, :trace_id)) + + upload_span = request_transaction[:spans].find { |s| s[:op] == "file.service_upload.active_storage" } + expect(upload_span).not_to be_nil + expect(upload_span[:origin]).to eq("auto.file.rails") + expect(upload_span[:description]).to eq("Disk") + expect(upload_span.dig(:data, :key)).to be_nil + expect(upload_span[:trace_id]).to eq(request_transaction.dig(:contexts, :trace, :trace_id)) end end @@ -73,10 +72,10 @@ request_transaction = transport.events.last.to_h expect(request_transaction[:type]).to eq("transaction") - expect(request_transaction[:spans].count).to eq(2) - span = request_transaction[:spans][1] - expect(span.dig(:data, :key)).to eq(p.cover.key) + upload_span = request_transaction[:spans].find { |s| s[:op] == "file.service_upload.active_storage" } + expect(upload_span).not_to be_nil + expect(upload_span.dig(:data, :key)).to eq(p.cover.key) end end diff --git a/spec/apps/svelte-mini/src/App.svelte b/spec/apps/svelte-mini/src/App.svelte index f7a93b0a6..bc21def22 100644 --- a/spec/apps/svelte-mini/src/App.svelte +++ b/spec/apps/svelte-mini/src/App.svelte @@ -2,6 +2,9 @@ let loading = false; let result = ""; + let jobLoading = false; + let jobResult = ""; + async function triggerError() { loading = true; try { @@ -24,6 +27,29 @@ loading = false; } } + + async function triggerJob() { + jobLoading = true; + try { + const response = await fetch(`${SENTRY_E2E_RAILS_APP_URL}/jobs/sample`, { + method: "POST", + headers: { + "Content-Type": "application/json", + }, + }); + + if (response.ok) { + const data = await response.json(); + jobResult = `Job: ${JSON.stringify(data)}`; + } else { + jobResult = `Error: ${response.status} ${response.statusText}`; + } + } catch (error) { + jobResult = `Error: ${error.message}`; + } finally { + jobLoading = false; + } + }
@@ -43,6 +69,23 @@
{result}
{/if} + +

+ Click the button to enqueue an ActiveJob in the Rails app — distributed + tracing should connect this fetch, the Rails controller, the + queue.publish span, and the async-executed job: +

+ + + + {#if jobResult} +
+

Job result:

+
{jobResult}
+
+ {/if}