[#369] Conditional HTTP-body log encoding

Signed-off-by: Nikita Zinkevich <n.zinkevich@yadro.com>

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
+	Enabled    bool
-	MaxBody     int64
+	MaxBody    int64
-	MaxLogSize  int
+	MaxLogSize int
-	OutputPath  string
+	OutputPath string
-	UseGzip     bool
+	UseGzip    bool
-	LogResponse 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 := filelog.getHTTPLogger(r)
-			httplog = withFieldIfExist(httplog, "headers", r.Header)
+			httplog.withFieldIfExist("query", r.URL.Query())
-			if r.ContentLength > 0 && r.ContentLength <= config.MaxBody {
+			httplog.withFieldIfExist("headers", r.Header)
-				httplog, err = withBody(httplog, r)
+
-				if err != nil {
+			payload, err := getBody(r.Body)
-					l.Warn(logs.FailedToGetRequestBody, zap.Error(err))
+			if err != nil {
-				}
+				l.Error(logs.FailedToGetHTTPBody,
+					zap.Error(err),
+					zap.String("body type", payloadLabel))
+				return
 			}
-			if !config.LogResponse {
+			r.Body = io.NopCloser(bytes.NewReader(payload))
-				httplog.Info(logs.LogHTTP)
+
-				h.ServeHTTP(w, r)
+			respBuf := &bytes.Buffer{}
-			} else {
+			wr := &responseReadWriter{ResponseWriter: w, response: respBuf}
-				var resp = bytes.Buffer{}
+			h.ServeHTTP(wr, r)
-				ww := &responseReadWriter{ResponseWriter: w, response: &resp}
+
-				h.ServeHTTP(ww, r)
+			payloadReader := io.LimitReader(bytes.NewReader(payload), config.MaxBody)
-				if int64(resp.Len()) <= config.MaxBody {
+			httplog, err = httplog.withProcessedBody(payloadLabel, payloadReader)
-					httplog.With(zap.String("response", base64.StdEncoding.EncodeToString(resp.Bytes()))).
+			if err != nil {
-						Info(logs.LogHTTP)
+				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.
+// getBody reads http.Body and returns its io.Reader.
-func withBody(httplog *zap.Logger, r *http.Request) (*zap.Logger, error) {
+func getBody(httpBody io.ReadCloser) ([]byte, error) {
-	body, err := io.ReadAll(r.Body)
+	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()
+	return body, nil
-	r.Body = io.NopCloser(bytes.NewBuffer(body))
+}
 
-	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
 }

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

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
+	FailedToInitializeHTTPLogger                         = "failed to initialize http logger"                                                                  // Error in ../../api/middleware/log_http.go
-	FailedToReloadHTTPFileLogger                         = "failed to reload http file logger"                                                                 // Warn in ../../api/middleware/log_http.go
+	FailedToReloadHTTPFileLogger                         = "failed to reload http file logger"                                                                 // Error in ../../api/middleware/log_http.go
-	FailedToGetRequestBody                               = "failed to get request body"                                                                        // Warn 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