diff --git a/.travis.yml b/.travis.yml deleted file mode 100644 index 6c7ba86..0000000 --- a/.travis.yml +++ /dev/null @@ -1,16 +0,0 @@ -sudo: false -language: ruby -jdk: - - openjdk8 -rvm: - - 2.3.0 - - 2.7.0 - - jruby-9.1.7.0 - - jruby-9.2.13.0 -before_install: - # Install and start gnatsd - - ./scripts/install_gnatsd.sh - - $HOME/nats-server/nats-server & - # Install deps for project - - gem install bundler - - gem update --system diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c419f1..7acffd6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,61 @@ ## Changelog +### 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. + +#### Client: response-muxer heap bound +- The shared response "firehose" is bounded by both a message count (`PB_NATS_RESPONSE_MUXER_QUEUE_SIZE`, default `1024`) and a byte ceiling (`PB_NATS_RESPONSE_MUXER_QUEUE_BYTES`, default 64 MiB); nats-pure drops (`SlowConsumer`) on whichever trips first and the RPC retries. Previously only nats-pure's 65,536-message count applied with the byte limit disabled, so a burst of large responses could hold gigabytes of Ruby objects on the JVM heap. +- The muxer now decrements the subscription's `pending_size` after each pop, keeping a *finite* byte limit accurate — instead of disabling it as before. If a subscription can't support that accounting (no `#synchronize`), `start` raises `IncompatibleSubscription` (a tripwire for a breaking nats-pure change) rather than silently degrading. +- New gauges: `response_muxer.pending_queue_size` and `response_muxer.pending_queue_peak` (high-water mark between the ~60s samples). + +#### 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. + +### 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. + +#### Client: reconnect & retry +- Restored dropped-connection retries (the retry rescue matched an error nothing raised). The client now retries the transport errors nats-pure actually raises: `EOFError`, `IOError`, `Errno::ECONNRESET`/`EPIPE`/`ECONNREFUSED`/`ECONNABORTED`/`ETIMEDOUT`/`EHOSTUNREACH`/`ENETUNREACH`, `NATS::IO::ConnectionClosedError`, and Java `IOException` on JRuby. +- A terminally closed connection self-heals: `on_close` drops the cached connection, the next request (or in-flight retry) rebuilds it, and the response muxer detects the swap and re-subscribes on the live connection. Previously every RPC timed out until the process restarted. +- A muxer restart wakes in-flight waiters immediately instead of leaving them to burn the full timeout on responses that can never arrive. +- Retries are bounded and jittered (`PB_NATS_CLIENT_MAX_RETRIES`, `PB_NATS_CLIENT_RECONNECT_DELAY_SPLAY_LIMIT`), and the final failed attempt raises immediately instead of sleeping first. +- The muxer token TTL stretches with a response timeout configured beyond 600s, so long waits aren't cleaned up mid-request. + +#### Server: reliability +- Subscriptions no longer go permanently deaf under cumulative traffic: the byte-based slow-consumer limit (which nats-pure never decrements on our consumption path) is disabled on both client and server subscriptions; the accurate message-count limit still applies. +- Tuning `PB_NATS_SERVER_INTAKE_QUEUE_SIZE` down is safe: the slow-consumer limit is kept aligned with the queue capacity, so overload drops promptly instead of blocking nats-pure's read thread (which froze PING/PONG and every subject). +- A terminally closed connection stops the server (logs + `server.connection_closed`) so a supervisor restarts it, instead of idling forever subscribed to nothing. +- Failed handlers publish an RPC error response so the client fails fast instead of hanging until its response timeout; a failed success-publish no longer emits a duplicate error response; client-facing error messages are generic (details stay in server logs). +- Pause/resume no longer leaks subscriptions; the thread-pool counter no longer goes negative at shutdown; dispatch/intake threads park instead of busy-spinning on a closed queue; self-healing always respawns a replacement dispatcher, with thread-safe backoff that decays when healthy. +- Opt-in stale-request shedding (`PB_NATS_SERVER_STALE_REQUEST_MS`) and opt-in overdue-handler reclaim (`PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS`). Handlers are still never aborted by default, and shutdown drains in-flight handlers before closing. +- Lifecycle callbacks (client and server) register before `connect`, so handshake-window events are observed; a failed handshake closes the half-open client instead of leaking its reader/flusher threads. + +#### Performance +- Server intake fans out across `PB_NATS_SERVER_SUBSCRIPTION_HANDLERS` threads (default `processor_count` on JRuby, 1 on CRuby): ~8.5× intake throughput, head-of-line stalls ~505ms → ~0.4ms (`bench/server_intake_bench.rb`). +- Muxer dispatch dropped its per-message lock (~2.7× faster on JRuby, `bench/muxer_resilience_bench.rb`) and extracts reply tokens without `split` allocations. +- `ThreadPool#push` no longer supervises the worker pool per request (the server's 1s `replenish` tick is the sole respawn path), and `ResponseMuxer#start`'s once-per-RPC check is a lock-free atomic read. +- User error callbacks run on a bounded executor off nats-pure's read thread; drops are counted (`error_callback_drop_count`) and instrumented. + +#### Failover & configuration +- New yaml keys `reconnect_time_wait`, `ping_interval`, and `max_outstanding_pings` are forwarded to nats-pure for faster dead-node detection (defaults unchanged); `max_reconnect_attempts: -1` reconnects forever. +- Numeric env vars parse strictly: malformed values (`"5s"`, `"fast,slow"`) log and fall back to defaults instead of silently becoming `0`; `PB_NATS_SERVER_MAX_QUEUE_SIZE` defaults to the resolved thread count. +- `connection_options` forwards only nats-pure-recognized keys (the dead JNats-era `:disable_reconnect_buffer` option is gone), and connections are named (`PB_NATS_CONNECTION_NAME` > yaml `connection_name` > hostname) for NATS monitoring. +- A yaml config that is empty or has no section for the current environment falls back to defaults instead of crashing at boot. +- New in-flight handler observability: `server.inflight_count`, `server.inflight_oldest_age_ms`, `server.overdue_handler_count`, `server.pending_intake_queue_size`, `server.slow_handler` (opt-in), `server.thread_pool_saturated`; server durations use a monotonic clock. + +#### Security +- TLS now verifies the NATS server certificate chain (`VERIFY_PEER`, trusting `tls_ca_cert` or the system store). **Breaking for misconfigured deployments** whose certificates don't chain to the trusted CA — they previously connected unverified. +- TLS negotiates 1.2–1.3 (replacing the deprecated 1.2 hard pin); OpenSSL builds without TLS 1.3 degrade to a 1.2 ceiling instead of raising. +- YAML config uses `safe_load` (aliases allowed, arbitrary object deserialization rejected). TLS client keys may be any key type (`OpenSSL::PKey.read`). +- Known gap: TLS hostname (SAN/CN) verification remains off — it needs per-connection plumbing in nats-pure; tracked separately. + +#### Testing, CI, dependencies +- Real-NATS integration specs (auto-detected on `localhost:4222`): full RPC round trip, concurrency with real NACK backpressure, terminal-close self-heal, and a two-node cluster failover spec that spawns its own cluster and kills the node the client is connected to (gated on the `nats-server` binary). GitHub Actions runs the suite on CRuby 3.1/3.4 and JRuby 9.4/10.0. +- nats-pure pinned to `>= 2.5, < 3`: the gem relies on nats-pure internals (pending-queue swap, slow-consumer semantics, subscription replay, infinite-reconnect flag) verified against 2.5. +- Removed the unused `connection_pool` dependency and the dead client subscription-pool code; `require "timeout"` is explicit where used. +- Soak-tested with chaos runs (nats-server killed twice mid-run): 99.4% success on CRuby 3.4, 100% on JRuby 10.0. + ### 0.13.0 This is a large overhaul of the client and server internals. @@ -21,4 +77,3 @@ This is a large overhaul of the client and server internals. - Bumped `activesupport` to `>= 6.1` (from `>= 3.2`). - Added `concurrent-ruby` (`~> 1.3.6`, pinned so `logger` is included) and `uuid7` runtime dependencies. - Pinned `i18n` to `< 1.15.0` in the Gemfile (workaround for ruby-i18n/i18n#735). - diff --git a/README.md b/README.md index 1dc84fd..7d1b3a0 100644 --- a/README.md +++ b/README.md @@ -16,87 +16,9 @@ Add this line to your application's Gemfile: gem 'protobuf-nats' ``` -And then execute: - - $ bundle - -Or install it yourself as: - - $ gem install protobuf-nats - -## Configuring - -### Environment Variables - -You can also use the following environment variables to tune parameters: - -`PB_NATS_SERVER_MAX_QUEUE_SIZE` - The size of the queue in front of your thread pool (default: thread count passed to CLI). - -`PB_NATS_SERVER_PAUSE_FILE_PATH` - If this file exists, the server will pause by unsubscribing all services. When the -file is removed it will resubscribe and restart slow start (default: `nil`). - -`PB_NATS_SERVER_SLOW_START_DELAY` - Seconds to wait before adding another round of subscriptions (default 10). - -`PB_NATS_SERVER_SUBSCRIPTIONS_PER_RPC_ENDPOINT` - Number of subscriptions to create for each rpc endpoint. This number is -used to allow JVM based servers to warm-up slowly to prevent jolts in runtime performance across your RPC network -(default: 10). - -`PB_NATS_CLIENT_ACK_TIMEOUT` - Seconds to wait for an ACK from the rpc server (default: 5 seconds). - -`PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS` - Array of milliseconds to wait between NACK retries (default: "0,1,3,5,10"). - -`PB_NATS_CLIENT_NACK_BACKOFF_SPLAY_LIMIT` - Milliseconds to add to the NACK backoff timeout to avoid bursting retries -(default: 10 milliseconds). - -`PB_NATS_CLIENT_RESPONSE_TIMEOUT` - Seconds to wait for a non-ACK response from the rpc server (default: 60 seconds). - -`PB_NATS_CLIENT_RECONNECT_DELAY` - If we detect a reconnect delay, we will wait this many seconds (default: the ACK timeout). - -`PB_NATS_CLIENT_SUBSCRIPTION_POOL_SIZE` - If subscription pooling is desired for the request/response cycle then the pool size maximum should be set; the pool is lazy and therefore will only start new subscriptions as necessary (default: 0) - -`PB_NATS_RESPONSE_MUXER_DISPATCHERS` - Number of dispatcher threads draining the shared response subscription (see [ResponseMuxer](#how-it-works)). Defaults to `Concurrent.processor_count` on JRuby (true parallelism) and `1` on CRuby (the GVL makes extra dispatchers pointless). Minimum of 1. - -`PROTOBUF_NATS_CONFIG_PATH` - Custom path to the config yaml (default: "config/protobuf_nats.yml"). - -### YAML Config - -The client and server are configured via environment variables defined in the `nats-pure` gem. However, there are a -few params which cannot be set: `servers`, `uses_tls`, `subscription_key_replacements`, and `connect_timeout`, so those must be defined in a yml file. - -The library will automatically look for a file with a relative path of `config/protobuf_nats.yml`, but you may override -this by specifying a different file via the `PROTOBUF_NATS_CONFIG_PATH` env variable. - -The `subscription_key_replacements` feature is something we have found useful for local testing, but it is subject to breaking changes. - -An example config looks like this: -``` -# Stored at config/protobuf_nats.yml ---- - production: - servers: - - "nats://127.0.0.1:4222" - - "nats://127.0.0.1:4223" - - "nats://127.0.0.1:4224" - max_reconnect_attempts: 500 - uses_tls: true - tls_client_cert: "/path/to/client-cert.pem" - tls_client_key: "/path/to/client-key.pem" - tls_ca_cert: "/path/to/ca.pem" - connect_timeout: 2 - server_subscription_key_only_subscribe_to_when_includes_any_of: - - "search" - - "create" - server_subscription_key_do_not_subscribe_to_when_includes_any_of: - - "old_search" - - "old_create" - subscription_key_replacements: - - "original_service": "replacement_service" -``` - ## Usage -This library is designed to be an alternative transport implementation used by the `protobuf` gem. In order to make -`protobuf` use this library, you need to set the following env variable: +This library is an alternative transport for the `protobuf` gem. Point `protobuf` at it with: ``` PB_SERVER_TYPE="protobuf/nats/runner" @@ -105,11 +27,10 @@ PB_CLIENT_TYPE="protobuf/nats/client" ## Example -NOTE: For a more detailed example, look at the `warehouse` app in the `examples` directory of this project. - -Here's a tl;dr example. You might have a protobuf definition and implementation like this: +For a more detailed example, see the `warehouse` app in the `examples` directory. ```ruby +# app.rb require "protobuf/nats" class User < ::Protobuf::Message @@ -126,61 +47,191 @@ class UserService < ::Protobuf::Rpc::Service end ``` -Let's assume we saved this in a file called `app.rb` - -We can now start an rpc server using the protobuf-nats runner and client: +Start a server, then call it from a client: ``` $ export PB_SERVER_TYPE="protobuf/nats/runner" $ export PB_CLIENT_TYPE="protobuf/nats/client" $ bundle exec rpc_server start ./app.rb -... -I, [2017-03-24T12:16:02.539930 #12512] INFO -- : Creating subscriptions: -I, [2017-03-24T12:16:02.543927 #12512] INFO -- : - rpc.user_service.create -... -``` -And we can start a client and begin communicating: - -``` -$ export PB_SERVER_TYPE="protobuf/nats/runner" -$ export PB_CLIENT_TYPE="protobuf/nats/client" $ bundle exec irb -r ./app -irb(main):001:0> UserService.client.create(User.new(:username => "testing 123")) +irb> UserService.client.create(User.new(:username => "testing 123")) => # ``` -And we can see the message was sent to the server and the server replied with a user which now has an `id`. +An rpc without a matching instance method (e.g. an unimplemented `search`) is simply not subscribed to. -If we were to add another service endpoint called `search` to the `UserService` but fail to define an instance method -`search`, then `protobuf-nats` will not subscribe to that route. +## Configuring -## How it works +### Environment variables + +Numeric variables are parsed strictly: a malformed value (e.g. `PB_NATS_CLIENT_ACK_TIMEOUT=5s`) is logged and the +default is used, instead of silently becoming `0`. + +#### Client + +| Variable | Default | Description | +| --- | --- | --- | +| `PB_NATS_CLIENT_ACK_TIMEOUT` | `5` | Seconds to wait for the server's ACK. | +| `PB_NATS_CLIENT_RESPONSE_TIMEOUT` | `60` | Seconds to wait for the RPC response. | +| `PB_NATS_CLIENT_MAX_RETRIES` | `3` | Attempts for ACK timeouts and transient transport errors. Retries re-send the request — see [Delivery semantics](#delivery-semantics-at-least-once). | +| `PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS` | `0,1,3,5,10` | Milliseconds to wait between NACK retries (one attempt per interval). | +| `PB_NATS_CLIENT_NACK_BACKOFF_SPLAY_LIMIT` | `10` | Random jitter (ms) added to each NACK backoff. | +| `PB_NATS_CLIENT_RECONNECT_DELAY` | ACK timeout | Seconds to sleep before retrying after a transient transport error — see [Resilience](#resilience). | +| `PB_NATS_CLIENT_RECONNECT_DELAY_SPLAY_LIMIT` | `1000` | Random jitter (ms, `0..limit`) added to the reconnect delay so a fleet doesn't retry in lockstep. `0` disables. | +| `PB_NATS_RESPONSE_MUXER_DISPATCHERS` | CPUs on JRuby, `1` on CRuby | Threads draining the shared response subscription (min 1). | +| `PB_NATS_RESPONSE_MUXER_QUEUE_SIZE` | `1024` | Message-count cap for the shared response subscription. Dispatchers drain it to ~0, so this is burst headroom, not a working set: each in-flight request holds only ~2 messages (ACK + response). Beyond it nats-pure drops (`SlowConsumer`) and the RPC retries, rather than buffering unbounded response objects on the heap. Set it to your app's request-thread-pool size if that exceeds the default (min 1). | +| `PB_NATS_RESPONSE_MUXER_QUEUE_BYTES` | `67108864` (64 MiB) | Byte cap for the shared response subscription — the true heap ceiling. The count cap alone says nothing about size (1024 large payloads can still be gigabytes), so the firehose is bounded by whichever trips first: `PB_NATS_RESPONSE_MUXER_QUEUE_SIZE` messages or this many bytes. Matches the NATS ecosystem's per-subscription byte default (nats-pure / nats.go both use 64 MiB). Raise it if you have large payloads and heap to spare; lower it to tighten the ceiling (min 1). | + +#### Server + +| Variable | Default | Description | +| --- | --- | --- | +| `PB_NATS_SERVER_MAX_QUEUE_SIZE` | thread count | Queue in front of the handler thread pool; requests beyond it are NACKed. | +| `PB_NATS_SERVER_SUBSCRIPTION_HANDLERS` | CPUs on JRuby, `1` on CRuby | Threads draining the shared intake queue and publishing ACK/NACKs (min 1). Consumer parallelism only — does not change queue-group delivery. | +| `PB_NATS_SERVER_INTAKE_QUEUE_SIZE` | `65536` | Message-count capacity of the shared intake queue. Smaller turns overload into prompt drops-and-retries instead of a deep stale backlog; tune down alongside `PB_NATS_SERVER_STALE_REQUEST_MS`. | +| `PB_NATS_SERVER_INTAKE_QUEUE_BYTES` | `134217728` (128 MiB) | Byte capacity of the shared intake queue — the aggregate-heap bound the count alone can't give (65,536 large requests is a lot of heap). A request that would exceed it is dropped (the client retries), never buffered. Bounds bytes across all subscriptions; higher than the client muxer's 64 MiB since the server's count cap is higher too (min 1). | +| `PB_NATS_SERVER_SUBSCRIPTIONS_PER_RPC_ENDPOINT` | `10` | Subscriptions created per endpoint (lets JVM servers warm up gradually). Queue groups still deliver each request to exactly one consumer. | +| `PB_NATS_SERVER_SLOW_START_DELAY` | `10` | Seconds between slow-start subscription rounds. | +| `PB_NATS_SERVER_PAUSE_FILE_PATH` | `nil` | While this file exists the server unsubscribes from all services; it resubscribes (with slow start) when the file is removed. | +| `PB_NATS_SERVER_SLOW_HANDLER_THRESHOLD_MS` | `0` (off) | Emit `server.slow_handler` when a handler runs longer than this. Informational only. | +| `PB_NATS_SERVER_HANDLER_OVERDUE_MS` | `65000` | Age at which a still-running handler is reported overdue (its client has already given up). Keep ≈ your clients' response timeout plus a small grace. | +| `PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS` | `false` | `"true"` reclaims an overdue handler's pool slot by aborting it — see note below. | +| `PB_NATS_SERVER_STALE_REQUEST_MS` | `0` (off) | Drop requests older than this at intake (the client has already retried or given up) — see note below. | +| `PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT` | overdue ms / 1000 + 5 | Seconds to let in-flight handlers finish during shutdown before abandoning them. | + +#### Shared + +| Variable | Default | Description | +| --- | --- | --- | +| `PB_NATS_CONNECTION_NAME` | hostname | Connection name shown in NATS server monitoring. Precedence: env var > yaml `connection_name` > hostname. | +| `PROTOBUF_NATS_CONFIG_PATH` | `config/protobuf_nats.yml` | Path to the yaml config. | + +**Overdue handlers are never aborted by default** — killing a thread mid-handler can corrupt state. Enable +`PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS` only when orphaned work (whose clients already gave up) is saturating the +pool and healthy traffic is being NACKed. + +**Stale-request shedding trusts client clocks.** The request age comes from the UUIDv7 reply token, which encodes the +*client's* wall-clock time — enable only with sane NTP across hosts, and keep the threshold comfortably above the +client ACK timeout. Requests without a UUIDv7 token (foreign clients) are never shed. + +### YAML config + +Connection-level settings live in a yaml file, keyed by environment (`RAILS_ENV` / `RACK_ENV` / `APP_ENV`, default +`development`). The default path is `config/protobuf_nats.yml`; override with `PROTOBUF_NATS_CONFIG_PATH`. + +```yaml +# config/protobuf_nats.yml +--- + production: + servers: + - "nats://127.0.0.1:4222" + - "nats://127.0.0.1:4223" + - "nats://127.0.0.1:4224" + max_reconnect_attempts: 500 # -1 reconnects forever + reconnect_time_wait: 2 # seconds between reconnect attempts (nats-pure default: 2) + ping_interval: 120 # seconds between health-check PINGs (nats-pure default: 120) + max_outstanding_pings: 2 # missed PINGs before the connection is declared dead (nats-pure default: 2) + connection_name: "my-service" + connect_timeout: 2 + uses_tls: true + tls_client_cert: "/path/to/client-cert.pem" + tls_client_key: "/path/to/client-key.pem" + tls_ca_cert: "/path/to/ca.pem" + server_subscription_key_only_subscribe_to_when_includes_any_of: + - "search" + - "create" + server_subscription_key_do_not_subscribe_to_when_includes_any_of: + - "old_search" + - "old_create" + subscription_key_replacements: + - "original_service": "replacement_service" +``` + +`subscription_key_replacements` is useful for local testing but subject to breaking changes. -`protobuf-nats` uses a single NATS client implementation (`NATS::IO::Client` from `nats-pure`) on both CRuby and JRuby. +### TLS -- **ResponseMuxer** (`lib/protobuf/nats/response_muxer.rb`) — the client uses a single wildcard subscription to multiplex - all RPC responses (similar to the Golang NATS client) instead of subscribing/unsubscribing per request. One or more - dispatcher threads drain the shared subscription and route each reply to the waiting caller via a `Concurrent::Map`, - keyed by a UUIDv7 request token. Tune the dispatcher count with `PB_NATS_RESPONSE_MUXER_DISPATCHERS`. -- **SuperSubscriptionManager** (`lib/protobuf/nats/super_subscription_manager.rb`) — the server manages the lifecycle of - RPC endpoint subscriptions, including slow start, pausing, and resubscription. +With `uses_tls`, the client negotiates TLS 1.2–1.3 and **verifies the NATS server's certificate chain** +(`VERIFY_PEER`): certificates must chain to `tls_ca_cert` when set, or to the system trust store otherwise. If you are +upgrading from a release that did not verify (`< 0.13.1`), make sure `tls_ca_cert` points at the CA that signed your +NATS server certificate, or the connection will be rejected. Hostname (SAN/CN) verification is not yet enabled. + +## How it works + +`protobuf-nats` uses `nats-pure`'s `NATS::IO::Client` on both CRuby and JRuby. + +- **ResponseMuxer** (client) — one wildcard subscription multiplexes all RPC responses instead of subscribing per + request. Dispatcher threads route each reply to its waiting caller by UUIDv7 token, lock-free on the hot path, and + self-heal with decaying exponential backoff if they crash. +- **SuperSubscriptionManager** (server) — manages the endpoint subscriptions (NATS queue groups: one consumer per + request) including slow start and pause/resume. All subscriptions feed one shared intake queue drained by handler + threads, so a slow ACK publish can't head-of-line block other subjects. Handlers self-heal like the muxer. +- **Observability** — thread-pool gauges plus in-flight handler metrics (`server.inflight_count`, + `server.inflight_oldest_age_ms`, `server.overdue_handler_count`, `server.pending_intake_queue_size`, + `server.pending_intake_queue_bytes`, `server.thread_pool_saturated`). A request dropped because it would exceed the + intake byte ceiling emits `server.intake_bytes_dropped` (see `PB_NATS_SERVER_INTAKE_QUEUE_BYTES`). The client muxer + gauges its response firehose (`response_muxer.pending_queue_size` and, so a burst between the ~60s samples isn't + missed, `response_muxer.pending_queue_peak`), plus `response_muxer.stale_tokens_cleaned`, `client.unexpected_message`, + and `client.invalid_message`. Error callbacks run on a bounded background executor; drops are counted + (`Protobuf::Nats.error_callback_drop_count`) and emit `error_callback_dropped`. + +## Resilience + +The client rides out transient NATS hiccups rather than surfacing them as request failures: + +- **Transient transport errors are retried** (`Errors::RETRYABLE_TRANSPORT_ERRORS`): the client sleeps + `PB_NATS_CLIENT_RECONNECT_DELAY` (plus jitter) and retries up to `PB_NATS_CLIENT_MAX_RETRIES`, rebuilding a + terminally closed connection — and moving the muxer's subscription onto it — before each retry. +- **A failing NATS node fails over automatically.** `nats-pure` reconnects through the whole `servers` pool and replays + all subscriptions on the new node. A node that dies *silently* (no FIN/RST) is only detected by the PING health + check — up to `ping_interval * max_outstanding_pings` (240s at defaults); lower those yaml keys for faster failover. +- **Missing ACKs and NACKs are retried** with their own timeouts/backoff. Every retry re-sends the request — see + [Delivery semantics](#delivery-semantics-at-least-once). +- **Server-side failures fail the caller fast.** A failed handler publishes a generic RPC error response (details stay + in server logs) so the client raises immediately instead of waiting out its response timeout. +- **The server exits rather than running deaf.** If its connection is terminally closed (reconnects exhausted), the run + loop stops — emitting `server.connection_closed` — so a supervisor restarts the process. Use + `max_reconnect_attempts: -1` to prefer in-process reconnects forever. + +## Delivery semantics (at-least-once) + +RPC delivery is **at-least-once** and the gem does **not** deduplicate: a client retry can re-send a request the server +already processed, so a single call can run a handler more than once. This is deliberate — dropping work on a transient +blip is usually worse than occasionally repeating it. + +Making that safe is the service author's responsibility: key writes on a natural id or idempotency token +(upsert / `find_or_create`), and make external side effects (charges, emails, downstream RPCs) safe to repeat or guard +them with your own dedup. An opt-in per-RPC dedup with a pluggable store may be added later; it will not be the default. + +## Future improvements -## Future Improvements (locked behind ruby version) - Migrate from the `uuid7` gem to native `Random#uuid_v7` once the minimum Ruby version supports it (see `UUIDv7Helper`). -## Development +## Benchmarks + +Microbenchmarks live in `bench/` and need no NATS server; see `bench/bench.md`. Highlights on JRuby: muxer dispatch +~2.5× faster with the per-message lock removed (`bench/muxer_resilience_bench.rb`), server intake fan-out ~8× +throughput with head-of-line stalls ~505ms → ~2ms (`bench/server_intake_bench.rb`). -After checking out the repo, run `bin/setup` to install dependencies. Then, run `rake test` to run the tests. You can also run `bin/console` for an interactive prompt that will allow you to experiment. +``` +bundle exec ruby -Ilib bench/server_intake_bench.rb +bundle exec ruby -Ilib bench/muxer_resilience_bench.rb +``` -To install this gem onto your local machine, run `bundle exec rake install`. To release a new version, update the version number in `version.rb`, and then run `bundle exec rake release`, which will create a git tag for the version, push git commits and tags, and push the `.gem` file to [rubygems.org](https://rubygems.org). +## Development +After checking out the repo, run `bin/setup` to install dependencies. Then, run `rake test` to run the tests. You can +also run `bin/console` for an interactive prompt that will allow you to experiment. + +To install this gem onto your local machine, run `bundle exec rake install`. To release a new version, update the +version number in `version.rb`, and then run `bundle exec rake release`, which will create a git tag for the version, +push git commits and tags, and push the `.gem` file to [rubygems.org](https://rubygems.org). ## Contributing Bug reports and pull requests are welcome on GitHub at https://github.com/mxenabled/protobuf-nats. - ## License The gem is available as open source under the terms of the [MIT License](http://opensource.org/licenses/MIT). diff --git a/bench/bench.md b/bench/bench.md index 09ce783..1aae1f6 100644 --- a/bench/bench.md +++ b/bench/bench.md @@ -1,16 +1,96 @@ +## Benchmarks -Notes: -`-Xjit.threshold=0` - Setting the threshold to 0 forces JRuby to compile every method into Java bytecode immediately before its very first execution. This is particularly useful for debugging or bypassing warm-up times during profiling +- `bench/concurrency_bench.rb` — end-to-end hot-path throughput (muxer round-trip, + subscription-key cache, thread pool) across thread counts. No NATS server needed. +- `bench/muxer_resilience_bench.rb` — measures the response-muxer hot-path and + self-healing fixes (both old/baseline and new/patched behavior in one process): + - **A. Dispatch hot-path** — per-message `pending_size` accounting that was + removed; the dispatch step is ~**2.7× faster** per message on JRuby once the + per-message subscription lock is gone. + - **B. nil-`@resp_sub` resilience** — during a restart window the old loop + busy-spun (a `NoMethodError` + logged error/callback every iteration); the new + loop parks, doing **~0.2%** of the old wasted work and emitting **0** errors. + - **C. Self-healing crash counter** — a plain Integer mutated by N dispatcher + threads loses ~**45%** of updates on JRuby (corrupting the exponential backoff); + the `Concurrent::AtomicFixnum` replacement loses none. + Run: `bundle exec ruby -Ilib bench/muxer_resilience_bench.rb` +- `bench/server_intake_bench.rb` — server intake fan-out + handler observability + (old single-handler vs new N-handler intake, in one process): + - **A. Intake throughput** — with a per-ACK publish cost, N drain threads scale + intake ~linearly (measured **~8.5×** at 8 handlers on JRuby vs the old single + intake thread). + - **B. Head-of-line blocking** — behind one slow (0.5s) publish, 50 quick + messages finished in **~505ms** with one handler vs **~0.4ms** with N. + - **C. Observability demo** — with hung handlers the new notifications report + `inflight_count` / `inflight_oldest_age_ms` / `overdue_handler_count` and fire + `server.handler_overdue`, where before only `server.message_dropped` was visible. -`-Xjit.threshold=10 -J-XX:CompileThreshold=10` - If you are running benchmarks and want both JRuby and the JVM to aggressively optimize early, you can lower both thresholds simultaneously + Run: `bundle exec ruby -Ilib bench/server_intake_bench.rb` +- `bench/soak.rb` — opt-in soak/chaos test: spawns its own `nats-server`, runs a + real protobuf-nats server + client in-process under sustained concurrency + (including deliberately long handlers), bounces the nats-server mid-run, and + asserts recovery (≥90% success) while reporting the resilience signals. Skips + if `nats-server` isn't on PATH. -`bundle; bx ruby -I lib bench/real_client.rb` + Run: `SOAK_DURATION=20 SOAK_BOUNCES=3 bundle exec ruby -Ilib bench/soak.rb` -Start local nats server so details can be monitored. -`/opt/homebrew/opt/nats-server/bin/nats-server -DV -m 8222 -p 4222` +--- +## Running benchmarks (warm + reliable) + +These numbers are meaningless cold. On JRuby the JVM has to load classes and JIT-compile the hot paths before it reaches steady state, so the first second(s) of any run are far slower than production. Always warm up, repeat, and compare like-for-like. + +### 1. Use the production engine + +Run on JRuby (what production uses); CRuby numbers differ because the GVL serializes the parallelism these benches exercise. + +``` +rbenv shell jruby-9.4.14.0 # or your deployed JRuby +ruby -v # confirm engine before trusting any number +``` + +### 2. Benchmarking JRUBY_OPTS + +Fix the heap so GC resizing doesn't jitter the run, give the young gen room, and don't block on entropy: + +``` +export JRUBY_OPTS="-J-Xms4g -J-Xmx4g -J-Xmn1g --disable:did_you_mean -J-Djava.security.egd=file:/dev/./urandom" +``` + +- Set `-Xms == -Xmx` so the heap never resizes mid-measurement. +- Do **not** use `--dev` for benchmarking — it disables the JIT for fast startup and will understate performance. +- Optional faster warmup (compile sooner): add `-Xjit.threshold=10 -J-XX:CompileThreshold=10`. `-Xjit.threshold=0` forces immediate compilation — useful for profiling, but prefer real warmup for representative steady-state numbers. + +### 3. Warm up, then measure + +- `muxer_resilience_bench.rb` section A uses **benchmark-ips**, which warms up on its own (warmup then a timed window) — no extra flags needed. +- The loop-driven benches (`concurrency_bench.rb`, and the throughput sections of `server_intake_bench.rb`) measure a fixed window. Give them a real warmup and a longer window: + +``` +BENCH_WARMUP=5 BENCH_DURATION=10 BENCH_THREADS=1,4,8,16 bundle exec ruby -Ilib bench/concurrency_bench.rb +``` + +### 4. Repeat and take the median + +JVM warmup and machine noise make any single run unreliable. Run each bench **3+ times**, discard the first (cold class-load/JIT), and report the **median**. Keep the machine quiet (close other apps, disable CPU throttling / keep laptops on AC) and run one bench at a time. + +### Per-script tuning knobs + +| Script | Env knobs (defaults) | +| --- | --- | +| `concurrency_bench.rb` | `BENCH_DURATION` (4), `BENCH_WARMUP` (2), `BENCH_THREADS` (`1,4,8,16`), `BENCH_POOL_WORKERS` (8) | +| `muxer_resilience_bench.rb` | none — benchmark-ips controls warmup/time | +| `server_intake_bench.rb` | `BENCH_HANDLERS` (cores), `BENCH_MSGS` (20000), `BENCH_PUBLISH_LATENCY_US` (50) | +| `soak.rb` | `SOAK_DURATION` (15), `SOAK_THREADS` (12), `SOAK_BOUNCES` (2), `SOAK_NATS_PORT` (4299) | + +### Real end-to-end run (optional, needs a NATS server) + +`bench/real_client.rb` drives the example app against a live server. Start a local nats-server (with monitoring) first: ``` -export JRUBY_OPTS="--disable:did_you_mean -J-Djava.security.egd=file:/dev/./urandom -J-Xmx2g -J-Xms1024m -J-Xmn512m -Xjit.threshold=10 -J-XX:CompileThreshold=10" +nats-server -DV -m 8222 -p 4222 # or: /opt/homebrew/opt/nats-server/bin/nats-server ... +bundle exec ruby -Ilib bench/real_client.rb ``` + +`bench/soak.rb` spawns and bounces its own throwaway nats-server, so it needs only the `nats-server` binary on PATH (it self-skips otherwise). diff --git a/bench/muxer_resilience_bench.rb b/bench/muxer_resilience_bench.rb new file mode 100644 index 0000000..66ef735 --- /dev/null +++ b/bench/muxer_resilience_bench.rb @@ -0,0 +1,151 @@ +# Benchmarks for the response-muxer hot-path and self-healing changes. +# +# This file measures BOTH the old (baseline) and new (patched) behavior in one +# process so the speedup/robustness delta is reproducible on CRuby and JRuby +# without a NATS server: +# +# A. Dispatch hot-path cost -- per-message pending_size accounting that was +# removed (#1). benchmark-ips, lower is better. +# B. nil-@resp_sub resilience -- busy-spin vs park during a restart window (#3). +# C. Self-healing counter -- lost updates with a plain int vs AtomicFixnum +# under concurrent crashes (#4). +# +# Usage: +# bundle exec ruby -Ilib bench/muxer_resilience_bench.rb + +require "bundler/setup" +require "benchmark/ips" +require "concurrent" +require "nats/client" # real NATS::Subscription / NATS::Msg + +def mono + ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) +end + +puts "=" * 72 +puts "protobuf-nats response-muxer resilience bench" +puts "engine=#{RUBY_ENGINE} #{RUBY_VERSION} processor_count=#{::Concurrent.processor_count}" +puts "=" * 72 + +# -------------------------------------------------------------------------- +# A. Dispatch hot-path: per-message pending_size accounting (removed in #1). +# +# Old dispatch did `sub.synchronize { sub.pending_size -= msg.data.size }` for +# EVERY response message; the new code does nothing here. We compare the old +# accounting step against the cheapest real per-message op (a Concurrent::Map +# lookup, which the dispatcher still does) so the delta is the lock overhead we +# removed from the hot path. +# -------------------------------------------------------------------------- +puts "\nA. Dispatch hot-path per-message overhead (higher ips = better)\n\n" + +sub = ::NATS::Subscription.new +sub.pending_size = 0 +resp_map = ::Concurrent::Map.new +resp_map["tok"] = { :queue => ::Queue.new } +size = 64 + +Benchmark.ips do |x| + x.config(:time => 3, :warmup => 1) + + x.report("old: synchronize { pending_size -= n } + map lookup") do + sub.synchronize { sub.pending_size -= size } + resp_map["tok"] + end + + x.report("new: map lookup only (accounting removed)") do + resp_map["tok"] + end + + x.compare! +end + +# -------------------------------------------------------------------------- +# B. nil-@resp_sub resilience (#3). During a restart @resp_sub can briefly be +# nil. The old loop dereferenced it unconditionally (NoMethodError every +# iteration -> busy-spin + a logged error/callback per spin); the new loop +# parks. We run each for a fixed window and count iterations and "errors that +# would be logged/dispatched to callbacks". +# -------------------------------------------------------------------------- +puts "\nB. Behavior while @resp_sub is nil for #{(WINDOW = 0.5)}s (lower spin = better)\n\n" + +def run_old_loop(window) + resp_sub = nil # the restart window + iters = 0 + errors = 0 + deadline = mono + window + while mono < deadline + begin + resp_sub.pending_queue.pop # NoMethodError on nil + rescue => _e + errors += 1 # old code logs + notify_error_callbacks here + end + iters += 1 + end + [iters, errors] +end + +def run_new_loop(window) + resp_sub = nil + iters = 0 + errors = 0 + deadline = mono + window + while mono < deadline + s = resp_sub + if s.nil? + sleep 0.01 # park instead of spinning + iters += 1 + next + end + begin + s.pending_queue.pop + rescue => _e + errors += 1 + end + iters += 1 + end + [iters, errors] +end + +old_iters, old_errs = run_old_loop(WINDOW) +new_iters, new_errs = run_new_loop(WINDOW) + +printf(" old loop: %12d iterations, %12d errors logged/dispatched\n", old_iters, old_errs) +printf(" new loop: %12d iterations, %12d errors logged/dispatched\n", new_iters, new_errs) +printf(" => new loop does %.5f%% of the old loop's wasted work\n", + old_iters.zero? ? 0.0 : (new_iters.to_f / old_iters * 100)) + +# -------------------------------------------------------------------------- +# C. Self-healing crash counter (#4). The old counter was a plain Integer +# mutated by multiple dispatcher threads (`@crash_count = (@crash_count||0)+1`), +# which loses updates under true parallelism, corrupting the exponential +# backoff. The new counter is a Concurrent::AtomicFixnum. We have N threads each +# "crash" K times and check the final count. +# -------------------------------------------------------------------------- +puts "\nC. Crash-counter accuracy under concurrent crashes (expected == actual is correct)\n\n" + +def hammer(counter, threads, per_thread) + ts = threads.times.map do + ::Thread.new do + per_thread.times { counter.call } + end + end + ts.each(&:join) +end + +threads = [::Concurrent.processor_count, 4].max +per_thread = 50_000 +expected = threads * per_thread + +# Old: plain integer read-modify-write (racy). +plain = 0 +hammer(->{ plain = plain + 1 }, threads, per_thread) + +# New: atomic increment. +atomic = ::Concurrent::AtomicFixnum.new(0) +hammer(->{ atomic.increment }, threads, per_thread) + +printf(" threads=%d per_thread=%d expected=%d\n", threads, per_thread, expected) +printf(" old plain Integer: %10d (lost %d updates)\n", plain, expected - plain) +printf(" new AtomicFixnum: %10d (lost %d updates)\n", atomic.value, expected - atomic.value) + +puts "\ndone." diff --git a/bench/server_intake_bench.rb b/bench/server_intake_bench.rb new file mode 100644 index 0000000..e3c6b2d --- /dev/null +++ b/bench/server_intake_bench.rb @@ -0,0 +1,158 @@ +# Benchmarks for the server intake fan-out (#1) and handler observability (#2). +# +# Models old (1 intake handler) vs new (N intake handlers) in one process, plus +# a demonstration of the #2 in-flight observability. No NATS server required. +# +# A. Intake throughput -- acks/sec with 1 vs N drain threads when each ACK +# publish has some latency (the real bottleneck). +# B. Head-of-line blocking -- how long other subjects stall behind one slow +# publish with 1 vs N handlers. +# C. Observability demo -- with hung handlers, the new server notifications +# surface the saturation/overdue work that was +# previously invisible (only message_dropped). +# +# Usage: +# bundle exec ruby -Ilib bench/server_intake_bench.rb + +require "bundler/setup" +require "concurrent" +require "nats/client" # real NATS::Subscription / NATS::Msg +require "protobuf/nats" + +::Protobuf::Logging.logger = ::Logger.new(nil) + +def mono + ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) +end + +HANDLERS = Integer(ENV.fetch("BENCH_HANDLERS", [::Concurrent.processor_count, 4].max.to_s)) +MSGS = Integer(ENV.fetch("BENCH_MSGS", "20000")) +PUBLISH_LAT_US = Integer(ENV.fetch("BENCH_PUBLISH_LATENCY_US", "50")) # per-ACK publish latency + +puts "=" * 72 +puts "protobuf-nats server intake bench" +puts "engine=#{RUBY_ENGINE} #{RUBY_VERSION} processor_count=#{::Concurrent.processor_count}" +puts "handlers(new)=#{HANDLERS} msgs=#{MSGS} publish_latency=#{PUBLISH_LAT_US}us" +puts "=" * 72 + +# -------------------------------------------------------------------------- +# Shared intake model: a SizedQueue fed with `total` messages, drained by +# `handlers` threads. Each message does light work + an ACK "publish" that +# costs `publish_latency` seconds (the part that serializes on one thread today). +# -------------------------------------------------------------------------- +def drain(handlers, total, publish_latency) + queue = ::SizedQueue.new(total + handlers) + total.times { queue.push(:msg) } + handlers.times { queue.push(:stop) } + processed = ::Concurrent::AtomicFixnum.new(0) + + t0 = mono + threads = handlers.times.map do + ::Thread.new do + loop do + m = queue.pop + break if m == :stop + sleep(publish_latency) if publish_latency.positive? + processed.increment + end + end + end + threads.each(&:join) + elapsed = mono - t0 + { per_sec: processed.value / elapsed, elapsed: elapsed } +end + +puts "\nA. Intake throughput (acks/sec; higher is better)\n\n" +lat = PUBLISH_LAT_US / 1_000_000.0 +old = drain(1, MSGS, lat) +new = drain(HANDLERS, MSGS, lat) +printf(" old (1 handler): %12.0f acks/s (%.2fs)\n", old[:per_sec], old[:elapsed]) +printf(" new (%d handlers): %12.0f acks/s (%.2fs)\n", HANDLERS, new[:per_sec], new[:elapsed]) +printf(" => %.2fx faster intake\n", new[:per_sec] / old[:per_sec]) + +# -------------------------------------------------------------------------- +# B. Head-of-line blocking: one slow publish is enqueued first, followed by +# `fast_count` quick messages. Measure how long until all the quick messages +# finish. With one handler they wait behind the slow publish; with N they don't. +# -------------------------------------------------------------------------- +def head_of_line(handlers, slow_latency, fast_count) + queue = ::SizedQueue.new(fast_count + 1 + handlers) + queue.push(:slow) + fast_count.times { queue.push(:fast) } + handlers.times { queue.push(:stop) } + + fast_done = ::Concurrent::AtomicFixnum.new(0) + last_fast_at = ::Concurrent::AtomicReference.new(nil) + + start = mono + threads = handlers.times.map do + ::Thread.new do + loop do + m = queue.pop + break if m == :stop + if m == :slow + sleep slow_latency + else + last_fast_at.set(mono) if fast_done.increment == fast_count + end + end + end + end + threads.each(&:join) + (last_fast_at.get || mono) - start +end + +puts "\nB. Head-of-line blocking behind one slow (0.5s) publish (lower = better)\n\n" +slow = 0.5 +old_b = head_of_line(1, slow, 50) +new_b = head_of_line(HANDLERS, slow, 50) +printf(" old (1 handler): 50 quick messages finished after %6.1f ms (stuck behind the slow publish)\n", old_b * 1000) +printf(" new (%d handlers): 50 quick messages finished after %6.1f ms (unaffected)\n", HANDLERS, new_b * 1000) + +# -------------------------------------------------------------------------- +# C. #2 observability demo: hung handlers occupy the pool. Today operators only +# see `message_dropped`; now the in-flight gauges + overdue event explain why. +# -------------------------------------------------------------------------- +puts "\nC. Handler-exhaustion observability (what an operator now sees)\n\n" + +ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "1" +ENV["PB_NATS_SERVER_HANDLER_OVERDUE_MS"] = "100" + +class DemoNats + def connect(*); end + def new_inbox; "_INBOX.demo"; end + def subscribe(_s, *_a) + sub = ::NATS::Subscription.new + sub.pending_queue = ::SizedQueue.new(1024) + sub + end + def publish(*); end + def flush(*); end + %i[on_disconnect on_reconnect on_close on_error].each { |m| define_method(m) { |*| } } + def close; end +end + +server = ::Protobuf::Nats::Server.new(:threads => 4, :client => DemoNats.new, :server => "bench") +release = ::Queue.new +server.define_singleton_method(:handle_request) { |*_| release.pop; "" } + +gauges = {} +%w[inflight_count inflight_oldest_age_ms overdue_handler_count handler_overdue pending_intake_queue_size].each do |name| + ::ActiveSupport::Notifications.subscribe("server.#{name}.protobuf-nats") { |_, _, _, _, v| gauges[name] = v } +end + +4.times { |i| server.enqueue_request("req#{i}", "inbox#{i}") } # all 4 pool slots now hung +sleep 0.15 # exceed the 100ms overdue window +server.enqueue_request("req5", "inbox5") # pool full -> NACK + saturated +server.instrument_inflight_handlers + +printf(" inflight_count = %s (handlers stuck on the downstream)\n", gauges["inflight_count"]) +printf(" inflight_oldest_age_ms = %.0f\n", gauges["inflight_oldest_age_ms"] || 0) +printf(" overdue_handler_count = %s (client already gave up on these)\n", gauges["overdue_handler_count"]) +printf(" handler_overdue fired = %s\n", gauges.key?("handler_overdue")) +puts " (previously: only server.message_dropped, with no hint that handlers were stuck)" + +release << :go while !release.num_waiting.zero? +4.times { release << :go } + +puts "\ndone." diff --git a/bench/soak.rb b/bench/soak.rb new file mode 100644 index 0000000..8237b1e --- /dev/null +++ b/bench/soak.rb @@ -0,0 +1,146 @@ +# Soak / chaos test for protobuf-nats. +# +# Runs a real protobuf-nats server + client in one process against a real +# nats-server, drives sustained concurrent RPCs (including deliberately long +# handlers), and induces chaos by bouncing the nats-server mid-run. It then +# asserts the system recovers (the vast majority of requests still succeed) and +# prints the resilience signals it observed. +# +# This is an opt-in tool (like bench/real_client.rb), not part of the suite. It +# self-skips if `nats-server` isn't on PATH. +# +# Usage: +# bundle exec ruby -Ilib bench/soak.rb +# SOAK_DURATION=20 SOAK_THREADS=16 SOAK_BOUNCES=3 bundle exec ruby -Ilib bench/soak.rb + +require "bundler/setup" +require "fileutils" +require "socket" +require "securerandom" +require "yaml" +require "concurrent" + +unless system("which nats-server > /dev/null 2>&1") + puts "[soak] nats-server not found on PATH -- skipping. (brew install nats-server)" + exit 0 +end + +DURATION = Integer(ENV.fetch("SOAK_DURATION", "15")) +THREADS = Integer(ENV.fetch("SOAK_THREADS", "12")) +BOUNCES = Integer(ENV.fetch("SOAK_BOUNCES", "2")) +PORT = Integer(ENV.fetch("SOAK_NATS_PORT", "4299")) + +ENV["PB_CLIENT_TYPE"] = "protobuf/nats/client" +ENV["PB_SERVER_TYPE"] = "protobuf/nats/runner" +# Point the client/server at our throwaway nats-server. +config_path = ::File.expand_path("../tmp/soak_protobuf_nats.yml", __dir__) +::FileUtils.mkdir_p(::File.dirname(config_path)) +::File.write(config_path, { "development" => { "servers" => ["nats://127.0.0.1:#{PORT}"], "max_reconnect_attempts" => 60_000 } }.to_yaml) +ENV["PROTOBUF_NATS_CONFIG_PATH"] = config_path + +def mono; ::Process.clock_gettime(::Process::CLOCK_MONOTONIC); end + +def start_nats(port) + pid = ::Process.spawn("nats-server", "-p", port.to_s, [:out, :err] => "/dev/null") + # Wait for the port to accept connections. + deadline = mono + 10 + loop do + begin + ::TCPSocket.new("127.0.0.1", port).close + break + rescue + raise "nats-server did not start" if mono > deadline + sleep 0.05 + end + end + pid +end + +require "socket" +require "securerandom" +require "concurrent" + +nats_pid = start_nats(PORT) +puts "[soak] nats-server pid=#{nats_pid} on :#{PORT} duration=#{DURATION}s threads=#{THREADS} bounces=#{BOUNCES}" + +require "./examples/warehouse/app" +::Protobuf::Logging.logger = ::Logger.new(nil) + +# --- Observe the resilience signals --- +counters = ::Concurrent::Map.new +%w[client.request_timeout client.request_nack server.message_dropped + server.handler_overdue server.thread_pool_saturated].each do |evt| + counters[evt] = ::Concurrent::AtomicFixnum.new(0) + ::ActiveSupport::Notifications.subscribe("#{evt}.protobuf-nats") { counters[evt].increment } +end +# --- Start the server in a background thread --- +server = ::Protobuf::Nats::Server.new(:threads => 10) +server_thread = ::Thread.new { server.run } +sleep 1 # let it subscribe / slow-start a round + +# --- Drive load --- +ok = ::Concurrent::AtomicFixnum.new(0) +err = ::Concurrent::AtomicFixnum.new(0) +stop = ::Concurrent::AtomicBoolean.new(false) + +workers = THREADS.times.map do + ::Thread.new do + until stop.true? + begin + # Mostly fast; ~10% deliberately long handlers (allowed, not aborted). + sleep_ms = (rand(10).zero? ? 300 : 0) + req = ::Warehouse::Shipment.new(:guid => ::SecureRandom.uuid, :sleep_time_ms => sleep_ms) + ::Warehouse::ShipmentService.client.create(req) + ok.increment + rescue => _e + err.increment + end + end + end +end + +# --- Chaos: bounce nats-server a few times during the run --- +chaos = ::Thread.new do + interval = DURATION.to_f / (BOUNCES + 1) + BOUNCES.times do |i| + sleep interval + puts "[soak] chaos bounce #{i + 1}/#{BOUNCES}: killing nats-server" + ::Process.kill("KILL", nats_pid) rescue nil + ::Process.wait(nats_pid) rescue nil + sleep 0.5 + nats_pid = start_nats(PORT) + puts "[soak] nats-server restarted pid=#{nats_pid}" + end +end + +sleep DURATION +stop.make_true +workers.each(&:join) +chaos.join + +server.stop +server_thread.join(15) + +total = ok.value + err.value +rate = total.zero? ? 0.0 : (ok.value.to_f / total * 100) + +puts +puts "================ soak results ================" +puts "duration=#{DURATION}s threads=#{THREADS} nats bounces=#{BOUNCES}" +printf "requests: %d ok, %d failed (%.2f%% success)\n", ok.value, err.value, rate +puts "observed signals:" +counters.each_pair { |evt, c| printf(" %-32s %d\n", evt, c.value) } +puts "==============================================" + +# After chaos settles, the system should recover: most requests succeed. +if rate >= 90.0 + puts "[soak] PASS (recovered through #{BOUNCES} nats bounces)" + status = 0 +else + puts "[soak] FAIL (success rate #{rate.round(2)}% < 90%)" + status = 1 +end + +::Process.kill("KILL", nats_pid) rescue nil +::Process.wait(nats_pid) rescue nil +exit status diff --git a/lib/protobuf/nats.rb b/lib/protobuf/nats.rb index 3199c90..a2a5bc8 100644 --- a/lib/protobuf/nats.rb +++ b/lib/protobuf/nats.rb @@ -5,6 +5,7 @@ require "protobuf/rpc/service_directory" require "nats/io/client" +require "concurrent" @@ -58,6 +59,14 @@ 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") { ... }`. + def self.instrument(event, payload = {}, &block) + ::ActiveSupport::Notifications.instrument("#{event}.protobuf-nats", payload, &block) + end + def self.notify_error_callbacks(error) error_callbacks.each do |callback| begin @@ -70,6 +79,46 @@ 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). + ERROR_CALLBACK_EXECUTOR = ::Concurrent::ThreadPoolExecutor.new( + :min_threads => 0, + :max_threads => 1, + :max_queue => 1024, + :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. + ERROR_CALLBACK_DROP_COUNT = ::Concurrent::AtomicFixnum.new(0) + + def self.error_callback_drop_count + ERROR_CALLBACK_DROP_COUNT.value + 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. + 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). + def self.record_dropped_error_callback + ERROR_CALLBACK_DROP_COUNT.increment + instrument("error_callback_dropped", 1) + nil + end + def self.subscription_key(service_klass, service_method) service_class_name = service_klass.name.underscore.gsub("/", ".") service_method_name = service_method.to_s.underscore @@ -84,15 +133,16 @@ def self.start_client_nats_connection GET_CONNECTED_MUTEX.synchronize do break true if @client_nats_connection - # Disable publisher pending buffer on reconnect - options = config.connection_options.merge(:disable_reconnect_buffer => true) + # 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. + options = config.connection_options client = NatsClient.new - client.connect(options) - - # Ensure we have a valid connection to the NATS server. - client.flush(5) + # Register lifecycle callbacks BEFORE connecting so a disconnect or + # error during the initial handshake is still observed. client.on_disconnect do logger.warn("Client NATS connection was disconnected") end @@ -103,10 +153,30 @@ 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. + @client_nats_connection = nil end client.on_error do |error| - notify_error_callbacks(error) + # Runs on nats-pure's read/flush thread -- offload so a slow callback + # can't stall message processing. + notify_error_callbacks_async(error) + end + + begin + client.connect(options) + # Ensure we have a valid connection to the NATS server. + 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). + client.close rescue nil + raise e end @client_nats_connection = client @@ -115,6 +185,78 @@ 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. + 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. + def self.env_int(name, default, min: nil) + raw = ::ENV[name] + return default if raw.nil? + + value = Integer(raw, 10) + if min && value < min + logger.error "Ignoring out-of-range ENV #{name}=#{raw.inspect} (minimum #{min}); using default #{default}" + return default + end + value + rescue ::ArgumentError, ::TypeError + logger.error "Ignoring malformed integer in ENV #{name}=#{raw.inspect}; using default #{default}" + default + end + + # Float sibling of env_int, same strict-parse-or-default contract. + def self.env_float(name, default) + raw = ::ENV[name] + return default if raw.nil? + Float(raw) + rescue ::ArgumentError, ::TypeError + logger.error "Ignoring malformed number in ENV #{name}=#{raw.inspect}; using default #{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). + 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. + 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. + # + # 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. + 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. + def self.crash_backoff_seconds(crash_count, cap = 60) + [(crash_count**2), cap].min + end + def self.log_error(error) logger.error error.to_s logger.error error.class.to_s diff --git a/lib/protobuf/nats/byte_bounded_queue.rb b/lib/protobuf/nats/byte_bounded_queue.rb new file mode 100644 index 0000000..64ac924 --- /dev/null +++ b/lib/protobuf/nats/byte_bounded_queue.rb @@ -0,0 +1,72 @@ +require "concurrent" + +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. + # + # 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 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. + class ByteBoundedQueue < ::SizedQueue + def initialize(max_msgs, max_bytes, on_drop: nil) + super(max_msgs) + @max_bytes = max_bytes + @on_drop = on_drop + @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, before + # any bytes are counted. + 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) + self + end + alias_method :<<, :push + + def pop(non_block = false) + obj = super + # nil == closed/empty non_block; nothing dequeued, nothing to subtract. + @bytes.update { |value| [value - byte_size(obj), 0].max } if obj + obj + end + + def clear + super + @bytes.value = 0 + end + + # Current resident byte total (gauge for observability). + 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. + def byte_size(obj) + obj.respond_to?(:data) && obj.data ? obj.data.bytesize : 0 + end + end + end +end diff --git a/lib/protobuf/nats/client.rb b/lib/protobuf/nats/client.rb index a4fb640..53a4dd1 100644 --- a/lib/protobuf/nats/client.rb +++ b/lib/protobuf/nats/client.rb @@ -1,5 +1,4 @@ require 'securerandom' -require "connection_pool" require "concurrent" require "protobuf/nats" require "protobuf/rpc/connectors/base" @@ -22,15 +21,6 @@ class Client < ::Protobuf::Rpc::Connectors::Base CONCURRENT_SUBSCRIPTION_CACHE = (::RUBY_ENGINE == "jruby") @subscription_key_cache = CONCURRENT_SUBSCRIPTION_CACHE ? ::Concurrent::Map.new : {} - @subscription_pool_lock = ::Mutex.new - - # Structure to hold subscription and inbox to use within pool - SubscriptionInbox = ::Struct.new(:subscription, :inbox) do - def swap(sub_inbox) - self.subscription = sub_inbox.subscription - self.inbox = sub_inbox.inbox - end - end def logger ::Protobuf::Logging.logger @@ -40,29 +30,6 @@ def response_muxer RESPONSE_MUXER end - def self.subscription_pool - return @subscription_pool if @subscription_pool - - @subscription_pool_lock.synchronize do - # The double-check ensures we don't create a new pool if another - # thread created one while we were waiting for the lock. - return @subscription_pool if @subscription_pool - - @subscription_pool = ::ConnectionPool.new(:size => subscription_pool_size, :timeout => 0.1) do - inbox = ::Protobuf::Nats.client_nats_connection.new_inbox - SubscriptionInbox.new(::Protobuf::Nats.client_nats_connection.subscribe(inbox), inbox) - end - end - end - - def self.subscription_pool_size - @subscription_pool_size ||= if ::ENV.key?("PB_NATS_CLIENT_SUBSCRIPTION_POOL_SIZE") - ::ENV["PB_NATS_CLIENT_SUBSCRIPTION_POOL_SIZE"].to_i - else - 0 - end - end - def initialize(options) # may need to override to setup connection at this stage ... may also do on load of class super @@ -74,32 +41,6 @@ def initialize(options) RESPONSE_MUXER.start end - def new_subscription_inbox - nats = ::Protobuf::Nats.client_nats_connection - inbox = nats.new_inbox - sub = if use_subscription_pooling? - nats.subscribe(inbox) - else - nats.subscribe(inbox, :max => 2) - end - - SubscriptionInbox.new(sub, inbox) - end - - def with_subscription - return_value = nil - - if use_subscription_pooling? - self.class.subscription_pool.with do |sub_inbox| - return_value = yield sub_inbox - end - else - return_value = yield new_subscription_inbox - end - - return_value - end - def close_connection # no-op (I think for now), the connection to server is persistent end @@ -109,18 +50,26 @@ def self.subscription_key_cache end def ack_timeout - @ack_timeout ||= if ::ENV.key?("PB_NATS_CLIENT_ACK_TIMEOUT") - ::ENV["PB_NATS_CLIENT_ACK_TIMEOUT"].to_i - else - 5 - end + @ack_timeout ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_ACK_TIMEOUT", 5) end + DEFAULT_NACK_BACKOFF_INTERVALS = [0, 1, 3, 5, 10].freeze + def nack_backoff_intervals - @nack_backoff_intervals ||= if ::ENV.key?("PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS") - ::ENV["PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS"].split(",").map(&:to_i) - else - [0, 1, 3, 5, 10] + @nack_backoff_intervals ||= begin + raw = ::ENV["PB_NATS_CLIENT_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. + begin + raw.split(",").map { |interval| Integer(interval.strip, 10) } + rescue ::ArgumentError + logger.error "Ignoring malformed interval list in ENV PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS=#{raw.inspect}; using default #{DEFAULT_NACK_BACKOFF_INTERVALS.inspect}" + DEFAULT_NACK_BACKOFF_INTERVALS + end + end end end @@ -133,50 +82,44 @@ def nack_backoff_splay end def nack_backoff_splay_limit - @nack_backoff_splay_limit ||= if ::ENV.key?("PB_NATS_CLIENT_NACK_BACKOFF_SPLAY_LIMIT") - ::ENV["PB_NATS_CLIENT_NACK_BACKOFF_SPLAY_LIMIT"].to_i - else - 10 - end + @nack_backoff_splay_limit ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_NACK_BACKOFF_SPLAY_LIMIT", 10) end def reconnect_delay - @reconnect_delay ||= if ::ENV.key?("PB_NATS_CLIENT_RECONNECT_DELAY") - ::ENV["PB_NATS_CLIENT_RECONNECT_DELAY"].to_i - else - ack_timeout - end + @reconnect_delay ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_RECONNECT_DELAY", ack_timeout) end - def response_timeout - @response_timeout ||= if ::ENV.key?("PB_NATS_CLIENT_RESPONSE_TIMEOUT") - ::ENV["PB_NATS_CLIENT_RESPONSE_TIMEOUT"].to_i - else - 60 - 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. + def reconnect_delay_splay + return 0 unless reconnect_delay_splay_limit > 0 + rand(reconnect_delay_splay_limit) / 1000.0 end - def use_subscription_pooling? - return @use_subscription_pooling unless @use_subscription_pooling.nil? - @use_subscription_pooling = self.class.subscription_pool_size > 0 + 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. + def max_retries + @max_retries ||= ::Protobuf::Nats.env_int("PB_NATS_CLIENT_MAX_RETRIES", 3, :min => 1) + end + + def response_timeout + @response_timeout ||= ::Protobuf::Nats.client_response_timeout end def send_request # This will ensure the client is started. ::Protobuf::Nats.start_client_nats_connection - if use_subscription_pooling? - available = self.class.subscription_pool.instance_variable_get("@available") - ::ActiveSupport::Notifications.instrument "client.subscription_pool_available_size.protobuf-nats", available.length - end - - ::ActiveSupport::Notifications.instrument "client.request_duration.protobuf-nats" do + ::Protobuf::Nats.instrument "client.request_duration" do send_request_through_nats end end def send_request_through_nats - retries ||= 3 + retries ||= max_retries nack_retry ||= 0 loop do @@ -185,11 +128,11 @@ def send_request_through_nats @response_data = nats_request_with_two_responses(cached_subscription_key, @request_data, request_options) case @response_data when :ack_timeout - ::ActiveSupport::Notifications.instrument "client.request_timeout.protobuf-nats" + ::Protobuf::Nats.instrument "client.request_timeout" next if (retries -= 1) > 0 raise ::Protobuf::Nats::Errors::RequestTimeout, formatted_service_and_method_name when :nack - ::ActiveSupport::Notifications.instrument "client.request_nack.protobuf-nats" + ::Protobuf::Nats.instrument "client.request_nack" interval = nack_backoff_intervals[nack_retry] nack_retry += 1 raise ::Protobuf::Nats::Errors::RequestTimeout, formatted_service_and_method_name if interval.nil? @@ -201,14 +144,32 @@ def send_request_through_nats end parse_response - rescue ::Protobuf::Nats::Errors::IOException => error + rescue *::Protobuf::Nats::Errors::RETRYABLE_TRANSPORT_ERRORS => error ::Protobuf::Nats.log_error(error) - delay = reconnect_delay - logger.warn "An IOException was raised. We are going to sleep for #{delay} seconds." - sleep delay - - retry if (retries -= 1) > 0 + 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. + 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. + begin + ::Protobuf::Nats.start_client_nats_connection + response_muxer.start + rescue => reconnect_error + ::Protobuf::Nats.log_error(reconnect_error) + end + retry + end raise end @@ -235,12 +196,11 @@ def formatted_service_and_method_name end def nats_request_with_two_responses(subject, data, opts) - # Wait for the ACK from the server - ack_timeout = opts[:ack_timeout] || 5 + # Wait for the ACK from the server. (Named to avoid shadowing the + # instance methods used as fallbacks.) + first_message_timeout = opts[:ack_timeout] || ack_timeout # Wait for the protobuf response - timeout = opts[:timeout] || 60 - - nats = Protobuf::Nats.client_nats_connection + response_message_timeout = opts[:timeout] || response_timeout # Publish message with the reply topic pointed at the response muxer. req = RESPONSE_MUXER.new_request @@ -248,7 +208,7 @@ def nats_request_with_two_responses(subject, data, opts) # Receive the first message begin - first_message = req.next_message(ack_timeout) + first_message = req.next_message(first_message_timeout) logger.debug { "received message with subject:#{first_message.subject}" } if logger.debug? rescue ::NATS::Timeout => e return :ack_timeout @@ -259,7 +219,7 @@ def nats_request_with_two_responses(subject, data, opts) # Receive the second message begin - second_message = req.next_message(timeout) + second_message = req.next_message(response_message_timeout) rescue ::NATS::Timeout # ignore to raise a repsonse timeout below end diff --git a/lib/protobuf/nats/config.rb b/lib/protobuf/nats/config.rb index 68885f0..8eb84f1 100644 --- a/lib/protobuf/nats/config.rb +++ b/lib/protobuf/nats/config.rb @@ -1,11 +1,13 @@ require "erb" require "openssl" +require "socket" require "yaml" module Protobuf module Nats class Config - attr_accessor :uses_tls, :servers, :connect_timeout, :tls_client_cert, :tls_client_key, :tls_ca_cert, :max_reconnect_attempts + attr_accessor :uses_tls, :servers, :connect_timeout, :tls_client_cert, :tls_client_key, :tls_ca_cert, :max_reconnect_attempts, :connection_name + attr_accessor :reconnect_time_wait, :ping_interval, :max_outstanding_pings attr_accessor :server_subscription_key_do_not_subscribe_to_when_includes_any_of, :server_subscription_key_only_subscribe_to_when_includes_any_of, :subscription_key_replacements @@ -14,8 +16,21 @@ 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. :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. + :reconnect_time_wait => nil, + :ping_interval => nil, + :max_outstanding_pings => nil, :servers => nil, + :connection_name => nil, :tls_client_cert => nil, :tls_client_key => nil, :tls_ca_cert => nil, @@ -42,12 +57,14 @@ 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 - # Psych 4 and newer requires unsafe_load_file in order for aliases to be used - yaml_config = if ::YAML.respond_to?(:unsafe_load_file) - ::YAML.unsafe_load(yaml_string)[env] - else - ::YAML.load(yaml_string)[env] - end + # safe_load (no arbitrary object deserialization) with aliases + # enabled so the common `&defaults` / `<<: *defaults` pattern works. + 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. + yaml_config = (parsed && parsed[env]) || {} end DEFAULTS.each_pair do |key, value| @@ -63,31 +80,86 @@ 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. def connection_options(reload = false) @connection_options = false if reload @connection_options ||= begin options = { servers: servers, max_reconnect_attempts: max_reconnect_attempts, - uses_tls: uses_tls, - tls_client_cert: tls_client_cert, - tls_client_key: tls_client_key, - tls_ca_cert: tls_ca_cert, connect_timeout: connect_timeout, - server_subscription_key_do_not_subscribe_to_when_includes_any_of: server_subscription_key_do_not_subscribe_to_when_includes_any_of, - server_subscription_key_only_subscribe_to_when_includes_any_of: server_subscription_key_only_subscribe_to_when_includes_any_of, - subscription_key_replacements: subscription_key_replacements, + # nil values are safe to forward: nats-pure nil-fills each of these + # with its own default during connect. + 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. + name: resolved_connection_name, } options[:tls] = {:context => new_tls_context} if uses_tls options 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. + def resolved_connection_name + ::ENV["PB_NATS_CONNECTION_NAME"] || connection_name || ::Socket.gethostname + end + def new_tls_context tls_context = ::OpenSSL::SSL::SSLContext.new - tls_context.ssl_version = :TLSv1_2 + # 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). + # + # 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. + 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 + else + ::OpenSSL::SSL::TLS1_2_VERSION + end tls_context.cert = ::OpenSSL::X509::Certificate.new(::File.read(tls_client_cert)) if tls_client_cert - tls_context.key = ::OpenSSL::PKey::RSA.new(::File.read(tls_client_key)) if tls_client_key + # PKey.read handles any key type (RSA, EC, Ed25519...); the previous + # PKey::RSA.new rejected non-RSA client 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. + 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). + cert_store.add_file(tls_ca_cert) + else + # No CA configured: fall back to 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. tls_context end diff --git a/lib/protobuf/nats/errors.rb b/lib/protobuf/nats/errors.rb index f73b816..6d806a8 100644 --- a/lib/protobuf/nats/errors.rb +++ b/lib/protobuf/nats/errors.rb @@ -13,10 +13,67 @@ 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. + # + # 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. + 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. + 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. + # + # 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. + 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. + ResponseMuxer, + ::EOFError, + ::IOError, + ::Errno::ECONNRESET, + ::Errno::ECONNREFUSED, + ::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. + ::Errno::EHOSTUNREACH, + ::Errno::ENETUNREACH, + ].tap do |errors| + # nats-pure raises this when publishing on a closed connection. + errors << ::NATS::IO::ConnectionClosedError if defined?(::NATS::IO::ConnectionClosedError) + # On JRuby, socket EOF can still surface as a Java IOException. + errors << ::Java::JavaIo::IOException if defined?(::JRUBY_VERSION) + end.freeze end end end diff --git a/lib/protobuf/nats/response_muxer.rb b/lib/protobuf/nats/response_muxer.rb index 15113f4..31d7fc0 100644 --- a/lib/protobuf/nats/response_muxer.rb +++ b/lib/protobuf/nats/response_muxer.rb @@ -1,5 +1,4 @@ require 'securerandom' -require "connection_pool" require "protobuf/nats" require "protobuf/rpc/connectors/base" require "monitor" @@ -14,6 +13,30 @@ 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 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. + 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. + QUEUE_WAKE = ::Object.new + 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, @@ -27,16 +50,38 @@ def initialize @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. + @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. + @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. + @pending_queue_peak = ::Concurrent::AtomicFixnum.new(0) end def logger ::Protobuf::Logging.logger end - # Monotonic clock for token TTL accounting. Cheaper than Time.now (no Time - # object / timezone work per request) and immune to wall-clock jumps. + # Monotonic clock for token TTL accounting (single source of truth in + # Protobuf::Nats.monotonic_time). Immune to wall-clock jumps. def monotonic_now - ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + ::Protobuf::Nats.monotonic_time end # Number of dispatcher threads draining the response subscription. On JRuby @@ -45,20 +90,47 @@ def monotonic_now # pointless, so we stay at 1. Overridable via env for tuning/tests. def dispatcher_count @dispatcher_count ||= begin - if ::ENV.key?("PB_NATS_RESPONSE_MUXER_DISPATCHERS") - [::ENV["PB_NATS_RESPONSE_MUXER_DISPATCHERS"].to_i, 1].max - elsif ::RUBY_ENGINE == "jruby" - [::Concurrent.processor_count, 1].max - else - 1 - end + default = ::RUBY_ENGINE == "jruby" ? ::Concurrent.processor_count : 1 + ::Protobuf::Nats.env_int("PB_NATS_RESPONSE_MUXER_DISPATCHERS", default, :min => 1) 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 + # memoization is needed. + def response_queue_size + ::Protobuf::Nats.env_int("PB_NATS_RESPONSE_MUXER_QUEUE_SIZE", DEFAULT_RESPONSE_QUEUE_SIZE, :min => 1) + end + + 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. + def pending_queue_size + @resp_sub&.pending_queue&.size || 0 + end + def cleanup(token) - # Atomic remove-and-return; close the queue to wake any waiting threads. + # Atomic remove-and-return; wake+close the queue to release any waiter. entry = @resp_map.delete(token) - entry[:queue]&.close if entry + 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. + 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. + end + queue.close end def next_message(token, timeout) @@ -91,7 +163,10 @@ def next_message(token, timeout) # Queue.pop returns nil when: # 1. The queue is closed # 2. The timeout expires - unless msg + # 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. + if msg.nil? || msg.equal?(QUEUE_WAKE) logger.warn "Queue closed or timeout for token #{token} during next_message" raise ::NATS::Timeout end @@ -125,6 +200,14 @@ def publish(subject, data, token) 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. + if nats.nil? + raise ::Protobuf::Nats::Errors::ResponseMuxer, "NATS connection unavailable (closed and not yet rebuilt) - cannot publish" + end + reply_to = "#{@resp_inbox_prefix}.#{token}" nats.publish(subject, data, reply_to) end @@ -153,21 +236,10 @@ def restart LOCK.synchronize do @resp_handlers.each(&:kill) @resp_handlers.clear - if @resp_sub - begin - @resp_sub.unsubscribe - rescue => e - logger.warn "Failed to unsubscribe old response muxer subscription: #{e.message}" - ensure - # Always set to nil, even if unsubscribe raises - @resp_sub = nil - end - end + drop_subscription_locked("during restart") # Stop the cleanup thread stop_cleanup_thread - - @started = false end # Then start it fresh. @@ -179,7 +251,35 @@ def restart end def start - return if started? + 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. + 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). + stale = false + LOCK.synchronize do + if _started? + return if current_nats.nil? || @subscribed_nats.get.equal?(current_nats) + stale = true + end + end + + if stale + logger.warn "ResponseMuxer NATS connection was replaced; restarting the muxer on the new connection" + restart + return + 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. @@ -192,13 +292,31 @@ def start begin @resp_inbox_prefix = nats.new_inbox - # Subscribe to our per-instance 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. + 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). + @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) @started = false logger.error "Failed to start ResponseMuxer: #{e.message}" raise @@ -221,9 +339,24 @@ def started? LOCK.synchronize { _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. + 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. + 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 + 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 @@ -240,13 +373,26 @@ def cleanup_stale_tokens next unless data stale_count += 1 logger.warn "Cleaning up stale token #{token} created at #{data[:created_at]}" - # Close the queue to wake any waiting threads - data[:queue]&.close + # Wake any waiting thread, then close the queue. + wake_and_close_queue(data[:queue]) end if stale_count > 0 - ::ActiveSupport::Notifications.instrument "response_muxer.stale_tokens_cleaned.protobuf-nats", stale_count + ::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). + ::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. + peak = 0 + @pending_queue_peak.update do |current_value| + peak = current_value + 0 # set to 0 end + ::Protobuf::Nats.instrument "response_muxer.pending_queue_peak", peak end # Stop the cleanup thread @@ -255,16 +401,7 @@ def stop stop_cleanup_thread @resp_handlers.each(&:kill) @resp_handlers.clear - if @resp_sub - begin - @resp_sub.unsubscribe - rescue => e - logger.warn "Failed to unsubscribe during stop: #{e.message}" - ensure - @resp_sub = nil - end - end - @started = false + drop_subscription_locked("during stop") end end @@ -274,6 +411,40 @@ 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. + def drop_subscription_locked(context) + if @resp_sub + begin + @resp_sub.unsubscribe + 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. + fail_inflight_requests + end + + # Must be called while holding LOCK (only 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. @@ -282,8 +453,6 @@ def spawn_dispatcher # Unique thread name for debugging Thread.current.name = "response-muxer-#{Thread.current.object_id}" begin - # Reset crash count on successful start - @crash_count = 0 run_dispatch_loop rescue => fatal_error # Only truly fatal errors that kill the loop reach here (ThreadError @@ -292,25 +461,27 @@ def spawn_dispatcher ::Protobuf::Nats.notify_error_callbacks(fatal_error) # --- Self-healing logic --- - @crash_count = (@crash_count || 0) + 1 - # Exponential backoff, e.g., 1, 4, 9, 16s... capped at 60s. - sleep_duration = [(@crash_count**2), 60].min + # 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. + crashes = @crash_count.increment + # Exponential backoff, e.g., 1, 4, 9, 16s... capped at 60s (shared formula). + 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. LOCK.synchronize do - if @resp_sub - begin - @resp_sub.unsubscribe - rescue => e - logger.warn "Failed to unsubscribe old response muxer subscription during self-healing: #{e.message}" - ensure - @resp_sub = nil - end - end - @started = false + # Remove ourselves from the handler pool BEFORE start re-tops it up. + # This thread is still alive (running this rescue) but is about to + # exit, so start'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). + @resp_handlers.delete(::Thread.current) + + drop_subscription_locked("during self-healing") end start end @@ -321,17 +492,45 @@ def run_dispatch_loop loop do begin # --- Start of per-message block --- - msg = @resp_sub.pending_queue.pop + # @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. + sub = @resp_sub + if sub.nil? + sleep 0.01 + next + end + + msg = sub.pending_queue.pop - # ACK means the message has been picked up and put into the waiting thread_pool - next if msg.nil? + # 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. + 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.) + sub.synchronize { sub.pending_size -= msg.data.size } - # Decrease pending size since consumed already. - # NOTE: advisory metric only; with multiple dispatchers this is a - # benign lost-update race on the NATS subscription's counter. - @resp_sub.pending_size -= msg.data.size if @resp_sub + # Sample post-pop depth into the high-water mark so a burst that fills + # and drains between the 60s gauge samples is still 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. + @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. @@ -347,7 +546,7 @@ def run_dispatch_loop def dispatch_message(msg) # Validate message subject before processing unless msg.subject.is_a?(String) && msg.subject.include?('.') - ::ActiveSupport::Notifications.instrument "client.invalid_message.protobuf-nats", 1 + ::Protobuf::Nats.instrument "client.invalid_message", 1 logger.warn "Received message with invalid subject: #{msg.subject}. Dropping." return @@ -355,7 +554,11 @@ def dispatch_message(msg) # example(random data): # _INBOX.{random_data}.{random_data_msg_id} - token = msg.subject.split('.').last + # 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 = msg.subject + token = subject[(subject.rindex(".") + 1)..] logger.debug { "token: #{token}, resp_map.keys:#{@resp_map.keys}" } if logger.debug? @@ -367,7 +570,7 @@ def dispatch_message(msg) # Try to decode the UUIDv7 timestamp to calculate message age delay_seconds = UUIDv7Helper.age_in_seconds(token) - ::ActiveSupport::Notifications.instrument "client.unexpected_message.protobuf-nats", delay_seconds || 1 + ::Protobuf::Nats.instrument "client.unexpected_message", delay_seconds || 1 if delay_seconds logger.warn "Received unexpected message (#{delay_seconds.round(3)}s old). MSG.subject=#{msg.subject}. RESP_SUBJ.subject=#{@resp_sub.subject rescue 'unknown'}. Dropping unexpected message." diff --git a/lib/protobuf/nats/response_muxer_request.rb b/lib/protobuf/nats/response_muxer_request.rb index 60f0676..1ad88bc 100644 --- a/lib/protobuf/nats/response_muxer_request.rb +++ b/lib/protobuf/nats/response_muxer_request.rb @@ -1,9 +1,3 @@ -require 'securerandom' -require "connection_pool" -require "protobuf/nats" -require "protobuf/rpc/connectors/base" -require "monitor" - module Protobuf module Nats class ResponseMuxerRequest diff --git a/lib/protobuf/nats/server.rb b/lib/protobuf/nats/server.rb index 957309f..5c45ce8 100644 --- a/lib/protobuf/nats/server.rb +++ b/lib/protobuf/nats/server.rb @@ -1,8 +1,11 @@ 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" +require "protobuf/nats/uuidv7_helper" module Protobuf module Nats @@ -22,34 +25,191 @@ def initialize(options) @pause_mutex = ::Mutex.new @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). + @nats.on_disconnect do + logger.warn "Server NATS connection was disconnected" + end + + @nats.on_reconnect do + logger.warn "Server NATS connection was reconnected" + 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. + ::Protobuf::Nats.notify_error_callbacks_async(error) + end + + @nats.on_close do + handle_connection_closed + end + @nats.connect(::Protobuf::Nats.config.connection_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. + next if stale_request?(reply_id) + unless enqueue_request(request_data, reply_id) logger.error { "Thread pool is full! Dropping message for subject: #{subject}" } end 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. + @inflight = ::Concurrent::Map.new + @overdue_flagged = ::Concurrent::Map.new + @request_seq = ::Concurrent::AtomicFixnum.new(0) + end + + def monotonic + ::Protobuf::Nats.monotonic_time + end + + 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. + 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. + def stale_request_ms + @stale_request_ms ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_STALE_REQUEST_MS", 0) + end + + def stale_request?(reply_id) + return false unless stale_request_ms.positive? + + age_ms = ::Protobuf::Nats::UUIDv7Helper.age_ms(reply_id.to_s[/[^.]*\z/]) + return false if age_ms.nil? || age_ms < stale_request_ms + + logger.debug { "Dropping stale request (age=#{age_ms}ms >= #{stale_request_ms}ms); the client has already retried or timed out" } + ::Protobuf::Nats.instrument "server.stale_request_dropped", age_ms + 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. + 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. + 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. + @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. + def shutdown_drain_timeout + @shutdown_drain_timeout ||= ::Protobuf::Nats.env_float("PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT", (handler_overdue_ms / 1000.0) + 5) end def instrument_thread_pool_sizes - ::ActiveSupport::Notifications.instrument("server.thread_pool_enqueued_size.protobuf-nats", thread_pool.enqueued_size) - ::ActiveSupport::Notifications.instrument("server.thread_pool_max_size.protobuf-nats", thread_pool.max_size) - ::ActiveSupport::Notifications.instrument("server.thread_pool_running_size.protobuf-nats", thread_pool.size) + ::Protobuf::Nats.instrument("server.thread_pool_enqueued_size", thread_pool.enqueued_size) + ::Protobuf::Nats.instrument("server.thread_pool_max_size", thread_pool.max_size) + ::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. + def instrument_inflight_handlers + now = monotonic + overdue_ms = handler_overdue_ms + count = 0 + oldest_age_ms = 0.0 + overdue = 0 + + @inflight.each_pair do |id, entry| + started_at, handler_thread = entry + count += 1 + age_ms = (now - started_at) * MILLISECOND + oldest_age_ms = age_ms if age_ms > oldest_age_ms + next unless overdue_ms.positive? && age_ms >= overdue_ms + + 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). + 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). + 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" + ::Protobuf::Nats.instrument("server.handler_overdue", age_ms) + end + + ::Protobuf::Nats.instrument("server.pending_intake_queue_size", subscription_manager.pending_queue_size) + ::Protobuf::Nats.instrument("server.pending_intake_queue_bytes", subscription_manager.pending_queue_bytes) + ::Protobuf::Nats.instrument("server.inflight_count", count) + ::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. + @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. def max_queue_size - ::ENV.fetch("PB_NATS_SERVER_MAX_QUEUE_SIZE", @options[:threads]).to_i + ::Protobuf::Nats.env_int("PB_NATS_SERVER_MAX_QUEUE_SIZE", threads) end def slow_start_delay - @slow_start_delay ||= ::ENV.fetch("PB_NATS_SERVER_SLOW_START_DELAY", 10).to_i + @slow_start_delay ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_SLOW_START_DELAY", 10) end def subscriptions_per_rpc_endpoint - @subscriptions_per_rpc_endpoint ||= ::ENV.fetch("PB_NATS_SERVER_SUBSCRIPTIONS_PER_RPC_ENDPOINT", 10).to_i + @subscriptions_per_rpc_endpoint ||= ::Protobuf::Nats.env_int("PB_NATS_SERVER_SUBSCRIPTIONS_PER_RPC_ENDPOINT", 10) end def threads @@ -61,30 +221,82 @@ def service_klasses end def enqueue_request(request_data, reply_id) - ::ActiveSupport::Notifications.instrument "server.message_received.protobuf-nats" + ::Protobuf::Nats.instrument "server.message_received" - enqueued_at = ::Time.now + 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). + response_data = nil begin # Instrument the thread pool time-to-execute duration. - processed_at = ::Time.now - ::ActiveSupport::Notifications.instrument("server.thread_pool_execution_delay.protobuf-nats", - (processed_at - enqueued_at) * MILLISECOND) - - # Process request. - response_data = handle_request(request_data, 'server' => @server) - - # Publish response. - logger.debug { "Publishing response to #{reply_id}" } if logger.debug? - nats.publish(reply_id, response_data) - rescue => error - logger.debug { "rescued error => #{error}" } if logger.debug? - ::Protobuf::Nats.notify_error_callbacks(error) + 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. + @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. + 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. + ::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.) + begin + error_response = ::Protobuf::Rpc::PbError.new("Internal server error") + nats.publish(reply_id, error_response.encode) + rescue => publish_error + logger.error "Failed to publish error response for #{reply_id}: #{publish_error.message}" + 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. + if response_data + logger.debug { "Publishing response to #{reply_id}" } if logger.debug? + begin + nats.publish(reply_id, response_data) + rescue => publish_error + logger.error "Failed to publish response for #{reply_id}: #{publish_error.message}" + ::Protobuf::Nats.notify_error_callbacks(publish_error) + end + end ensure + @inflight.delete(request_id) + @overdue_flagged.delete(request_id) + # Instrument the request duration. - completed_at = ::Time.now - ::ActiveSupport::Notifications.instrument("server.request_duration.protobuf-nats", - (completed_at - enqueued_at) * MILLISECOND) + completed_at = monotonic + ::Protobuf::Nats.instrument("server.request_duration", (completed_at - enqueued_at) * MILLISECOND) + + # Informational slow-handler marker (opt-in; default off). + if processed_at && slow_handler_threshold_ms.positive? + handler_ms = (completed_at - processed_at) * MILLISECOND + if handler_ms >= slow_handler_threshold_ms + logger.warn "Slow handler for #{reply_id}: #{handler_ms.round}ms" + ::Protobuf::Nats.instrument("server.slow_handler", handler_ms) + end + end end end @@ -94,7 +306,8 @@ def enqueue_request(request_data, reply_id) logger.debug { "[reply_id=#{reply_id}] Sending ACK" } if logger.debug? nats.publish(reply_id, ::Protobuf::Nats::Messages::ACK) else # Drop message if the thread pool is full - ::ActiveSupport::Notifications.instrument "server.message_dropped.protobuf-nats" + ::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. @@ -210,23 +423,24 @@ def paused? !pause_file_path.nil? && ::File.exist?(pause_file_path) end - def run - nats.on_reconnect do - logger.warn "Server NATS connection was reconnected" - end - - nats.on_disconnect do - logger.warn "Server NATS connection was disconnected" - end - - nats.on_error do |error| - ::Protobuf::Nats.notify_error_callbacks(error) - end - - nats.on_close do - logger.warn "Server NATS connection was closed" - 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. + 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" + ::Protobuf::Nats.instrument "server.connection_closed" + stop + end + def run print_subscription_keys if paused? yield if block_given? @@ -238,6 +452,8 @@ def run break unless @running detect_and_handle_a_pause instrument_thread_pool_sizes + instrument_inflight_handlers + thread_pool.replenish # respawn workers killed by non-StandardError sleep 1 end @@ -254,11 +470,18 @@ def run logger.error "Error during subscription manager shutdown: #{e.message}" end - logger.info "Waiting up to 60 seconds for the thread pool to finish shutting down..." + # 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. + 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 - unless thread_pool.wait_for_termination(60) - logger.warn "Thread pool did not shut down cleanly within 60 seconds!" - ::ActiveSupport::Notifications.instrument "server.thread_pool_shutdown_timeout.protobuf-nats" + unless thread_pool.wait_for_termination(drain_timeout) + abandoned = @inflight.size + logger.warn "Thread pool did not shut down cleanly within #{drain_timeout.round}s! Abandoned #{abandoned} in-flight handler(s)." + ::Protobuf::Nats.instrument "server.thread_pool_shutdown_timeout" + ::Protobuf::Nats.instrument "server.shutdown_abandoned_handlers", abandoned end ensure @stopped = true diff --git a/lib/protobuf/nats/super_subscription_manager.rb b/lib/protobuf/nats/super_subscription_manager.rb index 60a0aa1..80635fd 100644 --- a/lib/protobuf/nats/super_subscription_manager.rb +++ b/lib/protobuf/nats/super_subscription_manager.rb @@ -1,71 +1,99 @@ 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" +require "protobuf/nats/byte_bounded_queue" module Protobuf module Nats class SuperSubscriptionManager def initialize(nats, &cb) - # Central queue used by all subscriptions - @pending_queue = ::SizedQueue.new(::NATS::IO::DEFAULT_SUB_PENDING_MSGS_LIMIT) + # 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. + @pending_queue = ::Protobuf::Nats::ByteBoundedQueue.new( + intake_queue_size, intake_queue_bytes, + :on_drop => lambda { |bytes| ::Protobuf::Nats.instrument("server.intake_bytes_dropped", bytes) } + ) @subscriptions = [] + @subscriptions_mutex = ::Mutex.new @nats = nats @callback = cb - @crash_count = 0 - @pending_queue_handler = Thread.new do - Thread.current.name = "subscription-manager-#{object_id}" - begin - @crash_count = 0 # Reset on successful start - - loop do - msg = nil - begin - # --- Per-message processing --- - msg = @pending_queue.pop - # Check for shutdown poison pill - break if msg == :shutdown - - @callback.call(msg.data, msg.reply, msg.subject) - # --- End per-message processing --- - rescue => per_message_error - # Log the error for the specific message, but DON'T kill the thread. - 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 - end - rescue => fatal_error - raise if fatal_error.is_a?(SystemExit) || fatal_error.is_a?(Interrupt) || fatal_error.is_a?(SignalException) + # 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. + @pending_queue_handlers = handler_count.times.map { |i| spawn_handler(i) } - # 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_count", @pending_queue_handlers.size) + end - # Self-healing with exponential backoff - @crash_count += 1 - sleep_duration = [(@crash_count**2), 60].min - logger.warn("Waiting #{sleep_duration}s before restarting SubscriptionManager handler...") - sleep sleep_duration + def logger + ::Protobuf::Logging.logger + end - retry # Restart the loop - 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. + def handler_count + @handler_count ||= begin + default = ::RUBY_ENGINE == "jruby" ? ::Concurrent.processor_count : 1 + ::Protobuf::Nats.env_int("PB_NATS_SERVER_SUBSCRIPTION_HANDLERS", default, :min => 1) end end - def logger - ::Protobuf::Logging.logger + # 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. + 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. + DEFAULT_INTAKE_QUEUE_BYTES = 128 * 1024 * 1024 # 128MiB + + # Read once, in #initialize, so no memoization is needed. + def intake_queue_bytes + ::Protobuf::Nats.env_int("PB_NATS_SERVER_INTAKE_QUEUE_BYTES", DEFAULT_INTAKE_QUEUE_BYTES, :min => 1) end def queue_subscribe(name) logger.debug { "queue_subscribe(#{name})" } sub = @nats.subscribe(name, :queue => name) + # Rationale on Protobuf::Nats.disable_subscription_byte_limit!. + ::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. + 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. @@ -73,16 +101,19 @@ def queue_subscribe(name) max_migrations = 10000 # Safety limit while !existing_pending_queue.empty? && migrated_count < max_migrations - msg = existing_pending_queue.pop - - # Non-blocking push with timeout + # Non-blocking pop: another consumer could in theory drain it, so don't block. begin - Timeout.timeout(1) do - @pending_queue << msg - end + 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). + if push_with_deadline(msg, 1) migrated_count += 1 logger.warn "Migrated message #{migrated_count} from old queue to central queue" - rescue Timeout::Error + else logger.error "Failed to migrate message to central queue (queue full), dropping message" break end @@ -92,45 +123,69 @@ def queue_subscribe(name) logger.error "Hit migration limit! Old queue still has #{existing_pending_queue.size} messages" end - @subscriptions << sub + @subscriptions_mutex.synchronize { @subscriptions << sub } sub end def shutdown(timeout = 5) - # Check if thread is alive first - return unless @pending_queue_handler&.alive? + handlers = @pending_queue_handlers.select(&:alive?) + return if handlers.empty? - # Non-blocking push of shutdown signal - begin - # Clear some space if queue is full - if @pending_queue.num_waiting == 0 && @pending_queue.size >= @pending_queue.max + # Wake every handler with its own poison pill. + handlers.size.times do + # Clear some space if the queue is full so the shutdown signal 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 - Timeout.timeout(1) do - @pending_queue << :shutdown + # Push with a deadline (see push_with_deadline: no Timeout.timeout, + # which corrupts the SizedQueue mutex on JRuby). + unless push_with_deadline(:shutdown, 1) + logger.error "Failed to send shutdown signal (queue blocked); will force-kill remaining handlers" + break end - rescue Timeout::Error - logger.error "Failed to send shutdown signal (queue blocked), force killing thread" - @pending_queue_handler.kill if @pending_queue_handler&.alive? - return end - # Handle timeout and force kill if needed - unless @pending_queue_handler.join(timeout) - logger.warn "Handler thread did not shutdown within #{timeout}s, forcefully killing..." - @pending_queue_handler.kill - @pending_queue_handler.join(1) rescue nil + # Join all handlers within a single shared deadline, then force-kill stragglers. + deadline = monotonic + timeout + handlers.each do |handler| + remaining = deadline - monotonic + handler.join(remaining.positive? ? remaining : 0) + end + + handlers.each do |handler| + next unless handler.alive? + logger.warn "Handler thread did not shut down in time, forcefully killing..." + handler.kill + 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). + def pending_queue_size + @pending_queue.size + end + + # Resident bytes in the shared intake queue = heap backpressure (gauge). + def pending_queue_bytes + @pending_queue.bytesize + end + def unsubscribe_all - @subscriptions.each do |sub| + # 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. + subscriptions = @subscriptions_mutex.synchronize do + subs = @subscriptions.dup + @subscriptions.clear + subs + end + subscriptions.each do |sub| begin sub.unsubscribe rescue => e @@ -138,6 +193,95 @@ def unsubscribe_all end end end + + private + + 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. + def push_with_deadline(obj, timeout) + deadline = monotonic + timeout + loop do + begin + @pending_queue.push(obj, true) # non_block: raises ThreadError when full + return true + rescue ::ClosedQueueError + return false + rescue ::ThreadError + return false if monotonic >= deadline + sleep 0.01 + end + 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. + def spawn_handler(index) + ::Thread.new do + ::Thread.current.name = "subscription-manager-#{object_id}-#{index}" + crash_count = 0 + + begin + 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. + if msg.nil? + sleep ::Protobuf::Nats::CLOSED_QUEUE_PARK_SECONDS + next + end + + # Check for 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 --- + rescue => per_message_error + # Log the error for the specific message, but DON'T kill the thread. + 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 + end + 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). + 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 + end + end + end end end end diff --git a/lib/protobuf/nats/thread_pool.rb b/lib/protobuf/nats/thread_pool.rb index 4e9fec2..2721430 100644 --- a/lib/protobuf/nats/thread_pool.rb +++ b/lib/protobuf/nats/thread_pool.rb @@ -1,4 +1,5 @@ require "concurrent" +require "protobuf/nats/errors" module Protobuf module Nats @@ -57,9 +58,6 @@ def push(&work_cb) end @queue << [:work, work_cb] - - # Supervise outside any lock-held section to avoid holding it during thread creation. - supervise_workers true end @@ -76,16 +74,31 @@ 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). def wait_for_termination(seconds = nil) - started_at = ::Time.now + deadline = seconds && (::Protobuf::Nats.monotonic_time + seconds) loop do + @mutex.synchronize { prune_dead_workers } + return true if @workers.empty? + return false if deadline && ::Protobuf::Nats.monotonic_time >= deadline sleep 0.1 - break if seconds && (::Time.now - started_at) >= seconds - break if @workers.empty? - prune_dead_workers 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. + 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 } @@ -121,13 +134,22 @@ def spawn_worker ::Thread.new do Thread.current.name = "thread-pool-worker" loop do - type, cb = @queue.pop begin - # Break if we're shutting down - break if type == :stop - # Perform work + 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. + 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. + break if type == :stop + + begin cb.call - # Update stats rescue => error @cb_mutex.synchronize { @error_cb.call(error) } ensure diff --git a/lib/protobuf/nats/uuidv7_helper.rb b/lib/protobuf/nats/uuidv7_helper.rb index afe41d0..7a376ae 100644 --- a/lib/protobuf/nats/uuidv7_helper.rb +++ b/lib/protobuf/nats/uuidv7_helper.rb @@ -55,6 +55,21 @@ 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 + # intake path. + 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) + ::Process.clock_gettime(::Process::CLOCK_REALTIME, :millisecond) - unix_ts_ms + end end end end diff --git a/lib/protobuf/nats/version.rb b/lib/protobuf/nats/version.rb index 2961c8b..7798dc3 100644 --- a/lib/protobuf/nats/version.rb +++ b/lib/protobuf/nats/version.rb @@ -1,5 +1,5 @@ module Protobuf module Nats - VERSION = "0.13.0" + VERSION = "0.13.2.pre2" end end diff --git a/protobuf-nats.gemspec b/protobuf-nats.gemspec index 4e48361..74c1a1d 100644 --- a/protobuf-nats.gemspec +++ b/protobuf-nats.gemspec @@ -35,9 +35,12 @@ Gem::Specification.new do |spec| spec.add_runtime_dependency "activesupport", ">= 6.1" spec.add_runtime_dependency "concurrent-ruby", "~> 1.3.6" # pinned so logger is included - spec.add_runtime_dependency "connection_pool" spec.add_runtime_dependency "protobuf", "~> 3.7", ">= 3.7.2" - spec.add_runtime_dependency "nats-pure", "~> 2" + # Floor at 2.5: this gem reaches into nats-pure internals that are not + # public API (the subscription pending_queue swap, pending_msgs_limit drop + # semantics, subscription replay on reconnect, max_reconnect_attempts < 0 == + # infinite), all verified against 2.5. Re-verify those before widening. + spec.add_runtime_dependency "nats-pure", ">= 2.5", "< 3" spec.add_dependency "uuid7" # Remove once on newer ruby versions which include this in PRNG. diff --git a/spec/fake_nats_client.rb b/spec/fake_nats_client.rb index 7556cda..ab7ffde 100644 --- a/spec/fake_nats_client.rb +++ b/spec/fake_nats_client.rb @@ -3,7 +3,7 @@ require "nats/client" # Using the real NATS::Msg for accuracy class FakeNatsClient - attr_reader :subscriptions, :published_messages + attr_reader :subscriptions, :published_messages, :callbacks def initialize(options = {}) @inbox_base = options[:inbox] || "_INBOX.FAKE" @@ -11,12 +11,25 @@ def initialize(options = {}) @subscriptions = {} @replies = [] @published_messages = [] + @callbacks = {} end def connect(*) # No-op end + # Lifecycle callbacks (mirroring nats-pure). Stored so tests can fire them, + # e.g. client.fire_callback(:close) to simulate a terminal connection loss. + %i[disconnect reconnect error close].each do |event| + define_method("on_#{event}") do |&block| + @callbacks[event] = block + end + end + + def fire_callback(event, *args) + @callbacks[event]&.call(*args) + end + def new_inbox @inbox_id += 1 "#{@inbox_base}.#{@inbox_id}" diff --git a/spec/integration/failover_spec.rb b/spec/integration/failover_spec.rb new file mode 100644 index 0000000..f16a0c9 --- /dev/null +++ b/spec/integration/failover_spec.rb @@ -0,0 +1,148 @@ +require "spec_helper" + +# Failover across a real two-node NATS cluster (gated on the nats-server +# binary; see spec_helper). This is the one test that exercises the behaviors +# the gem relies on from nats-pure internals -- server-pool failover, +# subscription replay on reconnect -- against a real cluster, so a nats-pure +# upgrade that changes them fails here instead of in production. +class FailoverPing < ::Protobuf::Message + optional :string, :payload, 1 +end + +class FailoverEchoService < ::Protobuf::Rpc::Service + rpc :echo, FailoverPing, FailoverPing + + def echo + respond_with ::FailoverPing.new(:payload => request.payload) + end +end + +describe "failover across a two-node NATS cluster", :integration_cluster => true do + NODE_PORTS = { 14_222 => 14_248, 14_223 => 14_249 }.freeze # client port => cluster port + + def port_open?(port) + ::Socket.tcp("127.0.0.1", port, :connect_timeout => 0.2).close + true + rescue ::StandardError + false + end + + def spawn_node(client_port, cluster_port, route_port) + pid = ::Process.spawn( + "nats-server", + "-a", "127.0.0.1", + "-p", client_port.to_s, + "--cluster_name", "pb-nats-failover", + "--cluster", "nats://127.0.0.1:#{cluster_port}", + "--routes", "nats://127.0.0.1:#{route_port}", + :out => ::File::NULL, :err => ::File::NULL + ) + wait_until(timeout: 10) { port_open?(client_port) } + pid + end + + def kill_node(pid) + ::Process.kill("KILL", pid) # hard kill: no FIN handshake, like a dead host + ::Process.wait(pid) + rescue ::Errno::ESRCH, ::Errno::ECHILD + # already gone + end + + def build_request_data(payload) + ::Protobuf::Socketrpc::Request.new( + :service_name => "FailoverEchoService", + :method_name => "echo", + :request_proto => ::FailoverPing.new(:payload => payload).encode, + :caller => "failover-spec" + ).encode + end + + def new_client + ::Protobuf::Nats::Client.new(:service => FailoverEchoService, :method => :echo) + end + + # Drives an RPC the way the production loop does: NACKs, ack timeouts, and + # transient transport errors are all retried, because during the failover + # window every one of those is expected. + def rpc_with_retry(payload, attempts: 40) + request_data = build_request_data(payload) + opts = { :ack_timeout => 2, :timeout => 5 } + last = nil + attempts.times do + client = new_client + begin + last = client.nats_request_with_two_responses(client.cached_subscription_key, request_data, opts) + rescue *::Protobuf::Nats::Errors::RETRYABLE_TRANSPORT_ERRORS => e + last = e + sleep 0.25 + next + end + break unless last.is_a?(::Symbol) # :nack / :ack_timeout -> retry + sleep 0.25 + end + raise "request did not complete: #{last.inspect}" if last.is_a?(::Symbol) || last.is_a?(::Exception) + + response = ::Protobuf::Socketrpc::Response.decode(last) + raise "rpc error: #{response.error}" unless response.error.to_s.empty? + ::FailoverPing.decode(response.response_proto).payload + end + + before(:all) do + ports = NODE_PORTS.keys + clusters = NODE_PORTS.values + @node_pids = { + ports[0] => spawn_node(ports[0], clusters[0], clusters[1]), + ports[1] => spawn_node(ports[1], clusters[1], clusters[0]), + } + + ::Protobuf::Nats.config.servers = ports.map { |p| "nats://127.0.0.1:#{p}" } + # Fast failover for the test (also dogfoods the new config keys). + ::Protobuf::Nats.config.reconnect_time_wait = 0.25 + ::Protobuf::Nats.config.connection_options(true) + + @server_nats = ::Protobuf::Nats::NatsClient.new + @server = ::Protobuf::Nats::Server.new(:threads => 2, :client => @server_nats, :server => "failover-spec") + @server.subscribe_to_services_once + @server_nats.flush(5) + end + + after(:all) do + @server.subscription_manager.unsubscribe_all rescue nil + @server.subscription_manager.shutdown(2) rescue nil + @server.thread_pool.shutdown + @server.thread_pool.wait_for_termination(5) + @server_nats.close rescue nil + + ::Protobuf::Nats.config.servers = nil + ::Protobuf::Nats.config.reconnect_time_wait = nil + ::Protobuf::Nats.config.connection_options(true) + + (@node_pids || {}).each_value { |pid| kill_node(pid) } + end + + after do + # Same clean-slate reset as real_nats_spec: the shared connection + muxer + # singleton must not leak into the fake-connection unit examples. + connection = ::Protobuf::Nats.client_nats_connection + ::Protobuf::Nats::Client::RESPONSE_MUXER.stop + ::Protobuf::Nats.instance_variable_set(:@client_nats_connection, nil) + connection.close rescue nil + end + + it "keeps serving RPCs after the node the client is connected to dies" do + expect(rpc_with_retry("before-failover")).to eq("before-failover") + + connection = ::Protobuf::Nats.client_nats_connection + killed_port = connection.connected_server.port + surviving_port = (NODE_PORTS.keys - [killed_port]).first + + kill_node(@node_pids.fetch(killed_port)) + wait_until(timeout: 10) { !port_open?(killed_port) } + + # The client connection must fail over to the surviving node (nats-pure + # walks the server pool and replays the muxer's inbox subscription), and + # the gem server -- whichever node it was on -- must keep answering. + expect(rpc_with_retry("after-failover")).to eq("after-failover") + expect(::Protobuf::Nats.client_nats_connection.connected_server.port).to eq(surviving_port) + end +end diff --git a/spec/integration/real_nats_spec.rb b/spec/integration/real_nats_spec.rb new file mode 100644 index 0000000..010ef08 --- /dev/null +++ b/spec/integration/real_nats_spec.rb @@ -0,0 +1,113 @@ +require "spec_helper" + +# Full-stack integration against a real NATS server (see spec_helper for how +# these are gated). Exercises the actual wire protocol: client publish with a +# muxer reply inbox -> server intake -> ACK -> thread-pool handler -> response. +class IntegrationPing < ::Protobuf::Message + optional :string, :payload, 1 +end + +class IntegrationEchoService < ::Protobuf::Rpc::Service + rpc :echo, IntegrationPing, IntegrationPing + + def echo + respond_with ::IntegrationPing.new(:payload => request.payload) + end +end + +describe "protobuf-nats against a real NATS server", :integration => true do + def build_request_data(payload) + ::Protobuf::Socketrpc::Request.new( + :service_name => "IntegrationEchoService", + :method_name => "echo", + :request_proto => ::IntegrationPing.new(:payload => payload).encode, + :caller => "integration-spec" + ).encode + end + + def new_client + ::Protobuf::Nats::Client.new(:service => IntegrationEchoService, :method => :echo) + end + + # Drives a real RPC and returns the echoed payload. Retries NACKs (the + # server's real backpressure signal when its 2-thread pool saturates) the + # same way the production client loop does. + def rpc(client, payload) + opts = { :ack_timeout => 5, :timeout => 10 } + request_data = build_request_data(payload) + data = nil + 30.times do + data = client.nats_request_with_two_responses(client.cached_subscription_key, request_data, opts) + break unless data == :nack + sleep 0.05 + end + raise "request did not complete: #{data.inspect}" if data.is_a?(::Symbol) + + response = ::Protobuf::Socketrpc::Response.decode(data) + raise "rpc error: #{response.error}" unless response.error.to_s.empty? + ::IntegrationPing.decode(response.response_proto).payload + end + + before(:all) do + ::Protobuf::Nats.config.servers = ["nats://#{PB_NATS_INTEGRATION_HOST}:#{PB_NATS_INTEGRATION_PORT}"] + ::Protobuf::Nats.config.connection_options(true) + + @server_nats = ::Protobuf::Nats::NatsClient.new + @server = ::Protobuf::Nats::Server.new(:threads => 2, :client => @server_nats, :server => "integration-spec") + # One round of subscriptions is enough; skip Server#run's slow start / + # supervision loop, which this transport-level test doesn't need. + @server.subscribe_to_services_once + @server_nats.flush(5) + end + + after(:all) do + @server.subscription_manager.unsubscribe_all + @server.subscription_manager.shutdown(2) + @server.thread_pool.shutdown + @server.thread_pool.wait_for_termination(5) + @server_nats.close rescue nil + + ::Protobuf::Nats.config.servers = nil + ::Protobuf::Nats.config.connection_options(true) + end + + after do + # Return the shared client connection + muxer singleton to a clean slate so + # the (fake-connection) unit examples that run in the same process are + # unaffected. + connection = ::Protobuf::Nats.client_nats_connection + ::Protobuf::Nats::Client::RESPONSE_MUXER.stop + ::Protobuf::Nats.instance_variable_set(:@client_nats_connection, nil) + connection.close rescue nil + end + + it "completes a full RPC round trip (request -> ACK -> handler -> response)" do + expect(rpc(new_client, "hello-integration")).to eq("hello-integration") + end + + it "handles concurrent requests" do + payloads = 10.times.map { |i| "concurrent-#{i}" } + results = payloads.map { |p| ::Thread.new { rpc(new_client, p) } }.map(&:value) + expect(results).to match_array(payloads) + end + + it "self-heals after a terminal connection close (the muxer restarts on the new connection)" do + expect(rpc(new_client, "before-close")).to eq("before-close") + + # Simulate nats-pure giving up: closing fires on_close, which drops the + # memoized connection so the next request rebuilds it. + old_connection = ::Protobuf::Nats.client_nats_connection + old_connection.close + wait_until(timeout: 5) { ::Protobuf::Nats.instance_variable_get(:@client_nats_connection).nil? } + + # The next client must build a fresh connection AND move the muxer's inbox + # subscription onto it -- previously the muxer stayed subscribed to the + # dead connection and every response was lost forever. + client = new_client + new_connection = ::Protobuf::Nats.client_nats_connection + expect(new_connection).not_to equal(old_connection) + expect(::Protobuf::Nats::Client::RESPONSE_MUXER.subscribed_to?(new_connection)).to be(true) + + expect(rpc(client, "after-close")).to eq("after-close") + end +end diff --git a/spec/protobuf/nats/byte_bounded_queue_spec.rb b/spec/protobuf/nats/byte_bounded_queue_spec.rb new file mode 100644 index 0000000..b540ec6 --- /dev/null +++ b/spec/protobuf/nats/byte_bounded_queue_spec.rb @@ -0,0 +1,117 @@ +require "spec_helper" + +describe ::Protobuf::Nats::ByteBoundedQueue do + def msg(bytes) + ::NATS::Msg.new(:subject => "x", :data => "x" * bytes) + end + + # Build a queue whose on_drop callback records the byte count of each drop. + def queue_with_drops(max_msgs, max_bytes) + dropped = [] + q = described_class.new(max_msgs, max_bytes, :on_drop => lambda { |bytes| dropped << bytes }) + [q, dropped] + end + + describe "byte accounting" do + it "tracks resident bytes as items are pushed and popped" do + q = described_class.new(100, 10_000) + q.push(msg(500)) + q << msg(300) + + expect(q.size).to eq(2) + expect(q.bytesize).to eq(800) + + q.pop + expect(q.bytesize).to eq(300) + end + + it "resets the byte counter on clear" do + q = described_class.new(100, 10_000) + q.push(msg(500)) + q.clear + expect(q.size).to eq(0) + expect(q.bytesize).to eq(0) + end + + it "counts non-message sentinels (the :shutdown poison pill) as zero bytes" do + q = described_class.new(100, 10_000) + q.push(:shutdown) + expect(q.size).to eq(1) + expect(q.bytesize).to eq(0) + end + end + + describe "byte ceiling (negative paths)" do + it "drops a message that would exceed the byte ceiling and reports it via on_drop" do + q, dropped = queue_with_drops(100, 10) # 10-byte ceiling + q.push(msg(6)) # ok: 6 <= 10 + q.push(msg(6)) # 6 + 6 = 12 > 10 -> drop + + expect(q.size).to eq(1) # the second message was not enqueued + expect(q.bytesize).to eq(6) # ...and its bytes were not counted + expect(dropped).to eq([6]) # ...and the drop was reported + end + + it "does not require an on_drop callback" do + q = described_class.new(100, 10) # no on_drop + expect { q.push(msg(64)) }.not_to raise_error + expect(q.size).to eq(0) + end + + it "still accepts messages after a pop frees byte headroom" do + q = described_class.new(100, 10) + q.push(msg(8)) + q.push(msg(8)) # dropped: 16 > 10 + expect(q.size).to eq(1) + + q.pop # frees 8 bytes -> bytesize 0 + q.push(msg(8)) # now fits + expect(q.size).to eq(1) + expect(q.bytesize).to eq(8) + end + + it "never drops a zero-byte sentinel even when the byte ceiling is already reached" do + q = described_class.new(100, 5) + q.push(msg(5)) # at the ceiling + q.push(:shutdown) + expect(q.size).to eq(2) + expect(q.bytesize).to eq(5) + end + + it "drops a single message larger than the entire byte ceiling, even into an empty queue" do + q, dropped = queue_with_drops(100, 10) + + q.push(msg(64)) # 64 > 10, queue empty + + expect(q.size).to eq(0) + expect(q.bytesize).to eq(0) + expect(dropped).to eq([64]) + end + + it "admits a message that lands exactly on the byte ceiling (boundary is inclusive)" do + q = described_class.new(100, 10) + q.push(msg(10)) # 10 == 10, not > 10 + expect(q.size).to eq(1) + expect(q.bytesize).to eq(10) + 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 + q.push(msg(100)) + q.push(msg(100)) + expect(q.bytesize).to eq(200) + + expect { q.push(msg(100), true) }.to raise_error(::ThreadError) + expect(q.size).to eq(2) + expect(q.bytesize).to eq(200) # dropped push did not add bytes + end + + it "raises ThreadError on a non-blocking pop from an empty queue without underflowing the byte counter" do + q = described_class.new(2, 10_000) + expect { q.pop(true) }.to raise_error(::ThreadError) + expect(q.bytesize).to eq(0) + end + end +end diff --git a/spec/protobuf/nats/client_spec.rb b/spec/protobuf/nats/client_spec.rb index 9850722..486676a 100644 --- a/spec/protobuf/nats/client_spec.rb +++ b/spec/protobuf/nats/client_spec.rb @@ -40,6 +40,15 @@ class ExampleServiceClass; end it "has a default value" do expect(subject.nack_backoff_intervals).to eq([0, 1, 3, 5, 10]) end + + it "falls back to the default (instead of zeros) and logs on a malformed value" do + ::ENV["PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS"] = "fast,slow" + + expect(subject.logger).to receive(:error).with(/malformed interval list.*PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS/i) + expect(subject.nack_backoff_intervals).to eq([0, 1, 3, 5, 10]) + + ::ENV.delete("PB_NATS_CLIENT_NACK_BACKOFF_INTERVALS") + end end describe "#nack_backoff_splay" do @@ -161,10 +170,11 @@ def inbox_muxer_reply_to(inbox, msg_token) end describe "#send_request" do - let(:subscription_inbox) { ::Protobuf::Nats::Client::SubscriptionInbox.new(double("sub", :is_valid => true), "INBOX") } - before do - allow_any_instance_of(::Protobuf::Nats::Client).to receive(:new_subscription_inbox).and_return(subscription_inbox) + # Keep retry jitter out of timing-sensitive assertions by default. + # (allow_any_instance_of so we don't instantiate `subject` before the + # per-test client_nats_connection stub, which would start the muxer early.) + allow_any_instance_of(::Protobuf::Nats::Client).to receive(:reconnect_delay_splay).and_return(0) end it "retries 3 times when and raises a NATS timeout" do @@ -193,10 +203,149 @@ def inbox_muxer_reply_to(inbox, msg_token) allow(::Protobuf::Nats).to receive(:client_nats_connection).and_return(client) allow(client).to receive(:publish).and_raise(error) allow(subject).to receive(:setup_connection) - expect(subject).to receive(:reconnect_delay).and_return(0.01).exactly(3).times + # Only the two attempts followed by a retry wait; the final attempt + # raises without sleeping. + expect(subject).to receive(:reconnect_delay).and_return(0.01).twice expect { subject.send_request }.to raise_error(error) end + # Regression: when jnats was dropped for nats-pure, the rescue only matched + # the (never-raised) MriIOException, so a dropped connection escaped as an + # immediate RPC_ERROR instead of being retried. These cover the errors the + # pure-ruby client and socket layer actually raise on a broken connection. + [ + ::EOFError.new("EOF"), + ::IOError.new("stream closed"), + ::Errno::ECONNRESET.new, + ::Errno::EPIPE.new, + # A node dying without FIN/RST (partition, hard host failure) surfaces as + # unreachable-host/network errors while nats-pure fails over. + ::Errno::ECONNABORTED.new, + ::Errno::EHOSTUNREACH.new, + ::Errno::ENETUNREACH.new, + # Raised by the muxer when the memoized connection was closed and not yet + # rebuilt; must ride the same retry path. + ::Protobuf::Nats::Errors::ResponseMuxer.new("NATS connection unavailable"), + ].each do |transport_error| + it "retries and waits reconnect_delay on a #{transport_error.class} transport error" do + client = ::FakeNatsClient.new + allow(::Protobuf::Nats).to receive(:client_nats_connection).and_return(client) + allow(client).to receive(:publish).and_raise(transport_error) + allow(subject).to receive(:setup_connection) + expect(subject).to receive(:reconnect_delay).and_return(0.01).twice + expect { subject.send_request }.to raise_error(transport_error.class) + end + end + + it "recovers after a single transient transport error and returns the response" do + allow(subject).to receive(:setup_connection) + allow(subject).to receive(:reconnect_delay).and_return(0.01) + allow(subject).to receive(:parse_response) { subject.instance_variable_get(:@response_data) } + call_count = 0 + allow(subject).to receive(:nats_request_with_two_responses) do + call_count += 1 + raise ::Errno::ECONNRESET if call_count == 1 + "final count down" + end + + expect(subject.send_request).to eq("final count down") + expect(call_count).to eq(2) + end + + it "rebuilds the NATS connection and restarts the muxer before a transport retry" do + allow(subject).to receive(:setup_connection) + allow(subject).to receive(:reconnect_delay).and_return(0.01) + allow(subject).to receive(:parse_response) { subject.instance_variable_get(:@response_data) } + call_count = 0 + allow(subject).to receive(:nats_request_with_two_responses) do + call_count += 1 + raise ::Errno::ECONNRESET if call_count == 1 + "rebuilt" + end + + # One call on send_request entry, one rebuild in the retry path. + expect(::Protobuf::Nats).to receive(:start_client_nats_connection).twice + # The muxer restart only happens in the retry path. + expect(subject.response_muxer).to receive(:start).once + + expect(subject.send_request).to eq("rebuilt") + end + + it "does not attempt a rebuild after the final failed attempt" do + allow(subject).to receive(:setup_connection) + allow(subject).to receive(:reconnect_delay).and_return(0) + allow(subject).to receive(:nats_request_with_two_responses).and_raise(::Errno::ECONNRESET) + + # max_retries is 3: one entry call plus a rebuild before each of the two + # retries -- but none after the third (final) failure, which must raise + # immediately instead of wasting a reconnect attempt on a dead request. + expect(::Protobuf::Nats).to receive(:start_client_nats_connection).exactly(3).times + expect(subject.response_muxer).to receive(:start).twice + + expect { subject.send_request }.to raise_error(::Errno::ECONNRESET) + end + + it "still retries the request when the connection rebuild itself fails" do + allow(subject).to receive(:setup_connection) + allow(subject).to receive(:reconnect_delay).and_return(0.01) + allow(subject).to receive(:parse_response) { subject.instance_variable_get(:@response_data) } + call_count = 0 + allow(subject).to receive(:nats_request_with_two_responses) do + call_count += 1 + raise ::Errno::ECONNRESET if call_count == 1 + "recovered" + end + + # Only the in-retry rebuild fails (all nodes still down at that instant); + # the entry call must stay healthy or send_request never starts. + start_calls = 0 + allow(::Protobuf::Nats).to receive(:start_client_nats_connection) do + start_calls += 1 + raise ::Errno::ECONNREFUSED if start_calls > 1 + end + + expect(subject.send_request).to eq("recovered") + expect(call_count).to eq(2) + end + + it "does not sleep before raising on the final failed attempt" do + allow(subject).to receive(:setup_connection) + allow(subject).to receive(:reconnect_delay).and_return(5) + allow(subject).to receive(:nats_request_with_two_responses).and_raise(::Errno::ECONNRESET) + slept = 0 + allow(subject).to receive(:sleep) { slept += 1 } + + expect { subject.send_request }.to raise_error(::Errno::ECONNRESET) + # max_retries is 3: sleep before retry 2 and retry 3, but never before + # the final raise (that only delayed the failure by reconnect_delay). + expect(slept).to eq(2) + end + + it "adds jitter to the reconnect delay between transport retries" do + allow(subject).to receive(:reconnect_delay_splay).and_call_original + ::ENV["PB_NATS_CLIENT_RECONNECT_DELAY_SPLAY_LIMIT"] = "1000" + allow(subject).to receive(:reconnect_delay).and_return(0) + allow(subject).to receive(:setup_connection) + slept = [] + allow(subject).to receive(:sleep) { |s| slept << s } + allow(subject).to receive(:nats_request_with_two_responses).and_raise(::Errno::ECONNRESET) + + expect { subject.send_request }.to raise_error(::Errno::ECONNRESET) + # Jitter present (splay in [0,1)s) and bounded. + expect(slept).to all(be_between(0, 1)) + ensure + ::ENV.delete("PB_NATS_CLIENT_RECONNECT_DELAY_SPLAY_LIMIT") + end + + it "honors PB_NATS_CLIENT_MAX_RETRIES" do + ::ENV["PB_NATS_CLIENT_MAX_RETRIES"] = "2" + expect(subject).to receive(:setup_connection).exactly(2).times + expect(subject).to receive(:nats_request_with_two_responses).and_return(:ack_timeout).exactly(2).times + expect { subject.send_request }.to raise_error(::Protobuf::Nats::Errors::RequestTimeout) + ensure + ::ENV.delete("PB_NATS_CLIENT_MAX_RETRIES") + end + context "instrumentation" do it "instruments when a request times out" do allow(subject).to receive(:setup_connection) diff --git a/spec/protobuf/nats/config_spec.rb b/spec/protobuf/nats/config_spec.rb index eaf9d8a..f562abc 100644 --- a/spec/protobuf/nats/config_spec.rb +++ b/spec/protobuf/nats/config_spec.rb @@ -8,21 +8,90 @@ it "has default options without tls" do subject.servers = ["nats://127.0.0.1:4222"] + # Only nats-pure-recognized keys are forwarded to connect; app-level + # settings are read via their own accessors, not via connection_options. expected_options = { :servers => ["nats://127.0.0.1:4222"], :connect_timeout => nil, - :tls_ca_cert => nil, - :tls_client_cert => nil, - :tls_client_key => nil, - :uses_tls => false, :max_reconnect_attempts => 60_000, - :server_subscription_key_do_not_subscribe_to_when_includes_any_of => [], - :server_subscription_key_only_subscribe_to_when_includes_any_of => [], - :subscription_key_replacements => [], + :reconnect_time_wait => nil, + :ping_interval => nil, + :max_outstanding_pings => nil, + :name => ::Socket.gethostname, } expect(subject.connection_options).to eq(expected_options) end + # Failover tuning for a failing NATS node. All nil by default: nats-pure + # nil-fills each during connect, so forwarding nil never overrides its + # defaults (reconnect_time_wait: 2s, ping_interval: 120s, max_outstanding_pings: 2). + describe "failover tuning" do + it "forwards reconnect_time_wait, ping_interval and max_outstanding_pings when configured" do + subject.reconnect_time_wait = 1 + subject.ping_interval = 10 + subject.max_outstanding_pings = 2 + + options = subject.connection_options + expect(options[:reconnect_time_wait]).to eq(1) + expect(options[:ping_interval]).to eq(10) + expect(options[:max_outstanding_pings]).to eq(2) + end + + it "leaves them nil by default so nats-pure applies its own defaults" do + expect(subject.connection_options).to include( + :reconnect_time_wait => nil, + :ping_interval => nil, + :max_outstanding_pings => nil + ) + end + + it "forwards a negative max_reconnect_attempts (reconnect forever) unchanged" do + subject.max_reconnect_attempts = -1 + expect(subject.connection_options[:max_reconnect_attempts]).to eq(-1) + end + + it "loads the failover keys from yml" do + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" + + subject.load_from_yml + expect(subject.ping_interval).to eq(20) + expect(subject.max_outstanding_pings).to eq(3) + expect(subject.reconnect_time_wait).to eq(1) + ensure + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + end + + describe "connection name" do + it "falls back to the hostname when nothing is configured" do + expect(subject.connection_options[:name]).to eq(::Socket.gethostname) + end + + it "uses connection_name over the hostname when configured" do + subject.connection_name = "my-service" + expect(subject.connection_options[:name]).to eq("my-service") + end + + it "prefers the PB_NATS_CONNECTION_NAME env var over everything" do + subject.connection_name = "my-service" + ENV["PB_NATS_CONNECTION_NAME"] = "env-name" + expect(subject.connection_options[:name]).to eq("env-name") + ensure + ENV["PB_NATS_CONNECTION_NAME"] = nil + end + end + + it "does not forward app-level keys to nats-pure" do + subject.servers = ["nats://127.0.0.1:4222"] + subject.uses_tls = false + %i[uses_tls tls_client_cert tls_client_key tls_ca_cert + server_subscription_key_do_not_subscribe_to_when_includes_any_of + server_subscription_key_only_subscribe_to_when_includes_any_of + subscription_key_replacements].each do |app_key| + expect(subject.connection_options).not_to have_key(app_key) + end + end + it "can provide a tls context" do subject.servers = ["nats://127.0.0.1:4222"] subject.uses_tls = true @@ -30,6 +99,24 @@ expect(tls_context).to be_an(::OpenSSL::SSL::SSLContext) end + it "degrades to a TLS 1.2 ceiling when the OpenSSL build lacks TLS1_3_VERSION" do + hide_const("OpenSSL::SSL::TLS1_3_VERSION") + + context = nil + expect { context = subject.new_tls_context }.not_to raise_error + expect(context).to be_an(::OpenSSL::SSL::SSLContext) + end + + it "floors TLS at 1.2 and ceilings at 1.3" do + context = subject.new_tls_context + # Accessors are write-only on some OpenSSL builds, so assert via the C-level + # min/max which both JRuby 9.4 and 10.0 expose through the setters we used. + expect { context.min_version = ::OpenSSL::SSL::TLS1_2_VERSION }.not_to raise_error + expect(::OpenSSL::SSL::TLS1_2_VERSION).to eq(771) + expect(::OpenSSL::SSL::TLS1_3_VERSION).to eq(772) + expect(context).to be_an(::OpenSSL::SSL::SSLContext) + end + it "can load a custom cert into the ssl context" do ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" @@ -77,14 +164,13 @@ ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil end - it "adds the tls options to the connection options" do + it "builds a TLS context (from the configured certs) in the connection options" do ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" subject.load_from_yml - connection_options = subject.connection_options - expect(connection_options[:tls_client_cert]).to eq("./spec/support/certs/client-cert.pem") - expect(connection_options[:tls_client_key]).to eq("./spec/support/certs/client-key.pem") - expect(connection_options[:tls_ca_cert]).to eq("./spec/support/certs/ca.pem") + # The cert/key/ca are loaded into the TLS context, not forwarded as raw keys. + expect(subject.tls_client_cert).to eq("./spec/support/certs/client-cert.pem") + expect(subject.connection_options[:tls][:context]).to be_an(::OpenSSL::SSL::SSLContext) ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil end @@ -98,4 +184,91 @@ expect(subject.make_subscription_key_replacements("rpc.another_subscription")).to eq "rpc.different_subscription" expect(subject.make_subscription_key_replacements("rpc.subscription")).to eq "rpc.subscription" end + + # Negative cases: the file exists but does not yield a hash for the current + # environment. Previously these raised NoMethodError (nil[]) on boot. + it "loads defaults without raising when the yml has no section for the current environment" do + original_env = { "RAILS_ENV" => ENV["RAILS_ENV"], "RACK_ENV" => ENV["RACK_ENV"], "APP_ENV" => ENV["APP_ENV"] } + ENV["RAILS_ENV"] = "environment_that_does_not_exist" + ENV["RACK_ENV"] = nil + ENV["APP_ENV"] = nil + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" + + expect { subject.load_from_yml }.not_to raise_error + expect(subject.servers).to eq(nil) + expect(subject.max_reconnect_attempts).to eq(60_000) + ensure + original_env.each { |k, v| ENV[k] = v } + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + + it "loads defaults without raising when the yml file is empty" do + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/empty_protobuf_nats.yml" + + expect { subject.load_from_yml }.not_to raise_error + expect(subject.servers).to eq(nil) + expect(subject.uses_tls).to eq(false) + ensure + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + + # #2 -- safe_load boundary. The config switched from YAML.unsafe_load to + # safe_load(aliases: true): YAML anchors/merge keys must still work, but + # arbitrary Ruby object deserialization must now be rejected. + describe "safe YAML loading" do + it "still resolves anchors and merge keys (aliases enabled)" do + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" + + # The fixture defines `&defaults` and merges it via `<<: *defaults` into + # each environment; this only loads cleanly when aliases are permitted. + expect { subject.load_from_yml }.not_to raise_error + expect(subject.max_reconnect_attempts).to eq(1234) + ensure + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + + it "rejects arbitrary Ruby object deserialization" do + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/unsafe_protobuf_nats.yml" + + expect { subject.load_from_yml }.to raise_error(::Psych::DisallowedClass) + ensure + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + end + + # #1 -- the supplied TLS context must actually verify the server certificate. + # nats-pure uses our context verbatim and skips its own set_params, so without + # this the OpenSSL default (VERIFY_NONE) accepted any certificate. + describe "TLS server certificate verification" do + it "verifies the peer certificate chain" do + subject.uses_tls = true + context = subject.new_tls_context + + expect(context.verify_mode).to eq(::OpenSSL::SSL::VERIFY_PEER) + expect(context.verify_mode).not_to eq(::OpenSSL::SSL::VERIFY_NONE) + end + + it "trusts the configured CA bundle" do + ENV["PROTOBUF_NATS_CONFIG_PATH"] = "spec/support/protobuf_nats.yml" + subject.load_from_yml + + # With a CA configured, a dedicated store (not the system default) backs + # verification. add_file would have raised on a bad path, so reaching here + # with a store and VERIFY_PEER means the CA was loaded. + context = subject.new_tls_context + expect(subject.tls_ca_cert).to eq("./spec/support/certs/ca.pem") + expect(context.cert_store).to be_an(::OpenSSL::X509::Store) + expect(context.verify_mode).to eq(::OpenSSL::SSL::VERIFY_PEER) + ensure + ENV["PROTOBUF_NATS_CONFIG_PATH"] = nil + end + + it "falls back to the system trust store when no CA is configured" do + subject.uses_tls = true + subject.tls_ca_cert = nil + + expect { subject.new_tls_context }.not_to raise_error + expect(subject.new_tls_context.cert_store).to be_an(::OpenSSL::X509::Store) + end + end end diff --git a/spec/protobuf/nats/response_muxer_spec.rb b/spec/protobuf/nats/response_muxer_spec.rb index 49a4cf8..7f8d81f 100644 --- a/spec/protobuf/nats/response_muxer_spec.rb +++ b/spec/protobuf/nats/response_muxer_spec.rb @@ -29,10 +29,10 @@ it "logs a per-message error and continues processing" do allow(nats_client).to receive(:subscribe).and_return(subscription) - # Create a message that will cause an error during processing - # We need it to pass subject validation but fail later - bad_message = double(:subject => "valid.subject.token", :data => "bar") - allow(bad_message).to receive(:data).and_raise(StandardError, "Simulated error") + # Create a message that raises while being processed (dispatch_message + # reads #subject first) so we hit the per-message rescue. + bad_message = double(:data => "bar") + allow(bad_message).to receive(:subject).and_raise(StandardError, "Simulated error") allow(queue).to receive(:pop).and_return(bad_message, nil) expect(subject.logger).to receive(:error).with(/failed to process a message/i).once @@ -86,12 +86,7 @@ subject.send(:start) # Wait until start has been called twice. - retries = 0 - - until mutex.synchronize { start_calls } >= 2 || retries > 20 # 2 seconds - sleep 0.1 - retries += 1 - end + wait_until(timeout: 3) { mutex.synchronize { start_calls } >= 2 } expect(mutex.synchronize { start_calls }).to be >= 2 # Verify sleep was called at least once (could be from cleanup thread or crash recovery) @@ -100,6 +95,37 @@ end end + describe "#start after the connection is replaced" do + it "restarts onto the new connection instead of staying subscribed to the dead one" do + subject.start + expect(subject.started?).to be(true) + old_sub = subject.instance_variable_get(:@resp_sub) + + # Simulate on_close dropping the memoized client and the next request + # building a fresh connection. + new_client = ::FakeNatsClient.new(:inbox => "_INBOX.NEW") + allow(::Protobuf::Nats).to receive(:client_nats_connection).and_return(new_client) + expect(subject.logger).to receive(:warn).with(/connection was replaced/i) + + subject.start + + expect(subject.started?).to be(true) + expect(subject.subscribed_to?(new_client)).to be(true) + expect(subject.instance_variable_get(:@resp_sub)).not_to equal(old_sub) + expect(subject.instance_variable_get(:@resp_inbox_prefix)).to start_with("_INBOX.NEW") + end + + it "is a no-op when the connection is unchanged" do + subject.start + old_sub = subject.instance_variable_get(:@resp_sub) + + expect(subject).not_to receive(:restart) + subject.start + + expect(subject.instance_variable_get(:@resp_sub)).to equal(old_sub) + end + end + describe "edge cases and vulnerabilities" do describe "concurrent restart protection" do it "prevents multiple concurrent restart calls" do @@ -180,7 +206,7 @@ # Kill the handler to make it dead original_handler.kill - sleep 0.05 + wait_until { !original_handler.alive? } expect(original_handler).not_to be_alive # Trigger restart @@ -189,6 +215,42 @@ handlers = subject.instance_variable_get(:@resp_handlers) expect(handlers.any? { |t| !t.alive? }).to be(false) 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 + allow(nats_client).to receive(:subscribe).and_return(subscription) + # Make the self-healing backoff instant so the test doesn't wait. + allow(::Protobuf::Nats).to receive(:crash_backoff_seconds).and_return(0) + + 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 # replacement dispatcher parks here and stays alive + nil + end + + subject.send(:start) + crashed = subject.instance_variable_get(:@resp_handlers).first + + # The crashed dispatcher must exit and be replaced -- previously the + # still-alive crashing thread was counted by start's top-up, so no + # replacement spawned and the pool dropped to zero dispatchers. + wait_until(timeout: 3) { !crashed.alive? } + wait_until(timeout: 3) do + handlers = subject.instance_variable_get(:@resp_handlers) + handlers.count(&:alive?) >= 1 && !handlers.include?(crashed) + end + + handlers = subject.instance_variable_get(:@resp_handlers) + expect(handlers.count(&:alive?)).to eq(1) + expect(handlers).not_to include(crashed) + + handlers.each(&:kill) + end end describe "cleanup while next_message is waiting" do @@ -375,25 +437,142 @@ end end - describe "pending_size accounting" do - it "does not crash if pending_size goes negative" do + describe "in-flight requests during a restart" do + after { subject.stop } + + it "wakes waiters immediately instead of leaving them to burn the full timeout" do + subject.start + req = subject.new_request + + waiter_error = nil + waiter = Thread.new do + begin + # Deliberately generous timeout: without the wake-on-restart this + # would block for 5s and the join below would fail fast. + req.next_message(5) + rescue => e + waiter_error = e + end + end + wait_until { waiter.status == "sleep" } + + subject.restart + + expect(waiter.join(1)).to eq(waiter), "waiter was not woken by the restart" + expect(waiter_error).to be_a(::NATS::Timeout) + end + + it "still serves new requests created after the restart" do + subject.start + subject.restart + + req = subject.new_request + req.publish("test.subject", "data") + message = nats_client.published_messages.last + # The reply inbox must carry the *new* prefix so responses route to the + # rebuilt subscription. + expect(message[:reply_to]).to start_with(subject.instance_variable_get(:@resp_inbox_prefix)) + end + end + + describe "start fast path" do + after { subject.stop } + + it "does not take the muxer LOCK when already started on the current connection" do + subject.start + + # Spy (not a message expectation) so the after-hook stop, which + # legitimately takes LOCK, doesn't fail the example. + allow(::Protobuf::Nats::ResponseMuxer::LOCK).to receive(:synchronize).and_call_original + subject.start + expect(::Protobuf::Nats::ResponseMuxer::LOCK).not_to have_received(:synchronize) + end + + it "still detects a replaced connection (negative: fast path must not mask staleness)" do + subject.start + + new_client = ::FakeNatsClient.new + allow(::Protobuf::Nats).to receive(:client_nats_connection).and_return(new_client) + expect(subject).to receive(:restart).and_call_original + + subject.start + expect(subject.subscribed_to?(new_client)).to be(true) + end + end + + describe "publish after the connection was closed" do + after { subject.stop } + + it "raises the retryable ResponseMuxer error instead of NoMethodError on nil" do + subject.start + # nats-pure fired on_close and the memoized connection was dropped; the + # next request has not rebuilt it yet. + allow(::Protobuf::Nats).to receive(:client_nats_connection).and_return(nil) + + expect { + subject.publish("test.subject", "data", "token123") + }.to raise_error(::Protobuf::Nats::Errors::ResponseMuxer, /connection unavailable/i) + end + + it "publishes normally while the connection is present" do + subject.start + + subject.publish("test.subject", "data", "token123") + + message = nats_client.published_messages.last + expect(message[:subject]).to eq("test.subject") + expect(message[:data]).to eq("data") + expect(message[:reply_to]).to end_with(".token123") + end + end + + describe "slow-consumer protection" do + # The muxer bounds the response firehose by BOTH message count and bytes. + # To keep the byte limit finite it mirrors nats-pure's pending_size + # accounting on the dispatch hot path (decrement after each pop), so the + # counter can't drift and false-trip. See ResponseMuxer#run_dispatch_loop. + it "sets a finite byte-based slow-consumer limit on the response subscription" do subject.start subscription = subject.instance_variable_get(:@resp_sub) - # Manually set pending_size to a small value - subscription.pending_size = 5 + expect(subscription.pending_bytes_limit).to eq(::Protobuf::Nats::ResponseMuxer::DEFAULT_RESPONSE_QUEUE_BYTES) + expect(subscription.pending_bytes_limit).to be_finite + end + + it "routes messages without depending on pending_size" do + subject.start + subscription = subject.instance_variable_get(:@resp_sub) + # A drifted/arbitrary pending_size must not affect delivery. + subscription.pending_size = 10_000_000 req = subject.new_request token = req.instance_variable_get(:@token) + subscription.pending_queue.push(::NATS::Msg.new(:subject => "#{subscription.subject}.#{token}", :data => "response")) - # Send a message with data larger than pending_size - msg = double(:subject => "#{subscription.subject}.#{token}", :data => "x" * 100) - subscription.pending_queue.push(msg) + message = req.next_message(2) + expect(message.data).to eq("response") + end + end - sleep 0.1 + describe "self-healing backoff counter" do + it "uses an atomic counter that decays once a dispatcher is healthy" do + subject.start + crash_count = subject.instance_variable_get(:@crash_count) + expect(crash_count).to be_a(::Concurrent::AtomicFixnum) + + # Simulate accumulated crashes, then prove a healthy dispatch resets it + # (so a later transient crash restarts the backoff from 1s). + crash_count.value = 5 + + subscription = subject.instance_variable_get(:@resp_sub) + req = subject.new_request + token = req.instance_variable_get(:@token) + subscription.pending_queue.push(::NATS::Msg.new(:subject => "#{subscription.subject}.#{token}", :data => "ok")) + req.next_message(2) - # pending_size should now be negative - expect(subscription.pending_size).to be < 0 + deadline = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + 2 + sleep 0.01 until crash_count.value.zero? || ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) > deadline + expect(crash_count.value).to eq(0) end end @@ -462,22 +641,19 @@ end describe "crash count growth" do - it "resets crash count to 0 on successful start" do + it "does not reset the crash count merely by starting (only after a healthy dispatch)" do subscription = nats_client.subscribe("test.subscription") - queue = subscription.pending_queue allow(nats_client).to receive(:subscribe).and_return(subscription) - # Manually set crash count to a high value before start - subject.instance_variable_set(:@crash_count, 5) - subject.start - # Give the handler thread time to start and reset the counter + # Simulate accumulated crashes while the dispatcher idles with no work. + # Starting/idling must NOT wipe the backoff state (the old eager reset + # defeated the exponential backoff under a sustained crash loop). + subject.instance_variable_get(:@crash_count).value = 5 sleep 0.1 - # With the fix, crash count is reset to 0 on successful start - actual_crash_count = subject.instance_variable_get(:@crash_count) - expect(actual_crash_count).to eq(0) + expect(subject.instance_variable_get(:@crash_count).value).to eq(5) end it "uses exponential backoff capped at 60 seconds" do @@ -665,6 +841,8 @@ # Expect warnings for stale tokens expect(subject.logger).to receive(:warn).with(/cleaning up stale token #{token1}/i) expect(subject.logger).to receive(:warn).with(/cleaning up stale token #{token3}/i) + # Tolerate the firehose-depth gauges cleanup_stale_tokens also emits. + allow(::ActiveSupport::Notifications).to receive(:instrument).and_call_original expect(::ActiveSupport::Notifications).to receive(:instrument).with("response_muxer.stale_tokens_cleaned.protobuf-nats", 2) # Run cleanup @@ -827,4 +1005,240 @@ expect(cleanup_thread.join(0.5)).to eq(cleanup_thread) end end + + describe "response firehose bound" do + let(:subscription) { nats_client.subscribe("test.subscription") } + + before { allow(nats_client).to receive(:subscribe).and_return(subscription) } + after { subject.stop } + + it "caps the shared response subscription at the default message count instead of nats-pure's 65,536" do + subject.start + expect(subscription.pending_msgs_limit).to eq(::Protobuf::Nats::ResponseMuxer::DEFAULT_RESPONSE_QUEUE_SIZE) + expect(subscription.pending_msgs_limit).to be < ::NATS::IO::DEFAULT_SUB_PENDING_MSGS_LIMIT + end + + it "caps the shared response subscription by bytes with a finite limit (not INFINITY)" do + subject.start + expect(subscription.pending_bytes_limit).to eq(::Protobuf::Nats::ResponseMuxer::DEFAULT_RESPONSE_QUEUE_BYTES) + expect(subscription.pending_bytes_limit).to be_finite + end + + it "raises when the subscription cannot support pending_size byte accounting (no #synchronize)" do + # A subscription missing #synchronize means nats-pure's internals changed in + # a way that breaks byte accounting -- start must fail loudly, not degrade. + no_monitor_sub = Class.new do + attr_accessor :pending_msgs_limit, :pending_bytes_limit + attr_reader :pending_queue + def initialize; @pending_queue = ::SizedQueue.new(16); end + def subject; "no.monitor"; end + def unsubscribe; end + end.new + allow(nats_client).to receive(:subscribe).and_return(no_monitor_sub) + + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + + expect(no_monitor_sub.respond_to?(:synchronize)).to be(false) + expect { muxer.start }.to raise_error(::Protobuf::Nats::Errors::IncompatibleSubscription, /synchronize/) + ensure + muxer.stop + end + + it "honors PB_NATS_RESPONSE_MUXER_QUEUE_SIZE" do + previous = ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = "42" + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + + muxer.start + expect(subscription.pending_msgs_limit).to eq(42) + ensure + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = previous + muxer.stop + end + + it "honors PB_NATS_RESPONSE_MUXER_QUEUE_BYTES" do + previous = ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] = "1048576" + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + + muxer.start + expect(subscription.pending_bytes_limit).to eq(1_048_576) + ensure + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] = previous + muxer.stop + end + + # Negative paths: a malformed or out-of-range override must not silently + # become 0 (which would drop every response); it falls back to the default. + it "falls back to the default message count when PB_NATS_RESPONSE_MUXER_QUEUE_SIZE is malformed" do + previous = ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = "not-a-number" + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + + muxer.start + expect(subscription.pending_msgs_limit).to eq(::Protobuf::Nats::ResponseMuxer::DEFAULT_RESPONSE_QUEUE_SIZE) + ensure + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = previous + muxer.stop + end + + it "falls back to the default byte ceiling when PB_NATS_RESPONSE_MUXER_QUEUE_BYTES is out of range" do + previous = ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] = "0" # below the min of 1 + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + + muxer.start + expect(subscription.pending_bytes_limit).to eq(::Protobuf::Nats::ResponseMuxer::DEFAULT_RESPONSE_QUEUE_BYTES) + ensure + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] = previous + muxer.stop + end + + it "reports zero firehose depth before the muxer has started" do + expect(described_class.new.pending_queue_size).to eq(0) + end + end + + describe "firehose limit binding (min of count and bytes)" do + let(:subscription) { nats_client.subscribe("test.subscription") } + + before { allow(nats_client).to receive(:subscribe).and_return(subscription) } + + # Simulate nats-pure's read-thread admission (client.rb #process_msg): a + # message is accepted only while BOTH pending_queue.size < pending_msgs_limit + # AND pending_size < pending_bytes_limit; accepting one accounts its bytes + # exactly as Subscription#dispatch does. Returns the number admitted before a + # limit trips (a SlowConsumer drop). + def admit_until_full(sub, payload, cap: 100_000) + admitted = 0 + while admitted < cap + break if sub.pending_queue.size >= sub.pending_msgs_limit + break if sub.pending_size >= sub.pending_bytes_limit + sub.pending_queue.push(::NATS::Msg.new(:subject => "reply.x", :data => payload)) + sub.synchronize { sub.pending_size += payload.size } + admitted += 1 + end + admitted + end + + # Freeze the firehose the muxer configured: stop the dispatchers so nothing + # drains while we fill it, and reset to a clean baseline. + def freeze_firehose(muxer, sub) + muxer.instance_variable_get(:@resp_handlers).each { |t| t.kill; t.join(1) } + sub.pending_queue.clear + sub.synchronize { sub.pending_size = 0 } + end + + it "trips the byte ceiling well before the message-count cap when messages are large" do + # 1 MiB of bytes but 10,000 messages allowed: bytes must bind first. + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_BYTES"] = (1024 * 1024).to_s + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = "10000" + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + muxer.start + freeze_firehose(muxer, subscription) + + admitted = admit_until_full(subscription, "x" * (256 * 1024)) # 256 KiB each + + # 1 MiB / 256 KiB == 4 large messages, far below the 10,000-message cap: + # the heap ceiling, not the count, is what stops the firehose. + expect(admitted).to eq(4) + expect(subscription.pending_queue.size).to be < subscription.pending_msgs_limit + expect(subscription.pending_size).to be >= subscription.pending_bytes_limit + ensure + ENV.delete("PB_NATS_RESPONSE_MUXER_QUEUE_BYTES") + ENV.delete("PB_NATS_RESPONSE_MUXER_QUEUE_SIZE") + muxer.stop + end + + it "trips the message-count cap first when messages are tiny" do + # Tiny messages can never reach the 64 MiB byte ceiling, so the count binds. + ENV["PB_NATS_RESPONSE_MUXER_QUEUE_SIZE"] = "8" + muxer = described_class.new + allow(muxer).to receive(:logger).and_return(::Logger.new(nil)) + muxer.start + freeze_firehose(muxer, subscription) + + admitted = admit_until_full(subscription, "x") # 1 byte each + + expect(admitted).to eq(8) + expect(subscription.pending_queue.size).to eq(subscription.pending_msgs_limit) + expect(subscription.pending_size).to be < subscription.pending_bytes_limit + ensure + ENV.delete("PB_NATS_RESPONSE_MUXER_QUEUE_SIZE") + muxer.stop + end + end + + describe "pending_size byte accounting" do + let(:subscription) { nats_client.subscribe("test.subscription") } + + before { allow(nats_client).to receive(:subscribe).and_return(subscription) } + after { subject.stop } + + it "decrements the subscription's pending_size after draining a message so a finite byte limit stays accurate" do + subject.start + + # Register a token so dispatch_message routes (not drops) the message. + req = subject.new_request + token = req.instance_variable_get(:@token) + + # Simulate nats-pure's read thread: enqueue a message and account its bytes + # into pending_size (Subscription#dispatch does size accounting on push). + data = "x" * 500 + message = ::NATS::Msg.new(:subject => "reply.#{token}", :data => data) + subscription.synchronize { subscription.pending_size += data.size } + subscription.pending_queue.push(message) + + # The dispatcher should pop it and decrement pending_size back toward zero. + wait_until { subscription.pending_size.zero? } + expect(subscription.pending_size).to eq(0) + end + end + + describe "firehose depth instrumentation" do + let(:subscription) { nats_client.subscribe("test.subscription") } + + before { allow(nats_client).to receive(:subscribe).and_return(subscription) } + after { subject.stop } + + it "emits current depth and a per-cycle peak on cleanup" do + subject.start + + events = [] + callback = lambda do |name, _start, _finish, _id, payload| + events << [name, payload] + end + + ::ActiveSupport::Notifications.subscribed(callback, /response_muxer\.pending_queue/) do + subject.cleanup_stale_tokens + end + + names = events.map(&:first) + expect(names).to include("response_muxer.pending_queue_size.protobuf-nats") + expect(names).to include("response_muxer.pending_queue_peak.protobuf-nats") + end + + it "resets the peak high-water mark after each cleanup cycle" do + subject.start + peak = subject.instance_variable_get(:@pending_queue_peak) + peak.value = 17 + + captured = nil + callback = lambda do |_name, _start, _finish, _id, payload| + captured = payload + end + ::ActiveSupport::Notifications.subscribed(callback, "response_muxer.pending_queue_peak.protobuf-nats") do + subject.cleanup_stale_tokens + end + + expect(captured).to eq(17) + expect(peak.value).to eq(0) + end + end end diff --git a/spec/protobuf/nats/server_spec.rb b/spec/protobuf/nats/server_spec.rb index 813d074..981dd9e 100644 --- a/spec/protobuf/nats/server_spec.rb +++ b/spec/protobuf/nats/server_spec.rb @@ -22,6 +22,15 @@ def implemented_again; end subject { described_class.new(options) } + # Keep one intake handler by default so these tests don't spawn processor_count + # threads per subject; the fan-out itself is covered in the manager spec. + around do |example| + previous = ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "1" + example.run + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = previous + end + before do allow(::Protobuf::Logging).to receive(:logger).and_return(logger) allow(subject).to receive(:service_klasses).and_return([SomeRandomService]) @@ -105,6 +114,52 @@ def implemented_again; end end end + describe "#stale_request?" do + # Build a syntactically valid UUIDv7 whose embedded timestamp is `time`. + def uuidv7_at(time) + ms = (time.to_f * 1000).to_i & 0xffffffffffff + format("%08x-%04x-7%03x-%04x-%04x%08x", + (ms >> 16) & 0xffffffff, ms & 0xffff, 0x123, 0x8123, 0x4567, 0x89abcdef) + end + + def reply_id_for(token) + "_INBOX.someprefix.#{token}" + end + + it "is off by default (returns false even for an old token)" do + expect(subject.stale_request?(reply_id_for(uuidv7_at(Time.now - 3600)))).to eq(false) + end + + context "when PB_NATS_SERVER_STALE_REQUEST_MS is set" do + around do |example| + ::ENV["PB_NATS_SERVER_STALE_REQUEST_MS"] = "1000" + example.run + ensure + ::ENV.delete("PB_NATS_SERVER_STALE_REQUEST_MS") + end + + it "sheds a request older than the threshold and instruments it" do + age_ms = nil + subscription = ::ActiveSupport::Notifications.subscribe "server.stale_request_dropped.protobuf-nats" do |_, _, _, _, payload| + age_ms = payload + end + + expect(subject.stale_request?(reply_id_for(uuidv7_at(Time.now - 10)))).to eq(true) + expect(age_ms).to be > 1000 + ::ActiveSupport::Notifications.unsubscribe(subscription) + end + + it "keeps a fresh request" do + expect(subject.stale_request?(reply_id_for(::Protobuf::Nats::UUIDv7Helper.generate))).to eq(false) + end + + it "keeps a request whose reply token is not a UUIDv7 (foreign client)" do + expect(subject.stale_request?(reply_id_for("aBcDeFnuidStyleToken00"))).to eq(false) + expect(subject.stale_request?(nil)).to eq(false) + end + end + end + describe "pause_file_path" do it "is nil by default" do expect(subject.pause_file_path).to eq(nil) @@ -302,12 +357,271 @@ def implemented_again; end response = "some response data" inbox = "inbox_123" expect(subject).to receive(:handle_request).and_return(response) - expect(client).to receive(:publish).once.ordered.with(inbox, ::Protobuf::Nats::Messages::ACK) - expect(client).to receive(:publish).once.ordered.with(inbox, response) - # Wait for promise to finish executing. + # The ACK is published on the intake thread and the response on a worker + # thread, so their order is NOT guaranteed (the client muxer accepts either + # order). Record both via a thread-safe Queue and assert order-independently. + published = ::Queue.new + allow(client).to receive(:publish) { |reply_id, data| published << [reply_id, data] } + expect(subject.enqueue_request("", inbox)).to eq(true) + wait_until { published.size >= 2 } + + got = [] + got << published.pop until published.empty? + expect(got).to contain_exactly( + [inbox, ::Protobuf::Nats::Messages::ACK], + [inbox, response], + ) + end + + # Negative: when handling the request fails after the ACK was sent, the + # client is blocked waiting for a response. The server must publish an + # encoded RPC error so the client fails fast instead of hanging until + # response_timeout. + it "publishes a generic encoded RPC error response when the request handler raises" do + inbox = "inbox_123" + allow(::Protobuf::Nats).to receive(:notify_error_callbacks) + expect(subject).to receive(:handle_request).and_raise(::RuntimeError, "boom") + + # ACK (intake thread) and error response (worker thread) race; record both + # via a thread-safe Queue and assert order-independently. + published = ::Queue.new + allow(client).to receive(:publish) { |reply_id, data| published << [reply_id, data] } + + expect(subject.enqueue_request("req", inbox)).to eq(true) + wait_until { published.size >= 2 } + + got = [] + got << published.pop until published.empty? + expect(got).to include([inbox, ::Protobuf::Nats::Messages::ACK]) + + error_payload = got.find { |reply_id, data| reply_id == inbox && data != ::Protobuf::Nats::Messages::ACK }&.last + expect(error_payload).not_to be_nil + decoded = ::Protobuf::Socketrpc::Response.decode(error_payload) + # Generic message -- internal handler details ("boom") are not leaked. + expect(decoded.error).to eq("Internal server error") + expect(decoded.error).not_to include("boom") + expect(decoded.error_reason).to eq(::Protobuf::Socketrpc::ErrorReason::RPC_ERROR) + end + + it "does not raise when publishing the error response also fails" do + inbox = "inbox_123" + allow(::Protobuf::Nats).to receive(:notify_error_callbacks) + expect(subject).to receive(:handle_request).and_raise(::RuntimeError, "boom") + # Any publish blows up (e.g. connection dropped) except the ACK, which we + # let through so the failure happens on the error-response publish. + allow(client).to receive(:publish).and_raise(::Errno::ECONNRESET) + allow(client).to receive(:publish).with(inbox, ::Protobuf::Nats::Messages::ACK) + expect(logger).to receive(:error).with(/Failed to publish error response/) + + expect { subject.enqueue_request("req", inbox) }.not_to raise_error + sleep 0.1 until subject.thread_pool.size.zero? + end + + it "does not emit a duplicate error response when the success-response publish fails" do + inbox = "inbox_pub_fail" + allow(::Protobuf::Nats).to receive(:notify_error_callbacks) + expect(subject).to receive(:handle_request).and_return("ok") + allow(logger).to receive(:error) + + publishes = [] + allow(client).to receive(:publish) do |reply_id, data| + publishes << [reply_id, data] + raise ::Errno::ECONNRESET if data == "ok" # only the response publish fails + end + expect(logger).to receive(:error).with(/Failed to publish response/) + + expect(subject.enqueue_request("req", inbox)).to eq(true) sleep 0.1 until subject.thread_pool.size.zero? + + # The only publishes to the reply inbox are the ACK and the (failed) + # response attempt -- NOT a follow-up PbError for a request that succeeded. + extra = publishes.select do |reply_id, data| + reply_id == inbox && data != ::Protobuf::Nats::Messages::ACK && data != "ok" + end + expect(extra).to be_empty + end + end + + describe "#shutdown_drain_timeout" do + it "defaults above the handler overdue window so long handlers can finish" do + expect(subject.shutdown_drain_timeout).to be > (subject.handler_overdue_ms / 1000.0) + end + + it "is configurable via PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT" do + ENV["PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT"] = "12.5" + expect(subject.shutdown_drain_timeout).to eq(12.5) + ensure + ENV.delete("PB_NATS_SERVER_SHUTDOWN_DRAIN_TIMEOUT") + end + end + + describe "handler observability" do + def capture(event) + seen = [] + sub = ::ActiveSupport::Notifications.subscribe(event) { |_, _, _, _, payload| seen << payload } + yield + ::ActiveSupport::Notifications.unsubscribe(sub) + seen + end + + it "allows a long-running handler to complete without aborting or flagging it" do + # Defaults: slow=off, overdue=65s. A handler that runs a while is normal. + inbox = "inbox_long" + allow(subject).to receive(:handle_request) { sleep 0.3; "done" } + + slow = capture("server.slow_handler.protobuf-nats") do + expect(client).to receive(:publish).with(inbox, ::Protobuf::Nats::Messages::ACK) + expect(client).to receive(:publish).with(inbox, "done") # completed, not aborted + subject.enqueue_request("req", inbox) + sleep 0.1 until subject.thread_pool.size.zero? + end + + expect(slow).to be_empty + end + + it "emits server.slow_handler only when the slow threshold is exceeded" do + ENV["PB_NATS_SERVER_SLOW_HANDLER_THRESHOLD_MS"] = "1" + allow(subject).to receive(:handle_request) { sleep 0.05; "ok" } + + slow = capture("server.slow_handler.protobuf-nats") do + subject.enqueue_request("req", "inbox") + sleep 0.1 until subject.thread_pool.size.zero? + end + + expect(slow.size).to eq(1) + expect(slow.first).to be >= 1 + ensure + ENV.delete("PB_NATS_SERVER_SLOW_HANDLER_THRESHOLD_MS") + end + + it "tracks in-flight handlers and clears them on completion" do + release = ::Queue.new + allow(subject).to receive(:handle_request) { release.pop; "ok" } + allow(client).to receive(:publish) + + subject.enqueue_request("req", "inbox") + # Wait for the worker to actually start and register in-flight (don't race a + # fixed sleep against thread scheduling). + wait_until { subject.instance_variable_get(:@inflight).size >= 1 } + + inflight = capture("server.inflight_count.protobuf-nats") { subject.instrument_inflight_handlers } + expect(inflight.last).to be >= 1 + + release << :go + sleep 0.1 until subject.thread_pool.size.zero? + + cleared = capture("server.inflight_count.protobuf-nats") { subject.instrument_inflight_handlers } + expect(cleared.last).to eq(0) + end + + it "flags an overdue handler past the window but counts a long-but-not-overdue one as in-flight only" do + ENV["PB_NATS_SERVER_HANDLER_OVERDUE_MS"] = "50" + release = ::Queue.new + allow(subject).to receive(:handle_request) { release.pop; "ok" } + allow(client).to receive(:publish) + + subject.enqueue_request("req", "inbox") + # Wait for in-flight registration, then exceed the 50ms overdue window while + # the handler is still blocked. + wait_until { subject.instance_variable_get(:@inflight).size >= 1 } + sleep 0.07 + + overdue_events = capture("server.handler_overdue.protobuf-nats") do + @overdue_count = capture("server.overdue_handler_count.protobuf-nats") do + subject.instrument_inflight_handlers + end + end + + expect(overdue_events.size).to eq(1) + expect(@overdue_count.last).to be >= 1 + ensure + release << :go + ENV.delete("PB_NATS_SERVER_HANDLER_OVERDUE_MS") + sleep 0.1 until subject.thread_pool.size.zero? + end + + it "does not abort an overdue handler by default (handlers are never aborted)" do + ENV["PB_NATS_SERVER_HANDLER_OVERDUE_MS"] = "50" + release = ::Queue.new + allow(subject).to receive(:handle_request) { release.pop; "ok" } + allow(client).to receive(:publish) + + subject.enqueue_request("req", "inbox") + wait_until { subject.instance_variable_get(:@inflight).size >= 1 } + sleep 0.07 # exceed the overdue window while still in-flight + + reclaimed = capture("server.handler_reclaimed.protobuf-nats") do + subject.instrument_inflight_handlers + end + + # Flagged overdue, but not reclaimed -- it stays in-flight until released. + expect(reclaimed).to be_empty + expect(subject.thread_pool.size).to be >= 1 + ensure + release << :go + ENV.delete("PB_NATS_SERVER_HANDLER_OVERDUE_MS") + sleep 0.1 until subject.thread_pool.size.zero? + end + + it "reclaims an overdue handler when PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS is enabled" do + ENV["PB_NATS_SERVER_HANDLER_OVERDUE_MS"] = "50" + ENV["PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS"] = "true" + release = ::Queue.new + # Blocks until released OR until HandlerOverdue is raised into the thread. + allow(subject).to receive(:handle_request) { release.pop; "ok" } + allow(client).to receive(:publish) + + subject.enqueue_request("req", "inbox") + wait_until { subject.instance_variable_get(:@inflight).size >= 1 } + sleep 0.07 # exceed the overdue window while still in-flight + + reclaimed = capture("server.handler_reclaimed.protobuf-nats") do + subject.instrument_inflight_handlers + end + + expect(reclaimed.size).to eq(1) + # The handler thread was aborted, so the pool drains without releasing it. + wait_until(timeout: 2) { subject.thread_pool.size.zero? } + ensure + release << :go rescue nil + ENV.delete("PB_NATS_SERVER_HANDLER_OVERDUE_MS") + ENV.delete("PB_NATS_SERVER_RECLAIM_OVERDUE_HANDLERS") + end + + it "reaps orphaned overdue flags whose handler is no longer in-flight" do + inflight = subject.instance_variable_get(:@inflight) + overdue_flagged = subject.instance_variable_get(:@overdue_flagged) + + # An overdue flag left behind by the set-after-ensure-delete race: its id + # is not in @inflight, so nothing else would ever remove it. + overdue_flagged[:orphan] = true + # A flag for a still-in-flight handler must be preserved. + inflight[:live] = [subject.send(:monotonic), ::Thread.current] + overdue_flagged[:live] = true + + subject.instrument_inflight_handlers + + expect(overdue_flagged.key?(:orphan)).to be(false) + expect(overdue_flagged.key?(:live)).to be(true) + ensure + inflight.delete(:live) + overdue_flagged.delete(:live) + end + + it "emits server.thread_pool_saturated and NACKs when the pool is full" do + # Fill the pool + queue (threads: 2, max_queue defaults to threads). + 4.times { subject.thread_pool.push { sleep 1 } } + + allow(client).to receive(:publish) + saturated = capture("server.thread_pool_saturated.protobuf-nats") do + expect(client).to receive(:publish).with("inbox", ::Protobuf::Nats::Messages::NACK) + expect(subject.enqueue_request("", "inbox")).to eq(false) + end + + expect(saturated.size).to eq(1) + subject.thread_pool.kill end end @@ -480,6 +794,44 @@ def implemented_again; end end end + describe "connection lifecycle" do + it "registers all lifecycle callbacks at initialize, before connect" do + subject # force initialize + expect(client.callbacks.keys).to match_array(%i[disconnect reconnect error close]) + end + + it "stops the server when the connection closes unexpectedly (reconnects exhausted)" do + subject # force initialize so callbacks are registered + instrumented = false + subscription = ::ActiveSupport::Notifications.subscribe("server.connection_closed.protobuf-nats") do + instrumented = true + end + expect(logger).to receive(:error).with(/closed unexpectedly/i) + + client.fire_callback(:close) + + expect(subject.instance_variable_get(:@running)).to be(false) + expect(instrumented).to be(true) + ensure + ::ActiveSupport::Notifications.unsubscribe(subscription) + end + + it "does not treat a close during graceful shutdown as a failure" do + subject.stop + instrumented = false + subscription = ::ActiveSupport::Notifications.subscribe("server.connection_closed.protobuf-nats") do + instrumented = true + end + expect(logger).not_to receive(:error) + + client.fire_callback(:close) + + expect(instrumented).to be(false) + ensure + ::ActiveSupport::Notifications.unsubscribe(subscription) + end + end + describe "shutdown sequence" do before do # Stub NATS callback methods diff --git a/spec/protobuf/nats/super_subscription_manager_spec.rb b/spec/protobuf/nats/super_subscription_manager_spec.rb index 8b2f869..53bc4f8 100644 --- a/spec/protobuf/nats/super_subscription_manager_spec.rb +++ b/spec/protobuf/nats/super_subscription_manager_spec.rb @@ -6,16 +6,25 @@ let(:callback) { proc { |data, reply, subject| } } subject { described_class.new(nats_client, &callback) } + # Default to a single intake handler so the existing single-handler tests are + # deterministic regardless of CPU count; fan-out tests override this. + around do |example| + previous = ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "1" + example.run + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = previous + end + after do # Ensure the thread is killed after each test subject.shutdown(0.1) end describe "#initialize" do - it "starts a pending queue handler thread" do - handler_thread = subject.instance_variable_get(:@pending_queue_handler) - expect(handler_thread).to be_a(Thread) - expect(handler_thread.alive?).to be(true) + it "starts pending queue handler threads" do + handlers = subject.instance_variable_get(:@pending_queue_handlers) + expect(handlers).to all(be_a(Thread)) + expect(handlers).to all(be_alive) end end @@ -50,6 +59,44 @@ subject.queue_subscribe("my.queue.name") end + it "disables the byte-based slow-consumer limit (we never run nats-pure's pending_size decrement paths)" do + fake_subscription = nats_client.subscribe("test.sub") + allow(nats_client).to receive(:subscribe).and_return(fake_subscription) + + subject.queue_subscribe("my.queue.name") + + expect(fake_subscription.pending_bytes_limit).to eq(::Float::INFINITY) + end + + it "aligns the slow-consumer message limit with a tuned-down intake queue so the read thread drops instead of blocking" do + previous = ENV["PB_NATS_SERVER_INTAKE_QUEUE_SIZE"] + ENV["PB_NATS_SERVER_INTAKE_QUEUE_SIZE"] = "5" + manager = described_class.new(nats_client, &callback) + + fake_subscription = nats_client.subscribe("test.sub") + allow(nats_client).to receive(:subscribe).and_return(fake_subscription) + manager.queue_subscribe("my.queue.name") + + # nats-pure only drops (SlowConsumer) when pending_queue.size >= + # pending_msgs_limit. With the default limit (65,536) above a 5-slot + # SizedQueue, the push into the full queue would block the connection's + # read thread instead. + expect(fake_subscription.pending_msgs_limit).to eq(5) + expect(fake_subscription.pending_queue.max).to eq(5) + ensure + ENV["PB_NATS_SERVER_INTAKE_QUEUE_SIZE"] = previous + manager.shutdown(1) + end + + it "keeps the message limit at the nats-pure default when the intake queue is not tuned" do + fake_subscription = nats_client.subscribe("test.sub") + allow(nats_client).to receive(:subscribe).and_return(fake_subscription) + + subject.queue_subscribe("my.queue.name") + + expect(fake_subscription.pending_msgs_limit).to eq(::NATS::IO::DEFAULT_SUB_PENDING_MSGS_LIMIT) + end + it "shovels messages from old queue to the new one" do # Create a subscription with a message already in its queue subscription = nats_client.subscribe("my.queue.name") @@ -76,6 +123,103 @@ end end + describe "intake byte cap" do + it "builds the shared intake queue as a ByteBoundedQueue bounded by count and bytes" do + queue = subject.instance_variable_get(:@pending_queue) + expect(queue).to be_a(::Protobuf::Nats::ByteBoundedQueue) + expect(queue.max).to eq(subject.intake_queue_size) + expect(queue.instance_variable_get(:@max_bytes)).to eq(subject.intake_queue_bytes) + end + + it "defaults the byte ceiling to 128 MiB" do + expect(subject.intake_queue_bytes).to eq(::Protobuf::Nats::SuperSubscriptionManager::DEFAULT_INTAKE_QUEUE_BYTES) + expect(subject.intake_queue_bytes).to eq(128 * 1024 * 1024) + end + + it "honors PB_NATS_SERVER_INTAKE_QUEUE_BYTES" do + previous = ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = (1024 * 1024).to_s + manager = described_class.new(nats_client, &callback) + + expect(manager.intake_queue_bytes).to eq(1024 * 1024) + expect(manager.instance_variable_get(:@pending_queue).instance_variable_get(:@max_bytes)).to eq(1024 * 1024) + ensure + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = previous + manager.shutdown(1) + end + + it "reports resident intake bytes via pending_queue_bytes" do + # Stop handlers so the pushed message isn't drained before we read the gauge. + subject.instance_variable_get(:@pending_queue_handlers).each { |h| h.kill; h.join(1) } + queue = subject.instance_variable_get(:@pending_queue) + + expect(subject.pending_queue_bytes).to eq(0) + queue.push(::NATS::Msg.new(:subject => "s", :data => "x" * 250)) + expect(subject.pending_queue_bytes).to eq(250) + end + + it "emits server.intake_bytes_dropped when the intake queue drops an over-ceiling message" do + previous = ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = "10" # tiny ceiling + manager = described_class.new(nats_client, &callback) + # Stop handlers so the pushed message isn't drained before the byte gate runs. + manager.instance_variable_get(:@pending_queue_handlers).each { |h| h.kill; h.join(1) } + queue = manager.instance_variable_get(:@pending_queue) + + events = [] + cb = lambda { |name, _s, _f, _id, payload| events << [name, payload] } + ::ActiveSupport::Notifications.subscribed(cb, "server.intake_bytes_dropped.protobuf-nats") do + queue.push(::NATS::Msg.new(:subject => "s", :data => "x" * 64)) # 64 > 10 -> drop + end + + expect(events.map(&:first)).to eq(["server.intake_bytes_dropped.protobuf-nats"]) + expect(events.first.last).to eq(64) + ensure + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = previous + manager.shutdown(1) + end + + # Negative paths: a malformed or out-of-range override must not silently + # become 0 (a 0-byte ceiling would drop every request); it falls back. + it "falls back to the default byte ceiling when the env var is malformed" do + previous = ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = "128MB" + manager = described_class.new(nats_client, &callback) + + expect(manager.intake_queue_bytes).to eq(::Protobuf::Nats::SuperSubscriptionManager::DEFAULT_INTAKE_QUEUE_BYTES) + ensure + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = previous + manager.shutdown(1) + end + + it "falls back to the default byte ceiling when the env var is out of range" do + previous = ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = "0" # below the min of 1 + manager = described_class.new(nats_client, &callback) + + expect(manager.intake_queue_bytes).to eq(::Protobuf::Nats::SuperSubscriptionManager::DEFAULT_INTAKE_QUEUE_BYTES) + ensure + ENV["PB_NATS_SERVER_INTAKE_QUEUE_BYTES"] = previous + manager.shutdown(1) + end + end + + describe "#unsubscribe_all" do + it "unsubscribes and clears the tracked subscriptions so pause/resume cycles don't leak" do + fake_subscription = nats_client.subscribe("test.sub") + allow(nats_client).to receive(:subscribe).and_return(fake_subscription) + expect(fake_subscription).to receive(:unsubscribe).once + + subject.queue_subscribe("my.queue.name") + subject.unsubscribe_all + + expect(subject.instance_variable_get(:@subscriptions)).to be_empty + + # A second pass (the next pause) must not re-unsubscribe stale entries. + subject.unsubscribe_all + end + end + describe "error handling" do it "logs per-message errors and continues" do mutex = Mutex.new @@ -100,22 +244,22 @@ mutex.synchronize { cond.wait(mutex, 1) } # The thread should still be alive - handler_thread = manager.instance_variable_get(:@pending_queue_handler) + handler_thread = manager.instance_variable_get(:@pending_queue_handlers).first expect(handler_thread.alive?).to be(true) - + manager.shutdown(0.1) end end describe "#shutdown" do - it "stops the handler thread" do - handler_thread = subject.instance_variable_get(:@pending_queue_handler) - expect(handler_thread.alive?).to be(true) - + it "stops the handler threads" do + handlers = subject.instance_variable_get(:@pending_queue_handlers) + expect(handlers).to all(be_alive) + subject.shutdown - - expect(handler_thread.join(1)).to eq(handler_thread) - expect(handler_thread.alive?).to be(false) + + handlers.each { |h| h.join(1) } + expect(handlers.any?(&:alive?)).to be(false) end end @@ -164,29 +308,18 @@ describe "edge cases and fixes" do describe "handler thread self-healing" do - it "has self-healing logic in place" do - # Test that the crash count and retry logic exists - # We can't easily test the actual retry without hanging tests - # So we just verify the code paths exist - - crash_count = 0 - exploding_callback = proc do |data, reply, subject| - crash_count += 1 - # Don't actually crash - just verify callback is called - end + it "processes messages on the handler threads" do + # The crash counter is now per-thread (no shared @crash_count), so we + # just verify a handler picks up and runs a message. + processed = ::Queue.new + counting_callback = proc { |data, reply, subject| processed << data } - manager = described_class.new(nats_client, &exploding_callback) + manager = described_class.new(nats_client, &counting_callback) - # Verify crash count instance variable exists - expect(manager.instance_variable_get(:@crash_count)).to eq(0) - - # Push a message and verify it's processed pending_queue = manager.instance_variable_get(:@pending_queue) pending_queue.push(double(:data => "d", :reply => "r", :subject => "s")) - sleep 0.1 - - expect(crash_count).to eq(1) + expect(::Timeout.timeout(1) { processed.pop }).to eq("d") manager.shutdown(0.1) end @@ -212,10 +345,11 @@ it "does not block if thread is already dead" do manager = described_class.new(nats_client, &callback) - # Kill the thread - handler = manager.instance_variable_get(:@pending_queue_handler) - handler.kill - handler.join(1) + # Kill the threads + manager.instance_variable_get(:@pending_queue_handlers).each do |handler| + handler.kill + handler.join(1) + end # Shutdown should return immediately without blocking start_time = Time.now @@ -248,23 +382,25 @@ # Should have timed out and killed quickly expect(elapsed).to be < 2 - handler = manager.instance_variable_get(:@pending_queue_handler) - expect(handler.alive?).to be(false) + handlers = manager.instance_variable_get(:@pending_queue_handlers) + expect(handlers.any?(&:alive?)).to be(false) end it "handles full queue during shutdown gracefully" do manager = described_class.new(nats_client, &callback) pending_queue = manager.instance_variable_get(:@pending_queue) - # Try to fill the queue (but don't hang if it blocks) - begin - Timeout.timeout(1) do - 1000.times do - pending_queue << double(:data => "d", :reply => "r", :subject => "s") - end + # Fill the queue with a non-blocking push (stops as soon as it's full). + # NB: do NOT wrap a blocking `<<` in Timeout.timeout -- its async + # Thread#raise corrupts the SizedQueue mutex on JRuby 10 (raises + # "ThreadError: Attempt to unlock a mutex..."), which is exactly what + # push_with_deadline in the manager avoids. + 1000.times do + begin + pending_queue.push(double(:data => "d", :reply => "r", :subject => "s"), true) + rescue ThreadError + break # queue full end - rescue Timeout::Error - # Queue is full or blocked, that's fine end # Mock logger @@ -308,13 +444,64 @@ end end + describe "intake fan-out" do + it "spawns PB_NATS_SERVER_SUBSCRIPTION_HANDLERS handler threads" do + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "3" + manager = described_class.new(nats_client, &callback) + + handlers = manager.instance_variable_get(:@pending_queue_handlers) + expect(handlers.size).to eq(3) + expect(handlers).to all(be_alive) + + manager.shutdown(0.5) + end + + it "keeps processing other messages when one handler is blocked (no head-of-line blocking)" do + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "2" + + release = ::Queue.new + processed = ::Queue.new + calls = ::Concurrent::AtomicFixnum.new(0) + cb = proc do |data, _reply, _subject| + if calls.increment == 1 + release.pop # first message pins its handler until released + else + processed << data + end + end + + manager = described_class.new(nats_client, &cb) + queue = manager.instance_variable_get(:@pending_queue) + queue.push(double(:data => "A", :reply => "r", :subject => "s")) + sleep 0.05 # let one handler pick up A and block + queue.push(double(:data => "B", :reply => "r", :subject => "s")) + + # With a single handler this pop would block forever (head-of-line); + # the second handler must process B while A is stuck. + expect(::Timeout.timeout(2) { processed.pop }).to eq("B") + ensure + release << :go + manager&.shutdown(0.5) + end + + it "shuts down every handler thread" do + ENV["PB_NATS_SERVER_SUBSCRIPTION_HANDLERS"] = "3" + manager = described_class.new(nats_client, &callback) + handlers = manager.instance_variable_get(:@pending_queue_handlers) + + manager.shutdown(1) + + expect(handlers.any?(&:alive?)).to be(false) + end + end + describe "thread naming" do it "uses unique thread names with object_id" do manager1 = described_class.new(nats_client, &callback) manager2 = described_class.new(nats_client, &callback) - thread1 = manager1.instance_variable_get(:@pending_queue_handler) - thread2 = manager2.instance_variable_get(:@pending_queue_handler) + thread1 = manager1.instance_variable_get(:@pending_queue_handlers).first + thread2 = manager2.instance_variable_get(:@pending_queue_handlers).first # Give threads time to set their names (race condition fix) # The name is set inside Thread.new, but might not have executed yet diff --git a/spec/protobuf/nats/thread_pool_spec.rb b/spec/protobuf/nats/thread_pool_spec.rb new file mode 100644 index 0000000..9e290cd --- /dev/null +++ b/spec/protobuf/nats/thread_pool_spec.rb @@ -0,0 +1,95 @@ +require "spec_helper" + +describe ::Protobuf::Nats::ThreadPool do + describe "#wait_for_termination" do + it "returns true once the pool drains" do + pool = described_class.new(2) + pool.shutdown + expect(pool.wait_for_termination(2)).to be(true) + end + + it "returns false when the timeout elapses first" do + pool = described_class.new(1) + # No shutdown: workers block on the queue and never exit -> timeout. + expect(pool.wait_for_termination(0.2)).to be(false) + pool.kill + end + end + + describe "#shutdown" do + it "does not drive the active-work counter negative (the :stop pill never claimed a slot)" do + pool = described_class.new(2) + pool.shutdown + expect(pool.wait_for_termination(2)).to be(true) + 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) + worker = pool.instance_variable_get(:@workers).first + + # Wait until the worker is actually parked in @queue.pop (inside the + # rescue); a raise during thread startup lands outside it, which is the + # (acceptable) replenish-covered case, not the one under test. + wait_until(timeout: 2, interval: 0.01) { worker.status == "sleep" } + + worker.raise(::Protobuf::Nats::Errors::HandlerOverdue, "late reclaim") + sleep 0.1 + + expect(worker.alive?).to be(true) + # The worker still processes work afterwards. + done = ::Queue.new + pool.push { done << :ok } + expect(done.pop).to eq(:ok) + pool.kill + end + end + + describe "#replenish" do + it "respawns workers killed outside the per-task rescue" do + pool = described_class.new(2) + workers = pool.instance_variable_get(:@workers) + victim = workers.first + victim.kill + victim.join(1) + + pool.replenish + + alive = pool.instance_variable_get(:@workers).select(&:alive?) + expect(alive.size).to eq(2) + pool.kill + end + + it "is the only respawn path: push does not supervise the worker pool (hot-path contention)" do + pool = described_class.new(2) + workers = pool.instance_variable_get(:@workers) + victim = workers.first + victim.kill + victim.join(1) + + expect(pool.push { :noop }).to eq(true) + + # push enqueued the work but must not have replaced the dead worker; + # only the periodic replenish (server run loop) does that. + alive = pool.instance_variable_get(:@workers).select(&:alive?) + expect(alive.size).to eq(1) + + pool.replenish + alive = pool.instance_variable_get(:@workers).select(&:alive?) + expect(alive.size).to eq(2) + pool.kill + end + + it "does not respawn workers once shutting down" do + pool = described_class.new(2) + pool.shutdown + expect(pool.wait_for_termination(2)).to be(true) + + pool.replenish + + expect(pool.instance_variable_get(:@workers).select(&:alive?)).to be_empty + end + end +end diff --git a/spec/protobuf/nats_spec.rb b/spec/protobuf/nats_spec.rb index be34d2b..46a0e94 100644 --- a/spec/protobuf/nats_spec.rb +++ b/spec/protobuf/nats_spec.rb @@ -11,6 +11,67 @@ class ExampleServiceKlassBro; end expect(described_class.subscription_key(ExampleServiceKlassBro, :yolo_dude)).to eq("rpc.example_service_klass_bro.yolo_dude") end + describe ".env_int" do + after { ::ENV.delete("PB_NATS_TEST_INT") } + + it "returns the default when the var is unset" do + expect(described_class.env_int("PB_NATS_TEST_INT", 5)).to eq(5) + end + + it "parses a valid integer" do + ::ENV["PB_NATS_TEST_INT"] = "42" + expect(described_class.env_int("PB_NATS_TEST_INT", 5)).to eq(42) + end + + it "falls back to the default (instead of 0) and logs on a malformed value" do + ::ENV["PB_NATS_TEST_INT"] = "5s" + expect(described_class.logger).to receive(:error).with(/malformed integer.*PB_NATS_TEST_INT/i) + expect(described_class.env_int("PB_NATS_TEST_INT", 5)).to eq(5) + end + + it "accepts a value at the minimum" do + ::ENV["PB_NATS_TEST_INT"] = "1" + expect(described_class.env_int("PB_NATS_TEST_INT", 5, :min => 1)).to eq(1) + end + + it "falls back to the default and logs on a value below the minimum" do + ::ENV["PB_NATS_TEST_INT"] = "0" + expect(described_class.logger).to receive(:error).with(/out-of-range.*PB_NATS_TEST_INT/i) + expect(described_class.env_int("PB_NATS_TEST_INT", 5, :min => 1)).to eq(5) + end + end + + describe ".env_float" do + after { ::ENV.delete("PB_NATS_TEST_FLOAT") } + + it "returns the default when the var is unset" do + expect(described_class.env_float("PB_NATS_TEST_FLOAT", 2.5)).to eq(2.5) + end + + it "parses a valid float" do + ::ENV["PB_NATS_TEST_FLOAT"] = "12.5" + expect(described_class.env_float("PB_NATS_TEST_FLOAT", 2.5)).to eq(12.5) + end + + it "falls back to the default (instead of 0.0) and logs on a malformed value" do + ::ENV["PB_NATS_TEST_FLOAT"] = "5s" + expect(described_class.logger).to receive(:error).with(/malformed number.*PB_NATS_TEST_FLOAT/i) + expect(described_class.env_float("PB_NATS_TEST_FLOAT", 2.5)).to eq(2.5) + end + end + + describe ".disable_subscription_byte_limit!" do + it "sets the byte limit to infinity when supported" do + sub = ::NATS::Subscription.new + described_class.disable_subscription_byte_limit!(sub) + expect(sub.pending_bytes_limit).to eq(::Float::INFINITY) + end + + it "is a no-op for objects without the accessor" do + expect { described_class.disable_subscription_byte_limit!(Object.new) }.not_to raise_error + end + end + describe "#on_error" do # Reset error callbacks. before { described_class.instance_variable_set(:@error_callbacks, nil) } @@ -69,4 +130,93 @@ class ExampleServiceKlassBro; end described_class.notify_error_callbacks("yolo") end end + + describe "#notify_error_callbacks_async" do + before { described_class.instance_variable_set(:@error_callbacks, nil) } + after { described_class.instance_variable_set(:@error_callbacks, nil) } + + it "runs the callbacks off the calling thread" do + delivered = ::Queue.new + described_class.on_error { |e| delivered << e } + + described_class.notify_error_callbacks_async("boom") + + expect(::Timeout.timeout(2) { delivered.pop }).to eq("boom") + end + + it "records a dropped error callback when the bounded executor is saturated" do + before_count = described_class.error_callback_drop_count + # Simulate the :discard fallback policy rejecting the job (queue full). + allow(described_class::ERROR_CALLBACK_EXECUTOR).to receive(:post).and_return(false) + expect(described_class).to receive(:instrument).with("error_callback_dropped", 1) + + described_class.notify_error_callbacks_async(::RuntimeError.new("flood")) + + expect(described_class.error_callback_drop_count).to eq(before_count + 1) + end + end + + describe "#start_client_nats_connection" do + around do |example| + previous = described_class.client_nats_connection + described_class.client_nats_connection = nil + example.run + described_class.client_nats_connection = previous + end + + it "connects with the unmodified connection options (no dead :disable_reconnect_buffer)" do + # spec_helper stubs this to a no-op by default; run the real thing here. + allow(described_class).to receive(:start_client_nats_connection).and_call_original + + fake_nats = ::FakeNatsClient.new + received_options = nil + allow(::Protobuf::Nats::NatsClient).to receive(:new).and_return(fake_nats) + allow(fake_nats).to receive(:connect) { |opts| received_options = opts } + # Stub the rest of the connection lifecycle calls. + %i[flush on_disconnect on_reconnect on_close on_error].each do |m| + allow(fake_nats).to receive(m) + end + + described_class.start_client_nats_connection + + expect(received_options).to eq(described_class.config.connection_options) + expect(received_options).not_to have_key(:disable_reconnect_buffer) + end + + it "closes the half-open client and does not cache the connection when the handshake fails" do + allow(described_class).to receive(:start_client_nats_connection).and_call_original + + fake_nats = ::FakeNatsClient.new + allow(::Protobuf::Nats::NatsClient).to receive(:new).and_return(fake_nats) + %i[on_disconnect on_reconnect on_close on_error connect].each do |m| + allow(fake_nats).to receive(m) + end + allow(fake_nats).to receive(:flush).and_raise(::NATS::IO::Timeout) + # The half-open client must be closed so its reader/flusher threads don't leak. + expect(fake_nats).to receive(:close) + + expect { described_class.start_client_nats_connection }.to raise_error(::NATS::IO::Timeout) + expect(described_class.client_nats_connection).to be_nil + end + + it "drops the cached connection when it closes so the next call rebuilds" do + allow(described_class).to receive(:start_client_nats_connection).and_call_original + + fake_nats = ::FakeNatsClient.new + allow(::Protobuf::Nats::NatsClient).to receive(:new).and_return(fake_nats) + %i[on_disconnect on_reconnect on_error connect flush].each { |m| allow(fake_nats).to receive(m) } + + # Capture the on_close callback the lifecycle registers so we can fire it. + close_callback = nil + allow(fake_nats).to receive(:on_close) { |&blk| close_callback = blk } + + described_class.start_client_nats_connection + expect(described_class.client_nats_connection).to eq(fake_nats) + + # nats-pure fires on_close when the connection terminally closes. + close_callback.call + + expect(described_class.client_nats_connection).to be_nil + end + end end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index d9a2aff..7de74ce 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -6,14 +6,54 @@ ENV["PB_NATS_RESPONSE_MUXER_DISPATCHERS"] ||= "1" require "bundler/setup" +require "socket" require "protobuf/nats" require "fake_nats_client" require "pry" +# Integration specs (spec/integration/) exercise a real NATS server. They run +# automatically when one is reachable (a local `nats-server`, or the CI service +# container) and are excluded otherwise, so the unit suite never needs NATS. +PB_NATS_INTEGRATION_HOST = ENV.fetch("PB_NATS_INTEGRATION_HOST", "127.0.0.1") +PB_NATS_INTEGRATION_PORT = Integer(ENV.fetch("PB_NATS_INTEGRATION_PORT", "4222")) +PB_NATS_INTEGRATION_AVAILABLE = begin + # Bounded connect so an unreachable (packet-dropping) host can't stall + # every test run for the OS connect timeout. + ::Socket.tcp(PB_NATS_INTEGRATION_HOST, PB_NATS_INTEGRATION_PORT, :connect_timeout => 1).close + true +rescue ::StandardError + false +end + +# The cluster failover spec (spec/integration/failover_spec.rb) spawns its own +# two-node cluster, so it needs the nats-server binary itself (not just a +# reachable server). +PB_NATS_SERVER_BINARY_AVAILABLE = begin + system("nats-server", "--version", :out => ::File::NULL, :err => ::File::NULL) ? true : false +rescue ::StandardError + false +end + # Turn off protobuf logging. ::Protobuf::Logging.logger = ::Logger.new(nil) +# Deterministic polling helper for concurrency specs: wait for a condition +# instead of sleeping a fixed amount and hoping. Fails fast on timeout. +module WaitHelpers + def wait_until(timeout: 2, interval: 0.005) + deadline = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + timeout + until yield + if ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) > deadline + raise "wait_until timed out after #{timeout}s" + end + sleep interval + end + end +end + RSpec.configure do |config| + config.include WaitHelpers + # Enable flags like --only-failures and --next-failure config.example_status_persistence_file_path = ".rspec_status" config.order = :random @@ -23,8 +63,14 @@ c.syntax = :expect end - config.before(:each) do - allow(::Protobuf::Nats).to receive(:start_client_nats_connection) + config.filter_run_excluding(:integration => true) unless PB_NATS_INTEGRATION_AVAILABLE + config.filter_run_excluding(:integration_cluster => true) unless PB_NATS_SERVER_BINARY_AVAILABLE + + config.before(:each) do |example| + # Integration examples open a real connection; everything else must never. + unless example.metadata[:integration] || example.metadata[:integration_cluster] + allow(::Protobuf::Nats).to receive(:start_client_nats_connection) + end ::Protobuf::Nats::Client::RESPONSE_MUXER.restart end diff --git a/spec/support/empty_protobuf_nats.yml b/spec/support/empty_protobuf_nats.yml new file mode 100644 index 0000000..e69de29 diff --git a/spec/support/protobuf_nats.yml b/spec/support/protobuf_nats.yml index 699270d..830fa56 100644 --- a/spec/support/protobuf_nats.yml +++ b/spec/support/protobuf_nats.yml @@ -6,6 +6,9 @@ - "nats://127.0.0.1:4223" - "nats://127.0.0.1:4224" max_reconnect_attempts: 1234 + reconnect_time_wait: 1 + ping_interval: 20 + max_outstanding_pings: 3 uses_tls: true tls_client_cert: "./spec/support/certs/client-cert.pem" tls_client_key: "./spec/support/certs/client-key.pem" diff --git a/spec/support/unsafe_protobuf_nats.yml b/spec/support/unsafe_protobuf_nats.yml new file mode 100644 index 0000000..4a091c1 --- /dev/null +++ b/spec/support/unsafe_protobuf_nats.yml @@ -0,0 +1,7 @@ +--- +development: + servers: + - "nats://127.0.0.1:4222" + # An arbitrary Ruby object tag. Under the old YAML.unsafe_load this would be + # deserialized; under safe_load it must raise Psych::DisallowedClass. + injected: !ruby/object:Object {}