Enhance audit logging to capture responseTimes (#8067)

Audit logging requires to have

- timeToFirstByte
- timeToResponse

timing information

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)
 	}
 }

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"`
+		Name            string `json:"name,omitempty"`
-		Bucket     string `json:"bucket,omitempty"`
+		Bucket          string `json:"bucket,omitempty"`
-		Object     string `json:"object,omitempty"`
+		Object          string `json:"object,omitempty"`
-		Status     string `json:"status,omitempty"`
+		Status          string `json:"status,omitempty"`
-		StatusCode int    `json:"statusCode,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 {
+func ToEntry(w http.ResponseWriter, r *http.Request, reqClaims map[string]interface{}, deploymentID string) Entry {
-	vars := mux.Vars(r)
-	bucket := vars["bucket"]
-	object := vars["object"]
-
 	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
 }

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",
+  "deploymentid": "bc0e4d1e-bacc-42eb-91ad-2d7f3eacfa8d",
-  "time": "2018-11-21T23:16:06.828154172Z",
+  "time": "2019-08-12T21:34:37.187817748Z",
   "api": {
     "name": "PutObject",
-    "bucket": "my-bucketname",
+    "bucket": "testbucket",
-    "object": "my-objectname",
+    "object": "hosts",
     "status": "OK",
-    "statusCode": 200
+    "statusCode": 200,
+    "timeToFirstByte": "0s",
+    "timeToResponse": "2.143308ms"
   },
   "remotehost": "127.0.0.1",
-  "requestID": "156946C6C1E7842C",
+  "requestID": "15BA4A72C0C70AFC",
-  "userAgent": "MinIO (linux; amd64) minio-go/v6.0.6",
+  "userAgent": "MinIO (linux; amd64) minio-go/v6.0.32 mc/2019-08-12T18:27:13Z",
-  "requestClaims": {
-    "accessKey": "A1YABB5YPX3ZPL4227XJ",
-    "aud": "PoEgXP6uVO45IsENRngDXj5Au5Ya",
-    "azp": "PoEgXP6uVO45IsENRngDXj5Au5Ya",
-    "exp": 1542845766,
-    "iat": 1542842166,
-    "iss": "https://localhost:9443/oauth2/token",
-    "jti": "33527fcc-254f-43d2-a558-4942554b8ff8"
-  },
   "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",
+    "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": "184",
+    "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-Date": "20190812T213437Z",
-    "X-Amz-Decoded-Content-Length": "12",
+    "X-Amz-Decoded-Content-Length": "512"
-    "X-Amz-Security-Token": "eyJhbGciOiJIUzUxMiIsInR5cCI6IkpXVCJ9.eyJhY2Nlc3NLZXkiOiJBMVlBQkI1WVBYM1pQTDQyMjdYSiIsImF1ZCI6IlBvRWdYUDZ1Vk80NUlzRU5SbmdEWGo1QXU1WWEiLCJhenAiOiJQb0VnWFA2dVZPNDVJc0VOUm5nRFhqNUF1NVlhIiwiZXhwIjoxNTQyODQ1NzY2LCJpYXQiOjE1NDI4NDIxNjYsImlzcyI6Imh0dHBzOi8vbG9jYWxob3N0Ojk0NDMvb2F1dGgyL3Rva2VuIiwianRpIjoiMzM1MjdmY2MtMjU0Zi00M2QyLWE1NTgtNDk0MjU1NGI4ZmY4In0.KEuAq2cQ3H7dfIB5DVuvcgBXT38mr0gthrIbVRSZcA2OWo8QiH1-DWXj9xYbndgr1p2tiEUsQ49cuszQGEVGMQ"
   },
   "responseHeader": {
     "Accept-Ranges": "bytes",
+    "Content-Length": "0",
     "Content-Security-Policy": "block-all-mixed-content",
-    "Content-Type": "application/xml",
+    "ETag": "a414c889dc276457bd7175f974332cb0-1",
-    "Etag": "",
+    "Server": "MinIO/DEVELOPMENT.2019-08-12T21-28-07Z",
-    "Server": "MinIO/DEVELOPMENT.2018-11-21T23-15-06Z (linux; amd64)",
     "Vary": "Origin",
-    "X-Amz-Request-Id": "156946C6C1E7842C",
+    "X-Amz-Request-Id": "15BA4A72C0C70AFC",
-    "X-Minio-Deployment-Id": "1b3002bf-5005-4d9b-853e-64a05008ebb2",
     "X-Xss-Protection": "1; mode=block"
   }
 }