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

Draft
acid-ant wants to merge 6 commits from acid-ant/frostfs-node:feature/log-tags into master
Member

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

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:29 +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
All checks were successful
DCO action / DCO (pull_request) Successful in 37s
Required
Details
Vulncheck / Vulncheck (pull_request) Successful in 1m4s
Required
Details
Build / Build Components (pull_request) Successful in 1m36s
Required
Details
Pre-commit hooks / Pre-commit (pull_request) Successful in 1m39s
Required
Details
Tests and linters / Run gofumpt (pull_request) Successful in 3m44s
Required
Details
Tests and linters / Lint (pull_request) Successful in 3m56s
Required
Details
Tests and linters / gopls check (pull_request) Successful in 4m5s
Required
Details
Tests and linters / Tests (pull_request) Successful in 4m34s
Required
Details
Tests and linters / Staticcheck (pull_request) Successful in 4m53s
Required
Details
Tests and linters / Tests with -race (pull_request) Successful in 5m5s
Required
Details
This pull request is marked as a work in progress.
This branch is out-of-date with the base branch
View command line instructions

Checkout

From your project repository, check out a new branch and test the changes.
git fetch -u feature/log-tags:acid-ant-feature/log-tags
git checkout acid-ant-feature/log-tags
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.