Deprecate set_http_or_background_queue_start (#1175)

Deprecate the `Transaction#set_http_or_background_queue_start` method so
that the transaction doesn't need to know about any 'request' set on the
transaction. The instrumentations themselves can set the queue start
using the `Transaction#set_queue_start` method.

Move the logic for conversion of the queue start time from request
headers to a utils class so it can be accessed by the instrumentations.

.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.

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
           "<h1>Hello world!</h1>" 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")

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

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"

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)

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)

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

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

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

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

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

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