From 866dffcd6229eca21c30c64cf2b85290e1852222 Mon Sep 17 00:00:00 2001 From: "A. Elleuch" Date: Wed, 25 Oct 2017 03:04:51 +0100 Subject: [PATCH] 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. --- cmd/api-router.go | 58 ++++----- cmd/common-main.go | 2 + cmd/gateway-main.go | 1 - cmd/gateway-router.go | 54 ++++----- cmd/globals.go | 3 + cmd/handler-utils.go | 19 +++ cmd/lock-instrument_test.go | 1 + pkg/handlers/http-tracer.go | 201 +++++++++++++++++++++++++++++++ pkg/handlers/http-tracer_test.go | 154 +++++++++++++++++++++++ 9 files changed, 437 insertions(+), 56 deletions(-) create mode 100644 pkg/handlers/http-tracer.go create mode 100644 pkg/handlers/http-tracer_test.go diff --git a/cmd/api-router.go b/cmd/api-router.go index b9c76f772..50844d201 100644 --- a/cmd/api-router.go +++ b/cmd/api-router.go @@ -16,7 +16,9 @@ package cmd -import router "github.com/gorilla/mux" +import ( + router "github.com/gorilla/mux" +) // objectAPIHandler implements and provides http handlers for S3 API. type objectAPIHandlers struct { @@ -39,63 +41,63 @@ func registerAPIRouter(mux *router.Router) { /// Object operations // HeadObject - bucket.Methods("HEAD").Path("/{object:.+}").HandlerFunc(api.HeadObjectHandler) + bucket.Methods("HEAD").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.HeadObjectHandler)) // CopyObjectPart - bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(api.CopyObjectPartHandler).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") + bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(httpTraceAll(api.CopyObjectPartHandler)).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") // PutObjectPart - bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(api.PutObjectPartHandler).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") + bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.PutObjectPartHandler)).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") // ListObjectPxarts - bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(api.ListObjectPartsHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.ListObjectPartsHandler)).Queries("uploadId", "{uploadId:.*}") // CompleteMultipartUpload - bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(api.CompleteMultipartUploadHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.CompleteMultipartUploadHandler)).Queries("uploadId", "{uploadId:.*}") // NewMultipartUpload - bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(api.NewMultipartUploadHandler).Queries("uploads", "") + bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.NewMultipartUploadHandler)).Queries("uploads", "") // AbortMultipartUpload - bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(api.AbortMultipartUploadHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.AbortMultipartUploadHandler)).Queries("uploadId", "{uploadId:.*}") // GetObject - bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(api.GetObjectHandler) + bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.GetObjectHandler)) // CopyObject - bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(api.CopyObjectHandler) + bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(httpTraceAll(api.CopyObjectHandler)) // PutObject - bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(api.PutObjectHandler) + bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.PutObjectHandler)) // DeleteObject - bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(api.DeleteObjectHandler) + bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.DeleteObjectHandler)) /// Bucket operations // GetBucketLocation - bucket.Methods("GET").HandlerFunc(api.GetBucketLocationHandler).Queries("location", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketLocationHandler)).Queries("location", "") // GetBucketPolicy - bucket.Methods("GET").HandlerFunc(api.GetBucketPolicyHandler).Queries("policy", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketPolicyHandler)).Queries("policy", "") // GetBucketNotification - bucket.Methods("GET").HandlerFunc(api.GetBucketNotificationHandler).Queries("notification", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketNotificationHandler)).Queries("notification", "") // ListenBucketNotification - bucket.Methods("GET").HandlerFunc(api.ListenBucketNotificationHandler).Queries("events", "{events:.*}") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListenBucketNotificationHandler)).Queries("events", "{events:.*}") // ListMultipartUploads - bucket.Methods("GET").HandlerFunc(api.ListMultipartUploadsHandler).Queries("uploads", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListMultipartUploadsHandler)).Queries("uploads", "") // ListObjectsV2 - bucket.Methods("GET").HandlerFunc(api.ListObjectsV2Handler).Queries("list-type", "2") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListObjectsV2Handler)).Queries("list-type", "2") // ListObjectsV1 (Legacy) - bucket.Methods("GET").HandlerFunc(api.ListObjectsV1Handler) + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListObjectsV1Handler)) // PutBucketPolicy - bucket.Methods("PUT").HandlerFunc(api.PutBucketPolicyHandler).Queries("policy", "") + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketPolicyHandler)).Queries("policy", "") // PutBucketNotification - bucket.Methods("PUT").HandlerFunc(api.PutBucketNotificationHandler).Queries("notification", "") + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketNotificationHandler)).Queries("notification", "") // PutBucket - bucket.Methods("PUT").HandlerFunc(api.PutBucketHandler) + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketHandler)) // HeadBucket - bucket.Methods("HEAD").HandlerFunc(api.HeadBucketHandler) + bucket.Methods("HEAD").HandlerFunc(httpTraceAll(api.HeadBucketHandler)) // PostPolicy - bucket.Methods("POST").HeadersRegexp("Content-Type", "multipart/form-data*").HandlerFunc(api.PostPolicyBucketHandler) + bucket.Methods("POST").HeadersRegexp("Content-Type", "multipart/form-data*").HandlerFunc(httpTraceAll(api.PostPolicyBucketHandler)) // DeleteMultipleObjects - bucket.Methods("POST").HandlerFunc(api.DeleteMultipleObjectsHandler) + bucket.Methods("POST").HandlerFunc(httpTraceAll(api.DeleteMultipleObjectsHandler)) // DeleteBucketPolicy - bucket.Methods("DELETE").HandlerFunc(api.DeleteBucketPolicyHandler).Queries("policy", "") + bucket.Methods("DELETE").HandlerFunc(httpTraceAll(api.DeleteBucketPolicyHandler)).Queries("policy", "") // DeleteBucket - bucket.Methods("DELETE").HandlerFunc(api.DeleteBucketHandler) + bucket.Methods("DELETE").HandlerFunc(httpTraceAll(api.DeleteBucketHandler)) /// Root operation // ListBuckets - apiRouter.Methods("GET").HandlerFunc(api.ListBucketsHandler) + apiRouter.Methods("GET").HandlerFunc(httpTraceAll(api.ListBucketsHandler)) } diff --git a/cmd/common-main.go b/cmd/common-main.go index c9041f8f4..2640fd06e 100644 --- a/cmd/common-main.go +++ b/cmd/common-main.go @@ -114,4 +114,6 @@ func handleCommonEnvVars() { globalIsEnvBrowser = true globalIsBrowserEnabled = bool(browserFlag) } + + globalHTTPTrace = os.Getenv("MINIO_HTTP_TRACE") != "" } diff --git a/cmd/gateway-main.go b/cmd/gateway-main.go index 973edcd13..efbff23c5 100644 --- a/cmd/gateway-main.go +++ b/cmd/gateway-main.go @@ -427,7 +427,6 @@ func gatewayMain(ctx *cli.Context, backendType gatewayBackend) { // invalid/unsupported signatures. setAuthHandler, // Add new handlers here. - } globalHTTPServer = miniohttp.NewServer([]string{gatewayAddr}, registerHandlers(router, handlerFns...), globalTLSCertificate) diff --git a/cmd/gateway-router.go b/cmd/gateway-router.go index 542f12794..35ff7da4e 100644 --- a/cmd/gateway-router.go +++ b/cmd/gateway-router.go @@ -68,63 +68,63 @@ func registerGatewayAPIRouter(mux *router.Router, gw GatewayLayer) { /// Object operations // HeadObject - bucket.Methods("HEAD").Path("/{object:.+}").HandlerFunc(api.HeadObjectHandler) + bucket.Methods("HEAD").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.HeadObjectHandler)) // CopyObjectPart - bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(api.CopyObjectPartHandler).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") + bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(httpTraceAll(api.CopyObjectPartHandler)).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") // PutObjectPart - bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(api.PutObjectPartHandler).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") + bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.PutObjectPartHandler)).Queries("partNumber", "{partNumber:[0-9]+}", "uploadId", "{uploadId:.*}") // ListObjectPxarts - bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(api.ListObjectPartsHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.ListObjectPartsHandler)).Queries("uploadId", "{uploadId:.*}") // CompleteMultipartUpload - bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(api.CompleteMultipartUploadHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.CompleteMultipartUploadHandler)).Queries("uploadId", "{uploadId:.*}") // NewMultipartUpload - bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(api.NewMultipartUploadHandler).Queries("uploads", "") + bucket.Methods("POST").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.NewMultipartUploadHandler)).Queries("uploads", "") // AbortMultipartUpload - bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(api.AbortMultipartUploadHandler).Queries("uploadId", "{uploadId:.*}") + bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.AbortMultipartUploadHandler)).Queries("uploadId", "{uploadId:.*}") // GetObject - bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(api.GetObjectHandler) + bucket.Methods("GET").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.GetObjectHandler)) // CopyObject - bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(api.CopyObjectHandler) + bucket.Methods("PUT").Path("/{object:.+}").HeadersRegexp("X-Amz-Copy-Source", ".*?(\\/|%2F).*?").HandlerFunc(httpTraceAll(api.CopyObjectHandler)) // PutObject - bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(api.PutObjectHandler) + bucket.Methods("PUT").Path("/{object:.+}").HandlerFunc(httpTraceHdrs(api.PutObjectHandler)) // DeleteObject - bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(api.DeleteObjectHandler) + bucket.Methods("DELETE").Path("/{object:.+}").HandlerFunc(httpTraceAll(api.DeleteObjectHandler)) /// Bucket operations // GetBucketLocation - bucket.Methods("GET").HandlerFunc(api.GetBucketLocationHandler).Queries("location", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketLocationHandler)).Queries("location", "") // GetBucketPolicy - bucket.Methods("GET").HandlerFunc(api.GetBucketPolicyHandler).Queries("policy", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketPolicyHandler)).Queries("policy", "") // GetBucketNotification - bucket.Methods("GET").HandlerFunc(api.GetBucketNotificationHandler).Queries("notification", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.GetBucketNotificationHandler)).Queries("notification", "") // ListenBucketNotification - bucket.Methods("GET").HandlerFunc(api.ListenBucketNotificationHandler).Queries("events", "{events:.*}") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListenBucketNotificationHandler)).Queries("events", "{events:.*}") // ListMultipartUploads - bucket.Methods("GET").HandlerFunc(api.ListMultipartUploadsHandler).Queries("uploads", "") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListMultipartUploadsHandler)).Queries("uploads", "") // ListObjectsV2 - bucket.Methods("GET").HandlerFunc(api.ListObjectsV2Handler).Queries("list-type", "2") + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListObjectsV2Handler)).Queries("list-type", "2") // ListObjectsV1 (Legacy) - bucket.Methods("GET").HandlerFunc(api.ListObjectsV1Handler) + bucket.Methods("GET").HandlerFunc(httpTraceAll(api.ListObjectsV1Handler)) // PutBucketPolicy - bucket.Methods("PUT").HandlerFunc(api.PutBucketPolicyHandler).Queries("policy", "") + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketPolicyHandler)).Queries("policy", "") // PutBucketNotification - bucket.Methods("PUT").HandlerFunc(api.PutBucketNotificationHandler).Queries("notification", "") + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketNotificationHandler)).Queries("notification", "") // PutBucket - bucket.Methods("PUT").HandlerFunc(api.PutBucketHandler) + bucket.Methods("PUT").HandlerFunc(httpTraceAll(api.PutBucketHandler)) // HeadBucket - bucket.Methods("HEAD").HandlerFunc(api.HeadBucketHandler) + bucket.Methods("HEAD").HandlerFunc(httpTraceAll(api.HeadBucketHandler)) // PostPolicy - bucket.Methods("POST").HeadersRegexp("Content-Type", "multipart/form-data*").HandlerFunc(api.PostPolicyBucketHandler) + bucket.Methods("POST").HeadersRegexp("Content-Type", "multipart/form-data*").HandlerFunc(httpTraceAll(api.PostPolicyBucketHandler)) // DeleteMultipleObjects - bucket.Methods("POST").HandlerFunc(api.DeleteMultipleObjectsHandler) + bucket.Methods("POST").HandlerFunc(httpTraceAll(api.DeleteMultipleObjectsHandler)) // DeleteBucketPolicy - bucket.Methods("DELETE").HandlerFunc(api.DeleteBucketPolicyHandler).Queries("policy", "") + bucket.Methods("DELETE").HandlerFunc(httpTraceAll(api.DeleteBucketPolicyHandler)).Queries("policy", "") // DeleteBucket - bucket.Methods("DELETE").HandlerFunc(api.DeleteBucketHandler) + bucket.Methods("DELETE").HandlerFunc(httpTraceAll(api.DeleteBucketHandler)) /// Root operation // ListBuckets - apiRouter.Methods("GET").HandlerFunc(api.ListBucketsHandler) + apiRouter.Methods("GET").HandlerFunc(httpTraceAll(api.ListBucketsHandler)) } diff --git a/cmd/globals.go b/cmd/globals.go index d958d6713..af544fe88 100644 --- a/cmd/globals.go +++ b/cmd/globals.go @@ -125,6 +125,9 @@ var ( globalHTTPServerErrorCh = make(chan error) globalOSSignalCh = make(chan os.Signal, 1) + // Enable HTTP request/response headers and body logging. + globalHTTPTrace bool + // List of admin peers. globalAdminPeers = adminPeers{} diff --git a/cmd/handler-utils.go b/cmd/handler-utils.go index 1c34c16a4..175291704 100644 --- a/cmd/handler-utils.go +++ b/cmd/handler-utils.go @@ -21,7 +21,10 @@ import ( "mime/multipart" "net/http" "net/url" + "os" "strings" + + httptracer "github.com/minio/minio/pkg/handlers" ) // Parses location constraint from the incoming reader. @@ -240,3 +243,19 @@ func extractPostPolicyFormValues(form *multipart.Form) (filePart io.ReadCloser, return filePart, fileName, fileSize, formValues, nil } + +// Log headers and body. +func httpTraceAll(f http.HandlerFunc) http.HandlerFunc { + if !globalHTTPTrace { + return f + } + return httptracer.TraceReqHandlerFunc(f, os.Stdout, true) +} + +// Log only the headers. +func httpTraceHdrs(f http.HandlerFunc) http.HandlerFunc { + if !globalHTTPTrace { + return f + } + return httptracer.TraceReqHandlerFunc(f, os.Stdout, false) +} diff --git a/cmd/lock-instrument_test.go b/cmd/lock-instrument_test.go index 3078f9307..8e2f8f1e9 100644 --- a/cmd/lock-instrument_test.go +++ b/cmd/lock-instrument_test.go @@ -218,6 +218,7 @@ func TestNewDebugLockInfoPerVolumePath(t *testing.T) { // TestNsLockMapStatusBlockedToRunning - Validates the function for changing the lock state from blocked to running. func TestNsLockMapStatusBlockedToRunning(t *testing.T) { + testCases := []struct { volume string path string diff --git a/pkg/handlers/http-tracer.go b/pkg/handlers/http-tracer.go new file mode 100644 index 000000000..87f468ef4 --- /dev/null +++ b/pkg/handlers/http-tracer.go @@ -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("") + + 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 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 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()) + } +} diff --git a/pkg/handlers/http-tracer_test.go b/pkg/handlers/http-tracer_test.go new file mode 100644 index 000000000..4bb242095 --- /dev/null +++ b/pkg/handlers/http-tracer_test.go @@ -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 + + + +\[RESPONSE\] \[[^\]]*\] \[[^\]]*\] +200 OK + + + +`, + }, + { + 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 + + + +\[RESPONSE\] \[[^\]]*\] \[[^\]]*\] +404 Not Found + + + +`, + }, + } + + 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())) + } + } +}