github/kubernetes
1
0
Fork 0
mirror of https://github.com/k3s-io/kubernetes.git synced 2025-07-24 12:15:52 +00:00
Code Issues Projects Releases Wiki Activity

Merge pull request #91833 from AkashSarda/structured_logging

Browse Source 
Structured logging for Apiserver [Issue #1602 Structured logging]
This commit is contained in:
Kubernetes Prow Robot 2020-06-22 15:01:40 -07:00 committed by GitHub
commit db194acd69
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 23 additions and 22 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
staging/src/k8s.io/apiserver/pkg/endpoints/handlers/get.go
View File

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

36
staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
View File

@ -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.

7
staging/src/k8s.io/apiserver/pkg/storage/etcd3/watcher.go
View File

@ -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: