Add instrumentation for Rails apps

CHANGELOG.md

@@ -1,5 +1,9 @@
 ## master
 
+- Added ActiveSupport-based instrumentation. ([@palkan][])
+
+  See [PR#4](https://github.com/palkan/action_policy/pull/4)
+
 - Allow passing authorization context explicitly. ([@palkan][])
 
   Closes [#3](https://github.com/palkan/action_policy/issues/3).

docs/instrumentation.md

@@ -1,5 +1,73 @@
 # Instrumentation
 
-🛠 **WORK IN PROGRESS**
+Action Policy integrates with [Rails instrumentation system](https://guides.rubyonrails.org/active_support_instrumentation.html), `ActiveSupport::Notifications`.
 
-See [the PR](https://github.com/palkan/action_policy/pull/4).
+## Events
+
+### `action_policy.apply_rule`
+
+This event is triggered every time a policy rule is applied:
+- when `authorize!` is called
+- when `allowed_to?` is called within the policy or the [behaviour](behaviour)
+- when `apply_rule` is called explicitly (i.e. `SomePolicy.new(record, context).apply_rule(record)`).
+
+The event contains the following information:
+- `:policy` – policy class name
+- `:rule` – applied rule (String)
+- `:value` – the result of the rule application (true of false)
+- `:cached` – whether we hit the [cache](caching)\*.
+
+\* This parameter tracks only the cache store usage, not memoization.
+
+You can use this event to track your policy cache usage and also detect _slow_ checks.
+
+Here is an example code for sending policy stats to [Librato](https://librato.com/)
+using [`librato-rack`](https://github.com/librato/librato-rack):
+
+```ruby
+ActiveSupport::Notifications.subscribe("action_policy.apply_rule") do |event, started, finished, _, data|
+  # Track hit and miss events separately (to display two measurements)
+  measurement = "#{event}.#{(data[:cached] ? "hit" : "miss")}"
+  # show ms times
+  timing = ((finished - started) * 1000).to_i
+  Librato.tracker.check_worker
+  Librato.timing measurement, timing, percentile: [95, 99]
+end
+```
+
+### `action_policy.authorize`
+
+This event is identical to `action_policy.apply_rule` with the one difference:
+**it's only triggered when `authorize!` method is called**.
+
+The motivation behind having a separate event for this method is to monitor the number of failed
+authorizations: the high number of failed authorizations usually means that we do not take
+into account authorization rules in the application UI (e.g., we show a "Delete" button to the user not
+permitted to do that).
+
+The `action_policy.apply_rule` might have a large number of failures, 'cause it also tracks the usage of non-raising applications (i.e. `allowed_to?`).
+
+## Turn off instrumentation
+
+Instrumentation is enabled by default. To turn it off add to your configuration:
+
+```ruby
+config.action_policy.instrumentation_enabled = false
+```
+
+**NOTE:** changing this setting after the application has been initialized doesn't take any effect.
+
+## Non-Rails usage
+
+If you don't use Rails itself but have `ActiveSupport::Notifications` available in your application,
+you can use the instrumentation feature with some additional configuration:
+
+```ruby
+# Enable `apply_rule` event by extending the base policy class
+require "action_policy/rails/policy/instrumentation"
+ActionPolicy::Base.include ActionPolicy::Policy::Rails::Instrumentation
+
+# Enabled `authorize` event by extending the authorizer class
+require "action_policy/rails/authorizer"
+ActionPolicy::Authorizer.singleton_class.prepend ActionPolicy::Rails::Authorizer
+```

lib/action_policy/authorizer.rb

@@ -20,10 +20,14 @@ module Authorizer
     class << self
       # Performs authorization, raises an exception when check failed.
       def call(policy, rule)
-        policy.apply(rule) ||
+        authorize(policy, rule) ||
           raise(::ActionPolicy::Unauthorized.new(policy, rule))
       end
 
+      def authorize(policy, rule)
+        policy.apply(rule)
+      end
+
       # Applies scope to the target
       def scopify(target, policy, **options)
         policy.apply_scope(target, **options)

lib/action_policy/policy/cache.rb

@@ -42,7 +42,10 @@ def apply_with_cache(rule)
 
         ActionPolicy.cache_store.then do |store|
           @result = store.read(key)
-          next result.value unless result.nil?
+          unless result.nil?
+            result.cached!
+            next result.value
+          end
           yield
           store.write(key, result, options)
           result.value

lib/action_policy/policy/core.rb

@@ -65,7 +65,7 @@ def identifier
 
       attr_reader :record, :result
 
-      def initialize(record = nil)
+      def initialize(record = nil, **_opts)
         @record = record
       end
 

lib/action_policy/policy/execution_result.rb

@@ -27,6 +27,14 @@ def fail?
         @value == false
       end
 
+      def cached!
+        @cached = true
+      end
+
+      def cached?
+        @cached == true
+      end
+
       def inspect
         "<#{policy}##{rule}: #{@value}>"
       end

lib/action_policy/rails/authorizer.rb

@@ -0,0 +1,20 @@
+# frozen_string_literal: true
+
+module ActionPolicy # :nodoc:
+  module Rails
+    # Add instrumentation for `authorize!` method
+    module Authorizer
+      EVENT_NAME = "action_policy.authorize"
+
+      def authorize(policy, rule)
+        event = {policy: policy.class.name, rule: rule.to_s}
+        ActiveSupport::Notifications.instrument(EVENT_NAME, event) do
+          res = super
+          event[:cached] = policy.result.cached?
+          event[:value] = policy.result.value
+          res
+        end
+      end
+    end
+  end
+end

lib/action_policy/rails/policy/instrumentation.rb

@@ -0,0 +1,24 @@
+# frozen_string_literal: true
+
+module ActionPolicy # :nodoc:
+  module Policy
+    module Rails
+      # Add ActiveSupport::Notifications support.
+      #
+      # Fires `action_policy.apply_rule` event on every `#apply` call.
+      module Instrumentation
+        EVENT_NAME = "action_policy.apply_rule"
+
+        def apply(rule)
+          event = {policy: self.class.name, rule: rule.to_s}
+          ActiveSupport::Notifications.instrument(EVENT_NAME, event) do
+            res = super
+            event[:cached] = result.cached?
+            event[:value] = result.value
+            res
+          end
+        end
+      end
+    end
+  end
+end

lib/action_policy/railtie.rb

@@ -30,6 +30,10 @@ class << self
         # Enabled only in production by default.
         attr_accessor :namespace_cache_enabled
 
+        # Define whether to include instrumentation functionality.
+        # Enabled by default.
+        attr_accessor :instrumentation_enabled
+
         def cache_store=(store)
           # Handle both:
           #   store = :memory
@@ -46,13 +50,14 @@ def cache_store=(store)
       self.controller_authorize_current_user = true
       self.auto_inject_into_channel = true
       self.channel_authorize_current_user = true
-      self.namespace_cache_enabled = Rails.env.production?
+      self.namespace_cache_enabled = ::Rails.env.production?
+      self.instrumentation_enabled = true
     end
 
     config.action_policy = Config
 
     initializer "action_policy.clear_per_thread_cache" do |app|
-      if Rails::VERSION::MAJOR >= 5
+      if ::Rails::VERSION::MAJOR >= 5
         app.executor.to_run { ActionPolicy::PerThreadCache.clear_all }
         app.executor.to_complete { ActionPolicy::PerThreadCache.clear_all }
       else
@@ -61,28 +66,38 @@ def cache_store=(store)
       end
     end
 
+    config.after_initialize do
+      next unless ::Rails.application.config.action_policy.instrumentation_enabled
+
+      require "action_policy/rails/policy/instrumentation"
+      require "action_policy/rails/authorizer"
+
+      ActionPolicy::Base.prepend ActionPolicy::Policy::Rails::Instrumentation
+      ActionPolicy::Authorizer.singleton_class.prepend ActionPolicy::Rails::Authorizer
+    end
+
     config.to_prepare do |_app|
       ActionPolicy::LookupChain.namespace_cache_enabled =
-        Rails.application.config.action_policy.namespace_cache_enabled
+        ::Rails.application.config.action_policy.namespace_cache_enabled
 
       ActiveSupport.on_load(:action_controller) do
         require "action_policy/rails/scope_matchers/action_controller_params"
 
-        next unless Rails.application.config.action_policy.auto_inject_into_controller
+        next unless ::Rails.application.config.action_policy.auto_inject_into_controller
 
         ActionController::Base.include ActionPolicy::Controller
 
-        next unless Rails.application.config.action_policy.controller_authorize_current_user
+        next unless ::Rails.application.config.action_policy.controller_authorize_current_user
 
         ActionController::Base.authorize :user, through: :current_user
       end
 
       ActiveSupport.on_load(:action_cable) do
-        next unless Rails.application.config.action_policy.auto_inject_into_channel
+        next unless ::Rails.application.config.action_policy.auto_inject_into_channel
 
         ActionCable::Channel::Base.include ActionPolicy::Channel
 
-        next unless Rails.application.config.action_policy.channel_authorize_current_user
+        next unless ::Rails.application.config.action_policy.channel_authorize_current_user
 
         ActionCable::Channel::Base.authorize :user, through: :current_user
       end

test/action_policy/policy/cache_test.rb

@@ -2,29 +2,7 @@
 
 require "test_helper"
 
-class InMemoryCache
-  attr_accessor :store
-
-  def initialize
-    self.store = {}
-  end
-
-  def read(key)
-    deserialize(store[key]) if store.key?(key)
-  end
-
-  def write(key, val, _options)
-    store[key] = serialize(val)
-  end
-
-  def serialize(val)
-    Marshal.dump(val)
-  end
-
-  def deserialize(val)
-    Marshal.load(val)
-  end
-end
+require "stubs/in_memory_cache"
 
 class TestCache < Minitest::Test
   class TestPolicy