diff --git a/config.go b/config.go index 7e1f5b7be..5a0e27a9e 100644 --- a/config.go +++ b/config.go @@ -240,8 +240,14 @@ type Config struct { // // On the native engines (epoll, io_uring, adaptive) it is measured from the // connection's last read (on io_uring also from the start and the completion - // of its sends, on epoll also from the end of a response the kernel did not - // take at once). + // of its sends). On epoll a response the kernel did not take whole is + // bounded by WriteTimeout's minimum rate alone, from the first sweep that + // finds it parked until it ends (see WriteTimeout): ReadTimeout and + // IdleTimeout run again from its end, and, where the socket reports no + // acknowledged bytes, from the last flush that took bytes. A request + // pipelined behind such a response is bounded by ReadHeaderTimeout for its + // headers and by ReadTimeout only once the response has been sent; the + // overrun check of an HTTP/1.1 async handler is suspended the same way. // // An HTTP/2 connection is not closed by it or by IdleTimeout while it has a // stream open whose request is whole and no response is waiting for the @@ -315,38 +321,68 @@ type Config struct { // a large download or a chunked body written with [Context.StreamWriter] // without Detach, stays under WriteTimeout as an absolute deadline for the // whole response: raise it or set -1 for such routes. On the epoll engine - // (and adaptive while it runs on epoll) WriteTimeout bounds a response - // that is not detached differently: it is "no progress for WriteTimeout", - // the time a client may go without taking any of a response the kernel has - // not accepted whole, restarted each time it takes some. A download read - // steadily for longer than WriteTimeout is not cut there, and a client - // that reads nothing is closed WriteTimeout after the response stalled. - // Progress is seen when the engine flushes, which follows the socket - // becoming writable again, about when half of its send queue has drained, - // or the client sending something (a pipelined request, an HTTP/2 PING or - // WINDOW_UPDATE), whose read flushes what the room it made allows. - // A client that takes less than half a send queue per WriteTimeout and - // sends nothing (a deep send queue and a slow reader) is closed while it - // is still reading; one that takes - // about half a send queue per WriteTimeout is never closed, and holds the - // connection and the whole response queued for it in memory for as long as - // it keeps doing so (std and io_uring end such a response at WriteTimeout, - // as a whole). Nothing else bounds that on epoll: while a response is - // queued, ReadTimeout and IdleTimeout run from the last progress too, so - // they slide with it, and the earlier of ReadTimeout and WriteTimeout - // is the time a client may take no bytes at all (ReadTimeout 5s with - // WriteTimeout 60s closes a client that pauses for 6s). io_uring bounds the - // response as a whole, measured from the last read or completed flush - // of the connection (a client that sends another request restarts it), not - // from the request's headers as std does. On io_uring a response whose + // (and adaptive while it runs on epoll) WriteTimeout bounds a response that + // is not detached differently: it is a minimum rate on the bytes the client + // acknowledges, with no elapsed-time ceiling. A response the kernel did not + // accept whole is queued in the engine ("parked"); the engine's sweep reads + // how many bytes the client has acknowledged (tcp_info) and holds the + // connection another WriteTimeout if the client acknowledged at least 64 KiB + // in the last one (a floor of 64 KiB per WriteTimeout: 64 KiB/s at 1s, + // about 1 KiB/s at the 60s default), and closes it if it did not. A client + // that reads at or above the floor is never cut, however long the response + // takes, and one that reads steadily between two EPOLLOUT edges is not + // mistaken for a stalled one: a download completes whatever IdleTimeout is. + // A client that takes less, in whatever pieces (nothing, a byte at a time, + // a half send queue per WriteTimeout), is closed at the end of the first + // window, between WriteTimeout and WriteTimeout plus two sweeps after the + // response parked (the first sweep takes the baseline, the window ends at + // the first sweep a WriteTimeout later); one that stops after a window it + // passed, within two WriteTimeouts plus two sweeps after its last byte. A + // client that takes exactly 64 KiB per window holds the connection, and the + // part of the response not yet sent, for as many windows as the response has + // 64 KiB (a response of S bytes: S/64 KiB times WriteTimeout, 64 minutes + // for 4 MiB at 60s; a smaller WriteTimeout raises the floor), so size + // WriteTimeout with that in mind. WriteTimeout -1 is no write timeout at + // any rate. What the client sends is not progress: a pipelined request or + // an HTTP/2 PING does not hold a parked response. The times above hold + // with ReadHeaderTimeout set (the default): the engine's 25 ms sweep timer + // is armed only then, and without it a stalled response can outlast them by + // seconds (measured: WriteTimeout 1s, ReadHeaderTimeout -1, closed at 5 s, + // on main too). + // + // While the rule has a baseline for a parked response (from the first sweep + // that finds it parked), it is the only bound on the connection: + // ReadTimeout and IdleTimeout do not apply, so a client at or above the + // floor is not cut by either whatever they are next to WriteTimeout (the + // defaults are 60s, 600s and 60s), and one that stops is closed by the rule + // within the times above. They apply again from the end of the response. A + // socket that does not report acknowledged bytes (not TCP, or a TCP stack + // that leaves bytes_acked at 0) has the flush clock alone, "no flush took + // bytes for WriteTimeout", and ReadTimeout and IdleTimeout run from the + // last flush that took bytes there, as before the rule. The rule covers an + // HTTP/2 response parked on the socket too. A response that waits for the + // client's HTTP/2 flow-control window is not parked (nothing is queued on + // the socket) and WriteTimeout does not bound it on epoll: ReadTimeout and + // IdleTimeout do, from the client's last frame, so a client that sends a + // frame of any kind (a PING) at least once per ReadTimeout holds it, until + // per-stream deadlines are added. A request error read while a + // response is queued (a malformed request) puts the connection on the + // closing drain below, which counts each byte the client acknowledges and + // has no floor: a client that sends one and then takes a few bytes per + // WriteTimeout holds the connection, a known limit that is not changed here. + // io_uring is unchanged: it has no rate, and measures WriteTimeout from + // the last read, the start of a send from an idle connection or a + // completed send (a client that completes one send per WriteTimeout, or + // sends another request, restarts it), not from the request's headers as + // std does. On io_uring a response whose // unsent remainder is under 64 KiB, to a client that stops reading, on an // otherwise idle worker, can outlast WriteTimeout (measured with async // responses of 96 to 144 KiB; the larger and the sync sizes are closed). // On epoll, a response parked behind a handler that holds the connection's // dispatch lock for longer than WriteTimeout can be closed at WriteTimeout // even though nothing is queued for it (a narrow pipelined-handler case). - // A response that ends the connection (Connection: close, a refused write) - // has a drain of its own on both native engines: the connection is cut + // A response that ends the connection (Connection: close, a request error, + // a refused write) has a drain of its own on both native engines: the connection is cut // once the client has taken no byte for WriteTimeout (epoll) or // max(5s, WriteTimeout) (io_uring), and for 5 s on either when WriteTimeout // is -1. A byte taken is a flush or send completion that moved the @@ -371,7 +407,8 @@ type Config struct { WriteTimeout time.Duration // IdleTimeout is the max duration a keep-alive connection may be idle. // Zero uses the default (600s). Set to -1 for no timeout. On an HTTP/2 - // connection with a stream the server owes an answer for, see ReadTimeout. + // connection with a stream the server owes an answer for, see ReadTimeout; + // on epoll, for a response parked on the socket, see WriteTimeout. IdleTimeout time.Duration // ShutdownTimeout is the deadline of the graceful shutdown that cancelling // the context of StartWithContext or StartWithListenerAndContext starts diff --git a/internal/engine/epoll/conn.go b/internal/engine/epoll/conn.go index efcd6e140..3762602d8 100644 --- a/internal/engine/epoll/conn.go +++ b/internal/engine/epoll/conn.go @@ -270,6 +270,14 @@ type connState struct { // the 4-byte hole before closeSince: see TestConnStateStaysInItsSizeClass.) gen uint32 + // closeAcked, closeAckedKnown and closeSampled have a third user, a live + // conn's parked response (parkedBelowRate, write_rate_885.go, celeris#885 + // item 51): the baseline of the rate rule's window, sampled by the + // sweep while writeSince is set and closeSince is 0, forgotten where the + // response's clock ends (endWriteSlow, the sweep's empty-queue case) and by + // markClosing, which hands them to the drain below. A conn is in one of the + // three states at a time. + // // closeSince, closePending and closeAcked are the clock of that deferred // close (celeris#876): closeSince is when the engine last saw the close // move forward, in nanoseconds, from the request that deferred it diff --git a/internal/engine/epoll/loop.go b/internal/engine/epoll/loop.go index 5901e814a..4e39b6c8b 100644 --- a/internal/engine/epoll/loop.go +++ b/internal/engine/epoll/loop.go @@ -370,6 +370,12 @@ type Loop struct { // asking the kernel about a descriptor number that may now belong to // something else. Written once before ready; read only after it. listenAddr net.Addr + + // ackedProbe replaces the getsockopt that reads a conn's acknowledged + // byte count when set (bytesAcked, write_rate_885.go): a test seam for a + // TCP stack whose TCP_INFO answers but does not fill it. nil in + // production. Loop thread (a test sets it before it drives the loop). + ackedProbe func(fd int) (uint64, error) } func newLoop(id, cpuID int, handler stream.Handler, @@ -2279,6 +2285,7 @@ func (l *Loop) markClosing(cs *connState, pending int) { } cs.closeSince = time.Now().UnixNano() cs.closePending = pending + cs.closeAckedKnown = false // a live conn's window baseline (parkedBelowRate) is not the drain's } // noteClosingProgress restarts the drain clock of a conn markClosing deferred @@ -2373,6 +2380,14 @@ func (cs *connState) endWrite() { // inlines at its call sites (the drain paths of every response). func (cs *connState) endWriteSlow() { cs.writeSince = 0 + cs.closeAckedKnown = false // the baseline of the response's window (parkedBelowRate) + if cs.closeSince == 0 { + // A live conn's last sample is of the response that ended: the next + // one parks with no baseline and takes it at its first sweep, not + // after a quarter of WriteTimeout (closing and detached conns keep + // theirs, which they own). + cs.closeSampled = 0 + } cs.lastActivity = time.Now().UnixNano() } @@ -4911,7 +4926,10 @@ func (cs *connState) endDetachedStall() { // write clock (writeSince), or is on the dirty list. WriteTimeout is "no // progress for WriteTimeout" there: the clock starts at the first partial flush // and restarts when a flush takes bytes (noteWriteProgress), where std's is an -// absolute deadline for the whole response. It answers the instant IdleTimeout +// absolute deadline for the whole response; where the peer's acknowledged bytes +// can be read the minimum-rate rule decides instead (parkedBelowRate, celeris#885 +// item 51), and is then the only bound: the conn is exempt from the idle scan +// for as long as the rule has a baseline. It answers the instant IdleTimeout // and ReadTimeout are measured from, the later of the last read and the clock, // and whether the conn is done for this sweep (closed, or exempt from the idle // scan). Kept out of line: the sweep of a conn without a clock does not run it. @@ -4940,14 +4958,56 @@ func (l *Loop) sweepWriteClock(cs *connState, fd int, now, last int64) (from int pending = csWritePending(cs) } if pending { - if wt := l.cfg.WriteTimeout; wt > 0 && time.Duration(now-ws) > wt { - l.closeConn(fd) - return last, true + if wt := l.cfg.WriteTimeout; wt > 0 { + // The minimum-rate rule (celeris#885 item 51) reaps a conn whose + // peer's acknowledged bytes it can see; the flush clock the rest. + if l.parkedBelowRate(cs, now, ws, int64(wt)) { + l.closeConn(fd) + return last, true + } + if cs.closeAckedKnown { + // The rule has a baseline for this response and is its only + // bound (celeris#885 item 51): a peer taking at least the floor + // per window is not stalled, whatever the idle clocks say. They + // run from the last flush that took bytes or the last window + // passed, and a client reading steadily between two EPOLLOUT + // edges moves neither (a ReadTimeout or IdleTimeout not above + // WriteTimeout, the defaults' shape, would cut it before the + // rule decides). The price: a request pipelined behind the + // response is bounded by ReadHeaderTimeout for its head (the + // hdrDL check above runs first and the loop keeps EPOLLIN armed + // while parked), but a pipelined request whose head is whole and + // whose body is pending has no header deadline, and ReadTimeout + // does not bound it until the response ends (measured: ReadTimeout + // 1 s cut it at 1.34 s on main, the head held it for the run; + // after the drain ReadTimeout applies again, gone at 6.94 s on + // both). The skip also bypasses h2ServerOwes' dispatchBusy answer + // for an async HTTP/1.1 conn (read, not measured): a pipelined + // handler that overruns ReadTimeout is not closed while an earlier + // response on the conn is rate-held. Bounded by the rule: the + // client must keep acknowledging the floor. A peer that stops is + // closed by the rule one window after it falls under the floor. + // Back to the idle scan when the response ends (endWrite) or the + // baseline is lost (a failed sample). + return last, true + } + if time.Duration(now-cs.writeSince) > wt { + l.closeConn(fd) + return last, true + } } } else { // End the clock as endWrite does, from its last stamp, which is no - // later than the drain. + // later than the drain. A response the rule governed has no recent + // stamp (it moves once per window): the drain is dated by this + // sweep, so that ReadTimeout or IdleTimeout, shorter than the + // window, do not cut the conn on the instant its response ended. + if cs.closeAckedKnown { + ws = now + } cs.writeSince = 0 + cs.closeAckedKnown = false + cs.closeSampled = 0 // the next response's baseline is not delayed by this one's sample if ws > last { cs.lastActivity = ws } diff --git a/internal/engine/epoll/write_clock_885_linux_test.go b/internal/engine/epoll/write_clock_885_linux_test.go index 5d2fa5927..41fd9e748 100644 --- a/internal/engine/epoll/write_clock_885_linux_test.go +++ b/internal/engine/epoll/write_clock_885_linux_test.go @@ -76,10 +76,16 @@ func TestWriteClockRestartsWhenTheFlushTakesBytes885(t *testing.T) { "the clock must restart when a flush takes bytes", time.Since(start).Round(time.Millisecond), bound) } } - time.Sleep(bound + 100*time.Millisecond) - r.l.checkTimeouts() + // The peer took bytes in the window that is running (the rate rule holds a + // conn another window when the last passed, celeris#885 item 51), and none + // after: it goes when that window has passed, within two WriteTimeouts. + deadline := time.Now().Add(2*bound + 200*time.Millisecond) + for r.open() && time.Now().Before(deadline) { + time.Sleep(25 * time.Millisecond) + r.l.checkTimeouts() + } if r.open() { - t.Fatalf("a peer that stopped reading was not reaped %v after its last byte", bound+100*time.Millisecond) + t.Fatalf("a peer that stopped reading was not reaped %v after its last byte", 2*bound+200*time.Millisecond) } } diff --git a/internal/engine/epoll/write_rate_885.go b/internal/engine/epoll/write_rate_885.go new file mode 100644 index 000000000..9d896eeb3 --- /dev/null +++ b/internal/engine/epoll/write_rate_885.go @@ -0,0 +1,115 @@ +//go:build linux + +package epoll + +import ( + "golang.org/x/sys/unix" +) + +// parkedMinAcked is the least number of bytes the peer must acknowledge in one +// WriteTimeout window, for a response a keep-alive conn has parked on the +// socket, for the conn to be held another window (celeris#885 item 51). With +// WriteTimeout T the floor is parkedMinAcked/T: 64 KiB/s at 1 s, about 1 KiB/s +// at the 60 s default. The constant, and the window being WriteTimeout, are the +// rule; see parkedBelowRate. +const parkedMinAcked = 64 << 10 + +// parkedBelowRate is the sweep's minimum-rate rule for a live conn that holds a +// response the kernel has not taken whole (celeris#885 item 51); it reports +// whether the conn is to be closed. It replaces "no flush took bytes for +// WriteTimeout", which sees the peer only at an EPOLLOUT edge (about half a send +// queue drained) or a read of the peer, as the measure of a slow reader: +// +// - a client that reads steadily but takes less than half a send queue per +// WriteTimeout is closed while it reads (no edge, no flush); +// - one that takes about half a queue per WriteTimeout, an edge every time, +// is never closed, and a client that sends bytes while it reads is held +// longer still (a pipelined request, an HTTP/2 PING). +// +// The measure here is the bytes the peer has acknowledged (tcp_info +// bytes_acked, which only grows, read by one getsockopt), and nothing the peer +// sends moves it. Windows of WriteTimeout: the first sweep that finds the +// response parked takes the baseline and opens a window (closeAcked, +// closeSampled; closeAckedKnown says there is one), and when the window has +// passed the conn is held another if the peer acknowledged at least +// parkedMinAcked in it (the baseline moves to that sample and so does the write +// clock, writeSince) and closed if it did not. The sample is one getsockopt per +// conn per window. +// +// So a peer that takes nothing (a zero window, a byte per second: the +// kernel acknowledges a window update, not a byte) is closed between +// WriteTimeout and WriteTimeout plus two sweeps after the response parked (the +// first sweep takes the baseline, the window ends at the first sweep a +// WriteTimeout later), and one that stops after a window it passed within two +// WriteTimeouts plus two sweeps. A peer that +// takes exactly parkedMinAcked per window holds the conn and what is queued for +// it for (response / parkedMinAcked) windows: there is no elapsed-time ceiling, +// and a client that takes the response at a reasonable rate is never cut. +// +// While the baseline is known the flush clock does not reap: its stamp moves at +// flushes the peer's reading did not cause as well (a request read, a flush of a +// byte), and the rule here is the one that counts bytes taken. Nor do +// ReadTimeout and IdleTimeout (sweepWriteClock exempts the conn from the idle +// scan while the baseline is known): they run from the last flush that took +// bytes or the last window passed, which a peer reading steadily between two +// EPOLLOUT edges moves at neither, and with them not above WriteTimeout (the +// defaults' shape) they would cut it before the rule had decided. A conn whose +// socket does not report acknowledged bytes (not TCP, a failed getsockopt, a +// count of 0 as a stack that does not fill bytes_acked answers, review r3 F4; +// retried at most every quarter of WriteTimeout) has the flush clock alone, as +// before, and ReadTimeout and IdleTimeout from it. +// ws is the flush clock, writeSince. Loop thread; the caller's conn is parked +// (pending) and WriteTimeout wt > 0. +func (l *Loop) parkedBelowRate(cs *connState, now, ws, wt int64) bool { + if !cs.closeAckedKnown { + if now-cs.closeSampled < wt/4 { + return false // a failed sample, not tried again yet + } + cs.closeSampled = now + acked, err := l.bytesAcked(cs.fd) + if err != nil || acked == 0 { + // No count, or a count of 0: a parked conn has had bytes sent, so + // a stack that reports bytes_acked reads more than 0 once the peer + // has taken any; 0 is a peer that has taken none yet (retried + // every quarter window, the flush clock bounds it meanwhile) or a + // stack that does not fill the field (gVisor; Linux before 4.1), + // where a baseline of 0 would read every peer as acknowledging + // nothing and turn the rule into a hard cutoff. + return false + } + cs.closeAcked, cs.closeAckedKnown = acked, true + // A conn first met after the flush clock's bound had passed has no + // window behind it and no evidence of progress: it is judged by the + // clock, as before (a loop whose sweeps are further apart than + // WriteTimeout). + return now-ws > wt + } + if now-cs.closeSampled < wt { + return false + } + acked, err := l.bytesAcked(cs.fd) + if err != nil || acked == 0 { + cs.closeAckedKnown = false // the flush clock from here + cs.closeSampled = now + return false + } + if acked-cs.closeAcked >= parkedMinAcked { + cs.closeAcked, cs.closeSampled = acked, now + cs.writeSince = now + return false + } + return true +} + +// bytesAcked reads how many bytes the peer of fd has acknowledged (tcp_info +// bytes_acked, which only grows). +func (l *Loop) bytesAcked(fd int) (uint64, error) { + if f := l.ackedProbe; f != nil { + return f(fd) + } + ti, err := unix.GetsockoptTCPInfo(fd, unix.IPPROTO_TCP, unix.TCP_INFO) + if err != nil { + return 0, err + } + return ti.Bytes_acked, nil +} diff --git a/internal/engine/epoll/write_rate_885_linux_test.go b/internal/engine/epoll/write_rate_885_linux_test.go new file mode 100644 index 000000000..5a41b6c7d --- /dev/null +++ b/internal/engine/epoll/write_rate_885_linux_test.go @@ -0,0 +1,401 @@ +//go:build linux + +package epoll + +import ( + "bufio" + "fmt" + "io" + "net/http" + "os" + "strings" + "testing" + "time" + + "github.com/goceleris/celeris/internal/resource" +) + +// celeris#885 item 51, the minimum-rate rule (parkedBelowRate): a response a +// keep-alive conn has parked on the socket is held another WriteTimeout window +// if the peer acknowledged at least parkedMinAcked (64 KiB) in the last one, and +// closed if it did not; nothing the peer sends moves it, and there is no +// elapsed-time ceiling. WriteTimeout <= 0 is no write timeout at all. +// +// The rig tests drive the real checkTimeouts, armEpollOut and handleWritable on +// a real TCP pair (parked885: a 256 KiB send buffer, a 16 KiB receive buffer on +// the peer, 8 MiB queued); the engine tests are the reviewer's probes of the +// first design of this item (celeris PR 1116, whose IdleTimeout ceiling cut a +// download at IdleTimeout and was refreshed by any inbound byte). + +// rateFloor885 is the floor of the rule, 64 KiB per window, as the tests state +// it (parkedMinAcked in the engine: the tests do not read the constant, so that +// they build against main, where they fail). +const rateFloor885 = 64 << 10 + +// TestParkedPeerAboveTheFloorWithoutAnEdgeIsNotReaped885: the peer takes four +// times the floor (about 320 KiB/s, 256 KiB per 800 ms window; a reader that +// falls behind catches up on the next tick, ride885) for five windows, no +// EPOLLOUT edge (handleWritable is never called) and no flush: the write clock +// the flushes keep is at its first stamp. The conn must survive every sweep +// (main closed it a WriteTimeout in). Then the peer stops, and the conn goes +// within two windows of its last byte. (Margin 4x: the first cut read at twice +// the floor, which a loaded runner could stretch below it, review r3 F9.) +func TestParkedPeerAboveTheFloorWithoutAnEdgeIsNotReaped885(t *testing.T) { + const bound = 800 * time.Millisecond + const stop = 5 * bound + var run riderRun885 + for attempt := 1; attempt <= 3; attempt++ { + run = ride885(t, resource.Config{ReadTimeout: -1, IdleTimeout: -1, WriteTimeout: bound}, 4, 0, stop, stop+4*bound) + if run.closedAt == 0 || run.closedAt >= stop || !run.shortfall(int(run.closedAt/bound)) { + break + } + t.Logf("attempt %d: the peer itself took %v bytes per window, under the floor: retrying", attempt, run.windows) + } + if run.closedAt != 0 && run.closedAt < stop { + t.Fatalf("celeris#885 item 51: reaped %v in, the peer taking 4x the floor (taken per %v window: %v; floor %d KiB) and no edge", + run.closedAt.Round(time.Millisecond), bound, run.windows, rateFloor885>>10) + } + if run.closedAt == 0 { + t.Fatalf("a peer that stopped reading was not reaped %v after its last byte", 4*bound) + } + if gone := run.closedAt - stop; gone > 2*bound+250*time.Millisecond { + t.Errorf("a peer that stopped was reaped %v after its last byte, want within two windows (%v)", gone.Round(time.Millisecond), 2*bound) + } +} + +// TestParkedPeerBelowTheFloorIsReapedWhateverItsFlushes885: the peer takes 12 KiB +// every 300 ms (40 KiB/s, 24 KiB per 600 ms window, under the floor) and every +// read is followed by an EPOLLOUT edge, handleWritable, whose flush takes bytes +// and restarts the flush clock; the acknowledged bytes per window are what count, +// and the conn is gone within three windows of parking. +func TestParkedPeerBelowTheFloorIsReapedWhateverItsFlushes885(t *testing.T) { + const bound = 600 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: -1, IdleTimeout: -1, WriteTimeout: bound}) + start := time.Now() + for time.Since(start) < 6*bound { + time.Sleep(300 * time.Millisecond) + r.read(12 << 10) + r.l.handleWritable(r.cs) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(start); gone > 3*bound { + t.Errorf("reaped %v in, want within three windows (%v)", gone.Round(time.Millisecond), 3*bound) + } + return + } + } + t.Fatalf("celeris#885 item 51: the conn of a peer taking 12 KiB every 300 ms (under the floor of %d KiB per %v), flushing at every edge, "+ + "was still held %v in", rateFloor885>>10, bound, 6*bound) +} + +// TestParkedConnWithNoWriteTimeoutIsNeverReapedByTheRate885: WriteTimeout -1 is +// no write timeout, at any rate: a peer that takes nothing for 2 s, with +// ReadTimeout and IdleTimeout off, is still held. (The same on main.) +func TestParkedConnWithNoWriteTimeoutIsNeverReapedByTheRate885(t *testing.T) { + r := parked885(t, resource.Config{ReadTimeout: -1, IdleTimeout: -1, WriteTimeout: -1}) + for start := time.Now(); time.Since(start) < 2*time.Second; { + time.Sleep(50 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + t.Fatalf("the conn was reaped %v in with WriteTimeout -1, ReadTimeout and IdleTimeout off", time.Since(start).Round(time.Millisecond)) + } + } +} + +// goneAfter885 waits until the engine has counted the connection (an accepted +// connection that the engine has not counted yet reads as "gone": review r3 +// F10), then polls until the conn is gone, up to limit from there, and reports +// when (0: still open), measured from the count. +func goneAfter885(t *testing.T, e *Engine, limit time.Duration, between func()) time.Duration { + t.Helper() + for dl := time.Now().Add(5 * time.Second); e.Metrics().ActiveConnections == 0; time.Sleep(time.Millisecond) { + if time.Now().After(dl) { + t.Fatalf("apparatus: the engine never counted the connection") + } + } + t0 := time.Now() + for time.Since(t0) < limit { + time.Sleep(20 * time.Millisecond) + if between != nil { + between() + } + if e.Metrics().ActiveConnections == 0 { + return time.Since(t0) + } + } + return 0 +} + +// TestEngineDownloadAtAModerateRateCompletesUnderIdleTimeout885 is the first +// design's blocker (celeris PR 1116, probe P1): a 12 MiB keep-alive response +// read at about 2 MiB/s (64 KiB every 30 ms), ReadTimeout off, IdleTimeout 2 s, +// WriteTimeout 60 s and -1. The response takes about 6 s, three times +// IdleTimeout, and the client takes it steadily: it must arrive whole. The first +// design closed it at IdleTimeout, a download of any size at any rate. +func TestEngineDownloadAtAModerateRateCompletesUnderIdleTimeout885(t *testing.T) { + for _, wt := range []time.Duration{-1, 60 * time.Second} { + for _, async := range []bool{false, true} { + t.Run(fmt.Sprintf("wt=%v/async=%v", wt, async), func(t *testing.T) { + const body = 12 << 20 + _, addr := startE2E885(t, async, newPathHandler885(body), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = 2 * time.Second + c.WriteTimeout = wt + }) + c := dialRcvBuf885(t, addr, 64<<10) + get885(t, c, "/big") + t0 := time.Now() + _ = c.SetReadDeadline(time.Now().Add(30 * time.Second)) + resp, err := http.ReadResponse(bufio.NewReader(c), nil) + if err != nil { + t.Fatalf("response head: %v", err) + } + var got int64 + buf := make([]byte, 64<<10) + for { + n, err := resp.Body.Read(buf) + got += int64(n) + if err != nil { + break + } + time.Sleep(30 * time.Millisecond) + } + took := time.Since(t0) + t.Logf("celeris885 download wt=%v async=%v: %d of %d bytes in %v", wt, async, got, body, took.Round(10*time.Millisecond)) + if got != body { + t.Errorf("the client received %d of %d bytes %v in, reading steadily at about 2 MiB/s, with IdleTimeout 2s: "+ + "a response is not an idle connection", got, body, took.Round(10*time.Millisecond)) + } + if took < 4*time.Second { + t.Errorf("apparatus: the transfer took %v, not well over IdleTimeout", took) + } + }) + } + } +} + +// TestEngineReaderAboveTheFloorIsNotClosedBetweenEdges885: a deep send queue +// (1 MiB, so that half of it takes the client four seconds or more), a client +// with a 4 KiB receive buffer reading 128 KiB/s (4 KiB turns, a reader that +// falls behind catches up on the next one), WriteTimeout 2 s (a floor of 32 +// KiB/s: the client takes four times the 64 KiB per window), ReadTimeout and +// IdleTimeout off. No EPOLLOUT edge comes in the first window; the conn is +// held for three windows. Main closes it at the first WriteTimeout. (The first +// cut read at 1.6 times the floor of a 1 s window, which a loaded runner +// stretched under it: 10 of 10 failures with six busy loops, review r3 F9; the +// run retries when the client itself took under the floor in a window.) +func TestEngineReaderAboveTheFloorIsNotClosedBetweenEdges885(t *testing.T) { + const wt = 2 * time.Second + const runFor = 3*wt + 500*time.Millisecond + const rate = 128 << 10 + t.Logf("net.core.wmem_max=%s", sysctl885("net/core/wmem_max")) + for _, async := range []bool{false, true} { + t.Run(fmt.Sprintf("async=%v", async), func(t *testing.T) { + for attempt := 1; ; attempt++ { + e, addr := startE2E885(t, async, newPathHandler885(64<<20), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = -1 + c.WriteTimeout = wt + c.Resources.SocketSend = 1 << 20 + }) + c := dialRcvBuf885(t, addr, 4096) + get885(t, c, "/big") + var got float64 + windows := make([]int, int(runFor/wt)+1) + buf := make([]byte, 4096) + var t0 time.Time + gone := goneAfter885(t, e, runFor, func() { + if t0.IsZero() { + t0 = time.Now() + } + el := time.Since(t0) + for due := rate*el.Seconds() - got; due >= 4096; due -= 4096 { + _ = c.SetReadDeadline(time.Now().Add(5 * time.Millisecond)) + n, _ := c.Read(buf) + if n == 0 { + break + } + got += float64(n) + windows[int(el/wt)] += n + } + }) + t.Logf("celeris885 above-floor async=%v attempt %d: taken per %v window %v, gone at %v", async, attempt, wt, windows, gone) + if gone == 0 { + return + } + short := false + for i := 0; i < int(gone/wt) && i < len(windows); i++ { + short = short || float64(windows[i]) < 1.25*rateFloor885 + } + if short && attempt < 3 { + continue // the client itself fell under the floor: not the engine's doing + } + t.Errorf("the conn of a client reading steadily at 4x the floor (taken per %v window: %v, floor %d KiB) was closed %v in, "+ + "WriteTimeout %v: progress between two EPOLLOUT edges is progress", wt, windows, rateFloor885>>10, gone.Round(time.Millisecond), wt) + return + } + }) + } +} + +// sysctl885 reads a /proc/sys value for a test log. +func sysctl885(name string) string { + b, err := os.ReadFile("/proc/sys/" + name) + if err != nil { + return err.Error() + } + return strings.TrimSpace(string(b)) +} + +// TestEngineSlowlorisBelowTheFloorIsClosed885 is the issue's hold: a shallow +// send queue (16 KiB), so that every half queue the client takes is an EPOLLOUT +// edge and a flush that restarts the flush clock, and a client reading 4, 8, 12 +// and 16 KiB in turn every 250 ms (40 KiB/s) of a 16 MiB response, WriteTimeout +// 1 s, ReadTimeout and IdleTimeout off. Main holds it for ever: the issue's +// probe held it for the 10 s it watched. The rate is under the floor of 64 KiB +// per window: the conn is closed within three windows. +func TestEngineSlowlorisBelowTheFloorIsClosed885(t *testing.T) { + for _, async := range []bool{false, true} { + t.Run(fmt.Sprintf("async=%v", async), func(t *testing.T) { + e, addr := startE2E885(t, async, newPathHandler885(16<<20), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = -1 + c.WriteTimeout = time.Second + c.Resources.SocketSend = 16 << 10 + }) + c := dialRcvBuf885(t, addr, 4096) + get885(t, c, "/big") + buf := make([]byte, 16<<10) + var lastRead time.Time + turn := 0 + gone := goneAfter885(t, e, 8*time.Second, func() { + if time.Since(lastRead) >= 250*time.Millisecond { + lastRead = time.Now() + turn++ + _ = c.SetReadDeadline(time.Now().Add(100 * time.Millisecond)) + _, _ = c.Read(buf[:4096*(1+turn%4)]) + } + }) + t.Logf("celeris885 slowloris async=%v: gone at %v", async, gone) + if gone == 0 { + t.Errorf("a client taking 40 KiB/s of a response, flushing at every edge, WriteTimeout 1s, was still held 8 s in: " + + "nothing bounds a parked response whose peer takes a half queue per window") + } else if gone > 3500*time.Millisecond || gone < 850*time.Millisecond { + t.Errorf("the conn was closed %v in, want between a window (1 s) and three (3.5 s)", gone.Round(time.Millisecond)) + } + }) + } +} + +// TestEnginePeerInboundBytesDoNotRefreshTheWriteClock885 is the first design's +// M1 (probe P2d): a deep queue, WriteTimeout 1 s, IdleTimeout 3 s, ReadTimeout +// off, a client reading 4 KiB every 400 ms (10 KiB/s) of a 3 MiB response that +// also sends nothing, a bare CRLF every 2 s (the reviewer's probe), or a pipelined +// GET every 400 ms. The rate is under the floor: the conn is gone within 3 s in +// every case, a window and the sweeps after the response parked, whatever the +// client sends (the first design held the CRLF and the GET clients for 15 s; main +// holds the GET client for ever). +// +// A bare CRLF is not a request: the engine answers it as a request error and +// closes the conn once its queue has gone, so that conn is in the closing drain +// (celeris#876), whose clock restarts at every byte the client acknowledges and +// which this rule does not change (the PR body says so). The CRLF client is +// closed here because its first CRLF comes after the first window has passed; +// one sent every 400 ms would hold the conn in the closing drain. +func TestEnginePeerInboundBytesDoNotRefreshTheWriteClock885(t *testing.T) { + for _, p := range []struct { + poke string + every time.Duration + }{{"", 0}, {"\r\n", 2 * time.Second}, {"GET /small HTTP/1.1\r\nHost: x\r\n\r\n", 400 * time.Millisecond}} { + poke := p.poke + for _, async := range []bool{false, true} { + t.Run(fmt.Sprintf("poke=%q/async=%v", poke, async), func(t *testing.T) { + e, addr := startE2E885(t, async, newPathHandler885(3<<20), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = 3 * time.Second + c.WriteTimeout = time.Second + c.Resources.SocketSend = 256 << 10 + }) + c := dialRcvBuf885(t, addr, 4096) + get885(t, c, "/big") + buf := make([]byte, 4096) + var lastRead, lastPoke time.Time + gone := goneAfter885(t, e, 8*time.Second, func() { + if time.Since(lastRead) >= 400*time.Millisecond { + lastRead = time.Now() + _ = c.SetReadDeadline(time.Now().Add(100 * time.Millisecond)) + _, _ = c.Read(buf) + } + if poke != "" && time.Since(lastPoke) >= p.every { + lastPoke = time.Now() + _ = c.SetWriteDeadline(time.Now().Add(time.Second)) + _, _ = io.WriteString(c, poke) + } + }) + t.Logf("celeris885 inbound poke=%q async=%v: gone at %v", poke, async, gone) + if gone == 0 || gone > 3*time.Second || gone < 850*time.Millisecond { + t.Errorf("a client reading 10 KiB/s and sending %q was closed at %v (0: still open), want between a window (1 s) and 3 s: "+ + "the bytes it sends are not progress", poke, gone) + } + }) + } + } +} + +// TestEngineStuckPeersAreClosedWithinTwoWindows885: a client that takes nothing +// (a zero window, also with a pipelined GET sent every second) and one that reads +// a byte every 900 ms (the kernel acknowledges a window update, not a byte), with +// WriteTimeout 1 s: both gone within 3 s. +func TestEngineStuckPeersAreClosedWithinTwoWindows885(t *testing.T) { + for _, name := range []string{"zero-window", "zero-window+GET/s", "1B/900ms"} { + t.Run(name, func(t *testing.T) { + e, addr := startE2E885(t, false, newPathHandler885(16<<20), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = -1 + c.WriteTimeout = time.Second + c.Resources.SocketSend = 256 << 10 + }) + c := dialRcvBuf885(t, addr, 4096) + get885(t, c, "/big") + var lastAct time.Time + one := make([]byte, 1) + gone := goneAfter885(t, e, 6*time.Second, func() { + switch name { + case "zero-window+GET/s": + if time.Since(lastAct) >= time.Second { + lastAct = time.Now() + _ = c.SetWriteDeadline(time.Now().Add(time.Second)) + _, _ = io.WriteString(c, "GET /small HTTP/1.1\r\nHost: x\r\n\r\n") + } + case "1B/900ms": + if time.Since(lastAct) >= 900*time.Millisecond { + lastAct = time.Now() + _ = c.SetReadDeadline(time.Now().Add(50 * time.Millisecond)) + _, _ = c.Read(one) + } + } + }) + t.Logf("celeris885 stuck %s: gone at %v", name, gone) + if gone == 0 || gone > 3*time.Second || gone < 850*time.Millisecond { + t.Errorf("%s: closed at %v (0: still open), want between a window (1 s) and 3 s (two windows+)", name, gone) + } + }) + } +} + +// TestEngineNoWriteTimeoutHoldsAStuckPeer885: WriteTimeout -1, ReadTimeout and +// IdleTimeout off: a client that takes nothing for 4 s is still connected. (The +// same on main.) +func TestEngineNoWriteTimeoutHoldsAStuckPeer885(t *testing.T) { + e, addr := startE2E885(t, false, newPathHandler885(16<<20), func(c *resource.Config) { + c.ReadTimeout = -1 + c.IdleTimeout = -1 + c.WriteTimeout = -1 + c.Resources.SocketSend = 256 << 10 + }) + c := dialRcvBuf885(t, addr, 4096) + get885(t, c, "/big") + if gone := goneAfter885(t, e, 4*time.Second, nil); gone != 0 { + t.Errorf("the conn of a client that takes nothing was closed %v in with WriteTimeout -1 and ReadTimeout and IdleTimeout off", gone) + } +} diff --git a/internal/engine/epoll/write_rate_rtit_885_linux_test.go b/internal/engine/epoll/write_rate_rtit_885_linux_test.go new file mode 100644 index 000000000..bcf659c17 --- /dev/null +++ b/internal/engine/epoll/write_rate_rtit_885_linux_test.go @@ -0,0 +1,322 @@ +//go:build linux + +package epoll + +import ( + "fmt" + "testing" + "time" + + "github.com/goceleris/celeris/internal/resource" +) + +// celeris#885 item 51, review r3 finding F1: ReadTimeout and IdleTimeout of a +// parked response. The rate rule (parkedBelowRate) is what bounds a response +// the kernel has not taken whole; a client that takes it at or above the floor +// (64 KiB acknowledged per WriteTimeout window) is not to be closed by +// ReadTimeout or IdleTimeout because it sends no frame and no EPOLLOUT edge +// has restarted their clock, whatever their value is next to WriteTimeout +// (the defaults are 60 s, 600 s and 60 s). A conn with no parked response is +// reaped by them as before. +// +// The rig is parked885's (a real TCP pair, 8 MiB queued, no EPOLLOUT edge: +// handleWritable is never called). Times are scaled down; the ratios are the +// point. + +// floorRate885 is bytes/s of the floor at WriteTimeout wt, as the tests state it. +func floorRate885(wt time.Duration) float64 { + return float64(rateFloor885) / wt.Seconds() +} + +// riderRun885 is what one run of the paced reader saw. +type riderRun885 struct { + closedAt time.Duration // 0: still open at the end + windows []int // bytes the reader took in each WriteTimeout of wall clock from the start + stoppedAt time.Duration +} + +// shortfall reports whether the reader itself fell under the floor (with a +// quarter of margin for the receive buffer) in a full window it was meant to +// be reading in: the apparatus failed, not the engine. stopped windows are not +// counted. +func (r riderRun885) shortfall(upTo int) bool { + for i := 0; i < upTo && i < len(r.windows); i++ { + if float64(r.windows[i]) < 1.25*rateFloor885 { + return true + } + } + return false +} + +// ride885 parks a response on the rig with cfg and reads it from the peer at +// mult times the floor of WriteTimeout (a reader that falls behind catches up +// on the next tick, so a stalled test process does not lower the rate the +// engine sees), running the sweep every 25 ms from gap after the start (the +// gap puts the first sweep, which takes the rule's baseline, well after the +// response parked, so that the order of ReadTimeout and the first window end +// does not depend on sweep phase). With stopAfter > 0 the reader stops then. +// It returns when the conn is gone or after total. +func ride885(t *testing.T, cfg resource.Config, mult float64, gap, stopAfter, total time.Duration) riderRun885 { + t.Helper() + wt := cfg.WriteTimeout + r := parked885(t, cfg) + rate := mult * floorRate885(wt) + out := riderRun885{windows: make([]int, int(total/wt)+1)} + start := time.Now() + var took float64 + for { + time.Sleep(20 * time.Millisecond) + el := time.Since(start) + if el >= total { + return out + } + if stopAfter == 0 || el < stopAfter { + for due := rate*el.Seconds() - took; due >= 4096; { + n := r.read(min(int(due), 16<<10)) + if n == 0 { + break + } + took += float64(n) + due -= float64(n) + out.windows[int(el/wt)] += n + } + // What the kernel took is what the peer can read: the engine's own + // flush keeps it supplied. flushWrites is no EPOLLOUT edge and no + // progress for the flush clock. + _ = r.l.flushWrites(r.cs, true) + } else if out.stoppedAt == 0 { + out.stoppedAt = el + } + if el >= gap { + r.l.checkTimeouts() + } + if !r.open() { + out.closedAt = time.Since(start) + return out + } + } +} + +// TestParkedReaderAboveTheFloorIsNotCutByReadOrIdleTimeout885: a client taking +// 1.6 and 4 times the floor, no EPOLLOUT edge, with ReadTimeout or IdleTimeout +// equal to WriteTimeout (the defaults' shape: 60 s and 60 s, IdleTimeout ten +// times that), half of it, and both: the rule decides, not the idle clocks, +// which a flush that took bytes or a window passed move and an acknowledged +// byte between two edges does not. Main and the first cut of this item closed +// all of them at ReadTimeout or IdleTimeout (the reviewer's rig: 806 ms at +// RT=WT, 401 ms at RT=WT/2, 811 ms at IT=WT). +func TestParkedReaderAboveTheFloorIsNotCutByReadOrIdleTimeout885(t *testing.T) { + const wt = 600 * time.Millisecond + cells := []struct { + name string + rt, it time.Duration + }{ + {"RT=WT,IT=off", wt, -1}, + {"RT=WT/2,IT=off", wt / 2, -1}, + {"RT=off,IT=WT", -1, wt}, + {"RT=IT=WT", wt, wt}, + {"defaults-shaped RT=WT,IT=10WT", wt, 10 * wt}, + } + for _, c := range cells { + for _, mult := range []float64{1.6, 4} { + t.Run(fmt.Sprintf("%s/%.1fx", c.name, mult), func(t *testing.T) { + var run riderRun885 + for attempt := 1; attempt <= 3; attempt++ { + run = ride885(t, resource.Config{ReadTimeout: c.rt, IdleTimeout: c.it, WriteTimeout: wt}, + mult, 100*time.Millisecond, 0, 3*wt) + if run.closedAt == 0 || !run.shortfall(int(run.closedAt/wt)) { + break + } + t.Logf("attempt %d: the reader itself took %v bytes per window, under the floor: retrying", attempt, run.windows) + } + if run.closedAt != 0 { + t.Fatalf("celeris#885 item 51: reaped %v in, the reader taking %.1fx the floor (%d KiB per %v window; "+ + "taken per window: %v), no EPOLLOUT edge, ReadTimeout %v IdleTimeout %v WriteTimeout %v: "+ + "the rate rule decides a parked response, not ReadTimeout or IdleTimeout", + run.closedAt.Round(time.Millisecond), mult, rateFloor885>>10, wt, run.windows, c.rt, c.it, wt) + } + }) + } + } +} + +// TestParkedReaderThatStopsIsClosedWithinTwoWindowsWhateverReadTimeout885: a +// client at 4 times the floor for two windows that then takes nothing is closed +// by the rule within two windows of its last byte (a window it passed holds +// the conn one more), with ReadTimeout and IdleTimeout shorter than, equal to, +// and longer than WriteTimeout: the rule's bound is WriteTimeout's, not the idle clocks'. +func TestParkedReaderThatStopsIsClosedWithinTwoWindowsWhateverReadTimeout885(t *testing.T) { + const wt = 600 * time.Millisecond + for _, c := range []struct { + name string + rt, it time.Duration + }{{"RT=WT/2,IT=off", wt / 2, -1}, {"RT=IT=WT", wt, wt}, {"RT=off,IT=off", -1, -1}} { + t.Run(c.name, func(t *testing.T) { + const stop = 2 * wt + run := ride885(t, resource.Config{ReadTimeout: c.rt, IdleTimeout: c.it, WriteTimeout: wt}, 4, 100*time.Millisecond, stop, stop+4*wt) + if run.closedAt == 0 { + t.Fatalf("a reader that stopped after %v was still held %v later (ReadTimeout %v IdleTimeout %v WriteTimeout %v)", stop, 4*wt, c.rt, c.it, wt) + } + if run.closedAt < stop || run.closedAt > stop+2*wt+250*time.Millisecond { + t.Errorf("closed at %v with the reader stopped at %v (taken per window: %v), want within two windows (%v) of it, and not before", + run.closedAt.Round(time.Millisecond), stop, run.windows, 2*wt) + } + }) + } +} + +// TestParkedSecondResponseRightAfterTheFirstIsRateGoverned885: a keep-alive +// conn that parks a second large response right after the first drained, with +// ReadTimeout (150 ms) below a quarter of WriteTimeout (800 ms), and a client +// taking 4 times the floor, is held. The window baseline of the first +// response must not delay the second's: nothing was sampled for it yet, and +// ReadTimeout runs on it until the rule has a baseline. +func TestParkedSecondResponseRightAfterTheFirstIsRateGoverned885(t *testing.T) { + const wt = 800 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: time.Hour, IdleTimeout: -1, WriteTimeout: wt}) + rate := 4 * floorRate885(wt) + start := time.Now() + var took float64 + tick := func() bool { + time.Sleep(20 * time.Millisecond) + for due := rate*time.Since(start).Seconds() - took; due >= 4096; { + n := r.read(min(int(due), 16<<10)) + if n == 0 { + break + } + took += float64(n) + due -= float64(n) + } + _ = r.l.flushWrites(r.cs, true) + r.l.checkTimeouts() + return r.open() + } + // The first response: until a window has passed (the sample the second + // response's start must not inherit). + passed := false + var base int64 + for time.Since(start) < 3*wt && !passed { + if !tick() { + t.Fatalf("apparatus: the first response's conn was reaped %v in", time.Since(start).Round(time.Millisecond)) + } + if r.cs.closeAckedKnown { + if base == 0 { + base = r.cs.closeSampled + } else if r.cs.closeSampled != base { + passed = true // a window passed: the sample just moved + } + } + } + if !passed { + t.Fatalf("apparatus: no window passed in %v", 3*wt) + } + // The first response ends (the drain site's own call) and a second is + // queued and parked at once. + r.cs.writeBuf = r.cs.writeBuf[:0] + r.cs.writePos = 0 + r.cs.endWrite() + r.cs.writeBuf = append(r.cs.writeBuf, make([]byte, 8<<20)...) + _ = r.l.flushWrites(r.cs, true) + r.cs.pendingBytes = csPendingBytes(r.cs) + if !csWritePending(r.cs) { + t.Fatalf("apparatus: the second response was taken whole") + } + r.l.armEpollOut(r.cs) + r.l.cfg.ReadTimeout = 150 * time.Millisecond // the first response ran under an hour + second := time.Now() + for time.Since(second) < 3*wt { + if !tick() { + t.Fatalf("celeris#885 item 51: the second response's conn was reaped %v after it parked, the reader taking 4x the floor, "+ + "ReadTimeout 150 ms (under WriteTimeout/4: the stale sample of the first response left it with no baseline)", + time.Since(second).Round(time.Millisecond)) + } + } +} + +// TestParkedConnWithNothingParkedIsStillReapedByReadTimeout885: the other face +// of F1, a guard that holds on main and must go on holding: a conn whose +// response the client has taken whole and that then sits idle is reaped by +// ReadTimeout (300 ms) from the end of the response with WriteTimeout 600 ms +// on a TCP socket, and one whose socket does not report acknowledged bytes +// (an AF_UNIX pair, as the 876 rig has) and holds a response nobody takes is +// reaped by ReadTimeout from the last progress, not held for WriteTimeout (an +// hour). +func TestParkedConnWithNothingParkedIsStillReapedByReadTimeout885(t *testing.T) { + t.Run("tcp-drained-then-idle", func(t *testing.T) { + const rt = 300 * time.Millisecond + r := newTCPClosingRig876(t, resource.Config{ReadTimeout: rt, IdleTimeout: -1, WriteTimeout: 600 * time.Millisecond}, 1<<20) + r.cs.lastActivity = time.Now().UnixNano() + r.l.armEpollOut(r.cs) + for i := 0; i < 400 && csWritePending(r.cs); i++ { + for r.read(256<<10) > 0 { + } + r.l.handleWritable(r.cs) + } + if csWritePending(r.cs) || r.cs.writeSince != 0 { + t.Fatalf("apparatus: the response did not drain (writeSince=%d)", r.cs.writeSince) + } + drained := time.Now() + for time.Since(drained) < 2*time.Second { + time.Sleep(20 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(drained); gone < rt || gone > rt+250*time.Millisecond { + t.Errorf("an idle conn was reaped %v after its response ended, want ReadTimeout %v", gone.Round(time.Millisecond), rt) + } + return + } + } + t.Fatalf("an idle keep-alive conn was not reaped by ReadTimeout %v, 2 s after its response ended", rt) + }) + t.Run("not-tcp-parked", func(t *testing.T) { + const rt = 300 * time.Millisecond + r := newClosingRig876(t, resource.Config{ReadTimeout: rt, IdleTimeout: -1, WriteTimeout: time.Hour}, 1<<20) + r.cs.lastActivity = time.Now().UnixNano() + r.l.armEpollOut(r.cs) + start := time.Now() + for time.Since(start) < 2*time.Second { + time.Sleep(20 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(start); gone < rt || gone > rt+250*time.Millisecond { + t.Errorf("a parked conn whose socket reports no acknowledged bytes was reaped %v in, want ReadTimeout %v", gone.Round(time.Millisecond), rt) + } + return + } + } + t.Fatalf("a parked conn with no acknowledged-bytes signal was not reaped by ReadTimeout %v, 2 s in", rt) + }) +} + +// TestParkedResponseDrainedBehindTheLoopStartsTheIdleClockAtTheSweep885: a +// response the rule governs (a baseline is known, writeSince is the last +// window's stamp) that the dispatch goroutine's own flush drains, which the +// loop sees at a sweep (the queue is found empty), starts ReadTimeout from that +// sweep and not from the stamp of a window passed long before: a conn is not +// reaped at the instant its response ended because ReadTimeout (200 ms) is +// shorter than the window (1.6 s) it was last stamped in. +func TestParkedResponseDrainedBehindTheLoopStartsTheIdleClockAtTheSweep885(t *testing.T) { + const wt = 1600 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: time.Hour, IdleTimeout: -1, WriteTimeout: wt}) + r.l.checkTimeouts() // the baseline + if !r.cs.closeAckedKnown { + t.Fatalf("apparatus: no baseline after the first sweep") + } + r.l.cfg.ReadTimeout = 200 * time.Millisecond + time.Sleep(500 * time.Millisecond) // the stamp is now older than ReadTimeout + r.l.checkTimeouts() + if !r.open() { + t.Fatalf("the rule governs a parked response; ReadTimeout reaped it") + } + // The goroutine's flush emptied the queue; the loop has not seen it. + r.cs.writeBuf = r.cs.writeBuf[:0] + r.cs.writePos = 0 + r.cs.pendingBytes = 0 + r.l.checkTimeouts() + if !r.open() { + t.Fatalf("the conn was reaped at the sweep that found its response drained: ReadTimeout ran from the stamp of a window passed 500 ms before") + } + if r.cs.writeSince != 0 || r.cs.closeAckedKnown { + t.Errorf("the sweep left the clock running (writeSince=%d known=%v)", r.cs.writeSince, r.cs.closeAckedKnown) + } +} diff --git a/internal/engine/epoll/write_rate_unreported_885_linux_test.go b/internal/engine/epoll/write_rate_unreported_885_linux_test.go new file mode 100644 index 000000000..5ac60d76e --- /dev/null +++ b/internal/engine/epoll/write_rate_unreported_885_linux_test.go @@ -0,0 +1,133 @@ +//go:build linux + +package epoll + +import ( + "testing" + "time" + + "github.com/goceleris/celeris/internal/resource" +) + +// celeris#885 item 51, review r3 finding F4: a TCP stack that answers +// getsockopt(TCP_INFO) but does not fill tcpi_bytes_acked (the report is a +// user-space stack such as gVisor's; Linux before 4.1 returns a short struct) +// reads 0 for every conn. The rule must not take that for a peer that +// acknowledges nothing: a parked response is then judged by the flush clock as +// it was before the rule, and the rule is back as soon as the socket reports a +// count. A parked conn has had bytes sent, so a real stack's count is not 0 +// when the peer has taken any. +// +// The tests use the Loop's ackedProbe seam as the stack that reports 0. + +func zeroAcked885(int) (uint64, error) { return 0, nil } + +// TestParkedConnOfAStackThatReportsNoAckedBytesIsJudgedByTheFlushClock885: the +// peer takes 64 KiB every 100 ms and an EPOLLOUT edge (handleWritable) follows +// each read, so the flush clock moves at every one; the count the stack reports +// is 0. WriteTimeout 600 ms: the conn is held for 5 windows, as the flush clock +// holds it (and as the conn of a stack that reports the count and a peer above +// the floor is). Then the peer stops and the flush clock closes it a +// WriteTimeout later. +func TestParkedConnOfAStackThatReportsNoAckedBytesIsJudgedByTheFlushClock885(t *testing.T) { + const wt = 600 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: time.Hour, IdleTimeout: time.Hour, WriteTimeout: wt}) + r.l.ackedProbe = zeroAcked885 + start := time.Now() + for time.Since(start) < 5*wt { + time.Sleep(100 * time.Millisecond) + if r.read(64<<10) == 0 { + t.Fatalf("apparatus: the peer read nothing") + } + r.l.handleWritable(r.cs) + r.l.checkTimeouts() + if !r.open() { + t.Fatalf("celeris#885 item 51: a stack that reports bytes_acked = 0 turned the rule into a hard cutoff: the conn was reaped %v in, "+ + "the peer taking 64 KiB every 100 ms with an edge at each (the flush clock holds that)", time.Since(start).Round(time.Millisecond)) + } + } + stopped := time.Now() + for time.Since(stopped) < 3*wt { + time.Sleep(25 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(stopped); gone < wt-100*time.Millisecond || gone > wt+300*time.Millisecond { + t.Errorf("a peer that stopped was reaped %v after its last byte, want about one WriteTimeout (%v): the flush clock's", gone.Round(time.Millisecond), wt) + } + return + } + } + t.Fatalf("a peer that stopped reading was not reaped by the flush clock %v after its last byte", 3*wt) +} + +// TestParkedConnIsRateGovernedOnceTheStackReportsAckedBytes885: the stack +// reports 0 for the first 300 ms of the response and the real count after (a +// peer that had acknowledged nothing at the first sweeps: a high round trip), and +// the peer reads 4 times the floor with no edge: the rule takes the conn from +// there and it is held 4 windows past the point where the flush clock would +// have reaped it (ReadTimeout and IdleTimeout off); then the peer stops and the +// rule closes it within two windows. +func TestParkedConnIsRateGovernedOnceTheStackReportsAckedBytes885(t *testing.T) { + const wt = 600 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: -1, IdleTimeout: -1, WriteTimeout: wt}) + start := time.Now() + r.l.ackedProbe = func(fd int) (uint64, error) { + if time.Since(start) < 300*time.Millisecond { + return 0, nil + } + r.l.ackedProbe = nil // the real read from here (the loop thread is this one) + return r.l.bytesAcked(fd) + } + rate := 4 * floorRate885(wt) + var took float64 + for time.Since(start) < 4*wt { + time.Sleep(20 * time.Millisecond) + el := time.Since(start) + for due := rate*el.Seconds() - took; due >= 4096; { + n := r.read(min(int(due), 16<<10)) + if n == 0 { + break + } + took += float64(n) + due -= float64(n) + } + _ = r.l.flushWrites(r.cs, true) + r.l.checkTimeouts() + if !r.open() { + t.Fatalf("reaped %v in, the peer taking 4x the floor with no edge once the stack reports the count (from 300 ms)", el.Round(time.Millisecond)) + } + } + stopped := time.Now() + for time.Since(stopped) < 4*wt { + time.Sleep(25 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(stopped); gone > 2*wt+250*time.Millisecond { + t.Errorf("a peer that stopped was reaped %v after its last byte, want within two windows (%v)", gone.Round(time.Millisecond), 2*wt) + } + return + } + } + t.Fatalf("a peer that stopped reading was not reaped %v after its last byte", 4*wt) +} + +// TestParkedConnOfAStackThatReportsNoAckedBytesAndATakesNothingIsReaped885 +// (guard, holds before the fix too): nothing taken, a count of 0, WriteTimeout +// 600 ms: reaped between one and two windows in, by the flush clock. +func TestParkedConnOfAStackThatReportsNoAckedBytesAndATakesNothingIsReaped885(t *testing.T) { + const wt = 600 * time.Millisecond + r := parked885(t, resource.Config{ReadTimeout: -1, IdleTimeout: -1, WriteTimeout: wt}) + r.l.ackedProbe = zeroAcked885 + start := time.Now() + for time.Since(start) < 4*wt { + time.Sleep(25 * time.Millisecond) + r.l.checkTimeouts() + if !r.open() { + if gone := time.Since(start); gone < wt || gone > 2*wt { + t.Errorf("reaped %v in, want between one and two windows (%v)", gone.Round(time.Millisecond), wt) + } + return + } + } + t.Fatalf("a peer that takes nothing was not reaped %v in", 4*wt) +} diff --git a/test/server/write_rate_sendfile_885_linux_test.go b/test/server/write_rate_sendfile_885_linux_test.go new file mode 100644 index 000000000..5cc045473 --- /dev/null +++ b/test/server/write_rate_sendfile_885_linux_test.go @@ -0,0 +1,69 @@ +//go:build linux + +package celeris_test + +import ( + "bufio" + "net" + "net/http" + "os" + "path/filepath" + "strconv" + "testing" + "time" + + "github.com/goceleris/celeris" +) + +// TestEpollStaticFileDownloadAtAModerateRateCompletes885 is the sendfile half of +// the first design's blocker (celeris PR 1116): a 12 MiB file sent with c.File +// (sendfile(2)) to a client reading about 2 MiB/s (64 KiB every 30 ms), IdleTimeout 2 s, +// WriteTimeout -1 and 60 s. The transfer takes about 6 s, three times +// IdleTimeout, and the client takes it steadily: it must arrive whole (the first +// design cut it at IdleTimeout: EOF at 3.9 s with IdleTimeout 3 s, 8.1 MB of 24). +func TestEpollStaticFileDownloadAtAModerateRateCompletes885(t *testing.T) { + dir := t.TempDir() + const size = 12 << 20 + if err := os.WriteFile(filepath.Join(dir, "f"), make([]byte, size), 0o600); err != nil { + t.Fatal(err) + } + for _, wt := range []time.Duration{-1, 60 * time.Second} { + t.Run(wt.String(), func(t *testing.T) { + addr := startServerConfig421(t, celeris.Config{Engine: celeris.Epoll, WriteTimeout: wt, IdleTimeout: 2 * time.Second, ReadTimeout: -1}, func(s *celeris.Server) { + s.GET("/f", func(c *celeris.Context) error { return c.File(filepath.Join(dir, "f")) }) + }) + c, err := net.Dial("tcp", addr) + if err != nil { + t.Fatal(err) + } + defer func() { _ = c.Close() }() + if _, err := c.Write([]byte("GET /f HTTP/1.1\r\nHost: x\r\n\r\n")); err != nil { + t.Fatal(err) + } + t0 := time.Now() + _ = c.SetReadDeadline(time.Now().Add(30 * time.Second)) + resp, err := http.ReadResponse(bufio.NewReader(c), nil) + if err != nil { + t.Fatalf("response head: %v", err) + } + var got int64 + buf := make([]byte, 64<<10) + for { + n, err := resp.Body.Read(buf) + got += int64(n) + if err != nil { + break + } + time.Sleep(30 * time.Millisecond) + } + took := time.Since(t0) + t.Logf("celeris885 sendfile wt=%v: %d of %d bytes in %v (Content-Length %s)", wt, got, size, took.Round(10*time.Millisecond), strconv.FormatInt(resp.ContentLength, 10)) + if got != size { + t.Errorf("the client received %d of %d bytes of the file %v in, reading steadily, with IdleTimeout 2s", got, size, took.Round(10*time.Millisecond)) + } + if took < 4*time.Second { + t.Errorf("apparatus: the transfer took %v, not well over IdleTimeout", took) + } + }) + } +}