Log queue duration for Grape API callssh-tag-queue-duration-api-calls

This mimics the same thing the RailsQueueDuration does for Rails controller
requests and will help diagnose issues with API delays.

Closes #46601

4 files changed, 68 insertions, 1 deletions

diff --git a/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml b/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml
new file mode 100644
index 00000000000..686cceaab62
--- /dev/null
+++ b/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml
@@ -0,0 +1,5 @@
+---
+title: Log Workhorse queue duration for Grape API calls
+merge_request:
+author:
+type: other
diff --git a/lib/api/api.rb b/lib/api/api.rb
index de20b2b8e67..206fabe5c43 100644
--- a/lib/api/api.rb
+++ b/lib/api/api.rb
@@ -15,7 +15,8 @@ module API
                   include: [
                     GrapeLogging::Loggers::FilterParameters.new,
                     GrapeLogging::Loggers::ClientEnv.new,
-                    Gitlab::GrapeLogging::Loggers::UserLogger.new
+                    Gitlab::GrapeLogging::Loggers::UserLogger.new,
+                    Gitlab::GrapeLogging::Loggers::QueueDurationLogger.new
                   ]
 
     allow_access_with_scope :api
diff --git a/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb b/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb
new file mode 100644
index 00000000000..0adac79f25a
--- /dev/null
+++ b/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb
@@ -0,0 +1,26 @@
+# This grape_logging module (https://github.com/aserafin/grape_logging) makes it
+# possible to log how much time an API request was queued by Workhorse.
+module Gitlab
+  module GrapeLogging
+    module Loggers
+      class QueueDurationLogger < ::GrapeLogging::Loggers::Base
+        attr_accessor :start_time
+
+        def before
+          @start_time = Time.now
+        end
+
+        def parameters(request, _)
+          proxy_start = request.env['HTTP_GITLAB_WORKHORSE_PROXY_START'].presence
+
+          return {} unless proxy_start && start_time
+
+          # Time in milliseconds since gitlab-workhorse started the request
+          duration = (start_time.to_f * 1_000 - proxy_start.to_f / 1_000_000).round(2)
+
+          { 'queue_duration': duration }
+        end
+      end
+    end
+  end
+end
diff --git a/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb b/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb
new file mode 100644
index 00000000000..f47b9dd3498
--- /dev/null
+++ b/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb
@@ -0,0 +1,35 @@
+require 'spec_helper'
+
+describe Gitlab::GrapeLogging::Loggers::QueueDurationLogger do
+  subject { described_class.new }
+
+  describe ".parameters" do
+    let(:start_time) { Time.new(2018, 01, 01) }
+
+    describe 'when no proxy time is available' do
+      let(:mock_request) { OpenStruct.new(env: {}) }
+
+      it 'returns an empty hash' do
+        expect(subject.parameters(mock_request, nil)).to eq({})
+      end
+    end
+
+    describe 'when a proxy time is available' do
+      let(:mock_request) do
+        OpenStruct.new(
+          env: {
+            'HTTP_GITLAB_WORKHORSE_PROXY_START' => (start_time - 1.hour).to_i * (10**9)
+          }
+        )
+      end
+
+      it 'returns the correct duration in ms' do
+        Timecop.freeze(start_time) do
+          subject.before
+
+          expect(subject.parameters(mock_request, nil)).to eq( { 'queue_duration': 1.hour.to_f * 1000 })
+        end
+      end
+    end
+  end
+end