[#369] Enhanced http requests logging

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

api/middleware/log_http.go

@@ -0,0 +1,245 @@
+//go:build loghttp
+
+package middleware
+
+import (
+	"bytes"
+	"io"
+	"net/http"
+	"os"
+
+	"git.frostfs.info/TrueCloudLab/frostfs-s3-gw/internal/logs"
+	"git.frostfs.info/TrueCloudLab/frostfs-s3-gw/pkg/detector"
+	"git.frostfs.info/TrueCloudLab/frostfs-s3-gw/pkg/xmlutils"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"gopkg.in/natefinch/lumberjack.v2"
+)
+
+type (
+	LogHTTPSettings interface {
+		LogHTTPConfig() LogHTTPConfig
+	}
+	LogHTTPConfig struct {
+		Enabled    bool
+		MaxBody    int64
+		MaxLogSize int
+		OutputPath string
+		UseGzip    bool
+		log        *httpLogger
+	}
+	httpLogger struct {
+		*zap.Logger
+		logRoller *lumberjack.Logger
+	}
+	// Implementation of zap.Sink for using lumberjack.
+	lumberjackSink struct {
+		*lumberjack.Logger
+	}
+	// responseReadWriter helps read http response body.
+	responseReadWriter struct {
+		http.ResponseWriter
+		response   *bytes.Buffer
+		statusCode int
+	}
+)
+
+const (
+	payloadLabel  = "payload"
+	responseLabel = "response"
+)
+
+func (lumberjackSink) Sync() error {
+	return nil
+}
+
+func (lc *LogHTTPConfig) InitHTTPLogger(log *zap.Logger) {
+	if err := lc.initHTTPLogger(); err != nil {
+		log.Error(logs.FailedToInitializeHTTPLogger, zap.Error(err))
+	}
+}
+
+// initHTTPLogger returns registers zap sink and returns new httpLogger.
+func (lc *LogHTTPConfig) initHTTPLogger() (err error) {
+	lc.log = &httpLogger{
+		Logger:    zap.NewNop(),
+		logRoller: &lumberjack.Logger{},
+	}
+	c := newLoggerConfig()
+	lc.log.Logger, err = c.Build()
+	if err != nil {
+		return err
+	}
+	lc.setLogOutput()
+
+	return nil
+}
+
+// newLoggerConfig creates new zap.Config with disabled base fields.
+func newLoggerConfig() zap.Config {
+	c := zap.NewProductionConfig()
+	c.DisableCaller = true
+	c.DisableStacktrace = true
+	c.EncoderConfig = newEncoderConfig()
+	c.Sampling = nil
+
+	return c
+}
+
+func (lc *LogHTTPConfig) setLogOutput() {
+	var output zapcore.WriteSyncer
+	switch lc.OutputPath {
+	case "", StdoutPath:
+		output = zapcore.AddSync(os.Stdout)
+	case StderrPath:
+		output = zapcore.AddSync(os.Stderr)
+	default:
+		output = zapcore.AddSync(&lumberjack.Logger{
+			Filename: lc.OutputPath,
+			MaxSize:  lc.MaxLogSize,
+			Compress: lc.UseGzip,
+		})
+	}
+
+	// create logger with new sync
+	lc.log.Logger = lc.log.Logger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core {
+		return zapcore.NewCore(zapcore.NewJSONEncoder(newEncoderConfig()), output, zapcore.InfoLevel)
+	}))
+}
+
+func newEncoderConfig() zapcore.EncoderConfig {
+	c := zap.NewProductionEncoderConfig()
+	c.MessageKey = zapcore.OmitKey
+	c.LevelKey = zapcore.OmitKey
+	c.TimeKey = zapcore.OmitKey
+	c.FunctionKey = zapcore.OmitKey
+
+	return c
+}
+
+func (ww *responseReadWriter) Write(data []byte) (int, error) {
+	ww.response.Write(data)
+	return ww.ResponseWriter.Write(data)
+}
+
+func (ww *responseReadWriter) WriteHeader(code int) {
+	ww.statusCode = code
+	ww.ResponseWriter.WriteHeader(code)
+}
+
+func (ww *responseReadWriter) Flush() {
+	if f, ok := ww.ResponseWriter.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+// LogHTTP logs http parameters from s3 request.
+func LogHTTP(l *zap.Logger, settings LogHTTPSettings) Func {
+	return func(h http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			config := settings.LogHTTPConfig()
+			if !config.Enabled || config.log == nil {
+				h.ServeHTTP(w, r)
+				return
+			}
+
+			httplog := config.log.getHTTPLogger(r).
+				withFieldIfExist("query", r.URL.Query()).
+				withFieldIfExist("headers", r.Header)
+
+			payload := getBody(r.Body, l)
+			r.Body = io.NopCloser(bytes.NewReader(payload))
+
+			payloadReader := io.LimitReader(bytes.NewReader(payload), config.MaxBody)
+			httplog = httplog.withProcessedBody(payloadLabel, payloadReader, l)
+
+			wr := newResponseReadWriter(w)
+			h.ServeHTTP(wr, r)
+
+			respReader := io.LimitReader(wr.response, config.MaxBody)
+			httplog = httplog.withProcessedBody(responseLabel, respReader, l)
+			httplog = httplog.with(zap.Int("status", wr.statusCode))
+
+			httplog.Info(logs.LogHTTP)
+		})
+	}
+}
+
+// withFieldIfExist checks whether data is not empty and attach it to log output.
+func (lg *httpLogger) withFieldIfExist(label string, data map[string][]string) *httpLogger {
+	if len(data) != 0 {
+		return lg.with(zap.Any(label, data))
+	}
+	return lg
+}
+
+func (lg *httpLogger) with(fields ...zap.Field) *httpLogger {
+	return &httpLogger{
+		Logger:    lg.Logger.With(fields...),
+		logRoller: lg.logRoller,
+	}
+}
+
+func (lg *httpLogger) getHTTPLogger(r *http.Request) *httpLogger {
+	return lg.with(
+		zap.String("from", r.RemoteAddr),
+		zap.String("URI", r.RequestURI),
+		zap.String("method", r.Method),
+		zap.String("protocol", r.Proto),
+	)
+}
+
+func (lg *httpLogger) withProcessedBody(label string, bodyReader io.Reader, l *zap.Logger) *httpLogger {
+	resp, err := processBody(bodyReader)
+	if err != nil {
+		l.Error(logs.FailedToProcessHTTPBody,
+			zap.Error(err),
+			zap.String("body type", payloadLabel))
+		return lg
+	}
+
+	return lg.with(zap.ByteString(label, resp))
+}
+
+func newResponseReadWriter(w http.ResponseWriter) *responseReadWriter {
+	return &responseReadWriter{
+		ResponseWriter: w,
+		response:       &bytes.Buffer{},
+	}
+}
+
+func getBody(httpBody io.ReadCloser, l *zap.Logger) []byte {
+	defer func(httpBody io.ReadCloser) {
+		if err := httpBody.Close(); err != nil {
+			l.Error(logs.FailedToCloseHTTPBody, zap.Error(err))
+		}
+	}(httpBody)
+
+	body, err := io.ReadAll(httpBody)
+	if err != nil {
+		l.Error(logs.FailedToReadHTTPBody,
+			zap.Error(err),
+			zap.String("body type", payloadLabel))
+		return nil
+	}
+	return body
+}
+
+// processBody reads body and base64 encode it if it's not XML.
+func processBody(bodyReader io.Reader) ([]byte, error) {
+	resultBody := &bytes.Buffer{}
+	detect := detector.NewDetector(bodyReader, xmlutils.DetectXML)
+	dataType, err := detect.Detect()
+	if err != nil {
+		return nil, err
+	}
+	writer := xmlutils.ChooseWriter(dataType, resultBody)
+	if _, err = io.Copy(writer, detect.RestoredReader()); err != nil {
+		return nil, err
+	}
+	if err = writer.Close(); err != nil {
+		return nil, err
+	}
+
+	return resultBody.Bytes(), nil
+}