Log queue duration for Grape API calls

changelogs/unreleased/sh-tag-queue-duration-api-calls.yml

+---
+title: Log Workhorse queue duration for Grape API calls
+merge_request:
+author:
+type: other

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

lib/gitlab/grape_logging/loggers/queue_duration_logger.rb

+# 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

spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb

+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