2021-04-18 15:41:13 -04:00
|
|
|
// Copyright (c) 2015-2021 MinIO, Inc.
|
|
|
|
|
//
|
|
|
|
|
// This file is part of MinIO Object Storage stack
|
|
|
|
|
//
|
|
|
|
|
// This program is free software: you can redistribute it and/or modify
|
|
|
|
|
// it under the terms of the GNU Affero General Public License as published by
|
|
|
|
|
// the Free Software Foundation, either version 3 of the License, or
|
|
|
|
|
// (at your option) any later version.
|
|
|
|
|
//
|
|
|
|
|
// This program is distributed in the hope that it will be useful
|
|
|
|
|
// but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
|
|
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
|
|
|
|
// GNU Affero General Public License for more details.
|
|
|
|
|
//
|
|
|
|
|
// You should have received a copy of the GNU Affero General Public License
|
|
|
|
|
// along with this program. If not, see <http://www.gnu.org/licenses/>.
|
2018-11-19 17:47:03 -05:00
|
|
|
|
|
|
|
|
package logger
|
|
|
|
|
|
|
|
|
|
import (
|
2019-09-23 16:34:28 -04:00
|
|
|
"bytes"
|
2021-01-26 16:21:51 -05:00
|
|
|
"context"
|
2019-09-23 16:34:28 -04:00
|
|
|
"fmt"
|
|
|
|
|
"io"
|
2018-11-19 17:47:03 -05:00
|
|
|
"net/http"
|
2020-05-19 21:34:02 -04:00
|
|
|
"strconv"
|
2019-08-12 23:32:34 -04:00
|
|
|
"time"
|
2018-11-19 17:47:03 -05:00
|
|
|
|
2021-06-01 17:59:40 -04:00
|
|
|
"github.com/minio/minio/internal/logger/message/audit"
|
2018-11-19 17:47:03 -05:00
|
|
|
)
|
|
|
|
|
|
|
|
|
|
// ResponseWriter - is a wrapper to trap the http response status code.
|
|
|
|
|
type ResponseWriter struct {
|
|
|
|
|
http.ResponseWriter
|
2019-09-23 16:34:28 -04:00
|
|
|
StatusCode int
|
2020-04-30 14:27:19 -04:00
|
|
|
// Log body of 4xx or 5xx responses
|
|
|
|
|
LogErrBody bool
|
|
|
|
|
// Log body of all responses
|
|
|
|
|
LogAllBody bool
|
|
|
|
|
|
2019-09-23 16:34:28 -04:00
|
|
|
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
|
2018-11-19 17:47:03 -05:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
// NewResponseWriter - returns a wrapped response writer to trap
|
2021-03-24 13:25:27 -04:00
|
|
|
// http status codes for auditing purposes.
|
2018-11-19 17:47:03 -05:00
|
|
|
func NewResponseWriter(w http.ResponseWriter) *ResponseWriter {
|
2019-08-12 23:32:34 -04:00
|
|
|
return &ResponseWriter{
|
|
|
|
|
ResponseWriter: w,
|
2019-09-23 16:34:28 -04:00
|
|
|
StatusCode: http.StatusOK,
|
|
|
|
|
StartTime: time.Now().UTC(),
|
2019-08-12 23:32:34 -04:00
|
|
|
}
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
func (lrw *ResponseWriter) Write(p []byte) (int, error) {
|
2019-09-23 16:34:28 -04:00
|
|
|
if !lrw.headersLogged {
|
|
|
|
|
// We assume the response code to be '200 OK' when WriteHeader() is not called,
|
|
|
|
|
// that way following Golang HTTP response behavior.
|
2020-10-08 12:29:10 -04:00
|
|
|
lrw.WriteHeader(http.StatusOK)
|
2019-09-23 16:34:28 -04:00
|
|
|
}
|
2020-10-08 15:32:32 -04:00
|
|
|
n, err := lrw.ResponseWriter.Write(p)
|
|
|
|
|
lrw.bytesWritten += n
|
|
|
|
|
if lrw.TimeToFirstByte == 0 {
|
|
|
|
|
lrw.TimeToFirstByte = time.Now().UTC().Sub(lrw.StartTime)
|
|
|
|
|
}
|
2020-04-30 14:27:19 -04:00
|
|
|
if (lrw.LogErrBody && lrw.StatusCode >= http.StatusBadRequest) || lrw.LogAllBody {
|
2019-09-23 16:34:28 -04:00
|
|
|
// Always logging error responses.
|
|
|
|
|
lrw.body.Write(p)
|
|
|
|
|
}
|
2019-08-12 23:32:34 -04:00
|
|
|
if err != nil {
|
|
|
|
|
return n, err
|
|
|
|
|
}
|
|
|
|
|
return n, err
|
2018-11-19 17:47:03 -05:00
|
|
|
}
|
|
|
|
|
|
2019-09-23 16:34:28 -04:00
|
|
|
// 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
|
2020-04-30 14:27:19 -04:00
|
|
|
if (lrw.LogErrBody && lrw.StatusCode >= http.StatusBadRequest) || lrw.LogAllBody {
|
2019-09-23 16:34:28 -04:00
|
|
|
return lrw.body.Bytes()
|
|
|
|
|
}
|
|
|
|
|
// ... otherwise we return the <BODY> place holder
|
|
|
|
|
return BodyPlaceHolder
|
|
|
|
|
}
|
|
|
|
|
|
2018-11-19 17:47:03 -05:00
|
|
|
// WriteHeader - writes http status code
|
|
|
|
|
func (lrw *ResponseWriter) WriteHeader(code int) {
|
2019-09-23 16:34:28 -04:00
|
|
|
if !lrw.headersLogged {
|
2020-10-08 12:29:10 -04:00
|
|
|
lrw.StatusCode = code
|
2019-09-23 16:34:28 -04:00
|
|
|
lrw.writeHeaders(&lrw.headers, code, lrw.ResponseWriter.Header())
|
|
|
|
|
lrw.headersLogged = true
|
2020-10-08 12:29:10 -04:00
|
|
|
lrw.ResponseWriter.WriteHeader(code)
|
2019-09-23 16:34:28 -04:00
|
|
|
}
|
2018-11-19 17:47:03 -05:00
|
|
|
}
|
|
|
|
|
|
|
|
|
|
// Flush - Calls the underlying Flush.
|
|
|
|
|
func (lrw *ResponseWriter) Flush() {
|
|
|
|
|
lrw.ResponseWriter.(http.Flusher).Flush()
|
|
|
|
|
}
|
|
|
|
|
|
2019-09-23 16:34:28 -04:00
|
|
|
// Size - reutrns the number of bytes written
|
|
|
|
|
func (lrw *ResponseWriter) Size() int {
|
|
|
|
|
return lrw.bytesWritten
|
|
|
|
|
}
|
|
|
|
|
|
2021-04-23 12:51:12 -04:00
|
|
|
const contextAuditKey = contextKeyType("audit-entry")
|
|
|
|
|
|
|
|
|
|
// SetAuditEntry sets Audit info in the context.
|
|
|
|
|
func SetAuditEntry(ctx context.Context, audit *audit.Entry) context.Context {
|
|
|
|
|
if ctx == nil {
|
|
|
|
|
LogIf(context.Background(), fmt.Errorf("context is nil"))
|
|
|
|
|
return nil
|
2020-04-30 01:17:36 -04:00
|
|
|
}
|
2021-04-23 12:51:12 -04:00
|
|
|
return context.WithValue(ctx, contextAuditKey, audit)
|
|
|
|
|
}
|
2020-04-30 01:17:36 -04:00
|
|
|
|
2021-04-23 12:51:12 -04:00
|
|
|
// GetAuditEntry returns Audit entry if set.
|
|
|
|
|
func GetAuditEntry(ctx context.Context) *audit.Entry {
|
|
|
|
|
if ctx != nil {
|
|
|
|
|
r, ok := ctx.Value(contextAuditKey).(*audit.Entry)
|
|
|
|
|
if ok {
|
|
|
|
|
return r
|
|
|
|
|
}
|
|
|
|
|
r = &audit.Entry{}
|
|
|
|
|
SetAuditEntry(ctx, r)
|
|
|
|
|
return r
|
2018-11-19 17:47:03 -05:00
|
|
|
}
|
2021-04-23 12:51:12 -04:00
|
|
|
return nil
|
|
|
|
|
}
|
2019-08-12 23:32:34 -04:00
|
|
|
|
2021-04-23 12:51:12 -04:00
|
|
|
// AuditLog - logs audit logs to all audit targets.
|
|
|
|
|
func AuditLog(ctx context.Context, w http.ResponseWriter, r *http.Request, reqClaims map[string]interface{}, filterKeys ...string) {
|
|
|
|
|
// Fast exit if there is not audit target configured
|
|
|
|
|
if len(AuditTargets) == 0 {
|
2021-01-26 16:21:51 -05:00
|
|
|
return
|
2020-02-11 22:38:02 -05:00
|
|
|
}
|
2019-08-12 23:32:34 -04:00
|
|
|
|
2021-04-23 12:51:12 -04:00
|
|
|
var entry audit.Entry
|
|
|
|
|
|
|
|
|
|
if w != nil && r != nil {
|
|
|
|
|
reqInfo := GetReqInfo(ctx)
|
|
|
|
|
if reqInfo == nil {
|
|
|
|
|
return
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
entry = audit.ToEntry(w, r, reqClaims, globalDeploymentID)
|
|
|
|
|
entry.Trigger = "external-request"
|
|
|
|
|
|
|
|
|
|
for _, filterKey := range filterKeys {
|
|
|
|
|
delete(entry.ReqClaims, filterKey)
|
|
|
|
|
delete(entry.ReqQuery, filterKey)
|
|
|
|
|
delete(entry.ReqHeader, filterKey)
|
|
|
|
|
delete(entry.RespHeader, filterKey)
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
var (
|
|
|
|
|
statusCode int
|
|
|
|
|
timeToResponse time.Duration
|
|
|
|
|
timeToFirstByte time.Duration
|
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
st, ok := w.(*ResponseWriter)
|
|
|
|
|
if ok {
|
|
|
|
|
statusCode = st.StatusCode
|
|
|
|
|
timeToResponse = time.Now().UTC().Sub(st.StartTime)
|
|
|
|
|
timeToFirstByte = st.TimeToFirstByte
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
entry.API.Name = reqInfo.API
|
|
|
|
|
entry.API.Bucket = reqInfo.BucketName
|
|
|
|
|
entry.API.Object = reqInfo.ObjectName
|
|
|
|
|
entry.API.Status = http.StatusText(statusCode)
|
|
|
|
|
entry.API.StatusCode = statusCode
|
|
|
|
|
entry.API.TimeToResponse = strconv.FormatInt(timeToResponse.Nanoseconds(), 10) + "ns"
|
|
|
|
|
entry.Tags = reqInfo.GetTagsMap()
|
|
|
|
|
// ttfb will be recorded only for GET requests, Ignore such cases where ttfb will be empty.
|
|
|
|
|
if timeToFirstByte != 0 {
|
|
|
|
|
entry.API.TimeToFirstByte = strconv.FormatInt(timeToFirstByte.Nanoseconds(), 10) + "ns"
|
|
|
|
|
}
|
|
|
|
|
} else {
|
|
|
|
|
auditEntry := GetAuditEntry(ctx)
|
|
|
|
|
if auditEntry != nil {
|
|
|
|
|
entry = *auditEntry
|
|
|
|
|
}
|
2020-05-19 21:34:02 -04:00
|
|
|
}
|
2020-04-30 01:17:36 -04:00
|
|
|
|
2018-11-19 17:47:03 -05:00
|
|
|
// Send audit logs only to http targets.
|
|
|
|
|
for _, t := range AuditTargets {
|
2019-10-11 21:50:54 -04:00
|
|
|
_ = t.Send(entry, string(All))
|
2018-11-19 17:47:03 -05:00
|
|
|
}
|
|
|
|
|
}
|
