Detect and log long running http(s) requests

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.
 

lib/request_started_on_middleware.rb

@@ -0,0 +1,57 @@
+# Add to config/application.rb:
+#
+#     config.middleware.use 'RequestStartedOnMiddleware'
+#
+class RequestStartedOnMiddleware
+  def initialize(app)
+    @app = app
+  end
+
+  def call(env)
+    start_request(env['PATH_INFO'], Time.now.utc)
+    @app.call(env)
+  ensure
+    complete_request
+  end
+
+  def start_request(path, started_on)
+    Thread.current[:current_request] = path
+    Thread.current[:current_request_started_on] = started_on
+  end
+
+  def complete_request
+    Thread.current[:current_request] = nil
+    Thread.current[:current_request_started_on] = nil
+  end
+
+  def self.long_running_requests
+    requests = []
+    timed_out_request_started_on = request_timeout.ago.utc
+
+    relevant_thread_list.each do |thread|
+      request    = thread[:current_request]
+      started_on = thread[:current_request_started_on]
+
+      # There's a race condition where the complete_request method runs in another
+      # thread after we set one or more of the above local variables. The fallout
+      # of this is we return a false positive for a request that finished very close
+      # to the 2 minute timeout.
+      if request.present? && started_on.kind_of?(Time) && timed_out_request_started_on > started_on
+        duration = (Time.now.utc - started_on).to_f
+        requests << [request, duration, thread]
+      end
+    end
+
+    requests
+  end
+
+  REQUEST_TIMEOUT = 2.minutes
+  private_class_method def self.request_timeout
+    REQUEST_TIMEOUT
+  end
+
+  # For testing: mocking Thread.list feels dangerous
+  private_class_method def self.relevant_thread_list
+    Thread.list
+  end
+end

spec/lib/request_started_on_middleware_spec.rb

@@ -0,0 +1,28 @@
+describe RequestStartedOnMiddleware do
+  context ".long_running_requests" do
+    before do
+      allow(described_class).to receive(:relevant_thread_list) { fake_threads }
+      allow(described_class).to receive(:request_timeout).and_return(2.minutes)
+    end
+
+    let(:fake_threads) { [@fake_thread] }
+
+    it "returns request, duration and thread" do
+      @fake_thread = {:current_request => "/api/ping", :current_request_started_on => 3.minutes.ago}
+      long_requests = described_class.long_running_requests.first
+      expect(long_requests[0]).to eql "/api/ping"
+      expect(long_requests[1]).to be_within(0.1).of(Time.now.utc - 3.minutes.ago)
+      expect(long_requests[2]).to eql @fake_thread
+    end
+
+    it "skips threads that haven't timed out yet" do
+      @fake_thread = {:current_request => "/api/ping", :current_request_started_on => 30.seconds.ago}
+      expect(described_class.long_running_requests).to be_empty
+    end
+
+    it "skips threads with no requests" do
+      @fake_thread = {}
+      expect(described_class.long_running_requests).to be_empty
+    end
+  end
+end