From 341864ae606e232713f2139248a4694d755a283b Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:16:16 -0600 Subject: [PATCH 01/15] Fix permanent byte-counter drift in ByteBoundedQueue ByteBoundedQueue#push counted an item's bytes AFTER handing it to SizedQueue#push, so a consumer could pop the item and subtract its bytes before the producer had added them. #pop clamps at zero, so that subtraction was swallowed, and the producer's increment then landed on an item that was already gone -- a permanent overcount. The counter therefore only ratcheted up. The server funnels every subscription through one shared queue and pops it from N handler threads (processor_count on JRuby), so the race is live on every message. Once the drift reaches the 128 MiB ceiling, push drops every subsequent request and the server goes dark while looking healthy. This is the same failure class as the nats-pure pending_size drift fixed in 0.13.1. Count the bytes before the enqueue and roll them back in an ensure if the enqueue does not happen (ThreadError on a non_block push into a count-full queue, ClosedQueueError, or an async unwind). The counter can now briefly overcount an in-flight push, which errs toward dropping rather than admitting, and resolves as soon as the push completes or rolls back. The concurrency spec fails on the old code (100 phantom bytes in an empty queue) and passes on the fix. Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/byte_bounded_queue.rb | 33 +++++++++-- spec/protobuf/nats/byte_bounded_queue_spec.rb | 58 +++++++++++++++++++ 2 files changed, 87 insertions(+), 4 deletions(-) diff --git a/lib/protobuf/nats/byte_bounded_queue.rb b/lib/protobuf/nats/byte_bounded_queue.rb index 64ac924..8d412e2 100644 --- a/lib/protobuf/nats/byte_bounded_queue.rb +++ b/lib/protobuf/nats/byte_bounded_queue.rb @@ -29,16 +29,38 @@ def initialize(max_msgs, max_bytes, on_drop: nil) # only concurrent pops (which lower @bytes), so the ceiling can be exceeded # by at most one in-flight message -- a soft limit, like nats-pure's own # byte accounting. Returns self (SizedQueue#push contract). Raises - # ThreadError from super on a non_block push into a count-full queue, before - # any bytes are counted. + # ThreadError from super on a non_block push into a count-full queue; the + # bytes counted for that attempt are rolled back before it propagates. def push(obj, non_block = false) bytes = byte_size(obj) if bytes > 0 && (@bytes.value + bytes) > @max_bytes @on_drop&.call(bytes) return self end - super(obj, non_block) - @bytes.increment(bytes) + + # Count the bytes BEFORE the enqueue, and roll back if the enqueue does + # not happen. Counting after `super` lets a consumer pop the object and + # subtract its bytes before this thread has added them; #pop's clamp at + # zero then swallows that subtraction, and the increment that lands + # afterwards becomes a permanent overcount for a message that is already + # gone. The counter only ever ratchets up, and once it reaches + # @max_bytes every later push is dropped forever -- the same drift class + # as the nats-pure pending_size bug. + # + # A blocking push (non_block false, count-full queue) leaves the bytes + # counted while we wait. That is a deliberate short overcount: it errs + # toward dropping rather than admitting, and it resolves as soon as the + # push completes or rolls back. + @bytes.increment(bytes) if bytes > 0 + pushed = false + begin + super(obj, non_block) + pushed = true + ensure + # ensure (not rescue) so an async Thread#raise or a non-StandardError + # unwind rolls the counter back too. + @bytes.decrement(bytes) if bytes > 0 && !pushed + end self end alias_method :<<, :push @@ -46,6 +68,9 @@ def push(obj, non_block = false) def pop(non_block = false) obj = super # nil == closed/empty non_block; nothing dequeued, nothing to subtract. + # The clamp at zero is only a backstop for #clear racing an in-flight + # pop (clear zeroes the counter, then the pop subtracts). #push counts + # bytes before enqueueing, so a normal pop always has its bytes present. @bytes.update { |value| [value - byte_size(obj), 0].max } if obj obj end diff --git a/spec/protobuf/nats/byte_bounded_queue_spec.rb b/spec/protobuf/nats/byte_bounded_queue_spec.rb index b540ec6..46880ba 100644 --- a/spec/protobuf/nats/byte_bounded_queue_spec.rb +++ b/spec/protobuf/nats/byte_bounded_queue_spec.rb @@ -96,6 +96,64 @@ def queue_with_drops(max_msgs, max_bytes) end end + describe "byte accounting under concurrency (regression)" do + # Counting bytes AFTER the enqueue let a consumer pop the object and + # subtract its bytes before the producer added them: #pop's clamp at zero + # swallowed the subtraction and the producer's later increment became a + # permanent overcount. The counter only ratcheted up, so a long-lived + # server eventually reported a full queue and dropped every request. + it "does not drift upward when producers and consumers run concurrently" do + q = described_class.new(64, 100_000_000) # ceilings high enough never to drop + message_bytes = 100 + producers = 8 + per_producer = 250 + total = producers * per_producer + + popped = ::Concurrent::AtomicFixnum.new(0) + consumers = 8.times.map do + ::Thread.new do + loop do + item = q.pop + break if item == :done + popped.increment + end + end + end + + producer_threads = producers.times.map do + ::Thread.new { per_producer.times { q.push(msg(message_bytes)) } } + end + producer_threads.each(&:join) + + # Drain, then stop each consumer with its own sentinel. + consumers.size.times { q.push(:done) } + consumers.each(&:join) + + expect(popped.value).to eq(total) + expect(q.size).to eq(0) + # The queue is empty, so the byte counter must be exactly zero. Any + # phantom bytes here are permanent drift. + expect(q.bytesize).to eq(0) + end + + it "rolls back the counted bytes when a non-blocking push is rejected" do + q = described_class.new(1, 100_000) + q.push(msg(500)) + + expect { q.push(msg(500), true) }.to raise_error(::ThreadError) + + # The rejected push must leave no trace in the counter. + expect(q.size).to eq(1) + expect(q.bytesize).to eq(500) + + # ...and the freed headroom must still be usable afterwards. + q.pop + expect(q.bytesize).to eq(0) + q.push(msg(500)) + expect(q.bytesize).to eq(500) + end + end + describe "message-count ceiling (inherited SizedQueue)" do it "raises ThreadError on a non-blocking push into a count-full queue without counting bytes" do q = described_class.new(2, 10_000) # 2-message capacity From bc504e4085f880c2f055486a766a396403e74eb6 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:17:32 -0600 Subject: [PATCH 02/15] Remove Timeout.timeout wrapper around subscription manager shutdown 0.13.1 removed Timeout.timeout from SuperSubscriptionManager because its async Thread#raise, fired while a thread holds the SizedQueue mutex, makes JRuby 10 unwind through the held mutex and raise "Attempt to unlock a mutex which is locked by another thread/fiber". Server#run still wrapped the whole shutdown call in Timeout.timeout(10), reintroducing the same hazard one frame up. The wrapper could genuinely fire: #shutdown is not bounded by 10s. Its worst case is one 1s push deadline per handler, then a 5s join, then 1s kill-joins -- past 10s once there are more than a few handlers, and the JRuby default is processor_count. The resulting ThreadError is caught by the existing rescue, but the corrupted queue mutex can then hang the trailing @pending_queue.clear. #shutdown already bounds itself with a monotonic deadline and non-blocking pushes, so drop the wrapper and keep the rescue. The dead `require "timeout"` goes too, in both files, so the hazard is not silently available again; specs that use Timeout directly now require it via spec_helper. Replaces the spec for the deleted timeout branch with one covering the surviving rescue, plus a guard spec that fails if the wrapper returns. Co-Authored-By: Claude Fable 5 --- ANALYSIS.md | 190 ++++++++++++++++++ lib/protobuf/nats/server.rb | 18 +- .../nats/super_subscription_manager.rb | 1 - spec/protobuf/nats/server_spec.rb | 32 ++- spec/spec_helper.rb | 1 + 5 files changed, 227 insertions(+), 15 deletions(-) create mode 100644 ANALYSIS.md diff --git a/ANALYSIS.md b/ANALYSIS.md new file mode 100644 index 0000000..08b0811 --- /dev/null +++ b/ANALYSIS.md @@ -0,0 +1,190 @@ +# Analysis of protobuf-nats & Commit `ebf219b` (v0.13.1) + +This document provides a comprehensive code analysis of `protobuf-nats` and the changes introduced in commit `ebf219b` (v0.13.1 / PR #12), detailing performance optimizations, identified bugs, concurrency race conditions, and recommended remediations. + +--- + +## 1. Overview & Context + +`protobuf-nats` provides client and server RPC bindings over [NATS](https://nats.io) for Ruby and JRuby applications using Google Protocol Buffers. + +Commit `ebf219b8afe9212c4793bdafe108ada0b0b7e4bd` (`0.13.1`) addresses regressions from the `jnats` -> `nats-pure` migration (introduced in `0.13.0`) and introduces major performance, resilience, and observability enhancements across both client and server: + +* **Transport & Resilience:** Restores retryable transport errors (`Errors::RETRYABLE_TRANSPORT_ERRORS`), adds bounded and jittered reconnect sleeps, and automatically drops dead memoized connections on terminal `on_close`. +* **Client Response Muxer:** Removes the `pending_size` lock bottleneck, uses `TimeoutQueue` with `QUEUE_WAKE` sentinels for lock-free waiting, and adds decaying atomic crash counters for self-healing. +* **Server Architecture:** Parallelizes intake across multiple threads (`PB_NATS_SERVER_SUBSCRIPTION_HANDLERS`), introduces `ByteBoundedQueue` to cap total aggregate heap memory across all subscriptions without blocking the NATS reader thread, fails fast with `PbError` on server handler crashes, and adds in-flight handler observability. +* **Engine Compatibility:** Eliminates `Timeout.timeout` around `SizedQueue` operations to prevent JRuby 10 `ThreadError` crashes. + +--- + +## 2. Performance Optimizations & Architectural Wins + +### 2.1 Hot-Path Allocation Reductions +1. **Response Muxer Subject Slicing (`lib/protobuf/nats/response_muxer.rb:558`)**: + * **Before:** `token = msg.subject.split('.').last` (allocated an Array and multiple sub-strings per message). + * **After:** `token = subject[(subject.rindex(".") + 1)..]` (single zero-copy / minimal string slice). +2. **UUIDv7 Generation Optimization (`lib/protobuf/nats/uuidv7_helper.rb:16`)**: + * **Before:** Relied on `SecureRandom.gen_random`, which incurred mutex contention in OpenSSL/Java and created 4 GC-triggering allocations per request. + * **After:** Uses a thread-local non-cryptographic RNG (`Thread.current[:pb_nats_uuid_rng] ||= Random.new`) formatted to RFC 9562 UUIDv7 layout, halving CPU time and garbage generation. +3. **Monotonic Clock Usage (`lib/protobuf/nats.rb:190`)**: + * Replaced `Time.now` across request tracking, token TTLs, and metrics with `Process.clock_gettime(CLOCK_MONOTONIC)`. This avoids Time/timezone object allocations and protects against NTP wall-clock jumps. + +### 2.2 Lock Contention Reductions +1. **Thread Pool Push Hot Path (`lib/protobuf/nats/thread_pool.rb:50-68`)**: + * Replaced mutex-synchronized work counters and per-request `supervise_workers` scans with a lock-free `Concurrent::AtomicFixnum` (`@active_work`). Worker replenishment now runs on a 1-second background tick in `Server#run`. +2. **Response Muxer Token Map (`lib/protobuf/nats/response_muxer.rb:39`)**: + * Utilizes `Concurrent::Map` (backed by `ConcurrentHashMap` on JRuby) and per-token `Concurrent::Collection::TimeoutQueue`s to eliminate global mutex serialization across concurrent requests. + +### 2.3 Server Intake Parallelism & Memory Bounding +1. **Multi-Threaded Server Intake (`lib/protobuf/nats/super_subscription_manager.rb:30`)**: + * Ingestion is fanned out across `PB_NATS_SERVER_SUBSCRIPTION_HANDLERS` threads (defaults to CPU core count on JRuby, 1 on CRuby). This eliminates head-of-line blocking where one slow ACK publish stalled message intake for all other subjects. +2. **Heap Bounding via `ByteBoundedQueue` (`lib/protobuf/nats/byte_bounded_queue.rb`)**: + * Bounds total aggregate payload bytes (default 128 MiB) across all subscriptions. If the queue byte ceiling is reached, messages are dropped (mirroring NATS `SlowConsumer` behavior) rather than blocking the single NATS connection socket read thread. + +--- + +## 3. Bugs, Race Conditions & Edge Cases Identified + +--- + +### 🐛 Bug 1: `UUIDv7Helper.extract_timestamp` & `age_in_seconds` produce bogus ages (~56 years) for non-UUID tokens + +* **Files:** `lib/protobuf/nats/uuidv7_helper.rb:33-57` and `lib/protobuf/nats/response_muxer.rb:571` +* **Root Cause:** + `UUIDv7Helper.age_ms` was updated with `UUIDV7_REGEX` validation, but `UUIDv7Helper.extract_timestamp` only checks `uuid_bytes.length < 12` and calls `uuid_bytes[0...12].to_i(16)`. + If an unexpected message arrives with a non-UUID reply token (e.g. from an external service or foreign client): + ```ruby + uuid = "non-uuid-reply-token" + uuid_bytes = uuid.gsub('-', '') # "nonuuidreplytoken" + timestamp_ms = uuid_bytes[0...12].to_i(16) # "nonuuidreply"[0...12].to_i(16) => 0 + Time.at(0 / 1000.0) # => 1970-01-01 00:00:00 UTC + ``` +* **Impact:** + `age_in_seconds` calculates an age of `~1,787,800,000` seconds (56+ years). When an unexpected message arrives, `ResponseMuxer#dispatch_message` logs: + `"Received unexpected message (1787802435.611s old)..."` + and instruments `client.unexpected_message` with `1.7e9`, skewing metrics and dashboards. +* **Suggested Fix:** + Enforce strict `UUIDV7_REGEX` matching in `extract_timestamp`: + ```ruby + def self.extract_timestamp(uuid) + return nil unless uuid.is_a?(String) && uuid.match?(UUIDV7_REGEX) + + timestamp_ms = (uuid[0, 8].to_i(16) << 16) | uuid[9, 4].to_i(16) + Time.at(timestamp_ms / 1000.0) + rescue => e + nil + end + ``` + +--- + +### 🐛 Bug 2: `Timeout.timeout(10)` in `Server#run` reintroduces JRuby 10 `ThreadError` + +* **File:** `lib/protobuf/nats/server.rb:462-468` +* **Root Cause:** + Commit `ebf219b` explicitly removed `Timeout.timeout` inside `SuperSubscriptionManager` because async `Thread#raise` mid-operation causes JRuby 10 to unwind improperly through held mutexes and raise: + `ThreadError: Attempt to unlock a mutex which is locked by another thread/fiber` + However, in `Server#run`: + ```ruby + logger.info "Shutting down subscription manager..." + begin + Timeout.timeout(10) do + subscription_manager.shutdown(5) + end + rescue Timeout::Error + logger.error "Subscription manager shutdown timed out!" + rescue => e + logger.error "Error during subscription manager shutdown: #{e.message}" + end + ``` + `subscription_manager.shutdown(5)` already enforces a strict monotonic deadline (`monotonic + timeout`) and uses non-blocking `push_with_deadline`. +* **Impact:** + Wrapping `subscription_manager.shutdown(5)` in `Timeout.timeout(10)` re-exposes the JRuby 10 `ThreadError` vulnerability if shutdown ever encounters a delay while manipulating `@pending_queue`. +* **Suggested Fix:** + Call `subscription_manager.shutdown(5)` directly without the outer `Timeout.timeout`: + ```ruby + logger.info "Shutting down subscription manager..." + begin + subscription_manager.shutdown(5) + rescue => e + logger.error "Error during subscription manager shutdown: #{e.message}" + end + ``` + +--- + +### ⚠️ Race Condition 3: Cascading Re-subscriptions during Concurrent Dispatcher Crashes + +* **File:** `lib/protobuf/nats/response_muxer.rb:475-485` +* **Root Cause:** + In `ResponseMuxer#spawn_dispatcher`, the fatal crash handler runs: + ```ruby + LOCK.synchronize do + @resp_handlers.delete(::Thread.current) + drop_subscription_locked("during self-healing") + end + start + ``` + If multiple dispatcher threads encounter a fatal error concurrently (such as a broken socket / closed queue): + 1. Dispatcher 1 acquires `LOCK`, tears down the subscription (`drop_subscription_locked`), and calls `start`, establishing a new inbox subscription. + 2. Dispatcher 2 then acquires `LOCK` and immediately calls `drop_subscription_locked` and `start` again, tearing down the freshly-created subscription from Dispatcher 1 and cancelling all in-flight requests that just arrived on it. +* **Impact:** + Multiple simultaneous dispatcher failures cause repeated subscription teardowns and request cancellations instead of a single coordinated restart. +* **Suggested Fix:** + Guard the teardown so that only the first failing dispatcher triggers a subscription rebuild, or check if the subscription was already replaced before executing `drop_subscription_locked`. + +--- + +### ⚠️ Race Condition 4: `ThreadPool#push` vs `shutdown` Work Loss & Active Work Counter Leak + +* **File:** `lib/protobuf/nats/thread_pool.rb:50-68` +* **Root Cause:** + In `ThreadPool#push`: + ```ruby + def push(&work_cb) + return false if @shutting_down.true? + + if @active_work.increment > @max_size + @active_work.decrement + return false + end + + @queue << [:work, work_cb] + true + end + ``` + If `push` runs concurrently with `shutdown`: + 1. `push` checks `@shutting_down.true?` (which is `false`). + 2. `shutdown` executes, sets `@shutting_down` to `true`, and pushes `@max_workers` `[:stop, nil]` poison pills to `@queue`. + 3. `push` resumes, increments `@active_work`, and enqueues `[:work, work_cb]` *after* the `[:stop, nil]` items. + 4. Worker threads pop `[:stop, nil]` and terminate immediately. + 5. The `[:work, work_cb]` task remains stranded in `@queue` without being executed. + 6. `@active_work` was incremented but never decremented by `ensure`, permanently leaking the active work count. +* **Suggested Fix:** + Re-verify `@shutting_down.true?` after the atomic increment, rolling back the increment and returning `false` if shutdown started. + +--- + +## 4. Code Quality & Test Suite Notes + +### 4.1 RSpec False-Positive Warnings +In `spec/protobuf/nats/response_muxer_spec.rb:193` & `:197`: +```ruby +expect { subject.new_request }.not_to raise_error(NoMethodError) +expect { subject.cleanup("token") }.not_to raise_error(NoMethodError) +``` +RSpec emits warnings: +`WARNING: Using expect { }.not_to raise_error(SpecificErrorClass) risks false positives...` +Replacing these with `expect { ... }.not_to raise_error` avoids suppressed failures. + +--- + +## 5. Summary & Action Items + +| Item | Component | Severity | Description / Action | +|---|---|---|---| +| **1** | `UUIDv7Helper` | **Bug** | Enforce `UUIDV7_REGEX` in `extract_timestamp` so non-UUID tokens don't emit 56-year-old message metrics. | +| **2** | `Server#run` | **Bug** | Remove `Timeout.timeout(10)` wrapper around `subscription_manager.shutdown(5)` to eliminate JRuby 10 `ThreadError` risks. | +| **3** | `ResponseMuxer` | **Race Condition** | Coordinate self-healing restarts when multiple dispatcher threads crash simultaneously. | +| **4** | `ThreadPool` | **Race Condition** | Re-check `@shutting_down` in `ThreadPool#push` to prevent stranded work and counter leaks during shutdown. | +| **5** | `Specs` | **Quality** | Update RSpec `not_to raise_error` expectations to remove deprecation warnings. | diff --git a/lib/protobuf/nats/server.rb b/lib/protobuf/nats/server.rb index 5c45ce8..f3e7571 100644 --- a/lib/protobuf/nats/server.rb +++ b/lib/protobuf/nats/server.rb @@ -1,7 +1,6 @@ require "active_support" require "active_support/core_ext/class/subclasses" require "concurrent" -require "timeout" require "protobuf/rpc/server" require "protobuf/rpc/service" require "protobuf/nats/thread_pool" @@ -461,11 +460,18 @@ def run logger.info "Shutting down subscription manager..." begin - Timeout.timeout(10) do - subscription_manager.shutdown(5) - end - rescue Timeout::Error - logger.error "Subscription manager shutdown timed out!" + # No Timeout.timeout here. #shutdown already bounds itself with a + # monotonic deadline and non-blocking pushes, and Timeout's async + # Thread#raise is exactly what 0.13.1 removed from the manager: firing + # it while a thread holds the SizedQueue mutex leaves JRuby unwinding + # through a held mutex ("Attempt to unlock a mutex which is locked by + # another thread"), which can then hang the queue for good. + # + # The wrapper could genuinely fire, too: #shutdown's own worst case + # (one 1s push deadline per handler, then a 5s join, then 1s + # kill-joins) exceeds 10s once there are more than a few handlers -- + # the JRuby default is processor_count. + subscription_manager.shutdown(5) rescue => e logger.error "Error during subscription manager shutdown: #{e.message}" end diff --git a/lib/protobuf/nats/super_subscription_manager.rb b/lib/protobuf/nats/super_subscription_manager.rb index 80635fd..7aa78ea 100644 --- a/lib/protobuf/nats/super_subscription_manager.rb +++ b/lib/protobuf/nats/super_subscription_manager.rb @@ -1,7 +1,6 @@ require "active_support" require "active_support/core_ext/class/subclasses" require "concurrent" -require "timeout" require "protobuf/rpc/server" require "protobuf/rpc/service" require "protobuf/nats/thread_pool" diff --git a/spec/protobuf/nats/server_spec.rb b/spec/protobuf/nats/server_spec.rb index 981dd9e..e78d9e4 100644 --- a/spec/protobuf/nats/server_spec.rb +++ b/spec/protobuf/nats/server_spec.rb @@ -857,18 +857,14 @@ def capture(event) subject.run end - it "handles subscription manager shutdown timeout" do + it "logs and continues when subscription manager shutdown raises" do # Mock the run loop to exit immediately allow(subject).to receive(:loop) allow(subject).to receive(:print_subscription_keys) allow(subject).to receive(:subscribe) allow(subject).to receive(:unsubscribe) - # Make shutdown hang (but Timeout will catch it in 10 seconds, which is mocked) - allow(subject.subscription_manager).to receive(:shutdown) { sleep 100 } - - # Stub Timeout to trigger immediately instead of waiting 10 seconds - allow(Timeout).to receive(:timeout).with(10).and_raise(Timeout::Error) + allow(subject.subscription_manager).to receive(:shutdown).and_raise(::RuntimeError, "boom") # Allow any error logs allow(logger).to receive(:error) @@ -878,8 +874,28 @@ def capture(event) subject.instance_variable_set(:@running, false) subject.run - # Verify the error was logged - expect(logger).to have_received(:error).with(/subscription manager shutdown timed out/i) + expect(logger).to have_received(:error).with(/Error during subscription manager shutdown: boom/) + end + + # Regression: 0.13.1 removed Timeout.timeout from SuperSubscriptionManager + # because its async Thread#raise corrupts the SizedQueue mutex on JRuby, + # but left a Timeout.timeout(10) wrapper around the whole shutdown call -- + # reintroducing the same hazard one frame up. #shutdown self-bounds, so + # there must be no Timeout around it. + it "does not wrap subscription manager shutdown in Timeout.timeout" do + allow(subject).to receive(:loop) + allow(subject).to receive(:print_subscription_keys) + allow(subject).to receive(:subscribe) + allow(subject).to receive(:unsubscribe) + allow(subject.subscription_manager).to receive(:shutdown) + allow(logger).to receive(:error) + allow(logger).to receive(:info) + allow(logger).to receive(:warn) + + expect(::Timeout).not_to receive(:timeout) + + subject.instance_variable_set(:@running, false) + subject.run end it "handles thread pool shutdown timeout" do diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 7de74ce..2d1d257 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -7,6 +7,7 @@ require "bundler/setup" require "socket" +require "timeout" require "protobuf/nats" require "fake_nats_client" require "pry" From fbce03bdac95e49cadaf3e381d2b34435f8978a8 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:18:53 -0600 Subject: [PATCH 03/15] Run work stranded behind ThreadPool shutdown poison pills ThreadPool#push checks @shutting_down and then enqueues, so #shutdown can push its poison pills between those two steps. The work landed BEHIND the pills, workers took a pill and exited, and the task was never run. The server has already published an ACK for that request, so its client blocked until response_timeout (60s). The abandoned @active_work increment also leaked, leaving the size gauge permanently wrong. Re-checking @shutting_down after the increment was the obvious fix, but it does not close the window (shutdown can still land between the re-check and the enqueue) and it introduces a false negative: work enqueued before the pills runs regardless, so reporting it as rejected would make the caller NACK work that executes anyway -- duplicating effects for non-idempotent RPCs. Instead, a worker that takes a pill drains any :work still queued behind it before exiting, releasing each slot as it goes. Pills are conserved: a sibling's pill is put back and ends the drain, so every worker still gets exactly one and the pool terminates as before. All three specs fail on the old code (the stranded tasks never run). Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/thread_pool.rb | 42 ++++++++++++++++++- spec/protobuf/nats/thread_pool_spec.rb | 56 ++++++++++++++++++++++++++ 2 files changed, 97 insertions(+), 1 deletion(-) diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index 2721430..df490d5 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -130,6 +130,34 @@ def supervise_workers end end + # Run any :work left in the queue behind a poison pill, then stop. Called + # only from a worker that has already taken its pill, so the pool is + # shutting down and no new work can be admitted past this drain. + def drain_remaining_work + loop do + begin + type, cb = @queue.pop(true) # non_block: empty queue ends the drain + rescue ::ThreadError + break + end + + # Another worker's pill: put it back so that worker still exits, and + # stop draining (the remaining pills are theirs, not ours). + if type == :stop + @queue << [:stop, nil] + break + end + + begin + cb.call + rescue => error + @cb_mutex.synchronize { @error_cb.call(error) } + ensure + @active_work.decrement + end + end + end + def spawn_worker ::Thread.new do Thread.current.name = "thread-pool-worker" @@ -146,7 +174,19 @@ def spawn_worker # The :stop poison pill never claimed an @active_work slot (see # #shutdown), so it must not reach the ensure below -- decrementing # for it drove the counter negative at shutdown. - break if type == :stop + if type == :stop + # #push admits work by checking @shutting_down and then enqueueing, + # so #shutdown can slip its pills in between those two steps and + # leave real work sitting BEHIND them. Exiting here would strand + # that work forever -- and the server has already published an ACK + # for it, so its client blocks until response_timeout (60s). + # + # Drain what is behind us before leaving. Pop non-blocking so an + # empty queue ends the drain immediately; hand any sibling's pill + # back so every worker still gets one. + drain_remaining_work + break + end begin cb.call diff --git a/spec/protobuf/nats/thread_pool_spec.rb b/spec/protobuf/nats/thread_pool_spec.rb index 9e290cd..12dd120 100644 --- a/spec/protobuf/nats/thread_pool_spec.rb +++ b/spec/protobuf/nats/thread_pool_spec.rb @@ -25,6 +25,62 @@ end end + describe "work enqueued as shutdown begins" do + # #push checks @shutting_down and then enqueues, so #shutdown can push its + # poison pills between those two steps. The work then sits BEHIND the pills: + # workers used to take a pill and exit, stranding it forever. The server has + # already ACKed that request, so its client blocks until response_timeout. + it "runs work that lands behind the poison pills instead of stranding it" do + pool = described_class.new(2) + ran = ::Queue.new + + # Reproduce the interleaving deterministically: shutdown first (pills are + # now queued), then enqueue work behind them, bypassing the @shutting_down + # guard exactly as a push that already passed the check would. + pool.shutdown + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { ran << :ran }] + + expect(pool.wait_for_termination(5)).to be(true) + expect(ran.size).to eq(1) + # ...and the drained work released its slot. + expect(pool.size).to eq(0) + end + + it "still stops every worker when work is interleaved with the pills" do + pool = described_class.new(4) + ran = ::Queue.new + + pool.shutdown + 3.times do + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { ran << :ran }] + end + + # Every worker must still exit: the drain puts a sibling's pill back + # rather than consuming it. + expect(pool.wait_for_termination(5)).to be(true) + expect(ran.size).to eq(3) + expect(pool.size).to eq(0) + end + + it "keeps draining after a drained task raises" do + pool = described_class.new(1) + ran = ::Queue.new + pool.on_error { |_error| nil } # swallow the expected error + + pool.shutdown + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { raise "boom" }] + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { ran << :ran }] + + expect(pool.wait_for_termination(5)).to be(true) + expect(ran.size).to eq(1) + expect(pool.size).to eq(0) + end + end + describe "overdue-reclaim raise between tasks" do it "survives a HandlerOverdue raised while parked on the queue" do pool = described_class.new(1) From 9b8eb2e656a123d923ec1dfdf4cc42932c0f4c44 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:21:52 -0600 Subject: [PATCH 04/15] Stop a late muxer dispatcher from tearing down a healed subscription A dispatcher that crashes fatally sleeps a backoff, then unconditionally called drop_subscription_locked before restarting. When several dispatchers crash together (JRuby runs processor_count of them) they wake on DIFFERENT backoffs -- 1s, then 4s -- so the late one tore down the subscription the earlier one had just rebuilt, and fail_inflight_requests cancelled every request that had already arrived on it. The staggered backoff makes this more likely, not less. Tear down only the subscription this dispatcher actually died on. The dispatch loop records it in a thread-local as it drains, so the crash handler can distinguish "still mine, I must heal it" from "a sibling already replaced it, just rejoin the pool". A nil value means we died before draining anything, so there is nothing of ours to tear down. The thread-local is written by the loop rather than captured when the thread starts: a capture races the sibling's swap and would read whichever subscription happens to be current after the backoff -- the very value the check needs to compare against. The spec fails on the unguarded code (the healed subscription is destroyed and the in-flight token queue is closed). Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/response_muxer.rb | 31 +++++++++++++- spec/protobuf/nats/response_muxer_spec.rb | 52 +++++++++++++++++++++++ 2 files changed, 82 insertions(+), 1 deletion(-) diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index 31d7fc0..e1e7d86 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -37,6 +37,10 @@ class ResponseMuxer # immediately on every engine; next_message treats it as a timeout. QUEUE_WAKE = ::Object.new + # Thread-local key naming the subscription a dispatcher is currently + # draining (see run_dispatch_loop / spawn_dispatcher). + DISPATCHING_SUB_KEY = :pb_nats_dispatching_sub + def initialize # Per-token response queues for lock-free message delivery. @resp_map is a # Concurrent::Map so request threads and dispatcher threads can insert, @@ -481,7 +485,27 @@ def spawn_dispatcher # the muxer would stop delivering responses entirely). @resp_handlers.delete(::Thread.current) - drop_subscription_locked("during self-healing") + # Only tear down the subscription we actually died on. When several + # dispatchers crash together they wake on different backoffs (1s, + # then 4s...), so an unconditional teardown here would destroy the + # subscription an earlier sibling just rebuilt and, via + # fail_inflight_requests, cancel every request that had already + # arrived on it. If a sibling healed us, our subscription is stale + # and start's top-up below is all that is left to do. + # + # DISPATCHING_SUB_KEY is written by run_dispatch_loop on this same + # thread, so it names the subscription this dispatcher was really + # draining. Capturing @resp_sub here (or when the thread starts) + # would instead read whatever is current after the backoff, which + # is exactly the value we need to compare against. A nil value + # means we died before draining anything, so there is nothing of + # ours to tear down. + dispatching_sub = ::Thread.current[DISPATCHING_SUB_KEY] + if @resp_sub.nil? || @resp_sub.equal?(dispatching_sub) + drop_subscription_locked("during self-healing") + else + logger.info "ResponseMuxer already healed by another dispatcher; rejoining the pool without a teardown" + end end start end @@ -501,6 +525,11 @@ def run_dispatch_loop next end + # Record what we are draining for the crash handler in + # spawn_dispatcher. Thread-local, so each dispatcher tracks its own + # subscription across restarts (a shared ivar could not). + ::Thread.current[DISPATCHING_SUB_KEY] = sub + msg = sub.pending_queue.pop # nil means the queue was closed/woken (e.g. the connection died diff --git a/spec/protobuf/nats/response_muxer_spec.rb b/spec/protobuf/nats/response_muxer_spec.rb index 7f8d81f..93098de 100644 --- a/spec/protobuf/nats/response_muxer_spec.rb +++ b/spec/protobuf/nats/response_muxer_spec.rb @@ -216,6 +216,58 @@ expect(handlers.any? { |t| !t.alive? }).to be(false) end + # Several dispatchers that crash together wake on DIFFERENT backoffs + # (1s, then 4s...). The late one used to tear down unconditionally, + # destroying the subscription the earlier one had just rebuilt and, via + # fail_inflight_requests, cancelling every request already waiting on it. + it "does not tear down a subscription another dispatcher already rebuilt" do + crashing_sub = nats_client.subscribe("test.subscription") + # Build the stand-in for the sibling's rebuilt subscription BEFORE the + # stub below, or `subscribe` would hand back crashing_sub itself and the + # two would be the same object (making the identity check trivially true). + healed_sub = nats_client.subscribe("healed.subscription") + queue = crashing_sub.pending_queue + allow(nats_client).to receive(:subscribe).and_return(crashing_sub) + # Long enough to swap in the "healed" subscription mid-backoff. + allow(::Protobuf::Nats).to receive(:crash_backoff_seconds).and_return(0.3) + + raised = false + allow(queue).to receive(:pop) do + unless raised + raised = true + raise ::ThreadError, "Queue closed" # fatal: kills the dispatch loop + end + sleep 0.01 + nil + end + + subject.send(:start) + crashed = subject.instance_variable_get(:@resp_handlers).first + + # Stand in for a sibling that already healed the muxer: a DIFFERENT + # subscription object is now current, with a live in-flight token on it. + expect(healed_sub).not_to equal(crashing_sub) + allow(healed_sub.pending_queue).to receive(:pop) { sleep 0.01; nil } + subject.instance_variable_set(:@resp_sub, healed_sub) + subject.instance_variable_set(:@started, true) + request = subject.new_request + token = request.instance_variable_get(:@token) + + # Let the crashed dispatcher finish its backoff and run its handler. + wait_until(timeout: 3) { !crashed.alive? } + + # The healed subscription must survive untouched... + expect(subject.instance_variable_get(:@resp_sub)).to equal(healed_sub) + expect(subject.started?).to be(true) + # ...and the in-flight request must NOT have been cancelled: a teardown + # closes every token queue via fail_inflight_requests. + entry = subject.instance_variable_get(:@resp_map)[token] + expect(entry).not_to be_nil + expect(entry[:queue]).not_to be_closed + + subject.instance_variable_get(:@resp_handlers).each(&:kill) + end + it "spawns a replacement (does not drop to zero) when the sole dispatcher crashes fatally" do subscription = nats_client.subscribe("test.subscription") queue = subscription.pending_queue From f2799c8fcd0bf53f9bc70c40e43e5fe309978ded Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:23:07 -0600 Subject: [PATCH 05/15] Reject non-UUID tokens in extract_timestamp; fix RSpec warnings String#to_i(16) stops at the first non-hex character and returns 0 rather than raising, so extract_timestamp's length-only check let a non-UUID reply token ("non-uuid-reply-token") parse as epoch 0. age_in_seconds then reported ~1.79e9 seconds -- 56 years -- which ResponseMuxer#dispatch_message logs and feeds into the client.unexpected_message gauge, skewing dashboards. Validate the whole token instead of its length. age_ms already did this via UUIDV7_REGEX; extract_timestamp now shares it, plus a compact (dash-free) variant so the form the method has always accepted -- and which uuidv7_helper_spec covers -- keeps working. The dashed regex alone would have failed that existing spec. Impact is metrics quality, not correctness: in practice these tokens are this gem's own UUIDv7s, so a garbage age needs a foreign publisher on the inbox subject. Also switches two `not_to raise_error(NoMethodError)` matchers to the bare form. RSpec warns that they pass on any error -- including one raised before the code under test is reached. Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/uuidv7_helper.rb | 28 ++++++++++++++++------- spec/protobuf/nats/response_muxer_spec.rb | 4 ++-- spec/protobuf/nats/uuidv7_helper_spec.rb | 16 +++++++++++++ 3 files changed, 38 insertions(+), 10 deletions(-) diff --git a/lib/protobuf/nats/uuidv7_helper.rb b/lib/protobuf/nats/uuidv7_helper.rb index 7a376ae..a42e10e 100644 --- a/lib/protobuf/nats/uuidv7_helper.rb +++ b/lib/protobuf/nats/uuidv7_helper.rb @@ -1,6 +1,17 @@ module Protobuf module Nats class UUIDv7Helper + # Strict RFC 9562 UUIDv7 shape, matching what .generate produces. The + # strictness matters to callers like the server's stale-request shedding: + # treating a non-UUID token (e.g. from a foreign client) as a timestamp + # would compute a garbage age. + UUIDV7_REGEX = /\A\h{8}-\h{4}-7\h{3}-\h{4}-\h{12}\z/ + + # Same shape without dashes. extract_timestamp has always accepted this + # form, so validating with the dashed pattern alone would reject tokens + # the method documents as supported. + UUIDV7_COMPACT_REGEX = /\A\h{12}7\h{3}\h{4}\h{12}\z/ + # Generate a UUIDv7 string without a CSPRNG. Callers that only need a # 48-bit millisecond timestamp prefix (so #age_in_seconds can report a # value) plus enough randomness to stay unique among concurrent generators @@ -27,17 +38,23 @@ def self.generate # Extract the Unix timestamp (in seconds) from a UUIDv7 string # Returns nil if the UUID cannot be parsed # + # Validates the whole token, not just its length. String#to_i(16) stops at + # the first non-hex character and returns 0 rather than raising, so a + # non-UUID reply token ("non-uuid-reply-token") used to parse as epoch 0 + # and report an age of ~56 years -- which #age_in_seconds then fed + # straight into the client.unexpected_message gauge. + # # @param uuid [String] A UUIDv7 string (e.g., "01234567-89ab-7def-0123-456789abcdef") # @return [Time, nil] The timestamp embedded in the UUID, or nil if parsing fails def self.extract_timestamp(uuid) return nil unless uuid.is_a?(String) + return nil unless uuid.match?(UUIDV7_REGEX) || uuid.match?(UUIDV7_COMPACT_REGEX) # UUIDv7 format: first 48 bits (12 hex chars) are Unix timestamp in milliseconds # Remove dashes and extract the timestamp portion - uuid_bytes = uuid.gsub('-', '') - return nil if uuid_bytes.length < 12 + uuid_bytes = uuid.tr('-', '') - timestamp_ms = uuid_bytes[0...12].to_i(16) + timestamp_ms = uuid_bytes[0, 12].to_i(16) Time.at(timestamp_ms / 1000.0) rescue => e nil @@ -56,11 +73,6 @@ def self.age_in_seconds(uuid, current_time: Time.now) current_time - timestamp end - # Strict RFC 9562 UUIDv7 shape, matching what .generate produces. The - # strictness matters to callers like the server's stale-request shedding: - # extract_timestamp is permissive, and treating a non-UUID token (e.g. - # from a foreign client) as a timestamp would compute a garbage age. - UUIDV7_REGEX = /\A\h{8}-\h{4}-7\h{3}-\h{4}-\h{12}\z/ # Age (integer ms) of a strictly-validated UUIDv7 token, or nil for a # non-UUIDv7 token. Allocation-light: runs per message on the server's diff --git a/spec/protobuf/nats/response_muxer_spec.rb b/spec/protobuf/nats/response_muxer_spec.rb index 93098de..2724506 100644 --- a/spec/protobuf/nats/response_muxer_spec.rb +++ b/spec/protobuf/nats/response_muxer_spec.rb @@ -190,11 +190,11 @@ describe "unstarted / failed start state" do it "does not raise NoMethodError on nil when calling new_request before start" do - expect { subject.new_request }.not_to raise_error(NoMethodError) + expect { subject.new_request }.not_to raise_error end it "does not raise NoMethodError on nil when calling cleanup before start" do - expect { subject.cleanup("token") }.not_to raise_error(NoMethodError) + expect { subject.cleanup("token") }.not_to raise_error end end diff --git a/spec/protobuf/nats/uuidv7_helper_spec.rb b/spec/protobuf/nats/uuidv7_helper_spec.rb index 3613823..8f0be8f 100644 --- a/spec/protobuf/nats/uuidv7_helper_spec.rb +++ b/spec/protobuf/nats/uuidv7_helper_spec.rb @@ -83,6 +83,19 @@ expect(described_class.extract_timestamp("123")).to be_nil end + # String#to_i(16) stops at the first non-hex char and returns 0 instead of + # raising, so these used to parse as epoch 0 -- an age of ~56 years, which + # #age_in_seconds fed straight into the client.unexpected_message gauge. + it "returns nil for a long non-hex token instead of parsing it as epoch 0" do + expect(described_class.extract_timestamp("non-uuid-reply-token")).to be_nil + expect(described_class.extract_timestamp("some.other.subject.token")).to be_nil + end + + it "returns nil for a hex string that is not UUIDv7-shaped" do + # Right length, right characters, wrong layout (no version 7 nibble). + expect(described_class.extract_timestamp("0123456789abcdef0123456789abcdef")).to be_nil + end + it "handles UUIDs without dashes" do known_time = Time.utc(2024, 1, 1, 0, 0, 0) timestamp_ms = (known_time.to_f * 1000).to_i @@ -127,6 +140,9 @@ it "returns nil for invalid UUIDs" do expect(described_class.age_in_seconds("invalid")).to be_nil expect(described_class.age_in_seconds(nil)).to be_nil + # Regression: a non-UUID reply token reported ~1.7e9 seconds (56 years), + # skewing the client.unexpected_message metric. + expect(described_class.age_in_seconds("non-uuid-reply-token")).to be_nil end end end From b912e5c96376688019fef5328a4931d759e3582b Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:29:26 -0600 Subject: [PATCH 06/15] Drain late-arriving work after the last ThreadPool worker exits The worker-side drain left a gap: if a worker takes its poison pill and drains before the racing push lands, it finds an empty queue and exits, and the work is stranded exactly as before. This surfaced as a ~8% flake in the new drain specs -- a real hole in the fix, not test timing. wait_for_termination now drains once more after the last worker is gone, on the caller's thread, where nothing can race it. This does not make admission and shutdown atomic (#push is lock-free by design), but it closes the window that matters: everything enqueued up to the moment the pool reports termination runs, so no ACKed request is silently dropped. The added spec forces the ordering deterministically -- worker exits first, push lands after -- and fails without the final drain. Previously-flaky spec now passes 25/25; full suite 297 examples, 0 failures across five runs. Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/thread_pool.rb | 20 +++++++++++++++++--- spec/protobuf/nats/thread_pool_spec.rb | 21 +++++++++++++++++++++ 2 files changed, 38 insertions(+), 3 deletions(-) diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index df490d5..f38d7eb 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -80,7 +80,15 @@ def wait_for_termination(seconds = nil) deadline = seconds && (::Protobuf::Nats.monotonic_time + seconds) loop do @mutex.synchronize { prune_dead_workers } - return true if @workers.empty? + if @workers.empty? + # Workers drain what is behind their poison pill, but a push that + # had already passed the @shutting_down check can land after the + # last worker has drained and exited. Nothing would ever run it, + # and the server has already ACKed it. Run it here, on the caller's + # thread, now that no worker is left to race us. + drain_remaining_work + return true + end return false if deadline && ::Protobuf::Nats.monotonic_time >= deadline sleep 0.1 end @@ -131,8 +139,14 @@ def supervise_workers end # Run any :work left in the queue behind a poison pill, then stop. Called - # only from a worker that has already taken its pill, so the pool is - # shutting down and no new work can be admitted past this drain. + # by a worker that has taken its pill, and once more by + # #wait_for_termination after the last worker exits (a push that already + # passed the @shutting_down check can land after every worker has gone). + # + # This does not make admission and shutdown atomic -- #push is lock-free + # by design, so work can still arrive after the final drain. It closes the + # window that matters: everything enqueued up to the moment the pool + # reports termination runs, so no ACKed request is silently dropped. def drain_remaining_work loop do begin diff --git a/spec/protobuf/nats/thread_pool_spec.rb b/spec/protobuf/nats/thread_pool_spec.rb index 12dd120..b684b8e 100644 --- a/spec/protobuf/nats/thread_pool_spec.rb +++ b/spec/protobuf/nats/thread_pool_spec.rb @@ -64,6 +64,27 @@ expect(pool.size).to eq(0) end + # The worker drain alone is not enough: if the worker takes its pill and + # drains BEFORE the racing push lands, it finds an empty queue and exits, + # and the late work is stranded exactly as before. wait_for_termination + # drains once more after the last worker is gone. + it "runs work that lands after every worker has already exited" do + pool = described_class.new(1) + ran = ::Queue.new + + pool.shutdown + # Let the worker take its pill, drain nothing, and exit first. + wait_until(timeout: 3) { pool.instance_variable_get(:@workers).none?(&:alive?) } + + # Only now does the racing push land. + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { ran << :ran }] + + expect(pool.wait_for_termination(5)).to be(true) + expect(ran.size).to eq(1) + expect(pool.size).to eq(0) + end + it "keeps draining after a drained task raises" do pool = described_class.new(1) ran = ::Queue.new From 8751bc05db67dbcafbbaed1ac2ec81dae22a9ccd Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:30:08 -0600 Subject: [PATCH 07/15] Document the applied fixes in the 0.13.2 changelog Version is 0.13.2.pre2 and ByteBoundedQueue was introduced in that same unreleased section, so these entries belong there rather than in a new version heading. Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7acffd6..465f718 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,13 @@ Bounds the RPC transport's in-memory buffering to prevent the JVM-heap OOM intro #### Server: intake heap bound - The shared intake queue is now bounded by bytes as well as count: new `PB_NATS_SERVER_INTAKE_QUEUE_BYTES` (default 128 MiB), enforced by a `ByteBoundedQueue` with a shared byte counter. A request that would exceed the ceiling is dropped (the client retries) and emits `server.intake_bytes_dropped`; new gauge `server.pending_intake_queue_bytes`. nats-pure's per-subscription byte limit stays disabled — the shared queue counter owns byte bounding, since many subscriptions funnel into one queue. - Fixed a slow leak of orphaned `@overdue_flagged` entries caused by a handler-completion race; the periodic monitor now reaps them. +- Fixed permanent upward drift in the `ByteBoundedQueue` byte counter. Bytes were counted *after* the enqueue, so a consumer could pop an item and subtract its bytes first; `pop`'s clamp at zero swallowed that subtraction and the producer's increment then applied to an item already gone. The counter only ratcheted up, and on reaching the ceiling the server dropped every request while appearing healthy. Bytes are now counted before the enqueue and rolled back if it does not happen. + +#### Shutdown & self-healing correctness +- Work accepted just as shutdown begins is no longer stranded. `ThreadPool#push` checks the shutdown flag and then enqueues, so `shutdown` could slip its poison pills between those steps; workers took a pill and exited, leaving an already-ACKed request to hang until the client's response timeout. Workers now drain work queued behind their pill, and `wait_for_termination` drains once more after the last worker exits. +- Removed the `Timeout.timeout(10)` wrapper around `SuperSubscriptionManager#shutdown` in `Server#run`. 0.13.1 removed `Timeout` from the manager because its async `Thread#raise` corrupts the `SizedQueue` mutex on JRuby; the wrapper reintroduced the same hazard one frame up, and could genuinely fire (shutdown's own worst case exceeds 10s once there are more than a few handlers). `#shutdown` already self-bounds. +- A response-muxer dispatcher that crashes now tears down only the subscription it actually died on. Dispatchers that crash together wake on staggered backoffs, so a late one destroyed the subscription an earlier one had just rebuilt and cancelled every request already waiting on it. +- `UUIDv7Helper.extract_timestamp` validates the whole token instead of just its length. `String#to_i(16)` returns 0 for non-hex input, so a foreign reply token parsed as epoch 0 and reported a ~56-year age into the `client.unexpected_message` gauge. ### 0.13.1 Fixes regressions from the JNats → nats-pure migration (0.13.0) plus a full reliability, performance, and security hardening pass. Highlights: the client reconnects and retries correctly through dropped connections, failing nodes, and terminal closes; the server survives overload and connection loss instead of going silently deaf; TLS actually verifies the server certificate. From d36dcc4420a9c405dd884aaf9fd1b71fb036b808 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:33:30 -0600 Subject: [PATCH 08/15] Bump to 0.13.3.pre1 and move the fixes into their own changelog section v0.13.2.pre2 is already tagged and released, so the correctness fixes from this branch cannot live under the 0.13.2 heading -- that section now describes shipped code. Restore it byte-for-byte to its released contents and move the entries into a new 0.13.3.pre1 section, expanded with the impact and the mechanism for each fix. The ByteBoundedQueue drift is noted as new in 0.13.2, since that is the release that introduced the queue. Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 23 ++++++++++++++++------- lib/protobuf/nats/version.rb | 2 +- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 465f718..fe735d7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,21 @@ ## Changelog +### 0.13.3.pre1 +Correctness fixes for concurrency bugs found while reviewing the 0.13.1/0.13.2 changes. Every fix ships with a spec verified to fail against the previous code. No API or configuration changes. + +#### Byte accounting +- Fixed permanent upward drift in the `ByteBoundedQueue` byte counter (new in 0.13.2). Bytes were counted *after* the enqueue, so a consumer could pop an item and subtract its bytes first; `pop`'s clamp at zero swallowed that subtraction, and the producer's increment then applied to an item that was already gone. The counter only ratcheted up, so a long-running server eventually reached the 128 MiB ceiling and dropped **every** request while still looking healthy. The server pops the shared queue from `processor_count` handler threads on JRuby, so the race was live on every message. Bytes are now counted before the enqueue and rolled back if it does not happen. + +#### Shutdown +- Work accepted just as shutdown begins is no longer stranded. `ThreadPool#push` checks the shutdown flag and then enqueues, so `shutdown` could slip its poison pills between those two steps; workers took a pill and exited, leaving an already-ACKed request to hang until the client's response timeout (60s default). Workers now drain work queued behind their pill, and `wait_for_termination` drains once more after the last worker exits. Admission and shutdown are still not atomic (`#push` is lock-free by design), but nothing enqueued before the pool reports termination is dropped. +- Removed the `Timeout.timeout(10)` wrapper around `SuperSubscriptionManager#shutdown` in `Server#run`. 0.13.1 removed `Timeout` from the manager because its async `Thread#raise`, fired while a thread holds the `SizedQueue` mutex, makes JRuby unwind through the held mutex; the wrapper reintroduced that hazard one frame up. It could genuinely fire: `#shutdown` is not bounded by 10s (one 1s push deadline per handler, then a 5s join, then 1s kill-joins). `#shutdown` already self-bounds, so the wrapper is gone along with the now-dead `require "timeout"`. + +#### Self-healing +- A response-muxer dispatcher that crashes now tears down only the subscription it actually died on. Dispatchers that crash together wake on staggered backoffs (1s, then 4s), so a late one destroyed the subscription an earlier one had just rebuilt and, via `fail_inflight_requests`, cancelled every request already waiting on it. + +#### Observability +- `UUIDv7Helper.extract_timestamp` validates the whole token instead of just its length. `String#to_i(16)` stops at the first non-hex character and returns 0 rather than raising, so a foreign reply token parsed as epoch 0 and reported a ~56-year age into the `client.unexpected_message` gauge. Both the dashed and compact (dash-free) UUIDv7 forms are still accepted. + ### 0.13.2 Bounds the RPC transport's in-memory buffering to prevent the JVM-heap OOM introduced by the JNats → nats-pure migration. Both the client response muxer and the server intake queue are now capped by message count **and** total bytes, dropping (with client retry) rather than buffering unbounded protobuf payloads on the heap. @@ -11,13 +27,6 @@ Bounds the RPC transport's in-memory buffering to prevent the JVM-heap OOM intro #### Server: intake heap bound - The shared intake queue is now bounded by bytes as well as count: new `PB_NATS_SERVER_INTAKE_QUEUE_BYTES` (default 128 MiB), enforced by a `ByteBoundedQueue` with a shared byte counter. A request that would exceed the ceiling is dropped (the client retries) and emits `server.intake_bytes_dropped`; new gauge `server.pending_intake_queue_bytes`. nats-pure's per-subscription byte limit stays disabled — the shared queue counter owns byte bounding, since many subscriptions funnel into one queue. - Fixed a slow leak of orphaned `@overdue_flagged` entries caused by a handler-completion race; the periodic monitor now reaps them. -- Fixed permanent upward drift in the `ByteBoundedQueue` byte counter. Bytes were counted *after* the enqueue, so a consumer could pop an item and subtract its bytes first; `pop`'s clamp at zero swallowed that subtraction and the producer's increment then applied to an item already gone. The counter only ratcheted up, and on reaching the ceiling the server dropped every request while appearing healthy. Bytes are now counted before the enqueue and rolled back if it does not happen. - -#### Shutdown & self-healing correctness -- Work accepted just as shutdown begins is no longer stranded. `ThreadPool#push` checks the shutdown flag and then enqueues, so `shutdown` could slip its poison pills between those steps; workers took a pill and exited, leaving an already-ACKed request to hang until the client's response timeout. Workers now drain work queued behind their pill, and `wait_for_termination` drains once more after the last worker exits. -- Removed the `Timeout.timeout(10)` wrapper around `SuperSubscriptionManager#shutdown` in `Server#run`. 0.13.1 removed `Timeout` from the manager because its async `Thread#raise` corrupts the `SizedQueue` mutex on JRuby; the wrapper reintroduced the same hazard one frame up, and could genuinely fire (shutdown's own worst case exceeds 10s once there are more than a few handlers). `#shutdown` already self-bounds. -- A response-muxer dispatcher that crashes now tears down only the subscription it actually died on. Dispatchers that crash together wake on staggered backoffs, so a late one destroyed the subscription an earlier one had just rebuilt and cancelled every request already waiting on it. -- `UUIDv7Helper.extract_timestamp` validates the whole token instead of just its length. `String#to_i(16)` returns 0 for non-hex input, so a foreign reply token parsed as epoch 0 and reported a ~56-year age into the `client.unexpected_message` gauge. ### 0.13.1 Fixes regressions from the JNats → nats-pure migration (0.13.0) plus a full reliability, performance, and security hardening pass. Highlights: the client reconnects and retries correctly through dropped connections, failing nodes, and terminal closes; the server survives overload and connection loss instead of going silently deaf; TLS actually verifies the server certificate. diff --git a/lib/protobuf/nats/version.rb b/lib/protobuf/nats/version.rb index 7798dc3..76de11f 100644 --- a/lib/protobuf/nats/version.rb +++ b/lib/protobuf/nats/version.rb @@ -1,5 +1,5 @@ module Protobuf module Nats - VERSION = "0.13.2.pre2" + VERSION = "0.13.3.pre1" end end From 41b5c03095134bfc37ec34a00d33f947edb587d8 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 22:39:24 -0600 Subject: [PATCH 09/15] removed analysis --- ANALYSIS.md | 190 ---------------------------------------------------- 1 file changed, 190 deletions(-) delete mode 100644 ANALYSIS.md diff --git a/ANALYSIS.md b/ANALYSIS.md deleted file mode 100644 index 08b0811..0000000 --- a/ANALYSIS.md +++ /dev/null @@ -1,190 +0,0 @@ -# Analysis of protobuf-nats & Commit `ebf219b` (v0.13.1) - -This document provides a comprehensive code analysis of `protobuf-nats` and the changes introduced in commit `ebf219b` (v0.13.1 / PR #12), detailing performance optimizations, identified bugs, concurrency race conditions, and recommended remediations. - ---- - -## 1. Overview & Context - -`protobuf-nats` provides client and server RPC bindings over [NATS](https://nats.io) for Ruby and JRuby applications using Google Protocol Buffers. - -Commit `ebf219b8afe9212c4793bdafe108ada0b0b7e4bd` (`0.13.1`) addresses regressions from the `jnats` -> `nats-pure` migration (introduced in `0.13.0`) and introduces major performance, resilience, and observability enhancements across both client and server: - -* **Transport & Resilience:** Restores retryable transport errors (`Errors::RETRYABLE_TRANSPORT_ERRORS`), adds bounded and jittered reconnect sleeps, and automatically drops dead memoized connections on terminal `on_close`. -* **Client Response Muxer:** Removes the `pending_size` lock bottleneck, uses `TimeoutQueue` with `QUEUE_WAKE` sentinels for lock-free waiting, and adds decaying atomic crash counters for self-healing. -* **Server Architecture:** Parallelizes intake across multiple threads (`PB_NATS_SERVER_SUBSCRIPTION_HANDLERS`), introduces `ByteBoundedQueue` to cap total aggregate heap memory across all subscriptions without blocking the NATS reader thread, fails fast with `PbError` on server handler crashes, and adds in-flight handler observability. -* **Engine Compatibility:** Eliminates `Timeout.timeout` around `SizedQueue` operations to prevent JRuby 10 `ThreadError` crashes. - ---- - -## 2. Performance Optimizations & Architectural Wins - -### 2.1 Hot-Path Allocation Reductions -1. **Response Muxer Subject Slicing (`lib/protobuf/nats/response_muxer.rb:558`)**: - * **Before:** `token = msg.subject.split('.').last` (allocated an Array and multiple sub-strings per message). - * **After:** `token = subject[(subject.rindex(".") + 1)..]` (single zero-copy / minimal string slice). -2. **UUIDv7 Generation Optimization (`lib/protobuf/nats/uuidv7_helper.rb:16`)**: - * **Before:** Relied on `SecureRandom.gen_random`, which incurred mutex contention in OpenSSL/Java and created 4 GC-triggering allocations per request. - * **After:** Uses a thread-local non-cryptographic RNG (`Thread.current[:pb_nats_uuid_rng] ||= Random.new`) formatted to RFC 9562 UUIDv7 layout, halving CPU time and garbage generation. -3. **Monotonic Clock Usage (`lib/protobuf/nats.rb:190`)**: - * Replaced `Time.now` across request tracking, token TTLs, and metrics with `Process.clock_gettime(CLOCK_MONOTONIC)`. This avoids Time/timezone object allocations and protects against NTP wall-clock jumps. - -### 2.2 Lock Contention Reductions -1. **Thread Pool Push Hot Path (`lib/protobuf/nats/thread_pool.rb:50-68`)**: - * Replaced mutex-synchronized work counters and per-request `supervise_workers` scans with a lock-free `Concurrent::AtomicFixnum` (`@active_work`). Worker replenishment now runs on a 1-second background tick in `Server#run`. -2. **Response Muxer Token Map (`lib/protobuf/nats/response_muxer.rb:39`)**: - * Utilizes `Concurrent::Map` (backed by `ConcurrentHashMap` on JRuby) and per-token `Concurrent::Collection::TimeoutQueue`s to eliminate global mutex serialization across concurrent requests. - -### 2.3 Server Intake Parallelism & Memory Bounding -1. **Multi-Threaded Server Intake (`lib/protobuf/nats/super_subscription_manager.rb:30`)**: - * Ingestion is fanned out across `PB_NATS_SERVER_SUBSCRIPTION_HANDLERS` threads (defaults to CPU core count on JRuby, 1 on CRuby). This eliminates head-of-line blocking where one slow ACK publish stalled message intake for all other subjects. -2. **Heap Bounding via `ByteBoundedQueue` (`lib/protobuf/nats/byte_bounded_queue.rb`)**: - * Bounds total aggregate payload bytes (default 128 MiB) across all subscriptions. If the queue byte ceiling is reached, messages are dropped (mirroring NATS `SlowConsumer` behavior) rather than blocking the single NATS connection socket read thread. - ---- - -## 3. Bugs, Race Conditions & Edge Cases Identified - ---- - -### 🐛 Bug 1: `UUIDv7Helper.extract_timestamp` & `age_in_seconds` produce bogus ages (~56 years) for non-UUID tokens - -* **Files:** `lib/protobuf/nats/uuidv7_helper.rb:33-57` and `lib/protobuf/nats/response_muxer.rb:571` -* **Root Cause:** - `UUIDv7Helper.age_ms` was updated with `UUIDV7_REGEX` validation, but `UUIDv7Helper.extract_timestamp` only checks `uuid_bytes.length < 12` and calls `uuid_bytes[0...12].to_i(16)`. - If an unexpected message arrives with a non-UUID reply token (e.g. from an external service or foreign client): - ```ruby - uuid = "non-uuid-reply-token" - uuid_bytes = uuid.gsub('-', '') # "nonuuidreplytoken" - timestamp_ms = uuid_bytes[0...12].to_i(16) # "nonuuidreply"[0...12].to_i(16) => 0 - Time.at(0 / 1000.0) # => 1970-01-01 00:00:00 UTC - ``` -* **Impact:** - `age_in_seconds` calculates an age of `~1,787,800,000` seconds (56+ years). When an unexpected message arrives, `ResponseMuxer#dispatch_message` logs: - `"Received unexpected message (1787802435.611s old)..."` - and instruments `client.unexpected_message` with `1.7e9`, skewing metrics and dashboards. -* **Suggested Fix:** - Enforce strict `UUIDV7_REGEX` matching in `extract_timestamp`: - ```ruby - def self.extract_timestamp(uuid) - return nil unless uuid.is_a?(String) && uuid.match?(UUIDV7_REGEX) - - timestamp_ms = (uuid[0, 8].to_i(16) << 16) | uuid[9, 4].to_i(16) - Time.at(timestamp_ms / 1000.0) - rescue => e - nil - end - ``` - ---- - -### 🐛 Bug 2: `Timeout.timeout(10)` in `Server#run` reintroduces JRuby 10 `ThreadError` - -* **File:** `lib/protobuf/nats/server.rb:462-468` -* **Root Cause:** - Commit `ebf219b` explicitly removed `Timeout.timeout` inside `SuperSubscriptionManager` because async `Thread#raise` mid-operation causes JRuby 10 to unwind improperly through held mutexes and raise: - `ThreadError: Attempt to unlock a mutex which is locked by another thread/fiber` - However, in `Server#run`: - ```ruby - logger.info "Shutting down subscription manager..." - begin - Timeout.timeout(10) do - subscription_manager.shutdown(5) - end - rescue Timeout::Error - logger.error "Subscription manager shutdown timed out!" - rescue => e - logger.error "Error during subscription manager shutdown: #{e.message}" - end - ``` - `subscription_manager.shutdown(5)` already enforces a strict monotonic deadline (`monotonic + timeout`) and uses non-blocking `push_with_deadline`. -* **Impact:** - Wrapping `subscription_manager.shutdown(5)` in `Timeout.timeout(10)` re-exposes the JRuby 10 `ThreadError` vulnerability if shutdown ever encounters a delay while manipulating `@pending_queue`. -* **Suggested Fix:** - Call `subscription_manager.shutdown(5)` directly without the outer `Timeout.timeout`: - ```ruby - logger.info "Shutting down subscription manager..." - begin - subscription_manager.shutdown(5) - rescue => e - logger.error "Error during subscription manager shutdown: #{e.message}" - end - ``` - ---- - -### ⚠️ Race Condition 3: Cascading Re-subscriptions during Concurrent Dispatcher Crashes - -* **File:** `lib/protobuf/nats/response_muxer.rb:475-485` -* **Root Cause:** - In `ResponseMuxer#spawn_dispatcher`, the fatal crash handler runs: - ```ruby - LOCK.synchronize do - @resp_handlers.delete(::Thread.current) - drop_subscription_locked("during self-healing") - end - start - ``` - If multiple dispatcher threads encounter a fatal error concurrently (such as a broken socket / closed queue): - 1. Dispatcher 1 acquires `LOCK`, tears down the subscription (`drop_subscription_locked`), and calls `start`, establishing a new inbox subscription. - 2. Dispatcher 2 then acquires `LOCK` and immediately calls `drop_subscription_locked` and `start` again, tearing down the freshly-created subscription from Dispatcher 1 and cancelling all in-flight requests that just arrived on it. -* **Impact:** - Multiple simultaneous dispatcher failures cause repeated subscription teardowns and request cancellations instead of a single coordinated restart. -* **Suggested Fix:** - Guard the teardown so that only the first failing dispatcher triggers a subscription rebuild, or check if the subscription was already replaced before executing `drop_subscription_locked`. - ---- - -### ⚠️ Race Condition 4: `ThreadPool#push` vs `shutdown` Work Loss & Active Work Counter Leak - -* **File:** `lib/protobuf/nats/thread_pool.rb:50-68` -* **Root Cause:** - In `ThreadPool#push`: - ```ruby - def push(&work_cb) - return false if @shutting_down.true? - - if @active_work.increment > @max_size - @active_work.decrement - return false - end - - @queue << [:work, work_cb] - true - end - ``` - If `push` runs concurrently with `shutdown`: - 1. `push` checks `@shutting_down.true?` (which is `false`). - 2. `shutdown` executes, sets `@shutting_down` to `true`, and pushes `@max_workers` `[:stop, nil]` poison pills to `@queue`. - 3. `push` resumes, increments `@active_work`, and enqueues `[:work, work_cb]` *after* the `[:stop, nil]` items. - 4. Worker threads pop `[:stop, nil]` and terminate immediately. - 5. The `[:work, work_cb]` task remains stranded in `@queue` without being executed. - 6. `@active_work` was incremented but never decremented by `ensure`, permanently leaking the active work count. -* **Suggested Fix:** - Re-verify `@shutting_down.true?` after the atomic increment, rolling back the increment and returning `false` if shutdown started. - ---- - -## 4. Code Quality & Test Suite Notes - -### 4.1 RSpec False-Positive Warnings -In `spec/protobuf/nats/response_muxer_spec.rb:193` & `:197`: -```ruby -expect { subject.new_request }.not_to raise_error(NoMethodError) -expect { subject.cleanup("token") }.not_to raise_error(NoMethodError) -``` -RSpec emits warnings: -`WARNING: Using expect { }.not_to raise_error(SpecificErrorClass) risks false positives...` -Replacing these with `expect { ... }.not_to raise_error` avoids suppressed failures. - ---- - -## 5. Summary & Action Items - -| Item | Component | Severity | Description / Action | -|---|---|---|---| -| **1** | `UUIDv7Helper` | **Bug** | Enforce `UUIDV7_REGEX` in `extract_timestamp` so non-UUID tokens don't emit 56-year-old message metrics. | -| **2** | `Server#run` | **Bug** | Remove `Timeout.timeout(10)` wrapper around `subscription_manager.shutdown(5)` to eliminate JRuby 10 `ThreadError` risks. | -| **3** | `ResponseMuxer` | **Race Condition** | Coordinate self-healing restarts when multiple dispatcher threads crash simultaneously. | -| **4** | `ThreadPool` | **Race Condition** | Re-check `@shutting_down` in `ThreadPool#push` to prevent stranded work and counter leaks during shutdown. | -| **5** | `Specs` | **Quality** | Update RSpec `not_to raise_error` expectations to remove deprecation warnings. | From c89f5c2f3725aa4ea2dcb3c4f2a8f99e38886e10 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Wed, 26 Aug 2026 23:29:45 -0600 Subject: [PATCH 10/15] Record the muxer lock review decision in the code The per-message sub.synchronize in run_dispatch_loop was flagged twice as a performance concern and deferred twice. Write the measurements and the decision next to the code so a future pass does not re-open it from scratch. Measured on JRuby 9.4.14.0 / 15 cores: the line costs ~9.6us per message, and because it takes the same monitor nats-pure's single read thread holds for all of #process_msg, dispatchers contend with the feeder for every subscription on the connection -- read-thread ingress falls to 43% of its one-dispatcher rate at 8 dispatchers. Throughput peaks at 4 dispatchers and declines above it. Left as-is: expected load is <=2000 req/s, about 1% of the 203k msg/s ceiling. The comment records the two conditions that would reopen it (peak rate nearing 100k msg/s, or sharing the connection with another high-volume subject) and the fix to use if it does -- batch the decrement, do not drop it. Also notes at dispatcher_count that the processor_count default is deliberate despite the measured peak at 4, so the default is not "corrected" later. Comments only; no behavior change. 297 examples, 0 failures. Co-Authored-By: Claude Fable 5 --- lib/protobuf/nats/response_muxer.rb | 26 ++++++++++++++++++++++++++ 1 file changed, 26 insertions(+) diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index e1e7d86..73f3f24 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -92,6 +92,13 @@ def monotonic_now # (true parallelism) a single dispatcher is a hard throughput ceiling, so we # fan out to processor_count; on CRuby the GVL makes extra dispatchers # pointless, so we stay at 1. Overridable via env for tuning/tests. + # + # Note (2026-08-26): measured throughput actually PEAKS at 4 dispatchers + # and declines above it, because every dispatcher contends on the + # subscription monitor in run_dispatch_loop (rationale there). The + # processor_count default is left alone deliberately -- it only costs + # anything near saturation, which this deployment is nowhere near. Cap via + # PB_NATS_RESPONSE_MUXER_DISPATCHERS=4 if that ever changes. def dispatcher_count @dispatcher_count ||= begin default = ::RUBY_ENGINE == "jruby" ? ::Concurrent.processor_count : 1 @@ -547,6 +554,25 @@ def run_dispatch_loop # false-trip the finite pending_bytes_limit, dropping every later # response. Take the same monitor nats-pure's read thread uses. # (#start guarantees the subscription responds to #synchronize.) + # + # Reviewed and deliberately left as-is (2026-08-26). This monitor is + # the one nats-pure's single read thread holds for all of + # #process_msg, so dispatchers contend with the feeder for EVERY + # subscription on the connection, not just this inbox. Measured on + # JRuby 9.4/15 cores: ~9.6us per message, and read-thread ingress + # falls to 43% of its one-dispatcher rate at 8 dispatchers (203k + # msg/s) -- throughput actually peaks at 4 dispatchers and declines + # above it. Real, but this deployment expects <=2000 req/s, i.e. ~1% + # of that ceiling and ~2% of one core, so the cost is noise. + # + # Do NOT re-flag this on load alone. Reopen only if PEAK (not mean) + # response rate nears 100k msg/s, or if this process starts sharing + # its NATS connection with another high-volume subject -- that + # subject pays the read-thread penalty even while the muxer is idle. + # If it must change: batch the decrement (flush every N messages; + # ~1.8x at N=8) rather than dropping it, and keep the total + # overshoot far below pending_bytes_limit. Capping + # PB_NATS_RESPONSE_MUXER_DISPATCHERS at 4 is the no-code option. sub.synchronize { sub.pending_size -= msg.data.size } # Sample post-pop depth into the high-water mark so a burst that fills From fbffc88237cd8d4e3b418c2ecc1246e0775dd647 Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Thu, 24 Sep 2026 10:15:52 -0700 Subject: [PATCH 11/15] Drain past orphan poison pills after the last ThreadPool worker exits A worker killed by a non-StandardError is not replaced during shutdown, but #shutdown still pushes one pill per max_workers. The final drain in #wait_for_termination handed that orphan pill back and stopped, so late work queued behind it was never run while the pool reported a clean termination. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/protobuf/nats/thread_pool.rb | 16 ++++++++++++---- spec/protobuf/nats/thread_pool_spec.rb | 24 ++++++++++++++++++++++++ 2 files changed, 36 insertions(+), 4 deletions(-) diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index f38d7eb..2aaa45e 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -85,8 +85,11 @@ def wait_for_termination(seconds = nil) # had already passed the @shutting_down check can land after the # last worker has drained and exited. Nothing would ever run it, # and the server has already ACKed it. Run it here, on the caller's - # thread, now that no worker is left to race us. - drain_remaining_work + # thread, now that no worker is left to race us. No worker is left + # to take a pill either, so skip past any orphan pill (e.g. one + # meant for a worker that died and was never replaced) instead of + # stopping at it. + drain_remaining_work(requeue_pills: false) return true end return false if deadline && ::Protobuf::Nats.monotonic_time >= deadline @@ -147,7 +150,10 @@ def supervise_workers # by design, so work can still arrive after the final drain. It closes the # window that matters: everything enqueued up to the moment the pool # reports termination runs, so no ACKed request is silently dropped. - def drain_remaining_work + # + # requeue_pills: true when a worker drains (a pill it finds belongs to a + # live sibling); false for the final drain, where no worker is left. + def drain_remaining_work(requeue_pills: true) loop do begin type, cb = @queue.pop(true) # non_block: empty queue ends the drain @@ -156,8 +162,10 @@ def drain_remaining_work end # Another worker's pill: put it back so that worker still exits, and - # stop draining (the remaining pills are theirs, not ours). + # stop draining (the remaining pills are theirs, not ours). With no + # worker left, the pill is an orphan: discard it and keep draining. if type == :stop + next unless requeue_pills @queue << [:stop, nil] break end diff --git a/spec/protobuf/nats/thread_pool_spec.rb b/spec/protobuf/nats/thread_pool_spec.rb index b684b8e..10600e5 100644 --- a/spec/protobuf/nats/thread_pool_spec.rb +++ b/spec/protobuf/nats/thread_pool_spec.rb @@ -85,6 +85,30 @@ expect(pool.size).to eq(0) end + # A worker killed by a non-StandardError is not replaced during shutdown + # (replenish is a no-op then), yet #shutdown still pushes one pill per + # max_workers. The orphan pill outlives every worker. The final drain used + # to hand it back and stop, stranding any late work queued behind it. + it "runs late work queued behind a pill that no worker is left to take" do + pool = described_class.new(2) + ran = ::Queue.new + + pool.instance_variable_get(:@workers).first.kill + wait_until(timeout: 3) { pool.instance_variable_get(:@workers).count(&:alive?) == 1 } + + pool.shutdown + # The surviving worker takes one pill, hands the orphan back, and exits. + wait_until(timeout: 3) { pool.instance_variable_get(:@workers).none?(&:alive?) } + + pool.instance_variable_get(:@active_work).increment + pool.instance_variable_get(:@queue) << [:work, lambda { ran << :ran }] + + expect(pool.wait_for_termination(5)).to be(true) + expect(ran.size).to eq(1) + expect(pool.size).to eq(0) + expect(pool.enqueued_size).to eq(0) + end + it "keeps draining after a drained task raises" do pool = described_class.new(1) ran = ::Queue.new From 48d7c0cfb8fbec88810bc89de3a1150be61131ae Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Thu, 24 Sep 2026 10:16:56 -0700 Subject: [PATCH 12/15] Replace a crashed muxer dispatcher when a sibling already healed The self-heal guard skipped the teardown, so @subscribed_nats stayed set and the following start returned at its fast path without reaching the pool top-up. The crashed dispatcher had already left @resp_handlers, so each guarded crash shrank the pool by one (4 crashing together ended at 1). Extract the top-up into top_up_dispatchers_locked and call it from the guarded branch. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/protobuf/nats/response_muxer.rb | 36 ++++++++++++--------- spec/protobuf/nats/response_muxer_spec.rb | 38 +++++++++++++++++++++++ 2 files changed, 60 insertions(+), 14 deletions(-) diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index 73f3f24..3d9238a 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -337,13 +337,7 @@ def start # Start the cleanup thread start_cleanup_thread - # Top up the dispatcher pool to dispatcher_count. Prunes dead threads - # first so self-healing restarts converge to the target count instead of - # multiplying threads. - LOCK.synchronize do - @resp_handlers.select!(&:alive?) - @resp_handlers << spawn_dispatcher while @resp_handlers.size < dispatcher_count - end + LOCK.synchronize { top_up_dispatchers_locked } end def started? @@ -483,10 +477,11 @@ def spawn_dispatcher # --- End of self-healing logic --- # After sleeping, reset the state and try to start again. + healed = false LOCK.synchronize do - # Remove ourselves from the handler pool BEFORE start re-tops it up. + # Remove ourselves from the handler pool BEFORE the top-up runs. # This thread is still alive (running this rescue) but is about to - # exit, so start's `select!(&:alive?)` would otherwise count it as a + # exit, so the top-up's `select!(&:alive?)` would otherwise count it as a # live dispatcher and spawn no replacement -- leaving the pool one # short (zero dispatchers on CRuby, where dispatcher_count == 1, and # the muxer would stop delivering responses entirely). @@ -498,7 +493,7 @@ def spawn_dispatcher # subscription an earlier sibling just rebuilt and, via # fail_inflight_requests, cancel every request that had already # arrived on it. If a sibling healed us, our subscription is stale - # and start's top-up below is all that is left to do. + # and only the pool top-up is left to do. # # DISPATCHING_SUB_KEY is written by run_dispatch_loop on this same # thread, so it names the subscription this dispatcher was really @@ -508,17 +503,30 @@ def spawn_dispatcher # means we died before draining anything, so there is nothing of # ours to tear down. dispatching_sub = ::Thread.current[DISPATCHING_SUB_KEY] - if @resp_sub.nil? || @resp_sub.equal?(dispatching_sub) - drop_subscription_locked("during self-healing") + healed = !@resp_sub.nil? && !@resp_sub.equal?(dispatching_sub) + if healed + # Not `start`: the muxer is still started on the live + # connection, so start would return at its fast path and never + # reach the top-up, leaving the pool one short per guarded crash. + logger.info "ResponseMuxer already healed by another dispatcher; replacing this dispatcher without a teardown" + top_up_dispatchers_locked else - logger.info "ResponseMuxer already healed by another dispatcher; rejoining the pool without a teardown" + drop_subscription_locked("during self-healing") end end - start + start unless healed end end end + # Top up the dispatcher pool to dispatcher_count. Prunes dead threads + # first so self-healing restarts converge to the target count instead of + # multiplying threads. Must be called while holding LOCK. + def top_up_dispatchers_locked + @resp_handlers.select!(&:alive?) + @resp_handlers << spawn_dispatcher while @resp_handlers.size < dispatcher_count + end + def run_dispatch_loop loop do begin diff --git a/spec/protobuf/nats/response_muxer_spec.rb b/spec/protobuf/nats/response_muxer_spec.rb index 2724506..70d673a 100644 --- a/spec/protobuf/nats/response_muxer_spec.rb +++ b/spec/protobuf/nats/response_muxer_spec.rb @@ -268,6 +268,44 @@ subject.instance_variable_get(:@resp_handlers).each(&:kill) end + # The guarded (no-teardown) branch leaves @subscribed_nats set, so the + # bare `start` it used to call returned at the fast path and never + # reached the top-up. The crashed dispatcher had already removed itself + # from the pool, so every guarded crash left the pool one short. + it "tops the pool back up after a guarded crash that skips the teardown" do + crashing_sub = nats_client.subscribe("test.subscription") + healed_sub = nats_client.subscribe("healed.subscription") + queue = crashing_sub.pending_queue + allow(nats_client).to receive(:subscribe).and_return(crashing_sub) + allow(subject).to receive(:dispatcher_count).and_return(2) + allow(::Protobuf::Nats).to receive(:crash_backoff_seconds).and_return(0.3) + + raised = ::Concurrent::AtomicBoolean.new(false) + allow(queue).to receive(:pop) do + raise ::ThreadError, "Queue closed" if raised.make_true + sleep 0.01 + nil + end + allow(healed_sub.pending_queue).to receive(:pop) { sleep 0.01; nil } + + subject.send(:start) + original = subject.instance_variable_get(:@resp_handlers).dup + expect(original.size).to eq(2) + + # A sibling already healed the muxer onto a different subscription. + subject.instance_variable_set(:@resp_sub, healed_sub) + + wait_until(timeout: 3) { original.any? { |t| !t.alive? } } + crashed = original.find { |t| !t.alive? } + + handlers = subject.instance_variable_get(:@resp_handlers) + expect(subject.instance_variable_get(:@resp_sub)).to equal(healed_sub) + expect(handlers).not_to include(crashed) + expect(handlers.count(&:alive?)).to eq(2) + + handlers.each(&:kill) + end + it "spawns a replacement (does not drop to zero) when the sole dispatcher crashes fatally" do subscription = nats_client.subscribe("test.subscription") queue = subscription.pending_queue From 636b072575ebfbead1e4878b176ed64344f6a77a Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Thu, 24 Sep 2026 10:17:28 -0700 Subject: [PATCH 13/15] Tidy UUIDv7 helper, note the unbounded final drain, update changelog Co-Authored-By: Claude Opus 5.5 (1M context) --- CHANGELOG.md | 4 ++-- lib/protobuf/nats/thread_pool.rb | 4 ++++ lib/protobuf/nats/uuidv7_helper.rb | 3 +-- 3 files changed, 7 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index fe735d7..722506b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,11 +7,11 @@ Correctness fixes for concurrency bugs found while reviewing the 0.13.1/0.13.2 c - Fixed permanent upward drift in the `ByteBoundedQueue` byte counter (new in 0.13.2). Bytes were counted *after* the enqueue, so a consumer could pop an item and subtract its bytes first; `pop`'s clamp at zero swallowed that subtraction, and the producer's increment then applied to an item that was already gone. The counter only ratcheted up, so a long-running server eventually reached the 128 MiB ceiling and dropped **every** request while still looking healthy. The server pops the shared queue from `processor_count` handler threads on JRuby, so the race was live on every message. Bytes are now counted before the enqueue and rolled back if it does not happen. #### Shutdown -- Work accepted just as shutdown begins is no longer stranded. `ThreadPool#push` checks the shutdown flag and then enqueues, so `shutdown` could slip its poison pills between those two steps; workers took a pill and exited, leaving an already-ACKed request to hang until the client's response timeout (60s default). Workers now drain work queued behind their pill, and `wait_for_termination` drains once more after the last worker exits. Admission and shutdown are still not atomic (`#push` is lock-free by design), but nothing enqueued before the pool reports termination is dropped. +- Work accepted just as shutdown begins is no longer stranded. `ThreadPool#push` checks the shutdown flag and then enqueues, so `shutdown` could slip its poison pills between those two steps; workers took a pill and exited, leaving an already-ACKed request to hang until the client's response timeout (60s default). Workers now drain work queued behind their pill, and `wait_for_termination` drains once more after the last worker exits. Admission and shutdown are still not atomic (`#push` is lock-free by design), but nothing enqueued before the pool reports termination is dropped. The final drain also skips past orphan poison pills: a worker killed by a non-`StandardError` is not replaced during shutdown, so its pill outlives every worker and used to stop the drain with work still behind it. - Removed the `Timeout.timeout(10)` wrapper around `SuperSubscriptionManager#shutdown` in `Server#run`. 0.13.1 removed `Timeout` from the manager because its async `Thread#raise`, fired while a thread holds the `SizedQueue` mutex, makes JRuby unwind through the held mutex; the wrapper reintroduced that hazard one frame up. It could genuinely fire: `#shutdown` is not bounded by 10s (one 1s push deadline per handler, then a 5s join, then 1s kill-joins). `#shutdown` already self-bounds, so the wrapper is gone along with the now-dead `require "timeout"`. #### Self-healing -- A response-muxer dispatcher that crashes now tears down only the subscription it actually died on. Dispatchers that crash together wake on staggered backoffs (1s, then 4s), so a late one destroyed the subscription an earlier one had just rebuilt and, via `fail_inflight_requests`, cancelled every request already waiting on it. +- A response-muxer dispatcher that crashes now tears down only the subscription it actually died on. Dispatchers that crash together wake on staggered backoffs (1s, then 4s), so a late one destroyed the subscription an earlier one had just rebuilt and, via `fail_inflight_requests`, cancelled every request already waiting on it. A dispatcher that finds its subscription already healed now spawns its replacement directly; calling `start` there returned at the fast path and left the pool one dispatcher short per crash. #### Observability - `UUIDv7Helper.extract_timestamp` validates the whole token instead of just its length. `String#to_i(16)` stops at the first non-hex character and returns 0 rather than raising, so a foreign reply token parsed as epoch 0 and reported a ~56-year age into the `client.unexpected_message` gauge. Both the dashed and compact (dash-free) UUIDv7 forms are still accepted. diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index 2aaa45e..d19b7bf 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -89,6 +89,10 @@ def wait_for_termination(seconds = nil) # to take a pill either, so skip past any orphan pill (e.g. one # meant for a worker that died and was never replaced) instead of # stopping at it. + # + # This drain is not bounded by `seconds`: a slow late handler holds + # the caller past the deadline. Accepted, because the alternative is + # dropping an ACKed request, and at most a few pushes can land here. drain_remaining_work(requeue_pills: false) return true end diff --git a/lib/protobuf/nats/uuidv7_helper.rb b/lib/protobuf/nats/uuidv7_helper.rb index a42e10e..41d31e3 100644 --- a/lib/protobuf/nats/uuidv7_helper.rb +++ b/lib/protobuf/nats/uuidv7_helper.rb @@ -56,7 +56,7 @@ def self.extract_timestamp(uuid) timestamp_ms = uuid_bytes[0, 12].to_i(16) Time.at(timestamp_ms / 1000.0) - rescue => e + rescue nil end @@ -73,7 +73,6 @@ def self.age_in_seconds(uuid, current_time: Time.now) current_time - timestamp end - # Age (integer ms) of a strictly-validated UUIDv7 token, or nil for a # non-UUIDv7 token. Allocation-light: runs per message on the server's # intake path. From 308da64476a74c977474117f0fa82ea2379fc5da Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Thu, 24 Sep 2026 10:32:32 -0700 Subject: [PATCH 14/15] Simplify self-heal and drain code after review Return healed from the LOCK block, state the orphan-pill rationale once in drain_remaining_work, and use the same AtomicBoolean raise-once stub in both muxer self-heal specs. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/protobuf/nats/response_muxer.rb | 4 ++-- lib/protobuf/nats/thread_pool.rb | 16 +++++++--------- spec/protobuf/nats/response_muxer_spec.rb | 7 ++----- 3 files changed, 11 insertions(+), 16 deletions(-) diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index 3d9238a..da5cf88 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -477,8 +477,7 @@ def spawn_dispatcher # --- End of self-healing logic --- # After sleeping, reset the state and try to start again. - healed = false - LOCK.synchronize do + healed = LOCK.synchronize do # Remove ourselves from the handler pool BEFORE the top-up runs. # This thread is still alive (running this rescue) but is about to # exit, so the top-up's `select!(&:alive?)` would otherwise count it as a @@ -513,6 +512,7 @@ def spawn_dispatcher else drop_subscription_locked("during self-healing") end + healed end start unless healed end diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index d19b7bf..af6657d 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -85,10 +85,7 @@ def wait_for_termination(seconds = nil) # had already passed the @shutting_down check can land after the # last worker has drained and exited. Nothing would ever run it, # and the server has already ACKed it. Run it here, on the caller's - # thread, now that no worker is left to race us. No worker is left - # to take a pill either, so skip past any orphan pill (e.g. one - # meant for a worker that died and was never replaced) instead of - # stopping at it. + # thread, now that no worker is left to race us. # # This drain is not bounded by `seconds`: a slow late handler holds # the caller past the deadline. Accepted, because the alternative is @@ -155,8 +152,10 @@ def supervise_workers # window that matters: everything enqueued up to the moment the pool # reports termination runs, so no ACKed request is silently dropped. # - # requeue_pills: true when a worker drains (a pill it finds belongs to a - # live sibling); false for the final drain, where no worker is left. + # requeue_pills: true when a worker drains, because a pill it finds + # belongs to a live sibling. False for the final drain: no worker is left, + # so any pill is an orphan (e.g. one meant for a worker that died and was + # not replaced during shutdown). The drain discards it and continues. def drain_remaining_work(requeue_pills: true) loop do begin @@ -165,9 +164,8 @@ def drain_remaining_work(requeue_pills: true) break end - # Another worker's pill: put it back so that worker still exits, and - # stop draining (the remaining pills are theirs, not ours). With no - # worker left, the pill is an orphan: discard it and keep draining. + # A sibling's pill: put it back so that worker still exits, and stop + # draining. An orphan pill (see requeue_pills): discard it. if type == :stop next unless requeue_pills @queue << [:stop, nil] diff --git a/spec/protobuf/nats/response_muxer_spec.rb b/spec/protobuf/nats/response_muxer_spec.rb index 70d673a..4246e25 100644 --- a/spec/protobuf/nats/response_muxer_spec.rb +++ b/spec/protobuf/nats/response_muxer_spec.rb @@ -231,12 +231,9 @@ # Long enough to swap in the "healed" subscription mid-backoff. allow(::Protobuf::Nats).to receive(:crash_backoff_seconds).and_return(0.3) - raised = false + raised = ::Concurrent::AtomicBoolean.new(false) allow(queue).to receive(:pop) do - unless raised - raised = true - raise ::ThreadError, "Queue closed" # fatal: kills the dispatch loop - end + raise ::ThreadError, "Queue closed" if raised.make_true # fatal: kills the dispatch loop sleep 0.01 nil end From 95b1c0681b9bf69f5c80655699653556ec7ad24e Mon Sep 17 00:00:00 2001 From: John Bolliger Date: Thu, 24 Sep 2026 10:53:10 -0700 Subject: [PATCH 15/15] Rewrite library comments in Simplified Technical English Comments only: shorter sentences, active voice, no idioms, one term per concept. Narration and restated code are gone; every rationale, measured number, dated decision, and JRuby/nats-pure hazard stays. Comment words across lib/ drop from 8121 to 5487 (-32%). A Ripper token comparison against the previous commit confirms no code, string, or log message changed. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/protobuf/nats.rb | 122 +++-- lib/protobuf/nats/byte_bounded_queue.rb | 70 ++- lib/protobuf/nats/client.rb | 64 ++- lib/protobuf/nats/config.rb | 92 ++-- lib/protobuf/nats/errors.rb | 58 ++- lib/protobuf/nats/response_muxer.rb | 420 ++++++++---------- lib/protobuf/nats/server.rb | 201 ++++----- .../nats/super_subscription_manager.rb | 141 +++--- lib/protobuf/nats/thread_pool.rb | 106 ++--- lib/protobuf/nats/uuidv7_helper.rb | 57 +-- 10 files changed, 555 insertions(+), 776 deletions(-) diff --git a/lib/protobuf/nats.rb b/lib/protobuf/nats.rb index a2a5bc8..6687f1c 100644 --- a/lib/protobuf/nats.rb +++ b/lib/protobuf/nats.rb @@ -1,7 +1,7 @@ require "protobuf/nats/version" require "protobuf" -# We don't need this, but the CLI attempts to terminate. +# Unused here, but the protobuf CLI calls ServiceDirectory#stop on shutdown. require "protobuf/rpc/service_directory" require "nats/io/client" @@ -42,15 +42,15 @@ def self.config end end - # Eagerly load the yml config. + # Load the YAML config now. config - # We will always log an error. + # Always log an error. def self.error_callbacks @error_callbacks ||= [lambda { |error| log_error(error) }] end - # Eagerly load the yml config. + # Load the default error callback now. error_callbacks def self.on_error(&block) @@ -59,10 +59,8 @@ def self.on_error(&block) nil end - # Single instrumentation entry point. Appends the gem's `.protobuf-nats` - # suffix so callers don't repeat it (and can't typo it). Supports both the - # value form `instrument("server.x", 5)` and the block form - # `instrument("client.request_duration") { ... }`. + # Single entry point for instrumentation. Adds the `.protobuf-nats` + # suffix so callers do not repeat it. def self.instrument(event, payload = {}, &block) ::ActiveSupport::Notifications.instrument("#{event}.protobuf-nats", payload, &block) end @@ -79,10 +77,9 @@ def self.notify_error_callbacks(error) nil end - # Bounded, single-thread executor for running error callbacks OFF hot/shared - # threads (notably nats-pure's read/flush thread via on_error). A slow user - # callback must not stall message processing for every subject. The queue is - # bounded and over-capacity notifications are discarded (they're advisory). + # Runs error callbacks off nats-pure's read/flush thread, so a slow + # callback cannot stall message processing. Drops callbacks over the + # queue limit; they are advisory only. ERROR_CALLBACK_EXECUTOR = ::Concurrent::ThreadPoolExecutor.new( :min_threads => 0, :max_threads => 1, @@ -90,9 +87,8 @@ def self.notify_error_callbacks(error) :fallback_policy => :discard ) - # Count of error callbacks discarded because the bounded executor was - # saturated. Lets a flood of dropped callbacks during an incident be observed - # instead of vanishing silently. + # Counts error callbacks dropped when the queue is full. Makes a flood + # of drops visible during an incident. ERROR_CALLBACK_DROP_COUNT = ::Concurrent::AtomicFixnum.new(0) def self.error_callback_drop_count @@ -100,19 +96,15 @@ def self.error_callback_drop_count end def self.notify_error_callbacks_async(error) - # #post returns false when the job is rejected. With the :discard fallback - # policy the job is silently dropped (returning false) rather than raising, - # so the false return is the only drop signal to handle. + # #post returns false on rejection. The :discard policy drops the + # job instead of raising, so false is the only drop signal. accepted = ERROR_CALLBACK_EXECUTOR.post { notify_error_callbacks(error) } record_dropped_error_callback unless accepted nil end - # Record a discarded error callback. Kept cheap -- this runs on nats-pure's - # read/flush thread, so it must NOT format/log the error synchronously (the - # whole point of the async path). The atomic counter is the durable signal; - # the instrument gauge emits a discrete event for dashboards (drops only - # happen under a severe flood, so a notification per drop is acceptable). + # Records a dropped callback. Runs on nats-pure's read/flush thread, so + # do NOT format or log the error here; that would defeat the async path. def self.record_dropped_error_callback ERROR_CALLBACK_DROP_COUNT.increment instrument("error_callback_dropped", 1) @@ -133,16 +125,16 @@ def self.start_client_nats_connection GET_CONNECTED_MUTEX.synchronize do break true if @client_nats_connection - # NOTE: nats-pure has no :disable_reconnect_buffer option (it was a - # jnats concept). During a reconnect nats-pure buffers publishes and, - # if the connection is fully closed, raises ConnectionClosedError -- - # both of which the client's transient-error retry path now handles. + # nats-pure has no :disable_reconnect_buffer option (a jnats + # concept). It buffers publishes during reconnect, and raises + # ConnectionClosedError if the connection fully closes. The + # client's retry path handles both cases. options = config.connection_options client = NatsClient.new - # Register lifecycle callbacks BEFORE connecting so a disconnect or - # error during the initial handshake is still observed. + # Register lifecycle callbacks before connecting, so the handshake + # is also observed. client.on_disconnect do logger.warn("Client NATS connection was disconnected") end @@ -153,28 +145,26 @@ def self.start_client_nats_connection client.on_close do logger.warn("Client NATS connection was closed") - # A close is terminal for this client object (nats-pure only reconnects - # via on_disconnect/on_reconnect; on_close means it gave up). Drop the - # memoized reference so the next start_client_nats_connection rebuilds a - # fresh connection instead of reusing a permanently-dead one. In-flight - # callers keep their own local reference; only new calls rebuild. + # A close is terminal (nats-pure only reconnects via + # on_disconnect/on_reconnect). Clear the memo, so the next call + # builds a fresh connection. Callers with a local reference keep it. @client_nats_connection = nil end client.on_error do |error| - # Runs on nats-pure's read/flush thread -- offload so a slow callback - # can't stall message processing. + # Runs on nats-pure's read/flush thread; offload it so a slow + # callback cannot stall message processing. notify_error_callbacks_async(error) end begin client.connect(options) - # Ensure we have a valid connection to the NATS server. + # Confirm the connection is valid. client.flush(5) rescue => e - # A failed handshake can leave nats-pure's reader/flusher threads - # running on a half-open client; close it so we don't leak them, then - # surface the failure (the next call will retry with a fresh client). + # A failed handshake can leave nats-pure's threads running on a + # half-open client. Close it to avoid a leak, then raise; the + # next call retries with a fresh client. client.close rescue nil raise e end @@ -185,17 +175,16 @@ def self.start_client_nats_connection end end - # Monotonic clock for durations/ages; immune to wall-clock (NTP) jumps. - # Single source of truth shared by the client muxer and server pools. + # Monotonic clock for durations and ages, immune to wall-clock (NTP) + # jumps. Shared by the client muxer and server pools. def self.monotonic_time ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) end - # Strict integer parsing for env overrides. String#to_i silently turns a - # malformed value ("5s", "abc") into 0 -- which for a timeout means "fail - # every request instantly". Log loudly and fall back to the default - # instead. Values below `min` (when given) are rejected the same way, so - # range policy lives here rather than ad hoc at each call site. + # Strict integer parsing for env overrides. String#to_i silently turns + # a bad value ("5s", "abc") into 0, which fails every request instantly + # for a timeout. Log an error and use the default instead. Also + # rejects a value below `min`. def self.env_int(name, default, min: nil) raw = ::ENV[name] return default if raw.nil? @@ -211,7 +200,7 @@ def self.env_int(name, default, min: nil) default end - # Float sibling of env_int, same strict-parse-or-default contract. + # Float version of env_int. Same strict-parse-or-default rule. def self.env_float(name, default) raw = ::ENV[name] return default if raw.nil? @@ -221,38 +210,33 @@ def self.env_float(name, default) default end - # Client response timeout (seconds). Single source of truth for the env - # var and its default: the client waits this long per request, and the - # muxer stretches its token TTL past it (ResponseMuxer#token_ttl_seconds). + # Client response timeout, in seconds. The muxer sets its token TTL + # longer than this (ResponseMuxer#token_ttl_seconds). def self.client_response_timeout env_int("PB_NATS_CLIENT_RESPONSE_TIMEOUT", 60) end - # How long a consumer loop parks when its queue pops nil (a closed queue - # returns nil immediately forever). Shared by the muxer dispatch loop and - # the server intake handlers so the two mirrored loops can't drift. + # How long a consumer loop waits after its queue pops nil (a closed + # queue always returns nil). Shared by the muxer and server intake + # loops, so they cannot drift apart. CLOSED_QUEUE_PARK_SECONDS = 0.05 - # nats-pure increments a subscription's pending_size (bytes) for every - # inbound message and only decrements it in its own consumption paths - # (next_msg / the sub's message thread). The server intake pops - # pending_queue directly and never runs those paths, so pending_size grows - # monotonically and the byte-based slow-consumer limit would eventually trip - # on *cumulative* traffic -- silently dropping every later message on that - # subscription. Disable the byte limit; the message-count limit - # (pending_queue depth, tracked accurately for free) still bounds a genuinely - # slow consumer. Guarded so a non-standard/faked subscription is a no-op. + # nats-pure only decrements pending_size (bytes) in its own consumption + # paths. Server intake pops pending_queue directly and skips those + # paths, so pending_size only grows and would eventually trip the byte + # limit on cumulative traffic, dropping every later message. Disable + # the byte limit; the message-count limit (pending_queue depth) still + # catches a slow consumer. No-op on a non-standard subscription. # - # NOTE: only the server uses this now. The client muxer instead decrements - # pending_size itself after each pop (ResponseMuxer#run_dispatch_loop), which - # keeps the counter accurate and lets it enforce a finite byte ceiling. + # NOTE: only the server uses this. The client muxer decrements + # pending_size itself after each pop (ResponseMuxer#run_dispatch_loop) + # and enforces its own byte ceiling. def self.disable_subscription_byte_limit!(sub) sub.pending_bytes_limit = ::Float::INFINITY if sub.respond_to?(:pending_bytes_limit=) end - # Exponential backoff (seconds) for self-healing worker threads after a fatal - # crash, capped. Shared by the ResponseMuxer dispatcher pool and the server - # SuperSubscriptionManager handler pool so the formula can't drift between them. + # Exponential backoff, in seconds, for a worker thread after a fatal + # crash. Shared by the ResponseMuxer and SuperSubscriptionManager pools. def self.crash_backoff_seconds(crash_count, cap = 60) [(crash_count**2), cap].min end diff --git a/lib/protobuf/nats/byte_bounded_queue.rb b/lib/protobuf/nats/byte_bounded_queue.rb index 8d412e2..bed5865 100644 --- a/lib/protobuf/nats/byte_bounded_queue.rb +++ b/lib/protobuf/nats/byte_bounded_queue.rb @@ -2,21 +2,18 @@ module Protobuf module Nats - # A SizedQueue that additionally bounds the total *bytes* of its contents, - # not just the message count. The server funnels every subscription into one - # shared intake queue, so a per-subscription byte limit (nats-pure's - # pending_bytes_limit) can't bound the aggregate heap -- this shared counter - # can. Count is still bounded by the SizedQueue capacity it inherits. + # A `SizedQueue` that also bounds total bytes, not just message count. + # One shared intake queue serves all subscriptions, so a per-subscription + # limit (nats-pure's `pending_bytes_limit`) can't bound the combined + # heap; this shared counter can. # - # When a push would exceed the byte ceiling we DROP the message rather than - # block: pushes happen on nats-pure's read thread (Subscription#dispatch), and - # blocking it would stall PING/PONG and every other subject. A drop mirrors - # nats-pure's own SlowConsumer behaviour. Non-message items (the :shutdown - # poison pill) carry zero bytes, so they are never dropped by the byte gate. + # A push over the byte limit drops the message instead of blocking, like + # nats-pure's SlowConsumer: pushes run on nats-pure's read thread + # (`Subscription#dispatch`), and blocking it would stall PING/PONG. The + # `:shutdown` poison pill counts as zero bytes and is never dropped. # - # A drop invokes the optional +on_drop+ callback with the dropped byte count, - # so the caller owns any (context-specific) instrumentation rather than this - # generic queue class hard-coding it. + # A drop calls the optional `on_drop` callback with the byte count, so + # the caller owns instrumentation. class ByteBoundedQueue < ::SizedQueue def initialize(max_msgs, max_bytes, on_drop: nil) super(max_msgs) @@ -25,12 +22,10 @@ def initialize(max_msgs, max_bytes, on_drop: nil) @bytes = ::Concurrent::AtomicFixnum.new(0) end - # Enqueue unless it would exceed the byte ceiling. The check-then-add races - # only concurrent pops (which lower @bytes), so the ceiling can be exceeded - # by at most one in-flight message -- a soft limit, like nats-pure's own - # byte accounting. Returns self (SizedQueue#push contract). Raises - # ThreadError from super on a non_block push into a count-full queue; the - # bytes counted for that attempt are rolled back before it propagates. + # Enqueue unless it would exceed the byte limit. The check-then-add + # races only concurrent pops, so this soft limit (like nats-pure's own + # byte accounting) can be exceeded by at most one in-flight message. + # Returns `self`, the `SizedQueue#push` contract. def push(obj, non_block = false) bytes = byte_size(obj) if bytes > 0 && (@bytes.value + bytes) > @max_bytes @@ -38,27 +33,23 @@ def push(obj, non_block = false) return self end - # Count the bytes BEFORE the enqueue, and roll back if the enqueue does - # not happen. Counting after `super` lets a consumer pop the object and - # subtract its bytes before this thread has added them; #pop's clamp at - # zero then swallows that subtraction, and the increment that lands - # afterwards becomes a permanent overcount for a message that is already - # gone. The counter only ever ratchets up, and once it reaches - # @max_bytes every later push is dropped forever -- the same drift class - # as the nats-pure pending_size bug. + # Count bytes before the enqueue, and roll back on failure. Counting + # after `super` would let a pop subtract first; `#pop`'s zero-clamp + # then swallows it, and the later increment permanently overcounts a + # message already gone. That drift only climbs, jamming every push + # once it hits `@max_bytes` -- same bug class as nats-pure's + # `pending_size` bug. # - # A blocking push (non_block false, count-full queue) leaves the bytes - # counted while we wait. That is a deliberate short overcount: it errs - # toward dropping rather than admitting, and it resolves as soon as the - # push completes or rolls back. + # A blocking push on a full queue counts bytes while it waits: a + # deliberate short overcount, resolved once the push completes. @bytes.increment(bytes) if bytes > 0 pushed = false begin super(obj, non_block) pushed = true ensure - # ensure (not rescue) so an async Thread#raise or a non-StandardError - # unwind rolls the counter back too. + # `ensure`, not `rescue`: also rolls back on an async + # `Thread#raise` or non-`StandardError` unwind. @bytes.decrement(bytes) if bytes > 0 && !pushed end self @@ -67,10 +58,9 @@ def push(obj, non_block = false) def pop(non_block = false) obj = super - # nil == closed/empty non_block; nothing dequeued, nothing to subtract. - # The clamp at zero is only a backstop for #clear racing an in-flight - # pop (clear zeroes the counter, then the pop subtracts). #push counts - # bytes before enqueueing, so a normal pop always has its bytes present. + # nil means closed or empty (non-blocking): nothing to subtract. The + # zero-clamp only guards `#clear` racing an in-flight pop; `#push` + # counts bytes first, so a normal pop always finds them present. @bytes.update { |value| [value - byte_size(obj), 0].max } if obj obj end @@ -80,15 +70,15 @@ def clear @bytes.value = 0 end - # Current resident byte total (gauge for observability). + # Current resident byte total (an observability gauge). def bytesize @bytes.value end private - # Bytes attributable to a queued item. NATS::Msg carries #data; the - # :shutdown poison pill (and any other non-message sentinel) counts as 0. + # Bytes charged to a queued item. `NATS::Msg` carries `#data`; the + # `:shutdown` poison pill and other sentinels count as 0. def byte_size(obj) obj.respond_to?(:data) && obj.data ? obj.data.bytesize : 0 end diff --git a/lib/protobuf/nats/client.rb b/lib/protobuf/nats/client.rb index 53a4dd1..2ce8624 100644 --- a/lib/protobuf/nats/client.rb +++ b/lib/protobuf/nats/client.rb @@ -4,7 +4,7 @@ require "protobuf/rpc/connectors/base" require "monitor" -# Load this independently because we store the class singleton in a const. +# Required here: we store the class singleton in a const below. require "protobuf/nats/response_muxer" module Protobuf @@ -13,11 +13,10 @@ class Client < ::Protobuf::Rpc::Connectors::Base RESPONSE_MUXER = ::Protobuf::Nats::ResponseMuxer.new - # On JRuby (true parallelism) concurrent writes to a plain nested Hash can - # raise ConcurrentModificationError / corrupt the map, so the cache must be - # a Concurrent::Map. On CRuby the GVL makes plain-Hash reads/writes atomic - # (a racing `||=` at worst recomputes an identical value), and a plain Hash - # is meaningfully faster than Concurrent::Map, so we keep the Hash there. + # On JRuby, concurrent writes to a plain Hash can raise + # ConcurrentModificationError, so the cache must be a Concurrent::Map. + # On CRuby the GVL makes plain-Hash access atomic, and a plain Hash + # is faster, so we keep the Hash there. CONCURRENT_SUBSCRIPTION_CACHE = (::RUBY_ENGINE == "jruby") @subscription_key_cache = CONCURRENT_SUBSCRIPTION_CACHE ? ::Concurrent::Map.new : {} @@ -31,18 +30,14 @@ def response_muxer end def initialize(options) - # may need to override to setup connection at this stage ... may also do on load of class super - # This will ensure the client is started. ::Protobuf::Nats.start_client_nats_connection - - # Ensure the response muxer is started RESPONSE_MUXER.start end def close_connection - # no-op (I think for now), the connection to server is persistent + # No-op. The connection to the server stays open and is shared. end def self.subscription_key_cache @@ -61,8 +56,8 @@ def nack_backoff_intervals if raw.nil? DEFAULT_NACK_BACKOFF_INTERVALS else - # Strict parse, matching env_int: "fast,slow".to_i would silently - # become [0, 0] (retry with no backoff) instead of the default. + # Parse strictly, like env_int. "fast,slow".to_i would silently + # give [0, 0] (no backoff) instead of the default. begin raw.split(",").map { |interval| Integer(interval.strip, 10) } rescue ::ArgumentError @@ -89,8 +84,8 @@ def reconnect_delay @reconnect_delay ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_RECONNECT_DELAY", ack_timeout) end - # Random jitter (seconds) added to reconnect_delay so a fleet hitting the - # same NATS outage doesn't reconnect in lockstep. Limit is in milliseconds. + # Random jitter (seconds) added to reconnect_delay, so a fleet does + # not reconnect in lockstep after a shared outage. Limit is in ms. def reconnect_delay_splay return 0 unless reconnect_delay_splay_limit > 0 rand(reconnect_delay_splay_limit) / 1000.0 @@ -100,7 +95,7 @@ def reconnect_delay_splay_limit @reconnect_delay_splay_limit ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_RECONNECT_DELAY_SPLAY_LIMIT", 1000) end - # Number of attempts for ack-timeouts and transient transport errors. + # Retry count for ack-timeouts and transient transport errors. def max_retries @max_retries ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_MAX_RETRIES", 3, :min => 1) end @@ -110,7 +105,6 @@ def response_timeout end def send_request - # This will ensure the client is started. ::Protobuf::Nats.start_client_nats_connection ::Protobuf::Nats.instrument "client.request_duration" do @@ -148,20 +142,18 @@ def send_request_through_nats ::Protobuf::Nats.log_error(error) if (retries -= 1) > 0 - # Only sleep when there is a retry to wait for -- sleeping before the - # raise on the final attempt just delayed the failure by - # reconnect_delay for nothing. + # Only sleep when a retry follows. Sleeping before the final + # raise would just delay the failure for nothing. delay = reconnect_delay + reconnect_delay_splay logger.warn "A transient transport error was raised (#{error.class}). Sleeping #{delay.round(3)}s before retrying." sleep delay - # The connection object may be terminally dead (nats-pure exhausted its - # reconnect attempts, fired on_close, and the memoized client was - # dropped). Rebuild it -- and move the muxer's inbox subscription onto - # the new connection -- before retrying; otherwise the retry would - # publish into a nil/closed connection and fail identically. A rebuild - # failure (all nodes still down) just consumes this retry attempt like - # any other transport error. + # The connection may be terminally dead (nats-pure gave up + # reconnecting and dropped the memoized client). Rebuild it, and + # move the muxer's inbox onto the new connection, before + # retrying; otherwise the retry publishes into a closed + # connection and fails the same way. A rebuild failure just + # uses up this retry, like any other transport error. begin ::Protobuf::Nats.start_client_nats_connection response_muxer.start @@ -196,17 +188,14 @@ def formatted_service_and_method_name end def nats_request_with_two_responses(subject, data, opts) - # Wait for the ACK from the server. (Named to avoid shadowing the - # instance methods used as fallbacks.) + # Named first_message_timeout, not ack_timeout, to avoid shadowing + # the #ack_timeout fallback method used below. first_message_timeout = opts[:ack_timeout] || ack_timeout - # Wait for the protobuf response response_message_timeout = opts[:timeout] || response_timeout - # Publish message with the reply topic pointed at the response muxer. req = RESPONSE_MUXER.new_request req.publish(subject, data) - # Receive the first message begin first_message = req.next_message(first_message_timeout) logger.debug { "received message with subject:#{first_message.subject}" } if logger.debug? @@ -214,27 +203,24 @@ def nats_request_with_two_responses(subject, data, opts) return :ack_timeout end - # Check for a NACK return :nack if first_message.data == ::Protobuf::Nats::Messages::NACK - # Receive the second message begin second_message = req.next_message(response_message_timeout) rescue ::NATS::Timeout - # ignore to raise a repsonse timeout below + # Ignore. This raises a response timeout below instead. end - # NOTE: This might be nil, so be careful checking the data value + # May be nil: check the data value carefully below. second_message_data = second_message&.data - # This should never happen, if it does, then return an :ack_timeout because something went wrong + # Two ACKs should never happen. Treat it as a timeout if it does. if first_message&.data == ::Protobuf::Nats::Messages::ACK && second_message&.data == ::Protobuf::Nats::Messages::ACK logger.warn "received ACK/ACK message." return :ack_timeout end - # Check messages response = case ::Protobuf::Nats::Messages::ACK when first_message&.data then second_message_data when second_message&.data then first_message&.data @@ -245,7 +231,7 @@ def nats_request_with_two_responses(subject, data, opts) response ensure - # cleanup the token from the request map + # Remove the token from the request map. req.cleanup if req end diff --git a/lib/protobuf/nats/config.rb b/lib/protobuf/nats/config.rb index 8eb84f1..b20b977 100644 --- a/lib/protobuf/nats/config.rb +++ b/lib/protobuf/nats/config.rb @@ -16,16 +16,15 @@ class Config DEFAULTS = { :connect_timeout => nil, - # Per-server reconnect attempt cap. -1 means reconnect forever - # (nats-pure treats a negative value as infinite). When exhausted on - # every server, nats-pure fires on_close and the connection is - # terminally dead. + # Per-server reconnect cap. -1 means forever (nats-pure treats + # negative as infinite). Once exhausted on every server, nats-pure + # fires on_close and the connection is dead for good. :max_reconnect_attempts => 60_000, - # Failover tuning; nil falls through to the nats-pure defaults - # (reconnect_time_wait: 2s, ping_interval: 120s, max_outstanding_pings: 2). - # A node that dies silently (partition, hard host failure) is only - # detected after ping_interval * max_outstanding_pings, so lower these - # for faster failover to a healthy node. + # Failover tuning; nil uses the nats-pure defaults + # (reconnect_time_wait: 2s, ping_interval: 120s, + # max_outstanding_pings: 2). A silent node death is detected only + # after ping_interval times max_outstanding_pings. Lower these for + # faster failover. :reconnect_time_wait => nil, :ping_interval => nil, :max_outstanding_pings => nil, @@ -57,13 +56,11 @@ def load_from_yml(reload = false) absolute_config_path = ::File.expand_path(config_path) if ::File.exist?(absolute_config_path) yaml_string = ::ERB.new(::File.read(absolute_config_path)).result - # safe_load (no arbitrary object deserialization) with aliases - # enabled so the common `&defaults` / `<<: *defaults` pattern works. + # safe_load blocks object deserialization; aliases stay on for + # `&defaults` / `<<: *defaults`. parsed = ::YAML.safe_load(yaml_string, :aliases => true) - # An empty file parses to nil/false, and a file without a section - # for the current env yields nil on lookup -- guard both so we - # don't blow up with NoMethodError below. + # Guard nil: an empty file, or one missing the env section. yaml_config = (parsed && parsed[env]) || {} end @@ -80,12 +77,11 @@ def load_from_yml(reload = false) end end - # Only the keys nats-pure's `connect` actually consumes. App-level settings - # (uses_tls, tls_client_cert, tls_client_key, tls_ca_cert, - # server_subscription_key_*, subscription_key_replacements) are read - # directly via their accessors elsewhere and must NOT be forwarded to - # nats-pure (it ignores unknown keys today, but that is brittle). The TLS - # cert/key/CA are folded into the :tls context by #new_tls_context. + # Only the keys nats-pure's `connect` consumes. App-level settings + # (uses_tls, tls_client_cert/key/ca_cert, server_subscription_key_*, + # subscription_key_replacements) are read via their own accessors. + # Do NOT forward them; nats-pure ignores unknown keys today, but that + # is brittle. #new_tls_context folds the TLS settings into :tls. def connection_options(reload = false) @connection_options = false if reload @connection_options ||= begin @@ -93,15 +89,12 @@ def connection_options(reload = false) servers: servers, max_reconnect_attempts: max_reconnect_attempts, connect_timeout: connect_timeout, - # nil values are safe to forward: nats-pure nil-fills each of these - # with its own default during connect. + # nil is safe here; nats-pure fills each with its own default. reconnect_time_wait: reconnect_time_wait, ping_interval: ping_interval, max_outstanding_pings: max_outstanding_pings, - # A friendly connection name surfaces in NATS server monitoring, - # error reporting, and debugging (highly recommended by the NATS - # docs). Shared by both the client and server connections since both - # build from this hash. + # A friendly name helps NATS server monitoring, error reports, + # and debugging. Both client and server build from this hash. name: resolved_connection_name, } options[:tls] = {:context => new_tls_context} if uses_tls @@ -109,23 +102,21 @@ def connection_options(reload = false) end end - # Precedence: PB_NATS_CONNECTION_NAME env var > yaml/DEFAULT connection_name - # > hostname. Env wins so ops can set a per-pod/per-host name without a - # config file; the hostname fallback ensures the name is never blank. + # Precedence: PB_NATS_CONNECTION_NAME env var, then config + # connection_name, then hostname (never blank). def resolved_connection_name ::ENV["PB_NATS_CONNECTION_NAME"] || connection_name || ::Socket.gethostname end def new_tls_context tls_context = ::OpenSSL::SSL::SSLContext.new - # Floor at TLS 1.2, ceiling at TLS 1.3 (replaces the deprecated - # ssl_version=:TLSv1_2 hard pin). The client offers 1.2 and 1.3 and - # negotiates the highest the server also supports, so a TLS-1.2-only - # transport still connects (verified on JRuby 9.4 and 10.0). + # Floor TLS 1.2, ceiling TLS 1.3 (replaces the deprecated + # ssl_version=:TLSv1_2 pin). Negotiates the highest version the + # server supports; a TLS-1.2-only server still connects (verified + # on JRuby 9.4 and 10.0). # - # An OpenSSL build without TLS 1.3 support does not define - # TLS1_3_VERSION (#7); degrade to a 1.2-only ceiling there instead of - # raising NameError at connect time. + # An OpenSSL build without TLS 1.3 lacks TLS1_3_VERSION (#7); + # degrade to 1.2-only instead of raising NameError. tls_context.min_version = ::OpenSSL::SSL::TLS1_2_VERSION tls_context.max_version = if defined?(::OpenSSL::SSL::TLS1_3_VERSION) ::OpenSSL::SSL::TLS1_3_VERSION @@ -133,33 +124,30 @@ def new_tls_context ::OpenSSL::SSL::TLS1_2_VERSION end tls_context.cert = ::OpenSSL::X509::Certificate.new(::File.read(tls_client_cert)) if tls_client_cert - # PKey.read handles any key type (RSA, EC, Ed25519...); the previous - # PKey::RSA.new rejected non-RSA client keys. + # PKey.read accepts any key type; PKey::RSA.new rejects non-RSA keys. tls_context.key = ::OpenSSL::PKey.read(::File.read(tls_client_key)) if tls_client_key - # Verify the NATS server's certificate chain. This context is handed to - # nats-pure as :tls => {:context => ...}; nats-pure uses a supplied - # context verbatim and does NOT call #set_params, so verification has to - # be configured here. Without this the OpenSSL default (VERIFY_NONE) - # stood and any certificate -- including an attacker's -- was accepted. + # Verify the server's certificate chain. nats-pure uses a supplied + # :tls context verbatim and does NOT call #set_params, so + # verification must be set here. Without it, OpenSSL's VERIFY_NONE + # default let any certificate through, including an attacker's. tls_context.verify_mode = ::OpenSSL::SSL::VERIFY_PEER cert_store = ::OpenSSL::X509::Store.new if tls_ca_cert - # Trust the configured CA bundle (the private-CA deployment case). + # Trust the configured CA bundle (private-CA deployment). cert_store.add_file(tls_ca_cert) else - # No CA configured: fall back to the system trust store. + # No CA configured: use the system trust store. cert_store.set_default_paths end tls_context.cert_store = cert_store - # NOTE: hostname (SAN/CN) verification is NOT enabled here. nats-pure only - # sets the SSLSocket hostname from @tls[:hostname], which it populates - # itself only when it builds the context; for a supplied context it stays - # nil, and a single static hostname would be wrong for a multi-server - # cluster that reconnects across hosts. Chain verification above still - # ensures the cert is signed by the trusted CA. Plumbing per-connection - # hostname verification is tracked separately. + # NOTE: hostname (SAN/CN) verification is still OFF. nats-pure only + # sets the SSLSocket hostname when it builds the context itself; a + # supplied context gets no hostname, and one static value would be + # wrong for a multi-server cluster anyway. Chain verification above + # still confirms the cert is CA-signed. Per-connection hostname + # verification is separate future work. tls_context end diff --git a/lib/protobuf/nats/errors.rb b/lib/protobuf/nats/errors.rb index 6d806a8..6c8e31d 100644 --- a/lib/protobuf/nats/errors.rb +++ b/lib/protobuf/nats/errors.rb @@ -13,48 +13,42 @@ class ResponseTimeout < ClientError class ResponseMuxer < ClientError end - # Raised by ResponseMuxer#start when the response subscription can't support - # the muxer's pending_size byte accounting (it doesn't respond to - # #synchronize). nats-pure's Subscription always includes MonitorMixin, so - # in practice this never fires against a real connection -- it's a tripwire - # for a significant change in nats-pure's internals (or a non-standard - # injected client). We take @resp_sub.synchronize on every pop to decrement - # pending_size and keep the finite byte cap accurate; without it that counter - # would only grow and eventually false-trip the limit, silently dropping - # every response. Failing loudly at start beats degrading silently at runtime. + # Raised by ResponseMuxer#start when the response subscription lacks + # #synchronize, needed for pending_size byte accounting. nats-pure's + # Subscription always includes MonitorMixin, so this is a tripwire + # for a nats-pure internals change or a non-standard client, not a + # real-world case. Without #synchronize, pending_size would only + # grow and eventually false-trip the byte cap, silently dropping + # every response. Fail loudly at start instead. # - # Deliberately NOT in RETRYABLE_TRANSPORT_ERRORS: retrying can't fix a - # structural mismatch. NOTE: intentionally undocumented in the README -- it's - # an internal invariant/tripwire, not a user-facing knob or metric. + # Not in RETRYABLE_TRANSPORT_ERRORS: retrying cannot fix a structural + # mismatch. Left out of the README as an internal tripwire. class IncompatibleSubscription < ClientError end class MriIOException < ::StandardError end - # Raised into a worker thread to reclaim a handler that has outlived the - # client's response_timeout. Only used when overdue-reclaim is explicitly - # enabled via PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS (default off); the - # documented default is that handlers are never aborted. + # Raised into a worker thread to reclaim a handler that outlived the + # client's response_timeout. Only used when + # PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS is on (default off). class HandlerOverdue < ::StandardError end IOException = MriIOException - # Transient transport errors that mean the NATS connection is unavailable - # or was dropped mid-request. These should be ridden out by sleeping for - # reconnect_delay and retrying (nats-pure reconnects in a background - # thread), rather than bubbling up as an immediate RPC_ERROR. + # Transient transport errors: the connection is unavailable or was + # dropped mid-request. Sleep for reconnect_delay and retry (nats-pure + # reconnects in the background) instead of raising RPC_ERROR. # - # NOTE: when jnats was removed in favor of nats-pure, IOException was - # collapsed to MriIOException, which nothing ever raises -- silently - # disabling the client's reconnect/retry path. This list restores it by - # matching the errors the pure-ruby client and socket layer actually raise. + # NOTE: removing jnats collapsed IOException to MriIOException, which + # nothing raises, silently disabling reconnect/retry. This list + # restores it with the errors the pure-ruby client actually raises. RETRYABLE_TRANSPORT_ERRORS = [ IOException, # legacy / explicit wraps - # Raised when a request races a ResponseMuxer restart (its inbox prefix - # is briefly nil while it rebuilds on a new connection). Transient by - # nature: the next attempt runs after the muxer has restarted. + # Raised when a request races a ResponseMuxer restart (its inbox + # prefix is briefly nil while rebuilding). The next attempt runs + # after the muxer restarts. ResponseMuxer, ::EOFError, ::IOError, @@ -63,15 +57,15 @@ class HandlerOverdue < ::StandardError ::Errno::ECONNABORTED, ::Errno::EPIPE, ::Errno::ETIMEDOUT, - # Raised when a NATS node (or the route to it) dies without sending a - # FIN/RST -- e.g. a network partition or a hard host failure. nats-pure - # fails over to another node in the pool; ride it out and retry. + # Raised when a NATS node (or its route) dies without a FIN/RST, + # e.g. a network partition or hard host failure. nats-pure fails + # over to another node; ride it out and retry. ::Errno::EHOSTUNREACH, ::Errno::ENETUNREACH, ].tap do |errors| - # nats-pure raises this when publishing on a closed connection. + # nats-pure raises this on a publish to a closed connection. errors << ::NATS::IO::ConnectionClosedError if defined?(::NATS::IO::ConnectionClosedError) - # On JRuby, socket EOF can still surface as a Java IOException. + # On JRuby, socket EOF can surface as a Java IOException. errors << ::Java::JavaIo::IOException if defined?(::JRUBY_VERSION) end.freeze end diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index da5cf88..5635af1 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -13,68 +13,58 @@ class ResponseMuxer MAX_RESPONSES_PER_TOKEN = 10 TOKEN_TTL_SECONDS = 600 # 10 minutes - # The shared response subscription is bounded by BOTH a message count and a - # byte ceiling; nats-pure drops (SlowConsumer) on whichever trips first, so - # the firehose is capped at min(count, bytes) instead of buffering unbounded - # protobuf payloads on the JVM heap (the 0.13.2 OOM). Dispatchers drain it to - # ~0, so these are burst headroom, not a working set. + # The response queue caps message count and bytes. nats-pure drops + # messages (SlowConsumer) when either limit trips, so memory stays + # bounded instead of filling the JVM heap (caused an OOM in 0.13.2). + # Dispatchers keep the queue near empty, so these limits bound bursts. # - # The count is deliberately tighter than the ecosystem's per-subscription - # defaults (nats-pure 65,536; nats.go 500,000): those bound off-heap buffers, - # this is Ruby objects on the heap, and the byte cap is the real ceiling. The - # byte default stays aligned at 64 MiB (nats-pure/nats.go both use it). - # Override via PB_NATS_RESPONSE_MUXER_QUEUE_SIZE / _QUEUE_BYTES. + # The count is lower than nats-pure (65,536) or nats.go (500,000), + # because those bound off-heap buffers, not Ruby heap objects. The byte + # limit is the real ceiling, set to 64 MiB to match both clients. + # Override with PB_NATS_RESPONSE_MUXER_QUEUE_SIZE and _QUEUE_BYTES. DEFAULT_RESPONSE_QUEUE_SIZE = 1024 DEFAULT_RESPONSE_QUEUE_BYTES = 64 * 1024 * 1024 # 64MiB - # Sentinel pushed onto a token's queue to wake a waiter blocked in - # next_message. We cannot rely on Queue#close alone: on JRuby, close does - # NOT wake a pop() that is blocked with a timeout: -- neither the native - # Queue (Ruby >= 3.2 / JRuby 10) nor concurrent-ruby's RubyTimeoutQueue - # (Ruby < 3.2 / JRuby 9.4, whose timed pop only wakes on push) signals a - # timed waiter on close. CRuby's Queue#close does wake it, which is why - # this only ever bit JRuby. Pushing an explicit sentinel wakes the waiter - # immediately on every engine; next_message treats it as a timeout. + # Sentinel pushed onto a token's queue to wake a waiter in next_message. + # On JRuby, Queue#close does not wake a timed pop (native Queue on JRuby + # 10, concurrent-ruby's RubyTimeoutQueue on JRuby 9.4); CRuby's close + # does. Pushing this sentinel wakes the waiter on every engine; + # next_message treats it as a timeout. QUEUE_WAKE = ::Object.new - # Thread-local key naming the subscription a dispatcher is currently - # draining (see run_dispatch_loop / spawn_dispatcher). + # Thread-local key naming the subscription a dispatcher is draining + # (see run_dispatch_loop and spawn_dispatcher). DISPATCHING_SUB_KEY = :pb_nats_dispatching_sub def initialize - # Per-token response queues for lock-free message delivery. @resp_map is a - # Concurrent::Map so request threads and dispatcher threads can insert, - # look up, and delete tokens without serializing on a single mutex (on - # JRuby it is backed by java.util.concurrent.ConcurrentHashMap). Each - # value is a Hash { queue:, created_at: }. + # @resp_map is a Concurrent::Map, so request and dispatcher threads + # insert, read, and delete tokens without one shared mutex (backed by + # java.util.concurrent.ConcurrentHashMap on JRuby). Each value is a + # Hash { queue:, created_at: }. @resp_map = ::Concurrent::Map.new @resp_handlers = [] @cleanup_thread = nil @shutdown = false @cleanup_mutex = ::Mutex.new @cleanup_cv = ::ConditionVariable.new - @restarting = false # Flag to prevent concurrent restarts - # The connection object the inbox subscription lives on. Compared by - # identity in #start so a rebuilt connection (nats-pure fired on_close - # and start_client_nats_connection made a fresh client) triggers a - # restart instead of leaving the muxer subscribed to a dead connection. - # An AtomicReference (not a plain ivar) so #start's healthy fast path - # can read it without taking LOCK -- start runs once per RPC, and on - # JRuby a per-request LOCK acquisition is real contention. Writes still - # happen only while holding LOCK. + @restarting = false # Prevents concurrent restarts + # Connection the inbox subscription lives on. #start compares this by + # identity to detect a rebuilt connection (nats-pure fired on_close + # and made a fresh client) and trigger a restart. An AtomicReference, + # not a plain ivar, so #start's fast path reads it without LOCK -- + # start runs once per RPC, and LOCK contention on JRuby is real. @subscribed_nats = ::Concurrent::AtomicReference.new(nil) - # Shared self-healing backoff counter for the dispatcher pool. Atomic so - # concurrent dispatchers don't lose updates when several crash at once, - # and it decays back to zero once a dispatcher is healthy again (see - # run_dispatch_loop), so a later transient crash restarts the backoff - # from 1s instead of staying pinned at the cap. + # Self-healing backoff counter for the dispatcher pool. Atomic so + # simultaneous crashes don't lose updates. Decays to zero once a + # dispatcher is healthy (see run_dispatch_loop), so a later crash + # restarts the backoff from 1s instead of staying at the cap. @crash_count = ::Concurrent::AtomicFixnum.new(0) - # High-water mark of the response queue depth since the last cleanup - # cycle. Sampled in the dispatch loop, emitted+reset by the cleanup thread - # (response_muxer.pending_queue_peak) so a burst between gauge samples is - # still visible. + # High-water mark of response queue depth since the last cleanup + # cycle. The cleanup thread emits and resets it + # (response_muxer.pending_queue_peak), so a burst between gauge + # samples stays visible. @pending_queue_peak = ::Concurrent::AtomicFixnum.new(0) end @@ -82,23 +72,21 @@ def logger ::Protobuf::Logging.logger end - # Monotonic clock for token TTL accounting (single source of truth in - # Protobuf::Nats.monotonic_time). Immune to wall-clock jumps. + # Monotonic clock for token TTL accounting. Ignores wall-clock jumps. def monotonic_now ::Protobuf::Nats.monotonic_time end - # Number of dispatcher threads draining the response subscription. On JRuby - # (true parallelism) a single dispatcher is a hard throughput ceiling, so we - # fan out to processor_count; on CRuby the GVL makes extra dispatchers - # pointless, so we stay at 1. Overridable via env for tuning/tests. + # Number of dispatcher threads draining the response subscription. JRuby + # has true parallelism, so one dispatcher is a throughput ceiling; fan + # out to processor_count. CRuby's GVL makes extra dispatchers useless, + # so stay at 1. Override with an env var. # - # Note (2026-08-26): measured throughput actually PEAKS at 4 dispatchers - # and declines above it, because every dispatcher contends on the - # subscription monitor in run_dispatch_loop (rationale there). The - # processor_count default is left alone deliberately -- it only costs - # anything near saturation, which this deployment is nowhere near. Cap via - # PB_NATS_RESPONSE_MUXER_DISPATCHERS=4 if that ever changes. + # Measured (2026-08-26): throughput peaks at 4 dispatchers and declines + # above it, from monitor contention (see run_dispatch_loop). Default + # stays at processor_count: the cost only matters near saturation, far + # above this deployment's load. Cap with + # PB_NATS_RESPONSE_MUXER_DISPATCHERS=4 if that changes. def dispatcher_count @dispatcher_count ||= begin default = ::RUBY_ENGINE == "jruby" ? ::Concurrent.processor_count : 1 @@ -106,8 +94,8 @@ def dispatcher_count end end - # Message-count and byte caps for the shared response subscription (see - # DEFAULT_RESPONSE_QUEUE_SIZE / _BYTES). Read once each, in #start, so no + # Message-count and byte caps for the response queue (see + # DEFAULT_RESPONSE_QUEUE_SIZE / _BYTES). #start reads each once, so no # memoization is needed. def response_queue_size ::Protobuf::Nats.env_int("PB_NATS_RESPONSE_MUXER_QUEUE_SIZE", DEFAULT_RESPONSE_QUEUE_SIZE, :min => 1) @@ -117,35 +105,33 @@ def response_queue_bytes ::Protobuf::Nats.env_int("PB_NATS_RESPONSE_MUXER_QUEUE_BYTES", DEFAULT_RESPONSE_QUEUE_BYTES, :min => 1) end - # Current depth of the shared firehose; 0 before the muxer starts. Gauge for - # observability -- mirrors SuperSubscriptionManager#pending_queue_size. + # Current depth of the response queue; 0 before the muxer starts. + # Matches SuperSubscriptionManager#pending_queue_size. def pending_queue_size @resp_sub&.pending_queue&.size || 0 end def cleanup(token) - # Atomic remove-and-return; wake+close the queue to release any waiter. + # Remove and return the entry atomically, then wake and close its queue. entry = @resp_map.delete(token) wake_and_close_queue(entry[:queue]) if entry end - # Wake any waiter blocked in next_message on this queue, then close it. - # Pushing QUEUE_WAKE is what actually wakes a timed pop on JRuby (see the - # QUEUE_WAKE comment); close alone is insufficient there. Safe to call on - # an already-closed queue. + # Wake any waiter in next_message on this queue, then close it. Pushing + # QUEUE_WAKE is what wakes a timed pop on JRuby; close alone does not + # (see QUEUE_WAKE). Safe to call on an already-closed queue. def wake_and_close_queue(queue) return unless queue begin queue.push(QUEUE_WAKE) rescue ::ClosedQueueError, ::ThreadError - # Already closed by another path; a plain (untimed) waiter, if any, - # was already woken by that close. Nothing more to do. + # Already closed elsewhere; any plain waiter was already woken. end queue.close end def next_message(token, timeout) - # Lock-free get of the per-token queue. + # Lock-free read of the per-token queue. entry = @resp_map[token] queue = entry && entry[:queue] @@ -154,29 +140,21 @@ def next_message(token, timeout) raise ::NATS::Timeout end - # Handle edge case: zero or negative timeout if timeout && timeout <= 0 raise ::NATS::Timeout end - # Use TimeoutQueue's native timeout support for efficient, lock-free waiting per token - # Each token has its own queue, eliminating contention between different requests + # TimeoutQueue.pop(non_block, timeout:) blocks until a message arrives + # or the timeout expires (nil), or blocks indefinitely with no timeout. begin - # TimeoutQueue.pop(non_block, timeout: seconds) - # - With timeout: blocks until message arrives or timeout expires (returns nil on timeout) - # - Without timeout (nil): blocks indefinitely until message arrives msg = if timeout queue.pop(false, timeout: timeout) else queue.pop(false) end - # Queue.pop returns nil when: - # 1. The queue is closed - # 2. The timeout expires - # QUEUE_WAKE is the sentinel pushed by wake_and_close_queue to wake a - # timed pop on JRuby (where close alone does not); treat it as a - # timeout so the caller fails over instead of returning garbage. + # nil means the queue closed or the timeout expired. QUEUE_WAKE is + # the sentinel from wake_and_close_queue; treat both as a timeout. if msg.nil? || msg.equal?(QUEUE_WAKE) logger.warn "Queue closed or timeout for token #{token} during next_message" raise ::NATS::Timeout @@ -184,18 +162,16 @@ def next_message(token, timeout) msg rescue ThreadError - # Queue was closed - treat as timeout logger.warn "Queue closed for token #{token} during next_message" raise ::NATS::Timeout end end def new_request - # Use UUIDv7 so we can figure out what time a message was originally created in-memory. - token = UUIDv7Helper.generate # nats.new_inbox with nuid is not threadsafe. + # UUIDv7 encodes creation time. nats.new_inbox's nuid is not thread-safe. + token = UUIDv7Helper.generate - # Create a dedicated queue for this token. Concurrent::Map#[]= is atomic, - # so no surrounding lock is required. + # Concurrent::Map#[]= is atomic, so no lock is needed here. @resp_map[token] = { queue: ::Concurrent::Collection::TimeoutQueue.new, created_at: monotonic_now @@ -205,16 +181,14 @@ def new_request end def publish(subject, data, token) - # Validate muxer started before publish unless @resp_inbox_prefix raise ::Protobuf::Nats::Errors::ResponseMuxer, "ResponseMuxer not started - cannot publish" end nats = Protobuf::Nats.client_nats_connection - # The memoized connection is dropped when nats-pure fires on_close - # (reconnect attempts exhausted). Raise the muxer's retryable error - # instead of NoMethodError-on-nil so the client's transient-transport - # retry path rebuilds the connection and tries again. + # nats-pure drops the memoized connection when it fires on_close after + # exhausting reconnect attempts. Raise the muxer's retryable error + # instead of NoMethodError so the client retries and rebuilds it. if nats.nil? raise ::Protobuf::Nats::Errors::ResponseMuxer, "NATS connection unavailable (closed and not yet rebuilt) - cannot publish" end @@ -226,7 +200,7 @@ def publish(subject, data, token) def restart logger.debug "restarting response_muxer" - # Prevent concurrent restarts - only one restart at a time + # Only one restart runs at a time. LOCK.synchronize do if @restarting logger.warn "Restart already in progress, skipping concurrent restart request" @@ -235,28 +209,22 @@ def restart @restarting = true end - # Yield so other restart callers spawned around the same time get a - # chance to reach the @restarting check above and skip. Without this, - # CRuby's GVL can let the current thread run the entire restart to - # completion (clearing @restarting) before sibling threads even enter - # the method, defeating the concurrent-restart guard. + # Yield so other restart callers reach the @restarting check above + # and skip. Without this, CRuby's GVL can let this thread finish the + # whole restart before a sibling thread enters the method. Thread.pass begin - # Stop the existing muxer first, if it's running + # Stop the existing muxer first, if it is running. LOCK.synchronize do @resp_handlers.each(&:kill) @resp_handlers.clear drop_subscription_locked("during restart") - - # Stop the cleanup thread stop_cleanup_thread end - # Then start it fresh. start ensure - # Always clear the restarting flag LOCK.synchronize { @restarting = false } end end @@ -264,19 +232,16 @@ def restart def start current_nats = ::Protobuf::Nats.client_nats_connection - # Runs in Client#initialize, i.e. once per RPC, so the healthy path is - # lock-free: a volatile read of the connection the inbox subscription - # lives on. When set, also detect a replaced connection (nats-pure - # fired on_close, on_close dropped the memoized client, and the next - # request built a fresh one): our inbox subscription lived on the dead - # connection, so without a rebuild every response would be lost and - # every RPC would time out until the process restarted. + # Runs once per RPC, so the healthy path stays lock-free: a volatile + # read of the connection the inbox subscription lives on. Also + # detects a replaced connection (nats-pure fired on_close and the + # next request built a fresh client): without a rebuild, every RPC + # times out on the dead connection until the process restarts. subscribed = @subscribed_nats.get return if subscribed && (current_nats.nil? || subscribed.equal?(current_nats)) - # Slow path: not started, or the connection was replaced. Re-check - # under LOCK (double-checked locking; the atomic read above may race a - # concurrent start/restart). + # Not started, or the connection changed. Re-check under LOCK: the + # read above can race a concurrent start or restart. stale = false LOCK.synchronize do if _started? @@ -292,39 +257,32 @@ def start end LOCK.synchronize do - # We check this twice in case another thread was waiting for the lock to - # start this party. Use the unlocked check to prevent deadlocks. + # Re-check: another thread may have started it while we waited for LOCK. return if _started? nats = ::Protobuf::Nats.client_nats_connection return if nats.nil? - # Clean up partial state on exception begin @resp_inbox_prefix = nats.new_inbox - - # Subscribe to our per-instance inbox. @resp_sub = nats.subscribe("#{@resp_inbox_prefix}.*") - # The dispatch loop takes @resp_sub.synchronize to decrement - # pending_size after each pop, which keeps the finite byte cap accurate. - # nats-pure's Subscription includes MonitorMixin, so this always holds; - # if it ever doesn't, nats-pure's internals changed in a way that would - # break byte accounting (a growing counter that false-trips the limit - # and drops every response). Fail loudly rather than degrade silently. + # run_dispatch_loop uses @resp_sub.synchronize to decrement + # pending_size after each pop, keeping the byte cap accurate. + # nats-pure's Subscription always includes MonitorMixin; fail + # loudly if that ever changes, instead of silently miscounting + # bytes and dropping every response. unless @resp_sub.respond_to?(:synchronize) raise ::Protobuf::Nats::Errors::IncompatibleSubscription, "NATS subscription does not respond to #synchronize; cannot maintain pending_size byte accounting (nats-pure internals changed?)" end - # Bound the firehose by both message count and bytes (see - # DEFAULT_RESPONSE_QUEUE_SIZE / _BYTES). + # Bound the queue by count and bytes (see DEFAULT_RESPONSE_QUEUE_SIZE / _BYTES). @resp_sub.pending_msgs_limit = response_queue_size @resp_sub.pending_bytes_limit = response_queue_bytes @subscribed_nats.set(nats) @started = true rescue => e - # Clean up partial state @resp_inbox_prefix = nil @resp_sub = nil @subscribed_nats.set(nil) @@ -334,7 +292,6 @@ def start end end - # Start the cleanup thread start_cleanup_thread LOCK.synchronize { top_up_dispatchers_locked } @@ -345,27 +302,24 @@ def started? end # True when the muxer's inbox subscription lives on this exact connection - # object. Identity (not equality) is the point: a rebuilt connection to - # the same servers is still a different socket with no subscriptions. + # object. Uses identity, not equality: a rebuilt connection to the same + # servers is still a different socket with no subscriptions. def subscribed_to?(nats) @subscribed_nats.get.equal?(nats) end - # Token TTL. Floors at TOKEN_TTL_SECONDS but stretches when the client's - # response_timeout is configured beyond it -- otherwise the cleanup thread - # would close a token's queue out from under a caller still legitimately - # waiting on a long response. + # Token TTL. Floors at TOKEN_TTL_SECONDS, but stretches for a longer + # client response_timeout, so cleanup never closes a queue a caller is + # still waiting on. def token_ttl_seconds @token_ttl_seconds ||= [TOKEN_TTL_SECONDS, ::Protobuf::Nats.client_response_timeout + 60].max end - # Periodic cleanup of stale tokens def cleanup_stale_tokens cutoff = monotonic_now - token_ttl_seconds - # Collect stale tokens first, then delete. Concurrent::Map iteration does - # not hold a global lock, so request threads are never blocked across this - # O(n) scan (unlike the previous single-mutex implementation). + # Collect stale tokens, then delete. Concurrent::Map iteration holds no + # global lock, so request threads never block on this O(n) scan. stale_tokens = [] @resp_map.each_pair do |token, data| created_at = data[:created_at] @@ -378,7 +332,6 @@ def cleanup_stale_tokens next unless data stale_count += 1 logger.warn "Cleaning up stale token #{token} created at #{data[:created_at]}" - # Wake any waiting thread, then close the queue. wake_and_close_queue(data[:queue]) end @@ -386,12 +339,11 @@ def cleanup_stale_tokens ::Protobuf::Nats.instrument "response_muxer.stale_tokens_cleaned", stale_count end - # Gauge the shared response firehose so a climbing backlog is visible - # before it turns into timeouts/SlowConsumer drops. current == depth at - # sample time; peak == high-water since the last cycle (reset here). + # Gauge the response queue so a growing backlog is visible before it + # turns into timeouts or SlowConsumer drops. current is depth at + # sample time; peak is the high-water mark since the last cycle. ::Protobuf::Nats.instrument "response_muxer.pending_queue_size", pending_queue_size - # Atomic read-and-reset of the high-water mark (AtomicFixnum has no - # get_and_set): capture the prior value inside the update block. + # AtomicFixnum has no get_and_set, so read and reset inside the update block. peak = 0 @pending_queue_peak.update do |current_value| peak = current_value @@ -400,7 +352,6 @@ def cleanup_stale_tokens ::Protobuf::Nats.instrument "response_muxer.pending_queue_peak", peak end - # Stop the cleanup thread def stop LOCK.synchronize do stop_cleanup_thread @@ -416,8 +367,8 @@ def _started? !!@started end - # Tear down the inbox subscription and mark the muxer stopped. Must be - # called while holding LOCK; `context` labels the failure log. + # Tear down the inbox subscription and mark the muxer stopped. Caller + # must hold LOCK. `context` labels the failure log. def drop_subscription_locked(context) if @resp_sub begin @@ -425,88 +376,74 @@ def drop_subscription_locked(context) rescue => e logger.warn "Failed to unsubscribe old response muxer subscription #{context}: #{e.message}" ensure - # Always set to nil, even if unsubscribe raises @resp_sub = nil end end @subscribed_nats.set(nil) @started = false - # The inbox prefix dies with the subscription (start generates a fresh - # one), so no in-flight response can ever arrive -- without this, each - # waiter sits blocked until its ack/response timeout expires. Closing a - # token's queue wakes its waiter immediately (next_message raises - # NATS::Timeout), which rides the client's existing retry path onto the - # new connection. Entries stay in @resp_map: the owning request's - # ensure-cleanup (or the TTL sweep) removes them, and dispatchers - # already drop pushes to a closed queue. + # The inbox prefix dies with the subscription, so no in-flight + # response can arrive. Closing each token's queue wakes its waiter now + # (next_message raises NATS::Timeout) instead of blocking until its + # own timeout; the client's retry path picks it up on the new + # connection. Entries stay in @resp_map until owner cleanup or the + # TTL sweep removes them. fail_inflight_requests end - # Must be called while holding LOCK (only from drop_subscription_locked). + # Caller must hold LOCK (only called from drop_subscription_locked). def fail_inflight_requests @resp_map.each_pair do |_token, entry| wake_and_close_queue(entry[:queue]) end end - # Spawn a single dispatcher thread. Multiple dispatchers safely share the - # one @resp_sub.pending_queue (Queue is thread-safe) and route via the - # lock-free @resp_map. + # Spawn one dispatcher thread. Dispatchers share @resp_sub.pending_queue + # (thread-safe Queue) and route messages through the lock-free @resp_map. def spawn_dispatcher Thread.new do - # Unique thread name for debugging Thread.current.name = "response-muxer-#{Thread.current.object_id}" begin run_dispatch_loop rescue => fatal_error - # Only truly fatal errors that kill the loop reach here (ThreadError - # from the shared pending_queue being closed). + # Only a fatal error reaches here: ThreadError from the shared + # pending_queue being closed. logger.error("ResponseMuxer thread crashed fatally. Error: #{fatal_error.message}") ::Protobuf::Nats.notify_error_callbacks(fatal_error) # --- Self-healing logic --- - # Atomic increment so simultaneous crashes don't lose updates. The - # counter decays in run_dispatch_loop once a dispatcher is healthy, - # so this only grows under a sustained crash loop. + # Atomic increment so simultaneous crashes don't lose updates. + # run_dispatch_loop decays this once a dispatcher is healthy, so it + # only grows under a sustained crash loop. crashes = @crash_count.increment - # Exponential backoff, e.g., 1, 4, 9, 16s... capped at 60s (shared formula). + # Exponential backoff (1, 4, 9, 16s...), capped at 60s. sleep_duration = ::Protobuf::Nats.crash_backoff_seconds(crashes) logger.warn("Waiting #{sleep_duration}s before attempting to restart ResponseMuxer.") sleep sleep_duration # --- End of self-healing logic --- - # After sleeping, reset the state and try to start again. healed = LOCK.synchronize do - # Remove ourselves from the handler pool BEFORE the top-up runs. - # This thread is still alive (running this rescue) but is about to - # exit, so the top-up's `select!(&:alive?)` would otherwise count it as a - # live dispatcher and spawn no replacement -- leaving the pool one - # short (zero dispatchers on CRuby, where dispatcher_count == 1, and - # the muxer would stop delivering responses entirely). + # Remove this thread before the top-up runs. It is still alive + # here but about to exit; otherwise select!(&:alive?) would + # count it as live and spawn no replacement, leaving the pool + # short (zero dispatchers on CRuby). @resp_handlers.delete(::Thread.current) - # Only tear down the subscription we actually died on. When several - # dispatchers crash together they wake on different backoffs (1s, - # then 4s...), so an unconditional teardown here would destroy the - # subscription an earlier sibling just rebuilt and, via - # fail_inflight_requests, cancel every request that had already - # arrived on it. If a sibling healed us, our subscription is stale - # and only the pool top-up is left to do. + # Tear down only the subscription this thread died on. Siblings + # can crash together on different backoffs; an unconditional + # teardown could destroy one a sibling already rebuilt and cancel + # its already-arrived requests via fail_inflight_requests. If a + # sibling healed us, only the pool top-up is needed. # - # DISPATCHING_SUB_KEY is written by run_dispatch_loop on this same - # thread, so it names the subscription this dispatcher was really - # draining. Capturing @resp_sub here (or when the thread starts) - # would instead read whatever is current after the backoff, which - # is exactly the value we need to compare against. A nil value - # means we died before draining anything, so there is nothing of - # ours to tear down. + # DISPATCHING_SUB_KEY, set by run_dispatch_loop on this thread, + # names the subscription actually drained -- @resp_sub would + # give the post-backoff current value instead. nil means this + # thread died before draining anything. dispatching_sub = ::Thread.current[DISPATCHING_SUB_KEY] healed = !@resp_sub.nil? && !@resp_sub.equal?(dispatching_sub) if healed - # Not `start`: the muxer is still started on the live - # connection, so start would return at its fast path and never - # reach the top-up, leaving the pool one short per guarded crash. + # Not `start`: the muxer is already started on the live + # connection, so start would return early and skip the top-up. logger.info "ResponseMuxer already healed by another dispatcher; replacing this dispatcher without a teardown" top_up_dispatchers_locked else @@ -520,8 +457,8 @@ def spawn_dispatcher end # Top up the dispatcher pool to dispatcher_count. Prunes dead threads - # first so self-healing restarts converge to the target count instead of - # multiplying threads. Must be called while holding LOCK. + # first so repeated self-healing converges instead of multiplying + # threads. Caller must hold LOCK. def top_up_dispatchers_locked @resp_handlers.select!(&:alive?) @resp_handlers << spawn_dispatcher while @resp_handlers.size < dispatcher_count @@ -532,74 +469,70 @@ def run_dispatch_loop begin # --- Start of per-message block --- # @resp_sub can briefly be nil during a restart. Park instead of - # dereferencing nil, which would raise NoMethodError every iteration - # and busy-spin (flooding logs and error callbacks) until it is set. + # dereferencing nil, which would raise NoMethodError and busy-spin + # (flooding logs and error callbacks) until it is set. sub = @resp_sub if sub.nil? sleep 0.01 next end - # Record what we are draining for the crash handler in + # Record what this dispatcher drains, for the crash handler in # spawn_dispatcher. Thread-local, so each dispatcher tracks its own - # subscription across restarts (a shared ivar could not). + # subscription across restarts. ::Thread.current[DISPATCHING_SUB_KEY] = sub msg = sub.pending_queue.pop - # nil means the queue was closed/woken (e.g. the connection died - # and its queue was closed). A closed queue returns nil immediately - # forever, so park briefly instead of spinning at 100% CPU until a - # restart swaps in a live subscription. + # nil means the queue closed (e.g. the connection died). A closed + # queue returns nil forever, so park briefly instead of spinning + # at 100% CPU until a restart swaps in a live subscription. if msg.nil? sleep ::Protobuf::Nats::CLOSED_QUEUE_PARK_SECONDS next end - # Drop the popped message's bytes from pending_size. nats-pure only - # decrements it in #process, which we bypass by popping pending_queue - # directly; without this the counter climbs monotonically and would - # false-trip the finite pending_bytes_limit, dropping every later - # response. Take the same monitor nats-pure's read thread uses. - # (#start guarantees the subscription responds to #synchronize.) + # Drop the popped message's bytes from pending_size. nats-pure + # only decrements it in #process, bypassed here by popping + # pending_queue directly; skipping this lets the counter climb and + # false-trip pending_bytes_limit, dropping every later response. + # Uses the same monitor nats-pure's read thread holds (#start + # guarantees #synchronize). # - # Reviewed and deliberately left as-is (2026-08-26). This monitor is - # the one nats-pure's single read thread holds for all of - # #process_msg, so dispatchers contend with the feeder for EVERY - # subscription on the connection, not just this inbox. Measured on - # JRuby 9.4/15 cores: ~9.6us per message, and read-thread ingress - # falls to 43% of its one-dispatcher rate at 8 dispatchers (203k - # msg/s) -- throughput actually peaks at 4 dispatchers and declines - # above it. Real, but this deployment expects <=2000 req/s, i.e. ~1% - # of that ceiling and ~2% of one core, so the cost is noise. + # Reviewed, left as-is (2026-08-26): this monitor is shared with + # every subscription on the connection, so dispatchers contend + # with the read thread for all of them. Measured on JRuby 9.4/15 + # cores: ~9.6us per message; ingress falls to 43% of + # one-dispatcher rate at 8 dispatchers (203k msg/s), and + # throughput peaks at 4. This deployment expects <=2000 req/s + # (~1% of that ceiling), so the cost is noise. # - # Do NOT re-flag this on load alone. Reopen only if PEAK (not mean) - # response rate nears 100k msg/s, or if this process starts sharing - # its NATS connection with another high-volume subject -- that - # subject pays the read-thread penalty even while the muxer is idle. - # If it must change: batch the decrement (flush every N messages; - # ~1.8x at N=8) rather than dropping it, and keep the total - # overshoot far below pending_bytes_limit. Capping - # PB_NATS_RESPONSE_MUXER_DISPATCHERS at 4 is the no-code option. + # Do NOT re-flag this on load alone. Reopen only if peak response + # rate nears 100k msg/s, or another high-volume subject shares + # this connection (it then pays this cost even while idle). If it + # must change: batch the decrement (flush every N messages, ~1.8x + # at N=8) instead of dropping it, staying well below + # pending_bytes_limit. Capping PB_NATS_RESPONSE_MUXER_DISPATCHERS + # at 4 needs no code change. sub.synchronize { sub.pending_size -= msg.data.size } - # Sample post-pop depth into the high-water mark so a burst that fills - # and drains between the 60s gauge samples is still visible. + # Sample post-pop depth into the high-water mark, so a burst that + # fills and drains between 60s gauge samples stays visible. depth = sub.pending_queue.size @pending_queue_peak.update { |current_value| [depth, current_value].max } dispatch_message(msg) - # A processed message means this dispatcher is healthy: let the - # self-healing backoff decay so a later transient crash restarts the - # backoff from 1s. Only write when non-zero to keep this cheap. + # A processed message means this dispatcher is healthy: decay the + # backoff so a later transient crash restarts it from 1s. Skip the + # write when already zero, to keep this cheap. @crash_count.value = 0 unless @crash_count.value.zero? # --- End of per-message block --- rescue => per_message_error - # ThreadError is fatal, it means the queue is closed and the loop cannot continue. + # ThreadError means the queue closed; the loop cannot continue. raise if per_message_error.is_a?(::ThreadError) - # Log the error for the specific message, but DON'T kill the thread. + # Log and continue; do not kill the thread for one bad message. logger.error("ResponseMuxer failed to process a message. Error: #{per_message_error.message}") ::Protobuf::Nats.notify_error_callbacks(per_message_error) end @@ -607,7 +540,6 @@ def run_dispatch_loop end def dispatch_message(msg) - # Validate message subject before processing unless msg.subject.is_a?(String) && msg.subject.include?('.') ::Protobuf::Nats.instrument "client.invalid_message", 1 @@ -615,22 +547,20 @@ def dispatch_message(msg) return end - # example(random data): - # _INBOX.{random_data}.{random_data_msg_id} - # Hot path: take the last segment via rindex/slice instead of split, - # which allocates an array plus a string per segment for every response. - # The include?('.') check above guarantees rindex is non-nil. + # Subject format: _INBOX.{random_data}.{random_data_msg_id} + # Hot path: rindex/slice avoids the array and string split() allocates + # per response. include?('.') above guarantees rindex is non-nil. subject = msg.subject token = subject[(subject.rindex(".") + 1)..] logger.debug { "token: #{token}, resp_map.keys:#{@resp_map.keys}" } if logger.debug? - # Lock-free get of the per-token queue. + # Lock-free read of the per-token queue. entry = @resp_map[token] queue = entry && entry[:queue] unless queue - # Try to decode the UUIDv7 timestamp to calculate message age + # Decode the UUIDv7 timestamp to get the message's age, if possible. delay_seconds = UUIDv7Helper.age_in_seconds(token) ::Protobuf::Nats.instrument "client.unexpected_message", delay_seconds || 1 @@ -643,9 +573,8 @@ def dispatch_message(msg) return end - # Push message onto the queue - this is lock-free and thread-safe. + # Push is lock-free and thread-safe. begin - # Check queue size to prevent memory bloat if queue.size >= MAX_RESPONSES_PER_TOKEN logger.warn "Token #{token} has #{queue.size} queued responses. Possible duplicate messages or slow consumer. Dropping message." return @@ -653,20 +582,19 @@ def dispatch_message(msg) queue.push(msg) rescue ThreadError - # Queue was closed (cleanup happened) - this is fine, just drop the message + # Queue was already closed by cleanup; drop the message. logger.debug "Queue closed for token #{token}, dropping message" end end def start_cleanup_thread - # Only start if not already running return if @cleanup_thread&.alive? @cleanup_mutex.synchronize { @shutdown = false } @cleanup_thread = Thread.new do begin loop do - # Wait for 60 seconds or until signaled to shutdown + # Wait 60 seconds, or until signaled to shut down. @cleanup_mutex.synchronize do @cleanup_cv.wait(@cleanup_mutex, 60) unless @shutdown end @@ -685,9 +613,8 @@ def start_cleanup_thread ::Protobuf::Nats.notify_error_callbacks(fatal_error) end end - # Name the thread from the outside so the name is visible to callers - # immediately after start_cleanup_thread returns (no race with the - # thread body executing). + # Named from the outside, so the name is set before start_cleanup_thread + # returns and cannot race the thread body. @cleanup_thread.name = "response-muxer-cleanup-#{object_id}" end @@ -695,11 +622,10 @@ def stop_cleanup_thread if @cleanup_thread&.alive? @cleanup_mutex.synchronize do @shutdown = true - @cleanup_cv.signal # Wake up the cleanup thread immediately + @cleanup_cv.signal end - # Should exit almost immediately now @cleanup_thread.join(0.5) - # Force kill if still alive (shouldn't happen) + # Force kill if still alive; should not normally happen. @cleanup_thread.kill if @cleanup_thread&.alive? end @cleanup_thread = nil diff --git a/lib/protobuf/nats/server.rb b/lib/protobuf/nats/server.rb index f3e7571..00535b4 100644 --- a/lib/protobuf/nats/server.rb +++ b/lib/protobuf/nats/server.rb @@ -25,9 +25,7 @@ def initialize(options) @nats = @options[:client] || ::Protobuf::Nats::NatsClient.new - # Register lifecycle callbacks BEFORE connecting so a disconnect or - # error during the initial handshake is still observed (mirrors - # Protobuf::Nats.start_client_nats_connection on the client side). + # Register callbacks before connect, to catch handshake errors too. @nats.on_disconnect do logger.warn "Server NATS connection was disconnected" end @@ -37,8 +35,8 @@ def initialize(options) end @nats.on_error do |error| - # Runs on nats-pure's read/flush thread -- offload so a slow callback - # can't stall the server's intake. + # This runs on the nats-pure read/flush thread. Go async so a + # slow callback cannot block intake. ::Protobuf::Nats.notify_error_callbacks_async(error) end @@ -51,7 +49,7 @@ def initialize(options) @thread_pool = ::Protobuf::Nats::ThreadPool.new(threads, :max_queue => max_queue_size) @subscription_manager = ::Protobuf::Nats::SuperSubscriptionManager.new(@nats) do |request_data, reply_id, subject| - # Opt-in intake shedding; rationale on #stale_request_ms. + # See #stale_request_ms for why we drop old requests here. next if stale_request?(reply_id) unless enqueue_request(request_data, reply_id) @@ -60,9 +58,8 @@ def initialize(options) end @server = options.fetch(:server, ::Socket.gethostname) - # In-flight handler tracking for observability. Long-running handlers are - # allowed (and never aborted); we only measure/report. id => monotonic - # start time; @overdue_flagged dedupes the per-handler overdue event. + # Track in-flight handlers for reporting only; never aborted. + # @overdue_flagged stops us reporting the same one twice. @inflight = ::Concurrent::Map.new @overdue_flagged = ::Concurrent::Map.new @request_seq = ::Concurrent::AtomicFixnum.new(0) @@ -76,20 +73,17 @@ def handler_count subscription_manager.handler_count end - # Informational SLA marker for slow handlers. Default 0 (off) so normal - # long-running operations are not flagged. + # Threshold for reporting a slow handler. Default 0 (off). def slow_handler_threshold_ms @slow_handler_threshold_ms ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_SLOW_HANDLER_THRESHOLD_MS", 0) end - # Age (ms) beyond which a request is shed at intake instead of processed: - # a request whose client has already retried or timed out is abandoned - # work -- executing it only burns a pool slot (and duplicates effects for - # non-idempotent RPCs). Default 0 (off). The age comes from the UUIDv7 - # token this gem's client embeds in the reply inbox, which encodes - # *client wall-clock* time -- enable only with sane NTP across hosts, and - # keep the threshold comfortably above the client's ack_timeout (5s - # default) to absorb skew. + # Age (ms) at which we drop a request instead of running it. Past + # this age the client has likely retried or given up, so the work + # is wasted and can duplicate effects on non-idempotent RPCs. + # Default 0 (off). Age comes from a UUIDv7 token in the reply inbox, + # which encodes client wall-clock time: enable only with synced + # clocks (NTP), and set well above the client's 5s ack_timeout. def stale_request_ms @stale_request_ms ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_STALE_REQUEST_MS", 0) end @@ -105,30 +99,30 @@ def stale_request?(reply_id) true end - # A handler still running past this is "overdue": the client has already - # given up (its response_timeout), so the work is orphaned and holding a - # pool slot for nothing. Defaults above the client's 60s response_timeout - # so legitimate ≤60s operations are never flagged. + # Age (ms) at which a handler is "overdue": the client has already + # given up (response_timeout), so it now holds a pool slot for + # nothing. Default is above the client's 60s response_timeout, so + # normal handlers are never flagged. def handler_overdue_ms @handler_overdue_ms ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_HANDLER_OVERDUE_MS", 65_000) end - # Whether to actively reclaim (abort) an overdue handler's pool slot. OFF by - # default: the documented contract is that handlers are never aborted, since - # killing a thread mid-handler can corrupt state. Enable only when you would - # rather shed orphaned work (whose client already gave up) than let it pin a - # pool slot -- e.g. when overdue handlers are saturating the pool and the - # server is NACKing healthy traffic. Reclaim raises Errors::HandlerOverdue - # into the worker, which the handler rescue turns into an RPC error response. + # Whether to abort an overdue handler to reclaim its pool slot. Off + # by default: our contract is that handlers are never aborted, since + # killing a thread mid-handler can corrupt state. Enable only if + # overdue handlers are saturating the pool and healthy traffic gets + # NACKed. Reclaim raises `Errors::HandlerOverdue` in the worker, + # which the handler rescue turns into an RPC error response. def reclaim_overdue_handlers? - # Memoize the raw string (never falsey, so ||= is safe) and derive the - # boolean per call -- avoids the nil-guard dance for a false-able memo. + # Memoize the raw string, not the boolean. A memoized `false` looks + # unset to `||=` and would be recomputed every time. @reclaim_overdue_handlers ||= ::ENV.fetch("PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS", "false") @reclaim_overdue_handlers == "true" end - # How long to let in-flight handlers finish on shutdown. Tracks the overdue - # window (plus grace) so a legitimate long handler isn't killed mid-flight. + # How long to wait for handlers to finish on shutdown. Tracks the + # overdue window plus a grace period, so a long handler is not + # killed mid-flight. def shutdown_drain_timeout @shutdown_drain_timeout ||= ::Protobuf::Nats.env_float("PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT", (handler_overdue_ms / 1000.0) + 5) end @@ -139,10 +133,9 @@ def instrument_thread_pool_sizes ::Protobuf::Nats.instrument("server.thread_pool_running_size", thread_pool.size) end - # Periodic in-flight handler health. Long handlers are normal, so - # inflight_oldest_age_ms can legitimately approach the client's - # response_timeout; only overdue_handler_count (work the client has already - # abandoned) signals a problem. + # Report in-flight handler health. `inflight_oldest_age_ms` can + # normally approach response_timeout; only `overdue_handler_count` + # signals a real problem. def instrument_inflight_handlers now = monotonic overdue_ms = handler_overdue_ms @@ -159,21 +152,17 @@ def instrument_inflight_handlers overdue += 1 - # Optionally reclaim the slot by aborting the orphaned handler (opt-in; - # see #reclaim_overdue_handlers?). Done before the dedupe below so the - # reclaim is attempted even after the overdue event was already emitted. - # The @inflight re-check narrows the window in which the raise could - # land on a worker that already finished this request and moved on to - # another (the ThreadPool worker also swallows a raise that lands - # between tasks). + # Reclaim the slot by aborting the handler, if enabled (see + # #reclaim_overdue_handlers?). The @inflight re-check narrows + # the chance the raise lands on a worker already on a new + # request; ThreadPool also swallows a raise between tasks. if reclaim_overdue_handlers? && handler_thread&.alive? && @inflight[id].equal?(entry) logger.warn "Reclaiming overdue handler (age=#{age_ms.round}ms, client already gave up) to free its pool slot" handler_thread.raise(::Protobuf::Nats::Errors::HandlerOverdue, "handler exceeded #{overdue_ms}ms; reclaimed") ::Protobuf::Nats.instrument("server.handler_reclaimed", age_ms) end - # Emit the per-handler overdue event once (the client has already - # given up; this handler's result is orphaned). + # Report each overdue handler once; its result is discarded. next if @overdue_flagged[id] @overdue_flagged[id] = true logger.warn "Handler exceeded #{overdue_ms}ms (client already gave up); in-flight age=#{age_ms.round}ms" @@ -186,19 +175,17 @@ def instrument_inflight_handlers ::Protobuf::Nats.instrument("server.inflight_oldest_age_ms", oldest_age_ms) ::Protobuf::Nats.instrument("server.overdue_handler_count", overdue) - # Reap orphaned overdue flags. The handler's ensure normally deletes - # @overdue_flagged[id], but the flag set above can race a completing - # handler: we read id from @inflight, the ensure deletes both maps, then - # we set @overdue_flagged[id] -- an entry nothing else will ever remove. - # A flag whose id is no longer in-flight is by definition orphaned. + # Remove orphaned overdue flags. A race is possible: we read id + # from @inflight, the handler's `ensure` deletes both maps, then + # we set @overdue_flagged[id] here. Nothing else removes that + # entry, so clear any flag whose id is no longer in-flight. @overdue_flagged.each_key do |id| @overdue_flagged.delete(id) unless @inflight.key?(id) end end - # Defaults to #threads (not the raw option) so a server built with no - # :threads option gets a queue matching its 10 default workers instead of - # nil.to_i == 0. + # Uses #threads, not the raw option, so a queue always matches the + # actual worker count. def max_queue_size ::Protobuf::Nats.env_int("PB_NATS_SERVER_MAX_QUEUE_SIZE", threads) end @@ -212,7 +199,7 @@ def subscriptions_per_rpc_endpoint end def threads - @options[:threads] || 10 # Default to 10 if not provided, consistent with original behavior + @options[:threads] || 10 end def service_klasses @@ -225,41 +212,32 @@ def enqueue_request(request_data, reply_id) enqueued_at = monotonic request_id = @request_seq.increment was_enqueued = thread_pool.push do - # nil response_data is the "handler failed, don't publish a success - # response" sentinel (a successful encode is always a non-nil String, - # even when empty). + # nil response_data means "handler failed, skip the success + # publish". A successful encode is always a non-nil String. response_data = nil begin - # Instrument the thread pool time-to-execute duration. processed_at = monotonic ::Protobuf::Nats.instrument("server.thread_pool_execution_delay", (processed_at - enqueued_at) * MILLISECOND) - # Track this handler as in-flight (long handlers are allowed; this is - # only for observability -- we never abort it unless overdue-reclaim - # is explicitly enabled). Store the worker thread so reclaim can - # target it; the start time drives age/overdue accounting. + # Track this handler as in-flight, for reporting only (see + # #reclaim_overdue_handlers?). @inflight[request_id] = [processed_at, ::Thread.current] - # Process request. Only the handler is wrapped here so a transport - # failure on the success-response publish (below) cannot fall into - # this rescue and emit a *second* (error) publish for a request whose - # handler actually succeeded. + # Wrap only the handler here, so a publish failure below does + # not land in this rescue and send a duplicate response. begin response_data = handle_request(request_data, 'server' => @server) rescue => error response_data = nil # ensure the success-publish below is skipped logger.debug { "rescued error => #{error}" } if logger.debug? - # Logs the real error server-side (via the default log_error - # callback) so it isn't lost; the client gets only a generic message. + # Log the real error server-side; the client gets only a + # generic message. ::Protobuf::Nats.notify_error_callbacks(error) - # The client has already received our ACK and is now blocked waiting - # for the response message. If we don't send one it will hang until - # response_timeout (60s by default). Publish an encoded RPC error so - # the client fails fast instead. Use a generic message rather than - # error.message so internal handler details aren't leaked over the - # wire. (If the failure was the connection itself, this publish will - # also fail and is swallowed below.) + # The client already got our ACK and now waits for a + # response. Without one it hangs until response_timeout + # (60s default). Send a generic RPC error instead, without + # leaking error.message over the wire. begin error_response = ::Protobuf::Rpc::PbError.new("Internal server error") nats.publish(reply_id, error_response.encode) @@ -268,9 +246,8 @@ def enqueue_request(request_data, reply_id) end end - # Publish the successful response. Kept outside the handler rescue so a - # publish failure here is logged rather than triggering a duplicate - # (error) response for a request that already succeeded. + # Publish outside the handler rescue, so a failure here is + # logged instead of sending a duplicate error response. if response_data logger.debug { "Publishing response to #{reply_id}" } if logger.debug? begin @@ -284,11 +261,10 @@ def enqueue_request(request_data, reply_id) @inflight.delete(request_id) @overdue_flagged.delete(request_id) - # Instrument the request duration. completed_at = monotonic ::Protobuf::Nats.instrument("server.request_duration", (completed_at - enqueued_at) * MILLISECOND) - # Informational slow-handler marker (opt-in; default off). + # Report a slow handler, if enabled (default off). if processed_at && slow_handler_threshold_ms.positive? handler_ms = (completed_at - processed_at) * MILLISECOND if handler_ms >= slow_handler_threshold_ms @@ -299,7 +275,7 @@ def enqueue_request(request_data, reply_id) end end - # Publish an ACK to signal the server has picked up the work. + # Send an ACK, or a NACK if the pool was full. begin if was_enqueued logger.debug { "[reply_id=#{reply_id}] Sending ACK" } if logger.debug? @@ -308,8 +284,6 @@ def enqueue_request(request_data, reply_id) ::Protobuf::Nats.instrument "server.thread_pool_saturated" ::Protobuf::Nats.instrument "server.message_dropped" logger.debug { "[reply_id=#{reply_id}] Sending NACK" } if logger.debug? - - # Let the client know we are not processing the message. nats.publish(reply_id, ::Protobuf::Nats::Messages::NACK) end rescue => e @@ -361,7 +335,7 @@ def with_each_subscription_key service_klasses.each do |service_klass| service_klass.rpcs.each do |service_method, _| - # Skip services that are not implemented. + # Skip unimplemented services. next unless service_klass.method_defined?(service_method) subscription_key = ::Protobuf::Nats.subscription_key(service_klass, service_method) next if do_not_subscribe_to_includes?(subscription_key) @@ -372,14 +346,13 @@ def with_each_subscription_key end end - # Slow start subscriptions by adding X rounds of subz every - # Y seconds, where X is subscriptions_per_rpc_endpoint and Y is - # slow_start_delay. + # Add subscription rounds slowly: subscriptions_per_rpc_endpoint + # rounds, slow_start_delay seconds apart. def finish_slow_start logger.info "Slow start has started..." completed = 1 - # We have (X - 1) here because we always subscribe at least once. + # One round already ran, so only (X - 1) rounds remain. (subscriptions_per_rpc_endpoint - 1).times do unless @running logger.info "Slow start interrupted (server stopping) after #{completed}/#{subscriptions_per_rpc_endpoint} rounds" @@ -403,13 +376,13 @@ def finish_slow_start def detect_and_handle_a_pause @pause_mutex.synchronize do case - # If we are taking requests and detect a pause file, then unsubscribe. + # A pause file appeared while we were processing. Unsubscribe. when @processing_requests && paused? @processing_requests = false logger.warn("Pausing server!") unsubscribe - # If we were paused and the pause file is no longer present, then subscribe again. + # The pause file is gone. Subscribe again. when !@processing_requests && !paused? logger.warn("Resuming server: resubscribing to all services and restarting slow start!") @processing_requests = true @@ -422,16 +395,13 @@ def paused? !pause_file_path.nil? && ::File.exist?(pause_file_path) end - # nats-pure fires on_close when the connection is terminally closed: - # either we called close (normal shutdown, @running already false) or the - # reconnect loop exhausted max_reconnect_attempts on every server in the - # pool. In the latter case the server would otherwise keep running forever - # with a dead connection -- subscribed to nothing, receiving nothing -- - # indistinguishable from healthy-but-idle. Stop the run loop instead so - # the process exits and the supervisor (systemd/k8s/foreman) restarts it - # with a fresh connection. Deployments that prefer in-process retries - # forever can set max_reconnect_attempts: -1, in which case nats-pure - # never fires this for a mere outage. + # nats-pure fires on_close when we called close (normal shutdown), or + # when the reconnect loop exhausted max_reconnect_attempts on every + # server. In the second case, the server would otherwise run forever + # with a dead connection and look healthy while idle. Stop the run + # loop so a supervisor (systemd/k8s/foreman) restarts the process + # with a fresh connection. Set max_reconnect_attempts: -1 to retry + # in-process forever instead; then this never fires for an outage. def handle_connection_closed return unless @running logger.error "Server NATS connection was closed unexpectedly (reconnect attempts exhausted); stopping server so a supervisor can restart it" @@ -452,7 +422,7 @@ def run detect_and_handle_a_pause instrument_thread_pool_sizes instrument_inflight_handlers - thread_pool.replenish # respawn workers killed by non-StandardError + thread_pool.replenish # Respawn workers killed by a non-StandardError. sleep 1 end @@ -460,26 +430,21 @@ def run logger.info "Shutting down subscription manager..." begin - # No Timeout.timeout here. #shutdown already bounds itself with a - # monotonic deadline and non-blocking pushes, and Timeout's async - # Thread#raise is exactly what 0.13.1 removed from the manager: firing - # it while a thread holds the SizedQueue mutex leaves JRuby unwinding - # through a held mutex ("Attempt to unlock a mutex which is locked by - # another thread"), which can then hang the queue for good. - # - # The wrapper could genuinely fire, too: #shutdown's own worst case - # (one 1s push deadline per handler, then a 5s join, then 1s - # kill-joins) exceeds 10s once there are more than a few handlers -- - # the JRuby default is processor_count. + # Do not wrap this in Timeout.timeout. #shutdown already bounds + # itself with a deadline and non-blocking pushes. Timeout's + # Thread#raise can fire while a thread holds the SizedQueue + # mutex; JRuby then hangs the queue trying to unwind through a + # held mutex. A Timeout wrapper could also fire for real: + # #shutdown's worst case can exceed 10s past a few handlers + # (JRuby's default thread count is processor_count). subscription_manager.shutdown(5) rescue => e logger.error "Error during subscription manager shutdown: #{e.message}" end - # Give in-flight handlers time to finish. Long operations are allowed - # (up to ~the client's response_timeout), so the drain timeout tracks - # handler_overdue_ms rather than a fixed 60s -- otherwise a legitimate - # ~60s handler would be killed and its client left waiting. + # Give in-flight handlers time to finish. This timeout tracks + # handler_overdue_ms, not a fixed 60s, so a legitimate ~60s handler + # is not killed while its client still waits. drain_timeout = shutdown_drain_timeout logger.info "Waiting up to #{drain_timeout.round}s for the thread pool to finish shutting down..." thread_pool.shutdown diff --git a/lib/protobuf/nats/super_subscription_manager.rb b/lib/protobuf/nats/super_subscription_manager.rb index 7aa78ea..e004290 100644 --- a/lib/protobuf/nats/super_subscription_manager.rb +++ b/lib/protobuf/nats/super_subscription_manager.rb @@ -10,9 +10,9 @@ module Protobuf module Nats class SuperSubscriptionManager def initialize(nats, &cb) - # Central queue used by all subscriptions, bounded by both message count - # and total bytes (see intake_queue_size / intake_queue_bytes). A byte-cap - # drop is surfaced here as server.intake_bytes_dropped. + # Shared queue for all subscriptions, bounded by count and bytes + # (see `intake_queue_size` / `intake_queue_bytes`). Byte drops + # report as `server.intake_bytes_dropped`. @pending_queue = ::Protobuf::Nats::ByteBoundedQueue.new( intake_queue_size, intake_queue_bytes, :on_drop => lambda { |bytes| ::Protobuf::Nats.instrument("server.intake_bytes_dropped", bytes) } @@ -22,10 +22,8 @@ def initialize(nats, &cb) @nats = nats @callback = cb - # Fan out the intake across several handler threads. A single thread is a - # throughput ceiling on JRuby and lets one slow publish (ACK) inside the - # callback head-of-line block every other subject. Each handler pops the - # shared SizedQueue (thread-safe) independently. + # Several handler threads process intake: one thread caps throughput + # on JRuby, and a slow callback ACK would block every other subject. @pending_queue_handlers = handler_count.times.map { |i| spawn_handler(i) } ::Protobuf::Nats.instrument("server.subscription_handler_count", @pending_queue_handlers.size) @@ -35,9 +33,9 @@ def logger ::Protobuf::Logging.logger end - # Number of intake handler threads. On JRuby (true parallelism) fan out to - # processor_count; on CRuby the GVL makes extra handlers pointless, so 1. - # Overridable via env for tuning/tests. Mirrors ResponseMuxer#dispatcher_count. + # Handler thread count: `processor_count` on JRuby (true parallelism), + # 1 on CRuby (the GVL makes more useless). Env var overrides for + # tuning or tests. Matches `ResponseMuxer#dispatcher_count`. def handler_count @handler_count ||= begin default = ::RUBY_ENGINE == "jruby" ? ::Concurrent.processor_count : 1 @@ -45,27 +43,23 @@ def handler_count end end - # Capacity of the shared intake queue. The nats-pure default (65,536) - # lets requests queue far longer than any client's ack_timeout under - # sustained load -- the client has retried or given up long before the - # message is popped, so the backlog is mostly abandoned work. A smaller - # size turns overload into prompt drops (and client retries with - # backoff) instead of a deep stale backlog. Kept at the nats-pure - # default for compatibility; tune down alongside - # PB_NATS_SERVER_STALE_REQUEST_MS. + # Capacity of the shared intake queue. nats-pure's default (65,536) + # lets requests wait past a client's `ack_timeout`, so a deep backlog + # is mostly abandoned work. A smaller size trades that for fast drops + # and retries. Kept at the nats-pure default; tune down with + # `PB_NATS_SERVER_STALE_REQUEST_MS`. def intake_queue_size @intake_queue_size ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_INTAKE_QUEUE_SIZE", ::NATS::IO::DEFAULT_SUB_PENDING_MSGS_LIMIT, :min => 1) end - # Byte ceiling for the shared intake queue -- the aggregate-heap bound the - # message count alone can't give (65,536 large requests is a lot of heap). - # Bounds resident bytes across ALL subscriptions; the ByteBoundedQueue drops - # a message that would exceed it rather than block nats-pure's read thread. - # Default 128 MiB: higher than the client muxer's 64 MiB because the server - # fans requests across many handler threads and its count cap is higher too. + # Byte limit for the shared intake queue: message count alone can't + # bound heap use (65,536 large requests is a lot of heap). + # `ByteBoundedQueue` drops a message over this limit rather than + # blocking nats-pure's read thread. Default 128 MiB: higher than the + # client muxer's 64 MiB, since the server fans out to more handlers. DEFAULT_INTAKE_QUEUE_BYTES = 128 * 1024 * 1024 # 128MiB - # Read once, in #initialize, so no memoization is needed. + # Read once in `#initialize`; no memoization needed. def intake_queue_bytes ::Protobuf::Nats.env_int("PB_NATS_SERVER_INTAKE_QUEUE_BYTES", DEFAULT_INTAKE_QUEUE_BYTES, :min => 1) end @@ -74,41 +68,34 @@ def queue_subscribe(name) logger.debug { "queue_subscribe(#{name})" } sub = @nats.subscribe(name, :queue => name) - # Rationale on Protobuf::Nats.disable_subscription_byte_limit!. + # See `Protobuf::Nats.disable_subscription_byte_limit!` for why. ::Protobuf::Nats.disable_subscription_byte_limit!(sub) - # Create a subscription but reset the pending queue to use a central pending queue. existing_pending_queue = sub.pending_queue sub.pending_queue = @pending_queue - # Align the slow-consumer message-count limit with the shared queue's - # capacity. nats-pure's read thread only drops a message (SlowConsumer) - # when pending_queue.size >= pending_msgs_limit -- otherwise it pushes. - # With the sub's default limit (65,536) above a smaller tuned intake - # queue, the drop check never fires and the push into the full - # SizedQueue BLOCKS the connection's single read thread, stalling - # PING/PONG and every other subject until a handler pops. limit == - # capacity makes the check trip exactly before the push would block, so - # overload becomes prompt drops (and client NACK-style retries) as - # intended. + # Match the SlowConsumer limit to the shared queue's capacity. + # nats-pure's read thread drops a message only when + # `pending_queue.size >= pending_msgs_limit`; else it pushes, even + # into a full queue, blocking the read thread and PING/PONG. The + # sub's default (65,536) sits above a smaller tuned queue, so that + # never fires. limit == capacity trips the drop before a push blocks. sub.pending_msgs_limit = intake_queue_size if sub.respond_to?(:pending_msgs_limit=) - # Push all race-conditioned messages onto the pending queue. - # Should address a potential race condition. Chances of the round-trip message to an - # existing queue before this queue swap happens seems extremely low, but possible. + # Move any messages already on the old queue to the new one: one can + # land there in the brief window before this swap (rare, not zero). migrated_count = 0 max_migrations = 10000 # Safety limit while !existing_pending_queue.empty? && migrated_count < max_migrations - # Non-blocking pop: another consumer could in theory drain it, so don't block. + # Non-blocking pop: another consumer could drain this queue too. begin msg = existing_pending_queue.pop(true) rescue ThreadError break end - # Push with a deadline (see push_with_deadline: no Timeout.timeout, - # which corrupts the SizedQueue mutex on JRuby). + # See `#push_with_deadline` for why not `Timeout.timeout`. if push_with_deadline(msg, 1) migrated_count += 1 logger.warn "Migrated message #{migrated_count} from old queue to central queue" @@ -131,23 +118,22 @@ def shutdown(timeout = 5) handlers = @pending_queue_handlers.select(&:alive?) return if handlers.empty? - # Wake every handler with its own poison pill. + # Send each handler its own poison pill to wake it. handlers.size.times do - # Clear some space if the queue is full so the shutdown signal fits. + # Clear space if the queue is full, so the pill fits. if @pending_queue.num_waiting.zero? && @pending_queue.size >= @pending_queue.max logger.warn "Queue full during shutdown, clearing to make room for shutdown signal" @pending_queue.clear rescue nil end - # Push with a deadline (see push_with_deadline: no Timeout.timeout, - # which corrupts the SizedQueue mutex on JRuby). + # See `#push_with_deadline` for why not `Timeout.timeout`. unless push_with_deadline(:shutdown, 1) logger.error "Failed to send shutdown signal (queue blocked); will force-kill remaining handlers" break end end - # Join all handlers within a single shared deadline, then force-kill stragglers. + # Join all handlers within one shared deadline. Force-kill stragglers. deadline = monotonic + timeout handlers.each do |handler| remaining = deadline - monotonic @@ -161,24 +147,23 @@ def shutdown(timeout = 5) handler.join(1) rescue nil end - # Clean up queue @pending_queue.clear rescue nil end - # Depth of the shared intake queue = intake backpressure (for observability). + # Intake backpressure gauge: depth of the shared intake queue. def pending_queue_size @pending_queue.size end - # Resident bytes in the shared intake queue = heap backpressure (gauge). + # Heap backpressure gauge: resident bytes in the shared intake queue. def pending_queue_bytes @pending_queue.bytesize end def unsubscribe_all - # Take ownership and clear: pause/resume cycles re-subscribe from - # scratch, so keeping the old entries only grew the array without bound - # and re-unsubscribed dead subscriptions on every later pause. + # Take and clear the list: pause/resume re-subscribes from scratch, + # so keeping old entries would grow it forever and re-unsubscribe + # already-dead subscriptions on every later pause. subscriptions = @subscriptions_mutex.synchronize do subs = @subscriptions.dup @subscriptions.clear @@ -199,17 +184,14 @@ def monotonic ::Protobuf::Nats.monotonic_time end - # Push onto the shared SizedQueue with a deadline, WITHOUT Timeout.timeout. - # Timeout uses an asynchronous Thread#raise, which is unsafe around the - # mutex SizedQueue#push takes internally: on JRuby (10.x in particular) a - # timeout firing mid-push unwinds through the held mutex and raises - # "ThreadError: Attempt to unlock a mutex which is locked by another - # thread/fiber" instead of Timeout::Error -- so the rescue :Timeout::Error - # never fires and shutdown/migration blow up. CRuby happens to unwind - # cleanly, which is why this only bit JRuby. Poll a non-blocking push - # against a monotonic deadline instead: no async raise, safe on every - # engine. Returns true if pushed, false if the deadline passed (queue - # still full) or the queue was closed. + # Push with a deadline, without `Timeout.timeout`: its async + # `Thread#raise` is unsafe around `SizedQueue#push`'s internal mutex. + # On JRuby 10.x a timeout mid-push raises `ThreadError: Attempt to + # unlock a mutex which is locked by another thread/fiber` instead of + # `Timeout::Error`, so shutdown or migration fails. CRuby unwinds + # cleanly, so only JRuby hits this. Poll a non-blocking push against a + # monotonic deadline instead. Returns true if pushed, false on + # deadline or a closed queue. def push_with_deadline(obj, timeout) deadline = monotonic + timeout loop do @@ -225,11 +207,10 @@ def push_with_deadline(obj, timeout) end end - # Spawn one intake handler. Each thread owns its own crash_count so the - # self-healing exponential backoff is correct under true parallelism (a - # shared counter would lose updates across handlers on JRuby). The counter - # decays to zero once a handler processes a message again, so a later - # transient crash restarts the backoff from 1s. + # Spawn one intake handler with its own `crash_count`: a shared counter + # would lose updates across handlers on JRuby's true parallelism. The + # counter decays to zero on the next processed message, so a later + # crash restarts the backoff from 1 second. def spawn_handler(index) ::Thread.new do ::Thread.current.name = "subscription-manager-#{object_id}-#{index}" @@ -239,26 +220,23 @@ def spawn_handler(index) loop do msg = nil begin - # --- Per-message processing --- msg = @pending_queue.pop - # nil means the queue was closed (e.g. nats-pure closed the - # swapped sub queue on connection close). A closed queue pops - # nil immediately forever, so park briefly instead of raising - # NoMethodError-per-iteration through the rescue below. + # nil means the queue closed (e.g. nats-pure closes the + # swapped sub queue on connection close). It pops nil + # forever, so park briefly instead of looping on the rescue. if msg.nil? sleep ::Protobuf::Nats::CLOSED_QUEUE_PARK_SECONDS next end - # Check for shutdown poison pill + # Stop on the shutdown poison pill. break if msg == :shutdown @callback.call(msg.data, msg.reply, msg.subject) - crash_count = 0 unless crash_count.zero? # healthy: decay backoff - # --- End per-message processing --- + crash_count = 0 unless crash_count.zero? # healthy: decay the backoff rescue => per_message_error - # Log the error for the specific message, but DON'T kill the thread. + # Log this message's error; keep the thread running. logger.error("SubscriptionManager failed to process message: #{msg.inspect rescue 'unknown'}. Error: #{per_message_error.message}") ::Protobuf::Nats.notify_error_callbacks(per_message_error) rescue nil end @@ -266,18 +244,17 @@ def spawn_handler(index) rescue => fatal_error raise if fatal_error.is_a?(SystemExit) || fatal_error.is_a?(Interrupt) || fatal_error.is_a?(SignalException) - # This block is for fatal errors that crash the thread itself. logger.error("SubscriptionManager handler crashed fatally! Error: #{fatal_error.message}") ::Protobuf::Nats.notify_error_callbacks(fatal_error) rescue nil ::Protobuf::Nats.instrument("server.subscription_handler_crashed", 1) rescue nil - # Self-healing with exponential backoff (per-thread counter). + # Self-heal with exponential backoff (counter is per thread). crash_count += 1 sleep_duration = ::Protobuf::Nats.crash_backoff_seconds(crash_count) logger.warn("Waiting #{sleep_duration}s before restarting SubscriptionManager handler...") sleep sleep_duration - retry # Restart the loop + retry # Restart the loop. end end end diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index af6657d..dac4a55 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -7,23 +7,19 @@ class ThreadPool def initialize(size, opts = {}) @queue = ::Queue.new - # Lock-free counter of in-flight work. Replaces a mutex-guarded integer so - # that N workers running in true parallel (JRuby) don't serialize on every - # task completion. + # Lock-free counter of in-flight work, so parallel workers on JRuby + # don't serialize on every task completion. @active_work = ::Concurrent::AtomicFixnum.new(0) - # Callbacks @error_cb = lambda do |error| logger.error("Error in ThreadPool worker: #{error.message} #{error.backtrace.join(" ")}") end - # Synchronization @mutex = ::Mutex.new # guards the @workers array only @cb_mutex = ::Mutex.new - # Let's get this party started queue_size = opts[:max_queue].to_i || 0 @max_size = size + queue_size @max_workers = size @@ -36,7 +32,6 @@ def enqueued_size @queue.size end - # Thread-safe access to check if the pool is full. def full? @active_work.value >= @max_size end @@ -45,13 +40,11 @@ def max_size @max_size end - # This method is now thread-safe. def push(&work_cb) return false if @shutting_down.true? - # Optimistically claim a slot; back off if we exceeded the cap. This admits - # work only while active_work < max_size, matching the original guard, but - # without holding a mutex across the enqueue. + # Claim a slot first, then back off over the cap. Admits work while + # `active_work < max_size`, without a mutex across the enqueue. if @active_work.increment > @max_size @active_work.decrement return false @@ -61,9 +54,8 @@ def push(&work_cb) true end - # This method is now thread-safe. def shutdown - # CAS ensures the poison pills are pushed exactly once. + # CAS ensures the poison pills push exactly once. return unless @shutting_down.make_true @max_workers.times { @queue << [:stop, nil] } @@ -74,22 +66,19 @@ def kill @workers.map(&:kill) end - # Wait until all workers exit. Returns true if the pool drained, false if - # the timeout elapsed first. Prunes under the mutex (it mutates @workers). + # Wait until all workers exit. Returns true if drained, false on + # timeout. Prune under the mutex, since it changes `@workers`. def wait_for_termination(seconds = nil) deadline = seconds && (::Protobuf::Nats.monotonic_time + seconds) loop do @mutex.synchronize { prune_dead_workers } if @workers.empty? - # Workers drain what is behind their poison pill, but a push that - # had already passed the @shutting_down check can land after the - # last worker has drained and exited. Nothing would ever run it, - # and the server has already ACKed it. Run it here, on the caller's - # thread, now that no worker is left to race us. - # - # This drain is not bounded by `seconds`: a slow late handler holds - # the caller past the deadline. Accepted, because the alternative is - # dropping an ACKed request, and at most a few pushes can land here. + # A push past the `@shutting_down` check can land after the last + # worker drains and exits, so nothing would run it though the + # server already ACKed it. Run it here on the caller's thread. + # This ignores `seconds`: a slow handler can hold the caller past + # the deadline. Accepted, since the alternative drops an ACKed + # request, and only a few pushes can land here. drain_remaining_work(requeue_pills: false) return true end @@ -98,25 +87,21 @@ def wait_for_termination(seconds = nil) end end - # Top the pool back up to max_workers if workers have died (e.g. one was - # killed by a non-StandardError, which the per-task rescue can't catch). - # This is the ONLY respawn path after initialize -- #push deliberately - # does not supervise (a mutex acquisition plus an O(workers) alive? scan - # per request is contention on the hot enqueue path); the server's run - # loop calls this every second, so a dead worker is replaced within ~1s - # and its queued work is picked up then. - # No-op while shutting down so we don't resurrect workers mid-drain. + # Replace workers killed by a non-`StandardError` past the per-task + # rescue. The only respawn path after `initialize`: `#push` skips + # supervising, since a mutex plus an `alive?` scan would add + # contention to the hot enqueue path. The server's run loop calls this + # every second instead. No-op while shutting down, to not restart + # workers mid-drain. def replenish return if @shutting_down.true? supervise_workers end - # This callback is executed in a thread safe manner. def on_error(&cb) @cb_mutex.synchronize { @error_cb = cb } end - # Thread-safe access to the current active work size. def size @active_work.value end @@ -127,8 +112,8 @@ def logger ::Protobuf::Logging.logger end + # Call this only inside `@mutex`. def prune_dead_workers - # This must be called inside @mutex. @workers = @workers.select(&:alive?) end @@ -142,20 +127,19 @@ def supervise_workers end end - # Run any :work left in the queue behind a poison pill, then stop. Called - # by a worker that has taken its pill, and once more by - # #wait_for_termination after the last worker exits (a push that already - # passed the @shutting_down check can land after every worker has gone). + # Run any `:work` left behind a poison pill, then stop. A worker calls + # this after taking its pill; `#wait_for_termination` also calls it + # once more after the last worker exits (see there for why). # - # This does not make admission and shutdown atomic -- #push is lock-free - # by design, so work can still arrive after the final drain. It closes the - # window that matters: everything enqueued up to the moment the pool - # reports termination runs, so no ACKed request is silently dropped. + # This does not make admission and shutdown atomic: `#push` is + # lock-free, so work can still arrive after the final drain. It closes + # the window that matters instead, running everything enqueued up to + # the moment the pool reports termination, so no ACKed request drops. # - # requeue_pills: true when a worker drains, because a pill it finds - # belongs to a live sibling. False for the final drain: no worker is left, - # so any pill is an orphan (e.g. one meant for a worker that died and was - # not replaced during shutdown). The drain discards it and continues. + # `requeue_pills`: true when a worker drains, since a pill found there + # belongs to a live sibling. False for the final drain: no worker is + # left, so any pill is an orphan (e.g. one for a worker that died and + # was not replaced during shutdown); discard it. def drain_remaining_work(requeue_pills: true) loop do begin @@ -164,8 +148,8 @@ def drain_remaining_work(requeue_pills: true) break end - # A sibling's pill: put it back so that worker still exits, and stop - # draining. An orphan pill (see requeue_pills): discard it. + # A sibling's pill: put it back so that worker still exits, then + # stop draining. An orphan pill (see `requeue_pills`): discard it. if type == :stop next unless requeue_pills @queue << [:stop, nil] @@ -190,24 +174,20 @@ def spawn_worker type, cb = @queue.pop rescue ::Protobuf::Nats::Errors::HandlerOverdue # A late overdue-reclaim raise (opt-in server feature) can land - # while the worker is parked between tasks; swallow it rather - # than losing the worker until the next replenish tick. + # while the worker waits between tasks. Swallow it, rather than + # losing the worker until the next replenish tick. next end - # The :stop poison pill never claimed an @active_work slot (see - # #shutdown), so it must not reach the ensure below -- decrementing - # for it drove the counter negative at shutdown. + # The `:stop` pill never claimed an `@active_work` slot (see + # `#shutdown`), so it must skip the ensure below: decrementing + # for it would drive the counter negative. if type == :stop - # #push admits work by checking @shutting_down and then enqueueing, - # so #shutdown can slip its pills in between those two steps and - # leave real work sitting BEHIND them. Exiting here would strand - # that work forever -- and the server has already published an ACK - # for it, so its client blocks until response_timeout (60s). - # - # Drain what is behind us before leaving. Pop non-blocking so an - # empty queue ends the drain immediately; hand any sibling's pill - # back so every worker still gets one. + # `#shutdown` can slip pills in between `#push`'s + # `@shutting_down` check and its enqueue, stranding real work + # behind them otherwise. The server already ACKed that work, + # so its client would block until `response_timeout` (60s). + # See `#drain_remaining_work`. drain_remaining_work break end diff --git a/lib/protobuf/nats/uuidv7_helper.rb b/lib/protobuf/nats/uuidv7_helper.rb index 41d31e3..bddf0f5 100644 --- a/lib/protobuf/nats/uuidv7_helper.rb +++ b/lib/protobuf/nats/uuidv7_helper.rb @@ -1,24 +1,18 @@ module Protobuf module Nats class UUIDv7Helper - # Strict RFC 9562 UUIDv7 shape, matching what .generate produces. The - # strictness matters to callers like the server's stale-request shedding: - # treating a non-UUID token (e.g. from a foreign client) as a timestamp - # would compute a garbage age. + # Strict RFC 9562 UUIDv7 shape, matching .generate's output. A + # non-UUID token read as a timestamp gives callers a garbage age. UUIDV7_REGEX = /\A\h{8}-\h{4}-7\h{3}-\h{4}-\h{12}\z/ - # Same shape without dashes. extract_timestamp has always accepted this - # form, so validating with the dashed pattern alone would reject tokens - # the method documents as supported. + # Same shape without dashes. extract_timestamp accepts this form too. UUIDV7_COMPACT_REGEX = /\A\h{12}7\h{3}\h{4}\h{12}\z/ - # Generate a UUIDv7 string without a CSPRNG. Callers that only need a - # 48-bit millisecond timestamp prefix (so #age_in_seconds can report a - # value) plus enough randomness to stay unique among concurrent generators - # don't need SecureRandom: its gen_random call dominated per-request CPU - # and garbage (measured ~6.8us/op and 4 GC-triggering allocations). A - # per-thread non-cryptographic Random halves both. The layout still matches - # RFC 9562 UUIDv7 (version 7 + RFC 4122 variant bits). + # Generates a UUIDv7 without a CSPRNG. Callers only need the 48-bit + # ms timestamp prefix plus enough randomness for uniqueness. + # SecureRandom's gen_random dominated per-request CPU and garbage + # (measured ~6.8us/op, 4 GC-triggering allocations); a per-thread + # non-cryptographic Random halves both. Layout still matches RFC 9562. # # @return [String] a UUIDv7 string (e.g. "01234567-89ab-7def-8123-456789abcdef") def self.generate @@ -26,8 +20,8 @@ def self.generate rng = (::Thread.current[:pb_nats_uuid_rng] ||= ::Random.new) format( "%08x-%04x-%04x-%04x-%04x%08x", - (unix_ts_ms >> 16) & 0xffffffff, # 32 high bits of the ms timestamp - unix_ts_ms & 0xffff, # 16 low bits of the ms timestamp + (unix_ts_ms >> 16) & 0xffffffff, # high 32 bits of ms timestamp + unix_ts_ms & 0xffff, # low 16 bits of ms timestamp (0x7000 | rng.rand(0x1000)), # version 7 + 12 random bits (0x8000 | rng.rand(0x4000)), # RFC 4122 variant + 14 random bits rng.rand(0x10000), # 16 random bits @@ -35,23 +29,20 @@ def self.generate ) end - # Extract the Unix timestamp (in seconds) from a UUIDv7 string - # Returns nil if the UUID cannot be parsed + # Extracts the Unix timestamp (seconds) from a UUIDv7 string. # - # Validates the whole token, not just its length. String#to_i(16) stops at - # the first non-hex character and returns 0 rather than raising, so a - # non-UUID reply token ("non-uuid-reply-token") used to parse as epoch 0 - # and report an age of ~56 years -- which #age_in_seconds then fed - # straight into the client.unexpected_message gauge. + # Validates the whole token. String#to_i(16) stops at the first + # non-hex character and returns 0 instead of raising. A non-UUID + # token used to parse as epoch 0, reporting a ~56-year age into the + # client.unexpected_message gauge. # - # @param uuid [String] A UUIDv7 string (e.g., "01234567-89ab-7def-0123-456789abcdef") - # @return [Time, nil] The timestamp embedded in the UUID, or nil if parsing fails + # @param uuid [String] a UUIDv7 string + # @return [Time, nil] the embedded timestamp, or nil if parsing fails def self.extract_timestamp(uuid) return nil unless uuid.is_a?(String) return nil unless uuid.match?(UUIDV7_REGEX) || uuid.match?(UUIDV7_COMPACT_REGEX) - # UUIDv7 format: first 48 bits (12 hex chars) are Unix timestamp in milliseconds - # Remove dashes and extract the timestamp portion + # First 48 bits (12 hex chars) are the Unix timestamp in ms. uuid_bytes = uuid.tr('-', '') timestamp_ms = uuid_bytes[0, 12].to_i(16) @@ -60,12 +51,11 @@ def self.extract_timestamp(uuid) nil end - # Calculate the age of a UUIDv7 in seconds - # Returns nil if the UUID cannot be parsed + # Calculates the age of a UUIDv7 in seconds. # - # @param uuid [String] A UUIDv7 string - # @param current_time [Time] The time to compare against (defaults to Time.now) - # @return [Float, nil] The age in seconds, or nil if parsing fails + # @param uuid [String] a UUIDv7 string + # @param current_time [Time] time to compare against (default: now) + # @return [Float, nil] the age in seconds, or nil if parsing fails def self.age_in_seconds(uuid, current_time: Time.now) timestamp = extract_timestamp(uuid) return nil unless timestamp @@ -74,8 +64,7 @@ def self.age_in_seconds(uuid, current_time: Time.now) end # Age (integer ms) of a strictly-validated UUIDv7 token, or nil for a - # non-UUIDv7 token. Allocation-light: runs per message on the server's - # intake path. + # non-UUIDv7 token. Allocation-light; runs per message on server intake. def self.age_ms(token) return nil unless token.is_a?(String) && token.match?(UUIDV7_REGEX) unix_ts_ms = (token[0, 8].to_i(16) << 16) | token[9, 4].to_i(16)