Log the context metadata for rails requests

This logs the context for Rails-controller and Grape-API reqeusts
similar to what we do for Sidekiq.

The information comes from Labkit::Context.

This also avoids logging information for unpersisted groups and
projects in controllers. This was needed since the `#new` actions of
controllers would assign those ivars but the information is not
relevant for logs.

app/controllers/application_controller.rb

@@ -20,6 +20,7 @@ class ApplicationController < ActionController::Base
   include InitializesCurrentUserMode
   include Impersonation
   include Gitlab::Logging::CloudflareHelper
+  include Gitlab::Utils::StrongMemoize
 
   before_action :authenticate_user!, except: [:route_not_found]
   before_action :enforce_terms!, if: :should_enforce_terms?
@@ -37,6 +38,10 @@ class ApplicationController < ActionController::Base
   before_action :check_impersonation_availability
   before_action :required_signup_info
 
+  # Make sure the `auth_user` is memoized so it can be logged, we do this after
+  # all other before filters that could have set the user.
+  before_action :auth_user
+
   prepend_around_action :set_current_context
 
   around_action :sessionless_bypass_admin_mode!, if: :sessionless_user?
@@ -143,10 +148,11 @@ class ApplicationController < ActionController::Base
 
     payload[:ua] = request.env["HTTP_USER_AGENT"]
     payload[:remote_ip] = request.remote_ip
+
     payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
+    payload[:metadata] = @current_context
 
     logged_user = auth_user
-
     if logged_user.present?
       payload[:user_id] = logged_user.try(:id)
       payload[:username] = logged_user.try(:username)
@@ -162,10 +168,12 @@ class ApplicationController < ActionController::Base
   # (e.g. tokens) to authenticate the user, whereas Devise sets current_user.
   #
   def auth_user
-    if user_signed_in?
-      current_user
-    else
-      try(:authenticated_user)
+    strong_memoize(:auth_user) do
+      if user_signed_in?
+        current_user
+      else
+        try(:authenticated_user)
+      end
     end
   end
 
@@ -457,11 +465,16 @@ class ApplicationController < ActionController::Base
 
   def set_current_context(&block)
     Gitlab::ApplicationContext.with_context(
-      user: -> { auth_user },
-      project: -> { @project },
-      namespace: -> { @group },
-      caller_id: full_action_name,
-      &block)
+      # Avoid loading the auth_user again after the request. Otherwise calling
+      # `auth_user` again would also trigger the Warden callbacks again
+      user: -> { auth_user if strong_memoized?(:auth_user) },
+      project: -> { @project if @project&.persisted? },
+      namespace: -> { @group if @group&.persisted? },
+      caller_id: full_action_name) do
+      yield
+    ensure
+      @current_context = Labkit::Context.current.to_h
+    end
   end
 
   def set_locale(&block)

app/controllers/jwt_controller.rb

@@ -4,7 +4,9 @@ class JwtController < ApplicationController
   skip_around_action :set_session_storage
   skip_before_action :authenticate_user!
   skip_before_action :verify_authenticity_token
-  before_action :authenticate_project_or_user
+
+  # Add this before other actions, since we want to have the user or project
+  prepend_before_action :auth_user, :authenticate_project_or_user
 
   SERVICES = {
     Auth::ContainerRegistryAuthenticationService::AUDIENCE => Auth::ContainerRegistryAuthenticationService
@@ -77,7 +79,9 @@ class JwtController < ApplicationController
   end
 
   def auth_user
-    actor = @authentication_result&.actor
-    actor.is_a?(User) ? actor : nil
+    strong_memoize(:auth_user) do
+      actor = @authentication_result&.actor
+      actor.is_a?(User) ? actor : nil
+    end
   end
 end

doc/development/logging.md

@@ -261,6 +261,8 @@ I, [2020-01-13T19:01:17.091Z #11056]  INFO -- : {"message"=>"Message", "project_
 lifecycle, which can then be added to the web request
 or Sidekiq logs.
 
+The API, Rails and Sidekiq logs contain fields starting with `meta.` with this context information.
+
 Entry points can be seen at:
 
 - [`ApplicationController`](https://gitlab.com/gitlab-org/gitlab/blob/master/app/controllers/application_controller.rb)

ee/lib/ee/gitlab/application_context.rb

@@ -13,7 +13,11 @@ module EE
       end
 
       def subcription_plan_name
-        object = namespace || project
+        object = namespace
+        # Avoid loading the project's namespace if it wasn't loaded
+        object ||= project.namespace if project&.association(:namespace)&.loaded?
+        # Avoid loading or creating a plan if it wasn't already.
+        return unless object&.strong_memoized?(:actual_plan)
 
         object&.actual_plan_name
       end

ee/spec/lib/ee/gitlab/application_context_spec.rb

@@ -18,6 +18,8 @@ describe Gitlab::ApplicationContext do
     end
 
     it 'correctly loads the expected values' do
+      # Make sure the plan is loaded, otherwise it would not be included in the context
+      subgroup.actual_plan
       context = described_class.new(namespace: -> { subgroup })
 
       expect(result(context))
@@ -27,6 +29,7 @@ describe Gitlab::ApplicationContext do
 
     it 'falls back to a projects namespace plan when a project is passed but no namespace' do
       create(:gitlab_subscription, :silver, namespace: project.namespace)
+      project.actual_plan_name
       context = described_class.new(project: project)
 
       expect(result(context))

lib/api/api.rb

@@ -24,7 +24,8 @@ module API
                     Gitlab::GrapeLogging::Loggers::ExceptionLogger.new,
                     Gitlab::GrapeLogging::Loggers::QueueDurationLogger.new,
                     Gitlab::GrapeLogging::Loggers::PerfLogger.new,
-                    Gitlab::GrapeLogging::Loggers::CorrelationIdLogger.new
+                    Gitlab::GrapeLogging::Loggers::CorrelationIdLogger.new,
+                    Gitlab::GrapeLogging::Loggers::ContextLogger.new
                   ]
 
     allow_access_with_scope :api

lib/gitlab/grape_logging/loggers/context_logger.rb

+# frozen_string_literal: true
+
+# This module adds additional correlation id the grape logger
+module Gitlab
+  module GrapeLogging
+    module Loggers
+      class ContextLogger < ::GrapeLogging::Loggers::Base
+        def parameters(_, _)
+          Labkit::Context.current.to_h
+        end
+      end
+    end
+  end
+end

lib/gitlab/lograge/custom_options.rb

@@ -23,6 +23,8 @@ module Gitlab
           queue_duration_s: event.payload[:queue_duration_s]
         }
 
+        payload.merge!(event.payload[:metadata]) if event.payload[:metadata]
+
         ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
 
         payload[:response] = event.payload[:response] if event.payload[:response]

spec/controllers/application_controller_spec.rb

@@ -530,6 +530,14 @@ describe ApplicationController do
 
       expect(controller.last_payload).to include('correlation_id' => 'new-id')
     end
+
+    it 'adds context metadata to the payload' do
+      sign_in user
+
+      get :index
+
+      expect(controller.last_payload[:metadata]).to include('meta.user' => user.username)
+    end
   end
 
   describe '#access_denied' do
@@ -891,7 +899,7 @@ describe ApplicationController do
     end
 
     it 'sets the group if it was available' do
-      group = build(:group)
+      group = build_stubbed(:group)
       controller.instance_variable_set(:@group, group)
 
       get :index, format: :json
@@ -900,7 +908,7 @@ describe ApplicationController do
     end
 
     it 'sets the project if one was available' do
-      project = build(:project)
+      project = build_stubbed(:project)
       controller.instance_variable_set(:@project, project)
 
       get :index, format: :json
@@ -913,6 +921,20 @@ describe ApplicationController do
 
       expect(json_response['meta.caller_id']).to eq('AnonymousController#index')
     end
+
+    it 'assigns the context to a variable for logging' do
+      get :index, format: :json
+
+      expect(assigns(:current_context)).to include('meta.user' => user.username)
+    end
+
+    it 'assigns the context when the action caused an error' do
+      allow(controller).to receive(:index) { raise 'Broken' }
+
+      expect { get :index, format: :json }.to raise_error('Broken')
+
+      expect(assigns(:current_context)).to include('meta.user' => user.username)
+    end
   end
 
   describe '#current_user' do

spec/lib/gitlab/application_context_spec.rb

@@ -55,10 +55,10 @@ describe Gitlab::ApplicationContext do
   end
 
   describe '#to_lazy_hash' do
-    let(:user) { build(:user) }
-    let(:project) { build(:project) }
-    let(:namespace) { create(:group) }
-    let(:subgroup) { create(:group, parent: namespace) }
+    let_it_be(:user) { create(:user) }
+    let_it_be(:project) { create(:project) }
+    let_it_be(:namespace) { create(:group) }
+    let_it_be(:subgroup) { create(:group, parent: namespace) }
 
     def result(context)
       context.to_lazy_hash.transform_values { |v| v.respond_to?(:call) ? v.call : v }
@@ -106,5 +106,11 @@ describe Gitlab::ApplicationContext do
 
       context.use {}
     end
+
+    it 'does not cause queries' do
+      context = described_class.new(project: create(:project), namespace: create(:group, :nested), user: create(:user))
+
+      expect { context.use { Labkit::Context.current.to_h } }.not_to exceed_query_limit(0)
+    end
   end
 end

spec/lib/gitlab/lograge/custom_options_spec.rb

@@ -23,7 +23,8 @@ describe Gitlab::Lograge::CustomOptions do
           params: params,
           user_id: 'test',
           cf_ray: SecureRandom.hex,
-          cf_request_id: SecureRandom.hex
+          cf_request_id: SecureRandom.hex,
+          metadata: { 'meta.user' => 'jane.doe' }
         }
       )
     end
@@ -56,5 +57,25 @@ describe Gitlab::Lograge::CustomOptions do
       expect(subject[:cf_ray]).to eq(event.payload[:cf_ray])
       expect(subject[:cf_request_id]).to eq(event.payload[:cf_request_id])
     end
+
+    it 'adds the metadata' do
+      expect(subject['meta.user']).to eq('jane.doe')
+    end
+
+    context 'when metadata is missing' do
+      let(:event) do
+        ActiveSupport::Notifications::Event.new(
+          'test',
+          1,
+          2,
+          'transaction_id',
+          { params: {} }
+        )
+      end
+
+      it 'does not break' do
+        expect { subject }.not_to raise_error
+      end
+    end
   end
 end

spec/requests/jwt_controller_spec.rb

@@ -23,6 +23,7 @@ describe JwtController do
     it 'logs username and ID' do
       expect(log_data['username']).to eq(user.username)
       expect(log_data['user_id']).to eq(user.id)
+      expect(log_data['meta.user']).to eq(user.username)
     end
   end