diff --git a/.changesets/deprecate--appsignal--transaction-set_http_or_background_queue_start-.md b/.changesets/deprecate--appsignal--transaction-set_http_or_background_queue_start-.md new file mode 100644 index 000000000..b3226bda9 --- /dev/null +++ b/.changesets/deprecate--appsignal--transaction-set_http_or_background_queue_start-.md @@ -0,0 +1,6 @@ +--- +bump: patch +type: deprecate +--- + +Deprecate the `Appsignal::Transaction#set_http_or_background_queue_start` method. Use the `Appsignal::Transaction#set_queue_start` instead. diff --git a/lib/appsignal/demo.rb b/lib/appsignal/demo.rb index a54b2db8b..52d53b043 100644 --- a/lib/appsignal/demo.rb +++ b/lib/appsignal/demo.rb @@ -50,7 +50,6 @@ def create_example_error_request rescue => error Appsignal.set_error(error) end - transaction.set_http_or_background_queue_start transaction.set_metadata("path", "/hello") transaction.set_metadata("method", "GET") transaction.set_action("DemoController#hello") @@ -68,7 +67,6 @@ def create_example_performance_request "

Hello world!

" do sleep 2 end - transaction.set_http_or_background_queue_start transaction.set_metadata("path", "/hello") transaction.set_metadata("method", "GET") transaction.set_action("DemoController#hello") diff --git a/lib/appsignal/helpers/instrumentation.rb b/lib/appsignal/helpers/instrumentation.rb index 42a18d5c7..8a2872f44 100644 --- a/lib/appsignal/helpers/instrumentation.rb +++ b/lib/appsignal/helpers/instrumentation.rb @@ -88,7 +88,9 @@ def monitor_transaction(name, env = {}, &block) raise error ensure transaction.set_http_or_background_action(request.env) - transaction.set_http_or_background_queue_start + queue_start = Appsignal::Rack::Utils.queue_start_from(request.env) || + (env[:queue_start]&.to_i&.* 1_000) + transaction.set_queue_start(queue_start) if queue_start Appsignal::Transaction.complete_current! end end diff --git a/lib/appsignal/integrations/sidekiq.rb b/lib/appsignal/integrations/sidekiq.rb index a34dcf5ce..02bd9aab8 100644 --- a/lib/appsignal/integrations/sidekiq.rb +++ b/lib/appsignal/integrations/sidekiq.rb @@ -68,9 +68,7 @@ def call(_worker, item, _queue, &block) transaction = Appsignal::Transaction.create( item["jid"], Appsignal::Transaction::BACKGROUND_JOB, - Appsignal::Transaction::GenericRequest.new( - :queue_start => item["enqueued_at"] - ) + Appsignal::Transaction::GenericRequest.new({}) ) transaction.set_action_if_nil(formatted_action_name(item)) @@ -85,7 +83,8 @@ def call(_worker, item, _queue, &block) ensure if transaction transaction.set_params_if_nil { parse_arguments(item) } - transaction.set_http_or_background_queue_start + queue_start = (item["enqueued_at"].to_f * 1000.0).to_i # Convert seconds to milliseconds + transaction.set_queue_start(queue_start) Appsignal::Transaction.complete_current! unless exception queue = item["queue"] || "unknown" diff --git a/lib/appsignal/rack.rb b/lib/appsignal/rack.rb index 57211ad7c..2d60702ab 100644 --- a/lib/appsignal/rack.rb +++ b/lib/appsignal/rack.rb @@ -3,6 +3,35 @@ module Appsignal # @api private module Rack + class Utils + # Fetch the queue start time from the request environment. + # + # @since 3.11.0 + # @param env [Hash] Request environment hash. + # @return [Integer, NilClass] + def self.queue_start_from(env) + return unless env + + env_var = env["HTTP_X_QUEUE_START"] || env["HTTP_X_REQUEST_START"] + return unless env_var + + cleaned_value = env_var.tr("^0-9", "") + return if cleaned_value.empty? + + value = cleaned_value.to_i + if value > 4_102_441_200_000 + # Value is in microseconds. Transform to milliseconds. + value / 1_000 + elsif value < 946_681_200_000 + # Value is too low to be plausible + nil + else + # Value is in milliseconds + value + end + end + end + # Alias constants that have moved with a warning message that points to the # place to update the reference. def self.const_missing(name) diff --git a/lib/appsignal/rack/abstract_middleware.rb b/lib/appsignal/rack/abstract_middleware.rb index 7ed5aea6f..1b0ebbd35 100644 --- a/lib/appsignal/rack/abstract_middleware.rb +++ b/lib/appsignal/rack/abstract_middleware.rb @@ -148,7 +148,8 @@ def add_transaction_metadata_after(transaction, request) transaction.set_metadata("method", request_method) if request_method transaction.set_params_if_nil { params_for(request) } - transaction.set_http_or_background_queue_start + queue_start = Appsignal::Rack::Utils.queue_start_from(request.env) + transaction.set_queue_start(queue_start) if queue_start end def params_for(request) diff --git a/lib/appsignal/rack/event_handler.rb b/lib/appsignal/rack/event_handler.rb index db2602826..b73f29faa 100644 --- a/lib/appsignal/rack/event_handler.rb +++ b/lib/appsignal/rack/event_handler.rb @@ -75,7 +75,8 @@ def on_start(request, _response) Appsignal::Rack::EventHandler .safe_execution("Appsignal::Rack::EventHandler's after_reply") do transaction.finish_event("process_request.rack", "", "") - transaction.set_http_or_background_queue_start + queue_start = Appsignal::Rack::Utils.queue_start_from(request.env) + transaction.set_queue_start(queue_start) if queue_start end # Make sure the current transaction is always closed when the request @@ -113,7 +114,8 @@ def on_finish(request, response) self.class.safe_execution("Appsignal::Rack::EventHandler#on_finish") do transaction.finish_event("process_request.rack", "", "") - transaction.set_http_or_background_queue_start + queue_start = Appsignal::Rack::Utils.queue_start_from(request.env) + transaction.set_queue_start(queue_start) if queue_start response_status = if response response.status diff --git a/lib/appsignal/transaction.rb b/lib/appsignal/transaction.rb index 0bd908c00..1e30173e1 100644 --- a/lib/appsignal/transaction.rb +++ b/lib/appsignal/transaction.rb @@ -436,8 +436,6 @@ def set_http_or_background_action(from = request.params) # Set queue start time for transaction. # - # Most commononly called by {set_http_or_background_queue_start}. - # # @param start [Integer] Queue start time in milliseconds. # @raise [RangeError] When the queue start time value is too big, this # method raises a RangeError. @@ -467,8 +465,14 @@ def set_queue_start(start) # AppSignal as seconds. # # @see https://docs.appsignal.com/ruby/instrumentation/request-queue-time.html + # @deprecated Use {#set_queue_start} instead. # @return [void] def set_http_or_background_queue_start + Appsignal::Utils::StdoutAndLoggerMessage.warning \ + "The Appsignal::Transaction#set_http_or_background_queue_start " \ + "method has been deprecated. " \ + "Please use the Appsignal::Transaction#set_queue_start method instead." + start = http_queue_start || background_queue_start return unless start @@ -683,25 +687,7 @@ def background_queue_start # @return [Integer] queue start in milliseconds. def http_queue_start env = environment - return unless env - - env_var = env["HTTP_X_QUEUE_START"] || env["HTTP_X_REQUEST_START"] - return unless env_var - - cleaned_value = env_var.tr("^0-9", "") - return if cleaned_value.empty? - - value = cleaned_value.to_i - if value > 4_102_441_200_000 - # Value is in microseconds. Transform to milliseconds. - value / 1_000 - elsif value < 946_681_200_000 - # Value is too low to be plausible - nil - else - # Value is in milliseconds - value - end + Appsignal::Rack::Utils.queue_start_from(env) end def sanitized_params diff --git a/spec/lib/appsignal/rack_spec.rb b/spec/lib/appsignal/rack_spec.rb new file mode 100644 index 000000000..6d7bec5df --- /dev/null +++ b/spec/lib/appsignal/rack_spec.rb @@ -0,0 +1,63 @@ +describe Appsignal::Rack::Utils do + describe ".queue_start_from" do + let(:header_time) { fixed_time - 0.4 } + let(:header_time_value) { (header_time * factor).to_i } + subject { described_class.queue_start_from(env) } + + shared_examples "HTTP queue start" do + context "when env is nil" do + let(:env) { nil } + + it { is_expected.to be_nil } + end + + context "with no relevant header set" do + let(:env) { {} } + + it { is_expected.to be_nil } + end + + context "with the HTTP_X_REQUEST_START header set" do + let(:env) { { "HTTP_X_REQUEST_START" => "t=#{header_time_value}" } } + + it { is_expected.to eq 1_389_783_599_600 } + + context "with unparsable content" do + let(:env) { { "HTTP_X_REQUEST_START" => "something" } } + + it { is_expected.to be_nil } + end + + context "with unparsable content at the end" do + let(:env) { { "HTTP_X_REQUEST_START" => "t=#{header_time_value}aaaa" } } + + it { is_expected.to eq 1_389_783_599_600 } + end + + context "with a really low number" do + let(:env) { { "HTTP_X_REQUEST_START" => "t=100" } } + + it { is_expected.to be_nil } + end + + context "with the alternate HTTP_X_QUEUE_START header set" do + let(:env) { { "HTTP_X_QUEUE_START" => "t=#{header_time_value}" } } + + it { is_expected.to eq 1_389_783_599_600 } + end + end + end + + context "time in milliseconds" do + let(:factor) { 1_000 } + + it_should_behave_like "HTTP queue start" + end + + context "time in microseconds" do + let(:factor) { 1_000_000 } + + it_should_behave_like "HTTP queue start" + end + end +end diff --git a/spec/lib/appsignal/transaction_spec.rb b/spec/lib/appsignal/transaction_spec.rb index 15be522b6..2868316d3 100644 --- a/spec/lib/appsignal/transaction_spec.rb +++ b/spec/lib/appsignal/transaction_spec.rb @@ -1019,15 +1019,15 @@ def create_transaction(id = transaction_id) describe "#set_queue_start" do it "sets the queue start in extension" do - expect(transaction.ext).to receive(:set_queue_start).with(10.0).once + transaction.set_queue_start(10) - transaction.set_queue_start(10.0) + expect(transaction).to have_queue_start(10) end it "does not set the queue start in extension when value is nil" do - expect(transaction.ext).to_not receive(:set_queue_start) - transaction.set_queue_start(nil) + + expect(transaction).to_not have_queue_start end it "does not raise an error when the queue start is too big" do @@ -1040,17 +1040,44 @@ def create_transaction(id = transaction_id) end describe "#set_http_or_background_queue_start" do + let(:err_stream) { std_stream } + let(:stderr) { err_stream.read } let(:header_factor) { 1_000 } let(:env_queue_start) { fixed_time + 20 } # in seconds + def set_http_or_background_queue_start + capture_std_streams(std_stream, err_stream) do + transaction.set_http_or_background_queue_start + end + end + context "when a queue time is found in a request header" do let(:header_time) { ((fixed_time + 10) * header_factor).to_i } # in milliseconds let(:env) { { "HTTP_X_REQUEST_START" => "t=#{header_time}" } } it "sets the http header value in milliseconds on the transaction" do - expect(transaction).to receive(:set_queue_start).with(1_389_783_610_000) + set_http_or_background_queue_start - transaction.set_http_or_background_queue_start + expect(transaction).to have_queue_start(1_389_783_610_000) + end + + it "logs a deprecation message" do + logs = capture_logs { set_http_or_background_queue_start } + + expect(logs).to contains_log( + :warn, + "The Appsignal::Transaction#set_http_or_background_queue_start " \ + "method has been deprecated." + ) + end + + it "prints a deprecation message" do + set_http_or_background_queue_start + + expect(stderr).to include( + "The Appsignal::Transaction#set_http_or_background_queue_start " \ + "method has been deprecated." + ) end context "when a :queue_start key is found in the transaction environment" do @@ -1062,9 +1089,9 @@ def create_transaction(id = transaction_id) end it "sets the http header value in milliseconds on the transaction" do - expect(transaction).to receive(:set_queue_start).with(1_389_783_610_000) - transaction.set_http_or_background_queue_start + + expect(transaction).to have_queue_start(1_389_783_610_000) end end end @@ -1073,9 +1100,9 @@ def create_transaction(id = transaction_id) let(:env) { { :queue_start => env_queue_start } } # in seconds it "sets the :queue_start value in milliseconds on the transaction" do - expect(transaction).to receive(:set_queue_start).with(1_389_783_620_000) - transaction.set_http_or_background_queue_start + + expect(transaction).to have_queue_start(1_389_783_620_000) end end end diff --git a/spec/lib/appsignal_spec.rb b/spec/lib/appsignal_spec.rb index 7cb37808d..ef792467e 100644 --- a/spec/lib/appsignal_spec.rb +++ b/spec/lib/appsignal_spec.rb @@ -368,7 +368,8 @@ "perform_job.something", { :class => "BackgroundJob", - :method => "perform" + :method => "perform", + :queue_start => fixed_time.to_i } ) do :return_value @@ -380,6 +381,7 @@ expect(transaction).to have_namespace(Appsignal::Transaction::BACKGROUND_JOB) expect(transaction).to have_action("BackgroundJob#perform") expect(transaction).to include_event("name" => "perform_job.something") + expect(transaction).to have_queue_start(1_389_783_600_000) expect(transaction).to be_completed end @@ -391,7 +393,8 @@ "process_action.something", { :controller => "BlogPostsController", - :action => "show" + :action => "show", + "HTTP_X_REQUEST_START" => "t=#{fixed_time.to_i * 1000}" } ) do :return_value @@ -403,6 +406,7 @@ expect(transaction).to have_namespace(Appsignal::Transaction::HTTP_REQUEST) expect(transaction).to have_action("BlogPostsController#show") expect(transaction).to include_event("name" => "process_action.something") + expect(transaction).to have_queue_start(1_389_783_600_000) expect(transaction).to be_completed end end diff --git a/spec/support/matchers/transaction.rb b/spec/support/matchers/transaction.rb index 2d7ef19a6..234eb1e77 100644 --- a/spec/support/matchers/transaction.rb +++ b/spec/support/matchers/transaction.rb @@ -180,6 +180,18 @@ def format_breadcrumb(action, category, message, metadata, time) RSpec::Matchers.define :have_queue_start do |queue_start_time| match(:notify_expectation_failures => true) do |transaction| - expect(transaction.ext.queue_start).to eq(queue_start_time) + if queue_start_time + expect(transaction.ext.queue_start).to eq(queue_start_time) + else + expect(transaction.ext.queue_start).to_not be_nil + end + end + + match_when_negated(:notify_expectation_failures => true) do |transaction| + if queue_start_time + expect(transaction.ext.queue_start).to_not eq(queue_start_time) + else + expect(transaction.ext.queue_start).to be_nil + end end end