Active Support notifications for CSRF warnings

actionpack/CHANGELOG.md

@@ -1,3 +1,14 @@
+*   Active Support notifications for CSRF warnings.
+
+    Switches from direct logging to event-driven logging, allowing others to
+    subscribe to and act on CSRF events:
+
+    - `csrf_token_fallback.action_controller`
+    - `csrf_request_blocked.action_controller`
+    - `csrf_javascript_blocked.action_controller`
+
+    *Jeremy Daer*
+
 *   Modern header-based CSRF protection.
 
     Modern browsers send the `Sec-Fetch-Site` header to indicate the relationship

actionpack/lib/action_controller/log_subscriber.rb

@@ -87,6 +87,30 @@ def unpermitted_parameters(event)
     end
     event_log_level :unpermitted_parameters, :debug
 
+    def csrf_token_fallback(event)
+      return unless ActionController::Base.log_warning_on_csrf_failure
+
+      warn do
+        payload = event[:payload]
+        "Falling back to CSRF token verification for #{payload[:controller]}##{payload[:action]}"
+      end
+    end
+    event_log_level :csrf_token_fallback, :info
+
+    def csrf_request_blocked(event)
+      return unless ActionController::Base.log_warning_on_csrf_failure
+
+      warn { event[:payload][:message] }
+    end
+    event_log_level :csrf_request_blocked, :info
+
+    def csrf_javascript_blocked(event)
+      return unless ActionController::Base.log_warning_on_csrf_failure
+
+      warn { event[:payload][:message] }
+    end
+    event_log_level :csrf_javascript_blocked, :info
+
     def fragment_cache(event)
       return unless ActionController::Base.enable_fragment_cache_logging
 

actionpack/lib/action_controller/metal/request_forgery_protection.rb

@@ -470,7 +470,7 @@ def verify_request_for_forgery_protection # :doc:
         mark_for_same_origin_verification!
 
         if !verified_request?
-          logger.warn unverified_request_warning_message if logger && log_warning_on_csrf_failure
+          instrument_unverified_request
 
           handle_unverified_request
         end
@@ -516,9 +516,7 @@ def unverified_request_warning_message
       # serving an unauthorized cross-origin response.
       def verify_same_origin_request # :doc:
         if marked_for_same_origin_verification? && non_xhr_javascript_response?
-          if logger && log_warning_on_csrf_failure
-            logger.warn CROSS_ORIGIN_JAVASCRIPT_WARNING
-          end
+          instrument_cross_origin_javascript
           raise ActionController::InvalidCrossOriginRequest, CROSS_ORIGIN_JAVASCRIPT_WARNING
         end
       end
@@ -593,11 +591,34 @@ def verified_with_legacy_token?
         when "cross-site"
           origin_trusted?
         else # "none" or missing
-          logger.warn "Falling back to CSRF token check for forgery protection" if logger && log_warning_on_csrf_failure
+          instrument_csrf_token_fallback
           any_authenticity_token_valid?
         end
       end
 
+      def instrument_csrf_token_fallback
+        instrument_csrf_event "csrf_token_fallback.action_controller"
+      end
+
+      def instrument_unverified_request
+        instrument_csrf_event "csrf_request_blocked.action_controller",
+          message: unverified_request_warning_message
+      end
+
+      def instrument_cross_origin_javascript
+        instrument_csrf_event "csrf_javascript_blocked.action_controller",
+          message: CROSS_ORIGIN_JAVASCRIPT_WARNING
+      end
+
+      def instrument_csrf_event(event, message: nil)
+        ActiveSupport::Notifications.instrument event,
+          request: request,
+          controller: self.class.name,
+          action: action_name,
+          sec_fetch_site: sec_fetch_site_value,
+          message: message
+      end
+
       def origin_trusted?
         origin = request.origin
         origin.present? && forgery_protection_trusted_origins.include?(origin)

actionpack/lib/action_controller/structured_event_subscriber.rb

@@ -91,6 +91,26 @@ def unpermitted_parameters(event)
     end
     debug_only :unpermitted_parameters
 
+    def csrf_token_fallback(event)
+      emit_csrf_event "action_controller.csrf_token_fallback", event.payload
+    end
+
+    def csrf_request_blocked(event)
+      emit_csrf_event "action_controller.csrf_request_blocked", event.payload
+    end
+
+    def csrf_javascript_blocked(event)
+      emit_csrf_event "action_controller.csrf_javascript_blocked", event.payload
+    end
+
+    private def emit_csrf_event(name, payload)
+      emit_event name,
+        controller: payload[:controller],
+        action: payload[:action],
+        sec_fetch_site: payload[:sec_fetch_site],
+        message: payload[:message]
+    end
+
     def write_fragment(event)
       fragment_cache(__method__, event)
     end

actionpack/test/controller/request_forgery_protection_test.rb

@@ -536,9 +536,9 @@ def test_should_raise_for_post_with_null_origin
   end
 
   def test_should_block_post_with_origin_checking_and_wrong_origin
-    old_logger = ActionController::Base.logger
     logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
-    ActionController::Base.logger = logger
+    old_logger = ActionController::LogSubscriber.logger
+    ActionController::LogSubscriber.logger = logger
 
     forgery_protection_origin_check do
       initialize_csrf_token
@@ -555,14 +555,14 @@ def test_should_block_post_with_origin_checking_and_wrong_origin
       logger.logged(:warn).last
     )
   ensure
-    ActionController::Base.logger = old_logger
+    ActionController::LogSubscriber.logger = old_logger
   end
 
 
   def test_should_warn_on_missing_csrf_token
-    old_logger = ActionController::Base.logger
     logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
-    ActionController::Base.logger = logger
+    old_logger = ActionController::LogSubscriber.logger
+    ActionController::LogSubscriber.logger = logger
 
     begin
       assert_blocked { post :index }
@@ -571,22 +571,22 @@ def test_should_warn_on_missing_csrf_token
       assert_match(/Falling back to CSRF token/, logger.logged(:warn).first)
       assert_match(/CSRF token authenticity/, logger.logged(:warn).last)
     ensure
-      ActionController::Base.logger = old_logger
+      ActionController::LogSubscriber.logger = old_logger
     end
   end
 
   def test_should_not_warn_if_csrf_logging_disabled
-    old_logger = ActionController::Base.logger
     logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
-    ActionController::Base.logger = logger
+    old_logger = ActionController::LogSubscriber.logger
+    ActionController::LogSubscriber.logger = logger
     ActionController::Base.log_warning_on_csrf_failure = false
 
     begin
       assert_blocked { post :index }
 
       assert_equal 0, logger.logged(:warn).size
     ensure
-      ActionController::Base.logger = old_logger
+      ActionController::LogSubscriber.logger = old_logger
       ActionController::Base.log_warning_on_csrf_failure = true
     end
   end
@@ -613,32 +613,32 @@ def test_should_only_allow_same_origin_js_get_with_xhr_header
   end
 
   def test_should_warn_on_not_same_origin_js
-    old_logger = ActionController::Base.logger
     logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
-    ActionController::Base.logger = logger
+    old_logger = ActionController::LogSubscriber.logger
+    ActionController::LogSubscriber.logger = logger
 
     begin
       assert_cross_origin_blocked { get :same_origin_js }
 
       assert_equal 1, logger.logged(:warn).size
       assert_match(/<script> tag on another site requested protected JavaScript/, logger.logged(:warn).last)
     ensure
-      ActionController::Base.logger = old_logger
+      ActionController::LogSubscriber.logger = old_logger
     end
   end
 
   def test_should_not_warn_if_csrf_logging_disabled_and_not_same_origin_js
-    old_logger = ActionController::Base.logger
     logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
-    ActionController::Base.logger = logger
+    old_logger = ActionController::LogSubscriber.logger
+    ActionController::LogSubscriber.logger = logger
     ActionController::Base.log_warning_on_csrf_failure = false
 
     begin
       assert_cross_origin_blocked { get :same_origin_js }
 
       assert_equal 0, logger.logged(:warn).size
     ensure
-      ActionController::Base.logger = old_logger
+      ActionController::LogSubscriber.logger = old_logger
       ActionController::Base.log_warning_on_csrf_failure = true
     end
   end
@@ -884,7 +884,7 @@ def test_should_allow_all_methods_without_token
 class CustomAuthenticityParamControllerTest < ActionController::TestCase
   def setup
     super
-    @old_logger = ActionController::Base.logger
+    @old_logger = ActionController::LogSubscriber.logger
     @logger = ActiveSupport::LogSubscriber::TestHelper::MockLogger.new
     @token = Base64.urlsafe_encode64(SecureRandom.random_bytes(32))
     @old_request_forgery_protection_token = ActionController::Base.request_forgery_protection_token
@@ -897,7 +897,7 @@ def teardown
   end
 
   def test_should_not_warn_if_form_authenticity_param_matches_form_authenticity_token
-    ActionController::Base.logger = @logger
+    ActionController::LogSubscriber.logger = @logger
     begin
       @controller.stub :valid_authenticity_token?, :true do
         post :index, params: { custom_token_name: "foobar" }
@@ -906,12 +906,12 @@ def test_should_not_warn_if_form_authenticity_param_matches_form_authenticity_to
         assert_match(/Falling back to CSRF token/, @logger.logged(:warn).first)
       end
     ensure
-      ActionController::Base.logger = @old_logger
+      ActionController::LogSubscriber.logger = @old_logger
     end
   end
 
   def test_should_warn_if_form_authenticity_param_does_not_match_form_authenticity_token
-    ActionController::Base.logger = @logger
+    ActionController::LogSubscriber.logger = @logger
 
     begin
       post :index, params: { custom_token_name: "bazqux" }
@@ -920,7 +920,7 @@ def test_should_warn_if_form_authenticity_param_does_not_match_form_authenticity
       assert_match(/Falling back to CSRF token/, @logger.logged(:warn).first)
       assert_match(/CSRF token authenticity/, @logger.logged(:warn).last)
     ensure
-      ActionController::Base.logger = @old_logger
+      ActionController::LogSubscriber.logger = @old_logger
     end
   end
 end