Merge branch 'sh-log-token-failure-data' into 'master'

Add more log fields in 401 Unauthorized requests

See merge request https://gitlab.com/gitlab-org/gitlab/-/merge_requests/157277



Merged-by: Alex Pooley <apooley@gitlab.com>
Approved-by: Tarun Vellishetty <tvellishetty@gitlab.com>
Approved-by: Shreyas Agarwal <sagarwal@gitlab.com>
Approved-by: Alex Pooley <apooley@gitlab.com>
Approved-by: Imre Farkas <ifarkas@gitlab.com>
Reviewed-by: Alex Pooley <apooley@gitlab.com>
Reviewed-by: Shreyas Agarwal <sagarwal@gitlab.com>
Co-authored-by: smriti <sgarg@gitlab.com>
Co-authored-by: Stan Hu <stanhu@gmail.com>

app/channels/application_cable/channel.rb

@@ -9,7 +9,7 @@ class Channel < ActionCable::Channel::Base
     def validate_token_scope
       validate_and_save_access_token!(scopes: [:api, :read_api])
-    rescue Gitlab::Auth::InsufficientScopeError
+    rescue Gitlab::Auth::AuthenticationError
       reject
     end

app/channels/application_cable/connection.rb

@@ -11,7 +11,7 @@ class Connection < ActionCable::Connection::Base
     def connect
       self.current_user = find_user_from_bearer_token || find_user_from_session_store
-    rescue Gitlab::Auth::UnauthorizedError
+    rescue Gitlab::Auth::AuthenticationError
       reject_unauthorized_connection
     end

app/graphql/mutations/admin/sidekiq_queues/delete_jobs.rb

@@ -8,7 +8,7 @@ class DeleteJobs < BaseMutation
         ADMIN_MESSAGE = 'You must be an admin to use this mutation'
-        ::Gitlab::ApplicationContext.known_keys.each do |key|
+        ::Gitlab::ApplicationContext.allowed_job_keys.each do |key|
           argument key,
                    GraphQL::Types::String,
                    required: false,

lib/gitlab/application_context.rb

@@ -26,10 +26,18 @@ class ApplicationContext
       :artifacts_dependencies_size,
       :artifacts_dependencies_count,
       :root_caller_id,
-      :merge_action_status
+      :merge_action_status,
+      :auth_fail_reason,
+      :auth_fail_token_id
     ].freeze
     private_constant :KNOWN_KEYS
+    WEB_ONLY_KEYS = [
+      :auth_fail_reason,
+      :auth_fail_token_id
+    ].freeze
+    private_constant :WEB_ONLY_KEYS
+
     APPLICATION_ATTRIBUTES = [
       Attribute.new(:project, Project),
       Attribute.new(:namespace, Namespace),
@@ -45,7 +53,9 @@ class ApplicationContext
       Attribute.new(:artifacts_dependencies_size, Integer),
       Attribute.new(:artifacts_dependencies_count, Integer),
       Attribute.new(:root_caller_id, String),
-      Attribute.new(:merge_action_status, String)
+      Attribute.new(:merge_action_status, String),
+      Attribute.new(:auth_fail_reason, String),
+      Attribute.new(:auth_fail_token_id, String)
     ].freeze
     private_constant :APPLICATION_ATTRIBUTES
@@ -53,6 +63,12 @@ def self.known_keys
       KNOWN_KEYS
     end
+    # Sidekiq jobs may be deleted by matching keys in ApplicationContext.
+    # Filter out keys that aren't available in Sidekiq jobs.
+    def self.allowed_job_keys
+      known_keys - WEB_ONLY_KEYS
+    end
+
     def self.application_attributes
       APPLICATION_ATTRIBUTES
     end
@@ -106,6 +122,8 @@ def to_lazy_hash
         assign_hash_if_value(hash, :artifacts_dependencies_size)
         assign_hash_if_value(hash, :artifacts_dependencies_count)
         assign_hash_if_value(hash, :merge_action_status)
+        assign_hash_if_value(hash, :auth_fail_reason)
+        assign_hash_if_value(hash, :auth_fail_token_id)
         hash[:user] = -> { username } if include_user?
         hash[:user_id] = -> { user_id } if include_user?

lib/gitlab/auth/auth_finders.rb

@@ -193,7 +193,7 @@ def find_runner_from_token
         ::Ci::Runner.find_by_token(token) || raise(UnauthorizedError)
       end
-      def validate_and_save_access_token!(scopes: [])
+      def validate_and_save_access_token!(scopes: [], save_auth_context: true)
         # return early if we've already authenticated via a job token
         return if @current_authenticated_job.present? # rubocop:disable Gitlab/ModuleWithInstanceVariables
@@ -204,14 +204,18 @@ def validate_and_save_access_token!(scopes: [])
         case AccessTokenValidationService.new(access_token, request: request).validate(scopes: scopes)
         when AccessTokenValidationService::INSUFFICIENT_SCOPE
+          save_auth_failure_in_application_context(access_token, :insufficient_scope) if save_auth_context
           raise InsufficientScopeError, scopes
         when AccessTokenValidationService::EXPIRED
+          save_auth_failure_in_application_context(access_token, :token_expired) if save_auth_context
           raise ExpiredError
         when AccessTokenValidationService::REVOKED
+          save_auth_failure_in_application_context(access_token, :token_revoked) if save_auth_context
           revoke_token_family(access_token)
           raise RevokedError
         when AccessTokenValidationService::IMPERSONATION_DISABLED
+          save_auth_failure_in_application_context(access_token, :impersonation_disabled) if save_auth_context
           raise ImpersonationDisabled
         end
@@ -230,6 +234,12 @@ def save_current_token_in_env
         request.env[API_TOKEN_ENV] = { token_id: access_token.id, token_type: access_token.class.to_s }
       end
+      def save_auth_failure_in_application_context(access_token, cause)
+        Gitlab::ApplicationContext.push(
+          auth_fail_reason: cause.to_s,
+          auth_fail_token_id: "#{access_token.class}/#{access_token.id}")
+      end
+
       def find_user_from_job_bearer_token
         return unless route_authentication_setting[:job_token_allowed]

lib/gitlab/auth/request_authenticator.rb

@@ -70,7 +70,9 @@ def find_user_from_personal_access_token_for_api_or_git
       end
       def valid_access_token?(scopes: [])
-        validate_and_save_access_token!(scopes: scopes)
+        # We may just be checking whether the user has :admin_mode access, so
+        # don't construe an auth failure as a real failure.
+        validate_and_save_access_token!(scopes: scopes, save_auth_context: false)
         true
       rescue Gitlab::Auth::AuthenticationError

lib/gitlab/sidekiq_queue.rb

@@ -8,7 +8,7 @@ class SidekiqQueue
     InvalidQueueError = Class.new(StandardError)
     WORKER_KEY = 'worker_class'
-    ALLOWED_KEYS = Gitlab::ApplicationContext.known_keys.map(&:to_s) + [WORKER_KEY]
+    ALLOWED_KEYS = Gitlab::ApplicationContext.allowed_job_keys.map(&:to_s) + [WORKER_KEY]
     attr_reader :queue_name

spec/channels/application_cable/connection_spec.rb

@@ -46,12 +46,47 @@
   context 'when bearer header is provided' do
     context 'when it is a personal_access_token' do
       let(:user_pat) { create(:personal_access_token) }
+      let(:app_context) { Gitlab::ApplicationContext.current }
+      let_it_be(:expired_token) { create(:personal_access_token, :expired, scopes: %w[read_api]) }
+      let_it_be(:revoked_token) { create(:personal_access_token, :revoked, scopes: %w[read_api]) }
       it 'finds user by PAT' do
         connect(ActionCable.server.config.mount_path, headers: { Authorization: "Bearer #{user_pat.token}" })
         expect(connection.current_user).to eq(user_pat.user)
       end
+
+      context 'when an expired personal_access_token' do
+        let_it_be(:user_pat) { expired_token }
+
+        it 'sets the current_user as `nil`, and rejects the connection' do
+          expect do
+            connect(ActionCable.server.config.mount_path,
+              headers: { Authorization: "Bearer #{user_pat.token}" }
+            )
+          end.to have_rejected_connection
+
+          expect(connection.current_user).to be_nil
+          expect(app_context['meta.auth_fail_reason']).to eq('token_expired')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{user_pat.id}")
+        end
+      end
+
+      context 'when a revoked personal_access_token' do
+        let_it_be(:user_pat) { revoked_token }
+
+        it 'sets the current_user as `nil`, and rejects the connection' do
+          expect do
+            connect(ActionCable.server.config.mount_path,
+              headers: { Authorization: "Bearer #{user_pat.token}" }
+            )
+          end.to have_rejected_connection
+
+          expect(connection.current_user).to be_nil
+          expect(app_context['meta.auth_fail_reason']).to eq('token_revoked')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{user_pat.id}")
+        end
+      end
     end
     context 'when it is an OAuth access token' do

spec/channels/graphql_channel_spec.rb

@@ -11,6 +11,9 @@
     create(:personal_access_token, scopes: %w[read_user read_api], user: user)
   end
+  let_it_be(:expired_token) { create(:personal_access_token, :expired, scopes: %w[read_api], user: user) }
+  let_it_be(:revoked_token) { create(:personal_access_token, :revoked, scopes: %w[read_api], user: user) }
+
   describe '#subscribed' do
     let(:query) do
       <<~GRAPHQL
@@ -41,6 +44,8 @@
     end
     context 'with a personal access token' do
+      let(:app_context) { Gitlab::ApplicationContext.current }
+
       before do
         stub_action_cable_connection current_user: user, access_token: access_token
       end
@@ -53,6 +58,7 @@
           expect(subscription).to be_confirmed
           expect(subscription.streams).to include(/graphql-event::mergeRequestReviewersUpdated:issuableId/)
+          expect(app_context.keys).not_to include('meta.auth_fail_reason', 'meta.auth_fail_token_id')
         end
       end
@@ -63,6 +69,8 @@
           subscribe(subscribe_params)
           expect(subscription).not_to be_confirmed
+          expect(app_context['meta.auth_fail_reason']).to eq('insufficient_scope')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{access_token.id}")
         end
       end
@@ -74,6 +82,31 @@
           expect(subscription).to be_confirmed
           expect(subscription.streams).to include(/graphql-event::mergeRequestReviewersUpdated:issuableId/)
+          expect(app_context.keys).not_to include('meta.auth_fail_reason', 'meta.auth_fail_token_id')
+        end
+      end
+
+      context 'with an expired read_user personal access token' do
+        let(:access_token) { expired_token }
+
+        it 'does not subscribe to the given graphql subscription' do
+          subscribe(subscribe_params)
+
+          expect(subscription).not_to be_confirmed
+          expect(app_context['meta.auth_fail_reason']).to eq('token_expired')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{access_token.id}")
+        end
+      end
+
+      context 'with a revoked read_user personal access token' do
+        let(:access_token) { revoked_token }
+
+        it 'does not subscribe to the given graphql subscription' do
+          subscribe(subscribe_params)
+
+          expect(subscription).not_to be_confirmed
+          expect(app_context['meta.auth_fail_reason']).to eq('token_revoked')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{access_token.id}")
         end
       end
     end

spec/controllers/graphql_controller_spec.rb

@@ -8,6 +8,8 @@
   # two days is enough to make timezones irrelevant
   let_it_be(:last_activity_on) { 2.days.ago.to_date }
+  let(:app_context) { Gitlab::ApplicationContext.current }
+
   describe 'rescue_from' do
     let_it_be(:message) { 'green ideas sleep furiously' }
@@ -326,6 +328,32 @@
         end
       end
+      context 'with an expired token' do
+        let(:token) { create(:personal_access_token, :expired, user: user, scopes: [:api]) }
+
+        it_behaves_like 'invalid token'
+
+        it 'registers token_expire in application context' do
+          subject
+
+          expect(app_context['meta.auth_fail_reason']).to eq('token_expired')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{token.id}")
+        end
+      end
+
+      context 'with a revoked token' do
+        let(:token) { create(:personal_access_token, :revoked, user: user, scopes: [:api]) }
+
+        it_behaves_like 'invalid token'
+
+        it 'registers token_expire in application context' do
+          subject
+
+          expect(app_context['meta.auth_fail_reason']).to eq('token_revoked')
+          expect(app_context['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{token.id}")
+        end
+      end
+
       context 'with an invalid token' do
         context 'with auth header' do
           subject do
@@ -433,7 +461,8 @@
       it "assigns username in ApplicationContext" do
         subject
-        expect(Gitlab::ApplicationContext.current).to include('meta.user' => user.username)
+        expect(app_context).to include('meta.user' => user.username)
+        expect(app_context.keys).not_to include('meta.auth_fail_reason', 'meta.auth_fail_token_id')
       end
       it 'calls the track api when trackable method' do
@@ -513,7 +542,8 @@
       it "does not assign a username in ApplicationContext" do
         subject
-        expect(Gitlab::ApplicationContext.current.key?('meta.user')).to be false
+        expect(app_context.key?('meta.user')).to be false
+        expect(app_context.keys).not_to include('meta.auth_fail_reason', 'meta.auth_fail_token_id')
       end
     end

spec/lib/gitlab/application_context_spec.rb

@@ -2,7 +2,14 @@
 require 'spec_helper'
-RSpec.describe Gitlab::ApplicationContext do
+RSpec.describe Gitlab::ApplicationContext, feature_category: :shared do
+  describe '.allowed_job_keys' do
+    it 'includes known keys but omits Web-specific keys' do
+      expect(described_class.allowed_job_keys).to include(:user, :user_id, :project, :root_namespace, :client_id)
+      expect(described_class.allowed_job_keys).not_to include(:auth_fail_reason, :auth_fail_token_id)
+    end
+  end
+
   describe '.with_context' do
     it 'yields the block' do
       expect { |b| described_class.with_context({}, &b) }.to yield_control

spec/lib/gitlab/auth/auth_finders_spec.rb

@@ -959,6 +959,8 @@ def auth_header_with(token)
           expect { validate_and_save_access_token! }.to raise_error(Gitlab::Auth::ExpiredError)
           expect(request.env).not_to have_key(described_class::API_TOKEN_ENV)
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_reason']).to eq('token_expired')
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{personal_access_token.id}")
         end
         it 'returns Gitlab::Auth::RevokedError if token revoked', :aggregate_failures do
@@ -966,11 +968,15 @@ def auth_header_with(token)
           expect { validate_and_save_access_token! }.to raise_error(Gitlab::Auth::RevokedError)
           expect(request.env).not_to have_key(described_class::API_TOKEN_ENV)
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_reason']).to eq('token_revoked')
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{personal_access_token.id}")
         end
         it 'returns Gitlab::Auth::InsufficientScopeError if invalid token scope', :aggregate_failures do
           expect { validate_and_save_access_token!(scopes: [:sudo]) }.to raise_error(Gitlab::Auth::InsufficientScopeError)
           expect(request.env).not_to have_key(described_class::API_TOKEN_ENV)
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_reason']).to eq('insufficient_scope')
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{personal_access_token.id}")
         end
       end
     end
@@ -986,6 +992,8 @@ def auth_header_with(token)
         it 'returns Gitlab::Auth::ImpersonationDisabled' do
           expect { validate_and_save_access_token! }.to raise_error(Gitlab::Auth::ImpersonationDisabled)
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_reason']).to eq('impersonation_disabled')
+          expect(Gitlab::ApplicationContext.current['meta.auth_fail_token_id']).to eq("PersonalAccessToken/#{personal_access_token.id}")
         end
       end
     end

spec/requests/api/api_spec.rb

@@ -140,6 +140,30 @@
         end
       end
+      context 'with an expired token' do
+        let_it_be(:private_project) { create(:project) }
+        let_it_be(:token) { create(:personal_access_token, :expired, user: user) }
+
+        it 'logs all application context fields and the route' do
+          expect(described_class::LOG_FORMATTER).to receive(:call) do |_severity, _datetime, _, data|
+            expect(data.stringify_keys).to include(
+              'correlation_id' => an_instance_of(String),
+              'meta.caller_id' => 'GET /api/:version/projects/:id/issues',
+              'meta.remote_ip' => an_instance_of(String),
+              'meta.client_id' => a_string_matching(%r{\Aip/.+}),
+              'meta.auth_fail_reason' => "token_expired",
+              'meta.auth_fail_token_id' => "PersonalAccessToken/#{token.id}",
+              'meta.feature_category' => 'team_planning',
+              'route' => '/api/:version/projects/:id/issues'
+            )
+          end
+
+          get(api("/projects/#{private_project.id}/issues", personal_access_token: token))
+
+          expect(response).to have_gitlab_http_status(:unauthorized)
+        end
+      end
+
       it 'skips context fields that do not apply' do
         expect(described_class::LOG_FORMATTER).to receive(:call) do |_severity, _datetime, _, data|
           expect(data.stringify_keys)