Cleanup ResponseWriter function for audit and trace (#8283)

2025-11-07 21:02:58 -05:00 · 2019-09-23 13:34:28 -07:00
parent 3b05e175d7
commit 2e02e1889b
3 changed files with 84 additions and 104 deletions
--- 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>")
+
+// 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 <BODY> 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)