Merge pull request kubernetes#91833 from AkashSarda/structured_logging

Structured logging for Apiserver [Issue kubernetes#1602 Structured logging]

Author: k8s-ci-robot

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)

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.

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: