From 0b4a7d656b224c145072946f06539fcff40cc8ca Mon Sep 17 00:00:00 2001
From: "micael.bergeron" <micaelbergeron@gmail.com>
Date: Tue, 14 Nov 2017 09:22:15 -0500
Subject: [PATCH] rework the logging to be simpler and add a threshold

---
 app/workers/update_merge_requests_worker.rb    | 18 ++++++++++++------
 .../update_merge_requests_worker_spec.rb       | 12 +++++++++---
 2 files changed, 21 insertions(+), 9 deletions(-)

diff --git a/app/workers/update_merge_requests_worker.rb b/app/workers/update_merge_requests_worker.rb
index d8d818aee8e..ab831858676 100644
--- a/app/workers/update_merge_requests_worker.rb
+++ b/app/workers/update_merge_requests_worker.rb
@@ -2,6 +2,8 @@ class UpdateMergeRequestsWorker
   include Sidekiq::Worker
   include DedicatedSidekiqQueue
 
+  LOG_TIME_THRESHOLD = 90 # seconds
+
   def perform(project_id, user_id, oldrev, newrev, ref)
     project = Project.find_by(id: project_id)
     return unless project
@@ -14,12 +16,16 @@ class UpdateMergeRequestsWorker
       MergeRequests::RefreshService.new(project, user).execute(oldrev, newrev, ref)
     end
 
-    log_args = ["elapsed=#{time.real}"]
-    method(__method__).parameters.map do |_, p|
-      pname = p.to_s
-      log_args << [pname, binding.local_variable_get(pname)].join('=')
-    end
+    args_log = [
+      "elapsed=#{time.real}",
+      "project_id=#{project_id}",
+      "user_id=#{user_id}",
+      "oldrev=#{oldrev}",
+      "newrev=#{newrev}",
+      "ref=#{ref}"
+    ].join(',')
 
-    Rails.logger.info("UpdateMergeRequestsWorker#perform #{log_args.join(',')}")
+    Rails.logger.info("UpdateMergeRequestsWorker#perform #{args_log}") if time.real > LOG_TIME_THRESHOLD
   end
+
 end
diff --git a/spec/workers/update_merge_requests_worker_spec.rb b/spec/workers/update_merge_requests_worker_spec.rb
index 5c711399cd5..0fa19ac84bb 100644
--- a/spec/workers/update_merge_requests_worker_spec.rb
+++ b/spec/workers/update_merge_requests_worker_spec.rb
@@ -24,10 +24,16 @@ describe UpdateMergeRequestsWorker do
       perform
     end
 
-    it 'logs performance' do
-      expect(Rails.logger).to receive(:info).with(a_string_matching(/\AUpdateMergeRequestsWorker#perform.*project_id=#{project.id},user_id=#{user.id},oldrev=#{oldrev},newrev=#{newrev},ref=#{ref}/))
+    context 'when slow' do
+      before do
+        stub_const("UpdateMergeRequestsWorker::LOG_TIME_THRESHOLD", -1)
+      end
 
-      perform
+      it 'logs debug info' do
+        expect(Rails.logger).to receive(:info).with(a_string_matching(/\AUpdateMergeRequestsWorker#perform.*project_id=#{project.id},user_id=#{user.id},oldrev=#{oldrev},newrev=#{newrev},ref=#{ref}/))
+
+        perform
+      end
     end
   end
 end