WIP: logger: Filter entries by tags provided in config #1619

Closed
acid-ant wants to merge 6 commits from acid-ant/frostfs-node:feature/log-tags into master
37 changed files with 550 additions and 110 deletions

View file

@ -4,11 +4,14 @@ import (
"context" "context"
"os" "os"
"os/signal" "os/signal"
"strconv"
"syscall" "syscall"
configViper "git.frostfs.info/TrueCloudLab/frostfs-node/cmd/internal/common/config" configViper "git.frostfs.info/TrueCloudLab/frostfs-node/cmd/internal/common/config"
"git.frostfs.info/TrueCloudLab/frostfs-node/internal/logs" "git.frostfs.info/TrueCloudLab/frostfs-node/internal/logs"
control "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/control/ir" control "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/control/ir"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"github.com/spf13/cast"
"github.com/spf13/viper" "github.com/spf13/viper"
"go.uber.org/zap" "go.uber.org/zap"
) )
@ -38,13 +41,33 @@ func reloadConfig() error {
} }
cmode.Store(cfg.GetBool("node.kludge_compatibility_mode")) cmode.Store(cfg.GetBool("node.kludge_compatibility_mode"))
audit.Store(cfg.GetBool("audit.enabled")) audit.Store(cfg.GetBool("audit.enabled"))
var logPrm logger.Prm
err = logPrm.SetLevelString(cfg.GetString("logger.level")) err = logPrm.SetLevelString(cfg.GetString("logger.level"))
if err != nil { if err != nil {
return err return err
} }
logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp") err = logPrm.SetTags(loggerTags())
dstepanov-yadro marked this conversation as resolved Outdated

As it was: a global variable, in which two fields were redefined, and the other fields remained the same.
How it became: a local variable, for which we set two fields.
Looks like this code was lost:


	logPrm.SamplingHook = metrics.LogMetrics().GetSamplingHook()
	logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp")
As it was: a global variable, in which two fields were redefined, and the other fields remained the same. How it became: a local variable, for which we set two fields. Looks like this code was lost: ``` logPrm.SamplingHook = metrics.LogMetrics().GetSamplingHook() logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp") ```

The was done intentionally because on reloading config by SIGHUP this new parameters just set and never used. There are no code which use it after reloading.

The was done intentionally because on reloading config by SIGHUP this new parameters just set and never used. There are no code which use it after reloading.

Where did PrependTimestamp part go?

Where did `PrependTimestamp` part go?

Removed because it is never used for logger reloading.

Removed because it is never used for logger reloading.

I don't understand, it was in this function before, it surely has to do something, no?

I don't understand, it was in this function before, it surely has to do something, no?

It is used only when we instantiate the new logger here and here. During reloading, we just set it and do nothing.

It is used only when we instantiate the new logger [here](https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/9b113c315668fd26a9d43f8b29c9139fcf3fbb5e/pkg/util/logger/logger.go#L126) and [here](https://git.frostfs.info/TrueCloudLab/frostfs-node/src/commit/9b113c315668fd26a9d43f8b29c9139fcf3fbb5e/pkg/util/logger/logger.go#L156). During reloading, we just set it and do nothing.
if err != nil {
return err
}
log.Reload(logPrm)
return logPrm.Reload() return nil
}
func loggerTags() [][]string {
var res [][]string
for i := 0; ; i++ {
var item []string
index := strconv.FormatInt(int64(i), 10)
names := cast.ToString(cfg.Get("logger.tags." + index + ".names"))
if names == "" {
break
}
item = append(item, names, cast.ToString(cfg.Get("logger.tags."+index+".level")))
res = append(res, item)
}
return res
} }
func watchForSignal(ctx context.Context, cancel func()) { func watchForSignal(ctx context.Context, cancel func()) {

View file

@ -31,7 +31,6 @@ const (
var ( var (
wg = new(sync.WaitGroup) wg = new(sync.WaitGroup)
intErr = make(chan error) // internal inner ring errors intErr = make(chan error) // internal inner ring errors
logPrm = new(logger.Prm)
innerRing *innerring.Server innerRing *innerring.Server
pprofCmp *pprofComponent pprofCmp *pprofComponent
metricsCmp *httpComponent metricsCmp *httpComponent
@ -70,6 +69,7 @@ func main() {
metrics := irMetrics.NewInnerRingMetrics() metrics := irMetrics.NewInnerRingMetrics()
var logPrm logger.Prm
err = logPrm.SetLevelString( err = logPrm.SetLevelString(
cfg.GetString("logger.level"), cfg.GetString("logger.level"),
) )
@ -80,6 +80,8 @@ func main() {
exitErr(err) exitErr(err)
logPrm.SamplingHook = metrics.LogMetrics().GetSamplingHook() logPrm.SamplingHook = metrics.LogMetrics().GetSamplingHook()
logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp") logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp")
err = logPrm.SetTags(loggerTags())
exitErr(err)
log, err = logger.NewLogger(logPrm) log, err = logger.NewLogger(logPrm)
exitErr(err) exitErr(err)

View file

@ -108,6 +108,7 @@ type applicationConfiguration struct {
level string level string
destination string destination string
timestamp bool timestamp bool
tags [][]string
} }
ObjectCfg struct { ObjectCfg struct {
@ -232,6 +233,7 @@ func (a *applicationConfiguration) readConfig(c *config.Config) error {
a.LoggerCfg.level = loggerconfig.Level(c) a.LoggerCfg.level = loggerconfig.Level(c)
a.LoggerCfg.destination = loggerconfig.Destination(c) a.LoggerCfg.destination = loggerconfig.Destination(c)
a.LoggerCfg.timestamp = loggerconfig.Timestamp(c) a.LoggerCfg.timestamp = loggerconfig.Timestamp(c)
a.LoggerCfg.tags = loggerconfig.Tags(c)
// Object // Object
@ -473,7 +475,6 @@ type shared struct {
// dynamicConfiguration stores parameters of the // dynamicConfiguration stores parameters of the
// components that supports runtime reconfigurations. // components that supports runtime reconfigurations.
type dynamicConfiguration struct { type dynamicConfiguration struct {
logger *logger.Prm
pprof *httpComponent pprof *httpComponent
metrics *httpComponent metrics *httpComponent
} }
@ -714,7 +715,8 @@ func initCfg(appCfg *config.Config) *cfg {
netState.metrics = c.metricsCollector netState.metrics = c.metricsCollector
logPrm := c.loggerPrm() logPrm, err := c.loggerPrm()
fatalOnErr(err)
logPrm.SamplingHook = c.metricsCollector.LogMetrics().GetSamplingHook() logPrm.SamplingHook = c.metricsCollector.LogMetrics().GetSamplingHook()
log, err := logger.NewLogger(logPrm) log, err := logger.NewLogger(logPrm)
fatalOnErr(err) fatalOnErr(err)
@ -1076,26 +1078,27 @@ func (c *cfg) getShardOpts(ctx context.Context, shCfg shardCfg) shardOptsWithID
return sh return sh
} }
func (c *cfg) loggerPrm() *logger.Prm { func (c *cfg) loggerPrm() (logger.Prm, error) {
// check if it has been inited before var prm logger.Prm
if c.dynamicConfiguration.logger == nil {
c.dynamicConfiguration.logger = new(logger.Prm)
}
// (re)init read configuration // (re)init read configuration
err := c.dynamicConfiguration.logger.SetLevelString(c.LoggerCfg.level) err := prm.SetLevelString(c.LoggerCfg.level)
if err != nil { if err != nil {
// not expected since validation should be performed before // not expected since validation should be performed before
panic("incorrect log level format: " + c.LoggerCfg.level) return logger.Prm{}, errors.New("incorrect log level format: " + c.LoggerCfg.level)
} }
err = c.dynamicConfiguration.logger.SetDestination(c.LoggerCfg.destination) err = prm.SetDestination(c.LoggerCfg.destination)
if err != nil { if err != nil {
// not expected since validation should be performed before // not expected since validation should be performed before
panic("incorrect log destination format: " + c.LoggerCfg.destination) return logger.Prm{}, errors.New("incorrect log destination format: " + c.LoggerCfg.destination)
}
prm.PrependTimestamp = c.LoggerCfg.timestamp
err = prm.SetTags(c.LoggerCfg.tags)
if err != nil {
// not expected since validation should be performed before
return logger.Prm{}, errors.New("incorrect allowed tags format: " + c.LoggerCfg.destination)
} }
c.dynamicConfiguration.logger.PrependTimestamp = c.LoggerCfg.timestamp
return c.dynamicConfiguration.logger return prm, nil
} }
func (c *cfg) LocalAddress() network.AddressGroup { func (c *cfg) LocalAddress() network.AddressGroup {
@ -1335,11 +1338,7 @@ func (c *cfg) reloadConfig(ctx context.Context) {
// all the components are expected to support // all the components are expected to support
// Logger's dynamic reconfiguration approach // Logger's dynamic reconfiguration approach
// Logger components := c.getComponents(ctx)
logPrm := c.loggerPrm()
components := c.getComponents(ctx, logPrm)
// Object // Object
c.cfgObject.tombstoneLifetime.Store(c.ObjectCfg.tombstoneLifetime) c.cfgObject.tombstoneLifetime.Store(c.ObjectCfg.tombstoneLifetime)
@ -1377,10 +1376,17 @@ func (c *cfg) reloadConfig(ctx context.Context) {
c.log.Info(ctx, logs.FrostFSNodeConfigurationHasBeenReloadedSuccessfully) c.log.Info(ctx, logs.FrostFSNodeConfigurationHasBeenReloadedSuccessfully)
} }
func (c *cfg) getComponents(ctx context.Context, logPrm *logger.Prm) []dCmp { func (c *cfg) getComponents(ctx context.Context) []dCmp {
var components []dCmp var components []dCmp
components = append(components, dCmp{"logger", logPrm.Reload}) components = append(components, dCmp{"logger", func() error {
prm, err := c.loggerPrm()
if err != nil {
return err
}
c.log.Reload(prm)
return nil
}})
components = append(components, dCmp{"runtime", func() error { components = append(components, dCmp{"runtime", func() error {
setRuntimeParameters(ctx, c) setRuntimeParameters(ctx, c)
return nil return nil

View file

@ -2,6 +2,7 @@ package loggerconfig
import ( import (
"os" "os"
"strconv"
"time" "time"
"git.frostfs.info/TrueCloudLab/frostfs-node/cmd/frostfs-node/config" "git.frostfs.info/TrueCloudLab/frostfs-node/cmd/frostfs-node/config"
@ -60,6 +61,23 @@ func Timestamp(c *config.Config) bool {
return config.BoolSafe(c.Sub(subsection), "timestamp") return config.BoolSafe(c.Sub(subsection), "timestamp")
} }
// Tags returns the value of "tags" config parameter from "logger" section.
func Tags(c *config.Config) [][]string {
var res [][]string
sub := c.Sub(subsection).Sub("tags")
for i := 0; ; i++ {
var item []string
s := sub.Sub(strconv.FormatInt(int64(i), 10))
names := config.StringSafe(s, "names")
if names == "" {
break
}
item = append(item, names, config.StringSafe(s, "level"))

Before this line item is nil, so why do we have

var item []string
item = append(item, xxx)

instead of item := xxx

I think we can even get rid of this variable.

Before this line `item` is nil, so why do we have ``` var item []string item = append(item, xxx) ``` instead of `item := xxx` I think we can even get rid of this variable.
res = append(res, item)
}
return res
}
// ToLokiConfig extracts loki config. // ToLokiConfig extracts loki config.
func ToLokiConfig(c *config.Config) loki.Config { func ToLokiConfig(c *config.Config) loki.Config {
hostname, _ := os.Hostname() hostname, _ := os.Hostname()

View file

@ -22,6 +22,9 @@ func TestLoggerSection_Level(t *testing.T) {
require.Equal(t, "debug", loggerconfig.Level(c)) require.Equal(t, "debug", loggerconfig.Level(c))
require.Equal(t, "journald", loggerconfig.Destination(c)) require.Equal(t, "journald", loggerconfig.Destination(c))
require.Equal(t, true, loggerconfig.Timestamp(c)) require.Equal(t, true, loggerconfig.Timestamp(c))
tags := loggerconfig.Tags(c)
require.Equal(t, "main, morph", tags[0][0])
require.Equal(t, "debug", tags[0][1])
} }
configtest.ForEachFileType(path, fileConfigTest) configtest.ForEachFileType(path, fileConfigTest)

View file

@ -14,6 +14,7 @@ import (
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event"
netmapEvent "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event/netmap" netmapEvent "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event/netmap"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/subscriber" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/subscriber"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/rand" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/rand"
"github.com/nspcc-dev/neo-go/pkg/core/block" "github.com/nspcc-dev/neo-go/pkg/core/block"
"github.com/nspcc-dev/neo-go/pkg/core/state" "github.com/nspcc-dev/neo-go/pkg/core/state"
@ -83,7 +84,7 @@ func initMorphClient(ctx context.Context, c *cfg) {
cli, err := client.New(ctx, cli, err := client.New(ctx,
c.key, c.key,
client.WithDialTimeout(morphconfig.DialTimeout(c.appCfg)), client.WithDialTimeout(morphconfig.DialTimeout(c.appCfg)),
client.WithLogger(c.log), client.WithLogger(c.log.WithTag(logger.TagMorph)),
client.WithMetrics(c.metricsCollector.MorphClientMetrics()), client.WithMetrics(c.metricsCollector.MorphClientMetrics()),
client.WithEndpoints(addresses...), client.WithEndpoints(addresses...),
client.WithConnLostCallback(func() { client.WithConnLostCallback(func() {
@ -164,6 +165,7 @@ func listenMorphNotifications(ctx context.Context, c *cfg) {
err error err error
subs subscriber.Subscriber subs subscriber.Subscriber
) )
log := c.log.WithTag(logger.TagMorph)
fromSideChainBlock, err := c.persistate.UInt32(persistateSideChainLastBlockKey) fromSideChainBlock, err := c.persistate.UInt32(persistateSideChainLastBlockKey)
if err != nil { if err != nil {
@ -172,14 +174,14 @@ func listenMorphNotifications(ctx context.Context, c *cfg) {
} }
subs, err = subscriber.New(ctx, &subscriber.Params{ subs, err = subscriber.New(ctx, &subscriber.Params{
Log: c.log, Log: log,
StartFromBlock: fromSideChainBlock, StartFromBlock: fromSideChainBlock,
Client: c.cfgMorph.client, Client: c.cfgMorph.client,
}) })
fatalOnErr(err) fatalOnErr(err)
lis, err := event.NewListener(event.ListenerParams{ lis, err := event.NewListener(event.ListenerParams{
Logger: c.log, Logger: log,
Subscriber: subs, Subscriber: subs,
}) })
fatalOnErr(err) fatalOnErr(err)
@ -197,7 +199,7 @@ func listenMorphNotifications(ctx context.Context, c *cfg) {
setNetmapNotificationParser(c, newEpochNotification, func(src *state.ContainedNotificationEvent) (event.Event, error) { setNetmapNotificationParser(c, newEpochNotification, func(src *state.ContainedNotificationEvent) (event.Event, error) {
res, err := netmapEvent.ParseNewEpoch(src) res, err := netmapEvent.ParseNewEpoch(src)
if err == nil { if err == nil {
c.log.Info(ctx, logs.FrostFSNodeNewEpochEventFromSidechain, log.Info(ctx, logs.FrostFSNodeNewEpochEventFromSidechain,
zap.Uint64("number", res.(netmapEvent.NewEpoch).EpochNumber()), zap.Uint64("number", res.(netmapEvent.NewEpoch).EpochNumber()),
) )
} }
@ -208,11 +210,11 @@ func listenMorphNotifications(ctx context.Context, c *cfg) {
registerNotificationHandlers(c.cfgContainer.scriptHash, lis, c.cfgContainer.parsers, c.cfgContainer.subscribers) registerNotificationHandlers(c.cfgContainer.scriptHash, lis, c.cfgContainer.parsers, c.cfgContainer.subscribers)
registerBlockHandler(lis, func(ctx context.Context, block *block.Block) { registerBlockHandler(lis, func(ctx context.Context, block *block.Block) {
c.log.Debug(ctx, logs.FrostFSNodeNewBlock, zap.Uint32("index", block.Index)) log.Debug(ctx, logs.FrostFSNodeNewBlock, zap.Uint32("index", block.Index))
err = c.persistate.SetUInt32(persistateSideChainLastBlockKey, block.Index) err = c.persistate.SetUInt32(persistateSideChainLastBlockKey, block.Index)
if err != nil { if err != nil {
c.log.Warn(ctx, logs.FrostFSNodeCantUpdatePersistentState, log.Warn(ctx, logs.FrostFSNodeCantUpdatePersistentState,
zap.String("chain", "side"), zap.String("chain", "side"),
zap.Uint32("block_index", block.Index)) zap.Uint32("block_index", block.Index))
} }

View file

@ -14,6 +14,7 @@ import (
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage/persistent" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage/persistent"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage/temporary" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/session/storage/temporary"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/session" "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/session"
sessionGRPC "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/session/grpc" sessionGRPC "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/api/session/grpc"
"git.frostfs.info/TrueCloudLab/frostfs-sdk-go/user" "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/user"
@ -55,7 +56,7 @@ func initSessionService(c *cfg) {
server := sessionTransportGRPC.New( server := sessionTransportGRPC.New(
sessionSvc.NewSignService( sessionSvc.NewSignService(
&c.key.PrivateKey, &c.key.PrivateKey,
sessionSvc.NewExecutionService(c.privateTokenStore, c.respSvc, c.log), sessionSvc.NewExecutionService(c.privateTokenStore, c.respSvc, c.log.WithTag(logger.TagSessionSvc)),
), ),
) )

View file

@ -14,6 +14,7 @@ import (
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event"
containerEvent "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event/container" containerEvent "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/morph/event/container"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/tree" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/tree"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
cid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/container/id" cid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/container/id"
"go.uber.org/zap" "go.uber.org/zap"
"google.golang.org/grpc" "google.golang.org/grpc"
@ -56,7 +57,7 @@ func initTreeService(c *cfg) {
tree.WithFrostfsidSubjectProvider(c.shared.frostfsidClient), tree.WithFrostfsidSubjectProvider(c.shared.frostfsidClient),
tree.WithNetmapSource(c.netMapSource), tree.WithNetmapSource(c.netMapSource),
tree.WithPrivateKey(&c.key.PrivateKey), tree.WithPrivateKey(&c.key.PrivateKey),
tree.WithLogger(c.log), tree.WithLogger(c.log.WithTag(logger.TagTreeSvc)),
tree.WithStorage(c.cfgObject.cfgLocalStorage.localStorage), tree.WithStorage(c.cfgObject.cfgLocalStorage.localStorage),
tree.WithContainerCacheSize(treeConfig.CacheSize()), tree.WithContainerCacheSize(treeConfig.CacheSize()),
tree.WithReplicationTimeout(treeConfig.ReplicationTimeout()), tree.WithReplicationTimeout(treeConfig.ReplicationTimeout()),

View file

@ -30,6 +30,11 @@ func validateConfig(c *config.Config) error {
return fmt.Errorf("invalid logger destination: %w", err) return fmt.Errorf("invalid logger destination: %w", err)
} }
err = loggerPrm.SetTags(loggerconfig.Tags(c))
fyrchik marked this conversation as resolved Outdated

Why have you chosen an approach different from SetLevelString and SetDestination (i.e. "parse, don't validate")?
Calling validation is easy to forget, with SetAllowedTags it will become mandatory.

Why have you chosen an approach different from `SetLevelString` and `SetDestination` (i.e. "parse, don't validate")? Calling validation is easy to forget, with `SetAllowedTags` it will become mandatory.

Agree, added method SetAllowedTags.

Agree, added method `SetAllowedTags`.
if err != nil {
return fmt.Errorf("invalid list of allowed tags: %w", err)
}
// shard configuration validation // shard configuration validation
shardNum := 0 shardNum := 0

View file

@ -1,5 +1,7 @@
FROSTFS_IR_LOGGER_LEVEL=info FROSTFS_IR_LOGGER_LEVEL=info
FROSTFS_IR_LOGGER_TIMESTAMP=true FROSTFS_IR_LOGGER_TIMESTAMP=true
FROSTFS_IR_LOGGER_TAGS_0_NAMES="main, morph"
FROSTFS_IR_LOGGER_TAGS_0_LEVEL="debug"
FROSTFS_IR_WALLET_PATH=/path/to/wallet.json FROSTFS_IR_WALLET_PATH=/path/to/wallet.json
FROSTFS_IR_WALLET_ADDRESS=NUHtW3eM6a4mmFCgyyr4rj4wygsTKB88XX FROSTFS_IR_WALLET_ADDRESS=NUHtW3eM6a4mmFCgyyr4rj4wygsTKB88XX

View file

@ -3,6 +3,9 @@
logger: logger:
level: info # Logger level: one of "debug", "info" (default), "warn", "error", "dpanic", "panic", "fatal" level: info # Logger level: one of "debug", "info" (default), "warn", "error", "dpanic", "panic", "fatal"
timestamp: true timestamp: true
tags:
- names: "main, morph" # Possible values: `main`, `morph`, `grpc_svc`, `ir`, `processor`.
level: debug
wallet: wallet:
path: /path/to/wallet.json # Path to NEP-6 NEO wallet file path: /path/to/wallet.json # Path to NEP-6 NEO wallet file

View file

@ -1,6 +1,8 @@
FROSTFS_LOGGER_LEVEL=debug FROSTFS_LOGGER_LEVEL=debug
FROSTFS_LOGGER_DESTINATION=journald FROSTFS_LOGGER_DESTINATION=journald
FROSTFS_LOGGER_TIMESTAMP=true FROSTFS_LOGGER_TIMESTAMP=true
FROSTFS_LOGGER_TAGS_0_NAMES="main, morph"
FROSTFS_LOGGER_TAGS_0_LEVEL="debug"
FROSTFS_PPROF_ENABLED=true FROSTFS_PPROF_ENABLED=true
FROSTFS_PPROF_ADDRESS=localhost:6060 FROSTFS_PPROF_ADDRESS=localhost:6060

View file

@ -2,7 +2,13 @@
"logger": { "logger": {
"level": "debug", "level": "debug",
"destination": "journald", "destination": "journald",
"timestamp": true "timestamp": true,
"tags": [
{
"names": "main, morph",
"level": "debug"
}
]
}, },
"pprof": { "pprof": {
"enabled": true, "enabled": true,

View file

@ -2,6 +2,9 @@ logger:
level: debug # logger level: one of "debug", "info" (default), "warn", "error", "dpanic", "panic", "fatal" level: debug # logger level: one of "debug", "info" (default), "warn", "error", "dpanic", "panic", "fatal"
destination: journald # logger destination: one of "stdout" (default), "journald" destination: journald # logger destination: one of "stdout" (default), "journald"
timestamp: true timestamp: true
tags:
- names: "main, morph"
level: debug
systemdnotify: systemdnotify:
enabled: true enabled: true

View file

@ -111,11 +111,21 @@ Contains logger parameters.
```yaml ```yaml
logger: logger:
level: info level: info
tags:
- names: "main, morph"
level: debug
``` ```
| Parameter | Type | Default value | Description | | Parameter | Type | Default value | Description |
|-----------|----------|---------------|---------------------------------------------------------------------------------------------------| |-----------|-----------------------------------------------|---------------|---------------------------------------------------------------------------------------------------|
| `level` | `string` | `info` | Logging level.<br/>Possible values: `debug`, `info`, `warn`, `error`, `dpanic`, `panic`, `fatal` | | `level` | `string` | `info` | Logging level.<br/>Possible values: `debug`, `info`, `warn`, `error`, `dpanic`, `panic`, `fatal` |
| `tags` | list of [tags descriptions](#tags-subsection) | | Array of tags description. |
## `tags` subsection
| Parameter | Type | Default value | Description |
|-----------|----------|---------------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| `names` | `string` | | List of components divided by `,`.<br/>Possible values: `main`, `morph`, `grpc_svc`, `ir`, `processor`, `engine`, `blobovnicza`, `blobstor`, `fstree`, `gc`, `shard`, `writecache`, `deletesvc`, `getsvc`, `searchsvc`, `sessionsvc`, `treesvc`, `policer`, `replicator`. |
| `level` | `string` | | Logging level for the components from `names`, overrides default logging level. |
# `contracts` section # `contracts` section
Contains override values for FrostFS side-chain contract hashes. Most of the time contract Contains override values for FrostFS side-chain contract hashes. Most of the time contract

View file

@ -50,7 +50,7 @@ func (s *Server) initNetmapProcessor(ctx context.Context, cfg *viper.Viper,
var err error var err error
s.netmapProcessor, err = netmap.New(&netmap.Params{ s.netmapProcessor, err = netmap.New(&netmap.Params{
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
PoolSize: poolSize, PoolSize: poolSize,
NetmapClient: netmap.NewNetmapClient(s.netmapClient), NetmapClient: netmap.NewNetmapClient(s.netmapClient),
@ -159,7 +159,7 @@ func (s *Server) createAlphaSync(cfg *viper.Viper, frostfsCli *frostfsClient.Cli
} else { } else {
// create governance processor // create governance processor
governanceProcessor, err := governance.New(&governance.Params{ governanceProcessor, err := governance.New(&governance.Params{
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
FrostFSClient: frostfsCli, FrostFSClient: frostfsCli,
AlphabetState: s, AlphabetState: s,
@ -225,7 +225,7 @@ func (s *Server) initAlphabetProcessor(ctx context.Context, cfg *viper.Viper) er
// create alphabet processor // create alphabet processor
s.alphabetProcessor, err = alphabet.New(&alphabet.Params{ s.alphabetProcessor, err = alphabet.New(&alphabet.Params{
ParsedWallets: parsedWallets, ParsedWallets: parsedWallets,
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
PoolSize: poolSize, PoolSize: poolSize,
AlphabetContracts: s.contracts.alphabet, AlphabetContracts: s.contracts.alphabet,
@ -247,7 +247,7 @@ func (s *Server) initContainerProcessor(ctx context.Context, cfg *viper.Viper, c
s.log.Debug(ctx, logs.ContainerContainerWorkerPool, zap.Int("size", poolSize)) s.log.Debug(ctx, logs.ContainerContainerWorkerPool, zap.Int("size", poolSize))
// container processor // container processor
containerProcessor, err := cont.New(&cont.Params{ containerProcessor, err := cont.New(&cont.Params{
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
PoolSize: poolSize, PoolSize: poolSize,
AlphabetState: s, AlphabetState: s,
@ -268,7 +268,7 @@ func (s *Server) initBalanceProcessor(ctx context.Context, cfg *viper.Viper, fro
s.log.Debug(ctx, logs.BalanceBalanceWorkerPool, zap.Int("size", poolSize)) s.log.Debug(ctx, logs.BalanceBalanceWorkerPool, zap.Int("size", poolSize))
// create balance processor // create balance processor
balanceProcessor, err := balance.New(&balance.Params{ balanceProcessor, err := balance.New(&balance.Params{
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
PoolSize: poolSize, PoolSize: poolSize,
FrostFSClient: frostfsCli, FrostFSClient: frostfsCli,
@ -291,7 +291,7 @@ func (s *Server) initFrostFSMainnetProcessor(ctx context.Context, cfg *viper.Vip
s.log.Debug(ctx, logs.FrostFSFrostfsWorkerPool, zap.Int("size", poolSize)) s.log.Debug(ctx, logs.FrostFSFrostfsWorkerPool, zap.Int("size", poolSize))
frostfsProcessor, err := frostfs.New(&frostfs.Params{ frostfsProcessor, err := frostfs.New(&frostfs.Params{
Log: s.log, Log: s.log.WithTag(logger.TagProcessor),
Metrics: s.irMetrics, Metrics: s.irMetrics,
PoolSize: poolSize, PoolSize: poolSize,
FrostFSContract: s.contracts.frostfs, FrostFSContract: s.contracts.frostfs,
@ -342,7 +342,7 @@ func (s *Server) initGRPCServer(ctx context.Context, cfg *viper.Viper, log *logg
controlSvc := controlsrv.NewAuditService(controlsrv.New(p, s.netmapClient, s.containerClient, controlSvc := controlsrv.NewAuditService(controlsrv.New(p, s.netmapClient, s.containerClient,
controlsrv.WithAllowedKeys(authKeys), controlsrv.WithAllowedKeys(authKeys),
), log, audit) ), log.WithTag(logger.TagGrpcSvc), audit)
grpcControlSrv := grpc.NewServer() grpcControlSrv := grpc.NewServer()
control.RegisterControlServiceServer(grpcControlSrv, controlSvc) control.RegisterControlServiceServer(grpcControlSrv, controlSvc)
@ -458,7 +458,7 @@ func (s *Server) initMorph(ctx context.Context, cfg *viper.Viper, errChan chan<-
} }
morphChain := &chainParams{ morphChain := &chainParams{
log: s.log, log: s.log.WithTag(logger.TagMorph),
cfg: cfg, cfg: cfg,
key: s.key, key: s.key,
name: morphPrefix, name: morphPrefix,

View file

@ -339,7 +339,7 @@ func New(ctx context.Context, log *logger.Logger, cfg *viper.Viper, errChan chan
) (*Server, error) { ) (*Server, error) {
var err error var err error
server := &Server{ server := &Server{
log: log, log: log.WithTag(logger.TagIr),
irMetrics: metrics, irMetrics: metrics,
cmode: cmode, cmode: cmode,
} }

View file

@ -110,7 +110,7 @@ func WithFullSizeLimit(lim uint64) Option {
// WithLogger returns an option to specify Blobovnicza's logger. // WithLogger returns an option to specify Blobovnicza's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l.With(zap.String("component", "Blobovnicza")) c.log = l.WithTag(logger.TagBlobovnicza)
} }
} }

View file

@ -91,7 +91,7 @@ func WithStorages(st []SubStorage) Option {
// WithLogger returns option to specify BlobStor's logger. // WithLogger returns option to specify BlobStor's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l.With(zap.String("component", "BlobStor")) c.log = l.WithTag(logger.TagBlobstor)
} }
} }

View file

@ -4,7 +4,6 @@ import (
"io/fs" "io/fs"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"go.uber.org/zap"
) )
type Option func(*FSTree) type Option func(*FSTree)
@ -53,6 +52,6 @@ func WithFileCounter(c FileCounter) Option {
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(f *FSTree) { return func(f *FSTree) {
f.log = l.With(zap.String("component", "FSTree")) f.log = l.WithTag(logger.TagFSTree)
} }
} }

View file

@ -224,7 +224,7 @@ func New(opts ...Option) *StorageEngine {
// WithLogger returns option to set StorageEngine's logger. // WithLogger returns option to set StorageEngine's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l c.log = l.WithTag(logger.TagEngine)
} }
} }

View file

@ -495,7 +495,7 @@ func (s *Shard) collectExpiredTombstones(ctx context.Context, e Event) {
}() }()
epoch := e.(newEpoch).epoch epoch := e.(newEpoch).epoch
log := s.log.With(zap.Uint64("epoch", epoch)) log := s.log.With(zap.Uint64("epoch", epoch)).WithTag(logger.TagGC)
log.Debug(ctx, logs.ShardStartedExpiredTombstonesHandling) log.Debug(ctx, logs.ShardStartedExpiredTombstonesHandling)
defer log.Debug(ctx, logs.ShardFinishedExpiredTombstonesHandling) defer log.Debug(ctx, logs.ShardFinishedExpiredTombstonesHandling)

View file

@ -204,8 +204,8 @@ func WithPiloramaOptions(opts ...pilorama.Option) Option {
// WithLogger returns option to set Shard's logger. // WithLogger returns option to set Shard's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l c.log = l.WithTag(logger.TagShard)
c.gcCfg.log = l c.gcCfg.log = l.WithTag(logger.TagGC)
} }
} }

View file

@ -5,7 +5,6 @@ import (
"git.frostfs.info/TrueCloudLab/frostfs-node/internal/qos" "git.frostfs.info/TrueCloudLab/frostfs-node/internal/qos"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"go.uber.org/zap"
) )
// Option represents write-cache configuration option. // Option represents write-cache configuration option.
@ -46,7 +45,7 @@ type options struct {
// WithLogger sets logger. // WithLogger sets logger.
func WithLogger(log *logger.Logger) Option { func WithLogger(log *logger.Logger) Option {
return func(o *options) { return func(o *options) {
o.log = log.With(zap.String("component", "WriteCache")) o.log = log.WithTag(logger.TagWriteCache)
} }
} }

View file

@ -130,7 +130,7 @@ func TestECWriter(t *testing.T) {
nodeKey, err := keys.NewPrivateKey() nodeKey, err := keys.NewPrivateKey()
require.NoError(t, err) require.NoError(t, err)
log, err := logger.NewLogger(nil) log, err := logger.NewLogger(logger.Prm{})
require.NoError(t, err) require.NoError(t, err)
var n nmKeys var n nmKeys

View file

@ -92,6 +92,6 @@ func New(gs *getsvc.Service,
// WithLogger returns option to specify Delete service's logger. // WithLogger returns option to specify Delete service's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l.With(zap.String("component", "objectSDK.Delete service")) c.log = l.WithTag(logger.TagDeleteSvc)
} }
} }

View file

@ -53,6 +53,6 @@ func New(
// WithLogger returns option to specify Get service's logger. // WithLogger returns option to specify Get service's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(s *Service) { return func(s *Service) {
s.log = l.With(zap.String("component", "Object.Get service")) s.log = l.WithTag(logger.TagGetSvc)
} }
} }

View file

@ -145,6 +145,6 @@ func (s *Service) Head(ctx context.Context, req *objectV2.HeadRequest) (*objectV
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l.With(zap.String("component", "Object.Get V2 service")) c.log = l.WithTag(logger.TagGetSvc)
} }
} }

View file

@ -94,6 +94,6 @@ func New(e *engine.StorageEngine,
// WithLogger returns option to specify Get service's logger. // WithLogger returns option to specify Get service's logger.
func WithLogger(l *logger.Logger) Option { func WithLogger(l *logger.Logger) Option {
return func(c *cfg) { return func(c *cfg) {
c.log = l.With(zap.String("component", "Object.Search service")) c.log = l.WithTag(logger.TagSearchSvc)
} }
} }

View file

@ -4,9 +4,9 @@ import (
"sync" "sync"
"time" "time"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
oid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object/id" oid "git.frostfs.info/TrueCloudLab/frostfs-sdk-go/object/id"
lru "github.com/hashicorp/golang-lru/v2" lru "github.com/hashicorp/golang-lru/v2"
"go.uber.org/zap"
) )
type objectsInWork struct { type objectsInWork struct {
@ -54,7 +54,7 @@ func New(opts ...Option) *Policer {
opts[i](c) opts[i](c)
} }
c.log = c.log.With(zap.String("component", "Object Policer")) c.log = c.log.WithTag(logger.TagPolicer)
cache, err := lru.New[oid.Address, time.Time](int(c.cacheSize)) cache, err := lru.New[oid.Address, time.Time](int(c.cacheSize))
if err != nil { if err != nil {

View file

@ -7,7 +7,6 @@ import (
objectwriter "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/object/common/writer" objectwriter "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/object/common/writer"
getsvc "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/object/get" getsvc "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/services/object/get"
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger"
"go.uber.org/zap"
) )
// Replicator represents the utility that replicates // Replicator represents the utility that replicates
@ -45,7 +44,7 @@ func New(opts ...Option) *Replicator {
opts[i](c) opts[i](c)
} }
c.log = c.log.With(zap.String("component", "Object Replicator")) c.log = c.log.WithTag(logger.TagReplicator)
return &Replicator{ return &Replicator{
cfg: c, cfg: c,

View file

@ -33,10 +33,7 @@ func NewExecutionService(exec ServiceExecutor, respSvc *response.Service, l *log
} }
func (s *executorSvc) Create(ctx context.Context, req *session.CreateRequest) (*session.CreateResponse, error) { func (s *executorSvc) Create(ctx context.Context, req *session.CreateRequest) (*session.CreateResponse, error) {
s.log.Debug(ctx, logs.ServingRequest, s.log.Debug(ctx, logs.ServingRequest, zap.String("request", "Create"))
zap.String("component", "SessionService"),
zap.String("request", "Create"),
)
respBody, err := s.exec.Create(ctx, req.GetBody()) respBody, err := s.exec.Create(ctx, req.GetBody())
if err != nil { if err != nil {

View file

@ -6,21 +6,34 @@ import (
"git.frostfs.info/TrueCloudLab/frostfs-node/pkg/tracing" "git.frostfs.info/TrueCloudLab/frostfs-node/pkg/tracing"
qos "git.frostfs.info/TrueCloudLab/frostfs-qos/tagging" qos "git.frostfs.info/TrueCloudLab/frostfs-qos/tagging"
"go.uber.org/zap" "go.uber.org/zap"
"go.uber.org/zap/zapcore"
) )
func (l *Logger) Debug(ctx context.Context, msg string, fields ...zap.Field) { func (l *Logger) Debug(ctx context.Context, msg string, fields ...zap.Field) {
if l.denyLogEntry(zapcore.DebugLevel) {
return
}
l.z.Debug(msg, appendContext(ctx, fields...)...) l.z.Debug(msg, appendContext(ctx, fields...)...)
} }
func (l *Logger) Info(ctx context.Context, msg string, fields ...zap.Field) { func (l *Logger) Info(ctx context.Context, msg string, fields ...zap.Field) {
if l.denyLogEntry(zapcore.InfoLevel) {
return
}
l.z.Info(msg, appendContext(ctx, fields...)...) l.z.Info(msg, appendContext(ctx, fields...)...)
} }
func (l *Logger) Warn(ctx context.Context, msg string, fields ...zap.Field) { func (l *Logger) Warn(ctx context.Context, msg string, fields ...zap.Field) {
if l.denyLogEntry(zapcore.WarnLevel) {
return
}
l.z.Warn(msg, appendContext(ctx, fields...)...) l.z.Warn(msg, appendContext(ctx, fields...)...)
} }
func (l *Logger) Error(ctx context.Context, msg string, fields ...zap.Field) { func (l *Logger) Error(ctx context.Context, msg string, fields ...zap.Field) {
if l.denyLogEntry(zapcore.ErrorLevel) {
return
}
l.z.Error(msg, appendContext(ctx, fields...)...) l.z.Error(msg, appendContext(ctx, fields...)...)
} }
@ -33,3 +46,11 @@ func appendContext(ctx context.Context, fields ...zap.Field) []zap.Field {
} }
return fields return fields
} }
func (l *Logger) denyLogEntry(level zapcore.Level) bool {
tl := l.tl.Load().(map[Tag]zapcore.Level)
if lvl, ok := tl[l.t]; ok {
return level < lvl
}
return level < l.lvl.Level()

This is exactly the check that l.z.Info() or l.z.Debug methods will do.
Am I right?

I don't oppose to having it here, but we are duplicating logic.
On the other hand appendContext may allocate, so this optimization is worth having.

This is exactly the check that `l.z.Info()` or `l.z.Debug` methods will do. Am I right? I don't oppose to having it here, but we are duplicating logic. On the other hand `appendContext` may allocate, so this optimization is worth having.
}

View file

@ -2,6 +2,7 @@ package logger
import ( import (
"fmt" "fmt"
"sync/atomic"
"time" "time"
"git.frostfs.info/TrueCloudLab/zapjournald" "git.frostfs.info/TrueCloudLab/zapjournald"
@ -15,6 +16,12 @@ import (
type Logger struct { type Logger struct {
z *zap.Logger z *zap.Logger
lvl zap.AtomicLevel lvl zap.AtomicLevel
// Tag used by Logger

Please give these variables more meaningful names.

Please give these variables more meaningful names.

Added comments for each new variable.

Added comments for each new variable.
t Tag
// Contains map of Tag to log level, overrides lvl
tl *atomic.Value
dstepanov-yadro marked this conversation as resolved Outdated

Looks like that mtx *sync.RWMutex protects at & tl, but these variables change simultaneously. Looks like it could be just one atomic.

Looks like that `mtx *sync.RWMutex` protects `at` & `tl`, but these variables change simultaneously. Looks like it could be just one atomic.

Thanks, there are no necessity to use sync.RWMutex - code updated.

Thanks, there are no necessity to use `sync.RWMutex` - code updated.
// Parent zap.Logger, required to override field zapTagFieldName in the output
pz *zap.Logger
} }
// Prm groups Logger's parameters. // Prm groups Logger's parameters.
@ -23,16 +30,8 @@ type Logger struct {
// Parameters that have been connected to the Logger support its // Parameters that have been connected to the Logger support its
// configuration changing. // configuration changing.
// //
// Passing Prm after a successful connection via the NewLogger, connects // See also Logger.Reload, SetLevelString.
// the Prm to a new instance of the Logger.
//
// See also Reload, SetLevelString.
type Prm struct { type Prm struct {
// link to the created Logger
// instance; used for a runtime
// reconfiguration
_log *Logger
// support runtime rereading // support runtime rereading
level zapcore.Level level zapcore.Level
@ -44,12 +43,17 @@ type Prm struct {
// PrependTimestamp specifies whether to prepend a timestamp in the log // PrependTimestamp specifies whether to prepend a timestamp in the log
PrependTimestamp bool PrependTimestamp bool
// map of tag's bit masks to log level, overrides lvl
tl map[Tag]zapcore.Level
} }
const ( const (
DestinationUndefined = "" DestinationUndefined = ""
DestinationStdout = "stdout" DestinationStdout = "stdout"
DestinationJournald = "journald" DestinationJournald = "journald"
zapTagFieldName = "tag"
) )
// SetLevelString sets the minimum logging level. Default is // SetLevelString sets the minimum logging level. Default is
@ -73,20 +77,10 @@ func (p *Prm) SetDestination(d string) error {
return nil return nil
} }
// Reload reloads configuration of a connected instance of the Logger. // SetTags parses list of tags with log level.
// Returns ErrLoggerNotConnected if no connection has been performed. func (p *Prm) SetTags(tags [][]string) (err error) {
// Returns any reconfiguration error from the Logger directly. p.tl, err = parseTags(tags)
func (p Prm) Reload() error { return err
if p._log == nil {
// incorrect logger usage
panic("parameters are not connected to any Logger")
}
return p._log.reload(p)
}
func defaultPrm() *Prm {
return new(Prm)
} }
// NewLogger constructs a new zap logger instance. Constructing with nil // NewLogger constructs a new zap logger instance. Constructing with nil
@ -100,10 +94,7 @@ func defaultPrm() *Prm {
// - ISO8601 time encoding. // - ISO8601 time encoding.
// //
// Logger records a stack trace for all messages at or above fatal level. // Logger records a stack trace for all messages at or above fatal level.
func NewLogger(prm *Prm) (*Logger, error) { func NewLogger(prm Prm) (*Logger, error) {
if prm == nil {
prm = defaultPrm()
}
switch prm.dest { switch prm.dest {
case DestinationUndefined, DestinationStdout: case DestinationUndefined, DestinationStdout:
return newConsoleLogger(prm) return newConsoleLogger(prm)
@ -114,11 +105,9 @@ func NewLogger(prm *Prm) (*Logger, error) {
} }
} }
func newConsoleLogger(prm *Prm) (*Logger, error) { func newConsoleLogger(prm Prm) (*Logger, error) {
lvl := zap.NewAtomicLevelAt(prm.level)
c := zap.NewProductionConfig() c := zap.NewProductionConfig()
c.Level = lvl c.Level = zap.NewAtomicLevelAt(zapcore.DebugLevel)
c.Encoding = "console" c.Encoding = "console"
if prm.SamplingHook != nil { if prm.SamplingHook != nil {
c.Sampling.Hook = prm.SamplingHook c.Sampling.Hook = prm.SamplingHook
@ -137,16 +126,19 @@ func newConsoleLogger(prm *Prm) (*Logger, error) {
if err != nil { if err != nil {
return nil, err return nil, err
fyrchik marked this conversation as resolved Outdated

Where does at name come from?

Where does `at` name come from?

It's a short version of allowedTags.

It's a short version of `allowedTags`.

Ah, ok.
It looked like a short version of ATomic which could've been wrong.

Ah, ok. It looked like a short version of `ATomic` which could've been wrong.
} }
parentZap := *lZap
lZap = lZap.With(zap.String(zapTagFieldName, tagToString(TagMain)))
l := &Logger{z: lZap, lvl: lvl} v := atomic.Value{}
prm._log = l v.Store(prm.tl)
l := &Logger{z: lZap, pz: &parentZap, lvl: zap.NewAtomicLevelAt(prm.level), t: TagMain, tl: &v}
return l, nil return l, nil
} }
func newJournaldLogger(prm *Prm) (*Logger, error) { func newJournaldLogger(prm Prm) (*Logger, error) {
lvl := zap.NewAtomicLevelAt(prm.level) lvl := zap.NewAtomicLevelAt(zapcore.DebugLevel)
c := zap.NewProductionConfig() c := zap.NewProductionConfig()
if prm.SamplingHook != nil { if prm.SamplingHook != nil {
c.Sampling.Hook = prm.SamplingHook c.Sampling.Hook = prm.SamplingHook
@ -179,28 +171,48 @@ func newJournaldLogger(prm *Prm) (*Logger, error) {
samplerOpts..., samplerOpts...,
) )
lZap := zap.New(samplingCore, zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel)), zap.AddCallerSkip(1)) lZap := zap.New(samplingCore, zap.AddStacktrace(zap.NewAtomicLevelAt(zap.FatalLevel)), zap.AddCallerSkip(1))
parentZap := *lZap
lZap = lZap.With(zap.String(zapTagFieldName, tagToString(TagMain)))
fyrchik marked this conversation as resolved Outdated

parseAllowedTags can be invoked without having l.mtx taken.

`parseAllowedTags` can be invoked without having `l.mtx` taken.

Right, rewrote this part with usage of package atomic.

Right, rewrote this part with usage of package `atomic`.
l := &Logger{z: lZap, lvl: lvl} v := atomic.Value{}
prm._log = l v.Store(prm.tl)
l := &Logger{z: lZap, pz: &parentZap, lvl: zap.NewAtomicLevelAt(prm.level), t: TagMain, tl: &v}
return l, nil return l, nil
fyrchik marked this conversation as resolved Outdated

We have already allocated tl in parseAllowedTags.
Why do we do this clear and copy?

We have already allocated `tl` in `parseAllowedTags`. Why do we do this `clear` and copy?

This part updated, please review.

This part updated, please review.
} }
func (l *Logger) reload(prm Prm) error { func (l *Logger) Reload(prm Prm) {
l.lvl.SetLevel(prm.level) l.lvl.SetLevel(prm.level)
return nil l.tl.Store(prm.tl)
} }
func (l *Logger) WithOptions(options ...zap.Option) { func (l *Logger) WithOptions(options ...zap.Option) {
l.z = l.z.WithOptions(options...) l.z = l.z.WithOptions(options...)
l.pz = l.pz.WithOptions(options...)
} }
func (l *Logger) With(fields ...zap.Field) *Logger { func (l *Logger) With(fields ...zap.Field) *Logger {
return &Logger{z: l.z.With(fields...)} c := *l
c.z = l.z.With(fields...)
return &c
}
func (l *Logger) WithTag(tag Tag) *Logger {
c := *l
c.t = tag
c.z = c.pz.With(zap.String(zapTagFieldName, tagToString(tag)))

Could you explain, why do we need this pz?
I feel there is some dark magic here.

Could you explain, why do we need this `pz`? I feel there is some dark magic here.
return &c
} }
func NewLoggerWrapper(z *zap.Logger) *Logger { func NewLoggerWrapper(z *zap.Logger) *Logger {
tl := &atomic.Value{}
tl.Store(make(map[Tag]zapcore.Level))
return &Logger{ return &Logger{
z: z.WithOptions(zap.AddCallerSkip(1)), z: z.WithOptions(zap.AddCallerSkip(1)),
pz: z.WithOptions(zap.AddCallerSkip(1)),
tl: tl,
lvl: zap.NewAtomicLevelAt(zapcore.DebugLevel),
} }
} }

View file

@ -0,0 +1,78 @@
package logger
import (
"context"
"testing"
"github.com/stretchr/testify/require"
)
func BenchmarkLoggerDebug(b *testing.B) {

Could you make this benchmark more fine-grained?
Specifically, we have 2 degrees of freedom:

  1. Log level may be greater or lesser than the allowed one.
  2. Tag may be allowed or not.

That gives us 4 different benchmarks, that we would like to compare against each other.

Could you make this benchmark more fine-grained? Specifically, we have 2 degrees of freedom: 1. Log level may be greater or lesser than the allowed one. 2. Tag may be allowed or not. That gives us 4 different benchmarks, that we would like to compare against each other.

Extended number of benchmarks, divided them by separate functions to have ability to execute them separately in cli. In other case, it is impossible to determine in output test result - go hide name of the benchmark unpredictably.

Extended number of benchmarks, divided them by separate functions to have ability to execute them separately in `cli`. In other case, it is impossible to determine in output test result - `go` hide name of the benchmark unpredictably.
ctx := context.Background()
prm := Prm{}
a-savchuk marked this conversation as resolved Outdated

Here's from your benchmark results:

goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
1000000000	         0.005202 ns/op	       0 B/op	       0 allocs/op
...

As for me this average time is not correct because you don't use b.N. I think the shown number of iterations (1e9) is used when calculating the average time, not the actual number you use (1e4).

If you want to specify number of iterations, you can use -benchtime flag, for example -benchtime=1m (1 minute) or -benchtime=10000x (10000 times).

Here's from your benchmark results: ``` goos: linux goarch: amd64 pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz 1000000000 0.005202 ns/op 0 B/op 0 allocs/op ... ``` As for me this average time is not correct because you don't use `b.N`. I think the shown number of iterations (1e9) is used when calculating the average time, not the actual number you use (1e4). If you want to specify number of iterations, you can use `-benchtime` flag, for example `-benchtime=1m` (1 minute) or `-benchtime=10000x` (10000 times).

Thanks, change a bit benchmark to use b.N. Commit messages were updated too.

Thanks, change a bit benchmark to use `b.N`. Commit messages were updated too.
require.NoError(b, prm.SetLevelString("debug"))
logger, err := NewLogger(prm)
require.NoError(b, err)
b.ResetTimer()
b.ReportAllocs()
for range b.N {
logger.Debug(ctx, "test debug")
logger.Info(ctx, "test info")
logger.Warn(ctx, "test warn")
logger.Error(ctx, "test error")
}
}
func BenchmarkLoggerError(b *testing.B) {
ctx := context.Background()
prm := Prm{}
require.NoError(b, prm.SetLevelString("error"))
logger, err := NewLogger(prm)
require.NoError(b, err)
b.ResetTimer()
b.ReportAllocs()
for range b.N {
logger.Debug(ctx, "test debug")
logger.Info(ctx, "test info")
logger.Warn(ctx, "test warn")
logger.Error(ctx, "test error")
}
}
func BenchmarkLoggerLevelLess(b *testing.B) {
ctx := context.Background()
prm := Prm{}
require.NoError(b, prm.SetLevelString("info"))
require.NoError(b, prm.SetTags([][]string{{"main", "debug"}, {"morph", "debug"}}))

You have tags here, but each .Debug etc. call has no tag, so what do we achieve with these tags?

You have tags here, but each `.Debug` etc. call has no tag, so what do we achieve with these tags?
logger, err := NewLogger(prm)
require.NoError(b, err)
b.ResetTimer()
b.ReportAllocs()
for range b.N {
logger.Debug(ctx, "test debug")
logger.Info(ctx, "test info")
logger.Warn(ctx, "test warn")
logger.Error(ctx, "test error")
}
}
func BenchmarkLoggerLevelGreater(b *testing.B) {
ctx := context.Background()
prm := Prm{}
require.NoError(b, prm.SetLevelString("debug"))
require.NoError(b, prm.SetTags([][]string{{"main", "error"}, {"morph", "debug"}}))
logger, err := NewLogger(prm)
require.NoError(b, err)
b.ResetTimer()
b.ReportAllocs()
for range b.N {
logger.Debug(ctx, "test debug")
logger.Info(ctx, "test info")
logger.Warn(ctx, "test warn")
logger.Error(ctx, "test error")
}
}

View file

@ -0,0 +1,71 @@
BenchmarkLoggerDebug
goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
10000 534.6 ns/op 23 B/op 0 allocs/op
10000 530.9 ns/op 23 B/op 0 allocs/op
10000 667.4 ns/op 23 B/op 0 allocs/op
10000 582.2 ns/op 23 B/op 0 allocs/op
10000 530.7 ns/op 23 B/op 0 allocs/op
10000 666.8 ns/op 23 B/op 0 allocs/op
10000 533.1 ns/op 23 B/op 0 allocs/op
10000 531.8 ns/op 23 B/op 0 allocs/op
10000 529.5 ns/op 22 B/op 0 allocs/op
10000 645.0 ns/op 23 B/op 0 allocs/op
PASS
ok git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger 0.069s
BenchmarkLoggerError
goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
10000 137.3 ns/op 6 B/op 0 allocs/op
10000 144.2 ns/op 6 B/op 0 allocs/op
10000 137.5 ns/op 6 B/op 0 allocs/op
10000 142.6 ns/op 6 B/op 0 allocs/op
10000 136.3 ns/op 6 B/op 0 allocs/op
10000 137.0 ns/op 6 B/op 0 allocs/op
10000 144.0 ns/op 6 B/op 0 allocs/op
10000 152.6 ns/op 6 B/op 0 allocs/op
10000 136.4 ns/op 6 B/op 0 allocs/op
10000 137.9 ns/op 6 B/op 0 allocs/op
PASS
ok git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger 0.024s
BenchmarkLoggerLevelLess
goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
10000 554.3 ns/op 23 B/op 0 allocs/op
10000 630.1 ns/op 23 B/op 0 allocs/op
10000 642.0 ns/op 23 B/op 0 allocs/op
10000 548.0 ns/op 23 B/op 0 allocs/op
10000 562.7 ns/op 23 B/op 0 allocs/op
10000 572.7 ns/op 23 B/op 0 allocs/op
10000 552.1 ns/op 23 B/op 0 allocs/op
10000 555.4 ns/op 23 B/op 0 allocs/op
10000 546.0 ns/op 23 B/op 0 allocs/op
10000 561.0 ns/op 22 B/op 0 allocs/op
PASS
ok git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger 0.069s
BenchmarkLoggerLevelGreater
goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
10000 159.6 ns/op 6 B/op 0 allocs/op
10000 161.9 ns/op 6 B/op 0 allocs/op
10000 161.4 ns/op 6 B/op 0 allocs/op
10000 160.9 ns/op 6 B/op 0 allocs/op
10000 166.9 ns/op 6 B/op 0 allocs/op
10000 163.9 ns/op 6 B/op 0 allocs/op
10000 163.4 ns/op 6 B/op 0 allocs/op
10000 158.7 ns/op 6 B/op 0 allocs/op
10000 173.2 ns/op 6 B/op 0 allocs/op
10000 160.7 ns/op 6 B/op 0 allocs/op
PASS
ok git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger 0.028s

177
pkg/util/logger/tags.go Normal file
View file

@ -0,0 +1,177 @@
package logger
import (
"fmt"
"math"
"strings"
"go.uber.org/zap/zapcore"
)
type Tag uint8
const (
TagMain Tag = iota
TagMorph
TagGrpcSvc
TagIr
TagProcessor
TagEngine
TagBlobovnicza
TagBlobstor
TagFSTree
TagGC
TagShard
TagWriteCache
TagDeleteSvc
TagGetSvc
TagSearchSvc
TagSessionSvc
TagTreeSvc
TagPolicer
TagReplicator
tagMain = "main"
tagMorph = "morph"
tagGrpcSvc = "grpc_svc"
tagIr = "ir"
tagProcessor = "processor"
tagEngine = "engine"
tagBlobovnicza = "blobovnicza"
tagBlobstor = "blobstor"
tagFSTree = "fstree"
tagGC = "gc"
tagShard = "shard"
tagWriteCache = "writecache"
tagDeleteSvc = "deletesvc"
tagGetSvc = "getsvc"
tagSearchSvc = "searchsvc"
tagSessionSvc = "sessionsvc"
tagTreeSvc = "treesvc"
tagPolicer = "policer"
tagReplicator = "replicator"
)
// tagToMask return bit mask for the tag, encoded in uint32.

tagToMask -> tagFromString

`tagToMask` -> `tagFromString`
func tagFromString(str string) (Tag, error) {
switch str {
case tagMain:
return TagMain, nil
case tagMorph:
return TagMorph, nil
case tagGrpcSvc:
return TagGrpcSvc, nil
case tagIr:
return TagIr, nil
case tagProcessor:
return TagProcessor, nil
case tagEngine:
return TagEngine, nil
case tagBlobovnicza:
return TagBlobovnicza, nil
case tagBlobstor:
return TagBlobstor, nil
case tagFSTree:
return TagFSTree, nil
case tagGC:
return TagGC, nil
case tagShard:
return TagShard, nil
case tagWriteCache:
return TagWriteCache, nil
case tagDeleteSvc:
return TagDeleteSvc, nil
case tagGetSvc:
return TagGetSvc, nil
case tagSearchSvc:
return TagSearchSvc, nil
case tagSessionSvc:
return TagSessionSvc, nil
case tagTreeSvc:
return TagTreeSvc, nil
case tagPolicer:
return TagPolicer, nil
case tagReplicator:
return TagReplicator, nil
default:
return math.MaxUint8, fmt.Errorf("unsupported tag %s", str)
}
}
// tagToString return string representation for the tag.
func tagToString(tag Tag) string {

Can we use https://pkg.go.dev/golang.org/x/tools/cmd/stringer for this?
It supports custom strings, just add a comment, see 3e54c46281/pkg/vm/opcode/opcode.go (L50) for an example.

Can we use https://pkg.go.dev/golang.org/x/tools/cmd/stringer for this? It supports custom strings, just add a comment, see https://github.com/nspcc-dev/neo-go/blob/3e54c46281237124da7fd89a90501a9d58a3aa60/pkg/vm/opcode/opcode.go#L50 for an example.

It should also generate fromString map, so less opportunities to make an error there.

It should also generate `fromString` map, so less opportunities to make an error there.
switch tag {
case TagMain:
return tagMain
case TagMorph:
return tagMorph
case TagGrpcSvc:
return tagGrpcSvc
case TagIr:
return tagIr
case TagProcessor:
return tagProcessor
case TagEngine:
return tagEngine
case TagBlobovnicza:
return tagBlobovnicza
case TagBlobstor:
return tagBlobstor
case TagFSTree:
return tagFSTree
case TagGC:
return tagGC
case TagShard:
return tagShard
case TagWriteCache:
return tagWriteCache
case TagDeleteSvc:
return tagDeleteSvc
case TagGetSvc:
return tagGetSvc
case TagSearchSvc:
return tagSearchSvc
case TagSessionSvc:
return tagSessionSvc
case TagTreeSvc:
return tagTreeSvc
case TagPolicer:
return tagPolicer
case TagReplicator:
return tagReplicator
default:
return ""
}
}
// parseTags returns:
// - map(always instantiated) of tag to custom log level for that tag;
// - error if it occurred(map is empty).
func parseTags(raw [][]string) (map[Tag]zapcore.Level, error) {
m := make(map[Tag]zapcore.Level)
if len(raw) == 0 {
return m, nil
}
for _, item := range raw {
str, level := item[0], item[1]
if len(level) == 0 {
// It is not necessary to parse tags without level,
// because default log level will be used.
continue
}
var l zapcore.Level
err := l.UnmarshalText([]byte(level))
if err != nil {
return nil, err
}
tmp := strings.Split(str, ",")
for _, tagStr := range tmp {
tag, err := tagFromString(strings.TrimSpace(tagStr))
if err != nil {
return nil, err
}
m[tag] = l
}
}
return m, nil
}