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/>.
|
2017-10-24 22:04:51 -04:00
|
|
|
|
2019-06-08 18:54:41 -04:00
|
|
|
package cmd
|
2017-10-24 22:04:51 -04:00
|
|
|
|
|
|
|
import (
|
|
|
|
"bytes"
|
2022-06-24 02:19:24 -04:00
|
|
|
"context"
|
2017-10-24 22:04:51 -04:00
|
|
|
"io"
|
2019-07-05 23:41:35 -04:00
|
|
|
"net"
|
2017-10-24 22:04:51 -04:00
|
|
|
"net/http"
|
|
|
|
"reflect"
|
2021-03-09 17:43:16 -05:00
|
|
|
"regexp"
|
2017-10-24 22:04:51 -04:00
|
|
|
"runtime"
|
2019-06-08 18:54:41 -04:00
|
|
|
"strconv"
|
2017-10-24 22:04:51 -04:00
|
|
|
"strings"
|
|
|
|
"time"
|
2019-06-08 18:54:41 -04:00
|
|
|
|
2021-05-06 11:52:02 -04:00
|
|
|
"github.com/minio/madmin-go"
|
2021-06-01 17:59:40 -04:00
|
|
|
"github.com/minio/minio/internal/handlers"
|
|
|
|
"github.com/minio/minio/internal/logger"
|
2017-10-24 22:04:51 -04:00
|
|
|
)
|
|
|
|
|
|
|
|
// 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
|
2019-07-18 18:29:17 -04:00
|
|
|
// total bytes read including header size
|
|
|
|
bytesRead int
|
2017-10-24 22:04:51 -04:00
|
|
|
}
|
|
|
|
|
2021-10-07 22:03:46 -04:00
|
|
|
func (r *recordRequest) Close() error {
|
|
|
|
// no-op
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2017-10-24 22:04:51 -04:00
|
|
|
func (r *recordRequest) Read(p []byte) (n int, err error) {
|
|
|
|
n, err = r.Reader.Read(p)
|
2019-07-18 18:29:17 -04:00
|
|
|
r.bytesRead += n
|
|
|
|
|
2017-10-24 22:04:51 -04:00
|
|
|
if r.logBody {
|
|
|
|
r.buf.Write(p[:n])
|
|
|
|
}
|
|
|
|
if err != nil {
|
|
|
|
return n, err
|
|
|
|
}
|
|
|
|
return n, err
|
|
|
|
}
|
2021-10-07 22:03:46 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
func (r *recordRequest) BodySize() int {
|
|
|
|
return r.bytesRead
|
2019-07-18 18:29:17 -04:00
|
|
|
}
|
2017-10-24 22:04:51 -04:00
|
|
|
|
|
|
|
// Return the bytes that were recorded.
|
|
|
|
func (r *recordRequest) Data() []byte {
|
2019-07-10 14:49:02 -04:00
|
|
|
// If body logging is enabled then we return the actual body
|
|
|
|
if r.logBody {
|
|
|
|
return r.buf.Bytes()
|
|
|
|
}
|
|
|
|
// ... otherwise we return <BODY> placeholder
|
2019-09-23 16:34:28 -04:00
|
|
|
return logger.BodyPlaceHolder
|
2017-10-24 22:04:51 -04:00
|
|
|
}
|
|
|
|
|
2021-03-09 17:43:16 -05:00
|
|
|
var ldapPwdRegex = regexp.MustCompile("(^.*?)LDAPPassword=([^&]*?)(&(.*?))?$")
|
|
|
|
|
|
|
|
// redact LDAP password if part of string
|
|
|
|
func redactLDAPPwd(s string) string {
|
|
|
|
parts := ldapPwdRegex.FindStringSubmatch(s)
|
|
|
|
if len(parts) > 0 {
|
|
|
|
return parts[1] + "LDAPPassword=*REDACTED*" + parts[3]
|
|
|
|
}
|
|
|
|
return s
|
|
|
|
}
|
|
|
|
|
2019-06-18 16:55:13 -04:00
|
|
|
// getOpName sanitizes the operation name for mc
|
|
|
|
func getOpName(name string) (op string) {
|
|
|
|
op = strings.TrimPrefix(name, "github.com/minio/minio/cmd.")
|
|
|
|
op = strings.TrimSuffix(op, "Handler-fm")
|
|
|
|
op = strings.Replace(op, "objectAPIHandlers", "s3", 1)
|
|
|
|
op = strings.Replace(op, "adminAPIHandlers", "admin", 1)
|
2021-04-29 22:01:43 -04:00
|
|
|
op = strings.Replace(op, "(*webAPIHandlers)", "web", 1)
|
2019-06-18 16:55:13 -04:00
|
|
|
op = strings.Replace(op, "(*storageRESTServer)", "internal", 1)
|
|
|
|
op = strings.Replace(op, "(*peerRESTServer)", "internal", 1)
|
|
|
|
op = strings.Replace(op, "(*lockRESTServer)", "internal", 1)
|
2020-02-26 15:26:47 -05:00
|
|
|
op = strings.Replace(op, "(*stsAPIHandlers)", "sts", 1)
|
2019-06-18 16:55:13 -04:00
|
|
|
op = strings.Replace(op, "LivenessCheckHandler", "healthcheck", 1)
|
|
|
|
op = strings.Replace(op, "ReadinessCheckHandler", "healthcheck", 1)
|
2020-02-26 15:26:47 -05:00
|
|
|
op = strings.Replace(op, "-fm", "", 1)
|
2019-06-18 16:55:13 -04:00
|
|
|
return op
|
|
|
|
}
|
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
type contextTraceReqType string
|
2019-07-18 18:29:17 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
const contextTraceReqKey = contextTraceReqType("request-trace-info")
|
2021-03-27 02:24:07 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Hold related tracing data of a http request, any handler
|
|
|
|
// can modify this struct to modify the trace information .
|
|
|
|
type traceCtxt struct {
|
|
|
|
requestRecorder *recordRequest
|
|
|
|
responseRecorder *logger.ResponseWriter
|
|
|
|
funcName string
|
|
|
|
}
|
2021-03-27 02:24:07 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// If trace is enabled, execute the request if it is traced by other handlers
|
|
|
|
// otherwise, generate a trace event with request information but no response.
|
|
|
|
func httpTracer(h http.Handler) http.Handler {
|
|
|
|
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
|
|
if globalTrace.NumSubscribers() == 0 {
|
|
|
|
h.ServeHTTP(w, r)
|
|
|
|
return
|
|
|
|
}
|
2021-03-27 16:19:14 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Create tracing data structure and associate it to the request context
|
|
|
|
tc := traceCtxt{}
|
|
|
|
ctx := context.WithValue(r.Context(), contextTraceReqKey, &tc)
|
|
|
|
r = r.WithContext(ctx)
|
|
|
|
|
|
|
|
// Setup a http request and response body recorder
|
|
|
|
reqRecorder := &recordRequest{Reader: r.Body}
|
|
|
|
respRecorder := logger.NewResponseWriter(w)
|
|
|
|
|
|
|
|
tc.requestRecorder = reqRecorder
|
|
|
|
tc.responseRecorder = respRecorder
|
2021-03-27 16:19:14 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Execute call.
|
|
|
|
r.Body = reqRecorder
|
|
|
|
|
|
|
|
reqStartTime := time.Now().UTC()
|
|
|
|
h.ServeHTTP(respRecorder, r)
|
|
|
|
reqEndTime := time.Now().UTC()
|
|
|
|
|
|
|
|
// Calculate input body size with headers
|
|
|
|
reqHeaders := r.Header.Clone()
|
|
|
|
reqHeaders.Set("Host", r.Host)
|
|
|
|
if len(r.TransferEncoding) == 0 {
|
|
|
|
reqHeaders.Set("Content-Length", strconv.Itoa(int(r.ContentLength)))
|
|
|
|
} else {
|
|
|
|
reqHeaders.Set("Transfer-Encoding", strings.Join(r.TransferEncoding, ","))
|
|
|
|
}
|
|
|
|
inputBytes := reqRecorder.BodySize()
|
|
|
|
for k, v := range reqHeaders {
|
|
|
|
inputBytes += len(k) + len(v)
|
2021-03-27 16:19:14 -04:00
|
|
|
}
|
2021-03-27 02:24:07 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Calculate node name
|
|
|
|
nodeName := r.Host
|
|
|
|
if nodeName == "" || globalIsDistErasure {
|
|
|
|
nodeName = globalLocalNodeName
|
|
|
|
}
|
|
|
|
if host, port, err := net.SplitHostPort(nodeName); err == nil {
|
|
|
|
if port == "443" || port == "80" {
|
|
|
|
nodeName = host
|
|
|
|
}
|
|
|
|
}
|
2020-09-18 12:30:52 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Calculate reqPath
|
|
|
|
reqPath := r.URL.RawPath
|
|
|
|
if reqPath == "" {
|
|
|
|
reqPath = r.URL.Path
|
|
|
|
}
|
2021-05-26 11:04:12 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
// Calculate function name
|
|
|
|
funcName := tc.funcName
|
|
|
|
if funcName == "" {
|
|
|
|
funcName = "<unknown>"
|
|
|
|
}
|
2020-09-18 12:30:52 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
rq := madmin.TraceRequestInfo{
|
|
|
|
Time: reqStartTime,
|
|
|
|
Proto: r.Proto,
|
|
|
|
Method: r.Method,
|
|
|
|
RawQuery: redactLDAPPwd(r.URL.RawQuery),
|
|
|
|
Client: handlers.GetSourceIP(r),
|
|
|
|
Headers: reqHeaders,
|
|
|
|
Path: reqPath,
|
|
|
|
Body: reqRecorder.Data(),
|
|
|
|
}
|
2020-09-18 12:30:52 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
rs := madmin.TraceResponseInfo{
|
|
|
|
Time: reqEndTime,
|
|
|
|
Headers: respRecorder.Header().Clone(),
|
|
|
|
StatusCode: respRecorder.StatusCode,
|
|
|
|
Body: respRecorder.Body(),
|
|
|
|
}
|
2019-07-10 14:49:02 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
cs := madmin.TraceCallStats{
|
|
|
|
Latency: rs.Time.Sub(respRecorder.StartTime),
|
|
|
|
InputBytes: inputBytes,
|
|
|
|
OutputBytes: respRecorder.Size(),
|
|
|
|
TimeToFirstByte: respRecorder.TimeToFirstByte,
|
|
|
|
}
|
2020-09-18 12:30:52 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
t := madmin.TraceInfo{
|
|
|
|
TraceType: madmin.TraceHTTP,
|
|
|
|
FuncName: funcName,
|
|
|
|
NodeName: nodeName,
|
|
|
|
Time: reqStartTime,
|
|
|
|
ReqInfo: rq,
|
|
|
|
RespInfo: rs,
|
|
|
|
CallStats: cs,
|
|
|
|
}
|
2019-07-10 14:49:02 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
globalTrace.Publish(t)
|
|
|
|
})
|
|
|
|
}
|
|
|
|
|
|
|
|
func httpTrace(f http.HandlerFunc, logBody bool) http.HandlerFunc {
|
|
|
|
return func(w http.ResponseWriter, r *http.Request) {
|
|
|
|
tc, ok := r.Context().Value(contextTraceReqKey).(*traceCtxt)
|
|
|
|
if !ok {
|
|
|
|
// Tracing is not enabled for this request
|
|
|
|
f.ServeHTTP(w, r)
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
|
|
|
tc.funcName = getOpName(runtime.FuncForPC(reflect.ValueOf(f).Pointer()).Name())
|
|
|
|
tc.requestRecorder.logBody = logBody
|
|
|
|
tc.responseRecorder.LogAllBody = logBody
|
|
|
|
tc.responseRecorder.LogErrBody = true
|
2019-07-18 18:29:17 -04:00
|
|
|
|
2022-06-24 02:19:24 -04:00
|
|
|
f.ServeHTTP(w, r)
|
2019-08-15 19:17:46 -04:00
|
|
|
}
|
2022-06-24 02:19:24 -04:00
|
|
|
}
|
|
|
|
|
|
|
|
func httpTraceAll(f http.HandlerFunc) http.HandlerFunc {
|
|
|
|
return httpTrace(f, true)
|
|
|
|
}
|
|
|
|
|
|
|
|
func httpTraceHdrs(f http.HandlerFunc) http.HandlerFunc {
|
|
|
|
return httpTrace(f, false)
|
2017-10-24 22:04:51 -04:00
|
|
|
}
|