From 8ce424bacdbaf9cc68e4a7592b4469f3824fb148 Mon Sep 17 00:00:00 2001 From: Harshavardhana Date: Mon, 12 Aug 2019 20:32:34 -0700 Subject: [PATCH] Enhance audit logging to capture responseTimes (#8067) Audit logging requires to have - timeToFirstByte - timeToResponse timing information --- cmd/logger/audit.go | 42 ++++++++++++++++++++++++++--- cmd/logger/message/audit/entry.go | 25 ++++++----------- docs/logging/README.md | 45 +++++++++++++------------------ 3 files changed, 65 insertions(+), 47 deletions(-) diff --git a/cmd/logger/audit.go b/cmd/logger/audit.go index e759f4a4c..82380a890 100644 --- a/cmd/logger/audit.go +++ b/cmd/logger/audit.go @@ -18,20 +18,39 @@ package logger import ( "net/http" + "time" + "github.com/gorilla/mux" "github.com/minio/minio/cmd/logger/message/audit" ) // ResponseWriter - is a wrapper to trap the http response status code. type ResponseWriter struct { http.ResponseWriter - statusCode int + statusCode int + startTime time.Time + timeToFirstByte time.Duration } // NewResponseWriter - returns a wrapped response writer to trap // http status codes for auditiing purposes. func NewResponseWriter(w http.ResponseWriter) *ResponseWriter { - return &ResponseWriter{w, http.StatusOK} + return &ResponseWriter{ + ResponseWriter: w, + statusCode: http.StatusOK, + startTime: time.Now().UTC(), + } +} + +func (lrw *ResponseWriter) Write(p []byte) (int, error) { + n, err := lrw.ResponseWriter.Write(p) + if err != nil { + return n, err + } + if lrw.timeToFirstByte == 0 { + lrw.timeToFirstByte = time.Now().UTC().Sub(lrw.startTime) + } + return n, err } // WriteHeader - writes http status code @@ -57,12 +76,29 @@ func AddAuditTarget(t Target) { // AuditLog - logs audit logs to all audit targets. func AuditLog(w http.ResponseWriter, r *http.Request, api string, reqClaims map[string]interface{}) { var statusCode int + var timeToResponse time.Duration + var timeToFirstByte time.Duration lrw, ok := w.(*ResponseWriter) if ok { statusCode = lrw.statusCode + timeToResponse = time.Now().UTC().Sub(lrw.startTime) + timeToFirstByte = lrw.timeToFirstByte } + + vars := mux.Vars(r) + bucket := vars["bucket"] + object := vars["object"] + // Send audit logs only to http targets. for _, t := range AuditTargets { - _ = t.Send(audit.ToEntry(w, r, api, statusCode, reqClaims, globalDeploymentID)) + entry := audit.ToEntry(w, r, reqClaims, globalDeploymentID) + entry.API.Name = api + entry.API.Bucket = bucket + entry.API.Object = object + entry.API.Status = http.StatusText(statusCode) + entry.API.StatusCode = statusCode + entry.API.TimeToFirstByte = timeToFirstByte.String() + entry.API.TimeToResponse = timeToResponse.String() + _ = t.Send(entry) } } diff --git a/cmd/logger/message/audit/entry.go b/cmd/logger/message/audit/entry.go index 8a68e0c23..7f9fff339 100644 --- a/cmd/logger/message/audit/entry.go +++ b/cmd/logger/message/audit/entry.go @@ -21,7 +21,6 @@ import ( "strings" "time" - "github.com/gorilla/mux" xhttp "github.com/minio/minio/cmd/http" "github.com/minio/minio/pkg/handlers" ) @@ -35,11 +34,13 @@ type Entry struct { DeploymentID string `json:"deploymentid,omitempty"` Time string `json:"time"` API struct { - Name string `json:"name,omitempty"` - Bucket string `json:"bucket,omitempty"` - Object string `json:"object,omitempty"` - Status string `json:"status,omitempty"` - StatusCode int `json:"statusCode,omitempty"` + Name string `json:"name,omitempty"` + Bucket string `json:"bucket,omitempty"` + Object string `json:"object,omitempty"` + Status string `json:"status,omitempty"` + StatusCode int `json:"statusCode,omitempty"` + TimeToFirstByte string `json:"timeToFirstByte,omitempty"` + TimeToResponse string `json:"timeToResponse,omitempty"` } `json:"api"` RemoteHost string `json:"remotehost,omitempty"` RequestID string `json:"requestID,omitempty"` @@ -51,11 +52,7 @@ type Entry struct { } // ToEntry - constructs an audit entry object. -func ToEntry(w http.ResponseWriter, r *http.Request, api string, statusCode int, reqClaims map[string]interface{}, deploymentID string) Entry { - vars := mux.Vars(r) - bucket := vars["bucket"] - object := vars["object"] - +func ToEntry(w http.ResponseWriter, r *http.Request, reqClaims map[string]interface{}, deploymentID string) Entry { reqQuery := make(map[string]string) for k, v := range r.URL.Query() { reqQuery[k] = strings.Join(v, ",") @@ -83,11 +80,5 @@ func ToEntry(w http.ResponseWriter, r *http.Request, api string, statusCode int, RespHeader: respHeader, } - entry.API.Name = api - entry.API.Bucket = bucket - entry.API.Object = object - entry.API.Status = http.StatusText(statusCode) - entry.API.StatusCode = statusCode - return entry } diff --git a/docs/logging/README.md b/docs/logging/README.md index b38dd4a2c..8dba7e534 100644 --- a/docs/logging/README.md +++ b/docs/logging/README.md @@ -76,46 +76,37 @@ Setting this environment variable automatically enables audit logging to the HTT ```json { "version": "1", - "deploymentid": "1b3002bf-5005-4d9b-853e-64a05008ebb2", - "time": "2018-11-21T23:16:06.828154172Z", + "deploymentid": "bc0e4d1e-bacc-42eb-91ad-2d7f3eacfa8d", + "time": "2019-08-12T21:34:37.187817748Z", "api": { "name": "PutObject", - "bucket": "my-bucketname", - "object": "my-objectname", + "bucket": "testbucket", + "object": "hosts", "status": "OK", - "statusCode": 200 + "statusCode": 200, + "timeToFirstByte": "0s", + "timeToResponse": "2.143308ms" }, "remotehost": "127.0.0.1", - "requestID": "156946C6C1E7842C", - "userAgent": "MinIO (linux; amd64) minio-go/v6.0.6", - "requestClaims": { - "accessKey": "A1YABB5YPX3ZPL4227XJ", - "aud": "PoEgXP6uVO45IsENRngDXj5Au5Ya", - "azp": "PoEgXP6uVO45IsENRngDXj5Au5Ya", - "exp": 1542845766, - "iat": 1542842166, - "iss": "https://localhost:9443/oauth2/token", - "jti": "33527fcc-254f-43d2-a558-4942554b8ff8" - }, + "requestID": "15BA4A72C0C70AFC", + "userAgent": "MinIO (linux; amd64) minio-go/v6.0.32 mc/2019-08-12T18:27:13Z", "requestHeader": { - "Authorization": "AWS4-HMAC-SHA256 Credential=A1YABB5YPX3ZPL4227XJ/20181121/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date;x-amz-decoded-content-length;x-amz-security-token,Signature=689d9b8f67b5625ea2f0b8cbb3f777d8839a91d50aa81e6a5555f5a6360c1714", - "Content-Length": "184", + "Authorization": "AWS4-HMAC-SHA256 Credential=minio/20190812/us-east-1/s3/aws4_request,SignedHeaders=host;x-amz-content-sha256;x-amz-date;x-amz-decoded-content-length,Signature=d3f02a6aeddeb29b06e1773b6a8422112890981269f2463a26f307b60423177c", + "Content-Length": "686", "Content-Type": "application/octet-stream", - "User-Agent": "MinIO (linux; amd64) minio-go/v6.0.6", + "User-Agent": "MinIO (linux; amd64) minio-go/v6.0.32 mc/2019-08-12T18:27:13Z", "X-Amz-Content-Sha256": "STREAMING-AWS4-HMAC-SHA256-PAYLOAD", - "X-Amz-Date": "20181121T231606Z", - "X-Amz-Decoded-Content-Length": "12", - "X-Amz-Security-Token": "eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJhY2Nlc3NLZXkiOiJBMVlBQkI1WVBYM1pQTDQyMjdYSiIsImF1ZCI6IlBvRWdYUDZ1Vk80NUlzRU5SbmdEWGo1QXU1WWEiLCJhenAiOiJQb0VnWFA2dVZPNDVJc0VOUm5nRFhqNUF1NVlhIiwiZXhwIjoxNTQyODQ1NzY2LCJpYXQiOjE1NDI4NDIxNjYsImlzcyI6Imh0dHBzOi8vbG9jYWxob3N0Ojk0NDMvb2F1dGgyL3Rva2VuIiwianRpIjoiMzM1MjdmY2MtMjU0Zi00M2QyLWE1NTgtNDk0MjU1NGI4ZmY4In0.KEuAq2cQ3H7dfIB5DVuvcgBXT38mr0gthrIbVRSZcA2OWo8QiH1-DWXj9xYbndgr1p2tiEUsQ49cuszQGEVGMQ" + "X-Amz-Date": "20190812T213437Z", + "X-Amz-Decoded-Content-Length": "512" }, "responseHeader": { "Accept-Ranges": "bytes", + "Content-Length": "0", "Content-Security-Policy": "block-all-mixed-content", - "Content-Type": "application/xml", - "Etag": "", - "Server": "MinIO/DEVELOPMENT.2018-11-21T23-15-06Z (linux; amd64)", + "ETag": "a414c889dc276457bd7175f974332cb0-1", + "Server": "MinIO/DEVELOPMENT.2019-08-12T21-28-07Z", "Vary": "Origin", - "X-Amz-Request-Id": "156946C6C1E7842C", - "X-Minio-Deployment-Id": "1b3002bf-5005-4d9b-853e-64a05008ebb2", + "X-Amz-Request-Id": "15BA4A72C0C70AFC", "X-Xss-Protection": "1; mode=block" } }