diff --git a/coach.gemspec b/coach.gemspec index e2f0386..e8a6e7d 100644 --- a/coach.gemspec +++ b/coach.gemspec @@ -22,6 +22,7 @@ Gem::Specification.new do |spec| spec.add_dependency "actionpack", ">= 4.2" spec.add_dependency "activesupport", ">= 4.2" spec.add_dependency "commander", "~> 4.5" + spec.add_dependency "opentelemetry-sdk" spec.add_development_dependency "gc_ruboconfig", "~> 2.18.0" spec.add_development_dependency "pry", "~> 0.10" @@ -29,4 +30,5 @@ Gem::Specification.new do |spec| spec.add_development_dependency "rspec-its", "~> 1.2" spec.add_development_dependency "rspec_junit_formatter", "~> 0.4.0" spec.add_development_dependency "rubocop", "~> 1.12" + spec.add_development_dependency "rack", "~> 2.2" end diff --git a/lib/coach/handler.rb b/lib/coach/handler.rb index 3361f2b..cd1ef67 100644 --- a/lib/coach/handler.rb +++ b/lib/coach/handler.rb @@ -2,6 +2,7 @@ require "coach/errors" require "active_support/core_ext/object/try" +require "opentelemetry/sdk" module Coach class Handler @@ -27,36 +28,51 @@ def initialize(middleware, config = {}) # the current request, and invokes it. # rubocop:disable Metrics/MethodLength def call(env) - context = { request: ActionDispatch::Request.new(env) } + request = ActionDispatch::Request.new(env) + context = { request: request, tracer: tracer } sequence = build_sequence(root_item, context) chain = build_request_chain(sequence, context) event = build_event(context) - publish("start_handler.coach", event.dup) - instrument("finish_handler.coach", event) do - response = chain.instrument.call - rescue StandardError => e - raise - ensure - # We want to populate the response and metadata fields after the middleware - # chain has completed so that the end of the instrumentation can see them. The - # simplest way to do this is pass the event by reference to ActiveSupport, then - # modify the hash to contain this detail before the instrumentation completes. - # - # This way, the last finish_handler.coach event will have all the details. - status = response.try(:first) || STATUS_CODE_FOR_EXCEPTIONS - event.merge!( - response: { + tracer.in_span("Coach::Handler #{name}", attributes: tracer_attributes(request), + kind: :server) do |span| + publish("start_handler.coach", event.dup) + instrument("finish_handler.coach", event) do + response = chain.instrument.call + span.set_attribute("http.status_code", response.try(:first)) + response + rescue StandardError => e + raise + ensure + # We want to populate the response and metadata fields after the middleware + # chain has completed so that the end of the instrumentation can see them. The + # simplest way to do this is pass the event by reference to ActiveSupport, then + # modify the hash to contain this detail before the instrumentation completes. + # + # This way, the last finish_handler.coach event will have all the details. + status = response.try(:first) || STATUS_CODE_FOR_EXCEPTIONS + event[:response] = { status: status, exception: e, - }.compact, - metadata: context.fetch(:_metadata, {}), - ) + }.compact + event[:metadata] = context.fetch(:_metadata, {}) + # span.set_attribute("http.status_code", status) + span.record_exception(e) unless e.nil? + end end end # rubocop:enable Metrics/MethodLength + def tracer_attributes(request) + { + "http.method"=> request.method, + "http.url"=> request.original_url, + "http.target"=> request.original_fullpath, + "http.user_agent"=> request.headers["user-agent"], + }.compact + end + # Traverse the middlware tree to build a linear middleware sequence, # containing only middlewares that apply to this request. def build_sequence(item, context) @@ -96,6 +112,10 @@ def middleware @middleware ||= ActiveSupport::Inflector.constantize(name) end + def tracer + @tracer ||= OpenTelemetry.tracer_provider.tracer("coach", Coach::VERSION) + end + # Remove middleware that have been included multiple times with the same # config, leaving only the first instance def dedup_sequence(sequence) diff --git a/lib/coach/middleware.rb b/lib/coach/middleware.rb index fe14da4..454eb78 100644 --- a/lib/coach/middleware.rb +++ b/lib/coach/middleware.rb @@ -1,7 +1,10 @@ # frozen_string_literal: true +require "opentelemetry/sdk" require "coach/middleware_item" +require "opentelemetry/sdk" + module Coach class Middleware def self.uses(middleware, config = {}) @@ -63,6 +66,10 @@ def request @_context[:request] end + def tracer + @_context[:tracer] || OpenTelemetry.tracer_provider.tracer("coach", Coach::VERSION) + end + # Make values available to middleware further down the stack. Accepts a # hash of name => value pairs. Names must have been declared by calling # `provides` on the class. @@ -79,10 +86,13 @@ def provide(args) # Use ActiveSupport to instrument the execution of the subsequent chain. def instrument proc do - ActiveSupport::Notifications.publish("start_middleware.coach", middleware_event) - - ActiveSupport::Notifications. - instrument("finish_middleware.coach", middleware_event) { call } + tracer.in_span("Coach::Middleware #{self.class.name}") do + ActiveSupport::Notifications.publish("start_middleware.coach", middleware_event) + ActiveSupport::Notifications.instrument("finish_middleware.coach", + middleware_event) do + call + end + end end end diff --git a/spec/lib/coach/handler_spec.rb b/spec/lib/coach/handler_spec.rb index 26019cf..81ae41d 100644 --- a/spec/lib/coach/handler_spec.rb +++ b/spec/lib/coach/handler_spec.rb @@ -9,6 +9,8 @@ describe Coach::Handler do subject(:handler) { described_class.new(terminal_middleware, handler: true) } + + let(:request) { Rack::MockRequest.env_for("https://example.com:8080/full/path?query=string", {"REMOTE_ADDR" => "10.10.10.10"}) } let(:middleware_a) { build_middleware("A") } let(:middleware_b) { build_middleware("B") } let(:middleware_c) { build_middleware("C") } @@ -31,7 +33,7 @@ it "invokes all middleware in the chain" do expect(a_double).to receive(:call) expect(b_double).to receive(:call) - result = handler.call({}) + result = handler.call(request) expect(result).to eq(%w[A{} B{} Terminal{:handler=>true}]) end @@ -64,7 +66,7 @@ expect(a_double).to receive(:call) expect(b_double).to receive(:call) - result = handler.call({}) + result = handler.call(request) expect(result).to eq(%w[A{} B{} Terminal{:handler=>true}]) end @@ -77,20 +79,46 @@ end it "raises on first call" do - expect { handler.call({}) }. + expect { handler.call(request) }. to raise_error(Coach::Errors::MiddlewareDependencyNotMet) end end end end + describe "tracing" do + let(:exporter) { EXPORTER } + let(:spans) { exporter.finished_spans } + let(:handler_span) { spans.find{ |s| s.name == "Coach::Handler Terminal" } } + let(:parent_span) { spans.find { |s| s.span_id == handler_span.parent_span_id } } + + before do + exporter.reset + terminal_middleware.uses(middleware_a) + handler.call(request) + end + + it "includes the handler span" do + expect(spans.size).to eq(3) + expect(handler_span).to_not be_nil + expect(parent_span).to be_nil + expect(handler_span.attributes["http.method"]).to eq("GET") + end + + it "includes middleware as a child span" do + child_span = spans.find{ |s| s.parent_span_id == handler_span.span_id } + expect(child_span).to_not be_nil + expect(child_span.name).to eq("Coach::Middleware A") + end + end + describe "notifications" do subject(:coach_events) do events = [] subscription = ActiveSupport::Notifications. subscribe(/\.coach$/) { |name, *_args| events << name } - handler.call({}) + handler.call(request) ActiveSupport::Notifications.unsubscribe(subscription) events end @@ -121,7 +149,7 @@ end begin - handler.call({}) + handler.call(request) rescue StandardError :continue_anyway end @@ -142,7 +170,7 @@ end it "bubbles the error to the next handler" do - expect { handler.call({}) }.to raise_error(StandardError, "AH") + expect { handler.call(request) }.to raise_error(StandardError, "AH") end end end diff --git a/spec/lib/coach/notifications_spec.rb b/spec/lib/coach/notifications_spec.rb index caee2bf..558b624 100644 --- a/spec/lib/coach/notifications_spec.rb +++ b/spec/lib/coach/notifications_spec.rb @@ -5,6 +5,7 @@ describe Coach::Notifications do subject(:notifications) { described_class.instance } + let(:request) { Rack::MockRequest.env_for("https://example.com:8080/full/path?query=string", {"REMOTE_ADDR" => "10.10.10.10"}) } before do described_class.unsubscribe! @@ -47,12 +48,12 @@ end it "will now send request.coach" do - handler.call({}) + handler.call(request) expect(middleware_event).to_not be_nil end describe "request.coach event" do - before { handler.call({}) } + before { handler.call(request) } it "contains all middleware that have been run" do middleware_names = middleware_event[:chain].map { |item| item[:name] } @@ -70,13 +71,13 @@ it "disables any prior subscriptions" do notifications.subscribe! - handler.call({}) + handler.call(request) expect(events.count { |(name, _)| name == "request.coach" }). to eq(1) notifications.unsubscribe! - handler.call({}) + handler.call(request) expect(events.count { |(name, _)| name == "request.coach" }). to eq(1) end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 83de412..57d9de3 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -2,13 +2,23 @@ require "rspec/its" require "pry" +require "rack" require "coach" require "coach/rspec" +require "opentelemetry/sdk" Dir[Pathname(__FILE__).dirname.join("support", "**", "*.rb")]. sort. each { |path| require path } + +EXPORTER = OpenTelemetry::SDK::Trace::Export::InMemorySpanExporter.new +SPAN_PROCESSOR = OpenTelemetry::SDK::Trace::Export::SimpleSpanProcessor.new(EXPORTER) + +OpenTelemetry::SDK.configure do |c| + c.add_span_processor SPAN_PROCESSOR +end + RSpec.configure do |config| config.expect_with :rspec do |expectations| expectations.include_chain_clauses_in_custom_matcher_descriptions = true