debug log sent/received payload

CHANGELOG.md

@@ -4,6 +4,11 @@
 
 **New**
 
+* Debug-level wire-payload logging. When a `logger:` is configured, both
+  `SimpleClient` and `SharedClient` emit every request/response payload (the raw
+  JSON frame, exactly as written/read) at `DEBUG`, tagged `[JRPC::SimpleClient]`
+  / `[JRPC::SharedClient]` with `>>` (sent) / `<<` (received) markers. No logger,
+  no logging.
 * `JRPC::Transport::Test` — an in-process transport double for testing code that
   uses JRPC, without a real server. Not required by default: `require
   'jrpc/transport/test'`, then inject via `transport:` on either client. Stub

README.md

@@ -41,7 +41,7 @@ client = JRPC::SimpleClient.new(
   autoclose:           false, # close the socket after every call
   id_prefix:           nil,   # random per instance if nil
   tcp_md5_pass:        nil,   # RFC2385 TCP MD5 Signature key (Linux-only); nil disables
-  logger:              nil
+  logger:              nil    # when set, logs every wire payload at DEBUG; nil disables
 )
 
 result = client.request(:sum, [1, 2])
@@ -77,7 +77,7 @@ client = JRPC::SharedClient.new(
   max_queue_size:         10_000, # bounded; pass nil for unbounded (opt-in OOM risk)
   id_prefix:              nil,
   tcp_md5_pass:           nil,    # RFC2385 TCP MD5 Signature key (Linux-only); nil disables
-  logger:                 nil
+  logger:                 nil     # when set, logs every wire payload at DEBUG; nil disables
 )
 
 result = client.request(:sum, [1, 2])

lib/jrpc.rb

@@ -7,6 +7,7 @@
 require 'jrpc/errors'
 require 'jrpc/id_generator'
 require 'jrpc/message'
+require 'jrpc/payload_logging'
 require 'jrpc/transport'
 require 'jrpc/simple_client'
 require 'jrpc/shared_client/ticket'

lib/jrpc/payload_logging.rb

@@ -0,0 +1,19 @@
+# frozen_string_literal: true
+
+module JRPC
+  # Debug-level wire-payload logging shared by the clients. When a `logger` is
+  # configured, every request/response payload (the raw JSON netstring body,
+  # exactly as written/read) is emitted at DEBUG. Without a logger it is a no-op.
+  module PayloadLogging
+    SEND_MARK = '>>'
+    RECV_MARK = '<<'
+
+    def log_sent(payload)
+      @logger&.debug("[#{log_tag}] #{SEND_MARK} #{payload}")
+    end
+
+    def log_received(payload)
+      @logger&.debug("[#{log_tag}] #{RECV_MARK} #{payload}")
+    end
+  end
+end

lib/jrpc/shared_client/transport_loop.rb

@@ -3,6 +3,8 @@
 module JRPC
   class SharedClient
     class TransportLoop
+      include PayloadLogging
+
       SELECT_FLOOR = 60.0
 
       def initialize(
@@ -130,6 +132,7 @@ def flush_one_outbound
         end
 
         begin
+          log_sent(ticket.payload)
           @transport.write_frame(ticket.payload, timeout: @write_timeout)
         rescue Transport::Base::Timeout => e
           err = Errors::Timeout.new("write timeout: #{e.message}")
@@ -170,6 +173,7 @@ def consume_inbound
           break if frame == :wait
 
           @last_rx_at = clock_now
+          log_received(frame)
 
           begin
             parsed = Message.parse(frame)
@@ -283,7 +287,11 @@ def signal_or_log(ticket, err)
       end
 
       def log_error(msg)
-        @logger&.error("[JRPC::SharedClient] #{msg}")
+        @logger&.error("[#{log_tag}] #{msg}")
+      end
+
+      def log_tag
+        'JRPC::SharedClient'
       end
     end
   end

lib/jrpc/simple_client.rb

@@ -6,6 +6,8 @@ module JRPC
   # concurrent calls would interleave socket reads/writes and corrupt the framing
   # buffer. Use one instance per thread/fiber (or a pool of instances).
   class SimpleClient
+    include PayloadLogging
+
     attr_reader :server
 
     def initialize(server, **options)
@@ -31,8 +33,10 @@ def request(method, params = nil, read_timeout: @read_timeout, write_timeout: @w
 
       with_transport_error_handling do
         connect_if_needed!
+        log_sent(json)
         @transport.write_frame(json, timeout: write_timeout)
         raw = @transport.read_frame(timeout: read_timeout)
+        log_received(raw)
         response = Message.parse(raw)
         Message.validate_response!(response, id)
         raise Message.error_to_exception(response['error']) if response.key?('error')
@@ -48,6 +52,7 @@ def notification(method, params = nil, write_timeout: @write_timeout)
 
       with_transport_error_handling do
         connect_if_needed!
+        log_sent(json)
         @transport.write_frame(json, timeout: write_timeout)
         nil
       end
@@ -67,6 +72,10 @@ def closed?
 
     private
 
+    def log_tag
+      'JRPC::SimpleClient'
+    end
+
     def connect_if_needed!
       @transport.connect if @transport.closed?
     end

spec/shared_client/fiber_spec.rb

@@ -127,7 +127,7 @@ def auto_responder(count:, timeout: 3.0)
   end
 
   describe 'cancellation' do
-    let(:logger) { instance_double(Logger, error: nil) }
+    let(:logger) { instance_double(Logger, error: nil, debug: nil) }
 
     it 'cancels the ticket and orphans a late response when the fiber is stopped (Task#stop)' do
       client = build_client(logger: logger)

spec/shared_client_spec.rb

@@ -308,7 +308,7 @@ def build_client(**opts)
 
   describe 'orphan and server-initiated messages' do
     it 'logs and drops a response for an unknown id without crashing' do
-      logger = instance_double(Logger, error: nil)
+      logger = instance_double(Logger, error: nil, debug: nil)
       c = build_client(logger: logger)
       transport.inject_response(ok_response('unknown-99', 42))
       sleep 0.05
@@ -317,7 +317,7 @@ def build_client(**opts)
     end
 
     it 'drops a server-initiated notification (no id) without crashing' do
-      logger = instance_double(Logger, error: nil)
+      logger = instance_double(Logger, error: nil, debug: nil)
       c = build_client(logger: logger)
       transport.inject_response(JSON.generate({ 'jsonrpc' => '2.0', 'method' => 'ping' }))
       sleep 0.05
@@ -344,10 +344,31 @@ def build_client(**opts)
     end
   end
 
+  # ── debug payload logging ──────────────────────────────────────────────────
+
+  describe 'debug payload logging' do
+    let(:logger) { instance_double(Logger, error: nil, debug: nil) }
+    let(:client) { build_client(logger: logger) }
+
+    it 'logs the sent and received raw payloads at debug' do
+      result = nil
+      caller = Thread.new { result = client.request(:sum, [1, 2]) }
+      wait_for { transport.frames_written.size >= 1 }
+      transport.inject_response(ok_response('test-1', 42))
+      caller.join(2)
+
+      expect(result).to eq(42)
+      expect(logger).to have_received(:debug)
+        .with('[JRPC::SharedClient] >> {"jsonrpc":"2.0","method":"sum","id":"test-1","params":[1,2]}')
+      expect(logger).to have_received(:debug)
+        .with("[JRPC::SharedClient] << #{ok_response('test-1', 42)}")
+    end
+  end
+
   # ── caller-thread interruption (Thread#raise mid-wait) ─────────────────────
 
   describe 'caller interrupted while waiting' do
-    let(:logger) { instance_double(Logger, error: nil) }
+    let(:logger) { instance_double(Logger, error: nil, debug: nil) }
     let(:client) { build_client(logger: logger) }
 
     it 'cancels the ticket, cleans up the registry, and treats a late response as orphan' do
@@ -471,7 +492,7 @@ def build_client(**opts)
   # ── transport-thread crash ─────────────────────────────────────────────────
 
   describe 'transport-thread crash' do
-    let(:logger) { instance_double(Logger, error: nil) }
+    let(:logger) { instance_double(Logger, error: nil, debug: nil) }
     let(:client) { build_client(logger: logger) }
 
     # A non-transport StandardError from write_frame is not caught by the loop's

spec/simple_client_spec.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require 'logger'
+
 # Minimal transport double that records activity and lets tests configure outcomes.
 class TransportDouble
   attr_reader :connects, :closes, :frames_written
@@ -386,4 +388,35 @@ def error_response(id, code, message)
       end
     end
   end
+
+  # ── debug payload logging ───────────────────────────────────────────────────
+
+  describe 'debug payload logging' do
+    # Minimal logger spy recording debug lines.
+    let(:logger) { instance_spy(Logger) }
+
+    it 'logs sent and received raw payloads at debug when a logger is set' do
+      transport.queue_response(ok_response('test-1', 99))
+      described_class.new('127.0.0.1:1234', transport: transport, id_prefix: 'test', logger: logger)
+                     .request('sum', [1, 2])
+
+      expect(logger).to have_received(:debug)
+        .with('[JRPC::SimpleClient] >> {"jsonrpc":"2.0","method":"sum","id":"test-1","params":[1,2]}')
+      expect(logger).to have_received(:debug)
+        .with("[JRPC::SimpleClient] << #{ok_response('test-1', 99)}")
+    end
+
+    it 'logs the sent notification payload' do
+      described_class.new('127.0.0.1:1234', transport: transport, id_prefix: 'test', logger: logger)
+                     .notification('log', { 'msg' => 'hi' })
+
+      expect(logger).to have_received(:debug)
+        .with('[JRPC::SimpleClient] >> {"jsonrpc":"2.0","method":"log","params":{"msg":"hi"}}')
+    end
+
+    it 'does not raise and logs nothing when no logger is set' do
+      transport.queue_response(ok_response('test-1', 1))
+      expect { client.request('ping') }.not_to raise_error
+    end
+  end
 end