Log long running requests via RequestStartedOnMiddleware

https://bugzilla.redhat.com/show_bug.cgi?id=1614918

For puma based workers, we implement do_heartbeat_work to
log_long_running_requests. This method is run very frequently per minute,
so we ensure this check happens at most every 30 seconds.

The log message includes the requested URI path, the thread (in the same
PID:TID format that we log elsewhere) and the request duration so far.

Using the PID:TID information, users can then find the request
parameters by searching the logs for this PID:TID.

app/models/mixins/miq_web_server_runner_mixin.rb

@@ -33,4 +33,22 @@ def start_rails_server(options)
       server.start
     end
   end
+
+  def do_heartbeat_work
+    log_long_running_requests
+  end
+
+  CHECK_LONG_RUNNING_REQUESTS_INTERVAL = 30.seconds
+  def log_long_running_requests
+    @last_checked_hung_requests ||= Time.now.utc
+    return if @last_checked_hung_requests > CHECK_LONG_RUNNING_REQUESTS_INTERVAL.ago
+
+    RequestStartedOnMiddleware.long_running_requests.each do |request, duration, thread|
+      message = "Long running http(s) request: '#{request}' handled by ##{Process.pid}:#{thread.object_id.to_s(16)}, running for #{duration.round(2)} seconds"
+      _log.warn(message)
+      Rails.logger.warn(message)
+    end
+
+    @last_checked_hung_requests = Time.now.utc
+  end
 end

config/application.rb

@@ -109,6 +109,8 @@ class Application < Rails::Application
 
     config.autoload_once_paths << Rails.root.join("lib", "vmdb", "console_methods.rb").to_s
 
+    config.middleware.use 'RequestStartedOnMiddleware'
+
     # config.eager_load_paths accepts an array of paths from which Rails will eager load on boot if cache classes is enabled.
     # Defaults to every folder in the app directory of the application.