From aa68a53c1129ab372662cc50a224ad9ff4c673ad Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Thu, 11 Dec 2025 15:39:53 -0800 Subject: [PATCH 1/7] Add postfiltering logging to api/issues Lets collect postfiltering performance and prefiltering accuracy data to help guide us where to invest in our authorization efforts. * introduce postfilter_logging flag * introduce PostfilteringHelpers part of: https://gitlab.com/gitlab-org/gitlab/-/work_items/581753 --- .../gitlab_com_derisk/postfilter_logging.yml | 10 ++++ ee/spec/requests/api/issues_spec.rb | 17 +++++++ .../helpers/authz/postfiltering_helpers.rb | 29 ++++++++++++ lib/api/issues.rb | 8 +++- .../authz/postfiltering_helpers_spec.rb | 46 +++++++++++++++++++ 5 files changed, 109 insertions(+), 1 deletion(-) create mode 100644 config/feature_flags/gitlab_com_derisk/postfilter_logging.yml create mode 100644 lib/api/helpers/authz/postfiltering_helpers.rb create mode 100644 spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb 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 00000000000000..19c851e87ff0a2 --- /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: +rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/583834 +milestone: '18.7' +group: group::authorization +type: gitlab_com_derisk +default_enabled: false diff --git a/ee/spec/requests/api/issues_spec.rb b/ee/spec/requests/api/issues_spec.rb index 8aeb5bdf9842d5..2481d69a171316 100644 --- a/ee/spec/requests/api/issues_spec.rb +++ b/ee/spec/requests/api/issues_spec.rb @@ -334,6 +334,23 @@ expect_paginated_array_response([unrestricted_issue.id]) end + + context 'when postfiltering_logging is enabled' do + it 'logs postfiltering information' do + expect(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 + ) + + get api('/issues', current_user), params: { scope: 'all' } + + expect_paginated_array_response([unrestricted_issue.id]) + end + end end context "when IP is allowed" do diff --git a/lib/api/helpers/authz/postfiltering_helpers.rb b/lib/api/helpers/authz/postfiltering_helpers.rb new file mode 100644 index 00000000000000..f579751a9ef383 --- /dev/null +++ b/lib/api/helpers/authz/postfiltering_helpers.rb @@ -0,0 +1,29 @@ +# frozen_string_literal: true + +module API + module Helpers + module Authz + module PostfilteringHelpers + def filter_with_logging(count:, filter_proc:, resource_type:) + if 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: count - filtered.count, + postfiltering_duration: postfilter_duration, + user_id: current_user.id + ) + + filtered + else + filter_proc.call + end + end + end + end + end +end diff --git a/lib/api/issues.rb b/lib/api/issues.rb index 712d484eaa566b..a2e5a2468df473 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( + count: issues.count, + 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 00000000000000..42804aba507ef2 --- /dev/null +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -0,0 +1,46 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe API::Helpers::Authz::PostfilteringHelpers, feature_category: :permissions do + subject(:helper) { Class.new.include(described_class).new } + + let(:collection) { [1, 2, 3, 4, 5, 6] } + let(:filter_proc) { -> { collection.select(&:even?) } } + let(: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(count: 6, filter_proc: filter_proc, resource_type: 'api/evens') + end + + context 'when postfilter_logging feature is enabled' do + it 'logs and calls the proc' do + expect(Gitlab::AppLogger).to receive(:info).with( + message: "Post-filtering - api/evens", + redacted_count: 3, + postfiltering_duration: be_a(Float), + user_id: current_user.id + ) + + expect(filter_with_logging).to eq([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' do + expect(Gitlab::AppLogger).not_to receive(:info) + + expect(filter_with_logging).to eq([2, 4, 6]) + end + end + end +end -- GitLab From d62c71cfb01a630faadd63ae41a042605cbd1199 Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Thu, 11 Dec 2025 18:16:30 -0800 Subject: [PATCH 2/7] Safety third * move count (size really) to the helper method as it was causing some failures in specs. I think this was caused from executing the query with count and then the query exploding. I guess size doesn't execute the query and just references the objects in memory. -----* * add current_user.nil check * rescue and log errors * backfill more specs * move issues_spec to ce --- ee/spec/requests/api/issues_spec.rb | 17 ------ .../helpers/authz/postfiltering_helpers.rb | 15 ++++- lib/api/issues.rb | 2 +- .../authz/postfiltering_helpers_spec.rb | 55 +++++++++++++++---- spec/requests/api/issues/issues_spec.rb | 19 +++++++ 5 files changed, 75 insertions(+), 33 deletions(-) diff --git a/ee/spec/requests/api/issues_spec.rb b/ee/spec/requests/api/issues_spec.rb index 2481d69a171316..8aeb5bdf9842d5 100644 --- a/ee/spec/requests/api/issues_spec.rb +++ b/ee/spec/requests/api/issues_spec.rb @@ -334,23 +334,6 @@ expect_paginated_array_response([unrestricted_issue.id]) end - - context 'when postfiltering_logging is enabled' do - it 'logs postfiltering information' do - expect(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 - ) - - get api('/issues', current_user), params: { scope: 'all' } - - expect_paginated_array_response([unrestricted_issue.id]) - end - end end context "when IP is allowed" do diff --git a/lib/api/helpers/authz/postfiltering_helpers.rb b/lib/api/helpers/authz/postfiltering_helpers.rb index f579751a9ef383..86cfd71684a18b 100644 --- a/lib/api/helpers/authz/postfiltering_helpers.rb +++ b/lib/api/helpers/authz/postfiltering_helpers.rb @@ -4,8 +4,8 @@ module API module Helpers module Authz module PostfilteringHelpers - def filter_with_logging(count:, filter_proc:, resource_type:) - if Feature.enabled?(:postfilter_logging, current_user) + 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 @@ -13,7 +13,7 @@ def filter_with_logging(count:, filter_proc:, resource_type:) Gitlab::AppLogger.info( message: "Post-filtering - #{resource_type}", - redacted_count: count - filtered.count, + redacted_count: collection.size - filtered.count, # using size here to avoid querying. postfiltering_duration: postfilter_duration, user_id: current_user.id ) @@ -22,6 +22,15 @@ def filter_with_logging(count:, filter_proc:, resource_type:) 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 + ) + + filter_proc.call end end end diff --git a/lib/api/issues.rb b/lib/api/issues.rb index a2e5a2468df473..86bf52b1d06fa3 100644 --- a/lib/api/issues.rb +++ b/lib/api/issues.rb @@ -146,7 +146,7 @@ class Issues < ::API::Base issues = paginate(find_issues) issues = filter_with_logging( - count: issues.count, + collection: issues, filter_proc: -> { Ability.issues_readable_by_user(issues, current_user) }, resource_type: 'api/issues' ) diff --git a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb index 42804aba507ef2..e3072ff56f2490 100644 --- a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -15,19 +15,50 @@ describe '#filter_with_logging' do subject(:filter_with_logging) do - helper.filter_with_logging(count: 6, filter_proc: filter_proc, resource_type: 'api/evens') + helper.filter_with_logging(collection: collection, filter_proc: filter_proc, resource_type: 'api/evens') end context 'when postfilter_logging feature is enabled' do - it 'logs and calls the proc' do - expect(Gitlab::AppLogger).to receive(:info).with( - message: "Post-filtering - api/evens", - redacted_count: 3, - postfiltering_duration: be_a(Float), - user_id: current_user.id - ) - - expect(filter_with_logging).to eq([2, 4, 6]) + before do + stub_feature_flags(postfilter_logging: true) + 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 current_user exists' do + it 'logs and calls the proc' do + expect(Gitlab::AppLogger).to receive(:info).with( + message: "Post-filtering - api/evens", + redacted_count: 3, + postfiltering_duration: be_a(Float), + user_id: current_user.id + ) + + expect(filter_with_logging).to match_array([2, 4, 6]) + end + + context 'when exception is raised' do + it 'logs an error and executes the filter proc' 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 + ) + + expect(filter_with_logging).to match_array([2, 4, 6]) + end + end end end @@ -36,10 +67,10 @@ stub_feature_flags(postfilter_logging: false) end - it 'calls the proc' do + it 'calls the proc without logging' do expect(Gitlab::AppLogger).not_to receive(:info) - expect(filter_with_logging).to eq([2, 4, 6]) + expect(filter_with_logging).to match_array([2, 4, 6]) end end end diff --git a/spec/requests/api/issues/issues_spec.rb b/spec/requests/api/issues/issues_spec.rb index a2d61744d93b3c..6ad336352d8800 100644 --- a/spec/requests/api/issues/issues_spec.rb +++ b/spec/requests/api/issues/issues_spec.rb @@ -1159,6 +1159,25 @@ 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 + 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', test_me: true } + + expect_paginated_array_response(unrestricted_issue.id) + end + end end end end -- GitLab From cc9180cd4b6031a1d6da8f0bca7923a77d5bed79 Mon Sep 17 00:00:00 2001 From: Jay Date: Thu, 11 Dec 2025 18:20:36 -0800 Subject: [PATCH 3/7] Apply 1 suggestion(s) to 1 file(s) Co-authored-by: DANGER_GITLAB_API_TOKEN --- config/feature_flags/gitlab_com_derisk/postfilter_logging.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml b/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml index 19c851e87ff0a2..9ef33c1abbdf74 100644 --- a/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml +++ b/config/feature_flags/gitlab_com_derisk/postfilter_logging.yml @@ -2,7 +2,7 @@ name: postfilter_logging description: Log performance of postfiltering feature_issue_url: https://gitlab.com/gitlab-org/gitlab/-/work_items/581753 -introduced_by_url: +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.7' group: group::authorization -- GitLab From e180f3241dc77a49c276c830eb48510dbd588f07 Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Thu, 11 Dec 2025 18:22:30 -0800 Subject: [PATCH 4/7] Woops - remove testing params --- spec/requests/api/issues/issues_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/requests/api/issues/issues_spec.rb b/spec/requests/api/issues/issues_spec.rb index 6ad336352d8800..ccf865a4add09e 100644 --- a/spec/requests/api/issues/issues_spec.rb +++ b/spec/requests/api/issues/issues_spec.rb @@ -1173,7 +1173,7 @@ user_id: current_user.id ).at_least(:once).and_call_original - get api('/issues', current_user), params: { scope: 'assigned_to_me', test_me: true } + get api('/issues', current_user), params: { scope: 'assigned_to_me' } expect_paginated_array_response(unrestricted_issue.id) end -- GitLab From 95926583e2e0360f7da00780c21201282caefc4e Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Fri, 12 Dec 2025 16:18:21 -0800 Subject: [PATCH 5/7] Review feedback from Jason * execute query before calling size * use size for both collections ;) * re-raise exception instead of re-executing --- lib/api/helpers/authz/postfiltering_helpers.rb | 4 ++-- spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/api/helpers/authz/postfiltering_helpers.rb b/lib/api/helpers/authz/postfiltering_helpers.rb index 86cfd71684a18b..6b4eef7947fab8 100644 --- a/lib/api/helpers/authz/postfiltering_helpers.rb +++ b/lib/api/helpers/authz/postfiltering_helpers.rb @@ -13,7 +13,7 @@ def filter_with_logging(collection:, filter_proc:, resource_type:) Gitlab::AppLogger.info( message: "Post-filtering - #{resource_type}", - redacted_count: collection.size - filtered.count, # using size here to avoid querying. + redacted_count: collection.to_a.size - filtered.size, postfiltering_duration: postfilter_duration, user_id: current_user.id ) @@ -30,7 +30,7 @@ def filter_with_logging(collection:, filter_proc:, resource_type:) user_id: current_user&.id ) - filter_proc.call + raise e end end end diff --git a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb index e3072ff56f2490..2a3b188910e048 100644 --- a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -45,7 +45,7 @@ expect(filter_with_logging).to match_array([2, 4, 6]) end - context 'when exception is raised' do + context 'when exception is raised during logging' do it 'logs an error and executes the filter proc' do allow(Gitlab::AppLogger).to receive(:info).and_raise(StandardError.new('oopsy!')) @@ -56,7 +56,7 @@ user_id: current_user.id ) - expect(filter_with_logging).to match_array([2, 4, 6]) + expect { filter_with_logging }.to raise_error(StandardError, 'oopsy!') end end end -- GitLab From 37e258ebe5a31030625992e2751ab03bc486a1bb Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Mon, 15 Dec 2025 10:17:29 -0800 Subject: [PATCH 6/7] Review feedback * THOU SPEC SHALL PASS --- spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb | 2 +- spec/requests/api/issues/issues_spec.rb | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb index 2a3b188910e048..4bd8b624e4e5f4 100644 --- a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -46,7 +46,7 @@ end context 'when exception is raised during logging' do - it 'logs an error and executes the filter proc' 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( diff --git a/spec/requests/api/issues/issues_spec.rb b/spec/requests/api/issues/issues_spec.rb index ccf865a4add09e..b36f758ae94406 100644 --- a/spec/requests/api/issues/issues_spec.rb +++ b/spec/requests/api/issues/issues_spec.rb @@ -1166,6 +1166,7 @@ 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, -- GitLab From dd6ba0c0f122ff733c911796748f720f518cf245 Mon Sep 17 00:00:00 2001 From: Jay Swain Date: Mon, 15 Dec 2025 12:29:38 -0800 Subject: [PATCH 7/7] Undercoverage problems I'm now sure why I'm getting an undercoverage error here. Adding .and_call_original and crossing my fingers. --- spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb index 4bd8b624e4e5f4..5f015ac05057e0 100644 --- a/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb +++ b/spec/lib/api/helpers/authz/postfiltering_helpers_spec.rb @@ -40,7 +40,7 @@ redacted_count: 3, postfiltering_duration: be_a(Float), user_id: current_user.id - ) + ).and_call_original expect(filter_with_logging).to match_array([2, 4, 6]) end @@ -54,7 +54,7 @@ error_class: 'StandardError', error_message: 'oopsy!', user_id: current_user.id - ) + ).and_call_original expect { filter_with_logging }.to raise_error(StandardError, 'oopsy!') end -- GitLab