[rack] add request queuing option to the Rack middleware

docs/GettingStarted.md

@@ -47,6 +47,7 @@ For descriptions of terminology used in APM, take a look at the [official docume
      - [Sampling](#sampling)
          - [Priority sampling](#priority-sampling)
      - [Distributed tracing](#distributed-tracing)
+     - [HTTP request queuing](#http-request-queuing)
      - [Processing pipeline](#processing-pipeline)
          - [Filtering](#filtering)
          - [Processing](#processing)
@@ -582,6 +583,8 @@ Where `options` is an optional `Hash` that accepts the following parameters:
 | ``quantize.fragment`` | Defines behavior for URL fragments. Removes fragments by default. May be `:show` to show URL fragments. Option must be nested inside the `quantize` option. | ``nil`` |
 | ``application`` | Your Rack application. Necessary for enabling middleware resource names. | ``nil`` |
 | ``tracer`` | A ``Datadog::Tracer`` instance used to instrument the application. Usually you don't need to set that. | ``Datadog.tracer`` |
+| ``request_queuing`` | Track HTTP request time spent in the queue of the frontend server. See [HTTP request queuing](#http-request-queuing) for setup details. Set to `true` to enable. | ``false`` |
+| ``web_service_name`` | Service name for frontend server request queuing spans. (e.g. `'nginx'`) | ``'web-server'`` |
 
 **Configuring URL quantization behavior**
 
@@ -948,6 +951,30 @@ end
 
 Distributed tracing is disabled by default.
 
+### HTTP request queuing
+
+Traces that originate from HTTP requests can be configured to include the time spent in a frontend web server or load balancer queue, before the request reaches the Ruby application.
+
+This functionality is **experimental** and deactivated by default.
+
+To activate this feature, you must add a ``X-Request-Start`` or ``X-Queue-Start`` header from your web server (i.e. Nginx). The following is an Nginx configuration example:
+
+```
+# /etc/nginx/conf.d/ruby_service.conf
+server {
+    listen 8080;
+
+    location / {
+      proxy_set_header X-Request-Start "t=${msec}";
+      proxy_pass http://web:3000;
+    }
+}
+```
+
+Then you must enable the request queuing feature in the integration handling the request.
+
+For Rack based applications, see the [documentation](#rack) for details for enabling this feature.
+
 ### Processing Pipeline
 
 Some applications might require that traces be altered or filtered out before they are sent upstream. The processing pipeline allows users to create *processors* to define such behavior.

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
@@ -19,10 +20,28 @@ def initialize(app)
           @app = app
         end
 
+        def compute_queue_time(env, tracer)
+          return unless Datadog.configuration[:rack][:request_queuing]
+
+          # parse the request queue time
+          request_start = Datadog::Contrib::Rack::QueueTime.get_request_start(env)
+          return if request_start.nil?
+
+          tracer.trace(
+            'http_server.queue',
+            start_time: request_start,
+            service: Datadog.configuration[:rack][:web_service_name]
+          )
+        end
+
         def call(env)
           # retrieve integration settings
           tracer = Datadog.configuration[:rack][:tracer]
 
+          # [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_queue_time(env, tracer)
+
           trace_options = {
             service: Datadog.configuration[:rack][:service_name],
             resource: nil,
@@ -77,6 +96,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/patcher.rb

@@ -14,6 +14,13 @@ module Patcher
           get_option(:tracer).set_service_info(value, 'rack', Ext::AppTypes::WEB)
           value
         end
+        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
 
         module_function
 

lib/ddtrace/contrib/rack/request_queue.rb

@@ -0,0 +1,34 @@
+module Datadog
+  module Contrib
+    module Rack
+      # QueueTime simply...
+      module QueueTime
+        REQUEST_START = 'HTTP_X_REQUEST_START'.freeze
+        QUEUE_START = 'HTTP_X_QUEUE_START'.freeze
+
+        module_function
+
+        def get_request_start(env, now = Time.now.utc)
+          header = env[REQUEST_START] || env[QUEUE_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 StandardError => e
+          # in case of an Exception we don't create a
+          # `request.queuing` span
+          Datadog::Tracer.log.debug("[rack] unable to parse request queue headers: #{e}")
+          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_queuing_test.rb

@@ -0,0 +1,124 @@
+require 'contrib/rack/helpers'
+
+class RequestQueuingTest < RackBaseTest
+  def setup
+    super
+    # enable request_queuing
+    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.find { |s| s.name == 'rack.request' }
+    frontend_span = spans.find { |s| s.name == 'http_server.queue' }
+    refute_nil(rack_span)
+    refute_nil(frontend_span)
+
+    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_alternative_queuing_header
+    # ensure a queuing Span is created if the header is available
+    request_start = (Time.now.utc - 5).to_i
+    header 'x-queue-start', "t=#{request_start}"
+    get '/success/'
+    assert last_response.ok?
+
+    spans = @tracer.writer.spans
+    assert_equal(2, spans.length)
+
+    rack_span = spans.find { |s| s.name == 'rack.request' }
+    frontend_span = spans.find { |s| s.name == 'http_server.queue' }
+    refute_nil(rack_span)
+    refute_nil(frontend_span)
+
+    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.find { |s| s.name == 'rack.request' }
+    frontend_span = spans.find { |s| s.name == 'http_server.queue' }
+    refute_nil(rack_span)
+    refute_nil(frontend_span)
+
+    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