Always log remote_ip and client_id for API routes

Some API requests are handled by Grape directly without ever going
through `before` blocks. We can still log `remote_ip` (and hence
`client_id`) for those requests, as that doesn't depend on anything
application-specific.

We handle this by putting it in the logger itself as well as the
`before` block. This is because `client_id` is computed based on an
ApplicationContext instance, but this is backed by a Labkit::Context. A
Labkit::Context isn't aware of our models, and so `user` is only
inherited as a string, not an object - which means that `client_id`
could end up incorrectly using the IP rather than the user ID.

.rubocop_manual_todo.yml

@@ -741,7 +741,6 @@ RSpec/AnyInstanceOf:
     - 'spec/policies/ci/pipeline_policy_spec.rb'
     - 'spec/presenters/gitlab/blame_presenter_spec.rb'
     - 'spec/presenters/merge_request_presenter_spec.rb'
-    - 'spec/requests/api/api_spec.rb'
     - 'spec/requests/api/ci/runner/jobs_artifacts_spec.rb'
     - 'spec/requests/api/ci/runner/jobs_put_spec.rb'
     - 'spec/requests/api/ci/runner/jobs_request_post_spec.rb'

ee/spec/requests/api/api_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe API::API do
+  describe 'logging', :aggregate_failures do
+    let_it_be(:project) { create(:project, :public) }
+    let_it_be(:user) { project.owner }
+
+    context 'when the method is not allowed' do
+      it 'logs the route and context metadata for the client' 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.remote_ip' => an_instance_of(String),
+                        'meta.client_id' => a_string_matching(%r{\Aip/.+}),
+                        'route' => '/api/scim/:version/groups/:group/Users/:id')
+
+          expect(data.stringify_keys).not_to include('meta.caller_id', 'meta.user')
+        end
+
+        allow(Gitlab::Auth::GroupSaml::Config).to receive(:enabled?).and_return(true)
+
+        process(:put, '/api/scim/v2/groups/1/Users/foo')
+
+        expect(response).to have_gitlab_http_status(:method_not_allowed)
+      end
+    end
+  end
+end

ee/spec/requests/api/scim_spec.rb

@@ -237,7 +237,7 @@ RSpec.describe API::Scim do
         end
       end
 
-      it_behaves_like 'storing arguments in the application context' do
+      it_behaves_like 'storing arguments in the application context for the API' do
         let(:expected_params) { { root_namespace: group.full_path_components.first } }
 
         subject { post scim_api("scim/v2/groups/#{group.full_path}/Users?params=#{post_params}") }

lib/api/api.rb

@@ -11,11 +11,12 @@ module API
     COMMIT_ENDPOINT_REQUIREMENTS = NAMESPACE_OR_PROJECT_REQUIREMENTS.merge(sha: NO_SLASH_URL_PART_REGEX).freeze
     USER_REQUIREMENTS = { user_id: NO_SLASH_URL_PART_REGEX }.freeze
     LOG_FILTERS = ::Rails.application.config.filter_parameters + [/^output$/]
+    LOG_FORMATTER = Gitlab::GrapeLogging::Formatters::LogrageWithTimestamp.new
 
     insert_before Grape::Middleware::Error,
                   GrapeLogging::Middleware::RequestLogger,
                   logger: Logger.new(LOG_FILENAME),
-                  formatter: Gitlab::GrapeLogging::Formatters::LogrageWithTimestamp.new,
+                  formatter: LOG_FORMATTER,
                   include: [
                     GrapeLogging::Loggers::FilterParameters.new(LOG_FILTERS),
                     Gitlab::GrapeLogging::Loggers::ClientEnvLogger.new,
@@ -49,16 +50,19 @@ module API
     before do
       coerce_nil_params_to_array!
 
-      api_endpoint = env['api.endpoint']
+      api_endpoint = request.env[Grape::Env::API_ENDPOINT]
       feature_category = api_endpoint.options[:for].try(:feature_category_for_app, api_endpoint).to_s
 
+      # remote_ip is added here and the ContextLogger so that the
+      # client_id field is set correctly, as the user object does not
+      # survive between multiple context pushes.
       Gitlab::ApplicationContext.push(
         user: -> { @current_user },
         project: -> { @project },
         namespace: -> { @group },
         runner: -> { @current_runner || @runner },
-        caller_id: api_endpoint.endpoint_id,
         remote_ip: request.ip,
+        caller_id: api_endpoint.endpoint_id,
         feature_category: feature_category
       )
     end

lib/gitlab/grape_logging/loggers/context_logger.rb

 # frozen_string_literal: true
 
-# This module adds additional correlation id the grape logger
+# This class adds application context to the grape logger
 module Gitlab
   module GrapeLogging
     module Loggers
       class ContextLogger < ::GrapeLogging::Loggers::Base
-        def parameters(_, _)
+        def parameters(request, _)
+          # Add remote_ip if this request wasn't already handled. If we
+          # add it unconditionally we can break client_id due to the way
+          # the context inherits the user.
+          unless Gitlab::ApplicationContext.current_context_include?(:remote_ip)
+            Gitlab::ApplicationContext.push(remote_ip: request.ip)
+          end
+
           Gitlab::ApplicationContext.current
         end
       end

spec/requests/api/api_spec.rb

@@ -100,39 +100,105 @@ RSpec.describe API::API do
     end
   end
 
-  context 'application context' do
-    let_it_be(:project) { create(:project) }
+  describe 'logging', :aggregate_failures do
+    let_it_be(:project) { create(:project, :public) }
     let_it_be(:user) { project.owner }
 
-    it 'logs all application context fields' do
-      allow_any_instance_of(Gitlab::GrapeLogging::Loggers::ContextLogger).to receive(:parameters) do
-        Gitlab::ApplicationContext.current.tap do |log_context|
-          expect(log_context).to match('correlation_id' => an_instance_of(String),
-                                       'meta.caller_id' => 'GET /api/:version/projects/:id/issues',
-                                       'meta.remote_ip' => an_instance_of(String),
-                                       'meta.project' => project.full_path,
-                                       'meta.root_namespace' => project.namespace.full_path,
-                                       'meta.user' => user.username,
-                                       'meta.client_id' => an_instance_of(String),
-                                       'meta.feature_category' => 'issue_tracking')
+    context 'when the endpoint is handled by the application' do
+      context 'when the endpoint supports all possible fields' do
+        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.project' => project.full_path,
+                          'meta.root_namespace' => project.namespace.full_path,
+                          'meta.user' => user.username,
+                          'meta.client_id' => a_string_matching(%r{\Auser/.+}),
+                          'meta.feature_category' => 'issue_tracking',
+                          'route' => '/api/:version/projects/:id/issues')
+          end
+
+          get(api("/projects/#{project.id}/issues", user))
+
+          expect(response).to have_gitlab_http_status(:ok)
         end
       end
 
-      get(api("/projects/#{project.id}/issues", user))
+      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)
+            .to include('correlation_id' => an_instance_of(String),
+                        'meta.caller_id' => 'GET /api/:version/broadcast_messages',
+                        'meta.remote_ip' => an_instance_of(String),
+                        'meta.client_id' => a_string_matching(%r{\Aip/.+}),
+                        'meta.feature_category' => 'navigation',
+                        'route' => '/api/:version/broadcast_messages')
+
+          expect(data.stringify_keys).not_to include('meta.project', 'meta.root_namespace', 'meta.user')
+        end
+
+        get(api('/broadcast_messages'))
+
+        expect(response).to have_gitlab_http_status(:ok)
+      end
+    end
+
+    context 'when there is an unsupported media type' do
+      it 'logs the route and context metadata for the client' 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.remote_ip' => an_instance_of(String),
+                        'meta.client_id' => a_string_matching(%r{\Aip/.+}),
+                        'route' => '/api/:version/users/:id')
+
+          expect(data.stringify_keys).not_to include('meta.caller_id', 'meta.feature_category', 'meta.user')
+        end
+
+        put(api("/users/#{user.id}", user), params: { 'name' => 'Test' }, headers: { 'Content-Type' => 'image/png' })
+
+        expect(response).to have_gitlab_http_status(:unsupported_media_type)
+      end
     end
 
-    it 'skips fields that do not apply' do
-      allow_any_instance_of(Gitlab::GrapeLogging::Loggers::ContextLogger).to receive(:parameters) do
-        Gitlab::ApplicationContext.current.tap do |log_context|
-          expect(log_context).to match('correlation_id' => an_instance_of(String),
-                                       'meta.caller_id' => 'GET /api/:version/users',
-                                       'meta.remote_ip' => an_instance_of(String),
-                                       'meta.client_id' => an_instance_of(String),
-                                       'meta.feature_category' => 'users')
+    context 'when there is an OPTIONS request' do
+      it 'logs the route and context metadata for the client' 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.remote_ip' => an_instance_of(String),
+                        'meta.client_id' => a_string_matching(%r{\Auser/.+}),
+                        'meta.user' => user.username,
+                        'meta.feature_category' => 'users',
+                        'route' => '/api/:version/users')
+
+          expect(data.stringify_keys).not_to include('meta.caller_id')
         end
+
+        options(api('/users', user))
+
+        expect(response).to have_gitlab_http_status(:no_content)
       end
+    end
 
-      get(api('/users'))
+    context 'when the API version is not matched' do
+      it 'logs the route and context metadata for the client' 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.remote_ip' => an_instance_of(String),
+                        'meta.client_id' => a_string_matching(%r{\Aip/.+}),
+                        'route' => '/api/:version/*path')
+
+          expect(data.stringify_keys).not_to include('meta.caller_id', 'meta.user')
+        end
+
+        get('/api/v4_or_is_it')
+
+        expect(response).to have_gitlab_http_status(:not_found)
+      end
     end
   end
 

spec/requests/api/ci/runner/jobs_request_post_spec.rb

@@ -816,7 +816,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
 
             subject { request_job(id: job.id) }
 
-            it_behaves_like 'storing arguments in the application context' do
+            it_behaves_like 'storing arguments in the application context for the API' do
               let(:expected_params) { { user: user.username, project: project.full_path, client_id: "user/#{user.id}" } }
             end
 
@@ -827,7 +827,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
           end
 
           context 'when the runner is of project type' do
-            it_behaves_like 'storing arguments in the application context' do
+            it_behaves_like 'storing arguments in the application context for the API' do
               let(:expected_params) { { project: project.full_path, client_id: "runner/#{runner.id}" } }
             end
 
@@ -841,7 +841,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
             let(:group) { create(:group) }
             let(:runner) { create(:ci_runner, :group, groups: [group]) }
 
-            it_behaves_like 'storing arguments in the application context' do
+            it_behaves_like 'storing arguments in the application context for the API' do
               let(:expected_params) { { root_namespace: group.full_path_components.first, client_id: "runner/#{runner.id}" } }
             end
 

spec/requests/api/ci/runner/runners_delete_spec.rb

@@ -51,7 +51,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
           let(:params) { { token: runner.token } }
         end
 
-        it_behaves_like 'storing arguments in the application context' do
+        it_behaves_like 'storing arguments in the application context for the API' do
           let(:expected_params) { { client_id: "runner/#{runner.id}" } }
         end
       end

spec/requests/api/ci/runner/runners_post_spec.rb

@@ -58,7 +58,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
             expect(runner).to be_instance_type
           end
 
-          it_behaves_like 'storing arguments in the application context' do
+          it_behaves_like 'storing arguments in the application context for the API' do
             subject { request }
 
             let(:expected_params) { { client_id: "runner/#{::Ci::Runner.first.id}" } }
@@ -84,7 +84,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
             expect(runner).to be_project_type
           end
 
-          it_behaves_like 'storing arguments in the application context' do
+          it_behaves_like 'storing arguments in the application context for the API' do
             subject { request }
 
             let(:expected_params) { { project: project.full_path, client_id: "runner/#{::Ci::Runner.first.id}" } }
@@ -190,7 +190,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
             expect(runner).to be_group_type
           end
 
-          it_behaves_like 'storing arguments in the application context' do
+          it_behaves_like 'storing arguments in the application context for the API' do
             subject { request }
 
             let(:expected_params) { { root_namespace: group.full_path_components.first, client_id: "runner/#{::Ci::Runner.first.id}" } }

spec/requests/api/ci/runner/runners_verify_post_spec.rb

@@ -45,7 +45,7 @@ RSpec.describe API::Ci::Runner, :clean_gitlab_redis_shared_state do
           expect(response).to have_gitlab_http_status(:ok)
         end
 
-        it_behaves_like 'storing arguments in the application context' do
+        it_behaves_like 'storing arguments in the application context for the API' do
           let(:expected_params) { { client_id: "runner/#{runner.id}" } }
         end
       end

spec/requests/api/ci/triggers_spec.rb

@@ -131,7 +131,7 @@ RSpec.describe API::Ci::Triggers do
       let(:subject_proc) { proc { post api("/projects/#{project.id}/ref/master/trigger/pipeline?token=#{trigger_token}"), params: { ref: 'refs/heads/other-branch' } } }
 
       context 'when triggering a pipeline from a trigger token' do
-        it_behaves_like 'storing arguments in the application context'
+        it_behaves_like 'storing arguments in the application context for the API'
         it_behaves_like 'not executing any extra queries for the application context'
       end
 
@@ -142,7 +142,7 @@ RSpec.describe API::Ci::Triggers do
         context 'when other job is triggered by a user' do
           let(:trigger_token) { create(:ci_build, :running, project: project, user: user).token }
 
-          it_behaves_like 'storing arguments in the application context'
+          it_behaves_like 'storing arguments in the application context for the API'
           it_behaves_like 'not executing any extra queries for the application context'
         end
 
@@ -151,7 +151,7 @@ RSpec.describe API::Ci::Triggers do
           let(:runner) { create(:ci_runner) }
           let(:expected_params) { { client_id: "runner/#{runner.id}", project: project.full_path } }
 
-          it_behaves_like 'storing arguments in the application context'
+          it_behaves_like 'storing arguments in the application context for the API'
           it_behaves_like 'not executing any extra queries for the application context', 1
         end
       end

spec/requests/api/internal/base_spec.rb

@@ -609,7 +609,7 @@ RSpec.describe API::Internal::Base do
       end
 
       context 'with Project' do
-        it_behaves_like 'storing arguments in the application context' do
+        it_behaves_like 'storing arguments in the application context for the API' do
           let(:expected_params) { { user: key.user.username, project: project.full_path, caller_id: "POST /api/:version/internal/allowed" } }
 
           subject { push(key, project) }
@@ -617,7 +617,7 @@ RSpec.describe API::Internal::Base do
       end
 
       context 'with PersonalSnippet' do
-        it_behaves_like 'storing arguments in the application context' do
+        it_behaves_like 'storing arguments in the application context for the API' do
           let(:expected_params) { { user: key.user.username, caller_id: "POST /api/:version/internal/allowed" } }
 
           subject { push(key, personal_snippet) }
@@ -625,7 +625,7 @@ RSpec.describe API::Internal::Base do
       end
 
       context 'with ProjectSnippet' do
-        it_behaves_like 'storing arguments in the application context' do
+        it_behaves_like 'storing arguments in the application context for the API' do
           let(:expected_params) { { user: key.user.username, project: project_snippet.project.full_path, caller_id: "POST /api/:version/internal/allowed" } }
 
           subject { push(key, project_snippet) }
@@ -1197,7 +1197,7 @@ RSpec.describe API::Internal::Base do
         subject
       end
 
-      it_behaves_like 'storing arguments in the application context' do
+      it_behaves_like 'storing arguments in the application context for the API' do
         let(:expected_params) { expected_context }
       end
     end

spec/requests/api/projects_spec.rb

@@ -2591,7 +2591,7 @@ RSpec.describe API::Projects do
       end
     end
 
-    it_behaves_like 'storing arguments in the application context' do
+    it_behaves_like 'storing arguments in the application context for the API' do
       let_it_be(:user) { create(:user) }
       let_it_be(:project) { create(:project, :public) }
       let(:expected_params) { { user: user.username, project: project.full_path } }

spec/support/shared_examples/requests/api/logging_application_context_shared_examples.rb

@@ -15,6 +15,22 @@ RSpec.shared_examples 'storing arguments in the application context' do
   end
 end
 
+# For the API we need a slightly different approach as `client_id` is
+# calculated in API logging code.
+RSpec.shared_examples 'storing arguments in the application context for the API' do
+  it 'places the expected params in the application context' do
+    expect(::API::API::LOG_FORMATTER).to receive(:call) do
+      expect(Gitlab::ApplicationContext.current).to include(log_hash(expected_params))
+    end
+
+    subject
+  end
+
+  def log_hash(hash)
+    hash.transform_keys! { |key| "meta.#{key}" }
+  end
+end
+
 RSpec.shared_examples 'not executing any extra queries for the application context' do |expected_extra_queries = 0|
   it 'does not execute more queries than without adding anything to the application context' do
     # Call the subject once to memoize all factories being used for the spec, so they won't