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.

5 files changed, 17 insertions, 3 deletions

diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb
index 26cd5dc801f..af0b0c64814 100644
--- a/app/controllers/application_controller.rb
+++ b/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
 
   ##
diff --git a/changelogs/unreleased/sh-log-rails-queue-duration.yml b/changelogs/unreleased/sh-log-rails-queue-duration.yml
new file mode 100644
index 00000000000..89390aef108
--- /dev/null
+++ b/changelogs/unreleased/sh-log-rails-queue-duration.yml
@@ -0,0 +1,5 @@
+---
+title: Log queue duration in production_json.log
+merge_request: 25075
+author:
+type: other
diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb
index c897bc30e76..164954d1293 100644
--- a/config/initializers/lograge.rb
+++ b/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
diff --git a/doc/administration/logs.md b/doc/administration/logs.md
index 698f4caab3a..36dee75bd44 100644
--- a/doc/administration/logs.md
+++ b/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.
diff --git a/lib/gitlab/middleware/rails_queue_duration.rb b/lib/gitlab/middleware/rails_queue_duration.rb
index 96c6a0a7d28..a147e165262 100644
--- a/lib/gitlab/middleware/rails_queue_duration.rb
+++ b/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)