diff --git a/cmd/http-tracer.go b/cmd/http-tracer.go index b9a76da4f..d6424252c 100644 --- a/cmd/http-tracer.go +++ b/cmd/http-tracer.go @@ -18,7 +18,6 @@ package cmd import ( "bytes" - "fmt" "io" "io/ioutil" "net" @@ -34,8 +33,6 @@ import ( trace "github.com/minio/minio/pkg/trace" ) -var traceBodyPlaceHolder = []byte("") - // recordRequest - records the first recLen bytes // of a given io.Reader type recordRequest struct { @@ -78,81 +75,7 @@ func (r *recordRequest) Data() []byte { return r.buf.Bytes() } // ... otherwise we return placeholder - return traceBodyPlaceHolder -} - -// recordResponseWriter - records the first recLen bytes -// of a given http.ResponseWriter -type recordResponseWriter struct { - // Data source to record - http.ResponseWriter - // Response body should be logged - logBody bool - // Internal recording buffer - headers bytes.Buffer - body bytes.Buffer - // The status code of the current HTTP request - statusCode int - // Indicate if headers are written in the log - headersLogged bool - // number of bytes written - bytesWritten int -} - -// Write the headers into the given buffer -func (r *recordResponseWriter) writeHeaders(w io.Writer, statusCode int, headers http.Header) { - n, _ := fmt.Fprintf(w, "%d %s\n", statusCode, http.StatusText(statusCode)) - r.bytesWritten += n - for k, v := range headers { - n, _ := fmt.Fprintf(w, "%s: %s\n", k, v[0]) - r.bytesWritten += n - } -} - -// Record the headers. -func (r *recordResponseWriter) WriteHeader(i int) { - r.statusCode = i - if !r.headersLogged { - r.writeHeaders(&r.headers, i, r.ResponseWriter.Header()) - r.headersLogged = true - } - r.ResponseWriter.WriteHeader(i) -} - -func (r *recordResponseWriter) Write(p []byte) (n int, err error) { - n, err = r.ResponseWriter.Write(p) - r.bytesWritten += n - if !r.headersLogged { - // We assume the response code to be '200 OK' when WriteHeader() is not called, - // that way following Golang HTTP response behavior. - r.writeHeaders(&r.headers, http.StatusOK, r.ResponseWriter.Header()) - r.headersLogged = true - } - if r.statusCode >= http.StatusBadRequest || r.logBody { - // Always logging error responses. - r.body.Write(p) - } - return n, err -} - -func (r *recordResponseWriter) Size() int { - return r.bytesWritten -} - -// Calls the underlying Flush. -func (r *recordResponseWriter) Flush() { - r.ResponseWriter.(http.Flusher).Flush() -} - -// Return response body. -func (r *recordResponseWriter) Body() []byte { - // If there was an error response or body logging is enabled - // then we return the body contents - if r.statusCode >= http.StatusBadRequest || r.logBody { - return r.body.Bytes() - } - // ... otherwise we return the place holder - return traceBodyPlaceHolder + return logger.BodyPlaceHolder } // getOpName sanitizes the operation name for mc @@ -205,16 +128,15 @@ func Trace(f http.HandlerFunc, logBody bool, w http.ResponseWriter, r *http.Requ Headers: reqHeaders, Body: reqBodyRecorder.Data(), } - - // Setup a http response body recorder - respBodyRecorder := &recordResponseWriter{ResponseWriter: w, logBody: logBody} - f(logger.NewResponseWriter(respBodyRecorder), r) + rw, _ := w.(*logger.ResponseWriter) + rw.LogBody = logBody + f(rw, r) rs := trace.ResponseInfo{ Time: time.Now().UTC(), - Headers: respBodyRecorder.Header().Clone(), - StatusCode: respBodyRecorder.statusCode, - Body: respBodyRecorder.Body(), + Headers: rw.Header().Clone(), + StatusCode: rw.StatusCode, + Body: rw.Body(), } if rs.StatusCode == 0 { @@ -225,9 +147,10 @@ func Trace(f http.HandlerFunc, logBody bool, w http.ResponseWriter, r *http.Requ t.RespInfo = rs t.CallStats = trace.CallStats{ - Latency: rs.Time.Sub(rq.Time), - InputBytes: reqBodyRecorder.Size(), - OutputBytes: respBodyRecorder.Size(), + Latency: rs.Time.Sub(rw.StartTime), + InputBytes: reqBodyRecorder.Size(), + OutputBytes: rw.Size(), + TimeToFirstByte: rw.TimeToFirstByte, } return t } diff --git a/cmd/logger/audit.go b/cmd/logger/audit.go index 82380a890..d27a64f03 100644 --- a/cmd/logger/audit.go +++ b/cmd/logger/audit.go @@ -1,5 +1,5 @@ /* - * MinIO Cloud Storage, (C) 2018 MinIO, Inc. + * MinIO Cloud Storage, (C) 2018, 2019 MinIO, Inc. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -17,6 +17,9 @@ package logger import ( + "bytes" + "fmt" + "io" "net/http" "time" @@ -27,9 +30,18 @@ import ( // ResponseWriter - is a wrapper to trap the http response status code. type ResponseWriter struct { http.ResponseWriter - statusCode int - startTime time.Time - timeToFirstByte time.Duration + StatusCode int + // Response body should be logged + LogBody bool + TimeToFirstByte time.Duration + StartTime time.Time + // number of bytes written + bytesWritten int + // Internal recording buffer + headers bytes.Buffer + body bytes.Buffer + // Indicate if headers are written in the log + headersLogged bool } // NewResponseWriter - returns a wrapped response writer to trap @@ -37,25 +49,64 @@ type ResponseWriter struct { func NewResponseWriter(w http.ResponseWriter) *ResponseWriter { return &ResponseWriter{ ResponseWriter: w, - statusCode: http.StatusOK, - startTime: time.Now().UTC(), + StatusCode: http.StatusOK, + StartTime: time.Now().UTC(), } } func (lrw *ResponseWriter) Write(p []byte) (int, error) { n, err := lrw.ResponseWriter.Write(p) + lrw.bytesWritten += n + if lrw.TimeToFirstByte == 0 { + lrw.TimeToFirstByte = time.Now().UTC().Sub(lrw.StartTime) + } + if !lrw.headersLogged { + // We assume the response code to be '200 OK' when WriteHeader() is not called, + // that way following Golang HTTP response behavior. + lrw.writeHeaders(&lrw.headers, http.StatusOK, lrw.Header()) + lrw.headersLogged = true + } + if lrw.StatusCode >= http.StatusBadRequest || lrw.LogBody { + // Always logging error responses. + lrw.body.Write(p) + } if err != nil { return n, err } - if lrw.timeToFirstByte == 0 { - lrw.timeToFirstByte = time.Now().UTC().Sub(lrw.startTime) - } return n, err } +// Write the headers into the given buffer +func (lrw *ResponseWriter) writeHeaders(w io.Writer, statusCode int, headers http.Header) { + n, _ := fmt.Fprintf(w, "%d %s\n", statusCode, http.StatusText(statusCode)) + lrw.bytesWritten += n + for k, v := range headers { + n, _ := fmt.Fprintf(w, "%s: %s\n", k, v[0]) + lrw.bytesWritten += n + } +} + +// BodyPlaceHolder returns a dummy body placeholder +var BodyPlaceHolder = []byte("") + +// Body - Return response body. +func (lrw *ResponseWriter) Body() []byte { + // If there was an error response or body logging is enabled + // then we return the body contents + if lrw.StatusCode >= http.StatusBadRequest || lrw.LogBody { + return lrw.body.Bytes() + } + // ... otherwise we return the place holder + return BodyPlaceHolder +} + // WriteHeader - writes http status code func (lrw *ResponseWriter) WriteHeader(code int) { - lrw.statusCode = code + lrw.StatusCode = code + if !lrw.headersLogged { + lrw.writeHeaders(&lrw.headers, code, lrw.ResponseWriter.Header()) + lrw.headersLogged = true + } lrw.ResponseWriter.WriteHeader(code) } @@ -64,6 +115,11 @@ func (lrw *ResponseWriter) Flush() { lrw.ResponseWriter.(http.Flusher).Flush() } +// Size - reutrns the number of bytes written +func (lrw *ResponseWriter) Size() int { + return lrw.bytesWritten +} + // AuditTargets is the list of enabled audit loggers var AuditTargets = []Target{} @@ -80,9 +136,9 @@ func AuditLog(w http.ResponseWriter, r *http.Request, api string, reqClaims map[ var timeToFirstByte time.Duration lrw, ok := w.(*ResponseWriter) if ok { - statusCode = lrw.statusCode - timeToResponse = time.Now().UTC().Sub(lrw.startTime) - timeToFirstByte = lrw.timeToFirstByte + statusCode = lrw.StatusCode + timeToResponse = time.Now().UTC().Sub(lrw.StartTime) + timeToFirstByte = lrw.TimeToFirstByte } vars := mux.Vars(r) diff --git a/pkg/trace/trace.go b/pkg/trace/trace.go index 2ec9bed7d..5cc875787 100644 --- a/pkg/trace/trace.go +++ b/pkg/trace/trace.go @@ -33,9 +33,10 @@ type Info struct { // CallStats records request stats type CallStats struct { - InputBytes int `json:"inputbytes"` - OutputBytes int `json:"outputbytes"` - Latency time.Duration `json:"latency"` + InputBytes int `json:"inputbytes"` + OutputBytes int `json:"outputbytes"` + Latency time.Duration `json:"latency"` + TimeToFirstByte time.Duration `json:"timetofirstbyte"` } // RequestInfo represents trace of http request