[#461] Configure logger sampling policy #495

Merged
alexvanin merged 1 commit from pogpp/frostfs-s3-gw:feature/461_logger_sampling_pcy into master 2024-09-27 06:39:00 +00:00
4 changed files with 76 additions and 26 deletions

View file

@ -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"
dkirillov marked this conversation as resolved Outdated

We need flag that allow disable sampling at all

We need flag that allow disable sampling at all
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")
dkirillov marked this conversation as resolved Outdated

Should we disable it by default?

Should we disable it by default?
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:
alexvanin marked this conversation as resolved Outdated

Why sampler configuration only affects stdout logger? I think both loggers can use it.

Why sampler configuration only affects stdout logger? I think both loggers can use it.
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)
dkirillov marked this conversation as resolved Outdated

It seems before we use stderr (from zap production config). Is it ok that we change this?

It seems before we use `stderr` (from zap production config). Is it ok that we change this?
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,
}
}
dkirillov marked this conversation as resolved Outdated

What about configuring this value (I don't mind current behavior)?
Also we should mention all new params in doc/configuration.md

What about configuring this value (I don't mind current behavior)? Also we should mention all new params in `doc/configuration.md`
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)
dkirillov marked this conversation as resolved Outdated

As I understand this won't work as expected because we have already built logger wit production config that has enabled sampling

As I understand this won't work as expected because we have already built logger wit production config that has enabled sampling
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)
alexvanin marked this conversation as resolved Outdated

Can we set this before calling Build? You can set sampling config in c as it is done in c.Encoding and c.EncoderConfig.

Can we set this before calling Build? You can set sampling config in `c` as it is done in `c.Encoding` and `c.EncoderConfig`.
Outdated
Review
https://github.com/uber-go/zap/blob/master/config.go#L37

We need rewrite initialization then (e.g. TrueCloudLab/frostfs-s3-lifecycler#21)

We need rewrite initialization then (e.g. https://git.frostfs.info/TrueCloudLab/frostfs-s3-lifecycler/pulls/21)
l := zap.New(coreWithContext, zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel)))
return &Logger{
logger: l,
lvl: c.Level,
lvl: level,
}
alexvanin marked this conversation as resolved Outdated

One last suggestion.

Both jouranld and stdout logger require:

  • jsonEncoder
  • level

Can we make separate function to get console encoder and reuse it in both constructors? It will make code similar and much easier to read.

For example:

func consoleEncoder() zapcore.Encoder {
	c := zap.NewProductionEncoderConfig()
	c.EncodeTime = zapcore.ISO8601TimeEncoder
	return zapcore.NewConsoleEncoder(c)
}

func newJournaldLogger(v *viper.Viper, lvl zapcore.Level) *Logger {
	level := zap.NewAtomicLevelAt(lvl)
	consoleEnc := consoleEncoder()

	encoder := zapjournald.NewPartialEncoder(consoleEnc, zapjournald.SyslogFields)
	core := zapjournald.NewCore(level, encoder, &journald.Journal{}, zapjournald.SyslogFields)
	...
}

func newStdoutLogger(v *viper.Viper, lvl zapcore.Level) *Logger {
	level := zap.NewAtomicLevelAt(lvl)
	consoleEnc := consoleEncoder()

	stdout := zapcore.AddSync(os.Stdout)
	consoleOutCore := zapcore.NewCore(consoleEnc, stdout, level)
...
}
One last suggestion. Both jouranld and stdout logger require: * jsonEncoder * level Can we make separate function to get console encoder and reuse it in both constructors? It will make code *similar* and much easier to read. For example: ```go func consoleEncoder() zapcore.Encoder { c := zap.NewProductionEncoderConfig() c.EncodeTime = zapcore.ISO8601TimeEncoder return zapcore.NewConsoleEncoder(c) } func newJournaldLogger(v *viper.Viper, lvl zapcore.Level) *Logger { level := zap.NewAtomicLevelAt(lvl) consoleEnc := consoleEncoder() encoder := zapjournald.NewPartialEncoder(consoleEnc, zapjournald.SyslogFields) core := zapjournald.NewCore(level, encoder, &journald.Journal{}, zapjournald.SyslogFields) ... } func newStdoutLogger(v *viper.Viper, lvl zapcore.Level) *Logger { level := zap.NewAtomicLevelAt(lvl) consoleEnc := consoleEncoder() stdout := zapcore.AddSync(os.Stdout) consoleOutCore := zapcore.NewCore(consoleEnc, stdout, level) ... } ```
}
func newLogEncoder() zapcore.Encoder {
c := zap.NewProductionEncoderConfig()
c.EncodeTime = zapcore.ISO8601TimeEncoder
dkirillov marked this conversation as resolved Outdated

Can we hide this condition in separate function? Currently, we have exactly the same 8 lines here and in newStdoutLogger

Can we hide this condition in separate function? Currently, we have exactly the same 8 lines here and in `newStdoutLogger`
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) {
dkirillov marked this conversation as resolved Outdated

Maybe just

return zapcore.NewConsoleEncoder(c)
Maybe just ```golang return zapcore.NewConsoleEncoder(c) ```
var lvl zapcore.Level
lvlStr := v.GetString(cfgLoggerLevel)

View file

@ -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

View file

@ -55,6 +55,11 @@ vhs:
logger:
level: debug
destination: stdout
sampling:
enabled: false
initial: 100
thereafter: 100
alexvanin marked this conversation as resolved Outdated

interval is missing?

`interval` is missing?
interval: 1s
# log http request data (URI, headers, query, etc)
http_logging:

View file

@ -370,12 +370,21 @@ server:
logger:
level: debug
destination: stdout
sampling:
enabled: false
alexvanin marked this conversation as resolved Outdated

enabled is missing?

`enabled` is missing?

still missing

still missing
alexvanin marked this conversation as resolved Outdated

backtick symbol?

backtick symbol?
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