Refactor logger and make it configurable

* Add it at the top of the middleware stack.
* Inherit from Leverage Rack::CommonLogger though we don't use common log format.
* Improve handling of response output in when log_level is :debug

lib/twirp/rails/configuration.rb

@@ -9,6 +9,9 @@ class Configuration
       # Where to mount twirp routes. Defaults to /twirp
       attr_accessor :endpoint
 
+      # Logger to use for Twirp requests. Defaults to Rails.logger
+      attr_accessor :logger
+
       # An array of directories to search for *_twirp.rb files
       # Defaults to ["lib"]
       attr_accessor :load_paths
@@ -25,6 +28,7 @@ def initialize
         @auto_mount = false
         @endpoint = "/twirp"
         @load_paths = ["lib"]
+        @logger = Logger
         @middleware = []
         @service_hooks = {}
       end

lib/twirp/rails/engine.rb

@@ -26,10 +26,10 @@ class Engine < ::Rails::Engine
           app.config.twirp.send(key)
         end
 
+        app.config.middleware.use app.config.twirp.logger, ::Rails.logger
         app.config.twirp.middleware.each do |middleware|
           app.config.middleware.use middleware
         end
-        app.config.middleware.use Logger
 
         # Load all Twirp files
         app.config.twirp.load_paths.each do |directory|

lib/twirp/rails/logger.rb

@@ -1,22 +1,44 @@
 # frozen_string_literal: true
 
+# Rack::CommonLogger is nice but we can do better.
+# Rails doesn't use it, but we need to log Twirp requests.
+# Here's an example from Rack::CommonLogger:
+#   127.0.0.1 - - [12/Jan/2025:17:09:49 -0500] "POST /twirp/twirp.example.haberdasher.Haberdasher/MakeHat HTTP/1.0" 200 - 439.0060
+#
+# Rails gives us this:
+#   Started POST "/twirp/twirp.example.haberdasher.Haberdasher/MakeHat" for 127.0.0.1 at 2025-01-12 22:48:00 -0500
+# but we also want to know the result of the Twirp call.
+# Here's what this Logger adds:
+#   Twirp 200 in 2ms as application/protobuf
+#
+# If the logger is in debug mode, it also outputs the response body.
+
 module Twirp
   module Rails
-    class Logger
-      def initialize(app)
-        @app = app
-      end
-
+    class Logger < ::Rack::CommonLogger
       def call(env)
-        start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
-        @app.call(env).tap do |response|
-          ::Rails.logger.info("Twirp #{response.first} in #{duration_in_ms(start_time)}ms as #{response.second["content-type"]}")
-          ::Rails.logger.debug(response.last.first) # Response body
+        super.tap do |(status, headers, body)|
+          # If the logger is in debug mode, log the response body.
+          if @logger.level == ::Logger::DEBUG && !::Rack::Utils::STATUS_WITH_NO_ENTITY_BODY[status] && headers["content-encoding"].nil?
+            log_response_body(body)
+          end
         end
       end
 
+      private
+
+      def log(env, status, response_headers, began_at)
+        content_type = response_headers["content-type"].presence
+        @logger.info("Twirp #{status} in #{duration_in_ms(began_at)}ms#{" as #{content_type}" if content_type}")
+      end
+
+      def log_response_body(body)
+        body = [body.to_str] if body.respond_to?(:to_str)
+        @logger.debug("Twirp Response: #{body.join}")
+      end
+
       def duration_in_ms(time)
-        ((::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - time) * 1000).to_i
+        ((::Rack::Utils.clock_time - time) * 1000).to_i
       end
     end
   end

spec/requests/haberdasher_spec.rb

@@ -21,8 +21,8 @@ def make_hat_success_request
 
   it "makes a hat" do
     make_hat_success_request
-    expect(::Rails.logger).to have_received(:info).with(/Twirp 200 in \dms as application\/protobuf/)
-    expect(::Rails.logger).to have_received(:debug).with("\b\x18\x12\x03Tan\x1A\bPork Pie")
+    expect(::Rails.logger).to have_received(:info).with(/Twirp 200 in \d+ms as application\/protobuf/)
+    expect(::Rails.logger).to have_received(:debug).with("Twirp Response: \b\x18\x12\x03Tan\x1A\bPork Pie")
   end
 
   describe "error handling" do
@@ -39,8 +39,8 @@ def make_hat_success_request
       expect(response.content_type).to eq("application/json")
       expect(response.body).to eq('{"code":"invalid_argument","msg":"is too small","meta":{"argument":"inches"}}')
 
-      expect(::Rails.logger).to have_received(:info).with(/Twirp 400 in \dms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with('{"code":"invalid_argument","msg":"is too small","meta":{"argument":"inches"}}')
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 400 in \d+ms as application\/json/)
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: {"code":"invalid_argument","msg":"is too small","meta":{"argument":"inches"}}')
     end
 
     it "allows a before_action to return a Twirp::Error" do
@@ -56,8 +56,8 @@ def make_hat_success_request
       expect(response.content_type).to eq("application/json")
       expect(response.body).to eq('{"code":"invalid_argument","msg":"is too big","meta":{"argument":"inches"}}')
 
-      expect(::Rails.logger).to have_received(:info).with(/Twirp 400 in \dms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with('{"code":"invalid_argument","msg":"is too big","meta":{"argument":"inches"}}')
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 400 in \d+ms as application\/json/)
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: {"code":"invalid_argument","msg":"is too big","meta":{"argument":"inches"}}')
     end
 
     it "deals with unhandled exceptions" do
@@ -73,8 +73,8 @@ def make_hat_success_request
       expect(response.content_type).to eq("application/json")
       expect(response.body).to eq('{"code":"internal","msg":"Contrived Example Error","meta":{"cause":"RuntimeError"}}')
 
-      expect(::Rails.logger).to have_received(:info).with(/Twirp 500 in \dms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with('{"code":"internal","msg":"Contrived Example Error","meta":{"cause":"RuntimeError"}}')
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 500 in \d+ms as application\/json/)
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: {"code":"internal","msg":"Contrived Example Error","meta":{"cause":"RuntimeError"}}')
     end
   end
 
@@ -133,8 +133,11 @@ def make_hat_success_request
           "Content-Type" => "application/protobuf",
           "Accept-Encoding" => "gzip" # ask for GZIP encoding
         }
-      expect(response.headers["Vary"]).to eq("Accept-Encoding")
-      expect(response.headers["Content-Encoding"]).to eq("gzip")
+      expect(response.headers["vary"]).to eq("Accept-Encoding")
+      expect(response.headers["content-encoding"]).to eq("gzip")
+
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 200 in \d+ms as application\/protobuf/)
+      expect(::Rails.logger).not_to have_received(:debug) # No debug output when gzipped
     end
 
     it "ignores injected middleware when inappropriate" do
@@ -173,6 +176,8 @@ def make_hat_success_request
         }
 
       expect(response.status).to eq(304)
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 304 in \d+ms/)
+      expect(::Rails.logger).to have_received(:debug).with("Twirp Response: \b\x18\x12\x03Tan\x1A\bPork Pie")
     end
   end