From 91995f27f6e1708f810aa02370161a070c6d5bf1 Mon Sep 17 00:00:00 2001 From: Nikita Zinkevich Date: Fri, 12 Jul 2024 15:31:43 +0300 Subject: [PATCH] [#369] Enhanced http requests logging Signed-off-by: Nikita Zinkevich Signed-off-by: Alex Vanin --- api/middleware/log_http.go | 61 +++++++++++++++++++ api/router.go | 2 + cmd/s3-gw/app.go | 8 +++ cmd/s3-gw/app_settings.go | 7 +++ config/config.yaml | 6 ++ internal/logs/logs.go | 116 +++++++++++++++++++------------------ 6 files changed, 143 insertions(+), 57 deletions(-) create mode 100644 api/middleware/log_http.go diff --git a/api/middleware/log_http.go b/api/middleware/log_http.go new file mode 100644 index 00000000..ad1dd8a5 --- /dev/null +++ b/api/middleware/log_http.go @@ -0,0 +1,61 @@ +package middleware + +import ( + "io" + "net/http" + + "git.frostfs.info/TrueCloudLab/frostfs-s3-gw/internal/logs" + "go.uber.org/zap" +) + +type LogHTTPSettings struct { + Enabled bool + MaxBody int64 +} + +// 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) { + if !settings.Enabled { + h.ServeHTTP(w, r) + return + } + var httplog = l.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 <= settings.MaxBody { + var err error + httplog, err = withBody(httplog, r) + if err != nil { + l.Error("read body error") + } + } + httplog.Info(logs.RequestHTTP) + h.ServeHTTP(w, r) + }) + } +} + +func withBody(httplog *zap.Logger, r *http.Request) (*zap.Logger, error) { + var body = make([]byte, r.ContentLength) + _, err := r.Body.Read(body) + if err != nil && err != io.EOF { + return nil, err + } + httplog = httplog.With(zap.String("body", string(body))) + + return httplog, nil +} + +func withFieldIfExist(log *zap.Logger, label string, data map[string][]string) *zap.Logger { + if len(data) != 0 { + log = log.With(zap.Any(label, data)) + } + return log +} diff --git a/api/router.go b/api/router.go index df151439..a86e53b4 100644 --- a/api/router.go +++ b/api/router.go @@ -108,6 +108,7 @@ type Config struct { Handler Handler Center s3middleware.Center Log *zap.Logger + LogHTTP s3middleware.LogHTTPSettings Metrics *metrics.AppMetrics MiddlewareSettings Settings @@ -125,6 +126,7 @@ type Config struct { func NewRouter(cfg Config) *chi.Mux { api := chi.NewRouter() api.Use( + s3middleware.LogHTTP(cfg.Log, cfg.LogHTTP), s3middleware.Request(cfg.Log, cfg.MiddlewareSettings), middleware.ThrottleWithOpts(cfg.Throttle), middleware.Recoverer, diff --git a/cmd/s3-gw/app.go b/cmd/s3-gw/app.go index 86d56481..24ff9933 100644 --- a/cmd/s3-gw/app.go +++ b/cmd/s3-gw/app.go @@ -87,6 +87,8 @@ type ( appSettings struct { logLevel zap.AtomicLevel + httpLoggingEnabled bool + maxHTTPLogBody int64 maxClient maxClientsConfig defaultMaxAge int notificatorEnabled bool @@ -211,6 +213,8 @@ func newAppSettings(log *Logger, v *viper.Viper, key *keys.PrivateKey) *appSetti defaultMaxAge: fetchDefaultMaxAge(v, log.logger), notificatorEnabled: v.GetBool(cfgEnableNATS), frostfsidValidation: v.GetBool(cfgFrostfsIDValidationEnabled), + httpLoggingEnabled: v.GetBool(cfgLoggerRequestEnabled), + maxHTTPLogBody: v.GetInt64(cfgLoggerRequestMaxBody), } settings.resolveZoneList = v.GetStringSlice(cfgResolveBucketAllow) @@ -727,6 +731,10 @@ func (a *App) Serve(ctx context.Context) { Handler: a.api, Center: a.ctr, Log: a.log, + LogHTTP: s3middleware.LogHTTPSettings{ + Enabled: a.settings.httpLoggingEnabled, + MaxBody: a.settings.maxHTTPLogBody, + }, Metrics: a.metrics, Domains: domains, diff --git a/cmd/s3-gw/app_settings.go b/cmd/s3-gw/app_settings.go index 33e7e0e7..a345f906 100644 --- a/cmd/s3-gw/app_settings.go +++ b/cmd/s3-gw/app_settings.go @@ -75,6 +75,9 @@ const ( // Settings. cfgLoggerLevel = "logger.level" cfgLoggerDestination = "logger.destination" + cfgLoggerRequestEnabled = "http_logging.enabled" + cfgLoggerRequestMaxBody = "http_logging.max_body" + // Wallet. cfgWalletPath = "wallet.path" cfgWalletAddress = "wallet.address" @@ -739,6 +742,10 @@ func newSettings() *viper.Viper { v.SetDefault(cfgLoggerLevel, "debug") v.SetDefault(cfgLoggerDestination, "stdout") + // http logger + v.SetDefault(cfgLoggerRequestEnabled, false) + v.SetDefault(cfgLoggerRequestMaxBody, 1024) + // pool: v.SetDefault(cfgPoolErrorThreshold, defaultPoolErrorThreshold) v.SetDefault(cfgStreamTimeout, defaultStreamTimeout) diff --git a/config/config.yaml b/config/config.yaml index 28241dad..7a9a11e8 100644 --- a/config/config.yaml +++ b/config/config.yaml @@ -54,6 +54,12 @@ logger: level: debug destination: stdout +# log http request data (URI, headers, query, etc) +http_logging: + enabled: false + # max body size to log + max_body: 1024 + # RPC endpoint and order of resolving of bucket names rpc_endpoint: http://morph-chain.frostfs.devenv:30333 resolve_order: diff --git a/internal/logs/logs.go b/internal/logs/logs.go index b723ffcf..ad2e3a57 100644 --- a/internal/logs/logs.go +++ b/internal/logs/logs.go @@ -105,61 +105,63 @@ const ( FailedToPassAuthentication = "failed to pass authentication" // Error in ../../api/middleware/auth.go FailedToResolveCID = "failed to resolve CID" // Debug in ../../api/middleware/metrics.go RequestStart = "request start" // Info in ../../api/middleware/reqinfo.go - FailedToUnescapeObjectName = "failed to unescape object name" // Warn in ../../api/middleware/reqinfo.go - CouldNotHandleMessage = "could not handle message" // Error in ../../api/notifications/controller.go - CouldNotACKMessage = "could not ACK message" // Error in ../../api/notifications/controller.go - CouldntMarshalAnEvent = "couldn't marshal an event" // Error in ../../api/notifications/controller.go - CouldntSendAnEventToTopic = "couldn't send an event to topic" // Error in ../../api/notifications/controller.go - InvalidDefaultMaxAge = "invalid defaultMaxAge" // Fatal in ../../cmd/s3-gw/app_settings.go - CantShutDownService = "can't shut down service" // Panic in ../../cmd/s3-gw/service.go - CouldntGenerateRandomKey = "couldn't generate random key" // Fatal in ../../cmd/s3-gw/app.go - FailedToEnableNotifications = "failed to enable notifications" // Fatal in ../../cmd/s3-gw/app.go - CouldntInitializeLayer = "couldn't initialize layer" // Fatal in ../../cmd/s3-gw/app.go - FailedToCreateResolver = "failed to create resolver" // Fatal in ../../cmd/s3-gw/app.go - CouldNotLoadFrostFSPrivateKey = "could not load FrostFS private key" // Fatal in ../../cmd/s3-gw/app.go - FailedToCreateConnectionPool = "failed to create connection pool" // Fatal in ../../cmd/s3-gw/app.go - FailedToDialConnectionPool = "failed to dial connection pool" // Fatal in ../../cmd/s3-gw/app.go - FailedToCreateTreePool = "failed to create tree pool" // Fatal in ../../cmd/s3-gw/app.go - FailedToDialTreePool = "failed to dial tree pool" // Fatal in ../../cmd/s3-gw/app.go - ListenAndServe = "listen and serve" // Fatal in ../../cmd/s3-gw/app.go - NoHealthyServers = "no healthy servers" // Fatal in ../../cmd/s3-gw/app.go - CouldNotInitializeAPIHandler = "could not initialize API handler" // Fatal in ../../cmd/s3-gw/app.go - RuntimeSoftMemoryDefinedWithGOMEMLIMIT = "soft runtime memory defined with GOMEMLIMIT environment variable, config value skipped" // Warn in ../../cmd/s3-gw/app.go - RuntimeSoftMemoryLimitUpdated = "soft runtime memory limit value updated" // Info in ../../cmd/s3-gw/app.go - AnonRequestSkipFrostfsIDValidation = "anon request, skip FrostfsID validation" // Debug in ../../api/middleware/auth.go - FrostfsIDValidationFailed = "FrostfsID validation failed" // Error in ../../api/middleware/auth.go - InitFrostfsIDContractFailed = "init frostfsid contract failed" // Fatal in ../../cmd/s3-gw/app.go - InitPolicyContractFailed = "init policy contract failed" // Fatal in ../../cmd/s3-gw/app.go - ControlAPIHealthcheck = "healthcheck request" - ControlAPIPutPolicies = "put policies request" - ControlAPIRemovePolicies = "remove policies request" - ControlAPIGetPolicy = "get policy request" - ControlAPIListPolicies = "list policies request" - PolicyValidationFailed = "policy validation failed" - ParseTreeNode = "parse tree node" - FailedToGetRealObjectSize = "failed to get real object size" - CouldntDeleteObjectFromStorageContinueDeleting = "couldn't delete object from storage, continue deleting from tree" - CouldntPutAccessBoxIntoCache = "couldn't put accessbox into cache" - InvalidAccessBoxCacheRemovingCheckInterval = "invalid accessbox check removing interval, using default value" - CouldNotCloseRequestBody = "could not close request body" - BucketOwnerKeyIsMissing = "bucket owner key is missing" - SettingsNodeInvalidOwnerKey = "settings node: invalid owner key" - SuccessfulAuth = "successful auth" - PolicyRequest = "policy request" - FailedToGenerateRequestID = "failed to generate request id" - InvalidBucketObjectLockEnabledHeader = "invalid X-Amz-Bucket-Object-Lock-Enabled header" - InvalidTreeKV = "invalid tree service meta KV" - FailedToWriteResponse = "failed to write response" - PolicyCouldntBeConvertedToNativeRules = "policy couldn't be converted to native rules, only s3 rules be applied" - CouldntCacheSubject = "couldn't cache subject info" - UserGroupsListIsEmpty = "user groups list is empty, subject not found" - CouldntCacheUserKey = "couldn't cache user key" - FoundSeveralBucketCorsNodes = "found several bucket cors nodes, latest be used" - FoundSeveralNotificationConfigurationNodes = "found several notification configuration nodes, latest be used" - FoundSeveralObjectTaggingNodes = "found several object tagging nodes, latest be used" - FoundSeveralBucketTaggingNodes = "found several bucket tagging nodes, latest be used" - FoundSeveralBucketSettingsNodes = "found several bucket settings nodes, latest be used" - UnexpectedMultiNodeIDsInSubTreeMultiParts = "unexpected multi node ids in sub tree multi parts" - FoundSeveralSystemNodes = "found several system nodes, latest be used" - FailedToParsePartInfo = "failed to parse part info" + + RequestHTTP = "http request" + FailedToUnescapeObjectName = "failed to unescape object name" // Warn in ../../api/middleware/reqinfo.go + CouldNotHandleMessage = "could not handle message" // Error in ../../api/notifications/controller.go + CouldNotACKMessage = "could not ACK message" // Error in ../../api/notifications/controller.go + CouldntMarshalAnEvent = "couldn't marshal an event" // Error in ../../api/notifications/controller.go + CouldntSendAnEventToTopic = "couldn't send an event to topic" // Error in ../../api/notifications/controller.go + InvalidDefaultMaxAge = "invalid defaultMaxAge" // Fatal in ../../cmd/s3-gw/app_settings.go + CantShutDownService = "can't shut down service" // Panic in ../../cmd/s3-gw/service.go + CouldntGenerateRandomKey = "couldn't generate random key" // Fatal in ../../cmd/s3-gw/app.go + FailedToEnableNotifications = "failed to enable notifications" // Fatal in ../../cmd/s3-gw/app.go + CouldntInitializeLayer = "couldn't initialize layer" // Fatal in ../../cmd/s3-gw/app.go + FailedToCreateResolver = "failed to create resolver" // Fatal in ../../cmd/s3-gw/app.go + CouldNotLoadFrostFSPrivateKey = "could not load FrostFS private key" // Fatal in ../../cmd/s3-gw/app.go + FailedToCreateConnectionPool = "failed to create connection pool" // Fatal in ../../cmd/s3-gw/app.go + FailedToDialConnectionPool = "failed to dial connection pool" // Fatal in ../../cmd/s3-gw/app.go + FailedToCreateTreePool = "failed to create tree pool" // Fatal in ../../cmd/s3-gw/app.go + FailedToDialTreePool = "failed to dial tree pool" // Fatal in ../../cmd/s3-gw/app.go + ListenAndServe = "listen and serve" // Fatal in ../../cmd/s3-gw/app.go + NoHealthyServers = "no healthy servers" // Fatal in ../../cmd/s3-gw/app.go + CouldNotInitializeAPIHandler = "could not initialize API handler" // Fatal in ../../cmd/s3-gw/app.go + RuntimeSoftMemoryDefinedWithGOMEMLIMIT = "soft runtime memory defined with GOMEMLIMIT environment variable, config value skipped" // Warn in ../../cmd/s3-gw/app.go + RuntimeSoftMemoryLimitUpdated = "soft runtime memory limit value updated" // Info in ../../cmd/s3-gw/app.go + AnonRequestSkipFrostfsIDValidation = "anon request, skip FrostfsID validation" // Debug in ../../api/middleware/auth.go + FrostfsIDValidationFailed = "FrostfsID validation failed" // Error in ../../api/middleware/auth.go + InitFrostfsIDContractFailed = "init frostfsid contract failed" // Fatal in ../../cmd/s3-gw/app.go + InitPolicyContractFailed = "init policy contract failed" // Fatal in ../../cmd/s3-gw/app.go + ControlAPIHealthcheck = "healthcheck request" + ControlAPIPutPolicies = "put policies request" + ControlAPIRemovePolicies = "remove policies request" + ControlAPIGetPolicy = "get policy request" + ControlAPIListPolicies = "list policies request" + PolicyValidationFailed = "policy validation failed" + ParseTreeNode = "parse tree node" + FailedToGetRealObjectSize = "failed to get real object size" + CouldntDeleteObjectFromStorageContinueDeleting = "couldn't delete object from storage, continue deleting from tree" + CouldntPutAccessBoxIntoCache = "couldn't put accessbox into cache" + InvalidAccessBoxCacheRemovingCheckInterval = "invalid accessbox check removing interval, using default value" + CouldNotCloseRequestBody = "could not close request body" + BucketOwnerKeyIsMissing = "bucket owner key is missing" + SettingsNodeInvalidOwnerKey = "settings node: invalid owner key" + SuccessfulAuth = "successful auth" + PolicyRequest = "policy request" + FailedToGenerateRequestID = "failed to generate request id" + InvalidBucketObjectLockEnabledHeader = "invalid X-Amz-Bucket-Object-Lock-Enabled header" + InvalidTreeKV = "invalid tree service meta KV" + FailedToWriteResponse = "failed to write response" + PolicyCouldntBeConvertedToNativeRules = "policy couldn't be converted to native rules, only s3 rules be applied" + CouldntCacheSubject = "couldn't cache subject info" + UserGroupsListIsEmpty = "user groups list is empty, subject not found" + CouldntCacheUserKey = "couldn't cache user key" + FoundSeveralBucketCorsNodes = "found several bucket cors nodes, latest be used" + FoundSeveralNotificationConfigurationNodes = "found several notification configuration nodes, latest be used" + FoundSeveralObjectTaggingNodes = "found several object tagging nodes, latest be used" + FoundSeveralBucketTaggingNodes = "found several bucket tagging nodes, latest be used" + FoundSeveralBucketSettingsNodes = "found several bucket settings nodes, latest be used" + UnexpectedMultiNodeIDsInSubTreeMultiParts = "unexpected multi node ids in sub tree multi parts" + FoundSeveralSystemNodes = "found several system nodes, latest be used" + FailedToParsePartInfo = "failed to parse part info" )