cache: the Store.Set default bound is 1 second (v1.6.0, Refs #888)

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).

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

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()
-}

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)
+	}
+}