diff --git a/gonsole/CHANGELOG.md b/gonsole/CHANGELOG.md index 7e69c1d..3c051dc 100644 --- a/gonsole/CHANGELOG.md +++ b/gonsole/CHANGELOG.md @@ -8,6 +8,25 @@ v0.x, minor releases may contain breaking changes. Releases of this module are tagged `gonsole/vX.Y.Z`. +## [Unreleased] + +### Added + +- `Timeouts.CancelGrace` and `Timeouts.StopGrace`, read from the `SHUTDOWN_CANCEL_GRACE` and `SHUTDOWN_STOP_GRACE` settings. +- `ErrGraceRanOut`, the cause a request cancelled after the shutdown grace sees, and `ErrStillServing`. + +### Changed + +- `Serve` cancels the requests still running when the shutdown grace ends and logs a warning with their count. +- `Serve` closes the connections left when the cancel grace ends, with a warning, and returns `ErrStillServing` if a request still runs. A hijacked connection stays open. +- `Serve` wraps the `Handler` and the `BaseContext` of the server it runs, keeping the base's values but owning its cancellation. +- `Serve` refuses a grace, cancel grace or stop grace that is not above zero, before it listens. +- `Serve` no longer returns the deadline error of the server's own shutdown. + +### Fixed + +- `Serve` calls stop under the stop grace once the requests ended, never with what the shutdown grace left. + ## [0.1.0] - 2026-09-25 ### Added diff --git a/gonsole/internal/exampleapp/program.go b/gonsole/internal/exampleapp/program.go index ef84946..5fc66c8 100644 --- a/gonsole/internal/exampleapp/program.go +++ b/gonsole/internal/exampleapp/program.go @@ -77,6 +77,7 @@ func (demo) Commands() []gonsole.Command { func serve(ctx context.Context, call gonsole.Call) error { timeouts, err := call.Env.Timeouts(gonsole.Timeouts{ ReadHeader: 10 * time.Second, Read: 30 * time.Second, Idle: 120 * time.Second, Grace: 10 * time.Second, + CancelGrace: 5 * time.Second, StopGrace: 5 * time.Second, }) if err != nil { return err diff --git a/gonsole/serve.go b/gonsole/serve.go index 26d1e8d..c0ec877 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -10,10 +10,17 @@ import ( "log/slog" "net" "net/http" + "sync" "time" ) -// Timeouts are the HTTP timeouts and the shutdown grace one server runs under. +// ErrGraceRanOut is the cause context.Cause reports for a request Serve cancels after the shutdown grace. +var ErrGraceRanOut = errors.New("gonsole: the shutdown grace ran out") + +// ErrStillServing reports requests still running when the cancel grace ended. +var ErrStillServing = errors.New("gonsole: requests still running after the cancel grace") + +// Timeouts are the HTTP timeouts and the shutdown graces one server runs under. type Timeouts struct { // ReadHeader bounds reading one request's headers, the HTTP_READ_HEADER_TIMEOUT setting. ReadHeader time.Duration @@ -21,18 +28,24 @@ type Timeouts struct { Read time.Duration // Idle bounds how long a kept alive connection waits for its next request, the HTTP_IDLE_TIMEOUT setting. Idle time.Duration - // Grace bounds the shutdown of the server and the stop of what it serves, the SHUTDOWN_GRACE setting. + // Grace bounds how long open requests get to finish once the run ends, the SHUTDOWN_GRACE setting. Grace time.Duration + // CancelGrace bounds how long the requests cancelled after the grace get to end, the SHUTDOWN_CANCEL_GRACE setting. + CancelGrace time.Duration + // StopGrace bounds the stop of what the server serves, the SHUTDOWN_STOP_GRACE setting. + StopGrace time.Duration } -// Timeouts returns the HTTP timeouts and the shutdown grace, each falling back to fallback. +// Timeouts returns the HTTP timeouts and the shutdown graces, each falling back to fallback. func (e Env) Timeouts(fallback Timeouts) (Timeouts, error) { var read Timeouts - var failed [4]error + var failed [6]error read.ReadHeader, failed[0] = e.Duration("HTTP_READ_HEADER_TIMEOUT", fallback.ReadHeader) read.Read, failed[1] = e.Duration("HTTP_READ_TIMEOUT", fallback.Read) read.Idle, failed[2] = e.Duration("HTTP_IDLE_TIMEOUT", fallback.Idle) read.Grace, failed[3] = e.Duration("SHUTDOWN_GRACE", fallback.Grace) + read.CancelGrace, failed[4] = e.Duration("SHUTDOWN_CANCEL_GRACE", fallback.CancelGrace) + read.StopGrace, failed[5] = e.Duration("SHUTDOWN_STOP_GRACE", fallback.StopGrace) if err := errors.Join(failed[:]...); err != nil { return Timeouts{}, err } @@ -46,20 +59,36 @@ func NewServer(addr string, handler http.Handler, t Timeouts) *http.Server { } } -// Serve serves srv until ctx ends or serving fails, then shuts it down and calls stop within the grace. +// Serve serves srv until ctx ends or serving fails, then drains it, cancelling what outlasts the grace, and calls stop. func Serve( ctx context.Context, srv *http.Server, t Timeouts, stop func(context.Context) error, logger *slog.Logger, ) error { + if err := refuseGraces(t); err != nil { + return err + } listener, err := net.Listen("tcp", cmp.Or(srv.Addr, ":http")) if err != nil { - grace, cancel := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) - defer cancel() - return errors.Join(fmt.Errorf("http server: %w", err), optional(grace, stop)) + return errors.Join(fmt.Errorf("http server: %w", err), stopWithin(ctx, t, stop)) } return serveOn(ctx, srv, listener, t, stop, logger) } -// serveOn serves srv on listener until ctx ends or serving fails, then shuts it down and calls stop within the grace. +// refuseGraces returns an error naming each grace of t that does not stand above zero. +func refuseGraces(t Timeouts) error { + graces := []struct { + name string + grace time.Duration + }{{"Grace", t.Grace}, {"CancelGrace", t.CancelGrace}, {"StopGrace", t.StopGrace}} + var refused []error + for _, g := range graces { + if g.grace <= 0 { + refused = append(refused, fmt.Errorf("gonsole: Timeouts.%s must stand above zero, got %v", g.name, g.grace)) + } + } + return errors.Join(refused...) +} + +// serveOn serves srv on listener until ctx ends or serving fails, then drains it and calls stop within the stop grace. func serveOn( ctx context.Context, srv *http.Server, listener net.Listener, t Timeouts, stop func(context.Context) error, logger *slog.Logger, @@ -68,6 +97,7 @@ func serveOn( if srv.ErrorLog == nil { srv.ErrorLog = slog.NewLogLogger(logger.Handler(), slog.LevelError) } + requests := track(ctx, srv) served := make(chan error, 1) go func() { served <- srv.Serve(listener) }() logger.Info("listening", "addr", listener.Addr().String()) @@ -78,13 +108,147 @@ func serveOn( case <-ctx.Done(): logger.Info("shutting down") } - grace, cancel := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) - defer cancel() - shut := srv.Shutdown(grace) + still := drain(ctx, srv, requests, t, logger) if failed == nil { <-served } - return errors.Join(failed, shut, optional(grace, stop)) + return errors.Join(failed, still, stopWithin(ctx, t, stop)) +} + +// track points the requests of srv at a base only Serve cancels, keeping its own base's values, and counts them. +func track(ctx context.Context, srv *http.Server) *inflight { + base, cancel := context.WithCancelCause(context.WithoutCancel(ctx)) + requests := &inflight{cancel: cancel} + own := srv.BaseContext + srv.BaseContext = func(listener net.Listener) context.Context { + if own == nil { + return base + } + return within(own(listener), base) + } + srv.Handler = requests.wrap(cmp.Or[http.Handler](srv.Handler, http.DefaultServeMux)) + return requests +} + +// within returns a context holding the values of held that ends when base ends, with the same cause. +func within(held, base context.Context) context.Context { + joined, cancel := context.WithCancelCause(context.WithoutCancel(held)) + context.AfterFunc(base, func() { cancel(context.Cause(base)) }) + return joined +} + +// drain shuts srv down within the grace, cancels what still runs, and closes what outlives the cancel grace. +func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts, logger *slog.Logger) error { + shutting, stopShutting := context.WithCancel(context.WithoutCancel(ctx)) + shut := make(chan struct{}) + go func() { + _ = srv.Shutdown(shutting) + close(shut) + }() + grace, endGrace := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) + defer endGrace() + await(grace, shut) + if running := requests.settle(grace); running > 0 { + logger.Warn("cancelling the requests still running after the shutdown grace", "count", running) + } + requests.cancel(ErrGraceRanOut) + cancelGrace, endCancelGrace := context.WithTimeout(context.WithoutCancel(ctx), t.CancelGrace) + defer endCancelGrace() + await(cancelGrace, shut) + running := requests.settle(cancelGrace) + if !finished(shut) { + logger.Warn("closing the connections still open after the cancel grace") + } + stopShutting() + <-shut + _ = srv.Close() + if running > 0 { + return ErrStillServing + } + return nil +} + +// finished reports whether shut is closed. +func finished(shut <-chan struct{}) bool { + select { + case <-shut: + return true + default: + return false + } +} + +// await waits until shut closes or ctx ends. +func await(ctx context.Context, shut <-chan struct{}) { + select { + case <-shut: + case <-ctx.Done(): + } +} + +// inflight counts the requests one server is handling and cancels them together. +type inflight struct { + mu sync.Mutex + running int + idle chan struct{} + cancel context.CancelCauseFunc +} + +// wrap returns next, counting each request while it runs. +func (in *inflight) wrap(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + in.enter() + defer in.leave() + next.ServeHTTP(w, r) + }) +} + +// enter counts one more running request. +func (in *inflight) enter() { + in.mu.Lock() + defer in.mu.Unlock() + if in.running == 0 { + in.idle = make(chan struct{}) + } + in.running++ +} + +// leave counts one running request fewer. +func (in *inflight) leave() { + in.mu.Lock() + defer in.mu.Unlock() + in.running-- + if in.running == 0 { + close(in.idle) + } +} + +// state returns how many requests run and a channel closed once none does. +func (in *inflight) state() (int, <-chan struct{}) { + in.mu.Lock() + defer in.mu.Unlock() + return in.running, in.idle +} + +// settle waits until the requests running now end or ctx ends, then returns how many requests run. +func (in *inflight) settle(ctx context.Context) int { + running, idle := in.state() + if running == 0 { + return 0 + } + select { + case <-idle: + case <-ctx.Done(): + } + running, _ = in.state() + return running +} + +// stopWithin calls stop, when set, under a context the stop grace bounds and the end of ctx cannot cancel. +func stopWithin(ctx context.Context, t Timeouts, stop func(context.Context) error) error { + bounded, cancel := context.WithTimeout(context.WithoutCancel(ctx), t.StopGrace) + defer cancel() + return optional(bounded, stop) } // optional calls fn under ctx, nothing when fn is nil. diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index b332063..ebe9e59 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -10,8 +10,10 @@ import ( "net" "net/http" "strings" + "sync" "sync/atomic" "testing" + "testing/synctest" "time" ) @@ -47,7 +49,8 @@ func TestServeShutsTheServerDownBeforeItStopsWhenServingFails(t *testing.T) { } _, _ = io.WriteString(w, "quarterly\n") }) - timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, Grace: 5 * time.Second} + timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, Grace: 5 * time.Second, + CancelGrace: 5 * time.Second, StopGrace: 5 * time.Second} srv := NewServer(inner.Addr().String(), handler, timeouts) stop := func(ctx context.Context) error { stopped.Store(true) @@ -64,11 +67,11 @@ func TestServeShutsTheServerDownBeforeItStopsWhenServingFails(t *testing.T) { fetch(t, client, address) close(listener.broken) - served := <-done + served := ended(t, done, timeouts) _, second := client.Get(address) - if !strings.HasPrefix(errorLine(served), "http server: the listener broke") { - t.Errorf("serveOn() = %v, want the serving failure", served) + if errorLine(served) != "http server: the listener broke" { + t.Errorf("serveOn() = %v, want only the serving failure", served) } if second == nil || late.Load() != 0 { t.Errorf("a request after the failure = %v, handled after stop %d times, want none handled", second, late.Load()) @@ -78,6 +81,276 @@ func TestServeShutsTheServerDownBeforeItStopsWhenServingFails(t *testing.T) { } } +func TestServeCancelsBeforeItStopsWhenServingFails(t *testing.T) { + t.Parallel() + + inner, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listening: %v", err) + } + arrived := make(chan struct{}) + causes := make(chan error, 1) + waiting := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + close(arrived) + <-r.Context().Done() + causes <- context.Cause(r.Context()) + }) + timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, Grace: 50 * time.Millisecond, + CancelGrace: 5 * time.Second, StopGrace: 5 * time.Second} + srv := NewServer(inner.Addr().String(), waiting, timeouts) + endedFirst := false + stop := func(ctx context.Context) error { + endedFirst = len(causes) == 1 + return ctx.Err() + } + listener := &brittle{Listener: inner, broken: make(chan struct{})} + done := make(chan error, 1) + go func() { done <- serveOn(t.Context(), srv, listener, timeouts, stop, nil) }() + client := &http.Client{Transport: &http.Transport{}} + go func() { _, _ = client.Get("http://" + inner.Addr().String() + "/") }() + <-arrived + + close(listener.broken) + served := ended(t, done, timeouts) + + if errorLine(served) != "http server: the listener broke" || !endedFirst { + t.Errorf("serveOn() = %v, request ended before stop %t, want only the serving failure after it ended", + served, endedFirst) + } + select { + case cause := <-causes: + if !errors.Is(cause, ErrGraceRanOut) { + t.Errorf("cause = %v, want the grace to have run out", cause) + } + default: + t.Errorf("the request was still running when serveOn returned") + } +} + +func TestServeRunsTheShutdownHooksOnce(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + var calls atomic.Int32 + timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, Grace: time.Second, + CancelGrace: time.Second, StopGrace: time.Second} + srv := NewServer("127.0.0.1:0", http.NotFoundHandler(), timeouts) + srv.RegisterOnShutdown(func() { calls.Add(1) }) + ctx, cancel := context.WithCancel(t.Context()) + cancel() + + err := Serve(ctx, srv, timeouts, nil, nil) + synctest.Wait() + + if err != nil || calls.Load() != 1 { + t.Errorf("Serve() = %v, shutdown hooks ran %d times, want nil and once", err, calls.Load()) + } + }) +} + +// slowWrites is a listener whose connections wait before each write, as over a slow network. +type slowWrites struct { + net.Listener + delay time.Duration +} + +// Accept returns the next connection with its writes slowed. +func (s slowWrites) Accept() (net.Conn, error) { + conn, err := s.Listener.Accept() + if err != nil { + return nil, err + } + return slowConn{Conn: conn, delay: s.delay}, nil +} + +// slowConn is a connection whose writes wait before they start. +type slowConn struct { + net.Conn + delay time.Duration +} + +// Write waits the delay, then writes p. +func (c slowConn) Write(p []byte) (int, error) { + time.Sleep(c.delay) + return c.Conn.Write(p) +} + +func TestServeDeliversACancelledResponseOverASlowConnection(t *testing.T) { + t.Parallel() + + inner, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listening: %v", err) + } + arrived := make(chan struct{}) + unavailable := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(arrived) + <-r.Context().Done() + w.WriteHeader(http.StatusServiceUnavailable) + }) + timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, + Grace: 10 * time.Millisecond, CancelGrace: 5 * time.Second, StopGrace: 5 * time.Second} + srv := NewServer(inner.Addr().String(), unavailable, timeouts) + ctx, cancel := context.WithCancel(t.Context()) + listener := slowWrites{Listener: inner, delay: 50 * time.Millisecond} + done := make(chan error, 1) + go func() { done <- serveOn(ctx, srv, listener, timeouts, nil, nil) }() + client := &http.Client{Transport: &http.Transport{}, Timeout: 10 * time.Second} + answered := make(chan int, 1) + go func() { + response, err := client.Get("http://" + inner.Addr().String() + "/") + if err != nil { + answered <- 0 + return + } + _ = response.Body.Close() + answered <- response.StatusCode + }() + <-arrived + + cancel() + served := ended(t, done, timeouts) + + if code := <-answered; served != nil || code != http.StatusServiceUnavailable { + t.Errorf("serveOn() = %v, answer %d, want nil and the cancelled request's own 503", served, code) + } +} + +func TestServeWarnsWhenTheCancelGraceCutsAResponseStillBeingWritten(t *testing.T) { + t.Parallel() + + inner, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listening: %v", err) + } + arrived := make(chan struct{}) + unavailable := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(arrived) + <-r.Context().Done() + w.WriteHeader(http.StatusServiceUnavailable) + }) + timeouts := Timeouts{ReadHeader: time.Second, Read: time.Second, Idle: time.Minute, + Grace: 10 * time.Millisecond, CancelGrace: 100 * time.Millisecond, StopGrace: 5 * time.Second} + srv := NewServer(inner.Addr().String(), unavailable, timeouts) + ctx, cancel := context.WithCancel(t.Context()) + listener := slowWrites{Listener: inner, delay: time.Second} + var logged strings.Builder + done := make(chan error, 1) + go func() { + done <- serveOn(ctx, srv, listener, timeouts, nil, slog.New(slog.NewTextHandler(&logged, nil))) + }() + client := &http.Client{Transport: &http.Transport{}, Timeout: 10 * time.Second} + answered := make(chan error, 1) + go func() { + _, err := client.Get("http://" + inner.Addr().String() + "/") + answered <- err + }() + <-arrived + + cancel() + served := ended(t, done, timeouts) + + if cut := <-answered; served != nil || !errors.Is(cut, io.EOF) { + t.Errorf("serveOn() = %v, client error %v, want nil and the response cut", served, cut) + } + if !strings.Contains(logged.String(), `level=WARN msg="closing the connections still open after the cancel grace"`) { + t.Errorf("log = %q, want a warning that the cancel grace closed connections still open", logged.String()) + } +} + +// watched is a context that says when its Done channel is first asked for. +type watched struct { + context.Context + once sync.Once + asked chan struct{} +} + +// newWatched returns ctx, watched for the first ask of its Done channel. +func newWatched(ctx context.Context) *watched { + return &watched{Context: ctx, asked: make(chan struct{})} +} + +// Done closes asked on its first call and returns the context's Done channel. +func (w *watched) Done() <-chan struct{} { + w.once.Do(func() { close(w.asked) }) + return w.Context.Done() +} + +func TestSettleReturnsAtOnceWhenNoRequestRuns(t *testing.T) { + t.Parallel() + + var requests inflight + requests.enter() + requests.leave() + requests.enter() + requests.leave() + ctx := newWatched(t.Context()) + + running := requests.settle(ctx) + + select { + case <-ctx.asked: + t.Errorf("settle waited on its context with no request running") + default: + } + if running != 0 { + t.Errorf("settle() = %d, want 0", running) + } +} + +func TestSettleReturnsOnceTheRunningRequestsEnd(t *testing.T) { + t.Parallel() + + var requests inflight + requests.enter() + ctx := newWatched(t.Context()) + settled := make(chan int, 1) + go func() { settled <- requests.settle(ctx) }() + <-ctx.asked + + requests.leave() + + if running := <-settled; running != 0 { + t.Errorf("settle() = %d, want 0 once the request ended", running) + } +} + +func TestSettleCountsTheRequestsStillRunningWhenItsContextEnds(t *testing.T) { + t.Parallel() + + var requests inflight + requests.enter() + requests.enter() + ctx, cancel := context.WithCancel(t.Context()) + watching := newWatched(ctx) + settled := make(chan int, 1) + go func() { settled <- requests.settle(watching) }() + <-watching.asked + requests.leave() + + cancel() + + if running := <-settled; running != 1 { + t.Errorf("settle() = %d, want the one request still running", running) + } +} + +// slack is how much longer than its graces a serveOn run may take before a test calls it stuck. +const slack = 5 * time.Second + +// ended waits for the answer of a serveOn run under timeouts, stopping t when the run outlives its graces. +func ended(t *testing.T, done <-chan error, timeouts Timeouts) error { + t.Helper() + bound := timeouts.Grace + timeouts.CancelGrace + timeouts.StopGrace + slack + select { + case err := <-done: + return err + case <-time.After(bound): + t.Fatalf("serveOn() still running %v after the run ended, want it to end within its graces", bound) + return nil + } +} + // fetch fetches address with client and reads the whole answer. func fetch(t *testing.T, client *http.Client, address string) { t.Helper() diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 1255247..9dc7203 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -18,11 +18,13 @@ import ( "time" "github.com/gopherium/framework/gonsole" + "github.com/gopherium/framework/gonsole/testkit" ) // defaults are the timeouts a program falls back to when its settings are empty. var defaults = gonsole.Timeouts{ ReadHeader: 10 * time.Second, Read: 30 * time.Second, Idle: 120 * time.Second, Grace: 15 * time.Second, + CancelGrace: 5 * time.Second, StopGrace: 10 * time.Second, } func TestEnvReadsTheTimeouts(t *testing.T) { @@ -37,16 +39,20 @@ func TestEnvReadsTheTimeouts(t *testing.T) { {"no settings", nil, defaults, ""}, {"every setting", map[string]string{ "MYAPP_HTTP_READ_HEADER_TIMEOUT": "2s", "MYAPP_HTTP_READ_TIMEOUT": "5s", - "MYAPP_HTTP_IDLE_TIMEOUT": "1m", "MYAPP_SHUTDOWN_GRACE": "3s", + "MYAPP_HTTP_IDLE_TIMEOUT": "1m", "MYAPP_SHUTDOWN_GRACE": "3s", "MYAPP_SHUTDOWN_STOP_GRACE": "6s", + "MYAPP_SHUTDOWN_CANCEL_GRACE": "4s", }, gonsole.Timeouts{ReadHeader: 2 * time.Second, Read: 5 * time.Second, Idle: time.Minute, - Grace: 3 * time.Second}, ""}, + Grace: 3 * time.Second, CancelGrace: 4 * time.Second, StopGrace: 6 * time.Second}, ""}, {"settings that fail", map[string]string{ "MYAPP_HTTP_READ_HEADER_TIMEOUT": "soon", "MYAPP_HTTP_READ_TIMEOUT": "0s", - "MYAPP_HTTP_IDLE_TIMEOUT": "-1s", "MYAPP_SHUTDOWN_GRACE": "later", + "MYAPP_HTTP_IDLE_TIMEOUT": "-1s", "MYAPP_SHUTDOWN_GRACE": "later", "MYAPP_SHUTDOWN_STOP_GRACE": "never", + "MYAPP_SHUTDOWN_CANCEL_GRACE": "0s", }, gonsole.Timeouts{}, `MYAPP_HTTP_READ_HEADER_TIMEOUT: must be a duration like 30s, got "soon" MYAPP_HTTP_READ_TIMEOUT: must stand above zero, got "0s" MYAPP_HTTP_IDLE_TIMEOUT: must stand above zero, got "-1s" -MYAPP_SHUTDOWN_GRACE: must be a duration like 30s, got "later"`}, +MYAPP_SHUTDOWN_GRACE: must be a duration like 30s, got "later" +MYAPP_SHUTDOWN_CANCEL_GRACE: must stand above zero, got "0s" +MYAPP_SHUTDOWN_STOP_GRACE: must be a duration like 30s, got "never"`}, } for _, tc := range cases { t.Run(tc.name, func(t *testing.T) { @@ -83,19 +89,21 @@ func TestNewServerCarriesTheTimeouts(t *testing.T) { } } -// journal is a logger target that keeps every line and hands out the address the server listens on. +// journal is a logger target that keeps every line and signals when the server listens and when it shuts down. type journal struct { mu sync.Mutex lines []string listening chan string + down chan struct{} + downAt time.Time } // newJournal returns an empty journal. func newJournal() *journal { - return &journal{listening: make(chan string, 1)} + return &journal{listening: make(chan string, 1), down: make(chan struct{})} } -// Write keeps one log line and hands out its address when it says the server listens. +// Write keeps one log line, handing out its address when the server listens and closing down when it shuts down. func (j *journal) Write(line []byte) (int, error) { j.mu.Lock() defer j.mu.Unlock() @@ -105,9 +113,20 @@ func (j *journal) Write(line []byte) (int, error) { _, address, _ := strings.Cut(text, "addr=") j.listening <- address } + if strings.Contains(text, `msg="shutting down"`) { + j.downAt = time.Now() + close(j.down) + } return len(line), nil } +// sinceDown returns how long ago the server said it shuts down. +func (j *journal) sinceDown() time.Duration { + j.mu.Lock() + defer j.mu.Unlock() + return time.Since(j.downAt) +} + // said reports whether any kept line holds text. func (j *journal) said(text string) bool { j.mu.Lock() @@ -146,6 +165,13 @@ func (s *stopper) stop(ctx context.Context) error { return s.fails } +// ranOnceWithin reports whether stop ran once, under a live context whose deadline stood about grace away. +func (s *stopper) ranOnceWithin(grace time.Duration) bool { + s.mu.Lock() + defer s.mu.Unlock() + return s.calls == 1 && s.live && s.deadline > grace-time.Second && s.deadline <= grace +} + // reportNames answers every request with the report names. func reportNames() http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { @@ -177,9 +203,17 @@ func serving( t *testing.T, handler http.Handler, grace time.Duration, stop func(context.Context) error, j *journal, ) (string, func() error) { t.Helper() - ctx, cancel := context.WithCancel(t.Context()) timeouts := defaults timeouts.Grace = grace + return servingUnder(t, handler, timeouts, stop, j) +} + +// servingUnder is serving under the timeouts given. +func servingUnder( + t *testing.T, handler http.Handler, timeouts gonsole.Timeouts, stop func(context.Context) error, j *journal, +) (string, func() error) { + t.Helper() + ctx, cancel := context.WithCancel(t.Context()) srv := gonsole.NewServer("127.0.0.1:0", handler, timeouts) done := make(chan error, 1) go func() { done <- gonsole.Serve(ctx, srv, timeouts, stop, j.logger()) }() @@ -187,7 +221,7 @@ func serving( case address := <-j.listening: return address, func() error { cancel() - return <-done + return ended(t, done, timeouts) } case err := <-done: cancel() @@ -196,6 +230,25 @@ func serving( return "", nil } +// slack is how much longer than its graces a Serve run may take before a test calls it stuck. +const slack = 5 * time.Second + +// errStuck is what ended answers for a Serve run that outlived its graces. +var errStuck = errors.New("the serve run outlived its graces") + +// ended waits for the answer of a Serve run under timeouts, failing t when the run outlives its graces. +func ended(t *testing.T, done <-chan error, timeouts gonsole.Timeouts) error { + t.Helper() + bound := timeouts.Grace + timeouts.CancelGrace + timeouts.StopGrace + slack + select { + case err := <-done: + return err + case <-time.After(bound): + t.Errorf("Serve() still running %v after the run ended, want it to end within its graces", bound) + return errStuck + } +} + func TestServeAnswersUntilTheRunEnds(t *testing.T) { t.Parallel() @@ -212,37 +265,419 @@ func TestServeAnswersUntilTheRunEnds(t *testing.T) { if err != nil { t.Errorf("Serve() = %v, want nil", err) } - if !j.said("msg=\"shutting down\"") { - t.Errorf("log = %q, want a shutting down line", j.lines) + if !j.said("msg=\"shutting down\"") || j.said("level=WARN") { + t.Errorf("log = %q, want a shutting down line and no warning", j.lines) } - if s.calls != 1 || !s.live || s.deadline <= 0 || s.deadline > time.Minute { - t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the grace", + if !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace", s.calls, s.live, s.deadline) } } -func TestServeGivesUpOnARequestThatOutlastsTheGrace(t *testing.T) { +func TestServeGivesStopItsOwnGrace(t *testing.T) { + t.Parallel() + + var s stopper + _, end := serving(t, reportNames(), time.Hour, s.stop, newJournal()) + + err := end() + + if err != nil { + t.Errorf("Serve() = %v, want nil", err) + } + if !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace, not the grace", + s.calls, s.live, s.deadline) + } +} + +func TestServeCancelsARequestThatOutlastsTheGrace(t *testing.T) { + t.Parallel() + + grace := 50 * time.Millisecond + j := newJournal() + arrived := make(chan struct{}) + causes := make(chan error, 1) + var kept time.Duration + waiting := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + close(arrived) + <-r.Context().Done() + kept = j.sinceDown() + causes <- context.Cause(r.Context()) + }) + var s stopper + endedFirst := false + stop := func(ctx context.Context) error { + endedFirst = len(causes) == 1 + return s.stop(ctx) + } + address, end := serving(t, waiting, grace, stop, j) + go func() { _, _ = http.Get("http://" + address + "/") }() + <-arrived + + err := end() + + if err != nil { + t.Errorf("Serve() = %v, want nil once the cancelled request ended", err) + } + select { + case cause := <-causes: + if !errors.Is(cause, gonsole.ErrGraceRanOut) { + t.Errorf("cause = %v, want the grace to have run out", cause) + } + if kept < grace || kept >= defaults.CancelGrace { + t.Errorf("request cancelled %v after the shutdown began, want once the grace of %v ran out, well within %v", + kept, grace, defaults.CancelGrace) + } + default: + t.Errorf("the request was still running when Serve returned") + } + if !endedFirst || !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("request ended before stop %t, stop calls = %d, live %t, deadline in %v, want one live call after it", + endedFirst, s.calls, s.live, s.deadline) + } + if !j.said(`level=WARN msg="cancelling the requests still running after the shutdown grace" count=1`) { + t.Errorf("log = %q, want a warning counting one cancelled request", j.lines) + } +} + +func TestServeKeepsARequestsContextLiveThroughTheGrace(t *testing.T) { + t.Parallel() + + arrived := make(chan struct{}) + proceed := make(chan struct{}) + seen := make(chan error, 1) + pending := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(arrived) + <-proceed + seen <- r.Context().Err() + _, _ = io.WriteString(w, "quarterly\n") + }) + j := newJournal() + address, end := serving(t, pending, time.Minute, nil, j) + go func() { _, _ = http.Get("http://" + address + "/") }() + <-arrived + ended := make(chan error, 1) + go func() { ended <- end() }() + <-j.down + + close(proceed) + + if err := <-seen; err != nil { + t.Errorf("request context = %v once the run ended, want it live through the grace", err) + } + if err := <-ended; err != nil { + t.Errorf("Serve() = %v, want nil", err) + } +} + +func TestServeWaitsForAHijackedConnectionBeforeItStops(t *testing.T) { + t.Parallel() + + grace := 50 * time.Millisecond + j := newJournal() + arrived := make(chan struct{}) + ended := make(chan struct{}) + var kept time.Duration + hijacking := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + connection, _, err := http.NewResponseController(w).Hijack() + close(arrived) + if err != nil { + t.Errorf("hijacking the connection: %v", err) + return + } + defer func() { _ = connection.Close() }() + <-r.Context().Done() + kept = j.sinceDown() + close(ended) + }) + endedFirst := false + stop := func(context.Context) error { + select { + case <-ended: + endedFirst = true + default: + } + return nil + } + address, end := serving(t, hijacking, grace, stop, j) + client, err := net.Dial("tcp", address) + if err != nil { + t.Fatalf("dialling %s: %v", address, err) + } + defer func() { _ = client.Close() }() + _, _ = io.WriteString(client, "GET / HTTP/1.1\r\nHost: reports\r\n\r\n") + <-arrived + + err = end() + + if err != nil || !endedFirst { + t.Errorf("Serve() = %v, hijacked request ended before stop %t, want nil after it ended", err, endedFirst) + } + if kept < grace { + t.Errorf("hijacked request cancelled %v after the shutdown began, want the whole grace of %v first", kept, grace) + } +} + +func TestServeDeliversTheCancelledRequestsOwnResponse(t *testing.T) { + t.Parallel() + + arrived := make(chan struct{}) + unavailable := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(arrived) + <-r.Context().Done() + w.WriteHeader(http.StatusServiceUnavailable) + }) + address, end := serving(t, unavailable, 10*time.Millisecond, nil, newJournal()) + answered := make(chan int, 1) + go func() { + code, _ := status(address) + answered <- code + }() + <-arrived + + err := end() + + if code := <-answered; err != nil || code != http.StatusServiceUnavailable { + t.Errorf("Serve() = %v, answer %d, want nil and the cancelled request's own 503", err, code) + } +} + +// patient is the client the serve tests fetch with, giving up on an answer that never comes. +var patient = &http.Client{Timeout: 10 * time.Second} + +// status fetches the root of the server at address and returns the answer's status code, or the error when none came. +func status(address string) (int, error) { + response, err := patient.Get("http://" + address + "/") + if err != nil { + return 0, err + } + _ = response.Body.Close() + return response.StatusCode, nil +} + +func TestServeClosesARequestThatIgnoresTheCancel(t *testing.T) { t.Parallel() release := make(chan struct{}) defer close(release) arrived := make(chan struct{}) - slow := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + stubborn := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { close(arrived) <-release }) var s stopper - address, end := serving(t, slow, 50*time.Millisecond, s.stop, newJournal()) - go func() { _, _ = http.Get("http://" + address + "/") }() + timeouts := defaults + timeouts.Grace, timeouts.CancelGrace = 50*time.Millisecond, 50*time.Millisecond + address, end := servingUnder(t, stubborn, timeouts, s.stop, newJournal()) + answered := make(chan error, 1) + go func() { + _, err := status(address) + answered <- err + }() + <-arrived + + err := end() + + if !errors.Is(err, gonsole.ErrStillServing) { + t.Errorf("Serve() = %v, want the request still running after the cancel grace", err) + } + if closed := <-answered; !errors.Is(closed, io.EOF) { + t.Errorf("client error = %v, want its connection closed", closed) + } + if !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace", + s.calls, s.live, s.deadline) + } +} + +func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { + t.Parallel() + + ctx, cancel := context.WithCancel(t.Context()) + timeouts := defaults + timeouts.Grace, timeouts.CancelGrace = 50*time.Millisecond, 50*time.Millisecond + srv := gonsole.NewServer("127.0.0.1:0", reportNames(), timeouts) + accepted := make(chan struct{}) + var once sync.Once + srv.ConnState = func(_ net.Conn, state http.ConnState) { + if state == http.StateNew { + once.Do(func() { close(accepted) }) + } + } + j := newJournal() + done := make(chan error, 1) + go func() { done <- gonsole.Serve(ctx, srv, timeouts, nil, j.logger()) }() + silent, err := net.Dial("tcp", <-j.listening) + if err != nil { + t.Fatalf("dialling: %v", err) + } + defer func() { _ = silent.Close() }() + <-accepted + + cancel() + served := ended(t, done, timeouts) + + _ = silent.SetReadDeadline(time.Now().Add(5 * time.Second)) + _, read := silent.Read(make([]byte, 1)) + if served != nil || !errors.Is(read, io.EOF) { + t.Errorf("Serve() = %v, read %v, want nil and the silent connection closed", served, read) + } + if !j.said(`level=WARN msg="closing the connections still open after the cancel grace"`) { + t.Errorf("log = %q, want a warning that the cancel grace closed connections still open", j.lines) + } +} + +func TestServeKeepsTheValuesOfTheServersOwnBaseContext(t *testing.T) { + t.Parallel() + + type reportKey struct{} + arrived := make(chan struct{}) + seen := make(chan any, 1) + causes := make(chan error, 1) + waiting := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + seen <- r.Context().Value(reportKey{}) + close(arrived) + <-r.Context().Done() + causes <- context.Cause(r.Context()) + }) + timeouts := defaults + timeouts.Grace = 50 * time.Millisecond + ctx, cancel := context.WithCancel(t.Context()) + srv := gonsole.NewServer("127.0.0.1:0", waiting, timeouts) + srv.BaseContext = func(net.Listener) context.Context { + return context.WithValue(ctx, reportKey{}, "quarterly") + } + j := newJournal() + done := make(chan error, 1) + go func() { done <- gonsole.Serve(ctx, srv, timeouts, nil, j.logger()) }() + address := <-j.listening + go func() { _, _ = status(address) }() <-arrived + cancel() + err := ended(t, done, timeouts) + + if value := <-seen; value != "quarterly" || err != nil { + t.Errorf("request value = %v, Serve() = %v, want the value the server's own base context holds and nil", + value, err) + } + select { + case cause := <-causes: + if !errors.Is(cause, gonsole.ErrGraceRanOut) { + t.Errorf("cause = %v, want the grace to have run out, not the end of the run", cause) + } + default: + t.Errorf("the request was still running when Serve returned") + } +} + +func TestServeKeepsAConnectionsContextLiveThroughTheGrace(t *testing.T) { + t.Parallel() + + grace := 300 * time.Millisecond + timeouts := defaults + timeouts.Grace, timeouts.CancelGrace = grace, 50*time.Millisecond + ctx, cancel := context.WithCancel(t.Context()) + srv := gonsole.NewServer("127.0.0.1:0", reportNames(), timeouts) + contexts := make(chan context.Context, 1) + srv.ConnContext = func(conn context.Context, _ net.Conn) context.Context { + contexts <- conn + return conn + } + j := newJournal() + done := make(chan error, 1) + go func() { done <- gonsole.Serve(ctx, srv, timeouts, nil, j.logger()) }() + silent, err := net.Dial("tcp", <-j.listening) + if err != nil { + t.Fatalf("dialling: %v", err) + } + defer func() { _ = silent.Close() }() + conn := <-contexts + + cancel() + <-conn.Done() + kept := j.sinceDown() + served := ended(t, done, timeouts) + + if kept < grace || !errors.Is(context.Cause(conn), gonsole.ErrGraceRanOut) || served != nil { + t.Errorf("connection context ended %v after the shutdown began with %v, Serve() = %v, "+ + "want it live through the grace of %v, then ended by the grace running out, and nil", + kept, context.Cause(conn), served, grace) + } +} + +func TestServeStartsNoRequestThatArrivesOnceTheShutdownBegan(t *testing.T) { + t.Parallel() + + var handled atomic.Int32 + counting := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + handled.Add(1) + _, _ = io.WriteString(w, "quarterly\n") + }) + ctx, cancel := context.WithCancel(t.Context()) + srv := gonsole.NewServer("127.0.0.1:0", counting, defaults) + accepted := make(chan struct{}) + var acceptedOnce sync.Once + srv.ConnState = func(_ net.Conn, state http.ConnState) { + if state == http.StateNew { + acceptedOnce.Do(func() { close(accepted) }) + } + } + began := make(chan struct{}) + var beganOnce sync.Once + srv.RegisterOnShutdown(func() { beganOnce.Do(func() { close(began) }) }) + j := newJournal() + done := make(chan error, 1) + go func() { done <- gonsole.Serve(ctx, srv, defaults, nil, j.logger()) }() + early, err := net.Dial("tcp", <-j.listening) + if err != nil { + t.Fatalf("dialling: %v", err) + } + defer func() { _ = early.Close() }() + <-accepted + cancel() + <-began + + _, _ = io.WriteString(early, "GET / HTTP/1.1\r\nHost: reports\r\n\r\n") + _ = early.SetReadDeadline(time.Now().Add(5 * time.Second)) + reply, _ := io.ReadAll(early) + + if handled.Load() != 0 || len(reply) != 0 { + t.Errorf("handled %d, reply %q, want no request started once the shutdown began", handled.Load(), reply) + } + if err := ended(t, done, defaults); err != nil { + t.Errorf("Serve() = %v, want nil", err) + } +} + +func TestServeCountsDownARequestThatAborts(t *testing.T) { + t.Parallel() + + aborting := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { panic(http.ErrAbortHandler) }) + j := newJournal() + address, end := serving(t, aborting, 50*time.Millisecond, nil, j) + if code, err := status(address); err == nil { + t.Errorf("GET answered %d, want the aborted request's connection closed", code) + } + err := end() - if !errors.Is(err, context.DeadlineExceeded) { - t.Errorf("Serve() = %v, want the grace to run out", err) + if err != nil || j.said("level=WARN") { + t.Errorf("Serve() = %v, log %q, want nil and no request left to cancel", err, j.lines) } - if s.calls != 1 { - t.Errorf("stop calls = %d, want 1", s.calls) +} + +func TestServeAnswersThroughTheDefaultMuxWhenTheServerHasNoHandler(t *testing.T) { + t.Parallel() + + address, end := serving(t, nil, time.Minute, nil, newJournal()) + + code, _ := status(address) + err := end() + + if code != http.StatusNotFound || err != nil { + t.Errorf("GET answered %d, Serve() = %v, want the default mux's 404 and nil", code, err) } } @@ -287,6 +722,51 @@ func TestServeStopsOnlyAfterTheServerHasDrained(t *testing.T) { } } +func TestServeRefusesAGraceThatIsNotAboveZero(t *testing.T) { + t.Parallel() + + cases := []struct { + name string + set func(*gonsole.Timeouts) + err string + }{ + {"a zero grace", func(to *gonsole.Timeouts) { to.Grace = 0 }, + "gonsole: Timeouts.Grace must stand above zero, got 0s"}, + {"a zero cancel grace", func(to *gonsole.Timeouts) { to.CancelGrace = 0 }, + "gonsole: Timeouts.CancelGrace must stand above zero, got 0s"}, + {"a negative stop grace", func(to *gonsole.Timeouts) { to.StopGrace = -time.Second }, + "gonsole: Timeouts.StopGrace must stand above zero, got -1s"}, + {"no grace at all", func(to *gonsole.Timeouts) { to.Grace, to.CancelGrace, to.StopGrace = 0, 0, 0 }, + "gonsole: Timeouts.Grace must stand above zero, got 0s\n" + + "gonsole: Timeouts.CancelGrace must stand above zero, got 0s\n" + + "gonsole: Timeouts.StopGrace must stand above zero, got 0s"}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + timeouts := defaults + tc.set(&timeouts) + ctx, cancel := context.WithCancel(t.Context()) + cancel() + var s stopper + j := newJournal() + address := testkit.FreeAddr(t) + + err := gonsole.Serve(ctx, gonsole.NewServer(address, reportNames(), timeouts), timeouts, s.stop, j.logger()) + + again, taken := net.Listen("tcp", address) + if taken == nil { + _ = again.Close() + } + if errorText(err) != tc.err || j.said("msg=listening") || taken != nil || s.calls != 0 { + t.Errorf("Serve() = %q, listened %t, port taken %v, stop calls %d, want %q with nothing bound or stopped", + errorText(err), j.said("msg=listening"), taken, s.calls, tc.err) + } + }) + } +} + func TestServeTakesThePortOfHTTPForAnEmptyAddress(t *testing.T) { t.Parallel() @@ -341,7 +821,7 @@ func TestServeGivesThePortBackBeforeItReturns(t *testing.T) { } } -func TestServeStopsWithinTheGraceWhenTheRunEndedBeforeTheListenFailed(t *testing.T) { +func TestServeStopsWithinTheStopGraceWhenTheRunEndedBeforeTheListenFailed(t *testing.T) { t.Parallel() taken, err := net.Listen("tcp", "127.0.0.1:0") @@ -355,8 +835,8 @@ func TestServeStopsWithinTheGraceWhenTheRunEndedBeforeTheListenFailed(t *testing _ = gonsole.Serve(ctx, gonsole.NewServer(taken.Addr().String(), reportNames(), defaults), defaults, s.stop, nil) - if s.calls != 1 || !s.live || s.deadline <= 0 || s.deadline > defaults.Grace { - t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the grace", + if !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace", s.calls, s.live, s.deadline) } } @@ -393,8 +873,8 @@ func TestServeReportsAnAddressItCannotTake(t *testing.T) { if !strings.HasSuffix(errorText(err), "\nthe reports plugin did not stop") { t.Errorf("Serve() = %v, want the stop error joined", err) } - if s.calls != 1 || !s.live || s.deadline <= 0 || s.deadline > defaults.Grace { - t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the grace", + if !s.ranOnceWithin(defaults.StopGrace) { + t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace", s.calls, s.live, s.deadline) } } @@ -411,7 +891,7 @@ func TestServeRunsWithoutAStop(t *testing.T) { cancel() - if err := <-done; err != nil { + if err := ended(t, done, defaults); err != nil { t.Errorf("Serve() = %v, want nil", err) } } @@ -464,7 +944,7 @@ func TestServeKeepsTheErrorLogTheServerAlreadyHas(t *testing.T) { _, _ = bufio.NewReader(connection).ReadString('\n') _ = connection.Close() cancel() - <-done + _ = ended(t, done, defaults) mu.Lock() defer mu.Unlock()