diff --git a/Gemfile.lock b/Gemfile.lock index a9787f3..56afec2 100644 --- a/Gemfile.lock +++ b/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) diff --git a/entitlements-app.gemspec b/entitlements-app.gemspec index 717eda0..14549c1 100644 --- a/entitlements-app.gemspec +++ b/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" diff --git a/lib/entitlements.rb b/lib/entitlements.rb index 6e89811..c39fe0d 100644 --- a/lib/entitlements.rb +++ b/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 diff --git a/lib/entitlements/cli.rb b/lib/entitlements/cli.rb index 9f190f8..34ec45f 100644 --- a/lib/entitlements/cli.rb +++ b/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: diff --git a/lib/version.rb b/lib/version.rb index 412c637..06191dc 100644 --- a/lib/version.rb +++ b/lib/version.rb @@ -2,6 +2,6 @@ module Entitlements module Version - VERSION = "1.2.1" + VERSION = "1.2.2" end end diff --git a/spec/unit/entitlements_spec.rb b/spec/unit/entitlements_spec.rb index 96c05c9..99ea54a 100644 --- a/spec/unit/entitlements_spec.rb +++ b/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) } diff --git a/spec/unit/spec_helper.rb b/spec/unit/spec_helper.rb index 0f03937..5c909ef 100644 --- a/spec/unit/spec_helper.rb +++ b/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 diff --git a/vendor/cache/dogstatsd-ruby-5.7.1.gem b/vendor/cache/dogstatsd-ruby-5.7.1.gem new file mode 100644 index 0000000..f377a79 Binary files /dev/null and b/vendor/cache/dogstatsd-ruby-5.7.1.gem differ