Skip to content

adaptive: after the epoll→io_uring promote, a fresh connection's request is read off its socket and never answered (h2c closed at the 10 s header deadline, WS handshake timeout; 7 events, mechanism not attributed) #715

Description

@FumingPower3925

Summary

On the adaptive engine, after its epoll→io_uring promote, a fresh connection's request is sometimes read off the socket by the engine and never answered:

  • an h2c-churn GET / preamble gets no response, and the server closes the connection at the 10 s header deadline (hang-eof, read 10,001 ms);
  • a WS-torture upgrade request gets no 101 within the walker's 2 s (handshake-fail-timeout).

Seven events so far, all adaptive, all 20-73 s after the promote. In the five that an in-stall socket snapshot caught, the server socket had received every byte of the request and had nothing left in its receive queue, and had sent no data (no bytes_sent, no data segment out; its one segment out is at most the ACK of the request). Nothing in the process was blocked. The mechanism is not attributed.

This is the bug record for the event class that #588 exists to capture. #588 stays the measurement issue; its comments hold the per-run detail.

The events

# where engine / event write instant after the switch server socket in the in-stall ss
1 laptop container, no-fault leg of probatorium#412 run c7c3de4 adaptive, WS handshake-fail-timeout 2026-09-26 12:54:56.43Z +22.4 s not captured (before the in-stall dossier existed)
2 container, run 3a62131 adaptive, WS handshake-fail-timeout 17:09:43.13Z +24.1 s ESTAB, Recv-Q 0, bytes_received 156 = client bytes_sent 156, segs_out 1, at +1.0 s
3 container, run 3a62131 adaptive, WS handshake-fail-timeout 17:10:19.73Z +60.7 s ESTAB, Recv-Q 0, 156 = 156, segs_out 1, at +1.0 s
4 container, run ba0a3e0 adaptive, h2c hang-eof, read 10,001 ms 2026-09-27 05:04:14.27Z +20.3 s ESTAB, Recv-Q 0, bytes_received 126 = client bytes_sent 126, segs_out 1, at +3.0 s
5 container, run ba0a3e0 adaptive, WS handshake-fail-timeout 05:04:33.92Z +39.9 s ESTAB, Recv-Q 0, 156 = 156, segs_out 1, at +1.0 s
6 container, run ba0a3e0 adaptive, h2c hang-eof, read 10,001 ms 05:05:07.07Z +73.1 s ESTAB, Recv-Q 0, 126 = 126, segs_out 1, at +3.0 s
7 cluster, checkptr tier 36283577085 (msr1, cell-07) adaptive/arm64, h2c hang-eof, read 10,004 ms 2026-09-27 01:55:36.60Z +48.6 s not captured (the tier ran main 6f5521c, without probatorium#412)
  • Events 1-6 come from the no-fault legs of the lane-M container runs (auth_session_ratelimit, linux/arm64, nothing injected; the switch time is the refapp's engine switch completed line, 1 s resolution). Event 7 is detailed in Measure: capture enough at the next h2c_hang / ws_handshake_fail to root-cause it from the artifact, and try to force recurrence #588's 2026-09-27 04:27Z comment.
  • Events 1-6 are each on the first promote of their cell: adaptive_switches is 0 before it and 1 through the event (HANDOFF-*.txt).
  • Denominators over the five no-fault legs: adaptive 49,247 h2c and 14,927 WS attempts gave 2 and 4 failures. The plain io_uring, epoll and std cells of the same legs, about 13,500 h2c and 3,000 WS attempts each, gave 0. At adaptive's WS rate the io_uring cell expects about 0.8 WS events, so "adaptive only" is not established.

What the capture shows

The in-stall dossier (probatorium#412) is taken while the read still waits: at +3 s for h2c, at +1 s for WS. It takes ss -ltn / ss -tanpi first, then a goroutine dump from a debug side listener outside the engine.

  • The request reached the process. The server socket is ESTAB and owned by the refapp. Its bytes_received equals the client's bytes_sent: 126 for the h2c preamble, 156 for the WS upgrade. Its Recv-Q is 0. It shows no bytes_sent and no data_segs_out, and segs_out:1: it sent no data, only (at most) the ACK of the request, and the client's bytes_acked is bytes_sent + 1 (the request and the SYN were acknowledged). lastrcv is 1.0 or 3.0 s, i.e. the request arrived when it was written.
  • Every listener's accept queue is 0 (ss -ltn Recv-Q, every listener in every in-stall snapshot).
  • Nothing is blocked. In every in-stall side-listener dump (events 2-6):
    • the two io_uring worker threads are runnable, inside the engine or in inline middleware;
    • the two epoll standby loops are parked in select;
    • no goroutine is in sync.(*Mutex).Lock;
    • 13-22 idle runAsyncHandler goroutines wait in sync.Cond.Wait (the refapp runs async handlers).
    • In the three ba0a3e0 dossiers the dump was fetched 45-50 ms after the trigger. The 3a62131 dossiers predate the fetch stamp.
  • The hand-off was quiet (HANDOFF-ba0a3e0.txt, HANDOFF-3a62131.txt, 1 Hz series from 5 s before the switch to the last event):
  • The h2c close is the header deadline. The refapp sets no ReadHeaderTimeout, so celeris's 10 s default applies. The read ended at 10,001 ms with an orderly EOF.

What that excludes and what is left

Excluded by the snapshot, for events 2-6:

  • (b) an unarmed recv: the bytes would still be in the Recv-Q.
  • A connection never accepted: it would be ESTAB with no owning process, and an accept queue would be non-zero.
  • A handler or loop stall on a lock: the dump shows nothing blocked.

Also ruled out:

Left, and not separable from this artifact:

What would decide it

A per-connection record in the engine, keyed by descriptor and peer port and joined to the walker's local_addr, would separate (a) from (c): bytes received by a recv CQE, bytes handed to the parser or handler, and whether an async handler goroutine was started for the connection. #588's checkptr comment proposes the same kind of bounded per-read exemplar. The in-stall capture already takes a dump inside the stall. It cannot join a goroutine to a descriptor.

Evidence

evidence/measurements-585-587-588/lane-20260926/round3/588/:

  • NATURAL-EVENTS.txt, from natural-events-588.py over the five no-fault legs: rows 1-6, the denominators (DENOMINATORS), and the check that all five in-read captures show the same socket state (SIGNATURE, 5/5).
  • natural/NATURAL-EVENT.txt, from natural/natural-event-588.py over the ba0a3e0 cell: events 4-6 with both socket rows, the dump and the listeners, and the same check with the client's bytes_acked and the dump's lock-wait frames added (3/3).
  • HANDOFF-{c7c3de4,3a62131,ba0a3e0}.txt, from handoff-window-588.py: the series window (with the instant each counter goes flat) and the dump states.
  • Row 7 is from Measure: capture enough at the next h2c_hang / ws_handshake_fail to root-cause it from the artifact, and try to force recurrence #588's checkptr comment. The dossiers are under lane-20260926/588/20260926T*/nofault/ and lane-20260926/round2/588/20260927T044910Z-ba0a3e0/nofault/.

Refs #588, #685, #713, goceleris/probatorium#412.


Edited 2026-09-27 (lane M, probatorium#412 review round 3): the server's one outgoing segment is described as at most the ACK of the request (the client's bytes_acked = bytes_sent + 1), not as the SYN-ACK; the hand-off counters are flat from 05:04:05, not 05:04:10; the evidence list names the SIGNATURE checks the scripts now print. No conclusion changed.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/engineEngine interface or implementationbugSomething isn't workingengine/iouringio_uring engine specifics

    Type

    No type

    Projects

    No projects

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions