diff --git a/middleware/cache/config.go b/middleware/cache/config.go index bc91db198..37cf10aad 100644 --- a/middleware/cache/config.go +++ b/middleware/cache/config.go @@ -119,7 +119,7 @@ type Config struct { SkipPaths []string // SetTimeout bounds how long the middleware waits for each Store.Set it - // makes to store a response. Zero selects the default, 5 seconds, a + // makes to store a response. Zero selects the default, 1 second, a // negative value waits for ever, as before the field. // When the Set has not returned in time the request goes on without it: // the leader of a coalesced fill releases its key and writes its @@ -143,6 +143,12 @@ type Config struct { // one it was waiting for it is raised on the request, as without the // bound. // + // A Set that has not returned in time is abandoned silently: nothing is + // logged or counted (only a panic is), the Set's error is dropped, and the + // client gets a normal response marked X-Cache: MISS. A store whose Set can + // legitimately take longer than the default (Redis over a WAN, a saturated + // pool) needs a larger value, for example 5 * time.Second. + // // The bound applies to every store except [MemoryStore] and // [store.MemoryKV] themselves, which only take a lock. Any other type is // bounded, one that wraps an in-process store included (a type that @@ -153,10 +159,13 @@ type Config struct { } // defaultSetTimeout is the bound on a Store.Set when Config.SetTimeout is 0. -// PENDING the maintainer's decision (celeris#888 item 30): this one constant -// and the sentence "Zero selects the default, 5 seconds," in the SetTimeout -// field's doc are the only places to change. -const defaultSetTimeout = 5 * time.Second +// A Set that never returns holds its request, and on epoll and io_uring the +// event loop a sync request runs on, for the whole bound (a bystander on that +// loop was measured 951 ms late at 1 s and 2.95 s late at 3 s), so the default is +// short: a healthy Redis or Memcached Set takes well under a millisecond. This +// one constant and the sentence "Zero selects the default, 1 second," in the +// SetTimeout field's doc are the only places to change (celeris#888 item 30). +const defaultSetTimeout = time.Second // defaultConfig holds the defaults. Every bool field's default is false, so // a Config literal that leaves one out gets its default (celeris#922). diff --git a/middleware/cache/doc.go b/middleware/cache/doc.go index 0d622e4e5..3e6d062a4 100644 --- a/middleware/cache/doc.go +++ b/middleware/cache/doc.go @@ -19,6 +19,18 @@ // instance deployments, use [middleware/session/redisstore.New] with // a cache-specific prefix. // +// # Store.Set bound +// +// The middleware waits for each Store.Set for at most [Config].SetTimeout, +// 1 second by default, so a store whose Set hangs cannot hold the request +// (and on epoll and io_uring its event loop) for longer. A Set that has not +// returned in time is abandoned: the response is sent as usual, marked +// X-Cache: MISS, and is not stored; nothing is logged or counted unless the +// Set panics. A store that ignores the context it is given keeps running +// the abandoned Set in a goroutine until it returns. Raise the bound for a +// store whose Set is legitimately slower, for example +// Config{SetTimeout: 5 * time.Second}; a negative value waits for ever. +// // # Singleflight // // By default concurrent requests that miss on the same key coalesce: one diff --git a/middleware/cache/set_timeout_888_test.go b/middleware/cache/set_timeout_888_test.go index b68885ebb..6a4519875 100644 --- a/middleware/cache/set_timeout_888_test.go +++ b/middleware/cache/set_timeout_888_test.go @@ -4,7 +4,6 @@ import ( "bytes" "context" "os" - "strconv" "strings" "sync/atomic" "testing" @@ -16,10 +15,9 @@ import ( "github.com/goceleris/celeris/middleware/store" ) -// Config.SetTimeout (celeris#888 item 30). PENDING the maintainer's decision -// on the default: nothing here names its value except -// TestDefaultSetTimeoutIsInTheDoc888 and TestSetTimeoutZeroSelectsTheDefault888, -// which go through defaultSetTimeout. +// Config.SetTimeout (celeris#888 item 30). The default is 1 second (the +// maintainer's decision): TestDefaultSetTimeoutIsOneSecond888 and +// TestSetTimeoutZeroSelectsTheDefault888 name the number. // A Set that hangs no longer holds the leader past SetTimeout, with a store // that ignores its context and with one that honours it, coalesced or not. @@ -152,8 +150,26 @@ func TestSetTimeoutZeroSelectsTheDefault888(t *testing.T) { if d == nil { t.Fatal("the Set was given a context without a deadline") } - if until := time.Until(*d); until > defaultSetTimeout || until < defaultSetTimeout-2*time.Second { - t.Errorf("the Set's context ends in %v, want about defaultSetTimeout (%v)", until, defaultSetTimeout) + // The literal 1 s, not the constant: a changed default must fail here. + if until := time.Until(*d); until > time.Second || until < 500*time.Millisecond { + t.Errorf("the Set's context ends in %v, want between 500ms and 1s (the default, 1 second)", until) + } +} + +// TestDefaultSetTimeoutIsOneSecond888 pins the default's value: 1 second, a +// hung Set holds its event loop for the whole bound (celeris#888 item 30). +func TestDefaultSetTimeoutIsOneSecond888(t *testing.T) { + if defaultSetTimeout != time.Second { + t.Errorf("defaultSetTimeout = %v, want 1s", defaultSetTimeout) + } + if got := applyDefaults(Config{}).SetTimeout; got != time.Second { + t.Errorf("applyDefaults(Config{}).SetTimeout = %v, want 1s", got) + } + if got := applyDefaults(Config{SetTimeout: 3 * time.Second}).SetTimeout; got != 3*time.Second { + t.Errorf("an explicit SetTimeout of 3s became %v", got) + } + if got := applyDefaults(Config{SetTimeout: -1}).SetTimeout; got != -1 { + t.Errorf("a negative SetTimeout became %v, want it kept (no bound)", got) } } @@ -255,21 +271,10 @@ func TestDefaultSetTimeoutIsInTheDoc888(t *testing.T) { if err != nil { t.Fatal(err) } - want := "Zero selects the default, " + secondsWord888(defaultSetTimeout) + "," + want := "Zero selects the default, 1 second," src = bytes.Join(bytes.Fields(src), []byte(" ")) src = bytes.ReplaceAll(src, []byte(" // "), []byte(" ")) if !strings.Contains(string(src), want) { t.Errorf("config.go's SetTimeout doc does not say %q: change the doc with the constant", want) } } - -func secondsWord888(d time.Duration) string { - if d%time.Second == 0 { - n := int(d / time.Second) - if n == 1 { - return "1 second" - } - return strconv.Itoa(n) + " seconds" - } - return d.String() -} diff --git a/middleware/cache/set_timeout_default_888_linux_test.go b/middleware/cache/set_timeout_default_888_linux_test.go new file mode 100644 index 000000000..46afcd44b --- /dev/null +++ b/middleware/cache/set_timeout_default_888_linux_test.go @@ -0,0 +1,131 @@ +//go:build linux + +package cache_test + +import ( + "context" + "io" + "net" + "net/http" + "testing" + "time" + + "github.com/goceleris/celeris" + "github.com/goceleris/celeris/middleware/cache" + "github.com/goceleris/celeris/middleware/store" +) + +// neverSetKV is a store whose Set never returns and ignores its context (a +// remote store whose connection hung); release lets it go at the end. +type neverSetKV struct { + store.KV + entered chan struct{} + release chan struct{} +} + +func (s *neverSetKV) Set(_ context.Context, _ string, _ []byte, _ time.Duration) error { + select { + case s.entered <- struct{}{}: + default: + } + <-s.release + return nil +} + +// TestDefaultSetTimeoutBoundsTheLoopHold888 (celeris#888 item 30): a sync cache +// miss whose Store.Set never returns holds its epoll event loop for as long as +// the bound, and a request that lands on that loop waits as long. The default +// bound is 1 second: the reviewer measured a bystander delayed 951 ms at a 1 s +// bound and 2.95 s at 3 s. Config.SetTimeout is left unset: this is the +// default's test. +// +// The engine needs two workers at least, so bystanders are sent one after the +// other, each on a new connection, until the miss is answered: the first one +// the kernel hands to the held loop waits out the hold, the others are answered +// at once. The longest wait is the one that counts. +func TestDefaultSetTimeoutBoundsTheLoopHold888(t *testing.T) { + kv := &neverSetKV{KV: store.NewMemoryKV(), entered: make(chan struct{}, 1), release: make(chan struct{})} + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + addr := ln.Addr().String() + s := celeris.New(celeris.Config{Engine: celeris.Epoll, Workers: 2}) + s.GET("/ping", func(c *celeris.Context) error { return c.String(200, "ok") }) + s.GET("/c", cache.New(cache.Config{Store: kv}), func(c *celeris.Context) error { return c.String(200, "v") }) + started := make(chan error, 1) + go func() { started <- s.StartWithListener(ln) }() + t.Cleanup(func() { + close(kv.release) + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + _ = s.Shutdown(ctx) + <-started + }) + cl := &http.Client{Timeout: 20 * time.Second, Transport: &http.Transport{DisableKeepAlives: true}} + get := func(path string) (string, time.Duration, error) { + began := time.Now() + r, err := cl.Get("http://" + addr + path) + if err != nil { + return "", time.Since(began), err + } + defer func() { _ = r.Body.Close() }() + b, err := io.ReadAll(r.Body) + return r.Header.Get("X-Cache") + " " + string(b), time.Since(began), err + } + // The server is up when /ping answers. + for deadline := time.Now().Add(30 * time.Second); ; { + if _, _, err := get("/ping"); err == nil { + break + } + select { + case err := <-started: + t.Fatalf("Start returned %v", err) + case <-time.After(20 * time.Millisecond): + } + if time.Now().After(deadline) { + t.Fatal("the server did not come up in 30 s") + } + } + + type result struct { + out string + d time.Duration + err error + } + miss := make(chan result, 1) + go func() { + out, d, err := get("/c") + miss <- result{out, d, err} + }() + select { + case <-kv.entered: + case <-time.After(10 * time.Second): + t.Fatal("the miss never reached Store.Set") + } + var r result + var ping time.Duration // the longest wait of a bystander + for answered := false; !answered; { + select { + case r = <-miss: + answered = true + default: + if _, d, err := get("/ping"); err != nil { + t.Fatal(err) + } else { + ping = max(ping, d) + } + } + } + t.Logf("miss answered after %v; the bystander /ping waited %v", r.d.Round(time.Millisecond), ping.Round(time.Millisecond)) + if ping < 300*time.Millisecond { + t.Fatalf("the longest bystander wait was only %v: no bystander met the held loop, so this test measures nothing", ping) + } + const limit = 2500 * time.Millisecond // 1 s bound plus slack; a 5 s bound would give about 5 s + if r.d > limit || ping > limit { + t.Errorf("miss answered after %v, bystander waited %v; want both within %v (default bound 1 s)", r.d, ping, limit) + } + if r.d < 800*time.Millisecond { + t.Errorf("the miss was answered after %v, before the 1 s default bound", r.d) + } +}