diff --git a/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml b/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml new file mode 100644 index 0000000000000000000000000000000000000000..461b1d35788275c000144873fd6b304552fd2f73 --- /dev/null +++ b/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml @@ -0,0 +1,10 @@ +--- +name: postfilter_logging +description: Log performance of postfiltering +feature_issue_url: https://gitlab.com/gitlab-org/gitlab/-/work_items/581753 +introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/216229 +rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/583834 +milestone: '18.8' +group: group::authorization +type: gitlab_com_derisk +default_enabled: false diff --git a/lib/api/helpers/authz/postfiltering_helpers.rb b/lib/api/helpers/authz/postfiltering_helpers.rb new file mode 100644 index 0000000000000000000000000000000000000000..6b4eef7947fab856c1c53a06e7d3c2b4d5df6fa2 --- /dev/null +++ b/lib/api/helpers/authz/postfiltering_helpers.rb @@ -0,0 +1,38 @@ +# frozen_string_literal: true + +module API + module Helpers + module Authz + module PostfilteringHelpers + def filter_with_logging(collection:, filter_proc:, resource_type:) + if current_user.present? && Feature.enabled?(:postfilter_logging, current_user) + filtered = nil + postfilter_duration = Benchmark.realtime do + filtered = filter_proc.call + end + + Gitlab::AppLogger.info( + message: "Post-filtering - #{resource_type}", + redacted_count: collection.to_a.size - filtered.size, + postfiltering_duration: postfilter_duration, + user_id: current_user.id + ) + + filtered + else + filter_proc.call + end + rescue StandardError => e + Gitlab::AppLogger.warn( + message: "Post-filtering failed - #{resource_type}", + error_class: e.class.name, + error_message: e.message, + user_id: current_user&.id + ) + + raise e + end + end + end + end +end diff --git a/lib/api/issues.rb b/lib/api/issues.rb index 712d484eaa566b1550d40b811263a5a1eef94551..86bf52b1d06fa393f04927df999701e0498c3c3b 100644 --- a/lib/api/issues.rb +++ b/lib/api/issues.rb @@ -12,6 +12,7 @@ class Issues < ::API::Base allow_mcp_access_create helpers Helpers::IssuesHelpers + helpers Helpers::Authz::PostfilteringHelpers helpers SpammableActions::CaptchaCheck::RestApiActionsSupport before { authenticate_non_get! } @@ -143,7 +144,12 @@ class Issues < ::API::Base authenticate! unless params[:scope] == 'all' validate_search_rate_limit! if declared_params[:search].present? issues = paginate(find_issues) - issues = Ability.issues_readable_by_user(issues, current_user) + + issues = filter_with_logging( + collection: issues, + filter_proc: -> { Ability.issues_readable_by_user(issues, current_user) }, + resource_type: 'api/issues' + ) options = { with: Entities::Issue, diff --git a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..76392e8e6378ad3697bd05f98ae4323e50122227 --- /dev/null +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -0,0 +1,73 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe API::Helpers::Authz::PostfilteringHelpers, feature_category: :permissions do + let(:helper) { Class.new.include(described_class).new } + + let(:collection) { [1, 2, 3, 4, 5, 6] } + let(:filter_proc) { -> { collection.select(&:even?) } } + let_it_be(:current_user) { create(:user) } + + before do + allow(helper).to receive(:current_user).and_return(current_user) + end + + describe '#filter_with_logging' do + subject(:filter_with_logging) do + helper.filter_with_logging(collection: collection, filter_proc: filter_proc, resource_type: 'api/evens') + end + + before do + stub_feature_flags(postfilter_logging: true) + end + + it 'logs and calls the proc' do + expect(Gitlab::AppLogger).to receive(:info).with( + message: "Post-filtering - api/evens", + redacted_count: 3, + postfiltering_duration: an_instance_of(Float), + user_id: current_user.id + ).and_call_original + + expect(filter_with_logging).to match_array([2, 4, 6]) + end + + context 'when exception is raised during logging' do + it 'logs an error and bubbles the exception' do + allow(Gitlab::AppLogger).to receive(:info).and_raise(StandardError.new('oopsy!')) + + expect(Gitlab::AppLogger).to receive(:warn).with( + message: "Post-filtering failed - api/evens", + error_class: 'StandardError', + error_message: 'oopsy!', + user_id: current_user.id + ).and_call_original + + expect { filter_with_logging }.to raise_error(StandardError, 'oopsy!') + end + end + + context 'when current_user is nil' do + let(:current_user) { nil } + + it 'calls the proc without logging' do + expect(Gitlab::AppLogger).not_to receive(:info) + + expect(filter_with_logging).to match_array([2, 4, 6]) + end + end + + context 'when postfilter_logging feature is disabled' do + before do + stub_feature_flags(postfilter_logging: false) + end + + it 'calls the proc without logging' do + expect(Gitlab::AppLogger).not_to receive(:info) + + expect(filter_with_logging).to match_array([2, 4, 6]) + end + end + end +end diff --git a/spec/requests/api/issues/issues_spec.rb b/spec/requests/api/issues/issues_spec.rb index a2d61744d93b3c643c88c561f419338581124b90..b36f758ae944068fb87866c9f3b2f628f161aa1b 100644 --- a/spec/requests/api/issues/issues_spec.rb +++ b/spec/requests/api/issues/issues_spec.rb @@ -1159,6 +1159,26 @@ expect_paginated_array_response(unrestricted_issue.id) end + + context 'when postfiltering_logging is enabled' do + before do + stub_feature_flags(postfilter_logging: true) + end + + it 'logs postfiltering information' do + allow(Gitlab::AppLogger).to receive(:info).and_call_original + expect(Gitlab::AppLogger).to receive(:info).with( + message: "Post-filtering - api/issues", + redacted_count: 1, + postfiltering_duration: be_a(Float), + user_id: current_user.id + ).at_least(:once).and_call_original + + get api('/issues', current_user), params: { scope: 'assigned_to_me' } + + expect_paginated_array_response(unrestricted_issue.id) + end + end end end end