k8s.io/apiserver@v0.31.1/pkg/server/httplog/httplog.go (about) 1 /* 2 Copyright 2014 The Kubernetes Authors. 3 4 Licensed under the Apache License, Version 2.0 (the "License"); 5 you may not use this file except in compliance with the License. 6 You may obtain a copy of the License at 7 8 http://www.apache.org/licenses/LICENSE-2.0 9 10 Unless required by applicable law or agreed to in writing, software 11 distributed under the License is distributed on an "AS IS" BASIS, 12 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 See the License for the specific language governing permissions and 14 limitations under the License. 15 */ 16 17 package httplog 18 19 import ( 20 "bufio" 21 "context" 22 "fmt" 23 "net" 24 "net/http" 25 "runtime" 26 "strings" 27 "sync" 28 "time" 29 30 "k8s.io/apiserver/pkg/audit" 31 "k8s.io/apiserver/pkg/endpoints/metrics" 32 "k8s.io/apiserver/pkg/endpoints/request" 33 "k8s.io/apiserver/pkg/endpoints/responsewriter" 34 "k8s.io/apiserver/pkg/server/routine" 35 "k8s.io/klog/v2" 36 ) 37 38 // StacktracePred returns true if a stacktrace should be logged for this status. 39 type StacktracePred func(httpStatus int) (logStacktrace bool) 40 41 // ShouldLogRequestPred returns true if logging should be enabled for this request 42 type ShouldLogRequestPred func() bool 43 44 type logger interface { 45 Addf(format string, data ...interface{}) 46 } 47 48 type respLoggerContextKeyType int 49 50 // respLoggerContextKey is used to store the respLogger pointer in the request context. 51 const respLoggerContextKey respLoggerContextKeyType = iota 52 53 // Add a layer on top of ResponseWriter, so we can track latency and error 54 // message sources. 55 // 56 // TODO now that we're using go-restful, we shouldn't need to be wrapping 57 // the http.ResponseWriter. We can recover panics from go-restful, and 58 // the logging value is questionable. 59 type respLogger struct { 60 hijacked bool 61 statusRecorded bool 62 status int 63 statusStack string 64 // mutex is used when accessing addedInfo, addedKeyValuePairs and logStacktracePred. 65 // They can be modified by other goroutine when logging happens (in case of request timeout) 66 mutex sync.Mutex 67 addedInfo strings.Builder 68 addedKeyValuePairs []interface{} 69 startTime time.Time 70 71 captureErrorOutput bool 72 73 req *http.Request 74 userAgent string 75 w http.ResponseWriter 76 77 logStacktracePred StacktracePred 78 } 79 80 var _ http.ResponseWriter = &respLogger{} 81 var _ responsewriter.UserProvidedDecorator = &respLogger{} 82 83 func (rl *respLogger) Unwrap() http.ResponseWriter { 84 return rl.w 85 } 86 87 // Simple logger that logs immediately when Addf is called 88 type passthroughLogger struct{} 89 90 // Addf logs info immediately. 91 func (passthroughLogger) Addf(format string, data ...interface{}) { 92 klog.V(2).Info(fmt.Sprintf(format, data...)) 93 } 94 95 // DefaultStacktracePred is the default implementation of StacktracePred. 96 func DefaultStacktracePred(status int) bool { 97 return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols 98 } 99 100 const withLoggingLevel = 3 101 102 // WithLogging wraps the handler with logging. 103 func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { 104 return withLogging(handler, pred, func() bool { 105 return klog.V(withLoggingLevel).Enabled() 106 }) 107 } 108 109 func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogRequest ShouldLogRequestPred) http.Handler { 110 return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { 111 if !shouldLogRequest() { 112 handler.ServeHTTP(w, req) 113 return 114 } 115 116 ctx := req.Context() 117 if old := respLoggerFromRequest(req); old != nil { 118 panic("multiple WithLogging calls!") 119 } 120 121 startTime := time.Now() 122 if receivedTimestamp, ok := request.ReceivedTimestampFrom(ctx); ok { 123 startTime = receivedTimestamp 124 } 125 126 rl := newLoggedWithStartTime(req, w, startTime) 127 rl.StacktraceWhen(stackTracePred) 128 req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl)) 129 130 var logFunc func() 131 logFunc = rl.Log 132 defer func() { 133 if logFunc != nil { 134 logFunc() 135 } 136 }() 137 138 w = responsewriter.WrapForHTTP1Or2(rl) 139 handler.ServeHTTP(w, req) 140 141 // We need to ensure that the request is logged after it is processed. 142 // In case the request is executed in a separate goroutine created via 143 // WithRoutine handler in the handler chain (i.e. above handler.ServeHTTP() 144 // would return request is completely responsed), we want the logging to 145 // happen in that goroutine too, so we append it to the task. 146 if routine.AppendTask(ctx, &routine.Task{Func: rl.Log}) { 147 logFunc = nil 148 } 149 }) 150 } 151 152 // respLoggerFromContext returns the respLogger or nil. 153 func respLoggerFromContext(ctx context.Context) *respLogger { 154 val := ctx.Value(respLoggerContextKey) 155 if rl, ok := val.(*respLogger); ok { 156 return rl 157 } 158 return nil 159 } 160 161 func respLoggerFromRequest(req *http.Request) *respLogger { 162 return respLoggerFromContext(req.Context()) 163 } 164 165 func newLoggedWithStartTime(req *http.Request, w http.ResponseWriter, startTime time.Time) *respLogger { 166 logger := &respLogger{ 167 startTime: startTime, 168 req: req, 169 userAgent: req.UserAgent(), 170 w: w, 171 logStacktracePred: DefaultStacktracePred, 172 } 173 return logger 174 } 175 176 // newLogged turns a normal response writer into a logged response writer. 177 func newLogged(req *http.Request, w http.ResponseWriter) *respLogger { 178 return newLoggedWithStartTime(req, w, time.Now()) 179 } 180 181 // LogOf returns the logger hiding in w. If there is not an existing logger 182 // then a passthroughLogger will be created which will log to stdout immediately 183 // when Addf is called. 184 func LogOf(req *http.Request, w http.ResponseWriter) logger { 185 if rl := respLoggerFromRequest(req); rl != nil { 186 return rl 187 } 188 return &passthroughLogger{} 189 } 190 191 // Unlogged returns the original ResponseWriter, or w if it is not our inserted logger. 192 func Unlogged(req *http.Request, w http.ResponseWriter) http.ResponseWriter { 193 if rl := respLoggerFromRequest(req); rl != nil { 194 return rl.w 195 } 196 return w 197 } 198 199 // StacktraceWhen sets the stacktrace logging predicate, which decides when to log a stacktrace. 200 // There's a default, so you don't need to call this unless you don't like the default. 201 func (rl *respLogger) StacktraceWhen(pred StacktracePred) *respLogger { 202 rl.mutex.Lock() 203 defer rl.mutex.Unlock() 204 rl.logStacktracePred = pred 205 return rl 206 } 207 208 // StatusIsNot returns a StacktracePred which will cause stacktraces to be logged 209 // for any status *not* in the given list. 210 func StatusIsNot(statuses ...int) StacktracePred { 211 statusesNoTrace := map[int]bool{} 212 for _, s := range statuses { 213 statusesNoTrace[s] = true 214 } 215 return func(status int) bool { 216 _, ok := statusesNoTrace[status] 217 return !ok 218 } 219 } 220 221 // Addf adds additional data to be logged with this request. 222 func (rl *respLogger) Addf(format string, data ...interface{}) { 223 rl.mutex.Lock() 224 defer rl.mutex.Unlock() 225 rl.addedInfo.WriteString(fmt.Sprintf(format, data...)) 226 } 227 228 func AddInfof(ctx context.Context, format string, data ...interface{}) { 229 if rl := respLoggerFromContext(ctx); rl != nil { 230 rl.Addf(format, data...) 231 } 232 } 233 234 func (rl *respLogger) AddKeyValue(key string, value interface{}) { 235 rl.mutex.Lock() 236 defer rl.mutex.Unlock() 237 rl.addedKeyValuePairs = append(rl.addedKeyValuePairs, key, value) 238 } 239 240 // AddKeyValue adds a (key, value) pair to the httplog associated 241 // with the request. 242 // Use this function if you want your data to show up in httplog 243 // in a more structured and readable way. 244 func AddKeyValue(ctx context.Context, key string, value interface{}) { 245 if rl := respLoggerFromContext(ctx); rl != nil { 246 rl.AddKeyValue(key, value) 247 } 248 } 249 250 // SetStacktracePredicate sets a custom stacktrace predicate for the 251 // logger associated with the given request context. 252 func SetStacktracePredicate(ctx context.Context, pred StacktracePred) { 253 if rl := respLoggerFromContext(ctx); rl != nil { 254 rl.StacktraceWhen(pred) 255 } 256 } 257 258 // Log is intended to be called once at the end of your request handler, via defer 259 func (rl *respLogger) Log() { 260 latency := time.Since(rl.startTime) 261 auditID := audit.GetAuditIDTruncated(rl.req.Context()) 262 verb := metrics.NormalizedVerb(rl.req) 263 264 keysAndValues := []interface{}{ 265 "verb", verb, 266 "URI", rl.req.RequestURI, 267 "latency", latency, 268 // We can't get UserAgent from rl.req.UserAgent() here as it accesses headers map, 269 // which can be modified in another goroutine when apiserver request times out. 270 // For example authentication filter modifies request's headers, 271 // This can cause apiserver to crash with unrecoverable fatal error. 272 // More info about concurrent read and write for maps: https://golang.org/doc/go1.6#runtime 273 "userAgent", rl.userAgent, 274 "audit-ID", auditID, 275 "srcIP", rl.req.RemoteAddr, 276 } 277 // Lock for accessing addedKeyValuePairs and addedInfo 278 rl.mutex.Lock() 279 defer rl.mutex.Unlock() 280 keysAndValues = append(keysAndValues, rl.addedKeyValuePairs...) 281 282 if rl.hijacked { 283 keysAndValues = append(keysAndValues, "hijacked", true) 284 } else { 285 keysAndValues = append(keysAndValues, "resp", rl.status) 286 if len(rl.statusStack) > 0 { 287 keysAndValues = append(keysAndValues, "statusStack", rl.statusStack) 288 } 289 info := rl.addedInfo.String() 290 if len(info) > 0 { 291 keysAndValues = append(keysAndValues, "addedInfo", info) 292 } 293 } 294 295 klog.V(withLoggingLevel).InfoSDepth(1, "HTTP", keysAndValues...) 296 } 297 298 // Header implements http.ResponseWriter. 299 func (rl *respLogger) Header() http.Header { 300 return rl.w.Header() 301 } 302 303 // Write implements http.ResponseWriter. 304 func (rl *respLogger) Write(b []byte) (int, error) { 305 if !rl.statusRecorded { 306 rl.recordStatus(http.StatusOK) // Default if WriteHeader hasn't been called 307 } 308 if rl.captureErrorOutput { 309 rl.Addf("logging error output: %q\n", string(b)) 310 } 311 return rl.w.Write(b) 312 } 313 314 // WriteHeader implements http.ResponseWriter. 315 func (rl *respLogger) WriteHeader(status int) { 316 rl.recordStatus(status) 317 rl.w.WriteHeader(status) 318 } 319 320 func (rl *respLogger) Hijack() (net.Conn, *bufio.ReadWriter, error) { 321 rl.hijacked = true 322 323 // the outer ResponseWriter object returned by WrapForHTTP1Or2 implements 324 // http.Hijacker if the inner object (rl.w) implements http.Hijacker. 325 return rl.w.(http.Hijacker).Hijack() 326 } 327 328 func (rl *respLogger) recordStatus(status int) { 329 rl.mutex.Lock() 330 defer rl.mutex.Unlock() 331 rl.status = status 332 rl.statusRecorded = true 333 if rl.logStacktracePred(status) { 334 // Only log stacks for errors 335 stack := make([]byte, 50*1024) 336 stack = stack[:runtime.Stack(stack, false)] 337 rl.statusStack = "\n" + string(stack) 338 rl.captureErrorOutput = true 339 } else { 340 rl.statusStack = "" 341 } 342 }