From 40535cbaeafc7bf9bf09888fc961e8cd6547464d Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Wed, 26 Aug 2026 12:52:53 +0200 Subject: [PATCH 01/22] refactor: rework SPDK proxy to utilize fastapi The existing proxy executed at import time and utilized global state, making it difficult to reason about. Converting this to FastAPI addresses this issue, aligns the proxy with the other API code, and enables simpler integration of richer SPDK-side interaction. --- simplyblock_core/services/__main__.py | 4 +- .../services/spdk_http_proxy_server.py | 799 +++++++++--------- tests/AGENTS.md | 1 - tests/conftest_proxy.py | 55 -- tests/integration/test_spdk_proxy_e2e.py | 547 +++++------- tests/unit/test_service_entrypoints.py | 15 +- tests/unit/test_spdk_proxy_unit.py | 581 ++++++++----- 7 files changed, 1014 insertions(+), 988 deletions(-) delete mode 100644 tests/conftest_proxy.py diff --git a/simplyblock_core/services/__main__.py b/simplyblock_core/services/__main__.py index 40ea976b6a..06e0cc47fb 100644 --- a/simplyblock_core/services/__main__.py +++ b/simplyblock_core/services/__main__.py @@ -7,9 +7,7 @@ depend on a file layout, so consumers can migrate off the paths. ``runpy`` rather than importing and calling ``main()``: it reproduces the -semantics of running the file directly, including for the modules whose body -is at import time (see ``spdk_http_proxy_server``), so both invocations behave -identically. +semantics of running the file directly, so both invocations behave identically. """ import argparse import importlib diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 7ca96bbd1e..3bfef55696 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -1,415 +1,452 @@ +# coding=utf-8 +"""HTTP front-end for SPDK's JSON-RPC unix socket. + +Storage nodes run one instance of this next to every SPDK process. It accepts +basic-auth'd JSON-RPC POSTs (see ``simplyblock_core.rpc_client.RPCClient``) and +forwards the raw body to ``/mnt/ramdisk/spdk_/spdk.sock``. + +Importing this module has no side effects: configuration is read by +``ProxySettings``, the application is built by ``create_app`` and only ``main`` +(the ``__main__`` entry point used by the deployment manifests) binds a port. +""" + +import asyncio import base64 -from typing import ClassVar +import hmac import json import logging -import os -import socket +import ssl import sys -import threading import time -from typing import Optional +from contextlib import asynccontextmanager +from typing import Annotated, Any, AsyncGenerator, Dict, Optional -from http.server import HTTPServer -from http.server import ThreadingHTTPServer -from http.server import BaseHTTPRequestHandler +import uvicorn +from fastapi import FastAPI, Request, Response +from pydantic import BeforeValidator, Field, SecretStr +from pydantic_settings import BaseSettings, SettingsConfigDict +from starlette.requests import ClientDisconnect from simplyblock_core.settings import Settings -logger_handler = logging.StreamHandler(stream=sys.stdout) -logger_handler.setFormatter(logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')) -logger = logging.getLogger() -logger.addHandler(logger_handler) -logger.setLevel(logging.INFO) - -read_line_time_diff: dict = {} -recv_from_spdk_time_diff: dict = {} -def print_stats(): - # Paced by monotonic elapsed time, not just the sleep call: several - # integration tests patch a bare-imported `time.sleep` on some other - # module (e.g. storage_node_ops), which mutates the same shared stdlib - # `time` module and turns THIS sleep into a no-op for the duration of - # that patch. Without this guard the loop degenerates into a hot spin - # that floods stdout with duplicate stats and burns CPU other threads - # need — see tests/AGENTS.md's note on deadline loops paced by sleep(). - last_log = time.monotonic() - while True: - try: - time.sleep(3) - if time.monotonic() - last_log < 2.5: - continue - last_log = time.monotonic() - t = time.time_ns() - if len(read_line_time_diff) > 0: - read_line_time_diff_max = max(list(read_line_time_diff.values())) - read_line_time_diff_avg = int(sum(list(read_line_time_diff.values()))/len(read_line_time_diff)) - last_3_sec = [] - for k,v in read_line_time_diff.items(): - if k > t - 3*1000*1000*1000: - last_3_sec.append(v) - if len(last_3_sec) > 0: - read_line_time_diff_avg_last_3_sec = int(sum(last_3_sec)/len(last_3_sec)) - else: - read_line_time_diff_avg_last_3_sec = 0 - logger.info(f"Periodic stats: {t}: read_line_time: max={read_line_time_diff_max} ns, avg={read_line_time_diff_avg} ns, last_3s_avg={read_line_time_diff_avg_last_3_sec} ns") - if len(read_line_time_diff) > 10000: - read_line_time_diff.clear() - - if len(recv_from_spdk_time_diff) > 0: - recv_from_spdk_time_max = max(list(recv_from_spdk_time_diff.values())) - recv_from_spdk_time_avg = int(sum(list(recv_from_spdk_time_diff.values()))/len(recv_from_spdk_time_diff)) - last_3_sec = [] - for k,v in recv_from_spdk_time_diff.items(): - if k > t - 3*1000*1000*1000: - last_3_sec.append(v) - if len(last_3_sec) > 0: - recv_from_spdk_time_avg_last_3_sec = int(sum(last_3_sec)/len(last_3_sec)) - else: - recv_from_spdk_time_avg_last_3_sec = 0 - logger.info(f"Periodic stats: {t}: recv_from_spdk_time: max={recv_from_spdk_time_max} ns, avg={recv_from_spdk_time_avg} ns, last_3s_avg={recv_from_spdk_time_avg_last_3_sec} ns") - if len(recv_from_spdk_time_diff) > 10000: - recv_from_spdk_time_diff.clear() - except Exception as e: - logger.error(e) - - -def get_env_var(name, default=None, is_required=False): - if not name: - logger.warning("Invalid env var name %s", name) - return False - if name not in os.environ and is_required: - logger.error("env value is required: %s" % name) - raise Exception("env value is required: %s" % name) - return os.environ.get(name, default) - -unix_sockets: list[socket] = [] # type: ignore[valid-type] -spdk_semaphore: threading.Semaphore = None # type: ignore[assignment] # initialized after env vars are read -spdk_ready = False - - -def wait_for_spdk_ready(): - """Block until SPDK responds to spdk_get_version on the unix socket.""" - global spdk_ready - payload = json.dumps({'id': 1, 'method': 'spdk_get_version'}).encode('ascii') - while not spdk_ready: - sock = None - try: - sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) # type: ignore[attr-defined] # AF_UNIX: Linux-only, absent on Windows - sock.settimeout(5) - sock.connect(rpc_sock) - sock.sendall(payload) - buf = b'' - while True: - data = sock.recv(4096) - if data == b'': - break - buf += data - try: - json.loads(buf.decode('ascii')) - spdk_ready = True - logger.info("SPDK is ready (spdk_get_version responded)") - return - except ValueError: - continue - except (socket.error, OSError) as e: - logger.info(f"Waiting for SPDK to be ready: {e}") - finally: - if sock: - try: - sock.close() - except OSError: - pass - time.sleep(1) - - -def _resolve_sock_timeout(client_timeout): - """Bound the SPDK unix-socket wait (and hence the spdk_semaphore-slot hold) - to a value tied to the CALLER's HTTP timeout, rather than the global - ``TIMEOUT``. - - Each in-flight RPC holds one of ``MAX_CONCURRENT_SPDK`` semaphore slots for - the entire SPDK round-trip. If a slot were always held for the full global - ``TIMEOUT`` (default 300s) while the caller abandons the request after its - own (often 1-5s) timeout, a handful of never-completing RPCs (e.g. a - ``distr_status_events_update`` that the distrib can't finish applying) would - squat every slot for minutes and starve all other RPCs to this node — - unrelated calls (port_block, bdev_get_bdevs) then never even reach SPDK and - time out at the caller. Holding the slot only ~SPDK_TIMEOUT_MARGIN× longer - than the caller waits lets slots recycle promptly. Capped at the global - ``TIMEOUT`` so genuinely long operations keep today's budget; falls back to - ``TIMEOUT`` when the caller sends no hint (backward compatible). +logger = logging.getLogger(__name__) + +#: How often the periodic timing report is emitted, and the window the +#: ``last_Ns_avg`` figure covers. +STATS_INTERVAL_SEC = 3 +#: Samples are dropped wholesale once a series grows past this. +STATS_MAX_SAMPLES = 10000 +#: Per-attempt bound on the readiness probe, and the pause between attempts. +SPDK_READY_PROBE_TIMEOUT_SEC = 5 +SPDK_READY_POLL_INTERVAL_SEC = 1 +#: SPDK responses are read in one shot; matches the pre-FastAPI recv() size. +SPDK_RECV_SIZE = 1024 * 1024 * 1024 +#: Idle keep-alive window. The server this replaced spoke HTTP/1.0 and closed +#: after every response, so a connection could never be dropped underneath a +#: client that was about to reuse it. RPCClient deliberately keeps POST out of +#: its urllib3 retry set, so such a drop surfaces as a failed RPC rather than a +#: retry — hence an idle window far longer than the gap between RPCs to a node. +KEEP_ALIVE_TIMEOUT_SEC = 300 + + +def _rpc_port_or_default(value: Any) -> Any: + """Fall back to 8080 for an unparsable ``RPC_PORT``. + + Legacy behaviour, kept deliberately: deployments that pass a non-numeric + port have always silently landed on 8080 rather than failing to start. """ - if client_timeout is None: - return TIMEOUT try: - ct = float(client_timeout) + return int(value) except (TypeError, ValueError): - return TIMEOUT - if ct <= 0: - return TIMEOUT - return min(ct * SPDK_TIMEOUT_MARGIN, TIMEOUT) - -def rpc_call(req, client_timeout=None): - logger.info(f"active threads: {threading.active_count()}") - logger.info(f"active unix sockets: {len(unix_sockets)}") - req_data = json.loads(req.decode('ascii')) - req_time = time.time_ns() - params = "" - if "params" in req_data: - params = str(req_data['params']) - logger.info(f"Request:{req_time} function: {str(req_data['method'])}, params: {params}") - sock_timeout = _resolve_sock_timeout(client_timeout) - spdk_semaphore.acquire() - try: - return _rpc_call_inner(req, req_data, req_time, sock_timeout) - finally: - spdk_semaphore.release() + return 8080 -def _rpc_call_inner(req, req_data, req_time, sock_timeout): - sock = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) # type: ignore[attr-defined] # AF_UNIX: Linux-only, absent on Windows - unix_sockets.append(sock) - try: - sock.settimeout(sock_timeout) - sock.connect(rpc_sock) - sock.sendall(req) - if 'id' not in req_data: +class ProxySettings(BaseSettings): + """Environment configuration of the proxy. + + The variable names carry no ``SB_`` prefix — they are baked into the + deployed manifests (``simplyblock_web/templates/storage_deploy_spdk.yaml.j2``) + and into the docker launch path + (``simplyblock_web/api/internal/storage_node/docker.py``). + """ + + model_config = SettingsConfigDict(case_sensitive=False) + + server_ip: Annotated[str, Field(description="Address the HTTP server binds to")] + rpc_port: Annotated[ + int, + Field(description="Port the HTTP server binds to; also selects the SPDK unix socket"), + BeforeValidator(_rpc_port_or_default), + ] + rpc_username: str + rpc_password: SecretStr + timeout: Annotated[ + float, + Field(gt=0, description="Upper bound on how long a single SPDK round-trip may take"), + ] = 5 * 60 + max_concurrent_spdk: Annotated[ + int, + Field(gt=0, description="Number of RPCs allowed to be in flight against SPDK at once"), + ] = 16 + spdk_timeout_margin: Annotated[ + float, + Field( + gt=0, + description=( + "Multiplier applied to the caller-supplied HTTP timeout (X-RPC-Timeout header) " + "to derive how long the proxy waits on SPDK while holding a concurrency slot. " + ">1 so a request that completes just after the caller's deadline still returns " + "instead of being aborted; small enough that abandoned/stuck RPCs free their " + "slot quickly." + ), + ), + ] = 2.0 + multi_threading_enabled: Annotated[ + bool, + Field( + description=( + "Serve RPCs concurrently. When false the proxy forwards one RPC at a time, " + "matching the single-threaded HTTPServer this used to run on." + ) + ), + ] = False + + rpc_sock_path: Annotated[ + Optional[str], + Field(description=( + "Path of SPDK's JSON-RPC unix socket. Defaults to the location SPDK " + "binds for this RPC_PORT, which is what every deployment uses." + )), + ] = None + + @property + def rpc_sock(self) -> str: + return self.rpc_sock_path or f"/mnt/ramdisk/spdk_{self.rpc_port}/spdk.sock" + + @property + def authorization(self) -> str: + """The ``Authorization`` header value clients have to present.""" + credentials = f"{self.rpc_username}:{self.rpc_password.get_secret_value()}" + return 'Basic ' + base64.b64encode(credentials.encode('ascii')).decode('ascii') + + +class TimingStats: + """Rolling record of operation durations, reported periodically.""" + + def __init__(self, name: str) -> None: + self.name = name + self.samples: Dict[int, int] = {} + + def record(self, start_ns: int, duration_ns: int) -> None: + self.samples[start_ns] = duration_ns + + def report(self, now_ns: int) -> Optional[str]: + """Summarize the collected samples, clearing them once they pile up.""" + if not self.samples: return None - buf = '' - closed = False - response = None - recv_from_spdk_time_start = time.time_ns() - while not closed: - newdata = sock.recv(1024*1024*1024) - if newdata == b'': - closed = True - buf += newdata.decode('ascii') + durations = list(self.samples.values()) + window = [ + duration + for start, duration in self.samples.items() + if start > now_ns - STATS_INTERVAL_SEC * 1000 * 1000 * 1000 + ] + summary = ( + f"{self.name}: max={max(durations)} ns," + f" avg={int(sum(durations) / len(durations))} ns," + f" last_{STATS_INTERVAL_SEC}s_avg={int(sum(window) / len(window)) if window else 0} ns" + ) + + if len(self.samples) > STATS_MAX_SAMPLES: + self.samples.clear() + + return summary + + +class SpdkProxy: + """Forwards JSON-RPC requests to SPDK's unix socket.""" + + def __init__(self, settings: ProxySettings) -> None: + self.settings = settings + self.spdk_ready = False + #: Requests currently being served, and unix sockets currently open + #: towards SPDK. Both are logged per request and asserted on by tests. + self.active_requests = 0 + self.open_connections = 0 + self.read_body_stats = TimingStats('read_body_time') + self.recv_from_spdk_stats = TimingStats('recv_from_spdk_time') + # Without MULTI_THREADING_ENABLED the proxy used to run on a + # non-threading HTTPServer, i.e. one request at a time. + self.concurrency_limit = ( + settings.max_concurrent_spdk if settings.multi_threading_enabled else 1) + self._slots: Optional[asyncio.Semaphore] = None + logger.info("SPDK concurrency limit: %s", self.concurrency_limit) + + @property + def slots(self) -> asyncio.Semaphore: + """Gate on the number of RPCs in flight against SPDK. + + Built on first use: up to Python 3.9 a Semaphore binds to whichever + event loop is running when it is constructed, and the proxy is + constructed before the server's loop exists. + """ + if self._slots is None: + self._slots = asyncio.Semaphore(self.concurrency_limit) + return self._slots + + def authenticate(self, authorization: Optional[str]) -> bool: + # Compared as bytes: compare_digest rejects non-ASCII str outright, and + # the header is attacker-controlled. + return authorization is not None and hmac.compare_digest( + authorization.encode('utf-8'), + self.settings.authorization.encode('utf-8'), + ) + + async def report_stats(self) -> None: + """Log the collected timings every ``STATS_INTERVAL_SEC`` seconds.""" + while True: + await asyncio.sleep(STATS_INTERVAL_SEC) try: - response = json.loads(buf) - except ValueError: - continue # incomplete response; keep buffering - break - recv_from_spdk_time_end = time.time_ns() - time_diff = recv_from_spdk_time_end - recv_from_spdk_time_start - logger.info(f"recv_from_spdk_time_diff: {time_diff}") - recv_from_spdk_time_diff[recv_from_spdk_time_start] = time_diff - - if not response and len(buf) > 0: - raise ValueError('Invalid response') - - logger.info(f"Response:{req_time}") - - return buf - except socket.timeout: - logger.error(f"Socket timeout waiting for SPDK response (request {req_time}, function: {req_data.get('method', 'unknown')})") - raise ValueError('SPDK response timeout') - finally: + now = time.time_ns() + for stats in (self.read_body_stats, self.recv_from_spdk_stats): + if (summary := stats.report(now)) is not None: + logger.info("Periodic stats: %s: %s", now, summary) + except Exception as e: + logger.error(e) + + async def wait_for_spdk_ready(self) -> None: + """Block until SPDK responds to spdk_get_version on the unix socket.""" + payload = json.dumps({'id': 1, 'method': 'spdk_get_version'}).encode('ascii') + while not self.spdk_ready: + try: + self.spdk_ready = await asyncio.wait_for( + self._probe(payload), SPDK_READY_PROBE_TIMEOUT_SEC) + except (OSError, asyncio.TimeoutError) as e: + logger.info(f"Waiting for SPDK to be ready: {e}") + + if self.spdk_ready: + logger.info("SPDK is ready (spdk_get_version responded)") + return + + await asyncio.sleep(SPDK_READY_POLL_INTERVAL_SEC) + + async def _probe(self, payload: bytes) -> bool: + reader, writer = await asyncio.open_unix_connection(self.settings.rpc_sock) try: - sock.close() - except OSError: - pass + writer.write(payload) + await writer.drain() + + buf = b'' + while (data := await reader.read(4096)) != b'': + buf += data + try: + json.loads(buf.decode('ascii')) + except ValueError: + continue + return True + return False + finally: + _close(writer) + + def _resolve_sock_timeout(self, client_timeout: Optional[str]) -> float: + """Bound the SPDK unix-socket wait (and hence the concurrency-slot hold) + to a value tied to the CALLER's HTTP timeout, rather than the global + ``timeout``. + + Each in-flight RPC holds one of ``max_concurrent_spdk`` slots for the + entire SPDK round-trip. If a slot were always held for the full global + ``timeout`` (default 300s) while the caller abandons the request after + its own (often 1-5s) timeout, a handful of never-completing RPCs (e.g. a + ``distr_status_events_update`` that the distrib can't finish applying) + would squat every slot for minutes and starve all other RPCs to this + node — unrelated calls (port_block, bdev_get_bdevs) then never even + reach SPDK and time out at the caller. Holding the slot only + ~``spdk_timeout_margin``x longer than the caller waits lets slots + recycle promptly. Capped at the global ``timeout`` so genuinely long + operations keep today's budget; falls back to ``timeout`` when the + caller sends no hint (backward compatible). + """ + if client_timeout is None: + return self.settings.timeout try: - unix_sockets.remove(sock) - except ValueError: - pass - - -class ServerHandler(BaseHTTPRequestHandler): - server_session: ClassVar[list[int]] = [] - key = "" - - # The base class defaults to "HTTP/1.0", under which parse_request() - # forces close_connection=True unconditionally regardless of what the - # client sends — i.e. keep-alive never actually engages without this. - # Every response below sends an explicit Content-Length because HTTP/1.1 - # framing requires it (no more relying on connection-close as EOF). - protocol_version = "HTTP/1.1" - - # Idle-connection reclaim timeout — NOT the same thing as the server's - # own `httpd.timeout` (set in run_server(), only bounds serve_forever()'s - # accept loop). Assigned in run_server() once KEEPALIVE_TIMEOUT exists, - # same as `key` below. - timeout: ClassVar[Optional[float]] = None - - def do_HEAD(self, content_length=0): - self.send_response(200) - self.send_header('Content-type', 'text/html') - self.send_header('Content-Length', str(content_length)) - self.end_headers() - - def do_HEAD_no_content(self): - self.send_response(204) - self.send_header('Content-type', 'text/html') - self.send_header('Content-Length', '0') - self.end_headers() - - def do_AUTHHEAD(self): - self.send_response(401) - self.send_header('WWW-Authenticate', 'text/html') - self.send_header('Content-type', 'text/html') - self.send_header('Content-Length', '0') - self.end_headers() - - def do_INTERNALERROR(self): - self.send_response(500) - self.send_header('Content-type', 'text/html') - self.send_header('Content-Length', '0') - self.end_headers() - - def do_POST(self): + ct = float(client_timeout) + except (TypeError, ValueError): + return self.settings.timeout + if ct <= 0: + return self.settings.timeout + return min(ct * self.settings.spdk_timeout_margin, self.settings.timeout) + + async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Optional[str]: + """Forward one JSON-RPC request, returning SPDK's raw response. + + Returns ``None`` for a request without an ``id`` (a notification, which + SPDK does not answer). + """ + logger.info(f"active requests: {self.active_requests}") + logger.info(f"active unix sockets: {self.open_connections}") + req_data = json.loads(req.decode('ascii')) req_time = time.time_ns() - self.server_session.append(req_time) + params = str(req_data['params']) if 'params' in req_data else "" + logger.info(f"Request:{req_time} function: {str(req_data['method'])}, params: {params}") + sock_timeout = self._resolve_sock_timeout(client_timeout) + async with self.slots: + return await self._rpc_call_inner(req, req_data, req_time, sock_timeout) + + async def _rpc_call_inner( + self, + req: bytes, + req_data: dict, + req_time: int, + sock_timeout: float, + ) -> Optional[str]: try: - self._do_POST_inner(req_time) - finally: - # Cleanup must run for ANY exception the body below can raise - # (e.g. ConnectionResetError / socket timeout writing the - # response under load), not only the two kinds it explicitly - # handles — otherwise the entry is orphaned in server_session - # for the rest of the process. - self.server_session.remove(req_time) - - def _do_POST_inner(self, req_time): - logger.info(f"incoming request at: {req_time}") - logger.info(f"active server session: {len(self.server_session)}") - # Body must be drained before branching on auth, not only on the - # success path: on a kept-alive connection, an unread body from a - # rejected (401) request gets read as the START of the next request, - # which then fails to parse ("Bad request version"). - read_line_time_start = time.time_ns() - if "Content-Length" in self.headers: - data_string = self.rfile.read(int(self.headers['Content-Length'])) - elif "chunked" in self.headers.get("Transfer-Encoding", ""): - data_string = b'' - while True: - line = self.rfile.readline().strip() - chunk_length = int(line, 16) - - if chunk_length != 0: - chunk = self.rfile.read(chunk_length) - data_string += chunk - - # Each chunk is followed by an additional empty newline - # that we have to consume. - self.rfile.readline() - - # Finally, a chunk size of 0 is an end indication - if chunk_length == 0: - break - else: - data_string = b'' - read_line_time_end = time.time_ns() - time_diff = read_line_time_end - read_line_time_start - logger.info(f"read_line_time_diff: {time_diff}") - read_line_time_diff[read_line_time_start] = time_diff - - if self.headers['Authorization'] != 'Basic ' + self.key: - self.do_AUTHHEAD() - else: + return await asyncio.wait_for(self._exchange(req, req_data, req_time), sock_timeout) + except asyncio.TimeoutError as e: + logger.error( + f"Socket timeout waiting for SPDK response (request {req_time}, " + f"function: {req_data.get('method', 'unknown')})") + raise ValueError('SPDK response timeout') from e + + async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional[str]: + self.open_connections += 1 + try: + reader, writer = await asyncio.open_unix_connection(self.settings.rpc_sock) try: - response = rpc_call(data_string, self.headers.get('X-RPC-Timeout')) - if response is not None: - body = response.encode(encoding='ascii') - self.do_HEAD(len(body)) - self.wfile.write(body) - else: - self.do_HEAD_no_content() - - except BrokenPipeError: - logger.warning(f"BrokenPipeError: client disconnected before response could be sent (request {req_time})") - except ValueError: - self.do_INTERNALERROR() + writer.write(req) + await writer.drain() + + if 'id' not in req_data: + return None + + buf = b'' + response = None + recv_start = time.time_ns() + while True: + newdata = await reader.read(SPDK_RECV_SIZE) + closed = newdata == b'' + buf += newdata + try: + response = json.loads(buf.decode('ascii')) + except ValueError: + if closed: + break + continue + break + time_diff = time.time_ns() - recv_start + self.recv_from_spdk_stats.record(recv_start, time_diff) + logger.info(f"recv_from_spdk_time_diff: {time_diff}") + if not response and len(buf) > 0: + raise ValueError('Invalid response') -def _bound_connection_concurrency(httpd, max_connections): - """Cap concurrent connections on a ThreadingHTTPServer instance. + logger.info(f"Response:{req_time}") - ThreadingMixIn spawns one thread per accepted connection with no limit. - Under keep-alive a connection's thread can now sit alive for the whole - idle window between requests rather than exiting after one request, so - this bounds it — same pattern as the existing ``spdk_semaphore``. + return buf.decode('ascii') + finally: + _close(writer) + finally: + self.open_connections -= 1 - Implemented as an instance-level monkeypatch, not a ThreadingHTTPServer - subclass: tests/conftest_proxy.py patches ``http.server.ThreadingHTTPServer`` - to a MagicMock before importing this module, and a subclass statement at - module scope would evaluate against that mock and fail on import. - """ - semaphore = threading.Semaphore(max_connections) - base_process_request = httpd.process_request - base_process_request_thread = httpd.process_request_thread - def process_request(request, client_address): - # Acquire before spawning the thread (not inside it), so the accept - # loop itself blocks at the cap instead of spawning unboundedly. - semaphore.acquire() - base_process_request(request, client_address) +def _close(writer: asyncio.StreamWriter) -> None: + try: + writer.close() + except OSError: + pass + - def process_request_thread(request, client_address): +def create_app(settings: ProxySettings) -> FastAPI: + """Build the proxy application. + + Startup blocks until SPDK answers on its unix socket. uvicorn runs the + lifespan before it binds the listening socket, so — as with the + ``HTTPServer`` this replaced — the port stays closed until SPDK is up, + rather than accepting requests that could only fail. + """ + proxy = SpdkProxy(settings) + + @asynccontextmanager + async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: + stats_task = asyncio.create_task(proxy.report_stats()) try: - base_process_request_thread(request, client_address) + await proxy.wait_for_spdk_ready() + logger.info('Started RPC http proxy server') + yield finally: - semaphore.release() + stats_task.cancel() + + app = FastAPI(lifespan=lifespan, docs_url=None, redoc_url=None, openapi_url=None) + app.state.proxy = proxy - httpd.process_request = process_request - httpd.process_request_thread = process_request_thread + @app.post('/{path:path}') + async def rpc(request: Request) -> Response: + req_time = time.time_ns() + proxy.active_requests += 1 + logger.info(f"incoming request at: {req_time}") + logger.info(f"active server session: {proxy.active_requests}") + try: + if not proxy.authenticate(request.headers.get('Authorization')): + return Response(status_code=401, headers={'WWW-Authenticate': 'Basic'}) + read_start = time.time_ns() + try: + body = await request.body() + except ClientDisconnect: + logger.warning( + f"client disconnected before the request body arrived (request {req_time})") + return Response(status_code=400) + time_diff = time.time_ns() - read_start + proxy.read_body_stats.record(read_start, time_diff) + logger.info(f"read_body_time_diff: {time_diff}") -def run_server(host, port, user, password, is_threading_enabled=False): - # encoding user and password - key = base64.b64encode((user+':'+password).encode(encoding='ascii')).decode('ascii') - print_stats_thread = threading.Thread(target=print_stats, daemon=True) - print_stats_thread.start() - wait_for_spdk_ready() - try: - ServerHandler.key = key - ServerHandler.timeout = KEEPALIVE_TIMEOUT - httpd: HTTPServer - if is_threading_enabled: - httpd = ThreadingHTTPServer((host, port), ServerHandler) - _bound_connection_concurrency(httpd, MAX_CONCURRENT_CONNECTIONS) - else: - httpd = HTTPServer((host, port), ServerHandler) - settings = Settings() - context = settings.make_server_ssl_context() - if context is not None: - httpd.socket = context.wrap_socket(httpd.socket, server_side=True) - httpd.timeout = TIMEOUT - logger.info('Started RPC http proxy server') - httpd.serve_forever() - except KeyboardInterrupt: - logger.info('Shutting down server') - httpd.socket.close() - - -TIMEOUT = int(get_env_var("TIMEOUT", is_required=False, default=60*5)) -MAX_CONCURRENT_SPDK = int(get_env_var("MAX_CONCURRENT_SPDK", is_required=False, default=16)) -# Multiplier applied to the caller-supplied HTTP timeout (X-RPC-Timeout header) -# to derive how long the proxy waits on SPDK while holding a semaphore slot. -# >1 so a request that completes just after the caller's deadline still returns -# instead of being aborted; small enough that abandoned/stuck RPCs free their -# slot quickly. See _resolve_sock_timeout. -SPDK_TIMEOUT_MARGIN = float(get_env_var("SPDK_TIMEOUT_MARGIN", is_required=False, default=2)) -# Idle-connection reclaim timeout; 60s comfortably spans the 3-30s polling -# cadences of the background services that are this proxy's main callers. -KEEPALIVE_TIMEOUT = int(get_env_var("KEEPALIVE_TIMEOUT", is_required=False, default=60)) -# Cap on concurrent HTTP connections/threads. Above MAX_CONCURRENT_SPDK since -# a kept-alive connection can sit idle, not doing SPDK work, most of the time. -MAX_CONCURRENT_CONNECTIONS = int(get_env_var("MAX_CONCURRENT_CONNECTIONS", is_required=False, default=64)) -is_threading_enabled = get_env_var("MULTI_THREADING_ENABLED", is_required=False, default=False) -server_ip = get_env_var("SERVER_IP", is_required=True, default="") -rpc_port = get_env_var("RPC_PORT", is_required=True) -rpc_username = get_env_var("RPC_USERNAME", is_required=True) -rpc_password = get_env_var("RPC_PASSWORD", is_required=True) - -try: - rpc_port = int(rpc_port) -except Exception: - rpc_port = 8080 -rpc_sock = f"/mnt/ramdisk/spdk_{rpc_port}/spdk.sock" - -spdk_semaphore = threading.Semaphore(MAX_CONCURRENT_SPDK) -logger.info(f"SPDK concurrency limit: {MAX_CONCURRENT_SPDK}") - -is_threading_enabled = bool(is_threading_enabled) -run_server(server_ip, rpc_port, rpc_username, rpc_password, is_threading_enabled=is_threading_enabled) + try: + response = await proxy.rpc_call(body, request.headers.get('X-RPC-Timeout')) + except ValueError: + return Response(status_code=500) + except OSError as e: + # SPDK is gone (crashed, or never came back after a restart). + # The pre-FastAPI server let this escape the handler and dropped + # the connection; a 500 says the same thing legibly. + logger.error(f"Could not reach SPDK on {proxy.settings.rpc_sock}: {e}") + return Response(status_code=500) + + if response is None: + return Response(status_code=204) + + return Response(content=response, media_type='application/json') + finally: + proxy.active_requests -= 1 + + return app + + +def _configure_logging() -> None: + handler = logging.StreamHandler(stream=sys.stdout) + handler.setFormatter(logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')) + root = logging.getLogger() + root.addHandler(handler) + root.setLevel(logging.INFO) + + +def main() -> None: + _configure_logging() + # Required fields come from the environment, which mypy can't see without + # the pydantic plugin. + settings = ProxySettings() # type: ignore[call-arg] + tls = Settings() + uvicorn.Server(uvicorn.Config( + app=create_app(settings), + host=settings.server_ip, + port=settings.rpc_port, + log_level='info', + timeout_keep_alive=KEEP_ALIVE_TIMEOUT_SEC, + ssl_certfile=tls.tls_certificate if tls.tls_serve else None, + ssl_keyfile=tls.tls_key if tls.tls_serve else None, + ssl_ca_certs=tls.tls_certificate_authority if tls.tls_client_auth != ssl.CERT_NONE else None, + ssl_cert_reqs=tls.tls_client_auth, + )).run() + + +if __name__ == '__main__': + main() diff --git a/tests/AGENTS.md b/tests/AGENTS.md index 4d12fef95d..0db79d56da 100644 --- a/tests/AGENTS.md +++ b/tests/AGENTS.md @@ -8,7 +8,6 @@ Two-tier test suite for the Simplyblock control plane. Unit tests run as pure lo tests/ ├── conftest.py # Clears DBController/RPC caches before each test. Does NOT stub `fdb`. ├── _mocks.py # Shared mock factories (e.g. `make_mock_cluster`). -├── conftest_proxy.py # `import_proxy_module()` helper that neutralizes spdk_http_proxy_server's module-level run_server side-effect; used by both proxy unit + e2e tests. ├── unit/ # Pure-logic tests; single module under test, no model state, no flows. │ ├── conftest.py # Stubs the native `fdb` module so unit tests run without libfdb_c / a live cluster. │ ├── models/ # Every `BaseModel` test: field defaults, secrets, chunked reads, serialization. diff --git a/tests/conftest_proxy.py b/tests/conftest_proxy.py deleted file mode 100644 index cd22ba4a6a..0000000000 --- a/tests/conftest_proxy.py +++ /dev/null @@ -1,55 +0,0 @@ -# coding=utf-8 -""" -conftest_proxy.py – helper to import spdk_http_proxy_server safely in tests. - -The proxy module has module-level code that starts a server, so we must -mock the entire server startup chain before import. -""" - -import json -import os -import socket -import sys -import threading -from unittest.mock import patch, MagicMock - -# Windows compat -if not hasattr(socket, 'AF_UNIX'): - socket.AF_UNIX = 1 - -# Required env vars -os.environ.setdefault("SERVER_IP", "127.0.0.1") -os.environ.setdefault("RPC_PORT", "19999") -os.environ.setdefault("RPC_USERNAME", "test") -os.environ.setdefault("RPC_PASSWORD", "test") -os.environ.setdefault("TIMEOUT", "5") -os.environ.setdefault("MAX_CONCURRENT_SPDK", "4") - - -def import_proxy_module(): - """Import spdk_http_proxy_server with all side-effects neutralized.""" - # Remove cached module - sys.modules.pop("simplyblock_core.services.spdk_http_proxy_server", None) - - # Mock socket so wait_for_spdk_ready succeeds - resp = json.dumps({"jsonrpc": "2.0", "id": 1, "result": {"version": "1"}}).encode() - mock_sock = MagicMock() - mock_sock.recv = MagicMock(side_effect=[resp, b'']) - - # Mock HTTPServer so serve_forever doesn't block - mock_httpd = MagicMock() - mock_httpd.serve_forever = MagicMock(return_value=None) - - with patch("socket.socket", return_value=mock_sock): - with patch("http.server.HTTPServer", return_value=mock_httpd): - with patch("http.server.ThreadingHTTPServer", return_value=mock_httpd): - import simplyblock_core.services.spdk_http_proxy_server as mod - - # Reinitialize for testing - mod.spdk_semaphore = threading.Semaphore(4) - mod.spdk_ready = True - mod.rpc_sock = "/tmp/fake_test.sock" - mod.unix_sockets.clear() - mod.TIMEOUT = 5 - - return mod diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index b1e7f9359f..ce5611c0fa 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -1,48 +1,34 @@ # coding=utf-8 -""" -test_spdk_proxy_e2e.py – mocked end-to-end tests for spdk_http_proxy_server. +"""End-to-end tests for the SPDK HTTP proxy. -Uses a real unix socket mock SPDK server and the real proxy HTTP server -to test the full request flow: readiness gating, request forwarding, -timeout cleanup, and zombie socket prevention. +A real unix-socket server stands in for SPDK and the real proxy application is +served by uvicorn, so the full path is exercised: readiness gating, HTTP +framing, request forwarding, timeout handling and socket cleanup. NOTE: Requires AF_UNIX (Linux/macOS). Skipped on Windows. """ import base64 +import contextlib +import http.client import json import os +import socket import socketserver import sys import tempfile import threading import time import unittest -from unittest.mock import patch import requests +import uvicorn if sys.platform == "win32": raise unittest.SkipTest("AF_UNIX not available on Windows") -from tests.conftest_proxy import import_proxy_module - +from simplyblock_core.services.spdk_http_proxy_server import ProxySettings, create_app -def _wait_until(predicate, timeout=5, interval=0.02): - """Poll ``predicate`` instead of a fixed sleep-then-assert. - - A single fixed sleep assumes the process gets scheduled promptly; under - CI load (or another test's global time.sleep patch stealing this - process's CPU -- see print_stats in spdk_http_proxy_server.py) cleanup - that normally finishes in microseconds can take longer than that budget - without ever actually failing to happen. - """ - deadline = time.monotonic() + timeout - while time.monotonic() < deadline: - if predicate(): - return True - time.sleep(interval) - return predicate() # --------------------------------------------------------------------------- # Mock SPDK unix socket server @@ -78,9 +64,8 @@ class MockSPDKServer(socketserver.ThreadingUnixStreamServer): allow_reuse_address = True - def __init__(self, sock_path, ready=True, delay=0): + def __init__(self, sock_path, delay=0): self.sock_path = sock_path - self._ready = ready self._delay = delay self._call_log = [] self._lock = threading.Lock() @@ -106,217 +91,206 @@ def call_log(self): return list(self._call_log) -def _start_mock_spdk(sock_path, **kwargs): - """Start a mock SPDK server in a background thread.""" +@contextlib.contextmanager +def mock_spdk(sock_path, **kwargs): + """Serve a mock SPDK on ``sock_path`` for the duration of the block.""" server = MockSPDKServer(sock_path, **kwargs) - thread = threading.Thread(target=server.serve_forever, daemon=True) - thread.start() - return server + threading.Thread(target=server.serve_forever, daemon=True).start() + try: + yield server + finally: + server.shutdown() + server.server_close() + with contextlib.suppress(OSError): + os.unlink(sock_path) # --------------------------------------------------------------------------- -# Proxy launcher helper +# Proxy under test # --------------------------------------------------------------------------- -class _ProxyHandle: - """The proxy thread's bound port, when it bound, or why it could not. - - The proxy binds its HTTP port only AFTER ``wait_for_spdk_ready()`` - returns -- that ordering is the thing TestProxyReadinessGate exists to - verify -- so the port cannot be known before the thread runs. Publishing - it back turns two silent failure modes into loud ones: - - * a hardcoded port already in use raised OSError inside a daemon thread - and was swallowed, so the test saw only "Proxy should eventually come - up" after polling for 8s, with nothing to say why. That is exactly how - it failed in CI run 33668203362 on main. - * every other startup error looked identical to that one. - - Ports are now requested as 0, so the OS picks a free one and neither a - sibling test class nor a parallel CI job can contend for a fixed number. - """ - - def __init__(self): - self._ready = threading.Event() - self.port = None - self.bind_time = None - self.error = None - - def _publish_port(self, port, bind_time): - self.port = port - self.bind_time = bind_time - self._ready.set() - - def _publish_error(self, exc): - self.error = exc - self._ready.set() - - def settled_within(self, timeout): - """True if the thread has already bound (or failed) within timeout. - - Event.wait, deliberately, not time.sleep: another module in this test - session patches time.sleep globally, so any duration measured against - a sleep is meaningless here. That is what made the first version of - the gate assertion below read 7ms for a 1s delay in CI run - 33671036716 -- the delay simply never happened. - """ - return self._ready.wait(timeout) - - def wait(self, timeout=30): - """Bound port, or an assertion naming the actual problem.""" - if not self._ready.wait(timeout): - raise AssertionError( - f"proxy thread neither bound nor failed within {timeout}s") - if self.error is not None: - raise AssertionError(f"proxy failed to start: {self.error!r}") - return self.port - - -def _start_proxy(sock_path, http_port=0, max_concurrent=4, timeout=5): - """Start the spdk_http_proxy_server in a background thread. - - We import and configure the module, then run the server. - Returns (thread, stop_event, module, handle); pass http_port=0 (the - default) to get an OS-assigned port and read it off the handle. - """ - # The proxy module starts a real server at import time, so we use the - # shared helper that neutralizes that side-effect during import. The - # helper also pre-sets required env vars (SERVER_IP, RPC_PORT, ...). - mod = import_proxy_module() - - # Reconfigure module globals — the helper sets defaults; override with - # the values this test needs. - mod.rpc_sock = sock_path - mod.TIMEOUT = timeout - mod.MAX_CONCURRENT_SPDK = max_concurrent - mod.spdk_semaphore = threading.Semaphore(max_concurrent) - mod.spdk_ready = False - mod.unix_sockets.clear() - mod.ServerHandler.server_session.clear() - mod.read_line_time_diff.clear() - mod.recv_from_spdk_time_diff.clear() - - stop_event = threading.Event() - - handle = _ProxyHandle() - - def run(): +def _free_port(): + with socket.socket() as s: + s.bind(("127.0.0.1", 0)) + return s.getsockname()[1] + + +class RunningProxy: + """The real proxy app, served by uvicorn on a loopback port.""" + + def __init__(self, sock_path, **overrides): + settings = ProxySettings(**{ + "server_ip": "127.0.0.1", + "rpc_port": _free_port(), + "rpc_sock_path": sock_path, + "rpc_username": "test", + "rpc_password": "test", + "timeout": 5, + "max_concurrent_spdk": 4, + "multi_threading_enabled": True, + **overrides, + }) + self.address = ("127.0.0.1", settings.rpc_port) + self.url = f"http://127.0.0.1:{settings.rpc_port}/" + app = create_app(settings) + self.proxy = app.state.proxy + self._server = uvicorn.Server(uvicorn.Config( + app=app, host=settings.server_ip, port=settings.rpc_port, log_level="warning")) + self._thread = threading.Thread(target=self._server.run, daemon=True) + + def start(self): + self._thread.start() + + def stop(self): + self._server.should_exit = True + self._thread.join(timeout=10) + + def wait_until_serving(self, timeout=15): + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + try: + if self.post("spdk_get_version").status_code == 200: + return True + except requests.RequestException: + pass + time.sleep(0.1) + return False + + def is_refusing_connections(self): + try: + requests.post(self.url, data="{}", timeout=2) + except requests.ConnectionError: + return True + return False + + def post(self, method, params=None, auth=("test", "test"), headers=None, **kwargs): + payload = {"id": 1, "method": method} + if params: + payload["params"] = params + return self.request(json.dumps(payload), auth=auth, headers=headers, **kwargs) + + def request(self, body, auth=("test", "test"), headers=None, timeout=10, session=requests): + return session.post(self.url, data=body, auth=auth, headers=headers, timeout=timeout) + + @contextlib.contextmanager + def connection(self, timeout=10): + """One HTTP connection, kept open across requests.""" + conn = http.client.HTTPConnection(*self.address, timeout=timeout) try: - key = base64.b64encode(b"test:test").decode("ascii") - mod.wait_for_spdk_ready() - mod.ServerHandler.key = key - from http.server import ThreadingHTTPServer - httpd = ThreadingHTTPServer(("127.0.0.1", http_port), mod.ServerHandler) - # Accept timeout only -- the SPDK-side budget is mod.TIMEOUT. Kept - # short so stop_event is honoured (and the port released) within a - # fraction of a second instead of up to `timeout`, which used to - # leave a fixed port bound while the next test tried to claim it. - httpd.timeout = 0.2 - handle._publish_port(httpd.server_address[1], time.monotonic()) - except Exception as e: # noqa: BLE001 - reported via the handle - handle._publish_error(e) - return - - while not stop_event.is_set(): - httpd.handle_request() - httpd.server_close() - - thread = threading.Thread(target=run, daemon=True) - thread.start() - return thread, stop_event, mod, handle + conn.connect() + yield conn + finally: + conn.close() + + +@contextlib.contextmanager +def running_proxy(sock_path, **overrides): + proxy = RunningProxy(sock_path, **overrides) + proxy.start() + try: + yield proxy + finally: + proxy.stop() + + +@contextlib.contextmanager +def sock_path(): + with tempfile.TemporaryDirectory() as tmpdir: + yield os.path.join(tmpdir, "spdk.sock") class TestProxyE2E(unittest.TestCase): - """End-to-end tests with mock SPDK server + real proxy.""" + """Mock SPDK + the real proxy, over real HTTP.""" @classmethod def setUpClass(cls): - cls._tmpdir = tempfile.mkdtemp() - cls._sock_path = os.path.join(cls._tmpdir, "spdk_test.sock") - # Start mock SPDK - cls._spdk_server = _start_mock_spdk(cls._sock_path) - time.sleep(0.1) - - # Start proxy on an OS-assigned port (see _ProxyHandle). - cls._proxy_thread, cls._stop_event, cls._mod, handle = _start_proxy( - cls._sock_path, 0, max_concurrent=4, timeout=5) - cls._http_port = handle.wait() - - # Wait for proxy to be ready - for _ in range(30): - try: - r = requests.post( - f"http://127.0.0.1:{cls._http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("test", "test"), - timeout=2, - ) - if r.status_code == 200: - break - except requests.ConnectionError: - pass - time.sleep(0.2) + cls._stack = contextlib.ExitStack() + path = cls._stack.enter_context(sock_path()) + cls._spdk = cls._stack.enter_context(mock_spdk(path)) + cls._proxy = cls._stack.enter_context(running_proxy(path)) + if not cls._proxy.wait_until_serving(): + cls._stack.close() + raise unittest.SkipTest("proxy did not come up") @classmethod def tearDownClass(cls): - cls._stop_event.set() - cls._spdk_server.shutdown() - try: - os.unlink(cls._sock_path) - except OSError: - pass - try: - os.rmdir(cls._tmpdir) - except OSError: - pass - - def _post(self, method, params=None): - payload = {"id": 1, "method": method} - if params: - payload["params"] = params - r = requests.post( - f"http://127.0.0.1:{self._http_port}/", - data=json.dumps(payload), - auth=("test", "test"), - timeout=5, - ) - return r - - def test_readiness_gate_prevents_zombie_sockets(self): - """After startup, there should be zero lingering unix sockets.""" - self.assertEqual(len(self._mod.unix_sockets), 0) + cls._stack.close() def test_basic_rpc_roundtrip(self): - """A simple RPC should return a valid JSON-RPC response.""" - r = self._post("spdk_get_version") - self.assertEqual(r.status_code, 200) - data = r.json() - self.assertIn("result", data) - self.assertEqual(data["result"]["version"], "24.01") + response = self._proxy.post("spdk_get_version") + + self.assertEqual(response.status_code, 200) + self.assertEqual(response.json()["result"]["version"], "24.01") + + def test_request_reaches_spdk(self): + self._proxy.post("nvmf_get_subsystems") + + self.assertIn("nvmf_get_subsystems", self._spdk.call_log) def test_bdev_get_bdevs_roundtrip(self): - r = self._post("bdev_get_bdevs") - self.assertEqual(r.status_code, 200) - data = r.json() - self.assertIn("result", data) - self.assertIsInstance(data["result"], list) + response = self._proxy.post("bdev_get_bdevs") + + self.assertEqual(response.status_code, 200) + self.assertIsInstance(response.json()["result"], list) + + def test_notification_gets_204(self): + response = self._proxy.request(json.dumps({"method": "spdk_kill_instance"})) + + self.assertEqual(response.status_code, 204) + self.assertEqual(response.content, b'') + + def test_unauthorized_returns_401(self): + response = self._proxy.post("spdk_get_version", auth=("wrong", "creds")) + + self.assertEqual(response.status_code, 401) + + def test_malformed_body_returns_500(self): + response = self._proxy.request("not json") + + self.assertEqual(response.status_code, 500) + + def test_keep_alive_serves_several_requests_on_one_connection(self): + """The HTTP/1.0 server this replaced closed after every response, so + every RPC paid for a fresh TCP connection.""" + body = json.dumps({"id": 1, "method": "spdk_get_version"}) + headers = {"Authorization": "Basic " + base64.b64encode(b"test:test").decode("ascii")} + + with self._proxy.connection() as conn: + for _ in range(5): + conn.request("POST", "/", body=body, headers=headers) + response = conn.getresponse() + response.read() + + self.assertEqual(response.status, 200) + self.assertFalse(response.will_close, "proxy closed the connection after a response") + + def test_unauthorized_request_does_not_corrupt_the_connection(self): + """A rejected request leaves its body unread; on a kept-alive + connection that body used to be parsed as the next request.""" + with requests.Session() as session: + rejected = self._proxy.post( + "spdk_get_version", auth=("wrong", "creds"), session=session) + self.assertEqual(rejected.status_code, 401) + + accepted = self._proxy.post("spdk_get_version", session=session) + + self.assertEqual(accepted.status_code, 200) + self.assertEqual(accepted.json()["result"]["version"], "24.01") def test_no_socket_leak_after_requests(self): - """After several requests complete, no unix sockets should be leaked.""" for _ in range(5): - self._post("spdk_get_version") - _wait_until(lambda: len(self._mod.unix_sockets) == 0) - self.assertEqual(len(self._mod.unix_sockets), 0) + self._proxy.post("spdk_get_version") + + self.assertEqual(self._proxy.proxy.open_connections, 0) + self.assertEqual(self._proxy.proxy.active_requests, 0) def test_concurrent_requests(self): - """Multiple concurrent requests should all succeed.""" results = [] errors = [] def do_request(): try: - r = self._post("spdk_get_version") - results.append(r.status_code) + results.append(self._proxy.post("spdk_get_version").status_code) except Exception as e: errors.append(e) @@ -327,146 +301,41 @@ def do_request(): t.join(timeout=10) self.assertEqual(errors, []) - self.assertTrue(all(s == 200 for s in results), f"Got statuses: {results}") + self.assertEqual(results, [200] * 8) + self.assertEqual(self._proxy.proxy.open_connections, 0) - def test_unauthorized_returns_401(self): - """Request with wrong credentials should get 401.""" - r = requests.post( - f"http://127.0.0.1:{self._http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("wrong", "creds"), - timeout=5, - ) - self.assertEqual(r.status_code, 401) - - def test_session_count_returns_to_baseline(self): - """After requests complete, server_session should be empty.""" - for _ in range(3): - self._post("spdk_get_version") - _wait_until(lambda: len(self._mod.ServerHandler.server_session) == 0) - self.assertEqual(len(self._mod.ServerHandler.server_session), 0) - - def test_keep_alive_reuses_one_connection_for_several_requests(self): - """A client session issuing several requests should open ONE TCP - connection, not one per request.""" - connection_count = {"n": 0} - original_setup = self._mod.ServerHandler.setup - - def counting_setup(handler_self): - connection_count["n"] += 1 - original_setup(handler_self) - - with patch.object(self._mod.ServerHandler, "setup", counting_setup): - with requests.Session() as session: - for _ in range(5): - r = session.post( - f"http://127.0.0.1:{self._http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("test", "test"), - timeout=5, - ) - self.assertEqual(r.status_code, 200) - - self.assertEqual( - connection_count["n"], 1, - "expected all 5 requests on one requests.Session to reuse a " - "single kept-alive TCP connection to the proxy") - def test_unauthorized_request_does_not_corrupt_the_connection(self): - """Regression test: an undrained body on a 401 used to leak into the - next request on the same kept-alive connection ('Bad request version').""" - with requests.Session() as session: - r1 = session.post( - f"http://127.0.0.1:{self._http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("wrong", "creds"), - timeout=5, - ) - self.assertEqual(r1.status_code, 401) - - r2 = session.post( - f"http://127.0.0.1:{self._http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("test", "test"), - timeout=5, - ) - self.assertEqual(r2.status_code, 200) - self.assertEqual(r2.json()["result"]["version"], "24.01") +class TestProxyReadinessGate(unittest.TestCase): + def test_port_stays_closed_until_spdk_answers(self): + with sock_path() as path, running_proxy(path) as proxy: + self.assertTrue( + proxy.is_refusing_connections(), + "proxy must not accept requests before SPDK is up") -class TestProxyReadinessGate(unittest.TestCase): - """Test that the proxy blocks until SPDK is ready.""" - - def test_proxy_waits_for_spdk(self): - """Proxy should not accept HTTP requests until SPDK responds.""" - tmpdir = tempfile.mkdtemp() - sock_path = os.path.join(tmpdir, "spdk_delayed.sock") - - ready_time = {"t": None} - # SPDK appears when this test says so, rather than after a sleep a - # sibling test module may have patched away. - release_spdk = threading.Event() - - # Start the SPDK server only once release_spdk fires. - def delayed_spdk(): - release_spdk.wait(30) - server = _start_mock_spdk(sock_path) - ready_time["t"] = time.monotonic() - return server - - spdk_thread = threading.Thread(target=delayed_spdk, daemon=True) - spdk_thread.start() - - _, stop_event, mod_ref, handle = _start_proxy( - sock_path, 0, max_concurrent=4, timeout=5) - - # The gate itself: with SPDK absent, the proxy must not open its HTTP - # port. This is the assertion the test was named for and never made. - self.assertFalse( - handle.settled_within(0.5), - "proxy bound its HTTP port while SPDK was still absent: the " - "readiness gate did not hold") - - # Now let SPDK up; the proxy should follow. - release_spdk.set() - http_port = handle.wait(timeout=30) - - # Wait for the bound proxy to serve. Paced with Event.wait rather - # than time.sleep: a sibling module patches time.sleep globally, which - # would collapse all 40 attempts into microseconds and turn a slow - # start into a spurious "Proxy should eventually come up". - pacer = threading.Event() - proxy_up = False - for _ in range(40): - try: - r = requests.post( - f"http://127.0.0.1:{http_port}/", - data=json.dumps({"id": 1, "method": "spdk_get_version"}), - auth=("test", "test"), - timeout=2, - ) - if r.status_code == 200: - proxy_up = True - break - except requests.ConnectionError: - pass - pacer.wait(0.2) + with mock_spdk(path): + self.assertTrue(proxy.wait_until_serving()) + self.assertTrue(proxy.proxy.spdk_ready) + self.assertEqual(proxy.proxy.open_connections, 0) - stop_event.set() - self.assertTrue(proxy_up, "Proxy should eventually come up") - self.assertIsNotNone(ready_time["t"], "mock SPDK never came up") - # Proxy should have waited for SPDK: verify no zombie sockets - self.assertEqual(len(mod_ref.unix_sockets), 0) +class TestProxyTimeout(unittest.TestCase): - try: - os.unlink(sock_path) - except OSError: - pass - try: - os.rmdir(tmpdir) - except OSError: - pass + def test_caller_timeout_bounds_the_spdk_wait(self): + """A caller-supplied X-RPC-Timeout must free the SPDK slot early rather + than pin it for the proxy-global timeout.""" + with sock_path() as path, mock_spdk(path) as spdk, running_proxy( + path, timeout=30, spdk_timeout_margin=2) as proxy: + self.assertTrue(proxy.wait_until_serving()) + spdk._delay = 1 # only now, so the readiness probe stays fast + + started = time.monotonic() + response = proxy.post("bdev_get_bdevs", headers={"X-RPC-Timeout": "0.2"}) + elapsed = time.monotonic() - started + + self.assertEqual(response.status_code, 500) + self.assertLess(elapsed, 1) + self.assertEqual(proxy.proxy.open_connections, 0) if __name__ == "__main__": diff --git a/tests/unit/test_service_entrypoints.py b/tests/unit/test_service_entrypoints.py index cd74ab4a97..c8d5377433 100644 --- a/tests/unit/test_service_entrypoints.py +++ b/tests/unit/test_service_entrypoints.py @@ -24,7 +24,6 @@ import importlib import pathlib import unittest -from typing import ClassVar from simplyblock_core.services import __main__ as dispatcher @@ -113,23 +112,11 @@ def test_all_are_dispatchable_by_name(self): class TestServicesHaveMain(unittest.TestCase): - """Each service should expose ``main()`` so it is callable and testable. - - ``spdk_http_proxy_server`` is deliberately exempt: its module body builds the - shared state ``ServerHandler`` and ``rpc_call`` read as globals (``TIMEOUT``, - ``MAX_CONCURRENT_SPDK``, ``spdk_semaphore``, ``rpc_sock``) and its - ``get_env_var(..., is_required=True)`` calls raise at import time, so wrapping - it changes binding semantics on the storage-node data path. The dispatcher - runs it through ``runpy``, which needs no ``main()``. - """ - - EXEMPT: ClassVar[str] = {"spdk_http_proxy_server"} + """Each service should expose ``main()`` so it is callable and testable.""" def test_every_service_defines_main(self): for name in dispatcher._service_names(): module = name.replace("-", "_") - if module in self.EXEMPT: - continue with self.subTest(service=name): tree = ast.parse(_module_path(name).read_text()) self.assertTrue( diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index fb6eb2fafc..6465b24d2e 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -1,267 +1,458 @@ # coding=utf-8 -""" -test_spdk_proxy_unit.py – unit tests for spdk_http_proxy_server changes. +"""Unit tests for the SPDK HTTP proxy. + +The module under test is imported plainly: building the app is an explicit +``create_app()`` call, so nothing here has to neutralize import-time side +effects. """ +import asyncio import json -import socket -import threading -import time +import os import unittest -from unittest.mock import patch, MagicMock +from unittest.mock import AsyncMock, patch -from tests.conftest_proxy import import_proxy_module +from fastapi.testclient import TestClient +from pydantic import ValidationError -proxy_mod = import_proxy_module() +from simplyblock_core.services import spdk_http_proxy_server as proxy_mod -class TestWaitForSpdkReady(unittest.TestCase): +REQUIRED_ENV = { + "SERVER_IP": "127.0.0.1", + "RPC_PORT": "19999", + "RPC_USERNAME": "test", + "RPC_PASSWORD": "secret", +} - def setUp(self): - proxy_mod.spdk_ready = False - - def tearDown(self): - proxy_mod.spdk_ready = True - - def test_retries_until_spdk_responds(self): - call_count = {"n": 0} - - def mock_socket_factory(*args, **kwargs): - call_count["n"] += 1 - s = MagicMock() - if call_count["n"] < 3: - s.connect = MagicMock(side_effect=ConnectionRefusedError("not ready")) - else: - response = json.dumps({"jsonrpc": "2.0", "id": 1, "result": {"version": "24.01"}}).encode() - s.connect = MagicMock() - s.sendall = MagicMock() - s.recv = MagicMock(side_effect=[response, b'']) - s.close = MagicMock() - return s - - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", side_effect=mock_socket_factory): - with patch("simplyblock_core.services.spdk_http_proxy_server.time.sleep"): - proxy_mod.wait_for_spdk_ready() - - self.assertTrue(proxy_mod.spdk_ready) - self.assertEqual(call_count["n"], 3) - - def test_already_ready_returns_immediately(self): - proxy_mod.spdk_ready = True - proxy_mod.wait_for_spdk_ready() - self.assertTrue(proxy_mod.spdk_ready) - - def test_socket_closed_on_connection_error(self): - attempt = {"n": 0} - socks = [] - - def mock_socket_factory(*args, **kwargs): - attempt["n"] += 1 - s = MagicMock() - socks.append(s) - if attempt["n"] == 1: - s.connect = MagicMock(side_effect=OSError("no socket")) - else: - response = json.dumps({"jsonrpc": "2.0", "id": 1, "result": {}}).encode() - s.connect = MagicMock() - s.sendall = MagicMock() - s.recv = MagicMock(side_effect=[response, b'']) - s.close = MagicMock() - return s - - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", side_effect=mock_socket_factory): - with patch("simplyblock_core.services.spdk_http_proxy_server.time.sleep"): - proxy_mod.wait_for_spdk_ready() - - socks[0].close.assert_called() - - -class TestRpcCallInnerSocketCleanup(unittest.TestCase): +# Every optional variable is pinned so an ambient value can't change a test. +OPTIONAL_ENV = { + "TIMEOUT": "5", + "MAX_CONCURRENT_SPDK": "4", + "SPDK_TIMEOUT_MARGIN": "2", + "MULTI_THREADING_ENABLED": "True", +} - def setUp(self): - proxy_mod.unix_sockets.clear() - def test_socket_closed_on_success(self): - req_data = {"id": 1, "method": "test"} - req = json.dumps(req_data).encode("ascii") - response = json.dumps({"jsonrpc": "2.0", "id": 1, "result": True}).encode("ascii") +def make_settings(**overrides) -> proxy_mod.ProxySettings: + params = dict( + server_ip="127.0.0.1", + rpc_port=19999, + rpc_username="test", + rpc_password="secret", + timeout=5, + max_concurrent_spdk=4, + spdk_timeout_margin=2, + multi_threading_enabled=True, + ) + params.update(overrides) + return proxy_mod.ProxySettings(**params) - mock_sock = MagicMock() - mock_sock.recv = MagicMock(side_effect=[response, b'']) - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", return_value=mock_sock): - result = proxy_mod._rpc_call_inner(req, req_data, time.time_ns(), proxy_mod.TIMEOUT) +def make_proxy(**overrides) -> proxy_mod.SpdkProxy: + return proxy_mod.SpdkProxy(make_settings(**overrides)) - self.assertIsNotNone(result) - mock_sock.close.assert_called_once() - self.assertEqual(len(proxy_mod.unix_sockets), 0) - def test_socket_closed_on_timeout(self): - req_data = {"id": 1, "method": "test"} - req = json.dumps(req_data).encode("ascii") +class FakeReader: + def __init__(self, chunks): + self._chunks = list(chunks) - mock_sock = MagicMock() - mock_sock.recv = MagicMock(side_effect=socket.timeout("timed out")) + async def read(self, n=-1): + return self._chunks.pop(0) if self._chunks else b'' - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", return_value=mock_sock): - with self.assertRaises(ValueError) as ctx: - proxy_mod._rpc_call_inner(req, req_data, time.time_ns(), proxy_mod.TIMEOUT) - self.assertIn("timeout", str(ctx.exception)) - mock_sock.close.assert_called_once() - self.assertEqual(len(proxy_mod.unix_sockets), 0) +class FakeWriter: + def __init__(self): + self.buffer = b'' + self.closed = False - def test_socket_closed_on_connect_error(self): - req_data = {"id": 1, "method": "test"} - req = json.dumps(req_data).encode("ascii") + def write(self, data): + self.buffer += data - mock_sock = MagicMock() - mock_sock.connect = MagicMock(side_effect=ConnectionRefusedError("refused")) + async def drain(self): + pass - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", return_value=mock_sock): - with self.assertRaises(ConnectionRefusedError): - proxy_mod._rpc_call_inner(req, req_data, time.time_ns(), proxy_mod.TIMEOUT) + def close(self): + self.closed = True - mock_sock.close.assert_called_once() - self.assertEqual(len(proxy_mod.unix_sockets), 0) - def test_no_id_request_closes_socket(self): - req_data = {"method": "notification_only"} - req = json.dumps(req_data).encode("ascii") - mock_sock = MagicMock() +class FakeSpdkSocket: + """Stands in for ``asyncio.open_unix_connection``. - with patch("simplyblock_core.services.spdk_http_proxy_server.socket.socket", return_value=mock_sock): - result = proxy_mod._rpc_call_inner(req, req_data, time.time_ns(), proxy_mod.TIMEOUT) + Each entry of ``attempts`` is either an exception to raise on connect or a + list of chunks the reader hands out. The last entry repeats once exhausted, + so a retry loop settles on a steady state. + """ - self.assertIsNone(result) - mock_sock.close.assert_called_once() - self.assertEqual(len(proxy_mod.unix_sockets), 0) + def __init__(self, *attempts): + self.attempts = list(attempts) + self.paths = [] + self.writers = [] + + async def __call__(self, path): + self.paths.append(path) + attempt = self.attempts.pop(0) if len(self.attempts) > 1 else self.attempts[0] + writer = FakeWriter() + self.writers.append(writer) + if isinstance(attempt, BaseException): + raise attempt + return FakeReader(attempt), writer + + @property + def attempt_count(self): + return len(self.paths) + + +def patch_connect(fake): + return patch.object(proxy_mod.asyncio, 'open_unix_connection', new=fake) + + +def rpc_response(**kwargs): + return json.dumps({"jsonrpc": "2.0", "id": 1, **kwargs}).encode('ascii') + + +class TestProxySettings(unittest.TestCase): + """The proxy is configured exclusively through unprefixed environment + variables that deployed manifests already set — defaults included.""" + + def test_defaults_match_the_documented_environment(self): + with patch.dict(os.environ, REQUIRED_ENV, clear=True): + settings = proxy_mod.ProxySettings() + + self.assertEqual(settings.server_ip, "127.0.0.1") + self.assertEqual(settings.rpc_port, 19999) + self.assertEqual(settings.rpc_username, "test") + self.assertEqual(settings.rpc_password.get_secret_value(), "secret") + self.assertEqual(settings.timeout, 5 * 60) + self.assertEqual(settings.max_concurrent_spdk, 16) + self.assertEqual(settings.spdk_timeout_margin, 2.0) + self.assertFalse(settings.multi_threading_enabled) + + def test_optional_environment_is_read(self): + with patch.dict(os.environ, {**REQUIRED_ENV, **OPTIONAL_ENV}, clear=True): + settings = proxy_mod.ProxySettings() + + self.assertEqual(settings.timeout, 5) + self.assertEqual(settings.max_concurrent_spdk, 4) + self.assertEqual(settings.spdk_timeout_margin, 2.0) + self.assertTrue(settings.multi_threading_enabled) + + def test_lowercase_environment_is_accepted(self): + with patch.dict(os.environ, {k.lower(): v for k, v in REQUIRED_ENV.items()}, clear=True): + self.assertEqual(proxy_mod.ProxySettings().rpc_port, 19999) + + def test_missing_required_variable_is_rejected(self): + for name in REQUIRED_ENV: + env = {k: v for k, v in REQUIRED_ENV.items() if k != name} + with self.subTest(missing=name), patch.dict(os.environ, env, clear=True): + with self.assertRaises(ValidationError): + proxy_mod.ProxySettings() + + def test_unparsable_rpc_port_falls_back_to_8080(self): + with patch.dict(os.environ, {**REQUIRED_ENV, "RPC_PORT": "not-a-port"}, clear=True): + settings = proxy_mod.ProxySettings() + + self.assertEqual(settings.rpc_port, 8080) + self.assertEqual(settings.rpc_sock, "/mnt/ramdisk/spdk_8080/spdk.sock") + + def test_rpc_sock_follows_the_rpc_port(self): + self.assertEqual( + make_settings(rpc_port=9060).rpc_sock, "/mnt/ramdisk/spdk_9060/spdk.sock") + + def test_authorization_header_is_basic_auth(self): + # 'test:secret' base64-encoded — what RPCClient's requests session sends. + self.assertEqual(make_settings().authorization, "Basic dGVzdDpzZWNyZXQ=") + + def test_password_is_masked_in_representations(self): + settings = make_settings() + self.assertNotIn("secret", repr(settings)) + self.assertNotIn("secret", str(settings)) + self.assertNotIn("secret", str(settings.model_dump())) class TestResolveSockTimeout(unittest.TestCase): - """The proxy must bound its SPDK wait (and hence the semaphore-slot hold) + """The proxy must bound its SPDK wait (and hence the concurrency-slot hold) to the caller's HTTP timeout, so an abandoned/stuck RPC frees its slot - quickly instead of squatting it for the full global TIMEOUT and starving + quickly instead of squatting it for the full global timeout and starving other RPCs to the node.""" + def setUp(self): + self.proxy = make_proxy(timeout=300, spdk_timeout_margin=2) + def test_missing_hint_falls_back_to_global(self): - self.assertEqual(proxy_mod._resolve_sock_timeout(None), proxy_mod.TIMEOUT) + self.assertEqual(self.proxy._resolve_sock_timeout(None), 300) def test_invalid_hint_falls_back_to_global(self): - self.assertEqual(proxy_mod._resolve_sock_timeout("not-a-number"), proxy_mod.TIMEOUT) - self.assertEqual(proxy_mod._resolve_sock_timeout("0"), proxy_mod.TIMEOUT) - self.assertEqual(proxy_mod._resolve_sock_timeout("-5"), proxy_mod.TIMEOUT) + self.assertEqual(self.proxy._resolve_sock_timeout("not-a-number"), 300) + self.assertEqual(self.proxy._resolve_sock_timeout("0"), 300) + self.assertEqual(self.proxy._resolve_sock_timeout("-5"), 300) def test_short_caller_timeout_yields_short_hold(self): # A 1s caller (e.g. distr_status_events_update) must not pin a slot for - # the global TIMEOUT; it gets margin x 1s, well under the global cap. - with patch.object(proxy_mod, "SPDK_TIMEOUT_MARGIN", 2), \ - patch.object(proxy_mod, "TIMEOUT", 300): - self.assertEqual(proxy_mod._resolve_sock_timeout("1"), 2) - self.assertEqual(proxy_mod._resolve_sock_timeout("3"), 6) + # the global timeout; it gets margin x 1s, well under the global cap. + self.assertEqual(self.proxy._resolve_sock_timeout("1"), 2) + self.assertEqual(self.proxy._resolve_sock_timeout("3"), 6) def test_long_caller_timeout_capped_at_global(self): - with patch.object(proxy_mod, "SPDK_TIMEOUT_MARGIN", 2), \ - patch.object(proxy_mod, "TIMEOUT", 300): - self.assertEqual(proxy_mod._resolve_sock_timeout("180"), 300) + self.assertEqual(self.proxy._resolve_sock_timeout("180"), 300) + + +class TestWaitForSpdkReady(unittest.IsolatedAsyncioTestCase): + + async def test_retries_until_spdk_responds(self): + fake = FakeSpdkSocket( + ConnectionRefusedError("not ready"), + ConnectionRefusedError("not ready"), + [rpc_response(result={"version": "24.01"})], + ) + proxy = make_proxy() + + with patch_connect(fake), patch.object(proxy_mod.asyncio, 'sleep', new=AsyncMock()): + await proxy.wait_for_spdk_ready() + self.assertTrue(proxy.spdk_ready) + self.assertEqual(fake.attempt_count, 3) + self.assertEqual(fake.paths[0], "/mnt/ramdisk/spdk_19999/spdk.sock") -class TestSemaphoreConcurrency(unittest.TestCase): + async def test_already_ready_returns_immediately(self): + fake = FakeSpdkSocket(ConnectionRefusedError("not ready")) + proxy = make_proxy() + proxy.spdk_ready = True - def test_semaphore_limits_concurrency(self): - max_concurrent = {"seen": 0, "current": 0} - lock = threading.Lock() + with patch_connect(fake): + await proxy.wait_for_spdk_ready() - def mock_inner(req, req_data, req_time, sock_timeout=None): - with lock: - max_concurrent["current"] += 1 - if max_concurrent["current"] > max_concurrent["seen"]: - max_concurrent["seen"] = max_concurrent["current"] - time.sleep(0.05) - with lock: - max_concurrent["current"] -= 1 - return json.dumps({"jsonrpc": "2.0", "id": 1, "result": True}) + self.assertEqual(fake.attempt_count, 0) + + async def test_probe_sends_spdk_get_version(self): + fake = FakeSpdkSocket([rpc_response(result={})]) + proxy = make_proxy() + + with patch_connect(fake): + await proxy.wait_for_spdk_ready() + + self.assertEqual(json.loads(fake.writers[0].buffer)["method"], "spdk_get_version") + + async def test_socket_closed_when_probe_gets_no_answer(self): + fake = FakeSpdkSocket([], [rpc_response(result={})]) # EOF, then a real answer + proxy = make_proxy() + + with patch_connect(fake), patch.object(proxy_mod.asyncio, 'sleep', new=AsyncMock()): + await proxy.wait_for_spdk_ready() + + self.assertTrue(all(writer.closed for writer in fake.writers)) + self.assertEqual(fake.attempt_count, 2) + + +class TestRpcCall(unittest.IsolatedAsyncioTestCase): + """Every RPC must give its unix socket back, whichever way it ends.""" + + def setUp(self): + self.proxy = make_proxy() + self.req = json.dumps({"id": 1, "method": "test"}).encode("ascii") + + async def test_response_is_returned_verbatim(self): + payload = rpc_response(result=True) + fake = FakeSpdkSocket([payload]) + + with patch_connect(fake): + result = await self.proxy.rpc_call(self.req) + + self.assertEqual(result, payload.decode("ascii")) + self.assertEqual(fake.writers[0].buffer, self.req) + self.assertTrue(fake.writers[0].closed) + self.assertEqual(self.proxy.open_connections, 0) + + async def test_chunked_response_is_reassembled(self): + payload = rpc_response(result={"a": 1, "b": 2}) + fake = FakeSpdkSocket([payload[:10], payload[10:]]) + + with patch_connect(fake): + result = await self.proxy.rpc_call(self.req) + + self.assertEqual(json.loads(result)["result"], {"a": 1, "b": 2}) + + async def test_socket_closed_on_timeout(self): + async def never_answers(*args, **kwargs): + await asyncio.sleep(3600) + + fake = FakeSpdkSocket([]) + + with patch_connect(fake), patch.object(FakeReader, 'read', never_answers): + with self.assertRaises(ValueError) as ctx: + await self.proxy.rpc_call(self.req, client_timeout="0.01") + + self.assertIn("timeout", str(ctx.exception)) + self.assertTrue(fake.writers[0].closed) + self.assertEqual(self.proxy.open_connections, 0) + + async def test_socket_released_on_connect_error(self): + fake = FakeSpdkSocket(ConnectionRefusedError("refused")) + + with patch_connect(fake): + with self.assertRaises(ConnectionRefusedError): + await self.proxy.rpc_call(self.req) + + self.assertEqual(self.proxy.open_connections, 0) + + async def test_request_without_id_gets_no_response(self): + req = json.dumps({"method": "notification_only"}).encode("ascii") + fake = FakeSpdkSocket([rpc_response(result=True)]) + + with patch_connect(fake): + result = await self.proxy.rpc_call(req) + + self.assertIsNone(result) + self.assertTrue(fake.writers[0].closed) + self.assertEqual(self.proxy.open_connections, 0) + + async def test_truncated_response_is_rejected(self): + fake = FakeSpdkSocket([b'{"jsonrpc": "2.0", "id"']) + + with patch_connect(fake): + with self.assertRaises(ValueError): + await self.proxy.rpc_call(self.req) + + self.assertEqual(self.proxy.open_connections, 0) + + async def test_caller_timeout_bounds_the_socket_wait(self): + fake = FakeSpdkSocket([rpc_response(result=True)]) + proxy = make_proxy(timeout=300, spdk_timeout_margin=2) + + with patch_connect(fake), patch.object( + proxy_mod.asyncio, 'wait_for', wraps=asyncio.wait_for) as wait_for: + await proxy.rpc_call(self.req, client_timeout="3") + + self.assertEqual(wait_for.call_args.args[1], 6) + + +class TestConcurrencyLimit(unittest.IsolatedAsyncioTestCase): + + async def _run_concurrently(self, proxy, count): + peak = {"seen": 0, "current": 0} + + async def inner(*args, **kwargs): + peak["current"] += 1 + peak["seen"] = max(peak["seen"], peak["current"]) + await asyncio.sleep(0.01) + peak["current"] -= 1 + return rpc_response(result=True).decode() req = json.dumps({"id": 1, "method": "test"}).encode("ascii") + with patch.object(proxy, '_rpc_call_inner', side_effect=inner): + await asyncio.gather(*(proxy.rpc_call(req) for _ in range(count))) - with patch.object(proxy_mod, "_rpc_call_inner", side_effect=mock_inner): - threads = [] - for _ in range(12): - t = threading.Thread(target=proxy_mod.rpc_call, args=(req,)) - threads.append(t) - t.start() - for t in threads: - t.join() + return peak["seen"] - self.assertLessEqual(max_concurrent["seen"], 4) + async def test_concurrency_is_capped_at_max_concurrent_spdk(self): + proxy = make_proxy(max_concurrent_spdk=4, multi_threading_enabled=True) + self.assertEqual(await self._run_concurrently(proxy, 12), 4) - def test_semaphore_released_on_exception(self): + async def test_without_multi_threading_rpcs_are_serialized(self): + # The pre-FastAPI server ran on a non-threading HTTPServer in this mode. + proxy = make_proxy(max_concurrent_spdk=4, multi_threading_enabled=False) + self.assertEqual(await self._run_concurrently(proxy, 12), 1) + + async def test_slot_released_on_exception(self): + proxy = make_proxy(max_concurrent_spdk=1) req = json.dumps({"id": 1, "method": "test"}).encode("ascii") - with patch.object(proxy_mod, "_rpc_call_inner", side_effect=RuntimeError("boom")): + with patch.object(proxy, '_rpc_call_inner', side_effect=RuntimeError("boom")): with self.assertRaises(RuntimeError): - proxy_mod.rpc_call(req) + await proxy.rpc_call(req) + + self.assertFalse(proxy.slots.locked()) + + +class TestEndpoint(unittest.TestCase): + """HTTP contract seen by ``simplyblock_core.rpc_client.RPCClient``.""" + + def setUp(self): + self.app = proxy_mod.create_app(make_settings()) + self.proxy = self.app.state.proxy + self.proxy.spdk_ready = True + # Lifespan (and with it the readiness gate) is deliberately not run: + # TestClient only starts it when used as a context manager. + self.client = TestClient(self.app) + self.body = json.dumps({"id": 1, "method": "spdk_get_version"}) + + def _post(self, auth=("test", "secret"), **kwargs): + return self.client.post("/", content=self.body, auth=auth, **kwargs) + + def test_response_is_passed_through(self): + payload = rpc_response(result={"version": "24.01"}).decode() + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(return_value=payload)): + response = self._post() + + self.assertEqual(response.status_code, 200) + self.assertEqual(response.json()["result"], {"version": "24.01"}) + + def test_notification_gets_204(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(return_value=None)): + response = self._post() + + self.assertEqual(response.status_code, 204) + self.assertEqual(response.content, b'') + + def test_wrong_credentials_get_401(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock()) as rpc_call: + response = self._post(auth=("wrong", "creds")) - acquired = proxy_mod.spdk_semaphore.acquire(timeout=1) - self.assertTrue(acquired) - proxy_mod.spdk_semaphore.release() + self.assertEqual(response.status_code, 401) + rpc_call.assert_not_called() + def test_missing_credentials_get_401(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock()) as rpc_call: + response = self.client.post("/", content=self.body) -class TestDoPostBrokenPipe(unittest.TestCase): + self.assertEqual(response.status_code, 401) + rpc_call.assert_not_called() - def _make_handler(self): - handler = proxy_mod.ServerHandler.__new__(proxy_mod.ServerHandler) - proxy_mod.ServerHandler.server_session = [] - handler.key = "dGVzdDp0ZXN0" + def test_non_ascii_credentials_get_401(self): + # A header hmac.compare_digest would refuse to compare as str. + response = self.client.post( + "/", content=self.body, headers={"Authorization": b"Basic \xe9"}) - body = json.dumps({"id": 1, "method": "test"}).encode() - header_map = { - "Authorization": "Basic dGVzdDp0ZXN0", - "Content-Length": str(len(body)), - } - handler.headers = MagicMock() - handler.headers.__getitem__ = MagicMock(side_effect=lambda k: header_map.get(k, "")) - handler.headers.__contains__ = MagicMock(side_effect=lambda k: k in header_map) - handler.headers.get = MagicMock(side_effect=lambda k, d="": header_map.get(k, d)) + self.assertEqual(response.status_code, 401) - handler.rfile = MagicMock() - handler.rfile.read = MagicMock(return_value=body) + def test_bad_spdk_response_gets_500(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): + response = self._post() - handler.wfile = MagicMock() - handler.send_response = MagicMock() - handler.send_header = MagicMock() - handler.end_headers = MagicMock() + self.assertEqual(response.status_code, 500) - return handler + def test_unreachable_spdk_gets_500(self): + error = ConnectionRefusedError("spdk is gone") + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=error)): + response = self._post() - @patch.object(proxy_mod, "rpc_call") - def test_broken_pipe_is_caught(self, mock_rpc): - mock_rpc.return_value = '{"jsonrpc":"2.0","id":1,"result":true}' - handler = self._make_handler() - handler.wfile.write = MagicMock(side_effect=BrokenPipeError("client gone")) + self.assertEqual(response.status_code, 500) - handler.do_POST() + def test_malformed_request_body_gets_500(self): + response = self.client.post("/", content="not json", auth=("test", "secret")) - self.assertEqual(len(proxy_mod.ServerHandler.server_session), 0) + self.assertEqual(response.status_code, 500) - @patch.object(proxy_mod, "rpc_call") - def test_value_error_returns_500(self, mock_rpc): - mock_rpc.side_effect = ValueError("bad response") - handler = self._make_handler() + def test_caller_timeout_header_is_forwarded(self): + payload = rpc_response(result=True).decode() + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(return_value=payload)) as rpc_call: + self._post(headers={"X-RPC-Timeout": "7"}) - handler.do_POST() + self.assertEqual(rpc_call.call_args.args[1], "7") - handler.send_response.assert_any_call(500) - self.assertEqual(len(proxy_mod.ServerHandler.server_session), 0) + def test_in_flight_count_returns_to_zero(self): + payload = rpc_response(result=True).decode() + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(return_value=payload)): + for _ in range(3): + self._post() - @patch.object(proxy_mod, "rpc_call") - def test_session_always_cleaned_up(self, mock_rpc): - mock_rpc.return_value = '{"jsonrpc":"2.0","id":1,"result":true}' - handler = self._make_handler() + self.assertEqual(self.proxy.active_requests, 0) - handler.do_POST() + def test_in_flight_count_returns_to_zero_after_failure(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): + self._post() - self.assertEqual(len(proxy_mod.ServerHandler.server_session), 0) + self.assertEqual(self.proxy.active_requests, 0) if __name__ == "__main__": From b17efe18a53fbbf97154858db1a10c0c75809f8a Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 02:10:44 +0200 Subject: [PATCH 02/22] Rework authentication as dependency --- .../services/spdk_http_proxy_server.py | 36 ++++++++++++------- tests/unit/test_spdk_proxy_unit.py | 15 ++++++++ 2 files changed, 38 insertions(+), 13 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 3bfef55696..96111a4c87 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -22,7 +22,7 @@ from typing import Annotated, Any, AsyncGenerator, Dict, Optional import uvicorn -from fastapi import FastAPI, Request, Response +from fastapi import Depends, FastAPI, HTTPException, Request, Response from pydantic import BeforeValidator, Field, SecretStr from pydantic_settings import BaseSettings, SettingsConfigDict from starlette.requests import ClientDisconnect @@ -195,14 +195,6 @@ def slots(self) -> asyncio.Semaphore: self._slots = asyncio.Semaphore(self.concurrency_limit) return self._slots - def authenticate(self, authorization: Optional[str]) -> bool: - # Compared as bytes: compare_digest rejects non-ASCII str outright, and - # the header is attacker-controlled. - return authorization is not None and hmac.compare_digest( - authorization.encode('utf-8'), - self.settings.authorization.encode('utf-8'), - ) - async def report_stats(self) -> None: """Log the collected timings every ``STATS_INTERVAL_SEC`` seconds.""" while True: @@ -356,6 +348,27 @@ def _close(writer: asyncio.StreamWriter) -> None: pass +def require_authorization(request: Request) -> None: + """Gate a request on the configured basic-auth credentials. + + Reads the proxy off the request's own application rather than a module + global, so apps built by separate ``create_app`` calls stay independent. + """ + settings: ProxySettings = request.app.state.proxy.settings + authorization = request.headers.get('Authorization') + # Compared as bytes: compare_digest rejects non-ASCII str outright, and + # the header is attacker-controlled. + if authorization is None or not hmac.compare_digest( + authorization.encode('utf-8'), + settings.authorization.encode('utf-8'), + ): + # The only trace a rejected request leaves: it never reaches the route, + # which is what logs every other request. + client = request.client.host if request.client is not None else 'unknown' + logger.warning(f"rejected an unauthorized request from {client}") + raise HTTPException(status_code=401, headers={'WWW-Authenticate': 'Basic'}) + + def create_app(settings: ProxySettings) -> FastAPI: """Build the proxy application. @@ -379,16 +392,13 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: app = FastAPI(lifespan=lifespan, docs_url=None, redoc_url=None, openapi_url=None) app.state.proxy = proxy - @app.post('/{path:path}') + @app.post('/{path:path}', dependencies=[Depends(require_authorization)]) async def rpc(request: Request) -> Response: req_time = time.time_ns() proxy.active_requests += 1 logger.info(f"incoming request at: {req_time}") logger.info(f"active server session: {proxy.active_requests}") try: - if not proxy.authenticate(request.headers.get('Authorization')): - return Response(status_code=401, headers={'WWW-Authenticate': 'Basic'}) - read_start = time.time_ns() try: body = await request.body() diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 6465b24d2e..8757220cbb 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -415,6 +415,21 @@ def test_non_ascii_credentials_get_401(self): self.assertEqual(response.status_code, 401) + def test_credentials_are_scoped_to_the_app_that_serves_the_request(self): + """The dependency resolves settings per request, so two apps built in + one process do not accept each other's credentials.""" + other = proxy_mod.create_app(make_settings(rpc_password="other")) + other.state.proxy.spdk_ready = True + + with patch.object(other.state.proxy, 'rpc_call', new=AsyncMock(return_value=None)): + accepted = TestClient(other).post( + "/", content=self.body, auth=("test", "other")) + rejected = TestClient(other).post( + "/", content=self.body, auth=("test", "secret")) + + self.assertEqual(accepted.status_code, 204) + self.assertEqual(rejected.status_code, 401) + def test_bad_spdk_response_gets_500(self): with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): response = self._post() From bd43c9bf2e3bbb300065f295bb0f8002c126c361 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 02:29:49 +0200 Subject: [PATCH 03/22] Use prometheus instrumentation for SPDK proxy metrics --- .../services/spdk_http_proxy_server.py | 303 +++++++++++++++--- tests/unit/test_spdk_proxy_unit.py | 244 ++++++++++++++ 2 files changed, 502 insertions(+), 45 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 96111a4c87..2c00ea5530 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -15,14 +15,17 @@ import hmac import json import logging +import math import ssl import sys import time from contextlib import asynccontextmanager -from typing import Annotated, Any, AsyncGenerator, Dict, Optional +from typing import Annotated, Any, AsyncGenerator, Dict, Optional, Set, Tuple import uvicorn from fastapi import Depends, FastAPI, HTTPException, Request, Response +from prometheus_client import CollectorRegistry, Counter, Gauge, Histogram +from prometheus_fastapi_instrumentator import Instrumentator from pydantic import BeforeValidator, Field, SecretStr from pydantic_settings import BaseSettings, SettingsConfigDict from starlette.requests import ClientDisconnect @@ -32,11 +35,32 @@ logger = logging.getLogger(__name__) -#: How often the periodic timing report is emitted, and the window the -#: ``last_Ns_avg`` figure covers. +#: How often the periodic timing report is emitted, and hence the interval +#: every figure in it covers. STATS_INTERVAL_SEC = 3 -#: Samples are dropped wholesale once a series grows past this. -STATS_MAX_SAMPLES = 10000 +#: Path the Prometheus exposition is served on, matching ``simplyblock_web``. +METRICS_ENDPOINT = '/_meta/metrics' +#: SPDK round-trips span a warm ``bdev_get_bdevs`` (well under a millisecond) +#: to ``ProxySettings.timeout``, 300s by default. Histogram's default buckets +#: stop at 10s, which would collapse the whole interesting tail into ``+Inf``: +#: RPCs issued under the port fence sit around 8s, and a slot starved by a +#: stuck ``distr_status_events_update`` holds for minutes. Hence the extra +#: resolution between 5s and 10s, and a ladder that reaches the timeout. +SPDK_DURATION_BUCKETS = ( + .001, .005, .01, .05, .1, .5, 1, 2.5, 5, 7.5, 10, 30, 60, 120, 300, math.inf) +#: Reading a request body off a loopback socket; a different order of +#: magnitude from anything SPDK does, so a separate, much finer ladder. +BODY_READ_DURATION_BUCKETS = ( + .0001, .0005, .001, .005, .01, .05, .1, .5, 1, math.inf) +#: Ceiling on distinct ``method`` label values. The method is read out of the +#: caller's JSON-RPC body, so a buggy or hostile client could otherwise mint +#: series without bound. A cap rather than an allowlist: SPDK's RPC surface is +#: hundreds of names and version-dependent, so an allowlist would silently +#: drop methods added by an SPDK upgrade. +MAX_METHOD_LABELS = 128 +MAX_METHOD_LABEL_LEN = 64 +#: Where methods past those limits are folded. +OTHER_METHOD_LABEL = 'other' #: Per-attempt bound on the readiness probe, and the pause between attempts. SPDK_READY_PROBE_TIMEOUT_SEC = 5 SPDK_READY_POLL_INTERVAL_SEC = 1 @@ -131,37 +155,201 @@ def authorization(self) -> str: return 'Basic ' + base64.b64encode(credentials.encode('ascii')).decode('ascii') -class TimingStats: - """Rolling record of operation durations, reported periodically.""" +#: ``(count, sum)`` per ``method`` label, and cumulative bucket counts by +#: upper bound, as read back off a histogram. +HistogramSnapshot = Tuple[Dict[str, Tuple[float, float]], Dict[float, float]] - def __init__(self, name: str) -> None: + +def _histogram_snapshot(histogram: Histogram) -> HistogramSnapshot: + """Read a histogram's own totals back out of its samples.""" + per_method: Dict[str, Tuple[float, float]] = {} + buckets: Dict[float, float] = {} + for metric in histogram.collect(): + for sample in metric.samples: + method = sample.labels.get('method', '') + count, total = per_method.get(method, (0.0, 0.0)) + if sample.name.endswith('_bucket'): + bound = float(sample.labels['le']) + buckets[bound] = buckets.get(bound, 0.0) + sample.value + elif sample.name.endswith('_count'): + per_method[method] = (count + sample.value, total) + elif sample.name.endswith('_sum'): + per_method[method] = (count, total + sample.value) + return per_method, buckets + + +def _bucket_quantile(buckets: Dict[float, float], quantile: float) -> Optional[float]: + """Upper bound of the bucket a quantile falls into. + + Buckets are cumulative, and the difference of two cumulative readings is + itself cumulative, so this works unchanged on an interval delta. + """ + if not buckets: + return None + ordered = sorted(buckets.items()) + total = ordered[-1][1] + if total <= 0: + return None + target = total * quantile + for bound, cumulative in ordered: + if cumulative >= target: + return bound + return ordered[-1][0] + + +def _format_seconds(seconds: float) -> str: + return f"{seconds * 1000:.1f}ms" if seconds < 1 else f"{seconds:.2f}s" + + +def _format_quantile(buckets: Dict[float, float], seconds: Optional[float]) -> str: + """Render a quantile as the comparison it actually is. + + A histogram resolves a quantile only to a bucket bound, so the figure can + exceed the largest duration actually observed. Spelling the bound as + ``<=`` keeps that from reading as ``p99 > max``, which is otherwise the + obvious conclusion when both sit on the same line. + """ + if seconds is None: + return '=-' + if not math.isinf(seconds): + return f"<={_format_seconds(seconds)}" + finite = [bound for bound in buckets if not math.isinf(bound)] + return f">{_format_seconds(max(finite))}" if finite else '=inf' + + +class IntervalReport: + """The periodic log line for one histogram. + + Everything reported comes from the histogram itself, so the log and the + Prometheus exposition can never disagree. Histograms are cumulative, so + interval figures are the difference between successive reads. + + The exception is ``max``: a histogram knows only bucket boundaries, and + the Python client's Summary carries no quantiles, so the peak is kept here + as a plain float and reset every tick. Deliberately not a Gauge -- a gauge + reset every few seconds sawtooths and reads badly in Prometheus. + """ + + def __init__(self, name: str, histogram: Histogram) -> None: self.name = name - self.samples: Dict[int, int] = {} + self.histogram = histogram + self._prev_methods: Dict[str, Tuple[float, float]] = {} + self._prev_buckets: Dict[float, float] = {} + self._peak_seconds = 0.0 + + def observe(self, seconds: float, method: Optional[str] = None) -> None: + target = self.histogram if method is None else self.histogram.labels(method=method) + target.observe(seconds) + self._peak_seconds = max(self._peak_seconds, seconds) + + def _slowest_method(self, methods: Dict[str, Tuple[float, float]]) -> Optional[str]: + """The method with the highest mean duration over the interval.""" + slowest, slowest_mean = None, 0.0 + for method, (count, total) in methods.items(): + prev_count, prev_total = self._prev_methods.get(method, (0.0, 0.0)) + if (advanced := count - prev_count) <= 0: + continue + if (mean := (total - prev_total) / advanced) > slowest_mean: + slowest, slowest_mean = method, mean + return slowest or None + + def report(self) -> Optional[str]: + """Summarize the interval, or ``None`` if nothing was observed in it.""" + methods, buckets = _histogram_snapshot(self.histogram) + advanced = ( + sum(count for count, _ in methods.values()) + - sum(count for count, _ in self._prev_methods.values()) + ) + elapsed = ( + sum(total for _, total in methods.values()) + - sum(total for _, total in self._prev_methods.values()) + ) + interval_buckets = { + bound: value - self._prev_buckets.get(bound, 0.0) + for bound, value in buckets.items() + } + peak, slowest = self._peak_seconds, self._slowest_method(methods) - def record(self, start_ns: int, duration_ns: int) -> None: - self.samples[start_ns] = duration_ns + self._prev_methods, self._prev_buckets = methods, buckets + self._peak_seconds = 0.0 - def report(self, now_ns: int) -> Optional[str]: - """Summarize the collected samples, clearing them once they pile up.""" - if not self.samples: + if advanced <= 0: return None - durations = list(self.samples.values()) - window = [ - duration - for start, duration in self.samples.items() - if start > now_ns - STATS_INTERVAL_SEC * 1000 * 1000 * 1000 - ] summary = ( - f"{self.name}: max={max(durations)} ns," - f" avg={int(sum(durations) / len(durations))} ns," - f" last_{STATS_INTERVAL_SEC}s_avg={int(sum(window) / len(window)) if window else 0} ns" + f"{self.name}:" + f" interval_avg={_format_seconds(elapsed / advanced)}" + f" p99{_format_quantile(interval_buckets, _bucket_quantile(interval_buckets, 0.99))}" + f" max={_format_seconds(peak)}" + f" n={int(advanced)}" ) + return summary if slowest is None else f"{summary} slowest={slowest}" - if len(self.samples) > STATS_MAX_SAMPLES: - self.samples.clear() - return summary +class ProxyMetrics: + """Prometheus metrics for one proxy application. + + Each application owns its registry rather than writing into the global + ``REGISTRY``. A storage node runs exactly one proxy per process so nothing + is lost, and the tests build several applications in one interpreter, + where module-level metrics would collide on the second ``create_app``. + """ + + def __init__(self) -> None: + self.registry = CollectorRegistry() + self._known_methods: Set[str] = set() + + self.spdk_response = IntervalReport('recv_from_spdk', Histogram( + 'spdk_proxy_response_duration_seconds', + 'Time awaiting and reading one JSON-RPC response from SPDK', + ['method'], + buckets=SPDK_DURATION_BUCKETS, + registry=self.registry, + )) + self.body_read = IntervalReport('read_body', Histogram( + 'spdk_proxy_body_read_duration_seconds', + 'Time spent reading one HTTP request body', + buckets=BODY_READ_DURATION_BUCKETS, + registry=self.registry, + )) + self.slots_in_use = Gauge( + 'spdk_proxy_rpc_slots_in_use', + 'SPDK concurrency slots currently held', + registry=self.registry, + ) + self.unix_connections = Gauge( + 'spdk_proxy_unix_connections_open', + 'Unix-socket connections currently open towards SPDK', + registry=self.registry, + ) + self.failures = Counter( + 'spdk_proxy_rpc_failures_total', + 'RPCs that never returned a SPDK response', + ['method', 'reason'], + registry=self.registry, + ) + + def method_label(self, method: str) -> str: + """Fold a caller-supplied method name into the bounded label set.""" + if method in self._known_methods: + return method + if len(method) > MAX_METHOD_LABEL_LEN or len(self._known_methods) >= MAX_METHOD_LABELS: + return OTHER_METHOD_LABEL + self._known_methods.add(method) + return method + + def observe_response(self, method: str, seconds: float) -> None: + self.spdk_response.observe(seconds, method=self.method_label(method)) + + def observe_body_read(self, seconds: float) -> None: + self.body_read.observe(seconds) + + def record_failure(self, method: str, reason: str) -> None: + self.failures.labels(method=self.method_label(method), reason=reason).inc() + + @property + def reports(self) -> Tuple[IntervalReport, ...]: + return (self.body_read, self.spdk_response) class SpdkProxy: @@ -174,8 +362,7 @@ def __init__(self, settings: ProxySettings) -> None: #: towards SPDK. Both are logged per request and asserted on by tests. self.active_requests = 0 self.open_connections = 0 - self.read_body_stats = TimingStats('read_body_time') - self.recv_from_spdk_stats = TimingStats('recv_from_spdk_time') + self.metrics = ProxyMetrics() # Without MULTI_THREADING_ENABLED the proxy used to run on a # non-threading HTTPServer, i.e. one request at a time. self.concurrency_limit = ( @@ -196,16 +383,20 @@ def slots(self) -> asyncio.Semaphore: return self._slots async def report_stats(self) -> None: - """Log the collected timings every ``STATS_INTERVAL_SEC`` seconds.""" + """Log the interval timings every ``STATS_INTERVAL_SEC`` seconds. + + Read off the same metrics the Prometheus endpoint serves, so the two + can never disagree. A series with no observations in the interval + logs nothing rather than repeating a stale summary. + """ while True: await asyncio.sleep(STATS_INTERVAL_SEC) try: - now = time.time_ns() - for stats in (self.read_body_stats, self.recv_from_spdk_stats): - if (summary := stats.report(now)) is not None: - logger.info("Periodic stats: %s: %s", now, summary) - except Exception as e: - logger.error(e) + for report in self.metrics.reports: + if (summary := report.report()) is not None: + logger.info("Periodic stats: %s", summary) + except (ValueError, KeyError, ZeroDivisionError) as e: + logger.error(f"Could not summarize proxy metrics: {e}") async def wait_for_spdk_ready(self) -> None: """Block until SPDK responds to spdk_get_version on the unix socket.""" @@ -283,7 +474,11 @@ async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Op logger.info(f"Request:{req_time} function: {str(req_data['method'])}, params: {params}") sock_timeout = self._resolve_sock_timeout(client_timeout) async with self.slots: - return await self._rpc_call_inner(req, req_data, req_time, sock_timeout) + self.metrics.slots_in_use.inc() + try: + return await self._rpc_call_inner(req, req_data, req_time, sock_timeout) + finally: + self.metrics.slots_in_use.dec() async def _rpc_call_inner( self, @@ -292,16 +487,25 @@ async def _rpc_call_inner( req_time: int, sock_timeout: float, ) -> Optional[str]: + method = str(req_data.get('method', 'unknown')) try: return await asyncio.wait_for(self._exchange(req, req_data, req_time), sock_timeout) except asyncio.TimeoutError as e: logger.error( f"Socket timeout waiting for SPDK response (request {req_time}, " - f"function: {req_data.get('method', 'unknown')})") + f"function: {method})") + self.metrics.record_failure(method, 'timeout') raise ValueError('SPDK response timeout') from e + except OSError: + self.metrics.record_failure(method, 'unreachable') + raise + except ValueError: + self.metrics.record_failure(method, 'invalid_response') + raise async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional[str]: self.open_connections += 1 + self.metrics.unix_connections.inc() try: reader, writer = await asyncio.open_unix_connection(self.settings.rpc_sock) try: @@ -313,7 +517,9 @@ async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional buf = b'' response = None - recv_start = time.time_ns() + # Monotonic: a duration must not be measured against a clock + # that can step backwards under NTP. + recv_start = time.monotonic() while True: newdata = await reader.read(SPDK_RECV_SIZE) closed = newdata == b'' @@ -325,9 +531,8 @@ async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional break continue break - time_diff = time.time_ns() - recv_start - self.recv_from_spdk_stats.record(recv_start, time_diff) - logger.info(f"recv_from_spdk_time_diff: {time_diff}") + self.metrics.observe_response( + str(req_data.get('method', 'unknown')), time.monotonic() - recv_start) if not response and len(buf) > 0: raise ValueError('Invalid response') @@ -339,6 +544,7 @@ async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional _close(writer) finally: self.open_connections -= 1 + self.metrics.unix_connections.dec() def _close(writer: asyncio.StreamWriter) -> None: @@ -392,6 +598,15 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: app = FastAPI(lifespan=lifespan, docs_url=None, redoc_url=None, openapi_url=None) app.state.proxy = proxy + # Served on the RPC port behind the same credentials as the RPCs + # themselves: `expose` forwards kwargs to the route decorator. + Instrumentator(registry=proxy.metrics.registry).instrument(app).expose( + app, + endpoint=METRICS_ENDPOINT, + include_in_schema=False, + dependencies=[Depends(require_authorization)], + ) + @app.post('/{path:path}', dependencies=[Depends(require_authorization)]) async def rpc(request: Request) -> Response: req_time = time.time_ns() @@ -399,16 +614,14 @@ async def rpc(request: Request) -> Response: logger.info(f"incoming request at: {req_time}") logger.info(f"active server session: {proxy.active_requests}") try: - read_start = time.time_ns() + read_start = time.monotonic() try: body = await request.body() except ClientDisconnect: logger.warning( f"client disconnected before the request body arrived (request {req_time})") return Response(status_code=400) - time_diff = time.time_ns() - read_start - proxy.read_body_stats.record(read_start, time_diff) - logger.info(f"read_body_time_diff: {time_diff}") + proxy.metrics.observe_body_read(time.monotonic() - read_start) try: response = await proxy.rpc_call(body, request.headers.get('X-RPC-Timeout')) diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 8757220cbb..9e39c7b79b 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -13,6 +13,7 @@ from unittest.mock import AsyncMock, patch from fastapi.testclient import TestClient +from prometheus_client import CollectorRegistry, Histogram from pydantic import ValidationError from simplyblock_core.services import spdk_http_proxy_server as proxy_mod @@ -470,5 +471,248 @@ def test_in_flight_count_returns_to_zero_after_failure(self): self.assertEqual(self.proxy.active_requests, 0) +class TestIntervalReport(unittest.TestCase): + """The periodic log line, computed from a histogram's own totals.""" + + def setUp(self): + registry = CollectorRegistry() + self.report = proxy_mod.IntervalReport('spdk', Histogram( + 'test_duration_seconds', 'test', ['method'], + buckets=(0.01, 0.1, 1, float("inf")), registry=registry)) + + def test_first_tick_without_observations_reports_nothing(self): + self.assertIsNone(self.report.report()) + + def test_interval_average_covers_only_the_new_observations(self): + self.report.observe(1.0, method="a") + self.report.report() + + # A second interval an order of magnitude faster: a cumulative average + # would still read ~0.5s, an interval average must read 0.1s. + self.report.observe(0.1, method="a") + summary = self.report.report() + + self.assertIn("interval_avg=100.0ms", summary) + self.assertIn("n=1", summary) + + def test_quiet_interval_reports_nothing_rather_than_dividing_by_zero(self): + self.report.observe(1.0, method="a") + self.report.report() + + self.assertIsNone(self.report.report()) + + def test_max_is_the_interval_peak_and_resets(self): + self.report.observe(0.5, method="a") + self.report.observe(0.02, method="a") + + self.assertIn("max=500.0ms", self.report.report()) + + self.report.observe(0.02, method="a") + + self.assertIn("max=20.0ms", self.report.report()) + + def test_totals_are_aggregated_across_methods(self): + self.report.observe(0.1, method="a") + self.report.observe(0.3, method="b") + summary = self.report.report() + + self.assertIn("n=2", summary) + self.assertIn("interval_avg=200.0ms", summary) + + def test_slowest_method_of_the_interval_is_named(self): + for _ in range(10): + self.report.observe(0.001, method="fast") + self.report.observe(0.9, method="slow") + + self.assertIn("slowest=slow", self.report.report()) + + def test_slowest_reflects_the_interval_not_history(self): + self.report.observe(0.9, method="slow") + self.report.report() + + self.report.observe(0.5, method="other") + self.assertIn("slowest=other", self.report.report()) + + def test_p99_lands_in_the_bucket_holding_the_tail(self): + for _ in range(95): + self.report.observe(0.005, method="a") + for _ in range(5): + self.report.observe(0.5, method="a") + + self.assertIn("p99<=1.00s", self.report.report()) + + def test_p99_ignores_a_tail_thinner_than_one_percent(self): + for _ in range(99): + self.report.observe(0.005, method="a") + self.report.observe(0.5, method="a") + + self.assertIn("p99<=10.0ms", self.report.report()) + + def test_p99_beyond_the_last_finite_bucket_is_marked_open_ended(self): + self.report.observe(30.0, method="a") + + self.assertIn("p99>1.00s", self.report.report()) + + def test_unlabelled_histogram_reports_without_a_slowest_field(self): + registry = CollectorRegistry() + report = proxy_mod.IntervalReport('body', Histogram( + 'test_body_seconds', 'test', buckets=(0.01, float("inf")), registry=registry)) + report.observe(0.005) + + summary = report.report() + + self.assertIn("n=1", summary) + self.assertNotIn("slowest=", summary) + + +class TestBucketQuantile(unittest.TestCase): + + def test_empty_buckets_have_no_quantile(self): + self.assertIsNone(proxy_mod._bucket_quantile({}, 0.99)) + + def test_all_zero_buckets_have_no_quantile(self): + self.assertIsNone(proxy_mod._bucket_quantile({0.1: 0.0, float("inf"): 0.0}, 0.99)) + + def test_quantile_is_the_bound_of_the_bucket_it_falls_in(self): + buckets = {0.1: 90.0, 1.0: 99.0, float("inf"): 100.0} + + self.assertEqual(proxy_mod._bucket_quantile(buckets, 0.5), 0.1) + self.assertEqual(proxy_mod._bucket_quantile(buckets, 0.99), 1.0) + self.assertEqual(proxy_mod._bucket_quantile(buckets, 1.0), float("inf")) + + +class TestMethodLabelCardinality(unittest.TestCase): + """The method label is caller-supplied, so its value set must be bounded.""" + + def setUp(self): + self.metrics = proxy_mod.ProxyMetrics() + + def test_known_methods_are_passed_through(self): + self.assertEqual(self.metrics.method_label("bdev_get_bdevs"), "bdev_get_bdevs") + + def test_methods_past_the_cap_collapse(self): + for i in range(proxy_mod.MAX_METHOD_LABELS): + self.metrics.method_label(f"method_{i}") + + self.assertEqual( + self.metrics.method_label("one_too_many"), proxy_mod.OTHER_METHOD_LABEL) + + def test_a_method_already_seen_survives_the_cap(self): + self.metrics.method_label("early") + for i in range(proxy_mod.MAX_METHOD_LABELS): + self.metrics.method_label(f"method_{i}") + + self.assertEqual(self.metrics.method_label("early"), "early") + + def test_absurdly_long_methods_collapse(self): + overlong = "x" * (proxy_mod.MAX_METHOD_LABEL_LEN + 1) + + self.assertEqual(self.metrics.method_label(overlong), proxy_mod.OTHER_METHOD_LABEL) + + +class TestMetricsEndpoint(unittest.TestCase): + + def setUp(self): + self.app = proxy_mod.create_app(make_settings()) + self.proxy = self.app.state.proxy + self.proxy.spdk_ready = True + self.client = TestClient(self.app) + + def test_metrics_require_credentials(self): + response = self.client.get(proxy_mod.METRICS_ENDPOINT) + + self.assertEqual(response.status_code, 401) + + def test_metrics_are_served_to_an_authorized_caller(self): + response = self.client.get(proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")) + + self.assertEqual(response.status_code, 200) + self.assertIn("spdk_proxy_response_duration_seconds", response.text) + self.assertIn("spdk_proxy_body_read_duration_seconds", response.text) + self.assertIn("spdk_proxy_rpc_slots_in_use", response.text) + self.assertIn("spdk_proxy_unix_connections_open", response.text) + + def test_observations_reach_the_exposition(self): + self.proxy.metrics.observe_response("bdev_get_bdevs", 0.25) + + response = self.client.get(proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")) + + self.assertIn('method="bdev_get_bdevs"', response.text) + + def test_credentials_never_appear_in_the_exposition(self): + response = self.client.get(proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")) + + self.assertNotIn("secret", response.text) + + def test_two_apps_keep_separate_metrics(self): + """Each app owns its registry, so building a second one neither raises + nor lets observations bleed between them.""" + other = proxy_mod.create_app(make_settings(rpc_password="other")) + other.state.proxy.spdk_ready = True + self.proxy.metrics.observe_response("only_in_the_first", 0.1) + + mine = self.client.get( + proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")).text + theirs = TestClient(other).get( + proxy_mod.METRICS_ENDPOINT, auth=("test", "other")).text + + self.assertIn('method="only_in_the_first"', mine) + self.assertNotIn('method="only_in_the_first"', theirs) + + +class TestMetricsObservation(unittest.IsolatedAsyncioTestCase): + """The gauges and counters have to settle back after every RPC.""" + + def setUp(self): + self.proxy = make_proxy() + self.req = json.dumps({"id": 1, "method": "bdev_get_bdevs"}).encode("ascii") + + def _value(self, metric, **labels): + return self.proxy.metrics.registry.get_sample_value(metric, labels or None) + + async def test_gauges_return_to_zero_after_a_successful_rpc(self): + fake = FakeSpdkSocket([rpc_response(result=True)]) + + with patch_connect(fake): + await self.proxy.rpc_call(self.req) + + self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) + + async def test_response_duration_is_recorded_against_the_method(self): + fake = FakeSpdkSocket([rpc_response(result=True)]) + + with patch_connect(fake): + await self.proxy.rpc_call(self.req) + + self.assertEqual( + self._value("spdk_proxy_response_duration_seconds_count", method="bdev_get_bdevs"), 1) + + async def test_timeout_is_counted_as_a_failure(self): + async def never_answers(*args, **kwargs): + await asyncio.sleep(3600) + + with patch_connect(FakeSpdkSocket([])), patch.object( + FakeReader, 'read', never_answers): + with self.assertRaises(ValueError): + await self.proxy.rpc_call(self.req, client_timeout="0.01") + + self.assertEqual( + self._value( + "spdk_proxy_rpc_failures_total", method="bdev_get_bdevs", reason="timeout"), 1) + self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + + async def test_unreachable_spdk_is_counted_as_a_failure(self): + with patch_connect(FakeSpdkSocket(ConnectionRefusedError("refused"))): + with self.assertRaises(ConnectionRefusedError): + await self.proxy.rpc_call(self.req) + + self.assertEqual( + self._value( + "spdk_proxy_rpc_failures_total", + method="bdev_get_bdevs", reason="unreachable"), 1) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) + + if __name__ == "__main__": unittest.main() From 32cd4a158f887a6fc6b3d9948de2c09cdd991e62 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 02:32:20 +0200 Subject: [PATCH 04/22] Fix handling of invalid requests --- .../services/spdk_http_proxy_server.py | 20 ++++++++++++------- tests/unit/test_spdk_proxy_unit.py | 15 ++++++++++++++ 2 files changed, 28 insertions(+), 7 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 2c00ea5530..45be56f679 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -469,14 +469,19 @@ async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Op logger.info(f"active requests: {self.active_requests}") logger.info(f"active unix sockets: {self.open_connections}") req_data = json.loads(req.decode('ascii')) + # Raised before the slot is taken, so a malformed request cannot be + # counted as an SPDK-side failure by _rpc_call_inner. + if not isinstance(req_data, dict) or 'method' not in req_data: + raise ValueError('Not a JSON-RPC request object') + method = str(req_data['method']) req_time = time.time_ns() params = str(req_data['params']) if 'params' in req_data else "" - logger.info(f"Request:{req_time} function: {str(req_data['method'])}, params: {params}") + logger.info(f"Request:{req_time} function: {method}, params: {params}") sock_timeout = self._resolve_sock_timeout(client_timeout) async with self.slots: self.metrics.slots_in_use.inc() try: - return await self._rpc_call_inner(req, req_data, req_time, sock_timeout) + return await self._rpc_call_inner(req, req_data, method, req_time, sock_timeout) finally: self.metrics.slots_in_use.dec() @@ -484,12 +489,13 @@ async def _rpc_call_inner( self, req: bytes, req_data: dict, + method: str, req_time: int, sock_timeout: float, ) -> Optional[str]: - method = str(req_data.get('method', 'unknown')) try: - return await asyncio.wait_for(self._exchange(req, req_data, req_time), sock_timeout) + return await asyncio.wait_for( + self._exchange(req, req_data, method, req_time), sock_timeout) except asyncio.TimeoutError as e: logger.error( f"Socket timeout waiting for SPDK response (request {req_time}, " @@ -503,7 +509,8 @@ async def _rpc_call_inner( self.metrics.record_failure(method, 'invalid_response') raise - async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional[str]: + async def _exchange( + self, req: bytes, req_data: dict, method: str, req_time: int) -> Optional[str]: self.open_connections += 1 self.metrics.unix_connections.inc() try: @@ -531,8 +538,7 @@ async def _exchange(self, req: bytes, req_data: dict, req_time: int) -> Optional break continue break - self.metrics.observe_response( - str(req_data.get('method', 'unknown')), time.monotonic() - recv_start) + self.metrics.observe_response(method, time.monotonic() - recv_start) if not response and len(buf) > 0: raise ValueError('Invalid response') diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 9e39c7b79b..c94c2224cd 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -449,6 +449,21 @@ def test_malformed_request_body_gets_500(self): self.assertEqual(response.status_code, 500) + def test_json_body_without_a_method_gets_500(self): + """Valid JSON that is not a JSON-RPC request used to raise KeyError out + of the handler, bypassing the 500 path and the failure counter.""" + response = self.client.post( + "/", content=json.dumps({"id": 1}), auth=("test", "secret")) + + self.assertEqual(response.status_code, 500) + + def test_json_body_that_is_not_an_object_gets_500(self): + for body in ("5", "[]", '"a string"', "null"): + with self.subTest(body=body): + response = self.client.post("/", content=body, auth=("test", "secret")) + + self.assertEqual(response.status_code, 500) + def test_caller_timeout_header_is_forwarded(self): payload = rpc_response(result=True).decode() with patch.object(self.proxy, 'rpc_call', new=AsyncMock(return_value=payload)) as rpc_call: From 17f078be5595ac8866f5daf1453f7332b23d8dfe Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 03:00:38 +0200 Subject: [PATCH 05/22] Reintroduce connection limit --- simplyblock_core/services/spdk_http_proxy_server.py | 13 +++++++++++++ tests/unit/test_spdk_proxy_unit.py | 7 +++++++ 2 files changed, 20 insertions(+) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 45be56f679..52e10b92f5 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -113,6 +113,18 @@ class ProxySettings(BaseSettings): int, Field(gt=0, description="Number of RPCs allowed to be in flight against SPDK at once"), ] = 16 + max_concurrent_connections: Annotated[ + int, + Field( + gt=0, + description=( + "Cap on concurrent HTTP connections. Above max_concurrent_spdk since a " + "kept-alive connection can sit idle, not doing SPDK work, most of the time. " + "Enforced by uvicorn, which answers 503 past the cap rather than waiting for " + "a slot the way the ThreadingHTTPServer this replaced blocked in accept()." + ), + ), + ] = 64 spdk_timeout_margin: Annotated[ float, Field( @@ -669,6 +681,7 @@ def main() -> None: host=settings.server_ip, port=settings.rpc_port, log_level='info', + limit_concurrency=settings.max_concurrent_connections, timeout_keep_alive=KEEP_ALIVE_TIMEOUT_SEC, ssl_certfile=tls.tls_certificate if tls.tls_serve else None, ssl_keyfile=tls.tls_key if tls.tls_serve else None, diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index c94c2224cd..7f6d70b763 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -30,6 +30,7 @@ OPTIONAL_ENV = { "TIMEOUT": "5", "MAX_CONCURRENT_SPDK": "4", + "MAX_CONCURRENT_CONNECTIONS": "8", "SPDK_TIMEOUT_MARGIN": "2", "MULTI_THREADING_ENABLED": "True", } @@ -126,6 +127,7 @@ def test_defaults_match_the_documented_environment(self): self.assertEqual(settings.rpc_password.get_secret_value(), "secret") self.assertEqual(settings.timeout, 5 * 60) self.assertEqual(settings.max_concurrent_spdk, 16) + self.assertEqual(settings.max_concurrent_connections, 64) self.assertEqual(settings.spdk_timeout_margin, 2.0) self.assertFalse(settings.multi_threading_enabled) @@ -135,6 +137,7 @@ def test_optional_environment_is_read(self): self.assertEqual(settings.timeout, 5) self.assertEqual(settings.max_concurrent_spdk, 4) + self.assertEqual(settings.max_concurrent_connections, 8) self.assertEqual(settings.spdk_timeout_margin, 2.0) self.assertTrue(settings.multi_threading_enabled) @@ -149,6 +152,10 @@ def test_missing_required_variable_is_rejected(self): with self.assertRaises(ValidationError): proxy_mod.ProxySettings() + def test_a_connection_cap_below_one_is_rejected(self): + with self.assertRaises(ValidationError): + make_settings(max_concurrent_connections=0) + def test_unparsable_rpc_port_falls_back_to_8080(self): with patch.dict(os.environ, {**REQUIRED_ENV, "RPC_PORT": "not-a-port"}, clear=True): settings = proxy_mod.ProxySettings() From d18cb0ea719edd5bb76ba0c159683fa77929a92f Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 13:16:27 +0200 Subject: [PATCH 06/22] Redact secrets on the SPDK proxy log --- AGENTS.md | 1 + .../services/spdk_http_proxy_server.py | 3 +- simplyblock_core/utils/secrets.py | 44 ++++++++++ tests/unit/test_spdk_proxy_unit.py | 88 +++++++++++++++++++ 4 files changed, 135 insertions(+), 1 deletion(-) diff --git a/AGENTS.md b/AGENTS.md index 49a49ce175..e8f46d7665 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -107,6 +107,7 @@ Key rules: - **v2 DTOs**: Use `@field_serializer('field', when_used='json')` to unwrap for JSON wire responses while keeping wrappers in Python-mode `model_dump()`. - **CLI arguments**: Declare the argument type as `secret` in `cli-reference.yaml`. The generator produces `SecretStr` as the argparse type converter, so the value is wrapped at parse time. - **Logging**: Never log unwrapped secret values. Response-body logging is gated by `Settings().log_response_bodies` (env `SB_LOG_RESPONSE_BODIES`, default `False`). External libraries that log HTTP bodies (`urllib3`, `kubernetes.client.rest`) are silenced to WARNING. The web access log records only `request.url.path`, never the query string. +- **Downstream of the unwrap**: `services/spdk_http_proxy_server.py` receives JSON-RPC bodies that have already been through `unwrap_secrets_for_send`, so no `SecretStr` survives to mask by. Log those through `redact_rpc_params` from `simplyblock_core/utils/secrets.py`, which masks by parameter name (`SENSITIVE_RPC_PARAMS`). An RPC that carries new key material or a new credential adds its parameter name to that set — masking by type in `rpc_client` alone does not reach the proxy. - **Comparison**: Use `hmac.compare_digest(secret.get_secret_value(), other)` for timing-safe comparison. - **Testing**: New secret-bearing code needs masking, wire-delivery, and FDB round-trip tests. See `tests/AGENTS.md` § Secret-handling tests for the required assertions and canonical examples. diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 52e10b92f5..7c6cb3a110 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -31,6 +31,7 @@ from starlette.requests import ClientDisconnect from simplyblock_core.settings import Settings +from simplyblock_core.utils.secrets import redact_rpc_params logger = logging.getLogger(__name__) @@ -487,7 +488,7 @@ async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Op raise ValueError('Not a JSON-RPC request object') method = str(req_data['method']) req_time = time.time_ns() - params = str(req_data['params']) if 'params' in req_data else "" + params = str(redact_rpc_params(req_data['params'])) if 'params' in req_data else "" logger.info(f"Request:{req_time} function: {method}, params: {params}") sock_timeout = self._resolve_sock_timeout(client_timeout) async with self.slots: diff --git a/simplyblock_core/utils/secrets.py b/simplyblock_core/utils/secrets.py index 9c47331b32..6614b69293 100644 --- a/simplyblock_core/utils/secrets.py +++ b/simplyblock_core/utils/secrets.py @@ -33,3 +33,47 @@ def unwrap_secret(value: Union[SecretStr, str, None]) -> Optional[str]: if isinstance(value, SecretStr): return value.get_secret_value() return value + + +#: JSON-RPC parameter names whose values are key material or credentials. +#: +#: Needed because a JSON-RPC body loses its type information at +#: ``unwrap_secrets_for_send``: by the time it reaches the SPDK proxy — a +#: separate process — there is no ``SecretStr`` left to mask by, so the only +#: representation that survives the boundary is the parameter's name. +#: +#: ``psk``/``dhchap_*`` currently carry SPDK keyring *names* rather than key +#: material (see ``controllers/host_auth.py``); they are listed anyway so that +#: passing a raw value stays safe. +SENSITIVE_RPC_PARAMS = frozenset({ + 'key', + 'key2', + 'secret_access_key', + 'psk', + 'dhchap_key', + 'dhchap_ctrlr_key', +}) + +#: Identical to ``SecretStr``'s own masked repr (and hence to what +#: ``utils.dump_json`` emits), so a name-redacted value and a type-masked one +#: are indistinguishable in a log line. +MASK = str(SecretStr('masked')) + + +def redact_rpc_params(params: Any) -> Any: + """Return a copy of a JSON-RPC ``params`` value with every + ``SENSITIVE_RPC_PARAMS`` entry replaced by ``MASK``. + + Total by construction: this runs on the unconditional request-log path of + ``spdk_http_proxy_server``, for a body an unauthenticated-until-one-hop-ago + caller controls, so it must accept positional (list) params, a scalar, or + anything else JSON can express without raising. + """ + if isinstance(params, dict): + return { + k: MASK if k in SENSITIVE_RPC_PARAMS else redact_rpc_params(v) + for k, v in params.items() + } + if isinstance(params, (list, tuple)): + return [redact_rpc_params(v) for v in params] + return params diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 7f6d70b763..9fe173a78c 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -17,6 +17,7 @@ from pydantic import ValidationError from simplyblock_core.services import spdk_http_proxy_server as proxy_mod +from simplyblock_core.utils.secrets import MASK REQUIRED_ENV = { @@ -334,6 +335,93 @@ async def test_caller_timeout_bounds_the_socket_wait(self): self.assertEqual(wait_for.call_args.args[1], 6) +class TestRequestLog(unittest.IsolatedAsyncioTestCase): + """The per-request log line is relied on for debugging across the org, so + it keeps logging params — but the proxy sees bodies that have already been + through ``unwrap_secrets_for_send``, with no ``SecretStr`` left to mask by. + Redaction is therefore by parameter name, and unconditional. + """ + + def setUp(self): + self.proxy = make_proxy() + + async def _log_for(self, **body): + req = json.dumps({"id": 1, **body}).encode("ascii") + fake = FakeSpdkSocket([rpc_response(result=True)]) + with patch_connect(fake): + with self.assertLogs(proxy_mod.logger, "INFO") as captured: + await self.proxy.rpc_call(req) + return "\n".join(captured.output) + + async def test_crypto_keys_are_masked(self): + log = await self._log_for( + method="accel_crypto_key_create", + params={ + "cipher": "AES_XTS", + "name": "key_lvol_1", + "key": "DEKSENTINELONE", + "key2": "DEKSENTINELTWO", + }, + ) + + self.assertNotIn("DEKSENTINELONE", log) + self.assertNotIn("DEKSENTINELTWO", log) + self.assertIn(MASK, log) + + async def test_the_line_still_names_the_method_and_its_safe_params(self): + """The point of the line. A future change must not "fix" a leak by + dropping the field.""" + log = await self._log_for( + method="accel_crypto_key_create", + params={ + "cipher": "AES_XTS", + "name": "key_lvol_1", + "key": "DEKSENTINELONE", + "key2": "DEKSENTINELTWO", + }, + ) + + self.assertIn("accel_crypto_key_create", log) + self.assertIn("AES_XTS", log) + self.assertIn("key_lvol_1", log) + + async def test_s3_secret_is_masked_but_its_access_key_id_is_not(self): + log = await self._log_for( + method="bdev_s3_create", + params={ + "name": "s3bdev", + "local_endpoint": "http://minio:9000", + "access_key_id": "AKIAIDENTIFIER", + "secret_access_key": "S3SENTINEL", + }, + ) + + self.assertNotIn("S3SENTINEL", log) + self.assertIn("AKIAIDENTIFIER", log) + self.assertIn("http://minio:9000", log) + + async def test_a_nested_secret_is_masked(self): + log = await self._log_for( + method="some_future_rpc", + params={"outer": [{"secret_access_key": "NESTEDSENTINEL"}]}, + ) + + self.assertNotIn("NESTEDSENTINEL", log) + + async def test_positional_params_do_not_break_the_line(self): + """Redaction runs on the unconditional path for a caller-controlled + body, so a shape SPDK never sends must not turn every RPC into a 500.""" + log = await self._log_for(method="some_future_rpc", params=[1, "two", None]) + + self.assertIn("some_future_rpc", log) + self.assertIn("two", log) + + async def test_scalar_params_do_not_break_the_line(self): + log = await self._log_for(method="some_future_rpc", params="bare") + + self.assertIn("some_future_rpc", log) + + class TestConcurrencyLimit(unittest.IsolatedAsyncioTestCase): async def _run_concurrently(self, proxy, count): From 47bc1e7ea3783d013b4d556c57a6d5e871c7a6dc Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 13:16:55 +0200 Subject: [PATCH 07/22] fix(rpc): add missing secret types to avoid leakage --- simplyblock_core/AGENTS.md | 2 + simplyblock_core/kms/_base.py | 8 +++- simplyblock_core/kms/_fdb.py | 20 +++++++--- simplyblock_core/kms/_hcp.py | 16 +++++--- simplyblock_core/rpc_client.py | 12 +++--- tests/integration/test_local_kms_fdb.py | 39 ++++++++++++++++-- tests/unit/test_client_secret_logging.py | 51 ++++++++++++++++++++++++ 7 files changed, 125 insertions(+), 23 deletions(-) diff --git a/simplyblock_core/AGENTS.md b/simplyblock_core/AGENTS.md index ddbad60698..6361aa7e50 100644 --- a/simplyblock_core/AGENTS.md +++ b/simplyblock_core/AGENTS.md @@ -50,6 +50,8 @@ Clients in `rpc_client.py`, `snode_client.py`, and `fw_api_client.py` accept `Se Response-body logging is gated by `Settings().log_response_bodies` (default `False`). When off, only status code and content-length are logged. +The request-side `logger.debug` in `_request2` / `_request3` masks by type for the params that are `SecretStr`, and passes every params dict through `redact_rpc_params` (`utils/secrets.py`) to cover the ones that arrive as plain `str` — the v1 API hands controllers raw JSON. The SPDK proxy applies the same redactor, since by the time a body reaches it the wrappers are gone. + ## Tests ```bash diff --git a/simplyblock_core/kms/_base.py b/simplyblock_core/kms/_base.py index 7381d4a07b..a43cfcbaab 100644 --- a/simplyblock_core/kms/_base.py +++ b/simplyblock_core/kms/_base.py @@ -4,6 +4,8 @@ from contextlib import AbstractContextManager from types import TracebackType +from pydantic import SecretStr + class KMS(AbstractContextManager): def __exit__( # Has to be defined to make the type-checker happy @@ -19,11 +21,13 @@ def create_data_encryption_keys(self, path: str, kek_name: str) -> None: raise NotImplementedError @abstractmethod - def import_data_encryption_keys(self, path: str, kek_name: str, keys: tuple[str, str]) -> None: + def import_data_encryption_keys( + self, path: str, kek_name: str, keys: tuple[SecretStr, SecretStr], + ) -> None: pass @abstractmethod - def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[str, str]: + def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[SecretStr, SecretStr]: pass @abstractmethod diff --git a/simplyblock_core/kms/_fdb.py b/simplyblock_core/kms/_fdb.py index 81e513e591..d86b5a7d17 100644 --- a/simplyblock_core/kms/_fdb.py +++ b/simplyblock_core/kms/_fdb.py @@ -1,5 +1,7 @@ import json +from pydantic import SecretStr + from simplyblock_core.db_controller import DBController from simplyblock_core.models.cluster import Cluster from simplyblock_core.utils import generate_hex_string @@ -21,18 +23,26 @@ def _key(path: str) -> bytes: def create_data_encryption_keys(self, path: str, kek_name: str) -> None: self.import_data_encryption_keys( - path, kek_name, (generate_hex_string(32), generate_hex_string(32)), + path, kek_name, + (SecretStr(generate_hex_string(32)), SecretStr(generate_hex_string(32))), ) - def import_data_encryption_keys(self, path: str, kek_name: str, keys: tuple[str, str]) -> None: - self._kv_store.set(self._key(path), json.dumps(list(keys)).encode()) + def import_data_encryption_keys( + self, path: str, kek_name: str, keys: tuple[SecretStr, SecretStr], + ) -> None: + # The persistence boundary, where plaintext is the stored form — + # the same exception ``BaseModel.write_to_db`` makes. + self._kv_store.set( + self._key(path), + json.dumps([key.get_secret_value() for key in keys]).encode(), + ) - def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[str, str]: + def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[SecretStr, SecretStr]: raw = self._kv_store.get(self._key(path)) if not raw: raise KMSException(f"No keys found at {path}") key1, key2 = json.loads(raw) - return key1, key2 + return SecretStr(key1), SecretStr(key2) def delete_data_encryption_keys(self, path: str) -> None: self._kv_store.clear(self._key(path)) diff --git a/simplyblock_core/kms/_hcp.py b/simplyblock_core/kms/_hcp.py index 5b3bbaccaa..a68d56b241 100644 --- a/simplyblock_core/kms/_hcp.py +++ b/simplyblock_core/kms/_hcp.py @@ -4,6 +4,7 @@ import hvac import hvac.exceptions +from pydantic import SecretStr from ._base import KMS from ._exceptions import KMSException @@ -50,8 +51,9 @@ def _create_data_encryption_key(self, kek_name: str) -> str: except hvac.exceptions.VaultError as e: raise KMSException("Request failed") from e - def _encrypt(self, kek_name: str, plaintext_hex: str) -> str: - plaintext_b64 = base64.b64encode(bytes.fromhex(plaintext_hex)).decode() + def _encrypt(self, kek_name: str, plaintext_hex: SecretStr) -> str: + plaintext_b64 = base64.b64encode( + bytes.fromhex(plaintext_hex.get_secret_value())).decode() try: return self.client.secrets.transit.encrypt_data( name=kek_name, plaintext=plaintext_b64, mount_point=self.transit_mount, @@ -59,14 +61,14 @@ def _encrypt(self, kek_name: str, plaintext_hex: str) -> str: except hvac.exceptions.VaultError as e: raise KMSException("Request failed") from e - def _decrypt(self, kek_name: str, ciphertext: str) -> str: + def _decrypt(self, kek_name: str, ciphertext: str) -> SecretStr: try: plaintext_b64 = self.client.secrets.transit.decrypt_data( name=kek_name, ciphertext=ciphertext, mount_point=self.transit_mount, )['data']['plaintext'] except hvac.exceptions.VaultError as e: raise KMSException("Request failed") from e - return base64.b64decode(plaintext_b64).hex() + return SecretStr(base64.b64decode(plaintext_b64).hex()) def create_data_encryption_keys(self, path: str, kek_name: str) -> None: try: @@ -81,7 +83,9 @@ def create_data_encryption_keys(self, path: str, kek_name: str) -> None: except hvac.exceptions.VaultError as e: raise KMSException("Request failed") from e - def import_data_encryption_keys(self, path: str, kek_name: str, keys: tuple[str, str]) -> None: + def import_data_encryption_keys( + self, path: str, kek_name: str, keys: tuple[SecretStr, SecretStr], + ) -> None: try: self.client.secrets.kv.v2.create_or_update_secret( path=path, @@ -94,7 +98,7 @@ def import_data_encryption_keys(self, path: str, kek_name: str, keys: tuple[str, except hvac.exceptions.VaultError as e: raise KMSException("Request failed") from e - def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[str, str]: + def get_data_encryption_keys(self, path: str, kek_name: str) -> tuple[SecretStr, SecretStr]: try: encrypted_key1, encrypted_key2 = self.client.secrets.kv.v2.read_secret_version( path=path, diff --git a/simplyblock_core/rpc_client.py b/simplyblock_core/rpc_client.py index 667cf238c0..28c6eb3218 100644 --- a/simplyblock_core/rpc_client.py +++ b/simplyblock_core/rpc_client.py @@ -18,7 +18,7 @@ from simplyblock_core import utils, constants from simplyblock_core.settings import Settings from simplyblock_core.utils.helpers import single_or_none -from simplyblock_core.utils.secrets import unwrap_secrets_for_send +from simplyblock_core.utils.secrets import redact_rpc_params, unwrap_secrets_for_send logger = utils.get_logger() @@ -293,7 +293,8 @@ def _request2(self, method, params=None, request_timeout=None): # window, where a single attach has to land within hundreds of ms). effective_timeout = request_timeout if request_timeout is not None else self.timeout try: - logger.debug("From: %s, Requesting method: %s, params: %s", self.host, method, params) + logger.debug("From: %s, Requesting method: %s, params: %s", + self.host, method, redact_rpc_params(params)) # Tell the SPDK proxy how long we are willing to wait, so it bounds # its own SPDK round-trip (and the semaphore slot it holds) to this # instead of the proxy-global timeout. Prevents an abandoned/stuck @@ -336,7 +337,7 @@ def _request2(self, method, params=None, request_timeout=None): return None, None def _request3(self, method: str, **kwargs): - logger.debug("Requesting method: %s, params: %s", method, kwargs) + logger.debug("Requesting method: %s, params: %s", method, redact_rpc_params(kwargs)) wire_payload = unwrap_secrets_for_send({ 'id': 1, 'method': method, @@ -826,8 +827,7 @@ def lvol_crypto_create(self, name, base_name, key_name): } return self._request("bdev_crypto_create", params) - def lvol_crypto_key_create(self, name, key, key2): - # todo: mask the keys so that they don't show up in logs + def lvol_crypto_key_create(self, name, key: SecretStr, key2: SecretStr): params = { "cipher": "AES_XTS", "key": key, @@ -2143,7 +2143,7 @@ def bdev_lvol_batch_transfer_final_step(self, lvol_names, lvol_ids, snapshot_nam def bdev_s3_create(self, name, secondary_target=0, with_compression=False, snapshot_backups=True, local_testing=False, local_endpoint="", - access_key_id="", secret_access_key="", + access_key_id="", secret_access_key: Optional[SecretStr] = None, bdb_lcpu_mask=0, s3_lcpu_mask=0, s3_thread_pool_size=0): """Create the S3 bdev device. Must be called before bdev_lvol_s3_bdev to attach it to an lvstore. diff --git a/tests/integration/test_local_kms_fdb.py b/tests/integration/test_local_kms_fdb.py index 8524609be2..8e9ffb2350 100644 --- a/tests/integration/test_local_kms_fdb.py +++ b/tests/integration/test_local_kms_fdb.py @@ -10,6 +10,7 @@ import uuid import pytest +from pydantic import SecretStr from simplyblock_core.db_controller import DBController from simplyblock_core.kms import KMSException @@ -30,7 +31,7 @@ def _unique_path() -> str: def test_round_trip_returns_stored_keys(local_kms): path = _unique_path() - key1, key2 = "deadbeef" * 8, "feedface" * 8 + key1, key2 = SecretStr("deadbeef" * 8), SecretStr("feedface" * 8) local_kms.import_data_encryption_keys(path, "kek", (key1, key2)) try: @@ -39,6 +40,35 @@ def test_round_trip_returns_stored_keys(local_kms): local_kms.delete_data_encryption_keys(path) +def test_stored_form_is_plaintext(local_kms): + """FDB holds plaintext hex, not a ``SecretStr`` repr. + + ``import_data_encryption_keys`` is the persistence boundary, so a record + written by this version must stay readable by one that predates the + wrapper — and a masked ``**********`` would be silently unrecoverable. + """ + path = _unique_path() + local_kms.import_data_encryption_keys( + path, "kek", (SecretStr("ab" * 32), SecretStr("cd" * 32))) + try: + assert b"ab" * 32 in local_kms._kv_store.get(local_kms._key(path)) + assert b"*" not in local_kms._kv_store.get(local_kms._key(path)) + finally: + local_kms.delete_data_encryption_keys(path) + + +def test_keys_are_masked_in_representations(local_kms): + path = _unique_path() + local_kms.create_data_encryption_keys(path, "kek") + try: + keys = local_kms.get_data_encryption_keys(path, "kek") + for key in keys: + assert key.get_secret_value() not in repr(keys) + assert key.get_secret_value() not in str(key) + finally: + local_kms.delete_data_encryption_keys(path) + + def test_create_then_get_works(local_kms): """``create_data_encryption_keys`` must persist keys readable by ``get``. @@ -52,8 +82,8 @@ def test_create_then_get_works(local_kms): local_kms.create_data_encryption_keys(path, "kek") try: key1, key2 = local_kms.get_data_encryption_keys(path, "kek") - assert isinstance(key1, str) and len(key1) == 64 - assert isinstance(key2, str) and len(key2) == 64 + assert isinstance(key1, SecretStr) and len(key1.get_secret_value()) == 64 + assert isinstance(key2, SecretStr) and len(key2.get_secret_value()) == 64 finally: local_kms.delete_data_encryption_keys(path) @@ -65,7 +95,8 @@ def test_get_missing_raises_kms_exception(local_kms): def test_delete_removes_keys(local_kms): path = _unique_path() - local_kms.import_data_encryption_keys(path, "kek", ("aa" * 32, "bb" * 32)) + local_kms.import_data_encryption_keys( + path, "kek", (SecretStr("aa" * 32), SecretStr("bb" * 32))) local_kms.delete_data_encryption_keys(path) with pytest.raises(KMSException): diff --git a/tests/unit/test_client_secret_logging.py b/tests/unit/test_client_secret_logging.py index 77c5f727f5..9b59c071de 100644 --- a/tests/unit/test_client_secret_logging.py +++ b/tests/unit/test_client_secret_logging.py @@ -7,6 +7,7 @@ from pydantic import SecretStr from simplyblock_core.rpc_client import RPCClient +from simplyblock_core.utils.secrets import MASK from simplyblock_core.snode_client import SNodeClient @@ -80,6 +81,56 @@ def test_rpc_client_response_body_logged_when_flag_on(rpc_client, caplog, monkey assert "RESPVALUE" in _captured_logs_text(caplog) +def test_rpc_client_masks_plaintext_crypto_keys_by_param_name(rpc_client, caplog): + """``lvol_crypto_key_create`` is now typed on ``SecretStr``, but the v1 API + hands controllers plain ``str`` from raw JSON. The name-based redactor is + what covers the values the type system cannot see.""" + rpc_client._fake_session.post.return_value = _make_json_response({ + "jsonrpc": "2.0", "id": 1, "result": True, + }) + + with caplog.at_level(logging.DEBUG): + rpc_client._request2("accel_crypto_key_create", { + "cipher": "AES_XTS", + "name": "key_lvol_1", + "key": "DEKPLAINONE", + "key2": "DEKPLAINTWO", + }) + + posted_body = rpc_client._fake_session.post.call_args.kwargs["data"] + parsed = json.loads(posted_body) + assert parsed["params"]["key"] == "DEKPLAINONE" + assert parsed["params"]["key2"] == "DEKPLAINTWO" + + logs = _captured_logs_text(caplog) + assert "DEKPLAINONE" not in logs + assert "DEKPLAINTWO" not in logs + assert MASK in logs + assert "accel_crypto_key_create" in logs + assert "AES_XTS" in logs + + +def test_rpc_client_request3_masks_secrets_by_param_name(rpc_client, caplog): + rpc_client._fake_session.post.return_value = _make_json_response({ + "jsonrpc": "2.0", "id": 1, "result": True, + }) + + with caplog.at_level(logging.DEBUG): + rpc_client.bdev_s3_create( + name="s3bdev", + local_endpoint="http://minio:9000", + access_key_id="AKIAIDENTIFIER", + secret_access_key=SecretStr("S3PLAIN"), + ) + + posted_body = rpc_client._fake_session.post.call_args.kwargs["data"] + assert json.loads(posted_body)["params"]["secret_access_key"] == "S3PLAIN" + + logs = _captured_logs_text(caplog) + assert "S3PLAIN" not in logs + assert "AKIAIDENTIFIER" in logs + + @pytest.fixture def snode_client(): with patch("simplyblock_core.snode_client.requests.session") as session_factory: From 5da302cdf286808d2cf04dda964fe0e8e428198a Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 13:28:46 +0200 Subject: [PATCH 08/22] Correctly indicate JSON RPC client errors --- .../services/spdk_http_proxy_server.py | 47 ++++++++++++--- tests/integration/test_spdk_proxy_e2e.py | 4 +- tests/unit/test_spdk_proxy_unit.py | 57 ++++++++++++++++--- 3 files changed, 92 insertions(+), 16 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 7c6cb3a110..3ad31cce8f 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -337,7 +337,7 @@ def __init__(self) -> None: ) self.failures = Counter( 'spdk_proxy_rpc_failures_total', - 'RPCs that never returned a SPDK response', + 'RPCs that reached SPDK and did not come back', ['method', 'reason'], registry=self.registry, ) @@ -365,6 +365,29 @@ def reports(self) -> Tuple[IntervalReport, ...]: return (self.body_read, self.spdk_response) +class InvalidRequest(Exception): + """The request body is not a JSON-RPC request object. + + A caller-side fault, kept distinct from the ``ValueError`` a failed SPDK + round-trip raises: nothing was sent to SPDK, so it earns a 400 and a + ``bad_request`` failure rather than a 500 that would read as "SPDK is + broken" on a status-code or failure-rate dashboard. + """ + + +def _parse_request(req: bytes) -> Dict[str, Any]: + """Decode a request body, or reject it as the caller's fault.""" + try: + req_data = json.loads(req.decode('ascii')) + except ValueError as e: + raise InvalidRequest(f"body is not ASCII JSON: {e}") from e + + if not isinstance(req_data, dict) or 'method' not in req_data: + raise InvalidRequest('body is not a JSON-RPC request object') + + return req_data + + class SpdkProxy: """Forwards JSON-RPC requests to SPDK's unix socket.""" @@ -481,11 +504,9 @@ async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Op """ logger.info(f"active requests: {self.active_requests}") logger.info(f"active unix sockets: {self.open_connections}") - req_data = json.loads(req.decode('ascii')) - # Raised before the slot is taken, so a malformed request cannot be - # counted as an SPDK-side failure by _rpc_call_inner. - if not isinstance(req_data, dict) or 'method' not in req_data: - raise ValueError('Not a JSON-RPC request object') + # Parsed before the slot is taken, so a malformed request neither + # occupies one nor gets counted as an SPDK-side failure. + req_data = _parse_request(req) method = str(req_data['method']) req_time = time.time_ns() params = str(redact_rpc_params(req_data['params'])) if 'params' in req_data else "" @@ -619,7 +640,16 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: # Served on the RPC port behind the same credentials as the RPCs # themselves: `expose` forwards kwargs to the route decorator. - Instrumentator(registry=proxy.metrics.registry).instrument(app).expose( + # Ungrouped status codes: the default folds every client-side rejection + # into one `4xx` series, which cannot tell a malformed body (400) from bad + # credentials (401). Only a handful of codes are reachable here, so the + # cardinality is negligible. `spdk_proxy_rpc_failures_total` deliberately + # does not duplicate any of this -- it exists for what a status code cannot + # say, namely which SPDK method failed and why a 500 was a 500. + Instrumentator( + registry=proxy.metrics.registry, + should_group_status_codes=False, + ).instrument(app).expose( app, endpoint=METRICS_ENDPOINT, include_in_schema=False, @@ -644,6 +674,9 @@ async def rpc(request: Request) -> Response: try: response = await proxy.rpc_call(body, request.headers.get('X-RPC-Timeout')) + except InvalidRequest as e: + logger.warning(f"rejected a malformed request (request {req_time}): {e}") + return Response(status_code=400) except ValueError: return Response(status_code=500) except OSError as e: diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index ce5611c0fa..6413f521ce 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -244,10 +244,10 @@ def test_unauthorized_returns_401(self): self.assertEqual(response.status_code, 401) - def test_malformed_body_returns_500(self): + def test_malformed_body_returns_400(self): response = self._proxy.request("not json") - self.assertEqual(response.status_code, 500) + self.assertEqual(response.status_code, 400) def test_keep_alive_serves_several_requests_on_one_connection(self): """The HTTP/1.0 server this replaced closed after every response, so diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 9fe173a78c..76557ab5a5 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -539,25 +539,41 @@ def test_unreachable_spdk_gets_500(self): self.assertEqual(response.status_code, 500) - def test_malformed_request_body_gets_500(self): + def test_malformed_request_body_gets_400(self): + """The caller sent junk; nothing reached SPDK, so a 500 would put the + blame on the wrong side of the socket.""" response = self.client.post("/", content="not json", auth=("test", "secret")) - self.assertEqual(response.status_code, 500) + self.assertEqual(response.status_code, 400) - def test_json_body_without_a_method_gets_500(self): + def test_json_body_without_a_method_gets_400(self): """Valid JSON that is not a JSON-RPC request used to raise KeyError out - of the handler, bypassing the 500 path and the failure counter.""" + of the handler, bypassing the error path and the failure counter.""" response = self.client.post( "/", content=json.dumps({"id": 1}), auth=("test", "secret")) - self.assertEqual(response.status_code, 500) + self.assertEqual(response.status_code, 400) - def test_json_body_that_is_not_an_object_gets_500(self): + def test_json_body_that_is_not_an_object_gets_400(self): for body in ("5", "[]", '"a string"', "null"): with self.subTest(body=body): response = self.client.post("/", content=body, auth=("test", "secret")) - self.assertEqual(response.status_code, 500) + self.assertEqual(response.status_code, 400) + + def test_non_ascii_body_gets_400(self): + response = self.client.post( + "/", content='{"id": 1, "method": "\u00e9"}'.encode("utf-8"), + auth=("test", "secret")) + + self.assertEqual(response.status_code, 400) + + def test_a_rejected_request_never_reaches_spdk(self): + with patch.object(proxy_mod.asyncio, 'open_unix_connection') as connect: + response = self.client.post("/", content="not json", auth=("test", "secret")) + + self.assertEqual(response.status_code, 400) + connect.assert_not_called() def test_caller_timeout_header_is_forwarded(self): payload = rpc_response(result=True).decode() @@ -749,6 +765,24 @@ def test_observations_reach_the_exposition(self): self.assertIn('method="bdev_get_bdevs"', response.text) + def test_client_and_server_errors_are_separate_series(self): + """Status codes are exposed ungrouped, so an operator can tell a + malformed body from bad credentials from a broken SPDK.""" + self.client.post("/", content="not json", auth=("test", "secret")) + self.client.post("/", content="not json", auth=("wrong", "creds")) + with patch.object( + self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): + self.client.post("/", content="{}", auth=("test", "secret")) + + for status in ("400", "401", "500"): + with self.subTest(status=status): + self.assertEqual( + self.proxy.metrics.registry.get_sample_value( + "http_requests_total", + {"handler": "/{path:path}", "method": "POST", "status": status}), + 1, + ) + def test_credentials_never_appear_in_the_exposition(self): response = self.client.get(proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")) @@ -812,6 +846,15 @@ async def never_answers(*args, **kwargs): "spdk_proxy_rpc_failures_total", method="bdev_get_bdevs", reason="timeout"), 1) self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + async def test_a_malformed_request_is_not_counted_as_an_spdk_failure(self): + """The counter is about SPDK; a rejected body is the caller's fault and + shows up as a 400 in ``http_requests_total``.""" + with self.assertRaises(proxy_mod.InvalidRequest): + await self.proxy.rpc_call(b"not json") + + self.assertIsNone(self._value("spdk_proxy_rpc_failures_total")) + self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + async def test_unreachable_spdk_is_counted_as_a_failure(self): with patch_connect(FakeSpdkSocket(ConnectionRefusedError("refused"))): with self.assertRaises(ConnectionRefusedError): From 66aa74c51b51b31f8e102b3b70c32ea5597afabb Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 13:44:35 +0200 Subject: [PATCH 09/22] Add keepalive description and configuration option --- .../services/spdk_http_proxy_server.py | 23 +++++++++++++------ tests/unit/test_spdk_proxy_unit.py | 3 +++ 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 3ad31cce8f..6302ffc57e 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -67,12 +67,6 @@ SPDK_READY_POLL_INTERVAL_SEC = 1 #: SPDK responses are read in one shot; matches the pre-FastAPI recv() size. SPDK_RECV_SIZE = 1024 * 1024 * 1024 -#: Idle keep-alive window. The server this replaced spoke HTTP/1.0 and closed -#: after every response, so a connection could never be dropped underneath a -#: client that was about to reuse it. RPCClient deliberately keeps POST out of -#: its urllib3 retry set, so such a drop surfaces as a failed RPC rather than a -#: retry — hence an idle window far longer than the gap between RPCs to a node. -KEEP_ALIVE_TIMEOUT_SEC = 300 def _rpc_port_or_default(value: Any) -> Any: @@ -126,6 +120,21 @@ class ProxySettings(BaseSettings): ), ), ] = 64 + keepalive_timeout: Annotated[ + int, + Field( + gt=0, + description=( + "Seconds an idle HTTP connection is kept open. The server this replaced spoke " + "HTTP/1.0 and closed after every response, so a connection could never be " + "dropped underneath a client about to reuse it. RPCClient deliberately keeps " + "POST out of its urllib3 retry set, so such a drop surfaces as a failed RPC " + "rather than a retry - hence a window far longer than the gap between RPCs to " + "a node, at the cost of idle connections holding a max_concurrent_connections " + "slot for that long. Was 60s before the move to uvicorn." + ), + ), + ] = 300 spdk_timeout_margin: Annotated[ float, Field( @@ -716,7 +725,7 @@ def main() -> None: port=settings.rpc_port, log_level='info', limit_concurrency=settings.max_concurrent_connections, - timeout_keep_alive=KEEP_ALIVE_TIMEOUT_SEC, + timeout_keep_alive=settings.keepalive_timeout, ssl_certfile=tls.tls_certificate if tls.tls_serve else None, ssl_keyfile=tls.tls_key if tls.tls_serve else None, ssl_ca_certs=tls.tls_certificate_authority if tls.tls_client_auth != ssl.CERT_NONE else None, diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 76557ab5a5..7ebead9205 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -32,6 +32,7 @@ "TIMEOUT": "5", "MAX_CONCURRENT_SPDK": "4", "MAX_CONCURRENT_CONNECTIONS": "8", + "KEEPALIVE_TIMEOUT": "30", "SPDK_TIMEOUT_MARGIN": "2", "MULTI_THREADING_ENABLED": "True", } @@ -129,6 +130,7 @@ def test_defaults_match_the_documented_environment(self): self.assertEqual(settings.timeout, 5 * 60) self.assertEqual(settings.max_concurrent_spdk, 16) self.assertEqual(settings.max_concurrent_connections, 64) + self.assertEqual(settings.keepalive_timeout, 300) self.assertEqual(settings.spdk_timeout_margin, 2.0) self.assertFalse(settings.multi_threading_enabled) @@ -139,6 +141,7 @@ def test_optional_environment_is_read(self): self.assertEqual(settings.timeout, 5) self.assertEqual(settings.max_concurrent_spdk, 4) self.assertEqual(settings.max_concurrent_connections, 8) + self.assertEqual(settings.keepalive_timeout, 30) self.assertEqual(settings.spdk_timeout_margin, 2.0) self.assertTrue(settings.multi_threading_enabled) From 186d0d16d89b23f2e109498e7f7746f372275967 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 15:28:22 +0200 Subject: [PATCH 10/22] address low priority review concerns --- simplyblock_core/AGENTS.md | 2 +- simplyblock_core/services/__main__.py | 5 +- .../services/spdk_http_proxy_server.py | 49 ++++++++++++--- tests/unit/test_spdk_proxy_unit.py | 60 +++++++++++++++++++ 4 files changed, 105 insertions(+), 11 deletions(-) diff --git a/simplyblock_core/AGENTS.md b/simplyblock_core/AGENTS.md index 6361aa7e50..5820e0a506 100644 --- a/simplyblock_core/AGENTS.md +++ b/simplyblock_core/AGENTS.md @@ -8,7 +8,7 @@ Core business logic, data models, and background services for the Simplyblock co - `models/` — Data models inheriting from `BaseModel` (see below). - `services/` — Background services for monitoring and async task execution (health checks, snapshot/lvol/storage-node monitors, task runners for backup, migration, restart, etc.). - `db_controller.py` — Singleton `DBController` wrapping FoundationDB. All data access goes through this class. -- `rpc_client.py` — JSON-RPC client for communicating with storage node SPDK processes. `Session` construction is pooled by `RPCSessionPool` (keyed on identity + retry; `timeout` stays per-call). `services/spdk_http_proxy_server.py`, the receiving end, supports HTTP/1.1 keep-alive so those pooled connections are actually reused end-to-end. +- `rpc_client.py` — JSON-RPC client for communicating with storage node SPDK processes. `Session` construction is pooled by `RPCSessionPool` (keyed on identity + retry; `timeout` stays per-call). `services/spdk_http_proxy_server.py`, the receiving end, supports HTTP/1.1 keep-alive so those pooled connections are actually reused end-to-end. It is a FastAPI app on uvicorn: `create_app()` builds it, importing the module has no side effects, and it exposes a Prometheus endpoint on `/_meta/metrics` (same path as `simplyblock_web`, behind the same basic-auth credentials as the RPCs) alongside a periodic timing summary in its log. - `kms/` — Key management abstraction: HashiCorp Vault (`_hcp.py`) and FDB-based (`_fdb.py`) backends. ## Data Model Pattern diff --git a/simplyblock_core/services/__main__.py b/simplyblock_core/services/__main__.py index 06e0cc47fb..20e5caaf7f 100644 --- a/simplyblock_core/services/__main__.py +++ b/simplyblock_core/services/__main__.py @@ -7,7 +7,10 @@ depend on a file layout, so consumers can migrate off the paths. ``runpy`` rather than importing and calling ``main()``: it reproduces the -semantics of running the file directly, so both invocations behave identically. +semantics of running the file directly -- ``__name__ == "__main__"``, so a +module's own entry-point guard is what runs, and ``sys.argv[0]`` set to the +module's path -- so both invocations behave identically without this dispatcher +having to assume every service spells its entry point ``main()``. """ import argparse import importlib diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 6302ffc57e..f5b784c74b 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -12,6 +12,7 @@ import asyncio import base64 +import functools import hmac import json import logging @@ -170,9 +171,14 @@ class ProxySettings(BaseSettings): def rpc_sock(self) -> str: return self.rpc_sock_path or f"/mnt/ramdisk/spdk_{self.rpc_port}/spdk.sock" - @property + @functools.cached_property def authorization(self) -> str: - """The ``Authorization`` header value clients have to present.""" + """The ``Authorization`` header value clients have to present. + + Cached: it is compared on every request, including the ones on the + data path, and neither the credentials nor their encoding change over + the process' life. + """ credentials = f"{self.rpc_username}:{self.rpc_password.get_secret_value()}" return 'Basic ' + base64.b64encode(credentials.encode('ascii')).decode('ascii') @@ -404,7 +410,9 @@ def __init__(self, settings: ProxySettings) -> None: self.settings = settings self.spdk_ready = False #: Requests currently being served, and unix sockets currently open - #: towards SPDK. Both are logged per request and asserted on by tests. + #: towards SPDK. Asserted on by tests; the operator-facing view of + #: both is ``spdk_proxy_rpc_slots_in_use`` / + #: ``spdk_proxy_unix_connections_open``, not a log line. self.active_requests = 0 self.open_connections = 0 self.metrics = ProxyMetrics() @@ -465,7 +473,7 @@ async def _probe(self, payload: bytes) -> bool: writer.write(payload) await writer.drain() - buf = b'' + buf = bytearray() while (data := await reader.read(4096)) != b'': buf += data try: @@ -511,8 +519,6 @@ async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Op Returns ``None`` for a request without an ``id`` (a notification, which SPDK does not answer). """ - logger.info(f"active requests: {self.active_requests}") - logger.info(f"active unix sockets: {self.open_connections}") # Parsed before the slot is taken, so a malformed request neither # occupies one nor gets counted as an SPDK-side failure. req_data = _parse_request(req) @@ -565,7 +571,9 @@ async def _exchange( if 'id' not in req_data: return None - buf = b'' + # bytearray, not bytes: it grows in place, where `bytes += + # bytes` copies the whole buffer on every chunk. + buf = bytearray() response = None # Monotonic: a duration must not be measured against a clock # that can step backwards under NTP. @@ -596,6 +604,21 @@ async def _exchange( self.metrics.unix_connections.dec() +def _log_task_death(task: "asyncio.Task[None]") -> None: + """Report a fire-and-forget task that ended on its own. + + Nothing awaits the stats task, so an exception it did not anticipate would + otherwise surface only as asyncio's "exception was never retrieved" + warning, at garbage-collection time and detached from the failure. + """ + if task.cancelled(): + return + if (error := task.exception()) is not None: + logger.error(f"Background task {task.get_name()} died: {error}", exc_info=error) + else: + logger.error(f"Background task {task.get_name()} returned unexpectedly") + + def _close(writer: asyncio.StreamWriter) -> None: try: writer.close() @@ -636,13 +659,18 @@ def create_app(settings: ProxySettings) -> FastAPI: @asynccontextmanager async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: - stats_task = asyncio.create_task(proxy.report_stats()) + stats_task = asyncio.create_task(proxy.report_stats(), name='report_stats') + stats_task.add_done_callback(_log_task_death) try: await proxy.wait_for_spdk_ready() logger.info('Started RPC http proxy server') yield finally: stats_task.cancel() + # Awaited so shutdown does not race the cancellation ("Task was + # destroyed but it is pending"); gathered so neither the + # CancelledError nor an already-logged failure escapes here. + await asyncio.gather(stats_task, return_exceptions=True) app = FastAPI(lifespan=lifespan, docs_url=None, redoc_url=None, openapi_url=None) app.state.proxy = proxy @@ -670,11 +698,14 @@ async def rpc(request: Request) -> Response: req_time = time.time_ns() proxy.active_requests += 1 logger.info(f"incoming request at: {req_time}") - logger.info(f"active server session: {proxy.active_requests}") try: read_start = time.monotonic() try: body = await request.body() + # The only disconnect this handler can observe. Writing the + # response is uvicorn's, so the BrokenPipeError the + # BaseHTTPRequestHandler this replaced had to catch around + # `wfile.write` cannot reach here. except ClientDisconnect: logger.warning( f"client disconnected before the request body arrived (request {req_time})") diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 7ebead9205..c74f3f3b87 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -600,6 +600,66 @@ def test_in_flight_count_returns_to_zero_after_failure(self): self.assertEqual(self.proxy.active_requests, 0) +class TestClientDisconnect(unittest.IsolatedAsyncioTestCase): + """A caller that vanishes mid-request must not cost anything. + + Driven as a raw ASGI call: ``TestClient`` always delivers a complete body, + so the ``http.disconnect`` message cannot be produced through it. + """ + + def setUp(self): + self.app = proxy_mod.create_app(make_settings()) + self.proxy = self.app.state.proxy + self.proxy.spdk_ready = True + + async def _disconnect_before_body(self): + scope = { + "type": "http", + "asgi": {"version": "3.0", "spec_version": "2.1"}, + "http_version": "1.1", + "method": "POST", + "scheme": "http", + "path": "/", + "raw_path": b"/", + "query_string": b"", + "root_path": "", + "headers": [ + (b"host", b"testserver"), + (b"authorization", self.proxy.settings.authorization.encode("ascii")), + (b"content-type", b"application/json"), + (b"content-length", b"42"), + ], + "client": ("127.0.0.1", 45678), + "server": ("testserver", 80), + } + sent = [] + + async def receive(): + return {"type": "http.disconnect"} + + async def send(message): + sent.append(message) + + await self.app(scope, receive, send) + return sent + + async def test_disconnect_before_the_body_gets_400(self): + sent = await self._disconnect_before_body() + + start = next(m for m in sent if m["type"] == "http.response.start") + self.assertEqual(start["status"], 400) + + async def test_disconnect_reaches_neither_spdk_nor_a_concurrency_slot(self): + with patch.object(self.proxy, 'rpc_call', new=AsyncMock()) as rpc_call: + await self._disconnect_before_body() + + rpc_call.assert_not_called() + self.assertEqual(self.proxy.active_requests, 0) + self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual( + self.proxy.metrics.registry.get_sample_value("spdk_proxy_rpc_slots_in_use"), 0) + + class TestIntervalReport(unittest.TestCase): """The periodic log line, computed from a histogram's own totals.""" From bd5a6252ff62ac26879226f5b1cfb37ca3071602 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:04:52 +0200 Subject: [PATCH 11/22] Convert spdk proxy log to middleware --- simplyblock_core/AGENTS.md | 2 +- .../services/spdk_http_proxy_server.py | 148 ++++++++++++++---- tests/unit/test_spdk_proxy_unit.py | 110 +++++++++++++ 3 files changed, 232 insertions(+), 28 deletions(-) diff --git a/simplyblock_core/AGENTS.md b/simplyblock_core/AGENTS.md index 5820e0a506..74509a62b0 100644 --- a/simplyblock_core/AGENTS.md +++ b/simplyblock_core/AGENTS.md @@ -8,7 +8,7 @@ Core business logic, data models, and background services for the Simplyblock co - `models/` — Data models inheriting from `BaseModel` (see below). - `services/` — Background services for monitoring and async task execution (health checks, snapshot/lvol/storage-node monitors, task runners for backup, migration, restart, etc.). - `db_controller.py` — Singleton `DBController` wrapping FoundationDB. All data access goes through this class. -- `rpc_client.py` — JSON-RPC client for communicating with storage node SPDK processes. `Session` construction is pooled by `RPCSessionPool` (keyed on identity + retry; `timeout` stays per-call). `services/spdk_http_proxy_server.py`, the receiving end, supports HTTP/1.1 keep-alive so those pooled connections are actually reused end-to-end. It is a FastAPI app on uvicorn: `create_app()` builds it, importing the module has no side effects, and it exposes a Prometheus endpoint on `/_meta/metrics` (same path as `simplyblock_web`, behind the same basic-auth credentials as the RPCs) alongside a periodic timing summary in its log. +- `rpc_client.py` — JSON-RPC client for communicating with storage node SPDK processes. `Session` construction is pooled by `RPCSessionPool` (keyed on identity + retry; `timeout` stays per-call). `services/spdk_http_proxy_server.py`, the receiving end, supports HTTP/1.1 keep-alive so those pooled connections are actually reused end-to-end. It is a FastAPI app on uvicorn: `create_app()` builds it, importing the module has no side effects, and it exposes a Prometheus endpoint on `/_meta/metrics` (same path as `simplyblock_web`, behind the same basic-auth credentials as the RPCs) alongside a periodic timing summary in its log. Per-request logging follows `simplyblock_web/app.py`: uvicorn's access log is off and an `AccessLogMiddleware` replaces it, enriched with the JSON-RPC method and the id that ties the access line to the request's own `Request:` line. - `kms/` — Key management abstraction: HashiCorp Vault (`_hcp.py`) and FDB-based (`_fdb.py`) backends. ## Data Model Pattern diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index f5b784c74b..e84cebdacd 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -12,6 +12,7 @@ import asyncio import base64 +import dataclasses import functools import hmac import json @@ -21,7 +22,7 @@ import sys import time from contextlib import asynccontextmanager -from typing import Annotated, Any, AsyncGenerator, Dict, Optional, Set, Tuple +from typing import Annotated, Any, AsyncGenerator, ClassVar, Dict, Optional, Set, Tuple import uvicorn from fastapi import Depends, FastAPI, HTTPException, Request, Response @@ -29,6 +30,7 @@ from prometheus_fastapi_instrumentator import Instrumentator from pydantic import BeforeValidator, Field, SecretStr from pydantic_settings import BaseSettings, SettingsConfigDict +from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint from starlette.requests import ClientDisconnect from simplyblock_core.settings import Settings @@ -36,6 +38,9 @@ logger = logging.getLogger(__name__) +#: Carries the access log alone, so its extra fields can be rendered by name. +#: The handler is attached by ``_configure_logging``. +access_logger = logging.getLogger(f'{__name__}.access') #: How often the periodic timing report is emitted, and hence the interval #: every figure in it covers. @@ -380,6 +385,75 @@ def reports(self) -> Tuple[IntervalReport, ...]: return (self.body_read, self.spdk_response) +@dataclasses.dataclass +class RequestLog: + """What one request contributes to its own log lines. + + Threaded through the call rather than logged where each field becomes + known. Every RPC is a POST to the same path, so an access line that cannot + name the JSON-RPC method cannot tell two requests apart -- and the method + is only known once ``rpc_call`` has parsed the body, well inside the + request. Carrying the id here too gives the pre-flight line (the only + place the params appear) and the access line one identifier in common. + """ + + request_id: int = dataclasses.field(default_factory=time.time_ns) + rpc_method: str = '-' + + +class AccessLogMiddleware(BaseHTTPMiddleware): + """One line per served request, in place of uvicorn's access log. + + Modelled on ``simplyblock_web.app.AccessLogMiddleware``: uvicorn's own + line is switched off in ``main`` and this replaces it, so the fields this + server cares about land on the same record as the status code and the + duration instead of in log lines of their own. + """ + + #: How ``_configure_logging`` renders the fields ``dispatch`` attaches to + #: the record. Prefix matches the other lines this process emits; the rest + #: follows ``simplyblock_web.app``, plus the two fields that are the point + #: of having our own access log here (the JSON-RPC method, and the id + #: shared with the request's own log line). + LOG_FORMAT: ClassVar[str] = ( + '%(asctime)s: %(levelname)s: %(client)s "%(message)s" rpc=%(rpc_method)s' + ' %(status_code)s req=%(request_size)s resp=%(response_size)s' + ' %(duration_ms).2fms id=%(request_id)s' + ) + + async def dispatch( + self, request: Request, call_next: RequestResponseEndpoint) -> Response: + request.state.request_log = log = RequestLog() + + start = time.monotonic() + response = await call_next(request) + duration_ms = (time.monotonic() - start) * 1000 + + # A scrape is not traffic: Prometheus polls this endpoint for the life + # of the process, and the exposition it gets back is its own record + # that it happened. + if request.url.path == METRICS_ENDPOINT: + return response + + access_logger.info( + '%s %s', + request.method, + # Query strings can carry credentials and have no type info to + # mask by, so log the path only. + request.url.path, + extra={ + 'client': request.client.host if request.client is not None else '-', + 'request_size': request.headers.get('content-length', '-'), + 'status_code': response.status_code, + 'response_size': response.headers.get('content-length', '-'), + 'duration_ms': duration_ms, + 'rpc_method': log.rpc_method, + 'request_id': log.request_id, + }, + ) + return response + + class InvalidRequest(Exception): """The request body is not a JSON-RPC request object. @@ -513,24 +587,34 @@ def _resolve_sock_timeout(self, client_timeout: Optional[str]) -> float: return self.settings.timeout return min(ct * self.settings.spdk_timeout_margin, self.settings.timeout) - async def rpc_call(self, req: bytes, client_timeout: Optional[str] = None) -> Optional[str]: + async def rpc_call( + self, + req: bytes, + client_timeout: Optional[str] = None, + log: Optional[RequestLog] = None, + ) -> Optional[str]: """Forward one JSON-RPC request, returning SPDK's raw response. Returns ``None`` for a request without an ``id`` (a notification, which SPDK does not answer). + + ``log`` is filled in as the request is understood, so the access line + can name what this call turned out to be. A caller that serves no HTTP + request leaves it out and gets one of its own. """ + log = RequestLog() if log is None else log # Parsed before the slot is taken, so a malformed request neither # occupies one nor gets counted as an SPDK-side failure. req_data = _parse_request(req) - method = str(req_data['method']) - req_time = time.time_ns() + log.rpc_method = str(req_data['method']) params = str(redact_rpc_params(req_data['params'])) if 'params' in req_data else "" - logger.info(f"Request:{req_time} function: {method}, params: {params}") + logger.info( + f"Request:{log.request_id} function: {log.rpc_method}, params: {params}") sock_timeout = self._resolve_sock_timeout(client_timeout) async with self.slots: self.metrics.slots_in_use.inc() try: - return await self._rpc_call_inner(req, req_data, method, req_time, sock_timeout) + return await self._rpc_call_inner(req, req_data, log, sock_timeout) finally: self.metrics.slots_in_use.dec() @@ -538,28 +622,25 @@ async def _rpc_call_inner( self, req: bytes, req_data: dict, - method: str, - req_time: int, + log: RequestLog, sock_timeout: float, ) -> Optional[str]: try: - return await asyncio.wait_for( - self._exchange(req, req_data, method, req_time), sock_timeout) + return await asyncio.wait_for(self._exchange(req, req_data, log), sock_timeout) except asyncio.TimeoutError as e: logger.error( - f"Socket timeout waiting for SPDK response (request {req_time}, " - f"function: {method})") - self.metrics.record_failure(method, 'timeout') + f"Socket timeout waiting for SPDK response (request {log.request_id}, " + f"function: {log.rpc_method})") + self.metrics.record_failure(log.rpc_method, 'timeout') raise ValueError('SPDK response timeout') from e except OSError: - self.metrics.record_failure(method, 'unreachable') + self.metrics.record_failure(log.rpc_method, 'unreachable') raise except ValueError: - self.metrics.record_failure(method, 'invalid_response') + self.metrics.record_failure(log.rpc_method, 'invalid_response') raise - async def _exchange( - self, req: bytes, req_data: dict, method: str, req_time: int) -> Optional[str]: + async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Optional[str]: self.open_connections += 1 self.metrics.unix_connections.inc() try: @@ -589,13 +670,11 @@ async def _exchange( break continue break - self.metrics.observe_response(method, time.monotonic() - recv_start) + self.metrics.observe_response(log.rpc_method, time.monotonic() - recv_start) if not response and len(buf) > 0: raise ValueError('Invalid response') - logger.info(f"Response:{req_time}") - return buf.decode('ascii') finally: _close(writer) @@ -640,8 +719,9 @@ def require_authorization(request: Request) -> None: authorization.encode('utf-8'), settings.authorization.encode('utf-8'), ): - # The only trace a rejected request leaves: it never reaches the route, - # which is what logs every other request. + # The access line records the 401 too, but at INFO and among every + # other request; a credential that does not match is worth a level + # something greps for. client = request.client.host if request.client is not None else 'unknown' logger.warning(f"rejected an unauthorized request from {client}") raise HTTPException(status_code=401, headers={'WWW-Authenticate': 'Basic'}) @@ -693,11 +773,12 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: dependencies=[Depends(require_authorization)], ) + app.add_middleware(AccessLogMiddleware) + @app.post('/{path:path}', dependencies=[Depends(require_authorization)]) async def rpc(request: Request) -> Response: - req_time = time.time_ns() + log: RequestLog = request.state.request_log proxy.active_requests += 1 - logger.info(f"incoming request at: {req_time}") try: read_start = time.monotonic() try: @@ -708,14 +789,16 @@ async def rpc(request: Request) -> Response: # `wfile.write` cannot reach here. except ClientDisconnect: logger.warning( - f"client disconnected before the request body arrived (request {req_time})") + "client disconnected before the request body arrived " + f"(request {log.request_id})") return Response(status_code=400) proxy.metrics.observe_body_read(time.monotonic() - read_start) try: - response = await proxy.rpc_call(body, request.headers.get('X-RPC-Timeout')) + response = await proxy.rpc_call( + body, request.headers.get('X-RPC-Timeout'), log) except InvalidRequest as e: - logger.warning(f"rejected a malformed request (request {req_time}): {e}") + logger.warning(f"rejected a malformed request (request {log.request_id}): {e}") return Response(status_code=400) except ValueError: return Response(status_code=500) @@ -743,6 +826,15 @@ def _configure_logging() -> None: root.addHandler(handler) root.setLevel(logging.INFO) + # The access log needs a format of its own to render the fields the + # middleware attaches, and must not propagate, or the root handler would + # print the same line again without them. Wired here rather than at import + # time, which the module docstring promises stays free of side effects. + access_handler = logging.StreamHandler(stream=sys.stdout) + access_handler.setFormatter(logging.Formatter(AccessLogMiddleware.LOG_FORMAT)) + access_logger.addHandler(access_handler) + access_logger.propagate = False + def main() -> None: _configure_logging() @@ -755,6 +847,8 @@ def main() -> None: host=settings.server_ip, port=settings.rpc_port, log_level='info', + # Replaced by AccessLogMiddleware, not dropped. + access_log=False, limit_concurrency=settings.max_concurrent_connections, timeout_keep_alive=settings.keepalive_timeout, ssl_certfile=tls.tls_certificate if tls.tls_serve else None, diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index c74f3f3b87..ebe70466f8 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -7,7 +7,9 @@ """ import asyncio +import contextlib import json +import logging import os import unittest from unittest.mock import AsyncMock, patch @@ -115,6 +117,30 @@ def rpc_response(**kwargs): return json.dumps({"jsonrpc": "2.0", "id": 1, **kwargs}).encode('ascii') +@contextlib.contextmanager +def captured_records(logger): + """Collect what a logger emits, including nothing at all. + + ``assertLogs`` fails a test that logs nothing, and ``assertNoLogs`` needs + python 3.10; the access logger has to be asserted both ways. + """ + records = [] + + class Capture(logging.Handler): + def emit(self, record): + records.append(record) + + handler = Capture() + logger.addHandler(handler) + previous = logger.level + logger.setLevel(logging.INFO) + try: + yield records + finally: + logger.removeHandler(handler) + logger.setLevel(previous) + + class TestProxySettings(unittest.TestCase): """The proxy is configured exclusively through unprefixed environment variables that deployed manifests already set — defaults included.""" @@ -600,6 +626,90 @@ def test_in_flight_count_returns_to_zero_after_failure(self): self.assertEqual(self.proxy.active_requests, 0) +class TestAccessLog(unittest.TestCase): + """The line that replaces uvicorn's access log. + + Asserted on the record rather than on rendered text: the formatter is + installed by ``_configure_logging``, which only ``main`` calls, and the + fields are what a different formatter would render anyway. + """ + + def setUp(self): + self.app = proxy_mod.create_app(make_settings()) + self.proxy = self.app.state.proxy + self.proxy.spdk_ready = True + self.client = TestClient(self.app) + self.body = json.dumps({"id": 1, "method": "bdev_get_bdevs"}) + + def _serve(self, path="/", auth=("test", "secret")): + """POST one RPC that SPDK answers, returning the access records.""" + fake = FakeSpdkSocket([rpc_response(result=True)]) + with captured_records(proxy_mod.access_logger) as records: + with patch_connect(fake): + self.client.post(path, content=self.body, auth=auth) + return records + + def test_one_line_per_request(self): + self.assertEqual(len(self._serve()), 1) + + def test_line_names_the_rpc_method(self): + record, = self._serve() + + self.assertEqual(record.rpc_method, "bdev_get_bdevs") + self.assertEqual(record.getMessage(), "POST /") + self.assertEqual(record.status_code, 200) + self.assertEqual(record.client, "testclient") + + def test_line_carries_sizes_and_a_duration(self): + record, = self._serve() + + self.assertEqual(record.request_size, str(len(self.body))) + self.assertEqual(record.response_size, str(len(rpc_response(result=True)))) + self.assertGreater(record.duration_ms, 0) + + def test_query_string_is_not_logged(self): + record, = self._serve(path="/?token=hunter2") + + self.assertEqual(record.getMessage(), "POST /") + self.assertNotIn("hunter2", str(record.__dict__)) + + def test_id_ties_the_line_to_the_request_it_logged(self): + """The params live on the request line, the outcome on the access + line; one id is what makes them one request.""" + fake = FakeSpdkSocket([rpc_response(result=True)]) + with captured_records(proxy_mod.access_logger) as access: + with self.assertLogs(proxy_mod.logger, "INFO") as request_lines: + with patch_connect(fake): + self.client.post("/", content=self.body, auth=("test", "secret")) + + record, = access + self.assertIn(f"Request:{record.request_id}", "\n".join(request_lines.output)) + + def test_a_rejected_request_is_logged_without_an_rpc_method(self): + record, = self._serve(auth=("test", "wrong")) + + self.assertEqual(record.status_code, 401) + self.assertEqual(record.rpc_method, "-") + + def test_the_configured_format_renders_the_line(self): + """LOG_FORMAT names fields the middleware has to supply, and a + mismatch would raise on the first served request in production.""" + record, = self._serve() + + line = logging.Formatter(proxy_mod.AccessLogMiddleware.LOG_FORMAT).format(record) + + self.assertIn('"POST /" rpc=bdev_get_bdevs 200', line) + self.assertIn(f"id={record.request_id}", line) + + def test_scrapes_are_not_logged(self): + with captured_records(proxy_mod.access_logger) as records: + response = self.client.get( + proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")) + + self.assertEqual(response.status_code, 200) + self.assertEqual(records, []) + + class TestClientDisconnect(unittest.IsolatedAsyncioTestCase): """A caller that vanishes mid-request must not cost anything. From ca73399a59caf797a6554bdba583703abc0cd7ae Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:07:46 +0200 Subject: [PATCH 12/22] Convert retry logic to tenacity --- tests/integration/test_spdk_proxy_e2e.py | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index 6413f521ce..8e6d6df8a7 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -23,6 +23,7 @@ import requests import uvicorn +from tenacity import Retrying, stop_after_delay, wait_fixed, retry_if_exception_type, retry_if_result, RetryError if sys.platform == "win32": raise unittest.SkipTest("AF_UNIX not available on Windows") @@ -146,15 +147,14 @@ def stop(self): self._thread.join(timeout=10) def wait_until_serving(self, timeout=15): - deadline = time.monotonic() + timeout - while time.monotonic() < deadline: - try: - if self.post("spdk_get_version").status_code == 200: - return True - except requests.RequestException: - pass - time.sleep(0.1) - return False + try: + return Retrying( + stop=stop_after_delay(timeout), + wait=wait_fixed(0.1), + retry=(retry_if_exception_type(requests.RequestException) | retry_if_result(lambda success: not success)), + )(lambda: self.post("spdk_get_version").status_code == 200) + except RetryError: + return False def is_refusing_connections(self): try: From ddbd70bbe503d0c0b5113834e1b3ef3d24f6c932 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:09:19 +0200 Subject: [PATCH 13/22] Prune comments --- simplyblock_core/services/spdk_http_proxy_server.py | 10 ---------- 1 file changed, 10 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index e84cebdacd..b7365e5b4c 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -89,11 +89,6 @@ def _rpc_port_or_default(value: Any) -> Any: class ProxySettings(BaseSettings): """Environment configuration of the proxy. - - The variable names carry no ``SB_`` prefix — they are baked into the - deployed manifests (``simplyblock_web/templates/storage_deploy_spdk.yaml.j2``) - and into the docker launch path - (``simplyblock_web/api/internal/storage_node/docker.py``). """ model_config = SettingsConfigDict(case_sensitive=False) @@ -403,11 +398,6 @@ class RequestLog: class AccessLogMiddleware(BaseHTTPMiddleware): """One line per served request, in place of uvicorn's access log. - - Modelled on ``simplyblock_web.app.AccessLogMiddleware``: uvicorn's own - line is switched off in ``main`` and this replaces it, so the fields this - server cares about land on the same record as the status code and the - duration instead of in log lines of their own. """ #: How ``_configure_logging`` renders the fields ``dispatch`` attaches to From ad3cf32caada37c7ff4ae4c90facec3939ff2ef9 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:18:39 +0200 Subject: [PATCH 14/22] Convert is-ready-flag to local --- .../services/spdk_http_proxy_server.py | 74 ++++++------------- tests/integration/test_spdk_proxy_e2e.py | 1 - tests/unit/test_spdk_proxy_unit.py | 17 ----- 3 files changed, 21 insertions(+), 71 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index b7365e5b4c..e666d781a6 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -38,8 +38,7 @@ logger = logging.getLogger(__name__) -#: Carries the access log alone, so its extra fields can be rendered by name. -#: The handler is attached by ``_configure_logging``. +#: The access log. Its handler is attached by ``_configure_logging``. access_logger = logging.getLogger(f'{__name__}.access') #: How often the periodic timing report is emitted, and hence the interval @@ -173,12 +172,7 @@ def rpc_sock(self) -> str: @functools.cached_property def authorization(self) -> str: - """The ``Authorization`` header value clients have to present. - - Cached: it is compared on every request, including the ones on the - data path, and neither the credentials nor their encoding change over - the process' life. - """ + """The ``Authorization`` header value clients have to present.""" credentials = f"{self.rpc_username}:{self.rpc_password.get_secret_value()}" return 'Basic ' + base64.b64encode(credentials.encode('ascii')).decode('ascii') @@ -382,14 +376,9 @@ def reports(self) -> Tuple[IntervalReport, ...]: @dataclasses.dataclass class RequestLog: - """What one request contributes to its own log lines. - - Threaded through the call rather than logged where each field becomes - known. Every RPC is a POST to the same path, so an access line that cannot - name the JSON-RPC method cannot tell two requests apart -- and the method - is only known once ``rpc_call`` has parsed the body, well inside the - request. Carrying the id here too gives the pre-flight line (the only - place the params appear) and the access line one identifier in common. + """The fields of a request's log lines that only the request knows. + + ``rpc_method`` is filled in by ``rpc_call`` once it has parsed the body. """ request_id: int = dataclasses.field(default_factory=time.time_ns) @@ -400,11 +389,8 @@ class AccessLogMiddleware(BaseHTTPMiddleware): """One line per served request, in place of uvicorn's access log. """ - #: How ``_configure_logging`` renders the fields ``dispatch`` attaches to - #: the record. Prefix matches the other lines this process emits; the rest - #: follows ``simplyblock_web.app``, plus the two fields that are the point - #: of having our own access log here (the JSON-RPC method, and the id - #: shared with the request's own log line). + #: Rendered by the handler ``_configure_logging`` installs, out of the + #: fields ``dispatch`` attaches to the record. LOG_FORMAT: ClassVar[str] = ( '%(asctime)s: %(levelname)s: %(client)s "%(message)s" rpc=%(rpc_method)s' ' %(status_code)s req=%(request_size)s resp=%(response_size)s' @@ -419,9 +405,7 @@ async def dispatch( response = await call_next(request) duration_ms = (time.monotonic() - start) * 1000 - # A scrape is not traffic: Prometheus polls this endpoint for the life - # of the process, and the exposition it gets back is its own record - # that it happened. + # Scrapes are not traffic worth a line each. if request.url.path == METRICS_ENDPOINT: return response @@ -472,11 +456,8 @@ class SpdkProxy: def __init__(self, settings: ProxySettings) -> None: self.settings = settings - self.spdk_ready = False #: Requests currently being served, and unix sockets currently open - #: towards SPDK. Asserted on by tests; the operator-facing view of - #: both is ``spdk_proxy_rpc_slots_in_use`` / - #: ``spdk_proxy_unix_connections_open``, not a log line. + #: towards SPDK. self.active_requests = 0 self.open_connections = 0 self.metrics = ProxyMetrics() @@ -518,14 +499,15 @@ async def report_stats(self) -> None: async def wait_for_spdk_ready(self) -> None: """Block until SPDK responds to spdk_get_version on the unix socket.""" payload = json.dumps({'id': 1, 'method': 'spdk_get_version'}).encode('ascii') - while not self.spdk_ready: + while True: try: - self.spdk_ready = await asyncio.wait_for( + ready = await asyncio.wait_for( self._probe(payload), SPDK_READY_PROBE_TIMEOUT_SEC) except (OSError, asyncio.TimeoutError) as e: logger.info(f"Waiting for SPDK to be ready: {e}") + ready = False - if self.spdk_ready: + if ready: logger.info("SPDK is ready (spdk_get_version responded)") return @@ -588,9 +570,7 @@ async def rpc_call( Returns ``None`` for a request without an ``id`` (a notification, which SPDK does not answer). - ``log`` is filled in as the request is understood, so the access line - can name what this call turned out to be. A caller that serves no HTTP - request leaves it out and gets one of its own. + A caller that serves no HTTP request may leave ``log`` out. """ log = RequestLog() if log is None else log # Parsed before the slot is taken, so a malformed request neither @@ -642,8 +622,7 @@ async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Option if 'id' not in req_data: return None - # bytearray, not bytes: it grows in place, where `bytes += - # bytes` copies the whole buffer on every chunk. + # bytearray grows in place, where `bytes +=` copies. buf = bytearray() response = None # Monotonic: a duration must not be measured against a clock @@ -676,9 +655,8 @@ async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Option def _log_task_death(task: "asyncio.Task[None]") -> None: """Report a fire-and-forget task that ended on its own. - Nothing awaits the stats task, so an exception it did not anticipate would - otherwise surface only as asyncio's "exception was never retrieved" - warning, at garbage-collection time and detached from the failure. + Nothing awaits the stats task, so a failure would otherwise surface only + as asyncio's "exception was never retrieved" warning at collection time. """ if task.cancelled(): return @@ -709,9 +687,6 @@ def require_authorization(request: Request) -> None: authorization.encode('utf-8'), settings.authorization.encode('utf-8'), ): - # The access line records the 401 too, but at INFO and among every - # other request; a credential that does not match is worth a level - # something greps for. client = request.client.host if request.client is not None else 'unknown' logger.warning(f"rejected an unauthorized request from {client}") raise HTTPException(status_code=401, headers={'WWW-Authenticate': 'Basic'}) @@ -737,9 +712,8 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: yield finally: stats_task.cancel() - # Awaited so shutdown does not race the cancellation ("Task was - # destroyed but it is pending"); gathered so neither the - # CancelledError nor an already-logged failure escapes here. + # Awaited so the task is really gone before shutdown continues; + # return_exceptions so its CancelledError does not escape. await asyncio.gather(stats_task, return_exceptions=True) app = FastAPI(lifespan=lifespan, docs_url=None, redoc_url=None, openapi_url=None) @@ -773,10 +747,6 @@ async def rpc(request: Request) -> Response: read_start = time.monotonic() try: body = await request.body() - # The only disconnect this handler can observe. Writing the - # response is uvicorn's, so the BrokenPipeError the - # BaseHTTPRequestHandler this replaced had to catch around - # `wfile.write` cannot reach here. except ClientDisconnect: logger.warning( "client disconnected before the request body arrived " @@ -816,10 +786,8 @@ def _configure_logging() -> None: root.addHandler(handler) root.setLevel(logging.INFO) - # The access log needs a format of its own to render the fields the - # middleware attaches, and must not propagate, or the root handler would - # print the same line again without them. Wired here rather than at import - # time, which the module docstring promises stays free of side effects. + # Not propagated: the root handler would print the same line again, + # without the fields. access_handler = logging.StreamHandler(stream=sys.stdout) access_handler.setFormatter(logging.Formatter(AccessLogMiddleware.LOG_FORMAT)) access_logger.addHandler(access_handler) diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index 8e6d6df8a7..33838ccc9c 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -315,7 +315,6 @@ def test_port_stays_closed_until_spdk_answers(self): with mock_spdk(path): self.assertTrue(proxy.wait_until_serving()) - self.assertTrue(proxy.proxy.spdk_ready) self.assertEqual(proxy.proxy.open_connections, 0) diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index ebe70466f8..f60fbeac3e 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -248,20 +248,9 @@ async def test_retries_until_spdk_responds(self): with patch_connect(fake), patch.object(proxy_mod.asyncio, 'sleep', new=AsyncMock()): await proxy.wait_for_spdk_ready() - self.assertTrue(proxy.spdk_ready) self.assertEqual(fake.attempt_count, 3) self.assertEqual(fake.paths[0], "/mnt/ramdisk/spdk_19999/spdk.sock") - async def test_already_ready_returns_immediately(self): - fake = FakeSpdkSocket(ConnectionRefusedError("not ready")) - proxy = make_proxy() - proxy.spdk_ready = True - - with patch_connect(fake): - await proxy.wait_for_spdk_ready() - - self.assertEqual(fake.attempt_count, 0) - async def test_probe_sends_spdk_get_version(self): fake = FakeSpdkSocket([rpc_response(result={})]) proxy = make_proxy() @@ -495,7 +484,6 @@ class TestEndpoint(unittest.TestCase): def setUp(self): self.app = proxy_mod.create_app(make_settings()) self.proxy = self.app.state.proxy - self.proxy.spdk_ready = True # Lifespan (and with it the readiness gate) is deliberately not run: # TestClient only starts it when used as a context manager. self.client = TestClient(self.app) @@ -544,7 +532,6 @@ def test_credentials_are_scoped_to_the_app_that_serves_the_request(self): """The dependency resolves settings per request, so two apps built in one process do not accept each other's credentials.""" other = proxy_mod.create_app(make_settings(rpc_password="other")) - other.state.proxy.spdk_ready = True with patch.object(other.state.proxy, 'rpc_call', new=AsyncMock(return_value=None)): accepted = TestClient(other).post( @@ -637,7 +624,6 @@ class TestAccessLog(unittest.TestCase): def setUp(self): self.app = proxy_mod.create_app(make_settings()) self.proxy = self.app.state.proxy - self.proxy.spdk_ready = True self.client = TestClient(self.app) self.body = json.dumps({"id": 1, "method": "bdev_get_bdevs"}) @@ -720,7 +706,6 @@ class TestClientDisconnect(unittest.IsolatedAsyncioTestCase): def setUp(self): self.app = proxy_mod.create_app(make_settings()) self.proxy = self.app.state.proxy - self.proxy.spdk_ready = True async def _disconnect_before_body(self): scope = { @@ -914,7 +899,6 @@ class TestMetricsEndpoint(unittest.TestCase): def setUp(self): self.app = proxy_mod.create_app(make_settings()) self.proxy = self.app.state.proxy - self.proxy.spdk_ready = True self.client = TestClient(self.app) def test_metrics_require_credentials(self): @@ -965,7 +949,6 @@ def test_two_apps_keep_separate_metrics(self): """Each app owns its registry, so building a second one neither raises nor lets observations bleed between them.""" other = proxy_mod.create_app(make_settings(rpc_password="other")) - other.state.proxy.spdk_ready = True self.proxy.metrics.observe_response("only_in_the_first", 0.1) mine = self.client.get( From 5de89a6f222e96fab920819e07cc81f0e41558bb Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:39:20 +0200 Subject: [PATCH 15/22] fixup! Prune comments --- .../services/spdk_http_proxy_server.py | 53 ++++++------------- tests/integration/test_spdk_proxy_e2e.py | 12 +---- tests/unit/test_spdk_proxy_unit.py | 5 +- 3 files changed, 20 insertions(+), 50 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index e666d781a6..b16b1b1666 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -38,7 +38,7 @@ logger = logging.getLogger(__name__) -#: The access log. Its handler is attached by ``_configure_logging``. +#: Handler and format are installed by ``_configure_logging``. access_logger = logging.getLogger(f'{__name__}.access') #: How often the periodic timing report is emitted, and hence the interval @@ -70,7 +70,7 @@ #: Per-attempt bound on the readiness probe, and the pause between attempts. SPDK_READY_PROBE_TIMEOUT_SEC = 5 SPDK_READY_POLL_INTERVAL_SEC = 1 -#: SPDK responses are read in one shot; matches the pre-FastAPI recv() size. +#: SPDK responses are read in one shot. SPDK_RECV_SIZE = 1024 * 1024 * 1024 @@ -87,9 +87,6 @@ def _rpc_port_or_default(value: Any) -> Any: class ProxySettings(BaseSettings): - """Environment configuration of the proxy. - """ - model_config = SettingsConfigDict(case_sensitive=False) server_ip: Annotated[str, Field(description="Address the HTTP server binds to")] @@ -115,8 +112,8 @@ class ProxySettings(BaseSettings): description=( "Cap on concurrent HTTP connections. Above max_concurrent_spdk since a " "kept-alive connection can sit idle, not doing SPDK work, most of the time. " - "Enforced by uvicorn, which answers 503 past the cap rather than waiting for " - "a slot the way the ThreadingHTTPServer this replaced blocked in accept()." + "Enforced by uvicorn, which answers 503 past the cap rather than waiting " + "for a slot." ), ), ] = 64 @@ -125,13 +122,11 @@ class ProxySettings(BaseSettings): Field( gt=0, description=( - "Seconds an idle HTTP connection is kept open. The server this replaced spoke " - "HTTP/1.0 and closed after every response, so a connection could never be " - "dropped underneath a client about to reuse it. RPCClient deliberately keeps " - "POST out of its urllib3 retry set, so such a drop surfaces as a failed RPC " - "rather than a retry - hence a window far longer than the gap between RPCs to " - "a node, at the cost of idle connections holding a max_concurrent_connections " - "slot for that long. Was 60s before the move to uvicorn." + "Seconds an idle HTTP connection is kept open. RPCClient deliberately keeps " + "POST out of its urllib3 retry set, so a connection dropped underneath a " + "client about to reuse it surfaces as a failed RPC rather than a retry - " + "hence a window far longer than the gap between RPCs to a node, at the cost " + "of idle connections holding a max_concurrent_connections slot for that long." ), ), ] = 300 @@ -152,8 +147,7 @@ class ProxySettings(BaseSettings): bool, Field( description=( - "Serve RPCs concurrently. When false the proxy forwards one RPC at a time, " - "matching the single-threaded HTTPServer this used to run on." + "Serve RPCs concurrently. When false the proxy forwards one RPC at a time." ) ), ] = False @@ -386,8 +380,7 @@ class RequestLog: class AccessLogMiddleware(BaseHTTPMiddleware): - """One line per served request, in place of uvicorn's access log. - """ + """One line per served request, in place of uvicorn's access log.""" #: Rendered by the handler ``_configure_logging`` installs, out of the #: fields ``dispatch`` attaches to the record. @@ -456,13 +449,9 @@ class SpdkProxy: def __init__(self, settings: ProxySettings) -> None: self.settings = settings - #: Requests currently being served, and unix sockets currently open - #: towards SPDK. self.active_requests = 0 self.open_connections = 0 self.metrics = ProxyMetrics() - # Without MULTI_THREADING_ENABLED the proxy used to run on a - # non-threading HTTPServer, i.e. one request at a time. self.concurrency_limit = ( settings.max_concurrent_spdk if settings.multi_threading_enabled else 1) self._slots: Optional[asyncio.Semaphore] = None @@ -546,8 +535,8 @@ def _resolve_sock_timeout(self, client_timeout: Optional[str]) -> float: reach SPDK and time out at the caller. Holding the slot only ~``spdk_timeout_margin``x longer than the caller waits lets slots recycle promptly. Capped at the global ``timeout`` so genuinely long - operations keep today's budget; falls back to ``timeout`` when the - caller sends no hint (backward compatible). + operations keep the full budget; falls back to ``timeout`` when the + caller sends no hint. """ if client_timeout is None: return self.settings.timeout @@ -625,8 +614,6 @@ async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Option # bytearray grows in place, where `bytes +=` copies. buf = bytearray() response = None - # Monotonic: a duration must not be measured against a clock - # that can step backwards under NTP. recv_start = time.monotonic() while True: newdata = await reader.read(SPDK_RECV_SIZE) @@ -696,9 +683,8 @@ def create_app(settings: ProxySettings) -> FastAPI: """Build the proxy application. Startup blocks until SPDK answers on its unix socket. uvicorn runs the - lifespan before it binds the listening socket, so — as with the - ``HTTPServer`` this replaced — the port stays closed until SPDK is up, - rather than accepting requests that could only fail. + lifespan before it binds the listening socket, so the port stays closed + until SPDK is up, rather than accepting requests that could only fail. """ proxy = SpdkProxy(settings) @@ -723,10 +709,7 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: # themselves: `expose` forwards kwargs to the route decorator. # Ungrouped status codes: the default folds every client-side rejection # into one `4xx` series, which cannot tell a malformed body (400) from bad - # credentials (401). Only a handful of codes are reachable here, so the - # cardinality is negligible. `spdk_proxy_rpc_failures_total` deliberately - # does not duplicate any of this -- it exists for what a status code cannot - # say, namely which SPDK method failed and why a 500 was a 500. + # credentials (401), and only a handful of codes are reachable here. Instrumentator( registry=proxy.metrics.registry, should_group_status_codes=False, @@ -764,8 +747,6 @@ async def rpc(request: Request) -> Response: return Response(status_code=500) except OSError as e: # SPDK is gone (crashed, or never came back after a restart). - # The pre-FastAPI server let this escape the handler and dropped - # the connection; a 500 says the same thing legibly. logger.error(f"Could not reach SPDK on {proxy.settings.rpc_sock}: {e}") return Response(status_code=500) @@ -805,7 +786,7 @@ def main() -> None: host=settings.server_ip, port=settings.rpc_port, log_level='info', - # Replaced by AccessLogMiddleware, not dropped. + # uvicorn's access log would duplicate AccessLogMiddleware. access_log=False, limit_concurrency=settings.max_concurrent_connections, timeout_keep_alive=settings.keepalive_timeout, diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index 33838ccc9c..d7f652f516 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -31,10 +31,6 @@ from simplyblock_core.services.spdk_http_proxy_server import ProxySettings, create_app -# --------------------------------------------------------------------------- -# Mock SPDK unix socket server -# --------------------------------------------------------------------------- - class MockSPDKHandler(socketserver.BaseRequestHandler): """Handles JSON-RPC 2.0 over a unix socket, mimicking SPDK.""" @@ -106,10 +102,6 @@ def mock_spdk(sock_path, **kwargs): os.unlink(sock_path) -# --------------------------------------------------------------------------- -# Proxy under test -# --------------------------------------------------------------------------- - def _free_port(): with socket.socket() as s: s.bind(("127.0.0.1", 0)) @@ -250,8 +242,6 @@ def test_malformed_body_returns_400(self): self.assertEqual(response.status_code, 400) def test_keep_alive_serves_several_requests_on_one_connection(self): - """The HTTP/1.0 server this replaced closed after every response, so - every RPC paid for a fresh TCP connection.""" body = json.dumps({"id": 1, "method": "spdk_get_version"}) headers = {"Authorization": "Basic " + base64.b64encode(b"test:test").decode("ascii")} @@ -266,7 +256,7 @@ def test_keep_alive_serves_several_requests_on_one_connection(self): def test_unauthorized_request_does_not_corrupt_the_connection(self): """A rejected request leaves its body unread; on a kept-alive - connection that body used to be parsed as the next request.""" + connection it must not be parsed as the next request.""" with requests.Session() as session: rejected = self._proxy.post( "spdk_get_version", auth=("wrong", "creds"), session=session) diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index f60fbeac3e..c3ff7a95fd 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -463,7 +463,6 @@ async def test_concurrency_is_capped_at_max_concurrent_spdk(self): self.assertEqual(await self._run_concurrently(proxy, 12), 4) async def test_without_multi_threading_rpcs_are_serialized(self): - # The pre-FastAPI server ran on a non-threading HTTPServer in this mode. proxy = make_proxy(max_concurrent_spdk=4, multi_threading_enabled=False) self.assertEqual(await self._run_concurrently(proxy, 12), 1) @@ -563,8 +562,8 @@ def test_malformed_request_body_gets_400(self): self.assertEqual(response.status_code, 400) def test_json_body_without_a_method_gets_400(self): - """Valid JSON that is not a JSON-RPC request used to raise KeyError out - of the handler, bypassing the error path and the failure counter.""" + """Valid JSON without a ``method`` never reaches SPDK, so it belongs on + the 400 path and its failure counter, not on the 500 one.""" response = self.client.post( "/", content=json.dumps({"id": 1}), auth=("test", "secret")) From 19ccd5509149f7fe2ccb6a3574adaa1a9fce7b4f Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:41:39 +0200 Subject: [PATCH 16/22] Adapt stale comment --- simplyblock_core/services/spdk_http_proxy_server.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index b16b1b1666..5d16df3541 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -425,9 +425,9 @@ class InvalidRequest(Exception): """The request body is not a JSON-RPC request object. A caller-side fault, kept distinct from the ``ValueError`` a failed SPDK - round-trip raises: nothing was sent to SPDK, so it earns a 400 and a - ``bad_request`` failure rather than a 500 that would read as "SPDK is - broken" on a status-code or failure-rate dashboard. + round-trip raises: nothing was sent to SPDK, so it earns a 400 rather + than a 500 that would read as "SPDK is broken" on a status-code + dashboard. """ From 343de9c8270c7b3118da1ef5004fb308ca42bc9c Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 16:50:00 +0200 Subject: [PATCH 17/22] Consistently handle absent responses from SPDK --- .../services/spdk_http_proxy_server.py | 6 +++-- tests/unit/test_spdk_proxy_unit.py | 24 +++++++++++++++++++ 2 files changed, 28 insertions(+), 2 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 5d16df3541..d8e9578ec5 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -628,8 +628,10 @@ async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Option break self.metrics.observe_response(log.rpc_method, time.monotonic() - recv_start) - if not response and len(buf) > 0: - raise ValueError('Invalid response') + if not response: + raise ValueError( + 'Invalid response' if buf + else 'SPDK closed the connection without responding') return buf.decode('ascii') finally: diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index c3ff7a95fd..d7f55da1a8 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -342,6 +342,18 @@ async def test_truncated_response_is_rejected(self): self.assertEqual(self.proxy.open_connections, 0) + async def test_close_without_a_response_is_rejected(self): + """SPDK dying mid-RPC leaves an empty buffer, which is not an answer.""" + fake = FakeSpdkSocket([]) + + with patch_connect(fake): + with self.assertRaises(ValueError) as ctx: + await self.proxy.rpc_call(self.req) + + self.assertIn("closed the connection", str(ctx.exception)) + self.assertTrue(fake.writers[0].closed) + self.assertEqual(self.proxy.open_connections, 0) + async def test_caller_timeout_bounds_the_socket_wait(self): fake = FakeSpdkSocket([rpc_response(result=True)]) proxy = make_proxy(timeout=300, spdk_timeout_margin=2) @@ -1010,6 +1022,18 @@ async def test_a_malformed_request_is_not_counted_as_an_spdk_failure(self): self.assertIsNone(self._value("spdk_proxy_rpc_failures_total")) self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + async def test_close_without_a_response_is_counted_as_a_failure(self): + with patch_connect(FakeSpdkSocket([])): + with self.assertRaises(ValueError): + await self.proxy.rpc_call(self.req) + + self.assertEqual( + self._value( + "spdk_proxy_rpc_failures_total", + method="bdev_get_bdevs", reason="invalid_response"), 1) + self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) + async def test_unreachable_spdk_is_counted_as_a_failure(self): with patch_connect(FakeSpdkSocket(ConnectionRefusedError("refused"))): with self.assertRaises(ConnectionRefusedError): From c9f0a75e0b91ec6aa1cd60bfdec43b96447552e9 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 17:04:12 +0200 Subject: [PATCH 18/22] fix(secrets): avoid leakage on DHCHAP key material --- .../controllers/backup_controller.py | 4 +- simplyblock_core/controllers/host_auth.py | 10 ++- simplyblock_core/snode_client.py | 2 +- tests/unit/test_client_secret_logging.py | 64 +++++++++++++++++++ 4 files changed, 75 insertions(+), 5 deletions(-) diff --git a/simplyblock_core/controllers/backup_controller.py b/simplyblock_core/controllers/backup_controller.py index 83ee41ef8e..4c52074482 100644 --- a/simplyblock_core/controllers/backup_controller.py +++ b/simplyblock_core/controllers/backup_controller.py @@ -465,7 +465,9 @@ def restore_backup(backup_id: str, lvol_name: str, pool_id_or_name: str, else: crypto_key = None - logger.info(f"Backup allowed hosts: {backup.allowed_hosts}") + logger.info("Backup allowed hosts: %s", + [h["nqn"] if isinstance(h, dict) else h + for h in (backup.allowed_hosts or [])]) lvol_id, error = lvol_controller.add_lvol_ha( name=lvol_name, size=size, diff --git a/simplyblock_core/controllers/host_auth.py b/simplyblock_core/controllers/host_auth.py index 1862094e78..c3473d7787 100644 --- a/simplyblock_core/controllers/host_auth.py +++ b/simplyblock_core/controllers/host_auth.py @@ -1,4 +1,6 @@ # coding=utf-8 +from pydantic import SecretStr + from simplyblock_core import constants, utils from simplyblock_core.db_controller import DBController @@ -36,8 +38,8 @@ def _register_pool_dhchap_keys_on_node(pool, snode, rpc_client): key_names = {} for key_type, key_value in ( - ("dhchap_key", pool.dhchap_key.get_secret_value()), - ("dhchap_ctrlr_key", pool.dhchap_ctrlr_key.get_secret_value()), + ("dhchap_key", pool.dhchap_key), + ("dhchap_ctrlr_key", pool.dhchap_ctrlr_key), ): if not key_value: continue @@ -79,7 +81,9 @@ def _register_dhchap_keys_on_node(snode, host_nqn, host_entry, rpc_client): if not key_value: continue key_name = f"{key_type}_{safe_host}" - result, error = snode_api.write_key_file(key_name, key_value) + # allowed_hosts is a list of plain dicts, so the key material arrives + # untyped; wrap it here or it reaches SNodeClient's request log in clear. + result, error = snode_api.write_key_file(key_name, SecretStr(key_value)) if error: logger.error("Failed to write key file %s on node %s: %s", key_name, snode.get_id(), error) continue diff --git a/simplyblock_core/snode_client.py b/simplyblock_core/snode_client.py index cad51daa86..aa17573ecd 100644 --- a/simplyblock_core/snode_client.py +++ b/simplyblock_core/snode_client.py @@ -114,7 +114,7 @@ def is_live(self): def info(self): return self._request("GET", "info") - def write_key_file(self, name, content): + def write_key_file(self, name, content: SecretStr): """Write a DHCHAP key file on the storage node for SPDK keyring.""" return self._request("POST", "write_key_file", {"name": name, "content": content}) diff --git a/tests/unit/test_client_secret_logging.py b/tests/unit/test_client_secret_logging.py index 9b59c071de..11aa3beca9 100644 --- a/tests/unit/test_client_secret_logging.py +++ b/tests/unit/test_client_secret_logging.py @@ -164,3 +164,67 @@ def test_snode_response_body_hidden_when_flag_off(snode_client, caplog, monkeypa with caplog.at_level(logging.DEBUG): snode_client._request("GET", "info") assert "RESPVAL" not in _captured_logs_text(caplog) + + +def test_snode_write_key_file_masks_pool_key(snode_client, caplog): + """The pool path passes the model's ``SecretStr`` through rather than unwrapping it.""" + from simplyblock_core.controllers import host_auth + + pool = MagicMock() + pool.get_id.return_value = "pool-1" + pool.dhchap_key = SecretStr("DHHC-1:00:POOLKEY:") + pool.dhchap_ctrlr_key = SecretStr("") + + snode = MagicMock() + snode.get_id.return_value = "node-1" + snode.client.return_value = snode_client + snode_client._fake_session.request.return_value = _make_json_response( + {"results": "/etc/simplyblock/dhchap/pool_key"}) + + rpc_client = MagicMock() + rpc_client._request2.return_value = ({"ok": True}, None) + + with caplog.at_level(logging.DEBUG): + key_names = host_auth._register_pool_dhchap_keys_on_node(pool, snode, rpc_client) + + assert key_names == {"dhchap_key": "pool_pool_1_dhchap_key"} + + posted_body = snode_client._fake_session.request.call_args.kwargs["data"] + assert json.loads(posted_body)["content"] == "DHHC-1:00:POOLKEY:" + + logs = _captured_logs_text(caplog) + assert "POOLKEY" not in logs + assert "pool_pool_1_dhchap_key" in logs + + +def test_snode_write_key_file_masks_per_host_key(snode_client, caplog): + """The per-host path reads key material out of ``lvol.allowed_hosts``, a list of + plain dicts, so nothing wraps it for us — ``host_auth`` has to.""" + from simplyblock_core.controllers import host_auth + + snode = MagicMock() + snode.get_id.return_value = "node-1" + snode.client.return_value = snode_client + snode_client._fake_session.request.return_value = _make_json_response( + {"results": "/etc/simplyblock/dhchap/host_key"}) + + rpc_client = MagicMock() + rpc_client._request2.return_value = ({"ok": True}, None) + + with caplog.at_level(logging.DEBUG): + key_names = host_auth._register_dhchap_keys_on_node( + snode, "nqn.2014-08.org.nvmexpress:uuid:host1", + {"dhchap_key": "DHHC-1:00:HOSTKEY:", "psk": "NVMeTLSkey-1:01:PSKPLAIN:"}, + rpc_client, + ) + + assert set(key_names) == {"dhchap_key", "psk"} + + posted = [json.loads(call.kwargs["data"]) + for call in snode_client._fake_session.request.call_args_list] + assert {entry["content"] for entry in posted} == { + "DHHC-1:00:HOSTKEY:", "NVMeTLSkey-1:01:PSKPLAIN:"} + + logs = _captured_logs_text(caplog) + assert "HOSTKEY" not in logs + assert "PSKPLAIN" not in logs From e6dfbe186ad23e7fc5bd1156dcced04cc8c5f991 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 17:12:58 +0200 Subject: [PATCH 19/22] Remove redundant counter of open connections --- .../services/spdk_http_proxy_server.py | 16 +++++--- tests/integration/test_spdk_proxy_e2e.py | 13 ++++--- tests/unit/test_spdk_proxy_unit.py | 39 +++++++++++-------- 3 files changed, 40 insertions(+), 28 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index d8e9578ec5..0d967c8ebe 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -338,6 +338,11 @@ def __init__(self) -> None: 'Unix-socket connections currently open towards SPDK', registry=self.registry, ) + self.requests_in_flight = Gauge( + 'spdk_proxy_requests_in_flight', + 'HTTP requests currently being served', + registry=self.registry, + ) self.failures = Counter( 'spdk_proxy_rpc_failures_total', 'RPCs that reached SPDK and did not come back', @@ -449,8 +454,6 @@ class SpdkProxy: def __init__(self, settings: ProxySettings) -> None: self.settings = settings - self.active_requests = 0 - self.open_connections = 0 self.metrics = ProxyMetrics() self.concurrency_limit = ( settings.max_concurrent_spdk if settings.multi_threading_enabled else 1) @@ -600,7 +603,6 @@ async def _rpc_call_inner( raise async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Optional[str]: - self.open_connections += 1 self.metrics.unix_connections.inc() try: reader, writer = await asyncio.open_unix_connection(self.settings.rpc_sock) @@ -637,7 +639,6 @@ async def _exchange(self, req: bytes, req_data: dict, log: RequestLog) -> Option finally: _close(writer) finally: - self.open_connections -= 1 self.metrics.unix_connections.dec() @@ -712,9 +713,12 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: # Ungrouped status codes: the default folds every client-side rejection # into one `4xx` series, which cannot tell a malformed body (400) from bad # credentials (401), and only a handful of codes are reachable here. + # Scrapes are excluded for the same reason the access log skips them: they + # are not traffic, and counting them makes every rate include the scraper. Instrumentator( registry=proxy.metrics.registry, should_group_status_codes=False, + excluded_handlers=[METRICS_ENDPOINT], ).instrument(app).expose( app, endpoint=METRICS_ENDPOINT, @@ -727,7 +731,7 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: @app.post('/{path:path}', dependencies=[Depends(require_authorization)]) async def rpc(request: Request) -> Response: log: RequestLog = request.state.request_log - proxy.active_requests += 1 + proxy.metrics.requests_in_flight.inc() try: read_start = time.monotonic() try: @@ -757,7 +761,7 @@ async def rpc(request: Request) -> Response: return Response(content=response, media_type='application/json') finally: - proxy.active_requests -= 1 + proxy.metrics.requests_in_flight.dec() return app diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index d7f652f516..291b784bd2 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -148,6 +148,9 @@ def wait_until_serving(self, timeout=15): except RetryError: return False + def metric(self, name, **labels): + return self.proxy.metrics.registry.get_sample_value(name, labels or None) + def is_refusing_connections(self): try: requests.post(self.url, data="{}", timeout=2) @@ -271,8 +274,8 @@ def test_no_socket_leak_after_requests(self): for _ in range(5): self._proxy.post("spdk_get_version") - self.assertEqual(self._proxy.proxy.open_connections, 0) - self.assertEqual(self._proxy.proxy.active_requests, 0) + self.assertEqual(self._proxy.metric("spdk_proxy_unix_connections_open"), 0) + self.assertEqual(self._proxy.metric("spdk_proxy_requests_in_flight"), 0) def test_concurrent_requests(self): results = [] @@ -292,7 +295,7 @@ def do_request(): self.assertEqual(errors, []) self.assertEqual(results, [200] * 8) - self.assertEqual(self._proxy.proxy.open_connections, 0) + self.assertEqual(self._proxy.metric("spdk_proxy_unix_connections_open"), 0) class TestProxyReadinessGate(unittest.TestCase): @@ -305,7 +308,7 @@ def test_port_stays_closed_until_spdk_answers(self): with mock_spdk(path): self.assertTrue(proxy.wait_until_serving()) - self.assertEqual(proxy.proxy.open_connections, 0) + self.assertEqual(proxy.metric("spdk_proxy_unix_connections_open"), 0) class TestProxyTimeout(unittest.TestCase): @@ -324,7 +327,7 @@ def test_caller_timeout_bounds_the_spdk_wait(self): self.assertEqual(response.status_code, 500) self.assertLess(elapsed, 1) - self.assertEqual(proxy.proxy.open_connections, 0) + self.assertEqual(proxy.metric("spdk_proxy_unix_connections_open"), 0) if __name__ == "__main__": diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index d7f55da1a8..63f30c1a23 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -59,6 +59,13 @@ def make_proxy(**overrides) -> proxy_mod.SpdkProxy: return proxy_mod.SpdkProxy(make_settings(**overrides)) +class MetricsReader: + """Reads samples out of the registry of the test's ``self.proxy``.""" + + def _value(self, metric, **labels): + return self.proxy.metrics.registry.get_sample_value(metric, labels or None) + + class FakeReader: def __init__(self, chunks): self._chunks = list(chunks) @@ -271,7 +278,7 @@ async def test_socket_closed_when_probe_gets_no_answer(self): self.assertEqual(fake.attempt_count, 2) -class TestRpcCall(unittest.IsolatedAsyncioTestCase): +class TestRpcCall(MetricsReader, unittest.IsolatedAsyncioTestCase): """Every RPC must give its unix socket back, whichever way it ends.""" def setUp(self): @@ -288,7 +295,7 @@ async def test_response_is_returned_verbatim(self): self.assertEqual(result, payload.decode("ascii")) self.assertEqual(fake.writers[0].buffer, self.req) self.assertTrue(fake.writers[0].closed) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_chunked_response_is_reassembled(self): payload = rpc_response(result={"a": 1, "b": 2}) @@ -311,7 +318,7 @@ async def never_answers(*args, **kwargs): self.assertIn("timeout", str(ctx.exception)) self.assertTrue(fake.writers[0].closed) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_socket_released_on_connect_error(self): fake = FakeSpdkSocket(ConnectionRefusedError("refused")) @@ -320,7 +327,7 @@ async def test_socket_released_on_connect_error(self): with self.assertRaises(ConnectionRefusedError): await self.proxy.rpc_call(self.req) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_request_without_id_gets_no_response(self): req = json.dumps({"method": "notification_only"}).encode("ascii") @@ -331,7 +338,7 @@ async def test_request_without_id_gets_no_response(self): self.assertIsNone(result) self.assertTrue(fake.writers[0].closed) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_truncated_response_is_rejected(self): fake = FakeSpdkSocket([b'{"jsonrpc": "2.0", "id"']) @@ -340,7 +347,7 @@ async def test_truncated_response_is_rejected(self): with self.assertRaises(ValueError): await self.proxy.rpc_call(self.req) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_close_without_a_response_is_rejected(self): """SPDK dying mid-RPC leaves an empty buffer, which is not an answer.""" @@ -352,7 +359,7 @@ async def test_close_without_a_response_is_rejected(self): self.assertIn("closed the connection", str(ctx.exception)) self.assertTrue(fake.writers[0].closed) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_caller_timeout_bounds_the_socket_wait(self): fake = FakeSpdkSocket([rpc_response(result=True)]) @@ -489,7 +496,7 @@ async def test_slot_released_on_exception(self): self.assertFalse(proxy.slots.locked()) -class TestEndpoint(unittest.TestCase): +class TestEndpoint(MetricsReader, unittest.TestCase): """HTTP contract seen by ``simplyblock_core.rpc_client.RPCClient``.""" def setUp(self): @@ -615,13 +622,13 @@ def test_in_flight_count_returns_to_zero(self): for _ in range(3): self._post() - self.assertEqual(self.proxy.active_requests, 0) + self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) def test_in_flight_count_returns_to_zero_after_failure(self): with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): self._post() - self.assertEqual(self.proxy.active_requests, 0) + self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) class TestAccessLog(unittest.TestCase): @@ -707,7 +714,7 @@ def test_scrapes_are_not_logged(self): self.assertEqual(records, []) -class TestClientDisconnect(unittest.IsolatedAsyncioTestCase): +class TestClientDisconnect(MetricsReader, unittest.IsolatedAsyncioTestCase): """A caller that vanishes mid-request must not cost anything. Driven as a raw ASGI call: ``TestClient`` always delivers a complete body, @@ -760,8 +767,8 @@ async def test_disconnect_reaches_neither_spdk_nor_a_concurrency_slot(self): await self._disconnect_before_body() rpc_call.assert_not_called() - self.assertEqual(self.proxy.active_requests, 0) - self.assertEqual(self.proxy.open_connections, 0) + self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) + self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) self.assertEqual( self.proxy.metrics.registry.get_sample_value("spdk_proxy_rpc_slots_in_use"), 0) @@ -925,6 +932,7 @@ def test_metrics_are_served_to_an_authorized_caller(self): self.assertIn("spdk_proxy_body_read_duration_seconds", response.text) self.assertIn("spdk_proxy_rpc_slots_in_use", response.text) self.assertIn("spdk_proxy_unix_connections_open", response.text) + self.assertIn("spdk_proxy_requests_in_flight", response.text) def test_observations_reach_the_exposition(self): self.proxy.metrics.observe_response("bdev_get_bdevs", 0.25) @@ -971,16 +979,13 @@ def test_two_apps_keep_separate_metrics(self): self.assertNotIn('method="only_in_the_first"', theirs) -class TestMetricsObservation(unittest.IsolatedAsyncioTestCase): +class TestMetricsObservation(MetricsReader, unittest.IsolatedAsyncioTestCase): """The gauges and counters have to settle back after every RPC.""" def setUp(self): self.proxy = make_proxy() self.req = json.dumps({"id": 1, "method": "bdev_get_bdevs"}).encode("ascii") - def _value(self, metric, **labels): - return self.proxy.metrics.registry.get_sample_value(metric, labels or None) - async def test_gauges_return_to_zero_after_a_successful_rpc(self): fake = FakeSpdkSocket([rpc_response(result=True)]) From c601dab74ee4648f2c1e22dbc64762d8ea78f180 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 17:25:55 +0200 Subject: [PATCH 20/22] Remove complexity of custom metrics --- .../services/spdk_http_proxy_server.py | 144 +++++------------- tests/unit/test_spdk_proxy_unit.py | 55 ++----- 2 files changed, 50 insertions(+), 149 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 0d967c8ebe..1583f289f5 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -171,133 +171,61 @@ def authorization(self) -> str: return 'Basic ' + base64.b64encode(credentials.encode('ascii')).decode('ascii') -#: ``(count, sum)`` per ``method`` label, and cumulative bucket counts by -#: upper bound, as read back off a histogram. -HistogramSnapshot = Tuple[Dict[str, Tuple[float, float]], Dict[float, float]] - - -def _histogram_snapshot(histogram: Histogram) -> HistogramSnapshot: - """Read a histogram's own totals back out of its samples.""" - per_method: Dict[str, Tuple[float, float]] = {} - buckets: Dict[float, float] = {} - for metric in histogram.collect(): - for sample in metric.samples: - method = sample.labels.get('method', '') - count, total = per_method.get(method, (0.0, 0.0)) - if sample.name.endswith('_bucket'): - bound = float(sample.labels['le']) - buckets[bound] = buckets.get(bound, 0.0) + sample.value - elif sample.name.endswith('_count'): - per_method[method] = (count + sample.value, total) - elif sample.name.endswith('_sum'): - per_method[method] = (count, total + sample.value) - return per_method, buckets - - -def _bucket_quantile(buckets: Dict[float, float], quantile: float) -> Optional[float]: - """Upper bound of the bucket a quantile falls into. - - Buckets are cumulative, and the difference of two cumulative readings is - itself cumulative, so this works unchanged on an interval delta. - """ - if not buckets: - return None - ordered = sorted(buckets.items()) - total = ordered[-1][1] - if total <= 0: - return None - target = total * quantile - for bound, cumulative in ordered: - if cumulative >= target: - return bound - return ordered[-1][0] - - def _format_seconds(seconds: float) -> str: return f"{seconds * 1000:.1f}ms" if seconds < 1 else f"{seconds:.2f}s" -def _format_quantile(buckets: Dict[float, float], seconds: Optional[float]) -> str: - """Render a quantile as the comparison it actually is. - - A histogram resolves a quantile only to a bucket bound, so the figure can - exceed the largest duration actually observed. Spelling the bound as - ``<=`` keeps that from reading as ``p99 > max``, which is otherwise the - obvious conclusion when both sit on the same line. - """ - if seconds is None: - return '=-' - if not math.isinf(seconds): - return f"<={_format_seconds(seconds)}" - finite = [bound for bound in buckets if not math.isinf(bound)] - return f">{_format_seconds(max(finite))}" if finite else '=inf' - - class IntervalReport: """The periodic log line for one histogram. - Everything reported comes from the histogram itself, so the log and the - Prometheus exposition can never disagree. Histograms are cumulative, so - interval figures are the difference between successive reads. + Totals are kept here rather than derived from the histogram's own + samples: both are fed by the single ``observe`` below, and count, sum and + peak are cheaper to accumulate than to read back out of cumulative + buckets. Every figure covers the interval since the last report. - The exception is ``max``: a histogram knows only bucket boundaries, and - the Python client's Summary carries no quantiles, so the peak is kept here - as a plain float and reset every tick. Deliberately not a Gauge -- a gauge - reset every few seconds sawtooths and reads badly in Prometheus. + ``max`` stays out of the exposition entirely: a gauge reset every few + seconds sawtooths and reads badly in Prometheus. """ def __init__(self, name: str, histogram: Histogram) -> None: self.name = name self.histogram = histogram - self._prev_methods: Dict[str, Tuple[float, float]] = {} - self._prev_buckets: Dict[float, float] = {} - self._peak_seconds = 0.0 + self._count = 0 + self._total = 0.0 + self._peak = 0.0 + self._methods: Dict[str, Tuple[int, float]] = {} def observe(self, seconds: float, method: Optional[str] = None) -> None: target = self.histogram if method is None else self.histogram.labels(method=method) target.observe(seconds) - self._peak_seconds = max(self._peak_seconds, seconds) - - def _slowest_method(self, methods: Dict[str, Tuple[float, float]]) -> Optional[str]: - """The method with the highest mean duration over the interval.""" - slowest, slowest_mean = None, 0.0 - for method, (count, total) in methods.items(): - prev_count, prev_total = self._prev_methods.get(method, (0.0, 0.0)) - if (advanced := count - prev_count) <= 0: - continue - if (mean := (total - prev_total) / advanced) > slowest_mean: - slowest, slowest_mean = method, mean - return slowest or None + + self._count += 1 + self._total += seconds + self._peak = max(self._peak, seconds) + if method is not None: + count, total = self._methods.get(method, (0, 0.0)) + self._methods[method] = (count + 1, total + seconds) def report(self) -> Optional[str]: """Summarize the interval, or ``None`` if nothing was observed in it.""" - methods, buckets = _histogram_snapshot(self.histogram) - advanced = ( - sum(count for count, _ in methods.values()) - - sum(count for count, _ in self._prev_methods.values()) - ) - elapsed = ( - sum(total for _, total in methods.values()) - - sum(total for _, total in self._prev_methods.values()) - ) - interval_buckets = { - bound: value - self._prev_buckets.get(bound, 0.0) - for bound, value in buckets.items() - } - peak, slowest = self._peak_seconds, self._slowest_method(methods) + count, total, peak = self._count, self._total, self._peak + methods = self._methods + self._count, self._total, self._peak = 0, 0.0, 0.0 + self._methods = {} - self._prev_methods, self._prev_buckets = methods, buckets - self._peak_seconds = 0.0 - - if advanced <= 0: + if count <= 0: return None + slowest = max( + methods, + key=lambda method: methods[method][1] / methods[method][0], + default=None, + ) summary = ( f"{self.name}:" - f" interval_avg={_format_seconds(elapsed / advanced)}" - f" p99{_format_quantile(interval_buckets, _bucket_quantile(interval_buckets, 0.99))}" + f" interval_avg={_format_seconds(total / count)}" f" max={_format_seconds(peak)}" - f" n={int(advanced)}" + f" n={count}" ) return summary if slowest is None else f"{summary} slowest={slowest}" @@ -475,18 +403,14 @@ def slots(self) -> asyncio.Semaphore: async def report_stats(self) -> None: """Log the interval timings every ``STATS_INTERVAL_SEC`` seconds. - Read off the same metrics the Prometheus endpoint serves, so the two - can never disagree. A series with no observations in the interval - logs nothing rather than repeating a stale summary. + A series with no observations in the interval logs nothing rather + than repeating a stale summary. """ while True: await asyncio.sleep(STATS_INTERVAL_SEC) - try: - for report in self.metrics.reports: - if (summary := report.report()) is not None: - logger.info("Periodic stats: %s", summary) - except (ValueError, KeyError, ZeroDivisionError) as e: - logger.error(f"Could not summarize proxy metrics: {e}") + for report in self.metrics.reports: + if (summary := report.report()) is not None: + logger.info("Periodic stats: %s", summary) async def wait_for_spdk_ready(self) -> None: """Block until SPDK responds to spdk_get_version on the unix socket.""" diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index 63f30c1a23..ca9db8b96a 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -774,17 +774,30 @@ async def test_disconnect_reaches_neither_spdk_nor_a_concurrency_slot(self): class TestIntervalReport(unittest.TestCase): - """The periodic log line, computed from a histogram's own totals.""" + """The periodic log line, and the histogram it observes alongside it.""" def setUp(self): - registry = CollectorRegistry() + self.registry = CollectorRegistry() self.report = proxy_mod.IntervalReport('spdk', Histogram( 'test_duration_seconds', 'test', ['method'], - buckets=(0.01, 0.1, 1, float("inf")), registry=registry)) + buckets=(0.01, 0.1, 1, float("inf")), registry=self.registry)) def test_first_tick_without_observations_reports_nothing(self): self.assertIsNone(self.report.report()) + def test_observations_reach_the_histogram_as_well_as_the_log_line(self): + self.report.observe(0.5, method="a") + self.report.report() + + # Reporting resets the log-line totals; the histogram is cumulative + # and must still carry the observation for the exposition. + self.assertEqual( + self.registry.get_sample_value( + 'test_duration_seconds_count', {'method': 'a'}), 1) + self.assertEqual( + self.registry.get_sample_value( + 'test_duration_seconds_sum', {'method': 'a'}), 0.5) + def test_interval_average_covers_only_the_new_observations(self): self.report.observe(1.0, method="a") self.report.report() @@ -835,26 +848,6 @@ def test_slowest_reflects_the_interval_not_history(self): self.report.observe(0.5, method="other") self.assertIn("slowest=other", self.report.report()) - def test_p99_lands_in_the_bucket_holding_the_tail(self): - for _ in range(95): - self.report.observe(0.005, method="a") - for _ in range(5): - self.report.observe(0.5, method="a") - - self.assertIn("p99<=1.00s", self.report.report()) - - def test_p99_ignores_a_tail_thinner_than_one_percent(self): - for _ in range(99): - self.report.observe(0.005, method="a") - self.report.observe(0.5, method="a") - - self.assertIn("p99<=10.0ms", self.report.report()) - - def test_p99_beyond_the_last_finite_bucket_is_marked_open_ended(self): - self.report.observe(30.0, method="a") - - self.assertIn("p99>1.00s", self.report.report()) - def test_unlabelled_histogram_reports_without_a_slowest_field(self): registry = CollectorRegistry() report = proxy_mod.IntervalReport('body', Histogram( @@ -867,22 +860,6 @@ def test_unlabelled_histogram_reports_without_a_slowest_field(self): self.assertNotIn("slowest=", summary) -class TestBucketQuantile(unittest.TestCase): - - def test_empty_buckets_have_no_quantile(self): - self.assertIsNone(proxy_mod._bucket_quantile({}, 0.99)) - - def test_all_zero_buckets_have_no_quantile(self): - self.assertIsNone(proxy_mod._bucket_quantile({0.1: 0.0, float("inf"): 0.0}, 0.99)) - - def test_quantile_is_the_bound_of_the_bucket_it_falls_in(self): - buckets = {0.1: 90.0, 1.0: 99.0, float("inf"): 100.0} - - self.assertEqual(proxy_mod._bucket_quantile(buckets, 0.5), 0.1) - self.assertEqual(proxy_mod._bucket_quantile(buckets, 0.99), 1.0) - self.assertEqual(proxy_mod._bucket_quantile(buckets, 1.0), float("inf")) - - class TestMethodLabelCardinality(unittest.TestCase): """The method label is caller-supplied, so its value set must be bounded.""" From 7f0135b5a4aa4ff6dfc09c8d7930eee469f06dcb Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Thu, 3 Sep 2026 17:51:52 +0200 Subject: [PATCH 21/22] Simplify metrics --- .../services/spdk_http_proxy_server.py | 134 ++++++++---------- tests/integration/test_spdk_proxy_e2e.py | 21 ++- tests/unit/test_spdk_proxy_unit.py | 123 ++++++++++------ 3 files changed, 160 insertions(+), 118 deletions(-) diff --git a/simplyblock_core/services/spdk_http_proxy_server.py b/simplyblock_core/services/spdk_http_proxy_server.py index 1583f289f5..32d5ef7c60 100644 --- a/simplyblock_core/services/spdk_http_proxy_server.py +++ b/simplyblock_core/services/spdk_http_proxy_server.py @@ -26,7 +26,7 @@ import uvicorn from fastapi import Depends, FastAPI, HTTPException, Request, Response -from prometheus_client import CollectorRegistry, Counter, Gauge, Histogram +from prometheus_client import Counter, Gauge, Histogram from prometheus_fastapi_instrumentator import Instrumentator from pydantic import BeforeValidator, Field, SecretStr from pydantic_settings import BaseSettings, SettingsConfigDict @@ -230,53 +230,49 @@ def report(self) -> Optional[str]: return summary if slowest is None else f"{summary} slowest={slowest}" +SPDK_RESPONSE_DURATION = Histogram( + 'spdk_proxy_response_duration_seconds', + 'Time awaiting and reading one JSON-RPC response from SPDK', + ['method'], + buckets=SPDK_DURATION_BUCKETS, +) +BODY_READ_DURATION = Histogram( + 'spdk_proxy_body_read_duration_seconds', + 'Time spent reading one HTTP request body', + buckets=BODY_READ_DURATION_BUCKETS, +) +RPC_SLOTS_IN_USE = Gauge( + 'spdk_proxy_rpc_slots_in_use', + 'SPDK concurrency slots currently held', +) +UNIX_CONNECTIONS_OPEN = Gauge( + 'spdk_proxy_unix_connections_open', + 'Unix-socket connections currently open towards SPDK', +) +RPC_FAILURES = Counter( + 'spdk_proxy_rpc_failures_total', + 'RPCs that reached SPDK and did not come back', + ['method', 'reason'], +) + + class ProxyMetrics: - """Prometheus metrics for one proxy application. + """What one proxy accumulates on top of the module-level metrics. - Each application owns its registry rather than writing into the global - ``REGISTRY``. A storage node runs exactly one proxy per process so nothing - is lost, and the tests build several applications in one interpreter, - where module-level metrics would collide on the second ``create_app``. + Holds the interval reports and the seen-method set behind + ``method_label``; the metrics themselves live in the default registry, + which is also what ``Instrumentator`` and the standard process + collectors write into. """ def __init__(self) -> None: - self.registry = CollectorRegistry() self._known_methods: Set[str] = set() - self.spdk_response = IntervalReport('recv_from_spdk', Histogram( - 'spdk_proxy_response_duration_seconds', - 'Time awaiting and reading one JSON-RPC response from SPDK', - ['method'], - buckets=SPDK_DURATION_BUCKETS, - registry=self.registry, - )) - self.body_read = IntervalReport('read_body', Histogram( - 'spdk_proxy_body_read_duration_seconds', - 'Time spent reading one HTTP request body', - buckets=BODY_READ_DURATION_BUCKETS, - registry=self.registry, - )) - self.slots_in_use = Gauge( - 'spdk_proxy_rpc_slots_in_use', - 'SPDK concurrency slots currently held', - registry=self.registry, - ) - self.unix_connections = Gauge( - 'spdk_proxy_unix_connections_open', - 'Unix-socket connections currently open towards SPDK', - registry=self.registry, - ) - self.requests_in_flight = Gauge( - 'spdk_proxy_requests_in_flight', - 'HTTP requests currently being served', - registry=self.registry, - ) - self.failures = Counter( - 'spdk_proxy_rpc_failures_total', - 'RPCs that reached SPDK and did not come back', - ['method', 'reason'], - registry=self.registry, - ) + self.spdk_response = IntervalReport('recv_from_spdk', SPDK_RESPONSE_DURATION) + self.body_read = IntervalReport('read_body', BODY_READ_DURATION) + self.slots_in_use = RPC_SLOTS_IN_USE + self.unix_connections = UNIX_CONNECTIONS_OPEN + self.failures = RPC_FAILURES def method_label(self, method: str) -> str: """Fold a caller-supplied method name into the bounded label set.""" @@ -640,8 +636,8 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: # Scrapes are excluded for the same reason the access log skips them: they # are not traffic, and counting them makes every rate include the scraper. Instrumentator( - registry=proxy.metrics.registry, should_group_status_codes=False, + should_instrument_requests_inprogress=True, excluded_handlers=[METRICS_ENDPOINT], ).instrument(app).expose( app, @@ -655,37 +651,33 @@ async def lifespan(app: FastAPI) -> AsyncGenerator[None, None]: @app.post('/{path:path}', dependencies=[Depends(require_authorization)]) async def rpc(request: Request) -> Response: log: RequestLog = request.state.request_log - proxy.metrics.requests_in_flight.inc() + read_start = time.monotonic() try: - read_start = time.monotonic() - try: - body = await request.body() - except ClientDisconnect: - logger.warning( - "client disconnected before the request body arrived " - f"(request {log.request_id})") - return Response(status_code=400) - proxy.metrics.observe_body_read(time.monotonic() - read_start) + body = await request.body() + except ClientDisconnect: + logger.warning( + "client disconnected before the request body arrived " + f"(request {log.request_id})") + return Response(status_code=400) + proxy.metrics.observe_body_read(time.monotonic() - read_start) - try: - response = await proxy.rpc_call( - body, request.headers.get('X-RPC-Timeout'), log) - except InvalidRequest as e: - logger.warning(f"rejected a malformed request (request {log.request_id}): {e}") - return Response(status_code=400) - except ValueError: - return Response(status_code=500) - except OSError as e: - # SPDK is gone (crashed, or never came back after a restart). - logger.error(f"Could not reach SPDK on {proxy.settings.rpc_sock}: {e}") - return Response(status_code=500) - - if response is None: - return Response(status_code=204) - - return Response(content=response, media_type='application/json') - finally: - proxy.metrics.requests_in_flight.dec() + try: + response = await proxy.rpc_call( + body, request.headers.get('X-RPC-Timeout'), log) + except InvalidRequest as e: + logger.warning(f"rejected a malformed request (request {log.request_id}): {e}") + return Response(status_code=400) + except ValueError: + return Response(status_code=500) + except OSError as e: + # SPDK is gone (crashed, or never came back after a restart). + logger.error(f"Could not reach SPDK on {proxy.settings.rpc_sock}: {e}") + return Response(status_code=500) + + if response is None: + return Response(status_code=204) + + return Response(content=response, media_type='application/json') return app diff --git a/tests/integration/test_spdk_proxy_e2e.py b/tests/integration/test_spdk_proxy_e2e.py index 291b784bd2..4635de23d8 100644 --- a/tests/integration/test_spdk_proxy_e2e.py +++ b/tests/integration/test_spdk_proxy_e2e.py @@ -28,9 +28,24 @@ if sys.platform == "win32": raise unittest.SkipTest("AF_UNIX not available on Windows") +from prometheus_client import REGISTRY + from simplyblock_core.services.spdk_http_proxy_server import ProxySettings, create_app +def _create_app(settings): + """Build an app on a registry a previous one may already have written to. + + ``Instrumentator`` re-registers its metrics per application, which the + default registry only survives once; only tests build more than one. + """ + for name, collector in list(REGISTRY._names_to_collectors.items()): + if name.startswith("http_"): + with contextlib.suppress(KeyError): + REGISTRY.unregister(collector) + return create_app(settings) + + class MockSPDKHandler(socketserver.BaseRequestHandler): """Handles JSON-RPC 2.0 over a unix socket, mimicking SPDK.""" @@ -125,7 +140,7 @@ def __init__(self, sock_path, **overrides): }) self.address = ("127.0.0.1", settings.rpc_port) self.url = f"http://127.0.0.1:{settings.rpc_port}/" - app = create_app(settings) + app = _create_app(settings) self.proxy = app.state.proxy self._server = uvicorn.Server(uvicorn.Config( app=app, host=settings.server_ip, port=settings.rpc_port, log_level="warning")) @@ -149,7 +164,8 @@ def wait_until_serving(self, timeout=15): return False def metric(self, name, **labels): - return self.proxy.metrics.registry.get_sample_value(name, labels or None) + value = REGISTRY.get_sample_value(name, labels or None) + return 0.0 if value is None else value def is_refusing_connections(self): try: @@ -275,7 +291,6 @@ def test_no_socket_leak_after_requests(self): self._proxy.post("spdk_get_version") self.assertEqual(self._proxy.metric("spdk_proxy_unix_connections_open"), 0) - self.assertEqual(self._proxy.metric("spdk_proxy_requests_in_flight"), 0) def test_concurrent_requests(self): results = [] diff --git a/tests/unit/test_spdk_proxy_unit.py b/tests/unit/test_spdk_proxy_unit.py index ca9db8b96a..86ffd75ac0 100644 --- a/tests/unit/test_spdk_proxy_unit.py +++ b/tests/unit/test_spdk_proxy_unit.py @@ -15,7 +15,7 @@ from unittest.mock import AsyncMock, patch from fastapi.testclient import TestClient -from prometheus_client import CollectorRegistry, Histogram +from prometheus_client import REGISTRY, CollectorRegistry, Histogram from pydantic import ValidationError from simplyblock_core.services import spdk_http_proxy_server as proxy_mod @@ -59,11 +59,45 @@ def make_proxy(**overrides) -> proxy_mod.SpdkProxy: return proxy_mod.SpdkProxy(make_settings(**overrides)) +def make_app(**overrides) -> "proxy_mod.FastAPI": + """Build an app, first clearing what a previous one left in the registry. + + ``Instrumentator`` re-registers its metrics per application against the + default registry, which a process only survives once: the in-progress + gauge raises on the second app, and the rest are silently dropped, so a + later app would serve no ``http_*`` series at all. Only tests build more + than one, so they hand each a clean slate. + """ + for name, collector in list(REGISTRY._names_to_collectors.items()): + if name.startswith("http_"): + with contextlib.suppress(KeyError): + REGISTRY.unregister(collector) + return proxy_mod.create_app(make_settings(**overrides)) + + class MetricsReader: - """Reads samples out of the registry of the test's ``self.proxy``.""" + """Reads samples out of the default registry, which every app shares. + + Since the registry outlives each test, a count is only meaningful as the + change one action caused: ``_sample`` captures a series, and calling what + it returns gives the increment since. + """ def _value(self, metric, **labels): - return self.proxy.metrics.registry.get_sample_value(metric, labels or None) + """One series, or every series of ``metric`` summed if unlabelled.""" + if labels: + value = REGISTRY.get_sample_value(metric, labels) + return 0.0 if value is None else value + return sum( + sample.value + for family in REGISTRY.collect() + for sample in family.samples + if sample.name == metric + ) + + def _sample(self, metric, **labels): + before = self._value(metric, **labels) + return lambda: self._value(metric, **labels) - before class FakeReader: @@ -500,7 +534,7 @@ class TestEndpoint(MetricsReader, unittest.TestCase): """HTTP contract seen by ``simplyblock_core.rpc_client.RPCClient``.""" def setUp(self): - self.app = proxy_mod.create_app(make_settings()) + self.app = make_app() self.proxy = self.app.state.proxy # Lifespan (and with it the readiness gate) is deliberately not run: # TestClient only starts it when used as a context manager. @@ -549,7 +583,7 @@ def test_non_ascii_credentials_get_401(self): def test_credentials_are_scoped_to_the_app_that_serves_the_request(self): """The dependency resolves settings per request, so two apps built in one process do not accept each other's credentials.""" - other = proxy_mod.create_app(make_settings(rpc_password="other")) + other = make_app(rpc_password="other") with patch.object(other.state.proxy, 'rpc_call', new=AsyncMock(return_value=None)): accepted = TestClient(other).post( @@ -622,13 +656,13 @@ def test_in_flight_count_returns_to_zero(self): for _ in range(3): self._post() - self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) + self.assertEqual(self._value("http_requests_inprogress"), 0) def test_in_flight_count_returns_to_zero_after_failure(self): with patch.object(self.proxy, 'rpc_call', new=AsyncMock(side_effect=ValueError("bad"))): self._post() - self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) + self.assertEqual(self._value("http_requests_inprogress"), 0) class TestAccessLog(unittest.TestCase): @@ -640,7 +674,7 @@ class TestAccessLog(unittest.TestCase): """ def setUp(self): - self.app = proxy_mod.create_app(make_settings()) + self.app = make_app() self.proxy = self.app.state.proxy self.client = TestClient(self.app) self.body = json.dumps({"id": 1, "method": "bdev_get_bdevs"}) @@ -722,7 +756,7 @@ class TestClientDisconnect(MetricsReader, unittest.IsolatedAsyncioTestCase): """ def setUp(self): - self.app = proxy_mod.create_app(make_settings()) + self.app = make_app() self.proxy = self.app.state.proxy async def _disconnect_before_body(self): @@ -767,10 +801,10 @@ async def test_disconnect_reaches_neither_spdk_nor_a_concurrency_slot(self): await self._disconnect_before_body() rpc_call.assert_not_called() - self.assertEqual(self._value("spdk_proxy_requests_in_flight"), 0) + self.assertEqual(self._value("http_requests_inprogress"), 0) self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) self.assertEqual( - self.proxy.metrics.registry.get_sample_value("spdk_proxy_rpc_slots_in_use"), 0) + self._value("spdk_proxy_rpc_slots_in_use"), 0) class TestIntervalReport(unittest.TestCase): @@ -889,10 +923,10 @@ def test_absurdly_long_methods_collapse(self): self.assertEqual(self.metrics.method_label(overlong), proxy_mod.OTHER_METHOD_LABEL) -class TestMetricsEndpoint(unittest.TestCase): +class TestMetricsEndpoint(MetricsReader, unittest.TestCase): def setUp(self): - self.app = proxy_mod.create_app(make_settings()) + self.app = make_app() self.proxy = self.app.state.proxy self.client = TestClient(self.app) @@ -909,7 +943,8 @@ def test_metrics_are_served_to_an_authorized_caller(self): self.assertIn("spdk_proxy_body_read_duration_seconds", response.text) self.assertIn("spdk_proxy_rpc_slots_in_use", response.text) self.assertIn("spdk_proxy_unix_connections_open", response.text) - self.assertIn("spdk_proxy_requests_in_flight", response.text) + self.assertIn("http_requests_inprogress", response.text) + self.assertIn("process_open_fds", response.text) def test_observations_reach_the_exposition(self): self.proxy.metrics.observe_response("bdev_get_bdevs", 0.25) @@ -921,6 +956,13 @@ def test_observations_reach_the_exposition(self): def test_client_and_server_errors_are_separate_series(self): """Status codes are exposed ungrouped, so an operator can tell a malformed body from bad credentials from a broken SPDK.""" + before = { + status: self._value( + "http_requests_total", + handler="/{path:path}", method="POST", status=status) + for status in ("400", "401", "500") + } + self.client.post("/", content="not json", auth=("test", "secret")) self.client.post("/", content="not json", auth=("wrong", "creds")) with patch.object( @@ -930,9 +972,10 @@ def test_client_and_server_errors_are_separate_series(self): for status in ("400", "401", "500"): with self.subTest(status=status): self.assertEqual( - self.proxy.metrics.registry.get_sample_value( + self._value( "http_requests_total", - {"handler": "/{path:path}", "method": "POST", "status": status}), + handler="/{path:path}", method="POST", status=status) + - before[status], 1, ) @@ -941,20 +984,6 @@ def test_credentials_never_appear_in_the_exposition(self): self.assertNotIn("secret", response.text) - def test_two_apps_keep_separate_metrics(self): - """Each app owns its registry, so building a second one neither raises - nor lets observations bleed between them.""" - other = proxy_mod.create_app(make_settings(rpc_password="other")) - self.proxy.metrics.observe_response("only_in_the_first", 0.1) - - mine = self.client.get( - proxy_mod.METRICS_ENDPOINT, auth=("test", "secret")).text - theirs = TestClient(other).get( - proxy_mod.METRICS_ENDPOINT, auth=("test", "other")).text - - self.assertIn('method="only_in_the_first"', mine) - self.assertNotIn('method="only_in_the_first"', theirs) - class TestMetricsObservation(MetricsReader, unittest.IsolatedAsyncioTestCase): """The gauges and counters have to settle back after every RPC.""" @@ -974,57 +1003,63 @@ async def test_gauges_return_to_zero_after_a_successful_rpc(self): async def test_response_duration_is_recorded_against_the_method(self): fake = FakeSpdkSocket([rpc_response(result=True)]) + observed = self._sample( + "spdk_proxy_response_duration_seconds_count", method="bdev_get_bdevs") with patch_connect(fake): await self.proxy.rpc_call(self.req) - self.assertEqual( - self._value("spdk_proxy_response_duration_seconds_count", method="bdev_get_bdevs"), 1) + self.assertEqual(observed(), 1) async def test_timeout_is_counted_as_a_failure(self): async def never_answers(*args, **kwargs): await asyncio.sleep(3600) + failures = self._sample( + "spdk_proxy_rpc_failures_total", method="bdev_get_bdevs", reason="timeout") + with patch_connect(FakeSpdkSocket([])), patch.object( FakeReader, 'read', never_answers): with self.assertRaises(ValueError): await self.proxy.rpc_call(self.req, client_timeout="0.01") - self.assertEqual( - self._value( - "spdk_proxy_rpc_failures_total", method="bdev_get_bdevs", reason="timeout"), 1) + self.assertEqual(failures(), 1) self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) async def test_a_malformed_request_is_not_counted_as_an_spdk_failure(self): """The counter is about SPDK; a rejected body is the caller's fault and shows up as a 400 in ``http_requests_total``.""" + failures = self._sample("spdk_proxy_rpc_failures_total") + with self.assertRaises(proxy_mod.InvalidRequest): await self.proxy.rpc_call(b"not json") - self.assertIsNone(self._value("spdk_proxy_rpc_failures_total")) + self.assertEqual(failures(), 0) self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) async def test_close_without_a_response_is_counted_as_a_failure(self): + failures = self._sample( + "spdk_proxy_rpc_failures_total", + method="bdev_get_bdevs", reason="invalid_response") + with patch_connect(FakeSpdkSocket([])): with self.assertRaises(ValueError): await self.proxy.rpc_call(self.req) - self.assertEqual( - self._value( - "spdk_proxy_rpc_failures_total", - method="bdev_get_bdevs", reason="invalid_response"), 1) + self.assertEqual(failures(), 1) self.assertEqual(self._value("spdk_proxy_rpc_slots_in_use"), 0) self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) async def test_unreachable_spdk_is_counted_as_a_failure(self): + failures = self._sample( + "spdk_proxy_rpc_failures_total", + method="bdev_get_bdevs", reason="unreachable") + with patch_connect(FakeSpdkSocket(ConnectionRefusedError("refused"))): with self.assertRaises(ConnectionRefusedError): await self.proxy.rpc_call(self.req) - self.assertEqual( - self._value( - "spdk_proxy_rpc_failures_total", - method="bdev_get_bdevs", reason="unreachable"), 1) + self.assertEqual(failures(), 1) self.assertEqual(self._value("spdk_proxy_unix_connections_open"), 0) From 2154d5d83721f4b8f8f1579abcf57a077869a7f9 Mon Sep 17 00:00:00 2001 From: Max Schettler Date: Fri, 4 Sep 2026 01:05:27 +0200 Subject: [PATCH 22/22] tests: fix ftt2 sleep patching These broke tests that executed later and relied on sleep behaving as intended. --- tests/integration/ftt2/conftest.py | 24 +++++++- tests/integration/ftt2/test_hublvol_paths.py | 10 +--- .../ftt2/test_restart_concurrent_ops.py | 45 ++++---------- tests/integration/ftt2/test_restart_guards.py | 30 ++-------- .../ftt2/test_restart_peer_states.py | 5 +- .../ftt2/test_restart_scenarios.py | 15 +---- tests/integration/test_dual_ft_e2e.py | 58 +++++++++---------- 7 files changed, 70 insertions(+), 117 deletions(-) diff --git a/tests/integration/ftt2/conftest.py b/tests/integration/ftt2/conftest.py index f36a7e9483..22953deb9c 100644 --- a/tests/integration/ftt2/conftest.py +++ b/tests/integration/ftt2/conftest.py @@ -23,6 +23,7 @@ n3 out: LVS_0 no impact, LVS_3 pri down (TAKEOVER), LVS_2 sibling-sec down """ +import contextlib import os import time import uuid as _uuid_mod @@ -491,8 +492,23 @@ def _sync_defer_remaining_attaches(self, rpc, ctrl_name, nqn, port, remaining, def patch_externals(): - """Mock all external deps so restart runs purely against mock RPC servers.""" - return [ + """Mock all external deps so restart runs purely against mock RPC servers. + + Returns an already-started ``contextlib.ExitStack``; callers ``.close()`` + it when done (or use it as a context manager) instead of looping over + individual patchers. Several targets below are ``.time.sleep`` + for different modules that each did ``import time`` — those all alias the + one stdlib ``time`` module, so more than one patch here targets the exact + same global attribute. Starting and then stopping a plain list of patches + in the same (declaration) order is exactly backwards for aliased targets: + whichever patch on a shared attribute stops last "restores" it to the + previous patch's Mock, not the real function, permanently breaking + ``time.sleep`` for the rest of the test process. ExitStack always unwinds + LIFO regardless of where or when ``.close()`` runs, so this can't recur + even as patches are added. + """ + stack = contextlib.ExitStack() + for p in [ # Hublvol multipath: drop the coordinator's inter-attach sleeps and run # the deferred redundant-path attach synchronously so tests see the # fully-converged multipath state immediately after restart returns. @@ -586,4 +602,6 @@ def patch_externals(): return_value=1), patch('simplyblock_core.storage_node_ops.time.sleep'), patch('simplyblock_core.models.storage_node.time.sleep'), - ] + ]: + stack.enter_context(p) + return stack diff --git a/tests/integration/ftt2/test_hublvol_paths.py b/tests/integration/ftt2/test_hublvol_paths.py index 624c27b00d..10efa03d4d 100644 --- a/tests/integration/ftt2/test_hublvol_paths.py +++ b/tests/integration/ftt2/test_hublvol_paths.py @@ -78,8 +78,6 @@ def _run_restart(env, node_idx): node = env['nodes'][node_idx] db = env['db'] patches = patch_externals() - for p in patches: - p.start() try: snode = db.get_storage_node_by_id(node.uuid) snode.status = StorageNode.STATUS_RESTARTING @@ -91,8 +89,7 @@ def _run_restart(env, node_idx): snode.write_to_db(db.kv_store) return result finally: - for p in patches: - p.stop() + patches.close() def _get_set_opts_roles(env, server_idx): @@ -137,8 +134,6 @@ def _activate(self, ftt2_env): # attach run synchronously (production defers it to a daemon thread), so # the tertiary's second path is present when the tests inspect state. patches = patch_externals() - for p in patches: - p.start() try: # Step 1: primary creates hublvol n0.create_hublvol(cluster_nqn=cluster.nqn) @@ -152,8 +147,7 @@ def _activate(self, ftt2_env): # Step 3b: tertiary connects with 2 paths (primary + sec_1) n2.connect_to_hublvol(n0, failover_node=n1, role="tertiary") finally: - for p in patches: - p.stop() + patches.close() def test_primary_hublvol_optimized_ana(self): """Primary's hublvol listener must use ANA state = optimized.""" diff --git a/tests/integration/ftt2/test_restart_concurrent_ops.py b/tests/integration/ftt2/test_restart_concurrent_ops.py index 12219dc15f..eb07006190 100644 --- a/tests/integration/ftt2/test_restart_concurrent_ops.py +++ b/tests/integration/ftt2/test_restart_concurrent_ops.py @@ -285,8 +285,6 @@ def _run_restart_in_thread(env, node_idx=RESTART_NODE): """ result_holder = {"result": None, "node": None, "error": None} patches = patch_externals() - for p in patches: - p.start() def _do(): try: @@ -334,8 +332,7 @@ def test_delete_during_port_block(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in _patches: - p.stop() + _patches.close() auditor.assert_no_proceed_during_blocked() assert stress.total_ops >= stress.num_threads, ( @@ -357,8 +354,7 @@ def test_create_during_port_block(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in _patches: - p.stop() + _patches.close() auditor.assert_no_proceed_during_blocked() @@ -381,8 +377,7 @@ def test_resize_during_port_block(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in _patches: - p.stop() + _patches.close() auditor.assert_no_proceed_during_blocked() @@ -404,8 +399,7 @@ def test_mixed_ops_high_frequency(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in _patches: - p.stop() + _patches.close() auditor.assert_no_proceed_during_blocked() # This used to read "only a handful of ops land inside the window, @@ -434,8 +428,7 @@ def test_long_running_stress(self, ftt2_env): stress.run_for() restart_thread.join(timeout=60) - for p in _patches: - p.stop() + _patches.close() auditor.assert_no_proceed_during_blocked() delayed = auditor.assert_delayed_ops_after_unblock() @@ -460,8 +453,7 @@ def test_ordering_preserved_for_delayed_ops(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in _patches: - p.stop() + _patches.close() # Check that delayed events are in timestamp order delayed = [e for e in auditor.events if e.result == "delay"] @@ -494,8 +486,6 @@ def test_mixed_ops_on_tertiary(self, ftt2_env): side_effect=auditor): node = env['nodes'][1] patches = patch_externals() - for p in patches: - p.start() restart_thread = threading.Thread( target=lambda: storage_node_ops.restart_storage_node(node.uuid), @@ -507,8 +497,7 @@ def test_mixed_ops_on_tertiary(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in patches: - p.stop() + patches.close() auditor.assert_no_proceed_during_blocked() @@ -525,8 +514,6 @@ def test_long_running_stress_on_tertiary(self, ftt2_env): side_effect=auditor): node = env['nodes'][1] patches = patch_externals() - for p in patches: - p.start() restart_thread = threading.Thread( target=lambda: storage_node_ops.restart_storage_node(node.uuid), @@ -538,8 +525,7 @@ def test_long_running_stress_on_tertiary(self, ftt2_env): stress.run_for() restart_thread.join(timeout=60) - for p in patches: - p.stop() + patches.close() auditor.assert_no_proceed_during_blocked() @@ -568,8 +554,6 @@ def test_async_delete_on_primary_during_sec_restart(self, ftt2_env): side_effect=auditor): node = env['nodes'][1] patches = patch_externals() - for p in patches: - p.start() restart_thread = threading.Thread( target=lambda: storage_node_ops.restart_storage_node(node.uuid), @@ -581,8 +565,7 @@ def test_async_delete_on_primary_during_sec_restart(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in patches: - p.stop() + patches.close() auditor.assert_no_proceed_during_blocked() @@ -599,8 +582,6 @@ def test_create_clone_resize_on_primary_during_sec_restart(self, ftt2_env): side_effect=auditor): node = env['nodes'][1] patches = patch_externals() - for p in patches: - p.start() restart_thread = threading.Thread( target=lambda: storage_node_ops.restart_storage_node(node.uuid), @@ -612,8 +593,7 @@ def test_create_clone_resize_on_primary_during_sec_restart(self, ftt2_env): stress.run_for() restart_thread.join(timeout=30) - for p in patches: - p.stop() + patches.close() auditor.assert_no_proceed_during_blocked() @@ -630,8 +610,6 @@ def test_long_stress_on_primary_during_tert_restart(self, ftt2_env): side_effect=auditor): node = env['nodes'][2] patches = patch_externals() - for p in patches: - p.start() restart_thread = threading.Thread( target=lambda: storage_node_ops.restart_storage_node(node.uuid), @@ -643,8 +621,7 @@ def test_long_stress_on_primary_during_tert_restart(self, ftt2_env): stress.run_for() restart_thread.join(timeout=60) - for p in patches: - p.stop() + patches.close() auditor.assert_no_proceed_during_blocked() delayed = auditor.assert_delayed_ops_after_unblock() diff --git a/tests/integration/ftt2/test_restart_guards.py b/tests/integration/ftt2/test_restart_guards.py index 6ff4f3a2e5..ef30cfc2ee 100644 --- a/tests/integration/ftt2/test_restart_guards.py +++ b/tests/integration/ftt2/test_restart_guards.py @@ -25,8 +25,6 @@ def _run_restart(env, node_idx=0): from simplyblock_core.db_controller import DBController node = env['nodes'][node_idx] patches = patch_externals() - for p in patches: - p.start() try: db = DBController() snode = db.get_storage_node_by_id(node.uuid) @@ -40,8 +38,7 @@ def _run_restart(env, node_idx=0): updated = db.get_storage_node_by_id(node.uuid) return result, updated finally: - for p in patches: - p.stop() + patches.close() # ########################################################################### @@ -61,14 +58,11 @@ def test_reject_restart_when_peer_restarting(self, ftt2_env): prepare_node_for_restart(env, RESTART_NODE) patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.restart_storage_node(env['nodes'][0].uuid) assert result is False, "Restart must be rejected" finally: - for p in patches: - p.stop() + patches.close() n1.status = StorageNode.STATUS_ONLINE n1.write_to_db(db.kv_store) @@ -108,8 +102,6 @@ def _restart_node(idx): # leave a MagicMock permanently installed (e.g. set_node_status), which # then breaks every subsequent test in the process. patches = patch_externals() - for p in patches: - p.start() try: t0 = threading.Thread(target=_restart_node, args=(0,)) t1 = threading.Thread(target=_restart_node, args=(1,)) @@ -118,8 +110,7 @@ def _restart_node(idx): t0.join(timeout=60) t1.join(timeout=60) finally: - for p in patches: - p.stop() + patches.close() # At most one should succeed (the FDB transaction prevents both) successes = sum(1 for r in results if r is True) @@ -143,14 +134,11 @@ def test_reject_restart_when_peer_shutting_down(self, ftt2_env): prepare_node_for_restart(env, RESTART_NODE) patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.restart_storage_node(env['nodes'][0].uuid) assert result is False, "Restart must be rejected during peer shutdown" finally: - for p in patches: - p.stop() + patches.close() n1.status = StorageNode.STATUS_ONLINE n1.write_to_db(db.kv_store) @@ -164,14 +152,11 @@ def test_reject_shutdown_when_peer_restarting(self, ftt2_env): # Try to shut down n1 patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.shutdown_storage_node(env['nodes'][1].uuid) assert result is False, "Shutdown must be rejected during peer restart" finally: - for p in patches: - p.stop() + patches.close() n0.status = StorageNode.STATUS_ONLINE n0.write_to_db(db.kv_store) @@ -184,14 +169,11 @@ def test_reject_shutdown_when_peer_shutting_down(self, ftt2_env): n0.write_to_db(db.kv_store) patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.shutdown_storage_node(env['nodes'][1].uuid) assert result is False, "Shutdown must be rejected during peer shutdown" finally: - for p in patches: - p.stop() + patches.close() n0.status = StorageNode.STATUS_ONLINE n0.write_to_db(db.kv_store) diff --git a/tests/integration/ftt2/test_restart_peer_states.py b/tests/integration/ftt2/test_restart_peer_states.py index 8943bd5beb..ada499b5de 100644 --- a/tests/integration/ftt2/test_restart_peer_states.py +++ b/tests/integration/ftt2/test_restart_peer_states.py @@ -47,8 +47,6 @@ def _run_restart(env): from simplyblock_core.db_controller import DBController node = env['nodes'][RESTART_NODE] patches = patch_externals() - for p in patches: - p.start() try: db = DBController() snode = db.get_storage_node_by_id(node.uuid) @@ -62,8 +60,7 @@ def _run_restart(env): updated = db.get_storage_node_by_id(node.uuid) return result, updated finally: - for p in patches: - p.stop() + patches.close() def _get_rpc_log(env, node_idx): diff --git a/tests/integration/ftt2/test_restart_scenarios.py b/tests/integration/ftt2/test_restart_scenarios.py index ee0e41e783..e4a6f72200 100644 --- a/tests/integration/ftt2/test_restart_scenarios.py +++ b/tests/integration/ftt2/test_restart_scenarios.py @@ -67,8 +67,6 @@ def _run_restart(env): from simplyblock_core.db_controller import DBController node = env['nodes'][RESTART_NODE] patches = patch_externals() - for p in patches: - p.start() try: db = DBController() snode = db.get_storage_node_by_id(node.uuid) @@ -82,8 +80,7 @@ def _run_restart(env): updated = db.get_storage_node_by_id(node.uuid) return result, updated finally: - for p in patches: - p.stop() + patches.close() def _assert_restart_ok(result, node): @@ -257,14 +254,11 @@ def test_reject_concurrent_restart(self, ftt2_env): prepare_node_for_restart(env, RESTART_NODE) patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.restart_storage_node(env['nodes'][0].uuid) assert result is False finally: - for p in patches: - p.stop() + patches.close() n1.status = StorageNode.STATUS_ONLINE n1.write_to_db(db.kv_store) @@ -278,15 +272,12 @@ def test_reject_during_peer_shutdown(self, ftt2_env): prepare_node_for_restart(env, RESTART_NODE) patches = patch_externals() - for p in patches: - p.start() try: result = storage_node_ops.restart_storage_node(env['nodes'][0].uuid) assert result is False, \ "Restart must be rejected when peer is IN_SHUTDOWN" finally: - for p in patches: - p.stop() + patches.close() n1.status = StorageNode.STATUS_ONLINE n1.write_to_db(db.kv_store) diff --git a/tests/integration/test_dual_ft_e2e.py b/tests/integration/test_dual_ft_e2e.py index 40a363a8d0..b6cf4ac8de 100644 --- a/tests/integration/test_dual_ft_e2e.py +++ b/tests/integration/test_dual_ft_e2e.py @@ -14,6 +14,7 @@ Requires FoundationDB running. """ +import contextlib import json import logging import os @@ -783,8 +784,21 @@ def _make_nic(ip: str) -> IFace: # =========================================================================== def _patch_externals(): - """Return a list of context managers that mock external dependencies.""" - patches = [ + """Mock external dependencies. + + Returns an already-started ``contextlib.ExitStack``; callers ``.close()`` + it when done. Several targets below are ``.time.sleep`` for + different modules that each did ``import time`` — those alias the one + stdlib ``time`` module, so more than one patch here targets the same + global attribute. Starting then stopping a plain list in the same + (declaration) order is exactly backwards for aliased targets: whichever + patch on a shared attribute stops last "restores" it to the previous + patch's Mock, not the real function, permanently breaking ``time.sleep`` + for the rest of the test process. ExitStack always unwinds LIFO + regardless of where/when ``.close()`` runs, so this can't recur. + """ + stack = contextlib.ExitStack() + for p in [ # distr_controller: send_cluster_map_to_distr always succeeds patch('simplyblock_core.distr_controller.send_cluster_map_to_distr', return_value=True), patch('simplyblock_core.distr_controller.send_cluster_map_add_node', return_value=True), @@ -846,8 +860,9 @@ def _patch_externals(): patch('simplyblock_core.utils.hublvol_reconnect.time.sleep'), patch('simplyblock_core.cluster_ops.time.sleep'), patch('simplyblock_core.models.storage_node.time.sleep'), - ] - return patches + ]: + stack.enter_context(p) + return stack def _mock_get_secondary_nodes(current_node, exclude_ids=None): @@ -925,8 +940,6 @@ def test_activate_assigns_dual_secondaries(self, cluster_env): cl = env['cluster'] patches = _patch_externals() - for p in patches: - p.start() try: cluster_ops.cluster_activate(cl.uuid) @@ -983,8 +996,7 @@ def test_activate_assigns_dual_secondaries(self, cluster_env): f"Server {i} has no lvstores" finally: - for p in patches: - p.stop() + patches.close() def test_activate_compression_resumed(self, cluster_env): """Verify JC compression is resumed on all nodes after activation.""" @@ -993,8 +1005,6 @@ def test_activate_compression_resumed(self, cluster_env): cl = env['cluster'] patches = _patch_externals() - for p in patches: - p.start() try: # Run activation (each test gets fresh fixture) cluster_ops.cluster_activate(cl.uuid) @@ -1006,8 +1016,7 @@ def test_activate_compression_resumed(self, cluster_env): assert not srv.state.compression_suspended, \ f"Primary server {i} compression still suspended after activation" finally: - for p in patches: - p.stop() + patches.close() # =========================================================================== @@ -1030,8 +1039,6 @@ def test_recreate_lvstore_on_non_leader_both_secondaries(self, cluster_env): cl = env['cluster'] patches = _patch_externals() - for p in patches: - p.start() try: # Activate cluster first @@ -1082,8 +1089,7 @@ def test_recreate_lvstore_on_non_leader_both_secondaries(self, cluster_env): "Secondary should have connected to primary's hublvol" finally: - for p in patches: - p.stop() + patches.close() def test_recreate_lvstore_secondary_2_min_cntlid(self, cluster_env): """ @@ -1098,8 +1104,6 @@ def test_recreate_lvstore_secondary_2_min_cntlid(self, cluster_env): cl = env['cluster'] patches = _patch_externals() - for p in patches: - p.start() try: # Activate cluster @@ -1137,8 +1141,7 @@ def test_recreate_lvstore_secondary_2_min_cntlid(self, cluster_env): assert cntlid_2 == 2000, "Secondary 2 should get min_cntlid=2000" finally: - for p in patches: - p.stop() + patches.close() # =========================================================================== @@ -1166,13 +1169,10 @@ def test_health_check_verifies_both_secondaries(self, cluster_env): # Activate cluster first ext_patches = _patch_externals() - for p in ext_patches: - p.start() try: cluster_ops.cluster_activate(cl.uuid) finally: - for p in ext_patches: - p.stop() + ext_patches.close() cluster = db.get_cluster_by_id(cl.uuid) assert cluster.status == Cluster.STATUS_ACTIVE @@ -1218,8 +1218,6 @@ def tracking_check_sec(node, **kwargs): return True patches = _patch_externals() - for p_item in patches: - p_item.start() try: with patch.object(health_controller, '_check_sec_node_hublvol', @@ -1246,8 +1244,7 @@ def tracking_check_sec(node, **kwargs): f"primary_node_id mismatch: {call['primary_node_id']} != {target_primary.uuid}" finally: - for p_item in patches: - p_item.stop() + patches.close() def test_health_check_port_checks_both_secondaries(self, cluster_env): """ @@ -1263,13 +1260,10 @@ def test_health_check_port_checks_both_secondaries(self, cluster_env): # Activate cluster first ext_patches = _patch_externals() - for p in ext_patches: - p.start() try: cluster_ops.cluster_activate(cl.uuid) finally: - for p in ext_patches: - p.stop() + ext_patches.close() cluster = db.get_cluster_by_id(cl.uuid) assert cluster.status == Cluster.STATUS_ACTIVE