Matthias Andreas Benkard | 832a54e | 2019-01-29 09:27:38 +0100 | [diff] [blame] | 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 | "fmt" |
| 22 | "net" |
| 23 | "net/http" |
| 24 | "runtime" |
| 25 | "time" |
| 26 | |
| 27 | "github.com/golang/glog" |
| 28 | ) |
| 29 | |
| 30 | // StacktracePred returns true if a stacktrace should be logged for this status. |
| 31 | type StacktracePred func(httpStatus int) (logStacktrace bool) |
| 32 | |
| 33 | type logger interface { |
| 34 | Addf(format string, data ...interface{}) |
| 35 | } |
| 36 | |
| 37 | // Add a layer on top of ResponseWriter, so we can track latency and error |
| 38 | // message sources. |
| 39 | // |
| 40 | // TODO now that we're using go-restful, we shouldn't need to be wrapping |
| 41 | // the http.ResponseWriter. We can recover panics from go-restful, and |
| 42 | // the logging value is questionable. |
| 43 | type respLogger struct { |
| 44 | hijacked bool |
| 45 | statusRecorded bool |
| 46 | status int |
| 47 | statusStack string |
| 48 | addedInfo string |
| 49 | startTime time.Time |
| 50 | |
| 51 | captureErrorOutput bool |
| 52 | |
| 53 | req *http.Request |
| 54 | w http.ResponseWriter |
| 55 | |
| 56 | logStacktracePred StacktracePred |
| 57 | } |
| 58 | |
| 59 | // Simple logger that logs immediately when Addf is called |
| 60 | type passthroughLogger struct{} |
| 61 | |
| 62 | // Addf logs info immediately. |
| 63 | func (passthroughLogger) Addf(format string, data ...interface{}) { |
| 64 | glog.V(2).Info(fmt.Sprintf(format, data...)) |
| 65 | } |
| 66 | |
| 67 | // DefaultStacktracePred is the default implementation of StacktracePred. |
| 68 | func DefaultStacktracePred(status int) bool { |
| 69 | return (status < http.StatusOK || status >= http.StatusInternalServerError) && status != http.StatusSwitchingProtocols |
| 70 | } |
| 71 | |
| 72 | // NewLogged turns a normal response writer into a logged response writer. |
| 73 | // |
| 74 | // Usage: |
| 75 | // |
| 76 | // defer NewLogged(req, &w).StacktraceWhen(StatusIsNot(200, 202)).Log() |
| 77 | // |
| 78 | // (Only the call to Log() is deferred, so you can set everything up in one line!) |
| 79 | // |
| 80 | // Note that this *changes* your writer, to route response writing actions |
| 81 | // through the logger. |
| 82 | // |
| 83 | // Use LogOf(w).Addf(...) to log something along with the response result. |
| 84 | func NewLogged(req *http.Request, w *http.ResponseWriter) *respLogger { |
| 85 | if _, ok := (*w).(*respLogger); ok { |
| 86 | // Don't double-wrap! |
| 87 | panic("multiple NewLogged calls!") |
| 88 | } |
| 89 | rl := &respLogger{ |
| 90 | startTime: time.Now(), |
| 91 | req: req, |
| 92 | w: *w, |
| 93 | logStacktracePred: DefaultStacktracePred, |
| 94 | } |
| 95 | *w = rl // hijack caller's writer! |
| 96 | return rl |
| 97 | } |
| 98 | |
| 99 | // LogOf returns the logger hiding in w. If there is not an existing logger |
| 100 | // then a passthroughLogger will be created which will log to stdout immediately |
| 101 | // when Addf is called. |
| 102 | func LogOf(req *http.Request, w http.ResponseWriter) logger { |
| 103 | if _, exists := w.(*respLogger); !exists { |
| 104 | pl := &passthroughLogger{} |
| 105 | return pl |
| 106 | } |
| 107 | if rl, ok := w.(*respLogger); ok { |
| 108 | return rl |
| 109 | } |
| 110 | panic("Unable to find or create the logger!") |
| 111 | } |
| 112 | |
| 113 | // Unlogged returns the original ResponseWriter, or w if it is not our inserted logger. |
| 114 | func Unlogged(w http.ResponseWriter) http.ResponseWriter { |
| 115 | if rl, ok := w.(*respLogger); ok { |
| 116 | return rl.w |
| 117 | } |
| 118 | return w |
| 119 | } |
| 120 | |
| 121 | // StacktraceWhen sets the stacktrace logging predicate, which decides when to log a stacktrace. |
| 122 | // There's a default, so you don't need to call this unless you don't like the default. |
| 123 | func (rl *respLogger) StacktraceWhen(pred StacktracePred) *respLogger { |
| 124 | rl.logStacktracePred = pred |
| 125 | return rl |
| 126 | } |
| 127 | |
| 128 | // StatusIsNot returns a StacktracePred which will cause stacktraces to be logged |
| 129 | // for any status *not* in the given list. |
| 130 | func StatusIsNot(statuses ...int) StacktracePred { |
| 131 | return func(status int) bool { |
| 132 | for _, s := range statuses { |
| 133 | if status == s { |
| 134 | return false |
| 135 | } |
| 136 | } |
| 137 | return true |
| 138 | } |
| 139 | } |
| 140 | |
| 141 | // Addf adds additional data to be logged with this request. |
| 142 | func (rl *respLogger) Addf(format string, data ...interface{}) { |
| 143 | rl.addedInfo += "\n" + fmt.Sprintf(format, data...) |
| 144 | } |
| 145 | |
| 146 | // Log is intended to be called once at the end of your request handler, via defer |
| 147 | func (rl *respLogger) Log() { |
| 148 | latency := time.Since(rl.startTime) |
| 149 | if glog.V(3) { |
| 150 | if !rl.hijacked { |
| 151 | glog.InfoDepth(1, fmt.Sprintf("%s %s: (%v) %v%v%v [%s %s]", rl.req.Method, rl.req.RequestURI, latency, rl.status, rl.statusStack, rl.addedInfo, rl.req.Header["User-Agent"], rl.req.RemoteAddr)) |
| 152 | } else { |
| 153 | glog.InfoDepth(1, fmt.Sprintf("%s %s: (%v) hijacked [%s %s]", rl.req.Method, rl.req.RequestURI, latency, rl.req.Header["User-Agent"], rl.req.RemoteAddr)) |
| 154 | } |
| 155 | } |
| 156 | } |
| 157 | |
| 158 | // Header implements http.ResponseWriter. |
| 159 | func (rl *respLogger) Header() http.Header { |
| 160 | return rl.w.Header() |
| 161 | } |
| 162 | |
| 163 | // Write implements http.ResponseWriter. |
| 164 | func (rl *respLogger) Write(b []byte) (int, error) { |
| 165 | if !rl.statusRecorded { |
| 166 | rl.recordStatus(http.StatusOK) // Default if WriteHeader hasn't been called |
| 167 | } |
| 168 | if rl.captureErrorOutput { |
| 169 | rl.Addf("logging error output: %q\n", string(b)) |
| 170 | } |
| 171 | return rl.w.Write(b) |
| 172 | } |
| 173 | |
| 174 | // Flush implements http.Flusher even if the underlying http.Writer doesn't implement it. |
| 175 | // Flush is used for streaming purposes and allows to flush buffered data to the client. |
| 176 | func (rl *respLogger) Flush() { |
| 177 | if flusher, ok := rl.w.(http.Flusher); ok { |
| 178 | flusher.Flush() |
| 179 | } else if glog.V(2) { |
| 180 | glog.InfoDepth(1, fmt.Sprintf("Unable to convert %+v into http.Flusher", rl.w)) |
| 181 | } |
| 182 | } |
| 183 | |
| 184 | // WriteHeader implements http.ResponseWriter. |
| 185 | func (rl *respLogger) WriteHeader(status int) { |
| 186 | rl.recordStatus(status) |
| 187 | rl.w.WriteHeader(status) |
| 188 | } |
| 189 | |
| 190 | // Hijack implements http.Hijacker. |
| 191 | func (rl *respLogger) Hijack() (net.Conn, *bufio.ReadWriter, error) { |
| 192 | rl.hijacked = true |
| 193 | return rl.w.(http.Hijacker).Hijack() |
| 194 | } |
| 195 | |
| 196 | // CloseNotify implements http.CloseNotifier |
| 197 | func (rl *respLogger) CloseNotify() <-chan bool { |
| 198 | return rl.w.(http.CloseNotifier).CloseNotify() |
| 199 | } |
| 200 | |
| 201 | func (rl *respLogger) recordStatus(status int) { |
| 202 | rl.status = status |
| 203 | rl.statusRecorded = true |
| 204 | if rl.logStacktracePred(status) { |
| 205 | // Only log stacks for errors |
| 206 | stack := make([]byte, 50*1024) |
| 207 | stack = stack[:runtime.Stack(stack, false)] |
| 208 | rl.statusStack = "\n" + string(stack) |
| 209 | rl.captureErrorOutput = true |
| 210 | } else { |
| 211 | rl.statusStack = "" |
| 212 | } |
| 213 | } |