Change up debug body logging again

* Move out of the Logger so we can output the response even when the actual response is gzip/brotli.
* Output Twirp objects rather than protobuf/json for readability.

lib/twirp/rails/engine.rb

@@ -45,9 +45,25 @@ def services
 
           # Install hooks that may be defined in the config
           @services.each do |service|
+            # Add user-defined hooks
             ::Rails.application.config.twirp.service_hooks.each do |hook_name, hook|
               service.send(hook_name, &hook)
             end
+
+            # Add our own logging hooks in debug mode
+            if ::Rails.logger.level == ::Logger::DEBUG
+              service.on_success do |env|
+                ::Rails.logger.debug("Twirp Response: #{env[:output].inspect}")
+              end
+
+              service.on_error do |error, _env|
+                ::Rails.logger.debug("Twirp Response: #{error.inspect}")
+              end
+
+              service.exception_raised do |exception, _env|
+                ::Rails.logger.debug("Twirp Exception (#{exception.class}: #{exception.message})\n#{exception.backtrace.join("\n")}")
+              end
+            end
           end
         end
 

lib/twirp/rails/logger.rb

@@ -11,20 +11,10 @@
 # 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 < ::Rack::CommonLogger
-      def call(env)
-        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)
@@ -33,11 +23,6 @@ def log(env, status, response_headers, began_at)
         @logger.info("Twirp #{status} in #{duration_in_ms(began_at)}ms#{" as #{content_type}" if content_type}#{" with content-encoding: #{content_encoding}" if content_encoding}")
       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)
         ((::Rack::Utils.clock_time - time) * 1000).to_i
       end

spec/requests/haberdasher_spec.rb

@@ -22,7 +22,7 @@ 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 \d+ms as application\/protobuf/)
-    expect(::Rails.logger).to have_received(:debug).with("Twirp Response: \b\x18\x12\x03Tan\x1A\bPork Pie")
+    expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')
   end
 
   describe "error handling" do
@@ -40,7 +40,7 @@ def make_hat_success_request
       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 \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"}}')
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Error code:invalid_argument msg:"is too small" meta:{argument: "inches"}>')
     end
 
     it "allows a before_action to return a Twirp::Error" do
@@ -57,7 +57,7 @@ def make_hat_success_request
       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 \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"}}')
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Error code:invalid_argument msg:"is too big" meta:{argument: "inches"}>')
     end
 
     it "deals with unhandled exceptions" do
@@ -74,7 +74,7 @@ def make_hat_success_request
       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 \d+ms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: {"code":"internal","msg":"Contrived Example Error","meta":{"cause":"RuntimeError"}}')
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Error code:internal msg:"Contrived Example Error" meta:{cause: "RuntimeError"}>')
     end
   end
 
@@ -137,7 +137,7 @@ def make_hat_success_request
       expect(response.headers["content-encoding"]).to eq("gzip")
 
       expect(::Rails.logger).to have_received(:info).with(/Twirp 200 in \d+ms as application\/protobuf with content-encoding: gzip/)
-      expect(::Rails.logger).not_to have_received(:debug) # No debug output when gzipped
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')
     end
 
     it "ignores injected middleware when inappropriate" do
@@ -168,6 +168,8 @@ def make_hat_success_request
       expect(decoded).to be_a(Twirp::Example::Haberdasher::Hat)
       expect(response.etag).to be_present
 
+      expect(::Rails.logger).to have_received(:info).with(/Twirp 200 in \d+ms as application\/protobuf/)
+
       post "/twirp/twirp.example.haberdasher.Haberdasher/MakeHat",
         params: size.to_proto, headers: {
           :accept => "application/protobuf",
@@ -177,7 +179,7 @@ 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")
+      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">').twice # once from before, once for the 304
     end
   end