From eea241a0926358b758f9b26acabdb8e746b4df87 Mon Sep 17 00:00:00 2001 From: Denis Talakevich Date: Fri, 29 May 2026 18:41:09 +0300 Subject: [PATCH] debug log sent/received payload --- CHANGELOG.md | 5 ++++ README.md | 4 +-- lib/jrpc.rb | 1 + lib/jrpc/payload_logging.rb | 19 ++++++++++++++ lib/jrpc/shared_client/transport_loop.rb | 10 ++++++- lib/jrpc/simple_client.rb | 9 +++++++ spec/shared_client/fiber_spec.rb | 2 +- spec/shared_client_spec.rb | 29 ++++++++++++++++++--- spec/simple_client_spec.rb | 33 ++++++++++++++++++++++++ 9 files changed, 104 insertions(+), 8 deletions(-) create mode 100644 lib/jrpc/payload_logging.rb diff --git a/CHANGELOG.md b/CHANGELOG.md index 6aa5be2..9496361 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/README.md b/README.md index a8c1371..184e989 100644 --- a/README.md +++ b/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]) diff --git a/lib/jrpc.rb b/lib/jrpc.rb index 0e990f5..446a80d 100644 --- a/lib/jrpc.rb +++ b/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' diff --git a/lib/jrpc/payload_logging.rb b/lib/jrpc/payload_logging.rb new file mode 100644 index 0000000..3c2e951 --- /dev/null +++ b/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 diff --git a/lib/jrpc/shared_client/transport_loop.rb b/lib/jrpc/shared_client/transport_loop.rb index 65ecb75..51fb35b 100644 --- a/lib/jrpc/shared_client/transport_loop.rb +++ b/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 diff --git a/lib/jrpc/simple_client.rb b/lib/jrpc/simple_client.rb index 9d8beab..f746774 100644 --- a/lib/jrpc/simple_client.rb +++ b/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 diff --git a/spec/shared_client/fiber_spec.rb b/spec/shared_client/fiber_spec.rb index 2d6c3ba..04867d2 100644 --- a/spec/shared_client/fiber_spec.rb +++ b/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) diff --git a/spec/shared_client_spec.rb b/spec/shared_client_spec.rb index 88d945e..85a73bf 100644 --- a/spec/shared_client_spec.rb +++ b/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 diff --git a/spec/simple_client_spec.rb b/spec/simple_client_spec.rb index c425d1e..f48a56b 100644 --- a/spec/simple_client_spec.rb +++ b/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