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
Member

Each log entry should be marked by tag:

2025-03-20T07:46:02.998Z        info    frostfs-node/main.go:76 initializing tracing service... {"tag": "main"}
...
2025-03-20T07:47:25.877Z        debug   frostfs-node/morph.go:213       new block       {"tag": "morph", "index": 118}

Default logger level can be redefined for each tag.

New parameters in config:

logger:
  level: error
  tags:
    - names: "morph, engine"
      level: debug

Signed-off-by: Anton Nikiforov an.nikiforov@yadro.com

Each log entry should be marked by tag: ``` 2025-03-20T07:46:02.998Z info frostfs-node/main.go:76 initializing tracing service... {"tag": "main"} ... 2025-03-20T07:47:25.877Z debug frostfs-node/morph.go:213 new block {"tag": "morph", "index": 118} ``` Default logger level can be redefined for each tag. New parameters in config: ``` logger: level: error tags: - names: "morph, engine" level: debug ``` Signed-off-by: Anton Nikiforov <an.nikiforov@yadro.com>
acid-ant force-pushed feature/log-tags from 3d122022ff to 3fc783c164 2025-01-29 12:44:48 +00:00 Compare
acid-ant changed title from WIP: logger: Filter log entries by tags provided in config to WIP: logger: Filter entries by tags provided in config 2025-01-29 12:45:14 +00:00
acid-ant force-pushed feature/log-tags from 3fc783c164 to 32dca3ad29 2025-01-29 12:45:48 +00:00 Compare
acid-ant force-pushed feature/log-tags from 32dca3ad29 to 3982cf3070 2025-01-30 15:42:37 +00:00 Compare
acid-ant force-pushed feature/log-tags from 3982cf3070 to d60252c150 2025-01-30 15:43:11 +00:00 Compare
acid-ant changed title from WIP: logger: Filter entries by tags provided in config to logger: Filter entries by tags provided in config 2025-01-30 15:48:34 +00:00
requested reviews from storage-core-committers, storage-core-developers 2025-01-30 15:48:35 +00:00
acid-ant force-pushed feature/log-tags from d60252c150 to e17e1f4b9d 2025-02-03 06:18:35 +00:00 Compare
acid-ant changed title from logger: Filter entries by tags provided in config to WIP: logger: Filter entries by tags provided in config 2025-02-03 09:11:36 +00:00
dstepanov-yadro reviewed 2025-02-03 09:32:17 +00:00
dstepanov-yadro left a comment
Member

Why allowed list but not disallowed list?

Why allowed list but not disallowed list?
@ -42,4 +44,3 @@
if err != nil {
return err
}
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")
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") ```
Author
Member

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.
dstepanov-yadro marked this conversation as resolved
@ -17,0 +19,4 @@
at *atomic.Uint32
m uint32
tl map[uint32]zapcore.Level
mtx *sync.RWMutex

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.
Author
Member

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

Thanks, there are no necessity to use `sync.RWMutex` - code updated.
dstepanov-yadro marked this conversation as resolved
fyrchik reviewed 2025-02-03 11:17:49 +00:00
@ -0,0 +10,4 @@
const (
BitMain uint8 = iota
BitMorph
Owner

Bit should be an implementation detail, I would rather use TagMorph

`Bit` should be an implementation detail, I would rather use `TagMorph`
Author
Member

Ok, renamed.

Ok, renamed.
fyrchik marked this conversation as resolved
fyrchik reviewed 2025-02-03 11:26:00 +00:00
@ -381,8 +383,6 @@ type internals struct {
appCfg *config.Config
log *logger.Logger
Owner

This part seems unnecessary, why do we move this field to cfg?

This part seems unnecessary, why do we move this field to `cfg`?
Author
Member

Right, removed these changes.

Right, removed these changes.
fyrchik marked this conversation as resolved
@ -142,0 +124,4 @@
return nil, err
}
var at atomic.Uint32
at.Store(pat)
Owner

Where does at name come from?

Where does `at` name come from?
Author
Member

It's a short version of allowedTags.

It's a short version of `allowedTags`.
Owner

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.
fyrchik marked this conversation as resolved
@ -180,0 +173,4 @@
func (l *Logger) Reload(prm Prm) error {
l.mtx.Lock()
defer l.mtx.Unlock()
at, tl, err := parseAllowedTags(prm.AllowedTags)
Owner

parseAllowedTags can be invoked without having l.mtx taken.

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

Right, rewrote this part with usage of package atomic.

Right, rewrote this part with usage of package `atomic`.
fyrchik marked this conversation as resolved
@ -180,1 +179,4 @@
}
l.lvl.SetLevel(prm.level)
l.at.Store(at)
clear(l.tl)
Owner

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?
Author
Member

This part updated, please review.

This part updated, please review.
fyrchik marked this conversation as resolved
acid-ant force-pushed feature/log-tags from e17e1f4b9d to 8b3cb41d5a 2025-02-04 07:45:22 +00:00 Compare
acid-ant force-pushed feature/log-tags from 8b3cb41d5a to c6be5a71f2 2025-02-04 07:48:57 +00:00 Compare
acid-ant changed title from WIP: logger: Filter entries by tags provided in config to logger: Filter entries by tags provided in config 2025-02-04 07:48:58 +00:00
acid-ant force-pushed feature/log-tags from c6be5a71f2 to e3d2319eb0 2025-02-04 07:50:21 +00:00 Compare
acid-ant force-pushed feature/log-tags from e3d2319eb0 to c02f69e3e2 2025-02-04 08:05:28 +00:00 Compare
acid-ant force-pushed feature/log-tags from c02f69e3e2 to 3d4dcf7d55 2025-02-04 08:11:41 +00:00 Compare
aarifullin approved these changes 2025-02-05 15:14:07 +00:00
Dismissed
fyrchik reviewed 2025-02-06 08:32:55 +00:00
@ -42,4 +44,3 @@
if err != nil {
return err
}
logPrm.PrependTimestamp = cfg.GetBool("logger.timestamp")
Owner

Where did PrependTimestamp part go?

Where did `PrependTimestamp` part go?
Author
Member

Removed because it is never used for logger reloading.

Removed because it is never used for logger reloading.
Owner

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?
Author
Member

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.
@ -405,3 +407,3 @@
// stops node's maintenance.
func (c *internals) stopMaintenance(ctx context.Context) {
func (c *cfg) stopMaintenance(ctx context.Context) {
Owner

Forgot to revert?

Forgot to revert?
Author
Member

Right, thanks.

Right, thanks.
fyrchik marked this conversation as resolved
@ -1337,2 +1347,3 @@
}
components := c.getComponents(ctx, logPrm)
components := c.getComponents(ctx)
Owner

Why don't we put it in components as before?

Why don't we put it in `components` as before?
Author
Member

Oh, right, reverted. Now it looks much simpler.

Oh, right, reverted. Now it looks much simpler.
fyrchik marked this conversation as resolved
fyrchik reviewed 2025-02-06 08:39:33 +00:00
@ -0,0 +69,4 @@
}
}
func parseAllowedTags(tags []string) (uint32, map[uint32]zapcore.Level, error) {
Owner

Do we have the format described somewhere?
It is hard to understand what this function should do vs what it actually does.

Do we have the format described somewhere? It is hard to understand what this function should do vs what it actually does.
Author
Member

Thanks, I've added doc for the function.

Thanks, I've added doc for the function.
fyrchik marked this conversation as resolved
@ -0,0 +77,4 @@
var v uint32
for _, str := range tags {
sep := strings.Index(str, ":")
var tag, level string
Owner

This and the following if could be replaced with tag, level, _ := strings.Cut(str, ":")

This and the following `if` could be replaced with `tag, level, _ := strings.Cut(str, ":")`
Author
Member

Fixed.

Fixed.
fyrchik marked this conversation as resolved
acid-ant force-pushed feature/log-tags from 3d4dcf7d55 to f94a8625fa 2025-02-06 09:06:18 +00:00 Compare
acid-ant dismissed aarifullin's review 2025-02-06 09:06:19 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

acid-ant force-pushed feature/log-tags from f94a8625fa to 4b6a8ca12d 2025-02-06 11:41:10 +00:00 Compare
acid-ant force-pushed feature/log-tags from 4b6a8ca12d to 1c14ab2ee1 2025-02-07 14:17:16 +00:00 Compare
acid-ant force-pushed feature/log-tags from 1c14ab2ee1 to b41cb386cb 2025-02-07 14:19:43 +00:00 Compare
a-savchuk reviewed 2025-02-10 15:55:58 +00:00
@ -0,0 +9,4 @@
func Benchmark_loggerLog(b *testing.B) {
ctx := context.Background()
num := 10000
Member

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).
Author
Member

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.
a-savchuk marked this conversation as resolved
acid-ant force-pushed feature/log-tags from b41cb386cb to 27f11febb9 2025-02-11 07:48:10 +00:00 Compare
Author
Member

Minor changes for benchmark.

Minor changes for benchmark.
dstepanov-yadro approved these changes 2025-02-11 14:29:14 +00:00
Dismissed
requested reviews from storage-core-committers, storage-core-developers 2025-02-13 12:22:28 +00:00
acid-ant changed title from logger: Filter entries by tags provided in config to WIP: logger: Filter entries by tags provided in config 2025-02-17 07:24:35 +00:00
acid-ant force-pushed feature/log-tags from 27f11febb9 to 09cc4b60dd 2025-02-18 11:28:16 +00:00 Compare
acid-ant dismissed dstepanov-yadro's review 2025-02-18 11:28:16 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

acid-ant force-pushed feature/log-tags from 09cc4b60dd to 5bf54e18ab 2025-02-18 11:29:10 +00:00 Compare
Author
Member

Added new behavior - log level for tag should be independent of the default log level.

Added new behavior - log level for tag should be independent of the default log level.
acid-ant changed title from WIP: logger: Filter entries by tags provided in config to logger: Filter entries by tags provided in config 2025-02-18 14:29:58 +00:00
dstepanov-yadro requested changes 2025-02-21 06:54:59 +00:00
Dismissed
@ -14,6 +16,9 @@ import (
type Logger struct {
z *zap.Logger
lvl zap.AtomicLevel
at *atomic.Uint32

Please give these variables more meaningful names.

Please give these variables more meaningful names.
Author
Member

Added comments for each new variable.

Added comments for each new variable.
acid-ant force-pushed feature/log-tags from 5bf54e18ab to cb1792c69b 2025-02-21 09:39:29 +00:00 Compare
dstepanov-yadro approved these changes 2025-02-21 14:47:59 +00:00
Dismissed
acid-ant force-pushed feature/log-tags from cb1792c69b to a775656620 2025-02-25 08:07:59 +00:00 Compare
acid-ant dismissed dstepanov-yadro's review 2025-02-25 08:07:59 +00:00
Reason:

New commits pushed, approval review dismissed automatically according to repository settings

Author
Member

Minor changes in docs.

Minor changes in docs.
fyrchik reviewed 2025-02-28 14:22:36 +00:00
@ -30,6 +30,11 @@ func validateConfig(c *config.Config) error {
return fmt.Errorf("invalid logger destination: %w", err)
}
err = logger.ValidateAllowedTags(loggerconfig.AllowedTags(c))
Owner

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.
Author
Member

Agree, added method SetAllowedTags.

Agree, added method `SetAllowedTags`.
fyrchik marked this conversation as resolved
@ -0,0 +25,4 @@
TagGetSvc
TagSearchSvc
TagPolicer
TagReplicator
Owner

Could you please put private constant tagLast here and add a test that checks tagLast <= 32?
I am not sure go vet catches uint32(1 << 32) problem.

Could you please put private constant `tagLast` here and add a test that checks `tagLast <= 32`? I am not sure go vet catches `uint32(1 << 32)` problem.
Author
Member

Nice question.

func TestCheckTagOverflow(t *testing.T) {
		t.Log(uint32(int(1) << 32))
}

output:
...
# git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger [git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger.test]
pkg/util/logger/logger_test.go:31:15: constant 4294967296 overflows uint32
FAIL	git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger [build failed]
...

Looks like it is redundant to check for tagLast <= 32, we will fail at runtime.

Nice question. ``` func TestCheckTagOverflow(t *testing.T) { t.Log(uint32(int(1) << 32)) } output: ... # git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger [git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger.test] pkg/util/logger/logger_test.go:31:15: constant 4294967296 overflows uint32 FAIL git.frostfs.info/TrueCloudLab/frostfs-node/pkg/util/logger [build failed] ... ``` Looks like it is redundant to check for `tagLast <= 32`, we will fail at runtime.
@ -0,0 +7,4 @@
"github.com/stretchr/testify/require"
)
func Benchmark_loggerLog(b *testing.B) {
Owner

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.
Author
Member

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.
acid-ant force-pushed feature/log-tags from a775656620 to e67f943a6d 2025-03-06 08:26:31 +00:00 Compare
acid-ant force-pushed feature/log-tags from e67f943a6d to eed9e131dc 2025-03-06 08:32:24 +00:00 Compare
acid-ant changed title from logger: Filter entries by tags provided in config to WIP: logger: Filter entries by tags provided in config 2025-03-11 14:12:25 +00:00
acid-ant force-pushed feature/log-tags from eed9e131dc to ad62603969 2025-03-18 14:18:33 +00:00 Compare
acid-ant changed title from WIP: logger: Filter entries by tags provided in config to logger: Filter entries by tags provided in config 2025-03-18 14:26:07 +00:00
requested reviews from storage-core-committers, storage-core-developers 2025-03-18 14:26:08 +00:00
fyrchik requested changes 2025-03-20 10:12:15 +00:00
fyrchik left a comment
Owner

A general remark about the benchmarks:
They are currently hard to compare and understand exactly.
Could you have a similar function (the for loop that is identical in all of the benchmarks) and have this function accept some parameters.
It is currently hard to understand what do we measure in each benchmark.

A general remark about the benchmarks: They are currently hard to compare and understand exactly. Could you have a similar function (the `for` loop that is identical in all of the benchmarks) and have this function accept some parameters. It is currently hard to understand _what_ do we measure in each benchmark.
@ -63,0 +72,4 @@
if names == "" {
break
}
item = append(item, names, config.StringSafe(s, "level"))
Owner

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.
@ -36,0 +52,4 @@
if lvl, ok := tl[l.t]; ok {
return level < lvl
}
return level < l.lvl.Level()
Owner

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.
@ -200,0 +201,4 @@
func (l *Logger) WithTag(tag Tag) *Logger {
c := *l
c.t = tag
c.z = c.pz.With(zap.String(zapTagFieldName, tagToString(tag)))
Owner

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.
@ -0,0 +45,4 @@
ctx := context.Background()
prm := Prm{}
require.NoError(b, prm.SetLevelString("info"))
require.NoError(b, prm.SetTags([][]string{{"main", "debug"}, {"morph", "debug"}}))
Owner

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?
@ -0,0 +52,4 @@
tagReplicator = "replicator"
)
// tagToMask return bit mask for the tag, encoded in uint32.
Owner

tagToMask -> tagFromString

`tagToMask` -> `tagFromString`
@ -0,0 +99,4 @@
}
// tagToString return string representation for the tag.
func tagToString(tag Tag) string {
Owner

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.
Owner

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.
acid-ant force-pushed feature/log-tags from ad62603969 to e20df71798 2025-03-21 07:32:17 +00:00 Compare
fyrchik changed title from logger: Filter entries by tags provided in config to WIP: logger: Filter entries by tags provided in config 2025-03-21 09:49:22 +00:00
fyrchik closed this pull request 2025-03-21 10:34:32 +00:00
snegurochka referenced this pull request from a commit 2025-04-16 10:25:29 +00:00
All checks were successful
DCO action / DCO (pull_request) Successful in 40s
Required
Details
Vulncheck / Vulncheck (pull_request) Successful in 1m0s
Required
Details
Pre-commit hooks / Pre-commit (pull_request) Successful in 1m28s
Required
Details
Build / Build Components (pull_request) Successful in 1m57s
Required
Details
Tests and linters / gopls check (pull_request) Successful in 3m42s
Required
Details
Tests and linters / Run gofumpt (pull_request) Successful in 4m55s
Required
Details
Tests and linters / Staticcheck (pull_request) Successful in 5m53s
Required
Details
Tests and linters / Lint (pull_request) Successful in 6m3s
Required
Details
Tests and linters / Tests (pull_request) Successful in 6m1s
Required
Details
Tests and linters / Tests with -race (pull_request) Successful in 6m46s
Required
Details

Pull request closed

Sign in to join this conversation.
No reviewers
No milestone
No project
No assignees
5 participants
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference: TrueCloudLab/frostfs-node#1619
No description provided.