diff --git a/app/models/mixins/miq_web_server_runner_mixin.rb b/app/models/mixins/miq_web_server_runner_mixin.rb index 59a46dd2791..45a62576936 100644 --- a/app/models/mixins/miq_web_server_runner_mixin.rb +++ b/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 diff --git a/config/application.rb b/config/application.rb index 987b239012d..98f5674d3cf 100644 --- a/config/application.rb +++ b/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. diff --git a/lib/request_started_on_middleware.rb b/lib/request_started_on_middleware.rb new file mode 100644 index 00000000000..25e1f597b17 --- /dev/null +++ b/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.zone.now) + @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 = [] + allowable_request_start_time = long_request.ago + + 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) && started_on < allowable_request_start_time + duration = (Time.zone.now - started_on).to_f + requests << [request, duration, thread] + end + end + + requests + end + + LONG_REQUEST = 1.minute + private_class_method def self.long_request + LONG_REQUEST + end + + # For testing: mocking Thread.list feels dangerous + private_class_method def self.relevant_thread_list + Thread.list + end +end diff --git a/spec/lib/request_started_on_middleware_spec.rb b/spec/lib/request_started_on_middleware_spec.rb new file mode 100644 index 00000000000..ffe59f50b8a --- /dev/null +++ b/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