Add provider timing metrics

Gemfile.lock

@@ -1,8 +1,9 @@
 PATH
   remote: .
   specs:
-    entitlements-app (1.2.1)
+    entitlements-app (1.2.2)
       concurrent-ruby (~> 1.3, >= 1.3.1)
+      dogstatsd-ruby (~> 5.7)
       faraday (~> 2.0)
       logger (~> 1.6)
       net-ldap (~> 0.19)
@@ -39,6 +40,7 @@ GEM
       reline (>= 0.3.1)
     diff-lcs (1.5.1)
     docile (1.4.0)
+    dogstatsd-ruby (5.7.1)
     drb (2.2.1)
     faraday (2.14.1)
       faraday-net_http (>= 2.0, < 3.5)

entitlements-app.gemspec

@@ -17,6 +17,7 @@ Gem::Specification.new do |s|
   s.required_ruby_version = ">= 3.0.0"
 
   s.add_dependency "concurrent-ruby", "~> 1.3", ">= 1.3.1"
+  s.add_dependency "dogstatsd-ruby", "~> 5.7"
   s.add_dependency "faraday", "~> 2.0"
   s.add_dependency "net-ldap", "~> 0.19"
   s.add_dependency "octokit", "~> 4.18"

lib/entitlements.rb

@@ -16,9 +16,11 @@
 # :nocov:
 
 require "contracts"
+require "datadog/statsd"
 require "erb"
 require "logger"
 require "ostruct"
+require "resolv"
 require "stringio"
 require "uri"
 require "yaml"
@@ -89,6 +91,7 @@ def self.reset!
     @config_file = nil
     @config_path_override = nil
     @person_extra_methods = {}
+    @statsd = nil
 
     reset_extras!
     Entitlements::Data::Groups::Calculated.reset!
@@ -354,6 +357,48 @@ def self.set_logger(logger)
   end
   # :nocov:
 
+  def self.statsd
+    @statsd ||= build_statsd
+  end
+
+  def self.set_statsd(statsd)
+    @statsd = statsd
+  end
+
+  def self.close_statsd
+    @statsd&.close
+    @statsd = nil
+  end
+
+  def self.build_statsd
+    host = Resolv.getaddress(ENV.fetch("DOGSTATSD_HOST", "localhost"))
+    port = Integer(ENV.fetch("DOGSTATSD_PORT", 28_125))
+    tags = [
+      "application:entitlements",
+      "kube_pod_name:#{ENV.fetch('KUBE_POD_NAME', 'not-on-kubernetes')}",
+      "app_env:#{ENV.fetch('APP_ENV', 'development')}"
+    ]
+    Datadog::Statsd.new(host, port, tags: tags)
+  end
+
+  def self.timed_operation(phase:, provider: nil, target: nil, span: "leaf", concurrent: false, count: nil)
+    tags = [
+      "phase:#{phase}",
+      "status:error",
+      "span:#{span}",
+      "concurrent:#{concurrent}"
+    ]
+    tags << "provider:#{provider}" if provider
+    tags << "target:#{target}" if target
+    tags << "count:#{count}" if count
+
+    statsd.time("entitlements.operation.duration", tags: tags) do
+      result = yield
+      tags[1] = "status:success"
+      result
+    end
+  end
+
   # Calculate - This runs the entitlements logic to calculate the differences, ultimately
   # populating a cache and returning a list of actions. The cache and actions can then be
   # consumed by `execute` to implement the changes.
@@ -363,14 +408,22 @@ def self.set_logger(logger)
   # Returns the array of actions.
   Contract C::None => C::ArrayOf[Entitlements::Models::Action]
   def self.calculate
+    timed_operation(phase: "calculate_total", span: "parent") { calculate_actions }
+  end
+
+  def self.calculate_actions
     # Load extras that are configured.
-    Entitlements.load_extras if Entitlements.config.key?("extras")
+    if Entitlements.config.key?("extras")
+      timed_operation(phase: "load_extras") { Entitlements.load_extras }
+    end
 
     # Pre-fetch people from configured people data sources.
-    Entitlements.prefetch_people
+    timed_operation(phase: "prefetch_people") { Entitlements.prefetch_people }
 
     # Register filters that are configured.
-    Entitlements.register_filters if Entitlements.config.key?("filters")
+    if Entitlements.config.key?("filters")
+      timed_operation(phase: "register_filters") { Entitlements.register_filters }
+    end
 
     # Keep track of the total change count.
     cache[:change_count] = 0
@@ -385,8 +438,9 @@ def self.calculate
       Concurrent::Future.execute({ executor: thread_pool }) do
         group_start = Time.now
         logger.debug("Begin prefetch and validate for #{group_name}")
-        obj.prefetch
-        obj.validate
+        provider = Entitlements.config["groups"].fetch(group_name).fetch("type")
+        timed_operation(phase: "prefetch", provider: provider, target: group_name, concurrent: true) { obj.prefetch }
+        timed_operation(phase: "validate", provider: provider, target: group_name, concurrent: true) { obj.validate }
         logger.debug("Finished prefetch and validate for #{group_name} in #{Time.now - group_start}")
       end
     end
@@ -398,7 +452,8 @@ def self.calculate
     calc_start = Time.now
     actions = []
     Entitlements.child_classes.map do |group_name, obj|
-      obj.calculate
+      provider = Entitlements.config["groups"].fetch(group_name).fetch("type")
+      timed_operation(phase: "calculate", provider: provider, target: group_name) { obj.calculate }
       if obj.change_count > 0
         logger.debug "Group #{group_name.inspect} contributes #{obj.change_count} change(s)."
         cache[:change_count] += obj.change_count
@@ -422,8 +477,14 @@ def self.calculate
     actions: C::ArrayOf[Entitlements::Models::Action]
   ] => nil
   def self.execute(actions:)
+    timed_operation(phase: "execute_total", span: "parent") { execute_actions(actions: actions) }
+  end
+
+  def self.execute_actions(actions:)
     # Set up auditors.
-    Entitlements.auditors.each { |auditor| auditor.setup }
+    Entitlements.auditors.each do |auditor|
+      timed_operation(phase: "audit_setup", provider: auditor.provider_id) { auditor.setup }
+    end
 
     # Track any raised exception to pass to the auditors.
     provider_exception = nil
@@ -433,14 +494,18 @@ def self.execute(actions:)
     # Sort the child classes by priority
     begin
       # Pre-apply changes for each class.
-      Entitlements.child_classes.each do |_, obj|
-        obj.preapply
+      Entitlements.child_classes.each do |group_name, obj|
+        provider = Entitlements.config["groups"].fetch(group_name).fetch("type")
+        timed_operation(phase: "preapply", provider: provider, target: group_name) { obj.preapply }
       end
 
       # Apply changes from all actions.
       actions.each do |action|
         obj = Entitlements.child_classes.fetch(action.ou)
-        obj.apply(action)
+        provider = Entitlements.config["groups"].fetch(action.ou).fetch("type")
+        timed_operation(phase: "apply", provider: provider, target: action.ou, count: 1) do
+          obj.apply(action)
+        end
         successful_actions.add(action.dn)
       end
     rescue => e
@@ -457,11 +522,13 @@ def self.execute(actions:)
         logger.debug "Recording data to #{Entitlements.auditors.size} audit provider(s)"
         Entitlements.auditors.each do |audit|
           begin
-            audit.commit(
-              actions: actions,
-              successful_actions: successful_actions,
-              provider_exception: provider_exception
-            )
+            timed_operation(phase: "audit_commit", provider: audit.provider_id) do
+              audit.commit(
+                actions: actions,
+                successful_actions: successful_actions,
+                provider_exception: provider_exception
+              )
+            end
             logger.debug "Audit #{audit.description} completed successfully"
           rescue => e
             logger.error "Audit #{audit.description} failed: #{e.class} #{e.message}"
@@ -564,7 +631,9 @@ def self.prefetch_people
 
       objects = people_data_sources.map do |ds_name, ds_config|
         people_obj = Entitlements::Data::People.new_from_config(ds_config)
-        people_obj.read
+        timed_operation(phase: "prefetch_people_source", provider: ds_config.fetch("type"), target: ds_name) do
+          people_obj.read
+        end
         [ds_name, people_obj]
       end.to_h
 

lib/entitlements/cli.rb

@@ -51,6 +51,8 @@ def self.run
       # Done.
       logger.info "Successfully applied #{Entitlements.cache[:change_count]} change(s)!"
       0
+    ensure
+      Entitlements.close_statsd
     end
     # :nocov:
 

lib/version.rb

@@ -2,6 +2,6 @@
 
 module Entitlements
   module Version
-    VERSION = "1.2.1"
+    VERSION = "1.2.2"
   end
 end

spec/unit/entitlements_spec.rb

@@ -171,8 +171,103 @@
     end
   end
 
+  describe "#build_statsd" do
+    it "builds a DogStatsD client using the IAM defaults" do
+      allow(ENV).to receive(:fetch).and_call_original
+      allow(ENV).to receive(:fetch).with("DOGSTATSD_HOST", "localhost").and_return("dogstatsd.example.com")
+      allow(ENV).to receive(:fetch).with("DOGSTATSD_PORT", 28_125).and_return("28125")
+      allow(ENV).to receive(:fetch).with("KUBE_POD_NAME", "not-on-kubernetes").and_return("entitlements-123")
+      allow(ENV).to receive(:fetch).with("APP_ENV", "development").and_return("production")
+      allow(Resolv).to receive(:getaddress).with("dogstatsd.example.com").and_return("192.0.2.1")
+
+      expect(Datadog::Statsd).to receive(:new).with(
+        "192.0.2.1",
+        28_125,
+        tags: [
+          "application:entitlements",
+          "kube_pod_name:entitlements-123",
+          "app_env:production"
+        ]
+      ).and_return(statsd)
+
+      expect(described_class.build_statsd).to eq(statsd)
+    end
+  end
+
+  describe "#close_statsd" do
+    it "closes and clears the configured client" do
+      expect(statsd).to receive(:close).once
+
+      described_class.close_statsd
+      described_class.close_statsd
+    end
+  end
+
+  describe "#timed_operation" do
+    it "measures a successful operation with provider details" do
+      tags = nil
+      expect(statsd).to receive(:time) do |metric, options, &block|
+        expect(metric).to eq("entitlements.operation.duration")
+        tags = options.fetch(:tags)
+        block.call
+      end
+
+      result = described_class.timed_operation(
+        phase: "apply",
+        provider: "aad",
+        target: "apps/azure_aad",
+        count: 1
+      ) { :result }
+
+      expect(result).to eq(:result)
+      expect(tags).to eq(
+        [
+          "phase:apply",
+          "status:success",
+          "span:leaf",
+          "concurrent:false",
+          "provider:aad",
+          "target:apps/azure_aad",
+          "count:1"
+        ]
+      )
+    end
+
+    it "measures failed operations before propagating the exception" do
+      tags = nil
+      expect(statsd).to receive(:time) do |metric, options, &block|
+        expect(metric).to eq("entitlements.operation.duration")
+        tags = options.fetch(:tags)
+        block.call
+      end
+
+      expect do
+        described_class.timed_operation(phase: "audit_setup") { raise "Boom" }
+      end.to raise_error(RuntimeError, "Boom")
+
+      expect(tags).to eq(
+        [
+          "phase:audit_setup",
+          "status:error",
+          "span:leaf",
+          "concurrent:false"
+        ]
+      )
+    end
+  end
+
   describe "#calculate" do
     let(:cache) { { people_obj: people_ldap } }
+    let(:entitlements_config_hash) do
+      {
+        "extras" => {},
+        "filters" => {},
+        "groups" => {
+          "ldap-dir" => { "type" => "ldap" },
+          "other-ldap-dir" => { "type" => "ldap" }
+        }
+      }
+    end
     let(:action1) { instance_double(Entitlements::Models::Action) }
     let(:action2) { instance_double(Entitlements::Models::Action) }
     let(:actions) { [action1, action2] }
@@ -208,8 +303,8 @@
     let(:cache) { { people_obj: people_ldap } }
     let(:people_ldap) { instance_double(Entitlements::Data::People::LDAP) }
 
-    let(:auditor1) { instance_double(Entitlements::Auditor::Base) }
-    let(:auditor2) { instance_double(Entitlements::Auditor::Base) }
+    let(:auditor1) { instance_double(Entitlements::Auditor::Base, provider_id: "auditor1") }
+    let(:auditor2) { instance_double(Entitlements::Auditor::Base, provider_id: "auditor2") }
 
     let(:action1) { instance_double(Entitlements::Models::Action) }
     let(:action2) { instance_double(Entitlements::Models::Action) }

spec/unit/spec_helper.rb

@@ -134,6 +134,11 @@ module MyLetDeclarations
   let(:entitlements_config_file) { fixture("config.yaml") }
   let(:entitlements_config_hash) { nil }
   let(:logger) { Entitlements.dummy_logger }
+  let(:statsd) do
+    instance_double(Datadog::Statsd).tap do |client|
+      allow(client).to receive(:time) { |*, &block| block.call }
+    end
+  end
 end
 
 module Contracts
@@ -163,6 +168,7 @@ def instance_double(klass, *args)
       Entitlements.validate_configuration_file!
     end
     Entitlements.set_logger(logger)
+    Entitlements.set_statsd(statsd)
   end
 
   config.after :each do