diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go index 2f8c8320357..dbae77190bd 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go @@ -248,7 +248,7 @@ func ListResource(r rest.Lister, rw rest.Watcher, scope *RequestScope, forceWatc if timeout == 0 && minRequestTimeout > 0 { timeout = time.Duration(float64(minRequestTimeout) * (rand.Float64() + 1.0)) } - klog.V(3).Infof("Starting watch for %s, rv=%s labels=%s fields=%s timeout=%s", req.URL.Path, opts.ResourceVersion, opts.LabelSelector, opts.FieldSelector, timeout) + klog.V(3).InfoS("Starting watch", "path", req.URL.Path, "resourceVersion", opts.ResourceVersion, "labels", opts.LabelSelector, "fields", opts.FieldSelector, "timeout", timeout) ctx, cancel := context.WithTimeout(ctx, timeout) defer cancel() watcher, err := rw.Watch(ctx, &opts) 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 6cffab5b3ff..a70c081c566 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go @@ -85,7 +85,7 @@ func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { rl := newLogged(req, w).StacktraceWhen(pred) req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl)) - defer rl.Log() + defer func() { klog.V(3).InfoS("Received HTTP request", rl.LogArgs()...) }() handler.ServeHTTP(rl, req) }) } @@ -153,24 +153,28 @@ func (rl *respLogger) Addf(format string, data ...interface{}) { rl.addedInfo += "\n" + fmt.Sprintf(format, data...) } -// Log is intended to be called once at the end of your request handler, via defer -func (rl *respLogger) Log() { +func (rl *respLogger) LogArgs() []interface{} { latency := time.Since(rl.startTime) - if klog.V(3).Enabled() { - if !rl.hijacked { - klog.InfoDepth(1, fmt.Sprintf("verb=%q URI=%q latency=%v resp=%v UserAgent=%q srcIP=%q: %v%v", - rl.req.Method, rl.req.RequestURI, - latency, rl.status, - rl.req.UserAgent(), rl.req.RemoteAddr, - rl.statusStack, rl.addedInfo, - )) - } else { - klog.InfoDepth(1, fmt.Sprintf("verb=%q URI=%q latency=%v UserAgent=%q srcIP=%q: hijacked", - rl.req.Method, rl.req.RequestURI, - latency, rl.req.UserAgent(), rl.req.RemoteAddr, - )) + args := []interface{}{ + "verb", rl.req.Method, + "URI", rl.req.RequestURI, + "latency", latency, + "userAgent", rl.req.UserAgent(), + "srcIP", rl.req.RemoteAddr, + } + if rl.hijacked { + args = append(args, "hijacked", true) + } else { + args = append(args, "resp", rl.status) + if len(rl.statusStack) > 0 { + args = append(args, "statusStack", rl.statusStack) + } + + if len(rl.addedInfo) > 0 { + args = append(args, "addedInfo", rl.addedInfo) } } + return args } // Header implements http.ResponseWriter. diff --git a/staging/src/k8s.io/apiserver/pkg/storage/etcd3/watcher.go b/staging/src/k8s.io/apiserver/pkg/storage/etcd3/watcher.go index 1071c0f7f8f..793495f3e08 100644 --- a/staging/src/k8s.io/apiserver/pkg/storage/etcd3/watcher.go +++ b/staging/src/k8s.io/apiserver/pkg/storage/etcd3/watcher.go @@ -261,8 +261,7 @@ func (wc *watchChan) processEvent(wg *sync.WaitGroup) { continue } if len(wc.resultChan) == outgoingBufSize { - klog.V(3).Infof("Fast watcher, slow processing. Number of buffered events: %d."+ - "Probably caused by slow dispatching events to watchers", outgoingBufSize) + klog.V(3).InfoS("Fast watcher, slow processing. Probably caused by slow dispatching events to watchers", "outgoingEvents", outgoingBufSize) } // If user couldn't receive results fast enough, we also block incoming events from watcher. // Because storing events in local will cause more memory usage. @@ -368,9 +367,7 @@ func (wc *watchChan) sendError(err error) { func (wc *watchChan) sendEvent(e *event) { if len(wc.incomingEventChan) == incomingBufSize { - klog.V(3).Infof("Fast watcher, slow processing. Number of buffered events: %d."+ - "Probably caused by slow decoding, user not receiving fast, or other processing logic", - incomingBufSize) + klog.V(3).InfoS("Fast watcher, slow processing. Probably caused by slow decoding, user not receiving fast, or other processing logic", "incomingEvents", incomingBufSize) } select { case wc.incomingEventChan <- e: