Skip to content

Commit e085225

Browse files
skunkworkerclaude
andcommitted
Fix nats-pure migration regressions and release 0.13.1
Fixes a production 500 (RPC_ERROR / "EOF") and a set of related issues, all of the same class: assumptions left over from the JNats -> nats-pure migration in 0.13.0 that became silently wrong. Each fix ships with negative/regression specs; a benchmark proves the performance/robustness wins. Client / transport - Dropped-connection retries were silently disabled. Removing JNats collapsed Errors::IOException to the never-raised MriIOException, so the client's reconnect/retry rescue became dead code and a dropped NATS connection escaped immediately as an RPC_ERROR (Rails 500) with no retry. The client now rescues the transport errors nats-pure and the socket layer actually raise (EOFError, IOError, Errno::ECONNRESET/EPIPE/ECONNREFUSED/ETIMEDOUT, NATS::IO::ConnectionClosedError, and java.io.IOException on JRuby) via Errors::RETRYABLE_TRANSPORT_ERRORS, routed through the reconnect_delay loop. - Removed the dead :disable_reconnect_buffer connect option (a JNats concept nats-pure silently ignores). - Connection lifecycle: register callbacks before connect so handshake events are observed; close the half-open client on a failed handshake so nats-pure reader/flusher threads aren't leaked. Response muxer (performance + robustness) - Drop the per-message pending_size lock from the dispatch hot path. Instead of mirroring nats-pure's synchronized pending_size increments with a synchronized decrement per message, disable the byte-based slow-consumer limit on the response subscription and rely on the message-count limit (SizedQueue depth, tracked accurately for free). ~2.7x faster per-message dispatch on JRuby and removes the pending_size-drift bug that could silently drop all responses. - Guard the dispatch loop against a nil @resp_sub during restart so it parks instead of busy-spinning on NoMethodError (which logged an error and fired an error callback every iteration). ~0.2% of the old wasted work. - Make the dispatcher self-healing crash counter a Concurrent::AtomicFixnum that decays once healthy (a plain Integer lost ~45% of updates under concurrent crashes on JRuby, corrupting the exponential backoff). Server - Publish an encoded RPC_ERROR response (via Protobuf::Rpc::PbError) when a request fails after it has been ACKed, so the client fails fast instead of blocking until response_timeout. Config - Don't crash when the yml has no section for the current environment (or is empty); fall back to defaults. Docs / bench - Document the client's transient-error retry / resilience behavior in the README. - Add bench/muxer_resilience_bench.rb (measures old vs new in one process) and document it in bench/bench.md. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent c77a5e5 commit e085225

17 files changed

Lines changed: 504 additions & 47 deletions

CHANGELOG.md

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,17 @@
11
## Changelog
22

3+
### 0.13.1
4+
Fixes a production regression and a set of related issues, all of the same class: assumptions left over from the JNats → nats-pure migration in 0.13.0 that became silently wrong.
5+
6+
- **Dropped-connection retries were silently disabled.** Dropping JNats collapsed `Errors::IOException` to the never-raised `MriIOException`, so the client's reconnect/retry `rescue` became dead code. A dropped NATS connection then escaped immediately as an `RPC_ERROR` (surfacing as a 500) instead of being retried. The client now rescues the transport errors `nats-pure` and the socket layer actually raise (`EOFError`, `IOError`, `Errno::ECONNRESET`/`EPIPE`/`ECONNREFUSED`/`ETIMEDOUT`, `NATS::IO::ConnectionClosedError`, and `java.io.IOException` on JRuby) via `Errors::RETRYABLE_TRANSPORT_ERRORS` and rides them out with the existing `reconnect_delay` retry loop.
7+
- **Response muxer `pending_size` drift (could silently drop all responses).** nats-pure increments a subscription's `pending_size` (synchronized) for every inbound message and uses it to enforce the slow-consumer byte limit; for a callback-less subscription it never decrements it, so the muxer would be the sole consumer. Rather than mirror that accounting with a lock on every message, the muxer now **disables the byte-based limit** on its response subscription and relies on the message-count limit (the `SizedQueue` depth, tracked accurately for free). This removes the per-message lock from the dispatch hot path (~**2.7× faster** per message on JRuby — see `bench/muxer_resilience_bench.rb`) and eliminates the drift bug entirely.
8+
- **Dispatcher no longer busy-spins during a restart window.** If `@resp_sub` was briefly `nil` while the muxer restarted, the dispatch loop raised `NoMethodError` every iteration — busy-spinning and emitting a logged error + error-callback per spin. It now parks briefly (~0.2% of the old wasted work, zero errors).
9+
- **Self-healing backoff counter is now thread-safe.** The shared dispatcher crash counter was a plain `Integer` mutated by multiple dispatcher threads (it lost ~45% of updates under true parallelism on JRuby, corrupting the exponential backoff). It is now a `Concurrent::AtomicFixnum` that decays once a dispatcher is healthy.
10+
- **Client connection lifecycle hardening.** Connection callbacks (`on_disconnect`/`on_reconnect`/`on_close`/`on_error`) are now registered before `connect`, so handshake-time events are observed; and a failed handshake closes the half-open client so nats-pure's reader/flusher threads aren't leaked.
11+
- **Removed the dead `:disable_reconnect_buffer` connect option.** nats-pure has no such option (it was a JNats concept), so it was silently ignored. Transient disconnects are now handled by the client's transport-error retry path and `ack_timeout`.
12+
- **Server no longer leaves clients hanging on handler/publish failure.** If processing a request fails after the ACK was sent, the server now publishes an encoded `RPC_ERROR` response so the client fails fast instead of blocking until `response_timeout` (60s).
13+
- **Config no longer crashes when the YAML file has no section for the current environment** (or is empty); it falls back to defaults.
14+
315
### 0.13.0
416
This is a large overhaul of the client and server internals.
517

README.md

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ used to allow JVM based servers to warm-up slowly to prevent jolts in runtime pe
5050

5151
`PB_NATS_CLIENT_RESPONSE_TIMEOUT` - Seconds to wait for a non-ACK response from the rpc server (default: 60 seconds).
5252

53-
`PB_NATS_CLIENT_RECONNECT_DELAY` - If we detect a reconnect delay, we will wait this many seconds (default: the ACK timeout).
53+
`PB_NATS_CLIENT_RECONNECT_DELAY` - When a request hits a transient transport error (e.g. the NATS connection drops or is reset), the client sleeps this many seconds before retrying — up to 3 attempts — to give the connection time to re-establish (default: the ACK timeout). See [Resilience](#resilience).
5454

5555
`PB_NATS_CLIENT_SUBSCRIPTION_POOL_SIZE` - If subscription pooling is desired for the request/response cycle then the pool size maximum should be set; the pool is lazy and therefore will only start new subscriptions as necessary (default: 0)
5656

@@ -162,10 +162,30 @@ If we were to add another service endpoint called `search` to the `UserService`
162162
- **ResponseMuxer** (`lib/protobuf/nats/response_muxer.rb`) — the client uses a single wildcard subscription to multiplex
163163
all RPC responses (similar to the Golang NATS client) instead of subscribing/unsubscribing per request. One or more
164164
dispatcher threads drain the shared subscription and route each reply to the waiting caller via a `Concurrent::Map`,
165-
keyed by a UUIDv7 request token. Tune the dispatcher count with `PB_NATS_RESPONSE_MUXER_DISPATCHERS`.
165+
keyed by a UUIDv7 request token. Tune the dispatcher count with `PB_NATS_RESPONSE_MUXER_DISPATCHERS`. Slow-consumer
166+
protection on the response subscription is by message count (the queue depth); the dispatch hot path does no per-message
167+
locking. Dispatcher threads self-heal: a crashed dispatcher is restarted with exponential backoff (capped at 60s) that
168+
decays once healthy.
166169
- **SuperSubscriptionManager** (`lib/protobuf/nats/super_subscription_manager.rb`) — the server manages the lifecycle of
167170
RPC endpoint subscriptions, including slow start, pausing, and resubscription.
168171

172+
## Resilience
173+
174+
The client is built to ride out transient NATS hiccups rather than surface them as request failures:
175+
176+
- **Transient transport errors are retried.** If a request hits a dropped/reset/closed connection (`EOFError`,
177+
`IOError`, `Errno::ECONNRESET`/`EPIPE`/`ECONNREFUSED`/`ETIMEDOUT`, `NATS::IO::ConnectionClosedError`, or a Java
178+
`IOException` on JRuby — see `Errors::RETRYABLE_TRANSPORT_ERRORS`), the client sleeps `PB_NATS_CLIENT_RECONNECT_DELAY`
179+
and retries (up to 3 attempts) while `nats-pure` re-establishes the connection in the background.
180+
- **Missing ACKs and NACKs are retried** with their own timeouts/backoff (`PB_NATS_CLIENT_ACK_TIMEOUT`,
181+
`PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS`).
182+
- **Server-side failures fail the caller fast.** If the server cannot process a request after it has ACKed, it publishes
183+
an encoded RPC error response so the client raises immediately instead of blocking until `PB_NATS_CLIENT_RESPONSE_TIMEOUT`.
184+
- **The response dispatcher self-heals.** A crashed muxer dispatcher restarts with exponential backoff, and a brief
185+
subscription-restart window won't busy-spin the dispatch loop.
186+
187+
See `bench/muxer_resilience_bench.rb` for microbenchmarks of the dispatch hot path and these resilience paths.
188+
169189
## Future Improvements (locked behind ruby version)
170190
- Migrate from the `uuid7` gem to native `Random#uuid_v7` once the minimum Ruby version supports it (see `UUIDv7Helper`).
171191

bench/bench.md

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,20 @@
1+
## Benchmarks
2+
3+
- `bench/concurrency_bench.rb` — end-to-end hot-path throughput (muxer round-trip,
4+
subscription-key cache, thread pool) across thread counts. No NATS server needed.
5+
- `bench/muxer_resilience_bench.rb` — measures the response-muxer hot-path and
6+
self-healing fixes (both old/baseline and new/patched behavior in one process):
7+
- **A. Dispatch hot-path** — per-message `pending_size` accounting that was
8+
removed; the dispatch step is ~**2.7× faster** per message on JRuby once the
9+
per-message subscription lock is gone.
10+
- **B. nil-`@resp_sub` resilience** — during a restart window the old loop
11+
busy-spun (a `NoMethodError` + logged error/callback every iteration); the new
12+
loop parks, doing **~0.2%** of the old wasted work and emitting **0** errors.
13+
- **C. Self-healing crash counter** — a plain Integer mutated by N dispatcher
14+
threads loses ~**45%** of updates on JRuby (corrupting the exponential backoff);
15+
the `Concurrent::AtomicFixnum` replacement loses none.
16+
17+
Run: `bundle exec ruby -Ilib bench/muxer_resilience_bench.rb`
118

219
Notes:
320
`-Xjit.threshold=0` - Setting the threshold to 0 forces JRuby to compile every method into Java bytecode immediately before its very first execution. This is particularly useful for debugging or bypassing warm-up times during profiling

bench/muxer_resilience_bench.rb

Lines changed: 151 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,151 @@
1+
# Benchmarks for the response-muxer hot-path and self-healing changes.
2+
#
3+
# This file measures BOTH the old (baseline) and new (patched) behavior in one
4+
# process so the speedup/robustness delta is reproducible on CRuby and JRuby
5+
# without a NATS server:
6+
#
7+
# A. Dispatch hot-path cost -- per-message pending_size accounting that was
8+
# removed (#1). benchmark-ips, lower is better.
9+
# B. nil-@resp_sub resilience -- busy-spin vs park during a restart window (#3).
10+
# C. Self-healing counter -- lost updates with a plain int vs AtomicFixnum
11+
# under concurrent crashes (#4).
12+
#
13+
# Usage:
14+
# bundle exec ruby -Ilib bench/muxer_resilience_bench.rb
15+
16+
require "bundler/setup"
17+
require "benchmark/ips"
18+
require "concurrent"
19+
require "nats/client" # real NATS::Subscription / NATS::Msg
20+
21+
def mono
22+
::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
23+
end
24+
25+
puts "=" * 72
26+
puts "protobuf-nats response-muxer resilience bench"
27+
puts "engine=#{RUBY_ENGINE} #{RUBY_VERSION} processor_count=#{::Concurrent.processor_count}"
28+
puts "=" * 72
29+
30+
# --------------------------------------------------------------------------
31+
# A. Dispatch hot-path: per-message pending_size accounting (removed in #1).
32+
#
33+
# Old dispatch did `sub.synchronize { sub.pending_size -= msg.data.size }` for
34+
# EVERY response message; the new code does nothing here. We compare the old
35+
# accounting step against the cheapest real per-message op (a Concurrent::Map
36+
# lookup, which the dispatcher still does) so the delta is the lock overhead we
37+
# removed from the hot path.
38+
# --------------------------------------------------------------------------
39+
puts "\nA. Dispatch hot-path per-message overhead (higher ips = better)\n\n"
40+
41+
sub = ::NATS::Subscription.new
42+
sub.pending_size = 0
43+
resp_map = ::Concurrent::Map.new
44+
resp_map["tok"] = { :queue => ::Queue.new }
45+
size = 64
46+
47+
Benchmark.ips do |x|
48+
x.config(:time => 3, :warmup => 1)
49+
50+
x.report("old: synchronize { pending_size -= n } + map lookup") do
51+
sub.synchronize { sub.pending_size -= size }
52+
resp_map["tok"]
53+
end
54+
55+
x.report("new: map lookup only (accounting removed)") do
56+
resp_map["tok"]
57+
end
58+
59+
x.compare!
60+
end
61+
62+
# --------------------------------------------------------------------------
63+
# B. nil-@resp_sub resilience (#3). During a restart @resp_sub can briefly be
64+
# nil. The old loop dereferenced it unconditionally (NoMethodError every
65+
# iteration -> busy-spin + a logged error/callback per spin); the new loop
66+
# parks. We run each for a fixed window and count iterations and "errors that
67+
# would be logged/dispatched to callbacks".
68+
# --------------------------------------------------------------------------
69+
puts "\nB. Behavior while @resp_sub is nil for #{(WINDOW = 0.5)}s (lower spin = better)\n\n"
70+
71+
def run_old_loop(window)
72+
resp_sub = nil # the restart window
73+
iters = 0
74+
errors = 0
75+
deadline = mono + window
76+
while mono < deadline
77+
begin
78+
resp_sub.pending_queue.pop # NoMethodError on nil
79+
rescue => _e
80+
errors += 1 # old code logs + notify_error_callbacks here
81+
end
82+
iters += 1
83+
end
84+
[iters, errors]
85+
end
86+
87+
def run_new_loop(window)
88+
resp_sub = nil
89+
iters = 0
90+
errors = 0
91+
deadline = mono + window
92+
while mono < deadline
93+
s = resp_sub
94+
if s.nil?
95+
sleep 0.01 # park instead of spinning
96+
iters += 1
97+
next
98+
end
99+
begin
100+
s.pending_queue.pop
101+
rescue => _e
102+
errors += 1
103+
end
104+
iters += 1
105+
end
106+
[iters, errors]
107+
end
108+
109+
old_iters, old_errs = run_old_loop(WINDOW)
110+
new_iters, new_errs = run_new_loop(WINDOW)
111+
112+
printf(" old loop: %12d iterations, %12d errors logged/dispatched\n", old_iters, old_errs)
113+
printf(" new loop: %12d iterations, %12d errors logged/dispatched\n", new_iters, new_errs)
114+
printf(" => new loop does %.5f%% of the old loop's wasted work\n",
115+
old_iters.zero? ? 0.0 : (new_iters.to_f / old_iters * 100))
116+
117+
# --------------------------------------------------------------------------
118+
# C. Self-healing crash counter (#4). The old counter was a plain Integer
119+
# mutated by multiple dispatcher threads (`@crash_count = (@crash_count||0)+1`),
120+
# which loses updates under true parallelism, corrupting the exponential
121+
# backoff. The new counter is a Concurrent::AtomicFixnum. We have N threads each
122+
# "crash" K times and check the final count.
123+
# --------------------------------------------------------------------------
124+
puts "\nC. Crash-counter accuracy under concurrent crashes (expected == actual is correct)\n\n"
125+
126+
def hammer(counter, threads, per_thread)
127+
ts = threads.times.map do
128+
::Thread.new do
129+
per_thread.times { counter.call }
130+
end
131+
end
132+
ts.each(&:join)
133+
end
134+
135+
threads = [::Concurrent.processor_count, 4].max
136+
per_thread = 50_000
137+
expected = threads * per_thread
138+
139+
# Old: plain integer read-modify-write (racy).
140+
plain = 0
141+
hammer(->{ plain = plain + 1 }, threads, per_thread)
142+
143+
# New: atomic increment.
144+
atomic = ::Concurrent::AtomicFixnum.new(0)
145+
hammer(->{ atomic.increment }, threads, per_thread)
146+
147+
printf(" threads=%d per_thread=%d expected=%d\n", threads, per_thread, expected)
148+
printf(" old plain Integer: %10d (lost %d updates)\n", plain, expected - plain)
149+
printf(" new AtomicFixnum: %10d (lost %d updates)\n", atomic.value, expected - atomic.value)
150+
151+
puts "\ndone."

lib/protobuf/nats.rb

Lines changed: 19 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -84,15 +84,16 @@ def self.start_client_nats_connection
8484
GET_CONNECTED_MUTEX.synchronize do
8585
break true if @client_nats_connection
8686

87-
# Disable publisher pending buffer on reconnect
88-
options = config.connection_options.merge(:disable_reconnect_buffer => true)
87+
# NOTE: nats-pure has no :disable_reconnect_buffer option (it was a
88+
# jnats concept). During a reconnect nats-pure buffers publishes and,
89+
# if the connection is fully closed, raises ConnectionClosedError --
90+
# both of which the client's transient-error retry path now handles.
91+
options = config.connection_options
8992

9093
client = NatsClient.new
91-
client.connect(options)
92-
93-
# Ensure we have a valid connection to the NATS server.
94-
client.flush(5)
9594

95+
# Register lifecycle callbacks BEFORE connecting so a disconnect or
96+
# error during the initial handshake is still observed.
9697
client.on_disconnect do
9798
logger.warn("Client NATS connection was disconnected")
9899
end
@@ -109,6 +110,18 @@ def self.start_client_nats_connection
109110
notify_error_callbacks(error)
110111
end
111112

113+
begin
114+
client.connect(options)
115+
# Ensure we have a valid connection to the NATS server.
116+
client.flush(5)
117+
rescue => e
118+
# A failed handshake can leave nats-pure's reader/flusher threads
119+
# running on a half-open client; close it so we don't leak them, then
120+
# surface the failure (the next call will retry with a fresh client).
121+
client.close rescue nil
122+
raise e
123+
end
124+
112125
@client_nats_connection = client
113126

114127
true

lib/protobuf/nats/client.rb

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -201,7 +201,7 @@ def send_request_through_nats
201201
end
202202

203203
parse_response
204-
rescue ::Protobuf::Nats::Errors::IOException => error
204+
rescue *::Protobuf::Nats::Errors::RETRYABLE_TRANSPORT_ERRORS => error
205205
::Protobuf::Nats.log_error(error)
206206

207207
delay = reconnect_delay

lib/protobuf/nats/config.rb

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -43,11 +43,16 @@ def load_from_yml(reload = false)
4343
if ::File.exist?(absolute_config_path)
4444
yaml_string = ::ERB.new(::File.read(absolute_config_path)).result
4545
# Psych 4 and newer requires unsafe_load_file in order for aliases to be used
46-
yaml_config = if ::YAML.respond_to?(:unsafe_load_file)
47-
::YAML.unsafe_load(yaml_string)[env]
46+
parsed = if ::YAML.respond_to?(:unsafe_load_file)
47+
::YAML.unsafe_load(yaml_string)
4848
else
49-
::YAML.load(yaml_string)[env]
49+
::YAML.load(yaml_string)
5050
end
51+
52+
# An empty file parses to nil/false, and a file without a section
53+
# for the current env yields nil on lookup -- guard both so we
54+
# don't blow up with NoMethodError below.
55+
yaml_config = (parsed && parsed[env]) || {}
5156
end
5257

5358
DEFAULTS.each_pair do |key, value|

lib/protobuf/nats/errors.rb

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,30 @@ class MriIOException < ::StandardError
1717
end
1818

1919
IOException = MriIOException
20+
21+
# Transient transport errors that mean the NATS connection is unavailable
22+
# or was dropped mid-request. These should be ridden out by sleeping for
23+
# reconnect_delay and retrying (nats-pure reconnects in a background
24+
# thread), rather than bubbling up as an immediate RPC_ERROR.
25+
#
26+
# NOTE: when jnats was removed in favor of nats-pure, IOException was
27+
# collapsed to MriIOException, which nothing ever raises -- silently
28+
# disabling the client's reconnect/retry path. This list restores it by
29+
# matching the errors the pure-ruby client and socket layer actually raise.
30+
RETRYABLE_TRANSPORT_ERRORS = [
31+
IOException, # legacy / explicit wraps
32+
::EOFError,
33+
::IOError,
34+
::Errno::ECONNRESET,
35+
::Errno::ECONNREFUSED,
36+
::Errno::EPIPE,
37+
::Errno::ETIMEDOUT,
38+
].tap do |errors|
39+
# nats-pure raises this when publishing on a closed connection.
40+
errors << ::NATS::IO::ConnectionClosedError if defined?(::NATS::IO::ConnectionClosedError)
41+
# On JRuby, socket EOF can still surface as a Java IOException.
42+
errors << ::Java::JavaIo::IOException if defined?(::JRUBY_VERSION)
43+
end.freeze
2044
end
2145
end
2246
end

0 commit comments

Comments
 (0)