diff --git a/.gitignore b/.gitignore index 41d61b23..7edfb533 100644 --- a/.gitignore +++ b/.gitignore @@ -13,6 +13,8 @@ .zig-cache-global/ *.pyc zig-out/ +# The stdio frontend builds to its own prefix for the frontend comparison. +zig-out-stdio/ zig-pkg/ /release/ /debug/ diff --git a/Taskfile.yml b/Taskfile.yml index 38949f15..e644e7bb 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -78,6 +78,33 @@ tasks: cmds: - zig build test --summary all + test:matrix: + desc: "Fault matrix: inject faults on both sides of the edge, both frontends" + aliases: [tm, matrix] + vars: + # Everything the suite needs, so a contributor runs one command. python + # and uv come from hermit; requests and zstandard come from uv; oha is a + # brew dependency and the load cases skip without it. + UV: ./bin/uv run --python ./bin/python3 --with requests --with zstandard + cmds: + - "{{.UV}} bench/matrix/run.py {{.CLI_ARGS}}" + + test:matrix:fast: + desc: "Fault matrix without the cases that wait on a 30 s deadline" + aliases: [tmf] + cmds: + - task: test:matrix + vars: + CLI_ARGS: "--fast {{.CLI_ARGS}}" + + bench:sweep: + desc: "Throughput, latency and memory by axis, both frontends" + aliases: [sweep] + vars: + UV: ./bin/uv run --python ./bin/python3 --with requests + cmds: + - "{{.UV}} bench/perf/sweep.py {{.CLI_ARGS}}" + format: desc: "Format all Zig source files" aliases: [fmt, f] diff --git a/bench/matrix/README.md b/bench/matrix/README.md new file mode 100644 index 00000000..61992547 --- /dev/null +++ b/bench/matrix/README.md @@ -0,0 +1,180 @@ +# Fault matrix + +What a customer hits when something goes wrong on either side of the edge: the +agent that sends to us, and the intake we send to. Every case runs against both +frontends, and **neither frontend is the oracle** — both are judged against what +the customer needs, and either can fail. + +```sh +UV="./bin/uv run --python ./bin/python3 --with requests --with zstandard" +$UV bench/matrix/run.py # both frontends, every case +$UV bench/matrix/run.py --fast # skip the 30 s deadline cases +$UV bench/matrix/run.py --frontend stdio -k b05 +``` + +`--fast` skips the cases that wait for a 30 s deadline. `--skip-build` reuses +the binaries already in `zig-out/` and `zig-out-stdio/`. + +`task test:matrix` (aliases `tm`, `matrix`) and `task test:matrix:fast` (`tmf`) +run the same thing through hermit. `lab-notebook.md` records what the suite +found and what we changed because of it. + +## How a case is written + +One case per file, one class per case, inheriting `MatrixCase`: + +```python +from harness import MatrixCase + + +class RejectEarly(MatrixCase): + def test_an_early_rejection_is_relayed(self): + self.intake.arm("reject_early", count=1) + self.assert_status(self.post_logs(), 400) +``` + +The base class starts the fault-injecting intake and the edge binary under +test, and tears both down. It also asserts, after every case: + +- the edge process is alive and still answers `/_health`; +- connection slots returned to their baseline; +- no connection was shed unless the case said it would be; +- every 5xx the edge produced itself left a log line. + +Useful attributes: `EDGE_CONFIG`, `EDGE_ENV`, `EDGE_POLICIES`, +`INTAKE_LATENCY`, `SLOW`, `EXPECT_SHED`, `DEFECTS`. + +## Declared defects + +A case never lowers its expectation to accommodate a frontend. Behaviour we +have already found and recorded is declared instead: + +```python +class Pipelined(MatrixCase): + DEFECTS = {"httpz": "answers 400 to a pipelined pair"} +``` + +The assertion still runs at full strength. The runner reports `xfail` with the +note, so the defect stays counted and visible, and reports `XPASS` on the day +it starts passing, which means the note must go. + +## Injecting intake faults + +The intake is the real `zig-out/bin/echo-server`. Faults are armed over HTTP, +and `count` limits them to the next N requests, so a case can fault the first +attempt and let the retry succeed: + +```python +self.intake.arm("close_early", count=1) +``` + +| mode | what the intake does | +|---|---| +| `status` | answers with `arg` as the status code | +| `slow` | answers after `arg` milliseconds | +| `hang` | reads the body and never answers | +| `close_early` | reads part of the body, then closes with no answer | +| `reject_early` | answers before reading the body, as an intake does when it rejects on headers | +| `reset` | closes with RST | +| `garbage` | writes bytes that are not HTTP | +| `truncate` | declares more body than it writes, then closes | +| `oversize` | answers with a body of `arg` bytes | +| `stale_keepalive` | answers, then drops the connection the client just pooled | + +`GET /stats` reports `fault`, `fault_arg` and `fault_applied`, so a case can +assert the fault actually fired. + +## Injecting sender faults + +`self.raw()` owns a socket, so a case can send a partial head, a body shorter +than its `Content-Length`, one byte per second, pipelined requests, or bytes +that are not HTTP at all. `self.post_logs()` and `requests` cover the +well-formed cases, and `harness.load` drives `oha` where a case needs real +load. + +## The cases + +`slow` waits on a 30 s deadline and is skipped by `--fast`. `xfail` is a +declared defect: the case still runs and still fails, and the runner reports it +with its note. + +### `a*` — the sender to the edge + +| Case | Fault injected | Must happen | Notes | +|---|---|---|---| +| a01 | Connects, never sends a byte | The slot is reclaimed at the idle deadline, counted by phase | slow | +| a02 | Part of a head, then stalls | 408, because a request is in flight | slow, xfail httpz: closes with no status | +| a03 | `Content-Length` larger than the body sent | 408 naming `InboundBodyTimeout` | slow, xfail httpz: closes with no status | +| a04 | Body dripped one byte per second | Cut off inside the deadline, by status or by close | slow | +| a05 | POST with no `Content-Length` and no chunking | Any answer, never a hang | | +| a06 | Well-formed chunked body | 202, and the intake receives it | | +| a07 | Chunk size that is not a number | Refused at once, not after the deadline | slow, xfail stdio: waits for the deadline | +| a08 | Body above `max_body_size` (16 KiB here) | 413, and nothing is forwarded | | +| a09 | Corrupt gzip, no policies loaded | Forwarded; the intake's answer is relayed | | +| a09 | Corrupt gzip, policies loaded | Fails open and forwards, with `policy.failed.open` | | +| a10 | `content-encoding: br` | Forwarded raw, per the router's documented intent | xfail stdio: std refuses the head. Skipped on httpz: our std-based intake refuses brotli too | +| a11 | Sender vanishes mid-body, five times | Slots return, and nothing blames the intake | | +| a12 | Two requests written in one packet | Both are served | xfail httpz: answers 400 | +| a13 | 50 requests on one keep-alive connection | All 202, and the connection count stays at one | | +| a14 | 80 request headers | Refused with a 4xx, never accepted with headers dropped | | +| a15 | Complete but invalid head | 400 at once | slow | +| a15 | Incomplete garbage, no head terminator | Bounded by the deadline | slow | +| a16 | zstd batch, what a current agent sends | 202, and the intake receives it | | +| a19 | `Content-Length` with chunked, two lengths, a length that is not a number | A 4xx, and nothing reaches the intake | the smuggling surface | +| a22 | `HEAD /_health`, `POST /_health` | Answered by the edge, never forwarded | | +| a22 | `GET http://example.com/_health` | Not forwarded as a mangled target | xfail stdio | +| a30 | 60 KiB batch, intake closes mid-request | Replayed, 202 | the resident side of the threshold | +| a30 | 300 KiB batch, intake closes mid-request | Replayed, 202 | xfail both, by design: a streamed batch cannot be replayed, and the agent retries the 502 | +| a35 | Small gzip that expands past the decoded cap, policies loaded | Bounded, and the batch is not lost | fails open; the raw cap still answers 413 | +| a35 | The same body with no policies loaded | Forwarded untouched, 202 | nothing reads it | + +### `b*` — the edge to the intake + +| Case | Fault injected | Must happen | Notes | +|---|---|---|---| +| b01 | Nothing listening | 502, after the dial is retried once | | +| b02 | Intake reads the body and never answers | 504 at the watchdog, with the timeout counted | slow | +| b03 | Intake answers after 6 s | 202, and `request.slow` records it | | +| b04 | Intake closes mid-request | Retried on a fresh connection, 202 | | +| b05 | Intake rejects on the head, before the body | The 400 is relayed, not turned into a 502 | the reported production signature | +| b06 | Intake answers 429, 500, 503 | Each is relayed verbatim | three methods | +| b07 | Response body above the response cap | A 5xx or a closed relay, never a silent 2xx | | +| b08 | Intake answers with bytes that are not HTTP | 5xx, and the connection is evicted | | +| b09 | Pooled keep-alive is already dead | Retried on a fresh dial, 202 | log intake clients do not retry | +| b10 | Intake resets the connection | Retried, 202 | | +| b11 | Intake declares more body than it sends | Never 202; `UpstreamResponseTruncated` | | +| b11b | Intake truncates *before* reading the body | The batch never arrived, so a retry repairs it | settles the b11 challenge | +| b11b | Intake reads the batch, *then* truncates | The batch is in, so our 502 costs a duplicate | settles the b11 challenge | +| b12 | Dial into a full accept queue, so SYNs are dropped | An answer inside 35 s | slow, xfail both: the dial has no deadline | +| b23 | Intake reads the whole batch, then closes with no answer | Exactly two copies at the intake | pins at-least-once | +| b24 | Every request fails the same way, 100 of them | At most two attempts each, health unaffected | | + +### `c*` — capacity + +| Case | Fault injected | Must happen | Notes | +|---|---|---|---| +| c01 | More connections than the slab holds (8) | Shed with 503 and a `Retry-After`, counted by reason | | +| c01b | Exactly `max_connections` senders at once | Every one served: the control reserve is capacity on top of the cap | found by a benchmark, not a test | +| c02 | Health probe arrives with a 15-sender burst against a 3 s intake, 20 times | The probe stays under 1 s | slow, xfail httpz: a batch of 16 goes to one pool thread | +| c03 | 12 idle sockets against 8 slots | Recovers on its own, without the senders closing | slow | +| c04 | 48 senders against an intake that never answers | Health and the scrape answer inside a second | slow | +| c05 | A probe while every slot is held | Health answers at capacity | xfail both: shed with the rest, which restarts the sidecar during the spike | +| c09 | 400 failing requests with a log pipe nobody drains | The edge keeps serving | slow | + +### `d*` — lifecycle + +| Case | Fault injected | Must happen | Notes | +|---|---|---|---| +| d01 | SIGTERM with four exchanges open against a 4 s intake | Exit inside 35 s, and no 202 for a batch never forwarded | slow | +| d02 | SIGTERM while the intake is hung | Exit inside 20 s | slow | +| d03 | SIGTERM with eight idle keep-alive connections | Exit inside 10 s | | + +Every case also asserts its telemetry, and the base class asserts that a +counter which moved is explainable from the log. + +## Requirements + +- `python3` and `uv` from hermit (`bin/`). +- `requests` and `zstandard`, supplied by `uv run --with`. Without `zstandard` + the zstd case skips rather than fails. +- `oha` for the load cases (`brew install oha`); those cases skip without it. diff --git a/bench/matrix/harness/__init__.py b/bench/matrix/harness/__init__.py new file mode 100644 index 00000000..1dd47475 --- /dev/null +++ b/bench/matrix/harness/__init__.py @@ -0,0 +1,15 @@ +"""Shared harness for the fault matrix suite.""" + +from .case import MatrixCase +from .procs import Edge, EchoIntake, free_port +from .raw import RawClient, RawResponse, request_head + +__all__ = [ + "MatrixCase", + "Edge", + "EchoIntake", + "free_port", + "RawClient", + "RawResponse", + "request_head", +] diff --git a/bench/matrix/harness/agent.py b/bench/matrix/harness/agent.py new file mode 100644 index 00000000..9cf671f7 --- /dev/null +++ b/bench/matrix/harness/agent.py @@ -0,0 +1,36 @@ +"""How the Datadog agent treats the status we answer. + +From `comp/logs-library/client/http/destination.go` in DataDog/datadog-agent +(`sendPost`): + + if resp.StatusCode == 400 || 401 || 403 || 413 { + tlmDropped.Inc() // "payloads dropped because of + return errClient // unrecoverable errors" + } else if resp.StatusCode > 400 { + return client.NewRetryableError(errServer) + } + +So the agent **drops the payload permanently** on 400, 401, 403 and 413, and +**retries with exponential backoff** on every other error status and on +transport failures. The backoff blocks that pipeline while it waits. + +Two consequences the suite cares about: + +- Answering a drop-class status for a batch the intake never received is + permanent data loss, not a retryable hiccup. That is the most severe thing + the edge can do. +- Answering a retry-class status for a request that can never succeed (a + header flood, say) costs an unbounded retry loop, whether we say 431 or 502. + The choice between them is about diagnosis, not about agent behaviour. +""" + +#: The agent discards the payload and never sends it again. +DROPS_PAYLOAD = frozenset({400, 401, 403, 413}) + + +def drops_payload(status: int) -> bool: + return status in DROPS_PAYLOAD + + +def retries(status: int) -> bool: + return status > 400 and status not in DROPS_PAYLOAD diff --git a/bench/matrix/harness/case.py b/bench/matrix/harness/case.py new file mode 100644 index 00000000..dfd70ce4 --- /dev/null +++ b/bench/matrix/harness/case.py @@ -0,0 +1,412 @@ +"""The shared base every matrix case inherits. + +One case is one file under `tests/`, and one class per file. The base starts a +fault-injecting intake and the edge binary under test, hands the case a set of +senders, and asserts the invariants that must hold whatever the fault was. + +Every case asserts what a customer needs, not what either frontend happens to +do. Neither frontend is the oracle: both are judged against the expectation, +and either can fail. + +A defect we have already found and recorded is declared with `DEFECTS`, keyed +by the frontend it affects. The case still runs, and the runner reports it as +`xfail` with the note, so the defect stays counted and visible rather than +skipped. If the case starts passing, the runner reports `XPASS`, which means +the defect is fixed and the note must go. + +Class attributes a case may set: + + EDGE_CONFIG merged into the generated edge config + EDGE_ENV extra environment for the edge process + EDGE_POLICIES policy document to load, so the decode path runs + INTAKE_LATENCY intake round trip, in milliseconds + SLOW true when the case waits for a 30 s deadline + EXPECT_SHED true when the case shed connections on purpose + DEFECTS {frontend: note} for behaviour we know is wrong today + +Telemetry is part of the expectation, not an afterthought. A fault an operator +cannot see is still a fault, so declare it: + + EXPECT_METRICS {series: minimum delta} for both frontends + EXPECT_METRICS_FOR {frontend: {series: minimum delta}} where a series is + frontend specific, such as the connection gauges + EXPECT_LOGS substrings that must appear in the edge log + EXPECT_LOGS_FOR {frontend: [substrings]} + FORBID_LOGS substrings that must NOT appear. This is the half that + earns its keep: it is how a sender-side fault is kept + from ever reading as an intake fault. +""" + +from __future__ import annotations + +import gzip +import json +import os +import tempfile +import time +import unittest + +from . import agent +from .procs import Edge, EchoIntake +from .raw import RawClient, request_head + +try: + import requests +except ImportError: # pragma: no cover - the runner installs it + requests = None + +LOG_PAYLOAD = [{"message": "matrix case", "ddsource": "matrix", "service": "suite"}] + + +class MatrixCase(unittest.TestCase): + EDGE_CONFIG: dict = {} + EDGE_ENV: dict = {} + EDGE_POLICIES: dict | None = None + INTAKE_LATENCY: int = 0 + SLOW: bool = False + EXPECT_SHED: bool = False + DEFECTS: dict = {} + #: The case ends the edge process itself, so the post-case invariants that + #: need a live server are skipped. + TERMINATES_EDGE: bool = False + #: A policy that keeps nothing makes a 2xx with no upstream request + #: legitimate, so the phantom-success rule is relaxed. + ALLOW_PHANTOM_SUCCESS: bool = False + #: The case answers a status the agent drops on purpose, and the batch is + #: genuinely unforwardable (too large, ambiguous framing). + EXPECT_PERMANENT_DROP: bool = False + #: Data paths only: health and the scrape answer 2xx without an upstream. + DATA_PATHS = ("api_v2_logs", "api_v2_series", "v1_logs", "v1_metrics", "v1_traces", "other") + EXPECT_METRICS: dict = {} + EXPECT_METRICS_FOR: dict = {} + EXPECT_LOGS: list = [] + EXPECT_LOGS_FOR: dict = {} + FORBID_LOGS: list = [] + + # A counter that moved must be explainable from the log. Checked in every + # case, so a case that declares nothing still cannot pass with silent + # telemetry. + METRIC_NEEDS_LOG = ( + (("edge_request_errors_total", 'class="uncaught"'), "request.failed"), + (("edge_request_errors_total", 'class="module"'), "policy.failed.open"), + (("edge_upstream_timeouts_total",), "upstream.timed.out"), + (("edge_upstream_retries_total",), "upstream.retried"), + (("edge_connections_shed_total",), "connection.shed"), + (("edge_requests_invalid_total",), "request.rejected"), + ) + + intake: EchoIntake + edge: Edge + + @property + def frontend(self) -> str: + """Which frontend this run is exercising, from the runner.""" + return os.environ.get("EDGE_FRONTEND", "unknown") + + def run(self, result=None): + """Turns a declared defect into a reported expected failure. + + The assertion stays exactly as strict as it is for the other frontend, + so the defect keeps failing until somebody fixes it, and the day it + passes the runner says so. + """ + note = self.DEFECTS.get(self.frontend) + if result is None or not note: + return super().run(result) + + inner = unittest.TestResult() + super().run(inner) + result.startTest(self) + try: + if inner.skipped: + result.addSkip(self, inner.skipped[0][1]) + elif inner.failures or inner.errors: + detail = (inner.failures + inner.errors)[0][1].strip().splitlines()[-1] + error = AssertionError("known defect on %s: %s [%s]" % (self.frontend, note, detail)) + result.addExpectedFailure(self, (AssertionError, error, None)) + else: + result.addUnexpectedSuccess(self) + finally: + result.stopTest(self) + return result + + def setUp(self) -> None: + if os.environ.get("MATRIX_FAST") and self.SLOW: + self.skipTest("slow case; unset MATRIX_FAST to run it") + self.intake = EchoIntake(latency_ms=self.INTAKE_LATENCY) + config = dict(self.EDGE_CONFIG) + if self.EDGE_POLICIES is not None: + handle = tempfile.NamedTemporaryFile("w", suffix=".policies.json", delete=False) + json.dump(self.EDGE_POLICIES, handle) + handle.close() + self._policy_path = handle.name + config["policy_providers"] = [{"id": "file", "type": "file", "path": handle.name}] + try: + self.edge = Edge(self.intake.url, config, self.EDGE_ENV) + except Exception: + self.intake.stop() + raise + # A stdio build without --prefix overwrites the httpz binary, which + # would silently test one frontend twice. The edge reports its own + # frontend, so trust that, not the path. + running = self.edge.frontend() + if running is not None and self.frontend in ("stdio", "httpz"): + self.assertEqual( + running, + self.frontend, + "EDGE_BIN carries the %s frontend, not %s; rebuild with " + "--prefix zig-out-stdio" % (running, self.frontend), + ) + self.baseline = self.edge.metrics() + self.baseline_descriptors = self.edge.descriptors() + self.baseline_intake = self.intake.requests_seen() + # Expectations are about what this case produced, so the startup lines + # (which name the configured upstream) must not count. Diff by line, + # because stdout and stderr are flushed independently. + self.log_snapshot = set(self.edge.logs().splitlines()) + + def tearDown(self) -> None: + try: + self.assert_telemetry() + self.assert_invariants() + finally: + self.edge.stop() + self.intake.stop() + + # ---------------------------------------------------------------- senders + + def post_logs(self, body=None, path: str = "/api/v2/logs", headers=None, timeout: float = 60.0, **kwargs): + """A well-formed request, the way an agent sends one.""" + self.assertIsNotNone(requests, "run through bench/matrix/run.py, which supplies requests") + payload = json.dumps(LOG_PAYLOAD if body is None else body).encode() + merged = {"Content-Type": "application/json"} + merged.update(headers or {}) + return requests.post( + self.edge.url + path, data=payload, headers=merged, timeout=timeout, **kwargs + ) + + def post_raw_body(self, body: bytes, path: str = "/api/v2/logs", headers=None, timeout: float = 60.0): + self.assertIsNotNone(requests, "run through bench/matrix/run.py, which supplies requests") + merged = {"Content-Type": "application/json"} + merged.update(headers or {}) + return requests.post(self.edge.url + path, data=body, headers=merged, timeout=timeout) + + def gzipped(self, body=None) -> bytes: + return gzip.compress(json.dumps(LOG_PAYLOAD if body is None else body).encode()) + + def raw(self, timeout: float = 60.0) -> RawClient: + return RawClient(self.edge.port, timeout=timeout) + + def head(self, path: str = "/api/v2/logs", body_len: int | None = None, extra: str = "") -> bytes: + return request_head(path, body_len, extra) + + def health(self, timeout: float = 10.0): + self.assertIsNotNone(requests, "run through bench/matrix/run.py, which supplies requests") + return requests.get(self.edge.url + "/_health", timeout=timeout) + + # --------------------------------------------------------------- asserts + + def assert_status(self, response, expected: int, why: str = "") -> None: + got = getattr(response, "status", None) + if got is None: + got = getattr(response, "status_code", None) + self.assertEqual(got, expected, "%s (response: %r)" % (why or "wrong status", response)) + + def case_logs(self) -> str: + """Only the lines this case produced.""" + return "\n".join( + line for line in self.edge.logs().splitlines() if line not in self.log_snapshot + ) + + def wait_for_log(self, needle: str, timeout: float = 5.0) -> bool: + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + if needle in self.case_logs(): + return True + time.sleep(0.2) + return False + + def assert_logged(self, needle: str, why: str = "") -> None: + if self.wait_for_log(needle): + return + logs = self.case_logs() + self.assertIn(needle, logs, "%s\n--- edge log ---\n%s" % (why or "missing log line", logs)) + + def assert_not_logged(self, needle: str) -> None: + self.assertNotIn(needle, self.case_logs()) + + def data_path_2xx(self) -> float: + """2xx answers on paths that must reach the intake.""" + total = 0.0 + for name, value in self.edge.metrics().items(): + if not name.startswith("edge_responses_total") or 's2xx' not in name: + continue + if not any('known_path="%s"' % p in name for p in self.DATA_PATHS): + continue + total += value - self.baseline.get(name, 0.0) + return total + + def dropped_by_agent(self) -> int: + """Data-path answers that make the agent discard the batch for good.""" + total = 0 + for name, value in self.edge.metrics().items(): + if not name.startswith("edge_responses_total") or 's4xx' not in name: + continue + if not any('known_path="%s"' % p in name for p in self.DATA_PATHS): + continue + total += int(value - self.baseline.get(name, 0.0)) + return total if self.data_path_4xx_was_a_drop() else 0 + + def data_path_4xx_was_a_drop(self) -> bool: + """True when the batch did not reach the intake. + + The status class is all the metrics carry, so this is conservative: + a 4xx counts as a drop only when nothing was forwarded for it. + """ + forwarded = self.intake.requests_seen() - self.baseline_intake + return forwarded < self.data_path_2xx() + 1 + + def metric_delta(self, name: str) -> float: + """How much a counter moved since the case started.""" + return self.edge.metric(name) - self.baseline.get(name, 0.0) + + def wait_for_metric(self, name: str, at_least: float, timeout: float = 10.0) -> float: + deadline = time.monotonic() + timeout + value = self.metric_delta(name) + while value < at_least and time.monotonic() < deadline: + time.sleep(0.2) + value = self.metric_delta(name) + self.assertGreaterEqual(value, at_least, "%s never reached %s" % (name, at_least)) + return value + + def intake_saw(self, at_least: int, timeout: float = 10.0) -> int: + deadline = time.monotonic() + timeout + seen = self.intake.requests_seen() + while seen < at_least and time.monotonic() < deadline: + time.sleep(0.1) + seen = self.intake.requests_seen() + return seen + + # ------------------------------------------------------------- telemetry + + def assert_telemetry(self) -> None: + """The declared metrics and logs, plus the universal pairing rule.""" + expected = dict(self.EXPECT_METRICS) + expected.update(self.EXPECT_METRICS_FOR.get(self.frontend, {})) + for series, minimum in expected.items(): + self.wait_for_metric(series, minimum, timeout=8) + + wanted = list(self.EXPECT_LOGS) + list(self.EXPECT_LOGS_FOR.get(self.frontend, [])) + for needle in wanted: + self.assertTrue( + self.wait_for_log(needle), + "missing %r in the edge log:\n%s" % (needle, self.case_logs()), + ) + + # A forbidden line may still be on its way, so settle before looking. + time.sleep(1.5) + logs = self.case_logs() + for needle in self.FORBID_LOGS: + self.assertNotIn( + needle, + logs, + "%r must not appear for this fault; it points at the wrong " + "subsystem:\n%s" % (needle, logs), + ) + + metrics = self.edge.metrics() + for parts, needle in self.METRIC_NEEDS_LOG: + def matches(name: str, parts=parts) -> bool: + return all(part in name for part in parts) + + moved = sum(v for k, v in metrics.items() if matches(k)) + base = sum(v for k, v in self.baseline.items() if matches(k)) + if moved > base: + self.assertTrue( + self.wait_for_log(needle), + "%s moved but %r never appeared, so the event is " + "unexplainable from the log:\n%s" + % ("+".join(parts), needle, self.case_logs()), + ) + + # ------------------------------------------------------------ invariants + + def assert_invariants(self) -> None: + """Holds in every cell, whatever the fault was.""" + if self.TERMINATES_EDGE: + return + self.assertTrue(self.edge.alive(), "the edge process died:\n%s" % self.edge.logs()) + + # No phantom success: the intake must have seen at least as many + # requests as the sender received 2xx answers on a data path. This one + # rule catches every "the edge answered for data it never forwarded". + if not self.ALLOW_PHANTOM_SUCCESS: + accepted = self.data_path_2xx() + forwarded = self.intake.requests_seen() - self.baseline_intake + self.assertGreaterEqual( + forwarded, + accepted, + "the sender got %d 2xx answers on data paths but the intake " + "saw %d requests" % (accepted, forwarded), + ) + + # No permanent loss: the agent discards a payload for good on 400, + # 401, 403 and 413 (see harness/agent.py). Answering one of those for + # a batch the intake never saw destroys customer data. + if not self.EXPECT_PERMANENT_DROP: + dropped = self.dropped_by_agent() + self.assertEqual( + dropped, + 0, + "answered %d status(es) the agent drops permanently, for a batch " + "the intake never received" % dropped, + ) + + # In-flight returns to zero: the scrape itself is the only request + # still open when we look. + in_flight = self.edge.metric("edge_requests_in_flight") + self.assertLessEqual(in_flight, 1, "requests are still in flight: %s" % in_flight) + + # Descriptors return to baseline, with room for pooled upstream + # connections and the scrape. + if self.baseline_descriptors > 0: + now = self.edge.descriptors() + if now > 0: + self.assertLessEqual( + now, + self.baseline_descriptors + 16, + "descriptors leaked: %d against a baseline of %d" + % (now, self.baseline_descriptors), + ) + + # It must still serve after the fault. + health = self.health() + self.assertEqual(health.status_code, 200, "health broke after the case") + + # Connection accounting must return to its baseline. stdio only: httpz + # cannot report this without a patch to the dependency. The scrape + # itself holds a slot, and the health probe above may still be on its + # way out, so the floor is the baseline plus one. + metrics = self.edge.metrics() + if "edge_connections_active" in metrics: + ceiling = max(1.0, self.baseline.get("edge_connections_active", 1.0)) + 2 + deadline = time.monotonic() + 8 + active = metrics["edge_connections_active"] + while active > ceiling and time.monotonic() < deadline: + time.sleep(1.0) + metrics = self.edge.metrics() + active = metrics["edge_connections_active"] + self.assertLessEqual( + active, + ceiling, + "connection slots leaked (%s open):\n%s" % (active, self.edge.logs()), + ) + + if not self.EXPECT_SHED: + shed = sum(v for k, v in metrics.items() if k.startswith("edge_connections_shed_total")) + base = sum(v for k, v in self.baseline.items() if k.startswith("edge_connections_shed_total")) + self.assertEqual(shed, base, "connections were shed unexpectedly") + + # A 5xx relayed from the intake is not our failure and owes no log + # line; b06 asserts that relay. The errors we produce ourselves are + # covered by METRIC_NEEDS_LOG in assert_telemetry. diff --git a/bench/matrix/harness/load.py b/bench/matrix/harness/load.py new file mode 100644 index 00000000..1617ff5b --- /dev/null +++ b/bench/matrix/harness/load.py @@ -0,0 +1,42 @@ +"""`oha` wrapper, for the cases that need real load rather than one request.""" + +from __future__ import annotations + +import json +import shutil +import subprocess +import tempfile + + +def available() -> bool: + return shutil.which("oha") is not None + + +def run(url: str, payload: bytes, connections: int, seconds: float, method: str = "POST") -> dict: + """Drives `oha` and returns its summary. Raises when oha is missing.""" + if not available(): + raise RuntimeError("oha is not installed (brew install oha)") + body = tempfile.NamedTemporaryFile("wb", suffix=".json", delete=False) + body.write(payload) + body.close() + out = tempfile.NamedTemporaryFile("r", suffix=".json", delete=False) + out.close() + subprocess.run( + [ + "oha", "-z", "%ds" % int(seconds), "-c", str(connections), "-m", method, + "-H", "Content-Type: application/json", "-D", body.name, + "--no-tui", "--output-format", "json", "-o", out.name, url, + ], + check=True, + capture_output=True, + ) + with open(out.name) as handle: + report = json.load(handle) + return { + "rps": report["summary"]["requestsPerSec"], + "p50": report["latencyPercentiles"]["p50"], + "p99": report["latencyPercentiles"]["p99"], + "p99.9": report["latencyPercentiles"]["p99.9"], + "max": report["summary"]["slowest"], + "codes": report["statusCodeDistribution"], + } diff --git a/bench/matrix/harness/procs.py b/bench/matrix/harness/procs.py new file mode 100644 index 00000000..e41d5526 --- /dev/null +++ b/bench/matrix/harness/procs.py @@ -0,0 +1,261 @@ +"""Process control for the two servers every case needs. + +`EchoIntake` is the real `zig-out/bin/echo-server`, which carries the fault +modes the matrix drives (`POST /fault?mode=...`). `Edge` is the real edge +binary under test. Both write their logs to files the case can read, because +half the assertions are about what we logged, not only what we answered. +""" + +from __future__ import annotations + +import json +import os +import socket +import subprocess +import tempfile +import time +import urllib.error +import urllib.request + +REPO_ROOT = os.path.abspath(os.path.join(os.path.dirname(__file__), "..", "..", "..")) + + +def free_port() -> int: + s = socket.socket() + s.bind(("127.0.0.1", 0)) + port = s.getsockname()[1] + s.close() + return port + + +def _get(url: str, timeout: float = 5.0) -> str: + with urllib.request.urlopen(url, timeout=timeout) as response: + return response.read().decode("utf-8", "replace") + + +class EchoIntake: + """The fake Datadog intake: `src/bench/echo_server.zig`.""" + + BINARY = os.path.join(REPO_ROOT, "zig-out", "bin", "echo-server") + + def __init__(self, latency_ms: int = 0, port: int | None = None): + self.port = port or free_port() + self.log_path = tempfile.mktemp(suffix=".echo.log") + env = dict(os.environ) + env["ECHO_LATENCY_MS"] = str(latency_ms) + self._log = open(self.log_path, "wb") + self._last_seen = 0 + self.proc = subprocess.Popen( + [self.BINARY, str(self.port), tempfile.gettempdir()], + stdout=self._log, + stderr=self._log, + env=env, + ) + self._wait_ready() + + @property + def url(self) -> str: + return "http://127.0.0.1:%d" % self.port + + def _wait_ready(self, timeout: float = 10.0) -> None: + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + try: + self.stats() + return + except (OSError, urllib.error.URLError): + time.sleep(0.05) + raise RuntimeError("echo server never became ready: %s" % self.log_path) + + def stats(self) -> dict: + return json.loads(_get("%s/stats" % self.url)) + + def reset(self) -> None: + urllib.request.urlopen("%s/reset" % self.url, data=b"", timeout=5).read() + + def arm(self, mode: str, arg: int = 0, count: int | None = None) -> None: + """Injects an intake fault. `count` limits it to the next N requests.""" + query = "mode=%s&arg=%d" % (mode, arg) + if count is not None: + query += "&count=%d" % count + urllib.request.urlopen("%s/fault?%s" % (self.url, query), data=b"", timeout=5).read() + + def faults_applied(self) -> int: + return int(self.stats().get("fault_applied", 0)) + + def requests_seen(self) -> int: + """Requests the intake recorded. + + A case may stop the intake on purpose (b01), and the teardown + invariants still ask. Fall back to the last known count rather than + turning a deliberate outage into a harness error. + """ + try: + self._last_seen = int(self.stats().get("total_requests", 0)) + except (OSError, urllib.error.URLError, ValueError): + pass + return self._last_seen + + def stop(self) -> None: + self.proc.terminate() + try: + self.proc.wait(timeout=10) + except subprocess.TimeoutExpired: + self.proc.kill() + self._log.close() + + +class Edge: + """The edge binary under test, with a config written for this case.""" + + def __init__( + self, + upstream_url: str, + config: dict | None = None, + env: dict | None = None, + stall_logs: bool = False, + ): + self.port = free_port() + self.binary = os.environ.get("EDGE_BIN", os.path.join(REPO_ROOT, "zig-out", "bin", "edge")) + merged = { + "listen_address": "127.0.0.1", + "listen_port": self.port, + "upstream_url": upstream_url, + "log_level": "info", + "max_body_size": 1048576, + } + merged.update(config or {}) + handle = tempfile.NamedTemporaryFile("w", suffix=".json", delete=False) + json.dump(merged, handle) + handle.close() + self.config_path = handle.name + self.config = merged + + self.out_path = tempfile.mktemp(suffix=".edge.out.log") + self.err_path = tempfile.mktemp(suffix=".edge.err.log") + self._out = open(self.out_path, "wb") + self._err = open(self.err_path, "wb") + self.stalled_pipe = None + if stall_logs: + # A log destination nobody drains. A logger that blocks on a full + # pipe takes the data plane down with it, which is what an ECS log + # driver in blocking mode can do. + read_fd, write_fd = os.pipe() + self.stalled_pipe = read_fd + self._out.close() + self._err.close() + self._out = os.fdopen(write_fd, "wb") + self._err = self._out + process_env = dict(os.environ) + process_env.update(env or {}) + self.proc = subprocess.Popen( + [self.binary, self.config_path], + stdout=self._out, + stderr=self._err, + env=process_env, + ) + self._wait_ready() + + @property + def url(self) -> str: + return "http://127.0.0.1:%d" % self.port + + def _wait_ready(self, timeout: float = 15.0) -> None: + deadline = time.monotonic() + timeout + while time.monotonic() < deadline: + if self.proc.poll() is not None: + raise RuntimeError("edge exited early:\n%s" % self.logs()) + try: + if _get("%s/_health" % self.url, timeout=1.0): + return + except (OSError, urllib.error.URLError): + time.sleep(0.05) + raise RuntimeError("edge never answered /_health:\n%s" % self.logs()) + + def alive(self) -> bool: + return self.proc.poll() is None + + @property + def pid(self) -> int: + return self.proc.pid + + def descriptors(self) -> int: + """Open file descriptors, for the leak invariant.""" + try: + out = subprocess.run( + ["lsof", "-p", str(self.proc.pid)], + capture_output=True, + text=True, + timeout=20, + ) + except (OSError, subprocess.TimeoutExpired): + return -1 + return max(0, len(out.stdout.splitlines()) - 1) + + def terminate_and_wait(self, timeout: float = 30.0) -> tuple[int | None, float]: + """SIGTERM, then wait. Returns the exit code and how long it took.""" + started = time.monotonic() + self.proc.terminate() + try: + code = self.proc.wait(timeout=timeout) + except subprocess.TimeoutExpired: + self.proc.kill() + return None, time.monotonic() - started + return code, time.monotonic() - started + + def frontend(self) -> str | None: + """Which frontend this binary actually carries, from its own log.""" + for line in self.logs().splitlines(): + marker = 'data.plane.budget frontend="' + if marker in line: + return line.split(marker, 1)[1].split('"', 1)[0] + return None + + def logs(self) -> str: + """Both streams. INFO and WARN land on stdout, ERROR on stderr.""" + if self.stalled_pipe is not None: + return "" # the log destination is a pipe on purpose + self._out.flush() + self._err.flush() + parts = [] + for path in (self.out_path, self.err_path): + with open(path, "r", errors="replace") as handle: + parts.append(handle.read()) + return "".join(parts) + + def metrics(self) -> dict[str, float]: + """The Prometheus scrape as a flat {series: value} map, labels kept.""" + out: dict[str, float] = {} + try: + text = _get("%s/_edge/metrics" % self.url, timeout=10) + except (OSError, urllib.error.URLError): + return out + for line in text.splitlines(): + if not line or line.startswith("#"): + continue + name, _, value = line.rpartition(" ") + try: + out[name.strip()] = float(value) + except ValueError: + continue + return out + + def metric(self, name: str, default: float = 0.0) -> float: + return self.metrics().get(name, default) + + def stop(self) -> None: + self.proc.terminate() + try: + self.proc.wait(timeout=10) + except subprocess.TimeoutExpired: + self.proc.kill() + if self.stalled_pipe is not None: + os.close(self.stalled_pipe) + self._out.close() + else: + self._out.close() + self._err.close() + try: + os.unlink(self.config_path) + except OSError: + pass diff --git a/bench/matrix/harness/raw.py b/bench/matrix/harness/raw.py new file mode 100644 index 00000000..557c33fa --- /dev/null +++ b/bench/matrix/harness/raw.py @@ -0,0 +1,98 @@ +"""Raw socket sender, for the requests `requests` cannot express. + +A malformed head, a body shorter than its `Content-Length`, a client that +stalls mid-body: every one of those is a byte-level case, so these helpers own +the socket and the timing. +""" + +from __future__ import annotations + +import socket +import time + + +class RawResponse: + """What came back, and how long it took.""" + + def __init__(self, raw: bytes, seconds: float, closed: bool): + self.raw = raw + self.seconds = seconds + self.closed = closed + + @property + def status(self) -> int | None: + if not self.raw.startswith(b"HTTP/"): + return None + try: + return int(self.raw.split(b" ", 2)[1]) + except (IndexError, ValueError): + return None + + @property + def head(self) -> str: + return self.raw.split(b"\r\n\r\n", 1)[0].decode("utf-8", "replace") + + def __repr__(self) -> str: + return "RawResponse(status=%s, seconds=%.1f, bytes=%d)" % ( + self.status, self.seconds, len(self.raw), + ) + + +class RawClient: + """One connection, driven byte by byte.""" + + def __init__(self, port: int, timeout: float = 60.0): + self.sock = socket.create_connection(("127.0.0.1", port), timeout=timeout) + self.sock.settimeout(timeout) + self.started = time.monotonic() + + def send(self, data: bytes) -> None: + self.sock.sendall(data) + + def drip(self, data: bytes, interval: float) -> None: + """One byte at a time. A sender that never stops but never finishes.""" + for i in range(len(data)): + self.sock.sendall(data[i : i + 1]) + time.sleep(interval) + + def read_response(self) -> RawResponse: + """Reads until the head is complete, the peer closes, or we time out.""" + started = time.monotonic() + data = b"" + closed = False + try: + while b"\r\n\r\n" not in data: + chunk = self.sock.recv(65536) + if not chunk: + closed = True + break + data += chunk + except (socket.timeout, OSError): + pass + return RawResponse(data, time.monotonic() - started, closed) + + def close(self) -> None: + try: + self.sock.close() + except OSError: + pass + + def __enter__(self) -> "RawClient": + return self + + def __exit__(self, *exc) -> None: + self.close() + + +def request_head(path: str, body_len: int | None, extra: str = "", method: str = "POST") -> bytes: + """A well-formed head. The caller decides what body follows, if any.""" + lines = [ + "%s %s HTTP/1.1" % (method, path), + "Host: 127.0.0.1", + "Content-Type: application/json", + ] + if body_len is not None: + lines.append("Content-Length: %d" % body_len) + if extra: + lines.append(extra.rstrip("\r\n")) + return ("\r\n".join(lines) + "\r\n\r\n").encode() diff --git a/bench/matrix/lab-notebook.md b/bench/matrix/lab-notebook.md new file mode 100644 index 00000000..57e90ec2 --- /dev/null +++ b/bench/matrix/lab-notebook.md @@ -0,0 +1,331 @@ +# Lab notebook + +What the fault matrix found, what we changed because of it, and what is still +open. Kept next to the suite, because every entry here points at a case in +`tests/`. `README.md` lists the cases; this file records the reasoning. + +## Fault matrix suite for both frontends (`bench/matrix/`) + +Goal: bubble up what a customer would hit, by injecting faults on both sides of +the edge — sender to edge, and edge to intake. + +**Neither frontend is the oracle.** An early draft treated httpz as correct and +marked every stdio difference as acceptable, which hid four httpz defects. Each +case now asserts what a customer needs, and both frontends are judged against +it. + +### Environment + +- [x] Install `python3` through hermit (3.12.3, `bin/python3`). +- [x] Use `uv` (already in `bin/`) for the `requests` and `zstandard` dependencies. +- [x] Keep `oha` for load cases; it stays a brew dependency, as `bench/perf/run.sh` already assumes. + +### Echo server: intake faults (`src/bench/echo_server.zig`) + +- [x] `Fault` enum: status, hang, close_early, reject_early, reset, garbage, truncate, slow, oversize, stale_keepalive. +- [x] Arm over HTTP: `POST /fault?mode=&arg=&count=`, so a case can fault the first N requests only. +- [x] Report `fault`, `fault_arg` and `fault_applied` from `/stats`. +- [x] Faults apply to the echo path only, so `/stats` and `/fault` stay reachable. +- [x] Build, format and lint clean. + +### Harness (`bench/matrix/harness/`) + +- [x] `procs.py`: the fault-injecting intake and the edge binary, with logs and metrics. +- [x] `raw.py`: raw socket sender for malformed, partial and dribbling senders. +- [x] `case.py`: the `MatrixCase` base, per-class config and policies, and the invariants every case asserts. +- [x] `load.py`: `oha` wrapper. +- [x] `run.py`: builds both binaries, runs the suite per frontend, prints the table and the findings. +- [x] Declared defects report as `xfail` with their note, and as `XPASS` once fixed. +- [x] `README.md`. +- [x] Declarative telemetry: `EXPECT_METRICS`, `EXPECT_METRICS_FOR`, `EXPECT_LOGS`, + `EXPECT_LOGS_FOR`, `FORBID_LOGS`, asserted for every case by the base class. +- [x] Universal pairing rule: a counter that moved must be explainable from the + log (`METRIC_NEEDS_LOG`), so a case that declares nothing still cannot + pass with silent telemetry. +- [x] 24 of 31 case files declare telemetry; the rest are covered by the + pairing rule alone. Verified by breaking one expectation on purpose. + +### Cases: sender to edge + +- [x] a01 idle connection, never sends. +- [x] a02 partial head, then stalls. +- [x] a03 `Content-Length` larger than the body sent. +- [x] a04 body drips one byte at a time. +- [x] a05 no `Content-Length` and no chunking. +- [x] a06 valid chunked body. +- [x] a07 invalid chunk size. +- [x] a08 body above `max_body_size`. +- [x] a09 corrupt gzip, with and without policies loaded. +- [x] a10 unsupported content encoding. +- [x] a11 client disconnects mid-body. +- [x] a12 pipelined requests. +- [x] a13 keep-alive reuse. +- [x] a14 more forward headers than the cap. +- [x] a15 garbage bytes, complete and incomplete. +- [x] a16 zstd batch, which is what a current Datadog agent sends. Passes on both frontends. + +### Cases: edge to intake + +- [x] b01 connection refused. +- [x] b02 intake never answers. +- [x] b03 intake answers slowly. +- [x] b04 intake closes mid-request. +- [x] b05 intake rejects on headers, before the body. +- [x] b06 status relay (429, 500, 503). +- [x] b07 response above the response cap. +- [x] b08 intake answers with garbage. +- [x] b09 stale pooled keep-alive. +- [x] b10 intake resets the connection. +- [x] b11 truncated response body. + +### Cases: capacity + +- [x] c01 shed above `max_connections`. +- [x] c02 health probe under a synchronised burst with a slow intake. +- [x] c03 idle socket flood. + +## Harness defects found while adding the telemetry assertions + +These were mine, not the product's, and each one had produced a false finding +before it was fixed: + +- Both edge streams were captured into one file. The edge writes INFO and WARN + to stdout and ERROR to stderr through independent buffers, so the single file + interleaved and cut lines in half. `request.failed` appeared at byte 0, ahead + of the startup lines. Fixed by capturing the streams separately. +- Case-scoped logs were sliced by byte offset, which assumes one append-ordered + file. Now diffed by line. +- Log assertions read once, so a line that arrived just after the response read + as missing. Now they poll, and the forbidden-line check settles first. +- The invariant "every 5xx must leave a log line" was wrong: a 5xx relayed from + the intake is not our failure and owes no log. Replaced by the pairing rule, + which only covers errors we produce ourselves. +- `FORBID_LOGS = ["upstream"]` matched the startup line `upstream.configured`, + which the case-scoped diff now excludes. + +## Backlog triage (BACKLOG.md) + +Fourteen cases taken from the backlog, in three groups: + +- **Verified first, then written:** a22 health methods, a30 the streaming + threshold, b11b the truncation challenge. Two backlog claims did not + reproduce as written and were corrected before the case was added. +- **Written as specified:** a19 framing conflicts, a35 decompression bomb, + b12 dial blackhole, b23 duplicate delivery, b24 retry amplification, + c04 hung-intake saturation, c05 health at capacity, c09 log back-pressure, + d01 to d03 SIGTERM behaviour. +- **Skipped, with reasons in the review:** the framer and OTLP torture cases + belong in the Zig unit tests, the idle-close race is nondeterministic, and + the soak and tiny-profile modes are runner projects. + +Three universal invariants came with them, and each one caught something the +per-case assertions missed: no phantom success, in-flight back to zero, and +descriptors back to baseline. + +## The two challenges, settled with tests + +1. **"Log intake clients do not retry" is wrong.** From the agent's own + source, `comp/logs-library/client/http/destination.go`: 400, 401, 403 and + 413 increment `payloads_dropped` and are never resent; every other error + status and every transport failure becomes a `RetryableError` with + exponential backoff. Encoded in `bench/matrix/harness/agent.py` and asserted + as an invariant: answering a drop-class status for a batch the intake never + received is permanent data loss. This raises the severity of our 4xx + choices and lowers it for our 5xx choices. +2. **The b11 note was half right.** Two cases now separate the halves. When the + intake truncates *before* reading the body it received nothing, so our 502 + and the agent's retry repair it. When it reads the whole batch and *then* + truncates, the batch is already in, and our 502 makes the agent deliver a + second copy, measured at exactly two. The fix worth making is to relay the + 2xx when we know the body was fully sent, and count the truncation. + +## Scope: remaining matrix cases and stdio fixes + +### Fixes we can make ourselves + +| Item | What | Effort | +|---|---|---| +| a22 absolute-form | Accept `GET http://host/path` and route on the path, per RFC 9112 §3.2.2, instead of forwarding the whole URL upstream as a path. stdio only | S | +| c05 health at capacity | Reserve a small number of slab slots that are handed out only after a normal claim fails, and serve those connections without keep-alive. A probe then answers during the spike that filled the slab, instead of being shed and restarting the sidecar | M | + +### Fixes that need a change outside our tree + +| Item | Why it is blocked | What the fix looks like | +|---|---|---| +| b12 dial deadline (both frontends) | `std.http.Client.ConnectTcpOptions` **declares** `timeout` and never passes it to `host.connect`, and `Connection.Plain.create` is private, so we cannot build a connection with our own bounded dial | One line in std to forward the timeout, plus a `timeout` on `RequestOptions`. Worth an upstream patch; we carry a circuit breaker only if that stalls | +| a10 unknown content encoding (stdio) | `std.http.Server` maps `content-encoding` through `ContentEncoding.fromString` and fails the whole head with `HttpHeadersInvalid`, with no distinct error to match on | std should carry an unknown encoding as opaque. Byte-rewriting the header in our own buffer is not worth it for an encoding no agent sends | +| a07 broken chunk (stdio) | std's chunked reader waits for a valid size line rather than erroring, so only the request deadline bounds it | std should reject an invalid chunk size | +| a30 streaming threshold | Deliberate. Documented at the decision | Expose the threshold as configuration | +| httpz dispatch, pipelining, stalled-sender status | Inside httpz | The fork series already scoped | + +### Cases still to write + +Ingress: a17 oversize head, a18 chunked above the cap, a20 Expect 100-continue, +a23 resync after a local error, a25 half-close, a26 RST mid-body, a27 vanish +after forward, a34 encoding spellings (reduced), a36 gzip with two members, +a37 record above the scratch cap, a39 unframeable JSON, a41 policy drop-all. + +Egress: b14 keep-alive off, b15 HTTP/1.0 read-until-close, b16 bodiless +statuses, b17 response header flood, b18 slow-drip response, b19 slow-reading +intake, b20 accept then silence, b21 early rejection of a streamed body, +b22 intake restart, b25 redirect, b26 base path and query fidelity, b28 slow +dial warning, b29 scrape path faults. + +Capacity and lifecycle: c06 memory budget under saturation, c07 connection +churn, d04 startup with the intake down, d05 policy hot reload under load. + +New echo modes they need: `keep_alive_off`, `slow_read`, `accept_silence`, +`slow_body`, `header_flood`, `redirect`, `bodiless`, `http10_no_length`, and +the last request target reported in `/stats` for b26. + +Left out on purpose: anything that needs a particular platform or container +shape (the Linux run, the constrained-CPU profile, c10 descriptor exhaustion), +the framer and OTLP torture cases (unit tests), a29 (nondeterministic), a21 +(h2 cannot work against an HTTP/1 edge), c08 and c13 (runner modes). + +## This round: cases added and fixes made + +### Cases added (28, taking the suite to 81) + +Ingress: a17 oversize head, a20 Expect 100-continue, a23 resync after a local +error, a25 half-close, a26 RST mid-body, a27 vanish after forward, a34 encoding +spellings, a41 policy drop-all plus the rejected-pattern case. + +Egress: b14 keep-alive off, b15 HTTP/1.0 read-until-close, b16 bodiless +statuses, b17 response header flood, b18 slow-drip response, b19 slow-reading +intake, b20 accept then silence, b21 early rejection of a streamed body, +b22 intake restart, b25 redirect, b26 target fidelity, b29 scrape path faults. + +Capacity and lifecycle: c06 memory budget, c07 connection churn, d04 startup +with the intake down, d05 policy reload under load. + +New intake fault modes: `keep_alive_off`, `bodiless`, `redirect`, +`header_flood`, `http10_no_length`, `slow_body`, `slow_read`, +`accept_silence`, `read_then_close`, `truncate_after_read`, plus the last +request target in `/stats`. + +### Fixes made this round + +- **`/_health` and `/_edge/*` claim every method.** A HEAD probe is answered, + everything else gets 405, and neither reaches the intake. (a22) +- **Control paths are labelled by path, not by method**, so a HEAD probe is no + longer counted as data traffic. +- **stdio accepts an absolute-form target** and routes on its path, per + RFC 9112 §3.2.2, instead of forwarding the whole URL upstream. (a22) +- **stdio interrupts its inbound sockets on shutdown.** 30 s to under 2 s. (d03) +- **A decoded-size overrun fails open**; only the raw cap answers 413. (a35) +- **stdio keeps a control reserve.** Two slots are held back, and a connection + taken from the reserve serves one control request and closes. A health probe + now answers while the slab is full, instead of being shed and restarting the + sidecar during the spike. (c05) +- **httpz relays response headers up to our own cap.** Its default of 16 + silently truncated an intake answer, so a `Retry-After` on a 429 vanished + while the request still reported 202. (b17) + +### Corrections to earlier claims + +- **`.*` is not a policy bug.** Hyperscan refuses a pattern that can match an + empty buffer, so `.*` never compiles and `.+` or `^.*$` is the correct way to + say "everything". The real finding is narrower: the matcher builds nothing + (`policy_count=0`), while the loader reports `loaded_count=1 failed_count=0` + and `/_edge/policies` lists the policy as enabled. A rule that cannot compile + looks live. (a41) +- **b16 is stdio only.** httpz keeps a 204 bodiless; stdio re-frames it as + chunked. + +## Latest round: the two defects that were ours + +- **A rejected pattern is now named.** policy-zig already recorded the reason; + the edge never read it. `/_edge/policies` leads with + `# REJECTED id=: log: match[0]: invalid regex ".*"`, the gauge + `edge_policies_rejected` counts them, and `policies.rejected` warns when the + count changes. A rule that cannot compile no longer reads as live. (a41) +- **stdio keeps a bodiless status bodiless.** 204, 304 and 1xx answer directly + instead of opening a streamed body, so the relay no longer frames a chunked + body onto a status that must not have one. (b16) + +Everything else on the ledger needs a change in `std`, in httpz, or a product +decision about the streaming threshold. + +## A shed connection carries `Retry-After` + +A connection refused because the edge has no connection slot keeps its +`503 Service Unavailable` and now carries `Retry-After: 1`. Both shed paths +send it: the slab is full, and the Io implementation is at its task limit. + +503 is the honest status here, and 429 is not. Connection exhaustion is a +condition of the whole proxy, not an allowance we granted one sender. The OTLP +spec admits either status for an overloaded server and scopes `Retry-After` to +both, and the collector retries 429, 502, 503 and 504 alike, so the status +alone changes no client behaviour. What it does change is how a gateway reads +it: collectors in gateway mode use 429 for a non-retryable tenant limit, and +the edge is deployed as a gateway. The Datadog agent is equally indifferent to +the two, because it backs off on every error status except 400, 401, 403 and +413. + +So the header is the whole improvement. A sender that honours `Retry-After` +waits the stated interval instead of retrying at once. `SHED_RETRY_AFTER_SECONDS` +sets both the header and the fixed shed response, so the two cannot disagree. + +## Findings + +### Fixed + +1. **stdio never retried any batch.** Bodies below the streaming threshold are + resident now. Caught by b04, b09, b10. +2. **A header flood answered 502**, now 431. Caught by a14. The agent retries + both, so this is about diagnosis rather than agent behaviour. +3. **A retried dial was uncounted.** Caught by b01. +4. **The streamed policy path dropped a body it could not decode**, which the + agent would have discarded for good on the 400. It fails open now, with + `policy.failed.open`. Caught by a09. +5. **A truncated intake response was reported as 202.** Now + `UpstreamResponseTruncated`. See the challenge above for the nuance. +6. **httpz dropped headers above its own cap in silence.** Caught by a14. + +### From the backlog cases: fixed + +7. **`/_health` was GET-only, so every other method reached Datadog.** An ALB + or ECS check configured for HEAD tested the intake, not the edge, and + failed whenever the intake was unreachable. The route claims every method + now: 200 for GET and HEAD, 405 for the rest. `/_edge/*` had the same hole + and got the same treatment. Both frontends. (a22) +8. **stdio took 30 s to shut down with idle keep-alive connections**, against + httpz's 2 s, because cancellation does not reach a task parked in a poll, + so each connection waited out its own idle deadline. The slab now records + the socket per slot and `stopAccepting` interrupts them all, the same way + the upstream watchdog already did. Exit is under 2 s. (d03) +9. **A body that expanded past the decoded cap answered 413**, which the agent + discards for good. The two size limits are split now: the raw cap stays + 413, because the sender can act on it, and a decoded-size overrun fails + open, because the sender cannot see our decode budget. (a35) +10. **Control paths were labelled by method, so a HEAD health probe counted as + data traffic** in `edge_responses_total`. Found by the phantom-success + invariant while checking the fix for 7. `/_health` and `/_edge/*` are + labelled by path now. + +### From the backlog cases: documented, not fixed + +11. **A batch above the streaming threshold cannot be replayed**, so an intake + blip mid-exchange ends it with a 502. Deliberate: the agent retries a 5xx + with backoff, so the cost is a delay and a duplicate risk, not loss. + Making every batch replayable costs one `max_body_size` buffer per + concurrent request, which policy deployments already pay and passthrough + deployments do not. Recorded at the decision in `stdio/conn.zig` and in + the a30 case. Exposing the threshold as configuration is the follow-up. + +### From the backlog cases: still open + +12. **stdio forwards an absolute-form target upstream** as a path; httpz + refuses it with 400. (a22) +13. **Health is shed at capacity** rather than reserved, which restarts the + sidecar during the spike that filled it. (c05) + +### Open: needs a change in a dependency + +- httpz hands a batch of up to 16 requests to one pool thread (c02). +- httpz refuses a pipelined pair (a12). +- httpz closes a stalled sender with no status (a02, a03). +- stdio cannot accept an unknown content encoding, because `std.http.Server` + fails the whole head (a10). The agent drops the batch for good on that 400. +- stdio waits for the request deadline on a broken chunk (a07). diff --git a/bench/matrix/run.py b/bench/matrix/run.py new file mode 100644 index 00000000..aae4c1a4 --- /dev/null +++ b/bench/matrix/run.py @@ -0,0 +1,229 @@ +#!/usr/bin/env python3 +"""Runs the fault matrix against both frontends and prints where they differ. + + ./bin/uv run --with requests bench/matrix/run.py + ./bin/uv run --with requests bench/matrix/run.py --fast + ./bin/uv run --with requests bench/matrix/run.py --frontend stdio -k b05 + +Every case asserts what a customer needs. Neither frontend is the oracle, and +either can fail. A case may declare `DEFECTS = {frontend: note}` for behaviour +we have already found and recorded: it then reports as `xfail` with the note, +so the defect stays counted, and as `XPASS` on the day it is fixed. +""" + +from __future__ import annotations + +import argparse +import io +import os +import subprocess +import sys +import time +import unittest + +sys.stdout.reconfigure(line_buffering=True) + +HERE = os.path.dirname(os.path.abspath(__file__)) +REPO_ROOT = os.path.abspath(os.path.join(HERE, "..", "..")) +sys.path.insert(0, HERE) + +BINARIES = { + "httpz": os.path.join(REPO_ROOT, "zig-out", "bin", "edge"), + "stdio": os.path.join(REPO_ROOT, "zig-out-stdio", "bin", "edge"), +} + + +def build(frontends: list[str]) -> None: + zig = os.path.join(REPO_ROOT, "bin", "zig") + print("building: echo server with fault injection") + subprocess.run([zig, "build", "echo-server", "-Doptimize=ReleaseFast"], cwd=REPO_ROOT, check=True) + if "httpz" in frontends: + print("building: httpz frontend") + subprocess.run([zig, "build", "-Doptimize=ReleaseFast"], cwd=REPO_ROOT, check=True) + if "stdio" in frontends: + print("building: stdio frontend") + subprocess.run( + [zig, "build", "-Dfrontend=stdio", "-Doptimize=ReleaseFast", "--prefix", "zig-out-stdio"], + cwd=REPO_ROOT, + check=True, + ) + + +def load_suite(pattern: str | None) -> unittest.TestSuite: + loader = unittest.TestLoader() + suite = loader.discover(start_dir=os.path.join(HERE, "tests"), top_level_dir=HERE) + if not pattern: + return suite + picked = unittest.TestSuite() + for case in iterate(suite): + if pattern in case.id(): + picked.addTest(case) + return picked + + +def iterate(suite): + for item in suite: + if isinstance(item, unittest.TestSuite): + yield from iterate(item) + else: + yield item + + +def short_id(case_id: str) -> str: + """tests.test_b05_reject_early.RejectEarly.test_x -> b05 reject_early.test_x""" + parts = case_id.split(".") + module = parts[1] if len(parts) > 1 else parts[0] + name = module.replace("test_", "", 1) + return "%s.%s" % (name, parts[-1]) + + +def first_cause(trace: str) -> str: + """The assertion line, not the log dump an assertion message carries.""" + for line in trace.strip().splitlines(): + stripped = line.strip() + if stripped.startswith(("AssertionError", "Error", "RuntimeError", "self.fail")): + return stripped[:200] + if "Error:" in stripped and not stripped.startswith("File "): + return stripped[:200] + return trace.strip().splitlines()[-1][:200] + + +class Progress(unittest.TextTestResult): + """Prints each case as it finishes, so a slow sweep shows its progress.""" + + def __init__(self, frontend, *args): + super().__init__(*args) + self.frontend = frontend + self.started_at = 0.0 + + def startTest(self, test): + self.started_at = time.monotonic() + super().startTest(test) + + def _note(self, test, status): + print(" %-6s %-6s %.0fs %s" % ( + self.frontend, status, time.monotonic() - self.started_at, short_id(test.id()))) + + def addSuccess(self, test): + super().addSuccess(test) + self._note(test, "pass") + + def addFailure(self, test, err): + super().addFailure(test, err) + self._note(test, "FAIL") + + def addError(self, test, err): + super().addError(test, err) + self._note(test, "ERROR") + + def addSkip(self, test, reason): + super().addSkip(test, reason) + self._note(test, "skip") + + def addExpectedFailure(self, test, err): + super().addExpectedFailure(test, err) + self._note(test, "xfail") + + def addUnexpectedSuccess(self, test): + super().addUnexpectedSuccess(test) + self._note(test, "XPASS") + + +def run_one(frontend: str, pattern: str | None, fast: bool) -> dict[str, tuple[str, str]]: + os.environ["EDGE_BIN"] = BINARIES[frontend] + os.environ["EDGE_FRONTEND"] = frontend + if fast: + os.environ["MATRIX_FAST"] = "1" + else: + os.environ.pop("MATRIX_FAST", None) + + suite = load_suite(pattern) + # unittest drops its references to the cases as it runs them, so the + # names have to be collected first. + names = [short_id(case.id()) for case in iterate(suite)] + + stream = io.StringIO() + runner = unittest.TextTestRunner( + stream=stream, + verbosity=0, + resultclass=lambda *args: Progress(frontend, *args), + ) + started = time.monotonic() + result = runner.run(suite) + elapsed = time.monotonic() - started + + outcomes: dict[str, tuple[str, str]] = {name: ("pass", "") for name in names} + for case, trace in result.failures + result.errors: + outcomes[short_id(case.id())] = ("FAIL", first_cause(trace)) + for case, reason in result.skipped: + outcomes[short_id(case.id())] = ("skip", reason[:200]) + for case, note in result.expectedFailures: + outcomes[short_id(case.id())] = ("xfail", first_cause(note)) + for case in result.unexpectedSuccesses: + outcomes[short_id(case.id())] = ("XPASS", "the declared defect no longer reproduces; drop the DEFECTS note") + + print(" %s: %d cases in %.0f s" % (frontend, len(outcomes), elapsed)) + return outcomes + + +def main() -> int: + parser = argparse.ArgumentParser() + parser.add_argument("--frontend", choices=("stdio", "httpz", "both"), default="both") + parser.add_argument("--fast", action="store_true", help="skip the cases that wait for a 30 s deadline") + parser.add_argument("--skip-build", action="store_true") + parser.add_argument("-k", dest="pattern", help="substring filter on the case id") + args = parser.parse_args() + + frontends = ["stdio", "httpz"] if args.frontend == "both" else [args.frontend] + if not args.skip_build: + build(frontends) + + results = {frontend: run_one(frontend, args.pattern, args.fast) for frontend in frontends} + + names = sorted({name for outcomes in results.values() for name in outcomes}) + width = max((len(n) for n in names), default=10) + print("\n%-*s %s" % (width, "case", " ".join("%-8s" % f for f in frontends))) + print("-" * (width + 2 + 10 * len(frontends))) + failures: list[tuple[str, str, str]] = [] + for name in names: + cells = [] + for frontend in frontends: + status, detail = results[frontend].get(name, ("n/a", "")) + cells.append("%-8s" % status) + if status == "FAIL": + failures.append((name, frontend, detail)) + print("%-*s %s" % (width, name, " ".join(cells))) + + if failures: + print("\nfailures:") + for name, frontend, detail in failures: + print(" %s [%s]\n %s" % (name, frontend, detail)) + + known = [ + (name, frontend, results[frontend][name][1]) + for name in names + for frontend in frontends + if results[frontend].get(name, ("", ""))[0] == "xfail" + ] + if known: + print("\nknown defects that reproduced:") + for name, frontend, detail in known: + print(" %s [%s]\n %s" % (name, frontend, detail)) + + fixed = [ + (name, frontend) + for name in names + for frontend in frontends + if results[frontend].get(name, ("", ""))[0] == "XPASS" + ] + if fixed: + print("\nno longer failing (remove the DEFECTS note):") + for name, frontend in fixed: + print(" %s [%s]" % (name, frontend)) + + print("\n%d case(s), %d failure(s), %d known defect(s)" % (len(names), len(failures), len(known))) + return 1 if failures else 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/bench/matrix/tests/__init__.py b/bench/matrix/tests/__init__.py new file mode 100644 index 00000000..bfff4567 --- /dev/null +++ b/bench/matrix/tests/__init__.py @@ -0,0 +1 @@ +"""Fault matrix cases. One case per file, one class per case.""" diff --git a/bench/matrix/tests/test_a01_idle_connection.py b/bench/matrix/tests/test_a01_idle_connection.py new file mode 100644 index 00000000..4e48eddd --- /dev/null +++ b/bench/matrix/tests/test_a01_idle_connection.py @@ -0,0 +1,26 @@ +"""A01: a sender connects and never sends a byte. + +This is the case that wedged the stdio frontend before inbound deadlines +existed: 300 such sockets took every connection slot and the frontend never +served again. +""" + +from harness import MatrixCase + + +class IdleConnection(MatrixCase): + # Nothing was requested, so nothing may be blamed on the intake. + EXPECT_METRICS_FOR = {"stdio": {'edge_inbound_timeouts_total{phase="idle"}': 1}} + FORBID_LOGS = ["upstream", "request.failed"] + SLOW = True + + def test_idle_connection_is_reclaimed(self): + with self.raw(timeout=60) as client: + answer = client.read_response() + + # The edge closes rather than answering: no request ever arrived. + self.assertTrue(answer.closed or answer.status is None, repr(answer)) + self.assertLess(answer.seconds, 45, "the idle socket was never reclaimed") + + if self.frontend == "stdio": + self.wait_for_metric('edge_inbound_timeouts_total{phase="idle"}', 1, timeout=5) diff --git a/bench/matrix/tests/test_a02_partial_head.py b/bench/matrix/tests/test_a02_partial_head.py new file mode 100644 index 00000000..57cab442 --- /dev/null +++ b/bench/matrix/tests/test_a02_partial_head.py @@ -0,0 +1,23 @@ +"""A02: a sender delivers part of a head, then stalls. + +No request is complete, but the sender is waiting for an answer, so the edge +must not close in silence. +""" + +from harness import MatrixCase + + +class PartialHead(MatrixCase): + EXPECT_PERMANENT_DROP = True + EXPECT_METRICS_FOR = {"stdio": {'edge_inbound_timeouts_total{phase="request"}': 1}} + EXPECT_LOGS_FOR = {"stdio": ["inbound.timeout"]} + FORBID_LOGS = ["upstream"] + SLOW = True + DEFECTS = {"httpz": "closes the connection with no status, so the sender cannot tell a timeout from a crash"} + + def test_partial_head_is_answered(self): + with self.raw(timeout=60) as client: + client.send(b"POST /api/v2/logs HTTP/1.1\r\nHost: 127.0.0.1\r\n") + answer = client.read_response() + + self.assert_status(answer, 408, "a stalled head must be answered") diff --git a/bench/matrix/tests/test_a03_short_body.py b/bench/matrix/tests/test_a03_short_body.py new file mode 100644 index 00000000..99a86626 --- /dev/null +++ b/bench/matrix/tests/test_a03_short_body.py @@ -0,0 +1,20 @@ +"""A03: the head declares more body than the sender delivers.""" + +from harness import MatrixCase + + +class ShortBody(MatrixCase): + EXPECT_PERMANENT_DROP = True + EXPECT_METRICS_FOR = {"stdio": {'edge_inbound_timeouts_total{phase="request"}': 1}} + EXPECT_LOGS_FOR = {"stdio": ["request.failed", "InboundBodyTimeout"]} + FORBID_LOGS = ["upstream"] + SLOW = True + DEFECTS = {"httpz": "closes the connection with no status"} + + def test_short_body_is_answered(self): + with self.raw(timeout=60) as client: + client.send(self.head(body_len=500)) + client.send(b'[{"message":"only the start') + answer = client.read_response() + + self.assert_status(answer, 408, "a stalled body must be answered") diff --git a/bench/matrix/tests/test_a04_slow_drip_body.py b/bench/matrix/tests/test_a04_slow_drip_body.py new file mode 100644 index 00000000..c043c514 --- /dev/null +++ b/bench/matrix/tests/test_a04_slow_drip_body.py @@ -0,0 +1,44 @@ +"""A04: the sender never stops, and never finishes. + +The edge must stop reading and free the slot. Whether the sender learns that +through a 408 or through a closed socket depends on how far its own write +buffer got, so both count. + +Both frontends pass: httpz measures its request timeout from accept, not per +read, so it catches a small dribbled body too. Its per-read timeout only +restarts for a body above `lazy_read_size`, which a handler thread reads. +""" + +import socket +import time + +from harness import MatrixCase + + +class SlowDripBody(MatrixCase): + EXPECT_PERMANENT_DROP = True + EXPECT_METRICS_FOR = {"stdio": {'edge_inbound_timeouts_total{phase="request"}': 1}} + FORBID_LOGS = ["upstream"] + SLOW = True + + def test_a_dribbling_sender_is_cut_off(self): + body = b'[{"message":"' + b"x" * 30 + b'"}]' + cut_off_after = None + answer = None + with self.raw(timeout=90) as client: + client.send(self.head(body_len=len(body) + 200)) + started = time.monotonic() + try: + for i in range(len(body)): + client.send(body[i : i + 1]) + time.sleep(1.0) + else: + answer = client.read_response() + except (BrokenPipeError, ConnectionResetError, socket.timeout, OSError): + cut_off_after = time.monotonic() - started + + if answer is not None and answer.status is not None: + self.assert_status(answer, 408, "a dribbling sender must be answered") + return + self.assertIsNotNone(cut_off_after, "the sender was never cut off") + self.assertLess(cut_off_after, 45, "the request deadline fired far too late") diff --git a/bench/matrix/tests/test_a05_unframed_body.py b/bench/matrix/tests/test_a05_unframed_body.py new file mode 100644 index 00000000..58651620 --- /dev/null +++ b/bench/matrix/tests/test_a05_unframed_body.py @@ -0,0 +1,17 @@ +"""A05: POST with neither Content-Length nor chunked framing.""" + +from harness import MatrixCase + + +class UnframedBody(MatrixCase): + EXPECT_PERMANENT_DROP = True + def test_unframed_post_gets_an_answer(self): + with self.raw(timeout=40) as client: + client.send(b"POST /api/v2/logs HTTP/1.1\r\nHost: 127.0.0.1\r\n" + b"Content-Type: application/json\r\n\r\n") + answer = client.read_response() + + # Either a status or a close is acceptable. A hang is not. + self.assertLess(answer.seconds, 35, "an unframed body must not hang") + if answer.status is not None: + self.assertIn(answer.status, (202, 400, 411), repr(answer)) diff --git a/bench/matrix/tests/test_a06_chunked_body.py b/bench/matrix/tests/test_a06_chunked_body.py new file mode 100644 index 00000000..f32ef398 --- /dev/null +++ b/bench/matrix/tests/test_a06_chunked_body.py @@ -0,0 +1,18 @@ +"""A06: a well-formed chunked request, which agents send when streaming.""" + +from harness import MatrixCase + + +class ChunkedBody(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 1} + FORBID_LOGS = ["request.failed"] + def test_chunked_body_reaches_the_intake(self): + payload = b'[{"message":"chunked","ddsource":"matrix"}]' + framed = b"%x\r\n%s\r\n0\r\n\r\n" % (len(payload), payload) + with self.raw(timeout=30) as client: + client.send(self.head(body_len=None, extra="Transfer-Encoding: chunked")) + client.send(framed) + answer = client.read_response() + + self.assert_status(answer, 202) + self.assertGreaterEqual(self.intake_saw(1), 1, "the intake never saw the batch") diff --git a/bench/matrix/tests/test_a07_chunked_invalid.py b/bench/matrix/tests/test_a07_chunked_invalid.py new file mode 100644 index 00000000..9ed799f7 --- /dev/null +++ b/bench/matrix/tests/test_a07_chunked_invalid.py @@ -0,0 +1,25 @@ +"""A07: a chunk size that is not a number. + +The head is complete and the framing is broken, so the edge can answer at +once. Waiting for the request deadline holds a connection slot for 30 s on +input we have already proven bad. +""" + +from harness import MatrixCase + + +class ChunkedInvalid(MatrixCase): + EXPECT_PERMANENT_DROP = True + FORBID_LOGS = ["upstream"] + SLOW = True + DEFECTS = {"stdio": "waits for the request deadline instead of rejecting the bad chunk"} + + def test_invalid_chunk_is_rejected_promptly(self): + with self.raw(timeout=60) as client: + client.send(self.head(body_len=None, extra="Transfer-Encoding: chunked")) + client.send(b"zzzz\r\ngarbage\r\n") + answer = client.read_response() + + self.assertLess(answer.seconds, 5, "broken framing should not hold a slot") + if answer.status is not None: + self.assertEqual(answer.status // 100, 4, repr(answer)) diff --git a/bench/matrix/tests/test_a08_body_too_large.py b/bench/matrix/tests/test_a08_body_too_large.py new file mode 100644 index 00000000..5b25ae64 --- /dev/null +++ b/bench/matrix/tests/test_a08_body_too_large.py @@ -0,0 +1,16 @@ +"""A08: a batch above max_body_size.""" + +from harness import MatrixCase + + +class BodyTooLarge(MatrixCase): + EXPECT_PERMANENT_DROP = True + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s4xx"}': 1} + EXPECT_LOGS = ["request.failed", "BodyTooLarge"] + FORBID_LOGS = ["upstream"] + EDGE_CONFIG = {"max_body_size": 16384} + + def test_oversize_body_is_rejected(self): + response = self.post_raw_body(b"x" * 65536) + self.assert_status(response, 413, "an oversize body must be refused") + self.assertEqual(self.intake_saw(1, timeout=2), 0, "an oversize body reached the intake") diff --git a/bench/matrix/tests/test_a09_corrupt_gzip.py b/bench/matrix/tests/test_a09_corrupt_gzip.py new file mode 100644 index 00000000..da5d0ee5 --- /dev/null +++ b/bench/matrix/tests/test_a09_corrupt_gzip.py @@ -0,0 +1,45 @@ +"""A09: a body that claims gzip and is not. + +The edge is a proxy, not a judge of the payload. A body it cannot decode must +still reach the intake, which is the only party that can accept or reject it. +The edge must never be the reason a batch disappears. +""" + +from harness import MatrixCase + + +class CorruptGzip(MatrixCase): + def test_an_undecodable_body_still_reaches_the_intake(self): + response = self.post_raw_body( + b"\x1f\x8b\x08\x00 not really gzip at all", + headers={"Content-Encoding": "gzip"}, + ) + self.assertGreaterEqual(self.intake_saw(1), 1, "the batch was dropped by the edge") + self.assertEqual(response.status_code, 202, "the intake's answer must be relayed") + + +class CorruptGzipWithPolicies(MatrixCase): + """The same body with policies loaded, so the decode path actually runs.""" + + EXPECT_LOGS = ["policy.failed.open"] + EDGE_POLICIES = { + "policies": [ + { + "id": "keep-all", + "name": "keep-all", + "log": {"match": [{"log_field": "body", "regex": ".*"}], "keep": "all"}, + } + ] + } + + def test_a_body_the_policy_path_cannot_decode_fails_open(self): + response = self.post_raw_body( + b"\x1f\x8b\x08\x00 not really gzip at all", + headers={"Content-Encoding": "gzip"}, + ) + self.assertGreaterEqual( + self.intake_saw(1), + 1, + "a body the policy path could not decode was dropped instead of forwarded", + ) + self.assertEqual(response.status_code, 202) diff --git a/bench/matrix/tests/test_a10_unsupported_encoding.py b/bench/matrix/tests/test_a10_unsupported_encoding.py new file mode 100644 index 00000000..65aaf22c --- /dev/null +++ b/bench/matrix/tests/test_a10_unsupported_encoding.py @@ -0,0 +1,31 @@ +"""A10: an encoding the edge cannot decode. + +`service/datadog` documents the intent, and the router honours it: an +unsupported content encoding plans `forward_raw`, so no policy reads the body +and the batch still goes to the intake. + +httpz does exactly that. Verified against a lenient intake: a brotli batch +comes back 200, relayed from upstream. It cannot be asserted here, because our +own intake is `std.http.Server` based and refuses the head for the same reason +stdio does. + +stdio cannot accept the request at all. `std.http.Server` maps +`content-encoding` through `ContentEncoding.fromString`, and anything outside +its five known values fails the whole head with `HttpHeadersInvalid`. There is +no distinct error, so we cannot tell an unknown encoding from a malformed +head, and the sender gets 400. An agent using brotli would retry it forever. +""" + +from harness import MatrixCase + + +class UnsupportedEncoding(MatrixCase): + DEFECTS = {"stdio": "std.http.Server refuses the head, so the batch is dropped with 400"} + FORBID_LOGS = ["upstream.timed.out"] + + def test_unknown_encoding_forwards_raw(self): + if self.frontend == "httpz": + self.skipTest("our std-based intake refuses brotli; httpz verified against a lenient one") + response = self.post_raw_body(b'[{"message":"brotli"}]', headers={"Content-Encoding": "br"}) + self.assert_status(response, 202, "an unsupported encoding must forward, not drop") + self.assertGreaterEqual(self.intake_saw(1), 1, "the batch never reached the intake") diff --git a/bench/matrix/tests/test_a11_client_disconnect.py b/bench/matrix/tests/test_a11_client_disconnect.py new file mode 100644 index 00000000..1d4bab5c --- /dev/null +++ b/bench/matrix/tests/test_a11_client_disconnect.py @@ -0,0 +1,21 @@ +"""A11: the sender vanishes mid-body. + +Nothing to answer, but the slot must come back and the upstream connection +must not leak. +""" + +from harness import MatrixCase + + +class ClientDisconnect(MatrixCase): + FORBID_LOGS = ["upstream.timed.out"] + def test_disconnect_frees_the_slot(self): + for _ in range(5): + client = self.raw(timeout=10) + client.send(self.head(body_len=4096)) + client.send(b'[{"message":"half') + client.close() + + # The invariants in tearDown carry the assertion: the edge still + # serves, and no connection slot leaked. + self.assertEqual(self.health().status_code, 200) diff --git a/bench/matrix/tests/test_a12_pipelined.py b/bench/matrix/tests/test_a12_pipelined.py new file mode 100644 index 00000000..fd786973 --- /dev/null +++ b/bench/matrix/tests/test_a12_pipelined.py @@ -0,0 +1,22 @@ +"""A12: two requests written in one packet. + +Pipelining is legal HTTP/1.1. An agent that reconnects under load can produce +it, and rejecting the pair loses the second batch. +""" + +from harness import MatrixCase + + +class Pipelined(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 2} + DEFECTS = {"httpz": "answers 400 to a pipelined pair"} + + def test_pipelined_requests_are_both_served(self): + body = b'[{"message":"pipelined"}]' + one = self.head(body_len=len(body)) + body + with self.raw(timeout=30) as client: + client.send(one + one) + first = client.read_response() + self.assert_status(first, 202) + + self.assertGreaterEqual(self.intake_saw(2), 2, "the second pipelined batch was lost") diff --git a/bench/matrix/tests/test_a13_keepalive_reuse.py b/bench/matrix/tests/test_a13_keepalive_reuse.py new file mode 100644 index 00000000..ca141586 --- /dev/null +++ b/bench/matrix/tests/test_a13_keepalive_reuse.py @@ -0,0 +1,27 @@ +"""A13: many requests on one connection, the way an agent actually sends.""" + +import requests + +from harness import MatrixCase + + +class KeepaliveReuse(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 50} + FORBID_LOGS = ["request.failed"] + def test_one_connection_serves_many_requests(self): + session = requests.Session() + try: + for _ in range(50): + response = session.post( + self.edge.url + "/api/v2/logs", + json=[{"message": "keepalive"}], + timeout=30, + ) + self.assertEqual(response.status_code, 202) + finally: + session.close() + + self.assertGreaterEqual(self.intake_saw(50), 50) + if self.frontend == "stdio": + # 50 requests, but the sender opened one connection. + self.assertLessEqual(self.metric_delta("edge_connections_total"), 4) diff --git a/bench/matrix/tests/test_a14_too_many_headers.py b/bench/matrix/tests/test_a14_too_many_headers.py new file mode 100644 index 00000000..b270d52b --- /dev/null +++ b/bench/matrix/tests/test_a14_too_many_headers.py @@ -0,0 +1,25 @@ +"""A14: more headers than the edge will carry. + +Two answers are defensible: forward every header, or refuse the request. What +is not defensible is accepting the request, dropping the headers above the cap +and answering 202, because the sender then believes an API key or a trace +header was forwarded when it was not. +""" + +from harness import MatrixCase + + +class TooManyHeaders(MatrixCase): + EXPECT_PERMANENT_DROP = True + EXPECT_LOGS = ["request.failed", "TooManyHeaders"] + FORBID_LOGS = ["upstream"] + + def test_a_header_flood_is_never_silently_truncated(self): + headers = {"X-Matrix-%d" % i: "v" for i in range(80)} + response = self.post_logs(headers=headers) + self.assertEqual( + response.status_code // 100, + 4, + "headers above the cap must be refused, not dropped in silence " + "(got %d)" % response.status_code, + ) diff --git a/bench/matrix/tests/test_a15_garbage_request.py b/bench/matrix/tests/test_a15_garbage_request.py new file mode 100644 index 00000000..3f5b1251 --- /dev/null +++ b/bench/matrix/tests/test_a15_garbage_request.py @@ -0,0 +1,25 @@ +"""A15: bytes that are not HTTP, such as a TLS hello on the plaintext port.""" + +from harness import MatrixCase + + +class GarbageRequest(MatrixCase): + EXPECT_PERMANENT_DROP = True + SLOW = True + + def test_a_complete_but_invalid_head_is_rejected(self): + with self.raw(timeout=30) as client: + client.send(b"\x16\x03\x01\x02\x00 not a request line\r\nAlso: not a header\r\n\r\n") + answer = client.read_response() + + self.assertLess(answer.seconds, 25, "an invalid head must be rejected at once") + if answer.status is not None: + self.assertEqual(answer.status, 400, repr(answer)) + + def test_an_incomplete_head_is_bounded_by_the_deadline(self): + with self.raw(timeout=60) as client: + client.send(b"\x16\x03\x01\x02\x00\x01\x00\x01\xfc") + answer = client.read_response() + + # Nothing here completes a head, so the deadline is the only bound. + self.assertLess(answer.seconds, 45, "garbage held the slot past the deadline") diff --git a/bench/matrix/tests/test_a16_zstd_body.py b/bench/matrix/tests/test_a16_zstd_body.py new file mode 100644 index 00000000..7b37d568 --- /dev/null +++ b/bench/matrix/tests/test_a16_zstd_body.py @@ -0,0 +1,33 @@ +"""A16: a zstd batch, which is what a current Datadog agent sends. + +The codec is supported inside the pipeline, so this checks the transport: the +frontend must accept the head and hand the body over for decoding. +""" + +from harness import MatrixCase + +def _compress(raw: bytes): + try: + from compression import zstd # python 3.14 and later + + return zstd.compress(raw) + except ImportError: + pass + try: + import zstandard + + return zstandard.ZstdCompressor().compress(raw) + except ImportError: + return None + + +class ZstdBody(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 1} + FORBID_LOGS = ["request.failed"] + def test_zstd_batch_is_accepted(self): + payload = _compress(b'[{"message":"zstd batch","ddsource":"matrix"}]') + if payload is None: + self.skipTest("no zstd binding; run the suite with --with zstandard") + response = self.post_raw_body(payload, headers={"Content-Encoding": "zstd"}) + self.assert_status(response, 202, "a zstd batch must be accepted") + self.assertGreaterEqual(self.intake_saw(1), 1, "the batch never reached the intake") diff --git a/bench/matrix/tests/test_a17_oversize_head.py b/bench/matrix/tests/test_a17_oversize_head.py new file mode 100644 index 00000000..2fd5cca5 --- /dev/null +++ b/bench/matrix/tests/test_a17_oversize_head.py @@ -0,0 +1,35 @@ +"""A17: a head larger than the receive buffer. + +One enormous header value, and many merely large ones. The edge owes a prompt +client error and a closed connection, not a 502 that blames the intake and not +a hang. +""" + +from harness import MatrixCase + + +class OversizeHead(MatrixCase): + EXPECT_PERMANENT_DROP = True + FORBID_LOGS = ["upstream"] + + def test_one_enormous_header_is_refused(self): + with self.raw(timeout=30) as client: + client.send( + b"POST /api/v2/logs HTTP/1.1\r\nHost: 127.0.0.1\r\n" + b"X-Huge: " + b"a" * (24 * 1024) + b"\r\n\r\n" + ) + answer = client.read_response() + + self.assertLess(answer.seconds, 10, "an oversize head must be refused at once") + if answer.status is not None: + self.assertIn(answer.status, (400, 431), repr(answer)) + self.assertEqual(self.intake.requests_seen(), 0, "an oversize head reached the intake") + + def test_many_large_headers_are_refused(self): + headers = b"".join(b"X-Pad-%d: %s\r\n" % (i, b"b" * 1024) for i in range(40)) + with self.raw(timeout=30) as client: + client.send(b"POST /api/v2/logs HTTP/1.1\r\nHost: 127.0.0.1\r\n" + headers + b"\r\n") + answer = client.read_response() + + self.assertLess(answer.seconds, 10) + self.assertEqual(self.intake.requests_seen(), 0) diff --git a/bench/matrix/tests/test_a19_framing_conflicts.py b/bench/matrix/tests/test_a19_framing_conflicts.py new file mode 100644 index 00000000..43417bcf --- /dev/null +++ b/bench/matrix/tests/test_a19_framing_conflicts.py @@ -0,0 +1,37 @@ +"""A19: framing the edge must refuse. + +Content-Length together with chunked, two different lengths, a length that is +not a number. This is the request-smuggling surface: whatever status we pick, +the request must not reach the intake, and the two frontends must agree. +""" + +from harness import MatrixCase + +CONFLICTS = { + "length_and_chunked": b"Content-Length: 18\r\nTransfer-Encoding: chunked", + "two_lengths": b"Content-Length: 18\r\nContent-Length: 7", + "negative_length": b"Content-Length: -1", + "not_a_number": b"Content-Length: abc", + "twenty_digits": b"Content-Length: 99999999999999999999", +} + + +class FramingConflicts(MatrixCase): + EXPECT_PERMANENT_DROP = True + def test_conflicting_framing_never_reaches_the_intake(self): + body = b'[{"message":"x"}]' + for name, framing in CONFLICTS.items(): + with self.subTest(framing=name): + with self.raw(timeout=20) as client: + client.send( + b"POST /api/v2/logs HTTP/1.1\r\nHost: 127.0.0.1\r\n" + b"Content-Type: application/json\r\n" + framing + b"\r\n\r\n" + body + ) + answer = client.read_response() + if answer.status is not None: + self.assertEqual( + answer.status // 100, + 4, + "%s owes a client error, got %s" % (name, answer.status), + ) + self.assertEqual(self.intake.requests_seen(), 0, "ambiguous framing reached the intake") diff --git a/bench/matrix/tests/test_a20_expect_continue.py b/bench/matrix/tests/test_a20_expect_continue.py new file mode 100644 index 00000000..5af077f6 --- /dev/null +++ b/bench/matrix/tests/test_a20_expect_continue.py @@ -0,0 +1,27 @@ +"""A20: a sender that waits for 100-continue before it sends the body. + +A strict client holds the body until the interim answer arrives. If the edge +never sends it, the sender stalls until its own timeout and the batch is late +or lost. `Expect` is also hop-by-hop: it must not travel to the intake. +""" + +from harness import MatrixCase + + +class ExpectContinue(MatrixCase): + def test_the_interim_answer_arrives_then_the_batch_lands(self): + body = b'[{"message":"expect"}]' + with self.raw(timeout=30) as client: + client.send(self.head(body_len=len(body), extra="Expect: 100-continue")) + interim = client.read_response() + self.assertIsNotNone(interim.status, "no interim answer, so a strict sender stalls") + if interim.status == 100: + client.send(body) + final = client.read_response() + self.assertEqual(final.status, 202, repr(final)) + else: + # Some servers answer the final status directly, which is also + # workable as long as the sender is not left waiting. + self.assertLess(interim.seconds, 5) + + self.assertGreaterEqual(self.intake_saw(1), 1, "the batch never reached the intake") diff --git a/bench/matrix/tests/test_a22_health_methods.py b/bench/matrix/tests/test_a22_health_methods.py new file mode 100644 index 00000000..7385951d --- /dev/null +++ b/bench/matrix/tests/test_a22_health_methods.py @@ -0,0 +1,59 @@ +"""A22: a health check that is not a GET, and a proxy-form target. + +`/_health` is registered GET-only, so any other method falls through to the +wildcard passthrough and is forwarded to the intake. An ALB or ECS check +configured for HEAD therefore does not test the edge at all: it tests Datadog, +and it fails whenever the intake is unreachable. That is the same failure mode +as the incident this suite exists for. +""" + +import requests + +from harness import MatrixCase + + +class HealthMethods(MatrixCase): + + def test_head_health_is_answered_locally(self): + before = self.intake.requests_seen() + try: + status = requests.head(self.edge.url + "/_health", timeout=10).status_code + except requests.exceptions.RequestException as err: + self.fail("HEAD /_health was not answered: %s" % type(err).__name__) + self.assertEqual(status, 200, "a HEAD probe must answer from the edge") + self.assertEqual( + self.intake.requests_seen(), + before, + "a health probe was forwarded to the intake", + ) + + +class HealthMethodsPost(MatrixCase): + + def test_post_health_does_not_reach_the_intake(self): + before = self.intake.requests_seen() + requests.post(self.edge.url + "/_health", data=b"", timeout=10) + self.assertEqual( + self.intake.requests_seen(), + before, + "POST /_health was forwarded to the intake as passthrough traffic", + ) + + +class AbsoluteFormTarget(MatrixCase): + + def test_absolute_form_target_is_not_forwarded_verbatim(self): + before = self.intake.requests_seen() + with self.raw(timeout=20) as client: + client.send( + b"GET http://example.com/_health HTTP/1.1\r\nHost: x\r\n" + b"Connection: close\r\n\r\n" + ) + answer = client.read_response() + # Either we answer health locally or we refuse it. Forwarding a + # mangled target to the intake is the one wrong answer. + self.assertEqual( + self.intake.requests_seen(), + before, + "an absolute-form target was forwarded to the intake (status %s)" % answer.status, + ) diff --git a/bench/matrix/tests/test_a23_resync_after_local_error.py b/bench/matrix/tests/test_a23_resync_after_local_error.py new file mode 100644 index 00000000..955a8200 --- /dev/null +++ b/bench/matrix/tests/test_a23_resync_after_local_error.py @@ -0,0 +1,40 @@ +"""A23: a request the edge answers itself, with a body still on the wire. + +After a 413 the rest of the body is still arriving. If the edge keeps the +connection and parses those leftover bytes as the next request, the following +batch dies with a bogus 400. Either a closed connection or a served second +request is correct; a 400 on the second request is not. +""" + +from harness import MatrixCase + + +class ResyncAfterLocalError(MatrixCase): + EDGE_CONFIG = {"max_body_size": 4096} + EXPECT_PERMANENT_DROP = True + + def test_the_next_request_is_not_parsed_out_of_leftover_bytes(self): + oversize = b"x" * 65536 + good = b'[{"message":"after"}]' + with self.raw(timeout=30) as client: + client.send(self.head(body_len=len(oversize))) + try: + client.send(oversize) + except OSError: + pass # the edge answered and closed mid-send, which is correct + first = client.read_response() + self.assertEqual(first.status, 413, repr(first)) + + try: + client.send(self.head(body_len=len(good)) + good) + except OSError: + # A closed connection is one of the two correct answers. + return + second = client.read_response() + + if second.status is not None: + self.assertNotEqual( + second.status, + 400, + "the second request was parsed out of the first body's leftovers", + ) diff --git a/bench/matrix/tests/test_a25_client_half_close.py b/bench/matrix/tests/test_a25_client_half_close.py new file mode 100644 index 00000000..8f84c51b --- /dev/null +++ b/bench/matrix/tests/test_a25_client_half_close.py @@ -0,0 +1,21 @@ +"""A25: the sender shuts down its write side and waits for the answer. + +A half-close is not a disconnect. A server that treats the FIN as one drops a +batch the intake may already have accepted. +""" + +import socket + +from harness import MatrixCase + + +class ClientHalfClose(MatrixCase): + def test_a_half_closed_sender_still_gets_its_answer(self): + body = b'[{"message":"half-close"}]' + with self.raw(timeout=30) as client: + client.send(self.head(body_len=len(body)) + body) + client.sock.shutdown(socket.SHUT_WR) + answer = client.read_response() + + self.assert_status(answer, 202, "a half-closed sender was dropped") + self.assertGreaterEqual(self.intake_saw(1), 1) diff --git a/bench/matrix/tests/test_a26_client_reset.py b/bench/matrix/tests/test_a26_client_reset.py new file mode 100644 index 00000000..a28db9ab --- /dev/null +++ b/bench/matrix/tests/test_a26_client_reset.py @@ -0,0 +1,24 @@ +"""A26: the sender resets the connection mid-body. + +The same shape as a disconnect, but an RST rather than a FIN. Slots must come +back and nothing may blame the intake. +""" + +import socket +import struct + +from harness import MatrixCase + + +class ClientReset(MatrixCase): + def test_resets_free_their_slots(self): + for _ in range(5): + client = self.raw(timeout=10) + client.send(self.head(body_len=8192)) + client.send(b'[{"message":"partial') + client.sock.setsockopt( + socket.SOL_SOCKET, socket.SO_LINGER, struct.pack("ii", 1, 0) + ) + client.close() + + self.assertEqual(self.health().status_code, 200) diff --git a/bench/matrix/tests/test_a27_client_vanishes_after_forward.py b/bench/matrix/tests/test_a27_client_vanishes_after_forward.py new file mode 100644 index 00000000..b16bd37f --- /dev/null +++ b/bench/matrix/tests/test_a27_client_vanishes_after_forward.py @@ -0,0 +1,28 @@ +"""A27: the sender leaves while the intake is still working. + +The batch is already on its way, so it must be delivered exactly once, the +undeliverable answer must be logged, and there must be no retry: the intake +has it. +""" + +import threading +import time + +from harness import MatrixCase + + +class ClientVanishesAfterForward(MatrixCase): + INTAKE_LATENCY = 2000 + ALLOW_PHANTOM_SUCCESS = True + + def test_the_batch_is_delivered_once_and_the_loss_is_logged(self): + body = b'[{"message":"vanishing"}]' + client = self.raw(timeout=30) + client.send(self.head(body_len=len(body)) + body) + time.sleep(0.5) # the exchange is open against the slow intake + client.close() + time.sleep(3.5) + + delivered = self.intake.requests_seen() - self.baseline_intake + self.assertEqual(delivered, 1, "the batch was delivered %d times" % delivered) + self.assertEqual(self.metric_delta("edge_upstream_retries_total"), 0, "a vanished sender caused a retry") diff --git a/bench/matrix/tests/test_a30_streaming_boundary.py b/bench/matrix/tests/test_a30_streaming_boundary.py new file mode 100644 index 00000000..c8d0d67b --- /dev/null +++ b/bench/matrix/tests/test_a30_streaming_boundary.py @@ -0,0 +1,38 @@ +"""A30: a batch either side of the streaming threshold. + +A body at or below the threshold stays resident and can be replayed after a +transport failure. A larger one streams, is consumed by its first send, and +cannot be retried, so an intake blip mid-exchange becomes a 502. + +Deliberate, and documented rather than fixed. The agent retries a 5xx with +backoff (harness/agent.py), so the cost is a delayed batch and a duplicate +risk, not lost data. Making every batch replayable means holding up to +`max_body_size` per concurrent request, which is the memory a policy +deployment already pays and a passthrough deployment does not. +""" + +import json + +from harness import MatrixCase + + +class BelowTheStreamingThreshold(MatrixCase): + def test_a_resident_batch_survives_a_mid_exchange_failure(self): + body = json.dumps([{"message": "x" * 60 * 1024}]).encode() + self.intake.arm("close_early", count=1) + response = self.post_raw_body(body, timeout=60) + self.assert_status(response, 202, "a resident batch must be replayed") + self.assertGreaterEqual(self.metric_delta("edge_upstream_retries_total"), 1) + + +class AboveTheStreamingThreshold(MatrixCase): + DEFECTS = { + "stdio": "a streamed batch cannot be replayed, so a mid-exchange failure loses it", + "httpz": "a streamed batch cannot be replayed, so a mid-exchange failure loses it", + } + + def test_a_streamed_batch_survives_a_mid_exchange_failure(self): + body = json.dumps([{"message": "x" * 300 * 1024}]).encode() + self.intake.arm("close_early", count=1) + response = self.post_raw_body(body, timeout=60) + self.assert_status(response, 202, "a batch above the threshold is lost on one blip") diff --git a/bench/matrix/tests/test_a34_encoding_spellings.py b/bench/matrix/tests/test_a34_encoding_spellings.py new file mode 100644 index 00000000..f83031b2 --- /dev/null +++ b/bench/matrix/tests/test_a34_encoding_spellings.py @@ -0,0 +1,52 @@ +"""A34: the spellings of an encoding an agent may send. + +stdio maps `content-encoding` through a std enum and httpz passes the raw +string to the router, so the two can disagree about the same header. Policies +are loaded, so the decode path actually runs. +""" + +import gzip +import json + +from harness import MatrixCase + +BATCH = json.dumps([{"message": "spelling", "ddsource": "matrix"}]).encode() + + +class EncodingSpellings(MatrixCase): + # Content codings are case-insensitive (RFC 9110 §8.4.1), but + # `std.http.Server` matches them case-sensitively, so stdio refuses + # `GZIP` with a 400 — which the agent discards for good. + DEFECTS = {"stdio": "refuses an uppercase content-encoding with 400"} + EDGE_POLICIES = { + "policies": [ + { + "id": "keep-all", + "name": "keep-all", + "log": {"match": [{"log_field": "body", "regex": ".*"}], "keep": "all"}, + } + ] + } + + def test_every_gzip_spelling_reaches_the_intake(self): + spellings = ("gzip", "GZIP", "x-gzip", "gzip ") + if self.frontend == "httpz": + # httpz forwards the raw string, so the case would only prove that + # our own std-based intake refuses `GZIP`, as in a10. + spellings = ("gzip", "x-gzip", "gzip ") + for spelling in spellings: + with self.subTest(spelling=spelling): + before = self.intake.requests_seen() + response = self.post_raw_body( + gzip.compress(BATCH), headers={"Content-Encoding": spelling} + ) + self.assertEqual( + response.status_code, + 202, + "%r answered %d" % (spelling, response.status_code), + ) + self.assertGreater( + self.intake.requests_seen(), + before, + "%r never reached the intake" % spelling, + ) diff --git a/bench/matrix/tests/test_a35_decompression_bomb.py b/bench/matrix/tests/test_a35_decompression_bomb.py new file mode 100644 index 00000000..6dd9924a --- /dev/null +++ b/bench/matrix/tests/test_a35_decompression_bomb.py @@ -0,0 +1,51 @@ +"""A35: a small body that expands past the decoded cap. + +With policies loaded the edge must decode to evaluate, so a bomb is a memory +question. Bounded rejection is the requirement; an unbounded decode is not. +Without policies the same body must forward untouched, since nothing reads it. +""" + +import gzip +import time + +from harness import MatrixCase + +BOMB = gzip.compress(b"[" + b'{"message":"' + b"a" * (40 * 1024 * 1024) + b'"}' + b"]") + + +class DecompressionBombWithPolicies(MatrixCase): + # The agent discards a payload for good on 413 (harness/agent.py), so a + # decode budget the sender cannot see must not end the batch. The policy + # paths fail open instead, and this case holds that line. + EDGE_CONFIG = {"max_body_size": 1048576, "max_decoded_bytes": 1048576} + EDGE_POLICIES = { + "policies": [ + { + "id": "keep-all", + "name": "keep-all", + "log": {"match": [{"log_field": "body", "regex": ".*"}], "keep": "all"}, + } + ] + } + ALLOW_PHANTOM_SUCCESS = True + + def test_a_bomb_is_bounded(self): + started = time.monotonic() + response = self.post_raw_body(BOMB, headers={"Content-Encoding": "gzip"}, timeout=60) + elapsed = time.monotonic() - started + self.assertLess(elapsed, 30, "the decode was not bounded promptly") + self.assertIn( + response.status_code, + (202, 413), + "a bomb owes either a bounded rejection or a fail-open forward, got %d" + % response.status_code, + ) + + +class DecompressionBombWithoutPolicies(MatrixCase): + EDGE_CONFIG = {"max_body_size": 1048576, "max_decoded_bytes": 1048576} + + def test_without_policies_the_body_is_never_decoded(self): + response = self.post_raw_body(BOMB, headers={"Content-Encoding": "gzip"}, timeout=60) + self.assert_status(response, 202, "nothing reads the body, so it must forward") + self.assertGreaterEqual(self.intake_saw(1), 1) diff --git a/bench/matrix/tests/test_a41_policy_drop_all.py b/bench/matrix/tests/test_a41_policy_drop_all.py new file mode 100644 index 00000000..5a1ca493 --- /dev/null +++ b/bench/matrix/tests/test_a41_policy_drop_all.py @@ -0,0 +1,81 @@ +"""A41: a policy that keeps nothing, and the regex that cannot say so. + +The sender must get a 2xx, because the edge accepted responsibility for the +batch, and the intake must receive either nothing or an empty batch. No +upstream error line either way. +""" + +from harness import MatrixCase + + +class PolicyDropAll(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + # `.+`, not `.*`: Hyperscan rejects a pattern that can match an empty + # buffer, so `.*` never compiles. See RejectedPatternIsVisible below. + EDGE_POLICIES = { + "policies": [ + { + "id": "drop-all", + "name": "drop-all", + "log": {"match": [{"log_field": "body", "regex": ".+"}], "keep": "none"}, + } + ] + } + FORBID_LOGS = ["request.failed", "upstream.retried"] + + def test_a_dropped_batch_is_still_a_success_for_the_sender(self): + response = self.post_logs(timeout=30) + self.assertEqual(response.status_code // 100, 2, "got %d" % response.status_code) + self.assertGreaterEqual( + self.metric_delta('edge_policy_records_dropped_total{telemetry="datadog_logs"}'), + 1, + "the policy dropped nothing, so the case proved nothing", + ) + + +class RejectedPatternIsVisible(MatrixCase): + """A pattern the engine will not compile must not look like a live policy. + + Hyperscan refuses a pattern that can match an empty buffer, so `.*` is + invalid and `.+` or `^.*$` is the way to say "everything". That part is + correct. What was wrong is what an operator saw: the matcher built nothing + while the snapshot listed the policy as enabled, so a rule that does + nothing looked live. The rejection is now named in three places. + """ + + # The rejection is settled before the case body runs, so these are + # absolute checks rather than deltas. + ALLOW_PHANTOM_SUCCESS = True + EDGE_POLICIES = { + "policies": [ + { + "id": "drop-all-star", + "name": "drop-all-star", + "log": {"match": [{"log_field": "body", "regex": ".*"}], "keep": "none"}, + } + ] + } + + def test_a_pattern_the_engine_rejects_is_named(self): + import requests + + # The scrape is what refreshes the gauge and emits the warning. + self.edge.metrics() + snapshot = requests.get(self.edge.url + "/_edge/policies", timeout=10).text + self.assertIn("REJECTED", snapshot, "the dump does not name the rejected policy") + self.assertIn("drop-all-star", snapshot) + self.assertIn( + "invalid regex", + snapshot, + "the dump names the policy but not the reason:\n%s" % snapshot, + ) + self.assertGreaterEqual( + self.edge.metric("edge_policies_rejected"), + 1, + "the rejected policy is not counted", + ) + self.assertIn( + "policies.rejected", + self.edge.logs(), + "nothing warned that a policy was refused", + ) diff --git a/bench/matrix/tests/test_b01_connection_refused.py b/bench/matrix/tests/test_b01_connection_refused.py new file mode 100644 index 00000000..f1978aa4 --- /dev/null +++ b/bench/matrix/tests/test_b01_connection_refused.py @@ -0,0 +1,17 @@ +"""B01: nothing is listening at the intake.""" + +from harness import MatrixCase + + +class ConnectionRefused(MatrixCase): + EXPECT_METRICS = {"edge_upstream_retries_total": 1, 'edge_responses_total{known_path="api_v2_logs",status_class="s5xx"}': 1} + EXPECT_LOGS = ["upstream.retried", "request.failed"] + def test_refused_dial_is_a_bad_gateway(self): + self.intake.stop() # the port is now dead + response = self.post_logs() + + self.assertEqual(response.status_code // 100, 5, "a dead intake is our failure to report") + self.assertEqual(response.status_code, 502, "got %d" % response.status_code) + self.assert_logged("upstream") + self.assertGreaterEqual(self.metric_delta("edge_upstream_retries_total"), 1, + "a failed dial must be retried once") diff --git a/bench/matrix/tests/test_b02_intake_hang.py b/bench/matrix/tests/test_b02_intake_hang.py new file mode 100644 index 00000000..5d378467 --- /dev/null +++ b/bench/matrix/tests/test_b02_intake_hang.py @@ -0,0 +1,21 @@ +"""B02: the intake accepts the body and never answers. + +The upstream watchdog owns this one. Without it the handler is held for as +long as the intake feels like. +""" + +from harness import MatrixCase + + +class IntakeHang(MatrixCase): + EXPECT_METRICS = {"edge_upstream_timeouts_total": 1} + EXPECT_LOGS = ["upstream.timed.out", "request.failed", "request.slow"] + SLOW = True + + def test_a_hung_intake_becomes_a_gateway_timeout(self): + self.intake.arm("hang", count=1) + response = self.post_logs(timeout=120) + + self.assert_status(response, 504, "a hung intake must surface as 504") + self.assertGreaterEqual(self.metric_delta("edge_upstream_timeouts_total"), 1) + self.assert_logged("upstream.timed.out") diff --git a/bench/matrix/tests/test_b03_intake_slow.py b/bench/matrix/tests/test_b03_intake_slow.py new file mode 100644 index 00000000..e10b19b1 --- /dev/null +++ b/bench/matrix/tests/test_b03_intake_slow.py @@ -0,0 +1,15 @@ +"""B03: the intake is slow but healthy. The batch must still land.""" + +from harness import MatrixCase + + +class IntakeSlow(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 1} + EXPECT_LOGS = ["request.slow"] + FORBID_LOGS = ["request.failed", "upstream.timed.out"] + def test_slow_intake_still_succeeds_and_is_logged(self): + self.intake.arm("slow", arg=6000, count=1) + response = self.post_logs(timeout=60) + + self.assert_status(response, 202) + self.assert_logged("request.slow", "a six second request must leave a record") diff --git a/bench/matrix/tests/test_b04_close_early.py b/bench/matrix/tests/test_b04_close_early.py new file mode 100644 index 00000000..2c752292 --- /dev/null +++ b/bench/matrix/tests/test_b04_close_early.py @@ -0,0 +1,19 @@ +"""B04: the intake closes mid-request. + +A log batch is replayable, so the edge owes the sender a retry rather than an +error. +""" + +from harness import MatrixCase + + +class CloseEarly(MatrixCase): + EXPECT_METRICS = {"edge_upstream_retries_total": 1, 'edge_responses_total{known_path="api_v2_logs",status_class="s2xx"}': 1} + EXPECT_LOGS = ["upstream.retried"] + def test_a_dropped_intake_connection_is_retried(self): + self.intake.arm("close_early", count=1) + response = self.post_logs(timeout=60) + + self.assert_status(response, 202, "a replayable batch must survive one dropped connection") + self.assertGreaterEqual(self.metric_delta("edge_upstream_retries_total"), 1) + self.assertGreaterEqual(self.intake.faults_applied(), 1, "the fault never fired") diff --git a/bench/matrix/tests/test_b05_reject_early.py b/bench/matrix/tests/test_b05_reject_early.py new file mode 100644 index 00000000..5b7e5359 --- /dev/null +++ b/bench/matrix/tests/test_b05_reject_early.py @@ -0,0 +1,23 @@ +"""B05: the intake rejects on the head, before it reads the body. + +This is the reported production signature: a broken connection, then a 400 on +the immediate retry of the same chunk. The edge must relay that 400 rather +than turn it into a 502, so the sender stops retrying a batch the intake will +never accept. +""" + +from harness import MatrixCase + + +class RejectEarly(MatrixCase): + # The intake made the call, not us: we relay its 400. The invariant cannot + # tell a relayed 4xx from one of ours, which is exactly why a separate + # `edge_upstream_responses_total` is worth having. + EXPECT_PERMANENT_DROP = True + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s4xx"}': 1} + FORBID_LOGS = ["request.failed"] + def test_an_early_rejection_is_relayed(self): + self.intake.arm("reject_early", count=1) + response = self.post_logs(timeout=60) + + self.assert_status(response, 400, "an intake rejection must reach the sender verbatim") diff --git a/bench/matrix/tests/test_b06_status_relay.py b/bench/matrix/tests/test_b06_status_relay.py new file mode 100644 index 00000000..a5249b26 --- /dev/null +++ b/bench/matrix/tests/test_b06_status_relay.py @@ -0,0 +1,19 @@ +"""B06: real intake statuses must arrive unchanged.""" + +from harness import MatrixCase + + +class StatusRelay(MatrixCase): + def _relay(self, status): + self.intake.arm("status", arg=status, count=1) + response = self.post_logs(timeout=60) + self.assert_status(response, status, "status %d was not relayed" % status) + + def test_rate_limit_is_relayed(self): + self._relay(429) + + def test_server_error_is_relayed(self): + self._relay(500) + + def test_unavailable_is_relayed(self): + self._relay(503) diff --git a/bench/matrix/tests/test_b07_oversize_response.py b/bench/matrix/tests/test_b07_oversize_response.py new file mode 100644 index 00000000..c579b40b --- /dev/null +++ b/bench/matrix/tests/test_b07_oversize_response.py @@ -0,0 +1,21 @@ +"""B07: the intake answers with more body than the edge will relay.""" + +from harness import MatrixCase + + +class OversizeResponse(MatrixCase): + EDGE_CONFIG = {"max_body_size": 65536} + + def test_an_oversize_response_is_bounded(self): + self.intake.arm("oversize", arg=1_048_576, count=1) + status = None + try: + status = self.post_logs(timeout=60).status_code + except Exception: + status = None # the relay closed rather than answering + + # Either answer is honest. What must not happen is a clean 2xx that + # hides a response the edge refused to carry. + if status is not None: + self.assertEqual(status // 100, 5, "an oversize relay reported %d" % status) + self.assert_logged("upstream") diff --git a/bench/matrix/tests/test_b08_garbage_response.py b/bench/matrix/tests/test_b08_garbage_response.py new file mode 100644 index 00000000..3697b8c3 --- /dev/null +++ b/bench/matrix/tests/test_b08_garbage_response.py @@ -0,0 +1,14 @@ +"""B08: the intake answers with bytes that are not HTTP.""" + +from harness import MatrixCase + + +class GarbageResponse(MatrixCase): + EXPECT_METRICS = {'edge_responses_total{known_path="api_v2_logs",status_class="s5xx"}': 1} + EXPECT_LOGS = ["request.failed", "upstream.connection.evicted"] + def test_garbage_from_the_intake_is_a_bad_gateway(self): + self.intake.arm("garbage", count=1) + response = self.post_logs(timeout=60) + + self.assertEqual(response.status_code // 100, 5, "got %d" % response.status_code) + self.assert_logged("upstream") diff --git a/bench/matrix/tests/test_b09_stale_keepalive.py b/bench/matrix/tests/test_b09_stale_keepalive.py new file mode 100644 index 00000000..ddacb960 --- /dev/null +++ b/bench/matrix/tests/test_b09_stale_keepalive.py @@ -0,0 +1,19 @@ +"""B09: the pooled intake connection is already dead. + +The intake answers, then closes at once. The next batch picks the pooled +connection, finds it gone, and must recover on a fresh dial. Log intake clients +do not retry, so a 5xx here is data loss. +""" + +from harness import MatrixCase + + +class StaleKeepalive(MatrixCase): + EXPECT_METRICS = {"edge_upstream_retries_total": 1} + EXPECT_LOGS = ["upstream.retried"] + def test_a_dead_pooled_connection_is_replaced(self): + self.assert_status(self.post_logs(timeout=30), 202) + self.intake.arm("stale_keepalive", count=1) + self.assert_status(self.post_logs(timeout=30), 202) + self.intake.arm("none") + self.assert_status(self.post_logs(timeout=30), 202) diff --git a/bench/matrix/tests/test_b10_intake_reset.py b/bench/matrix/tests/test_b10_intake_reset.py new file mode 100644 index 00000000..a3c57a0e --- /dev/null +++ b/bench/matrix/tests/test_b10_intake_reset.py @@ -0,0 +1,14 @@ +"""B10: the intake resets the connection instead of closing it.""" + +from harness import MatrixCase + + +class IntakeReset(MatrixCase): + EXPECT_METRICS = {"edge_upstream_retries_total": 1} + EXPECT_LOGS = ["upstream.retried"] + def test_a_reset_intake_is_retried(self): + self.intake.arm("reset", count=1) + response = self.post_logs(timeout=60) + + self.assert_status(response, 202, "a reset is a transport failure, so retry it") + self.assertGreaterEqual(self.metric_delta("edge_upstream_retries_total"), 1) diff --git a/bench/matrix/tests/test_b11_truncated_response.py b/bench/matrix/tests/test_b11_truncated_response.py new file mode 100644 index 00000000..2d33f387 --- /dev/null +++ b/bench/matrix/tests/test_b11_truncated_response.py @@ -0,0 +1,29 @@ +"""B11: the intake declares more response body than it sends. + +The edge has committed a status by then, so the body truncates. What the +sender must never get is a clean success for a batch the intake never +confirmed: an agent that reads 202 deletes its copy. +""" + +import requests + +from harness import MatrixCase + + +class TruncatedResponse(MatrixCase): + # The intake's head is relayed as it arrives, so a 2xx is recorded before + # the body is known to be short. b11b measures what that costs. + ALLOW_PHANTOM_SUCCESS = True + EXPECT_LOGS_FOR = {"stdio": ["response.truncated"]} + EXPECT_LOGS = ["UpstreamResponseTruncated"] + + def test_a_truncated_relay_is_never_reported_as_success(self): + self.intake.arm("truncate", count=1) + try: + response = self.post_logs(timeout=60) + status = response.status_code + except requests.exceptions.RequestException: + status = None # a broken relay is an honest answer + + if status == 202: + self.fail("a truncated intake response was reported as success") diff --git a/bench/matrix/tests/test_b11b_truncated_semantics.py b/bench/matrix/tests/test_b11b_truncated_semantics.py new file mode 100644 index 00000000..e990f5fc --- /dev/null +++ b/bench/matrix/tests/test_b11b_truncated_semantics.py @@ -0,0 +1,66 @@ +"""B11b: what a truncated answer means, and what our 502 costs. + +The challenge to b11: if the intake wrote a 202 head, it accepted the batch, +so a truncated response body changes nothing about the data, and answering 502 +makes a retrying sender deliver a second copy. + +That depends entirely on *when* the answer broke, so this measures both: + + truncate the intake answers before reading the body. The batch + never arrived, so a 502 and a retry repair it. + truncate_after_read the intake reads the whole batch, then breaks its + answer. The batch is already in, so a 502 and a retry + duplicate it. +""" + +import json + +from harness import MatrixCase + +BATCH = [{"message": "truncation semantics", "ddsource": "matrix"}] +PAYLOAD = json.dumps(BATCH).encode() + + +class TruncatedBeforeTheBodyWasRead(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_the_batch_never_arrived_so_a_retry_repairs_it(self): + self.intake.arm("truncate", count=1) + try: + self.post_raw_body(PAYLOAD, timeout=30) + except Exception: + pass + + received = self.intake.stats()["endpoints"].get("/api/v2/logs", {}).get("bytes", 0) + self.assertEqual(received, 0, "the intake read %d bytes before truncating" % received) + + +class TruncatedAfterTheBodyWasRead(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_the_batch_arrived_so_our_502_costs_a_duplicate(self): + self.intake.arm("truncate_after_read", count=1) + try: + first = self.post_raw_body(PAYLOAD, timeout=30).status_code + except Exception: + first = None + + received = self.intake.stats()["endpoints"].get("/api/v2/logs", {}).get("bytes", 0) + self.assertEqual( + received, + len(PAYLOAD), + "the intake accepted %d of %d body bytes before its answer broke" + % (received, len(PAYLOAD)), + ) + + # A sender that retries a transport failure or a 5xx, which is what a + # log agent does. + if first is None or first >= 500: + self.post_raw_body(PAYLOAD, timeout=30) + + delivered = self.intake.requests_seen() - self.baseline_intake + self.assertEqual( + delivered, + 2, + "the retry delivered %d copies of a batch the intake already had" % delivered, + ) diff --git a/bench/matrix/tests/test_b12_dial_blackhole.py b/bench/matrix/tests/test_b12_dial_blackhole.py new file mode 100644 index 00000000..cecdd2e0 --- /dev/null +++ b/bench/matrix/tests/test_b12_dial_blackhole.py @@ -0,0 +1,65 @@ +"""B12: the intake accepts nothing and the dial hangs. + +`std.http.Client` takes no connect timeout and the upstream watchdog has no +socket to interrupt until the dial returns, so a handler is held for the +kernel's connect timeout. A sender should not wait minutes for an answer the +edge already knows it cannot give. +""" + +import socket +import time + +from harness import MatrixCase, free_port +from harness.procs import Edge + + +class DialBlackhole(MatrixCase): + SLOW = True + DEFECTS = { + "stdio": "the dial has no deadline, so the sender waits for the kernel", + "httpz": "the dial has no deadline, so the sender waits for the kernel", + } + ALLOW_PHANTOM_SUCCESS = True + + def setUp(self): + super().setUp() + # Replace the edge with one pointed at an address that swallows SYNs. + self.edge.stop() + self.blackhole = socket.socket() + self.blackhole.bind(("127.0.0.1", free_port())) + self.blackhole.listen(1) + self.fillers = [] + for _ in range(8): # fill the accept queue so further SYNs are dropped + filler = socket.socket() + filler.setblocking(False) + try: + filler.connect_ex(("127.0.0.1", self.blackhole.getsockname()[1])) + except OSError: + pass + self.fillers.append(filler) + self.edge = Edge("http://127.0.0.1:%d" % self.blackhole.getsockname()[1]) + self.baseline = self.edge.metrics() + self.log_snapshot = set(self.edge.logs().splitlines()) + self.baseline_descriptors = self.edge.descriptors() + self.baseline_intake = self.intake.requests_seen() + + def tearDown(self): + for filler in self.fillers: + filler.close() + self.blackhole.close() + super().tearDown() + + def test_a_blackholed_dial_is_bounded(self): + started = time.monotonic() + try: + status = self.post_logs(timeout=120).status_code + except Exception: + status = None + elapsed = time.monotonic() - started + self.assertLess( + elapsed, + 35, + "the sender waited %.0f s for a dial that never connects" % elapsed, + ) + if status is not None: + self.assertIn(status, (502, 504)) diff --git a/bench/matrix/tests/test_b14_keep_alive_off.py b/bench/matrix/tests/test_b14_keep_alive_off.py new file mode 100644 index 00000000..6b240b4e --- /dev/null +++ b/bench/matrix/tests/test_b14_keep_alive_off.py @@ -0,0 +1,22 @@ +"""B14: the intake answers with `Connection: close`. + +A connection the intake said it would close must not be pooled. If it is, the +next batch finds a dead socket and pays a retry for nothing. +""" + +from harness import MatrixCase + + +class KeepAliveOff(MatrixCase): + FORBID_LOGS = ["upstream.retried"] + + def test_a_closed_connection_is_not_pooled(self): + self.intake.arm("keep_alive_off", count=1) + self.assert_status(self.post_logs(timeout=30), 202) + # The next batch must dial fresh and succeed without a retry line. + self.assert_status(self.post_logs(timeout=30), 202) + self.assertEqual( + self.metric_delta("edge_upstream_retries_total"), + 0, + "the edge pooled a connection the intake said it would close", + ) diff --git a/bench/matrix/tests/test_b15_http10_no_length.py b/bench/matrix/tests/test_b15_http10_no_length.py new file mode 100644 index 00000000..14e9078b --- /dev/null +++ b/bench/matrix/tests/test_b15_http10_no_length.py @@ -0,0 +1,29 @@ +"""B15: an HTTP/1.0 answer with no content-length. + +The body ends when the intake closes. A relay that waits for a length instead +holds the exchange until the watchdog fires, 30 s later, for an answer that +already arrived. +""" + +import time + +from harness import MatrixCase + + +class Http10NoLength(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_the_relay_ends_at_the_close(self): + self.intake.arm("http10_no_length", count=1) + started = time.monotonic() + try: + self.post_logs(timeout=60) + except Exception: + pass + elapsed = time.monotonic() - started + self.assertLess( + elapsed, + 20, + "the relay waited %.0f s for a body that ended at the close" % elapsed, + ) diff --git a/bench/matrix/tests/test_b16_bodiless_status.py b/bench/matrix/tests/test_b16_bodiless_status.py new file mode 100644 index 00000000..6cca2b06 --- /dev/null +++ b/bench/matrix/tests/test_b16_bodiless_status.py @@ -0,0 +1,23 @@ +"""B16: the intake answers 204, which carries no body. + +A relay that re-frames a 204 as chunked breaks the protocol, and some clients +reject it outright. +""" + +from harness import MatrixCase + + +class BodilessStatus(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_a_204_stays_bodiless(self): + self.intake.arm("bodiless", count=1) + response = self.post_logs(timeout=30) + + self.assert_status(response, 204, "the status must be relayed") + self.assertEqual(response.content, b"", "a 204 must carry no body") + self.assertNotIn( + "chunked", + response.headers.get("transfer-encoding", "").lower(), + "a 204 was re-framed as chunked", + ) diff --git a/bench/matrix/tests/test_b17_response_header_flood.py b/bench/matrix/tests/test_b17_response_header_flood.py new file mode 100644 index 00000000..0fb3055f --- /dev/null +++ b/bench/matrix/tests/test_b17_response_header_flood.py @@ -0,0 +1,25 @@ +"""B17: the intake answers with more headers than the relay carries. + +The mirror of a14. Dropping the excess in silence loses whatever the intake +was trying to say, and `Retry-After` on a 429 is the header agents act on. +""" + +from harness import MatrixCase + + +class ResponseHeaderFlood(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_a_response_header_flood_is_relayed_or_refused(self): + self.intake.arm("header_flood", arg=80, count=1) + response = self.post_logs(timeout=30) + + relayed = sum(1 for name in response.headers if name.lower().startswith("x-flood-")) + if response.status_code == 202: + self.assertGreaterEqual( + relayed, + 64, + "the relay kept %d of 80 response headers and still answered 202" % relayed, + ) + else: + self.assertEqual(response.status_code // 100, 5, repr(response)) diff --git a/bench/matrix/tests/test_b18_slow_response_body.py b/bench/matrix/tests/test_b18_slow_response_body.py new file mode 100644 index 00000000..650d1c99 --- /dev/null +++ b/bench/matrix/tests/test_b18_slow_response_body.py @@ -0,0 +1,25 @@ +"""B18: the intake dribbles its answer. + +The watchdog owns the whole attempt, so a body that never finishes must be cut +at the deadline with the slot returned, not held for as long as the intake +feels like dribbling. +""" + +import time + +from harness import MatrixCase + + +class SlowResponseBody(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_a_dribbled_answer_is_cut_at_the_deadline(self): + self.intake.arm("slow_body", arg=5000, count=1) + started = time.monotonic() + try: + self.post_logs(timeout=120) + except Exception: + pass + elapsed = time.monotonic() - started + self.assertLess(elapsed, 45, "the relay ran for %.0f s" % elapsed) diff --git a/bench/matrix/tests/test_b19_slow_reading_intake.py b/bench/matrix/tests/test_b19_slow_reading_intake.py new file mode 100644 index 00000000..a9481bf7 --- /dev/null +++ b/bench/matrix/tests/test_b19_slow_reading_intake.py @@ -0,0 +1,26 @@ +"""B19: the intake reads the batch at a trickle. + +With a body above the socket buffer our send blocks, so the watchdog has to +cover the send side as well as the read side. +""" + +import json +import time + +from harness import MatrixCase + + +class SlowReadingIntake(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_a_blocked_send_is_bounded(self): + self.intake.arm("slow_read", arg=200, count=1) + body = json.dumps([{"message": "x" * 400 * 1024}]).encode() + started = time.monotonic() + try: + self.post_raw_body(body, timeout=120) + except Exception: + pass + elapsed = time.monotonic() - started + self.assertLess(elapsed, 45, "a blocked send ran for %.0f s" % elapsed) diff --git a/bench/matrix/tests/test_b20_accept_then_silence.py b/bench/matrix/tests/test_b20_accept_then_silence.py new file mode 100644 index 00000000..f2bc33f0 --- /dev/null +++ b/bench/matrix/tests/test_b20_accept_then_silence.py @@ -0,0 +1,28 @@ +"""B20: the intake accepts the connection and does nothing at all. + +Unlike `hang`, it never even reads the body, so the send blocks first. Both a +small and a streamed batch owe an answer at the deadline. +""" + +import json +import time + +from harness import MatrixCase + + +class AcceptThenSilence(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_a_silent_intake_is_bounded(self): + self.intake.arm("accept_silence", count=1) + started = time.monotonic() + try: + status = self.post_logs(timeout=120).status_code + except Exception: + status = None + elapsed = time.monotonic() - started + + self.assertLess(elapsed, 70, "a silent intake held the sender for %.0f s" % elapsed) + if status is not None: + self.assertEqual(status // 100, 5, "got %d" % status) diff --git a/bench/matrix/tests/test_b21_reject_early_streamed.py b/bench/matrix/tests/test_b21_reject_early_streamed.py new file mode 100644 index 00000000..d530d2b9 --- /dev/null +++ b/bench/matrix/tests/test_b21_reject_early_streamed.py @@ -0,0 +1,44 @@ +"""B21: the intake rejects a large batch on its head. + +The early-response path answers before the body finished, so part of the +request body is still on the inbound socket. The next request on that same +connection must be served, not parsed out of the leftovers. +""" + +import json + +import requests + +from harness import MatrixCase + + +class RejectEarlyStreamed(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + EXPECT_PERMANENT_DROP = True # the intake rejected it, not us + + def test_the_next_request_on_the_connection_is_still_served(self): + session = requests.Session() + try: + big = json.dumps([{"message": "x" * 200 * 1024}]).encode() + self.intake.arm("reject_early", count=1) + first = session.post( + self.edge.url + "/api/v2/logs", + data=big, + headers={"Content-Type": "application/json"}, + timeout=60, + ) + self.assertEqual(first.status_code, 400, repr(first)) + + second = session.post( + self.edge.url + "/api/v2/logs", + json=[{"message": "after the rejection"}], + timeout=60, + ) + self.assertEqual( + second.status_code, + 202, + "the follow-up was answered %d, so leftover body bytes were " + "parsed as a request" % second.status_code, + ) + finally: + session.close() diff --git a/bench/matrix/tests/test_b22_intake_restart.py b/bench/matrix/tests/test_b22_intake_restart.py new file mode 100644 index 00000000..75038be0 --- /dev/null +++ b/bench/matrix/tests/test_b22_intake_restart.py @@ -0,0 +1,45 @@ +"""B22: the intake goes away mid-burst and comes back on the same port. + +A Datadog deployment looks like this. Pooled connections must be evicted and +the first batches after the restart must succeed. +""" + +import threading +import time + +from harness import MatrixCase, EchoIntake + + +class IntakeRestart(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_the_edge_recovers_when_the_intake_comes_back(self): + port = self.intake.port + for _ in range(5): + self.assert_status(self.post_logs(timeout=30), 202) + + stop = threading.Event() + + def sender(): + while not stop.is_set(): + try: + self.post_logs(timeout=20) + except Exception: + pass + + traffic = threading.Thread(target=sender, daemon=True) + traffic.start() + try: + self.intake.stop() + time.sleep(2) + self.intake = EchoIntake(port=port) + time.sleep(1) + finally: + stop.set() + traffic.join(timeout=30) + + # The first batches after the restart must land. + for _ in range(3): + self.assert_status(self.post_logs(timeout=30), 202) + self.assertEqual(self.health().status_code, 200) diff --git a/bench/matrix/tests/test_b23_duplicate_delivery.py b/bench/matrix/tests/test_b23_duplicate_delivery.py new file mode 100644 index 00000000..baf4c003 --- /dev/null +++ b/bench/matrix/tests/test_b23_duplicate_delivery.py @@ -0,0 +1,23 @@ +"""B23: the intake reads the whole batch, then dies before answering. + +The batch arrived, so the retry delivers it twice. That is at-least-once, and +it is a deliberate choice rather than an accident: this case pins it, and pins +that it stops at two. +""" + +from harness import MatrixCase + + +class DuplicateDelivery(MatrixCase): + def test_a_retry_after_a_silent_close_delivers_twice(self): + self.intake.arm("read_then_close", count=1) + response = self.post_logs(timeout=60) + + self.assert_status(response, 202, "the retry must succeed") + seen = self.intake_saw(2) + self.assertEqual( + seen, + 2, + "at-least-once means exactly two copies here, not %d" % seen, + ) + self.assertGreaterEqual(self.metric_delta("edge_upstream_retries_total"), 1) diff --git a/bench/matrix/tests/test_b24_retry_amplification.py b/bench/matrix/tests/test_b24_retry_amplification.py new file mode 100644 index 00000000..0a669346 --- /dev/null +++ b/bench/matrix/tests/test_b24_retry_amplification.py @@ -0,0 +1,24 @@ +"""B24: every request fails the same way, for a hundred requests. + +An intake outage makes every batch retry. The cost must stay bounded: at most +one retry each, no descriptor growth from the pool-less retry client, and +health unaffected while it happens. +""" + +from harness import MatrixCase + + +class RetryAmplification(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_retries_stay_bounded_under_a_total_outage(self): + self.intake.arm("close_early") # every request, no count + for _ in range(100): + try: + self.post_logs(timeout=30) + except Exception: + pass + + attempts = self.metric_delta("edge_upstream_attempts_total") + self.assertLessEqual(attempts, 220, "more than two attempts per request: %s" % attempts) + self.assertEqual(self.health().status_code, 200, "health suffered during the outage") diff --git a/bench/matrix/tests/test_b25_redirect.py b/bench/matrix/tests/test_b25_redirect.py new file mode 100644 index 00000000..d0436e9b --- /dev/null +++ b/bench/matrix/tests/test_b25_redirect.py @@ -0,0 +1,19 @@ +"""B25: the intake answers a redirect. + +Redirects are unhandled by design, so the sender gets it verbatim rather than +the edge chasing it. A wrong scheme in `upstream_url` looks exactly like this, +so the status must survive intact for anyone reading agent logs. +""" + +from harness import MatrixCase + + +class Redirect(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def test_a_redirect_is_relayed_verbatim(self): + self.intake.arm("redirect", count=1) + response = self.post_logs(timeout=30, allow_redirects=False) + + self.assertEqual(response.status_code, 308, repr(response)) + self.assertIn("location", {k.lower() for k in response.headers}) diff --git a/bench/matrix/tests/test_b26_target_fidelity.py b/bench/matrix/tests/test_b26_target_fidelity.py new file mode 100644 index 00000000..d8d80301 --- /dev/null +++ b/bench/matrix/tests/test_b26_target_fidelity.py @@ -0,0 +1,21 @@ +"""B26: the target the intake receives. + +Agents put tags, and sometimes credentials, in the query. A base path in +`upstream_url` is an ordinary proxy configuration. Both must arrive byte for +byte. +""" + +from harness import MatrixCase + + +class QueryFidelity(MatrixCase): + def test_the_query_survives_byte_for_byte(self): + target = "/api/v2/logs?ddtags=env%3Aprod%2Cteam%3Aplatform&dd-api-key=abc123&x=a+b" + response = self.post_logs(path=target, timeout=30) + self.assert_status(response, 202) + self.assertEqual(self.intake_saw(1), 1) + self.assertEqual( + self.intake.stats().get("last_target"), + target, + "the intake received a different target than the sender wrote", + ) diff --git a/bench/matrix/tests/test_b29_scrape_path_faults.py b/bench/matrix/tests/test_b29_scrape_path_faults.py new file mode 100644 index 00000000..e5162edf --- /dev/null +++ b/bench/matrix/tests/test_b29_scrape_path_faults.py @@ -0,0 +1,48 @@ +"""B29: the Prometheus scrape path, which nothing else covers. + +`/metrics` fetches from the upstream and filters it. A refused dial and a hung +intake must both end in a status rather than a hang, and a scraper must never +read a partial exposition as a complete one. +""" + +import time + +from harness import MatrixCase + + +class ScrapeWithRefusedDial(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + EXPECT_PERMANENT_DROP = True + + def test_a_refused_scrape_answers_promptly(self): + self.intake.stop() + started = time.monotonic() + try: + status = self.session_get("/metrics", timeout=30) + except Exception: + status = None + self.assertLess(time.monotonic() - started, 20, "the scrape hung") + if status is not None: + self.assertEqual(status // 100, 5, "got %d" % status) + + def session_get(self, path, timeout=30): + import requests + + return requests.get(self.edge.url + path, timeout=timeout).status_code + + +class ScrapeWithHungIntake(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + EXPECT_PERMANENT_DROP = True + + def test_a_hung_scrape_is_cut_at_the_deadline(self): + import requests + + self.intake.arm("hang") + started = time.monotonic() + try: + requests.get(self.edge.url + "/metrics", timeout=120) + except Exception: + pass + self.assertLess(time.monotonic() - started, 45, "the scrape outlived the deadline") diff --git a/bench/matrix/tests/test_c01_shed_at_capacity.py b/bench/matrix/tests/test_c01_shed_at_capacity.py new file mode 100644 index 00000000..fe302063 --- /dev/null +++ b/bench/matrix/tests/test_c01_shed_at_capacity.py @@ -0,0 +1,51 @@ +"""C01: more connections than the slab holds. + +Shedding is correct past the cap, and silent shedding is not: it is the signal +an operator needs when a sidecar is at its ceiling. Two things are asserted +here. Nothing is shed at exactly `max_connections` senders, because the +control reserve is capacity on top of the cap rather than a slice of it — a +benchmark caught that the other way round. And past the cap the answer is 503 +with `Retry-After`, because running out of connections is a condition of this +proxy rather than a limit on one sender, and the header is the part a sender +can act on. +""" + +from harness import MatrixCase + + +class ShedAtCapacity(MatrixCase): + EXPECT_METRICS_FOR = {"stdio": {'edge_connections_shed_total{reason="slab_full"}': 1}} + EXPECT_LOGS_FOR = {"stdio": ["connection.shed"]} + EDGE_CONFIG = {"max_connections": 8} + EXPECT_SHED = True + + def test_excess_connections_are_shed_with_a_status(self): + held = [] + answers = [] + try: + for _ in range(24): + client = self.raw(timeout=10) + held.append(client) + client.send(self.head(body_len=4096)) # occupy the slot + # A fresh sender past the ceiling. + with self.raw(timeout=10) as probe: + probe.send(self.head(body_len=0) + b"") + answers.append(probe.read_response()) + finally: + for client in held: + client.close() + + statuses = [a.status for a in answers] + self.assertTrue( + any(s == 503 for s in statuses) or any(s is None for s in statuses), + "past the ceiling the edge must shed, got %r" % statuses, + ) + for answer in answers: + if answer.status == 503: + self.assertIn( + "retry-after", + answer.head.lower(), + "a shed answer must tell the sender how long to wait:\n%s" % answer.head, + ) + if self.frontend == "stdio": + self.wait_for_metric('edge_connections_shed_total{reason="slab_full"}', 1, timeout=10) diff --git a/bench/matrix/tests/test_c01b_capacity_is_not_reserved_away.py b/bench/matrix/tests/test_c01b_capacity_is_not_reserved_away.py new file mode 100644 index 00000000..af3fdc85 --- /dev/null +++ b/bench/matrix/tests/test_c01b_capacity_is_not_reserved_away.py @@ -0,0 +1,43 @@ +"""C01b: senders up to the cap are all served. + +The control reserve exists so a health probe can be read while the slab is +full. It must be capacity on top of `max_connections`, not a slice of it: when +it was carved out of the cap, a deployment sized to its sender count shed the +last two senders forever. A benchmark caught that, not a test, so here is the +test. +""" + +import threading + +from harness import MatrixCase + + +class CapacityIsNotReservedAway(MatrixCase): + EDGE_CONFIG = {"max_connections": 8} + + def test_every_sender_up_to_the_cap_is_served(self): + cap = self.EDGE_CONFIG["max_connections"] + answers = [] + lock = threading.Lock() + start = threading.Barrier(cap) + + def sender(): + start.wait() + try: + status = self.post_logs(timeout=30).status_code + except Exception as err: + status = type(err).__name__ + with lock: + answers.append(status) + + threads = [threading.Thread(target=sender, daemon=True) for _ in range(cap)] + for thread in threads: + thread.start() + for thread in threads: + thread.join(timeout=60) + + self.assertEqual( + answers, + [202] * cap, + "%d senders against a cap of %d were not all served: %r" % (cap, cap, answers), + ) diff --git a/bench/matrix/tests/test_c02_health_under_burst.py b/bench/matrix/tests/test_c02_health_under_burst.py new file mode 100644 index 00000000..8c56b866 --- /dev/null +++ b/bench/matrix/tests/test_c02_health_under_burst.py @@ -0,0 +1,63 @@ +"""C02: a health probe that arrives with a burst, against a slow intake. + +This is the ECS failure the customer reported. The probe is a static route, so +it can only be slow if it cannot reach a thread. Arrivals are synchronised +here, because the effect depends on the probe landing in the same event batch +as the batches ahead of it: with per-thread queues the probe waits for every +request queued in front of it, however many threads are idle. +""" + +import threading + +from harness import MatrixCase + + +class HealthUnderBurst(MatrixCase): + FORBID_LOGS = ["request.failed"] + INTAKE_LATENCY = 3000 + DEFECTS = {"httpz": "a batch of up to 16 requests goes to one pool thread, so a probe waits behind it"} + + # The stall depends on the probe landing in the same event batch as the + # senders, which is probabilistic: measured at roughly 3 in 10 bursts. + # Eight bursts flapped, so run twenty. + SLOW = True + BURSTS = 20 + SENDERS = 15 + + def test_health_stays_fast_when_a_burst_arrives_with_it(self): + worst = 0.0 + for _ in range(self.BURSTS): + start = threading.Barrier(self.SENDERS + 1) + probe_seconds = {} + + def sender(): + start.wait() + try: + self.post_logs(timeout=60) + except Exception: + pass + + def probe(): + start.wait() + import time + began = time.monotonic() + try: + self.health(timeout=60) + probe_seconds["value"] = time.monotonic() - began + except Exception: + probe_seconds["value"] = 999.0 + + threads = [threading.Thread(target=sender, daemon=True) for _ in range(self.SENDERS)] + threads.append(threading.Thread(target=probe, daemon=True)) + for thread in threads: + thread.start() + for thread in threads: + thread.join(timeout=90) + worst = max(worst, probe_seconds.get("value", 0.0)) + + self.assertLess( + worst, + 1.0, + "a health probe waited %.1f s behind the burst; three such misses " + "take the task down" % worst, + ) diff --git a/bench/matrix/tests/test_c03_idle_socket_flood.py b/bench/matrix/tests/test_c03_idle_socket_flood.py new file mode 100644 index 00000000..19375d7b --- /dev/null +++ b/bench/matrix/tests/test_c03_idle_socket_flood.py @@ -0,0 +1,37 @@ +"""C03: every slot taken by senders that never send. + +The edge must reclaim the slots on its own, without the senders closing +anything, or one misbehaved client wedges the sidecar until it restarts. +""" + +import time + +from harness import MatrixCase + + +class IdleSocketFlood(MatrixCase): + EXPECT_METRICS_FOR = {"stdio": {'edge_inbound_timeouts_total{phase="idle"}': 1}} + EDGE_CONFIG = {"max_connections": 8} + EXPECT_SHED = True + SLOW = True + + def test_idle_sockets_do_not_wedge_the_edge(self): + held = [self.raw(timeout=90) for _ in range(12)] + recovered_at = None + try: + time.sleep(1) + started = time.monotonic() + while time.monotonic() - started < 60: + try: + if self.health(timeout=2).status_code == 200: + recovered_at = time.monotonic() - started + break + except Exception: + pass + time.sleep(1) + finally: + for client in held: + client.close() + + self.assertIsNotNone(recovered_at, "the edge never recovered while sockets were held") + self.assertLess(recovered_at, 45, "reclaim took %.0f s" % recovered_at) diff --git a/bench/matrix/tests/test_c04_hung_intake_saturation.py b/bench/matrix/tests/test_c04_hung_intake_saturation.py new file mode 100644 index 00000000..f6945fb3 --- /dev/null +++ b/bench/matrix/tests/test_c04_hung_intake_saturation.py @@ -0,0 +1,41 @@ +"""C04: more senders than handler threads, against an intake that never answers. + +Every handler ends up waiting on the watchdog. The control plane must keep +working while that happens: a health probe and a metrics scrape both have to +answer, or an orchestrator kills a sidecar that is merely waiting. +""" + +import threading +import time + +from harness import MatrixCase + + +class HungIntakeSaturation(MatrixCase): + SLOW = True + ALLOW_PHANTOM_SUCCESS = True + + def test_health_and_metrics_answer_while_every_handler_waits(self): + self.intake.arm("hang") + senders = [] + for _ in range(48): + thread = threading.Thread(target=lambda: self._quiet_post(), daemon=True) + thread.start() + senders.append(thread) + time.sleep(3) + + started = time.monotonic() + self.assertEqual(self.health(timeout=10).status_code, 200, "health stopped answering") + health_seconds = time.monotonic() - started + self.assertLess(health_seconds, 1.0, "health took %.1f s" % health_seconds) + self.assertTrue(self.edge.metrics(), "the metrics scrape stopped answering") + + self.intake.arm("none") + for thread in senders: + thread.join(timeout=90) + + def _quiet_post(self): + try: + self.post_logs(timeout=90) + except Exception: + pass diff --git a/bench/matrix/tests/test_c05_health_at_capacity.py b/bench/matrix/tests/test_c05_health_at_capacity.py new file mode 100644 index 00000000..6cda35af --- /dev/null +++ b/bench/matrix/tests/test_c05_health_at_capacity.py @@ -0,0 +1,31 @@ +"""C05: a health probe while every connection slot is taken. + +Today the probe is shed with the rest, which on ECS restarts the sidecar during the +very spike that filled it. The case asserts the behaviour we want — health +answers — so the choice is explicit rather than implied by the shed path. +""" + +from harness import MatrixCase + + +class HealthAtCapacity(MatrixCase): + EDGE_CONFIG = {"max_connections": 8} + EXPECT_SHED = True + DEFECTS = {"httpz": "health waits behind the full connection table"} + + def test_health_answers_at_capacity(self): + held = [] + try: + for _ in range(16): + client = self.raw(timeout=10) + client.send(self.head(body_len=4096)) # hold the slot open + held.append(client) + self.assertEqual( + self.health(timeout=5).status_code, + 200, + "a probe at capacity must still answer, or the orchestrator " + "restarts the sidecar during the spike", + ) + finally: + for client in held: + client.close() diff --git a/bench/matrix/tests/test_c06_memory_budget.py b/bench/matrix/tests/test_c06_memory_budget.py new file mode 100644 index 00000000..955996a8 --- /dev/null +++ b/bench/matrix/tests/test_c06_memory_budget.py @@ -0,0 +1,53 @@ +"""C06: memory under repeated saturation. + +Three rounds of concurrent large batches. RSS must not climb between rounds: +a per-connection or per-thread buffer that is never reused shows up here and +nowhere else. +""" + +import json +import subprocess +import threading + +from harness import MatrixCase + + +def rss_mb(pid: int) -> float: + out = subprocess.run(["ps", "-o", "rss=", "-p", str(pid)], capture_output=True, text=True) + try: + return int(out.stdout.strip()) / 1024 + except ValueError: + return -1.0 + + +class MemoryBudget(MatrixCase): + SLOW = True + EDGE_CONFIG = {"max_body_size": 1048576} + + def test_rss_does_not_climb_between_rounds(self): + body = json.dumps([{"message": "x" * 500 * 1024}]).encode() + rounds = [] + + for _ in range(3): + threads = [] + for _ in range(32): + thread = threading.Thread(target=lambda: self._quiet_post(body), daemon=True) + thread.start() + threads.append(thread) + for thread in threads: + thread.join(timeout=60) + rounds.append(rss_mb(self.edge.pid)) + + self.assertGreater(rounds[0], 0, "could not read RSS") + growth = rounds[-1] - rounds[1] + self.assertLess( + growth, + 32, + "RSS grew %.0f MB between rounds: %s" % (growth, [round(r) for r in rounds]), + ) + + def _quiet_post(self, body): + try: + self.post_raw_body(body, timeout=60) + except Exception: + pass diff --git a/bench/matrix/tests/test_c07_connection_churn.py b/bench/matrix/tests/test_c07_connection_churn.py new file mode 100644 index 00000000..c1de7ca7 --- /dev/null +++ b/bench/matrix/tests/test_c07_connection_churn.py @@ -0,0 +1,25 @@ +"""C07: connect, send, close, over and over. + +Gauges and descriptors must return to their baseline after thousands of +cycles, and nothing may be shed: this is ordinary agent behaviour when +keep-alive is off. +""" + +from harness import MatrixCase + + +class ConnectionChurn(MatrixCase): + SLOW = True + + def test_churn_leaves_no_residue(self): + body = b'[{"message":"churn"}]' + for _ in range(1500): + with self.raw(timeout=20) as client: + client.send(self.head(body_len=len(body)) + body) + answer = client.read_response() + if answer.status is not None: + self.assertEqual(answer.status, 202, repr(answer)) + + # The teardown invariants carry the rest: in-flight back to zero, + # descriptors back to baseline, nothing shed. + self.assertEqual(self.health().status_code, 200) diff --git a/bench/matrix/tests/test_c09_log_backpressure.py b/bench/matrix/tests/test_c09_log_backpressure.py new file mode 100644 index 00000000..30597f93 --- /dev/null +++ b/bench/matrix/tests/test_c09_log_backpressure.py @@ -0,0 +1,39 @@ +"""C09: the log destination stops draining. + +An ECS log driver in blocking mode does exactly this. A logger that blocks on +a full pipe takes the data plane with it, so the edge must keep serving even +when nothing reads its logs. +""" + +from harness import MatrixCase, EchoIntake +from harness.procs import Edge + + +class LogBackPressure(MatrixCase): + SLOW = True + # The case is about staying alive with a stalled log pipe, not delivery. + ALLOW_PHANTOM_SUCCESS = True + EXPECT_PERMANENT_DROP = True + + def setUp(self): + self.intake = EchoIntake() + # Logs go to a pipe nobody reads. 64 KiB of pipe buffer fills fast + # once every request fails. + self.edge = Edge(self.intake.url, {"log_level": "info"}, stall_logs=True) + self.baseline = self.edge.metrics() + self.log_snapshot = set() + self.baseline_descriptors = self.edge.descriptors() + self.baseline_intake = self.intake.requests_seen() + + def test_the_edge_serves_while_its_logs_are_ignored(self): + self.intake.arm("reject_early") # every request logs + for _ in range(400): + try: + self.post_logs(timeout=20) + except Exception: + pass + self.assertEqual( + self.health(timeout=10).status_code, + 200, + "the edge stopped serving once its log pipe filled", + ) diff --git a/bench/matrix/tests/test_d01_sigterm_inflight.py b/bench/matrix/tests/test_d01_sigterm_inflight.py new file mode 100644 index 00000000..8c93966c --- /dev/null +++ b/bench/matrix/tests/test_d01_sigterm_inflight.py @@ -0,0 +1,45 @@ +"""D01: SIGTERM while requests are in flight against a slow intake. + +Every ECS deployment sends SIGTERM. A batch that was accepted with 202 but +never forwarded is data the sender believes is safe, so the shutdown must +either finish the exchange or refuse it. +""" + +import threading +import time + +from harness import MatrixCase + + +class SigtermInFlight(MatrixCase): + INTAKE_LATENCY = 4000 + TERMINATES_EDGE = True + SLOW = True + + def test_shutdown_neither_hangs_nor_invents_success(self): + answers = [] + + def sender(): + try: + answers.append(self.post_logs(timeout=60).status_code) + except Exception as err: + answers.append(type(err).__name__) + + threads = [threading.Thread(target=sender, daemon=True) for _ in range(4)] + for thread in threads: + thread.start() + time.sleep(1.0) # the exchanges are open against the slow intake + + code, seconds = self.edge.terminate_and_wait(timeout=45) + for thread in threads: + thread.join(timeout=60) + + self.assertIsNotNone(code, "the edge did not exit within 45 s of SIGTERM") + self.assertLess(seconds, 35, "shutdown took %.0f s" % seconds) + + accepted = sum(1 for a in answers if a == 202) + self.assertLessEqual( + accepted, + self.intake.requests_seen(), + "a batch was accepted with 202 that the intake never received", + ) diff --git a/bench/matrix/tests/test_d02_sigterm_hung_intake.py b/bench/matrix/tests/test_d02_sigterm_hung_intake.py new file mode 100644 index 00000000..ac6800cf --- /dev/null +++ b/bench/matrix/tests/test_d02_sigterm_hung_intake.py @@ -0,0 +1,31 @@ +"""D02: SIGTERM while the intake is hung. + +Forced upstream expiry exists for this: the shutdown path cuts every tracked +exchange. Without it the container waits for the orchestrator's kill. +""" + +import threading +import time + +from harness import MatrixCase + + +class SigtermHungIntake(MatrixCase): + TERMINATES_EDGE = True + SLOW = True + + def test_a_hung_intake_does_not_delay_shutdown(self): + self.intake.arm("hang") + for _ in range(4): + threading.Thread(target=self._quiet_post, daemon=True).start() + time.sleep(2) + + code, seconds = self.edge.terminate_and_wait(timeout=45) + self.assertIsNotNone(code, "the edge never exited with a hung intake") + self.assertLess(seconds, 20, "shutdown waited %.0f s on a hung intake" % seconds) + + def _quiet_post(self): + try: + self.post_logs(timeout=60) + except Exception: + pass diff --git a/bench/matrix/tests/test_d03_sigterm_idle_keepalive.py b/bench/matrix/tests/test_d03_sigterm_idle_keepalive.py new file mode 100644 index 00000000..3783868f --- /dev/null +++ b/bench/matrix/tests/test_d03_sigterm_idle_keepalive.py @@ -0,0 +1,28 @@ +"""D03: SIGTERM with idle keep-alive connections open. + +The idle deadline is 30 s. If shutdown waits for it, every deployment stalls +for half a minute per task. +""" + +from harness import MatrixCase + + +class SigtermIdleKeepalive(MatrixCase): + TERMINATES_EDGE = True + + def test_idle_connections_do_not_delay_shutdown(self): + held = [self.raw(timeout=30) for _ in range(8)] + try: + for client in held: + client.send(self.head(body_len=0)) + code, seconds = self.edge.terminate_and_wait(timeout=45) + finally: + for client in held: + client.close() + + self.assertIsNotNone(code, "the edge never exited with idle connections open") + self.assertLess( + seconds, + 10, + "shutdown waited %.0f s for idle connections; the idle deadline is 30 s" % seconds, + ) diff --git a/bench/matrix/tests/test_d04_startup_with_intake_down.py b/bench/matrix/tests/test_d04_startup_with_intake_down.py new file mode 100644 index 00000000..278502e7 --- /dev/null +++ b/bench/matrix/tests/test_d04_startup_with_intake_down.py @@ -0,0 +1,45 @@ +"""D04: the intake is unreachable when the edge starts, then comes back. + +ECS starts a sidecar before the network settles. The edge must come up, answer +health throughout, and recover on its own once the intake appears — without a +restart. +""" + +import time + +from harness import MatrixCase, EchoIntake +from harness.procs import Edge, free_port + + +class StartupWithIntakeDown(MatrixCase): + ALLOW_PHANTOM_SUCCESS = True + + def setUp(self): + # Point the edge at a port nothing is listening on yet, and keep it so + # the intake can appear there later. + self.port = free_port() + self.intake = EchoIntake(port=self.port) + self.intake.stop() # the edge starts blind + self.edge = Edge("http://127.0.0.1:%d" % self.port) + self.baseline = self.edge.metrics() + self.log_snapshot = set(self.edge.logs().splitlines()) + self.baseline_descriptors = self.edge.descriptors() + self.baseline_intake = 0 + + def test_the_edge_starts_blind_and_recovers(self): + self.assertEqual(self.health().status_code, 200, "health must not depend on the intake") + try: + first = self.post_logs(timeout=30).status_code + except Exception: + first = None + self.assertNotEqual(first, 202, "a batch succeeded with no intake listening") + + # The intake appears on the port the edge was configured with. + self.intake = EchoIntake(port=self.port) + time.sleep(0.5) + self.assertEqual( + self.post_logs(timeout=30).status_code, + 202, + "the edge did not recover once the intake appeared", + ) + self.assertEqual(self.health().status_code, 200) diff --git a/bench/matrix/tests/test_d05_policy_reload.py b/bench/matrix/tests/test_d05_policy_reload.py new file mode 100644 index 00000000..a67fd59b --- /dev/null +++ b/bench/matrix/tests/test_d05_policy_reload.py @@ -0,0 +1,59 @@ +"""D05: the policy file changes while traffic flows. + +The control plane rewrites policies in production. A reload must not fail +requests, and an invalid file must leave the previous snapshot in place rather +than disarming the edge. +""" + +import json +import threading +import time + +from harness import MatrixCase + +KEEP_ALL = { + "policies": [ + { + "id": "keep-all", + "name": "keep-all", + "log": {"match": [{"log_field": "body", "regex": ".*"}], "keep": "all"}, + } + ] +} + + +class PolicyReloadUnderLoad(MatrixCase): + SLOW = True + EDGE_POLICIES = KEEP_ALL + + def test_a_reload_does_not_fail_requests(self): + failures = [] + stop = threading.Event() + + def sender(): + while not stop.is_set(): + try: + if self.post_logs(timeout=20).status_code != 202: + failures.append("status") + except Exception: + failures.append("error") + + traffic = [threading.Thread(target=sender, daemon=True) for _ in range(4)] + for thread in traffic: + thread.start() + try: + time.sleep(1) + # A valid rewrite, then a broken one. + with open(self._policy_path, "w") as handle: + json.dump(KEEP_ALL, handle) + time.sleep(2) + with open(self._policy_path, "w") as handle: + handle.write("{ this is not json") + time.sleep(3) + finally: + stop.set() + for thread in traffic: + thread.join(timeout=30) + + self.assertEqual(failures, [], "%d requests failed across the reload" % len(failures)) + self.assertEqual(self.health().status_code, 200) diff --git a/bench/perf/sweep.py b/bench/perf/sweep.py new file mode 100644 index 00000000..1b496f1a --- /dev/null +++ b/bench/perf/sweep.py @@ -0,0 +1,298 @@ +#!/usr/bin/env python3 +"""Throughput, latency and memory across the shapes and settings that matter. + +Drives `oha` against the real edge binary with the real echo server behind it, +for both frontends, and prints one table per axis. Each axis varies one thing +and holds the rest at the baseline, so a row is readable on its own and two +runs on the same host are comparable. + + ./bin/uv run --python ./bin/python3 --with requests bench/perf/sweep.py + ./bin/uv run --python ./bin/python3 --with requests bench/perf/sweep.py --axes policies,latency + ./bin/uv run --python ./bin/python3 --with requests bench/perf/sweep.py --seconds 20 --frontend stdio + +Baseline: the small Datadog payload, 64 connections, one policy loaded, an +intake that answers immediately, and the shipped thread-pool and connection +limits. + +Axes: + + payload small (228 B), boundary (64 KiB, where a body stops being held + resident), large (the 1.4 MB Datadog payload), gzip + conns concurrent senders + policies how many rules are loaded. Most do not match, which is the + shape a real policy set has + latency what the intake costs per request, in milliseconds + threads `thread_pool_count`. httpz sizes its handler pool from this; + stdio runs a task per connection and ignores it, which is worth + showing rather than assuming + maxconn `max_connections`, which sizes the connection slab on stdio and + the per-worker connection table on httpz +""" + +from __future__ import annotations + +import argparse +import gzip +import json +import os +import shutil +import subprocess +import sys +import tempfile +import threading +import time + +sys.stdout.reconfigure(line_buffering=True) + +HERE = os.path.dirname(os.path.abspath(__file__)) +REPO_ROOT = os.path.abspath(os.path.join(HERE, "..", "..")) +sys.path.insert(0, os.path.join(REPO_ROOT, "bench", "matrix")) + +from harness import Edge, EchoIntake # noqa: E402 + +BINARIES = { + "httpz": os.path.join(REPO_ROOT, "zig-out", "bin", "edge"), + "stdio": os.path.join(REPO_ROOT, "zig-out-stdio", "bin", "edge"), +} + +PAYLOAD_DIR = os.path.join(REPO_ROOT, "bench", "perf", "payloads") + +#: One row of settings. The axes below each change a single field. +BASELINE = { + "payload": "small", + "conns": 64, + "policies": 1, + "latency": 0, + "threads": None, # None means the shipped default + "maxconn": None, +} + +AXES = { + "payload": ["small", "boundary", "large", "gzip"], + "conns": [16, 64, 256], + "policies": [0, 1, 10, 50], + "latency": [0, 5, 50, 200], + "threads": [8, 32, 128], + "maxconn": [64, 256, 1024], +} + + +def payload(name: str) -> tuple[bytes, dict]: + if name == "small": + with open(os.path.join(PAYLOAD_DIR, "datadog-small.json"), "rb") as handle: + return handle.read(), {} + if name == "large": + with open(os.path.join(PAYLOAD_DIR, "datadog-1mb.json"), "rb") as handle: + return handle.read(), {} + if name == "boundary": + body = json.dumps([{"message": "x" * 64 * 1024, "ddsource": "bench"}]).encode() + return body, {} + if name == "gzip": + with open(os.path.join(PAYLOAD_DIR, "datadog-1mb.json"), "rb") as handle: + return gzip.compress(handle.read()), {"Content-Encoding": "gzip"} + raise SystemExit("unknown payload %r" % name) + + +def policy_document(count: int) -> dict: + """`count` rules, all but one non-matching. + + A real policy set is mostly rules that do not fire, and every one of them + is still evaluated per record. `.+` rather than `.*`, because Hyperscan + refuses a pattern that can match an empty buffer and the rule would + silently do nothing. + """ + policies = [] + for i in range(max(0, count - 1)): + policies.append({ + "id": "miss-%d" % i, + "name": "miss-%d" % i, + "log": {"match": [{"log_field": "body", "regex": "needle-%d-absent" % i}], "keep": "all"}, + }) + if count > 0: + policies.append({ + "id": "keep-all", + "name": "keep-all", + "log": {"match": [{"log_field": "body", "regex": ".+"}], "keep": "all"}, + }) + return {"policies": policies} + + +#: How much a short sleep may overshoot before the latency axis is measuring +#: the host instead of the edge. A millisecond or two is ordinary scheduling; +#: tens of milliseconds swamp a 5 ms intake. +TIMER_OVERSHOOT_BUDGET_MS = 3.0 + + +def timer_overshoot_ms() -> float: + """How far a short sleep overshoots on this host, in milliseconds. + + The latency axis simulates intake latency with a sleep, so a host whose + timers are stretched measures its own scheduler rather than the edge. One + machine here reported 33.5 ms for `sleep(5 ms)` while a busy-wait of the + same length measured 5.0 ms exactly: the CPU was fine and only + timer-driven wakeups were late. That run produced a table showing a 100x + throughput collapse that had nothing to do with either frontend, so the + axis now refuses to run on a host like that. + """ + want = 0.005 + rounds = 20 + started = time.monotonic() + for _ in range(rounds): + time.sleep(want) + measured = (time.monotonic() - started) / rounds + return (measured - want) * 1000 + + +def peak_rss_mb(pid: int, stop_after: float) -> float: + peak = 0.0 + deadline = time.monotonic() + stop_after + while time.monotonic() < deadline: + out = subprocess.run(["ps", "-o", "rss=", "-p", str(pid)], capture_output=True, text=True) + try: + peak = max(peak, int(out.stdout.strip()) / 1024) + except ValueError: + break + time.sleep(0.5) + return peak + + +def run_oha(url: str, body: bytes, headers: dict, connections: int, seconds: int) -> dict: + body_file = tempfile.NamedTemporaryFile("wb", suffix=".bin", delete=False) + body_file.write(body) + body_file.close() + out_file = tempfile.NamedTemporaryFile("r", suffix=".json", delete=False) + out_file.close() + + command = [ + "oha", "-z", "%ds" % seconds, "-c", str(connections), "-m", "POST", + "-H", "Content-Type: application/json", + ] + for name, value in headers.items(): + command += ["-H", "%s: %s" % (name, value)] + command += ["-D", body_file.name, "--no-tui", "--output-format", "json", "-o", out_file.name, url] + subprocess.run(command, check=True, capture_output=True) + + with open(out_file.name) as handle: + report = json.load(handle) + os.unlink(body_file.name) + os.unlink(out_file.name) + return report + + +def measure(frontend: str, settings: dict, seconds: int) -> dict: + body, headers = payload(settings["payload"]) + os.environ["EDGE_BIN"] = BINARIES[frontend] + + intake = EchoIntake(latency_ms=settings["latency"]) + config = {"max_body_size": 4 * 1024 * 1024} + if settings["threads"] is not None: + config["thread_pool_count"] = settings["threads"] + if settings["maxconn"] is not None: + config["max_connections"] = settings["maxconn"] + if settings["policies"] > 0: + handle = tempfile.NamedTemporaryFile("w", suffix=".json", delete=False) + json.dump(policy_document(settings["policies"]), handle) + handle.close() + config["policy_providers"] = [{"id": "file", "type": "file", "path": handle.name}] + + edge = Edge(intake.url, config) + running = edge.frontend() + if running is not None and running != frontend: + raise SystemExit("%s carries the %s frontend; rebuild with --prefix" % (BINARIES[frontend], running)) + try: + rss = {"peak": 0.0} + watcher = threading.Thread( + target=lambda: rss.update(peak=peak_rss_mb(edge.pid, seconds + 2)), daemon=True + ) + watcher.start() + report = run_oha(edge.url + "/api/v2/logs", body, headers, settings["conns"], seconds) + watcher.join(timeout=seconds + 10) + rejected = edge.metric("edge_policies_rejected") + finally: + edge.stop() + intake.stop() + + if rejected: + raise SystemExit("%d policies were rejected; the run measured the wrong path" % rejected) + + summary = report["summary"] + percentiles = report["latencyPercentiles"] + codes = report["statusCodeDistribution"] + return { + "frontend": frontend, + **settings, + "rps": summary["requestsPerSec"], + "p50": percentiles["p50"] * 1000, + "p99": percentiles["p99"] * 1000, + "p99.9": percentiles["p99.9"] * 1000, + "max": summary["slowest"] * 1000, + "rss": rss["peak"], + "codes": codes, + } + + +HEADER = "%-7s %-10s %9s %8s %8s %9s %9s %8s %s" +ROW = "%-7s %-10s %9.0f %8.1f %8.1f %9.1f %9.1f %8.1f %s" + + +def print_row(axis: str, row: dict) -> None: + other = ",".join( + "%s=%s" % (k, row[k]) for k in ("payload", "conns", "policies", "latency", "threads", "maxconn") + if k != axis and row[k] != BASELINE[k] + ) + non_2xx = {k: v for k, v in row["codes"].items() if not k.startswith("2")} + note = ("shed %s" % non_2xx) if non_2xx else other + print(ROW % ( + row["frontend"], str(row[axis]), row["rps"], row["p50"], row["p99"], + row["p99.9"], row["max"], row["rss"], note)) + + +def main() -> int: + parser = argparse.ArgumentParser() + parser.add_argument("--seconds", type=int, default=12) + parser.add_argument("--frontend", choices=("stdio", "httpz", "both"), default="both") + parser.add_argument("--axes", default=",".join(AXES)) + parser.add_argument("--out", default="/tmp/edge-perf-sweep.json") + parser.add_argument("--force-latency", action="store_true", + help="run the latency axis even where the host's timers are stretched") + args = parser.parse_args() + + if not shutil.which("oha"): + raise SystemExit("oha is required (brew install oha)") + + frontends = ["httpz", "stdio"] if args.frontend == "both" else [args.frontend] + results = [] + + axes = args.axes.split(",") + if "latency" in axes: + overshoot = timer_overshoot_ms() + print("timer check: sleep(5 ms) overshoots by %.1f ms on this host" % overshoot) + if overshoot > TIMER_OVERSHOOT_BUDGET_MS and not args.force_latency: + axes = [a for a in axes if a != "latency"] + print("skipping the latency axis: a %.0f ms overshoot would be the " + "intake's delay, not the intake. Pass --force-latency to run " + "it anyway." % overshoot) + + for axis in axes: + if axis not in AXES: + raise SystemExit("unknown axis %r; choose from %s" % (axis, ",".join(AXES))) + print("\n== %s (everything else at the baseline) ==" % axis) + print(HEADER % ("front", axis, "rps", "p50 ms", "p99 ms", "p99.9 ms", "max ms", "rss MB", "notes")) + print("-" * 104) + for value in AXES[axis]: + settings = dict(BASELINE) + settings[axis] = value + for frontend in frontends: + row = measure(frontend, settings, args.seconds) + row["axis"] = axis + results.append(row) + print_row(axis, row) + + with open(args.out, "w") as handle: + json.dump(results, handle, indent=1) + print("\n%d rows written to %s" % (len(results), args.out)) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/bin/.python3-3.12.3.pkg b/bin/.python3-3.12.3.pkg new file mode 120000 index 00000000..383f4511 --- /dev/null +++ b/bin/.python3-3.12.3.pkg @@ -0,0 +1 @@ +hermit \ No newline at end of file diff --git a/bin/pip b/bin/pip new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/pip @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/pip3 b/bin/pip3 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/pip3 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/pip3.12 b/bin/pip3.12 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/pip3.12 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/pydoc3 b/bin/pydoc3 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/pydoc3 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/pydoc3.12 b/bin/pydoc3.12 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/pydoc3.12 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/python b/bin/python new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/python @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/python3 b/bin/python3 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/python3 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/python3-config b/bin/python3-config new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/python3-config @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/python3.12 b/bin/python3.12 new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/python3.12 @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/bin/python3.12-config b/bin/python3.12-config new file mode 120000 index 00000000..0289f6d3 --- /dev/null +++ b/bin/python3.12-config @@ -0,0 +1 @@ +.python3-3.12.3.pkg \ No newline at end of file diff --git a/src/bench/echo_server.zig b/src/bench/echo_server.zig index 4bc9b011..6747b69a 100644 --- a/src/bench/echo_server.zig +++ b/src/bench/echo_server.zig @@ -11,6 +11,62 @@ const CapturedPayload = struct { data: []const u8, }; +/// Upstream faults the echo server can inject, so the matrix suite can drive +/// the edge's upstream leg through every failure it must survive. Armed over +/// HTTP (`POST /fault?mode=...`), applied to the echo path only, so /stats and +/// /fault stay reachable while a fault is armed. +pub const Fault = enum { + /// Answer 202 as usual. + none, + /// Answer with `arg` as the status code. + status, + /// Read the body, then never answer. The client's watchdog must cut it. + hang, + /// Read part of the body, then close with no answer. + close_early, + /// Answer before reading the body, as a real intake does when it rejects + /// a batch on its headers. + reject_early, + /// Close with RST and no answer. + reset, + /// Write bytes that are not HTTP. + garbage, + /// Declare a content-length larger than the body written, then close. + truncate, + /// Answer after `arg` milliseconds. + slow, + /// Answer with a body of `arg` bytes. + oversize, + /// Answer 202, then close at once, so the next pooled request finds a + /// dead keep-alive connection. + stale_keepalive, + /// Read the whole body, then close with no answer. The batch arrived, so + /// a retry delivers it twice: this is what pins at-least-once. + read_then_close, + /// Read the whole body, then answer 202 with a content-length it does not + /// fulfil. Unlike `truncate`, the batch was accepted before the answer + /// broke, which is the case where a retry duplicates rather than repairs. + truncate_after_read, + /// Answer 202 with `Connection: close`. The client must not pool it. + keep_alive_off, + /// Answer 204, which carries no body. A relay that re-frames it as + /// chunked violates the protocol and some clients reject it. + bodiless, + /// Answer 308 with a Location. Redirects are unhandled by design, so this + /// checks the sender is told rather than left guessing. + redirect, + /// Answer with `arg` extra headers, the mirror of a header flood inbound. + header_flood, + /// Answer HTTP/1.0 with no content-length, so the body ends at the close. + http10_no_length, + /// Dribble the answer body, one chunk per `arg` milliseconds. + slow_body, + /// Read the request body a few bytes at a time, so a large send blocks. + slow_read, + /// Accept the connection and never read or write it. + accept_silence, +}; + pub const ServerContext = struct { allocator: std.mem.Allocator, io: std.Io, @@ -19,6 +75,21 @@ pub const ServerContext = struct { total_requests: std.atomic.Value(u64) = std.atomic.Value(u64).init(0), total_bytes: std.atomic.Value(u64) = std.atomic.Value(u64).init(0), + /// The most recent request target, so a test can assert that a base path + /// and a query survive the trip byte for byte. + last_target: [512]u8 = undefined, + last_target_len: usize = 0, + + // Fault injection state + fault_mutex: std.Io.Mutex = .init, + fault: Fault = .none, + /// Status code, milliseconds or byte count, by fault. + fault_arg: u32 = 0, + /// Requests left to fault. `null` means every request until it is cleared. + fault_remaining: ?u32 = null, + /// Faults applied since the last arm, so a test can assert it fired. + fault_applied: std.atomic.Value(u64) = std.atomic.Value(u64).init(0), + // Capture mode state capture_mutex: std.Io.Mutex = .init, capture_enabled: bool = false, @@ -156,6 +227,50 @@ pub const ServerContext = struct { } } + pub fn armFault(self: *ServerContext, fault: Fault, arg: u32, count: ?u32) void { + self.fault_mutex.lockUncancelable(self.io); + defer self.fault_mutex.unlock(self.io); + self.fault = fault; + self.fault_arg = arg; + self.fault_remaining = count; + self.fault_applied.store(0, .monotonic); + } + + /// The fault for this request, with the counter spent. + pub fn takeFault(self: *ServerContext) struct { Fault, u32 } { + self.fault_mutex.lockUncancelable(self.io); + defer self.fault_mutex.unlock(self.io); + if (self.fault == .none) return .{ .none, 0 }; + if (self.fault_remaining) |left| { + if (left == 0) return .{ .none, 0 }; + self.fault_remaining = left - 1; + } + _ = self.fault_applied.fetchAdd(1, .monotonic); + return .{ self.fault, self.fault_arg }; + } + + pub fn clearFault(self: *ServerContext) void { + self.armFault(.none, 0, null); + } + + /// The armed fault without spending the counter. + pub fn peekFault(self: *ServerContext) Fault { + self.fault_mutex.lockUncancelable(self.io); + defer self.fault_mutex.unlock(self.io); + if (self.fault_remaining) |left| { + if (left == 0) return .none; + } + return self.fault; + } + + pub fn recordTarget(self: *ServerContext, target: []const u8) void { + self.mutex.lockUncancelable(self.io); + defer self.mutex.unlock(self.io); + const len = @min(target.len, self.last_target.len); + @memcpy(self.last_target[0..len], target[0..len]); + self.last_target_len = len; + } + pub fn reset(self: *ServerContext) void { self.total_requests.store(0, .monotonic); self.total_bytes.store(0, .monotonic); @@ -169,6 +284,8 @@ pub const ServerContext = struct { entry.value_ptr.bytes.store(0, .monotonic); } + self.clearFault(); + // Also clear captures self.capture_mutex.lockUncancelable(self.io); defer self.capture_mutex.unlock(self.io); @@ -198,12 +315,20 @@ pub const ServerContext = struct { self.capture_mutex.lockUncancelable(self.io); defer self.capture_mutex.unlock(self.io); - try writer.print("}},\"total_requests\":{d},\"total_bytes\":{d}," ++ - "\"capture_enabled\":{},\"captured_count\":{d}}}", .{ + self.fault_mutex.lockUncancelable(self.io); + defer self.fault_mutex.unlock(self.io); + + try writer.print("}},\"last_target\":\"{s}\",", .{self.last_target[0..self.last_target_len]}); + try writer.print("\"total_requests\":{d},\"total_bytes\":{d}," ++ + "\"capture_enabled\":{},\"captured_count\":{d}," ++ + "\"fault\":\"{s}\",\"fault_arg\":{d},\"fault_applied\":{d}}}", .{ self.total_requests.load(.monotonic), self.total_bytes.load(.monotonic), self.capture_enabled, self.captured_payloads.items.len, + @tagName(self.fault), + self.fault_arg, + self.fault_applied.load(.monotonic), }); } }; @@ -220,7 +345,46 @@ fn shutdown(_: std.posix.SIG) callconv(.c) void { std.process.exit(0); } -fn handleRequest(ctx: *ServerContext, request: *std.http.Server.Request, gpa: std.mem.Allocator) !void { +/// `key=value` from a raw query string, or null. +fn queryValue(query: []const u8, key: []const u8) ?[]const u8 { + var it = std.mem.splitScalar(u8, query, '&'); + while (it.next()) |pair| { + const eq = std.mem.findScalar(u8, pair, '=') orelse continue; + if (std.mem.eql(u8, pair[0..eq], key)) return pair[eq + 1 ..]; + } + return null; +} + +/// Closes with RST rather than FIN, which is what a peer that crashed looks +/// like. Bench-only code, so std.posix here is fine. +fn resetConnection(stream: std.Io.net.Stream) void { + const linger: std.posix.linger = .{ .onoff = 1, .linger = 0 }; + std.posix.setsockopt( + stream.socket.handle, + std.posix.SOL.SOCKET, + std.posix.SO.LINGER, + std.mem.asBytes(&linger), + ) catch |err| { + // The test that armed this fault expects an RST, so say when it + // degrades to a normal close. + std.debug.print("reset fault: SO_LINGER failed: {s}\n", .{@errorName(err)}); + }; +} + +/// Writes straight to the socket, past the HTTP state machine. +fn writeRaw(ctx: *ServerContext, stream: std.Io.net.Stream, bytes: []const u8) void { + var buf: [512]u8 = undefined; + var writer = std.Io.net.Stream.Writer.init(stream, ctx.io, &buf); + writer.interface.writeAll(bytes) catch return; + writer.interface.flush() catch return; +} + +fn handleRequest( + ctx: *ServerContext, + request: *std.http.Server.Request, + gpa: std.mem.Allocator, + stream: std.Io.net.Stream, +) !void { const target = request.head.target; const query_start = std.mem.findScalar(u8, target, '?'); const path = if (query_start) |i| target[0..i] else target; @@ -248,6 +412,29 @@ fn handleRequest(ctx: *ServerContext, request: *std.http.Server.Request, gpa: st return; } + if (std.mem.eql(u8, path, "/fault")) { + const mode = queryValue(query, "mode") orelse "none"; + const fault = std.meta.stringToEnum(Fault, mode) orelse { + try request.respond("{\"error\":\"unknown mode\"}", .{ + .keep_alive = keep_alive, + .status = .bad_request, + .extra_headers = &json_headers, + }); + return; + }; + const arg = if (queryValue(query, "arg")) |raw| std.fmt.parseInt(u32, raw, 10) catch 0 else 0; + const count: ?u32 = if (queryValue(query, "count")) |raw| + std.fmt.parseInt(u32, raw, 10) catch null + else + null; + ctx.armFault(fault, arg, count); + try request.respond("{\"status\":\"fault_armed\"}", .{ + .keep_alive = keep_alive, + .extra_headers = &json_headers, + }); + return; + } + if (std.mem.eql(u8, path, "/reset")) { ctx.reset(); try request.respond("{\"status\":\"reset\"}", .{ .keep_alive = keep_alive, .extra_headers = &json_headers }); @@ -288,6 +475,37 @@ fn handleRequest(ctx: *ServerContext, request: *std.http.Server.Request, gpa: st // record stats, optionally capture, answer 202. // path and content_type point into the head buffer, which the body read // below reuses — copy them first or they get clobbered with body bytes. + const fault, const fault_arg = ctx.takeFault(); + // These answer (or refuse to) before the body is read, which is what a + // real intake does when it rejects a batch on its headers. + switch (fault) { + .reject_early => { + try request.respond("{\"errors\":[\"invalid payload\"]}", .{ + .keep_alive = false, + .status = .bad_request, + .extra_headers = &json_headers, + }); + return; + }, + .reset => { + resetConnection(stream); + return error.FaultReset; + }, + .garbage => { + writeRaw(ctx, stream, "NOT-HTTP \x00\x01 garbage\r\n\r\n"); + return error.FaultGarbage; + }, + .truncate => { + writeRaw( + ctx, + stream, + "HTTP/1.1 202 Accepted\r\ncontent-length: 4096\r\n\r\nshort", + ); + return error.FaultTruncate; + }, + else => {}, + } + const path_copy = try gpa.dupe(u8, path); defer gpa.free(path_copy); const content_type_copy: ?[]const u8 = if (request.head.content_type) |ct| @@ -301,16 +519,21 @@ fn handleRequest(ctx: *ServerContext, request: *std.http.Server.Request, gpa: st defer captured.deinit(); if (!unframed_body) { const body_reader = try request.readerExpectContinue(&body_buf); + // `slow_read` trickles the body off the socket, so a sender with a + // body larger than the socket buffer blocks in its send. + const slice: usize = if (fault == .slow_read) 64 else 5 * 1024 * 1024; while (true) { - const n = body_reader.stream(&captured.writer, .limited(5 * 1024 * 1024)) catch |err| switch (err) { + const n = body_reader.stream(&captured.writer, .limited(slice)) catch |err| switch (err) { error.EndOfStream => break, else => return err, }; if (n == 0) break; + if (fault == .slow_read) try ctx.io.sleep(.fromMilliseconds(@max(fault_arg, 1)), .awake); } } const body = captured.written(); + ctx.recordTarget(target); ctx.recordRequest(path_copy, body.len); if (body.len > 0) { ctx.capturePayload(path_copy, content_type_copy orelse "application/octet-stream", body); @@ -321,12 +544,104 @@ fn handleRequest(ctx: *ServerContext, request: *std.http.Server.Request, gpa: st // throughput collapses to `handler_threads / round_trip`. Applied to the // echo path only, so /stats and /reset stay instant for the harness. if (latency_ms > 0) try ctx.io.sleep(.fromMilliseconds(latency_ms), .awake); + + switch (fault) { + .hang => { + // Long enough that every deadline under test fires first. + try ctx.io.sleep(.fromMilliseconds(600_000), .awake); + return; + }, + .close_early => return error.FaultCloseEarly, + // The body is already read and recorded by this point. + .read_then_close => return error.FaultReadThenClose, + .truncate_after_read => { + writeRaw( + ctx, + stream, + "HTTP/1.1 202 Accepted\r\ncontent-length: 4096\r\n\r\nshort", + ); + return error.FaultTruncateAfterRead; + }, + .slow => try ctx.io.sleep(.fromMilliseconds(fault_arg), .awake), + .status => { + try request.respond("{\"faulted\":true}", .{ + .keep_alive = keep_alive, + .status = @enumFromInt(fault_arg), + .extra_headers = &json_headers, + }); + return; + }, + .oversize => { + const filler = try gpa.alloc(u8, fault_arg); + defer gpa.free(filler); + @memset(filler, 'x'); + try request.respond(filler, .{ .keep_alive = keep_alive, .status = .accepted }); + return; + }, + .keep_alive_off => { + try request.respond("{}", .{ .keep_alive = false, .status = .accepted, .extra_headers = &json_headers }); + return; + }, + .bodiless => { + try request.respond("", .{ .keep_alive = keep_alive, .status = .no_content }); + return; + }, + .redirect => { + try request.respond("", .{ + .keep_alive = keep_alive, + .status = .permanent_redirect, + .extra_headers = &.{.{ .name = "location", .value = "http://127.0.0.1:1/moved" }}, + }); + return; + }, + .header_flood => { + const count = @min(fault_arg, 96); + var names: [96][16]u8 = undefined; + var headers: [96]std.http.Header = undefined; + for (0..count) |i| { + _ = std.fmt.bufPrint(&names[i], "x-flood-{d:0>3}", .{i}) catch unreachable; + headers[i] = .{ .name = names[i][0..11], .value = "v" }; + } + try request.respond("{}", .{ + .keep_alive = keep_alive, + .status = .accepted, + .extra_headers = headers[0..count], + }); + return; + }, + .http10_no_length => { + writeRaw(ctx, stream, "HTTP/1.0 202 Accepted\r\n\r\n{\"read\":\"until close\"}"); + return error.FaultHttp10; + }, + .slow_body => { + writeRaw(ctx, stream, "HTTP/1.1 202 Accepted\r\ncontent-length: 64\r\n\r\n"); + var sent: usize = 0; + while (sent < 64) : (sent += 8) { + writeRaw(ctx, stream, "xxxxxxxx"); + try ctx.io.sleep(.fromMilliseconds(@max(fault_arg, 1)), .awake); + } + return error.FaultSlowBody; + }, + .stale_keepalive => { + // Answer, then drop the connection the client just pooled. + try request.respond("{}", .{ .keep_alive = true, .status = .accepted, .extra_headers = &json_headers }); + return error.FaultStaleKeepalive; + }, + else => {}, + } try request.respond("{}", .{ .keep_alive = keep_alive, .status = .accepted, .extra_headers = &json_headers }); } fn serveConnection(ctx: *ServerContext, gpa: std.mem.Allocator, stream: std.Io.net.Stream) std.Io.Cancelable!void { defer stream.close(ctx.io); + // Accepted and then ignored: no read, no write, no answer. + if (ctx.peekFault() == .accept_silence) { + _ = ctx.takeFault(); + try ctx.io.sleep(.fromMilliseconds(600_000), .awake); + return; + } + var recv_buf: [32 * 1024]u8 = undefined; var send_buf: [32 * 1024]u8 = undefined; var net_reader = std.Io.net.Stream.Reader.init(stream, ctx.io, &recv_buf); @@ -335,7 +650,9 @@ fn serveConnection(ctx: *ServerContext, gpa: std.mem.Allocator, stream: std.Io.n while (server.reader.state == .ready) { var request = server.receiveHead() catch return; - handleRequest(ctx, &request, gpa) catch return; + // A fault that closes the connection surfaces as an error, and the + // defer above closes the stream. + handleRequest(ctx, &request, gpa, stream) catch return; } } @@ -398,6 +715,7 @@ pub fn main(init: std.process.Init) !void { std.debug.print(" POST /reset - Reset statistics\n", .{}); std.debug.print(" GET /capture/start?name= - Start capturing payloads\n", .{}); std.debug.print(" GET /capture/stop - Stop capturing and save to file\n", .{}); + std.debug.print(" POST /fault?mode=&arg=&count= - Arm an upstream fault\n", .{}); std.debug.print("Press Ctrl+C to stop\n", .{}); var group: std.Io.Group = .init; diff --git a/src/core/arena_pool.zig b/src/core/arena_pool.zig index 3e28813c..934901b8 100644 --- a/src/core/arena_pool.zig +++ b/src/core/arena_pool.zig @@ -16,7 +16,9 @@ pub const ArenaPool = struct { reserve: usize, pub fn init(gpa: std.mem.Allocator, limits: limits_mod.Limits) !ArenaPool { - const n = limits.max_connections; + // Matches the slab exactly, including the control reserve: a + // reserved connection claims an arena like any other. + const n = limits.connectionSlots(); std.debug.assert(n > 0); std.debug.assert(n < std.math.maxInt(u16)); diff --git a/src/core/conn_slab.zig b/src/core/conn_slab.zig index 220c43ca..bd029e9d 100644 --- a/src/core/conn_slab.zig +++ b/src/core/conn_slab.zig @@ -68,16 +68,27 @@ pub const ConnSlab = struct { buffers: []align(std.heap.page_size_min) u8, /// Stack of free slot indexes; claim pops, release pushes. free_list: []u16, + /// The socket each claimed slot is serving, so shutdown can interrupt a + /// read that is waiting on its deadline. Cancellation does not reach a + /// task parked in a poll, so without this a SIGTERM waited out the idle + /// deadline: 30 s per deployment, against the orchestrator's kill timer. + sockets: []?std.Io.net.Stream, free_count: usize, mutex: std.Io.Mutex, limits: limits_mod.Limits, + /// Slots an ordinary connection may not take, so a health probe can still + /// be read while the slab is full. See limits.CONTROL_RESERVE_SLOTS. + reserve: usize, pub fn init(gpa: std.mem.Allocator, limits: limits_mod.Limits) !ConnSlab { // u16 slot indexes bound the slab; 65k concurrent connections is far // beyond this proxy's design envelope. std.debug.assert(limits.max_connections > 0); - std.debug.assert(limits.max_connections < std.math.maxInt(u16)); - const n = limits.max_connections; + std.debug.assert(limits.connectionSlots() < std.math.maxInt(u16)); + // The control reserve is extra capacity, not a slice of the operator's + // cap: `claim` must still yield `max_connections` ordinary slots, or a + // deployment sized to its sender count sheds the last few senders. + const n = limits.connectionSlots(); var hot: std.MultiArrayList(ConnHot) = .empty; errdefer hot.deinit(gpa); @@ -97,6 +108,10 @@ pub const ConnSlab = struct { const free_list = try gpa.alloc(u16, n); errdefer gpa.free(free_list); + + const sockets = try gpa.alloc(?std.Io.net.Stream, n); + errdefer gpa.free(sockets); + @memset(sockets, null); // Pop order is LIFO: slot 0 first, keeping low slots (and their warm // cache lines) in rotation under light load. for (free_list, 0..) |*slot, i| slot.* = @intCast(n - 1 - i); @@ -105,9 +120,11 @@ pub const ConnSlab = struct { .hot = hot, .buffers = buffers, .free_list = free_list, + .sockets = sockets, .free_count = n, .mutex = .init, .limits = limits, + .reserve = limits_mod.CONTROL_RESERVE_SLOTS, }; } @@ -115,22 +132,40 @@ pub const ConnSlab = struct { self.hot.deinit(gpa); std.heap.page_allocator.free(self.buffers); gpa.free(self.free_list); + gpa.free(self.sockets); self.* = undefined; } /// Claims a slot, or null when the slab is exhausted (caller load-sheds /// with 503). Never blocks beyond the mutex, never allocates. + /// + /// Leaves `reserve` slots untouched; `claimReserved` reaches those, and + /// the caller must close such a connection after one request so the + /// reserve recycles. pub fn claim(self: *ConnSlab, io: std.Io) ?ConnId { + return self.claimInner(io, false); + } + + /// Claims from the reserve. Only for a connection that will be answered + /// and closed at once, so a control path can be served while the rest of + /// the slab is full. + pub fn claimReserved(self: *ConnSlab, io: std.Io) ?ConnId { + return self.claimInner(io, true); + } + + fn claimInner(self: *ConnSlab, io: std.Io, reserved: bool) ?ConnId { self.mutex.lockUncancelable(io); defer self.mutex.unlock(io); - if (self.free_count == 0) return null; + const floor = if (reserved) 0 else self.reserve; + if (self.free_count <= floor) return null; self.free_count -= 1; const slot = self.free_list[self.free_count]; const entry = self.hot.get(slot); std.debug.assert(entry.state == .free); self.hot.set(slot, .{ .state = .accepted, .generation = entry.generation }); + self.sockets[slot] = null; return ConnId.pack(slot, entry.generation); } @@ -147,6 +182,7 @@ pub const ConnSlab = struct { const entry = self.hot.get(s); std.debug.assert(entry.state != .free); self.hot.set(s, .{ .state = .free, .generation = entry.generation +% 1 }); + self.sockets[s] = null; std.debug.assert(self.free_count < self.free_list.len); self.free_list[self.free_count] = s; @@ -192,6 +228,33 @@ pub const ConnSlab = struct { self.hot.set(slot, .{ .state = next, .generation = entry.generation }); } + /// Records the socket a claimed slot is serving. Call once the stream is + /// known, so `shutdownAll` can reach it. + pub fn trackSocket(self: *ConnSlab, io: std.Io, id: ConnId, stream: std.Io.net.Stream) void { + self.mutex.lockUncancelable(io); + defer self.mutex.unlock(io); + self.sockets[self.checkedIndex(id)] = stream; + } + + /// Interrupts every connection the slab is serving. A reader parked on + /// its deadline returns at once, so shutdown does not wait out the idle + /// timeout. Safe to call from another task: shutdown only, and the worst + /// case is a read that was about to fail anyway. + pub fn shutdownAll(self: *ConnSlab, io: std.Io) usize { + self.mutex.lockUncancelable(io); + defer self.mutex.unlock(io); + var count: usize = 0; + for (self.sockets) |maybe_stream| { + const stream = maybe_stream orelse continue; + stream.shutdown(io, .both) catch |err| { + log.debug("failed to interrupt inbound socket: {s}", .{@errorName(err)}); + continue; + }; + count += 1; + } + return count; + } + pub fn recvBuf(self: *ConnSlab, id: ConnId) []u8 { return self.bufRegion(id, 0, self.limits.recv_buf); } @@ -270,8 +333,10 @@ test "exhausted slab returns null, recovers after release" { defer slab.deinit(testing.allocator); const io = testing.io; + // An ordinary claim stops at the reserve, not at zero. + const ordinary = slab.free_list.len - slab.reserve; var ids: [4]ConnId = undefined; - for (&ids) |*id| id.* = slab.claim(io).?; + for (ids[0..ordinary]) |*id| id.* = slab.claim(io).?; try testing.expectEqual(@as(?ConnId, null), slab.claim(io)); slab.release(io, ids[2]); @@ -280,10 +345,32 @@ test "exhausted slab returns null, recovers after release" { // Same slot, new generation: the old handle is dead. try testing.expect(ids[2] != again); - for (ids, 0..) |id, i| if (i != 2) slab.release(io, id); + for (ids[0..ordinary], 0..) |id, i| if (i != 2) slab.release(io, id); slab.release(io, again); } +test "the reserve is reachable only through claimReserved" { + var slab: ConnSlab = try .init(testing.allocator, testLimits()); + defer slab.deinit(testing.allocator); + const io = testing.io; + + try testing.expect(slab.reserve > 0); + // The promise: `claim` yields exactly `max_connections` slots, and the + // reserve is extra. + const ordinary = slab.free_list.len - slab.reserve; + try testing.expectEqual(testLimits().max_connections, ordinary); + + var ids: [8]ConnId = undefined; + for (ids[0..ordinary]) |*id| id.* = slab.claim(io).?; + // The slab looks full to an ordinary connection... + try testing.expectEqual(@as(?ConnId, null), slab.claim(io)); + // ...and a health probe still gets read. + const probe = slab.claimReserved(io).?; + slab.release(io, probe); + + for (ids[0..ordinary]) |id| slab.release(io, id); +} + test "buffer regions are disjoint per connection and per region" { var slab: ConnSlab = try .init(testing.allocator, testLimits()); defer slab.deinit(testing.allocator); diff --git a/src/core/limits.zig b/src/core/limits.zig index e106637d..faec535f 100644 --- a/src/core/limits.zig +++ b/src/core/limits.zig @@ -44,6 +44,23 @@ pub const CONN_ARENA_RESERVE_BYTES: usize = 16 * 1024; pub const DEFAULT_MAX_CONNECTIONS: usize = 256; +/// What a shed connection is told to wait, in seconds. The status alone is +/// only half the signal: a retryable status makes a sender try again at once, +/// and a sender that honours `Retry-After` needs the number to space it out. +pub const SHED_RETRY_AFTER_SECONDS: u32 = 1; + +/// Connection slots held back for the control paths. A health probe that +/// arrives while the slab is full is shed with 503 otherwise, and an +/// orchestrator reads that as a dead process and restarts the container +/// during the very spike that filled it. Two is enough for a probe and a +/// scrape at the same time. +pub const CONTROL_RESERVE_SLOTS: usize = 2; + +/// Forwardable request headers per request. The frontend's own parser must +/// admit more than this, or it drops the excess before this cap can refuse +/// the request, and the sender is told 202 for headers that never left. +pub const MAX_FORWARD_HEADERS: usize = 64; + /// Raw request body cap. Datadog agents batch up to ~5 MB uncompressed, which /// gzips to well under this; OTLP collector batches are smaller again. pub const DEFAULT_MAX_BODY_BYTES: u32 = 1536 * 1024; @@ -173,14 +190,22 @@ pub const Limits = struct { /// config-proportional state (router tables, policy snapshots) and /// libzstd contexts, which are bounded separately and logged by their /// owners. + /// Slots the frontend actually allocates: the operator's connection cap + /// plus the control reserve. The reserve sits on top of `max_connections` + /// rather than inside it, so a deployment that sizes the cap to its sender + /// count is not shedding two of them. + pub fn connectionSlots(self: Limits) usize { + return self.max_connections + CONTROL_RESERVE_SLOTS; + } + pub fn steadyStateBytes(self: Limits) usize { - return self.max_connections * (self.perConnBytes() + self.conn_arena_reserve); + return self.connectionSlots() * (self.perConnBytes() + self.conn_arena_reserve); } pub fn logStartup(self: Limits) void { log.info("steady-state data-plane budget: {d} bytes ({d} conns x {d} per-conn)", .{ self.steadyStateBytes(), - self.max_connections, + self.connectionSlots(), self.perConnBytes() + self.conn_arena_reserve, }); } @@ -192,14 +217,18 @@ test "Limits budget formula is locked" { // Hand-computed with the default 1 MiB max_body_size: // zstd window = clamp(1M, 256K, 8M) = 1024 KiB // per conn = 20K+20K (socket bufs) + 8K (body staging) = 48 KiB - // steady state = 256 x (48K + 16K arena) = 16 MiB reserved + // slots = 256 cap + 2 control reserve = 258 + // steady state = 258 x (48K + 16K arena) = 16.1 MiB reserved // Codec, record and upstream scratch are per thread, not per connection // (frontend/thread_bufs.zig), so they are outside this budget. // Any change to a buffer constant must show up as a diff in this test. try std.testing.expectEqual(@as(usize, 256), limits.max_connections); try std.testing.expectEqual(@as(usize, 1024 * 1024), limits.zstd_window_len); try std.testing.expectEqual(@as(usize, 48 * 1024), limits.perConnBytes()); - try std.testing.expectEqual(@as(usize, 256 * 64 * 1024), limits.steadyStateBytes()); + // The reserve is capacity on top of the cap, so a deployment sized to its + // sender count does not shed the last two senders. It costs two slots. + try std.testing.expectEqual(@as(usize, 258), limits.connectionSlots()); + try std.testing.expectEqual(@as(usize, 258 * 64 * 1024), limits.steadyStateBytes()); try std.testing.expectEqual(@as(u32, 1024 * 1024), limits.max_body_size); // max_decoded_bytes is decoupled from max_body_size: agents compress, so a // 1 MiB raw body routinely decodes to several MiB. diff --git a/src/frontend/exchange.zig b/src/frontend/exchange.zig index 61942846..105de2b3 100644 --- a/src/frontend/exchange.zig +++ b/src/frontend/exchange.zig @@ -9,6 +9,7 @@ const service_mod = @import("../service/service.zig"); const upstream_mod = @import("upstream.zig"); const pipeline_mod = @import("../pipeline/pipeline.zig"); const thread_bufs = @import("thread_bufs.zig"); +const limits_mod = @import("../core/limits.zig"); const ThreadBufs = thread_bufs.ThreadBufs; @@ -66,7 +67,7 @@ pub const BodySource = union(enum) { /// Upper bound on forwarded request headers; excess is an error, not a /// truncation. -const max_forward_headers = 64; +const max_forward_headers = limits_mod.MAX_FORWARD_HEADERS; /// Forwardable request headers into an arena-owned array. `iter` is any /// iterator whose `next()` yields `.{ .key, .value }`. @@ -87,10 +88,18 @@ pub fn collectForwardHeaders(arena: std.mem.Allocator, iter: anytype) ![]std.htt /// frontend answers with this when nothing has reached the wire yet. pub fn errorStatus(err: anyerror) u16 { return switch (err) { - error.DecodedBodyTooLarge, error.BodyTooLarge => 413, + // The raw cap is actionable: the sender can split the batch. A + // decoded-size overrun fails open in paths.zig instead, because the + // sender cannot see our decode budget and the agent discards a 413 + // permanently. + error.BodyTooLarge, error.DecodedBodyTooLarge => 413, error.InboundBodyTimeout => 408, error.InvalidRequestBody => 400, + // Our cap, and the sender can act on it. A 5xx would send an agent + // into a retry loop against a request that can never succeed. + error.TooManyHeaders => 431, error.UpstreamTimeout => 504, + error.UpstreamResponseTruncated => 502, error.OutOfMemory, error.WriteFailed => 503, else => 502, }; @@ -129,6 +138,9 @@ fn dialUpstream( return exec.openUpstreamWithClient(ctx, in.arena, in.method, in.target, in.headers, choice, client) catch |err| { // ziglint-ignore: Z010 (named type sets EventBus telemetry name) ctx.bus.info(UpstreamRetried{ .path = in.path, .err = @errorName(err) }); + // Counted like any other retry: a dial storm is invisible otherwise, + // since only this log line records it. + if (ctx.metrics) |metrics| metrics.recordUpstreamAttempt(true); return exec.openUpstreamWithClient(ctx, in.arena, in.method, in.target, in.headers, choice, client); }; } @@ -223,10 +235,19 @@ fn relayResponse( bufs: *ThreadBufs, ) !void { var extra_headers: [64]std.http.Header = undefined; + // Read before the body reader exists: creating it invalidates the head. + const declared = upstream_res.head.content_length; const relayed = try exec.collectUpstreamResponseHeaders(upstream_res, arena, &extra_headers); const out = try sink.begin(@intFromEnum(upstream_res.head.status), relayed); const upstream_body = upstream_res.reader(bufs.upstream); - _ = try pipeline_mod.streamReaderToWriter(upstream_body, out, max_response_body); + const copied = try pipeline_mod.streamReaderToWriter(upstream_body, out, max_response_body); + // An intake that declares more than it sends has not accepted the batch. + // The status is already on the wire, so the only honest signal is to fail + // here: the frontend then closes without finishing the body, and the + // sender retries instead of recording a success. + if (declared) |want| { + if (copied < want) return error.UpstreamResponseTruncated; + } try sink.end(); } diff --git a/src/frontend/exec.zig b/src/frontend/exec.zig index a1a6feec..b10030cf 100644 --- a/src/frontend/exec.zig +++ b/src/frontend/exec.zig @@ -55,6 +55,10 @@ pub const TapState = tap_mod.TapState; /// Shared, read-only state for every connection, regardless of frontend. /// Frontend-specific state (the stdio conn slab and arena pool) lives in the /// frontend's own server struct, NOT here — see PLAN-FRONTEND-SWAP.md §2. +/// Policies in the snapshot that the matcher refused to compile. Named type, +/// so the event carries the name `policies.rejected`. +const PoliciesRejected = struct { count: usize }; + pub const SharedCtx = struct { io: std.Io, gpa: std.mem.Allocator, @@ -71,6 +75,9 @@ pub const SharedCtx = struct { /// Extension dispatch sink (s3-dump), or null when extensions are off. /// Threaded into per-record policy evaluation on the Datadog log path. extension_sink: ?policy.ExtensionSink = null, + /// Last reported count of policies the matcher refused, so the warning + /// fires on a change rather than on every scrape. + rejected_policies: std.atomic.Value(u32) = .init(0), }; /// Routes and plans a request from transport-neutral parts. Returns null @@ -103,8 +110,12 @@ pub fn classifyKnownPath(path: []const u8, method: service_mod.HttpMethod) runti if (method == .POST and std.mem.endsWith(u8, path, "/v1/traces")) return .v1_traces; if (method == .GET and (std.mem.eql(u8, path, "/metrics") or std.mem.startsWith(u8, path, "/metrics/"))) return .metrics; - if (method == .GET and std.mem.eql(u8, path, "/_health")) return .health; - if (method == .GET and std.mem.eql(u8, path, "/_edge/metrics")) return .edge_metrics; + // The control paths are labelled by path, not by method. A HEAD probe is + // a health check, and a rejected POST to an observability endpoint is not + // customer data: labelling either as `other` puts control traffic in the + // data-path series and hides it from the ones that matter. + if (std.mem.eql(u8, path, "/_health")) return .health; + if (std.mem.startsWith(u8, path, "/_edge/")) return .edge_metrics; return .other; } @@ -224,6 +235,45 @@ pub fn refreshPolicyGauge(ctx: *SharedCtx) void { metrics.setPoliciesLoaded(.log, if (snapshot) |s| @intCast(s.getLogTargetIndices().len) else 0); metrics.setPoliciesLoaded(.metric, if (snapshot) |s| @intCast(s.getMetricTargetIndices().len) else 0); metrics.setPoliciesLoaded(.trace, if (snapshot) |s| @intCast(s.trace_target_indices.len) else 0); + + // A policy whose pattern the engine refused is in the snapshot and does + // nothing. Without this it reads as a live rule: the loader counts it as + // loaded, and the debug endpoint lists it as enabled. + const rejected = rejectedPolicyCount(ctx); + metrics.setPoliciesRejected(rejected); + const previous = ctx.rejected_policies.swap(@intCast(rejected), .monotonic); + if (rejected > 0 and previous != @as(u32, @intCast(rejected))) { + // ziglint-ignore: Z010 (named type sets EventBus telemetry name) + ctx.bus.warn(PoliciesRejected{ .count = rejected }); + } +} + +/// Policies the matcher could not compile. `collectStats` copies into the +/// arena, so this pays one small allocation per scrape and frees it here. +pub fn rejectedPolicyCount(ctx: *SharedCtx) usize { + var arena = std.heap.ArenaAllocator.init(ctx.gpa); + defer arena.deinit(); + const stats = ctx.registry.collectStats(arena.allocator()) catch return 0; + var count: usize = 0; + for (stats) |entry| { + if (entry.errors.len > 0) count += 1; + } + return count; +} + +/// Names the policies the matcher refused, with the reason, at the top of the +/// dump. A rule that cannot compile is in the snapshot and evaluates nothing, +/// so listing it as enabled without this is misleading. +fn writeRejectedPolicies(registry: *policy.Registry, w: *std.Io.Writer) !void { + var arena = std.heap.ArenaAllocator.init(std.heap.page_allocator); + defer arena.deinit(); + const stats = registry.collectStats(arena.allocator()) catch return; + for (stats) |entry| { + if (entry.errors.len == 0) continue; + for (entry.errors) |message| { + try w.print("# REJECTED id={s}: {s}\n", .{ entry.id, message }); + } + } } /// Dump the loaded policies in the active snapshot, for the `/_edge/policies` @@ -245,6 +295,7 @@ pub fn writePolicies(registry: *policy.Registry, w: *std.Io.Writer, json: bool) try w.writeAll("# no policy snapshot loaded (0 policies)\n"); return; }; + try writeRejectedPolicies(registry, w); try w.print("# snapshot version={d} policies={d} (log={d} metric={d} trace={d})\n", .{ s.version, s.policies.len, diff --git a/src/frontend/httpz/server.zig b/src/frontend/httpz/server.zig index 59910e7f..2a28db4b 100644 --- a/src/frontend/httpz/server.zig +++ b/src/frontend/httpz/server.zig @@ -151,6 +151,12 @@ pub fn configFromLimits(limits: limits_mod.Limits, address: [4]u8, port: u16) ht .max_body_size = limits.max_body_size, .buffer_size = limits.recv_buf, .lazy_read_size = limits.large_body_buffer_size, + // Above our own forward cap on purpose. httpz's default of 32 + // drops the excess in silence, so a request with more headers + // than that was forwarded incomplete and answered 202. With room + // to spare, our cap refuses the request instead. Past this count + // httpz truncates again, which needs a fix in httpz itself. + .max_header_count = limits_mod.MAX_FORWARD_HEADERS + 32, }, .workers = .{ .count = worker_count, @@ -158,6 +164,11 @@ pub fn configFromLimits(limits: limits_mod.Limits, address: [4]u8, port: u16) ht .large_buffer_count = limits.large_body_buffer_count, .large_buffer_size = limits.large_body_buffer_size, }, + // Same reasoning as the request header cap: httpz's default of 16 + // dropped the excess in silence, so an intake answer with more + // headers than that was relayed incomplete and still reported 202. + // A `Retry-After` on a 429 is exactly the header that vanished. + .response = .{ .max_header_count = limits_mod.MAX_FORWARD_HEADERS + 32 }, .thread_pool = .{ .count = limits.thread_pool_count }, .timeout = .{ .request = limits_mod.REQUEST_TIMEOUT_SECONDS, @@ -303,6 +314,12 @@ pub const Handler = struct { const path = req.url.path; var sink: Sink = .{ .res = res }; + // Claim the whole namespace whatever the method; see the stdio note. + if (std.mem.startsWith(u8, path, "/_edge/") and req.method != .GET) { + res.status = 405; + res.body = ""; + return; + } if (req.method == .GET and std.mem.eql(u8, path, "/_edge/metrics")) { return endpoints.metrics(ctx, &sink, &httpz.writeMetrics); } @@ -323,6 +340,11 @@ pub const Handler = struct { const n: u32 = if ((try req.query()).get("n")) |raw| std.fmt.parseInt(u32, raw, 10) catch 50 else 50; return endpoints.recordTap(ctx, &sink, stage, n); } + if (std.mem.startsWith(u8, path, "/_edge/")) { + res.status = 404; + res.body = ""; + return; + } const outcome = exec.planRequest( ctx, diff --git a/src/frontend/paths.zig b/src/frontend/paths.zig index 21f246ef..bf1ef3e0 100644 --- a/src/frontend/paths.zig +++ b/src/frontend/paths.zig @@ -20,6 +20,12 @@ const log = std.log.scoped(.httpz_server); const BodySource = exchange.BodySource; const Inbound = exchange.Inbound; +// Named event payloads: the type name is the telemetry event name. +/// A policy stage could not read the batch, so the batch went upstream +/// untouched. The edge must never be the reason data disappears: only the +/// intake can accept or reject a payload. +const PolicyFailedOpen = struct { path: []const u8, stage: []const u8, err: []const u8 }; + pub const InboundBody = union(enum) { /// Fully buffered by the frontend. Zero-copy slice. bytes: []const u8, @@ -77,6 +83,26 @@ pub fn execForwardRaw( return forwardInbound(ctx, in, sink, fwd.upstream, body, fwd.replayable); } +/// Forward the untouched batch after a policy stage failed to read it, and +/// say so. Counted as a module error, because the policy module failed even +/// though the request succeeds. +fn failOpen( + ctx: *exec.SharedCtx, + in: Inbound, + sink: anytype, + pipe: service_mod.PipeStream, + raw_body: []const u8, + stage: []const u8, + err: anyerror, +) !void { + // ziglint-ignore: Z010 (named type sets EventBus telemetry name) + ctx.bus.warn(PolicyFailedOpen{ .path = in.path, .stage = stage, .err = @errorName(err) }); + if (ctx.metrics) |metrics| { + metrics.recordRequestError(exec.classifyKnownPath(in.path, .POST), .module); + } + return exchange.exchange(ctx, in, sink, pipe.upstream, .{ .bytes = raw_body }, pipe.signal == .log); +} + pub fn execPipeStream( ctx: *exec.SharedCtx, in: Inbound, @@ -121,7 +147,10 @@ pub fn execPipeStream( break :blk probe_stats.dropped > 0 or probe_stats.replaced > 0; } else |err| switch (err) { error.BatchChanged => true, - error.ReadFailed => return error.InvalidRequestBody, + // A body we cannot read is still the customer's data. Forward it and + // let the intake judge it, exactly as execPipeBuffered does. + // A decode budget the sender cannot see must not destroy the batch. + error.ReadFailed, error.DecodedBodyTooLarge => return failOpen(ctx, in, sink, pipe, raw_body, "probe", err), else => return err, }; @@ -144,7 +173,7 @@ pub fn execPipeStream( encode_spec.encode = pipe.codec; const encoded = pipeline_mod.run(encode_spec, &body_reader, &output.writer, buffers, &record_sink); const stats = encoded catch |err| switch (err) { - error.ReadFailed => return error.InvalidRequestBody, + error.ReadFailed, error.DecodedBodyTooLarge => return failOpen(ctx, in, sink, pipe, raw_body, "encode", err), else => return err, }; if (ctx.metrics) |metrics| { @@ -163,8 +192,21 @@ pub fn execPipeBuffered( const raw_body = try residentBody(ctx, body); const processed: exec.BufferedResult = exec.processBuffered(ctx, pipe, in.arena, raw_body) catch |err| blk: { - if (err == error.BodyTooLarge or err == error.DecodedBodyTooLarge) return err; - log.warn("buffered transform failed open: {s}", .{@errorName(err)}); + // `BodyTooLarge` is the raw cap: the sender framed a batch we will not + // carry, and it can split it. `DecodedBodyTooLarge` is our decode + // budget, which the sender cannot see, so refusing it destroys data + // the intake would have taken — the agent discards a 413 for good. + // Fail open on that one and let the intake judge the payload. + if (err == error.BodyTooLarge) return err; + // ziglint-ignore: Z010 (named type sets EventBus telemetry name) + ctx.bus.warn(PolicyFailedOpen{ + .path = in.path, + .stage = "buffered", + .err = @errorName(err), + }); + if (ctx.metrics) |metrics| { + metrics.recordRequestError(exec.classifyKnownPath(in.path, .POST), .module); + } break :blk .{ .body = raw_body, .all_dropped = false }; }; diff --git a/src/frontend/stdio/conn.zig b/src/frontend/stdio/conn.zig index db2b5289..26f2ad04 100644 --- a/src/frontend/stdio/conn.zig +++ b/src/frontend/stdio/conn.zig @@ -42,7 +42,7 @@ const RequestFailed = struct { method: []const u8, path: []const u8, err: []cons const RequestCompleted = struct { method: []const u8, path: []const u8, status: u16, duration_ms: f64 }; /// Same shape at warn level, for a request that held its connection task. const RequestSlow = struct { method: []const u8, path: []const u8, status: u16, duration_ms: f64 }; -/// A connection refused before it carried a request, with the 503 sent. +/// A connection refused before it carried a request, with the status sent. const ConnectionShed = struct { reason: []const u8, answered: u16 }; /// An inbound read hit its deadline. `idle` is a keep-alive wait with no /// request in flight; `request` means a partial request stalled, which drops @@ -83,10 +83,29 @@ pub const Sink = struct { /// consumed before `begin`, so its slab region is reused here. buffer: []u8, body: ?std.http.BodyWriter = null, + /// Sink for a bodiless status, which is answered before the relay runs. + discard: std.Io.Writer.Discarding = .init(&.{}), status: u16 = 0, + /// 204 and 304 carry no body, and 1xx is interim. Streaming them frames + /// a chunked body onto a status that must not have one, which some + /// clients reject outright. + fn isBodiless(status: u16) bool { + return status == 204 or status == 304 or (status >= 100 and status < 200); + } + pub fn begin(self: *Sink, status: u16, headers: []const std.http.Header) !*std.Io.Writer { self.status = status; + if (isBodiless(status)) { + try self.request.respond("", .{ + .status = @enumFromInt(status), + .extra_headers = headers, + }); + // Nothing to write, and `end` has nothing to finish. The relay + // still writes into this, so hand it a discard. + self.discard = .init(&.{}); + return &self.discard.writer; + } self.body = try self.request.respondStreaming(self.buffer, .{ .respond_options = .{ .status = @enumFromInt(status), .extra_headers = headers }, }); @@ -114,13 +133,21 @@ pub fn serveConnection( // `inbound` is filled once the slab slot provides its receive buffer. var env: Env = undefined; - const conn_id = slab.claim(io) orelse { - // Load shed: no slab slot. One fixed write, then close. + // A full slab still keeps a couple of slots back, so a health probe can + // be read and answered during the spike that filled it. A connection + // served from the reserve gets exactly one request, and only a control + // path: anything else is shed after the head, not before it. + var reserved = false; + const conn_id = slab.claim(io) orelse claim_reserved: { + if (slab.claimReserved(io)) |id| { + reserved = true; + break :claim_reserved id; + } + // Load shed: no slab slot at all. One fixed write, then close. if (shared.metrics) |metrics| metrics.recordConnectionShed(.slab_full); // ziglint-ignore: Z010 (named type sets EventBus telemetry name) shared.bus.warn(ConnectionShed{ .reason = "connection_slab_full", .answered = 503 }); - const shed = "HTTP/1.1 503 Service Unavailable\r\ncontent-length: 0\r\nconnection: close\r\n\r\n"; - writeRawResponse(shared, io, stream, shed, 503); + writeRawResponse(shared, io, stream, shed_response, 503); return; }; defer slab.release(io, conn_id); @@ -131,6 +158,7 @@ pub fn serveConnection( const arena_slot = arenas.claim(io); defer arenas.release(io, arena_slot); + slab.trackSocket(io, conn_id, stream); var inbound: deadline_reader_mod.DeadlineReader = .init(io, stream, slab.recvBuf(conn_id)); env = .{ .shared = shared, .slab = slab, .arenas = arenas, .inbound = &inbound }; var net_writer = std.Io.net.Stream.Writer.init(stream, io, slab.sendBuf(conn_id)); @@ -155,6 +183,21 @@ pub fn serveConnection( return; }, }; + if (reserved and !isControlPath(pathOf(request.head.target))) { + // The reserve exists for the control paths. Everything else is + // shed here, one step later than usual, with the same status. + if (shared.metrics) |metrics| metrics.recordConnectionShed(.slab_full); + // ziglint-ignore: Z010 (named type sets EventBus telemetry name) + shared.bus.warn(ConnectionShed{ .reason = "connection_slab_full", .answered = 503 }); + request.respond("", .{ + .status = .service_unavailable, + .keep_alive = false, + .extra_headers = &.{.{ .name = "retry-after", .value = retry_after_value }}, + }) catch |err| { + undeliverable(shared, 503, err); + }; + return; + } handleRequest(&env, conn_id, arena_slot, &request) catch |err| { // handleRequest already reported and answered what it could; this // only decides the connection's fate. @@ -163,6 +206,8 @@ pub fn serveConnection( }; inbound.endRequest(); arenas.reset(arena_slot); + // A reserved slot serves one request, so the next probe finds it free. + if (reserved) return; } } @@ -183,7 +228,7 @@ fn handleRequest( // Head strings die when the body reader is created; the target must // outlive that for the upstream leg, logs and metrics. - const target = try arena.dupe(u8, request.head.target); + const target = try arena.dupe(u8, originForm(request.head.target)); const path = pathOf(target); const method = service_mod.HttpMethod.fromStd(request.head.method); const known_path = exec.classifyKnownPath(path, method); @@ -269,6 +314,13 @@ fn dispatch( const path = pathOf(target); const method = service_mod.HttpMethod.fromStd(request.head.method); + // Claim the whole namespace whatever the method. Matching only GET let + // `POST /_edge/metrics` fall through to the wildcard passthrough and + // travel to the intake, the same way `POST /_health` did. + if (std.mem.startsWith(u8, path, "/_edge/") and request.head.method != .GET) { + sink.status = 405; + return request.respond("", .{ .status = .method_not_allowed }); + } if (request.head.method == .GET and std.mem.eql(u8, path, "/_edge/metrics")) { // std.http.Server keeps no counters of its own. return endpoints.metrics(ctx, sink, null); @@ -289,6 +341,10 @@ fn dispatch( const n: u32 = if (queryParam(target, "n")) |raw| std.fmt.parseInt(u32, raw, 10) catch 50 else 50; return endpoints.recordTap(ctx, sink, stage, n); } + if (std.mem.startsWith(u8, path, "/_edge/")) { + sink.status = 404; + return request.respond("", .{ .status = .not_found }); + } const outcome = exec.planRequest( ctx, @@ -330,8 +386,46 @@ fn dispatch( } fn pathOf(target: []const u8) []const u8 { - const query_start = std.mem.findScalar(u8, target, '?'); - return if (query_start) |i| target[0..i] else target; + const relative = originForm(target); + const query_start = std.mem.findScalar(u8, relative, '?'); + return if (query_start) |i| relative[0..i] else relative; +} + +/// `Retry-After` as a header value, from the one constant that sets it. +pub const retry_after_value = std.fmt.comptimePrint("{d}", .{limits_mod.SHED_RETRY_AFTER_SECONDS}); + +/// The fixed answer to a connection we cannot serve. 503 with `Retry-After`, +/// not 429: the edge ran out of connections process-wide, which is a condition +/// of this proxy and not an allowance we granted one sender. The OTLP spec +/// admits either status and scopes `Retry-After` to both, and collectors in +/// gateway mode already read 429 as a non-retryable tenant limit, so 429 here +/// would invite exactly that reading. The header is the part a sender acts on. +pub const shed_response = + "HTTP/1.1 503 Service Unavailable\r\n" ++ + "content-length: 0\r\nconnection: close\r\n" ++ + "retry-after: " ++ retry_after_value ++ "\r\n\r\n"; + +/// The paths the edge answers itself. They never reach an upstream, so they +/// are the ones worth keeping a connection slot for. +fn isControlPath(path: []const u8) bool { + return std.mem.eql(u8, path, "/_health") or std.mem.startsWith(u8, path, "/_edge/"); +} + +/// The origin-form of a request target. +/// +/// A sender configured with a proxy sends the absolute-form +/// (`GET http://host/path HTTP/1.1`), which RFC 9112 §3.2.2 requires a server +/// to accept. Treating the whole URL as a path routed it to the wildcard +/// passthrough and shipped a mangled target upstream, so `/_health` behind a +/// proxy setting became intake traffic. +fn originForm(target: []const u8) []const u8 { + for ([_][]const u8{ "http://", "https://" }) |scheme| { + if (!std.ascii.startsWithIgnoreCase(target, scheme)) continue; + const after_scheme = target[scheme.len..]; + const slash = std.mem.findScalar(u8, after_scheme, '/') orelse return "/"; + return after_scheme[slash..]; + } + return target; } /// Value of `name` in the target's query string, undecoded. @@ -368,6 +462,23 @@ fn inboundBodyOf( if (len == 0) return .{ .bytes = "" }; if (len > limits.max_body_size) return error.BodyTooLarge; const reader = try request.readerExpectContinue(buffer); + // A streamed body is consumed by its first send and can never be + // replayed, so a transport failure mid-exchange ends the batch with a + // 502. Bodies below the streaming threshold stay resident and can be + // dialed again; httpz draws the same line at `lazy_read_size`. + // + // Above the threshold the batch is not replayable, which is deliberate. + // The Datadog agent retries a 5xx with exponential backoff, so the cost + // is a delayed batch and a duplicate risk rather than lost data. Raising + // the line to `max_body_size` would make every batch replayable, at the + // price of one `max_body_size` buffer per concurrent request: the memory + // a policy deployment already pays through `residentBody`, and a + // passthrough deployment does not. See bench/matrix a30. + if (len <= limits.large_body_buffer_size) { + var capture: std.Io.Writer.Allocating = .init(arena); + _ = try pipeline_mod.streamReaderToWriter(reader, &capture.writer, limits.max_body_size); + return .{ .bytes = capture.written() }; + } return .{ .lazy = .{ .reader = reader, .len = @intCast(len) } }; } diff --git a/src/frontend/stdio/server.zig b/src/frontend/stdio/server.zig index 826b4ae0..e565eacc 100644 --- a/src/frontend/stdio/server.zig +++ b/src/frontend/stdio/server.zig @@ -19,7 +19,7 @@ const thread_bufs = @import("../thread_bufs.zig"); const log = std.log.scoped(.http_server); // Named event payloads: the type name is the telemetry event name. -/// A connection refused before it carried a request, with the 503 sent. +/// A connection refused before it carried a request, with the status sent. const ConnectionShed = struct { reason: []const u8, answered: u16 }; pub const HttpServer = struct { @@ -75,6 +75,11 @@ pub const HttpServer = struct { /// listen loop is NOT Io-cancelable, does more here. pub fn stopAccepting(self: *HttpServer) void { thread_bufs.expireTrackedUpstreams(self.ctx, true); + // Cancellation does not reach a connection task parked in a poll, so + // without this a SIGTERM waited out the 30 s idle deadline while the + // orchestrator counted down its kill timer. + const interrupted = self.slab.shutdownAll(self.ctx.io); + if (interrupted > 0) log.info("interrupted {d} inbound connection(s)", .{interrupted}); } /// The accept loop; itself spawned into the lifecycle group, so @@ -124,7 +129,7 @@ fn shedConnection(io: std.Io, stream: std.Io.net.Stream) void { var buf: [256]u8 = undefined; var writer = std.Io.net.Stream.Writer.init(stream, io, &buf); writer.interface.writeAll( - "HTTP/1.1 503 Service Unavailable\r\ncontent-length: 0\r\nconnection: close\r\n\r\n", + conn_mod.shed_response, ) catch return; writer.interface.flush() catch return; } diff --git a/src/runtime/runtime_metrics.zig b/src/runtime/runtime_metrics.zig index eb53cf78..af7c0e33 100644 --- a/src/runtime/runtime_metrics.zig +++ b/src/runtime/runtime_metrics.zig @@ -206,6 +206,14 @@ const InternalMetrics = struct { edge_policy_records_kept_total: PolicyRecordsKeptTotal, edge_policy_records_dropped_total: PolicyRecordsDroppedTotal, edge_policies_loaded: PoliciesLoaded, + /// Policies present in the snapshot whose pattern the matcher refused. + /// They evaluate nothing, so a non-zero value means a rule an operator + /// believes is live is doing nothing at all. + edge_policies_rejected: m.Gauge(i64) = .init( + "edge_policies_rejected", + .{ .help = "Loaded policies the matcher could not compile." }, + .{}, + ), edge_build_info: BuildInfo, // s3-dump extension flush stats (aggregate across targets; the FlushResult @@ -569,6 +577,10 @@ pub const RuntimeMetrics = struct { log.warn("failed to set policies loaded metric: {}", .{err}); } + pub fn setPoliciesRejected(self: *RuntimeMetrics, count: usize) void { + self.internal.edge_policies_rejected.set(@intCast(count)); + } + pub fn setBuildInfo(self: *RuntimeMetrics, version: []const u8, commit: []const u8) void { self.internal.edge_build_info.set(.{ .version = version, diff --git a/src/service/health.zig b/src/service/health.zig index 75a3f946..497f1a26 100644 --- a/src/service/health.zig +++ b/src/service/health.zig @@ -3,17 +3,31 @@ const std = @import("std"); const service = @import("service.zig"); +/// Every method, not only GET. The route is what claims the path, so a +/// GET-only route let `HEAD /_health` and `POST /_health` fall through to the +/// wildcard passthrough and travel to the intake. A load balancer configured +/// for HEAD then tested the intake instead of this process, and failed +/// whenever the intake was unreachable. pub const routes = [_]service.RoutePattern{ - .exact("/_health", .{ .get = true }), + .exact("/_health", .all), }; pub const Health = struct { - pub fn plan(_: *const Health, _: service.PlanRequest) service.Outcome { - return .{ .respond = .{ - .status = 200, - .content_type = "application/json", - .body = "{\"status\":\"ok\"}", - } }; + pub fn plan(_: *const Health, request: service.PlanRequest) service.Outcome { + // HEAD must work wherever GET does (RFC 9110 §9.3.2). The frontends + // elide the body for HEAD, so the same outcome serves both. + return switch (request.method) { + .GET, .HEAD => .{ .respond = .{ + .status = 200, + .content_type = "application/json", + .body = "{\"status\":\"ok\"}", + } }, + else => .{ .respond = .{ + .status = 405, + .content_type = "application/json", + .body = "{\"error\":\"method not allowed\"}", + } }, + }; } }; @@ -24,3 +38,20 @@ test "health plans a static 200 with status json" { try std.testing.expectEqualStrings("{\"status\":\"ok\"}", outcome.respond.body); try std.testing.expectEqualStrings("application/json", outcome.respond.content_type); } + +test "health answers a HEAD probe, which load balancers use" { + const svc: Health = .{}; + const outcome = svc.plan(.{ .method = .HEAD, .path = "/_health" }); + try std.testing.expectEqual(@as(u16, 200), outcome.respond.status); +} + +test "health claims the path for every method, so nothing reaches the intake" { + const svc: Health = .{}; + for ([_]service.HttpMethod{ .POST, .PUT, .DELETE, .PATCH, .OPTIONS }) |method| { + const outcome = svc.plan(.{ .method = method, .path = "/_health" }); + try std.testing.expectEqual(@as(u16, 405), outcome.respond.status); + } + // The route must admit every method, or the passthrough catches it first. + try std.testing.expect(routes[0].methods.post); + try std.testing.expect(routes[0].methods.head); +}