feat: opt-in Datadog instrumentation of every KB call (1.2.0)

CHANGELOG.md

@@ -6,7 +6,11 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
 ## [unreleased]
-- See diff: https://github.com/barkibu/kb-ruby/compare/v1.1.0...HEAD
+- See diff: https://github.com/barkibu/kb-ruby/compare/v1.2.0...HEAD
+
+## [1.2.0]
+- `KB::Client` emits one `request.kb_client` `ActiveSupport::Notifications` event per KB call (`KB::Client::REQUEST_EVENT`), wrapping cache lookup, connect, TLS, write, read and parsing. Payload: `verb`, `path`, `base_url`, `cache_hit` (GET only), `status`, plus ActiveSupport's `exception`/`exception_object` when the call raised. Every public method now goes through one private `perform` seam; no behaviour change (same cache keys, params and error classes).
+- Add an opt-in Datadog subscriber: `require 'kb/instrumentation/datadog'` + `KB::Instrumentation::Datadog.subscribe!` turns each event into a `kb.client.request` APM span, opened on event start and closed on finish so the tracer's Net::HTTP spans nest under it. The span inherits the app's service and stays there (no `span.kind:client`/`peer.service`, so it is not attributed to the knowledge-base service), tags `peer.hostname`, `kb.method`, `kb.cache_hit`, `http.status_code`, and uses low-cardinality resources (`GET /v1/pets/?/contracts`). Motivation: connect timeouts happen before `Net::HTTP#request`, so the Datadog Net::HTTP tracer never sees them and they were invisible on our dashboards. Works with `ddtrace` 1.x and `datadog` 2.x; the tracer stays the app's dependency.
 
 ## [1.1.0]
 - Add `read_timeout:` to `KB::Client#request` to raise the read budget for a single call (e.g. `GET /v1/pets/birthdays`, whose server-side work runs for seconds). Connect and write budgets stay global; the override does not leak into later calls on the same connection.

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    barkibu-kb (1.1.0)
+    barkibu-kb (1.2.0)
       activemodel (>= 4.0.2)
       activerecord
       activesupport (>= 3.0.0)
@@ -10,8 +10,8 @@ PATH
       faraday-net_http (~> 1.0)
       faraday_middleware
       i18n
-    barkibu-kb-fake (1.1.0)
-      barkibu-kb (= 1.1.0)
+    barkibu-kb-fake (1.2.0)
+      barkibu-kb (= 1.2.0)
       countries
       sinatra
       webmock
@@ -44,12 +44,21 @@ GEM
     base64 (0.3.0)
     bigdecimal (4.1.2)
     byebug (11.1.3)
+    cgi (0.5.2)
     concurrent-ruby (1.3.7)
     connection_pool (3.0.2)
     countries (5.3.1)
       unaccent (~> 0.3)
     crack (0.4.5)
       rexml
+    datadog (2.43.0)
+      cgi
+      datadog-ruby_core_source (~> 3.5, >= 3.5.5)
+      libdatadog (~> 40.0.0.2.0)
+      libddwaf (~> 1.30.0.0.0)
+      logger
+      msgpack
+    datadog-ruby_core_source (3.5.5)
     diff-lcs (1.4.4)
     docile (1.4.0)
     drb (2.2.3)
@@ -84,14 +93,19 @@ GEM
     faraday-retry (1.0.3)
     faraday_middleware (1.2.0)
       faraday (~> 1.0)
+    ffi (1.17.4)
     hashdiff (1.0.1)
     i18n (1.15.2)
       concurrent-ruby (~> 1.0)
     json (2.20.0)
+    libdatadog (40.0.0.2.0)
+    libddwaf (1.30.0.0.2)
+      ffi (~> 1.0)
     logger (1.7.0)
     minitest (6.0.6)
       drb (~> 2.0)
       prism (~> 1.5)
+    msgpack (1.8.5)
     multipart-post (2.3.0)
     mustermann (3.0.0)
       ruby2_keywords (~> 0.0.1)
@@ -173,6 +187,7 @@ DEPENDENCIES
   bigdecimal
   bundler
   byebug
+  datadog (~> 2.0)
   rake (>= 12.3.3)
   rspec (~> 3.0)
   rubocop

README.md

@@ -74,6 +74,49 @@ and write budgets stay global:
 KB::Pet.kb_client.request('birthdays', filters: { month: 9, day: 22, size: 1000 }, read_timeout: 30)
 ```
 
+#### Instrumentation
+
+Every KB call emits one `request.kb_client` event through
+`ActiveSupport::Notifications`, wrapping the whole call: cache lookup, TCP
+connect, TLS, write, read and JSON parsing. The payload carries `verb`, `path`,
+`base_url`, `cache_hit` (GET calls only), `status` (when a response arrived) and
+ActiveSupport's `exception` / `exception_object` when the call raised. Subscribe
+to it for logging, metrics or anything else:
+
+```ruby
+ActiveSupport::Notifications.subscribe(KB::Client::REQUEST_EVENT) do |event|
+  Rails.logger.info("KB #{event.payload[:verb]} #{event.payload[:path]} #{event.duration.round}ms")
+end
+```
+
+##### Datadog
+
+A ready-made subscriber turns each event into a `kb.client.request` APM span.
+Opt in from the app's Datadog initializer, after `Datadog.configure`. Works with
+both `ddtrace` 1.x and `datadog` 2.x; the tracer gem is the app's dependency.
+
+```ruby
+# config/initializers/datadog_tracer.rb
+Datadog.configure { |c| ... }
+
+require 'kb/instrumentation/datadog'
+KB::Instrumentation::Datadog.subscribe!
+```
+
+The span opens when the event starts and closes when it finishes, so the
+tracer's own Net::HTTP spans nest under it. It inherits the app's service
+(`c.service`), so nothing new appears in the APM service list, and it carries no
+`span.kind:client` or `peer.service`, so Datadog does not attribute it to the
+knowledge-base service either: it measures the client's whole call, not a KB
+operation. Resources are low-cardinality (`GET /v1/pets/birthdays`,
+`GET /v1/pets/?/contracts`). Tags: `peer.hostname` (the KB host used),
+`kb.method`, `kb.cache_hit` (GET calls only), `http.status_code`, plus the
+standard `error.type`/`error.message` when the call raises.
+
+Why not rely on the Net::HTTP tracer alone: faraday-net_http opens the socket
+before `Net::HTTP#request`, the method that tracer patches, so a connect timeout
+produces no http span at all. This span sees every phase.
+
 ### Exposed Entities
 
 #### Pet Parent 🧍🏾

barkibu-kb.gemspec

@@ -39,6 +39,7 @@ Gem::Specification.new do |spec|
   spec.add_dependency 'dry-configurable', '~> 0.9'
   spec.add_development_dependency 'bundler'
   spec.add_development_dependency 'byebug'
+  spec.add_development_dependency 'datadog', '~> 2.0'
   spec.add_development_dependency 'rake', '>= 12.3.3'
   spec.add_development_dependency 'rspec', '~> 3.0'
   spec.add_development_dependency 'rubocop'

lib/kb/client.rb

@@ -1,5 +1,10 @@
 module KB
   class Client
+    # Emitted once per KB call, wrapping cache lookup and the HTTP request.
+    # Payload: verb, path, base_url, cache_hit (GET only), status (when a response arrived),
+    # plus ActiveSupport's exception/exception_object when the call raised.
+    REQUEST_EVENT = 'request.kb_client'.freeze
+
     attr_reader :api_key, :base_url
 
     def initialize(base_url, api_key: ENV['KB_API_KEY'])
@@ -11,47 +16,38 @@ def initialize(base_url, api_key: ENV['KB_API_KEY'])
     # for the few endpoints whose server-side work legitimately runs for seconds
     # (e.g. GET /v1/pets/birthdays). Connect and write budgets stay global.
     def request(sub_path, filters: nil, method: :get, read_timeout: nil)
-      options = request_options(read_timeout)
-      return connection.public_send(method, sub_path, attributes_to_json(filters), &options).body if method != :get
+      return perform(method, sub_path, attributes_to_json(filters), read_timeout: read_timeout) if method != :get
 
       cache_key = "#{@base_url}/#{sub_path}/#{(filters || {}).sort.to_h}"
-      KB::Cache.fetch(cache_key) do
-        connection.public_send(method, sub_path, filters, &options).body
-      end
+      perform(:get, sub_path, filters, cache_key: cache_key, read_timeout: read_timeout)
     end
 
     def all(filters = {})
-      cache_key = "#{@base_url}/#{filters.sort.to_h}"
-
-      KB::Cache.fetch(cache_key) do
-        connection.get('', attributes_case_transform(filters)).body
-      end
+      perform(:get, '', attributes_case_transform(filters), cache_key: "#{@base_url}/#{filters.sort.to_h}")
     end
 
     def find(key, params = {})
       raise Faraday::ResourceNotFound, {} if key.blank?
 
-      KB::Cache.fetch("#{@base_url}/#{key}") do
-        connection.get(key, attributes_case_transform(params)).body
-      end
+      perform(:get, key, attributes_case_transform(params), cache_key: "#{@base_url}/#{key}")
     end
 
     def create(attributes)
-      connection.post('', attributes_to_json(attributes)).body
+      perform(:post, '', attributes_to_json(attributes))
     end
 
     def update(key, attributes)
       clear_cache_for(key)
-      connection.patch(key.to_s, attributes_to_json(attributes)).body
+      perform(:patch, key.to_s, attributes_to_json(attributes))
     end
 
     def destroy(key)
       clear_cache_for(key)
-      connection.delete(key.to_s).body
+      perform(:delete, key.to_s)
     end
 
     def upsert(attributes)
-      connection.put('', attributes_to_json(attributes)).body
+      perform(:put, '', attributes_to_json(attributes))
     end
 
     def clear_cache_for(key)
@@ -60,6 +56,32 @@ def clear_cache_for(key)
 
     private
 
+    # Every public method ends up here, so this is the one place a KB call is
+    # observable as a whole: cache lookup, connect, TLS, write, read, parse.
+    def perform(verb, path, payload = nil, cache_key: nil, read_timeout: nil)
+      event = { verb: verb, path: path, base_url: base_url }
+      ActiveSupport::Notifications.instrument(REQUEST_EVENT, event) do
+        if cache_key
+          event[:cache_hit] = true
+          KB::Cache.fetch(cache_key) do
+            event[:cache_hit] = false
+            http(event, payload, read_timeout)
+          end
+        else
+          http(event, payload, read_timeout)
+        end
+      end
+    end
+
+    def http(event, payload, read_timeout)
+      response = connection.public_send(event[:verb], event[:path], payload, &request_options(read_timeout))
+      event[:status] = response.status
+      response.body
+    rescue Faraday::ClientError, Faraday::ServerError => e
+      event[:status] = e.response && e.response[:status]
+      raise
+    end
+
     def headers
       {
         'Content-Type': 'application/json',

lib/kb/instrumentation/datadog.rb

@@ -0,0 +1,81 @@
+require 'uri'
+require 'active_support/notifications'
+
+module KB
+  module Instrumentation
+    # Opt-in Datadog APM tracing for every KB call, as a subscriber to the
+    # client's `request.kb_client` notification.
+    #
+    #   # config/initializers/datadog_tracer.rb, after Datadog.configure
+    #   require 'kb/instrumentation/datadog'
+    #   KB::Instrumentation::Datadog.subscribe!
+    #
+    # One `kb.client.request` span per call, opened when the event starts and
+    # closed when it finishes, so it wraps cache lookup, TCP connect, TLS,
+    # write, read and JSON parsing, and the tracer's own Net::HTTP spans nest
+    # under it. No service is given, so the span inherits the app's, and it stays
+    # there: the KB host is a plain `peer.hostname` tag, with no `span.kind:client`
+    # or `peer.service` that would attribute it to KB. Works with
+    # `ddtrace` 1.x and `datadog` 2.x; the tracer gem is the app's dependency.
+    module Datadog
+      OPERATION = 'kb.client.request'.freeze
+      # Path segments that are identifiers, collapsed to `?` so resources stay
+      # low-cardinality: `GET /v1/pets/?/contracts` rather than one per pet.
+      IDENTIFIER_SEGMENT = /\A(?:\h{8}-\h{4}-\h{4}-\h{4}-\h{12}|\d+)\z/.freeze
+      SPAN_KEY = :datadog_span
+
+      class TracerMissing < StandardError; end
+
+      class << self
+        def subscribe!
+          unless defined?(::Datadog::Tracing)
+            raise TracerMissing, "Datadog tracing is not loaded; require 'ddtrace' or 'datadog' first"
+          end
+
+          return @subscriber if @subscriber
+
+          @subscriber = ActiveSupport::Notifications.subscribe(KB::Client::REQUEST_EVENT, Subscriber.new)
+        end
+
+        def unsubscribe!
+          ActiveSupport::Notifications.unsubscribe(@subscriber) if @subscriber
+          @subscriber = nil
+        end
+
+        def subscribed?
+          !@subscriber.nil?
+        end
+
+        def resource_for(base_url, verb, path)
+          segments = (URI(base_url).path.split('/') + path.to_s.split('/')).reject(&:empty?)
+          template = segments.map { |segment| segment.match?(IDENTIFIER_SEGMENT) ? '?' : segment }
+          "#{verb.to_s.upcase} /#{template.join('/')}"
+        end
+      end
+
+      class Subscriber
+        def start(_name, _id, payload)
+          span = ::Datadog::Tracing.trace(OPERATION, type: 'http',
+                                                     resource: Datadog.resource_for(payload[:base_url], payload[:verb],
+                                                                                    payload[:path]))
+          # No span.kind:client / peer.service on purpose: the span covers the
+          # client's whole call (cache lookup, connect, parse), so it must not be
+          # inferred onto the knowledge-base service page as one of KB's operations.
+          span.set_tag('peer.hostname', URI(payload[:base_url]).host)
+          span.set_tag('kb.method', payload[:verb].to_s.upcase)
+          payload[SPAN_KEY] = span
+        end
+
+        def finish(_name, _id, payload)
+          span = payload.delete(SPAN_KEY)
+          return unless span
+
+          span.set_tag('kb.cache_hit', payload[:cache_hit].to_s) if payload.key?(:cache_hit)
+          span.set_tag('http.status_code', payload[:status].to_s) if payload[:status]
+          span.set_error(payload[:exception_object]) if payload[:exception_object]
+          span.finish
+        end
+      end
+    end
+  end
+end

lib/kb/version.rb

@@ -1,3 +1,3 @@
 module KB
-  VERSION = '1.1.0'.freeze
+  VERSION = '1.2.0'.freeze
 end

spec/client_notifications_spec.rb

@@ -0,0 +1,58 @@
+require 'spec_helper'
+
+RSpec.describe KB::Client do
+  subject(:client) { described_class.new('http://kb.test/v1/pets', api_key: 'test') }
+
+  let(:events) { [] }
+
+  around do |example|
+    subscriber = ActiveSupport::Notifications.subscribe(described_class::REQUEST_EVENT) do |*, payload|
+      events << payload
+    end
+    example.run
+  ensure
+    ActiveSupport::Notifications.unsubscribe(subscriber)
+  end
+
+  describe 'request.kb_client notifications' do
+    it 'describes a successful GET' do
+      stub_request(:get, 'http://kb.test/v1/pets/birthdays?month=9')
+        .to_return(status: 200, body: '{}', headers: { 'Content-Type' => 'application/json' })
+
+      client.request('birthdays', filters: { month: 9 })
+
+      expect(events.last).to eq(verb: :get, path: 'birthdays', base_url: 'http://kb.test/v1/pets',
+                                cache_hit: false, status: 200)
+    end
+
+    it 'describes a write without a cache flag' do
+      stub_request(:post, 'http://kb.test/v1/pets').to_return(status: 201, body: '{}',
+                                                              headers: { 'Content-Type' => 'application/json' })
+
+      client.create(name: 'Rex')
+
+      expect(events.last).to eq(verb: :post, path: '', base_url: 'http://kb.test/v1/pets', status: 201)
+    end
+
+    it 'keeps the status code and the exception when the API answers an error' do
+      stub_request(:get, 'http://kb.test/v1/pets/missing').to_return(status: 404, body: 'Not Found')
+
+      raised = nil
+      begin
+        client.find('missing')
+      rescue Faraday::Error => e
+        raised = e.class
+      end
+
+      expect(
+        raised: raised, status: events.last[:status], exception_class: events.last[:exception_object].class
+      ).to eq(raised: Faraday::ResourceNotFound, status: 404, exception_class: Faraday::ResourceNotFound)
+    end
+
+    it 'still raises to the caller when the event has subscribers' do
+      stub_request(:get, 'http://kb.test/v1/pets/missing').to_return(status: 404, body: 'Not Found')
+
+      expect { client.find('missing') }.to raise_error(Faraday::ResourceNotFound)
+    end
+  end
+end