Merge branch 'sh-log-rails-queue-duration' into 'master'

Log queue duration in production_json.log

Closes #57420

See merge request gitlab-org/gitlab-ce!25075

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

@@ -0,0 +1,5 @@
+---
+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)