From f0533986f88062f824e439c84cd7db41e8f1be62 Mon Sep 17 00:00:00 2001 From: tigerwill90 <26261762+tigerwill90@users.noreply.github.com> Date: Thu, 15 Oct 2026 00:19:08 +0200 Subject: [PATCH 1/2] fix: guard Push after timeout and sync with net/http TimeoutHandler --- timeout.go | 20 ++++++-- timeout_test.go | 130 ++++++++++++++++++++++++++++++++++-------------- writer.go | 9 +++- 3 files changed, 118 insertions(+), 41 deletions(-) diff --git a/timeout.go b/timeout.go index d43e0f2..49d254c 100644 --- a/timeout.go +++ b/timeout.go @@ -11,6 +11,7 @@ import ( "bytes" "context" "fmt" + "log" "maps" "net/http" "runtime" @@ -159,9 +160,10 @@ func relevantCaller() runtime.Frame { frames := runtime.CallersFrames(pc[:n]) var frame runtime.Frame for { - f, more := frames.Next() - if !strings.HasPrefix(f.Function, "github.com/fox-toolkit/timeout.") { - return f + var more bool + frame, more = frames.Next() + if !strings.HasPrefix(frame.Function, "github.com/fox-toolkit/timeout.") { + return frame } if !more { break @@ -169,3 +171,15 @@ func relevantCaller() runtime.Frame { } return frame } + +// logf prints to the ErrorLog of the *http.Server associated with request r +// via http.ServerContextKey. If there's no associated server, or if ErrorLog +// is nil, logging is done via the log package's standard logger. +func logf(r *http.Request, format string, args ...any) { + s, _ := r.Context().Value(http.ServerContextKey).(*http.Server) + if s != nil && s.ErrorLog != nil { + s.ErrorLog.Printf(format, args...) + } else { + log.Printf(format, args...) + } +} diff --git a/timeout_test.go b/timeout_test.go index 88c9960..721864d 100644 --- a/timeout_test.go +++ b/timeout_test.go @@ -6,13 +6,16 @@ package timeout import ( "bytes" + "context" "fmt" "io" + "log" "log/slog" "net" "net/http" "net/http/httptest" "testing" + "testing/synctest" "time" "github.com/fox-toolkit/fox" @@ -26,29 +29,36 @@ func success201response(c *fox.Context) { } func TestMiddleware_WithTimeout(t *testing.T) { - f, err := fox.NewRouter(fox.WithMiddleware(Middleware(50 * time.Microsecond))) - require.NoError(t, err) - f.MustAdd(fox.MethodGet, "/foo", success201response) + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(50 * time.Microsecond))) + require.NoError(t, err) + f.MustAdd(fox.MethodGet, "/foo", success201response) - req := httptest.NewRequest(http.MethodGet, "/foo", nil) - w := httptest.NewRecorder() - f.ServeHTTP(w, req) + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) + + assert.Equal(t, http.StatusServiceUnavailable, w.Code) + assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusServiceUnavailable)), w.Body.String()) - assert.Equal(t, http.StatusServiceUnavailable, w.Code) - assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusServiceUnavailable)), w.Body.String()) + // Let the handler goroutine, which outlives the middleware after a timeout, finish. + time.Sleep(10 * time.Millisecond) + }) } func TestMiddleware_WithoutTimeout(t *testing.T) { - f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Second))) - require.NoError(t, err) - f.MustAdd(fox.MethodGet, "/foo", success201response) + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Second))) + require.NoError(t, err) + f.MustAdd(fox.MethodGet, "/foo", success201response) - req := httptest.NewRequest(http.MethodGet, "/foo", nil) - w := httptest.NewRecorder() - f.ServeHTTP(w, req) + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) - assert.Equal(t, http.StatusCreated, w.Code) - assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + assert.Equal(t, http.StatusCreated, w.Code) + assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + }) } func timeoutResponse(c *fox.Context) { @@ -56,16 +66,21 @@ func timeoutResponse(c *fox.Context) { } func TestMiddleware_WithResponse(t *testing.T) { - f, err := fox.NewRouter(fox.WithMiddleware(Middleware(50*time.Microsecond, WithResponse(timeoutResponse)))) - require.NoError(t, err) - f.MustAdd(fox.MethodGet, "/foo", success201response) + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(50*time.Microsecond, WithResponse(timeoutResponse)))) + require.NoError(t, err) + f.MustAdd(fox.MethodGet, "/foo", success201response) - req := httptest.NewRequest(http.MethodGet, "/foo", nil) - w := httptest.NewRecorder() - f.ServeHTTP(w, req) + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) - assert.Equal(t, http.StatusRequestTimeout, w.Code) - assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusRequestTimeout)), w.Body.String()) + assert.Equal(t, http.StatusRequestTimeout, w.Code) + assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusRequestTimeout)), w.Body.String()) + + // Let the handler goroutine, which outlives the middleware after a timeout, finish. + time.Sleep(10 * time.Millisecond) + }) } func panicResponse(c *fox.Context) { @@ -123,30 +138,73 @@ func TestMiddleware_ErrNotSupported(t *testing.T) { f.ServeHTTP(w, req) } -func TestMiddleware_WithHandlerTimeout(t *testing.T) { - f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Millisecond))) +func TestMiddleware_PushAfterTimeout(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(10 * time.Millisecond))) + require.NoError(t, err) + + pushErr := make(chan error, 1) + f.MustAdd(fox.MethodGet, "/foo", func(c *fox.Context) { + time.Sleep(20 * time.Millisecond) + pushErr <- c.Writer().Push("/style.css", nil) + }) + + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) + + assert.Equal(t, http.StatusServiceUnavailable, w.Code) + assert.ErrorIs(t, <-pushErr, http.ErrHandlerTimeout) + }) +} + +func TestMiddleware_SuperfluousWriteHeaderUsesServerErrorLog(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Second))) require.NoError(t, err) - f.MustAdd(fox.MethodGet, "/foo", success201response, OverrideHandler(2*time.Second)) + f.MustAdd(fox.MethodGet, "/foo", func(c *fox.Context) { + c.Writer().WriteHeader(http.StatusCreated) + c.Writer().WriteHeader(http.StatusAccepted) + }) + buf := new(bytes.Buffer) + srv := &http.Server{ErrorLog: log.New(buf, "", 0)} req := httptest.NewRequest(http.MethodGet, "/foo", nil) + req = req.WithContext(context.WithValue(req.Context(), http.ServerContextKey, srv)) w := httptest.NewRecorder() f.ServeHTTP(w, req) assert.Equal(t, http.StatusCreated, w.Code) - assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + assert.Contains(t, buf.String(), "http: superfluous response.WriteHeader call") +} + +func TestMiddleware_WithHandlerTimeout(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Millisecond))) + require.NoError(t, err) + f.MustAdd(fox.MethodGet, "/foo", success201response, OverrideHandler(2*time.Second)) + + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) + + assert.Equal(t, http.StatusCreated, w.Code) + assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + }) } func TestMiddleware_WithDisableTimeout(t *testing.T) { - f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Millisecond))) - require.NoError(t, err) - f.MustAdd(fox.MethodGet, "/foo", success201response, OverrideHandler(None)) + synctest.Test(t, func(t *testing.T) { + f, err := fox.NewRouter(fox.WithMiddleware(Middleware(1 * time.Millisecond))) + require.NoError(t, err) + f.MustAdd(fox.MethodGet, "/foo", success201response, OverrideHandler(None)) - req := httptest.NewRequest(http.MethodGet, "/foo", nil) - w := httptest.NewRecorder() - f.ServeHTTP(w, req) + req := httptest.NewRequest(http.MethodGet, "/foo", nil) + w := httptest.NewRecorder() + f.ServeHTTP(w, req) - assert.Equal(t, http.StatusCreated, w.Code) - assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + assert.Equal(t, http.StatusCreated, w.Code) + assert.Equal(t, fmt.Sprintf("%s\n", http.StatusText(http.StatusCreated)), w.Body.String()) + }) } func TestMiddleware_WithReadTimeout(t *testing.T) { diff --git a/writer.go b/writer.go index 80480a3..08aface 100644 --- a/writer.go +++ b/writer.go @@ -11,7 +11,6 @@ import ( "bufio" "bytes" "io" - "log" "net" "net/http" "path" @@ -74,6 +73,12 @@ func (tw *timeoutWriter) WriteString(s string) (int, error) { } func (tw *timeoutWriter) Push(target string, opts *http.PushOptions) error { + tw.mu.Lock() + defer tw.mu.Unlock() + // After a timeout, the underlying writer may already belong to another request. + if tw.err != nil { + return tw.err + } return tw.w.Push(target, opts) } @@ -103,7 +108,7 @@ func (tw *timeoutWriter) writeHeaderLocked(code int) { return case tw.written: caller := relevantCaller() - log.Printf("http: superfluous response.WriteHeader call from %s (%s:%d)", caller.Function, path.Base(caller.File), caller.Line) + logf(tw.req, "http: superfluous response.WriteHeader call from %s (%s:%d)", caller.Function, path.Base(caller.File), caller.Line) default: tw.written = true tw.code = code From 4d159e53920018a58ab657189d7d36707f7efb2b Mon Sep 17 00:00:00 2001 From: tigerwill90 <26261762+tigerwill90@users.noreply.github.com> Date: Thu, 15 Oct 2026 00:22:02 +0200 Subject: [PATCH 2/2] chore: remove redundant logf comment --- timeout.go | 3 --- 1 file changed, 3 deletions(-) diff --git a/timeout.go b/timeout.go index 49d254c..4d40a3f 100644 --- a/timeout.go +++ b/timeout.go @@ -172,9 +172,6 @@ func relevantCaller() runtime.Frame { return frame } -// logf prints to the ErrorLog of the *http.Server associated with request r -// via http.ServerContextKey. If there's no associated server, or if ErrorLog -// is nil, logging is done via the log package's standard logger. func logf(r *http.Request, format string, args ...any) { s, _ := r.Context().Value(http.ServerContextKey).(*http.Server) if s != nil && s.ErrorLog != nil {