From 8698eb3f8be994e144f193a3c4cda4a5eda30a53 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Fri, 17 Feb 2023 20:25:13 -0600 Subject: [PATCH 01/24] feat: Use Rack::Events for instrumentation This is an alternate implementation of the Rack instrumentation that leverages the [`Rack::Events` API](https://www.rubydoc.info/gems/rack/Rack/Events) instead of a custom`Rack::Middleware`. Why am I suggesting we change this instrumentation? At GitHub we leverage `Rack::BodyProxy` to write Rack Request logs after the request is complete, however Rack span is already finished and its related `Context` has already been detached. This means we are not able to correlate request logs to our traces. The advantage of using `Rack::Events` is that handlers are triggered during difference stages of a request, including for deferred operations like [`Rack::BodyProxy`](https://www.rubydoc.info/gems/rack/Rack/BodyProxy), as opposed to middlewares who _only_ are invoked inline. The disadvantage of this API is that it makes managing the request more difficult and we have to track the Context positions to detach in the `Rack::Env`. This implementation will be released along side the existing instrumtation to give users the option to use the middleware instead of the `Rack::Events` handler until we are able to run this in some of our heavy production workloads. Fixes https://github.com/open-telemetry/opentelemetry-ruby-contrib/issues/341 Related https://github.com/DataDog/dd-trace-rb/pull/1746 --- .../rack/middlewares/event_handler.rb | 146 +++++++ .../rack/middlewares/event_handler_test.rb | 367 ++++++++++++++++++ instrumentation/rack/test/test_helper.rb | 1 + 3 files changed, 514 insertions(+) create mode 100644 instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb create mode 100644 instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb new file mode 100644 index 000000000..3d9bfa0b1 --- /dev/null +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -0,0 +1,146 @@ +# frozen_string_literal: true + +# Copyright The OpenTelemetry Authors +# +# SPDX-License-Identifier: Apache-2.0 + +require 'opentelemetry/trace/status' + +module OpenTelemetry + module Instrumentation + module Rack + module Middlewares + # OTel Rack Event Handler + # + # This seeds the root context for this service with the server span as the `current_span` + # allowing for callers later in the stack to reference it using {OpenTelemetry::Trace.current_span} + # + # It also registers the server span in a context dedicated to this instrumentation that users may look up + # using {OpenTelemetry::Instrumentation::Rack.current_span}, which makes it possible for users to mutate the span, + # e.g. add events or update the span name like in the {ActionPack} instrumentation. + # + # @example Rack App Using BodyProxy + # GLOBAL_LOGGER = Logger.new($stderr) + # APP_TRACER = OpenTelemetry.tracer_provider.tracer('my-app', '1.0.0') + # + # Rack::Builder.new do + # use Rack::Events, [OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new] + # run lambda { |_arg| + # APP_TRACER.in_span('hello-world') do |_span| + # body = Rack::BodyProxy.new(['hello world!']) do + # rack_span = OpenTelemetry::Instrumentation::Rack.current_span + # GLOBAL_LOGGER.info("otel.trace_id=#{rack_span.context.hex_trace_id} otel.span_id=#{rack_span.context.hex_span_id}") + # end + # [200, { 'Content-Type' => 'text/plain' }, body] + # end + # } + # end + # + # @see Rack::Events + # @see OpenTelemetry::Instrumentation::Rack.current_span + class EventHandler + include ::Rack::Events::Abstract + + TOKENS_KEY = 'otel.context.tokens' + GOOD_HTTP_STATUSES = (100..499).freeze + + def initialize + @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') + end + + # Creates a server span for this current request using the incoming parent context + # and registers them as the {current_span} + # + # @param [Rack::Request] The current HTTP request + # @param [Rack::Response] This is nil in practice + # @return [void] + def on_start(request, _) + extracted_context = extract_remote_context(request) + span = new_server_span(extracted_context, request) + request.env[TOKENS_KEY] = register_current_span(span) + end + + # Records Unexpected Exceptions on the Rack span and set the Span Status to Error + # + # @note does nothing if the span is a non-recording span + # @param [Rack::Request] The current HTTP request + # @param [Rack::Response] The current HTTP response + # @param [Exception] An unxpected error raised by the application + def on_error(request, _, error) + span = OpenTelemetry::Instrumentation::Rack.current_span + return unless span.recording? + + span.record_exception(error) + span.status = OpenTelemetry::Trace::Status.error + end + + # Finishes the span making it eligible to be exported and cleans up existing contexts + # + # @note does nothing if the span is a non-recording span + # @param [Rack::Request] The current HTTP request + # @param [Rack::Response] The current HTTP response + def on_finish(request, response) + finish_rack_span(response) + remove_contexts(request) + end + + private + + def new_server_span(parent_context, request) + @tracer.start_span( + "HTTP #{request.request_method}", + with_parent: parent_context, + kind: :server, + attributes: request_span_attributes(request.env) + ) + end + + def extract_remote_context(request) + OpenTelemetry.propagation.extract( + request.env, + getter: OpenTelemetry::Common::Propagation.rack_env_getter + ) + end + + def register_current_span(span) + ctx = OpenTelemetry::Trace.context_with_span(span) + rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) + [OpenTelemetry::Context.attach(ctx), OpenTelemetry::Context.attach(rack_ctx)] + end + + def finish_rack_span(response) + span = OpenTelemetry::Instrumentation::Rack.current_span + return unless span.recording? + + if response + span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) + span.set_attribute('http.status_code', response.status.to_i) + end + span.finish + end + + def remove_contexts(request) + request.env[TOKENS_KEY]&.reverse&.each do |token| + OpenTelemetry::Context.detach(token) + rescue StandardError => e + OpenTelemetry.handle_error(message: 'Unable to detach Rack Context', exception: e) + end + end + + def request_span_attributes(env) + attributes = { + 'http.method' => env['REQUEST_METHOD'], + 'http.host' => env['HTTP_HOST'] || 'unknown', + 'http.scheme' => env['rack.url_scheme'], + 'http.target' => env['QUERY_STRING'].empty? ? env['PATH_INFO'] : "#{env['PATH_INFO']}?#{env['QUERY_STRING']}" + } + + attributes['http.user_agent'] = env['HTTP_USER_AGENT'] if env['HTTP_USER_AGENT'] + # attributes.merge!(allowed_request_headers(env)) + attributes + end + end + end + end + end +end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb new file mode 100644 index 000000000..8c6f697a9 --- /dev/null +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -0,0 +1,367 @@ +# frozen_string_literal: true + +# Copyright The OpenTelemetry Authors +# +# SPDX-License-Identifier: Apache-2.0 + +require 'test_helper' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack/instrumentation' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack/middlewares/event_handler' + +describe 'OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler' do + include Rack::Test::Methods + + let(:exporter) { EXPORTER } + let(:finished_spans) { exporter.finished_spans } + let(:first_span) { exporter.finished_spans.first } + let(:uri) { '/' } + let(:service) do + ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, 'Hello World'] } + end + + let(:app) do + wtaf = service + Rack::Builder.new { + use Rack::Events, [OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new] + run wtaf + } + end + + before do + # clear captured spans: + exporter.reset + + # simulate a fresh install: + # instrumentation.instance_variable_set('@installed', false) + # instrumentation.install(config) + + # clear out cached config: + # described_class.send(:clear_cached_config) + + # integrate tracer middleware: + # rack_builder.use Rack::Events, [described_class.new] + # rack_builder.run app + end + + # after do + # installation is 'global', so it should be reset: + # instrumentation.instance_variable_set('@installed', false) + # instrumentation.install(default_config) + # end + + describe '#call' do + before do + get uri + end + + it 'records attributes' do + _(first_span.attributes['http.method']).must_equal 'GET' + _(first_span.attributes['http.status_code']).must_equal 200 + _(first_span.attributes['http.target']).must_equal '/' + _(first_span.attributes['http.url']).must_be_nil + _(first_span.name).must_equal 'HTTP GET' + _(first_span.kind).must_equal :server + end + + it 'does not explicitly set status OK' do + _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET + end + + it 'has no parent' do + _(first_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID + end + + describe 'when a query is passed in' do + let(:uri) { '/endpoint?query=true' } + + it 'records the query path' do + _(first_span.attributes['http.target']).must_equal '/endpoint?query=true' + _(first_span.name).must_equal 'HTTP GET' + end + end + +=begin + describe 'config[:untraced_endpoints]' do + describe 'when an array is passed in' do + let(:config) { { untraced_endpoints: ['/ping'] } } + + it 'does not trace paths listed in the array' do + Rack::MockRequest.new(rack_builder).get('/ping', env) + + ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } + _(ping_span).must_be_nil + + root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } + _(root_span).wont_be_nil + end + end + + describe 'when a string is passed in' do + let(:config) { { untraced_endpoints: '/ping' } } + + it 'traces everything' do + Rack::MockRequest.new(rack_builder).get('/ping', env) + + ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } + _(ping_span).wont_be_nil + + root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } + _(root_span).wont_be_nil + end + end + + describe 'when nil is passed in' do + let(:config) { { untraced_endpoints: nil } } + + it 'traces everything' do + Rack::MockRequest.new(rack_builder).get('/ping', env) + + ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } + _(ping_span).wont_be_nil + + root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } + _(root_span).wont_be_nil + end + end + end + + describe 'config[:untraced_requests]' do + describe 'when a callable is passed in' do + let(:untraced_callable) do + ->(env) { env['PATH_INFO'] =~ %r{^\/assets} } + end + let(:config) { default_config.merge(untraced_requests: untraced_callable) } + + it 'does not trace requests in which the callable returns true' do + Rack::MockRequest.new(rack_builder).get('/assets', env) + + ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } + _(ping_span).must_be_nil + + root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } + _(root_span).wont_be_nil + end + end + + describe 'when nil is passed in' do + let(:config) { { untraced_requests: nil } } + + it 'traces everything' do + Rack::MockRequest.new(rack_builder).get('/assets', env) + + ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } + _(ping_span).wont_be_nil + + root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } + _(root_span).wont_be_nil + end + end + end +=end + +=begin + describe 'config[:allowed_request_headers]' do + let(:env) do + Hash( + 'CONTENT_LENGTH' => '123', + 'CONTENT_TYPE' => 'application/json', + 'HTTP_FOO_BAR' => 'http foo bar value' + ) + end + + it 'defaults to nil' do + _(first_span.attributes['http.request.header.foo_bar']).must_be_nil + end + + describe 'when configured' do + let(:config) { default_config.merge(allowed_request_headers: ['foo_BAR']) } + + it 'returns attribute' do + _(first_span.attributes['http.request.header.foo_bar']).must_equal 'http foo bar value' + end + end + + describe 'when content-type' do + let(:config) { default_config.merge(allowed_request_headers: ['CONTENT_TYPE']) } + + it 'returns attribute' do + _(first_span.attributes['http.request.header.content_type']).must_equal 'application/json' + end + end + + describe 'when content-length' do + let(:config) { default_config.merge(allowed_request_headers: ['CONTENT_LENGTH']) } + + it 'returns attribute' do + _(first_span.attributes['http.request.header.content_length']).must_equal '123' + end + end + end + + describe 'config[:allowed_response_headers]' do + let(:app) do + ->(_env) { [200, { 'Foo-Bar' => 'foo bar response header' }, ['OK']] } + end + + it 'defaults to nil' do + _(first_span.attributes['http.response.header.foo_bar']).must_be_nil + end + + describe 'when configured' do + let(:config) { default_config.merge(allowed_response_headers: ['Foo-Bar']) } + + it 'returns attribute' do + _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' + end + + describe 'case-sensitively' do + let(:config) { default_config.merge(allowed_response_headers: ['fOO-bAR']) } + + it 'returns attribute' do + _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' + end + end + end + end + + describe 'config[:record_frontend_span]' do + let(:request_span) { exporter.finished_spans.first } + + describe 'default' do + it 'does not record span' do + _(exporter.finished_spans.size).must_equal 1 + end + + it 'does not parent the request_span' do + _(request_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID + end + end + + describe 'when recordable' do + let(:config) { default_config.merge(record_frontend_span: true) } + let(:env) { Hash('HTTP_X_REQUEST_START' => Time.now.to_i) } + let(:frontend_span) { exporter.finished_spans[1] } + let(:request_span) { exporter.finished_spans[0] } + + it 'records span' do + _(exporter.finished_spans.size).must_equal 2 + _(frontend_span.name).must_equal 'http_server.proxy' + _(frontend_span.attributes['service']).must_be_nil + end + + it 'changes request_span kind' do + _(request_span.kind).must_equal :internal + end + + it 'frontend_span parents request_span' do + _(request_span.parent_span_id).must_equal frontend_span.span_id + end + end + end +=end + describe '#called with 400 level http status code' do + let(:service) do + ->(_env) { [404, { 'Foo-Bar' => 'foo bar response header' }, ['Not Found']] } + end + + it 'leaves status code unset' do + _(first_span.attributes['http.status_code']).must_equal 404 + _(first_span.kind).must_equal :server + _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET + end + end + end + +=begin + describe 'config[:quantization]' do + before do + Rack::MockRequest.new(rack_builder).get('/really_long_url', env) + end + + describe 'without quantization' do + it 'span.name defaults to low cardinality name HTTP method' do + _(first_span.name).must_equal 'HTTP GET' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end + end + + describe 'with simple quantization' do + let(:quantization_example) do + ->(url, _env) { url.to_s } + end + + let(:config) { default_config.merge(url_quantization: quantization_example) } + + it 'sets the span.name to the full path' do + _(first_span.name).must_equal '/really_long_url' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end + end + + describe 'with quantization' do + let(:quantization_example) do + # demonstrate simple shortening of URL: + ->(url, _env) { url.to_s[0..5] } + end + let(:config) { default_config.merge(url_quantization: quantization_example) } + + it 'mutates url according to url_quantization' do + _(first_span.name).must_equal '/reall' + end + end + end +=end + +=begin + describe 'config[:response_propagators]' do + describe 'with default options' do + it 'does not inject the traceresponse header' do + res = Rack::MockRequest.new(rack_builder).get('/ping', env) + _(res.headers).wont_include('traceresponse') + end + end + + describe 'with ResponseTextMapPropagator' do + let(:config) { default_config.merge(response_propagators: [OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator.new]) } + + it 'injects the traceresponse header' do + res = Rack::MockRequest.new(rack_builder).get('/ping', env) + _(res.headers).must_include('traceresponse') + end + end + + describe 'propagator throws' do + class MockPropagator < OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator + def inject(carrier) + raise 'Injection failed' + end + end + + let(:config) { default_config.merge(response_propagators: [MockPropagator.new]) } + + it 'leads to application errors when there are exceptions' do + assert_raises RuntimeError do + Rack::MockRequest.new(rack_builder).get('/ping', env) + end + end + end + end +=end + + describe '#call with error' do + SimulatedError = Class.new(StandardError) + + let(:service) do + ->(_env) { raise SimulatedError } + end + + it 'records error in span and then re-raises' do + assert_raises SimulatedError do + get '/' + end + + _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::ERROR + end + end +end diff --git a/instrumentation/rack/test/test_helper.rb b/instrumentation/rack/test/test_helper.rb index 2053b67ae..694fd320c 100644 --- a/instrumentation/rack/test/test_helper.rb +++ b/instrumentation/rack/test/test_helper.rb @@ -9,6 +9,7 @@ require 'minitest/autorun' require 'webmock/minitest' +require 'rack/events' require 'opentelemetry-instrumentation-rack' From 24ea56388d7623daa275efcac8a341ee6868f261 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Fri, 17 Feb 2023 21:55:14 -0600 Subject: [PATCH 02/24] squash: additional feature parity --- .../rack/middlewares/event_handler.rb | 37 ++++++++- .../rack/middlewares/event_handler_test.rb | 83 +++++++++---------- 2 files changed, 73 insertions(+), 47 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 3d9bfa0b1..688c7b32a 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -44,8 +44,19 @@ class EventHandler TOKENS_KEY = 'otel.context.tokens' GOOD_HTTP_STATUSES = (100..499).freeze - def initialize + def initialize(untraced_endpoints:, untraced_callable:, allowed_request_headers:) @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') + @untraced_endpoints = Array(untraced_endpoints).compact + @untraced_callable = untraced_callable + @allowed_request_headers = Array(allowed_request_headers).compact.each_with_object({}) do |header, memo| + key = header.to_s.upcase.gsub(/[-\s]/, '_') + case key + when 'CONTENT_TYPE', 'CONTENT_LENGTH' + memo[key] = build_attribute_name('http.request.header.', header) + else + memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) + end + end end # Creates a server span for this current request using the incoming parent context @@ -55,6 +66,8 @@ def initialize # @param [Rack::Response] This is nil in practice # @return [void] def on_start(request, _) + return if untraced_request?(request.env) + extracted_context = extract_remote_context(request) span = new_server_span(extracted_context, request) request.env[TOKENS_KEY] = register_current_span(span) @@ -86,6 +99,22 @@ def on_finish(request, response) private + EMPTY_HASH = {}.freeze + def extract_request_headers(env) + return EMPTY_HASH if @allowed_request_headers.empty? + + @allowed_request_headers.each_with_object({}) do |(key, value), result| + result[value] = env[key] if env.key?(key) + end + end + + def untraced_request?(env) + return true if @untraced_endpoints.include?(env['PATH_INFO']) + return true if @untraced_callable&.call(env) + + false + end + def new_server_span(parent_context, request) @tracer.start_span( "HTTP #{request.request_method}", @@ -136,9 +165,13 @@ def request_span_attributes(env) } attributes['http.user_agent'] = env['HTTP_USER_AGENT'] if env['HTTP_USER_AGENT'] - # attributes.merge!(allowed_request_headers(env)) + attributes.merge!(extract_request_headers(env)) attributes end + + def build_attribute_name(prefix, suffix) + prefix + suffix.to_s.downcase.gsub(/[-\s]/, '_') + end end end end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 8c6f697a9..a854a8e62 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -16,43 +16,36 @@ let(:finished_spans) { exporter.finished_spans } let(:first_span) { exporter.finished_spans.first } let(:uri) { '/' } + let(:handler) do + OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( + untraced_endpoints: untraced_endpoints, + untraced_callable: untraced_callable, + allowed_request_headers: allowed_request_headers + ) + end + let(:service) do ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, 'Hello World'] } end + let(:untraced_endpoints) { [] } + let(:untraced_callable) { nil } + let(:allowed_request_headers) { nil } + let(:headers) { Hash.new } let(:app) do - wtaf = service - Rack::Builder.new { - use Rack::Events, [OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new] - run wtaf - } + Rack::Builder.new.tap do |builder| + builder.use Rack::Events, [handler] + builder.run service + end end before do - # clear captured spans: exporter.reset - - # simulate a fresh install: - # instrumentation.instance_variable_set('@installed', false) - # instrumentation.install(config) - - # clear out cached config: - # described_class.send(:clear_cached_config) - - # integrate tracer middleware: - # rack_builder.use Rack::Events, [described_class.new] - # rack_builder.run app end - # after do - # installation is 'global', so it should be reset: - # instrumentation.instance_variable_set('@installed', false) - # instrumentation.install(default_config) - # end - describe '#call' do before do - get uri + get uri, {}, headers end it 'records attributes' do @@ -81,13 +74,12 @@ end end -=begin describe 'config[:untraced_endpoints]' do describe 'when an array is passed in' do - let(:config) { { untraced_endpoints: ['/ping'] } } + let(:untraced_endpoints) { ['/ping'] } it 'does not trace paths listed in the array' do - Rack::MockRequest.new(rack_builder).get('/ping', env) + get '/ping' ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } _(ping_span).must_be_nil @@ -98,13 +90,13 @@ end describe 'when a string is passed in' do - let(:config) { { untraced_endpoints: '/ping' } } + let(:untraced_endpoints) { '/ping' } - it 'traces everything' do - Rack::MockRequest.new(rack_builder).get('/ping', env) + it 'does not trace path' do + get '/ping' ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } - _(ping_span).wont_be_nil + _(ping_span).must_be_nil root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } _(root_span).wont_be_nil @@ -115,7 +107,7 @@ let(:config) { { untraced_endpoints: nil } } it 'traces everything' do - Rack::MockRequest.new(rack_builder).get('/ping', env) + get '/ping' ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } _(ping_span).wont_be_nil @@ -131,13 +123,12 @@ let(:untraced_callable) do ->(env) { env['PATH_INFO'] =~ %r{^\/assets} } end - let(:config) { default_config.merge(untraced_requests: untraced_callable) } it 'does not trace requests in which the callable returns true' do - Rack::MockRequest.new(rack_builder).get('/assets', env) + get '/assets' - ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } - _(ping_span).must_be_nil + assets_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } + _(assets_span).must_be_nil root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } _(root_span).wont_be_nil @@ -148,21 +139,19 @@ let(:config) { { untraced_requests: nil } } it 'traces everything' do - Rack::MockRequest.new(rack_builder).get('/assets', env) + get '/assets' - ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } - _(ping_span).wont_be_nil + asset_span = finished_spans.find { |s| s.attributes['http.target'] == '/assets' } + _(asset_span).wont_be_nil root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } _(root_span).wont_be_nil end end end -=end -=begin describe 'config[:allowed_request_headers]' do - let(:env) do + let(:headers) do Hash( 'CONTENT_LENGTH' => '123', 'CONTENT_TYPE' => 'application/json', @@ -170,12 +159,15 @@ ) end + it 'defaults to nil' do _(first_span.attributes['http.request.header.foo_bar']).must_be_nil end describe 'when configured' do - let(:config) { default_config.merge(allowed_request_headers: ['foo_BAR']) } + let(:allowed_request_headers) do + ['foo_BAR'] + end it 'returns attribute' do _(first_span.attributes['http.request.header.foo_bar']).must_equal 'http foo bar value' @@ -183,7 +175,7 @@ end describe 'when content-type' do - let(:config) { default_config.merge(allowed_request_headers: ['CONTENT_TYPE']) } + let(:allowed_request_headers) { ['CONTENT_TYPE'] } it 'returns attribute' do _(first_span.attributes['http.request.header.content_type']).must_equal 'application/json' @@ -191,7 +183,7 @@ end describe 'when content-length' do - let(:config) { default_config.merge(allowed_request_headers: ['CONTENT_LENGTH']) } + let(:allowed_request_headers) { ['CONTENT_LENGTH'] } it 'returns attribute' do _(first_span.attributes['http.request.header.content_length']).must_equal '123' @@ -199,6 +191,7 @@ end end +=begin describe 'config[:allowed_response_headers]' do let(:app) do ->(_env) { [200, { 'Foo-Bar' => 'foo bar response header' }, ['OK']] } From 06e4fe31864ad3d7a5fbe085bce50f91ea111e36 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Mon, 20 Feb 2023 08:18:52 -0600 Subject: [PATCH 03/24] squash: add allowed response headers --- .../rack/middlewares/event_handler.rb | 54 +++++++++++++++---- .../rack/middlewares/event_handler_test.rb | 16 +++--- 2 files changed, 51 insertions(+), 19 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 688c7b32a..a3f6a429a 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -44,19 +44,26 @@ class EventHandler TOKENS_KEY = 'otel.context.tokens' GOOD_HTTP_STATUSES = (100..499).freeze - def initialize(untraced_endpoints:, untraced_callable:, allowed_request_headers:) + def initialize(untraced_endpoints:, untraced_callable:, + allowed_request_headers:, allowed_response_headers:) @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') @untraced_endpoints = Array(untraced_endpoints).compact @untraced_callable = untraced_callable - @allowed_request_headers = Array(allowed_request_headers).compact.each_with_object({}) do |header, memo| - key = header.to_s.upcase.gsub(/[-\s]/, '_') - case key - when 'CONTENT_TYPE', 'CONTENT_LENGTH' - memo[key] = build_attribute_name('http.request.header.', header) - else - memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) - end - end + @allowed_request_headers = Array(allowed_request_headers) + .compact + .each_with_object({}) do |header, memo| + key = header.to_s.upcase.gsub(/[-\s]/, '_') + case key + when 'CONTENT_TYPE', 'CONTENT_LENGTH' + memo[key] = build_attribute_name('http.request.header.', header) + else + memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) + end + end + @allowed_response_headers = Array(allowed_response_headers).each_with_object({}) do |header, memo| + memo[header] = build_attribute_name('http.response.header.', header) + memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) + end end # Creates a server span for this current request using the incoming parent context @@ -108,6 +115,30 @@ def extract_request_headers(env) end end + def extract_response_attributes(response) + attributes = { 'http.status_code' => response.status.to_i } + attributes.merge!(extract_response_headers(response.headers)) + attributes + end + + def extract_response_headers(headers) + return EMPTY_HASH if @allowed_response_headers.empty? + + @allowed_response_headers.each_with_object({}) do |(key, value), result| + if headers.key?(key) + result[value] = headers[key] + else + # do case-insensitive match: + headers.each do |k, v| + if k.upcase == key + result[value] = v + break + end + end + end + end + end + def untraced_request?(env) return true if @untraced_endpoints.include?(env['PATH_INFO']) return true if @untraced_callable&.call(env) @@ -143,7 +174,8 @@ def finish_rack_span(response) if response span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) - span.set_attribute('http.status_code', response.status.to_i) + attributes = extract_response_attributes(response) + span.add_attributes(attributes) end span.finish end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index a854a8e62..0ae63a641 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -20,7 +20,8 @@ OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( untraced_endpoints: untraced_endpoints, untraced_callable: untraced_callable, - allowed_request_headers: allowed_request_headers + allowed_request_headers: allowed_request_headers, + allowed_response_headers: allowed_response_headers ) end @@ -30,8 +31,8 @@ let(:untraced_endpoints) { [] } let(:untraced_callable) { nil } let(:allowed_request_headers) { nil } - let(:headers) { Hash.new } - + let(:allowed_response_headers) { nil } + let(:headers) { {} } let(:app) do Rack::Builder.new.tap do |builder| builder.use Rack::Events, [handler] @@ -159,7 +160,6 @@ ) end - it 'defaults to nil' do _(first_span.attributes['http.request.header.foo_bar']).must_be_nil end @@ -191,9 +191,8 @@ end end -=begin describe 'config[:allowed_response_headers]' do - let(:app) do + let(:service) do ->(_env) { [200, { 'Foo-Bar' => 'foo bar response header' }, ['OK']] } end @@ -202,14 +201,14 @@ end describe 'when configured' do - let(:config) { default_config.merge(allowed_response_headers: ['Foo-Bar']) } + let(:allowed_response_headers) { ['Foo-Bar'] } it 'returns attribute' do _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' end describe 'case-sensitively' do - let(:config) { default_config.merge(allowed_response_headers: ['fOO-bAR']) } + let(:allowed_response_headers) { ['fOO-bAR'] } it 'returns attribute' do _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' @@ -218,6 +217,7 @@ end end +=begin describe 'config[:record_frontend_span]' do let(:request_span) { exporter.finished_spans.first } From 725b722111559e43d0f45d4d2226fb877bec50b4 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Mon, 20 Feb 2023 08:51:02 -0600 Subject: [PATCH 04/24] squash: url quantization --- .../rack/middlewares/event_handler.rb | 44 +++++--- .../rack/middlewares/event_handler_test.rb | 102 +++++++++++++----- 2 files changed, 105 insertions(+), 41 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index a3f6a429a..f115c059f 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -45,25 +45,27 @@ class EventHandler GOOD_HTTP_STATUSES = (100..499).freeze def initialize(untraced_endpoints:, untraced_callable:, - allowed_request_headers:, allowed_response_headers:) + allowed_request_headers:, allowed_response_headers:, + url_quantization:) @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') @untraced_endpoints = Array(untraced_endpoints).compact @untraced_callable = untraced_callable @allowed_request_headers = Array(allowed_request_headers) - .compact - .each_with_object({}) do |header, memo| - key = header.to_s.upcase.gsub(/[-\s]/, '_') - case key - when 'CONTENT_TYPE', 'CONTENT_LENGTH' - memo[key] = build_attribute_name('http.request.header.', header) - else - memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) - end - end + .compact + .each_with_object({}) do |header, memo| + key = header.to_s.upcase.gsub(/[-\s]/, '_') + case key + when 'CONTENT_TYPE', 'CONTENT_LENGTH' + memo[key] = build_attribute_name('http.request.header.', header) + else + memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) + end + end @allowed_response_headers = Array(allowed_response_headers).each_with_object({}) do |header, memo| memo[header] = build_attribute_name('http.response.header.', header) memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) end + @url_quantization = url_quantization end # Creates a server span for this current request using the incoming parent context @@ -148,13 +150,31 @@ def untraced_request?(env) def new_server_span(parent_context, request) @tracer.start_span( - "HTTP #{request.request_method}", + create_request_span_name(request), with_parent: parent_context, kind: :server, attributes: request_span_attributes(request.env) ) end + # https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/data-http.md#name + # + # recommendation: span.name(s) should be low-cardinality (e.g., + # strip off query param value, keep param name) + # + # see http://github.com/open-telemetry/opentelemetry-specification/pull/416/files + def create_request_span_name(request) + # NOTE: dd-trace-rb has implemented 'quantization' (which lowers url cardinality) + # see Datadog::Quantization::HTTP.url + + if (implementation = @url_quantization) + request_uri_or_path_info = request.env['REQUEST_URI'] || request.path_info + implementation.call(request_uri_or_path_info, request.env) + else + "HTTP #{request.request_method}" + end + end + def extract_remote_context(request) OpenTelemetry.propagation.extract( request.env, diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 0ae63a641..6f9183bdd 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -21,7 +21,8 @@ untraced_endpoints: untraced_endpoints, untraced_callable: untraced_callable, allowed_request_headers: allowed_request_headers, - allowed_response_headers: allowed_response_headers + allowed_response_headers: allowed_response_headers, + url_quantization: url_quantization ) end @@ -32,6 +33,7 @@ let(:untraced_callable) { nil } let(:allowed_request_headers) { nil } let(:allowed_response_headers) { nil } + let(:url_quantization) { nil } let(:headers) { {} } let(:app) do Rack::Builder.new.tap do |builder| @@ -266,45 +268,87 @@ end end -=begin - describe 'config[:quantization]' do - before do - Rack::MockRequest.new(rack_builder).get('/really_long_url', env) - end + describe 'url quantization' do + describe 'when using standard Rack environment variables' do + describe 'without quantization' do + it 'span.name defaults to low cardinality name HTTP method' do + get '/really_long_url' - describe 'without quantization' do - it 'span.name defaults to low cardinality name HTTP method' do - _(first_span.name).must_equal 'HTTP GET' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(first_span.name).must_equal 'HTTP GET' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end end - end - describe 'with simple quantization' do - let(:quantization_example) do - ->(url, _env) { url.to_s } + describe 'with simple quantization' do + let(:quantization_example) do + ->(url, _env) { url.to_s } + end + + let(:url_quantization) { quantization_example } + + it 'sets the span.name to the full path' do + get '/really_long_url' + + _(first_span.name).must_equal '/really_long_url' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end end - let(:config) { default_config.merge(url_quantization: quantization_example) } + describe 'with quantization' do + let(:quantization_example) do + # demonstrate simple shortening of URL: + ->(url, _env) { url.to_s[0..5] } + end + let(:url_quantization) { quantization_example } + + it 'mutates url according to url_quantization' do + get '/really_long_url' - it 'sets the span.name to the full path' do - _(first_span.name).must_equal '/really_long_url' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(first_span.name).must_equal '/reall' + end end end - describe 'with quantization' do - let(:quantization_example) do - # demonstrate simple shortening of URL: - ->(url, _env) { url.to_s[0..5] } + describe 'when using Action Dispatch custom environment variables' do + describe 'without quantization' do + it 'span.name defaults to low cardinality name HTTP method' do + get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } + + _(first_span.name).must_equal 'HTTP GET' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end + end + + describe 'with simple quantization' do + let(:quantization_example) do + ->(url, _env) { url.to_s } + end + + let(:url_quantization) { quantization_example } + + it 'sets the span.name to the full path' do + get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } + + _(first_span.name).must_equal '/action-dispatch-uri' + _(first_span.attributes['http.target']).must_equal '/really_long_url' + end end - let(:config) { default_config.merge(url_quantization: quantization_example) } - it 'mutates url according to url_quantization' do - _(first_span.name).must_equal '/reall' + describe 'with quantization' do + let(:quantization_example) do + # demonstrate simple shortening of URL: + ->(url, _env) { url.to_s[0..5] } + end + let(:url_quantization) { quantization_example } + + it 'mutates url according to url_quantization' do + get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } + + _(first_span.name).must_equal '/actio' + end end end end -=end =begin describe 'config[:response_propagators]' do @@ -343,14 +387,14 @@ def inject(carrier) =end describe '#call with error' do - SimulatedError = Class.new(StandardError) + EventHandlerError = Class.new(StandardError) let(:service) do - ->(_env) { raise SimulatedError } + ->(_env) { raise EventHandlerError } end it 'records error in span and then re-raises' do - assert_raises SimulatedError do + assert_raises EventHandlerError do get '/' end From 8a2dd292c810727fe8729f88ac4064cabcb763a2 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Mon, 20 Feb 2023 09:24:06 -0600 Subject: [PATCH 05/24] squash: Now with new Lemon Scented response headers --- .../rack/middlewares/event_handler.rb | 19 ++++++++++++- ...opentelemetry-instrumentation-rack.gemspec | 1 + .../rack/middlewares/event_handler_test.rb | 28 +++++++++---------- instrumentation/rack/test/test_helper.rb | 6 ++-- 4 files changed, 36 insertions(+), 18 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index f115c059f..06d56f6dc 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -46,7 +46,7 @@ class EventHandler def initialize(untraced_endpoints:, untraced_callable:, allowed_request_headers:, allowed_response_headers:, - url_quantization:) + url_quantization:, response_propagators:) @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') @untraced_endpoints = Array(untraced_endpoints).compact @untraced_callable = untraced_callable @@ -66,6 +66,7 @@ def initialize(untraced_endpoints:, untraced_callable:, memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) end @url_quantization = url_quantization + @response_propagators = response_propagators end # Creates a server span for this current request using the incoming parent context @@ -82,6 +83,22 @@ def on_start(request, _) request.env[TOKENS_KEY] = register_current_span(span) end + # Optionally adds debugging response headers injected from {response_propagators} + # + # @param [Rack::Request] The current HTTP request + # @param [Rack::Response] This current HTTP response + # @return [void] + def on_commit(request, response) + span = OpenTelemetry::Instrumentation::Rack.current_span + return unless span.recording? + + begin + @response_propagators&.each { |propagator| propagator.inject(response.headers) } + rescue StandardError => e + OpenTelemetry.handle_error(message: 'Unable to inject response propagation headers', exception: e) + end + end + # Records Unexpected Exceptions on the Rack span and set the Span Status to Error # # @note does nothing if the span is a non-recording span diff --git a/instrumentation/rack/opentelemetry-instrumentation-rack.gemspec b/instrumentation/rack/opentelemetry-instrumentation-rack.gemspec index 257b97a9e..1a9ce4e89 100644 --- a/instrumentation/rack/opentelemetry-instrumentation-rack.gemspec +++ b/instrumentation/rack/opentelemetry-instrumentation-rack.gemspec @@ -38,6 +38,7 @@ Gem::Specification.new do |spec| spec.add_development_dependency 'rack', '~> 2.0.8' spec.add_development_dependency 'rack-test', '~> 1.1.0' spec.add_development_dependency 'rake', '~> 13.0' + spec.add_development_dependency 'rspec-mocks' spec.add_development_dependency 'rubocop', '~> 1.41.1' spec.add_development_dependency 'simplecov', '~> 0.17.1' spec.add_development_dependency 'webmock', '~> 3.7.6' diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 6f9183bdd..b4e5bf991 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -22,7 +22,8 @@ untraced_callable: untraced_callable, allowed_request_headers: allowed_request_headers, allowed_response_headers: allowed_response_headers, - url_quantization: url_quantization + url_quantization: url_quantization, + response_propagators: response_propagators ) end @@ -33,6 +34,7 @@ let(:untraced_callable) { nil } let(:allowed_request_headers) { nil } let(:allowed_response_headers) { nil } + let(:response_propagators) { nil } let(:url_quantization) { nil } let(:headers) { {} } let(:app) do @@ -350,21 +352,20 @@ end end -=begin - describe 'config[:response_propagators]' do + describe 'response_propagators' do describe 'with default options' do it 'does not inject the traceresponse header' do - res = Rack::MockRequest.new(rack_builder).get('/ping', env) - _(res.headers).wont_include('traceresponse') + get '/ping' + _(last_response.headers).wont_include('traceresponse') end end describe 'with ResponseTextMapPropagator' do - let(:config) { default_config.merge(response_propagators: [OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator.new]) } + let(:response_propagators) { [OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator.new] } it 'injects the traceresponse header' do - res = Rack::MockRequest.new(rack_builder).get('/ping', env) - _(res.headers).must_include('traceresponse') + get '/ping' + _(last_response.headers).must_include('traceresponse') end end @@ -375,16 +376,15 @@ def inject(carrier) end end - let(:config) { default_config.merge(response_propagators: [MockPropagator.new]) } + let(:response_propagators) { [MockPropagator.new] } - it 'leads to application errors when there are exceptions' do - assert_raises RuntimeError do - Rack::MockRequest.new(rack_builder).get('/ping', env) - end + it 'records errors' do + expect(OpenTelemetry).to receive(:handle_error).with(exception: instance_of(RuntimeError), message: /Unable/) + + get '/ping' end end end -=end describe '#call with error' do EventHandlerError = Class.new(StandardError) diff --git a/instrumentation/rack/test/test_helper.rb b/instrumentation/rack/test/test_helper.rb index 694fd320c..9d8b9cf5f 100644 --- a/instrumentation/rack/test/test_helper.rb +++ b/instrumentation/rack/test/test_helper.rb @@ -6,12 +6,12 @@ require 'bundler/setup' Bundler.require(:default, :development, :test) +require 'rack/events' +require 'opentelemetry-instrumentation-rack' require 'minitest/autorun' require 'webmock/minitest' -require 'rack/events' - -require 'opentelemetry-instrumentation-rack' +require 'rspec/mocks/minitest_integration' # global opentelemetry-sdk setup: EXPORTER = OpenTelemetry::SDK::Trace::Export::InMemorySpanExporter.new From 752a73926424c2a102b19524a12f7d65941ac86c Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Tue, 21 Feb 2023 09:24:57 -0600 Subject: [PATCH 06/24] squash: we are now at parity --- .../lib/opentelemetry/instrumentation/rack.rb | 2 +- .../rack/middlewares/event_handler.rb | 91 ++++++++++--------- .../rack/middlewares/tracer_middleware.rb | 2 - .../instrumentation/rack/util.rb | 16 ++++ .../rack/middlewares/event_handler_test.rb | 17 ++-- 5 files changed, 75 insertions(+), 53 deletions(-) create mode 100644 instrumentation/rack/lib/opentelemetry/instrumentation/rack/util.rb diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack.rb index 0274c8975..fb175ce14 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack.rb @@ -14,7 +14,6 @@ module Rack extend self CURRENT_SPAN_KEY = Context.create_key('current-span') - private_constant :CURRENT_SPAN_KEY # Returns the current span from the current or provided context @@ -50,4 +49,5 @@ def with_span(span) end require_relative './rack/instrumentation' +require_relative './rack/util' require_relative './rack/version' diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 06d56f6dc..d8bf1b851 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -4,6 +4,7 @@ # # SPDX-License-Identifier: Apache-2.0 +require_relative '../util' require 'opentelemetry/trace/status' module OpenTelemetry @@ -46,13 +47,14 @@ class EventHandler def initialize(untraced_endpoints:, untraced_callable:, allowed_request_headers:, allowed_response_headers:, - url_quantization:, response_propagators:) + url_quantization:, response_propagators:, + record_frontend_span:) @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') @untraced_endpoints = Array(untraced_endpoints).compact @untraced_callable = untraced_callable @allowed_request_headers = Array(allowed_request_headers) .compact - .each_with_object({}) do |header, memo| + .each_with_object({}) { |header, memo| key = header.to_s.upcase.gsub(/[-\s]/, '_') case key when 'CONTENT_TYPE', 'CONTENT_LENGTH' @@ -60,13 +62,14 @@ def initialize(untraced_endpoints:, untraced_callable:, else memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) end - end + } @allowed_response_headers = Array(allowed_response_headers).each_with_object({}) do |header, memo| memo[header] = build_attribute_name('http.response.header.', header) memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) end @url_quantization = url_quantization @response_propagators = response_propagators + @record_frontend_span = record_frontend_span == true end # Creates a server span for this current request using the incoming parent context @@ -79,8 +82,36 @@ def on_start(request, _) return if untraced_request?(request.env) extracted_context = extract_remote_context(request) - span = new_server_span(extracted_context, request) - request.env[TOKENS_KEY] = register_current_span(span) + if @record_frontend_span + request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) + unless request_start_time.nil? + frontend_span = @tracer.start_span( + 'http_server.proxy', + with_parent: extracted_context, + start_timestamp: request_start_time, + kind: :server + ) + + frontend_context = OpenTelemetry::Trace.context_with_span(frontend_span, parent_context: extracted_context) + end + end + parent_context = frontend_context || extracted_context + + span = @tracer.start_span( + create_request_span_name(request), + with_parent: parent_context, + kind: frontend_context.nil? ? :server : :internal, + attributes: request_span_attributes(request.env) + ) + ctx = OpenTelemetry::Trace.context_with_span(span) + rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) + + contexts = [frontend_context, ctx, rack_ctx] + contexts.compact! + + tokens = contexts.map { |context| OpenTelemetry::Context.attach(context) } + + request.env[TOKENS_KEY] = tokens end # Optionally adds debugging response headers injected from {response_propagators} @@ -119,8 +150,19 @@ def on_error(request, _, error) # @param [Rack::Request] The current HTTP request # @param [Rack::Response] The current HTTP response def on_finish(request, response) - finish_rack_span(response) - remove_contexts(request) + span = OpenTelemetry::Instrumentation::Rack.current_span + return unless span.recording? + + if response + span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) + attributes = extract_response_attributes(response) + span.add_attributes(attributes) + end + + request.env[TOKENS_KEY]&.reverse&.each do |token| + OpenTelemetry::Context.detach(token) + OpenTelemetry::Trace.current_span.finish + end end private @@ -165,15 +207,6 @@ def untraced_request?(env) false end - def new_server_span(parent_context, request) - @tracer.start_span( - create_request_span_name(request), - with_parent: parent_context, - kind: :server, - attributes: request_span_attributes(request.env) - ) - end - # https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/data-http.md#name # # recommendation: span.name(s) should be low-cardinality (e.g., @@ -199,32 +232,6 @@ def extract_remote_context(request) ) end - def register_current_span(span) - ctx = OpenTelemetry::Trace.context_with_span(span) - rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) - [OpenTelemetry::Context.attach(ctx), OpenTelemetry::Context.attach(rack_ctx)] - end - - def finish_rack_span(response) - span = OpenTelemetry::Instrumentation::Rack.current_span - return unless span.recording? - - if response - span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) - attributes = extract_response_attributes(response) - span.add_attributes(attributes) - end - span.finish - end - - def remove_contexts(request) - request.env[TOKENS_KEY]&.reverse&.each do |token| - OpenTelemetry::Context.detach(token) - rescue StandardError => e - OpenTelemetry.handle_error(message: 'Unable to detach Rack Context', exception: e) - end - end - def request_span_attributes(env) attributes = { 'http.method' => env['REQUEST_METHOD'], diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb index e413ecabd..9075a6a53 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/tracer_middleware.rb @@ -6,8 +6,6 @@ require 'opentelemetry/trace/status' -require_relative '../util/queue_time' - module OpenTelemetry module Instrumentation module Rack diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/util.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/util.rb new file mode 100644 index 000000000..d9373cbcf --- /dev/null +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/util.rb @@ -0,0 +1,16 @@ +# frozen_string_literal: true + +# Copyright The OpenTelemetry Authors +# +# SPDX-License-Identifier: Apache-2.0 + +module OpenTelemetry + module Instrumentation + module Rack + # Provides utilities methods for creating Rack spans + module Util + require_relative 'util/queue_time' + end + end + end +end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index b4e5bf991..6c8401ada 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -23,7 +23,8 @@ allowed_request_headers: allowed_request_headers, allowed_response_headers: allowed_response_headers, url_quantization: url_quantization, - response_propagators: response_propagators + response_propagators: response_propagators, + record_frontend_span: record_frontend_span ) end @@ -34,6 +35,7 @@ let(:untraced_callable) { nil } let(:allowed_request_headers) { nil } let(:allowed_response_headers) { nil } + let(:record_frontend_span) { false } let(:response_propagators) { nil } let(:url_quantization) { nil } let(:headers) { {} } @@ -221,8 +223,7 @@ end end -=begin - describe 'config[:record_frontend_span]' do + describe 'record_frontend_span' do let(:request_span) { exporter.finished_spans.first } describe 'default' do @@ -236,8 +237,8 @@ end describe 'when recordable' do - let(:config) { default_config.merge(record_frontend_span: true) } - let(:env) { Hash('HTTP_X_REQUEST_START' => Time.now.to_i) } + let(:record_frontend_span) { true } + let(:headers) { Hash('HTTP_X_REQUEST_START' => Time.now.to_i) } let(:frontend_span) { exporter.finished_spans[1] } let(:request_span) { exporter.finished_spans[0] } @@ -256,7 +257,7 @@ end end end -=end + describe '#called with 400 level http status code' do let(:service) do ->(_env) { [404, { 'Foo-Bar' => 'foo bar response header' }, ['Not Found']] } @@ -370,13 +371,13 @@ end describe 'propagator throws' do - class MockPropagator < OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator + class EventMockPropagator < OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator def inject(carrier) raise 'Injection failed' end end - let(:response_propagators) { [MockPropagator.new] } + let(:response_propagators) { [EventMockPropagator.new] } it 'records errors' do expect(OpenTelemetry).to receive(:handle_error).with(exception: instance_of(RuntimeError), message: /Unable/) From aba820e899334223ca229a67cf31454fbabb324a Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Tue, 21 Feb 2023 10:03:42 -0600 Subject: [PATCH 07/24] squash: use instrumetation config --- .../instrumentation/rack/instrumentation.rb | 13 ++++++++ .../rack/middlewares/event_handler_test.rb | 32 +++++++++++++++---- 2 files changed, 39 insertions(+), 6 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index a4445efe2..d74a56a0f 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -32,9 +32,22 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base option :untraced_requests, default: nil, validate: :callable option :response_propagators, default: [], validate: :array + def new_rack_events_handler + OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( + untraced_endpoints: config[:untraced_endpoints], + untraced_callable: config[:untraced_callable], + allowed_request_headers: config[:allowed_request_headers], + allowed_response_headers: config[:allowed_response_headers], + url_quantization: config[:url_quantization], + response_propagators: config[:response_propagators], + record_frontend_span: config[:record_frontend_span] + ) + end + private def require_dependencies + require_relative 'middlewares/event_handler' require_relative 'middlewares/tracer_middleware' end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 6c8401ada..2fe3d3da3 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -12,12 +12,12 @@ describe 'OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler' do include Rack::Test::Methods - let(:exporter) { EXPORTER } - let(:finished_spans) { exporter.finished_spans } - let(:first_span) { exporter.finished_spans.first } - let(:uri) { '/' } - let(:handler) do - OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( + let(:instrumentation_module) { OpenTelemetry::Instrumentation::Rack } + let(:instrumentation_class) { instrumentation_module::Instrumentation } + let(:instrumentation) { instrumentation_class.instance } + + let(:config) do + { untraced_endpoints: untraced_endpoints, untraced_callable: untraced_callable, allowed_request_headers: allowed_request_headers, @@ -25,6 +25,22 @@ url_quantization: url_quantization, response_propagators: response_propagators, record_frontend_span: record_frontend_span + } + end + + let(:exporter) { EXPORTER } + let(:finished_spans) { exporter.finished_spans } + let(:first_span) { exporter.finished_spans.first } + let(:uri) { '/' } + let(:handler) do + OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( + untraced_endpoints: config[:untraced_endpoints], + untraced_callable: config[:untraced_callable], + allowed_request_headers: config[:allowed_request_headers], + allowed_response_headers: config[:allowed_response_headers], + url_quantization: config[:url_quantization], + response_propagators: config[:response_propagators], + record_frontend_span: config[:record_frontend_span] ) end @@ -48,6 +64,10 @@ before do exporter.reset + + # simulate a fresh install: + instrumentation.instance_variable_set('@installed', false) + instrumentation.install(config) end describe '#call' do From 999594eb1b8a604f834806aee5f0d26f9308ea4e Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 22 Feb 2023 09:27:03 -0600 Subject: [PATCH 08/24] squash: Use declarative config options --- .../instrumentation/rack/instrumentation.rb | 14 +-- .../rack/middlewares/event_handler.rb | 94 ++++++++++++------- .../rack/middlewares/event_handler_test.rb | 30 +----- 3 files changed, 63 insertions(+), 75 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index d74a56a0f..2e8ec8253 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -32,22 +32,10 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base option :untraced_requests, default: nil, validate: :callable option :response_propagators, default: [], validate: :array - def new_rack_events_handler - OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( - untraced_endpoints: config[:untraced_endpoints], - untraced_callable: config[:untraced_callable], - allowed_request_headers: config[:allowed_request_headers], - allowed_response_headers: config[:allowed_response_headers], - url_quantization: config[:url_quantization], - response_propagators: config[:response_propagators], - record_frontend_span: config[:record_frontend_span] - ) - end - private def require_dependencies - require_relative 'middlewares/event_handler' + require_relative 'middlewares/event_handler' if defined?(Rack::Events) require_relative 'middlewares/tracer_middleware' end diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index d8bf1b851..972f0df48 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -45,33 +45,6 @@ class EventHandler TOKENS_KEY = 'otel.context.tokens' GOOD_HTTP_STATUSES = (100..499).freeze - def initialize(untraced_endpoints:, untraced_callable:, - allowed_request_headers:, allowed_response_headers:, - url_quantization:, response_propagators:, - record_frontend_span:) - @tracer = OpenTelemetry.tracer_provider.tracer('rack', '1.0') - @untraced_endpoints = Array(untraced_endpoints).compact - @untraced_callable = untraced_callable - @allowed_request_headers = Array(allowed_request_headers) - .compact - .each_with_object({}) { |header, memo| - key = header.to_s.upcase.gsub(/[-\s]/, '_') - case key - when 'CONTENT_TYPE', 'CONTENT_LENGTH' - memo[key] = build_attribute_name('http.request.header.', header) - else - memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) - end - } - @allowed_response_headers = Array(allowed_response_headers).each_with_object({}) do |header, memo| - memo[header] = build_attribute_name('http.response.header.', header) - memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) - end - @url_quantization = url_quantization - @response_propagators = response_propagators - @record_frontend_span = record_frontend_span == true - end - # Creates a server span for this current request using the incoming parent context # and registers them as the {current_span} # @@ -82,10 +55,10 @@ def on_start(request, _) return if untraced_request?(request.env) extracted_context = extract_remote_context(request) - if @record_frontend_span + if record_frontend_span? request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) unless request_start_time.nil? - frontend_span = @tracer.start_span( + frontend_span = tracer.start_span( 'http_server.proxy', with_parent: extracted_context, start_timestamp: request_start_time, @@ -97,7 +70,7 @@ def on_start(request, _) end parent_context = frontend_context || extracted_context - span = @tracer.start_span( + span = tracer.start_span( create_request_span_name(request), with_parent: parent_context, kind: frontend_context.nil? ? :server : :internal, @@ -124,7 +97,7 @@ def on_commit(request, response) return unless span.recording? begin - @response_propagators&.each { |propagator| propagator.inject(response.headers) } + response_propagators&.each { |propagator| propagator.inject(response.headers) } rescue StandardError => e OpenTelemetry.handle_error(message: 'Unable to inject response propagation headers', exception: e) end @@ -183,9 +156,9 @@ def extract_response_attributes(response) end def extract_response_headers(headers) - return EMPTY_HASH if @allowed_response_headers.empty? + return EMPTY_HASH if allowed_response_headers.empty? - @allowed_response_headers.each_with_object({}) do |(key, value), result| + allowed_response_headers.each_with_object({}) do |(key, value), result| if headers.key?(key) result[value] = headers[key] else @@ -201,8 +174,8 @@ def extract_response_headers(headers) end def untraced_request?(env) - return true if @untraced_endpoints.include?(env['PATH_INFO']) - return true if @untraced_callable&.call(env) + return true if untraced_endpoints.include?(env['PATH_INFO']) + return true if untraced_requests&.call(env) false end @@ -217,7 +190,7 @@ def create_request_span_name(request) # NOTE: dd-trace-rb has implemented 'quantization' (which lowers url cardinality) # see Datadog::Quantization::HTTP.url - if (implementation = @url_quantization) + if (implementation = url_quantization) request_uri_or_path_info = request.env['REQUEST_URI'] || request.path_info implementation.call(request_uri_or_path_info, request.env) else @@ -248,6 +221,55 @@ def request_span_attributes(env) def build_attribute_name(prefix, suffix) prefix + suffix.to_s.downcase.gsub(/[-\s]/, '_') end + + def record_frontend_span? + config[:record_frontend_span] == true + end + + def untraced_endpoints + config[:untraced_endpoints].compact + end + + def untraced_requests + config[:untraced_requests] + end + + def url_quantization + config[:url_quantization] + end + + def response_propagators + config[:response_propagators] + end + + def allowed_request_headers + config[:allowed_request_headers] + .compact + .each_with_object({}) do |header, memo| + key = header.to_s.upcase.gsub(/[-\s]/, '_') + case key + when 'CONTENT_TYPE', 'CONTENT_LENGTH' + memo[key] = build_attribute_name('http.request.header.', header) + else + memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) + end + end + end + + def allowed_response_headers + config[:allowed_response_headers].each_with_object({}) do |header, memo| + memo[header] = build_attribute_name('http.response.header.', header) + memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) + end + end + + def tracer + OpenTelemetry::Instrumentation::Rack::Instrumentation.instance.tracer + end + + def config + OpenTelemetry::Instrumentation::Rack::Instrumentation.instance.config + end end end end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 2fe3d3da3..1263700ed 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -19,7 +19,7 @@ let(:config) do { untraced_endpoints: untraced_endpoints, - untraced_callable: untraced_callable, + untraced_requests: untraced_requests, allowed_request_headers: allowed_request_headers, allowed_response_headers: allowed_response_headers, url_quantization: url_quantization, @@ -33,22 +33,14 @@ let(:first_span) { exporter.finished_spans.first } let(:uri) { '/' } let(:handler) do - OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new( - untraced_endpoints: config[:untraced_endpoints], - untraced_callable: config[:untraced_callable], - allowed_request_headers: config[:allowed_request_headers], - allowed_response_headers: config[:allowed_response_headers], - url_quantization: config[:url_quantization], - response_propagators: config[:response_propagators], - record_frontend_span: config[:record_frontend_span] - ) + OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new end let(:service) do ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, 'Hello World'] } end let(:untraced_endpoints) { [] } - let(:untraced_callable) { nil } + let(:untraced_requests) { nil } let(:allowed_request_headers) { nil } let(:allowed_response_headers) { nil } let(:record_frontend_span) { false } @@ -116,20 +108,6 @@ end end - describe 'when a string is passed in' do - let(:untraced_endpoints) { '/ping' } - - it 'does not trace path' do - get '/ping' - - ping_span = finished_spans.find { |s| s.attributes['http.target'] == '/ping' } - _(ping_span).must_be_nil - - root_span = finished_spans.find { |s| s.attributes['http.target'] == '/' } - _(root_span).wont_be_nil - end - end - describe 'when nil is passed in' do let(:config) { { untraced_endpoints: nil } } @@ -147,7 +125,7 @@ describe 'config[:untraced_requests]' do describe 'when a callable is passed in' do - let(:untraced_callable) do + let(:untraced_requests) do ->(env) { env['PATH_INFO'] =~ %r{^\/assets} } end From 52616768658657daf862c741ff8f2d31441c4563 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Fri, 24 Feb 2023 21:41:50 -0600 Subject: [PATCH 09/24] squash: fix bad refactoring --- .../instrumentation/rack/middlewares/event_handler.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 972f0df48..fb1053bb6 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -142,9 +142,9 @@ def on_finish(request, response) EMPTY_HASH = {}.freeze def extract_request_headers(env) - return EMPTY_HASH if @allowed_request_headers.empty? + return EMPTY_HASH if allowed_request_headers.empty? - @allowed_request_headers.each_with_object({}) do |(key, value), result| + allowed_request_headers.each_with_object({}) do |(key, value), result| result[value] = env[key] if env.key?(key) end end From e66a1883b35975290f57628da3a4ecf88a03879f Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 20:28:02 -0600 Subject: [PATCH 10/24] convert proxy span to an event --- .../rack/middlewares/event_handler.rb | 23 +--- .../rack/middlewares/event_handler_test.rb | 110 +++++++----------- 2 files changed, 46 insertions(+), 87 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index fb1053bb6..6a15ea17b 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -54,32 +54,21 @@ class EventHandler def on_start(request, _) return if untraced_request?(request.env) - extracted_context = extract_remote_context(request) - if record_frontend_span? - request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) - unless request_start_time.nil? - frontend_span = tracer.start_span( - 'http_server.proxy', - with_parent: extracted_context, - start_timestamp: request_start_time, - kind: :server - ) - - frontend_context = OpenTelemetry::Trace.context_with_span(frontend_span, parent_context: extracted_context) - end - end - parent_context = frontend_context || extracted_context + parent_context = extract_remote_context(request) span = tracer.start_span( create_request_span_name(request), with_parent: parent_context, - kind: frontend_context.nil? ? :server : :internal, + kind: :server, attributes: request_span_attributes(request.env) ) + request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) + span.add_event('http.proxy.request.started', timestamp: request_start_time) unless request_start_time.nil? + ctx = OpenTelemetry::Trace.context_with_span(span) rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) - contexts = [frontend_context, ctx, rack_ctx] + contexts = [ctx, rack_ctx] contexts.compact! tokens = contexts.map { |context| OpenTelemetry::Context.attach(context) } diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 1263700ed..093027265 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -30,7 +30,8 @@ let(:exporter) { EXPORTER } let(:finished_spans) { exporter.finished_spans } - let(:first_span) { exporter.finished_spans.first } + let(:rack_span) { exporter.finished_spans.first } + let(:proxy_event) { rack_span.events&.first } let(:uri) { '/' } let(:handler) do OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new @@ -67,29 +68,24 @@ get uri, {}, headers end - it 'records attributes' do - _(first_span.attributes['http.method']).must_equal 'GET' - _(first_span.attributes['http.status_code']).must_equal 200 - _(first_span.attributes['http.target']).must_equal '/' - _(first_span.attributes['http.url']).must_be_nil - _(first_span.name).must_equal 'HTTP GET' - _(first_span.kind).must_equal :server - end - - it 'does not explicitly set status OK' do - _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET - end - - it 'has no parent' do - _(first_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID + it 'record a span' do + _(rack_span.attributes['http.method']).must_equal 'GET' + _(rack_span.attributes['http.status_code']).must_equal 200 + _(rack_span.attributes['http.target']).must_equal '/' + _(rack_span.attributes['http.url']).must_be_nil + _(rack_span.name).must_equal 'HTTP GET' + _(rack_span.kind).must_equal :server + _(rack_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET + _(rack_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID + _(proxy_event).must_be_nil end describe 'when a query is passed in' do let(:uri) { '/endpoint?query=true' } it 'records the query path' do - _(first_span.attributes['http.target']).must_equal '/endpoint?query=true' - _(first_span.name).must_equal 'HTTP GET' + _(rack_span.attributes['http.target']).must_equal '/endpoint?query=true' + _(rack_span.name).must_equal 'HTTP GET' end end @@ -165,7 +161,7 @@ end it 'defaults to nil' do - _(first_span.attributes['http.request.header.foo_bar']).must_be_nil + _(rack_span.attributes['http.request.header.foo_bar']).must_be_nil end describe 'when configured' do @@ -174,7 +170,7 @@ end it 'returns attribute' do - _(first_span.attributes['http.request.header.foo_bar']).must_equal 'http foo bar value' + _(rack_span.attributes['http.request.header.foo_bar']).must_equal 'http foo bar value' end end @@ -182,7 +178,7 @@ let(:allowed_request_headers) { ['CONTENT_TYPE'] } it 'returns attribute' do - _(first_span.attributes['http.request.header.content_type']).must_equal 'application/json' + _(rack_span.attributes['http.request.header.content_type']).must_equal 'application/json' end end @@ -190,7 +186,7 @@ let(:allowed_request_headers) { ['CONTENT_LENGTH'] } it 'returns attribute' do - _(first_span.attributes['http.request.header.content_length']).must_equal '123' + _(rack_span.attributes['http.request.header.content_length']).must_equal '123' end end end @@ -201,58 +197,32 @@ end it 'defaults to nil' do - _(first_span.attributes['http.response.header.foo_bar']).must_be_nil + _(rack_span.attributes['http.response.header.foo_bar']).must_be_nil end describe 'when configured' do let(:allowed_response_headers) { ['Foo-Bar'] } it 'returns attribute' do - _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' + _(rack_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' end describe 'case-sensitively' do let(:allowed_response_headers) { ['fOO-bAR'] } it 'returns attribute' do - _(first_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' + _(rack_span.attributes['http.response.header.foo_bar']).must_equal 'foo bar response header' end end end end - describe 'record_frontend_span' do - let(:request_span) { exporter.finished_spans.first } + describe 'given request proxy headers' do + let(:headers) { Hash('HTTP_X_REQUEST_START' => '1677723466') } - describe 'default' do - it 'does not record span' do - _(exporter.finished_spans.size).must_equal 1 - end - - it 'does not parent the request_span' do - _(request_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID - end - end - - describe 'when recordable' do - let(:record_frontend_span) { true } - let(:headers) { Hash('HTTP_X_REQUEST_START' => Time.now.to_i) } - let(:frontend_span) { exporter.finished_spans[1] } - let(:request_span) { exporter.finished_spans[0] } - - it 'records span' do - _(exporter.finished_spans.size).must_equal 2 - _(frontend_span.name).must_equal 'http_server.proxy' - _(frontend_span.attributes['service']).must_be_nil - end - - it 'changes request_span kind' do - _(request_span.kind).must_equal :internal - end - - it 'frontend_span parents request_span' do - _(request_span.parent_span_id).must_equal frontend_span.span_id - end + it 'records an event' do + _(proxy_event.name).must_equal 'http.proxy.request.started' + _(proxy_event.timestamp).must_equal 1_677_723_466_000_000_000 end end @@ -262,9 +232,9 @@ end it 'leaves status code unset' do - _(first_span.attributes['http.status_code']).must_equal 404 - _(first_span.kind).must_equal :server - _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET + _(rack_span.attributes['http.status_code']).must_equal 404 + _(rack_span.kind).must_equal :server + _(rack_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET end end end @@ -275,8 +245,8 @@ it 'span.name defaults to low cardinality name HTTP method' do get '/really_long_url' - _(first_span.name).must_equal 'HTTP GET' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(rack_span.name).must_equal 'HTTP GET' + _(rack_span.attributes['http.target']).must_equal '/really_long_url' end end @@ -290,8 +260,8 @@ it 'sets the span.name to the full path' do get '/really_long_url' - _(first_span.name).must_equal '/really_long_url' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(rack_span.name).must_equal '/really_long_url' + _(rack_span.attributes['http.target']).must_equal '/really_long_url' end end @@ -305,7 +275,7 @@ it 'mutates url according to url_quantization' do get '/really_long_url' - _(first_span.name).must_equal '/reall' + _(rack_span.name).must_equal '/reall' end end end @@ -315,8 +285,8 @@ it 'span.name defaults to low cardinality name HTTP method' do get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } - _(first_span.name).must_equal 'HTTP GET' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(rack_span.name).must_equal 'HTTP GET' + _(rack_span.attributes['http.target']).must_equal '/really_long_url' end end @@ -330,8 +300,8 @@ it 'sets the span.name to the full path' do get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } - _(first_span.name).must_equal '/action-dispatch-uri' - _(first_span.attributes['http.target']).must_equal '/really_long_url' + _(rack_span.name).must_equal '/action-dispatch-uri' + _(rack_span.attributes['http.target']).must_equal '/really_long_url' end end @@ -345,7 +315,7 @@ it 'mutates url according to url_quantization' do get '/really_long_url', {}, { 'REQUEST_URI' => '/action-dispatch-uri' } - _(first_span.name).must_equal '/actio' + _(rack_span.name).must_equal '/actio' end end end @@ -397,7 +367,7 @@ def inject(carrier) get '/' end - _(first_span.status.code).must_equal OpenTelemetry::Trace::Status::ERROR + _(rack_span.status.code).must_equal OpenTelemetry::Trace::Status::ERROR end end end From 700f58f51faf6e498bc64026025aeb9af185f914 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 21:23:05 -0600 Subject: [PATCH 11/24] refactor: move configurations to instrumentation install --- .../instrumentation/rack/instrumentation.rb | 24 +++++++ .../rack/middlewares/event_handler.rb | 65 ++++++++----------- 2 files changed, 50 insertions(+), 39 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index 2e8ec8253..b9160bb8b 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -16,6 +16,7 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base require_dependencies retain_middleware_names if config[:retain_middleware_names] + configure_defaults end present do @@ -62,6 +63,29 @@ def call(env) next_middleware.instance_variable_get('@app') end end + + def configure_defaults + config[:allowed_rack_request_headers] = config[:allowed_request_headers].compact.each_with_object({}) do |header, memo| + key = header.to_s.upcase.gsub(/[-\s]/, '_') + case key + when 'CONTENT_TYPE', 'CONTENT_LENGTH' + memo[key] = build_attribute_name('http.request.header.', header) + else + memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) + end + end + + config[:allowed_rack_response_headers] = config[:allowed_response_headers].each_with_object({}) do |header, memo| + memo[header] = build_attribute_name('http.response.header.', header) + memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) + end + + config[:untraced_endpoints]&.compact! + end + + def build_attribute_name(prefix, suffix) + prefix + suffix.to_s.downcase.gsub(/[-\s]/, '_') + end end end end diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 6a15ea17b..7bc6d34f8 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -55,25 +55,8 @@ def on_start(request, _) return if untraced_request?(request.env) parent_context = extract_remote_context(request) - - span = tracer.start_span( - create_request_span_name(request), - with_parent: parent_context, - kind: :server, - attributes: request_span_attributes(request.env) - ) - request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) - span.add_event('http.proxy.request.started', timestamp: request_start_time) unless request_start_time.nil? - - ctx = OpenTelemetry::Trace.context_with_span(span) - rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) - - contexts = [ctx, rack_ctx] - contexts.compact! - - tokens = contexts.map { |context| OpenTelemetry::Context.attach(context) } - - request.env[TOKENS_KEY] = tokens + span = create_span(parent_context, request) + request.env[TOKENS_KEY] = register_current_span(span) end # Optionally adds debugging response headers injected from {response_propagators} @@ -207,16 +190,12 @@ def request_span_attributes(env) attributes end - def build_attribute_name(prefix, suffix) - prefix + suffix.to_s.downcase.gsub(/[-\s]/, '_') - end - def record_frontend_span? config[:record_frontend_span] == true end def untraced_endpoints - config[:untraced_endpoints].compact + config[:untraced_endpoints] end def untraced_requests @@ -232,24 +211,11 @@ def response_propagators end def allowed_request_headers - config[:allowed_request_headers] - .compact - .each_with_object({}) do |header, memo| - key = header.to_s.upcase.gsub(/[-\s]/, '_') - case key - when 'CONTENT_TYPE', 'CONTENT_LENGTH' - memo[key] = build_attribute_name('http.request.header.', header) - else - memo["HTTP_#{key}"] = build_attribute_name('http.request.header.', header) - end - end + config[:allowed_rack_request_headers] end def allowed_response_headers - config[:allowed_response_headers].each_with_object({}) do |header, memo| - memo[header] = build_attribute_name('http.response.header.', header) - memo[header.to_s.upcase] = build_attribute_name('http.response.header.', header) - end + config[:allowed_rack_response_headers] end def tracer @@ -259,6 +225,27 @@ def tracer def config OpenTelemetry::Instrumentation::Rack::Instrumentation.instance.config end + + def register_current_span(span) + ctx = OpenTelemetry::Trace.context_with_span(span) + rack_ctx = OpenTelemetry::Instrumentation::Rack.context_with_span(span, parent_context: ctx) + + contexts = [ctx, rack_ctx] + contexts.compact! + contexts.map { |context| OpenTelemetry::Context.attach(context) } + end + + def create_span(parent_context, request) + span = tracer.start_span( + create_request_span_name(request), + with_parent: parent_context, + kind: :server, + attributes: request_span_attributes(request.env) + ) + request_start_time = OpenTelemetry::Instrumentation::Rack::Util::QueueTime.get_request_start(request.env) + span.add_event('http.proxy.request.started', timestamp: request_start_time) unless request_start_time.nil? + span + end end end end From 7154ec724e98343871f64a7f5ce3cab57ef9419d Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 21:34:04 -0600 Subject: [PATCH 12/24] squash: add test converage --- .rubocop.yml | 2 ++ .../rack/middlewares/event_handler_test.rb | 12 ++++++++++-- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/.rubocop.yml b/.rubocop.yml index fe91b0961..29a3231cb 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -20,6 +20,8 @@ Metrics/AbcSize: Enabled: false Metrics/BlockLength: Enabled: false +Metrics/ClassLength: + Enabled: false Metrics/MethodLength: Max: 25 Naming/FileName: diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 093027265..0443f0a4d 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -15,6 +15,7 @@ let(:instrumentation_module) { OpenTelemetry::Instrumentation::Rack } let(:instrumentation_class) { instrumentation_module::Instrumentation } let(:instrumentation) { instrumentation_class.instance } + let(:instrumentation_enabled) { true } let(:config) do { @@ -24,7 +25,7 @@ allowed_response_headers: allowed_response_headers, url_quantization: url_quantization, response_propagators: response_propagators, - record_frontend_span: record_frontend_span + enabled: instrumentation_enabled } end @@ -44,7 +45,6 @@ let(:untraced_requests) { nil } let(:allowed_request_headers) { nil } let(:allowed_response_headers) { nil } - let(:record_frontend_span) { false } let(:response_propagators) { nil } let(:url_quantization) { nil } let(:headers) { {} } @@ -370,4 +370,12 @@ def inject(carrier) _(rack_span.status.code).must_equal OpenTelemetry::Trace::Status::ERROR end end + + describe 'when the instrumentation is disabled' do + let(:instrumenation_enabled) { false } + + it 'does nothing' do + _(rack_span).must_be_nil + end + end end From 69e60eb2b7d6bf0f51fd8e12266b25fe64991a82 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 21:58:45 -0600 Subject: [PATCH 13/24] squash: make response headers a little more resilient --- .../rack/middlewares/event_handler.rb | 4 ++-- .../rack/middlewares/event_handler_test.rb | 12 +++++++----- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 7bc6d34f8..53b71607b 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -68,8 +68,8 @@ def on_commit(request, response) span = OpenTelemetry::Instrumentation::Rack.current_span return unless span.recording? - begin - response_propagators&.each { |propagator| propagator.inject(response.headers) } + response_propagators&.each do |propagator| + propagator.inject(response.headers) rescue StandardError => e OpenTelemetry.handle_error(message: 'Unable to inject response propagation headers', exception: e) end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 0443f0a4d..cbedb1efb 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -338,19 +338,21 @@ end end - describe 'propagator throws' do + describe 'response propagators that raise errors' do class EventMockPropagator < OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator + CustomError = Class.new(StandardError) def inject(carrier) - raise 'Injection failed' + raise CustomError, 'Injection failed' end end - let(:response_propagators) { [EventMockPropagator.new] } + let(:response_propagators) { [EventMockPropagator.new, OpenTelemetry::Trace::Propagation::TraceContext::ResponseTextMapPropagator.new] } - it 'records errors' do - expect(OpenTelemetry).to receive(:handle_error).with(exception: instance_of(RuntimeError), message: /Unable/) + it 'is fault tolerant' do + expect(OpenTelemetry).to receive(:handle_error).with(exception: instance_of(EventMockPropagator::CustomError), message: /Unable/) get '/ping' + _(last_response.headers).must_include('traceresponse') end end end From 006cea040e53a63d9c01f0749cb544b75de07d8c Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 23:04:24 -0600 Subject: [PATCH 14/24] squash: Ensures event middleware will not cause the application to crash when it encounters errors --- .../rack/middlewares/event_handler.rb | 34 +++++++++++++------ .../event_handler_reseliency_test.rb | 27 +++++++++++++++ 2 files changed, 51 insertions(+), 10 deletions(-) create mode 100644 instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 53b71607b..9c6adf46b 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -57,6 +57,8 @@ def on_start(request, _) parent_context = extract_remote_context(request) span = create_span(parent_context, request) request.env[TOKENS_KEY] = register_current_span(span) + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end # Optionally adds debugging response headers injected from {response_propagators} @@ -73,6 +75,9 @@ def on_commit(request, response) rescue StandardError => e OpenTelemetry.handle_error(message: 'Unable to inject response propagation headers', exception: e) end + + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end # Records Unexpected Exceptions on the Rack span and set the Span Status to Error @@ -87,6 +92,8 @@ def on_error(request, _, error) span.record_exception(error) span.status = OpenTelemetry::Trace::Status.error + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end # Finishes the span making it eligible to be exported and cleans up existing contexts @@ -98,16 +105,10 @@ def on_finish(request, response) span = OpenTelemetry::Instrumentation::Rack.current_span return unless span.recording? - if response - span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) - attributes = extract_response_attributes(response) - span.add_attributes(attributes) - end - - request.env[TOKENS_KEY]&.reverse&.each do |token| - OpenTelemetry::Context.detach(token) - OpenTelemetry::Trace.current_span.finish - end + add_response_attributes(span, response) if response + detach_contexts(request) + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end private @@ -190,6 +191,19 @@ def request_span_attributes(env) attributes end + def detach_contexts(request) + request.env[TOKENS_KEY]&.reverse&.each do |token| + OpenTelemetry::Context.detach(token) + OpenTelemetry::Trace.current_span.finish + end + end + + def add_response_attributes(span, response) + span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) + attributes = extract_response_attributes(response) + span.add_attributes(attributes) + end + def record_frontend_span? config[:record_frontend_span] == true end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb new file mode 100644 index 000000000..af0a972a2 --- /dev/null +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +# Copyright The OpenTelemetry Authors +# +# SPDX-License-Identifier: Apache-2.0 + +require 'test_helper' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack/instrumentation' +require_relative '../../../../../lib/opentelemetry/instrumentation/rack/middlewares/event_handler' + +describe 'OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler::ResiliencyTest' do + let(:handler) do + OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new + end + + it 'reports unexpected errors without causing request errors' do + allow(OpenTelemetry::Instrumentation::Rack).to receive(:current_span).and_raise('Bad news!') + expect(OpenTelemetry).to receive(:handle_error).exactly(4).times + + handler.on_start(nil, nil) + handler.on_commit(nil, nil) + handler.on_send(nil, nil) + handler.on_error(nil, nil, nil) + handler.on_finish(nil, nil) + end +end From 12c0e0f56a9e7d576c6cf355ac439299abc9e3db Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Wed, 1 Mar 2023 23:07:24 -0600 Subject: [PATCH 15/24] squash: fix linter error --- .../instrumentation/rack/middlewares/event_handler.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 9c6adf46b..000fe4895 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -75,7 +75,6 @@ def on_commit(request, response) rescue StandardError => e OpenTelemetry.handle_error(message: 'Unable to inject response propagation headers', exception: e) end - rescue StandardError => e OpenTelemetry.handle_error(exception: e) end From ef52a8cba1ffb63bb8fab2d69896954da39fdac7 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sat, 4 Mar 2023 22:17:10 -0600 Subject: [PATCH 16/24] feat: Add middleware args helper for ActionPack and Sinatra --- .../instrumentation/rack/instrumentation.rb | 16 ++++++++++++ .../rack/instrumentation_test.rb | 26 +++++++++++++++++++ .../rack/middlewares/event_handler_test.rb | 3 ++- 3 files changed, 44 insertions(+), 1 deletion(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index 2e4d3419f..d7f6b4204 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -29,6 +29,22 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base option :url_quantization, default: nil, validate: :callable option :untraced_requests, default: nil, validate: :callable option :response_propagators, default: [], validate: :array + option :use_rack_events, default: false, validate: :boolean + + # Temporary Helper for Sinatra and ActionPack middleware to use during installation + # @example Default usage + # Rack::Builder.new do + # use *OpenTelemetry::Instrumentation::Rack::Instrumenation.instance.middleware_args + # run lambda { |_arg| [200, { 'Content-Type' => 'text/plain' }, body] } + # end + # @return [Array] consisting of a middleware and arguments used in rack builders + def middleware_args + if config.fetch(:use_rack_events, false) == true + [::Rack::Events, [OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new]] + else + [OpenTelemetry::Instrumentation::Rack::Middlewares::TracerMiddleware] + end + end private diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb index e36f90871..def28f6d6 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb @@ -31,6 +31,7 @@ _(instrumentation.config[:url_quantization]).must_be_nil _(instrumentation.config[:untraced_requests]).must_be_nil _(instrumentation.config[:response_propagators]).must_be_empty + _(instrumentation.config[:use_rack_events]).must_equal false end end @@ -52,4 +53,29 @@ _(instrumentation.config[:response_propagators]).must_be_empty end end + + describe '#middleware_args' do + before do + instrumentation.install(config) + end + + describe 'when rack events are configured' do + let(:config) { Hash(use_rack_events: true) } + + it 'instantiates a custom event handler' do + args = instrumentation.middleware_args + _(args[0]).must_equal Rack::Events + _(args[1][0]).must_be_instance_of OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler + end + end + + describe 'when rack events are disabled' do + let(:config) { Hash(use_rack_events: false) } + + it 'instantiates a custom middleware' do + args = instrumentation.middleware_args + _(args).must_equal [OpenTelemetry::Instrumentation::Rack::Middlewares::TracerMiddleware] + end + end + end end diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index cbedb1efb..195d4d18b 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -25,7 +25,8 @@ allowed_response_headers: allowed_response_headers, url_quantization: url_quantization, response_propagators: response_propagators, - enabled: instrumentation_enabled + enabled: instrumentation_enabled, + use_rack_events: true } end From c53efcfab8936b8dff639a53456af0384a920fde Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 5 Mar 2023 08:33:08 -0600 Subject: [PATCH 17/24] fix: test case --- .../lib/opentelemetry/instrumentation/rack/instrumentation.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index d7f6b4204..38c000c17 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -18,7 +18,7 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base end present do - defined?(::Rack) + defined?(::Rack) && defined?(::Rack::Events) end option :allowed_request_headers, default: [], validate: :array @@ -49,7 +49,7 @@ def middleware_args private def require_dependencies - require_relative 'middlewares/event_handler' if defined?(Rack::Events) + require_relative 'middlewares/event_handler' require_relative 'middlewares/tracer_middleware' end From 3aee1c3b421b5e05e8e0d920d1dab895392b3faf Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 5 Mar 2023 08:52:09 -0600 Subject: [PATCH 18/24] fix: Rack Events is autoloaded so if the parent module is present so are submodules --- .../lib/opentelemetry/instrumentation/rack/instrumentation.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index 38c000c17..5d4d2bcdf 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -18,7 +18,7 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base end present do - defined?(::Rack) && defined?(::Rack::Events) + defined?(::Rack) end option :allowed_request_headers, default: [], validate: :array From fb5e826ebb1ecaa3f1c81a7913abb1258ab62342 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 5 Mar 2023 11:49:30 -0600 Subject: [PATCH 19/24] fix: More precise error handling --- .../instrumentation/rack/middlewares/event_handler.rb | 7 ++++++- .../rack/middlewares/event_handler_reseliency_test.rb | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb index 000fe4895..04c3985b1 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/middlewares/event_handler.rb @@ -105,9 +105,10 @@ def on_finish(request, response) return unless span.recording? add_response_attributes(span, response) if response - detach_contexts(request) rescue StandardError => e OpenTelemetry.handle_error(exception: e) + ensure + detach_contexts(request) end private @@ -195,12 +196,16 @@ def detach_contexts(request) OpenTelemetry::Context.detach(token) OpenTelemetry::Trace.current_span.finish end + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end def add_response_attributes(span, response) span.status = OpenTelemetry::Trace::Status.error unless GOOD_HTTP_STATUSES.include?(response.status.to_i) attributes = extract_response_attributes(response) span.add_attributes(attributes) + rescue StandardError => e + OpenTelemetry.handle_error(exception: e) end def record_frontend_span? diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb index af0a972a2..863f77b47 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_reseliency_test.rb @@ -16,7 +16,7 @@ it 'reports unexpected errors without causing request errors' do allow(OpenTelemetry::Instrumentation::Rack).to receive(:current_span).and_raise('Bad news!') - expect(OpenTelemetry).to receive(:handle_error).exactly(4).times + expect(OpenTelemetry).to receive(:handle_error).exactly(5).times handler.on_start(nil, nil) handler.on_commit(nil, nil) From 49f0bfe54d9a467d9c0a4ba9bcdbde9ed8d2ff7b Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 5 Mar 2023 12:29:08 -0600 Subject: [PATCH 20/24] fix: Ensure config is cleared/setup during installation --- .../instrumentation/rack/instrumentation.rb | 9 +++++---- .../instrumentation/rack/instrumentation_test.rb | 11 ++++++----- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index 5d4d2bcdf..1976f52ac 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -14,7 +14,6 @@ module Rack class Instrumentation < OpenTelemetry::Instrumentation::Base install do |_config| require_dependencies - configure_defaults end present do @@ -39,7 +38,7 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base # end # @return [Array] consisting of a middleware and arguments used in rack builders def middleware_args - if config.fetch(:use_rack_events, false) == true + if config.fetch(:use_rack_events, false) == true && defined?(::Rack::Events) [::Rack::Events, [OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new]] else [OpenTelemetry::Instrumentation::Rack::Middlewares::TracerMiddleware] @@ -49,11 +48,12 @@ def middleware_args private def require_dependencies - require_relative 'middlewares/event_handler' + require_relative 'middlewares/event_handler' if defined?(Rack::Events) require_relative 'middlewares/tracer_middleware' end - def configure_defaults + def config_options(user_config) + config = super(user_config) config[:allowed_rack_request_headers] = config[:allowed_request_headers].compact.each_with_object({}) do |header, memo| key = header.to_s.upcase.gsub(/[-\s]/, '_') case key @@ -70,6 +70,7 @@ def configure_defaults end config[:untraced_endpoints]&.compact! + config end def build_attribute_name(prefix, suffix) diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb index def28f6d6..c6a93f962 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb @@ -14,6 +14,7 @@ before do # simulate a fresh install: instrumentation.instance_variable_set('@installed', false) + instrumentation.config.clear end describe 'given default config options' do @@ -43,14 +44,14 @@ it 'skips installation' do _(instrumentation).wont_be :installed? - _(instrumentation.config[:allowed_request_headers]).must_be_empty - _(instrumentation.config[:allowed_response_headers]).must_be_empty + _(instrumentation.config[:allowed_request_headers]).must_be_nil + _(instrumentation.config[:allowed_response_headers]).must_be_nil _(instrumentation.config[:application]).must_be_nil - _(instrumentation.config[:record_frontend_span]).must_equal false - _(instrumentation.config[:untraced_endpoints]).must_be_empty + _(instrumentation.config[:record_frontend_span]).must_be_nil + _(instrumentation.config[:untraced_endpoints]).must_be_nil _(instrumentation.config[:url_quantization]).must_be_nil _(instrumentation.config[:untraced_requests]).must_be_nil - _(instrumentation.config[:response_propagators]).must_be_empty + _(instrumentation.config[:response_propagators]).must_be_nil end end From b7cad3f8755e5aef2d5df29fb543ce6b8cf38070 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Mon, 6 Mar 2023 08:09:00 -0600 Subject: [PATCH 21/24] fix: Sinatra 1.4 compatability --- .../lib/opentelemetry/instrumentation/rack/instrumentation.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb index 1976f52ac..b1c6f8763 100644 --- a/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb +++ b/instrumentation/rack/lib/opentelemetry/instrumentation/rack/instrumentation.rb @@ -28,9 +28,11 @@ class Instrumentation < OpenTelemetry::Instrumentation::Base option :url_quantization, default: nil, validate: :callable option :untraced_requests, default: nil, validate: :callable option :response_propagators, default: [], validate: :array + # This option is only valid for applicaitons using Rack 2.0 or greater option :use_rack_events, default: false, validate: :boolean # Temporary Helper for Sinatra and ActionPack middleware to use during installation + # # @example Default usage # Rack::Builder.new do # use *OpenTelemetry::Instrumentation::Rack::Instrumenation.instance.middleware_args From 205cd665e27ef0c259d474e2950c3e1063241081 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sat, 18 Mar 2023 21:33:00 -0500 Subject: [PATCH 22/24] fix: bad merge --- .../opentelemetry/instrumentation/rack/instrumentation_test.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb index ab1b50b3b..2814bde0d 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/instrumentation_test.rb @@ -44,6 +44,7 @@ it 'skips installation' do _(instrumentation).wont_be :installed? + end end describe '#middleware_args' do From e9e837ef0adee82c293288a900cbb9532b5b1c38 Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 19 Mar 2023 13:05:22 -0500 Subject: [PATCH 23/24] fix: invalid responses in test case --- .../instrumentation/rack/middlewares/event_handler_test.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 195d4d18b..187b952e1 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -40,7 +40,7 @@ end let(:service) do - ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, 'Hello World'] } + ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, ['Hello World']] } end let(:untraced_endpoints) { [] } let(:untraced_requests) { nil } From 0a961a107fe90acf24cdbc4af020f3343c75468f Mon Sep 17 00:00:00 2001 From: Ariel Valentin Date: Sun, 19 Mar 2023 13:21:51 -0500 Subject: [PATCH 24/24] squash: Added a few more test cases --- .../rack/middlewares/event_handler_test.rb | 31 ++++++++++++++++++- 1 file changed, 30 insertions(+), 1 deletion(-) diff --git a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb index 187b952e1..ff43da7d1 100644 --- a/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb +++ b/instrumentation/rack/test/opentelemetry/instrumentation/rack/middlewares/event_handler_test.rb @@ -39,8 +39,11 @@ OpenTelemetry::Instrumentation::Rack::Middlewares::EventHandler.new end + let(:after_close) { nil } + let(:response_body) { Rack::BodyProxy.new(['Hello World']) { after_close&.call } } + let(:service) do - ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, ['Hello World']] } + ->(_arg) { [200, { 'Content-Type' => 'text/plain' }, response_body] } end let(:untraced_endpoints) { [] } let(:untraced_requests) { nil } @@ -381,4 +384,30 @@ def inject(carrier) _(rack_span).must_be_nil end end + + describe 'when response body is called' do + let(:after_close) { -> { OpenTelemetry::Instrumentation::Rack.current_span.add_event('after-response-called') } } + + it 'has access to a Rack read/write span' do + get '/' + _(rack_span.events.map(&:name)).must_include('after-response-called') + end + end + + describe 'when response body is called' do + let(:response_body) { ['Simple, Hello World!'] } + + it 'has access to a Rack read/write span' do + get '/' + _(rack_span.attributes['http.method']).must_equal 'GET' + _(rack_span.attributes['http.status_code']).must_equal 200 + _(rack_span.attributes['http.target']).must_equal '/' + _(rack_span.attributes['http.url']).must_be_nil + _(rack_span.name).must_equal 'HTTP GET' + _(rack_span.kind).must_equal :server + _(rack_span.status.code).must_equal OpenTelemetry::Trace::Status::UNSET + _(rack_span.parent_span_id).must_equal OpenTelemetry::Trace::INVALID_SPAN_ID + _(proxy_event).must_be_nil + end + end end