test(serve): speed up serve.test.ts (~34s to ~16s release) and tighten its assertions

RO
3mo ago
+140-93

Problem

  • test/js/bun/http/serve.test.ts takes 25-33s on every CI lane (33s on debian x64 ASAN in build 97275, 25s on the aarch64 release lane), so most of the time is waiting, not running.
  • Release profile before (34.4s locally): should reset timeout after writes 15.0s, allow custom timeout per request 10.0s, should allow use of custom timeout 6.5-8s. They are in one it.concurrent group, so they cost ~15s of wall clock on every lane. Each one slept for a fixed 10-15s on top of uSockets' 4s timeout sweep.
  • Next in line: the two 1000 uploads & downloads ... do not leak ReadableStream cases (2.0s + 2.2s release, 23s + 25s in this container's debug build). Each of their requests asked for a full collection twice: Bun.gc(false) and, under the BUN_GARBAGE_COLLECTOR_LEVEL=1 that the CI runner sets, the per-request expect() (every matcher schedules a collection in that mode). That was ~40% of their time; the loop also ran 1024 requests, not the 1000 it asserts on.
  • Then the request body backpressure describe (6 cases, ~0.4s each, all of it waiting for an upload to plateau), the two proxying RSS cases (1.1s + 0.7s, each a subprocess with a fixed 500ms stall) and four subprocess-only tests right after the timeout group, all running one after another.
  • Weak spots in the same tests: request body and signal life cycle ended in expect().pass(), the timeout tests had unawaited .resolves / .rejects assertions, and the leak test stopped at the first wrong digest.

Fix

  • Timeout tests: uSockets checks timeouts once every 4s and arms them in whole sweeps (idleTimeout 1..4 fires at the next sweep, 5..8 at the one after), so each test now leaves one request unanswered and waits for the server to close it instead of sleeping:
    • should allow use of custom timeout (idleTimeout: 1): the stalled streaming response must be closed (client sees ECONNRESET, server sees req.signal abort); /ok is then served right after that sweep, so it has a whole sweep interval to complete and also shows the server still works after timing a request out.
    • should reset timeout after writes (idleTimeout: 5, two sweeps, because a one-sweep timeout fires at the next sweep whether or not a write re-armed it): the stream writes every 100ms; an unanswered canary is opened only after the stream has started, so its timeout is armed no earlier than the stream's. Once the canary is closed, the stream has outlived the sweep that would have closed it without the resets. The test then stops the stream itself and checks status, that the stream request was never aborted, and that the body holds exactly the chunks that were written.
    • allow custom timeout per request (idleTimeout: 1, server.timeout(req, 60)): the canary is opened after the long request has raised its own timeout; once the canary is closed the long request must still be unaborted, and is only then released and checked for status and body.
    • In both canary tests the release is driven from the test body after the client has seen the canary fail. Releasing from the canary's server-side abort event does not work: that event fires inside the sweep, the handler's response is written before the sweep reaches the other socket, and the write re-arms it (verified: that variant passed with server.timeout() removed).
    • Each rewritten test was checked against the regression it guards by removing the behaviour under test (stream writes removed; server.timeout() call removed): both variants fail at the toBe(false) abort assertions, at the same sweep that closes the canary. Output in the details below.
    • The group now takes one or two sweeps: 4-8s depending on the sweep phase (5.9s in the release run below, 0.3s / 1.1s / 4.5s for the three tests in the debug run). The 4s sweep period is the floor for this approach; #38470 does the same for fetch.test.ts. The original per-test timeouts (15s / 20s / 20s) are kept, which also leaves room if #33610 adds a sweep to every timeout.
  • Leak test: collects every fourth completed request (so collections still happen while the rest of the batch is in flight), runs exactly count requests, and asserts { completed, wrongDigests } once at the end. The post-GC ReadableStream count assertion is unchanged. This is where the file's expect() count drops (3802 to 1759).
  • Concurrency: the four subprocess-only tests after the timeout group are it.concurrent and so join that group (they finish inside its sweep wait); request body backpressure is describe.concurrent (each case has its own server and socket, and a plateau check can only end early if the upload stops, which is the property under test); the RSS pair is it.concurrent.each (separate subprocesses, RSS is per process), with its explicit timeout raised from 10s to 15s since the two fixtures now share the CPU. The other plateau tests move 32-128MB each on the test thread, so they were left sequential: concurrently they were not faster in the debug build, only closer to the 5s local default timeout.
  • Assertions: life cycle test checks all 640 responses are 200 (bodies are still left unread, which is what the test exercises); timeout tests check status and body via one toEqual, the unanswered request's code: "ECONNRESET" (also for the stalled stream, matching what #35988 proposes for that line) and that the request under test was not aborted; leak test reports the request count and every wrong digest.
  • Verified (this container; debug builds here are several times slower than CI):
    • bun bd test test/js/bun/http/serve.test.ts: 141.3s before, 111.6s after. With the CI runner's env (BUN_GARBAGE_COLLECTOR_LEVEL=1, BUN_JSC_randomIntegrityAuditRate=1.0): 155.1s before, 121.6s after.
    • USE_SYSTEM_BUN=1 bun test test/js/bun/http/serve.test.ts (release): 34.4s before, 16.2s and 16.3s after.
    • The tests touched here plus the rest of their concurrent group, 6 runs in a loop on the debug build: green every time (timeout tests landing anywhere between 0.3s and 2.5s / 4.5s and 6.9s depending on sweep phase).
    • The failing set is identical before and after and is this container's environment: server.requestIP > v6 (no IPv6), root range port(#7187) (running as root), #6583 (localhost resolves to the other family than the server bound), only serves /bun:info to loopback clients (egress proxy). The release binary additionally fails reload() that drops the node:http handler, which needs #38755 and passes on the debug build.
  • it.concurrent(name, fn) with a title longer than prettier's line width re-indents the does not dispatch a pipelined request ... test; git diff -w shows the real changes (124 insertions, 77 deletions).
  • Of the 54 open PRs that touch this file, 52 still apply on top of this branch exactly as they do on main (checked by applying each PR's serve.test.ts patch to both versions). The two that do not, #33610 and #35988, both edit the assertions of the old should allow use of custom timeout test that this PR rewrites; the code-based assertion here already covers what #35988 changes that line to.

Background

  • Bun.serve's idleTimeout and server.timeout(req, s) are uSockets socket timeouts. uSockets only walks its sockets every LIBUS_TIMEOUT_GRANULARITY (4) seconds and us_socket_timeout(s, seconds) stores now_tick + ceil(seconds / 4), so a 1s timeout fires at the next sweep (0-4s later, exactly 4s when this test's sockets are the ones that start the sweep timer) and a 5s one at the second sweep. Every write to the response re-arms the socket with the same value, which is what should reset timeout after writes tests and why it needs a two-sweep value. When a timeout fires uSockets force-closes the socket; a pending request sees req.signal abort and Bun's fetch() rejects with code: "ECONNRESET" (the ConnectionClosed mapping in FetchTasklet.rs), whether or not the head had been sent.
  • A request opened after another one has its timeout armed at the same tick or later, so "request B was closed by its timeout" implies "a sweep ran that would also have closed request A unless A's timeout had been reset or raised". That is the only ordering the rewritten tests rely on; they do not depend on the length of a tick.
  • Bun's fetch() retries an idempotent request once if a pooled keep-alive connection closes under it, but never on a fresh connection (allow_retry is only set when a pooled socket is reused, HTTPContext.rs). Each server here is new and its first connection is still busy when the canary is sent, so the canary always uses a fresh connection and its close is reported, not retried.
  • it.concurrent tests run together with the it.concurrent / describe.concurrent tests declared directly before and after them; a plain it in between is a barrier, and so is the end of a describe block (checked with a small probe file: tests declared after a describe block closes start a new batch, .each does not). That is why the four subprocess tests, which follow the timeout group at top level, join it, while the backpressure describe and the RSS pair each form their own batch. The CI runner passes --timeout=90000 (x3 on ASAN), and an explicit per-test timeout overrides that, which is why the only explicit timeout on a newly concurrent test was raised rather than added anywhere else.
Simulated regressions, debug build

Stream writes removed from should reset timeout after writes, and server.timeout(req, 60) removed from allow custom timeout per request (the real tests were run in the same file for comparison):

error: expect(received).toBe(expected)
Expected: false
Received: true
(fail) MUTATION per-request (must fail) [4134.84ms]
(pass) allow custom timeout per request [4224.84ms]
(pass) should allow use of custom timeout [4401.60ms]
error: expect(received).toBe(expected)
Expected: false
Received: true
(fail) MUTATION reset (must fail) [8103.94ms]
(pass) should reset timeout after writes [8189.55ms]

The earlier variant that released the long request from the canary's server-side abort event passed without server.timeout(), which is why the release now comes from the test body after the client has observed the canary's failure.

Release profile after (16.3s total)
5873ms  should reset timeout after writes            (group wall clock; the other two landed at ~1.9s in the same run)
1937ms  1000 uploads ... > direct
1835ms  1000 uploads ... > default
1108ms  bounds memory ... chunked                    (runs together with content-length, 728ms)
1063ms  request body backpressure > Bun.write        (the describe's 6 cases run together)
 349ms  type: direct stream awaiting flush(true) ...
 340ms  resumes a backpressured Response(ReadableStream) ...
 338ms  applies backpressure to a Response(ReadableStream) body ...

What is left is the 4-8s sweep floor of the timeout group, ~3.8s of the two leak cases (768KB uploaded and hashed per request; their payload size is what makes the request body arrive in more than one chunk, so it was left alone), and ~4s spread across the remaining ~280 tests.