diff --git a/repro_issue_185.sh b/repro_issue_185.sh new file mode 100755 index 00000000..2fddbd7b --- /dev/null +++ b/repro_issue_185.sh @@ -0,0 +1,179 @@ +#!/usr/bin/env bash +# +# repro_issue_185.sh — Reproduce the TCP-reset bug behind issue #185 / PR #389. +# +# Symptom: `hey`/clients see "connection reset by peer" (and pooled keepalive +# clients log `Unsolicited response received on idle HTTP channel starting with +# "HTTP/1.1 ..."`) when SLEdge answers a request *before* it has finished reading +# the request body. +# +# Why a plain bodyless GET does NOT reproduce it: +# 429/500/503 are emitted from on_client_request_received(), which only runs +# after the FULL request (body included) has been read. So those are clean. +# +# The reproducible path is 404. In on_client_request_receiving() +# (runtime/src/listener_thread.c, ~line 200) the route is matched the moment the +# URL is parsed from the *request line* — before the body arrives: +# +# if (session->route == NULL && strlen(session->http_request.full_url) > 0) { +# route = http_router_match_route(...); +# if (route == NULL) { ...404...; on_client_response_header_sending(); return; } +# } +# +# So: POST a sizeable body to a NON-existent route. SLEdge writes the 404 and +# close()es the socket while the client is still sending. On Linux, close() with +# unread data in the kernel receive buffer discards it and emits a RST instead of +# a graceful FIN -> "connection reset by peer". +# +# Expected result: +# * On master / fix/docker-dev-setup (unpatched): a nonzero number of +# "connection reset by peer" errors -> BUG REPRODUCED. +# * On fix/issue-185-graceful-close (patched tcp_session_close): 0 resets. +# +# Usage: +# ./repro_issue_185.sh +# +# Tunables (env vars): +# PORT=10000 tenant listen port +# REQUESTS=2400 total requests (hey -n) +# CONCURRENCY=32 concurrent connections (hey -c) +# BODY_BYTES=100000 request body size (~100 KB); larger = more resets +# +set -euo pipefail + +PORT="${PORT:-10000}" +REQUESTS="${REQUESTS:-2400}" +CONCURRENCY="${CONCURRENCY:-32}" +BODY_BYTES="${BODY_BYTES:-100000}" + +# --- locate the repo (this script lives at the repo root) --------------------- +REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd -P)" +BIN_DIR="$REPO_ROOT/runtime/bin" +SLEDGERT="$BIN_DIR/sledgert" +WASM="$BIN_DIR/empty.wasm.so" + +red() { printf '\033[1;31m%s\033[0m\n' "$*"; } +green() { printf '\033[0;32m%s\033[0m\n' "$*"; } +info() { printf '\033[0;36m==> %s\033[0m\n' "$*"; } + +# --- prerequisites ------------------------------------------------------------ +if ! command -v hey >/dev/null 2>&1; then + red "ERROR: 'hey' is not installed. Install it with:" + echo " go install github.com/rakyll/hey@latest (then add \$(go env GOPATH)/bin to PATH)" + echo " or: apt-get install -y hey" + exit 1 +fi + +if [[ ! -x "$SLEDGERT" ]]; then + red "ERROR: $SLEDGERT not found. Build the runtime first, e.g.:" + echo " make runtime # builds runtime/bin/sledgert" + echo " make install # full build incl. wasm apps" + exit 1 +fi + +if [[ ! -f "$WASM" ]]; then + red "ERROR: $WASM not found. Build the sample apps first, e.g.:" + echo " make install # builds the wasm apps incl. empty.wasm.so" + exit 1 +fi + +# Warn (don't block) if running on a branch that already contains the fix. +if grep -q 'shutdown(client_socket' "$REPO_ROOT/runtime/include/tcp_session.h" 2>/dev/null; then + info "NOTE: tcp_session.h contains the graceful-close fix — you are on a PATCHED" + info " checkout, so you should see 0 resets (the fix working). To see the BUG," + info " check out an unpatched branch (e.g. master) and 'make runtime' first." +fi + +# --- write a minimal tenant spec ---------------------------------------------- +SPEC="$(mktemp /tmp/issue185-spec.XXXXXX.json)" +cat > "$SPEC" < "$BODY" + +# --- launch sledgert ---------------------------------------------------------- +LOG="$(mktemp /tmp/issue185-sledge.XXXXXX.log)" +SLEDGE_PID="" + +cleanup() { + [[ -n "$SLEDGE_PID" ]] && kill "$SLEDGE_PID" 2>/dev/null || true + rm -f "$SPEC" "$BODY" "$LOG" +} +trap cleanup EXIT + +info "Starting sledgert on port $PORT (route /empty -> empty.wasm.so)" +# sledgert resolves the relative "empty.wasm.so" path against its CWD, and needs +# runtime/bin on LD_LIBRARY_PATH for libsledge/libck. 'exec' makes sledgert +# replace the subshell so $! is sledgert's own PID (so cleanup kills it). +( cd "$BIN_DIR" && exec env LD_LIBRARY_PATH="$BIN_DIR:${LD_LIBRARY_PATH:-}" "$SLEDGERT" "$SPEC" ) >"$LOG" 2>&1 & +SLEDGE_PID=$! + +# --- wait for the tenant port to accept connections --------------------------- +info "Waiting for port $PORT to come up..." +for _ in $(seq 1 50); do + if ! kill -0 "$SLEDGE_PID" 2>/dev/null; then + red "sledgert exited during startup. Log:" + cat "$LOG" + exit 1 + fi + if (exec 3<>"/dev/tcp/127.0.0.1/$PORT") 2>/dev/null; then + exec 3>&- 3<&- 2>/dev/null || true + break + fi + sleep 0.2 +done + +# Sanity checks: valid route -> 200, missing route (bodyless) -> 404 (clean). +ok="$(curl -s -o /dev/null -w '%{http_code}' -X POST --data hi "http://127.0.0.1:$PORT/empty" || true)" +nf="$(curl -s -o /dev/null -w '%{http_code}' "http://127.0.0.1:$PORT/nope" || true)" +info "Sanity: POST /empty -> $ok , GET /nope (bodyless) -> $nf" +if [[ "$ok" != "200" ]]; then + red "sledgert is not serving the valid route as expected. Log:" + cat "$LOG" + exit 1 +fi + +# --- the load that triggers the bug ------------------------------------------- +info "Firing $REQUESTS POSTs ($BODY_BYTES-byte body, concurrency $CONCURRENCY) at /nope (non-existent route)" +HEY_OUT="$(mktemp /tmp/issue185-hey.XXXXXX)" +hey -n "$REQUESTS" -c "$CONCURRENCY" -m POST -D "$BODY" "http://127.0.0.1:$PORT/nope" > "$HEY_OUT" 2>&1 || true + +echo +echo "----- hey status code distribution -----" +sed -n '/Status code distribution/,/^$/p' "$HEY_OUT" || true + +# Each reset is a distinct connection (unique source port), so count lines. +RESETS="$(grep -c 'connection reset by peer' "$HEY_OUT" || true)" +EPIPES="$(grep -c 'broken pipe' "$HEY_OUT" || true)" +rm -f "$HEY_OUT" + +echo +echo "============================================================" +echo " 'connection reset by peer' errors : $RESETS" +echo " 'broken pipe' (EPIPE) errors : $EPIPES (known large-body limitation)" +echo "============================================================" +if [[ "${RESETS:-0}" -gt 0 ]]; then + red "BUG REPRODUCED: SLEdge sent RSTs on early 404 responses (issue #185)." + echo "On fix/issue-185-graceful-close this count drops to 0." +else + green "No resets observed. If you are on the patched branch, this is the FIX working." + echo "If you expected the bug: confirm you 'make runtime' on an unpatched branch," + echo "and try a larger BODY_BYTES (e.g. BODY_BYTES=1000000) or higher CONCURRENCY." +fi diff --git a/runtime/include/tcp_session.h b/runtime/include/tcp_session.h index 995d8775..68390272 100644 --- a/runtime/include/tcp_session.h +++ b/runtime/include/tcp_session.h @@ -6,12 +6,21 @@ #include #include #include +#include #include #include "debuglog.h" #include "likely.h" #include "panic.h" +/* + * Bound on the non-blocking drain performed during a graceful close. 32 passes of an 8 KiB buffer + * (256 KiB) is far larger than any already-buffered request remainder we expect to see, while still + * guaranteeing the single listener thread cannot be held by a misbehaving client. See tcp_session_close(). + */ +#define TCP_SESSION_CLOSE_DRAIN_MAX_PASSES 32 +#define TCP_SESSION_CLOSE_DRAIN_BUFFER_LENGTH 8192 + static inline void tcp_session_close(int client_socket, struct sockaddr *client_address) { @@ -20,6 +29,39 @@ tcp_session_close(int client_socket, struct sockaddr *client_address) assert(client_socket != STDOUT_FILENO); assert(client_socket != STDERR_FILENO); + /* + * Graceful close to avoid sending the client a TCP RST (issue #185). + * + * SLEdge often answers a request before it has finished reading it: the short-circuit error + * responses (400/404/429/500/503) are written and the socket closed while the client may still be + * sending its request body. A bare close() with unread data still in the kernel receive buffer makes + * Linux discard that data and emit a RST instead of a graceful FIN. The client's HTTP stack then + * reports it as "connection reset by peer" or, on a pooled keepalive connection, as the Go net/http + * warning "Unsolicited response received on idle HTTP channel" that issue #185 describes. + * + * We instead (1) half-close the write side so the client receives our FIN (and, having a complete + * response, stops sending), then (2) drain any already-buffered inbound data so close() no longer + * sees unread data. The drain is non-blocking and bounded, so the listener thread can never block or + * spin on a slow client. This removes the RST for every request the client has finished sending + * (all bodyless GETs and small POSTs - i.e. the reported scenario). A client that keeps streaming a + * large body to a rejected route may still observe its own write abort as EPIPE; fully suppressing + * that would require lingering on the request in the event loop, which is out of scope here. + */ + shutdown(client_socket, SHUT_WR); + + thread_local static char drain[TCP_SESSION_CLOSE_DRAIN_BUFFER_LENGTH]; + for (int pass = 0; pass < TCP_SESSION_CLOSE_DRAIN_MAX_PASSES; pass++) { + ssize_t drained = read(client_socket, drain, sizeof(drain)); + if (drained == 0) break; /* EOF: client closed its side, nothing left to drain */ + if (drained < 0) { + if (errno == EINTR) continue; + /* EAGAIN/EWOULDBLOCK: receive buffer is empty, so close() will not RST. Any other + * error means the connection is already broken. Either way, stop draining. */ + break; + } + /* Drained a full buffer; more may be queued, so loop again (bounded). */ + } + if (unlikely(close(client_socket) < 0)) { char client_address_text[INET6_ADDRSTRLEN] = {'\0'}; if (unlikely(inet_ntop(AF_INET, &client_address, client_address_text, INET6_ADDRSTRLEN) == NULL)) {