From fd70457814b7273e24aa7d8feb2f4ae65058c2f9 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 16:39:51 +0200 Subject: [PATCH 01/13] fix(gonsole): give stop a grace of its own --- gonsole/serve.go | 28 +++++++++++++++-------- gonsole/serve_test.go | 53 ++++++++++++++++++++++++++++++++----------- 2 files changed, 58 insertions(+), 23 deletions(-) diff --git a/gonsole/serve.go b/gonsole/serve.go index 26d1e8d..49692e4 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -13,7 +13,7 @@ import ( "time" ) -// Timeouts are the HTTP timeouts and the shutdown grace one server runs under. +// 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 +21,21 @@ 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 + // 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 [5]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.StopGrace, failed[4] = e.Duration("SHUTDOWN_STOP_GRACE", fallback.StopGrace) if err := errors.Join(failed[:]...); err != nil { return Timeouts{}, err } @@ -46,20 +49,18 @@ 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 shuts it down and calls stop, each within its own grace. func Serve( ctx context.Context, srv *http.Server, t Timeouts, stop func(context.Context) error, logger *slog.Logger, ) error { 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. +// serveOn serves srv on listener until ctx ends or serving fails, then shuts it down and calls stop, each in its grace. func serveOn( ctx context.Context, srv *http.Server, listener net.Listener, t Timeouts, stop func(context.Context) error, logger *slog.Logger, @@ -84,7 +85,14 @@ func serveOn( if failed == nil { <-served } - return errors.Join(failed, shut, optional(grace, stop)) + return errors.Join(failed, shut, stopWithin(ctx, t, stop)) +} + +// 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_test.go b/gonsole/serve_test.go index 1255247..b78f2e6 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -23,6 +23,7 @@ import ( // 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, + StopGrace: 10 * time.Second, } func TestEnvReadsTheTimeouts(t *testing.T) { @@ -37,16 +38,17 @@ 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", }, gonsole.Timeouts{ReadHeader: 2 * time.Second, Read: 5 * time.Second, Idle: time.Minute, - Grace: 3 * time.Second}, ""}, + Grace: 3 * 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", }, 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_STOP_GRACE: must be a duration like 30s, got "never"`}, } for _, tc := range cases { t.Run(tc.name, func(t *testing.T) { @@ -146,6 +148,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) { @@ -215,8 +224,25 @@ func TestServeAnswersUntilTheRunEnds(t *testing.T) { if !j.said("msg=\"shutting down\"") { t.Errorf("log = %q, want a shutting down line", 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 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) } } @@ -241,8 +267,9 @@ func TestServeGivesUpOnARequestThatOutlastsTheGrace(t *testing.T) { if !errors.Is(err, context.DeadlineExceeded) { t.Errorf("Serve() = %v, want the grace to run out", err) } - if s.calls != 1 { - t.Errorf("stop calls = %d, want 1", s.calls) + 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) } } @@ -341,7 +368,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 +382,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 +420,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) } } From 95bc22f4607db25d2e5db53fff29d8d29549225d Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 17:33:21 +0200 Subject: [PATCH 02/13] fix(gonsole): cancel the requests still running when the grace ends --- gonsole/serve.go | 103 ++++++++++++++-- gonsole/serve_internal_test.go | 124 +++++++++++++++++++ gonsole/serve_test.go | 216 ++++++++++++++++++++++++++++++--- 3 files changed, 417 insertions(+), 26 deletions(-) diff --git a/gonsole/serve.go b/gonsole/serve.go index 49692e4..8995fa0 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -10,9 +10,13 @@ import ( "log/slog" "net" "net/http" + "sync" "time" ) +// 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") + // 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. @@ -23,6 +27,8 @@ type Timeouts struct { Idle time.Duration // 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 } @@ -30,12 +36,13 @@ type Timeouts struct { // 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 [5]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.StopGrace, failed[4] = e.Duration("SHUTDOWN_STOP_GRACE", fallback.StopGrace) + 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 } @@ -49,7 +56,7 @@ 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, each within its own 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 { @@ -60,7 +67,7 @@ func Serve( 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, each in its grace. +// 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, @@ -69,6 +76,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()) @@ -79,13 +87,92 @@ func serveOn( case <-ctx.Done(): logger.Info("shutting down") } - grace, cancel := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) - defer cancel() - shut := srv.Shutdown(grace) + drain(ctx, srv, requests, t, logger) if failed == nil { <-served } - return errors.Join(failed, shut, stopWithin(ctx, t, stop)) + return errors.Join(failed, stopWithin(ctx, t, stop)) +} + +// track points the requests of srv at a base context the end of ctx cannot cancel and counts them while they run. +func track(ctx context.Context, srv *http.Server) *inflight { + base, cancel := context.WithCancelCause(context.WithoutCancel(ctx)) + requests := &inflight{cancel: cancel} + srv.BaseContext = func(net.Listener) context.Context { return base } + srv.Handler = requests.wrap(cmp.Or[http.Handler](srv.Handler, http.DefaultServeMux)) + return requests +} + +// drain shuts srv down within the grace, then cancels what still runs and waits for it within the cancel grace. +func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts, logger *slog.Logger) { + grace, endGrace := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) + defer endGrace() + _ = srv.Shutdown(grace) + 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() + requests.settle(cancelGrace) +} + +// 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. diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index b332063..f4c1be6 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -10,6 +10,7 @@ import ( "net" "net/http" "strings" + "sync" "sync/atomic" "testing" "time" @@ -78,6 +79,129 @@ 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 := <-done + + 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") + } +} + +// 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) + } +} + // 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 b78f2e6..a0e4d1e 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -23,7 +23,7 @@ import ( // 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, - StopGrace: 10 * time.Second, + CancelGrace: 5 * time.Second, StopGrace: 10 * time.Second, } func TestEnvReadsTheTimeouts(t *testing.T) { @@ -39,15 +39,18 @@ func TestEnvReadsTheTimeouts(t *testing.T) { {"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_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, StopGrace: 6 * 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_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_CANCEL_GRACE: must stand above zero, got "0s" MYAPP_SHUTDOWN_STOP_GRACE: must be a duration like 30s, got "never"`}, } for _, tc := range cases { @@ -85,19 +88,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() @@ -107,9 +112,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() @@ -221,8 +237,8 @@ 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.ranOnceWithin(defaults.StopGrace) { t.Errorf("stop calls = %d, live %t, deadline in %v, want one live call within the stop grace", @@ -247,29 +263,193 @@ func TestServeGivesStopItsOwnGrace(t *testing.T) { } } -func TestServeGivesUpOnARequestThatOutlastsTheGrace(t *testing.T) { +func TestServeCancelsARequestThatOutlastsTheGrace(t *testing.T) { t.Parallel() - release := make(chan struct{}) - defer close(release) arrived := make(chan struct{}) - slow := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + causes := make(chan error, 1) + waiting := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { close(arrived) - <-release + <-r.Context().Done() + causes <- context.Cause(r.Context()) }) var s stopper - address, end := serving(t, slow, 50*time.Millisecond, s.stop, newJournal()) + endedFirst := false + stop := func(ctx context.Context) error { + endedFirst = len(causes) == 1 + return s.stop(ctx) + } + j := newJournal() + address, end := serving(t, waiting, 50*time.Millisecond, stop, j) go func() { _, _ = http.Get("http://" + address + "/") }() <-arrived err := end() - if !errors.Is(err, context.DeadlineExceeded) { - t.Errorf("Serve() = %v, want the grace to run out", err) + if err != nil { + t.Errorf("Serve() = %v, want nil once the cancelled request ended", err) } - 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) + select { + case cause := <-causes: + if !errors.Is(cause, gonsole.ErrGraceRanOut) { + t.Errorf("cause = %v, want the grace to have run out", cause) + } + 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() + + for range deliveries { + 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() { answered <- status(address) }() + <-arrived + + err := end() + + if code := <-answered; err != nil || code != http.StatusServiceUnavailable { + t.Fatalf("Serve() = %v, answer %d, want nil and the cancelled request's own 503", err, code) + } + } +} + +// deliveries is how many cancelled requests the delivery test serves, enough to catch a response lost now and then. +const deliveries = 40 + +// 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, zero when none came. +func status(address string) int { + response, err := patient.Get("http://" + address + "/") + if err != nil { + return 0 + } + _ = response.Body.Close() + return response.StatusCode +} + +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 := status(address); code != 0 { + t.Errorf("GET answered %d, want the aborted request's connection closed", code) + } + + err := end() + + if err != nil || j.said("level=WARN") { + t.Errorf("Serve() = %v, log %q, want nil and no request left to cancel", err, j.lines) + } +} + +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) } } From 4e4ff8ca9c179db8c940b403bc75134f02543627 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 17:49:20 +0200 Subject: [PATCH 03/13] fix(gonsole): close the requests that outlive the cancel grace --- gonsole/serve.go | 19 ++++++--- gonsole/serve_test.go | 96 +++++++++++++++++++++++++++++++++++++++---- 2 files changed, 102 insertions(+), 13 deletions(-) diff --git a/gonsole/serve.go b/gonsole/serve.go index 8995fa0..ab7b727 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -17,6 +17,9 @@ import ( // 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. @@ -87,11 +90,11 @@ func serveOn( case <-ctx.Done(): logger.Info("shutting down") } - drain(ctx, srv, requests, t, logger) + still := drain(ctx, srv, requests, t, logger) if failed == nil { <-served } - return errors.Join(failed, stopWithin(ctx, t, stop)) + return errors.Join(failed, still, stopWithin(ctx, t, stop)) } // track points the requests of srv at a base context the end of ctx cannot cancel and counts them while they run. @@ -103,8 +106,8 @@ func track(ctx context.Context, srv *http.Server) *inflight { return requests } -// drain shuts srv down within the grace, then cancels what still runs and waits for it within the cancel grace. -func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts, logger *slog.Logger) { +// 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 { grace, endGrace := context.WithTimeout(context.WithoutCancel(ctx), t.Grace) defer endGrace() _ = srv.Shutdown(grace) @@ -114,7 +117,13 @@ func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts requests.cancel(ErrGraceRanOut) cancelGrace, endCancelGrace := context.WithTimeout(context.WithoutCancel(ctx), t.CancelGrace) defer endCancelGrace() - requests.settle(cancelGrace) + _ = srv.Shutdown(cancelGrace) + running := requests.settle(cancelGrace) + _ = srv.Close() + if running > 0 { + return ErrStillServing + } + return nil } // inflight counts the requests one server is handling and cancels them together. diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index a0e4d1e..f2b85c5 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -202,9 +202,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()) }() @@ -396,7 +404,10 @@ func TestServeDeliversTheCancelledRequestsOwnResponse(t *testing.T) { }) address, end := serving(t, unavailable, 10*time.Millisecond, nil, newJournal()) answered := make(chan int, 1) - go func() { answered <- status(address) }() + go func() { + code, _ := status(address) + answered <- code + }() <-arrived err := end() @@ -413,14 +424,83 @@ const deliveries = 40 // 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, zero when none came. -func status(address string) int { +// 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 + return 0, err } _ = response.Body.Close() - return response.StatusCode + return response.StatusCode, nil +} + +func TestServeClosesARequestThatIgnoresTheCancel(t *testing.T) { + t.Parallel() + + release := make(chan struct{}) + defer close(release) + arrived := make(chan struct{}) + stubborn := http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + close(arrived) + <-release + }) + var s stopper + 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 := <-done + + _ = 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) + } } func TestServeCountsDownARequestThatAborts(t *testing.T) { @@ -429,7 +509,7 @@ func TestServeCountsDownARequestThatAborts(t *testing.T) { 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 := status(address); code != 0 { + if code, err := status(address); err == nil { t.Errorf("GET answered %d, want the aborted request's connection closed", code) } @@ -445,7 +525,7 @@ func TestServeAnswersThroughTheDefaultMuxWhenTheServerHasNoHandler(t *testing.T) address, end := serving(t, nil, time.Minute, nil, newJournal()) - code := status(address) + code, _ := status(address) err := end() if code != http.StatusNotFound || err != nil { From 8bc988476a2ecc8f648c8261a543335c8c5303d0 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 18:00:57 +0200 Subject: [PATCH 04/13] fix(gonsole): refuse a shutdown grace that is not above zero --- gonsole/internal/exampleapp/program.go | 1 + gonsole/serve.go | 18 ++++++++++ gonsole/serve_internal_test.go | 7 ++-- gonsole/serve_test.go | 46 ++++++++++++++++++++++++++ 4 files changed, 69 insertions(+), 3 deletions(-) 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 ab7b727..854ab52 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -63,6 +63,9 @@ func NewServer(addr string, handler http.Handler, t Timeouts) *http.Server { 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 { return errors.Join(fmt.Errorf("http server: %w", err), stopWithin(ctx, t, stop)) @@ -70,6 +73,21 @@ func Serve( return serveOn(ctx, srv, listener, t, stop, logger) } +// 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, diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index f4c1be6..280c7ee 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -48,7 +48,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) @@ -68,8 +69,8 @@ func TestServeShutsTheServerDownBeforeItStopsWhenServingFails(t *testing.T) { served := <-done _, 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()) diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index f2b85c5..43dc76e 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -18,6 +18,7 @@ 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. @@ -574,6 +575,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() From 7d27d7ca6740621513c9831d5683f8ffe01d6162 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 18:45:21 +0200 Subject: [PATCH 05/13] test(gonsole): pin that no request starts once the shutdown began --- gonsole/serve_test.go | 44 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 43dc76e..7ba0ca6 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -504,6 +504,50 @@ func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { } } +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 := <-done; err != nil { + t.Errorf("Serve() = %v, want nil", err) + } +} + func TestServeCountsDownARequestThatAborts(t *testing.T) { t.Parallel() From d8704e28b36f304051a3e80156feb83f31e60b50 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 18:45:21 +0200 Subject: [PATCH 06/13] fix(gonsole): shut the server down once so each shutdown hook runs once --- gonsole/serve.go | 19 ++++++- gonsole/serve_internal_test.go | 90 ++++++++++++++++++++++++++++++++++ 2 files changed, 107 insertions(+), 2 deletions(-) diff --git a/gonsole/serve.go b/gonsole/serve.go index 854ab52..463dc8a 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -126,17 +126,24 @@ func track(ctx context.Context, srv *http.Server) *inflight { // 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() - _ = srv.Shutdown(grace) 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() - _ = srv.Shutdown(cancelGrace) + await(cancelGrace, shut) running := requests.settle(cancelGrace) + stopShutting() + <-shut _ = srv.Close() if running > 0 { return ErrStillServing @@ -144,6 +151,14 @@ func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts return nil } +// 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 diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index 280c7ee..c8b00a6 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -13,6 +13,7 @@ import ( "sync" "sync/atomic" "testing" + "testing/synctest" "time" ) @@ -126,6 +127,95 @@ func TestServeCancelsBeforeItStopsWhenServingFails(t *testing.T) { } } +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 := <-done + + 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) + } +} + // watched is a context that says when its Done channel is first asked for. type watched struct { context.Context From ce054e457794cb8d5144f017c56694c6134717cb Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 18:45:22 +0200 Subject: [PATCH 07/13] docs(gonsole): record the shutdown changes under Unreleased --- gonsole/CHANGELOG.md | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/gonsole/CHANGELOG.md b/gonsole/CHANGELOG.md index 7e69c1d..aa62ca4 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 and returns `ErrStillServing`. A hijacked connection stays open. +- `Serve` sets `BaseContext` and wraps `Handler` on the server it runs. +- `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 From 687ac1bb7702a5cbfdd498096381867d78fa8450 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 20:06:13 +0200 Subject: [PATCH 08/13] test(gonsole): bound when the cancel comes and when Serve returns --- gonsole/serve_test.go | 40 +++++++++++++++++++++++++++++++++------- 1 file changed, 33 insertions(+), 7 deletions(-) diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 7ba0ca6..7b44043 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -221,7 +221,7 @@ func servingUnder( case address := <-j.listening: return address, func() error { cancel() - return <-done + return ended(t, done, timeouts) } case err := <-done: cancel() @@ -230,6 +230,25 @@ func servingUnder( 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() @@ -275,11 +294,15 @@ func TestServeGivesStopItsOwnGrace(t *testing.T) { 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 @@ -288,8 +311,7 @@ func TestServeCancelsARequestThatOutlastsTheGrace(t *testing.T) { endedFirst = len(causes) == 1 return s.stop(ctx) } - j := newJournal() - address, end := serving(t, waiting, 50*time.Millisecond, stop, j) + address, end := serving(t, waiting, grace, stop, j) go func() { _, _ = http.Get("http://" + address + "/") }() <-arrived @@ -303,6 +325,10 @@ func TestServeCancelsARequestThatOutlastsTheGrace(t *testing.T) { 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") } @@ -495,7 +521,7 @@ func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { <-accepted cancel() - served := <-done + served := ended(t, done, timeouts) _ = silent.SetReadDeadline(time.Now().Add(5 * time.Second)) _, read := silent.Read(make([]byte, 1)) @@ -543,7 +569,7 @@ func TestServeStartsNoRequestThatArrivesOnceTheShutdownBegan(t *testing.T) { 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 := <-done; err != nil { + if err := ended(t, done, defaults); err != nil { t.Errorf("Serve() = %v, want nil", err) } } @@ -788,7 +814,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) } } @@ -841,7 +867,7 @@ func TestServeKeepsTheErrorLogTheServerAlreadyHas(t *testing.T) { _, _ = bufio.NewReader(connection).ReadString('\n') _ = connection.Close() cancel() - <-done + _ = ended(t, done, defaults) mu.Lock() defer mu.Unlock() From 3febca0dbdc7e6a049da70928be560f9406cf29d Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 20:16:01 +0200 Subject: [PATCH 09/13] test(gonsole): deliver one cancelled response per run of the delivery test --- gonsole/serve_test.go | 41 ++++++++++++++++++----------------------- 1 file changed, 18 insertions(+), 23 deletions(-) diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 7b44043..17b1d6e 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -422,32 +422,27 @@ func TestServeWaitsForAHijackedConnectionBeforeItStops(t *testing.T) { func TestServeDeliversTheCancelledRequestsOwnResponse(t *testing.T) { t.Parallel() - for range deliveries { - 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.Fatalf("Serve() = %v, answer %d, want nil and the cancelled request's own 503", err, code) - } + 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) } } -// deliveries is how many cancelled requests the delivery test serves, enough to catch a response lost now and then. -const deliveries = 40 - // 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} From 1a54f2f8c06bff9c1e1a68a1006acc328f9d9159 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 21:13:58 +0200 Subject: [PATCH 10/13] fix(gonsole): keep connections through the grace before the cancel --- gonsole/serve.go | 1 + gonsole/serve_test.go | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 36 insertions(+) diff --git a/gonsole/serve.go b/gonsole/serve.go index 463dc8a..0c404ba 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -134,6 +134,7 @@ func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts }() 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) } diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 17b1d6e..39fba6d 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -525,6 +525,41 @@ func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { } } +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() From 579f306463bc1af45cbc158414a5b97ec8212962 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 21:23:08 +0200 Subject: [PATCH 11/13] fix(gonsole): keep the values of the server's own base context --- gonsole/CHANGELOG.md | 2 +- gonsole/serve.go | 17 +++++++++++++++-- gonsole/serve_test.go | 44 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 60 insertions(+), 3 deletions(-) diff --git a/gonsole/CHANGELOG.md b/gonsole/CHANGELOG.md index aa62ca4..3db6d06 100644 --- a/gonsole/CHANGELOG.md +++ b/gonsole/CHANGELOG.md @@ -19,7 +19,7 @@ Releases of this module are tagged `gonsole/vX.Y.Z`. - `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 and returns `ErrStillServing`. A hijacked connection stays open. -- `Serve` sets `BaseContext` and wraps `Handler` on the server it runs. +- `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. diff --git a/gonsole/serve.go b/gonsole/serve.go index 0c404ba..6247827 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -115,15 +115,28 @@ func serveOn( return errors.Join(failed, still, stopWithin(ctx, t, stop)) } -// track points the requests of srv at a base context the end of ctx cannot cancel and counts them while they run. +// 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} - srv.BaseContext = func(net.Listener) context.Context { return base } + 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)) diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 39fba6d..31dbe8b 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -525,6 +525,50 @@ func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { } } +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() From 7ba2f3f136cfceda6b8d4daf29431d6eb2467e75 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 21:27:43 +0200 Subject: [PATCH 12/13] fix(gonsole): warn when the cancel grace closes connections still open --- gonsole/CHANGELOG.md | 2 +- gonsole/serve.go | 13 +++++++++++ gonsole/serve_internal_test.go | 42 ++++++++++++++++++++++++++++++++++ gonsole/serve_test.go | 3 +++ 4 files changed, 59 insertions(+), 1 deletion(-) diff --git a/gonsole/CHANGELOG.md b/gonsole/CHANGELOG.md index 3db6d06..3c051dc 100644 --- a/gonsole/CHANGELOG.md +++ b/gonsole/CHANGELOG.md @@ -18,7 +18,7 @@ Releases of this module are tagged `gonsole/vX.Y.Z`. ### 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 and returns `ErrStillServing`. A hijacked connection stays open. +- `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. diff --git a/gonsole/serve.go b/gonsole/serve.go index 6247827..c0ec877 100644 --- a/gonsole/serve.go +++ b/gonsole/serve.go @@ -156,6 +156,9 @@ func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts 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() @@ -165,6 +168,16 @@ func drain(ctx context.Context, srv *http.Server, requests *inflight, t Timeouts 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 { diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index c8b00a6..0342f0f 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -216,6 +216,48 @@ func TestServeDeliversACancelledResponseOverASlowConnection(t *testing.T) { } } +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 := <-done + + 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 diff --git a/gonsole/serve_test.go b/gonsole/serve_test.go index 31dbe8b..9dc7203 100644 --- a/gonsole/serve_test.go +++ b/gonsole/serve_test.go @@ -523,6 +523,9 @@ func TestServeClosesAConnectionThatNeverSentARequest(t *testing.T) { 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) { From b79de4fb2f4aee05898d3992da57dcc46d9d3229 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 25 Sep 2026 21:48:39 +0200 Subject: [PATCH 13/13] test(gonsole): bound every wait for serveOn in the internal tests --- gonsole/serve_internal_test.go | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-) diff --git a/gonsole/serve_internal_test.go b/gonsole/serve_internal_test.go index 0342f0f..ebe9e59 100644 --- a/gonsole/serve_internal_test.go +++ b/gonsole/serve_internal_test.go @@ -67,7 +67,7 @@ func TestServeShutsTheServerDownBeforeItStopsWhenServingFails(t *testing.T) { fetch(t, client, address) close(listener.broken) - served := <-done + served := ended(t, done, timeouts) _, second := client.Get(address) if errorLine(served) != "http server: the listener broke" { @@ -111,7 +111,7 @@ func TestServeCancelsBeforeItStopsWhenServingFails(t *testing.T) { <-arrived close(listener.broken) - served := <-done + 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", @@ -209,7 +209,7 @@ func TestServeDeliversACancelledResponseOverASlowConnection(t *testing.T) { <-arrived cancel() - served := <-done + 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) @@ -248,7 +248,7 @@ func TestServeWarnsWhenTheCancelGraceCutsAResponseStillBeingWritten(t *testing.T <-arrived cancel() - served := <-done + 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) @@ -335,6 +335,22 @@ func TestSettleCountsTheRequestsStillRunningWhenItsContextEnds(t *testing.T) { } } +// 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()