Aug26 more improvements - #13
Open
skunkworker wants to merge 10 commits into
Open
Conversation
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Correctness fixes for concurrency bugs found while reviewing the 0.13.1 and 0.13.2 changes. No API or configuration changes; version bumped to
0.13.3.pre1.Every fix ships with a spec that was verified to fail against the pre-fix code — each library file was temporarily reverted to confirm the spec caught the bug, not just that it passed afterward. Suite goes from 287 to 297 examples, 0 failures, and the two pre-existing RSpec false-positive warnings are gone.
The one that would have caused an outage
ByteBoundedQueuebyte counter drifted permanently upward (341864a)pushcounted an item's bytes after handing it toSizedQueue#push, so a consumer could pop the item and subtract its bytes before the producer had added them.popclamps at zero, so that subtraction was swallowed, and the producer's increment then landed on an item that was already gone.The counter therefore only ever ratcheted up. The server funnels every subscription through one shared queue and pops it from
processor_counthandler threads on JRuby, so the race was live on every message. Once the drift reached the 128 MiB ceiling,pushwould drop every subsequent request — the server goes dark while still looking healthy. This is the same failure class as the nats-purepending_sizedrift fixed in 0.13.1.Bytes are now counted before the enqueue and rolled back in an
ensureif the enqueue doesn't happen. The regression spec fails on the old code with 100 phantom bytes in an empty queue.Shutdown
Work accepted as shutdown begins was stranded (
fbce03b,b912e5c)ThreadPool#pushchecks the shutdown flag and then enqueues, soshutdowncan slip its poison pills between those two steps. Workers took a pill and exited, leaving the work behind them unrun — and the server has already published an ACK for that request, so its client blocked untilresponse_timeout(60s default). The abandoned@active_workincrement leaked too.Re-checking the flag after the increment was the obvious fix, but it doesn't close the window and 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, workers drain any work queued behind their pill (putting a sibling's pill back so every worker still exits).
That alone turned out to be insufficient, which surfaced as a ~8% flake in the new specs — a real hole in the fix, not test timing. If a worker takes its pill and drains before the racing push lands, it finds an empty queue and exits, stranding the work exactly as before.
wait_for_terminationnow drains once more after the last worker is gone, on the caller's thread where nothing can race it. Admission and shutdown still aren't atomic (#pushis lock-free by design), but nothing enqueued before the pool reports termination is dropped.Timeout.timeout(10)reintroduced the JRuby mutex hazard (bc504e4)0.13.1 removed
TimeoutfromSuperSubscriptionManagerbecause its asyncThread#raise, fired while a thread holds theSizedQueuemutex, makes JRuby unwind through the held mutex and raise"Attempt to unlock a mutex which is locked by another thread/fiber".Server#runstill wrapped the whole shutdown call inTimeout.timeout(10), reintroducing the hazard one frame up.It could genuinely fire:
#shutdownis not bounded by 10s. 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 isprocessor_count. The resultingThreadErroris caught by the existing rescue, but the corrupted queue mutex can then hang the trailing@pending_queue.clear.#shutdownalready self-bounds with a monotonic deadline and non-blocking pushes, so the wrapper is gone, along with the now-deadrequire "timeout"in both files. A guard spec fails if it comes back.Self-healing
A late muxer dispatcher tore down a subscription a sibling had rebuilt (
9b8eb2e)A dispatcher that crashes fatally sleeps a backoff, then unconditionally called
drop_subscription_locked. When several crash together (JRuby runsprocessor_countof them) they wake on different backoffs — 1s, then 4s — so the late one destroyed the subscription the earlier one had just rebuilt, andfail_inflight_requestscancelled every request that had already arrived on it. The staggered backoff makes this more likely, not less.Each dispatcher now tears down only the subscription it actually died on. Worth noting for review: capturing that subscription when the thread starts does not work — it races the sibling's swap and reads whichever subscription is current after the backoff, which is the very value the check needs to compare against. The dispatch loop records what it's draining in a thread-local instead.
Observability
Non-UUID tokens reported ~56-year message ages (
f2799c8)String#to_i(16)stops at the first non-hex character and returns 0 rather than raising, soextract_timestamp's length-only check let a foreign reply token parse as epoch 0.age_in_secondsthen reported ~1.79e9 seconds into theclient.unexpected_messagegauge, skewing dashboards.extract_timestampnow validates the whole token. 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. Validation accepts both the dashed and compact forms, since the dashed regex alone would have failed the existing "handles UUIDs without dashes" spec.Also switches two
not_to raise_error(NoMethodError)matchers to the bare form; RSpec warns those pass on any error, including one raised before the code under test is reached.Not addressed here
sub.synchronizein the muxer dispatch loop — a documented throughput trade for the byte cap, not a defect. Worth measuring before changing.SystemExit/Interruptguard inside aStandardErrorrescue insuper_subscription_manager.rb:268— cosmetic.Verification
0.13.3.pre1.