Hook in some basic logging to the service

.github/workflows/ci.yml

@@ -19,6 +19,7 @@ jobs:
           - 3.1
           - 3.2
           - 3.3
+          - 3.4
 
     env:
       RUBYOPT: --enable=frozen-string-literal

README.md

@@ -151,6 +151,23 @@ As an Engine, we avoid all the standard Rails middleware. That's nice for simpli
 Rails.application.config.twirp.middleware = [Rack::Deflater]
 ```
 
+### Logging
+
+Our built-in logging outputs the result of each request. 
+
+You could replace our logger if you want different output: 
+
+```ruby
+Rails.application.config.twirp.logger = Rack::CommonLogger
+```
+
+Additionally, you can log the Twirp response object to help with debugging: 
+
+```ruby
+# Defaults to true if your log_level is :debug
+Rails.application.config.twirp.verbose_logging = true
+```
+
 ## Bonus Features
 
 Outside the [Twirp spec](https://twitchtv.github.io/twirp/docs/spec_v7.html), we have some (optional) extra magic. They might be useful to you, but you can easily ignore them too.

lib/twirp/rails/configuration.rb

@@ -9,6 +9,14 @@ 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
+
+      # Whether to log Twirp responses. Defaults to true if log level is :debug
+      # Example:
+      #   Twirp Response: <Twirp::Example::Haberdasher::Hat: inches: 24, color: "Tan", name: "Pork Pie">
+      attr_accessor :verbose_logging
+
       # An array of directories to search for *_twirp.rb files
       # Defaults to ["lib"]
       attr_accessor :load_paths
@@ -25,6 +33,8 @@ def initialize
         @auto_mount = false
         @endpoint = "/twirp"
         @load_paths = ["lib"]
+        @logger = Logger
+        @verbose_logging = nil
         @middleware = []
         @service_hooks = {}
       end

lib/twirp/rails/engine.rb

@@ -26,6 +26,10 @@ class Engine < ::Rails::Engine
           app.config.twirp.send(key)
         end
 
+        # Set up logging
+        app.config.middleware.use app.config.twirp.logger, ::Rails.logger
+        app.config.twirp.verbose_logging = ::Rails.logger.level == ::Logger::DEBUG if app.config.twirp.verbose_logging.nil?
+
         app.config.twirp.middleware.each do |middleware|
           app.config.middleware.use middleware
         end
@@ -44,9 +48,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 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}")
+              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

@@ -0,0 +1,31 @@
+# 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
+#
+
+module Twirp
+  module Rails
+    class Logger < ::Rack::CommonLogger
+      private
+
+      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}")
+      end
+
+      def duration_in_ms(time)
+        ((::Rack::Utils.clock_time - time) * 1000).to_i
+      end
+    end
+  end
+end

spec/rails_app/app/handlers/haberdasher_handler.rb

@@ -31,6 +31,11 @@ def track_request_ip
 
   # contrived example of using a before_action
   def reject_giant_hats
+    # This specific size raises an un-rescued error
+    if request.inches == 1_234
+      raise "Contrived Example Error"
+    end
+
     if request.inches >= 1_000
       Twirp::Error.invalid_argument("is too big", argument: "inches")
     end

spec/requests/haberdasher_spec.rb

@@ -1,6 +1,11 @@
 require "spec_helper"
 
 RSpec.describe "Haberdasher Service", type: :request do
+  before do
+    allow(::Rails.logger).to receive(:info).and_call_original
+    allow(::Rails.logger).to receive(:debug).and_call_original
+  end
+
   def make_hat_success_request
     size = Twirp::Example::Haberdasher::Size.new(inches: 24)
 
@@ -16,6 +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 \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">')
   end
 
   describe "error handling" do
@@ -31,6 +38,9 @@ def make_hat_success_request
       expect(response.status).to eq(400)
       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
     end
 
     it "allows a before_action to return a Twirp::Error" do
@@ -45,6 +55,26 @@ def make_hat_success_request
       expect(response.status).to eq(400)
       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
+    end
+
+    it "deals with unhandled exceptions" do
+      size = Twirp::Example::Haberdasher::Size.new(inches: 1_234) # Special size that raises an exception
+
+      post "/twirp/twirp.example.haberdasher.Haberdasher/MakeHat",
+        params: size.to_proto, headers: {
+          :accept => "application/protobuf",
+          "Content-Type" => "application/protobuf"
+        }
+
+      expect(response.status).to eq(500)
+      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
     end
   end
 
@@ -103,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 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">')
     end
 
     it "ignores injected middleware when inappropriate" do
@@ -135,6 +168,9 @@ 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">')
+
       post "/twirp/twirp.example.haberdasher.Haberdasher/MakeHat",
         params: size.to_proto, headers: {
           :accept => "application/protobuf",
@@ -143,6 +179,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
     end
   end