FEATURE: Allow registration of detailed request logger

Detailed request loggers can be used to gather rich timing info
from all requests (which in turn can be forwarded to monitoring solution)

Middleware::RequestTracker.detailed_request_logger(->|env, data| do
   # do stuff with env and data
end

lib/method_profiler.rb

@@ -0,0 +1,43 @@
+# see https://samsaffron.com/archive/2017/10/18/fastest-way-to-profile-a-method-in-ruby
+class MethodProfiler
+  def self.patch(klass, methods, name)
+    patches = methods.map do |method_name|
+      <<~RUBY
+      unless defined?(#{method_name}__mp_unpatched)
+        alias_method :#{method_name}__mp_unpatched, :#{method_name}
+        def #{method_name}(*args, &blk)
+          unless prof = Thread.current[:_method_profiler]
+            return #{method_name}__mp_unpatched(*args, &blk)
+          end
+          begin
+            start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+            #{method_name}__mp_unpatched(*args, &blk)
+          ensure
+            data = (prof[:#{name}] ||= {duration: 0.0, calls: 0})
+            data[:duration] += Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
+            data[:calls] += 1
+          end
+        end
+      end
+      RUBY
+    end.join("\n")
+
+    klass.class_eval patches
+  end
+
+  def self.start
+    Thread.current[:_method_profiler] = {
+      __start: Process.clock_gettime(Process::CLOCK_MONOTONIC)
+    }
+  end
+
+  def self.stop
+    finish = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+    if data = Thread.current[:_method_profiler]
+      Thread.current[:_method_profiler] = nil
+      start = data.delete(:__start)
+      data[:total_duration] = finish - start
+    end
+    data
+  end
+end

lib/middleware/request_tracker.rb

@@ -1,7 +1,43 @@
+# frozen_string_literal: true
+
 require_dependency 'middleware/anonymous_cache'
 
 class Middleware::RequestTracker
 
+  @@detailed_request_loggers = nil
+
+  # register callbacks for detailed request loggers called on every request
+  # example:
+  #
+  # Middleware::RequestTracker.detailed_request_logger(->|env, data| do
+  #   # do stuff with env and data
+  # end
+  def self.register_detailed_request_logger(callback)
+
+    unless @patched_instrumentation
+      require_dependency "method_profiler"
+      MethodProfiler.patch(PG::Connection, [
+        :exec, :async_exec, :exec_prepared, :send_query_prepared, :query
+      ], :sql)
+
+      MethodProfiler.patch(Redis::Client, [
+        :call, :call_pipeline
+      ], :redis)
+      @patched_instrumentation = true
+    end
+
+    (@@detailed_request_loggers ||= []) << callback
+  end
+
+  def self.unregister_detailed_request_logger(callback)
+    @@detailed_request_loggers.delete callback
+
+    if @@detailed_request_loggers.length == 0
+      @detailed_request_loggers = nil
+    end
+
+  end
+
   def initialize(app, settings = {})
     @app = app
   end
@@ -44,19 +80,17 @@ class Middleware::RequestTracker
 
   end
 
-  TRACK_VIEW = "HTTP_DISCOURSE_TRACK_VIEW".freeze
-  CONTENT_TYPE = "Content-Type".freeze
-  def self.get_data(env, result)
+  def self.get_data(env, result, timing)
     status, headers = result
     status = status.to_i
 
     helper = Middleware::AnonymousCache::Helper.new(env)
     request = Rack::Request.new(env)
 
-    env_track_view = env[TRACK_VIEW]
+    env_track_view = env["HTTP_DISCOURSE_TRACK_VIEW"]
     track_view = status == 200
-    track_view &&= env_track_view != "0".freeze && env_track_view != "false".freeze
-    track_view &&= env_track_view || (request.get? && !request.xhr? && headers[CONTENT_TYPE] =~ /text\/html/)
+    track_view &&= env_track_view != "0" && env_track_view != "false"
+    track_view &&= env_track_view || (request.get? && !request.xhr? && headers["Content-Type"] =~ /text\/html/)
     track_view = !!track_view
 
     {
@@ -65,22 +99,32 @@ class Middleware::RequestTracker
       has_auth_cookie: helper.has_auth_cookie?,
       is_background: request.path =~ /^\/message-bus\// || request.path == /\/topics\/timings/,
       is_mobile: helper.is_mobile?,
-      track_view: track_view
+      track_view: track_view,
+      timing: timing
     }
+
   end
 
   def call(env)
+    MethodProfiler.start if @@detailed_request_loggers
     result = @app.call(env)
+    info = MethodProfiler.stop if @@detailed_request_loggers
+    result
   ensure
 
     # we got to skip this on error ... its just logging
-    data = self.class.get_data(env, result) rescue nil
+    data = self.class.get_data(env, result, info) rescue nil
     host = RailsMultisite::ConnectionManagement.host(env)
 
     if data
       if result && (headers = result[1])
         headers["X-Discourse-TrackView"] = "1" if data[:track_view]
       end
+
+      if @@detailed_request_loggers
+        @@detailed_request_loggers.each { |logger| logger.call(env, data) }
+      end
+
       log_later(data, host)
     end
 

spec/components/middleware/request_tracker_spec.rb

@@ -21,7 +21,7 @@ describe Middleware::RequestTracker do
     def log_tracked_view(val)
       data = Middleware::RequestTracker.get_data(env(
         "HTTP_DISCOURSE_TRACK_VIEW" => val
-      ), ["200", { "Content-Type" => 'text/html' }])
+      ), ["200", { "Content-Type" => 'text/html' }], 0.2)
 
       Middleware::RequestTracker.log_request(data)
     end
@@ -40,19 +40,19 @@ describe Middleware::RequestTracker do
 
       data = Middleware::RequestTracker.get_data(env(
         "HTTP_USER_AGENT" => "AdsBot-Google (+http://www.google.com/adsbot.html)"
-      ), ["200", { "Content-Type" => 'text/html' }])
+      ), ["200", { "Content-Type" => 'text/html' }], 0.1)
 
       Middleware::RequestTracker.log_request(data)
 
       data = Middleware::RequestTracker.get_data(env(
         "HTTP_DISCOURSE_TRACK_VIEW" => "1"
-      ), ["200", {}])
+      ), ["200", {}], 0.1)
 
       Middleware::RequestTracker.log_request(data)
 
       data = Middleware::RequestTracker.get_data(env(
         "HTTP_USER_AGENT" => "Mozilla/5.0 (iPhone; CPU iPhone OS 8_1 like Mac OS X) AppleWebKit/600.1.4 (KHTML, like Gecko) Version/8.0 Mobile/12B410 Safari/600.1.4"
-      ), ["200", { "Content-Type" => 'text/html' }])
+      ), ["200", { "Content-Type" => 'text/html' }], 0.1)
 
       Middleware::RequestTracker.log_request(data)
 
@@ -65,5 +65,49 @@ describe Middleware::RequestTracker do
       expect(ApplicationRequest.page_view_crawler.first.count).to eq(1)
       expect(ApplicationRequest.page_view_anon_mobile.first.count).to eq(1)
     end
+
+  end
+
+  context "callbacks" do
+    def app(result, sql_calls: 0, redis_calls: 0)
+      lambda do |env|
+        sql_calls.times do
+          User.where(id: -100).first
+        end
+        redis_calls.times do
+          $redis.get("x")
+        end
+        result
+      end
+    end
+
+    let :logger do
+      ->(env, data) do
+        @env = env
+        @data = data
+      end
+    end
+
+    before do
+      Middleware::RequestTracker.register_detailed_request_logger(logger)
+    end
+
+    after do
+      Middleware::RequestTracker.register_detailed_request_logger(logger)
+    end
+
+    it "can correctly log detailed data" do
+      tracker = Middleware::RequestTracker.new(app([200, {}, []], sql_calls: 2, redis_calls: 2))
+      tracker.call(env)
+
+      timing = @data[:timing]
+      expect(timing[:total_duration]).to be > 0
+
+      expect(timing[:sql][:duration]).to be > 0
+      expect(timing[:sql][:calls]).to eq 2
+
+      expect(timing[:redis][:duration]).to be > 0
+      expect(timing[:redis][:calls]).to eq 2
+    end
   end
 end