log: Store http request/responses in a log file (#4804)
When MINIO_TRACE_DIR is provided, create a new log file and store all HTTP requests + responses data, body are excluded to reduce memory consumption. MINIO_HTTP_TRACE=1 enables logging. Use non mem consuming http req/resp recorders, the maximum is about 32k per request. This logs to STDOUT, body logging is disabled for PutObject PutObjectPart GetObject.master
A. Elleuch
7 years ago
committed by
deekoder
parent
5eb210dd2e
commit
866dffcd62
@ -0,0 +1,201 @@ |
|||||||
|
/* |
||||||
|
* Minio Cloud Storage, (C) 2017 Minio, Inc. |
||||||
|
* |
||||||
|
* Licensed under the Apache License, Version 2.0 (the "License"); |
||||||
|
* you may not use this file except in compliance with the License. |
||||||
|
* You may obtain a copy of the License at |
||||||
|
* |
||||||
|
* http://www.apache.org/licenses/LICENSE-2.0
|
||||||
|
* |
||||||
|
* Unless required by applicable law or agreed to in writing, software |
||||||
|
* distributed under the License is distributed on an "AS IS" BASIS, |
||||||
|
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||||
|
* See the License for the specific language governing permissions and |
||||||
|
* limitations under the License. |
||||||
|
*/ |
||||||
|
|
||||||
|
package handlers |
||||||
|
|
||||||
|
import ( |
||||||
|
"bytes" |
||||||
|
"fmt" |
||||||
|
"io" |
||||||
|
"io/ioutil" |
||||||
|
"net/http" |
||||||
|
"reflect" |
||||||
|
"runtime" |
||||||
|
"strings" |
||||||
|
"time" |
||||||
|
) |
||||||
|
|
||||||
|
// recordRequest - records the first recLen bytes
|
||||||
|
// of a given io.Reader
|
||||||
|
type recordRequest struct { |
||||||
|
// Data source to record
|
||||||
|
io.Reader |
||||||
|
// Response body should be logged
|
||||||
|
logBody bool |
||||||
|
// Internal recording buffer
|
||||||
|
buf bytes.Buffer |
||||||
|
} |
||||||
|
|
||||||
|
func (r *recordRequest) Read(p []byte) (n int, err error) { |
||||||
|
n, err = r.Reader.Read(p) |
||||||
|
if r.logBody { |
||||||
|
r.buf.Write(p[:n]) |
||||||
|
} |
||||||
|
if err != nil { |
||||||
|
return n, err |
||||||
|
} |
||||||
|
return n, err |
||||||
|
} |
||||||
|
|
||||||
|
// Return the bytes that were recorded.
|
||||||
|
func (r *recordRequest) Data() []byte { |
||||||
|
return r.buf.Bytes() |
||||||
|
} |
||||||
|
|
||||||
|
// 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 |
||||||
|
} |
||||||
|
|
||||||
|
// Write the headers into the given buffer
|
||||||
|
func writeHeaders(w io.Writer, statusCode int, headers http.Header) { |
||||||
|
fmt.Fprintf(w, "%d %s\n", statusCode, http.StatusText(statusCode)) |
||||||
|
for k, v := range headers { |
||||||
|
fmt.Fprintf(w, "%s: %s\n", k, v[0]) |
||||||
|
} |
||||||
|
} |
||||||
|
|
||||||
|
// Record the headers.
|
||||||
|
func (r *recordResponseWriter) WriteHeader(i int) { |
||||||
|
r.statusCode = i |
||||||
|
if !r.headersLogged { |
||||||
|
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) |
||||||
|
// We log after calling ResponseWriter.Write() because this latter
|
||||||
|
// proactively prepares headers when WriteHeader is not called yet.
|
||||||
|
if !r.headersLogged { |
||||||
|
writeHeaders(&r.headers, http.StatusOK, r.ResponseWriter.Header()) |
||||||
|
r.headersLogged = true |
||||||
|
} |
||||||
|
if r.statusCode != http.StatusOK && r.statusCode != http.StatusNoContent && r.statusCode != 0 { |
||||||
|
// We always log error responses.
|
||||||
|
r.body.Write(p) |
||||||
|
return |
||||||
|
} |
||||||
|
if r.logBody { |
||||||
|
r.body.Write(p) |
||||||
|
return |
||||||
|
} |
||||||
|
return n, err |
||||||
|
} |
||||||
|
|
||||||
|
// Calls the underlying Flush.
|
||||||
|
func (r *recordResponseWriter) Flush() { |
||||||
|
r.ResponseWriter.(http.Flusher).Flush() |
||||||
|
} |
||||||
|
|
||||||
|
// Return response headers.
|
||||||
|
func (r *recordResponseWriter) Headers() []byte { |
||||||
|
return r.headers.Bytes() |
||||||
|
} |
||||||
|
|
||||||
|
// Return response body.
|
||||||
|
func (r *recordResponseWriter) Body() []byte { |
||||||
|
return r.body.Bytes() |
||||||
|
} |
||||||
|
|
||||||
|
// TraceReqHandlerFunc logs request/response headers and body.
|
||||||
|
func TraceReqHandlerFunc(f http.HandlerFunc, output io.Writer, logBody bool) http.HandlerFunc { |
||||||
|
name := runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name() |
||||||
|
name = strings.TrimPrefix(name, "github.com/minio/minio/cmd.") |
||||||
|
bodyPlaceHolder := []byte("<BODY>") |
||||||
|
|
||||||
|
return func(w http.ResponseWriter, r *http.Request) { |
||||||
|
const timeFormat = "2006-01-02 15:04:05 -0700" |
||||||
|
var reqBodyRecorder *recordRequest |
||||||
|
|
||||||
|
// Generate short random request ID
|
||||||
|
reqID := fmt.Sprintf("%f", float64(time.Now().UnixNano())/1e10) |
||||||
|
|
||||||
|
reqBodyRecorder = &recordRequest{Reader: r.Body, logBody: logBody} |
||||||
|
r.Body = ioutil.NopCloser(reqBodyRecorder) |
||||||
|
|
||||||
|
// Setup a http response body recorder
|
||||||
|
respBodyRecorder := &recordResponseWriter{ResponseWriter: w, logBody: logBody} |
||||||
|
|
||||||
|
b := bytes.NewBuffer(nil) |
||||||
|
fmt.Fprintf(b, "[REQUEST %s] [%s] [%s]\n", name, reqID, time.Now().Format(timeFormat)) |
||||||
|
|
||||||
|
f(respBodyRecorder, r) |
||||||
|
|
||||||
|
// Build request log and write it to log file
|
||||||
|
fmt.Fprintf(b, "%s %s", r.Method, r.URL.Path) |
||||||
|
if r.URL.RawQuery != "" { |
||||||
|
fmt.Fprintf(b, "?%s", r.URL.RawQuery) |
||||||
|
} |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
|
||||||
|
fmt.Fprintf(b, "Host: %s\n", r.Host) |
||||||
|
for k, v := range r.Header { |
||||||
|
fmt.Fprintf(b, "%s: %s\n", k, v[0]) |
||||||
|
} |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
if logBody { |
||||||
|
bodyContents := reqBodyRecorder.Data() |
||||||
|
if bodyContents != nil { |
||||||
|
// If body logging is disabled then we print <BODY> as a placeholder
|
||||||
|
// for the actual body.
|
||||||
|
b.Write(bodyContents) |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
} |
||||||
|
} else { |
||||||
|
b.Write(bodyPlaceHolder) |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
} |
||||||
|
|
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
|
||||||
|
// Build response log and write it to log file
|
||||||
|
fmt.Fprintf(b, "[RESPONSE] [%s] [%s]\n", reqID, time.Now().Format(timeFormat)) |
||||||
|
|
||||||
|
b.Write(respBodyRecorder.Headers()) |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
bodyContents := respBodyRecorder.Body() |
||||||
|
if bodyContents != nil { |
||||||
|
b.Write(bodyContents) |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
} else { |
||||||
|
if !logBody { |
||||||
|
// If there was no error response and body logging is disabled
|
||||||
|
// then we print <BODY> as a placeholder for the actual body.
|
||||||
|
b.Write(bodyPlaceHolder) |
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
} |
||||||
|
} |
||||||
|
|
||||||
|
fmt.Fprintf(b, "\n") |
||||||
|
|
||||||
|
// Write the contents in one shot so that logs don't get interspersed.
|
||||||
|
output.Write(b.Bytes()) |
||||||
|
} |
||||||
|
} |
||||||
@ -0,0 +1,154 @@ |
|||||||
|
/* |
||||||
|
* Minio Cloud Storage, (C) 2017 Minio, Inc. |
||||||
|
* |
||||||
|
* Licensed under the Apache License, Version 2.0 (the "License"); |
||||||
|
* you may not use this file except in compliance with the License. |
||||||
|
* You may obtain a copy of the License at |
||||||
|
* |
||||||
|
* http://www.apache.org/licenses/LICENSE-2.0
|
||||||
|
* |
||||||
|
* Unless required by applicable law or agreed to in writing, software |
||||||
|
* distributed under the License is distributed on an "AS IS" BASIS, |
||||||
|
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
||||||
|
* See the License for the specific language governing permissions and |
||||||
|
* limitations under the License. |
||||||
|
*/ |
||||||
|
|
||||||
|
package handlers |
||||||
|
|
||||||
|
import ( |
||||||
|
"bytes" |
||||||
|
"io" |
||||||
|
"io/ioutil" |
||||||
|
"net/http" |
||||||
|
"net/http/httptest" |
||||||
|
"regexp" |
||||||
|
"testing" |
||||||
|
) |
||||||
|
|
||||||
|
func wsTestSuccessHandler(w http.ResponseWriter, r *http.Request) { |
||||||
|
// A very simple health check.
|
||||||
|
w.WriteHeader(http.StatusOK) |
||||||
|
w.Header().Set("Content-Type", "application/json") |
||||||
|
|
||||||
|
ioutil.ReadAll(r.Body) |
||||||
|
|
||||||
|
// In the future we could report back on the status of our DB, or our cache
|
||||||
|
// (e.g. Redis) by performing a simple PING, and include them in the response.
|
||||||
|
io.WriteString(w, `{"success": true}`) |
||||||
|
} |
||||||
|
|
||||||
|
func wsTest404Handler(w http.ResponseWriter, r *http.Request) { |
||||||
|
w.WriteHeader(http.StatusNotFound) |
||||||
|
} |
||||||
|
|
||||||
|
func TestTraceHTTPHandler(t *testing.T) { |
||||||
|
|
||||||
|
logOutput := bytes.NewBuffer([]byte("")) |
||||||
|
|
||||||
|
testCases := []struct { |
||||||
|
method string |
||||||
|
path string |
||||||
|
sentData string |
||||||
|
headers map[string]string |
||||||
|
handler http.HandlerFunc |
||||||
|
expectedStatus int |
||||||
|
expectedLogRegexp string |
||||||
|
}{ |
||||||
|
|
||||||
|
{ |
||||||
|
method: "PUT", |
||||||
|
path: "/test-log", |
||||||
|
sentData: "sending data", |
||||||
|
headers: map[string]string{"Test-Header": "TestHeaderValue"}, |
||||||
|
handler: TraceReqHandlerFunc(http.HandlerFunc(wsTestSuccessHandler), logOutput, true), |
||||||
|
expectedStatus: http.StatusOK, |
||||||
|
expectedLogRegexp: `\[REQUEST github.com/minio/minio/pkg/handlers.wsTestSuccessHandler\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
PUT /test-log |
||||||
|
Host:\
|
||||||
|
Test-Header: TestHeaderValue |
||||||
|
|
||||||
|
sending data |
||||||
|
|
||||||
|
\[RESPONSE\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
200 OK |
||||||
|
|
||||||
|
{"success": true} |
||||||
|
|
||||||
|
`, |
||||||
|
}, |
||||||
|
{ |
||||||
|
method: "POST", |
||||||
|
path: "/test-log", |
||||||
|
handler: TraceReqHandlerFunc(http.HandlerFunc(wsTestSuccessHandler), logOutput, false), |
||||||
|
headers: map[string]string{"Test-Header": "TestHeaderValue"}, |
||||||
|
expectedStatus: http.StatusOK, |
||||||
|
expectedLogRegexp: `\[REQUEST github.com/minio/minio/pkg/handlers.wsTestSuccessHandler\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
POST /test-log |
||||||
|
Host:\
|
||||||
|
Test-Header: TestHeaderValue |
||||||
|
|
||||||
|
<BODY> |
||||||
|
|
||||||
|
\[RESPONSE\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
200 OK |
||||||
|
|
||||||
|
<BODY> |
||||||
|
|
||||||
|
`, |
||||||
|
}, |
||||||
|
{ |
||||||
|
method: "POST", |
||||||
|
path: "/test-log", |
||||||
|
handler: TraceReqHandlerFunc(http.HandlerFunc(wsTest404Handler), logOutput, false), |
||||||
|
headers: map[string]string{"Test-Header": "TestHeaderValue"}, |
||||||
|
expectedStatus: http.StatusNotFound, |
||||||
|
expectedLogRegexp: `\[REQUEST github.com/minio/minio/pkg/handlers.wsTest404Handler\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
POST /test-log |
||||||
|
Host:\
|
||||||
|
Test-Header: TestHeaderValue |
||||||
|
|
||||||
|
<BODY> |
||||||
|
|
||||||
|
\[RESPONSE\] \[[^\]]*\] \[[^\]]*\] |
||||||
|
404 Not Found |
||||||
|
|
||||||
|
<BODY> |
||||||
|
|
||||||
|
`, |
||||||
|
}, |
||||||
|
} |
||||||
|
|
||||||
|
for i, testCase := range testCases { |
||||||
|
logOutput.Reset() |
||||||
|
|
||||||
|
req, err := http.NewRequest(testCase.method, testCase.path, bytes.NewBuffer([]byte(testCase.sentData))) |
||||||
|
if err != nil { |
||||||
|
t.Fatalf("Test %d: %v\n", i+1, err) |
||||||
|
} |
||||||
|
|
||||||
|
for k, v := range testCase.headers { |
||||||
|
req.Header.Set(k, v) |
||||||
|
} |
||||||
|
|
||||||
|
rr := httptest.NewRecorder() |
||||||
|
|
||||||
|
handler := testCase.handler |
||||||
|
handler.ServeHTTP(rr, req) |
||||||
|
|
||||||
|
// Check the status code is what we expect.
|
||||||
|
if status := rr.Code; status != testCase.expectedStatus { |
||||||
|
t.Errorf("Test %d: handler returned wrong status code: got %v want %v", i+1, |
||||||
|
status, testCase.expectedStatus) |
||||||
|
} |
||||||
|
|
||||||
|
matched, err := regexp.MatchString(testCase.expectedLogRegexp, string(logOutput.Bytes())) |
||||||
|
if err != nil { |
||||||
|
t.Fatalf("Test %d: Incorrect regexp: %v", i+1, err) |
||||||
|
} |
||||||
|
|
||||||
|
if !matched { |
||||||
|
t.Fatalf("Test %d: Unexpected log content, found: `%s`", i+1, string(logOutput.Bytes())) |
||||||
|
} |
||||||
|
} |
||||||
|
} |
||||||
Loading…
Reference in new issue