diff --git a/lib/ddtrace/contrib/rack/middlewares.rb b/lib/ddtrace/contrib/rack/middlewares.rb index 3f3921d910..af031e75fe 100644 --- a/lib/ddtrace/contrib/rack/middlewares.rb +++ b/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 diff --git a/lib/ddtrace/contrib/rack/request_queue.rb b/lib/ddtrace/contrib/rack/request_queue.rb new file mode 100644 index 0000000000..9638c69846 --- /dev/null +++ b/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 diff --git a/test/contrib/rack/request_parser_test.rb b/test/contrib/rack/request_parser_test.rb new file mode 100644 index 0000000000..d1a90a66b9 --- /dev/null +++ b/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 diff --git a/test/contrib/rack/request_queueing_test.rb b/test/contrib/rack/request_queueing_test.rb new file mode 100644 index 0000000000..756c92d3b0 --- /dev/null +++ b/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