diff --git a/pkg/kubelet/server/portforward/websocket.go b/pkg/kubelet/server/portforward/websocket.go index e6aa7897175..c2895658f89 100644 --- a/pkg/kubelet/server/portforward/websocket.go +++ b/pkg/kubelet/server/portforward/websocket.go @@ -113,7 +113,7 @@ func handleWebSocketStreams(req *http.Request, w http.ResponseWriter, portForwar }, }) conn.SetIdleTimeout(idleTimeout) - _, streams, err := conn.Open(httplog.Unlogged(w), req) + _, streams, err := conn.Open(httplog.Unlogged(req, w), req) if err != nil { err = fmt.Errorf("Unable to upgrade websocket connection: %v", err) return err diff --git a/pkg/kubelet/server/remotecommand/websocket.go b/pkg/kubelet/server/remotecommand/websocket.go index c60012b21f2..87cd012318f 100644 --- a/pkg/kubelet/server/remotecommand/websocket.go +++ b/pkg/kubelet/server/remotecommand/websocket.go @@ -95,7 +95,7 @@ func createWebSocketStreams(req *http.Request, w http.ResponseWriter, opts *Opti }, }) conn.SetIdleTimeout(idleTimeout) - negotiatedProtocol, streams, err := conn.Open(httplog.Unlogged(w), req) + negotiatedProtocol, streams, err := conn.Open(httplog.Unlogged(req, w), req) if err != nil { runtime.HandleError(fmt.Errorf("Unable to upgrade websocket connection: %v", err)) return nil, false diff --git a/pkg/kubelet/server/server.go b/pkg/kubelet/server/server.go index 74003b9ab64..aca56886189 100644 --- a/pkg/kubelet/server/server.go +++ b/pkg/kubelet/server/server.go @@ -856,7 +856,7 @@ var statusesNoTracePred = httplog.StatusIsNot( // ServeHTTP responds to HTTP requests on the Kubelet. func (s *Server) ServeHTTP(w http.ResponseWriter, req *http.Request) { - defer httplog.NewLogged(req, &w).StacktraceWhen(statusesNoTracePred).Log() + handler := httplog.WithLogging(s.restfulCont, statusesNoTracePred) // monitor http requests var serverType string @@ -878,7 +878,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, req *http.Request) { startTime := time.Now() defer servermetrics.HTTPRequestsDuration.WithLabelValues(method, path, serverType, longRunning).Observe(servermetrics.SinceInSeconds(startTime)) - s.restfulCont.ServeHTTP(w, req) + handler.ServeHTTP(w, req) } // prometheusHostAdapter adapts the HostInterface to the interface expected by the diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go index 3603350fec3..5aa9272a3a1 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/watch.go @@ -165,7 +165,7 @@ func (s *WatchServer) ServeHTTP(w http.ResponseWriter, req *http.Request) { metrics.RegisteredWatchers.WithLabelValues(kind.Group, kind.Version, kind.Kind).Inc() defer metrics.RegisteredWatchers.WithLabelValues(kind.Group, kind.Version, kind.Kind).Dec() - w = httplog.Unlogged(w) + w = httplog.Unlogged(req, w) if wsstream.IsWebSocketRequest(req) { w.Header().Set("Content-Type", s.MediaType) diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go index 0a75845611d..d99308861c8 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go @@ -34,14 +34,12 @@ func WithPanicRecovery(handler http.Handler) http.Handler { } func withPanicRecovery(handler http.Handler, crashHandler func(http.ResponseWriter, *http.Request, interface{})) http.Handler { + handler = httplog.WithLogging(handler, httplog.DefaultStacktracePred) return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { defer runtime.HandleCrash(func(err interface{}) { crashHandler(w, req, err) }) - logger := httplog.NewLogged(req, &w) - defer logger.Log() - // Dispatch to the internal handler handler.ServeHTTP(w, req) }) diff --git a/staging/src/k8s.io/apiserver/pkg/server/healthz/BUILD b/staging/src/k8s.io/apiserver/pkg/server/healthz/BUILD index 7907d0e6111..64ffaa25d13 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/healthz/BUILD +++ b/staging/src/k8s.io/apiserver/pkg/server/healthz/BUILD @@ -26,6 +26,7 @@ go_library( deps = [ "//staging/src/k8s.io/apimachinery/pkg/util/sets:go_default_library", "//staging/src/k8s.io/apimachinery/pkg/util/wait:go_default_library", + "//staging/src/k8s.io/apiserver/pkg/server/httplog:go_default_library", "//vendor/k8s.io/klog:go_default_library", ], ) diff --git a/staging/src/k8s.io/apiserver/pkg/server/healthz/healthz.go b/staging/src/k8s.io/apiserver/pkg/server/healthz/healthz.go index 81d2bccb4ed..c7f8686c460 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/healthz/healthz.go +++ b/staging/src/k8s.io/apiserver/pkg/server/healthz/healthz.go @@ -25,10 +25,10 @@ import ( "sync/atomic" "time" - "k8s.io/klog" - "k8s.io/apimachinery/pkg/util/sets" "k8s.io/apimachinery/pkg/util/wait" + "k8s.io/apiserver/pkg/server/httplog" + "k8s.io/klog" ) // HealthzChecker is a named healthz checker. @@ -181,7 +181,7 @@ func handleRootHealthz(checks ...HealthzChecker) http.HandlerFunc { // always be verbose on failure if failed { klog.V(2).Infof("%vhealthz check failed", verboseOut.String()) - http.Error(w, fmt.Sprintf("%vhealthz check failed", verboseOut.String()), http.StatusInternalServerError) + http.Error(httplog.Unlogged(r, w), fmt.Sprintf("%vhealthz check failed", verboseOut.String()), http.StatusInternalServerError) return } diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go index 8b7f1fd0474..e529edabe46 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go @@ -18,6 +18,7 @@ package httplog import ( "bufio" + "context" "fmt" "net" "net/http" @@ -34,6 +35,11 @@ type logger interface { Addf(format string, data ...interface{}) } +type respLoggerContextKeyType int + +// respLoggerContextKey is used to store the respLogger pointer in the request context. +const respLoggerContextKey respLoggerContextKeyType = iota + // Add a layer on top of ResponseWriter, so we can track latency and error // message sources. // @@ -69,47 +75,54 @@ func DefaultStacktracePred(status int) bool { return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols } -// NewLogged turns a normal response writer into a logged response writer. -// -// Usage: -// -// defer NewLogged(req, &w).StacktraceWhen(StatusIsNot(200, 202)).Log() -// -// (Only the call to Log() is deferred, so you can set everything up in one line!) -// -// Note that this *changes* your writer, to route response writing actions -// through the logger. -// -// Use LogOf(w).Addf(...) to log something along with the response result. -func NewLogged(req *http.Request, w *http.ResponseWriter) *respLogger { - if _, ok := (*w).(*respLogger); ok { - // Don't double-wrap! - panic("multiple NewLogged calls!") +// WithLogging wraps the handler with logging. +func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + ctx := req.Context() + if old := respLoggerFromContext(req); old != nil { + panic("multiple WithLogging calls!") + } + rl := newLogged(req, w).StacktraceWhen(pred) + req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl)) + + defer rl.Log() + handler.ServeHTTP(rl, req) + }) +} + +// respLoggerFromContext returns the respLogger or nil. +func respLoggerFromContext(req *http.Request) *respLogger { + ctx := req.Context() + val := ctx.Value(respLoggerContextKey) + if rl, ok := val.(*respLogger); ok { + return rl } - rl := &respLogger{ + return nil +} + +// newLogged turns a normal response writer into a logged response writer. +func newLogged(req *http.Request, w http.ResponseWriter) *respLogger { + return &respLogger{ startTime: time.Now(), req: req, - w: *w, + w: w, logStacktracePred: DefaultStacktracePred, } - *w = rl // hijack caller's writer! - return rl } // LogOf returns the logger hiding in w. If there is not an existing logger // then a passthroughLogger will be created which will log to stdout immediately // when Addf is called. func LogOf(req *http.Request, w http.ResponseWriter) logger { - if rl, ok := w.(*respLogger); ok { + if rl := respLoggerFromContext(req); rl != nil { return rl } - return &passthroughLogger{} } // Unlogged returns the original ResponseWriter, or w if it is not our inserted logger. -func Unlogged(w http.ResponseWriter) http.ResponseWriter { - if rl, ok := w.(*respLogger); ok { +func Unlogged(req *http.Request, w http.ResponseWriter) http.ResponseWriter { + if rl := respLoggerFromContext(req); rl != nil { return rl.w } return w diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go index 680b1e478c6..62f5ed76de8 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go @@ -56,22 +56,24 @@ func TestStatusIsNot(t *testing.T) { } } -func TestNewLogged(t *testing.T) { +func TestWithLogging(t *testing.T) { req, err := http.NewRequest("GET", "http://example.com", nil) if err != nil { t.Errorf("Unexpected error: %v", err) } - handler := func(w http.ResponseWriter, r *http.Request) { - NewLogged(req, &w) + var handler http.Handler + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {}) + handler = WithLogging(WithLogging(handler, DefaultStacktracePred), DefaultStacktracePred) + + func() { defer func() { if r := recover(); r == nil { - t.Errorf("Expected NewLogged to panic") + t.Errorf("Expected newLogged to panic") } }() - NewLogged(req, &w) - } - w := httptest.NewRecorder() - handler(w, req) + w := httptest.NewRecorder() + handler.ServeHTTP(w, req) + }() } func TestLogOf(t *testing.T) { @@ -81,21 +83,23 @@ func TestLogOf(t *testing.T) { if err != nil { t.Errorf("Unexpected error: %v", err) } - handler := func(w http.ResponseWriter, r *http.Request) { - var want string - if makeLogger { - NewLogged(req, &w) - want = "*httplog.respLogger" - } else { - want = "*httplog.passthroughLogger" - } + var want string + var handler http.Handler + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { got := reflect.TypeOf(LogOf(r, w)).String() if want != got { t.Errorf("Expected %v, got %v", want, got) } + }) + if makeLogger { + handler = WithLogging(handler, DefaultStacktracePred) + want = "*httplog.respLogger" + } else { + want = "*httplog.passthroughLogger" } + w := httptest.NewRecorder() - handler(w, req) + handler.ServeHTTP(w, req) } } @@ -106,18 +110,20 @@ func TestUnlogged(t *testing.T) { if err != nil { t.Errorf("Unexpected error: %v", err) } - handler := func(w http.ResponseWriter, r *http.Request) { - want := w - if makeLogger { - NewLogged(req, &w) - } - got := Unlogged(w) - if want != got { - t.Errorf("Expected %v, got %v", want, got) + + origWriter := httptest.NewRecorder() + var handler http.Handler + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + got := Unlogged(r, w) + if origWriter != got { + t.Errorf("Expected origin writer, got %#v", got) } + }) + if makeLogger { + handler = WithLogging(handler, DefaultStacktracePred) } - w := httptest.NewRecorder() - handler(w, req) + + handler.ServeHTTP(origWriter, req) } } @@ -134,7 +140,7 @@ func TestLoggedStatus(t *testing.T) { } var tw http.ResponseWriter = new(testResponseWriter) - logger := NewLogged(req, &tw) + logger := newLogged(req, tw) logger.Write(nil) if logger.status != http.StatusOK { @@ -142,7 +148,7 @@ func TestLoggedStatus(t *testing.T) { } tw = new(testResponseWriter) - logger = NewLogged(req, &tw) + logger = newLogged(req, tw) logger.WriteHeader(http.StatusForbidden) logger.Write(nil)