[#461] Configure logger sampling policy

Signed-off-by: Pavel Pogodaev <p.pogodaev@yadro.com>

cmd/s3-gw/app_settings.go

@@ -41,6 +41,8 @@ const (
 	defaultStreamTimeout      = 10 * time.Second
 	defaultShutdownTimeout    = 15 * time.Second
 
+	defaultLoggerSamplerInterval = 1 * time.Second
+
 	defaultGracefulCloseOnSwitchTimeout = 10 * time.Second
 
 	defaultPoolErrorThreshold uint32 = 100
@@ -81,6 +83,11 @@ const ( // Settings.
 	cfgLoggerLevel       = "logger.level"
 	cfgLoggerDestination = "logger.destination"
 
+	cfgLoggerSamplingEnabled    = "logger.sampling.enabled"
+	cfgLoggerSamplingInitial    = "logger.sampling.initial"
+	cfgLoggerSamplingThereafter = "logger.sampling.thereafter"
+	cfgLoggerSamplingInterval   = "logger.sampling.interval"
+
 	// HttpLogging.
 	cfgHTTPLoggingEnabled     = "http_logging.enabled"
 	cfgHTTPLoggingMaxBody     = "http_logging.max_body"
@@ -788,6 +795,10 @@ func newSettings() *viper.Viper {
 	// logger:
 	v.SetDefault(cfgLoggerLevel, "debug")
 	v.SetDefault(cfgLoggerDestination, "stdout")
+	v.SetDefault(cfgLoggerSamplingEnabled, false)
+	v.SetDefault(cfgLoggerSamplingThereafter, 100)
+	v.SetDefault(cfgLoggerSamplingInitial, 100)
+	v.SetDefault(cfgLoggerSamplingInterval, defaultLoggerSamplerInterval)
 
 	// http logger
 	v.SetDefault(cfgHTTPLoggingEnabled, false)
@@ -1031,9 +1042,9 @@ func pickLogger(v *viper.Viper) *Logger {
 
 	switch dest {
 	case destinationStdout:
-		return newStdoutLogger(lvl)
+		return newStdoutLogger(v, lvl)
 	case destinationJournald:
-		return newJournaldLogger(lvl)
+		return newJournaldLogger(v, lvl)
 	default:
 		panic(fmt.Sprintf("wrong destination for logger: %s", dest))
 	}
@@ -1046,53 +1057,74 @@ func pickLogger(v *viper.Viper) *Logger {
 //   - parameterized level (debug by default)
 //   - console encoding
 //   - ISO8601 time encoding
+//   - sampling intervals
 //
 // and atomic log level to dynamically change it.
 //
 // Logger records a stack trace for all messages at or above fatal level.
 //
 // See also zapcore.Level, zap.NewProductionConfig, zap.AddStacktrace.
-func newStdoutLogger(lvl zapcore.Level) *Logger {
-	c := zap.NewProductionConfig()
-	c.Level = zap.NewAtomicLevelAt(lvl)
-	c.Encoding = "console"
-	c.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
+func newStdoutLogger(v *viper.Viper, lvl zapcore.Level) *Logger {
+	stdout := zapcore.AddSync(os.Stderr)
+	level := zap.NewAtomicLevelAt(lvl)
 
-	l, err := c.Build(
-		zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel)),
-	)
-	if err != nil {
-		panic(fmt.Sprintf("build zap logger instance: %v", err))
-	}
+	consoleOutCore := zapcore.NewCore(newLogEncoder(), stdout, level)
+
+	consoleOutCore = samplingEnabling(v, consoleOutCore)
 
 	return &Logger{
-		logger: l,
-		lvl:    c.Level,
+		logger: zap.New(consoleOutCore, zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel))),
+		lvl:    level,
 	}
 }
 
-func newJournaldLogger(lvl zapcore.Level) *Logger {
-	c := zap.NewProductionConfig()
-	c.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
-	c.Level = zap.NewAtomicLevelAt(lvl)
+func newJournaldLogger(v *viper.Viper, lvl zapcore.Level) *Logger {
+	level := zap.NewAtomicLevelAt(lvl)
 
-	encoder := zapjournald.NewPartialEncoder(zapcore.NewConsoleEncoder(c.EncoderConfig), zapjournald.SyslogFields)
+	encoder := zapjournald.NewPartialEncoder(newLogEncoder(), zapjournald.SyslogFields)
 
-	core := zapjournald.NewCore(c.Level, encoder, &journald.Journal{}, zapjournald.SyslogFields)
+	core := zapjournald.NewCore(level, encoder, &journald.Journal{}, zapjournald.SyslogFields)
 	coreWithContext := core.With([]zapcore.Field{
 		zapjournald.SyslogFacility(zapjournald.LogDaemon),
 		zapjournald.SyslogIdentifier(),
 		zapjournald.SyslogPid(),
 	})
 
+	coreWithContext = samplingEnabling(v, coreWithContext)
+
 	l := zap.New(coreWithContext, zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel)))
 
 	return &Logger{
 		logger: l,
-		lvl:    c.Level,
+		lvl:    level,
 	}
 }
 
+func newLogEncoder() zapcore.Encoder {
+	c := zap.NewProductionEncoderConfig()
+	c.EncodeTime = zapcore.ISO8601TimeEncoder
+
+	return zapcore.NewConsoleEncoder(c)
+}
+
+func samplingEnabling(v *viper.Viper, core zapcore.Core) zapcore.Core {
+	// Zap samples by logging the first cgfLoggerSamplingInitial entries with a given level
+	// and message within the specified time interval.
+	// In the above config, only the first cgfLoggerSamplingInitial log entries with the same level and message
+	// are recorded in cfgLoggerSamplingInterval interval. Every other log entry will be dropped within the interval since
+	// cfgLoggerSamplingThereafter is specified here.
+	if v.GetBool(cfgLoggerSamplingEnabled) {
+		core = zapcore.NewSamplerWithOptions(
+			core,
+			v.GetDuration(cfgLoggerSamplingInterval),
+			v.GetInt(cfgLoggerSamplingInitial),
+			v.GetInt(cfgLoggerSamplingThereafter),
+		)
+	}
+
+	return core
+}
+
 func getLogLevel(v *viper.Viper) (zapcore.Level, error) {
 	var lvl zapcore.Level
 	lvlStr := v.GetString(cfgLoggerLevel)

config/config.env

@@ -51,6 +51,10 @@ S3_GW_CONFIG=/path/to/config/yaml
 
 # Logger
 S3_GW_LOGGER_LEVEL=debug
+S3_GW_LOGGER_SAMPLING_ENABLED=false
+S3_GW_LOGGER_SAMPLING_INITIAL=100
+S3_GW_LOGGER_SAMPLING_THEREAFTER=100
+S3_GW_LOGGER_SAMPLING_INTERVAL=1s
 
 # HTTP logger
 S3_GW_HTTP_LOGGING_ENABLED=false

config/config.yaml

@@ -55,6 +55,11 @@ vhs:
 logger:
   level: debug
   destination: stdout
+  sampling:
+    enabled: false
+    initial: 100
+    thereafter: 100
+    interval: 1s
 
 # log http request data (URI, headers, query, etc)
 http_logging:

docs/configuration.md

@@ -370,12 +370,21 @@ server:
 logger:
   level: debug
   destination: stdout
+  sampling:
+    enabled: false 
+    initial: 100
+    thereafter: 100
+    interval: 1s
 ```
 
-| Parameter     | Type     | SIGHUP reload | Default value | Description                                                                                        |
-|---------------|----------|---------------|---------------|----------------------------------------------------------------------------------------------------|
-| `level`       | `string` | yes           | `debug`       | Logging level.<br/>Possible values:  `debug`, `info`, `warn`, `error`, `dpanic`, `panic`, `fatal`. |
-| `destination` | `string` | no            | `stdout`      | Destination for logger: `stdout` or `journald`                                                     |
+| Parameter             | Type       | SIGHUP reload | Default value | Description                                                                                        |
+|-----------------------|------------|---------------|---------------|----------------------------------------------------------------------------------------------------|
+| `level`               | `string`   | yes           | `debug`       | Logging level.<br/>Possible values:  `debug`, `info`, `warn`, `error`, `dpanic`, `panic`, `fatal`. |
+| `destination`         | `string`   | no            | `stdout`      | Destination for logger: `stdout` or `journald`                                                     |
+| `sampling.enabled`    | `bool`     | no            | false         | Sampling enabling flag.                                                                            |
+| `sampling.initial`    | `int`      | no            | '100'         | Sampling count of first log entries.                                                               |
+| `sampling.thereafter` | `int`      | no            | '100'         | Sampling count of entries after an `interval`.                                                     |
+| `sampling.interval`   | `duration` | no            | '1s'          | Sampling interval of messaging similar entries.                                                    |
 
 
 ### `http_logging` section