diff --git a/api/middleware/log_http.go b/api/middleware/log_http.go index d9fc33d..8d1512a 100644 --- a/api/middleware/log_http.go +++ b/api/middleware/log_http.go @@ -4,25 +4,24 @@ package middleware import ( "bytes" - "encoding/base64" - "fmt" "io" "net/http" "net/url" "git.frostfs.info/TrueCloudLab/frostfs-s3-gw/internal/logs" + "git.frostfs.info/TrueCloudLab/frostfs-s3-gw/playback/utils" "go.uber.org/zap" "go.uber.org/zap/zapcore" "gopkg.in/natefinch/lumberjack.v2" ) type LogHTTPConfig struct { - Enabled bool - MaxBody int64 - MaxLogSize int - OutputPath string - UseGzip bool - LogResponse bool + Enabled bool + MaxBody int64 + MaxLogSize int + OutputPath string + UseGzip bool + LogBefore bool } type fileLogger struct { @@ -30,6 +29,11 @@ type fileLogger struct { logRoller *lumberjack.Logger } +const ( + payloadLabel = "payload" + responseLabel = "response" +) + var filelog = fileLogger{} // newFileLogger returns registers zap sink and returns new fileLogger. @@ -120,7 +124,7 @@ func LogHTTP(l *zap.Logger, config *LogHTTPConfig) Func { var err error filelog, err = newFileLogger(config) if err != nil { - l.Warn(logs.FailedToInitializeHTTPLogger) + l.Error(logs.FailedToInitializeHTTPLogger) return func(h http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { h.ServeHTTP(w, r) @@ -133,38 +137,68 @@ func LogHTTP(l *zap.Logger, config *LogHTTPConfig) Func { h.ServeHTTP(w, r) return } - var httplog = filelog.With( - zap.String("from", r.RemoteAddr), - zap.String("URI", r.RequestURI), - zap.String("method", r.Method), - ) - httplog = withFieldIfExist(httplog, "query", r.URL.Query()) - httplog = withFieldIfExist(httplog, "headers", r.Header) - if r.ContentLength > 0 && r.ContentLength <= config.MaxBody { - httplog, err = withBody(httplog, r) - if err != nil { - l.Warn(logs.FailedToGetRequestBody, zap.Error(err)) - } + httplog := filelog.getHTTPLogger(r) + httplog.withFieldIfExist("query", r.URL.Query()) + httplog.withFieldIfExist("headers", r.Header) + + payload, err := getBody(r.Body) + if err != nil { + l.Error(logs.FailedToGetHTTPBody, + zap.Error(err), + zap.String("body type", payloadLabel)) + return } - if !config.LogResponse { - httplog.Info(logs.LogHTTP) - h.ServeHTTP(w, r) - } else { - var resp = bytes.Buffer{} - ww := &responseReadWriter{ResponseWriter: w, response: &resp} - h.ServeHTTP(ww, r) - if int64(resp.Len()) <= config.MaxBody { - httplog.With(zap.String("response", base64.StdEncoding.EncodeToString(resp.Bytes()))). - Info(logs.LogHTTP) - } + r.Body = io.NopCloser(bytes.NewReader(payload)) + + respBuf := &bytes.Buffer{} + wr := &responseReadWriter{ResponseWriter: w, response: respBuf} + h.ServeHTTP(wr, r) + + payloadReader := io.LimitReader(bytes.NewReader(payload), config.MaxBody) + httplog, err = httplog.withProcessedBody(payloadLabel, payloadReader) + if err != nil { + l.Error(logs.FailedToProcessHTTPBody, + zap.Error(err), + zap.String("body type", payloadLabel)) } + respReader := io.LimitReader(respBuf, config.MaxBody) + httplog, err = httplog.withProcessedBody(responseLabel, respReader) + if err != nil { + l.Error(logs.FailedToProcessHTTPBody, + zap.Error(err), + zap.String("body type", responseLabel)) + } + + httplog.Info(logs.LogHTTP) }) } } +func (f *fileLogger) getHTTPLogger(r *http.Request) *fileLogger { + return &fileLogger{ + Logger: f.Logger.With( + zap.String("from", r.RemoteAddr), + zap.String("URI", r.RequestURI), + zap.String("method", r.Method), + zap.String("protocol", r.Proto), + ), + logRoller: f.logRoller, + } +} + +func (f *fileLogger) withProcessedBody(label string, bodyReader io.Reader) (*fileLogger, error) { + resp, err := ProcessBody(bodyReader) + if err != nil { + return f, err + } + f.Logger = f.Logger.With(zap.ByteString(label, resp)) + + return f, nil +} + // newLoggerConfig creates new zap.Config with disabled base fields. -func (*fileLogger) newLoggerConfig() zap.Config { +func (f *fileLogger) newLoggerConfig() zap.Config { c := zap.NewProductionConfig() c.DisableCaller = true c.DisableStacktrace = true @@ -176,24 +210,37 @@ func (*fileLogger) newLoggerConfig() zap.Config { return c } -// withBody reads body and attach it to log output. -func withBody(httplog *zap.Logger, r *http.Request) (*zap.Logger, error) { - body, err := io.ReadAll(r.Body) +// getBody reads http.Body and returns its io.Reader. +func getBody(httpBody io.ReadCloser) ([]byte, error) { + defer httpBody.Close() + + body, err := io.ReadAll(httpBody) if err != nil { - return nil, fmt.Errorf("read body error: %w", err) + return nil, err } - defer r.Body.Close() - r.Body = io.NopCloser(bytes.NewBuffer(body)) + return body, nil +} - httplog = httplog.With(zap.String("body", base64.StdEncoding.EncodeToString(body))) +// ProcessBody reads body and base64 encode it if it's not XML. +func ProcessBody(bodyReader io.Reader) ([]byte, error) { + resultBody := &bytes.Buffer{} + isXML, checkedPart, err := utils.DetectXML(bodyReader) + if err != nil { + return nil, err + } + writer := utils.ChooseWriter(isXML, resultBody) + writer.Write(checkedPart) + if _, err = io.Copy(writer, bodyReader); err != nil { + return nil, err + } - return httplog, nil + return resultBody.Bytes(), nil } // withFieldIfExist checks whether data is not empty and attach it to log output. -func withFieldIfExist(log *zap.Logger, label string, data map[string][]string) *zap.Logger { +func (f *fileLogger) withFieldIfExist(label string, data map[string][]string) *fileLogger { if len(data) != 0 { - log = log.With(zap.Any(label, data)) + f.Logger = f.Logger.With(zap.Any(label, data)) } - return log + return f } diff --git a/cmd/s3-gw/app.go b/cmd/s3-gw/app.go index 8795b47..1ef37b3 100644 --- a/cmd/s3-gw/app.go +++ b/cmd/s3-gw/app.go @@ -573,7 +573,7 @@ func (s *appSettings) updateHTTPLoggingSettings(cfg *viper.Viper, log *zap.Logge s.httpLogging.MaxLogSize = cfg.GetInt(cfgHTTPLoggingMaxLogSize) s.httpLogging.OutputPath = cfg.GetString(cfgHTTPLoggingDestination) s.httpLogging.UseGzip = cfg.GetBool(cfgHTTPLoggingGzip) - s.httpLogging.LogResponse = cfg.GetBool(cfgHTTPLoggingLogResponse) + s.httpLogging.LogBefore = cfg.GetBool(cfgHTTPLoggingLogResponse) if err := s3middleware.ReloadFileLogger(s.httpLogging); err != nil { log.Error(logs.FailedToReloadHTTPFileLogger, zap.Error(err)) } diff --git a/internal/logs/logs.go b/internal/logs/logs.go index fccdf61..d579332 100644 --- a/internal/logs/logs.go +++ b/internal/logs/logs.go @@ -101,9 +101,10 @@ const ( FailedToResolveCID = "failed to resolve CID" // Debug in ../../api/middleware/metrics.go RequestStart = "request start" // Info in ../../api/middleware/reqinfo.go LogHTTP = "http log" // Info in ../../api/middleware/log_http.go - FailedToInitializeHTTPLogger = "failed to initialize http logger" // Warn in ../../api/middleware/log_http.go - FailedToReloadHTTPFileLogger = "failed to reload http file logger" // Warn in ../../api/middleware/log_http.go - FailedToGetRequestBody = "failed to get request body" // Warn in ../../api/middleware/log_http.go + FailedToInitializeHTTPLogger = "failed to initialize http logger" // Error in ../../api/middleware/log_http.go + FailedToReloadHTTPFileLogger = "failed to reload http file logger" // Error in ../../api/middleware/log_http.go + FailedToGetHTTPBody = "failed to get http body" // Error in ../../api/middleware/log_http.go + FailedToProcessHTTPBody = "failed to process http body" // Error in ../../api/middleware/log_http.go LogHTTPDisabledInThisBuild = "http logging disabled in this build" // Warn in ../../api/middleware/log_http_stub.go FailedToUnescapeObjectName = "failed to unescape object name" // Warn in ../../api/middleware/reqinfo.go InvalidDefaultMaxAge = "invalid defaultMaxAge" // Fatal in ../../cmd/s3-gw/app_settings.go