diff --git a/cmd/activator/main.go b/cmd/activator/main.go index 29d535403ef3..213ce6a7f99e 100644 --- a/cmd/activator/main.go +++ b/cmd/activator/main.go @@ -230,7 +230,7 @@ func main() { return apiconfig.DefaultRevisionTimeoutSeconds * time.Second, apiconfig.DefaultRevisionResponseStartTimeoutSeconds * time.Second, apiconfig.DefaultRevisionIdleTimeoutSeconds * time.Second - }) + }, logger) ah = concurrencyReporter.Handler(ah) ah = activatorhandler.NewTracingAttributeHandler(tp, ah) reqLogHandler, err := pkghttp.NewRequestLogHandler(ah, logging.NewSyncFileWriter(os.Stdout), "", diff --git a/pkg/http/handler/timeout.go b/pkg/http/handler/timeout.go index 441ed1eac4b1..1f84a91666cb 100644 --- a/pkg/http/handler/timeout.go +++ b/pkg/http/handler/timeout.go @@ -25,6 +25,7 @@ import ( "sync" "time" + "go.uber.org/zap" "k8s.io/utils/clock" "knative.dev/pkg/websocket" ) @@ -37,6 +38,7 @@ type timeoutHandler struct { timeoutFunc TimeoutFunc body string clock clock.Clock + logger *zap.SugaredLogger } // NewTimeoutHandler returns a Handler that runs `h` with the @@ -55,12 +57,13 @@ type timeoutHandler struct { // https://golang.org/pkg/net/http/#Handler. // // The implementation is largely inspired by http.TimeoutHandler. -func NewTimeoutHandler(h http.Handler, msg string, timeoutFunc TimeoutFunc) http.Handler { +func NewTimeoutHandler(h http.Handler, msg string, timeoutFunc TimeoutFunc, logger *zap.SugaredLogger) http.Handler { return &timeoutHandler{ handler: h, body: msg, timeoutFunc: timeoutFunc, clock: clock.RealClock{}, + logger: logger, } } @@ -128,12 +131,14 @@ func (h *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { case <-timeout.C(): timeoutDrained = true if tw.tryTimeoutAndWriteError(h.body) { + h.logger.Warnf("Request timeout: %v", revTimeout) return } case now := <-idleTimeoutCh: timedOut, timeToNextTimeout := tw.tryIdleTimeoutAndWriteError(now, revIdleTimeout, h.body) if timedOut { idleTimeoutDrained = true + h.logger.Warnf("Idle timeout: %v", revIdleTimeout) return } idleTimeout.Reset(timeToNextTimeout) @@ -143,6 +148,7 @@ func (h *timeoutHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { responseStartTimeoutDrained = true timedOut := tw.tryResponseStartTimeoutAndWriteError(h.body) if timedOut { + h.logger.Warnf("Response start timeout: %v", revResponseStartTimeout) return } } diff --git a/pkg/http/handler/timeout_test.go b/pkg/http/handler/timeout_test.go index 7a7e7722cfe0..393062088e37 100644 --- a/pkg/http/handler/timeout_test.go +++ b/pkg/http/handler/timeout_test.go @@ -25,6 +25,7 @@ import ( "testing" "time" + "go.uber.org/zap/zaptest" "k8s.io/utils/clock" clocktest "k8s.io/utils/clock/testing" ) @@ -223,6 +224,7 @@ func testTimeoutScenario(t *testing.T, scenarios []timeoutHandlerTestScenario) { body: scenario.timeoutMessage, timeoutFunc: StaticTimeoutFunc(scenario.timeout, scenario.responseStartTimeout, scenario.idleTimeout), clock: fakeClock, + logger: zaptest.NewLogger(t).Sugar(), } defer func() { @@ -350,7 +352,7 @@ func TestResponseStartTimeoutAfterResponseStarted(t *testing.T) { // Create timeout handler with a responseStartTimeout timeoutHandler := NewTimeoutHandler(handler, "timeout", - StaticTimeoutFunc(30*time.Second, 50*time.Millisecond, 0)) + StaticTimeoutFunc(30*time.Second, 50*time.Millisecond, 0), zaptest.NewLogger(t).Sugar()) req := httptest.NewRequest(http.MethodGet, "/", nil) rr := httptest.NewRecorder() @@ -604,7 +606,7 @@ func BenchmarkTimeoutHandler(b *testing.B) { w.Write(write) } }) - handler := NewTimeoutHandler(baseHandler, "test", StaticTimeoutFunc(10*time.Minute, 10*time.Minute, 10*time.Minute)) + handler := NewTimeoutHandler(baseHandler, "test", StaticTimeoutFunc(10*time.Minute, 10*time.Minute, 10*time.Minute), zaptest.NewLogger(b).Sugar()) req := httptest.NewRequest(http.MethodPost, "http://example.com", nil) b.Run("sequential", func(b *testing.B) { diff --git a/pkg/queue/sharedmain/handlers.go b/pkg/queue/sharedmain/handlers.go index 86a1694def04..1f2a425bcc98 100644 --- a/pkg/queue/sharedmain/handlers.go +++ b/pkg/queue/sharedmain/handlers.go @@ -76,7 +76,7 @@ func mainHandler( composedHandler = queue.ForwardedShimHandler(composedHandler) composedHandler = handler.NewTimeoutHandler(composedHandler, "request timeout", func(r *http.Request) (time.Duration, time.Duration, time.Duration) { return timeout, responseStartTimeout, idleTimeout - }) + }, logger) composedHandler = queue.NewRouteTagHandler(composedHandler) composedHandler = withFullDuplex(composedHandler, env.EnableHTTPFullDuplex, logger)