Log queue duration in production_json.log

`queue_duration` is a useful metric that is currently in api_json.log
but not in production_json.log. We should add it because it tells us how
long the request sat in Workhorse before Unicorn processed it. Having
this field enables the support team to better troubleshoot when delays
began to happen.

app/controllers/application_controller.rb

@@ -137,6 +137,8 @@ class ApplicationController < ActionController::Base
     if response.status == 422 && response.body.present? && response.content_type == 'application/json'.freeze
       payload[:response] = response.body
     end
+
+    payload[:queue_duration] = request.env[::Gitlab::Middleware::RailsQueueDuration::GITLAB_RAILS_QUEUE_DURATION_KEY]
   end
 
   ##

changelogs/unreleased/sh-log-rails-queue-duration.yml

+---
+title: Log queue duration in production_json.log
+merge_request: 25075
+author:
+type: other

config/initializers/lograge.rb

@@ -23,7 +23,8 @@ unless Sidekiq.server?
         remote_ip: event.payload[:remote_ip],
         user_id: event.payload[:user_id],
         username: event.payload[:username],
-        ua: event.payload[:ua]
+        ua: event.payload[:ua],
+        queue_duration: event.payload[:queue_duration]
       }
 
       gitaly_calls = Gitlab::GitalyClient.get_request_count

doc/administration/logs.md

@@ -23,12 +23,13 @@ requests from the API are logged to a separate file in `api_json.log`.
 Each line contains a JSON line that can be ingested by Elasticsearch, Splunk, etc. For example:
 
 ```json
-{"method":"GET","path":"/gitlab/gitlab-ce/issues/1234","format":"html","controller":"Projects::IssuesController","action":"show","status":200,"duration":229.03,"view":174.07,"db":13.24,"time":"2017-08-08T20:15:54.821Z","params":[{"key":"param_key","value":"param_value"}],"remote_ip":"18.245.0.1","user_id":1,"username":"admin","gitaly_calls":76}
+{"method":"GET","path":"/gitlab/gitlab-ce/issues/1234","format":"html","controller":"Projects::IssuesController","action":"show","status":200,"duration":229.03,"view":174.07,"db":13.24,"time":"2017-08-08T20:15:54.821Z","params":[{"key":"param_key","value":"param_value"}],"remote_ip":"18.245.0.1","user_id":1,"username":"admin","gitaly_calls":76,"queue_duration": 112.47}
 ```
 
 In this example, you can see this was a GET request for a specific issue. Notice each line also contains performance data:
 
-1. `duration`: the total time taken to retrieve the request
+1. `duration`: total time in milliseconds taken to retrieve the request
+1. `queue_duration`: total time in milliseconds that the request was queued inside GitLab Workhorse
 1. `view`: total time taken inside the Rails views
 1. `db`: total time to retrieve data from the database
 1. `gitaly_calls`: total number of calls made to Gitaly
@@ -91,6 +92,8 @@ This entry above shows an access to an internal endpoint to check whether an
 associated SSH key can download the project in question via a `git fetch` or
 `git clone`. In this example, we see:
 
+1. `duration`: total time in milliseconds taken to retrieve the request
+1. `queue_duration`: total time in milliseconds that the request was queued inside GitLab Workhorse
 1. `method`: The HTTP method used to make the request
 1. `path`: The relative path of the query
 1. `params`: Key-value pairs passed in a query string or HTTP body. Sensitive parameters (e.g. passwords, tokens, etc.) are filtered out.

lib/gitlab/middleware/rails_queue_duration.rb

@@ -7,6 +7,8 @@
 module Gitlab
   module Middleware
     class RailsQueueDuration
+      GITLAB_RAILS_QUEUE_DURATION_KEY = 'GITLAB_RAILS_QUEUE_DURATION'
+
       def initialize(app)
         @app = app
       end
@@ -19,6 +21,7 @@ module Gitlab
           duration = Time.now.to_f * 1_000 - proxy_start.to_f / 1_000_000
           trans.set(:rails_queue_duration, duration)
           metric_rails_queue_duration_seconds.observe(trans.labels, duration / 1_000)
+          env[GITLAB_RAILS_QUEUE_DURATION_KEY] = duration.round(2)
         end
 
         @app.call(env)