Add distinct logging for timeout types

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), "",

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

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

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)