Use block syntax for log output

Refactor tests as the block syntax makes checking a little different. Ensure we have a test for exception_raised logging.
collectiveidea · Jan 14, 2025 · df249ea · df249ea
1 parent 55ba140
commit df249ea
Show file tree

Hide file tree

Showing 3 changed files with 30 additions and 27 deletions.
diff --git a/lib/twirp/rails/engine.rb b/lib/twirp/rails/engine.rb
@@ -53,19 +53,19 @@ def services
               service.send(hook_name, &hook)
             end
 
-            # Add our own logging hooks if verbose_logging is enabled
-            if ::Rails.application.config.twirp.verbose_logging
-              service.on_success do |env|
-                ::Rails.logger.debug("Twirp Response: #{env[:output].inspect}")
+            # Add our own logging hooks
+            service.on_success do |env|
+              if ::Rails.application.config.twirp.verbose_logging
+                ::Rails.logger.debug { "Twirp Response: #{env[:output].inspect}" }
               end
+            end
 
-              service.on_error do |error, _env|
-                ::Rails.logger.debug("Twirp Response: #{error.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
+            service.exception_raised do |exception, _env|
+              ::Rails.logger.error { "Twirp Exception (#{exception.class}: #{exception.message})\n#{exception.backtrace.join("\n")}" }
             end
           end
         end

diff --git a/lib/twirp/rails/logger.rb b/lib/twirp/rails/logger.rb
@@ -20,7 +20,7 @@ class Logger < ::Rack::CommonLogger
       def log(env, status, response_headers, began_at)
         content_type = response_headers["content-type"].presence
         content_encoding = response_headers["content-encoding"].presence
-        @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}")
+        @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 duration_in_ms(time)

diff --git a/spec/requests/haberdasher_spec.rb b/spec/requests/haberdasher_spec.rb
@@ -1,9 +1,11 @@
 require "spec_helper"
 
 RSpec.describe "Haberdasher Service", type: :request do
+  let!(:log) { StringIO.new }
+
   before do
-    allow(::Rails.logger).to receive(:info).and_call_original
-    allow(::Rails.logger).to receive(:debug).and_call_original
+    ::Rails.logger.broadcast_to(::Logger.new(log))
+    allow(log).to receive(:write).and_call_original
   end
 
   def make_hat_success_request
@@ -21,8 +23,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 \d+ms as application\/protobuf/)
-    expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')
+    expect(log).to have_received(:write).with(/INFO -- : Twirp 200 in \dms as application\/protobuf/)
+    expect(log).to have_received(:write).with(a_string_matching("DEBUG -- : Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: \"Tan\", name: \"Pork Pie\">"))
   end
 
   describe "error handling" do
@@ -39,8 +41,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 \d+ms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with("Twirp Response: <Twirp::Error code:invalid_argument msg:\"is too small\" meta:#{{argument: "inches"}}>") # standard:disable Lint/LiteralInInterpolation
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 400 in \d+ms as application\/json/)
+      expect(log).to have_received(:write).with(a_string_matching("DEBUG -- : Twirp Response: <Twirp::Error code:invalid_argument msg:\"is too small\" meta:#{{argument: "inches"}}>")) # standard:disable Lint/LiteralInInterpolation
     end
 
     it "allows a before_action to return a Twirp::Error" do
@@ -56,8 +58,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 \d+ms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with("Twirp Response: <Twirp::Error code:invalid_argument msg:\"is too big\" meta:#{{argument: "inches"}}>") # standard:disable Lint/LiteralInInterpolation
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 400 in \d+ms as application\/json/)
+      expect(log).to have_received(:write).with(a_string_matching("DEBUG -- : Twirp Response: <Twirp::Error code:invalid_argument msg:\"is too big\" meta:#{{argument: "inches"}}>")) # standard:disable Lint/LiteralInInterpolation
     end
 
     it "deals with unhandled exceptions" do
@@ -73,8 +75,9 @@ 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 \d+ms as application\/json/)
-      expect(::Rails.logger).to have_received(:debug).with("Twirp Response: <Twirp::Error code:internal msg:\"Contrived Example Error\" meta:#{{cause: "RuntimeError"}}>") # standard:disable Lint/LiteralInInterpolation
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 500 in \d+ms as application\/json/)
+      expect(log).to have_received(:write).with(/ERROR -- : Twirp Exception \(RuntimeError: Contrived Example Error\)\n.*in.*reject_giant_hats'/)
+      expect(log).to have_received(:write).with(a_string_matching("DEBUG -- : Twirp Response: <Twirp::Error code:internal msg:\"Contrived Example Error\" meta:#{{cause: "RuntimeError"}}>")) # standard:disable Lint/LiteralInInterpolation
     end
   end
 
@@ -136,8 +139,8 @@ def make_hat_success_request
       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 with content-encoding: gzip/)
-      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 200 in \d+ms as application\/protobuf with content-encoding: gzip/)
+      expect(log).to have_received(:write).with(a_string_matching('DEBUG -- : Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">'))
     end
 
     it "ignores injected middleware when inappropriate" do
@@ -168,8 +171,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/)
-      expect(::Rails.logger).to have_received(:debug).with('Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 200 in \d+ms as application\/protobuf/)
+      expect(log).to have_received(:write).with(a_string_matching('DEBUG -- : Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">'))
 
       post "/twirp/twirp.example.haberdasher.Haberdasher/MakeHat",
         params: size.to_proto, headers: {
@@ -179,8 +182,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: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">').twice # once from before, once for the 304
+      expect(log).to have_received(:write).with(/INFO -- : Twirp 304 in \d+ms/)
+      expect(log).to have_received(:write).with(a_string_matching('DEBUG -- : Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">')).twice # once from before, once for the 304
     end
   end