[rack] add request queuing option to the Rack middleware; compatibili…

…ty only for nginx

lib/ddtrace/contrib/rack/middlewares.rb

@@ -1,6 +1,7 @@
 require 'ddtrace/ext/app_types'
 require 'ddtrace/ext/http'
 require 'ddtrace/propagation/http_propagator'
+require 'ddtrace/contrib/rack/request_queue'
 
 module Datadog
   module Contrib
@@ -22,24 +23,47 @@ class TraceMiddleware
           value
         end
         option :distributed_tracing, default: false
+        option :request_queuing, default: false
+        option :web_service_name, default: 'web-server', depends_on: [:tracer, :request_queuing] do |value|
+          if get_option(:request_queuing)
+            get_option(:tracer).set_service_info(value, 'webserver', Ext::AppTypes::WEB)
+          end
+          value
+        end
 
         def initialize(app)
           @app = app
         end
 
+        def compute_queueing_time(env, tracer)
+          return unless Datadog.configuration[:rack][:request_queuing]
+
+          # parse the request enqueue time
+          request_start = Datadog::Contrib::Rack::QueueTime.get_request_start(env)
+          return if request_start.nil?
+
+          tracer.trace(
+            'request.enqueuing',
+            start_time: request_start,
+            service: Datadog.configuration[:rack][:web_service_name]
+          )
+        end
+
         def call(env)
           # retrieve integration settings
           tracer = Datadog.configuration[:rack][:tracer]
-          service = Datadog.configuration[:rack][:service_name]
-          distributed_tracing = Datadog.configuration[:rack][:distributed_tracing]
+
+          # [experimental] create a root Span to keep track of frontend web servers
+          # (i.e. Apache, nginx) if the header is properly set
+          frontend_span = compute_queueing_time(env, tracer)
 
           trace_options = {
-            service: service,
+            service: Datadog.configuration[:rack][:service_name],
             resource: nil,
             span_type: Datadog::Ext::HTTP::TYPE
           }
 
-          if distributed_tracing
+          if Datadog.configuration[:rack][:distributed_tracing]
             context = HTTPPropagator.extract(env)
             tracer.provider.context = context if context.trace_id
           end
@@ -99,6 +123,7 @@ def call(env)
           # ensure the request_span is finished and the context reset;
           # this assumes that the Rack middleware creates a root span
           request_span.finish
+          frontend_span.finish unless frontend_span.nil?
 
           # TODO: Remove this once we change how context propagation works. This
           # ensures we clean thread-local variables on each HTTP request avoiding

lib/ddtrace/contrib/rack/request_queue.rb

@@ -0,0 +1,32 @@
+module Datadog
+  module Contrib
+    module Rack
+      # QueueTime simply...
+      module QueueTime
+        REQUEST_START = 'HTTP_X_REQUEST_START'.freeze
+
+        module_function
+
+        def get_request_start(env, now = Time.now.utc)
+          header = env[REQUEST_START]
+          return unless header
+
+          # nginx header is in the format "t=1512379167.574"
+          # TODO: this should be generic enough to work with any
+          # frontend web server or load balancer
+          time_string = header.split('t=')[1]
+          return if time_string.nil?
+
+          # return the request_start only if it's lesser than
+          # current time, to avoid significant clock skew
+          request_start = Time.at(time_string.to_f)
+          request_start.utc > now ? nil : request_start
+        rescue
+          # in case of an Exception we don't create a
+          # `request.enqueuing` span
+          nil
+        end
+      end
+    end
+  end
+end

test/contrib/rack/request_parser_test.rb

@@ -0,0 +1,13 @@
+require 'ddtrace/contrib/rack/request_queue'
+
+class QueueTimeParserTest < Minitest::Test
+  include Rack::Test::Methods
+
+  def test_nginx_header
+    # ensure nginx headers are properly parsed
+    headers = {}
+    headers['HTTP_X_REQUEST_START'] = 't=1512379167.574'
+    request_start = Datadog::Contrib::Rack::QueueTime.get_request_start(headers)
+    assert_equal(1512379167.574, request_start.to_f)
+  end
+end

test/contrib/rack/request_queueing_test.rb

@@ -0,0 +1,96 @@
+require 'contrib/rack/helpers'
+
+class RequestQueuingTest < RackBaseTest
+  def setup
+    super
+    # enable request_queueing
+    Datadog.configuration[:rack][:request_queuing] = true
+  end
+
+  def test_request_queuing_header
+    # ensure a queuing Span is created if the header is available
+    request_start = (Time.now.utc - 5).to_i
+    header 'x-request-start', "t=#{request_start}"
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans()
+    assert_equal(2, spans.length)
+
+    rack_span = spans[0]
+    frontend_span = spans[1]
+    assert_equal('rack.request', rack_span.name)
+    assert_equal('request.enqueuing', frontend_span.name)
+
+    assert_equal('http', rack_span.span_type)
+    assert_equal('rack', rack_span.service)
+    assert_equal('GET 200', rack_span.resource)
+    assert_equal('GET', rack_span.get_tag('http.method'))
+    assert_equal('200', rack_span.get_tag('http.status_code'))
+    assert_equal('/success/', rack_span.get_tag('http.url'))
+    assert_equal(0, rack_span.status)
+    assert_equal(frontend_span.span_id, rack_span.parent_id)
+
+    assert_equal('web-server', frontend_span.service)
+    assert_equal(request_start, frontend_span.start_time.to_i)
+  end
+
+  def test_request_queuing_service_name
+    # ensure a queuing Span is created if the header is available
+    Datadog.configuration[:rack][:web_service_name] = 'nginx'
+    request_start = (Time.now.utc - 5).to_i
+    header 'x-request-start', "t=#{request_start}"
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans()
+    assert_equal(2, spans.length)
+
+    rack_span = spans[0]
+    frontend_span = spans[1]
+    assert_equal('rack.request', rack_span.name)
+    assert_equal('request.enqueuing', frontend_span.name)
+
+    assert_equal('nginx', frontend_span.service)
+  end
+
+  def test_clock_skew
+    # ensure a queuing Span is NOT created if there is a clock skew
+    # where the starting time is greater than current host Time.now
+    request_start = (Time.now.utc + 5).to_i
+    header 'x-request-start', "t=#{request_start}"
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans()
+    assert_equal(1, spans.length)
+
+    rack_span = spans[0]
+    assert_equal('rack.request', rack_span.name)
+  end
+
+  def test_wrong_header
+    # ensure a queuing Span is NOT created if the header is wrong
+    header 'x-request-start', 'something_weird'
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans()
+    assert_equal(1, spans.length)
+
+    rack_span = spans[0]
+    assert_equal('rack.request', rack_span.name)
+  end
+
+  def test_enabled_missing_header
+    # ensure a queuing Span is NOT created if the header is missing
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans()
+    assert_equal(1, spans.length)
+
+    rack_span = spans[0]
+    assert_equal('rack.request', rack_span.name)
+  end
+end