Add JSON logs for merge servicesosw-add-json-logs-to-merge-services

This commit prepares MergeRequests services
to use JSON log and also adds a log to the
mergeability check service.

10 files changed, 110 insertions, 20 deletions

diff --git a/app/services/base_service.rb b/app/services/base_service.rb
index 3e968c8f707..8ef874a1d4e 100644
--- a/app/services/base_service.rb
+++ b/app/services/base_service.rb
@@ -21,11 +21,11 @@ class BaseService
     TodoService.new
   end
 
-  def log_info(message)
+  def log_info(message, _params = {})
     Gitlab::AppLogger.info message
   end
 
-  def log_error(message)
+  def log_error(message, _params = {})
     Gitlab::AppLogger.error message
   end
 
diff --git a/app/services/merge_requests/base_service.rb b/app/services/merge_requests/base_service.rb
index 067510a8a0a..75780493b02 100644
--- a/app/services/merge_requests/base_service.rb
+++ b/app/services/merge_requests/base_service.rb
@@ -2,6 +2,8 @@
 
 module MergeRequests
   class BaseService < ::IssuableBaseService
+    extend ::Gitlab::Utils::Override
+
     def create_note(merge_request, state = merge_request.state)
       SystemNoteService.change_status(merge_request, merge_request.target_project, current_user, state, nil)
     end
@@ -31,6 +33,20 @@ module MergeRequests
 
     private
 
+    override :log_info
+    def log_info(message, params = {})
+      logger.info(params.merge(message: message))
+    end
+
+    override :log_error
+    def log_error(message, params = {})
+      logger.error(params.merge(message: message))
+    end
+
+    def logger
+      @logger ||= Gitlab::MergeRequestsServiceLogger.build
+    end
+
     def handle_wip_event(merge_request)
       if wip_event = params.delete(:wip_event)
         # We update the title that is provided in the params or we use the mr title
diff --git a/app/services/merge_requests/merge_service.rb b/app/services/merge_requests/merge_service.rb
index 6309052244d..a57249169f2 100644
--- a/app/services/merge_requests/merge_service.rb
+++ b/app/services/merge_requests/merge_service.rb
@@ -61,11 +61,11 @@ module MergeRequests
     end
 
     def commit
-      log_info("Git merge started on JID #{merge_jid}")
+      log_info("Git merge started", merge_jid: merge_jid)
       commit_id = try_merge
 
       if commit_id
-        log_info("Git merge finished on JID #{merge_jid} commit #{commit_id}")
+        log_info("Git merge finished", merge_jid: merge_jid, commit_id: commit_id)
       else
         raise_error('Conflicts detected during merge')
       end
@@ -86,9 +86,9 @@ module MergeRequests
     end
 
     def after_merge
-      log_info("Post merge started on JID #{merge_jid} with state #{state}")
+      log_info("Post merge started", merge_jid: merge_jid, state: state)
       MergeRequests::PostMergeService.new(project, current_user).execute(merge_request)
-      log_info("Post merge finished on JID #{merge_jid} with state #{state}")
+      log_info("Post merge finished", merge_jid: merge_jid, state: state)
 
       if delete_source_branch?
         DeleteBranchService.new(@merge_request.source_project, branch_deletion_user)
@@ -113,13 +113,24 @@ module MergeRequests
     end
 
     def handle_merge_error(log_message:, save_message_on_model: false)
-      Rails.logger.error("MergeService ERROR: #{merge_request_info} - #{log_message}") # rubocop:disable Gitlab/RailsLogger
+      log_error("MergeService ERROR #{log_message}")
       @merge_request.update(merge_error: log_message) if save_message_on_model
     end
 
-    def log_info(message)
-      @logger ||= Rails.logger # rubocop:disable Gitlab/RailsLogger
-      @logger.info("#{merge_request_info} - #{message}")
+    override :log_info
+    def log_info(message, params = {})
+      super(message, log_params.merge(params))
+    end
+
+    override :log_error
+    def log_error(message, params = {})
+      super(message, log_params.merge(params))
+    end
+
+    def log_params
+      {
+        reference: merge_request_info
+      }
     end
 
     def merge_request_info
diff --git a/app/services/merge_requests/mergeability_check_service.rb b/app/services/merge_requests/mergeability_check_service.rb
index c70c4f5f92d..2bb1e289fbe 100644
--- a/app/services/merge_requests/mergeability_check_service.rb
+++ b/app/services/merge_requests/mergeability_check_service.rb
@@ -1,7 +1,7 @@
 # frozen_string_literal: true
 
 module MergeRequests
-  class MergeabilityCheckService < ::BaseService
+  class MergeabilityCheckService < ::MergeRequests::BaseService
     include Gitlab::Utils::StrongMemoize
     include Gitlab::ExclusiveLeaseHelpers
 
@@ -37,6 +37,7 @@ module MergeRequests
         check_mergeability(recheck)
       end
     rescue FailedToObtainLockError => error
+      log_error(error.message, merge_request_id: merge_request.id)
       ServiceResponse.error(message: error.message)
     end
 
diff --git a/doc/administration/logs.md b/doc/administration/logs.md
index 31876dd178a..351cd8fbb88 100644
--- a/doc/administration/logs.md
+++ b/doc/administration/logs.md
@@ -308,6 +308,21 @@ GraphQL queries are recorded in that file. For example:
 {"query_string":"query IntrospectionQuery{__schema {queryType { name },mutationType { name }}}...(etc)","variables":{"a":1,"b":2},"complexity":181,"depth":1,"duration":7}
 ```
 
+## `merge_requests_service_json.log`
+
+Introduced in GitLab 12.1. This file lives in `/var/log/gitlab/gitlab-rails/merge_requests_service_json.log` for
+Omnibus GitLab packages or in `/home/git/gitlab/log/merge_requests_service_json.log` for
+installations from source.
+
+It logs merge request operations such as merge and mergeability checks.
+
+```
+{"severity":"ERROR","time":"2019-07-26T18:45:12.319Z","correlation_id":null,"merge_request_id":1,"message":"Failed to obtain a lock"}
+{"severity":"ERROR","time":"2019-07-26T18:45:12.319Z","correlation_id":null,"merge_request_id":1,"message":"Failed to obtain a lock"}
+{"severity":"INFO","time":"2019-07-26T18:56:34.071Z","correlation_id":null,"merge_jid":null,"reference":"namespace1/project1!1","message":"Git merge started"}
+{"severity":"INFO","time":"2019-07-26T18:56:34.103Z","correlation_id":null,"merge_jid":null,"commit_id":"14305ceac4f73d55e750a08b7886e0229d324571","reference":"namespace1/project1!1","message":"Git merge finished"}
+```
+
 ## Reconfigure Logs
 
 Reconfigure log files live in `/var/log/gitlab/reconfigure` for Omnibus GitLab
diff --git a/lib/gitlab/merge_requests_service_logger.rb b/lib/gitlab/merge_requests_service_logger.rb
new file mode 100644
index 00000000000..ea70112eb91
--- /dev/null
+++ b/lib/gitlab/merge_requests_service_logger.rb
@@ -0,0 +1,9 @@
+# frozen_string_literal: true
+
+module Gitlab
+  class MergeRequestsServiceLogger < Gitlab::JsonLogger
+    def self.file_name_noext
+      'merge_requests_service_json'
+    end
+  end
+end
diff --git a/spec/services/merge_requests/merge_service_spec.rb b/spec/services/merge_requests/merge_service_spec.rb
index 22578436c18..b794631b005 100644
--- a/spec/services/merge_requests/merge_service_spec.rb
+++ b/spec/services/merge_requests/merge_service_spec.rb
@@ -210,8 +210,8 @@ describe MergeRequests::MergeService do
     context "error handling" do
       let(:service) { described_class.new(project, user, commit_message: 'Awesome message') }
 
-      before do
-        allow(Rails.logger).to receive(:error)
+      let!(:logger_spy) do
+        stub_logger(Gitlab::MergeRequestsServiceLogger)
       end
 
       context 'when source is missing' do
@@ -223,7 +223,9 @@ describe MergeRequests::MergeService do
           service.execute(merge_request)
 
           expect(merge_request.merge_error).to eq(error_message)
-          expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+          expect(logger_spy).to have_received(:error)
+            .with(message: a_string_matching(error_message),
+                  reference: merge_request.to_reference(full: true))
         end
       end
 
@@ -236,7 +238,9 @@ describe MergeRequests::MergeService do
         service.execute(merge_request)
 
         expect(merge_request.merge_error).to include('Something went wrong during merge')
-        expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+        expect(logger_spy).to have_received(:error)
+          .with(message: a_string_matching(error_message),
+                reference: merge_request.to_reference(full: true))
       end
 
       it 'logs and saves error if user is not authorized' do
@@ -260,7 +264,9 @@ describe MergeRequests::MergeService do
         service.execute(merge_request)
 
         expect(merge_request.merge_error).to include('Something went wrong during merge pre-receive hook')
-        expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+        expect(logger_spy).to have_received(:error)
+          .with(message: a_string_matching(error_message),
+                reference: merge_request.to_reference(full: true))
       end
 
       it 'logs and saves error if there is a merge conflict' do
@@ -274,7 +280,9 @@ describe MergeRequests::MergeService do
         expect(merge_request).to be_open
         expect(merge_request.merge_commit_sha).to be_nil
         expect(merge_request.merge_error).to include(error_message)
-        expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+        expect(logger_spy).to have_received(:error)
+          .with(message: a_string_matching(error_message),
+                reference: merge_request.to_reference(full: true))
       end
 
       context 'when squashing' do
@@ -293,7 +301,9 @@ describe MergeRequests::MergeService do
           expect(merge_request).to be_open
           expect(merge_request.merge_commit_sha).to be_nil
           expect(merge_request.merge_error).to include(error_message)
-          expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+          expect(logger_spy).to have_received(:error)
+            .with(message: a_string_matching(error_message),
+                  reference: merge_request.to_reference(full: true))
         end
 
         it 'logs and saves error if there is a squash in progress' do
@@ -307,7 +317,9 @@ describe MergeRequests::MergeService do
           expect(merge_request).to be_open
           expect(merge_request.merge_commit_sha).to be_nil
           expect(merge_request.merge_error).to include(error_message)
-          expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+          expect(logger_spy).to have_received(:error)
+            .with(message: a_string_matching(error_message),
+                  reference: merge_request.to_reference(full: true))
         end
 
         context "when fast-forward merge is not allowed" do
@@ -327,7 +339,9 @@ describe MergeRequests::MergeService do
               expect(merge_request).to be_open
               expect(merge_request.merge_commit_sha).to be_nil
               expect(merge_request.merge_error).to include(error_message)
-              expect(Rails.logger).to have_received(:error).with(a_string_matching(error_message))
+              expect(logger_spy).to have_received(:error)
+                .with(message: a_string_matching(error_message),
+                      reference: merge_request.to_reference(full: true))
             end
           end
         end
diff --git a/spec/services/merge_requests/mergeability_check_service_spec.rb b/spec/services/merge_requests/mergeability_check_service_spec.rb
index fae9adbafe1..bb8bf3d3d60 100644
--- a/spec/services/merge_requests/mergeability_check_service_spec.rb
+++ b/spec/services/merge_requests/mergeability_check_service_spec.rb
@@ -67,6 +67,10 @@ describe MergeRequests::MergeabilityCheckService, :clean_gitlab_redis_shared_sta
     it_behaves_like 'mergeable merge request'
 
     context 'when concurrent calls' do
+      let!(:logger_spy) do
+        stub_logger(Gitlab::MergeRequestsServiceLogger)
+      end
+
       it 'succeeds through locking' do
         threads = []
 
@@ -83,6 +87,10 @@ describe MergeRequests::MergeabilityCheckService, :clean_gitlab_redis_shared_sta
         expect(results).to contain_exactly([:error, 'Failed to obtain a lock'],
                                            [:error, 'Failed to obtain a lock'],
                                            [:success, nil])
+
+        expect(logger_spy).to have_received(:error)
+          .with(message: 'Failed to obtain a lock', merge_request_id: merge_request.id)
+          .twice
       end
     end
 
diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb
index 6ef5f46c81b..a7f202172e2 100644
--- a/spec/spec_helper.rb
+++ b/spec/spec_helper.rb
@@ -79,6 +79,7 @@ RSpec.configure do |config|
   config.include FixtureHelpers
   config.include GitlabRoutingHelper
   config.include StubFeatureFlags
+  config.include LogHelpers
   config.include StubGitlabCalls
   config.include StubGitlabData
   config.include ExpectNextInstanceOf
diff --git a/spec/support/helpers/log_helpers.rb b/spec/support/helpers/log_helpers.rb
new file mode 100644
index 00000000000..d4d371acc20
--- /dev/null
+++ b/spec/support/helpers/log_helpers.rb
@@ -0,0 +1,15 @@
+module LogHelpers
+  # Returns a stubbed logger instance which can
+  # be used as a spy. E.g.:
+  #
+  # spy_logger = stub_logger(logger)
+  # expect(spy_logger).to have_received(:info).with(hash)
+  #
+  def stub_logger(logger)
+    logger_spy = instance_double(logger, error: nil, info: nil)
+
+    allow(logger).to receive(:build) { logger_spy }
+
+    logger_spy
+  end
+end